[Regression][BYT][rt5651]: 'ipc timed out for 0x60050000' after aplay music at the 2nd time #873

Activity

1. stevyan

   added

   bugSomething isn't workingSomething isn't working

   BYTApplies to Baytrail platformApplies to Baytrail platform

   regression

   on Apr 26, 2019
2. mengdonglin

   assigned

   keyonjie

   on Apr 26, 2019
3. keyonjie commented on Apr 26, 2019

   

   keyonjie

   on Apr 26, 2019

   More actions

   Hi @stevyan can you paste the sof-logger logs also please?
4. stevyan commented on Apr 26, 2019

   

   stevyan

   on Apr 26, 2019

   Author

   More actions

   ipc_error-sof-logger.log
5. stevyan commented on Apr 26, 2019

   

   stevyan

   on Apr 26, 2019

   Last edited by stevyan

   Author

   More actions

   Another issue also caused by PR #849,
   'ipc timed out for 0x60050000 | 0x60060000 | 0x60070000' after pause/resume music more than 5 times.

   To reproduce

   1. aplay -Dhw:0,0 -f dat /dev/zero -vv -i
   2. press space key to pause|resume playback, more than 5 times

   Actual Result

   === PAUSE ===                                                                   
   aplay: do_pause:1497: pause push error: Connection timed out
   === PAUSE ===
   === PAUSE ===
   === PAUSE ===
   aplay: do_pause:1497: pause push error: Connection timed out 
   === PAUSE ===
   === PAUSE ===
   aplay: pcm_write:2011: write error: Input/output error        
   

   Test Recipe
   date: 2019-04-26
   sof (master): 6a84b4e
   linux (topic/sof-dev): f7e9d4a
   topology: sof-byt-rt5651.tplg, sof-byt-nocodec.tplg

   dmesg log

   [   42.957378] sof-audio-acpi 80860F28:01: ipc tx: 0x60060000: GLB_STREAM_MSG: TRIG_PAUSE
   [   43.258694] sof-audio-acpi 80860F28:01: error: ipc timed out for 0x60060000 size 12
   [   43.258772] sof-audio-acpi 80860F28:01: error: unexpected fault 0x600a0001 trace 0x60060000
   [   43.258786] sof-audio-acpi 80860F28:01: error: waking up any trace sleepers
   [   43.258802]  Low Latency: ASoC: trigger FE failed -110
   [   43.258825] sof-audio-acpi 80860F28:01: pcm: trigger stream 0 dir 0 cmd 4
   [   43.258842] sof-audio-acpi 80860F28:01: ipc tx: 0x60070000: GLB_STREAM_MSG: TRIG_RELEASE
   [   43.562760] sof-audio-acpi 80860F28:01: error: ipc timed out for 0x60070000 size 12
   [   43.562838] sof-audio-acpi 80860F28:01: error: unexpected fault 0x600a0001 trace 0x60070000
   [   43.562852] sof-audio-acpi 80860F28:01: error: waking up any trace sleepers
   [   43.562868]  Low Latency: ASoC: trigger FE failed -110
   [   43.563171] sof-audio-acpi 80860F28:01: PCM: stream 0 dir 0 DMA position 3696 DAI position 269024
   [   43.563190] sof-audio-acpi 80860F28:01: pcm: trigger stream 0 dir 0 cmd 3
   [   43.563207] sof-audio-acpi 80860F28:01: ipc tx: 0x60060000: GLB_STREAM_MSG: TRIG_PAUSE
   [   43.866929] sof-audio-acpi 80860F28:01: error: ipc timed out for 0x60060000 size 12
   [   43.867007] sof-audio-acpi 80860F28:01: error: unexpected fault 0x600a0001 trace 0x60060000
   [   43.867021] sof-audio-acpi 80860F28:01: error: waking up any trace sleepers
   [   43.867037]  Low Latency: ASoC: trigger FE failed -110
   [   43.867061] sof-audio-acpi 80860F28:01: pcm: trigger stream 0 dir 0 cmd 4
   [   43.867079] sof-audio-acpi 80860F28:01: ipc tx: 0x60070000: GLB_STREAM_MSG: TRIG_RELEASE
   [   44.170620] sof-audio-acpi 80860F28:01: error: ipc timed out for 0x60070000 size 12
   [   44.170698] sof-audio-acpi 80860F28:01: error: unexpected fault 0x600a0001 trace 0x60070000
   [   44.170713] sof-audio-acpi 80860F28:01: error: waking up any trace sleepers
   [   44.170729]  Low Latency: ASoC: trigger FE failed -110
   [   44.170886] sof-audio-acpi 80860F28:01: PCM: stream 0 dir 0 DMA position 3696 DAI position 269024
   [   44.170894] sof-audio-acpi 80860F28:01: pcm: trigger stream 0 dir 0 cmd 3
   [   44.170902] sof-audio-acpi 80860F28:01: ipc tx: 0x60060000: GLB_STREAM_MSG: TRIG_PAUSE
   [   44.474543] sof-audio-acpi 80860F28:01: error: ipc timed out for 0x60060000 size 12
   [   44.474621] sof-audio-acpi 80860F28:01: error: unexpected fault 0x600a0001 trace 0x60060000
   [   44.474636] sof-audio-acpi 80860F28:01: error: waking up any trace sleepers
   [   44.474651]  Low Latency: ASoC: trigger FE failed -110
   [   44.474675] sof-audio-acpi 80860F28:01: pcm: trigger stream 0 dir 0 cmd 4
   [   44.474693] sof-audio-acpi 80860F28:01: ipc tx: 0x60070000: GLB_STREAM_MSG: TRIG_RELEASE
   [   44.778690] sof-audio-acpi 80860F28:01: error: ipc timed out for 0x60070000 size 12
   [   44.778764] sof-audio-acpi 80860F28:01: error: unexpected fault 0x600a0001 trace 0x60070000
   [   44.778777] sof-audio-acpi 80860F28:01: error: waking up any trace sleepers
   [   44.778790]  Low Latency: ASoC: trigger FE failed -110
   [   44.778985] sof-audio-acpi 80860F28:01: PCM: stream 0 dir 0 DMA position 3696 DAI position 269024
   [   45.383327] sof-audio-acpi 80860F28:01: PCM: stream 0 dir 0 DMA position 3696 DAI position 269024
   [   45.891087] sof-audio-acpi 80860F28:01: pcm: trigger stream 0 dir 0 cmd 0
   [   45.891109] sof-audio-acpi 80860F28:01: ipc tx: 0x60050000: GLB_STREAM_MSG: TRIG_STOP
   [   46.194887] sof-audio-acpi 80860F28:01: error: ipc timed out for 0x60050000 size 12
   [   46.194966] sof-audio-acpi 80860F28:01: error: unexpected fault 0x600a0001 trace 0x60050000
   [   46.194980] sof-audio-acpi 80860F28:01: error: waking up any trace sleepers
   [   46.194996]  Low Latency: ASoC: trigger FE failed -110
   [   46.195048] sof-audio-acpi 80860F28:01: pcm: free stream 0 dir 0
   [   46.195064] sof-audio-acpi 80860F28:01: ipc tx: 0x60030000: GLB_STREAM_MSG: PCM_FREE
   [   46.498894] sof-audio-acpi 80860F28:01: error: ipc timed out for 0x60030000 size 12
   [   46.498973] sof-audio-acpi 80860F28:01: error: unexpected fault 0x600a0001 trace 0x60030000
   [   46.498988] sof-audio-acpi 80860F28:01: error: waking up any trace sleepers
   

   ipc_error.log
   ipc_error-slogger.log
