Ubuntu
linux-oem-5.6 package

pulseaudio threaded-ml suspend issue

Bug #1918880 reported by kailoran
8
This bug affects 1 person
Affects Status Importance Assigned to Milestone
linux-oem-5.6 (Ubuntu)
Confirmed
Undecided
Unassigned

Bug Description

My laptop failed to suspend overnight and was unresponsive when I opened it back up. This is on Ubuntu 20.04.2 LTS with kernel 5.6.0-1048-oem and pulseaudio:amd64/focal-updates 1:13.99.1-1ubuntu3.10 uptodate. In syslog, I found a stream of suspend attempts with pulseaudio-related issues repeating in a 40s cycle, so reporting this as a PA issue.

Mar 12 00:08:31 churn systemd[1]: Reached target Sleep.
Mar 12 00:08:31 churn upowerd[1698]: Could not acquire inhibitor lock: GDBus.Error:org.freedesktop.login1.OperationInProgress: The operation inhibition has been requested for is already running
Mar 12 00:08:31 churn systemd[1]: Starting Suspend...
Mar 12 00:08:31 churn ModemManager[1427]: <warn> [sleep-monitor] inhibit failed: GDBus.Error:org.freedesktop.login1.OperationInProgress: The operation inhibition has been requested for is already running
Mar 12 00:08:31 churn kernel: [883904.845262] iwlwifi 0000:00:14.3: Applying debug destination EXTERNAL_DRAM
Mar 12 00:08:31 churn ModemManager[1427]: <info> Couldn't check support for device '/sys/devices/pci0000:00/0000:00:14.3': Device support check task already available for device '/sys/devices/pci0000:00/0000:00:14.3'
Mar 12 00:08:31 churn systemd-sleep[516395]: Suspending system...
Mar 12 00:08:31 churn kernel: [883904.853576] PM: suspend entry (s2idle)
Mar 12 00:08:51 churn kernel: [883904.856917] Filesystems sync: 0.003 seconds
Mar 12 00:08:51 churn kernel: [883904.857284] Freezing user space processes ...
Mar 12 00:08:51 churn kernel: [883904.991749] iwlwifi 0000:00:14.3: FW already configured (0) - re-configuring
Mar 12 00:08:51 churn kernel: [883924.868069] Freezing of tasks failed after 20.010 seconds (1 tasks refusing to freeze, wq_busy=0):
Mar 12 00:08:51 churn kernel: [883924.868160] threaded-ml D 0 3306 2128 0x80004326
Mar 12 00:08:51 churn kernel: [883924.868166] Call Trace:
Mar 12 00:08:51 churn kernel: [883924.868183] __schedule+0x2d8/0x760
Mar 12 00:08:51 churn kernel: [883924.868188] schedule+0x55/0xc0
Mar 12 00:08:51 churn kernel: [883924.868195] do_exit.cold+0x9f/0xb5
Mar 12 00:08:51 churn kernel: [883924.868200] rewind_stack_do_exit+0x17/0x20
Mar 12 00:08:51 churn kernel: [883924.868205] RIP: 0033:0x7fc8a96ebcb9
Mar 12 00:08:51 churn kernel: [883924.868216] Code: Bad RIP value.
Mar 12 00:08:51 churn kernel: [883924.868219] RSP: 002b:00007fc899504850 EFLAGS: 00000293 ORIG_RAX: 0000000000000007
Mar 12 00:08:51 churn kernel: [883924.868223] RAX: fffffffffffffdfc RBX: 0000208bbe357f60 RCX: 00007fc8a96ebcb9
Mar 12 00:08:51 churn kernel: [883924.868225] RDX: 0000000000007530 RSI: 0000000000000003 RDI: 0000208bbe357f60
Mar 12 00:08:51 churn kernel: [883924.868227] RBP: 0000000000000003 R08: 0000000000000000 R09: 000000001587756a
Mar 12 00:08:51 churn kernel: [883924.868229] R10: 0000000000000f90 R11: 0000000000000293 R12: 0000000000007530
Mar 12 00:08:51 churn kernel: [883924.868231] R13: 0000000000007530 R14: 0000208bbe3285d0 R15: 00007fff6f13d440
Mar 12 00:08:51 churn kernel: [883924.868427] OOM killer enabled.
Mar 12 00:08:51 churn rtkit-daemon[1608]: The canary thread is apparently starving. Taking action.
Mar 12 00:08:51 churn NetworkManager[1297]: <info> [1615504131.1026] device (p2p-dev-wlp0s20f3): state change: unmanaged -> unavailable (reason 'managed', sys-iface-state: 'managed')
Mar 12 00:08:51 churn rtkit-daemon[1608]: Demoting known real-time threads.
Mar 12 00:08:51 churn NetworkManager[1297]: <info> [1615504131.1036] manager: NetworkManager state is now DISCONNECTED
Mar 12 00:08:51 churn rtkit-daemon[1608]: Demoted 0 threads.
Mar 12 00:08:51 churn NetworkManager[1297]: <info> [1615504131.1039] manager: sleep: sleep requested (sleeping: no enabled: yes)
Mar 12 00:08:51 churn NetworkManager[1297]: <info> [1615504131.1039] device (wlp0s20f3): state change: unavailable -> unmanaged (reason 'sleeping', sys-iface-state: 'managed')
Mar 12 00:08:51 churn pulseaudio[2134]: q overrun, queuing locally
Mar 12 00:08:51 churn kernel: [883924.868429] Restarting tasks ... done.
Mar 12 00:08:51 churn pulseaudio[2134]: message repeated 4 times: [ q overrun, queuing locally]
Mar 12 00:08:51 churn NetworkManager[1297]: <info> [1615504131.1245] device (p2p-dev-wlp0s20f3): state change: unavailable -> unmanaged (reason 'sleeping', sys-iface-state: 'managed')
Mar 12 00:08:51 churn NetworkManager[1297]: <info> [1615504131.1247] manager: NetworkManager state is now ASLEEP
Mar 12 00:08:51 churn kernel: [883924.916329] PM: suspend exit
Mar 12 00:08:51 churn kernel: [883924.916367] PM: suspend entry (s2idle)
Mar 12 00:08:51 churn kernel: [883924.922458] Filesystems sync: 0.006 seconds
Mar 12 00:09:11 churn kernel: [883924.932177] Freezing user space processes ...
Mar 12 00:09:11 churn kernel: [883944.944348] Freezing of tasks failed after 20.012 seconds (1 tasks refusing to freeze, wq_busy=0):
Mar 12 00:09:11 churn kernel: [883944.944443] threaded-ml D 0 3306 2128 0x80004326
Mar 12 00:09:11 churn kernel: [883944.944450] Call Trace:
Mar 12 00:09:11 churn kernel: [883944.944471] __schedule+0x2d8/0x760
Mar 12 00:09:11 churn kernel: [883944.944477] schedule+0x55/0xc0
Mar 12 00:09:11 churn kernel: [883944.944486] do_exit.cold+0x9f/0xb5
Mar 12 00:09:11 churn kernel: [883944.944493] rewind_stack_do_exit+0x17/0x20
Mar 12 00:09:11 churn kernel: [883944.944499] RIP: 0033:0x7fc8a96ebcb9
Mar 12 00:09:11 churn kernel: [883944.944513] Code: Bad RIP value.
Mar 12 00:09:11 churn kernel: [883944.944516] RSP: 002b:00007fc899504850 EFLAGS: 00000293 ORIG_RAX: 0000000000000007
Mar 12 00:09:11 churn kernel: [883944.944521] RAX: fffffffffffffdfc RBX: 0000208bbe357f60 RCX: 00007fc8a96ebcb9
Mar 12 00:09:11 churn kernel: [883944.944524] RDX: 0000000000007530 RSI: 0000000000000003 RDI: 0000208bbe357f60
Mar 12 00:09:11 churn kernel: [883944.944527] RBP: 0000000000000003 R08: 0000000000000000 R09: 000000001587756a
Mar 12 00:09:11 churn kernel: [883944.944530] R10: 0000000000000f90 R11: 0000000000000293 R12: 0000000000007530
Mar 12 00:09:11 churn kernel: [883944.944532] R13: 0000000000007530 R14: 0000208bbe3285d0 R15: 00007fff6f13d440
Mar 12 00:09:11 churn kernel: [883944.944772] OOM killer enabled.
Mar 12 00:09:11 churn rtkit-daemon[1608]: The canary thread is apparently starving. Taking action.
Mar 12 00:09:11 churn rtkit-daemon[1608]: Demoting known real-time threads.
Mar 12 00:09:11 churn rtkit-daemon[1608]: Demoted 0 threads.
Mar 12 00:09:11 churn kernel: [883944.944774] Restarting tasks ...
Mar 12 00:09:11 churn kernel: [883944.950817] Lockdown: systemd-logind: hibernation is restricted; see man kernel_lockdown.7
Mar 12 00:09:11 churn kernel: [883944.954092] done.
Mar 12 00:09:11 churn kernel: [883944.954105] thermal thermal_zone5: failed to read out thermal zone (-61)
Mar 12 00:09:11 churn pulseaudio[2134]: q overrun, queuing locally
Mar 12 00:09:11 churn kernel: [883944.998101] PM: suspend exit
Mar 12 00:09:11 churn pulseaudio[2134]: message repeated 4 times: [ q overrun, queuing locally]
Mar 12 00:09:11 churn systemd-sleep[516395]: Failed to suspend system. System resumed again: Device or resource busy
Mar 12 00:09:11 churn systemd[1]: systemd-suspend.service: Main process exited, code=exited, status=1/FAILURE
Mar 12 00:09:11 churn systemd[1]: systemd-suspend.service: Failed with result 'exit-code'.
Mar 12 00:09:11 churn systemd[1]: Failed to start Suspend.
Mar 12 00:09:11 churn systemd[1]: Dependency failed for Suspend.
Mar 12 00:09:11 churn systemd[1]: suspend.target: Job suspend.target/start failed with result 'dependency'.
Mar 12 00:09:11 churn systemd[1]: Stopped target Sleep.
Mar 12 00:09:11 churn NetworkManager[1297]: <info> [1615504151.2427] manager: sleep: wake requested (sleeping: yes enabled: yes)
Mar 12 00:09:11 churn NetworkManager[1297]: <info> [1615504151.2427] device (wlp0s20f3): state change: unmanaged -> unavailable (reason 'managed', sys-iface-state: 'managed')
Mar 12 00:09:11 churn systemd[1]: Reached target Sleep.
[log pattern repeats]

