Pulseaudio leading to rtkit making hard kernel lock-up

[Daniel Ejsing-Duun]

After upgrading to 12.10 it takes about five minutes to boot my system while the system load goes crazy and unity occasionally crashes once or twice in the process. Looking at my syslog the only syspicious lines is

Nov 4 20:30:58 zelito rtkit-daemon[2524]: The canary thread is apparently starving. Taking action.
Nov 4 20:30:58 zelito rtkit-daemon[2524]: Demoting known real-time threads.
Nov 4 20:30:58 zelito rtkit-daemon[2524]: Successfully demoted thread 10780 of process 10774 (n/a).
Nov 4 20:30:58 zelito rtkit-daemon[2524]: Successfully demoted thread 10779 of process 10774 (n/a).
Nov 4 20:30:58 zelito rtkit-daemon[2524]: Successfully demoted thread 10774 of process 10774 (n/a).
Nov 4 20:30:58 zelito rtkit-daemon[2524]: Demoted 3 threads.

These lines repeat about 20 times and end up with a kernel lock-up

Nov 4 20:31:48 zelito rtkit-daemon[2524]: Demoted 3 threads.
Nov 4 20:31:49 zelito kernel: [ 373.910966] ------------[ cut here ]------------
Nov 4 20:31:49 zelito kernel: [ 373.910974] WARNING: at /build/buildd/linux-3.5.0/kernel/watchdog.c:242 watchdog_overflow_callback+0x9a/0xc0()
Nov 4 20:31:49 zelito kernel: [ 373.910975] Hardware name: NBLBX
Nov 4 20:31:49 zelito kernel: [ 373.910976] Watchdog detected hard LOCKUP on cpu 0
Nov 4 20:31:49 zelito kernel: [ 373.910977] Modules linked in: snd_hrtimer pci_stub vboxpci(O) vboxnetadp(O) vboxnetflt(O) vboxdrv(O) dm_crypt coretemp arc4 tpm_infineon psmouse kvm snd_hda_codec_hdmi hp_wmi sparse_keymap snd_hda_codec_realtek uvcvideo videobuf2_core videodev videobuf2_vmalloc videobuf2_memops snd_hda_intel snd_hda_codec snd_hwdep snd_pcm microcode snd_seq_midi snd_rawmidi serio_raw ath9k snd_seq_midi_event i7core_edac snd_seq edac_core mac80211 snd_timer ath9k_common snd_seq_device ath9k_hw ath fglrx(PO) intel_ips lpc_ich cfg80211 mei snd soundcore snd_page_alloc tpm_tis rfcomm bnep parport_pc bluetooth ppdev mac_hid lp parport binfmt_misc vesafb hid_generic usbhid hid r8169 wmi video
Nov 4 20:31:49 zelito kernel: [ 373.911020] Pid: 16187, comm: unity-music-dae Tainted: P O 3.5.0-18-generic #29-Ubuntu
Nov 4 20:31:49 zelito kernel: [ 373.911021] Call Trace:
Nov 4 20:31:49 zelito kernel: [ 373.911023] <NMI> [<ffffffff81051c1f>] warn_slowpath_common+0x7f/0xc0
Nov 4 20:31:49 zelito kernel: [ 373.911031] [<ffffffff81051d16>] warn_slowpath_fmt+0x46/0x50
Nov 4 20:31:49 zelito kernel: [ 373.911035] [<ffffffff810de160>] ? touch_nmi_watchdog+0x80/0x80
Nov 4 20:31:49 zelito kernel: [ 373.911038] [<ffffffff810de1fa>] watchdog_overflow_callback+0x9a/0xc0
Nov 4 20:31:49 zelito kernel: [ 373.911043] [<ffffffff8111a40d>] __perf_event_overflow+0x9d/0x230
Nov 4 20:31:49 zelito kernel: [ 373.911048] [<ffffffff810240c7>] ? x86_perf_event_set_period+0xd7/0x160
Nov 4 20:31:49 zelito kernel: [ 373.911051] [<ffffffff8111af24>] perf_event_overflow+0x14/0x20
Nov 4 20:31:49 zelito kernel: [ 373.911054] [<ffffffff81029453>] intel_pmu_handle_irq+0x193/0x310
Nov 4 20:31:49 zelito kernel: [ 373.911059] [<ffffffff8168505d>] perf_event_nmi_handler+0x1d/0x20
Nov 4 20:31:49 zelito kernel: [ 373.911062] [<ffffffff81684801>] nmi_handle.isra.0+0x51/0x80
Nov 4 20:31:49 zelito kernel: [ 373.911065] [<ffffffff81684910>] do_nmi+0xe0/0x360
Nov 4 20:31:49 zelito kernel: [ 373.911067] [<ffffffff81683e3c>] end_repeat_nmi+0x1a/0x1e
Nov 4 20:31:49 zelito kernel: [ 373.911069] <<EOE>>
Nov 4 20:31:49 zelito kernel: [ 373.911071] ---[ end trace 70e4a0a58141ab52 ]---

