Repository navigation
Stress test : keeping pressing space key when playback and capture at the same time causes ipc timed out. #210
Description
This issue exists on apl and cnl.
Environment:
on up^2 using gcc
sof-v4.14: 14d7f16ce31d27f9171368ef0bfbbf00f6f160d4
sof: 31d8aa4
soft: 91bb08d
tplg: sof-apl-nocodec.tplg
reproduce steps:
- aplay -Dhw:0,0 -fS16_LE -c 2 -r 48000 /dev/zero & arecord -Dhw:0,6 -f S32_LE -r 48000 -c 2 dmic.wav -vv -i
- keep pressing space key
log:
dmesg.log
memorywindow.log
rmbox.log
Environment:
on up^2 using gcc
sof-dev: 82009079505a086987500df352b33bb600964dcc
sof: 31d8aa4
soft: 91bb08d
tplg: sof-apl-nocodec.tplg
reproduce steps:
- aplay -Dhw:0,0 -fS16_LE -c 2 -r 48000 /dev/zero & arecord -Dhw:0,6 -f S32_LE -r 48000 -c 2 dmic.wav -vv -i
- keep pressing space key until input/output error then ctrt+c
- repeat step2 several times
Environment:
on cannonlake using gcc
sof-dev: 82009079505a086987500df352b33bb600964dcc
sof: 31d8aa4
soft: 91bb08d
tplg: test-ssp0-mclk-0-I2S-volume-s16le-s16le-48k-24000k-nocodec.tplg
reproduce steps:
- aplay -Dhw:0,0 -fS16_LE -c 2 -r 48000 /dev/zero & arecord -Dhw:0,0 -f S16_LE -r 48000 -c 2 test.wav -vv -i
- keep pressing space key until input/output error then ctrt+c
- repeat step2 several times
Activity
lgirdwood commentedon Aug 8, 2018
@RanderWang this is kernel bug related to IPC serialization.
plbossart commentedon Aug 9, 2018
Agree with @lgirdwood, there's definitively something fishy about IPCs (could be missing some interrupts since the code doesn't always use spin_lock_irqsave
xiulipan commentedon Aug 15, 2018
@lgirdwood @plbossart
I found that we may have some error inside the firmware.
When I reproduced one IPC timeout and dig into the trace, I found that the DSP come to alive after few mintes.
Here is the demsg logged the back to live DSP.
The DSP got into hang in 60s, and suddenly got back to live at 204s with a interrupt from
CAPTURE stream from function
irqreturn_t hda_dsp_stream_threaded_handler(int irq, void *context)It seems we have some error with our capture stream.
lgirdwood commentedon Aug 15, 2018
@xiulipan so you mean that FW blocks/spins/sleeps on something for 144s and then returns to normal ?
The capture IRQ is probably freeing a resource/lock ?
Might be worth adding some debug to IPC IRQ handler in FW to trace each message received. That way you can check if IPC IRQ is received for timeout message and work from there. Remeber IPC message is recived at IRQ level 2 but processed later on at level 0 (so can be pre-emptied).
xiulipan commentedon Aug 16, 2018
@lgirdwood
I am not sure about that. This bug is totally random and hard to reproduce if you add some log.
I will try to analysis the pattern like you said.
I still could not tell if the final TRIGGER_STOP ipc cause the DSP hang or the DSP hang make the ALSA send a STOP to DSP. I think it should be the DSP in hang first and no IPC message could be received then. I will have some log to figure this first as you recommend.
23 remaining items
RanderWang commentedon Aug 31, 2018
@lgirdwood @tlauda @xiulipan
Hi all, I don't think the deadloop is the root reason of this bug. It is a issue but never happen in normal case. It is caused by my change. I scheduled the pipe after ipc timeout.
I add many logs and confirm it is still caused by dai interrupt missing. I tuned my test case and made the IPC timeout at a fix point. The following is the fixed log.
0x0 [3.111575] delta [3.111575] ipc Pen
0x10 [5.678263] delta [2.566688] pipe run
0x20 [5.678267] delta [0.000003] pipe ept
0x30 [5.678268] delta [0.000001] pipe pxr // playback XRUN recovery
0x40 [5.678288] delta [0.000020] dma DDi
0x50 [5.678294] delta [0.000005] dai xrc //capture interrupt
0x60 [5.678299] delta [0.000006] pipe run
0x70 [5.678429] delta [0.000130] pipe fxr // playback XRUN recovery successfully
0x80 [5.678431] delta [0.000002] pipe stc
0x90 [5.678433] delta [0.000001] pipe ept
0xa0 [5.678474] delta [0.000041] pipe epe
0xb0 [5.678476] delta [0.000002] pipe stc
0xc0 [5.678483] delta [0.000007] pipe twk
0xd0 [5.679289] delta [0.000806] dai xrc //capture interrupt
0xe0 [5.679295] delta [0.000006] pipe run
0xf0 [5.679299] delta [0.000004] pipe ept
0x100 [5.679342] delta [0.000043] dai xrp //playback interrupt
0x110 [5.679347] delta [0.000005] pipe run
0x120 [5.679352] delta [0.000005] pipe epe
0x130 [5.679353] delta [0.000002] pipe stc
0x140 [5.679355] delta [0.000001] pipe ept
0x150 [5.679396] delta [0.000041] pipe epe
0x160 [5.679398] delta [0.000002] pipe stc
0x170 [5.679399] delta [0.000002] pipe tsk // _irq_task complete
// no more interrupt
And if I add code at the end of the in _irq_task to check the DMA engine
for(...)
trace_error_value(dw_read(dma, DW_SAR(0)));
trace_error_value(dw_read(dma+1, DW_DAR(1)));
more DMA irq would come.
0x170 [84.430771] delta [0.000002] pipe stc
0x180 [84.430773] delta [0.000002] ipc tsk
0x190 [84.430894] delta [0.000121] value 0x00000000be001324
0x1a0 [84.430896] delta [0.000001] value 0x00000000be00206c
0x1b0 [84.431017] delta [0.000121] value 0x00000000be00133c
0x1c0 [84.431018] delta [0.000001] value 0x00000000be002084
0x1d0 [84.431140] delta [0.000121] value 0x00000000be001350
0x1e0 [84.431141] delta [0.000001] value 0x00000000be00209c
0x1f0 [84.431262] delta [0.000121] value 0x00000000be001368
0x200 [84.431264] delta [0.000001] value 0x00000000be0020b0
0x210 [84.431385] delta [0.000121] value 0x00000000be00137c
0x220 [84.431386] delta [0.000001] value 0x00000000be0020c8
0x230 [84.431508] delta [0.000121] value 0x00000000be00137c
0x240 [84.431509] delta [0.000001] value 0x00000000be0020e0
0x250 [84.431630] delta [0.000121] value 0x00000000be00137c
0x260 [84.431632] delta [0.000001] value 0x00000000be0020f8
0x270 [84.431662] delta [0.000030] dai xrc
0x280 [84.431667] delta [0.000005] pipe run
0x290 [84.431706] delta [0.000039] dai xrp
0x2a0 [84.431712] delta [0.000005] pipe run
0x2b0 [84.431774] delta [0.000062] value 0x00000000be00124c
0x2c0 [84.431775] delta [0.000001] value 0x00000000be001f94
0x2d0 [84.431897] delta [0.000122] value 0x00000000be001264
0x2e0 [84.431898] delta [0.000001] value 0x00000000be001fac
0x2f0 [84.432019] delta [0.000121] value 0x00000000be00127c
0x300 [84.432021] delta [0.000001] value 0x00000000be001fc4
0x310 [84.432022] delta [0.000002] pipe ept
0x320 [84.432064] delta [0.000042] pipe epe
0x330 [84.432066] delta [0.000002] pipe stc
0x340 [84.432067] delta [0.000001] pipe ept
0x350 [84.432108] delta [0.000041] pipe epe
0x360 [84.432110] delta [0.000002] pipe stc
And FW again stop after pipe scheduled.
So it seems that DMA interrupt is blocked by something. I confirmed that the interrupt status is ok.
And I can trigger ssp interrupt and schedule interrupt after FW stop.
Actually, it is very difficult to reproduce this issue. Sometimes you need to wait a long time to get the bug. And when you add some logs to get FW info , the issue cant be reproduced.
lgirdwood commentedon Aug 31, 2018
@RanderWang Scheduler, workQ and DMA are all level 5 interrupts, meaning they cannot pre-empt each other. e.g if scheduler is running then DMA IRQ will not get services until scheduler IRQ completes. Please align with @xiulipan and mkae sure you also have latest scheduler & task testing updates.
RanderWang commentedon Aug 31, 2018
@lgirdwood but IRQ_task run on lower level than dma interrupt ? I also check the SSP setting when IPC timeout. all the ssp registers are correct. And I check the output of I2S pin, both bit clock and sync clock are
correct. And ssp is also a level 5 interrupt. If I set sss register to test ssp interrupt when ipc timeout, dma interrupt is triggered every 2us. So I don't know why so many dma interrupts when I test ssp interrupt
lgirdwood commentedon Aug 31, 2018
@RanderWang irq_task can run at multiple levels and is platform dependent. If the IRQ task priority < scheduler/workQ then it can be preempted. If you are seeing DMA irqs every 2us then the DMA irq is not being cleared. Please update with @xiulipan as there is a race that causes list corruption, leading to potential execution of random code (and hence you may never clear DMA IRQ).
RanderWang commentedon Sep 3, 2018
@lgirdwood @tlauda
fix by #292
ZhendanYang commentedon Sep 7, 2018
This issue can't be reproduced on APL and CNL with stable-1.2 branch(commit 251e68f).
xiulipan commentedon Sep 13, 2018
APL fixed with #367 #368 on master branch
Still need scheduler and task fix
ZhendanYang commentedon Sep 14, 2018
Latest status:
Test with stable 1.2 branch, APL and CNL have no such issue.
Test with master branch, on APL, there has DSP panic:
[ 707.987916] sof-audio sof-audio: error : DSP panic!
[ 707.987924] sof-audio sof-audio: panic: dsp_oops_offset 788480 offset 788480
[ 707.987928] sof-audio sof-audio: status: fw entered - code 00000005
[ 707.987949] sof-audio sof-audio: error: runtime exception
[ 707.987952] sof-audio sof-audio: error: trace point 00004000
[ 707.987955] sof-audio sof-audio: error: DSP Firmware Oops
[ 707.987958] sof-audio sof-audio: error: Exception Cause: LoadStorePIFDataErrorCause, Synchronous PIF data error during LoadStore access
[ 707.987961] sof-audio sof-audio: EXCCAUSE 0x0000000d EXCVADDR 0x00000028 PS 0x00070025 SAR 0x00000019
[ 707.987963] sof-audio sof-audio: EPC1 0xbe01cb86 EPC2 0xbe010d11 EPC3 0xbe0122bd EPC4 0x00000000
[ 707.987966] sof-audio sof-audio: EPC5 0xbe010d11 EPC6 0x00000000 EPC7 0x00000000 DEPC 0x00000000
[ 707.987969] sof-audio sof-audio: EPS2 0x00060720 EPS3 0x00060022 EPS4 0x00000000 EPS5 0x00060720
[ 707.987971] sof-audio sof-audio: EPS6 0x00000000 EPS7 0x00000000 INTENABL 0x000101d8 INTERRU 0x00000222
[ 707.987974] sof-audio sof-audio: stack dump from 0xbe07fd50
dmesg.log
rmbox.log
rmbox-t.log
Test with stable1.2, on CNL, there has input/output error, no ipc timeout, no DSP panic, and can recover itself.
Test env:
kernel: sof-dev ae5f868
sof: matster f17abe6
stable 1.2 f7ea2e6
soft: d77beaf