Repository navigation
[CML] rtcwake: aplay task refusing to freeze #3370
Description
Observed twice in a row: first on jf-cml-hel-rt5682-01 then on jf-cml-hel-rt5682-02
https://sof-ci.01.org/sofpr/PR5207/build11616/devicetest/?model=CML_HEL_RT5682&testcase=check-suspend-resume-with-playback-5
https://sof-ci.01.org/sofpr/PR5207/build11618/devicetest/?model=CML_HEL_RT5682&testcase=check-suspend-resume-with-playback-5
https://sof-ci.01.org/sofpr/PR5227/build11700/devicetest/?model=CML_HEL_RT5682&testcase=check-suspend-resume-with-playback-5
https://sof-ci.01.org/sofpr/PR5202/build11725/devicetest/?model=CML_HEL_RT5682&testcase=check-suspend-resume-with-playback-5
check-suspend-resume-with-capture-5.sh passed both times.
Start Time: 2022-01-14 02:20:28 UTC
End Time: 2022-01-14 02:56:57 UTC
Kernel Commit: ba28f9b
SOF Commit: 6b8b1ce
[ 1319.485729] kernel: sof-audio-pci-intel-cnl 0000:00:1f.3: ipc rx: 0x90020000: GLB_TRACE_MSG: DMA_POSITION
[ 1319.485779] kernel: sof-audio-pci-intel-cnl 0000:00:1f.3: ipc rx done: 0x90020000: GLB_TRACE_MSG: DMA_POSITION
[ 1321.647110] kernel: ax88179_178a 2-2.3:1.0 enx000ec66a7f60: ax88179 - Link status is: 1
[ 1323.971977] kernel: PM: suspend entry (s2idle)
[ 1323.972443] kernel: Filesystems sync: 0.000 seconds
[ 1323.976168] kernel: Freezing user space processes ...
[ 1343.985707] kernel: Freezing of tasks failed after 20.009 seconds (1 tasks refusing to freeze, wq_busy=0):
[ 1343.986049] kernel: task:aplay state:D stack:12928 pid:23088 ppid: 23012 flags:0x00000004
[ 1343.986069] kernel: Call Trace:
[ 1343.986074] kernel:
[ 1343.986084] kernel: __schedule+0x2ac/0x850
[ 1343.986109] kernel: schedule+0x49/0xc0
[ 1343.986120] kernel: schedule_timeout+0x1d5/0x340
[ 1343.986130] kernel: ? del_timer_sync+0x80/0x80
[ 1343.986155] kernel: snd_power_ref_and_wait+0xba/0x110 [snd]
[ 1343.986182] kernel: ? wake_up_q+0x80/0x80
[ 1343.986199] kernel: snd_power_wait+0xd/0x50 [snd]
[ 1343.986222] kernel: snd_pcm_common_ioctl+0x71/0x11c0 [snd_pcm]
[ 1343.986254] kernel: ? selinux_file_ioctl+0x16f/0x210
[ 1343.986269] kernel: ? lock_release+0x14b/0x3f0
[ 1343.986287] kernel: snd_pcm_ioctl+0x1e/0x30 [snd_pcm]
[ 1343.986310] kernel: __x64_sys_ioctl+0x7b/0xb0
[ 1343.986326] kernel: do_syscall_64+0x38/0x90
[ 1343.986335] kernel: entry_SYSCALL_64_after_hwframe+0x44/0xae
[ 1343.986345] kernel: RIP: 0033:0x7fb3b1f1350b
[ 1343.986352] kernel: RSP: 002b:00007ffcd8781b38 EFLAGS: 00000246 ORIG_RAX: 0000000000000010
[ 1343.986362] kernel: RAX: ffffffffffffffda RBX: 000055aa695caef0 RCX: 00007fb3b1f1350b
[ 1343.986367] kernel: RDX: 00007ffcd8781b40 RSI: 0000000040184150 RDI: 0000000000000004
[ 1343.986372] kernel: RBP: 000055aa695cae70 R08: 0000000000000000 R09: 000055aa695cc120
[ 1343.986378] kernel: R10: 000055aa695b2010 R11: 0000000000000246 R12: 000055aa695cc100
[ 1343.986382] kernel: R13: 0000000000000010 R14: 0000000000000000 R15: 0000000000001000
[ 1343.986402] kernel:
[ 1343.986411] kernel:
[ 1343.986414] kernel: OOM killer enabled.
[ 1343.986417] kernel: Restarting tasks ... done.
[ 1343.994689] kernel: PM: suspend exit
[ 1343.999179] kernel: rfkill: input handler enabled
[ 1344.053935] kernel: rfkill: input handler disabled
[ 1345.375290] kernel: sof-audio-pci-intel-cnl 0000:00:1f.3: ipc tx: 0x90040000: GLB_TRACE_MSG: FILTER_UPDATE
[ 1345.375536] kernel: sof-audio-pci-intel-cnl 0000:00:1f.3: ipc tx succeeded: 0x90040000: GLB_TRACE_MSG: FILTER_UPDATE
Activity
plbossart commentedon Jan 14, 2022
also seen in https://sof-ci.01.org/linuxpr/PR3338/build6982/devicetest/?model=CML_HEL_RT5682&testcase=check-suspend-resume-with-playback-5
this could be the result of an upstream merge. The call trace is new but in the past when we had rtcwake errors they seemed to be 100% correlated with this 'task refusing to freeze' issue.
plbossart commentedon Jan 14, 2022
yeah, this is not a new error, it's just that we can see it
Commit 8412dbd ('PM / sleep: Show freezing tasks that caused a suspend abort') added more information.
from the commit message it seems we have a task that is still freezing while we get a wake-up, a possible indication of a race condition.
This is excellent that we can trap this instead of seeing rtcwake fail miserably.
plbossart commentedon Jan 17, 2022
If I look at the call trace above, it seems the 'aplay' userspace task
initiates an ioctl while we are trying to freeze all tasks and suspend, and that ioctl will
try to bring the card back in D0 state.
that looks like a race condition to me, and I am not sure why a
userspace task is permitted to do this.
if I look at snd_power_ref_and_wait() it seems there's a possibility of
an infinite loop where we never return anything. Going back to D0 state
could take some time, typically hundreds of ms, so maybe this happens
because we report an error freezing a task because a power-related task
is in progress.
@tiwai @perexg I could use your guidance on this. Not sure what is happening here.
tiwai commentedon Jan 18, 2022
Hrm, weird. It's the place where suspend_prepare() calling the freezer, right? If so, the card power state must not be other than D0 at that point, as it's before the actual device suspend procedure takes place. (For ASoC, soc_suspend() calls snd_power_change_state() with D3hot, and this should be called after the freezer.)
The task flags (0x04) shows PF_EXITING, so this is a process being shut down, as it seems. But it still doesn't clarify why the loop for power D0 matters... We need to check whether it's really in that loop waiting for the power state D0 or not.
tiwai commentedon Jan 18, 2022
Does it have any influence if we replace wake_up(&card->power_sleep) with wake_up_all(&card->power_sleep) in snd_power_change_state() defined in include/sound/core.h?
tiwai commentedon Jan 18, 2022
Or a patch like below might help?
0001-ALSA-core-Simplify-snd_power_-with-the-standard-macr.patch.txt
plbossart commentedon Jan 18, 2022
@tiwai I don't fully follow your explanations - suspend_prepare doesn't seem to be part of sound/ and not clear either on what ASoC does with D3hot. I clearly don't have any understanding of the freeze part.
I added a simple check to trace when we start the loop to go back to D0, we'll see if this confirms the analysis. #3374
tiwai commentedon Jan 18, 2022
Yes, that'll be helpful for understanding the situation. Also, it'd be good to have debug prints at snd_power_change_state(), too.
plbossart commentedon Jan 18, 2022
it seems we have a 100% reproducible case on a Chromebook, see https://sof-ci.01.org/linuxpr/PR3374/build6987/devicetest/?model=CML_HEL_RT5682&testcase=check-suspend-resume-with-playback-5
dmesg.log
This looks like a sequence of suspend-resumes where we try to restore the D0 state when resuming but somehow never reach that state, and we suspend with an active thread?
tiwai commentedon Jan 18, 2022
ASoC does the resume in a deferred work, and that might be the reason?
The work is synced at snd_soc_suspend(), but it's called after user process freezing, hence it's too late.
plbossart commentedon Jan 18, 2022
Thanks @tiwai. Would it change anything if we did the workqueue sync in a .prepare callback?
tiwai commentedon Jan 18, 2022
I guess this won't fit,the PM prepare callback is handled at a later stage, IIRC. But I might be wrong, better to test actually, of course.
BTW, could you check whether the patch I attached in the above makes any difference?
plbossart commentedon Jan 18, 2022
I added the traces in snd_power_change_state, I don't really understand the results though
https://sof-ci.01.org/linuxpr/PR3374/build6988/devicetest/?model=CML_HEL_RT5682&testcase=check-suspend-resume-with-playback-5
I will give it a try with the .prepare step. prepare is supposed to be before any suspend/freeze. I will test your patch later today.
plbossart commentedon Jan 19, 2022
@tiwai I added a .prepare and that's not helping.
https://sof-ci.01.org/linuxpr/PR3374/build6991/devicetest/?model=CML_HEL_RT5682&testcase=check-suspend-resume-with-playback-5 shows we have exactly the same error before the .prepare is invoked.
I'll try your patch now.
plbossart commentedon Jan 19, 2022
@tiwai unfortunately your patch doesn't seem to improve the results. It's the same issue that we wait for the device to go back to D0 and start a suspend before the resume is complete. You can see in 5001794 that there are two traces, and only the first is found below. the log to indicate the end of the wait is not coming out.
38 remaining items
marc-hb commentedon Feb 3, 2022
I see that #3392 was merged on Jan 28 but with kernel
5.17.0-rc1-daily-default-20220202-0-13669-gbb45f689fa62I found thisDEBUG_LOCKS_WARN_ON(lock->magic != lock)by chance in the logs while looking for something else:marc-hb commentedon Feb 3, 2022
journalctl -g 'kernel/locking/mutex|Linux version|rt5682_jack_detect_handler'shows this WARNING has been printed on not all but almost all boots since Jan 21.#3392 merged on Jan 28 made no difference.
Same on both
jf-tglu-volt-sdw-01andjf-tglu-volt-sdw-03plbossart commentedon Feb 3, 2022
Humm, are we talking about a different platform @marc-hb ? Volteer is SoundWire based, so not sure if PR #3392 fixes any problems.
marc-hb commentedon Feb 3, 2022
Sorry if it's unrelated, #3392 did not seem platform specific to me but I'm very codec-ignorant.
Either way I thought people who just worked on an
rt5682_jack_detect_handlerdeadlock would be interested by another (and unrelated?)rt5682_jack_detect_handlerDEBUG_LOCKS_WARN_ONbut sorry if I connected the wrong dots; nevermind :-)ujfalusi commentedon Feb 3, 2022
@marc-hb, I will take a look, it is rare (but not impossible) that the lock debug produces false positive.
ujfalusi commentedon Feb 3, 2022
This print happens right during boot (@marc-hb can you point me to a log?), the sdw boot differs a bit from the i2c, it is going to schedule the jack_detect work in the sdw_slave .update_status callback. The mutex and work got initialized in the sdw probe, I assume this should be fine.
I don't have any device with this codec (neither i2c or sdw), so it is going to be again fun to figure this out.
ujfalusi commentedon Feb 3, 2022
What happened on Jan 21 or before it? Upstream merge, I assume, I'll take a look at those locking patches which took down the i2c path, they might had other issues as well.
marc-hb commentedon Feb 3, 2022
No, Jan 21 is just hitting the ~4G default maximum in journalctl, so that's as far as the log gets. For some unknown reason logging on these devices seems to be more verbose than usual... Because of SoundWire? Pure speculation.
plbossart commentedon Feb 3, 2022
Good point @marc-hb we seem to log all the SoundWire codec stuff. we don't do this for other types of HDaudio or I2C/I2S codecs. I can't recall why, maybe it was because SoundWire was still new and we needed always get more info.
SoundWire codecs
options snd_soc_rt700 dyndbg=+p
options snd_soc_rt5682_sdw dyndbg=+p
options snd_soc_rt5682 dyndbg=+p
options snd_soc_rt711 dyndbg=+p
options snd_soc_rt1308_sdw dyndbg=+p
options snd_soc_rt1308 dyndbg=+p
options snd_soc_rt715 dyndbg=+p
options snd_soc_max98373_sdw dyndbg=+p
options snd_soc_max98373 dyndbg=+p
options snd-soc-rt711-sdca dyndbg=+p
options snd-soc-rt1316-sdw dyndbg=+p
options snd-soc-rt715-sdca dyndbg=+p
that may not be stricly required any longer. I took a quick look at the TGL_VOLTEER device, most of the logs still seem to come from the IPC, not from the codec.
ujfalusi commentedon Feb 4, 2022
I think this issue is fixed now, can we close it?
@marc-hb, can you create a new issue for the
DEBUG_LOCKS_WARN_ON(lock->magic != lock)seen on Volteer?Nothing stands out in the code, I need access to a machine where I can debug it.
marc-hb commentedon Feb 4, 2022
#3416
marc-hb commentedon Feb 18, 2022
I'm seeing a lot of timeout these days but they don't seem as specific as this one so let's close it.