[alsa-devel] alsa-util.c: snd_pcm_avail() returned a value that is exceptionally large: 349696 bytes (1821 ms).
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
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
-- KeyID 0xE372A7DA98E6705C
Alsa-devel mailing list Alsa-devel@alsa-project.org http://mailman.alsa-project.org/mailman/listinfo/alsa-devel
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
Note - I reported this as bug# https://bugtrack.alsa-project.org/alsa-bug/view.php?id=4834 on 14 December.
if I use default period size of aplay , the pulseaudio server run quite well when I play audio with different sample rate
May be bug in PA server when adjusting latency if you play audio at different rate.
Another bug
I: sink-input.c: Created input 21 "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 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 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 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 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 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 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 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 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 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 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 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 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 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 E: asyncq.c: q overrun, queuing locally E: asyncq.c: q overrun, queuing locally E: asyncmsgq.c: Assertion 'pa_asyncq_push(a->asyncq, &i, TRUE) == 0' failed at pulsecore/asyncmsgq.c:164, function pa_asyncmsgq_send(). Aborting. Aborted
2009/12/20 Chris cpollock@embarqmail.com
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
Note - I reported this as bug# https://bugtrack.alsa-project.org/alsa-bug/view.php?id=4834 on 14 December.
2009/12/20 Chris cpollock@embarqmail.com
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
Note - I reported this as bug# https://bugtrack.alsa-project.org/alsa-bug/view.php?id=4834 on 14 December.
http://thread.gmane.org/gmane.linux.alsa.devel/60371
It seem that PA using one or two periods per buffer , the watermark is alwaysl 20ms for ens1371 for both cases.
when the alsa application (e.g. aplay ) using two periods per buffer , the buffer are almost 50% full at all time (i.e 175 ms watermark is much higher than PA glitch mode 's 20ms watermark )
The possibilty of getting underrun is quite high when PA server/PA client cannot fill the 350 ms buffer in 20ms
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
2009/12/21 Chris cpollock@embarqmail.com
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
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
you have to provide a test case which can reproduce this bug and a full pulseaudio log which recorded how this bug occur
http://www.pulseaudio.org/wiki/Community#BugsPatchesTranslations
If autospawning is enabled (which it now is by default) you might have to race against it when restarting PA, so it might be a good idea to issue "pulseaudio -k ; pulseaudio -vvvvv" in a single command
In my case , I suspect the latency and watermark calculation did not get the correct watermark/sleeping time when the alsa application using small period size (128 bytes is the alsa-pulse-plugin 's minimum period size ) since the error "asyncq.c: q overrun, queuing locally" does not occur when using the normal period_size of those applications (e.g. aplay , mplayer work quite well ) or rewind too much since snd_pcm_rewind() is a new function which is only used by PA server
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!
On Mon, 2009-12-21 at 09:45 +0800, Raymond Yau wrote:
2009/12/21 Chris cpollock@embarqmail.com
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
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
you have to provide a test case which can reproduce this bug and a full pulseaudio log which recorded how this bug occur
http://www.pulseaudio.org/wiki/Community#BugsPatchesTranslations
If autospawning is enabled (which it now is by default) you might have to race against it when restarting PA, so it might be a good idea to issue "pulseaudio -k ; pulseaudio -vvvvv" in a single command
In my case , I suspect the latency and watermark calculation did not get the correct watermark/sleeping time when the alsa application using small period size (128 bytes is the alsa-pulse-plugin 's minimum period size ) since the error "asyncq.c: q overrun, queuing locally" does not occur when using the normal period_size of those applications (e.g. aplay , mplayer work quite well ) or rewind too much since snd_pcm_rewind() is a new function which is only used by PA server
I have the output of the above command, where do I post it?
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
You have to provide the full pulseaudio log in order to find out which application cause the problem
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.
and pulseaudio parameters:- maxlength, tlength, base , ......
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
Only post the error message is useless for debugging
2009/12/27 Chris cpollock@embarqmail.com
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
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
-- KeyID 0xE372A7DA98E6705C
Alsa-devel mailing list Alsa-devel@alsa-project.org http://mailman.alsa-project.org/mailman/listinfo/alsa-devel
Do you mean that you cannot find a test case to reproduce the bug ?
you have to ask alsa developer whether it is correct to post your bzip in the mailing list
AFAIK there is a limit of 60KB on this mailing list
e.g. you will receive an Email
Is being held until the list moderator can review it for approval.
The reason it is being held:
Message body is too big: xxxxx bytes with a limit of 60 KB
Either the message will get posted to the list, or you will receive notification of the moderator's decision.
2009/12/28 Chris cpollock@embarqmail.com
On Sun, 2009-12-27 at 09:39 +0800, Raymond Yau wrote:
You have to provide the full pulseaudio log in order to find out which application cause the problem
Where should I post this log Raymond? I can bzip it and post here if that's allowed.
-- KeyID 0xE372A7DA98E6705C
Alsa-devel mailing list Alsa-devel@alsa-project.org http://mailman.alsa-project.org/mailman/listinfo/alsa-devel
On Mon, 2009-12-28 at 13:14 +0800, Raymond Yau wrote:
Do you mean that you cannot find a test case to reproduce the bug ?
Not exactly, for instance 20 seconds after freshclam ran I see this in my syslog:
Dec 28 21:26:30 localhost pulseaudio[11266]: ratelimit.c: 52 events suppressed Dec 28 21:26:30 localhost pulseaudio[11266]: asyncq.c: q overrun, queuing locally Dec 28 21:26:30 localhost last message repeated 10 times
then this:
Dec 28 21:27:24 localhost pulseaudio[11266]: asyncq.c: q overrun, queuing locally Dec 28 21:27:24 localhost last message repeated 10 times Dec 28 21:27:37 localhost pulseaudio[11266]: alsa-util.c: snd_pcm_avail() returned a value that is exceptionally large: 839968 bytes (4761 ms).
The above is while the drive was 'thrashing' for a couple of minutes
I've also determined via experimentation that with pulseaudio running copying a 1.2Gb file to a thumb drive takes an average of 30minutes. This what I've done:
1. Using Gnome Commander I attempted to copy the 1.2 Gb file to a thumb drive, after about 30 minutes I had to stop the transfer at about 35%. 2. Disabled pulseaudio in Mandriva command center, logged out and back in again. 3. Again tried to copy the save file to the thumb drive, this time it took about 3 minutes. 4. Re-enabled pulseaudio and again tried to copy the file, this time using pulseaudio -k ; pulseaudio -vvvv on the command line. I saw outputs like this:
W: asyncq.c: q overrun, queuing locally W: asyncq.c: q overrun, queuing locally W: asyncq.c: q overrun, queuing locally W: asyncq.c: q overrun, queuing locally W: asyncq.c: q overrun, queuing locally W: asyncq.c: q overrun, queuing locally W: asyncq.c: q overrun, queuing locally W: asyncq.c: q overrun, queuing locally W: asyncq.c: q overrun, queuing locally W: asyncq.c: q overrun, queuing locally W: asyncq.c: q overrun, queuing locally W: ratelimit.c: 600 events suppressed
I have the complete log as a 15k bziped file. Can it be sent to the list?
Chris
Refer to the pulseaudio log which you have posted to pulseaudio mailing list
1) what is the buffer time used to calculate the sleeping time ?
I: alsa-sink.c: Using 3.0 fragments of size 6396 bytes (33.31ms), buffer size is 19188 bytes (99.94ms)
D: alsa-util.c: Maximum hw buffer size is 341 ms
I: alsa-sink.c: Using 3.0 fragments of size 6396 bytes (33.31ms), buffer size is 19188 bytes (99.94ms) D: alsa-sink.c: hwbuf_unused=0 D: alsa-sink.c: setting avail_min=1 D: alsa-mixer.c: Activating path analog-output D: alsa-mixer.c: Path analog-output (Analog Output), direction=1, priority=100, probed=yes, supported=yes, has_mute=yes, has_volume=yes, has_dB=yes, min_volume=0, max_volume=31, min_dB=-127.5, max_dB=12 D: alsa-mixer.c: Element Master, direction=1, switch=1, volume=1, enumeration=0, required=0, required_absent=0, mask=0x3600000000f66, n_channels=2, override_map=yes D: alsa-mixer.c: Element Master Mono, direction=1, switch=2, volume=2, enumeration=0, required=0, required_absent=0, mask=0x7ffffffffffff, n_channels=1, override_map=no D: alsa-mixer.c: Element Surround, direction=1, switch=1, volume=1, enumeration=0, required=0, required_absent=0, mask=0x60, n_channels=2, override_map=yes D: alsa-mixer.c: Element Center, direction=1, switch=1, volume=1, enumeration=0, required=0, required_absent=0, mask=0x4900000000018, n_channels=1, override_map=yes D: alsa-mixer.c: Element LFE, direction=1, switch=1, volume=1, enumeration=0, required=0, required_absent=0, mask=0x80, n_channels=1, override_map=yes D: alsa-mixer.c: Element PCM, direction=1, switch=1, volume=1, enumeration=0, required=0, required_absent=0, mask=0x402b600000000f66, n_channels=2, override_map=yes D: alsa-mixer.c: Element External Amplifier, direction=1, switch=4, volume=0, enumeration=0, required=0, required_absent=0, mask=0x0, n_channels=0, override_map=no D: alsa-mixer.c: Option on (output-amplifier-on/Amplifier) index=1, priority=10 D: alsa-mixer.c: Option off (output-amplifier-off/No Amplifier) index=0, priority=0 D: alsa-mixer.c: Setting output-amplifier-on (Amplifier) priority=10 D: alsa-mixer.c: Setting output-amplifier-off (No Amplifier) priority=0 I: alsa-sink.c: Hardware volume ranges from -127.50 dB to 12.00 dB. I: alsa-sink.c: Fixing base volume to -12.00 dB I: alsa-sink.c: Using hardware volume control. Hardware dB scale supported. I: alsa-sink.c: Using hardware mute control. D: alsa-util.c: snd_pcm_dump(): D: alsa-util.c: Hardware PCM card 0 'VIA 8237' device 0 subdevice 0 D: alsa-util.c: Its setup is: D: alsa-util.c: stream : PLAYBACK D: alsa-util.c: access : MMAP_INTERLEAVED D: alsa-util.c: format : S16_LE D: alsa-util.c: subformat : STD D: alsa-util.c: channels : 2 D: alsa-util.c: rate : 48000 D: alsa-util.c: exact rate : 48000 (48000/1) D: alsa-util.c: msbits : 16 D: alsa-util.c: buffer_size : 4797 D: alsa-util.c: period_size : 1599 D: alsa-util.c: period_time : 33312 D: alsa-util.c: tstamp_mode : ENABLE D: alsa-util.c: period_step : 1 D: alsa-util.c: avail_min : 1599 D: alsa-util.c: period_event : 0 D: alsa-util.c: start_threshold : -1 D: alsa-util.c: stop_threshold : 1257504768 D: alsa-util.c: silence_threshold: 0 D: alsa-util.c: silence_size : 0 D: alsa-util.c: boundary : 1257504768 D: alsa-util.c: appl_ptr : 0 D: alsa-util.c: hw_ptr : 0 D: alsa-sink.c: Thread starting up D: alsa-sink.c: Requested volume: 0: 39% 1: 39% D: alsa-sink.c: Got hardware volume: 0: 40% 1: 40% D: alsa-sink.c: Calculated software volume: 0: 97% 1: 97% (accurate-enough=no) D: core-util.c: RealtimeKit worked. I: core-util.c: Successfully enabled SCHED_RR scheduling for thread, with priority 5. I: alsa-sink.c: Starting playback. D: alsa-util.c: Trying front:0 with SND_PCM_NO_AUTO_FORMAT ... D: alsa-util.c: Managed to open front:0 D: alsa-util.c: Maximum hw buffer size is 341 ms D: alsa-util.c: Set buffer size first, period size second. I: alsa-util.c: Device front:0 doesn't support 44100 Hz, changed to 48000 Hz. I: alsa-source.c: Successfully opened device front:0. I: alsa-source.c: Selected mapping 'Analog Stereo' (analog-stereo). I: alsa-source.c: Successfully enabled mmap() mode. I: (alsa-lib)control.c: Invalid CTL front:0 I: alsa-mixer.c: Unable to attach to mixer front:0: No such file or directory I: alsa-mixer.c: Successfully attached to mixer 'hw:0'
2) I: (alsa-lib)setup.c: Cannot lock ctl elem
D: alsa-mixer.c: Checking for recording on Analog Mono (analog-mono) D: alsa-util.c: Trying hw:1 with SND_PCM_NO_AUTO_FORMAT ... D: alsa-util.c: Managed to open hw:1 D: alsa-util.c: Maximum hw buffer size is 743 ms D: alsa-util.c: Set buffer size first, period size second. I: alsa-util.c: Device hw:1 doesn't support 44100 Hz, changed to 44099 Hz. D: alsa-mixer.c: Profile output:iec958-stereo+input:analog-mono supported. D: alsa-mixer.c: Looking at profile output:iec958-stereo+input:analog-stereo D: alsa-mixer.c: Checking for recording on Analog Stereo (analog-stereo) D: alsa-util.c: Trying front:1 with SND_PCM_NO_AUTO_FORMAT ... D: alsa-util.c: Managed to open front:1 D: alsa-util.c: Maximum hw buffer size is 371 ms D: alsa-util.c: Set buffer size first, period size second. I: alsa-util.c: Device front:1 doesn't support 44100 Hz, changed to 44099 Hz. D: alsa-mixer.c: Profile output:iec958-stereo+input:analog-stereo supported. D: alsa-mixer.c: Looking at profile output:iec958-stereo+input:iec958-stereo D: alsa-mixer.c: Checking for recording on Digital Stereo (IEC958) (iec958-stereo) D: alsa-util.c: Trying iec958:1 with SND_PCM_NO_AUTO_FORMAT ... D: alsa-util.c: Managed to open iec958:1 D: alsa-util.c: Maximum hw buffer size is 371 ms I: (alsa-lib)setup.c: Cannot lock ctl elem I: (alsa-lib)setup.c: Cannot lock ctl elem I: (alsa-lib)setup.c: Cannot lock ctl elem I: (alsa-lib)setup.c: Cannot lock ctl elem D: alsa-util.c: Set neither period nor buffer size. I: (alsa-lib)setup.c: Cannot lock ctl elem I: alsa-util.c: snd_pcm_hw_params failed: Device or resource busy D: alsa-util.c: Trying iec958:1 without SND_PCM_NO_AUTO_FORMAT ... D: alsa-util.c: Managed to open iec958:1 D: alsa-util.c: Maximum hw buffer size is 371 ms I: (alsa-lib)setup.c: Cannot lock ctl elem I: (alsa-lib)setup.c: Cannot lock ctl elem I: (alsa-lib)setup.c: Cannot lock ctl elem I: (alsa-lib)setup.c: Cannot lock ctl elem D: alsa-util.c: Set neither period nor buffer size. I: (alsa-lib)setup.c: Cannot lock ctl elem I: alsa-util.c: snd_pcm_hw_params failed: Device or resource busy D: alsa-util.c: Trying plug:iec958:1 with SND_PCM_NO_AUTO_FORMAT ... D: alsa-util.c: Managed to open plug:iec958:1 D: alsa-util.c: Maximum hw buffer size is 371 ms I: (alsa-lib)setup.c: Cannot lock ctl elem I: (alsa-lib)setup.c: Cannot lock ctl elem I: (alsa-lib)setup.c: Cannot lock ctl elem I: (alsa-lib)setup.c: Cannot lock ctl elem D: alsa-util.c: Set neither period nor buffer size. I: (alsa-lib)setup.c: Cannot lock ctl elem I: alsa-util.c: snd_pcm_hw_params failed: Device or resource busy D: alsa-util.c: Trying plug:iec958:1 without SND_PCM_NO_AUTO_FORMAT ... D: alsa-util.c: Managed to open plug:iec958:1 D: alsa-util.c: Maximum hw buffer size is 371 ms I: (alsa-lib)setup.c: Cannot lock ctl elem I: (alsa-lib)setup.c: Cannot lock ctl elem I: (alsa-lib)setup.c: Cannot lock ctl elem I: (alsa-lib)setup.c: Cannot lock ctl elem D: alsa-util.c: Set neither period nor buffer size. I: (alsa-lib)setup.c: Cannot lock ctl elem I: alsa-util.c: snd_pcm_hw_params failed: Device or resource busy
3) W: asyncq.c: q overrun, queuing locally D: memblock.c: Pool full
is not related to "alsa-util.c : snd_pcm_avail() returned a value that is exceptionally large" since this message did not appear in your pulseaudio.log
W: asyncq.c: q overrun, queuing locally W: asyncq.c: q overrun, queuing locally W: asyncq.c: q overrun, queuing locally W: asyncq.c: q overrun, queuing locally W: asyncq.c: q overrun, queuing locally D: memblock.c: Pool full W: asyncq.c: q overrun, queuing locally W: ratelimit.c: 794 events suppressed W: asyncq.c: q overrun, queuing locally W: asyncq.c: q overrun, queuing locally W: asyncq.c: q overrun, queuing locally W: asyncq.c: q overrun, queuing locally D: memblock.c: Pool full D: memblock.c: Pool full D: memblock.c: Pool full W: asyncq.c: q overrun, queuing locally W: asyncq.c: q overrun, queuing locally W: asyncq.c: q overrun, queuing locally W: asyncq.c: q overrun, queuing locally W: ratelimit.c: 819 events suppressed W: asyncq.c: q overrun, queuing locally W: asyncq.c: q overrun, queuing locally W: asyncq.c: q overrun, queuing locally
2009/12/29 Chris cpollock@embarqmail.com
On Mon, 2009-12-28 at 13:14 +0800, Raymond Yau wrote:
Do you mean that you cannot find a test case to reproduce the bug ?
Not exactly, for instance 20 seconds after freshclam ran I see this in my syslog:
Dec 28 21:26:30 localhost pulseaudio[11266]: ratelimit.c: 52 events suppressed Dec 28 21:26:30 localhost pulseaudio[11266]: asyncq.c: q overrun, queuing locally Dec 28 21:26:30 localhost last message repeated 10 times
then this:
Dec 28 21:27:24 localhost pulseaudio[11266]: asyncq.c: q overrun, queuing locally Dec 28 21:27:24 localhost last message repeated 10 times Dec 28 21:27:37 localhost pulseaudio[11266]: alsa-util.c: snd_pcm_avail() returned a value that is exceptionally large: 839968 bytes (4761 ms).
The above is while the drive was 'thrashing' for a couple of minutes
I've also determined via experimentation that with pulseaudio running copying a 1.2Gb file to a thumb drive takes an average of 30minutes. This what I've done:
- Using Gnome Commander I attempted to copy the 1.2 Gb file to a thumb
drive, after about 30 minutes I had to stop the transfer at about 35%. 2. Disabled pulseaudio in Mandriva command center, logged out and back in again. 3. Again tried to copy the save file to the thumb drive, this time it took about 3 minutes. 4. Re-enabled pulseaudio and again tried to copy the file, this time using pulseaudio -k ; pulseaudio -vvvv on the command line. I saw outputs like this:
W: asyncq.c: q overrun, queuing locally W: asyncq.c: q overrun, queuing locally W: asyncq.c: q overrun, queuing locally W: asyncq.c: q overrun, queuing locally W: asyncq.c: q overrun, queuing locally W: asyncq.c: q overrun, queuing locally W: asyncq.c: q overrun, queuing locally W: asyncq.c: q overrun, queuing locally W: asyncq.c: q overrun, queuing locally W: asyncq.c: q overrun, queuing locally W: asyncq.c: q overrun, queuing locally W: ratelimit.c: 600 events suppressed
I have the complete log as a 15k bziped file. Can it be sent to the list?
Chris
-- KeyID 0xE372A7DA98E6705C
Alsa-devel mailing list Alsa-devel@alsa-project.org http://mailman.alsa-project.org/mailman/listinfo/alsa-devel
Please post the output of alsa-info.sh
Do your VIA 8237/ens1371 has any digital output/input ?
D: alsa-util.c: Trying iec958:0 with SND_PCM_NO_AUTO_FORMAT ... I: alsa-util.c: Error opening PCM device iec958:0: Device or resource busy ... D: alsa-mixer.c: Checking for recording on Digital Stereo (IEC958) (iec958-stereo) D: alsa-util.c: Trying iec958:0 with SND_PCM_NO_AUTO_FORMAT ... I: alsa-util.c: Error opening PCM device iec958:0: Device or resource busy ... D: alsa-mixer.c: Looking at profile output:analog-surround-40+input:iec958-surround-40 D: alsa-mixer.c: Checking for recording on Digital Surround 4.0 (IEC958) (iec958-surround-40) D: alsa-util.c: Trying iec958:0 with SND_PCM_NO_AUTO_FORMAT ... I: alsa-util.c: Error opening PCM device iec958:0: Device or resource busy
Why do PA server try to open an non-existing device iec958 so many times ?
Have the PA developer ever tested those profiles on their machines " recording on Digital Surround 4.0 (IEC958) (iec958-surround-40)" ?
D: alsa-mixer.c: Looking at profile output:analog-surround-71 D: alsa-mixer.c: Checking for playback on Analog Surround 7.1 (analog-surround-71) D: alsa-util.c: Trying surround71:0 with SND_PCM_NO_AUTO_FORMAT ... I: (alsa-lib)conf.c: Unknown parameters 0 I: (alsa-lib)pcm.c: Unknown PCM surround71:0
Did PA server check any error when open those device ?
it is quite strange that PA still call snd_pcm_hw_params() when there is error "Cannot lock ctl elem" ?
D: alsa-mixer.c: Checking for recording on Digital Stereo (IEC958) (iec958-stereo) D: alsa-util.c: Trying iec958:1 with SND_PCM_NO_AUTO_FORMAT ... D: alsa-util.c: Managed to open iec958:1 D: alsa-util.c: Maximum hw buffer size is 371 ms I: (alsa-lib)setup.c: Cannot lock ctl elem I: (alsa-lib)setup.c: Cannot lock ctl elem I: (alsa-lib)setup.c: Cannot lock ctl elem I: (alsa-lib)setup.c: Cannot lock ctl elem D: alsa-util.c: Set neither period nor buffer size.
Cannot obtain info for CTL elem (MIXER,'AC97 2ch->4ch Copy Switch',0,0,0): No such file or directory
D: alsa-util.c: Trying surround40:1 with SND_PCM_NO_AUTO_FORMAT ... I: (alsa-lib)setup.c: Cannot obtain info for CTL elem (MIXER,'AC97 2ch->4ch Copy Switch',0,0,0): No such file or directory I: alsa-util.c: Error opening PCM device surround40:1: No such file or directory D: alsa-mixer.c: Looking at profile output:analog-surround-40+input:analog-mono D: alsa-mixer.c: Checking for playback on Analog Surround 4.0 (analog-surround-40) D: alsa-util.c: Trying surround40:1 with SND_PCM_NO_AUTO_FORMAT ... I: (alsa-lib)setup.c: Cannot obtain info for CTL elem (MIXER,'AC97 2ch->4ch Copy Switch',0,0,0): No such file or directory I: alsa-util.c: Error opening PCM device surround40:1: No such file or directory D: alsa-mixer.c: Looking at profile output:analog-surround-40+input:analog-stereo D: alsa-mixer.c: Checking for playback on Analog Surround 4.0 (analog-surround-40) D: alsa-util.c: Trying surround40:1 with SND_PCM_NO_AUTO_FORMAT ... I: (alsa-lib)setup.c: Cannot obtain info for CTL elem (MIXER,'AC97 2ch->4ch Copy Switch',0,0,0): No such file or directory I: alsa-util.c: Error opening PCM device surround40:1: No such file or directory D: alsa-mixer.c: Looking at profile output:analog-surround-40+input:iec958-stereo D: alsa-mixer.c: Checking for playback on Analog Surround 4.0 (analog-surround-40) D: alsa-util.c: Trying surround40:1 with SND_PCM_NO_AUTO_FORMAT ... I: (alsa-lib)setup.c: Cannot obtain info for CTL elem (MIXER,'AC97 2ch->4ch Copy Switch',0,0,0): No such file or directory I: alsa-util.c: Error opening PCM device surround40:1: No such file or directory D: alsa-mixer.c: Looking at profile output:analog-surround-40+input:iec958-surround-40 D: alsa-mixer.c: Checking for playback on Analog Surround 4.0 (analog-surround-40) D: alsa-util.c: Trying surround40:1 with SND_PCM_NO_AUTO_FORMAT ... I: (alsa-lib)setup.c: Cannot obtain info for CTL elem (MIXER,'AC97 2ch->4ch Copy Switch',0,0,0): No such file or directory I: alsa-util.c: Error opening PCM device surround40:1: No such file or directory D: alsa-mixer.c: Looking at profile output:analog-surround-41 D: alsa-mixer.c: Checking for playback on Analog Surround 4.1 (analog-surround-41) D: alsa-util.c: Trying surround41:1 with SND_PCM_NO_AUTO_FORMAT ... I: (alsa-lib)confmisc.c: Unable to find definition 'cards.ENS1371.pcm.surround51.0:CARD=1' I: (alsa-lib)conf.c: function snd_func_refer returned error: No such file or directory I: (alsa-lib)conf.c: Evaluate error: No such file or directory
D: alsa-mixer.c: Checking for playback on Analog Surround 5.0 (analog-surround-50) D: alsa-util.c: Trying surround50:1 with SND_PCM_NO_AUTO_FORMAT ... I: (alsa-lib)confmisc.c: Unable to find definition 'cards.ENS1371.pcm.surround51.0:CARD=1' I: (alsa-lib)conf.c: function snd_func_refer returned error: No such file or directory I: (alsa-lib)conf.c: Evaluate error: No such file or directory I: (alsa-lib)pcm.c: Unknown PCM surround50:1 I: alsa-util.c: Error opening PCM device surround50:1: No such file or directory D: alsa-mixer.c: Looking at profile output:analog-surround-50+input:analog-stereo D: alsa-mixer.c: Checking for playback on Analog Surround 5.0 (analog-surround-50) D: alsa-util.c: Trying surround50:1 with SND_PCM_NO_AUTO_FORMAT ... I: (alsa-lib)confmisc.c: Unable to find definition 'cards.ENS1371.pcm.surround51.0:CARD=1' I: (alsa-lib)conf.c: function snd_func_refer returned error: No such file or directory I: (alsa-lib)conf.c: Evaluate error: No such file or directory I: (alsa-lib)pcm.c: Unknown PCM surround50:1 I: alsa-util.c: Error opening PCM device surround50:1: No such file or directory D: alsa-mixer.c: Looking at profile output:analog-surround-50+input:iec958-stereo D: alsa-mixer.c: Checking for playback on Analog Surround 5.0 (analog-surround-50) D: alsa-util.c: Trying surround50:1 with SND_PCM_NO_AUTO_FORMAT ... I: (alsa-lib)confmisc.c: Unable to find definition 'cards.ENS1371.pcm.surround51.0:CARD=1' I: (alsa-lib)conf.c: function snd_func_refer returned error: No such file or directory I: (alsa-lib)conf.c: Evaluate error: No such file or directory I: (alsa-lib)pcm.c: Unknown PCM surround50:1 I: alsa-util.c: Error opening PCM device surround50:1: No such file or directory D: alsa-mixer.c: Looking at profile output:analog-surround-50+input:iec958-surround-40 D: alsa-mixer.c: Checking for playback on Analog Surround 5.0 (analog-surround-50) D: alsa-util.c: Trying surround50:1 with SND_PCM_NO_AUTO_FORMAT ... I: (alsa-lib)confmisc.c: Unable to find definition 'cards.ENS1371.pcm.surround51.0:CARD=1' I: (alsa-lib)conf.c: function snd_func_refer returned error: No such file or directory I: (alsa-lib)conf.c: Evaluate error: No such file or directory I: (alsa-lib)pcm.c: Unknown PCM surround50:1 I: alsa-util.c: Error opening PCM device surround50:1: No such file or directory D: alsa-mixer.c: Looking at profile output:analog-surround-51 D: alsa-mixer.c: Checking for playback on Analog Surround 5.1 (analog-surround-51) D: alsa-util.c: Trying surround51:1 with SND_PCM_NO_AUTO_FORMAT ... I: (alsa-lib)confmisc.c: Unable to find definition 'cards.ENS1371.pcm.surround51.0:CARD=1' I: (alsa-lib)conf.c: function snd_func_refer returned error: No such file or directory I: (alsa-lib)conf.c: Evaluate error: No such file or directory I: (alsa-lib)pcm.c: Unknown PCM surround51:1 I: alsa-util.c: Error opening PCM device surround51:1: No such file or directory D: alsa-mixer.c: Looking at profile output:analog-surround-51+input:analog-mono D: alsa-mixer.c: Checking for playback on Analog Surround 5.1 (analog-surround-51) D: alsa-util.c: Trying surround51:1 with SND_PCM_NO_AUTO_FORMAT ... I: (alsa-lib)confmisc.c: Unable to find definition 'cards.ENS1371.pcm.surround51.0:CARD=1' I: (alsa-lib)conf.c: function snd_func_refer returned error: No such file or directory I: (alsa-lib)conf.c: Evaluate error: No such file or directory I: (alsa-lib)pcm.c: Unknown PCM surround51:1 I: alsa-util.c: Error opening PCM device surround51:1: No such file or directory D: alsa-mixer.c: Looking at profile output:analog-surround-51+input:analog-stereo D: alsa-mixer.c: Checking for playback on Analog Surround 5.1 (analog-surround-51) D: alsa-util.c: Trying surround51:1 with SND_PCM_NO_AUTO_FORMAT ... I: (alsa-lib)confmisc.c: Unable to find definition 'cards.ENS1371.pcm.surround51.0:CARD=1' I: (alsa-lib)conf.c: function snd_func_refer returned error: No such file or directory I: (alsa-lib)conf.c: Evaluate error: No such file or directory I: (alsa-lib)pcm.c: Unknown PCM surround51:1 I: alsa-util.c: Error opening PCM device surround51:1: No such file or directory D: alsa-mixer.c: Looking at profile output:analog-surround-51+input:iec958-stereo D: alsa-mixer.c: Checking for playback on Analog Surround 5.1 (analog-surround-51) D: alsa-util.c: Trying surround51:1 with SND_PCM_NO_AUTO_FORMAT ... I: (alsa-lib)confmisc.c: Unable to find definition 'cards.ENS1371.pcm.surround51.0:CARD=1' I: (alsa-lib)conf.c: function snd_func_refer returned error: No such file or directory I: (alsa-lib)conf.c: Evaluate error: No such file or directory I: (alsa-lib)pcm.c: Unknown PCM surround51:1 I: alsa-util.c: Error opening PCM device surround51:1: No such file or directory D: alsa-mixer.c: Looking at profile output:analog-surround-51+input:iec958-surround-40 D: alsa-mixer.c: Checking for playback on Analog Surround 5.1 (analog-surround-51) D: alsa-util.c: Trying surround51:1 with SND_PCM_NO_AUTO_FORMAT ... I: (alsa-lib)confmisc.c: Unable to find definition 'cards.ENS1371.pcm.surround51.0:CARD=1' I: (alsa-lib)conf.c: function snd_func_refer returned error: No such file or directory I: (alsa-lib)conf.c: Evaluate error: No such file or directory I: (alsa-lib)pcm.c: Unknown PCM surround51:1 I: alsa-util.c: Error opening PCM device surround51:1: No such file or directory D: alsa-mixer.c: Looking at profile output:analog-surround-71 D: alsa-mixer.c: Checking for playback on Analog Surround 7.1 (analog-surround-71) D: alsa-util.c: Trying surround71:1 with SND_PCM_NO_AUTO_FORMAT ... I: (alsa-lib)conf.c: Unknown parameters 1 I: (alsa-lib)pcm.c: Unknown PCM surround71:1 I: alsa-util.c: Error opening PCM device surround71:1: Invalid argument
2009/12/29 Chris cpollock@embarqmail.com
On Mon, 2009-12-28 at 13:14 +0800, Raymond Yau wrote:
Do you mean that you cannot find a test case to reproduce the bug ?
Not exactly, for instance 20 seconds after freshclam ran I see this in my syslog:
Dec 28 21:26:30 localhost pulseaudio[11266]: ratelimit.c: 52 events suppressed Dec 28 21:26:30 localhost pulseaudio[11266]: asyncq.c: q overrun, queuing locally Dec 28 21:26:30 localhost last message repeated 10 times
then this:
Dec 28 21:27:24 localhost pulseaudio[11266]: asyncq.c: q overrun, queuing locally Dec 28 21:27:24 localhost last message repeated 10 times Dec 28 21:27:37 localhost pulseaudio[11266]: alsa-util.c: snd_pcm_avail() returned a value that is exceptionally large: 839968 bytes (4761 ms).
The above is while the drive was 'thrashing' for a couple of minutes
I've also determined via experimentation that with pulseaudio running copying a 1.2Gb file to a thumb drive takes an average of 30minutes. This what I've done:
- Using Gnome Commander I attempted to copy the 1.2 Gb file to a thumb
drive, after about 30 minutes I had to stop the transfer at about 35%. 2. Disabled pulseaudio in Mandriva command center, logged out and back in again. 3. Again tried to copy the save file to the thumb drive, this time it took about 3 minutes. 4. Re-enabled pulseaudio and again tried to copy the file, this time using pulseaudio -k ; pulseaudio -vvvv on the command line. I saw outputs like this:
W: asyncq.c: q overrun, queuing locally W: asyncq.c: q overrun, queuing locally W: asyncq.c: q overrun, queuing locally W: asyncq.c: q overrun, queuing locally W: asyncq.c: q overrun, queuing locally W: asyncq.c: q overrun, queuing locally W: asyncq.c: q overrun, queuing locally W: asyncq.c: q overrun, queuing locally W: asyncq.c: q overrun, queuing locally W: asyncq.c: q overrun, queuing locally W: asyncq.c: q overrun, queuing locally W: ratelimit.c: 600 events suppressed
I have the complete log as a 15k bziped file. Can it be sent to the list?
Chris
-- KeyID 0xE372A7DA98E6705C
Alsa-devel mailing list Alsa-devel@alsa-project.org http://mailman.alsa-project.org/mailman/listinfo/alsa-devel
2009/12/31 Chris cpollock@embarqmail.com
On Wed, 2009-12-30 at 15:07 +0800, Raymond Yau wrote:
Please post the output of alsa-info.sh
Raymond, I can't seem to locate that script.
http://git.alsa-project.org/?p=alsa-driver.git;a=blob_plain;f=utils/alsa-inf...
Do your VIA 8237/ens1371 has any digital output/input ?
That I can't answer
Do your motherboard/sound card has optical/coaxial spdif ?
Sorry, not much help I know
-- KeyID 0xE372A7DA98E6705C
Did PA developer tell you the meaning of those messages ?
D: memblock.c: Pool full
and
W: asyncq.c: q overrun, queuing locally
There are another message which need the PA developer to explain the meaning of "Underrun on "*/*.ogg" 0 bytes in queue "
D: protocol-native.c: Requesting rewind due to end of underrun. D: alsa-sink.c: Requested to rewind 17632 bytes. D: alsa-sink.c: Limited to 17600 bytes. D: alsa-sink.c: before: 4400 D: alsa-sink.c: after: 4400 D: alsa-sink.c: Rewound 17600 bytes. D: sink.c: Processing rewind... D: sink-input.c: Have to rewind 17600 bytes on render memblockq. D: source.c: Processing rewind... D: protocol-native.c: Underrun on '/usr/share/sounds/gnome/default/alerts/sonar.ogg', 0 bytes in queue.
On Thu, 2009-12-31 at 12:20 +0800, Raymond Yau wrote:
2009/12/31 Chris cpollock@embarqmail.com
On Wed, 2009-12-30 at 15:07 +0800, Raymond Yau wrote:
Please post the output of alsa-info.sh
Raymond, I can't seem to locate that script.
http://git.alsa-project.org/?p=alsa-driver.git;a=blob_plain;f=utils/alsa-inf...
Thank you, see attached script output.
Do your VIA 8237/ens1371 has any digital output/input ?
That I can't answer
Do your motherboard/sound card has optical/coaxial spdif ?
Not that I can see.
2009/12/31 Chris cpollock@embarqmail.com
On Thu, 2009-12-31 at 12:20 +0800, Raymond Yau wrote:
2009/12/31 Chris cpollock@embarqmail.com
On Wed, 2009-12-30 at 15:07 +0800, Raymond Yau wrote:
Please post the output of alsa-info.sh
Raymond, I can't seem to locate that script.
http://git.alsa-project.org/?p=alsa-driver.git;a=blob_plain;f=utils/alsa-inf...
Thank you, see attached script output.
Do your VIA 8237/ens1371 has any digital output/input ?
That I can't answer
Do your motherboard/sound card has optical/coaxial spdif ?
Not that I can see.
D: alsa-mixer.c: Checking for playback on Analog Mono (analog-mono) D: alsa-util.c: Trying hw:0 with SND_PCM_NO_AUTO_FORMAT ... D: alsa-util.c: Managed to open hw:0 D: alsa-util.c: Maximum hw buffer size is 682 ms D: alsa-util.c: Set buffer size first, period size second. I: alsa-util.c: Device hw:0 doesn't support 44100 Hz, changed to 48000 Hz.
http://git.alsa-project.org/?p=alsa-kernel.git;a=blob_plain;f=Documentation/...
Module snd-via82xx ------------------
Note: VIA8233/5/7 (not VIA8233A) can support DXS (direct sound) channels as the first PCM. On these channels, up to 4 streams can be played at the same time, and the controller can perform sample rate conversion with separate rates for each channel. As default (dxs_support = 0), 48k fixed rate is chosen except for the known devices since the output is often noisy except for 48k on some mother boards due to the bug of BIOS. Please try once dxs_support=5 and if it works on other sample rates (e.g. 44.1kHz of mp3 playback), please let us know the PCI subsystem vendor/device id's (output of "lspci -nv"). If dxs_support=5 does not work, try dxs_support=4; if it doesn't work too, try dxs_support=1. (dxs_support=1 is usually for old motherboards. The correct implemented board should work with 4 or 5.) If it still doesn't work and the default setting is ok, dxs_support=3 is the right choice. If the default setting doesn't work at all, try dxs_support=2 to disable the DXS channels. In any cases, please let us know the result and the subsystem vendor/device ids. See "Links and Addresses" below.
APLAY
**** List of PLAYBACK Hardware Devices **** card 0: V8237 [VIA 8237], device 0: VIA 8237 [VIA 8237] Subdevices: 4/4 Subdevice #0: subdevice #0 Subdevice #1: subdevice #1 Subdevice #2: subdevice #2 Subdevice #3: subdevice #3 card 0: V8237 [VIA 8237], device 1: VIA 8237 [VIA 8237] Subdevices: 1/1
2009/12/31 Chris cpollock@embarqmail.com
On Thu, 2009-12-31 at 12:20 +0800, Raymond Yau wrote:
2009/12/31 Chris cpollock@embarqmail.com
On Wed, 2009-12-30 at 15:07 +0800, Raymond Yau wrote:
Please post the output of alsa-info.sh
Raymond, I can't seem to locate that script.
http://git.alsa-project.org/?p=alsa-driver.git;a=blob_plain;f=utils/alsa-inf...
Thank you, see attached script output.
Do your VIA 8237/ens1371 has any digital output/input ?
That I can't answer
Do your motherboard/sound card has optical/coaxial spdif ?
Not that I can see.
With four subdevices in playback device 0 , you should able to run two or instance of aplay hw:0,0 concurrently as described in
http://pulseaudio.org/ticket/743#comment:2
1) Terminal 1: pasuspender cat
2) Terminal 2: aplay -D hw:0,0
3) Terminal 3: aplay -D hw:0,0 (again!)
APLAY
**** List of PLAYBACK Hardware Devices **** card 0: V8237 [VIA 8237], device 0: VIA 8237 [VIA 8237] Subdevices: 4/4 Subdevice #0: subdevice #0 Subdevice #1: subdevice #1 Subdevice #2: subdevice #2 Subdevice #3: subdevice #3
'Twas brillig, and Raymond Yau at 30/12/09 07:07 did gyre and gimble:
Why do PA server try to open an non-existing device iec958 so many times ?
It has to try and open the device several times to probe for available profiles. This is only done at startup and then cached for the duration of the run in the form of a list of available profiles.
Col
2009/12/31 Colin Guthrie gmane@colin.guthr.ie
'Twas brillig, and Raymond Yau at 30/12/09 07:07 did gyre and gimble:
Why do PA server try to open an non-existing device iec958 so many times
?
It has to try and open the device several times to probe for available profiles. This is only done at startup and then cached for the duration of the run in the form of a list of available profiles.
Col
--
what is the meaning of those messages in pulseaudio log ?
1) D: memblock.c: Pool full
2) W: asyncq.c: q overrun, queuing locally
3) D: protocol-native.c: Requesting rewind due to end of underrun.
4) D: alsa-sink.c: Requested to rewind 17632 bytes.
5) D: alsa-sink.c: Limited to 17600 bytes.
D: alsa-sink.c: before: 4400 D: alsa-sink.c: after: 4400 D: alsa-sink.c: Rewound 17600 bytes. D: sink.c: Processing rewind...
6) D: sink-input.c: Have to rewind 17600 bytes on render memblockq.
D: source.c: Processing rewind...
7) D: protocol-native.c: Underrun on '/usr/share/sounds/gnome/ default/alerts/sonar.ogg', 0 bytes in queue.
2009/12/31 Colin Guthrie gmane@colin.guthr.ie
'Twas brillig, and Raymond Yau at 30/12/09 07:07 did gyre and gimble:
Why do PA server try to open an non-existing device iec958 so many times
?
It has to try and open the device several times to probe for available profiles. This is only done at startup and then cached for the duration of the run in the form of a list of available profiles.
Col
D: alsa-mixer.c: Checking for recording on Digital Surround 4.0 (IEC958) (iec958-surround-40) D: alsa-util.c: Trying iec958:0 with SND_PCM_NO_AUTO_FORMAT ...
Refer to http://thread.gmane.org/gmane.linux.alsa.devel/53004/focus=53038
SPDIF is limited to 2 channels when using PCM. DTS/AC3 is the only way to get multi-channel out of SPDIF.
Have any PA developers really tested the "iec958-surround-40" profile on any machines ?
participants (3)
-
Chris -
Colin Guthrie -
Raymond Yau