Repository navigation
[BUG][ADLP] ipc tx timed out for 0x60060000（TRIG_PAUSE）when testing multiple-pause-resume on ADLP Chrome device #5850
Description
Describe the bug
CI detected this issue in today's daily test ID:12812. but failed to reproduced it again. IPC timed out when TRIG_PAUSE and there're some XRUNs detected in DMA trace.
[ 4182.403813] kernel: sof-audio-pci-intel-tgl 0000:00:1f.3: pcm: trigger stream 99 dir 1 cmd 3
[ 4182.403847] kernel: sof-audio-pci-intel-tgl 0000:00:1f.3: ipc tx: 0x60060000: GLB_STREAM_MSG: TRIG_PAUSE
[ 4182.911354] kernel: sof-audio-pci-intel-tgl 0000:00:1f.3: ipc tx timed out for 0x60060000 (msg/reply size: 12/12)
[ 4182.911388] kernel: sof-audio-pci-intel-tgl 0000:00:1f.3: preventing DSP entering D3 state to preserve context
[ 4182.911396] kernel: sof-audio-pci-intel-tgl 0000:00:1f.3: ------------[ IPC dump start ]------------
[ 4182.911421] kernel: sof-audio-pci-intel-tgl 0000:00:1f.3: hda irq intsts 0x00000000 intlctl 0xc0000083 rirb 00
[ 4182.911434] kernel: sof-audio-pci-intel-tgl 0000:00:1f.3: dsp irq ppsts 0x00000000 adspis 0x00000000
[ 4182.911455] kernel: sof-audio-pci-intel-tgl 0000:00:1f.3: error: host status 0x00000000 dsp status 0x00000000 mask 0x00000003
[ 4182.911464] kernel: sof-audio-pci-intel-tgl 0000:00:1f.3: ------------[ IPC dump end ]------------
[ 4182.911473] kernel: sof-audio-pci-intel-tgl 0000:00:1f.3: ------------[ DSP dump start ]------------
[ 4182.911480] kernel: sof-audio-pci-intel-tgl 0000:00:1f.3: IPC timeout
[ 4182.911488] kernel: sof-audio-pci-intel-tgl 0000:00:1f.3: fw_state: SOF_FW_BOOT_COMPLETE (6)
[ 4182.911508] kernel: sof-audio-pci-intel-tgl 0000:00:1f.3: status: fw entered - code 00000005
[ 4182.911646] kernel: sof-audio-pci-intel-tgl 0000:00:1f.3: unexpected fault 0x00000000 trace 0x00004000
[ 4182.911658] kernel: sof-audio-pci-intel-tgl 0000:00:1f.3: ------------[ DSP dump end ]------------
DMA-trace
[ 2482386.099276] ( 23.229166) c1 dmic-dai 2.0 ....../intel/dmic/dmic.c:418 INFO dmic_stop(), dmic_active_fifos_mask = 0x1
[ 2482423.026357] ( 28.281248) c1 zll-schedule src/schedule/zephyr_ll.c:69 INFO task complete 0xbe093a00 pipe-task [ 2482394.745108] ( 8.645833) c0 hda-dma ..../intel/hda/hda-dma.c:948 ERROR hda_dma_link_check_xrun(): underrun detected
[ 2482443.234690] ( 20.208332) c1 zll-schedule src/schedule/zephyr_ll.c:71 INFO num_tasks 2 total_num_tasks 4
[ 2482462.661772] ( 19.427082) c1 zll-schedule src/schedule/zephyr_ll.c:69 INFO task complete 0x9e087808 dmic-work <59c87728-d8f9-42f6-b89d-5870a87b0e1e>
[ 2482479.745105] ( 17.083332) c1 zll-schedule src/schedule/zephyr_ll.c:71 INFO num_tasks 1 total_num_tasks 3
[ 2482500.213854] ( 20.468750) c1 zll-schedule ......../zephyr_domain.c:210 INFO zephyr_domain_unregister domain->type 1 domain->clk 4
[ 2491369.744752] ( 8869.531250) c0 ipc src/ipc/ipc3/handler.c:1605 INFO ipc: new cmd 0x60060000
[ 2491403.807251] ( 34.062500) c0 pipe 8.43 ....../pipeline-stream.c:270 INFO pipe trigger cmd 2
[ 2492383.703045] ( 979.895813) c0 zll-schedule src/schedule/zephyr_ll.c:69 INFO task complete 0xbe093f80 pipe-task
[ 2492402.817627] ( 19.114582) c0 zll-schedule src/schedule/zephyr_ll.c:71 INFO num_tasks 2 total_num_tasks 2
[ 2492844.119693] ( 441.302063) c0 ipc src/ipc/ipc3/handler.c:1605 INFO ipc: new cmd 0x80010000
[ 2492873.338442] ( 29.218748) c0 ipc src/ipc/ipc3/handler.c:595 INFO ipc: dai 3.3 -> config
[ 2492894.484275] ( 21.145832) c0 dai src/lib/dai.c:166 INFO dai_get type 3 index 3 new sref 2
[ 2492915.161357] ( 20.677082) c0 hda-dai 3.3 /drivers/intel/hda/hda.c:42 INFO hda_set_config(): channels 2 rate 48000
[ 2492935.421773] ( 20.260416) c0 dai src/lib/dai.c:190 INFO dai_put type 3 index 3 new sref 1
[ 2492955.890522] ( 20.468750) c0 ipc src/ipc/ipc3/dai.c:185 INFO ipc_comp_dai_config() dai type = 3 index = 3
[ 2492996.567604] ( 40.677082) c0 dai 8.42 src/ipc/ipc3/dai.c:279 INFO dai_config() dai type = 3 index = 3 dd 0x9e089680
[ 2493123.755099] ( 127.187492) c1 ipc src/ipc/ipc3/handler.c:595 INFO ipc: dai 3.3 -> config
[ 2493144.223848] ( 20.468750) c1 ipc src/ipc/ipc3/dai.c:185 INFO ipc_comp_dai_config() dai type = 3 index = 3
[ 2494861.255030] ( 1717.031128) c0 ipc src/ipc/ipc3/handler.c:1605 INFO ipc: new cmd 0x60070000
[ 2494895.213362] ( 33.958332) c0 pipe 8.43 ....../pipeline-stream.c:270 INFO pipe trigger cmd 8
[ 2494923.702944] ( 28.489582) c0 zll-schedule src/schedule/zephyr_ll.c:289 INFO task add 0xbe093f80 pipe-task priority 0 flags 0x0
[ 2528776.149515] ( 140.312500) c0 ipc src/ipc/ipc3/handler.c:1605 INFO ipc: new cmd 0x60070000
[ 2528870.784928] ( 94.635414) c1 pipe 10.51 ....../pipeline-stream.c:270 INFO pipe trigger cmd 8
[ 2528907.034927] ( 36.250000) c1 zll-schedule src/schedule/zephyr_ll.c:289 INFO task add 0xbe093a00 pipe-task
[ 2512452.452247] ( 17528.750000) c0 hda-dma ..../intel/hda/hda-dma.c:948 ERROR hda_dma_link_check_xrun(): underrun detected
[ 2514490.525083] ( 2038.072876) c0 hda-dma ..../intel/hda/hda-dma.c:948 ERROR hda_dma_link_check_xrun(): underrun detected
[ 2516491.983337] ( 2001.458252) c0 hda-dma ..../intel/hda/hda-dma.c:948 ERROR hda_dma_link_check_xrun(): underrun detected
[ 2528635.837021] ( 12143.853516) c0 hda-dma ..../intel/hda/hda-dma.c:948 ERROR hda_dma_link_check_xrun(): underrun detected priority 0 flags 0x0
[ 2528945.524509] ( 38.489582) c1 zll-schedule ......../zephyr_domain.c:180 INFO zephyr_domain_register domain->type 1 domain->clk 4 domain->ticks_per_ms 38400 period 1000
To Reproduce
~/sof-test/test-case/multiple-pause-resume.sh -r 50
Reproduction Rate
This issue is reproducible. I reproduced this issue once in 5 rounds of tests.
Environment
Kernel Branch: topic/sof-dev
Kernel Commit: 0b48f05d38c9
SOF Branch: main
SOF Commit: 9611d12
Zephyr Commit:
70dbf7e695d2
TPLG:sof-adl-max98390-rt5682.tplg
Platform: ADLP Chrome device Gimble-I2S with Zephyr.
Activity
lgirdwood commentedon May 25, 2022
@keqiaozhang can you turn on Zephyr lock debugging and try again (Zephyr KCONFIG). @lyakh I assume this is correct method to enable Zephyr lock debug ?
keqiaozhang commentedon May 25, 2022
Before trying Zephyr lock debugging. I did more tests this afternoon.
First this issue is reproducible, I tested with 9611d12 and hit this issue twice in 10 rounds of
multiple-pause-resume.sh -r 50.Then I tested this cases ten times with the old commit f3ec2e5, no reproductions.
It seems that this issue was introduced by 9611d12.
But this does not rule out that this issue has nothing to do with zephyr, because zephyr has been updated accordingly.
I will check the last stable zephyr commit with sof f3ec2e5 next.
lgirdwood commentedon May 25, 2022
This is an optimization that make the pipeline run faster so we could be exposing a race.
@andrula-song can you fix the following
Locks should be acquired and released symmetrically. @keqiaozhang can you try again with the suggested change and then again with the lock debug.
andrula-song commentedon May 26, 2022
@lgirdwood @keqiaozhang Use new PR #5857 to track this bug.
keqiaozhang commentedon May 26, 2022
@lgirdwood and @andrula-song
Confirmed that PR #5857 can fix this issue. 15 rounds of test passed(
~/sof-test/test-case/multiple-pause-resume.sh -r 50). It took about 4 and a half hours.lyakh commentedon May 27, 2022
@keqiaozhang @lgirdwood yes, just enable
CONFIG_ASSERTthenCONFIG_SPIN_VALIDATEwill be enabled automatically toolyakh commentedon May 27, 2022
@lgirdwood @andrula-song Interesting. Locking and unlocking only takes place if the object is shared, which in this case should mean, if the buffer is connecting two pipelines, running on different cores. And AFAICS sof-tgl-sdw-max98373-rt5682.m4 has everything on core 0. So, this must be something different...
keqiaozhang commentedon May 30, 2022
Bad news, this issue still can be reproduced with the tip main branch. a7b2b29.
It seems that #5857 doesn't really fix the problem.
lyakh commentedon May 30, 2022
exactly. As my previous comment says - this doesn't appear related to me.
kv2019i commentedon May 30, 2022
I'd propose a P2 priority just to help order bugfixing work. I tried to locally reproduce this and it seems this takes multiple hours to trigger, so it seems P2. Please increase/decrease based on rate of occurence.
keqiaozhang commentedon Jun 9, 2022
Found another IPC timed out issue for 0x60040000 (TRIG_START) when testing multiple-pipeline-playback. Test report ID:http://sof-ci.sh.intel.com/#/result/planresultdetail/13207
[Edit]: I tried to reproduce it manually, 1000+ iterations passed, no reproductions so far.
dmesg
(dump from journalctl):
logger
logger.txt
kv2019i commentedon Jun 9, 2022
@keqiaozhang It would be good to get output of "sudo cat /sys/kernel/debug/sof/etrace" (or run "sudo cavstool.py -l" during the test). The sof-logger output doesn't show what happens around the error and it is possible the DSP hits a fatal error (and sof-logger stops working when this happens). The "etrace" file would show what has happened.
keqiaozhang commentedon Jun 9, 2022
Here are the logs I captured for IPC timed out 0x60040000 (TRIG_START):
etrace
$ sudo cat /sys/kernel/debug/sof/etrace
cavstool
dmesg
kv2019i commentedon Jun 9, 2022
Thanks @keqiaozhang . So there's no fatal errors from the OS in etrace, so this is something in the audio/IPC logic.
marc-hb commentedon Jun 10, 2022
There is thesofproject/sof-test#897 but I just confirmed
cavstool.pyis not compatible with D3. Off-topic here, discuss in thesofproject/sof-test#897miRoox commentedon Jun 27, 2022
Another IPC timed out issue for 0x80010000 (CONFIG) when testing multiple-pause-resume on ADLP_GMB_I2S is found in daily test (ID: 13547):
dmesg
full_dmesg.txt
keqiaozhang commentedon Aug 11, 2022
CI detected this issue on ADLP_RVP_NOCODEC:
http://sof-ci.sh.intel.com/#/result/planresultdetail/14549?model=ADLP_RVP_NOCODEC&testcase=multiple-pause-resume-50
etrace
dmesg
lyakh commentedon Aug 19, 2022
A similar failure on the same platform again in daily test Nr. 14634
lyakh commentedon Aug 22, 2022
@keqiaozhang sorry, I'm looking at 13207 and not seeing those IPC timeouts that you pasted here, are you sure it wasn't a different test? In that test I do see a multiple-pipeline-playback TIMEOUT failure on ADLP_GMB_I2S_ZEPHYR, but no IPC timeouts. However, there's also a check-sof-logger failure there with an IPC timeout for DMA_PARAMS_EXT, i.e. a failure to load the firmware.
keqiaozhang commentedon Sep 19, 2022
@fredoh9 have you seen this issue in recent tests? If no, I think we can close this one.
fredoh9 commentedon Oct 12, 2022
For past month I couldn't find same issue with stable-v2.2 branch.