I'm reporting it against pulseaudio since process 10774 which is the last demoted every time is pulseaudio. It seems not to be the first time this has happened, but the bug does not get a lot of attention:

http://ubuntuforums.org/archive/index.php/t-1874171.html
https://bugs.freedesktop.org/show_bug.cgi?id=45241

There is even an old (abandoned?) branch which seems to have tried to address this issue:
https://code.launchpad.net/~awe/pulseaudio/rtkit-conflicts

ProblemType: Bug
DistroRelease: Ubuntu 12.10
Package: pulseaudio 1:2.1-0ubuntu4
ProcVersionSignature: Ubuntu 3.5.0-18.29-generic 3.5.7
Uname: Linux 3.5.0-18-generic x86_64
NonfreeKernelModules: fglrx
ApportVersion: 2.6.1-0ubuntu6
Architecture: amd64
AudioDevicesInUse:
 USER PID ACCESS COMMAND
 /dev/snd/controlC1: zilvador 10774 F.... pulseaudio
 /dev/snd/controlC0: zilvador 10774 F.... pulseaudio
Date: Sun Nov 4 21:01:43 2012
InstallationDate: Installed on 2010-11-13 (721 days ago)
InstallationMedia: Ubuntu 10.10 "Maverick Meerkat" - Release amd64 (20101007)
MarkForUpload: True
SourcePackage: pulseaudio
UpgradeStatus: Upgraded to quantal on 2012-10-19 (16 days ago)
dmi.bios.date: 08/23/2010
dmi.bios.vendor: Insyde
dmi.bios.version: F.05
dmi.board.asset.tag: Base Board Asset Tag
dmi.board.name: NBLBX
dmi.board.vendor: Compal
dmi.board.version: Base Board Version
dmi.chassis.asset.tag: Chassis Asset Tag
dmi.chassis.type: 10
dmi.chassis.vendor: Compal
dmi.chassis.version: Chassis Version
dmi.modalias: dmi:bvnInsyde:bvrF.05:bd08/23/2010:svnCompal:pnNBLBX:pvrF.01:rvnCompal:rnNBLBX:rvrBaseBoardVersion:cvnCompal:ct10:cvrChassisVersion:
dmi.product.name: NBLBX
dmi.product.version: F.01
dmi.sys.vendor: Compal

[Launchpad Janitor (janitor)]

Status changed to 'Confirmed' because the bug affects multiple users.

[Daniel Ejsing-Duun (zilvador)]

Right now it happened again and the computer even froze completely, requiring a hard reboot.

[Pranesh Prakash (the-solipsist)]

I can confirm this. I've attached my syslog before the lock-up.

Interestingly, it has this line in the middle:

alsa-util.c: snd_pcm_avail() returned a value that is exceptionally large: 862552 bytes (4889 ms).

pulseaudio[2079]: [alsa-sink-CX20585 Analog] alsa-util.c: Most likely this is a bug in the ALSA driver 'snd_hda_intel'. Please report this issue to the ALSA developers.

I pkill -9'd the pulseaudio process, but it continued freezing again after the process respawned.

[Raymond (superquad-vortex2)]

Dec 6 02:22:11 sirius pulseaudio[12555]: [alsa-sink-CX20585 Analog] alsa-util.c: snd_pcm_delay() returned a value that is exceptionally large: -624212 bytes (-3538 ms).
Dec 6 02:22:11 sirius pulseaudio[12555]: [alsa-sink-CX20585 Analog] alsa-util.c: Most likely this is a bug in the ALSA driver 'snd_hda_intel'. Please report this issue to the ALSA developers.

http://www.alsa-project.org/alsa-doc/alsa-lib/group___p_c_m.html

For playback the delay is defined as the time that a frame that is written to the PCM stream shortly after this call will take to be actually audible. It is as such the overall latency from the write call to the final DAC.

http://www.alsa-project.org/main/index.php/XRUN_Debug

provide xrun_debug log

https://bugzilla.kernel.org/enter_bug.cgi?product=Drivers

[Nelson Castillo (nelsoneci)]

Hello there.

I am having a but that seems to be related. My computer freezes completely and i have to reboot it.

Kernel:

Linux fuga 3.13.0-29-generic #53-Ubuntu SMP Wed Jun 4 21:00:20 UTC 2014 x86_64 x86_64 x86_64 GNU/Linux

Attaching relevant syslog messages and lspci output.

Thanks.

[Nelson Castillo (nelsoneci)]

I'm sorry I missed the lspci output.

[George L. Yermulnik (yermulnik)]

I'm suffering from exactly the same issue. Has it been resolved?

[Fabio Rossi (rossi-f)]

I noticed the same problem, running on kernel 4.14.39. It has already happened twice recently, what I observe are the rtkit-daemon lines in syslog about starvation, the hard drives start to swap heavily and eventually (even after many hours) I have to hard reset the system. Very annoying but I am not sure if the real problem is rtkit-daemon