[BUG] RMMOD snd_sof_pci_intel_tgl takes too much time, causing check-sof-logger TIMEOUT/failure

[XiaoyunWu6666]

Describe the bug
when remove modules , it may cause over 1 min to remove module snd_sof_pci_intel_tgl , thus leading to testcase TIMEOUT or failure . Sometimes the DUT even gets hang.
Check-sof-logger testcase is also affected by it (logs attached at the end)

For TGLU_RVP_HDA, this happened since 4882 , but in daily 4849 it is good
For ADLP_RVP_HDA and ADLP_RVP_SDW , this happened since 4883 , but in the last daily-ADL 4850 it is good
So this may happen around June 25
To Reproduce
sof-test/tools/kmod/sof_remove.sh
OR
sof-test/testcases/check-sof-logger.sh

Reproduction Rate
100%

environment
(this is the recipe of 4883and 4882)
Kernel Branch: topic/sof-dev
Kernel Commit: 5b851f4
SOF Branch: main
SOF Commit: 86c9a037e212

Platform
tglu-rvp-hda
adlp-rvp-hda
adlp-rvp-sdw

logs when running check-sof-logger.sh

[For ADLP-RVP-HDA and ADLP-RVP-SDW]

console

2021-06-25 21:31:23 UTC [REMOTE_COMMAND] sudo /usr/local/bin/sof-logger  -t -f 3 -l  /etc/sof/sof-adl.ldc  -o  /home/ubuntu/sof-test/logs/check-sof-logger/2021-06-26-05:31:13-14923/logger.data.txt  2>  /home/ubuntu/sof-test/logs/check-sof-logger/2021-06-26-05:31:13-14923/logger.error.txt  &
2021-06-25 21:31:25 UTC [REMOTE_INFO] Trying to get the etrace mailbox ...
2021-06-25 21:31:25 UTC [REMOTE_COMMAND] sudo /usr/local/bin/sof-logger    -f 3 -l  /etc/sof/sof-adl.ldc  2>  /home/ubuntu/sof-test/logs/check-sof-logger/2021-06-26-05:31:13-14923/logger.etrace_stderr.txt  -o  /home/ubuntu/sof-test/logs/check-sof-logger/2021-06-26-05:31:13-14923/logger.etrace.txt

2021-06-25 21:31:25 UTC [REMOTE_ERROR] Reading (e)trace failed, run_loggers returned 2

2021-06-25 21:31:25 UTC [REMOTE_INFO] Log file logger.data.txt BEG::
cat: '/home/ubuntu/sof-test/logs/check-sof-logger/2021-06-26-05:31:13-14923/logger.data.txt': No such file or directory
2021-06-25 21:31:25 UTC [REMOTE_INFO] ::END log file logger.data.txt


2021-06-25 21:31:25 UTC [REMOTE_INFO] Log file logger.etrace.txt BEG::
cat: '/home/ubuntu/sof-test/logs/check-sof-logger/2021-06-26-05:31:13-14923/logger.etrace.txt': No such file or directory
2021-06-25 21:31:25 UTC [REMOTE_INFO] ::END log file logger.etrace.txt


2021-06-25 21:31:25 UTC [REMOTE_INFO] Log file logger.error.txt BEG::
error: Unable to open version file /sys/kernel/debug/sof/fw_version: No such file or directory
2021-06-25 21:31:25 UTC [REMOTE_INFO] ::END log file logger.error.txt


2021-06-25 21:31:25 UTC [REMOTE_INFO] Log file logger.etrace_stderr.txt BEG::
error: Unable to open version file /sys/kernel/debug/sof/fw_version: No such file or directory
2021-06-25 21:31:25 UTC [REMOTE_INFO] ::END log file logger.etrace_stderr.txt

2021-06-25 21:31:25 UTC [REMOTE_ERROR] Reading (e)trace failed, run_loggers returned 2

logger.error

error: Unable to open version file /sys/kernel/debug/sof/fw_version: No such file or directory

[for TGLU_RVP_HDA‘]

RMMOD	snd_usb_audio
SKIP	snd_hda_intel  	not loaded
SKIP	snd_sof_pci_intel_tng  	not loaded
SKIP	snd_sof_pci_intel_apl  	not loaded
SKIP	snd_sof_pci_intel_cnl  	not loaded
SKIP	snd_sof_pci_intel_icl  	not loaded
RMMOD	snd_sof_pci_intel_tgl

（and no log anymore ）

[marc-hb]

rmmod hangs when a device is in use. Every time I've seen rmmod hanging it was because of a leftover sof-logger reading the DMA /sys/kernel/debug/sof/trace. Reading the shared memory etrace is not a problem, does not cause any hang, maybe because it always completes quickly?

I just logged into ssh ubuntu@sh-tglu-rvp-hda-03.sh.intel.com and I found a hanging rmmod + this:

sudo lsof -n |grep sof/trace
sof-logge 1359                            root    6r      REG                0,6        0      18238 /sys/kernel/debug/sof/trace (deleted)
pgrep -f -a logger
1359 sof-logger -l /etc/sof/sof-tgl.ldc -t -o /home/ubuntu/reboot-logs/logger-t_100.log

[marc-hb]

For TGLU_RVP_HDA, this happened since 4882 , but in daily 4849 it is good
For ADLP_RVP_HDA and ADLP_RVP_SDW , this happened since 4883 , but in the last daily-ADL 4850 it is good
So this may happen around June 25

Thank you the report, this is extremely useful info. So I strongly suspect that this is cause by lingering sof-logger instances which were just exposed by commit thesofproject/sof-test@6a8871fb849a7af60 ("check-sof-logger: reload drivers first") in PR thesofproject/sof-test#710.

See tentative fix in thesofproject/sof-test#730

[marc-hb]

thesofproject/sof-test#730 is merged, if this does not happen in the next few days we should close.

[keqiaozhang]

This issue is not seen in recent daily tests. let's close this bug.

[XiaoyunWu6666]

@marc-hb
hi marc , appreciated that your PR makes check-sof-logger testcase results in daily tests much better.
However ,I have no idea why check-sof-logger keeps failing on ADL
see inner daily-ADL 5215?model=ADLP_RVP_SDW&testcase=check-sof-logger
and
inner daily-ADL 5215?model=ADLP_RVP_HDA&testcase=check-sof-logger.
After removing modules and module probing , the check-sof-logger failed with reading etrace failure

[marc-hb]

error: Unable to open version file /sys/kernel/debug/sof/fw_version: No such file or directory means the firmware did not boot completely (or very, very, very slowly - there is already a long delay in the test).

That's not a problem with the logger. The job of the logger is to find issues: it just found one. This is a firmware boot issue which is unrelated to this bug #3025.

If it were a problem with the logger itself, it would most likely affect more than one very specific platform.

[XiaoyunWu6666]

error: Unable to open version file /sys/kernel/debug/sof/fw_version: No such file or directory means the firmware did not boot completely (or very, very, very slowly - there is already a long delay in the test).

That's not a problem with the logger. The job of the logger is to find issues: it just found one. This is a firmware boot issue which is unrelated to this bug #3025.

If it were a problem with the logger itself, it would most likely affect more than one very specific platform.

Thanks
daily_ADL 5215?model=ADLP_RVP_SDW&testcase=check-sof-logger
daily_ADL /5215?model=ADLP_RVP_SDW&testcase=check-playback-all-formats
I think something wrong with firmware boot so that the SOF sound card cannot be detected in 'check-playback-all-formats' case , right? The second case was affected by the first one