[BUG] DSP panic when initializing the DMA trace

[1994lwz]

Describe the bug
This is a firmware regression. This issue occurs when initializing the DMA trace after sof firmware reloaded.
IPC info: ipc tx: 0x90030000: GLB_TRACE_MSG
This is a common issue and happens on different platforms when triggering the firmware reloading process, like runtime PM test, kmod test and suspend/resume test.

To Reproduce
Run such cases: suspend-resume, kmod-load-unload, or runtime-pm-check.
eg. run 'TPLG=/lib/firmware/intel/sof-tplg/sof-adl-rt711-4ch.tplg ~/sof-test/test-case/check-runtime-pm-status.sh -l 15' on adlp-rvp-sdw
Reproduction Rate
100%

Environment
Kernel Branch: topic/sof-dev
Kernel Commit: eb558167
SOF Branch: main
SOF Commit: 7df3674
Platform: TGLH/ADLP/TGLU/ICL/CML/GLK

Screenshots or console output
[dmesg]

[ 5390.222509] kernel: sof-audio-pci-intel-tgl 0000:00:1f.3: firmware boot complete
[ 5390.222535] kernel: sof-audio-pci-intel-tgl 0000:00:1f.3: Debug PCIR: 00000000 at  00000048
[ 5390.222541] kernel: sof-audio-pci-intel-tgl 0000:00:1f.3: Debug PCIW: 00000002 at  00000048
[ 5390.222582] kernel: sof-audio-pci-intel-tgl 0000:00:1f.3: Debug PCIR: 00000004 at  00000044
[ 5390.222587] kernel: sof-audio-pci-intel-tgl 0000:00:1f.3: Debug PCIW: 00000000 at  00000044
[ 5390.222607] kernel: sof-audio-pci-intel-tgl 0000:00:1f.3: FW Poll Status: reg[0x80]=0x40000 successful
[ 5390.222639] kernel: sof-audio-pci-intel-tgl 0000:00:1f.3: FW Poll Status: reg[0x80]=0x40000 successful
[ 5390.222644] kernel: sof-audio-pci-intel-tgl 0000:00:1f.3: hda_dsp_stream_setup_bdl: period_bytes:0x0
[ 5390.222647] kernel: sof-audio-pci-intel-tgl 0000:00:1f.3: hda_dsp_stream_setup_bdl: periods:1
[ 5390.222670] kernel: sof-audio-pci-intel-tgl 0000:00:1f.3: snd_sof_init_trace_ipc: stream_tag: 1
[ 5390.222680] kernel: sof-audio-pci-intel-tgl 0000:00:1f.3: ipc tx: 0x90030000: GLB_TRACE_MSG
[ 5390.223046] kernel: sof-audio-pci-intel-tgl 0000:00:1f.3: error : DSP panic!
[ 5390.223050] kernel: sof-audio-pci-intel-tgl 0000:00:1f.3: panic: dsp_oops_offset 788480 offset 788480
[ 5390.223053] kernel: sof-audio-pci-intel-tgl 0000:00:1f.3: ------------[ DSP dump start ]------------
[ 5390.223064] kernel: sof-audio-pci-intel-tgl 0000:00:1f.3: status: fw entered - code 00000005
[ 5390.223277] kernel: sof-audio-pci-intel-tgl 0000:00:1f.3: error: runtime exception
[ 5390.223279] kernel: sof-audio-pci-intel-tgl 0000:00:1f.3: error: trace point 00004000
[ 5390.223281] kernel: sof-audio-pci-intel-tgl 0000:00:1f.3: error: panic at :0
[ 5390.223284] kernel: sof-audio-pci-intel-tgl 0000:00:1f.3: error: DSP Firmware Oops
[ 5390.223286] kernel: sof-audio-pci-intel-tgl 0000:00:1f.3: error: Exception Cause: LoadStorePIFDataErrorCause, Synchronous PIF data error during LoadStore access
[ 5390.223288] kernel: sof-audio-pci-intel-tgl 0000:00:1f.3: EXCCAUSE 0x0000000d EXCVADDR 0x00000000 PS       0x00060725 SAR     0x00000000
[ 5390.223291] kernel: sof-audio-pci-intel-tgl 0000:00:1f.3: EPC1     0xbe031345 EPC2     0xbe053596 EPC3     0x00000000 EPC4    0x00000000
[ 5390.223293] kernel: sof-audio-pci-intel-tgl 0000:00:1f.3: EPC5     0x00000000 EPC6     0x00000000 EPC7     0x00000000 DEPC    0x00000000
[ 5390.223295] kernel: sof-audio-pci-intel-tgl 0000:00:1f.3: EPS2     0x00060f20 EPS3     0x00000000 EPS4     0x00000000 EPS5    0x00000000
[ 5390.223297] kernel: sof-audio-pci-intel-tgl 0000:00:1f.3: EPS6     0x00000000 EPS7     0x00000000 INTENABL 0x00000000 INTERRU 0x00000222
[ 5390.223299] kernel: sof-audio-pci-intel-tgl 0000:00:1f.3: stack dump from 0xbe07feb0
[ 5390.223302] kernel: sof-audio-pci-intel-tgl 0000:00:1f.3: 0xbe07feb0: 00000000 00000000 00000000 00000000
[ 5390.223305] kernel: sof-audio-pci-intel-tgl 0000:00:1f.3: 0xbe07feb4: 7e031345 be07ff30 00000020 000003e8
[ 5390.223307] kernel: sof-audio-pci-intel-tgl 0000:00:1f.3: 0xbe07feb8: 4e351800 55a6dc8e 70d09028 ffff9e91
[ 5390.223309] kernel: sof-audio-pci-intel-tgl 0000:00:1f.3: 0xbe07febc: 000c0800 00000000 70d09028 ffff9e91
[ 5390.223312] kernel: sof-audio-pci-intel-tgl 0000:00:1f.3: 0xbe07fec0: 70d09028 ffff9e91 00000091 00000000
[ 5390.223314] kernel: sof-audio-pci-intel-tgl 0000:00:1f.3: 0xbe07fec4: 9d0cfe28 ffffffff 70e4a200 ffff9e91
[ 5390.223316] kernel: sof-audio-pci-intel-tgl 0000:00:1f.3: 0xbe07fec8: 9d0cff20 ffffffff 4e351800 55a6dc8e
[ 5390.223318] kernel: sof-audio-pci-intel-tgl 0000:00:1f.3: 0xbe07fecc: 9d08d851 ffffffff 4d85f480 ffff9e91
[ 5390.223320] kernel: sof-audio-pci-intel-tgl 0000:00:1f.3: ------------[ DSP dump end ]------------
[ 5390.726844] kernel: sof-audio-pci-intel-tgl 0000:00:1f.3: ipc tx timed out for 0x90030000 (msg/reply size: 80/12)
[ 5390.726851] kernel: sof-audio-pci-intel-tgl 0000:00:1f.3: preventing DSP entering D3 state to preserve context
[ 5390.726854] kernel: sof-audio-pci-intel-tgl 0000:00:1f.3: ------------[ IPC dump start ]------------
[ 5390.726872] kernel: sof-audio-pci-intel-tgl 0000:00:1f.3: error: hda irq intsts 0x00000000 intlctl 0xc0000000 rirb 00
[ 5390.726875] kernel: sof-audio-pci-intel-tgl 0000:00:1f.3: error: dsp irq ppsts 0x00000000 adspis 0x00000000
[ 5390.726885] kernel: sof-audio-pci-intel-tgl 0000:00:1f.3: error: host status 0x00000000 dsp status 0x00000000 mask 0x00000003
[ 5390.726887] kernel: sof-audio-pci-intel-tgl 0000:00:1f.3: ------------[ IPC dump end ]------------
[ 5390.726890] kernel: sof-audio-pci-intel-tgl 0000:00:1f.3: error: can't set params for DMA for trace -110
[ 5390.726911] kernel: sof-audio-pci-intel-tgl 0000:00:1f.3: warning: failed to init trace after resume -110
[ 5390.726921] kernel: sof-audio-pci-intel-tgl 0000:00:1f.3: ipc tx: 0x30100000: GLB_TPLG_MSG: PIPE_NEW
[ 5391.230860] kernel: sof-audio-pci-intel-tgl 0000:00:1f.3: ipc tx timed out for 0x30100000 (msg/reply size: 48/20)
[ 5391.230869] kernel: sof-audio-pci-intel-tgl 0000:00:1f.3: error: failed to load widget PIPELINE.8.HDA2.OUT
[ 5391.230872] kernel: sof-audio-pci-intel-tgl 0000:00:1f.3: error: failed to restore pipeline after resume -110

[keyonjie]

Thanks for reporting, looks there is deference to NULL pointer issue in the DMA trace part.

[keyonjie]

@1994lwz can you please help to check if the PR #4678 help?

[plbossart]

This was detected in Intel daily test #6047

This can be root-caused to #4636

The question is: how come this wasn't found in CI tests? there's a post-mortem analysis needed on such a regression.

[lgirdwood]

Not sure why CI missed this as it tests the trace on all platforms (jenkins and Internal), the reload part is also tested on the PM tests. @keyonjie are we good to close ?

[1994lwz]

The bug is not reproduce on the daily #6090, and verify it by test the suspend-resume 200 times, runtime-pm-status 100 times, kmod-load-unload 100 times on the ADLP/TGLU/CML/ICL/TGLH.
This bug is fixed by the PR #4678 and #4636 so close it.

[marc-hb]

The question is: how come this wasn't found in CI tests? there's a post-mortem analysis needed on such a regression.

I spent some time looking at the test results of daily run 6047 and the reason this escaped PR testing is because even in the longer daily run 6047 this particular crash is relatively rare (there is a number of other, unrelated failures in that run). Only a few platforms have experienced it, not on every test and even when it happens it's not immediately but only after a fair number of test iterations. Confirmed by comment #4678 (comment)