The laptop is frequently connected to an usb dock with an audio output, and a separate usb microphone with a line out as well, but when the issue happened it was only plugged in to a charger. It also is often connected to a bluetooth speaker that may have been in range. While the system was mostly idle, I may have had (disconnected) mumble, zoom and discord apps open while the suspend broke and that's about it as far as audio-using apps go (plus a web browser).

ProblemType: Bug
DistroRelease: Ubuntu 20.04
Package: pulseaudio 1:13.99.1-1ubuntu3.10
ProcVersionSignature: Ubuntu 5.6.0-1048.52-oem 5.6.19
Uname: Linux 5.6.0-1048-oem x86_64
ApportVersion: 2.20.11-0ubuntu27.16
Architecture: amd64
AudioDevicesInUse:
 USER PID ACCESS COMMAND
 /dev/snd/controlC0: tsniatowski 2378 F.... pulseaudio
 /dev/snd/controlC2: tsniatowski 2378 F.... pulseaudio
 /dev/snd/controlC1: tsniatowski 2378 F.... pulseaudio
CasperMD5CheckResult: skip
CurrentDesktop: ubuntu:GNOME
Date: Fri Mar 12 08:16:57 2021
InstallationDate: Installed on 2021-02-27 (12 days ago)
InstallationMedia: Ubuntu 20.04.2.0 LTS "Focal Fossa" - Release amd64 (20210209.1)
SourcePackage: pulseaudio
UpgradeStatus: No upgrade log present (probably fresh install)
dmi.bios.date: 01/18/2021
dmi.bios.vendor: Dell Inc.
dmi.bios.version: 1.3.5
dmi.board.name: 095TWY
dmi.board.vendor: Dell Inc.
dmi.board.version: A00
dmi.chassis.type: 10
dmi.chassis.vendor: Dell Inc.
dmi.modalias: dmi:bvnDellInc.:bvr1.3.5:bd01/18/2021:svnDellInc.:pnLatitude7420:pvr:rvnDellInc.:rn095TWY:rvrA00:cvnDellInc.:ct10:cvr:
dmi.product.family: Latitude
dmi.product.name: Latitude 7420
dmi.product.sku: 0A36
dmi.sys.vendor: Dell Inc.

