Repository navigation
[BUG] [TGL] runtime-pm-status: dsp is not suspended after 15s, end test #6735
Description
Describe the bug
check-kmod-load-unload and check-kmod-load-unload-after-playback fail like this:
https://sof-ci.01.org/sofpr/PR6733/build2695/devicetest/index.html
2022-12-06 21:45:39 UTC Sub-Test: [REMOTE_INFO] Test Result: PASS!
2022-12-06 21:45:39 UTC [REMOTE_INFO] ===== Starting iteration 1 of 2 =====
2022-12-06 21:45:39 UTC Sub-Test: [REMOTE_INFO] ===== Starting iteration 1 of 1 =====
2022-12-06 21:45:39 UTC Sub-Test: [REMOTE_INFO] wait dsp power status to become suspended
2022-12-06 21:46:01 UTC Sub-Test: [REMOTE_ERROR] dsp is not suspended after 15s, end test
2022-12-06 21:46:01 UTC Sub-Test: [REMOTE_ERROR] Starting func_exit_handler(), exit status=1, FUNCNAME stack:
2022-12-06 21:46:01 UTC Sub-Test: [REMOTE_ERROR] die() @ /home/ubuntu/sof-test/case-lib/lib.sh
2022-12-06 21:46:01 UTC Sub-Test: [REMOTE_ERROR] main() @ /home/ubuntu/sof-test/test-case/check-kmod-load-unload.sh:72
2022-12-06 21:46:02 UTC Sub-Test: [REMOTE_INFO] pkill -TERM -f mtrace-reader.py
2022-12-06 21:46:02 UTC Sub-Test: [REMOTE_INFO] Test Result: FAIL!
2022-12-06 21:46:02 UTC [REMOTE_ERROR] kmod reload failed
2022-12-06 21:46:02 UTC [REMOTE_ERROR] Starting func_exit_handler(), exit status=1, FUNCNAME stack:
2022-12-06 21:46:02 UTC [REMOTE_ERROR] die() @ /home/ubuntu/sof-test/test-case/../case-lib/lib.sh
2022-12-06 21:46:02 UTC [REMOTE_ERROR] main() @ /home/ubuntu/sof-test/test-case/check-kmod-load-unload-after-playback.sh:76
2022-12-06 21:46:02 UTC [REMOTE_INFO] pkill -TERM -f mtrace-reader.py
2022-12-06 21:46:02 UTC [REMOTE_INFO] ktime=69 sof-test PID=1435: ending
2022-12-06 21:46:02 UTC [REMOTE_INFO] Test Result: FAIL!
Impact
Affects PR testing, examples:
- https://sof-ci.01.org/sofpr/PR6733/build2695/devicetest/index.html
- https://sof-ci.01.org/sofpr/PR6733/build2695/devicetest/index.html?model=TGLU_RVP_NOCODEC_IPC4ZPH&testcase=check-runtime-pm-status
- https://sof-ci.01.org/linuxpr/PR4080/build2383/devicetest/index.html?model=TGLU_RVP_NOCODEC_IPC4ZPH&testcase=check-kmod-load-unload-after-playback
- https://sof-ci.01.org/linuxpr/PR4080/build2383/devicetest/index.html?model=TGLU_RVP_NOCODEC_IPC4ZPH&testcase=check-runtime-pm-status
Reproduction Rate
Reproduction is high but probably not deterministic, here's a recent run passing:
https://sof-ci.01.org/sofpr/PR6732/build2684/devicetest/index.html
Environment
- Branch name and commit hash of the 2 repositories: sof (firmware/topology) and linux (kernel driver).
2022-12-06 is the first daily run where I found it. It seems to occur in most daily IPC4 test runs after that
Daily IPC4 18618?model=TGLU_RVP_NOCODEC_CAVSIPC4&testcase=check-kmod-load-unload-after-playback-5
Kernel Branch: topic/sof-dev
Kernel Commit: c78e584e7704
SOF Branch: main
SOF Commit: 4a9a99aeb24a
Zephyr Commit: ffed8388e7cb
- Name of the platform(s) on which the bug is observed.
- Platform: TGL IPC4
Activity
marc-hb commentedon Dec 7, 2022
It is not deterministic with a fairly high reproduction rate. Always on TGLU_RVP_NOCODEC_IPC4ZPH
???? https://sof-ci.01.org/sofpr/PR6733/build2685/devicetest/index.html
FAIL https://sof-ci.01.org/sofpr/PR6733/build2686/devicetest/index.html
PASS https://sof-ci.01.org/sofpr/PR6733/build2687/devicetest/index.html
PASS https://sof-ci.01.org/sofpr/PR6733/build2688/devicetest/index.html
FAIL https://sof-ci.01.org/sofpr/PR6733/build2689/devicetest/index.html
???? https://sof-ci.01.org/sofpr/PR6733/build2690/devicetest/index.html
FAIL https://sof-ci.01.org/sofpr/PR6733/build2691/devicetest/index.html
PASS https://sof-ci.01.org/sofpr/PR6733/build2692/devicetest/index.html
FAIL https://sof-ci.01.org/sofpr/PR6733/build2693/devicetest/index.html
PASS https://sof-ci.01.org/sofpr/PR6733/build2694/devicetest/index.html
FAIL https://sof-ci.01.org/sofpr/PR6733/build2695/devicetest/index.html
[-][BUG] kmod-load-unload: dsp is not suspended after 15s, end test[/-][+][BUG] kmod-load-unload & runtime-pm: dsp is not suspended after 15s, end test[/+]ujfalusi commentedon Dec 7, 2022
Interesting, in the logs where there is a fail, in dmesg there is not a single
fw_state change:after the initialfw_state change: 6 -> 7, so pm runtime is indeed does not work and the DSP never got powered down.Or, something is keeping the DSP powered up which we don't see.
ranj063 commentedon Dec 7, 2022
so in every instance of the failure that i have seen, the check-runtime-pm-status is the failure that actually causing the kmod tests to fail. So we should change the title to reflect that
ranj063 commentedon Dec 7, 2022
And the problem starts long before the check-runtime-pm-status test. Have a look at the dmesg after the check-sof-logger test. In the PASS case, the DSP is in D3 after topology loading is done: https://sof-ci.01.org/sofpr/PR6733/build2687/devicetest/index.html?model=TGLU_RVP_NOCODEC_IPC4ZPH&testcase=check-sof-logger
In the FAIL case, it isnt: https://sof-ci.01.org/sofpr/PR6733/build2686/devicetest/index.html?model=TGLU_RVP_NOCODEC_IPC4ZPH&testcase=check-sof-logger
[-][BUG] kmod-load-unload & runtime-pm: dsp is not suspended after 15s, end test[/-][+][BUG] [TGL] runtime-pm-status: dsp is not suspended after 15s, end test[/+]marc-hb commentedon Dec 7, 2022
The only recent and significant thing I found in the SOF git log is the nocodec deepbuffer PR #6508
(I did not check the kernel git log)
ranj063 commentedon Dec 7, 2022
The other difference I noticed between the PASS and the fail is the module param sof_debug value: In the FAIL case it seems to be: [ 134.208897] kernel: sof-audio-pci-intel-tgl 0000:00:1f.3: sof_debug value: 0x81 and in the PASS case it is: [ 114.705315] kernel: sof-audio-pci-intel-tgl 0000:00:1f.3: sof_debug value: 0x41
marc-hb commentedon Dec 7, 2022
Awesome @ranj063 , I was looking for a DUT difference last night but ran out of steam. Looking at it again now I see that all the FAIL in my list above happened on
jf-tglu-rvp-nocodec-1while all the PASS were onsh-tglu-rvp-nocodec-02...What debug bit is this one?
fredoh9 commentedon Dec 7, 2022
sof_debug param is currently set a bit messy, it is not centralized in deploy script.
desired value for sof_debug, 0x81 for MTL platform, any platform else is 0x41
ranj063 commentedon Dec 7, 2022
@fredoh9 can we please fix this? I think this will take care of the issue
fredoh9 commentedon Dec 7, 2022
Sure, I will take care of sof_debug param. There are some changes scattered here and there
marc-hb commentedon Dec 7, 2022
we should absolutely manage sof_debug bits better (EDIT: filed internal bug 339) but is it expected for this IMR debug bit to break runtime PM on TGL?
ranj063 commentedon Dec 7, 2022
@marc-hb @fredoh9 can we please check if the sof_debug param is indeed the culprit? If that is indeed the case, then it's likely a kernel issue that needs to be fixed
marc-hb commentedon Dec 7, 2022
Answering my own question with
git grep SOF_DBGI haven't tested anything but this looks like a smoking gun to me.
Just found this on
jf-tglu-rvp-nocodec-1:-(@fredoh9 we need the deploy scripts to not just stop adding stuff in Ubuntu-owned files (which clashes with Ubuntu) but ALSO scrub Ubuntu-owned files to fix past mistakes.
marc-hb commentedon Dec 7, 2022
Wrong! I tested both systems with various values of
/sys/module/snd_sof/parameters/sof_debugand it made no difference.So @ranj063 had a second look and found the real issue. Only the failing system has this file:
I renamed it, reloaded the drivers and
check-runtime-pm-status.shis now passing.However the file was only 2 hours old so maybe a rogue script will regenerate it again.
Let's move the deployment discussion to the internal bug 339.