6. wenqingfu

   assigned

   lyakh

   and unassigned

   keyonjie

   on May 2, 2019
7. lyakh commented on May 3, 2019

   

   lyakh

   on May 3, 2019

   Last edited by lyakh

   Collaborator

   More actions

   I'm unable to reproduce either of the two reported problems neither with nocodec nor with rt5651 with linux 3f6a2df and a recent SOF thesofproject/sof@6e4faef
   @stevyan could you try to double-check with the current trees?
8. Jiangxinx commented on May 6, 2019

   

   Jiangxinx

   on May 6, 2019

   More actions

   This issue can still be reproduced on daily test.
   To reproduce
   1.aplay -Dhw:0,0 -f dat /dev/zero
   2.ctrl + c
   3.aplay again with aplay -Dhw:0,0 -f dat /dev/zero

   Test Recipe
   sof (master): de5bba4
   linux (topic/sof-dev): 1071743
   topology: sof-byt-rt5651.tplg
9. lyakh commented on May 6, 2019

   

   lyakh

   on May 6, 2019

   Collaborator

   More actions

   @Jiangxinx strange, I cannot reproduce it here so far. I'll try to check out your exact commit IDs. Is that with pulseaudio or without?
10. Jiangxinx commented on May 6, 2019

    

    Jiangxinx

    on May 6, 2019

    More actions

    @lyakh I disabled pulseaudio, by the way, this issue can be reproduced by using paplay immediately if enable pulseaudio.
