Repository navigation
[BUG][MTL] MOD_SET_DX causes DSP exception (very recent regression) #7875
Description
Describe the bug
[ 75.070388] kernel: snd_sof:sof_ipc4_log_header: sof-audio-pci-intel-mtl 0000:00:1f.3: ipc tx : 0x44000000|0x3060004c: MOD_LARGE_CONFIG_SET [data size: 76]
[ 75.070781] kernel: snd_sof:sof_ipc4_log_header: sof-audio-pci-intel-mtl 0000:00:1f.3: ipc tx reply: 0x64000000|0x3060004c: MOD_LARGE_CONFIG_SET
[ 75.070825] kernel: snd_sof:sof_ipc4_log_header: sof-audio-pci-intel-mtl 0000:00:1f.3: ipc tx done : 0x44000000|0x3060004c: MOD_LARGE_CONFIG_SET [data size: 76]
[ 75.070838] kernel: snd_sof:sof_ipc4_log_header: sof-audio-pci-intel-mtl 0000:00:1f.3: ipc tx : 0x47000000|0x0: MOD_SET_DX [data size: 8]
[ 75.072688] kernel: snd_sof:sof_ipc4_log_header: sof-audio-pci-intel-mtl 0000:00:1f.3: ipc rx : 0x1b0a0000|0x0: GLB_NOTIFICATION|EXCEPTION_CAUGHT
[ 75.072697] kernel: snd_sof:sof_ipc4_rx_msg: sof-audio-pci-intel-mtl 0000:00:1f.3: Unhandled DSP message: 0x1b0a0000|0x0
[ 75.072702] kernel: snd_sof:sof_ipc4_log_header: sof-audio-pci-intel-mtl 0000:00:1f.3: ipc rx done : 0x1b0a0000|0x0: GLB_NOTIFICATION|EXCEPTION_CAUGHT
[ 75.576913] kernel: sof-audio-pci-intel-mtl 0000:00:1f.3: ipc timed out for 0x47000000|0x0
[ 75.576968] kernel: sof-audio-pci-intel-mtl 0000:00:1f.3: Attempting to prevent DSP from entering D3 state to preserve context
[ 75.576977] kernel: sof-audio-pci-intel-mtl 0000:00:1f.3: ------------[ IPC dump start ]------------
[ 75.577049] kernel: sof-audio-pci-intel-mtl 0000:00:1f.3: Host IPC initiator: 0xc7000000|0x0|0x0, target: 0x1b0a0000|0x0|0x0, ctl: 0x3
[ 75.577094] kernel: sof-audio-pci-intel-mtl 0000:00:1f.3: ------------[ IPC dump end ]------------
[ 75.577209] kernel: sof-audio-pci-intel-mtl 0000:00:1f.3: ------------[ DSP dump start ]------------
[ 75.577265] kernel: sof-audio-pci-intel-mtl 0000:00:1f.3: IPC timeout
[ 75.577307] kernel: sof-audio-pci-intel-mtl 0000:00:1f.3: fw_state: SOF_FW_BOOT_COMPLETE (7)
[ 75.577387] kernel: sof-audio-pci-intel-mtl 0000:00:1f.3: ROM status: 0x5, ROM error: 0x0
[ 75.577442] kernel: sof-audio-pci-intel-mtl 0000:00:1f.3: ROM debug status: 0x50000005, ROM debug error: 0x0
[ 75.577508] kernel: sof-audio-pci-intel-mtl 0000:00:1f.3: ROM feature bit enabled
[ 75.577542] kernel: sof-audio-pci-intel-mtl 0000:00:1f.3: ------------[ DSP dump end ]------------
[ 75.577570] kernel: sof-audio-pci-intel-mtl 0000:00:1f.3: ctx_save IPC error: -110, proceeding with suspend
To Reproduce
Either checking just booting dmesg or
running runtime pm test by (below is example of MTL NOCODEC)
TPLG=/lib/firmware/intel/sof-ace-tplg/sof-mtl-nocodec.tplg MODEL=MTLP_RVP_NOCODEC ~/sof-test/test-case/check-runtime-pm-status.sh -d 10
Reproduction Rate
100%
Expected behavior
No exception.
Reverting pr7857 and pr7325 is submitted, It looks working fine:
The manifest change in #7857 moved Zephyr about 100 commits forward.
Environment
Kernel Branch: topic/sof-dev
Kernel Commit: 5fc4e9175191
SOF Branch: main
SOF Commit: 2cef521c3672
Screenshots or console output
mtl-nocodec-dmesg.txt
mtl-nocodec-mtrace.txt
Activity
[-][BUG][MTL] MOD_SET_DX cause DSP exception[/-][+][BUG][MTL] MOD_SET_DX causes DSP exception[/+][-][BUG][MTL] MOD_SET_DX causes DSP exception[/-][+][BUG][MTL] MOD_SET_DX causes DSP exception (very recent regression)[/+]marc-hb commentedon Jun 29, 2023
Quoting @fredoh9 in a revert draft PR:
#7857 was daily tested. It alone doesn't create the crash.
Yesterday's daily test link: planresultdetail/28254 == PASS
Start Time: 2023-06-27 10:32:56 UTC
SOF Branch: main
SOF Commit: 73cd960e0ed4 == #7857 exactly
marc-hb commentedon Jun 29, 2023
https://sof-ci.01.org/sofpr/PR7700/build10102/devicetest/index.html has only verify-kernel-log.sh, check-runtime-pm.sh and checks-suspend-resume-*.sh always failing which is why 7700 is also a suspect.
The next daily test run planresultdetail/28309 fails the same tests and again it has only #7700 on top:
Start Time: 2023-06-28 10:34:13 UTC
Kernel Branch: topic/sof-dev
Kernel Commit: 5fc4e9175191
SOF Branch: main
SOF Commit: 2cef521c3672
Yet reverting only 7857 and 7325 seems to fix it... It's like ALL these are needed together to reproduce.
https://sof-ci.01.org/softestpr/PR1071/build516/devicetest/index.html is consistencly failing all PM tests with daily SOF build with commit 2cef521 = zephyr uprev + TDFB but no 7325 yet.
EDIT: and now totally unrelated and newer https://sof-ci.01.org/sofpr/PR7824/build10195/devicetest is passing... this is madness.
fredoh9 commentedon Jun 29, 2023
Today's daily build/test are fine. Can we explain this is as PR dependency problem?
#7325 has a dependency on #7857.
#7325 merged after the daily build, that’s why PR#7869 helped?
marc-hb commentedon Jun 29, 2023
I recommended these two to be separate. Maybe they shouldn't have been? Maybe the dependency is somehow "both ways".
Lowering priority because it's not reproducing anymore. Leaving open because there are still unexplained mysteries.
marc-hb commentedon Jun 30, 2023
While "upgrading" sof-test to finally catch firmware error messages, I just found a massive amount of these errors in most tests:
It's unfortunately very hard to tell how old are these errors.
aborisovich commentedon Jun 30, 2023
Yeap, reproducing it too...
Reverting just commits from my PR #7325 fixes the problem... Looking for a fix.
What is interesting is I do not see register polls for ssp after reverting (only HDA).
aborisovich commentedon Jul 3, 2023
Feel free to revert #7325, I do not know the root cause and I'm on vacation this week.
I suspect that explicitly disabling CONFIG_PM_DEVICE_RUNTIME_EXCLUSIVE
alternate how the existing SSP Device works
(previously only CONFIG_PM_DEVICE_RUNTIME had been enabled what select only Zephyr PM Runtime Device management to be operational and turns off Zephyr PM Device API). My change enables both PM Device APIs to be used simultaneously so it could break something indirectly.
aborisovich commentedon Jul 11, 2023
#7917 improves the issue - now dmesg did not show any dumps on platform boot.
Firmware enters D3 normally after system booting.
GLB_NOTIFICATION|EXCEPTION_CAUGHTdoes not occur anddai_intel_sspdoes not report any warnings/errors.Booting the platform looks ok. However, attempt to playback on Core1:
aplay -Dhw:0,1 -r 48000 -c 2 -f S16_LE -d 3 /dev/zero -v -qends with IPC TIMEOUT:
aborisovich commentedon Jul 21, 2023
Workaround - cherry-picking #7917 and turning off FW logs like so:
CONFIG_SOF_LOG_LEVEL_OFF=yFixes the issue
lgirdwood commentedon Jul 26, 2023
#7917 now merged.
keqiaozhang commentedon Aug 9, 2023
Closing this bug as fix #7917 merged.