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

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

[Chris]

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

Re: alsa-util.c: snd_pcm_avail() returned a value that is exceptionally large: 349696 bytes (1821 ms).

[Raymond Yau]

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
>

Re: alsa-util.c: snd_pcm_avail() returned a value that is exceptionally large: 349696 bytes (1821 ms).

[Chris]

[-- Attachment #1.1: Type: text/plain, Size: 327 bytes --]

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.


-- 
KeyID 0xE372A7DA98E6705C


[-- Attachment #1.2: This is a digitally signed message part --]
[-- Type: application/pgp-signature, Size: 198 bytes --]

[-- Attachment #2: Type: text/plain, Size: 160 bytes --]

_______________________________________________
Alsa-devel mailing list
Alsa-devel@alsa-project.org
http://mailman.alsa-project.org/mailman/listinfo/alsa-devel

Re: alsa-util.c: snd_pcm_avail() returned a value that is exceptionally large: 349696 bytes (1821 ms).

[Raymond Yau]

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.
>
>

Re: alsa-util.c: snd_pcm_avail() returned a value that is exceptionally large: 349696 bytes (1821 ms).

[Chris]

[-- Attachment #1.1: Type: text/plain, Size: 16665 bytes --]

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


-- 
KeyID 0xE372A7DA98E6705C


[-- Attachment #1.2: This is a digitally signed message part --]
[-- Type: application/pgp-signature, Size: 198 bytes --]

[-- Attachment #2: Type: text/plain, Size: 160 bytes --]

_______________________________________________
Alsa-devel mailing list
Alsa-devel@alsa-project.org
http://mailman.alsa-project.org/mailman/listinfo/alsa-devel

Re: alsa-util.c: snd_pcm_avail() returned a value that is exceptionally large: 349696 bytes (1821 ms).

[Raymond Yau]

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!

Re: alsa-util.c: snd_pcm_avail() returned a value that is exceptionally large: 349696 bytes (1821 ms).

[Raymond Yau]

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

Re: alsa-util.c: snd_pcm_avail() returned a value that is exceptionally large: 349696 bytes (1821 ms).

[Chris]

[-- Attachment #1.1: Type: text/plain, Size: 1783 bytes --]

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?



-- 
KeyID 0xE372A7DA98E6705C


[-- Attachment #1.2: This is a digitally signed message part --]
[-- Type: application/pgp-signature, Size: 198 bytes --]

[-- Attachment #2: Type: text/plain, Size: 160 bytes --]

_______________________________________________
Alsa-devel mailing list
Alsa-devel@alsa-project.org
http://mailman.alsa-project.org/mailman/listinfo/alsa-devel

Re: alsa-util.c: snd_pcm_avail() returned a value that is exceptionally large: 349696 bytes (1821 ms).

[Chris]

[-- Attachment #1.1: Type: text/plain, Size: 20281 bytes --]

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


-- 
KeyID 0xE372A7DA98E6705C


[-- Attachment #1.2: This is a digitally signed message part --]
[-- Type: application/pgp-signature, Size: 198 bytes --]

[-- Attachment #2: Type: text/plain, Size: 160 bytes --]

_______________________________________________
Alsa-devel mailing list
Alsa-devel@alsa-project.org
http://mailman.alsa-project.org/mailman/listinfo/alsa-devel

Re: alsa-util.c: snd_pcm_avail() returned a value that is exceptionally large: 349696 bytes (1821 ms).

[Raymond Yau]

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
>
>

Re: alsa-util.c: snd_pcm_avail() returned a value that is exceptionally large: 349696 bytes (1821 ms).

[Chris]

[-- Attachment #1.1: Type: text/plain, Size: 288 bytes --]

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


[-- Attachment #1.2: This is a digitally signed message part --]
[-- Type: application/pgp-signature, Size: 198 bytes --]

[-- Attachment #2: Type: text/plain, Size: 160 bytes --]

_______________________________________________
Alsa-devel mailing list
Alsa-devel@alsa-project.org
http://mailman.alsa-project.org/mailman/listinfo/alsa-devel

Re: alsa-util.c: snd_pcm_avail() returned a value that is exceptionally large: 349696 bytes (1821 ms).

[Raymond Yau]

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
>
>

Re: alsa-util.c: snd_pcm_avail() returned a value that is exceptionally large: 349696 bytes (1821 ms).

[Chris]

[-- Attachment #1.1: Type: text/plain, Size: 2074 bytes --]

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

-- 
KeyID 0xE372A7DA98E6705C


[-- Attachment #1.2: This is a digitally signed message part --]
[-- Type: application/pgp-signature, Size: 198 bytes --]

[-- Attachment #2: Type: text/plain, Size: 160 bytes --]

_______________________________________________
Alsa-devel mailing list
Alsa-devel@alsa-project.org
http://mailman.alsa-project.org/mailman/listinfo/alsa-devel

Re: alsa-util.c: snd_pcm_avail() returned a value that is exceptionally large: 349696 bytes (1821 ms).

[Raymond Yau]

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:
>
> 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
>
> --
> KeyID 0xE372A7DA98E6705C
>
>
> _______________________________________________
> Alsa-devel mailing list
> Alsa-devel@alsa-project.org
> http://mailman.alsa-project.org/mailman/listinfo/alsa-devel
>
>

Re: alsa-util.c: snd_pcm_avail() returned a value that is exceptionally large: 349696 bytes (1821 ms).

[Raymond Yau]

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:
>
> 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
>
> --
> KeyID 0xE372A7DA98E6705C
>
>
> _______________________________________________
> Alsa-devel mailing list
> Alsa-devel@alsa-project.org
> http://mailman.alsa-project.org/mailman/listinfo/alsa-devel
>
>

Re: alsa-util.c: snd_pcm_avail() returned a value that is exceptionally large: 349696 bytes (1821 ms).

[Chris]

[-- Attachment #1.1: Type: text/plain, Size: 291 bytes --]

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.
> Do your VIA 8237/ens1371 has any digital output/input ?
That I can't answer

Sorry, not much help I know


-- 
KeyID 0xE372A7DA98E6705C


[-- Attachment #1.2: This is a digitally signed message part --]
[-- Type: application/pgp-signature, Size: 198 bytes --]

[-- Attachment #2: Type: text/plain, Size: 160 bytes --]

_______________________________________________
Alsa-devel mailing list
Alsa-devel@alsa-project.org
http://mailman.alsa-project.org/mailman/listinfo/alsa-devel

Re: alsa-util.c: snd_pcm_avail() returned a value that is exceptionally large: 349696 bytes (1821 ms).

[Raymond Yau]

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-info.sh



> > 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.

Re: alsa-util.c: snd_pcm_avail() returned a value that is exceptionally large: 349696 bytes (1821 ms).

[Colin Guthrie]

'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

-- 

Colin Guthrie
gmane(at)colin.guthr.ie
http://colin.guthr.ie/

Day Job:
  Tribalogic Limited [http://www.tribalogic.net/]
Open Source:
  Mandriva Linux Contributor [http://www.mandriva.com/]
  PulseAudio Hacker [http://www.pulseaudio.org/]
  Trac Hacker [http://trac.edgewall.org/]

Re: alsa-util.c: snd_pcm_avail() returned a value that is exceptionally large: 349696 bytes (1821 ms).

[Chris]

[-- Attachment #1.1.1: Type: text/plain, Size: 625 bytes --]

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-info.sh
> 
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.




-- 
KeyID 0xE372A7DA98E6705C


[-- Attachment #1.1.2: alsa-info.txt.bz2 --]
[-- Type: application/x-bzip, Size: 5407 bytes --]

[-- Attachment #1.2: This is a digitally signed message part --]
[-- Type: application/pgp-signature, Size: 198 bytes --]

[-- Attachment #2: Type: text/plain, Size: 160 bytes --]

_______________________________________________
Alsa-devel mailing list
Alsa-devel@alsa-project.org
http://mailman.alsa-project.org/mailman/listinfo/alsa-devel

Re: alsa-util.c: snd_pcm_avail() returned a value that is exceptionally large: 349696 bytes (1821 ms).

[Raymond Yau]

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-info.sh
> >
> 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/sound/alsa/ALSA-Configuration.txt

  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

Re: alsa-util.c: snd_pcm_avail() returned a value that is exceptionally large: 349696 bytes (1821 ms).

[Raymond Yau]

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.

Re: alsa-util.c: snd_pcm_avail() returned a value that is exceptionally large: 349696 bytes (1821 ms).

[Raymond Yau]

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 ?

Re: alsa-util.c: snd_pcm_avail() returned a value that is exceptionally large: 349696 bytes (1821 ms).

[Raymond Yau]

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-info.sh
> >
> 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