[BUG] timeout on STREAM_SD_OFFSET read when suspend-resume on CML Helios

[XiaoyunWu6666]

Describe the bug
timeout on STREAM_SD_OFFSET read when suspend-resume on CML
inner daily /5515?model=CML_HEL_RT5682&testcase=check-suspend-resume-with-capture-5
To Reproduce

TPLG=/lib/firmware/intel/sof-tplg/sof-cml-rt1011-rt5682.tplg  \
 sof-test/test-case/check-suspend-resume-with-audio.sh -S 1 -w 3 -l 300 -m capture

-S 1 -w 3 save some time while preserving an acceptable ssh experience. For faster reproduction on a local system try -S 1 -w 1?

-m capture is critical: -m playback never reproduced even after 100 iterations.

Environment
Start Time: 2021-07-26 21:24:47 UTC
End Time: 2021-07-27 04:58:29 UTC
Kernel Branch: topic/sof-dev
Kernel Commit: 2113dc7f
SOF Branch: main
SOF Commit: 57ee04f
Topology:sof-cml-rt1011-rt5682.tplg
Platform:CML_HEL_RT5682

Screenshots or console output
[console]

2021-07-26 23:04:00 UTC Sub-Test: [REMOTE_INFO] ===== Round(2/5) =====
2021-07-26 23:04:00 UTC Sub-Test: [REMOTE_COMMAND] Run the command: rtcwake -m mem -s 5
rtcwake: assuming RTC uses UTC ...
rtcwake: wakeup from "mem" using /dev/rtc0 at Mon Jul 26 23:04:07 2021
2021-07-26 23:04:10 UTC Sub-Test: [REMOTE_COMMAND] sleep for 5
arecord: suspend:1691: suspend: prepare error: Connection timed out
2021-07-26 23:04:15 UTC Sub-Test: [REMOTE_INFO] Check for the kernel log status
declare -- cmd="journalctl_cmd --since=@1627340635"
2021-07-26 23:04:15 UTC [ERROR] Caught kernel log error
===========================>>
[ 5378.823476] kernel: sof-audio-pci-intel-cnl 0000:00:1f.3: error: hda_dsp_stream_trigger: cmd 5: timeout on STREAM_SD_OFFSET read
[ 5382.615214] kernel: sof-audio-pci-intel-cnl 0000:00:1f.3: error: cl_copy_fw: timeout HDA_DSP_SRAM_REG_ROM_STATUS read
[ 5382.616259] kernel: sof-audio-pci-intel-cnl 0000:00:1f.3: error: hda_dsp_stream_trigger: cmd 0: timeout on STREAM_SD_OFFSET read
[ 5382.616266] kernel: sof-audio-pci-intel-cnl 0000:00:1f.3: error: DMA trigger stop failed
[ 5382.616272] kernel: sof-audio-pci-intel-cnl 0000:00:1f.3: ------------[ DSP dump start ]------------
[ 5382.616305] kernel: sof-audio-pci-intel-cnl 0000:00:1f.3: error: extended rom status:  0x5000001 0x0 0x0 0x0 0x0 0x0 0x1811102 0x0
[ 5382.616311] kernel: sof-audio-pci-intel-cnl 0000:00:1f.3: ------------[ DSP dump end ]------------
[ 5382.616315] kernel: sof-audio-pci-intel-cnl 0000:00:1f.3: error: load fw failed ret: -110
[ 5382.616373] kernel: sof-audio-pci-intel-cnl 0000:00:1f.3: error: failed to start DSP
[ 5382.616378] kernel: sof-audio-pci-intel-cnl 0000:00:1f.3: error: failed to boot DSP firmware after resume -110
[ 5382.616382] kernel: PM: dpm_run_callback(): pci_pm_resume+0x0/0x80 returns -110
[ 5382.616513] kernel: sof-audio-pci-intel-cnl 0000:00:1f.3: PM: failed to resume async: error -110
[ 5383.132839] kernel: sof-audio-pci-intel-cnl 0000:00:1f.3: error: ipc timed out for 0x30100000 size 48
[ 5383.132909] kernel: sof-audio-pci-intel-cnl 0000:00:1f.3: ------------[ IPC dump start ]------------
[ 5383.132967] kernel: sof-audio-pci-intel-cnl 0000:00:1f.3: error: hda irq intsts 0x00000000 intlctl 0x00001388 rirb 00
[ 5383.133019] kernel: sof-audio-pci-intel-cnl 0000:00:1f.3: error: dsp irq ppsts 0x00000000 adspis 0x00000003
[ 5383.133077] kernel: sof-audio-pci-intel-cnl 0000:00:1f.3: error: host status 0x00000000 dsp status 0x00040000 mask 0x00000000
[ 5383.133131] kernel: sof-audio-pci-intel-cnl 0000:00:1f.3: ------------[ IPC dump end ]------------
[ 5383.133175] kernel: sof-audio-pci-intel-cnl 0000:00:1f.3: error: load pipeline ipc failure
[ 5383.133216] kernel: sof-audio-pci-intel-cnl 0000:00:1f.3: error: failed to load widget PIPELINE.11.DMIC1.IN
[ 5383.133264] kernel: sof-audio-pci-intel-cnl 0000:00:1f.3: error: failed widget list set up for pcm 7 dir 1
[ 5383.133313] kernel: sof-audio-pci-intel-cnl 0000:00:1f.3: error: set pcm hw_params after resume
[ 5383.133356] kernel: sof-audio-pci-intel-cnl 0000:00:1f.3: ASoC: error at snd_soc_pcm_component_prepare on 0000:00:1f.3: -110
[ 5383.133496] kernel:  DMIC16kHz: ASoC: soc_pcm_prepare() failed (-110)
[ 5383.133535] kernel:  DMIC16kHz: ASoC: dpcm_fe_dai_prepare() failed (-110)
<<===========================

