[BUG][TGLU] "error: cl_copy_fw: timeout HDA_DSP_SRAM_REG_ROM_STATUS read" when testing runtime PM

[keqiaozhang]

Describe the bug
CI detected below error when testing runtime PM:
dmesg

kernel: [ 6397.937083] sof-audio-pci 0000:00:1f.3: DSP core(s) enabled? 1 : core_mask 1
kernel: [ 6397.937646] sof-audio-pci 0000:00:1f.3: FW Poll Status: reg=0x80000000 successful
kernel: [ 6398.008897] sof-audio-pci 0000:00:1f.3: FW Poll Status: reg=0x5000001 successful
kernel: [ 6401.009420] sof-audio-pci 0000:00:1f.3: FW Poll Status: reg=0x5000001 timedout
kernel: [ 6401.009424] sof-audio-pci 0000:00:1f.3: error: cl_copy_fw: timeout HDA_DSP_SRAM_REG_ROM_STATUS read
kernel: [ 6401.009439] sof-audio-pci 0000:00:1f.3: FW Poll Status: reg=0x140000 successful
kernel: [ 6401.009450] sof-audio-pci 0000:00:1f.3: unknown ROM status value 05000001
kernel: [ 6401.009461] sof-audio-pci 0000:00:1f.3: error: status = 0x00000000 panic = 0x00000000
kernel: [ 6401.009481] sof-audio-pci 0000:00:1f.3: error: extended rom status:  0x5000001 0x0 0x0 0x0 0x0 0x0 0x25101c2 0x0
kernel: [ 6401.009491] sof-audio-pci 0000:00:1f.3: unknown ROM status value 05000001
kernel: [ 6401.009494] sof-audio-pci 0000:00:1f.3: error: load fw failed ret: -110
kernel: [ 6401.009534] sof-audio-pci 0000:00:1f.3: error: failed to reset DSP
kernel: [ 6401.009538] sof-audio-pci 0000:00:1f.3: error: failed to boot DSP firmware after resume -110
kernel: [ 6401.009551] intel-sdw intel-sdw.1: ASoC: error at snd_soc_pcm_component_pm_runtime_get on intel-sdw.1: -16
kernel: [ 6401.009557]  SDW1-Playback: ASoC: BE open failed -16
kernel: [ 6401.009562]  smart373-spk: ASoC: failed to start some BEs -16

etrace

[12772687158.489584] (             nan) c0 dma-trace             src/trace/dma-trace.c:339  ERROR FW ABI 0x3012001 DBG ABI 0x5002001 tag v1.5-rc1-987-geaa9a55d0b84 src hash 0x3be0d777 (ldc hash 0x3be0d777)
[12774108825.312500] (  1421666.875000) c0 dw-dma                 src/drivers/dw/dma.c:1101 ERROR dw_dma_get_data_size(): xrun detected
[12774108845.572918] (       20.260416) c0 dai          4.23           src/audio/dai.c:788  ERROR dai_report_xrun(): overrun due to no space available
[12774108864.687500] (       19.114584) c0 dai          4.23           src/audio/dai.c:685  ERROR comp_overrun(): sink->free = 64, copy_bytes = 0
[12774108963.593750] (       98.906250) c0 pipe         4.24      src/audio/pipeline.c:1029 ERROR pipeline_copy(): ret = -61, start->comp.id = 23, dir = 0
[12774108988.229168] (       24.635416) c0 pipe         4.24      src/audio/pipeline.c:1219 ERROR pipeline_task(): xrun recover failed! pipeline will be stopped!

To Reproduce
run "./check-runtime-pm-status.sh -l 15"

Reproduction Rate
first discovered by CI, need more tests.

Environment
Kernel Branch: topic/sof-dev
Kernel Commit: cc99fd4a
SOF Branch: master
SOF Commit: eaa9a55
2) Name of the topology file
* Topology: sof-tgl-sdw-max98373-rt5682-4ch
3) Name of the platform(s) on which the bug is observed.
* Platform: tgl chromebook Volteer

CI logs:https://sof-ci.sh.intel.com/#/result/planresultdetail/1371?model=TGLU_VOLT_SDW&testcase=check-runtime-pm-status-15

[xiulipan]

@aiChaoSONG Is this a familiar issue to you?

[aiChaoSONG]

@WYL-12 reported the same issue #3710, also reproduced in recent daily test. For me, this issue is new on volteer, but back to the previous year, I think it has reproduced on hatch/helios.

[marc-hb]

but back to the previous year, I think it has reproduced on hatch/helios.

Were some bug(s) filed?

[keqiaozhang]

This issue is caused by #3714. I checked the CI reports again and found that this issue only happens after issue #3714.
The root cause is that when #3714 happens, DSP will be in bad state. At this time, we shouldn't test the PM case directly, we need to restore or reboot the system first.

[marc-hb]

The root cause is that when #3714 happens, DSP will be in bad state.

@lgirdwood , @plbossart , how bad is the situation after #3714? Is it so bad that the DSP is not expected to handle the error and recover?

At this time, we shouldn't test the PM case directly, we need to restore or reboot the system first.

Agreed but only if what causes #3714 is so bad that the DSP is not expected to recover. Otherwise it's more complicated:

• On one one hand we want to test power management when starting from a "clean" state.
• On the other hand we ALSO want to test power management (and everything else) when starting from a "less clean" state polluted by [BUG][CI][SDW] xrun and trigger pause/release ipc error in multiple-pause-resume #3714 because we ALSO want to find error handling issues. Testing error handling is difficult (hence rarely done, hello security issues) and not rebooting between tests is an imperfect way but better than not testing error handling at all.
• Finally, we have finite resources and can't test everything.

See internal issue 541 on the same topic.

@keqiaozhang : while check-runtime-pm-status.sh fails after #3714, can any other test pass after #3714?

[keqiaozhang]

@keqiaozhang : while check-runtime-pm-status.sh fails after #3714, can any other test pass after #3714?
From the test result, runtime PM and kmod test cannot survive after #3714 . So I believe none of cases can pass after #3714.
Since the first kmod test failure will trigger system reboot to restore sof, so the following tests will back to normal.

[marc-hb]

@ranj063 , @plbossart , @lgirdwood do you agree that recovering after issue #3714 is not possible ever? If never possible then we can close this one.

[plbossart]

Yes, I think we should close this.