Revision history for this message
kailoran (kailoran) wrote :
Revision history for this message
Daniel van Vugt (vanvugt) wrote :

Please check that you haven't enabled:

  realtime-scheduling = yes

in /etc/pulse/daemon.conf. And if the problem continues to occur after that then please report it to the developers at:

  https://gitlab.freedesktop.org/pulseaudio/pulseaudio/-/issues

and tell us the new issue ID.

Changed in pulseaudio (Ubuntu):
status: New → Incomplete
Revision history for this message
kailoran (kailoran) wrote :

"; realtime-scheduling = yes" is commented away in /etc/pulse/daemon.conf (this is a very fresh install of 20.04 and I haven't customized much). Should I enable this?

Either way, I'll try to exercise suspend and keep an eye out for this issue happening again. I tried looking around but didn't find any similar reports.

Revision history for this message
Daniel van Vugt (vanvugt) wrote :

No there's no need to change the config file.

I'm guessing now that the issue is the daemon stuck in a system call. That usually means it's a kernel bug, or a bug in the kernel sound driver. So if you are comfortable doing so, please try some different kernel versions:

https://kernel.ubuntu.com/~kernel-ppa/mainline/?C=M;O=D

Changed in linux-oem-5.6 (Ubuntu):
status: New → Incomplete
Revision history for this message
kailoran (kailoran) wrote :

I haven't encountered the problem in over a week after switching to a 5.10 kernel (from linux-image-oem-20.04-edge).

Daniel van Vugt (vanvugt)
no longer affects: pulseaudio (Ubuntu)
Changed in linux-oem-5.6 (Ubuntu):
status: Incomplete → Confirmed
To post a comment you must log in.
This report contains Public information  
Everyone can see this information.
Subscribing...

Other bug subscribers

Remote bug watches

Bug watches keep track of this bug in other bug trackers.