F14 system hang - pulse audio-alsa-bug-canary starving

[pwalden]

I have a Sony vaio laptop with the latest F14 (2.6.35.10-74.fc14.i686.PAE #1 SMP). I use it to drive my entertainment centre running mpd for hours on end. The problem is a system sort-of-freeze/hang. that happens every day or so.

To describe the symptoms more accurately, this is what happens:

• The X-display gnome clock applet is stuck does not update, but the pointer will track, but I cannot select any menus items, run new apps, etc.
• Audio (if any is playing) sometimes continues to play,sometimes it stops or loops over and over on an audio fragment.
• I cannot access from another system via ssh. I cannot run a virtual terminal. Only recourse seems to be a hard power-off reboot.
• Persistent kernel alsa messages in the log. I have had these since F12, but they never hung the F12 system. At worst in F12, pulseaudio server would die and auto-restart. mpd would sometime pause at this point.

After a reboot, If I examine the log around the evet time I typically see:

Jan 22 13:34:55 walden6 kernel: [140816.523066] ALSA sound/core/pcm_lib.c:318: BUG: pcmC0D0p:0, pos = 16384, buffer size = 16384, period size = 16384
Jan 22 13:37:27 walden6 kernel: [140968.844661] ALSA sound/core/pcm_lib.c:318: BUG: pcmC0D0p:0, pos = 16384, buffer size = 16384, period size = 16384
Jan 22 13:39:38 walden6 kernel: [141100.361360] ALSA sound/core/pcm_lib.c:318: BUG: pcmC0D0p:0, pos = 16384, buffer size = 16384, period size = 16384
Jan 22 13:40:03 walden6 kernel: [141125.252921] ALSA sound/core/pcm_lib.c:318: BUG: pcmC0D0p:0, pos = 16384, buffer size = 16384, period size = 16384
Jan 22 13:41:47 walden6 kernel: [141229.134551] ALSA sound/core/pcm_lib.c:318: BUG: pcmC0D0p:0, pos = 16384, buffer size = 16384, period size = 16384
Jan 22 13:42:29 walden6 kernel: [141270.744350] ALSA sound/core/pcm_lib.c:318: BUG: pcmC0D0p:0, pos = 16384, buffer size = 16384, period size = 16384
Jan 22 13:42:49 walden6 kernel: [141290.806217] ALSA sound/core/pcm_lib.c:318: BUG: pcmC0D0p:0, pos = 16384, buffer size = 16384, period size = 16384
Jan 22 13:44:08 walden6 rtkit-daemon[1601]: The canary thread is apparently starving. Taking action.
Jan 22 13:44:08 walden6 rtkit-daemon[1601]: Demoting known real-time threads.
Jan 22 13:44:08 walden6 rtkit-daemon[1601]: Successfully demoted thread 1832 of process 1826 (/usr/bin/pulseaudio).
Jan 22 13:44:08 walden6 rtkit-daemon[1601]: Successfully demoted thread 1826 of process 1826 (/usr/bin/pulseaudio).
Jan 22 13:44:08 walden6 rtkit-daemon[1601]: Demoted 2 threads
^^^^^ last entry seems to be a a minute or two before the system stops ^^^

I also note that I have this ntpd/kernel bug, but they seem not to be correlated with this freeze/hang. Unless I notethat ntpd has stopped trying to correct the time drift for many hours as the PPM is too large.

[pwalden]

Had another hang this morning. The pointer was tracking the mouse. The gnome clock applet was frozen at 5:47 AM. There was no sound, even though he mpd had kicked in at 5:20 AM (cron'ed). This is the last log entry before the hard power off reboot.

Jan 23 03:39:21 walden6 rtkit-daemon[1607]: The canary thread is apparently starving. Taking action.
Jan 23 03:39:21 walden6 rtkit-daemon[1607]: Demoting known real-time threads.
Jan 23 03:39:21 walden6 rtkit-daemon[1607]: Demoted 0 threads.
Jan 23 03:45:01 walden6 ntpd[6198]: 0.0.0.0 0618 08 no_sys_peer
Jan 23 04:13:37 walden6 ntpd[6198]: 0.0.0.0 0613 03 spike_detect -9.373348 s
Jan 23 04:48:44 walden6 ntpd[6198]: 0.0.0.0 061c 0c clock_step -9.371519 s
Jan 23 04:48:44 walden6 ntpd[6198]: 0.0.0.0 0615 05 clock_sync
Jan 23 04:48:45 walden6 ntpd[6198]: 0.0.0.0 c618 08 no_sys_peer
Jan 23 05:28:08 walden6 ntpd[6198]: 0.0.0.0 0628 08 no_sys_peer
Jan 23 05:28:17 walden6 kernel: [56190.403213] ALSA sound/core/pcm_lib.c:318: BUG: pcmC0D0p:0, pos = 4408, buffer size = 4408, period size = 1102
Jan 23 05:28:24 walden6 kernel: [56197.899749] ALSA sound/core/pcm_lib.c:318: BUG: pcmC0D0p:0, pos = 4408, buffer size = 4408, period size = 1102

[zimon]

I have had these type of hangs also last couple of weeks in two different hardware F14-PCs which didn't have them before.

Last night was the latest. I am able to recover, if I do SAK on session (Alt+SysRq+K), but it takes several minutes to recover. Re-booting is and would be faster way.

Usually it triggers when some media player is just started or something "big" is done with the media player, like switching from/to full screen mode. It always complains about pulse-audio after the "canary is thread"-notice.

# uname -a
Linux localhost 2.6.35.13-91.fc14.x86_64 #1 SMP Tue May 3 13:23:06 UTC 2011 x86_64 x86_64 x86_64 GNU/Linux

Jun 5 03:07:07 frog rtkit-daemon[2216]: The canary thread is apparently starving. Taking action.
Jun 5 03:07:08 frog rtkit-daemon[2216]: Demoting known real-time threads.
Jun 5 03:07:08 frog rtkit-daemon[2216]: Demoted 0 threads.
Jun 5 03:07:08 frog pulseaudio[2373]: alsa-util.c: snd_pcm_avail() returned a value that is exceptionally large: 3159264 bytes (16454 ms).
Jun 5 03:07:08 frog pulseaudio[2373]: alsa-util.c: Most likely this is a bug in the ALSA driver 'snd_via82xx'. Please report this issue to the ALSA developers.
Jun 5 03:07:10 frog pulseaudio[2373]: alsa-util.c: snd_pcm_dump():
Jun 5 03:07:10 frog pulseaudio[2373]: alsa-util.c: Hooks PCM
Jun 5 03:07:10 frog pulseaudio[2373]: alsa-util.c: Its setup is:
Jun 5 03:07:10 frog pulseaudio[2373]: alsa-util.c: stream : PLAYBACK
Jun 5 03:07:10 frog pulseaudio[2373]: alsa-util.c: access : MMAP_INTERLEAVED
Jun 5 03:07:10 frog pulseaudio[2373]: alsa-util.c: format : S16_LE
Jun 5 03:07:10 frog pulseaudio[2373]: alsa-util.c: subformat : STD
Jun 5 03:07:10 frog pulseaudio[2373]: alsa-util.c: channels : 2
Jun 5 03:07:10 frog pulseaudio[2373]: alsa-util.c: rate : 48000
Jun 5 03:07:10 frog pulseaudio[2373]: alsa-util.c: exact rate : 48000 (48000/1)
Jun 5 03:07:10 frog pulseaudio[2373]: alsa-util.c: msbits : 16
Jun 5 03:07:10 frog pulseaudio[2373]: alsa-util.c: buffer_size : 16384
Jun 5 03:07:10 frog pulseaudio[2373]: alsa-util.c: period_size : 8192
Jun 5 03:07:10 frog pulseaudio[2373]: alsa-util.c: period_time : 170666
Jun 5 03:07:10 frog pulseaudio[2373]: alsa-util.c: tstamp_mode : ENABLE
Jun 5 03:07:10 frog pulseaudio[2373]: alsa-util.c: period_step : 1
Jun 5 03:07:10 frog pulseaudio[2373]: alsa-util.c: avail_min : 13217
Jun 5 03:07:10 frog pulseaudio[2373]: alsa-util.c: period_event : 0
Jun 5 03:07:10 frog pulseaudio[2373]: alsa-util.c: start_threshold : -1
Jun 5 03:07:10 frog pulseaudio[2373]: alsa-util.c: stop_threshold : 4611686018427387904
Jun 5 03:07:10 frog pulseaudio[2373]: alsa-util.c: silence_threshold: 0
Jun 5 03:07:10 frog pulseaudio[2373]: alsa-util.c: silence_size : 0
Jun 5 03:07:10 frog pulseaudio[2373]: alsa-util.c: boundary : 4611686018427387904
Jun 5 03:07:10 frog pulseaudio[2373]: alsa-util.c: Slave: Hardware PCM card 3 'VIA 8237' device 0 subdevice 3
Jun 5 03:07:10 frog pulseaudio[2373]: alsa-util.c: Its setup is:
Jun 5 03:07:10 frog pulseaudio[2373]: alsa-util.c: stream : PLAYBACK
Jun 5 03:07:10 frog pulseaudio[2373]: alsa-util.c: access : MMAP_INTERLEAVED
Jun 5 03:07:10 frog pulseaudio[2373]: alsa-util.c: format : S16_LE
Jun 5 03:07:10 frog pulseaudio[2373]: alsa-util.c: subformat : STD
Jun 5 03:07:10 frog pulseaudio[2373]: alsa-util.c: channels : 2
Jun 5 03:07:10 frog pulseaudio[2373]: alsa-util.c: rate : 48000
Jun 5 03:07:10 frog pulseaudio[2373]: alsa-util.c: exact rate : 48000 (48000/1)
Jun 5 03:07:10 frog pulseaudio[2373]: alsa-util.c: msbits : 16
Jun 5 03:07:10 frog pulseaudio[2373]: alsa-util.c: buffer_size : 16384
Jun 5 03:07:10 frog pulseaudio[2373]: alsa-util.c: period_size : 8192
Jun 5 03:07:10 frog pulseaudio[2373]: alsa-util.c: period_time : 170666
Jun 5 03:07:10 frog pulseaudio[2373]: alsa-util.c: tstamp_mode : ENABLE
Jun 5 03:07:10 frog pulseaudio[2373]: alsa-util.c: period_step : 1
Jun 5 03:07:10 frog pulseaudio[2373]: alsa-util.c: avail_min : 13217
Jun 5 03:07:10 frog pulseaudio[2373]: alsa-util.c: period_event : 0
Jun 5 03:07:10 frog pulseaudio[2373]: alsa-util.c: start_threshold : -1
Jun 5 03:07:10 frog pulseaudio[2373]: alsa-util.c: stop_threshold : 4611686018427387904
Jun 5 03:07:10 frog pulseaudio[2373]: alsa-util.c: silence_threshold: 0
Jun 5 03:07:10 frog pulseaudio[2373]: alsa-util.c: silence_size : 0
Jun 5 03:07:10 frog pulseaudio[2373]: alsa-util.c: boundary : 4611686018427387904
Jun 5 03:07:10 frog pulseaudio[2373]: alsa-util.c: appl_ptr : 20684985448
Jun 5 03:07:10 frog pulseaudio[2373]: alsa-util.c: hw_ptr : 20685946880
Jun 5 03:07:14 frog pulseaudio[2373]: alsa-util.c: snd_pcm_delay() returned a value that is exceptionally large: -4457280 bytes (-23215 ms).
Jun 5 03:07:14 frog pulseaudio[2373]: alsa-util.c: Most likely this is a bug in the ALSA driver 'snd_via82xx'. Please report this issue to the ALSA developers.

[pwalden]

This is still a problem for me on my Sony.

However, I switched my mpd server to HP OB6000 which has a different sound driver/chip as the repeated hangs every 1 to 3 days were annoying. The OB6000 has been running non-stop for 3 weeks with no issues.

Definitely seems to be related to the Sony hardware. The audio device appears to be a M5451 from ALI. The driver is snd_ali5451.