11. lyakh commented on May 6, 2019

    

    lyakh

    on May 6, 2019

    Collaborator

    More actions

    @Jiangxinx what command line do you use with paplay?
12. Jiangxinx commented on May 6, 2019

    

    Jiangxinx

    on May 6, 2019

    More actions

    @lyakh Just playback audio file simply: paplay audio.wav -vvvv
13. 6 remaining items

    Load more

14. mrajwa commented on May 6, 2019

    

    mrajwa

    on May 6, 2019

    More actions

    @lyakh, I saw that but it doesn't say much to me. What do you mean by "bisected"?
15. lyakh commented on May 6, 2019

    

    lyakh

    on May 6, 2019

    Collaborator

    More actions

    the first mistake with KPB is, that it's built when disabled in .config, but that's simple to fix. But maybe it's good that it was like that, otherwise we wouldn't find this bug. Or is KPB not supposed to work on BYT?
16. lyakh commented on May 6, 2019

    

    lyakh

    on May 6, 2019

    Collaborator

    More actions

    @mrajwa https://git-scm.com/docs/git-bisect
17. mrajwa commented on May 8, 2019

    

    mrajwa

    on May 8, 2019

    More actions

    @lyakh thanks, I haven't used this git feature before. Anyway, are you sure that exactly this commit causes the timeout? It barely change samples size for internal use of KPB, I can not imagine how could it affect any IPC message. Not to mention you probably don't use KPB in your topology at all, do you?

    PS: Bisect requires your judgement at the end of the day, so I feel like you spotted wrong commit.
18. lyakh commented on May 9, 2019

    

    lyakh

    on May 9, 2019

    Collaborator

    More actions

    @mrajwa no, bisect doesn't require your judgement, as long as the problem is 100% reproducible and you don't make mistakes during bisecting. Of course, such mistakes are possible, that's why usually, especially when I cannot see how the identified culprit causes the problem, I double check it: I test the tree before the identified commit and after it. So, you don't have to feel, just please, do the same - test the tree before and after that your commit.
    You are right, I'm not using KPB but KPB was built unconditionally before my recent commit, so, when checking that, if you use a recent tree, including my commit thesofproject/sof#1368 you'll have to enable KPB in the SOF configuration. But otherwise you don't need any special topology or run-time treatment.
19. mengdonglin

    added

    IPC timeoutIPC timeout observedIPC timeout observed

    on May 9, 2019
20. xun2z commented on May 16, 2019

    

    xun2z

    on May 16, 2019

    Last edited by xun2z

    More actions

    I root-caused this issue today. It seems we have some modification (2 commits) in dw-dma.c (SOF Firmware) leads to this issue. The following 2 both causes this issue.

    • dw-dma: handle interrupts per core [7275e42]
    • dw-dma: clear block/transfer irq after stop [433de9f]

    The second one is easy to understand: we have an additional process when calling stop trigger.

    So @stevyan , can you try to revert these two commits in SOF firmware and see if I'm right?