[plbossart]

@slawblauciak what makes you think it's a kernel issue? There's nothing that changed recently.

@lgirdwood Can you please look into this?

[plbossart]

@XiaoyunWu6666 The same problem affects other CML devices, it's not just CML_HEL_RT5682

http://sof-ci.sh.intel.com/#/result/planresultdetail/5515?model=CML_SKU0983_SDW&testcase=check-suspend-resume-with-capture-5

http://sof-ci.sh.intel.com/#/result/planresultdetail/5515?model=CML_SKU0955_HDA&testcase=check-suspend-resume-with-capture-5

It's an across-the-board problem for all CML devices using I2S/HDAudio or SoundWire links. That's very very suspicious.

[plbossart]

Reproduced in 10 iterations on CML SKU 09C6 (same as 0983)

2021-07-27 15:30:35 UTC Sub-Test: [INFO] ===== Round(10/50) =====
2021-07-27 15:30:35 UTC Sub-Test: [COMMAND] Run the command: rtcwake -m mem -s 5
rtcwake: assuming RTC uses UTC ...
rtcwake: wakeup from "mem" using /dev/rtc0 at Tue Jul 27 15:30:40 2021
2021-07-27 15:31:01 UTC Sub-Test: [COMMAND] sleep for 5
arecord: suspend:1716: suspend: prepare error: Connection timed out
2021-07-27 15:31:04 UTC Sub-Test: [INFO] Check for the kernel log status
declare -- cmd="journalctl_cmd --since=@1627399830"
2021-07-27 15:31:04 UTC [ERROR] Caught kernel log error
===========================>>
[  516.464381] kernel: sof-audio-pci-intel-cnl 0000:00:1f.3: error: hda_dsp_stream_trigger: cmd 5: timeout on STREAM_SD_OFFSET read
[  525.418163] kernel: sof-audio-pci-intel-cnl 0000:00:1f.3: error: cl_copy_fw: timeout HDA_DSP_SRAM_REG_ROM_STATUS read
[  525.418556] kernel: sof-audio-pci-intel-cnl 0000:00:1f.3: error: hda_dsp_stream_trigger: cmd 0: timeout on STREAM_SD_OFFSET read
[  525.418565] kernel: sof-audio-pci-intel-cnl 0000:00:1f.3: error: DMA trigger stop failed
[  525.418571] kernel: sof-audio-pci-intel-cnl 0000:00:1f.3: ------------[ DSP dump start ]------------
[  525.418598] kernel: sof-audio-pci-intel-cnl 0000:00:1f.3: error: extended rom status:  0x5000001 0x0 0x0 0x0 0x0 0x0 0x1811102 0x0
[  525.418604] kernel: sof-audio-pci-intel-cnl 0000:00:1f.3: ------------[ DSP dump end ]------------
[  525.418609] kernel: sof-audio-pci-intel-cnl 0000:00:1f.3: error: load fw failed ret: -110
[  525.418661] kernel: sof-audio-pci-intel-cnl 0000:00:1f.3: error: failed to start DSP
[  525.418667] kernel: sof-audio-pci-intel-cnl 0000:00:1f.3: error: failed to boot DSP firmware after resume -110
[  525.418673] kernel: PM: dpm_run_callback(): pci_pm_resume+0x0/0x80 returns -110
[  525.418703] kernel: sof-audio-pci-intel-cnl 0000:00:1f.3: PM: failed to resume async: error -110
[  525.419950] kernel: soundwire_intel soundwire_intel.link.0: Failed to power up link: -11
[  530.922894] kernel: rt711 sdw:0:025d:0711:00: Initialization not complete, timed out
[  530.922909] kernel: PM: dpm_run_callback(): acpi_subsys_resume+0x0/0x70 returns -110

