[pulseaudio-discuss] Some issues with 0.9.16.
Colin Guthrie
gmane at colin.guthr.ie
Mon Aug 31 09:00:11 PDT 2009
'Twas brillig, and Colin Guthrie at 31/08/09 12:12 did gyre and gimble:
> 'Twas brillig, and Lennart Poettering at 28/08/09 15:39 did gyre and
> gimble:
>>> 3) I'm also seeing quite regularly a deadlock in pulse. This one is
>>> quite serious as it obviously freezes the display of most
>>> libcanberra apps :s See attached pulse-deadlock.txt
>>
>>> #0 0x00007f706ab57ea7 in mlock () from /lib64/libc.so.6
>>> #1 0x00007f706e2ef0d2 in pa_will_need (p=0xc300c300c300c3, l=<value
>>> optimized out>) at pulsecore/core-util.c:2140
>>> #2 0x00007f706e2fdbea in pa_memchunk_will_need (c=0x23cf0f8) at
>>> pulsecore/memchunk.c:88
>>> #3 0x00007f706e2fccb9 in pa_memblockq_willneed (bq=<value optimized
>>> out>) at pulsecore/memblockq.c:914
>>
>> [...]
>>
>>> 4 Thread 0x7f706a86b910 (LWP 9012) 0x00007f706ab51a47 in ppoll ()
>>> from /lib64/libc.so.6
>>> 3 Thread 0x7f70648f4910 (LWP 9016) 0x00007f706ab51a47 in ppoll ()
>>> from /lib64/libc.so.6
>>> 2 Thread 0x7f70640f3910 (LWP 9149) 0x00007f706ab51a47 in ppoll ()
>>> from /lib64/libc.so.6
>>> * 1 Thread 0x7f706ebba6f0 (LWP 8899) 0x00007f706ab57ea7 in mlock ()
>>> from /lib64/libc.so.6
>>
>> The IO threads are hanging in ppoll(), and are hence not
>> deadlocked. The main thread hangs in mlock(). Which is a fucntion that
>> locks memory into RAM. We use it as a dirty hack for making sure
>> cached samples are swapped back into RAM before we ask the IO threads
>> to play them. Normally, mlock() should just swap things in and lock
>> them. We then immediately call munlock(). If this freezes for you then
>> there is something really wrong with your kernel. I have not seen this
>> issue before.
>
> This seems be be behaving better with a new kernel... not had the
> problem again so far. I think the rc8 had some messed up inotify stuff
> which may explain it.
I spoke to soon. This seems to be related to some alsa bug. Here is the
output in case this situation can be handled better in the event of this
bug happening:
D: reserve-wrap.c: Successfully acquired reservation lock on device 'Audio0'
I: alsa-sink.c: Trying resume...
D: alsa-util.c: Maximum hw buffer size is 371 ms
D: alsa-sink.c: hwbuf_unused=0
D: alsa-sink.c: setting avail_min=14798
I: alsa-sink.c: Resumed successfully...
I: alsa-sink.c: Starting playback.
D: alsa-sink.c: Cutting sleep time for the initial iterations by half.
D: module-suspend-on-idle.c: Sink
alsa_output.pci-0000_00_1b.0.analog-stereo becomes idle, timeout in 5
seconds.
D: alsa-sink.c: Cutting sleep time for the initial iterations by half.
D: alsa-sink.c: Cutting sleep time for the initial iterations by half.
D: module-suspend-on-idle.c: Sink
alsa_output.pci-0000_00_1b.0.analog-stereo becomes busy.
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 157 "tooltip-popup" on
alsa_output.pci-0000_00_1b.0.analog-stereo with sample spec s16le 2ch
44100Hz and channel map front-left,front-right
D: core-util.c: posix_madvise() failed (or doesn't exist), trying
mlock(): Cannot allocate memory
D: alsa-sink.c: Wakeup from ALSA!
D: alsa-sink.c: Wakeup from ALSA!
D: alsa-sink.c: Wakeup from ALSA!
E: alsa-util.c: snd_pcm_avail() returned a value that is exceptionally
large: 2705120 bytes (15335 ms).
E: alsa-util.c: Most likely this is a bug in the ALSA driver
'snd_hda_intel'. Please report this issue to the ALSA developers.
E: alsa-util.c: snd_pcm_dump():
E: alsa-util.c: Soft volume PCM
E: alsa-util.c: Control: PCM Playback Volume
E: alsa-util.c: min_dB: -51
E: alsa-util.c: max_dB: 0
E: alsa-util.c: resolution: 256
E: alsa-util.c: Its setup is:
E: alsa-util.c: stream : PLAYBACK
E: alsa-util.c: access : MMAP_INTERLEAVED
E: alsa-util.c: format : S16_LE
E: alsa-util.c: subformat : STD
E: alsa-util.c: channels : 2
E: alsa-util.c: rate : 44100
E: alsa-util.c: exact rate : 44100 (44100/1)
E: alsa-util.c: msbits : 16
E: alsa-util.c: buffer_size : 16384
E: alsa-util.c: period_size : 8192
E: alsa-util.c: period_time : 185759
E: alsa-util.c: tstamp_mode : ENABLE
E: alsa-util.c: period_step : 1
E: alsa-util.c: avail_min : 14798
E: alsa-util.c: period_event : 0
E: alsa-util.c: start_threshold : -1
E: alsa-util.c: stop_threshold : 4611686018427387904
E: alsa-util.c: silence_threshold: 0
E: alsa-util.c: silence_size : 0
E: alsa-util.c: boundary : 4611686018427387904
E: alsa-util.c: Slave: Hardware PCM card 0 'HDA Intel' device 0 subdevice 0
E: alsa-util.c: Its setup is:
E: alsa-util.c: stream : PLAYBACK
E: alsa-util.c: access : MMAP_INTERLEAVED
E: alsa-util.c: format : S16_LE
E: alsa-util.c: subformat : STD
E: alsa-util.c: channels : 2
E: alsa-util.c: rate : 44100
E: alsa-util.c: exact rate : 44100 (44100/1)
E: alsa-util.c: msbits : 16
E: alsa-util.c: buffer_size : 16384
E: alsa-util.c: period_size : 8192
E: alsa-util.c: period_time : 185759
E: alsa-util.c: tstamp_mode : ENABLE
E: alsa-util.c: period_step : 1
E: alsa-util.c: avail_min : 14798
E: alsa-util.c: period_event : 0
E: alsa-util.c: start_threshold : -1
E: alsa-util.c: stop_threshold : 4611686018427387904
E: alsa-util.c: silence_threshold: 0
E: alsa-util.c: silence_size : 0
E: alsa-util.c: boundary : 4611686018427387904
E: alsa-util.c: appl_ptr : 15417000
E: alsa-util.c: hw_ptr : 16076896
I: alsa-sink.c: Increasing wakeup watermark to 45.99 ms
I: alsa-sink.c: Increasing wakeup watermark to 55.99 ms
I: alsa-sink.c: Increasing wakeup watermark to 65.99 ms
I: alsa-sink.c: Increasing wakeup watermark to 75.99 ms
I: alsa-sink.c: Increasing wakeup watermark to 85.99 ms
I: alsa-sink.c: Increasing wakeup watermark to 95.99 ms
I: alsa-sink.c: Increasing wakeup watermark to 105.99 ms
I: alsa-sink.c: Increasing wakeup watermark to 115.99 ms
I: alsa-sink.c: Increasing wakeup watermark to 125.99 ms
I: alsa-sink.c: Increasing wakeup watermark to 135.99 ms
I: alsa-sink.c: Increasing wakeup watermark to 145.99 ms
E: alsa-util.c: snd_pcm_delay() returned a value that is exceptionally
large: -1984896 bytes (-11252 ms).
E: alsa-util.c: Most likely this is a bug in the ALSA driver
'snd_hda_intel'. Please report this issue to the ALSA developers.
E: alsa-util.c: snd_pcm_dump():
E: alsa-util.c: Soft volume PCM
E: alsa-util.c: Control: PCM Playback Volume
E: alsa-util.c: min_dB: -51
E: alsa-util.c: max_dB: 0
E: alsa-util.c: resolution: 256
E: alsa-util.c: Its setup is:
E: alsa-util.c: stream : PLAYBACK
E: alsa-util.c: access : MMAP_INTERLEAVED
E: alsa-util.c: format : S16_LE
E: alsa-util.c: subformat : STD
E: alsa-util.c: channels : 2
E: alsa-util.c: rate : 44100
E: alsa-util.c: exact rate : 44100 (44100/1)
E: alsa-util.c: msbits : 16
E: alsa-util.c: buffer_size : 16384
E: alsa-util.c: period_size : 8192
E: alsa-util.c: period_time : 185759
E: alsa-util.c: tstamp_mode : ENABLE
E: alsa-util.c: period_step : 1
E: alsa-util.c: avail_min : 14798
E: alsa-util.c: period_event : 0
E: alsa-util.c: start_threshold : -1
E: alsa-util.c: stop_threshold : 4611686018427387904
E: alsa-util.c: silence_threshold: 0
E: alsa-util.c: silence_size : 0
E: alsa-util.c: boundary : 4611686018427387904
E: alsa-util.c: Slave: Hardware PCM card 0 'HDA Intel' device 0 subdevice 0
E: alsa-util.c: Its setup is:
E: alsa-util.c: stream : PLAYBACK
E: alsa-util.c: access : MMAP_INTERLEAVED
E: alsa-util.c: format : S16_LE
E: alsa-util.c: subformat : STD
E: alsa-util.c: channels : 2
E: alsa-util.c: rate : 44100
E: alsa-util.c: exact rate : 44100 (44100/1)
E: alsa-util.c: msbits : 16
E: alsa-util.c: buffer_size : 16384
E: alsa-util.c: period_size : 8192
E: alsa-util.c: period_time : 185759
E: alsa-util.c: tstamp_mode : ENABLE
E: alsa-util.c: period_step : 1
E: alsa-util.c: avail_min : 14798
E: alsa-util.c: period_event : 0
E: alsa-util.c: start_threshold : -1
E: alsa-util.c: stop_threshold : 4611686018427387904
E: alsa-util.c: silence_threshold: 0
E: alsa-util.c: silence_size : 0
E: alsa-util.c: boundary : 4611686018427387904
E: alsa-util.c: appl_ptr : 15580840
E: alsa-util.c: hw_ptr : 16077064
D: alsa-sink.c: Wakeup from ALSA!
I: alsa-sink.c: Increasing wakeup watermark to 155.99 ms
I: alsa-sink.c: Increasing wakeup watermark to 165.99 ms
I: alsa-sink.c: Increasing wakeup watermark to 175.99 ms
I: alsa-sink.c: Increasing wakeup watermark to 185.99 ms
I: alsa-sink.c: Increasing wakeup watermark to 195.99 ms
I: alsa-sink.c: Increasing wakeup watermark to 205.99 ms
I: alsa-sink.c: Increasing wakeup watermark to 215.99 ms
I: alsa-sink.c: Increasing wakeup watermark to 225.99 ms
I: alsa-sink.c: Increasing wakeup watermark to 235.99 ms
I: alsa-sink.c: Increasing wakeup watermark to 245.99 ms
I: alsa-sink.c: Increasing wakeup watermark to 255.99 ms
D: alsa-sink.c: Wakeup from ALSA!
I: alsa-sink.c: Increasing wakeup watermark to 265.99 ms
I: alsa-sink.c: Increasing wakeup watermark to 275.99 ms
I: alsa-sink.c: Increasing wakeup watermark to 285.99 ms
I: alsa-sink.c: Increasing wakeup watermark to 295.99 ms
I: alsa-sink.c: Increasing wakeup watermark to 305.99 ms
I: alsa-sink.c: Increasing wakeup watermark to 315.99 ms
I: alsa-sink.c: Increasing wakeup watermark to 325.99 ms
I: alsa-sink.c: Increasing wakeup watermark to 335.99 ms
I: alsa-sink.c: Increasing wakeup watermark to 345.99 ms
I: alsa-sink.c: Increasing wakeup watermark to 355.99 ms
I: alsa-sink.c: Increasing wakeup watermark to 361.52 ms
D: alsa-sink.c: Wakeup from ALSA!
I: alsa-sink.c: Increasing minimal latency to 56.00 ms
D: alsa-sink.c: hwbuf_unused=0
D: alsa-sink.c: setting avail_min=442
D: alsa-sink.c: hwbuf_unused=0
D: alsa-sink.c: setting avail_min=442
I: alsa-sink.c: Increasing minimal latency to 66.00 ms
D: alsa-sink.c: hwbuf_unused=0
D: alsa-sink.c: setting avail_min=442
D: alsa-sink.c: hwbuf_unused=0
D: alsa-sink.c: setting avail_min=442
I: alsa-sink.c: Increasing minimal latency to 76.00 ms
D: alsa-sink.c: hwbuf_unused=0
D: alsa-sink.c: setting avail_min=442
D: alsa-sink.c: hwbuf_unused=0
D: alsa-sink.c: setting avail_min=442
I: alsa-sink.c: Increasing minimal latency to 86.00 ms
D: alsa-sink.c: hwbuf_unused=0
D: alsa-sink.c: setting avail_min=442
D: alsa-sink.c: hwbuf_unused=0
D: alsa-sink.c: setting avail_min=442
I: alsa-sink.c: Increasing minimal latency to 96.00 ms
D: alsa-sink.c: hwbuf_unused=0
D: alsa-sink.c: setting avail_min=442
D: alsa-sink.c: hwbuf_unused=0
D: alsa-sink.c: setting avail_min=442
I: alsa-sink.c: Increasing minimal latency to 106.00 ms
D: alsa-sink.c: hwbuf_unused=0
D: alsa-sink.c: setting avail_min=442
D: alsa-sink.c: hwbuf_unused=0
D: alsa-sink.c: setting avail_min=442
I: alsa-sink.c: Increasing minimal latency to 116.00 ms
D: alsa-sink.c: hwbuf_unused=0
D: alsa-sink.c: setting avail_min=442
D: alsa-sink.c: hwbuf_unused=0
D: alsa-sink.c: setting avail_min=442
I: alsa-sink.c: Underrun!
I: alsa-sink.c: Increasing minimal latency to 126.00 ms
D: alsa-sink.c: hwbuf_unused=0
D: alsa-sink.c: setting avail_min=442
D: alsa-sink.c: hwbuf_unused=0
D: alsa-sink.c: setting avail_min=442
I: alsa-sink.c: Decreasing wakeup watermark to 356.53 ms
^CI: alsa-sink.c: Decreasing wakeup watermark to 351.54 ms
I: alsa-sink.c: Decreasing wakeup watermark to 346.55 ms
I: alsa-sink.c: Decreasing wakeup watermark to 341.56 ms
Killed
--
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/]
More information about the pulseaudio-discuss
mailing list