21. stevyan commented on May 17, 2019

    

    stevyan

    on May 17, 2019

    Author

    More actions

    I root-caused this issue today. It seems we have some modification (2 commits) in dw-dma.c (SOF Firmware) leads to this issue. The following 2 both causes this issue.

    • dw-dma: handle interrupts per core [7275e42]
    • dw-dma: clear block/transfer irq after stop [433de9f]

    The second one is easy to understand: we have an additional process when calling stop trigger.

    So @stevyan , can you try to revert these two commits in SOF firmware and see if I'm right?

    This issue isn't occurred after reverted those 2 commits over 300 aplay & arecord interrupted test;

    Test Recipe
    date: 2019-05-17
    sof (master): f04bc83 + reverted (7275e42, 433de9f)
    linux (topic/sof-dev): 2291b8c
    topology: sof-byt-rt5651.tplg
22. lyakh commented on May 17, 2019

    

    lyakh

    on May 17, 2019

    Collaborator

    More actions

    @xun2z thanks for tracking those commits down! Somehow I was getting very inconsistent results with my debugging, but I managed to confirm, that indeed those two commits create problems on BYT. @tlauda have you tested those your patches on BYT? I can well see how those changes make sense "in theory" for all platforms, including BYT, but in practice we get breakage. Would you agree to revert your patch for non-CONFIG_HW_LLI platforms? Again - "in theory" this isn't the correct thing to do, because HW_LLI has nothing to do with the way interrupts are processed, but it just so happens for now, that that option is only disabled on "legacy" BYT, BDW, HSW and CHT platforms. So if we revert some parts of those your patches for non-HW_LLI, I think all the platforms will work. I'll attach a proposed diff here in a couple of hours.
23. tlauda commented on May 17, 2019

    

    tlauda

    on May 17, 2019

    More actions

    @lyakh Does the following change would be OK with you?

    diff --git a/src/drivers/dw/dma.c b/src/drivers/dw/dma.c
    index fa35693..3302c76 100644
    --- a/src/drivers/dw/dma.c
    +++ b/src/drivers/dw/dma.c
    @@ -494,9 +494,6 @@ static int dw_dma_stop(struct dma *dma, int channel)
     
     	dcache_writeback_region(chan->lli,
     				sizeof(struct dw_lli) * chan->desc_count);
    -#else
    -	/* clear transfer interrupt */
    -	dw_write(dma, DW_CLEAR_TFR, DW_CHAN(channel));
     #endif
     
     	chan->status = COMP_STATE_PREPARE;
    @@ -1075,6 +1072,7 @@ static void dw_dma_irq_handler(void *data)
     	status_src = dw_read(dma, DW_STATUS_BLOCK);
     #else
     	status_src = dw_read(dma, DW_STATUS_TFR);
    +	dw_write(dma, DW_CLEAR_TFR, status_src);
     #endif
     
     	/* TODO: handle errors, just clear them atm */
    @@ -1085,6 +1083,10 @@ static void dw_dma_irq_handler(void *data)
     		dw_write(dma, DW_CLEAR_ERR, status_err);
     	}
     
    +	/* clear platform and DSP interrupt */
    +	platform_interrupt_clear(dma_irq(dma, cpu_get_id()),
    +				 status_src | status_err);
    +
     	for (i = 0; i < dma->plat_data.channels; i++) {
     		/* skip if channel is not running */
     		if (p->chan[i].status != COMP_STATE_ACTIVE)
    @@ -1102,16 +1104,10 @@ static void dw_dma_irq_handler(void *data)
     			/* clear the source of our IRQ */
     #if CONFIG_HW_LLI
     			dw_write(dma, DW_CLEAR_BLOCK, status_src & mask);
    -#else
    -			dw_write(dma, DW_CLEAR_TFR, status_src & mask);
     #endif
     			dw_dma_irq_callback(dma, i, &next, DMA_CB_TYPE_IRQ);
     		}
     	}
    -
    -	/* clear platform and DSP interrupt */
    -	platform_interrupt_clear(dma_irq(dma, cpu_get_id()),
    -				 status_src | status_err);
     }
     
     static inline int dw_dma_interrupt_register(struct dma *dma, int channel)
    
