On Sun, 2009-12-20 at 17:41 -0600, Chris wrote:
On Sun, 2009-12-20 at 07:47 +0800, Raymond Yau wrote:
I can reproduce this bug on pulseaudio-0.9.14 by
aplay -v --period-size=32 any_rate_not_equal_44100Hz.wav
y-application-name:ALSA plug-in [aplay], because already set. I: module-alsa-sink.c: Trying resume... D: alsa-util.c: Maximum hw buffer size is 371 ms D: module-alsa-sink.c: hwbuf_unused_frames=0 D: module-alsa-sink.c: setting avail_min=4661 I: module-alsa-sink.c: Resumed successfully... D: module-suspend-on-idle.c: Sink alsa_output.pci_12eb_2_sound_card_0_alsa_playback_0 becomes idle. D: module-suspend-on-idle.c: Sink alsa_output.pci_12eb_2_sound_card_0_alsa_playback_0 becomes busy. D: resampler.c: Channel matrix: D: resampler.c: I00 D: resampler.c: +------ D: resampler.c: O00 | 1.000 D: resampler.c: O01 | 1.000 I: resampler.c: Using resampler 'speex-float-3' I: resampler.c: Using float32le as working format. I: resampler.c: Choosing speex quality setting 3. D: memblockq.c: memblockq requested: maxlength=33554432, tlength=0, base=4, prebuf=0, minreq=1 maxrewind=0 D: memblockq.c: memblockq sanitized: maxlength=33554432, tlength=33554432, base=4, prebuf=0, minreq=4 maxrewind=0 I: sink-input.c: Created input 0 "ALSA Playback" on alsa_output.pci_12eb_2_sound_card_0_alsa_playback_0 with sample spec u8 1ch 48000Hz and channel map mono I: protocol-native.c: Requested tlength=501.33 ms, minreq=2.67 ms D: protocol-native.c: Early requests mode enabled, configuring sink latency to minreq. D: memblockq.c: memblockq requested: maxlength=4194304, tlength=24064, base=1, prebuf=23936, minreq=128 maxrewind=0 D: memblockq.c: memblockq sanitized: maxlength=4194304, tlength=24064, base=1, prebuf=23936, minreq=128 maxrewind=0 I: protocol-native.c: Final latency 504.00 ms = 496.00 ms + 2*2.67 ms + 2.67 ms I: module-alsa-sink.c: Starting playback. D: module-alsa-sink.c: latency set to 4.00ms D: module-alsa-sink.c: hwbuf_unused_frames=1872 D: module-alsa-sink.c: setting avail_min=2225 D: module-alsa-sink.c: Requesting rewind due to latency change. D: module-alsa-sink.c: Requested to rewind 8192 bytes. D: module-alsa-sink.c: Limited to 7608 bytes. D: module-alsa-sink.c: before: 1902 D: module-alsa-sink.c: after: 1902 D: module-alsa-sink.c: Rewound 7608 bytes. D: sink.c: Processing rewind... D: sink-input.c: Have to rewind 7608 bytes on render memblockq. D: protocol-native.c: Requesting rewind due to end of underrun. D: protocol-native.c: Requesting rewind due to end of underrun. D: protocol-native.c: Requesting rewind due to end of underrun. D: sink-input.c: Requesting rewind due to corking D: module-suspend-on-idle.c: Sink alsa_output.pci_12eb_2_sound_card_0_alsa_playback_0 becomes idle. D: module-alsa-sink.c: hwbuf_unused_frames=0 D: module-alsa-sink.c: setting avail_min=7661 D: module-alsa-sink.c: Requested to rewind 8192 bytes. D: module-alsa-sink.c: Limited to 140 bytes. D: module-alsa-sink.c: before: 35 D: module-alsa-sink.c: after: 35 D: module-alsa-sink.c: Rewound 140 bytes. D: sink.c: Processing rewind... D: module-suspend-on-idle.c: Sink alsa_output.pci_12eb_2_sound_card_0_alsa_playback_0 becomes idle. I: sink-input.c: Freeing input 0 "ALSA Playback" I: client.c: Freed 1 "ALSA plug-in [aplay]" I: protocol-native.c: Connection died. I: client.c: Created 2 "Native client (UNIX socket client)" D: protocol-native.c: Protocol version: remote 14, local 14 I: protocol-native.c: Got credentials: uid=500 gid=500 success=1 D: protocol-native.c: SHM possible: yes D: protocol-native.c: Negotiated SHM: yes I: module-stream-restore.c: Restoring device for stream sink-input-by-application-name:ALSA plug-in [aplay]. I: module-stream-restore.c: Restoring volume for sink input sink-input-by-application-name:ALSA plug-in [aplay]. D: module-stream-restore.c: Not restoring mute state for sink input sink-input-by-application-name:ALSA plug-in [aplay], because already set. D: module-suspend-on-idle.c: Sink alsa_output.pci_12eb_2_sound_card_0_alsa_playback_0 becomes busy. I: resampler.c: Using resampler 'speex-float-3' I: resampler.c: Using float32le as working format. I: resampler.c: Choosing speex quality setting 3. D: memblockq.c: memblockq requested: maxlength=33554432, tlength=0, base=4, prebuf=0, minreq=1 maxrewind=0 D: memblockq.c: memblockq sanitized: maxlength=33554432, tlength=33554432, base=4, prebuf=0, minreq=4 maxrewind=0 I: sink-input.c: Created input 1 "ALSA Playback" on alsa_output.pci_12eb_2_sound_card_0_alsa_playback_0 with sample spec s16le 2ch 22050Hz and channel map front-left,front-right I: protocol-native.c: Requested tlength=500.68 ms, minreq=1.45 ms D: protocol-native.c: Early requests mode enabled, configuring sink latency to minreq. D: memblockq.c: memblockq requested: maxlength=4194304, tlength=44160, base=4, prebuf=44032, minreq=128 maxrewind=0 D: memblockq.c: memblockq sanitized: maxlength=4194304, tlength=44160, base=4, prebuf=44032, minreq=128 maxrewind=0 I: protocol-native.c: Final latency 502.13 ms = 497.78 ms + 2*1.45 ms + 1.45 ms D: module-alsa-sink.c: latency set to 4.00ms D: module-alsa-sink.c: hwbuf_unused_frames=1872 D: module-alsa-sink.c: setting avail_min=2225 D: module-alsa-sink.c: Requesting rewind due to latency change. D: module-alsa-sink.c: Requested to rewind 8192 bytes. D: module-alsa-sink.c: Limited to 7804 bytes. D: module-alsa-sink.c: before: 1951 D: module-alsa-sink.c: after: 1951 D: module-alsa-sink.c: Rewound 7804 bytes. D: sink.c: Processing rewind... D: sink-input.c: Have to rewind 7804 bytes on render memblockq. E: asyncq.c: q overrun, queuing locally E: asyncq.c: q overrun, queuing locally E: asyncq.c: q overrun, queuing locally E: asyncq.c: q overrun, queuing locally I: module-alsa-sink.c: Underrun! E: asyncq.c: q overrun, queuing locally E: asyncq.c: q overrun, queuing locally E: asyncq.c: q overrun, queuing locally D: protocol-native.c: Requesting rewind due to end of underrun. D: protocol-native.c: Requesting rewind due to end of underrun. D: protocol-native.c: Requesting rewind due to end of underrun. I: module-alsa-sink.c: Underrun! I: module-alsa-sink.c: Underrun! I: module-alsa-sink.c: Underrun! I: module-alsa-sink.c: Underrun! D: sink-input.c: Requesting rewind due to corking D: module-suspend-on-idle.c: Sink alsa_output.pci_12eb_2_sound_card_0_alsa_playback_0 becomes idle. D: module-alsa-sink.c: hwbuf_unused_frames=0 D: module-alsa-sink.c: setting avail_min=7661 D: module-alsa-sink.c: Requested to rewind 8192 bytes. D: module-suspend-on-idle.c: Sink alsa_output.pci_12eb_2_sound_card_0_alsa_playback_0 becomes idle. D: module-alsa-sink.c: Limited to 68 bytes. D: module-alsa-sink.c: before: 17 D: module-alsa-sink.c: after: 17 D: module-alsa-sink.c: Rewound 68 bytes. D: sink.c: Processing rewind... I: sink-input.c: Freeing input 1 "ALSA Playback" I: client.c: Freed 2 "ALSA plug-in [aplay]" I: protocol-native.c: Connection died. I: module-suspend-on-idle.c: Sink alsa_output.pci_12eb_2_sound_card_0_alsa_playback_0 idle for too long, suspending ... I: module-alsa-sink.c: Device suspended... I: client.c: Created 3 "Native client (UNIX socket client)" D: protocol-native.c: Protocol version: remote 14, local 14 I: protocol-native.c: Got credentials: uid=500 gid=500 success=1 D: protocol-native.c: SHM possible: yes D: protocol-native.c: Negotiated SHM: yes I: module-stream-restore.c: Restoring device for stream sink-input-by-application-name:ALSA plug-in [aplay]. I: module-stream-restore.c: Restoring volume for sink input sink-input-by-application-name:ALSA plug-in [aplay]. D: module-stream-restore.c: Not restoring mute state for sink input sink-input-by-application-name:ALSA plug-in [aplay], because already set. I: module-alsa-sink.c: Trying resume... D: alsa-util.c: Maximum hw buffer size is 371 ms D: module-alsa-sink.c: hwbuf_unused_frames=0 D: module-alsa-sink.c: setting avail_min=7661 I: module-alsa-sink.c: Resumed successfully... I: module-alsa-sink.c: Starting playback. D: module-suspend-on-idle.c: Sink alsa_output.pci_12eb_2_sound_card_0_alsa_playback_0 becomes idle. D: module-suspend-on-idle.c: Sink alsa_output.pci_12eb_2_sound_card_0_alsa_playback_0 becomes busy. I: resampler.c: Using resampler 'speex-float-3' I: resampler.c: Using float32le as working format. I: resampler.c: Choosing speex quality setting 3. D: memblockq.c: memblockq requested: maxlength=33554432, tlength=0, base=4, prebuf=0, minreq=1 maxrewind=0 D: memblockq.c: memblockq sanitized: maxlength=33554432, tlength=33554432, base=4, prebuf=0, minreq=4 maxrewind=0 I: sink-input.c: Created input 2 "ALSA Playback" on alsa_output.pci_12eb_2_sound_card_0_alsa_playback_0 with sample spec s16le 2ch 22050Hz and channel map front-left,front-right I: protocol-native.c: Requested tlength=500.68 ms, minreq=1.45 ms D: protocol-native.c: Early requests mode enabled, configuring sink latency to minreq. D: memblockq.c: memblockq requested: maxlength=4194304, tlength=44160, base=4, prebuf=44032, minreq=128 maxrewind=0 D: memblockq.c: memblockq sanitized: maxlength=4194304, tlength=44160, base=4, prebuf=44032, minreq=128 maxrewind=0 I: protocol-native.c: Final latency 502.13 ms = 497.78 ms + 2*1.45 ms + 1.45 ms D: module-alsa-sink.c: latency set to 4.00ms D: module-alsa-sink.c: hwbuf_unused_frames=1872 D: module-alsa-sink.c: setting avail_min=2225 D: module-alsa-sink.c: Requesting rewind due to latency change. D: module-alsa-sink.c: Requested to rewind 8192 bytes. D: module-alsa-sink.c: Limited to 7680 bytes. D: module-alsa-sink.c: before: 1920 D: module-alsa-sink.c: after: 1920 D: module-alsa-sink.c: Rewound 7680 bytes. D: sink.c: Processing rewind... D: sink-input.c: Have to rewind 7680 bytes on render memblockq. D: module-alsa-sink.c: Wakeup from ALSA! OUTPUT I: module-alsa-sink.c: Underrun! D: module-alsa-sink.c: Wakeup from ALSA! OUTPUT E: module-alsa-sink.c: ALSA woke us up to write new data to the device, but there was actually nothing to write! Most likely this is an ALSA driver bug. Please report this issue to the PulseAudio developers. D: module-alsa-sink.c: Wakeup from ALSA! OUTPUT D: module-alsa-sink.c: Wakeup from ALSA! OUTPUT
2009/12/19 Chris cpollock@embarqmail.com
Mandriva 2010.0, Gnome 2.28, pulseaudio 0.9.19-7mdv2010.0. With pulseaudio enabled in MCC periodically the hd light will constantly be on for a period of 4 or 5 minutes and system will slow down to a crawl. Also these comments will be in syslog:
pulseaudio[4331]: alsa-util.c: snd_pcm_avail() returned a value that is exceptionally large: 349696 bytes (1821 ms). Dec 14 20:26:29 localhost pulseaudio[4331]: alsa-util.c: Most likely this is a bug in the ALSA driver 'snd_via82xx'. Please report this issue to the ALSA developers. Dec 14 20:26:29 localhost pulseaudio[4331]: alsa-util.c: snd_pcm_dump(): Dec 14 20:26:29 localhost pulseaudio[4331]: alsa-util.c: Hardware PCM card 1 'VIA 8237' device 0 subdevice 0 Dec 14 20:26:29 localhost pulseaudio[4331]: alsa-util.c: Its setup is: Dec 14 20:26:29 localhost pulseaudio[4331]: alsa-util.c: stream : PLAYBACK Dec 14 20:26:29 localhost pulseaudio[4331]: alsa-util.c: access : MMAP_INTERLEAVED Dec 14 20:26:29 localhost pulseaudio[4331]: alsa-util.c: format : S16_LE Dec 14 20:26:29 localhost pulseaudio[4331]: alsa-util.c: subformat : STD Dec 14 20:26:29 localhost pulseaudio[4331]: alsa-util.c: channels : 2 Dec 14 20:26:29 localhost pulseaudio[4331]: alsa-util.c: rate : 48000 Dec 14 20:26:29 localhost pulseaudio[4331]: alsa-util.c: exact rate : 48000 (48000/1) Dec 14 20:26:29 localhost pulseaudio[4331]: alsa-util.c: msbits : 16 Dec 14 20:26:29 localhost pulseaudio[4331]: alsa-util.c: buffer_size : 16384 Dec 14 20:26:29 localhost pulseaudio[4331]: alsa-util.c: period_size : 8192 Dec 14 20:26:29 localhost pulseaudio[4331]: alsa-util.c: period_time : 170666 Dec 14 20:26:29 localhost pulseaudio[4331]: alsa-util.c: tstamp_mode : ENABLE Dec 14 20:26:29 localhost pulseaudio[4331]: alsa-util.c: period_step : 1 Dec 14 20:26:29 localhost pulseaudio[4331]: alsa-util.c: avail_min : 9665 Dec 14 20:26:29 localhost pulseaudio[4331]: alsa-util.c: period_event : 0 Dec 14 20:26:29 localhost pulseaudio[4331]: alsa-util.c: start_threshold : -1 Dec 14 20:26:29 localhost pulseaudio[4331]: alsa-util.c: stop_threshold : 1073741824 Dec 14 20:26:29 localhost pulseaudio[4331]: alsa-util.c: silence_threshold: 0 Dec 14 20:26:29 localhost pulseaudio[4331]: alsa-util.c: silence_size : 0 Dec 14 20:26:29 localhost pulseaudio[4331]: alsa-util.c: boundary : 1073741824 Dec 14 20:26:29 localhost pulseaudio[4331]: alsa-util.c: appl_ptr : 767919576 Dec 14 20:26:29 localhost pulseaudio[4331]: alsa-util.c: hw_ptr : 767990616 Dec 14 20:26:29 localhost pulseaudio[4331]: ratelimit.c: 7 events suppressed Dec 14 20:26:31 localhost pulseaudio[4331]: asyncq.c: q overrun, queuing locally
I also see this quite frequently:
Dec 14 20:15:29 localhost pulseaudio[4331]: asyncq.c: q overrun, queuing locally Dec 14 20:15:34 localhost pulseaudio[4331]: ratelimit.c: 657 events suppressed Dec 14 20:15:34 localhost pulseaudio[4331]: asyncq.c: q overrun, queuing locally Dec 14 20:15:39 localhost pulseaudio[4331]: ratelimit.c: 2508 events suppressed Dec 14 20:15:39 localhost pulseaudio[4331]: asyncq.c: q overrun, queuing locally Dec 14 20:15:44 localhost pulseaudio[4331]: ratelimit.c: 3530 events suppressed Dec 14 20:15:44 localhost pulseaudio[4331]: asyncq.c: q overrun, queuing locally Dec 14 20:15:44 localhost pulseaudio[4331]: asyncq.c: q overrun, queuing locally Dec 14 20:15:49 localhost pulseaudio[4331]: ratelimit.c: 2672 events suppressed Dec 14 20:15:49 localhost pulseaudio[4331]: asyncq.c: q overrun, queuing locally Dec 14 20:16:05 localhost pulseaudio[4331]: ratelimit.c: 2244 events suppressed Dec 14 20:16:18 localhost pulseaudio[4331]: ratelimit.c: 1 events suppressed Dec 14 20:16:23 localhost pulseaudio[4331]: ratelimit.c: 1 events suppressed Dec 14 20:16:34 localhost pulseaudio[4331]: ratelimit.c: 5 events suppressed Dec 14 20:16:39 localhost pulseaudio[4331]: ratelimit.c: 9 events suppressed Dec 14 20:16:45 localhost pulseaudio[4331]: ratelimit.c: 11 events suppressed Dec 14 20:16:50 localhost pulseaudio[4331]: ratelimit.c: 13 events suppressed Dec 14 20:16:55 localhost pulseaudio[4331]: ratelimit.c: 16 events suppressed Dec 14 20:17:01 localhost pulseaudio[4331]: ratelimit.c: 17 events suppressed Dec 14 20:17:06 localhost pulseaudio[4331]: ratelimit.c: 23 events suppressed Dec 14 20:17:11 localhost pulseaudio[4331]: ratelimit.c: 19 events suppressed Dec 14 20:17:31 localhost pulseaudio[4331]: ratelimit.c: 23 events suppressed Dec 14 20:17:36 localhost pulseaudio[4331]: ratelimit.c: 19 events suppressed Dec 14 20:17:42 localhost pulseaudio[4331]: ratelimit.c: 21 events suppressed Dec 14 20:17:47 localhost pulseaudio[4331]: ratelimit.c: 19 events suppressed
I have pulseaudio enabled but have glitch-free mode disabled. Any assistance in troubleshooting this would be appreciated.
Chris
Anyway to stop this from happening? When it does happen it's causing my drive to thrash for about 4-5 minutes or longer as shown below:
Dec 20 14:35:50 localhost pulseaudio[4331]: ratelimit.c: 271 events suppressed Dec 20 14:35:50 localhost pulseaudio[4331]: asyncq.c: q overrun, queuing locally
Dec 20 14:44:15 localhost pulseaudio[4331]: asyncq.c: q overrun, queuing locally
I'm still seeing this:
Dec 26 14:53:19 localhost pulseaudio[5772]: ratelimit.c: 468 events suppressed Dec 26 14:53:19 localhost pulseaudio[5772]: asyncq.c: q overrun, queuing locally Dec 26 14:53:19 localhost last message repeated 10 times
Dec 26 16:07:17 localhost pulseaudio[5772]: alsa-util.c: snd_pcm_avail() returned a value that is exceptionally large: 88384 bytes (501 ms). Dec 26 16:07:17 localhost pulseaudio[5772]: alsa-util.c: Most likely this is a bug in the ALSA driver 'snd_ens1371'. Please report this issue to the ALSA developers. Dec 26 16:07:17 localhost pulseaudio[5772]: alsa-util.c: snd_pcm_dump(): Dec 26 16:07:17 localhost pulseaudio[5772]: alsa-util.c: Hardware PCM card 1 'Ensoniq AudioPCI' device 0 subdevice 0 Dec 26 16:07:17 localhost pulseaudio[5772]: alsa-util.c: Its setup is: Dec 26 16:07:17 localhost pulseaudio[5772]: alsa-util.c: stream : PLAYBACK Dec 26 16:07:17 localhost pulseaudio[5772]: alsa-util.c: access : MMAP_INTERLEAVED Dec 26 16:07:17 localhost pulseaudio[5772]: alsa-util.c: format : S16_LE Dec 26 16:07:17 localhost pulseaudio[5772]: alsa-util.c: subformat : STD Dec 26 16:07:17 localhost pulseaudio[5772]: alsa-util.c: channels : 2 Dec 26 16:07:17 localhost pulseaudio[5772]: alsa-util.c: rate : 44100 Dec 26 16:07:17 localhost pulseaudio[5772]: alsa-util.c: exact rate : 44101 (1445100000/32768) Dec 26 16:07:17 localhost pulseaudio[5772]: alsa-util.c: msbits : 16 Dec 26 16:07:17 localhost pulseaudio[5772]: alsa-util.c: buffer_size : 4408 Dec 26 16:07:17 localhost pulseaudio[5772]: alsa-util.c: period_size : 1102 Dec 26 16:07:17 localhost pulseaudio[5772]: alsa-util.c: period_time : 24988 Dec 26 16:07:17 localhost pulseaudio[5772]: alsa-util.c: tstamp_mode : ENABLE Dec 26 16:07:17 localhost pulseaudio[5772]: alsa-util.c: period_step : 1 Dec 26 16:07:17 localhost pulseaudio[5772]: alsa-util.c: avail_min : 1102 Dec 26 16:07:17 localhost pulseaudio[5772]: alsa-util.c: period_event : 0 Dec 26 16:07:17 localhost pulseaudio[5772]: alsa-util.c: start_threshold : -1 Dec 26 16:07:17 localhost pulseaudio[5772]: alsa-util.c: stop_threshold : 1155530752 Dec 26 16:07:17 localhost pulseaudio[5772]: alsa-util.c: silence_threshold: 0 Dec 26 16:07:17 localhost pulseaudio[5772]: alsa-util.c: silence_size : 0 Dec 26 16:07:17 localhost pulseaudio[5772]: alsa-util.c: boundary : 1155530752 Dec 26 16:07:17 localhost pulseaudio[5772]: alsa-util.c: appl_ptr : 188107008 Dec 26 16:07:17 localhost pulseaudio[5772]: alsa-util.c: hw_ptr : 188130144 Dec 26 16:07:17 localhost pulseaudio[5772]: ratelimit.c: 9 events suppressed
though fortunately the drive doesn't seem to be thrashing any more. Is there anymore information I can provide that will help in troubleshooting this?
Chris