kernel SHA1: 85bfa34a88d6
SOF SHA1: 9a7a5ce (HEAD -> main, origin/main) pipeline: trigger START from the task context

[plbossart]

0def9056300a4b23d909ba0b36256087af91d2fe is the first bad commit
commit 0def9056300a4b23d909ba0b36256087af91d2fe
Author: Marc Herbert <marc.herbert@intel.com>
Date:   Fri Jul 16 08:00:02 2021 +0000

    trace: move CONFIG_TRACEM implementation up a couple levels
    
    From deep down trace.c:va_tracelog() up to the _log_message() level.
    
    Also rename va_tracelog() to the more specific dma_tracelog()
    
    Preparation to support the DMA trace in Zephyr.
    
    The only functional change in this commit is that DMA messages copied to
    the shared memory are not de-duplicated any more (a.k.a "adaptive rate
    limiting" or CONFIG_TRACE_FILTERING_ADAPTIVE). These are generally
    supposed to be high level hence rare enough; otherwise there is probably
    a "bigger problem".
    
    Signed-off-by: Marc Herbert <marc.herbert@intel.com>

 src/include/sof/trace/trace.h  | 28 +++++++++++++---
 src/trace/trace.c              | 72 ++++++++++++++++++++----------------------
 test/cmocka/src/common_mocks.c | 10 +++++-
 3 files changed, 67 insertions(+), 43 deletions(-)


git bisect log
git bisect start
# bad: [9a7a5ce17dcb339e3fd667c8f12dd50db13afe31] pipeline: trigger START from the task context
git bisect bad 9a7a5ce17dcb339e3fd667c8f12dd50db13afe31
# good: [9648fb65a5b8b86707e0a160efa992f3f3c97f59] alloc: fix heap_trace() block start index
git bisect good 9648fb65a5b8b86707e0a160efa992f3f3c97f59
# good: [b1c9e858969bf022b0b3f908ca5539548405934e] zephyr_ll.c: declare missing ll_tr trace context
git bisect good b1c9e858969bf022b0b3f908ca5539548405934e
# bad: [b96077cde05cb512ab0cfc1fa8ccf933e5f25b25] zephyr: intel: remove zephyr_ll from mandatory files
git bisect bad b96077cde05cb512ab0cfc1fa8ccf933e5f25b25
# good: [e1aa806d5c6679d93da9d6a6f024d0e504ee6353] trace: add 'atomic' argument to mtrace_dict_entry()
git bisect good e1aa806d5c6679d93da9d6a6f024d0e504ee6353
# bad: [57ee04f2d9312968a8e11fd916195bbacd667180] trace: add _log_nodict() and enable DMA trace for Zephyr
git bisect bad 57ee04f2d9312968a8e11fd916195bbacd667180
# bad: [0def9056300a4b23d909ba0b36256087af91d2fe] trace: move CONFIG_TRACEM implementation up a couple levels
git bisect bad 0def9056300a4b23d909ba0b36256087af91d2fe
# first bad commit: [0def9056300a4b23d909ba0b36256087af91d2fe] trace: move CONFIG_TRACEM implementation up a couple levels

[plbossart]

@XiaoyunWu6666 @marc-hb @fredoh9 @bardliao I would appreciate it if you can try to reproduce the issue on a CML device. My results show that there is a firmware regression since I don't see any issue with the latest kernel/older firmware.

More details for the record - @lgirdwood FYI
test 5515 on July 27 - BAD
Kernel Commit: 2113dc7f
SOF Commit: 57ee04f

test 5464 July 26 GOOD
Kernel Commit: d54b7803
SOF Commit: 9648fb6

so basically I bisected from yesterday's tested SOF commit
good: [9648fb6] alloc: fix heap_trace() block start index
until today's HEAD
bad: [9a7a5ce] pipeline: trigger START from the task context

[lgirdwood]

@plbossart thanks for bisect , can you confirm if the trace patch or the pipeline patch is bad ?

[plbossart]

I don't understand the question @lgirdwood. My tests show what the first bad commit was, I don't know if the last patches on pipelines are correct or not. It could also be that my 'good' tests are 'green failures', and the issue happens with an earlier commit.

[lgirdwood]

Sorry, was not clear. I mean is the bisect clear cut or vague - I agree though this is a FW issue.

0def9056300a4b23d909ba0b36256087af91d2fe is the first bad commit
commit 0def9056300a4b23d909ba0b36256087af91d2fe
Author: Marc Herbert <marc.herbert@intel.com>
Date:   Fri Jul 16 08:00:02 2021 +0000

OR

so basically I bisected from yesterday's tested SOF commit
good: [9648fb65a5b8b86707e0a160efa992f3f3c97f59] alloc: fix heap_trace() block start index
until today's HEAD
bad: [9a7a5ce17dcb339e3fd667c8f12dd50db13afe31] pipeline: trigger START from the task context

I guess what you are saying it could be either above two commits (and needs further investigation) ?

[plbossart]

no, I am saying: the problem started with 0def905 or earlier. I don't have a 100% confidence in the 'good' results, but I trust the tests when they tell me the DSP boot failed.

[lgirdwood]

@XiaoyunWu6666 are you able to do some further investigation.

1. locally revert 0def905 and try 20 iterations
2. locally revert 9a7a5ce and try 20 iterations.

OR redo the bisect with 20 iterations (based on @plbossart being able to reproduce with 10). Thanks !

@marc-hb @lyakh fyi

[plbossart]

Note that sometimes 10-20 iterations is not enough. I just ran a check which didn't fail in 50, and my last took 36 with the SOF main branch

2021-07-27 21:54:09 UTC Sub-Test: [INFO] ===== Round(36/50) =====
2021-07-27 21:54:09 UTC Sub-Test: [COMMAND] Run the command: rtcwake -m mem -s 5
rtcwake: assuming RTC uses UTC ...
rtcwake: wakeup from "mem" using /dev/rtc0 at Tue Jul 27 21:54:14 2021
2021-07-27 21:54:33 UTC Sub-Test: [COMMAND] sleep for 5
arecord: suspend:1716: suspend: prepare error: Connection timed out
2021-07-27 21:54:38 UTC Sub-Test: [INFO] Check for the kernel log status
declare -- cmd="journalctl_cmd --since=@1627422844"
2021-07-27 21:54:38 UTC [ERROR] Caught kernel log error
===========================>>
[ 1053.206429] kernel: sof-audio-pci-intel-cnl 0000:00:1f.3: error: hda_dsp_stream_trigger: cmd 5: timeout on STREAM_SD_OFFSET read
[ 1062.162980] kernel: sof-audio-pci-intel-cnl 0000:00:1f.3: error: cl_copy_fw: timeout HDA_DSP_SRAM_REG_ROM_STATUS read
[ 1062.163662] kernel: sof-audio-pci-intel-cnl 0000:00:1f.3: error: hda_dsp_stream_trigger: cmd 0: timeout on STREAM_SD_OFFSET read
[ 1062.163671] kernel: sof-audio-pci-intel-cnl 0000:00:1f.3: error: DMA trigger stop failed
[ 1062.163678] kernel: sof-audio-pci-intel-cnl 0000:00:1f.3: ------------[ DSP dump start ]------------
[ 1062.163705] kernel: sof-audio-pci-intel-cnl 0000:00:1f.3: error: extended rom status:  0x5000001 0x0 0x0 0x0 0x0 0x0 0x1811102 0x0
[ 1062.163712] kernel: sof-audio-pci-intel-cnl 0000:00:1f.3: ------------[ DSP dump end ]------------
[ 1062.163717] kernel: sof-audio-pci-intel-cnl 0000:00:1f.3: error: load fw failed ret: -110
[ 1062.163773] kernel: sof-audio-pci-intel-cnl 0000:00:1f.3: error: failed to start DSP
[ 1062.163780] kernel: sof-audio-pci-intel-cnl 0000:00:1f.3: error: failed to boot DSP firmware after resume -110

[plbossart]

With these two commands, I was able to run 100 iterations without issues.

git revert 57ee04f2d9312968a8e11fd916195bbacd667180
git revert 0def9056300a4b23d909ba0b36256087af91d2fe

test command:

TPLG=/lib/firmware/intel/sof-tplg/sof-cml-rt711-rt1308-mono-rt715.tplg ~/sof-test/test-case/check-suspend-resume-with-audio.sh -l 100 -m capture