24. lyakh commented on May 17, 2019

    

    lyakh

    on May 17, 2019

    Collaborator

    More actions

    @tlauda yes, almost, but with a bit of optimisation:

    diff --git a/src/drivers/dw/dma.c b/src/drivers/dw/dma.c
    index fa35693..db75730 100644
    --- a/src/drivers/dw/dma.c
    +++ b/src/drivers/dw/dma.c
    @@ -494,9 +494,6 @@ static int dw_dma_stop(struct dma *dma, int channel)
     
     	dcache_writeback_region(chan->lli,
     				sizeof(struct dw_lli) * chan->desc_count);
    -#else
    -	/* clear transfer interrupt */
    -	dw_write(dma, DW_CLEAR_TFR, DW_CHAN(channel));
     #endif
     
     	chan->status = COMP_STATE_PREPARE;
    @@ -1070,11 +1067,20 @@ static void dw_dma_irq_handler(void *data)
     	tracev_dwdma("dw_dma_irq_handler(): dma %d IRQ status 0x%x",
     		     dma->plat_data.id, status_intr);
     
    -	/* get the source of our IRQ */
    +	/* get the source of our IRQ and clear it */
     #if CONFIG_HW_LLI
    -	status_src = dw_read(dma, DW_STATUS_BLOCK);
    +#if CONFIG_DMA_AGGREGATED_IRQ
    +	/* skip if channel is not registered on this core */
    +	mask = p->mask_irq_channels[cpu_get_id()];
    +#else
    +	mask = ~0;
    +#endif
    +
    +	status_src = dw_read(dma, DW_STATUS_BLOCK) & mask;
    +	dw_write(dma, DW_CLEAR_BLOCK, status_src);
     #else
     	status_src = dw_read(dma, DW_STATUS_TFR);
    +	dw_write(dma, DW_CLEAR_TFR, status_src);
     #endif
     
     	/* TODO: handle errors, just clear them atm */
    @@ -1085,6 +1091,10 @@ static void dw_dma_irq_handler(void *data)
     		dw_write(dma, DW_CLEAR_ERR, status_err);
     	}
     
    +	/* clear platform and DSP interrupt */
    +	platform_interrupt_clear(dma_irq(dma, cpu_get_id()),
    +				 status_src | status_err);
    +
     	for (i = 0; i < dma->plat_data.channels; i++) {
     		/* skip if channel is not running */
     		if (p->chan[i].status != COMP_STATE_ACTIVE)
    @@ -1092,26 +1102,9 @@ static void dw_dma_irq_handler(void *data)
     
     		mask = 0x1 << i;
     
    -#if CONFIG_DMA_AGGREGATED_IRQ
    -		/* skip if channel is not registered on this core */
    -		if (!(p->mask_irq_channels[cpu_get_id()] & mask))
    -			continue;
    -#endif
    -
    -		if (status_src & mask) {
    -			/* clear the source of our IRQ */
    -#if CONFIG_HW_LLI
    -			dw_write(dma, DW_CLEAR_BLOCK, status_src & mask);
    -#else
    -			dw_write(dma, DW_CLEAR_TFR, status_src & mask);
    -#endif
    +		if (status_src & mask)
     			dw_dma_irq_callback(dma, i, &next, DMA_CB_TYPE_IRQ);
    -		}
     	}
    -
    -	/* clear platform and DSP interrupt */
    -	platform_interrupt_clear(dma_irq(dma, cpu_get_id()),
    -				 status_src | status_err);
     }
     
     static inline int dw_dma_interrupt_register(struct dma *dma, int channel)
    
25. lyakh commented on May 17, 2019

    

    lyakh

    on May 17, 2019

    Collaborator

    More actions

    @tlauda that way the original order is preserved on all platforms:

    1. clear the source IRQ
    2. clear the platform IRQ
    3. call the callbacks
26. tlauda commented on May 17, 2019

    

    tlauda

    on May 17, 2019

    More actions

    @lyakh Looks great. Could you prepare the PR for the FW?
27. lyakh commented on May 17, 2019

    

    lyakh

    on May 17, 2019

    Collaborator

    More actions

    @tlauda yep, ready to push, just doing some basic smoke-testing on up2
28. lgirdwood

    closed this as completedin sof#1451on May 22, 2019