[pulseaudio-discuss] huge skype sound events delay

Julian Sikorski belegdol at gmail.com
Tue Dec 11 22:21:08 PST 2012


W dniu 12.12.2012 06:11, Tanu Kaskinen pisze:
> On Tue, 2012-12-11 at 21:07 +0100, Julian Sikorski wrote:
>> Hi,
>>
>> I posted this on the skype community forums too, but I thought it might
>> be wise to attack the problem on different fronts.
> 
> This certainly sounds like a pulseaudio bug. It might be already fixed,
> so if possible, could you try the latest git version or the 2.99.3
> tarball (they are currently the same anyway)?
> 

I'm not sure how easy that would be. Given how basic element pulsaudio
is, this might require me to rebuild half of the distribution.

>> Basically, after
>> upgrading to Fedora 18, skype sounds produce a ridiculously long delay,
>> unless pavucontrol is started side-by side. Relevant logs are attached.
> 
> Could you repost the "no-pavucontrol" log with timestamps (give
> --log-time on the command line)?
> 

Here you go, file is attached.

Julian

-------------- next part --------------
(  47.563|  25.084) I: [pulseaudio] module-stream-restore.c: Restoring device for stream sink-input-by-media-role:event.
(  47.563|   0.000) D: [pulseaudio] module-intended-roles.c: Not setting device for stream Event Sound, because already set.
(  47.563|   0.000) I: [pulseaudio] sink-input.c: Trying to change sample rate
(  47.563|   0.000) I: [pulseaudio] alsa-sink.c: Updating rate for device front:0, new rate is 48000
(  47.563|   0.000) I: [pulseaudio] sink.c: Changed sampling rate successfully
(  47.563|   0.000) I: [pulseaudio] sink-input.c: Rate changed to 48000 Hz
(  47.564|   0.000) I: [pulseaudio] module-stream-restore.c: Restoring volume for sink input sink-input-by-media-role:event.
(  47.564|   0.000) I: [pulseaudio] module-stream-restore.c: Restoring mute state for sink input sink-input-by-media-role:event.
(  47.564|   0.000) D: [pulseaudio] sink.c: Suspend cause of sink alsa_output.pci-0000_00_1b.0.analog-stereo is 0x0000, resuming
(  47.565|   0.001) D: [pulseaudio] reserve-wrap.c: Failed to acquire reservation lock on device 'Audio0': Błąd wejścia/wyjścia
(  47.565|   0.000) I: [alsa-sink] alsa-sink.c: Trying resume...
(  47.565|   0.000) I: [alsa-sink] alsa-util.c: Trying to disable ALSA period wakeups, using timers only
(  47.565|   0.000) D: [alsa-sink] alsa-util.c: Maximum hw buffer size is 21845 ms
(  47.565|   0.000) D: [alsa-sink] alsa-util.c: Set buffer size first (to 88200 samples), period size second (to 44100 samples).
(  47.565|   0.000) I: [alsa-sink] alsa-util.c: ALSA period wakeups disabled
(  47.565|   0.000) D: [alsa-sink] alsa-sink.c: hwbuf_unused=0
(  47.565|   0.000) D: [alsa-sink] alsa-sink.c: setting avail_min=88009
(  47.565|   0.000) D: [alsa-sink] alsa-sink.c: hwbuf_unused=0
(  47.565|   0.000) D: [alsa-sink] alsa-sink.c: setting avail_min=87319
(  47.565|   0.000) D: [alsa-sink] alsa-sink.c: hwbuf_unused=0
(  47.565|   0.000) D: [alsa-sink] alsa-sink.c: setting avail_min=87319
(  47.565|   0.000) I: [alsa-sink] alsa-sink.c: Time scheduling watermark is 18,38ms
(  47.565|   0.000) I: [alsa-sink] alsa-sink.c: Resumed successfully...
(  47.565|   0.000) D: [pulseaudio] module-suspend-on-idle.c: Sink alsa_output.pci-0000_00_1b.0.analog-stereo becomes idle, timeout in 5 seconds.
(  47.566|   0.000) I: [alsa-sink] alsa-sink.c: Starting playback.
(  47.566|   0.000) D: [alsa-sink] alsa-sink.c: Cutting sleep time for the initial iterations by half.
(  47.566|   0.000) D: [alsa-sink] alsa-sink.c: Cutting sleep time for the initial iterations by half.
(  47.566|   0.000) D: [pulseaudio] module-suspend-on-idle.c: Sink alsa_output.pci-0000_00_1b.0.analog-stereo becomes busy.
(  47.566|   0.000) I: [pulseaudio] resampler.c: Forcing resampler 'copy', because of fixed, identical sample rates.
(  47.566|   0.000) D: [pulseaudio] resampler.c: Channel matrix:
(  47.566|   0.000) D: [pulseaudio] resampler.c:        I00 
(  47.566|   0.000) D: [pulseaudio] resampler.c:     +------
(  47.566|   0.000) D: [pulseaudio] resampler.c: O00 | 1,000
(  47.566|   0.000) D: [pulseaudio] resampler.c: O01 | 1,000
(  47.566|   0.000) I: [pulseaudio] remap_sse.c: Using SSE mono to stereo remapping
(  47.566|   0.000) I: [pulseaudio] resampler.c: Using resampler 'copy'
(  47.566|   0.000) I: [pulseaudio] resampler.c: Using s16le as working format.
(  47.566|   0.000) D: [pulseaudio] memblockq.c: memblockq requested: maxlength=33554432, tlength=0, base=4, prebuf=0, minreq=1 maxrewind=0
(  47.566|   0.000) D: [pulseaudio] memblockq.c: memblockq sanitized: maxlength=33554432, tlength=33554432, base=4, prebuf=0, minreq=4 maxrewind=0
(  47.566|   0.000) I: [pulseaudio] sink-input.c: Created input 2 "Event Sound" on alsa_output.pci-0000_00_1b.0.analog-stereo with sample spec s16le 1ch 48000Hz and channel map mono
(  47.566|   0.000) I: [pulseaudio] sink-input.c:     window.icon_name = "skype"
(  47.566|   0.000) I: [pulseaudio] sink-input.c:     application.icon_name = "skype"
(  47.566|   0.000) I: [pulseaudio] sink-input.c:     media.role = "event"
(  47.566|   0.000) I: [pulseaudio] sink-input.c:     media.name = "Event Sound"
(  47.566|   0.000) I: [pulseaudio] sink-input.c:     application.name = "Skype"
(  47.566|   0.000) I: [pulseaudio] sink-input.c:     native-protocol.peer = "UNIX socket client"
(  47.566|   0.000) I: [pulseaudio] sink-input.c:     native-protocol.version = "26"
(  47.566|   0.000) I: [pulseaudio] sink-input.c:     application.process.id = "24668"
(  47.566|   0.000) I: [pulseaudio] sink-input.c:     application.process.user = "julas"
(  47.566|   0.000) I: [pulseaudio] sink-input.c:     application.process.host = "snowball2"
(  47.566|   0.000) I: [pulseaudio] sink-input.c:     application.process.binary = "skype"
(  47.566|   0.000) I: [pulseaudio] sink-input.c:     application.language = "pl_PL.UTF-8"
(  47.566|   0.000) I: [pulseaudio] sink-input.c:     window.x11.display = ":0"
(  47.566|   0.000) I: [pulseaudio] sink-input.c:     application.process.machine_id = "98d51596bca05b5c8d3ab7dd0000000d"
(  47.566|   0.000) I: [pulseaudio] sink-input.c:     application.process.session_id = "98d51596bca05b5c8d3ab7dd0000000d-1355292705.444356-1722121657"
(  47.566|   0.000) I: [pulseaudio] sink-input.c:     module-stream-restore.id = "sink-input-by-media-role:event"
(  47.566|   0.000) I: [pulseaudio] protocol-native.c: Requested tlength=20,02 ms, minreq=20,00 ms
(  47.566|   0.000) D: [pulseaudio] protocol-native.c: Adjust latency mode enabled, configuring sink latency to half of overall latency.
(  47.567|   0.000) D: [alsa-sink] alsa-sink.c: Cutting sleep time for the initial iterations by half.
(  47.567|   0.000) D: [pulseaudio] protocol-native.c: Requested latency=0,00 ms, Received latency=0,50 ms
(  47.567|   0.000) D: [pulseaudio] memblockq.c: memblockq requested: maxlength=4194304, tlength=3888, base=2, prebuf=1970, minreq=1920 maxrewind=0
(  47.567|   0.000) D: [pulseaudio] memblockq.c: memblockq sanitized: maxlength=4194304, tlength=3888, base=2, prebuf=1970, minreq=1920 maxrewind=0
(  47.567|   0.000) I: [pulseaudio] protocol-native.c: Final latency 41,00 ms = 0,50 ms + 2*20,00 ms + 0,50 ms
(  47.567|   0.000) D: [alsa-sink] alsa-sink.c: Cutting sleep time for the initial iterations by half.
(  47.567|   0.000) D: [alsa-sink] alsa-sink.c: Latency set to 0,50ms
(  47.567|   0.000) D: [alsa-sink] alsa-sink.c: hwbuf_unused=352704
(  47.567|   0.000) D: [alsa-sink] alsa-sink.c: setting avail_min=88189
(  47.567|   0.000) D: [alsa-sink] alsa-sink.c: Requesting rewind due to latency change.
(  47.567|   0.000) D: [alsa-sink] alsa-sink.c: Requested volume: 0:  69% 1:  69%
(  47.567|   0.000) D: [alsa-sink] alsa-sink.c:            in dB: 0: -9,67 dB 1: -9,67 dB
(  47.567|   0.000) D: [alsa-sink] alsa-sink.c: Got hardware volume: 0:  69% 1:  69%
(  47.567|   0.000) D: [alsa-sink] alsa-sink.c:               in dB: 0: -9,60 dB 1: -9,60 dB
(  47.567|   0.000) D: [alsa-sink] alsa-sink.c: Calculated software volume: 0: 100% 1: 100% (accurate-enough=yes)
(  47.567|   0.000) D: [alsa-sink] alsa-sink.c:                      in dB: 0: -0,07 dB 1: -0,07 dB
(  47.567|   0.000) D: [alsa-sink] sink.c: Volume not changing
(  47.567|   0.000) D: [alsa-sink] alsa-sink.c: Requested to rewind 352800 bytes.
(  47.567|   0.000) D: [alsa-sink] alsa-sink.c: Limited to 352032 bytes.
(  47.567|   0.000) D: [alsa-sink] alsa-sink.c: before: 88008
(  47.567|   0.000) D: [alsa-sink] alsa-sink.c: after: 88008
(  47.567|   0.000) D: [alsa-sink] alsa-sink.c: Rewound 352032 bytes.
(  47.567|   0.000) D: [alsa-sink] sink.c: Processing rewind...
(  47.568|   0.000) D: [alsa-sink] sink.c: latency = 2065
(  47.568|   0.000) D: [alsa-sink] sink-input.c: Have to rewind 352032 bytes on render memblockq.
(  47.568|   0.000) D: [alsa-sink] source.c: Processing rewind...
(  47.568|   0.000) D: [alsa-sink] alsa-sink.c: Cutting sleep time for the initial iterations by half.
(  47.568|   0.000) D: [pulseaudio] protocol-dbus.c: Interface org.PulseAudio.Core1.Stream added for object /org/pulseaudio/core1/playback_stream2
(  47.568|   0.000) D: [alsa-sink] alsa-sink.c: Cutting sleep time for the initial iterations by half.
(  47.568|   0.000) D: [alsa-sink] alsa-sink.c: Cutting sleep time for the initial iterations by half.
(  47.568|   0.000) D: [alsa-sink] alsa-sink.c: Cutting sleep time for the initial iterations by half.
(  47.568|   0.000) D: [alsa-sink] alsa-sink.c: Cutting sleep time for the initial iterations by half.
(  47.568|   0.000) D: [alsa-sink] alsa-sink.c: Cutting sleep time for the initial iterations by half.
(  47.569|   0.000) D: [alsa-sink] alsa-sink.c: Cutting sleep time for the initial iterations by half.
(  47.569|   0.000) I: [alsa-sink] alsa-sink.c: Increasing minimal latency to 1,00 ms
(  47.569|   0.000) D: [alsa-sink] alsa-sink.c: Latency set to 1,00ms
(  47.569|   0.000) D: [alsa-sink] alsa-sink.c: hwbuf_unused=352608
(  47.569|   0.000) D: [alsa-sink] alsa-sink.c: setting avail_min=88177
(  47.569|   0.000) D: [alsa-sink] protocol-native.c: max_request changed, trying to update from 3888 to 3936.
(  47.569|   0.000) D: [alsa-sink] protocol-native.c: Notifying client about increased tlength
(  47.569|   0.000) D: [alsa-sink] alsa-sink.c: Latency set to 1,00ms
(  47.569|   0.000) D: [alsa-sink] alsa-sink.c: hwbuf_unused=352608
(  47.569|   0.000) D: [alsa-sink] alsa-sink.c: setting avail_min=88177
(  47.569|   0.000) D: [pulseaudio] sink.c: Suspend cause of sink alsa_output.pci-0000_00_1b.0.analog-stereo is 0x0004, suspending
(  47.570|   0.000) I: [alsa-sink] alsa-sink.c: Device suspended...
(  47.570|   0.000) I: [pulseaudio] alsa-sink.c: Updating rate for device front:0, new rate is 48000
(  47.570|   0.000) I: [pulseaudio] sink.c: Changed sampling rate successfully
(  47.570|   0.000) D: [alsa-sink] sink-input.c: Requesting rewind due to uncorking
(  47.570|   0.000) D: [pulseaudio] sink.c: Suspend cause of sink alsa_output.pci-0000_00_1b.0.analog-stereo is 0x0000, resuming
(  47.570|   0.000) D: [pulseaudio] reserve-wrap.c: Failed to acquire reservation lock on device 'Audio0': Błąd wejścia/wyjścia
(  47.571|   0.000) I: [alsa-sink] alsa-sink.c: Trying resume...
(  47.571|   0.000) I: [alsa-sink] alsa-util.c: Trying to disable ALSA period wakeups, using timers only
(  47.571|   0.000) D: [alsa-sink] alsa-util.c: Maximum hw buffer size is 21845 ms
(  47.572|   0.000) D: [alsa-sink] alsa-util.c: Set buffer size first (to 88200 samples), period size second (to 44100 samples).
(  47.572|   0.000) I: [alsa-sink] alsa-util.c: ALSA period wakeups disabled
(  47.572|   0.000) D: [alsa-sink] alsa-sink.c: Latency set to 1,00ms
(  47.572|   0.000) D: [alsa-sink] alsa-sink.c: hwbuf_unused=352608
(  47.572|   0.000) D: [alsa-sink] alsa-sink.c: setting avail_min=88177
(  47.572|   0.000) D: [alsa-sink] alsa-sink.c: Latency set to 0,50ms
(  47.572|   0.000) D: [alsa-sink] alsa-sink.c: hwbuf_unused=352704
(  47.572|   0.000) D: [alsa-sink] alsa-sink.c: setting avail_min=88189
(  47.572|   0.000) D: [alsa-sink] alsa-sink.c: Requesting rewind due to latency change.
(  47.572|   0.000) D: [alsa-sink] alsa-sink.c: Latency set to 0,50ms
(  47.572|   0.000) D: [alsa-sink] alsa-sink.c: hwbuf_unused=352704
(  47.572|   0.000) D: [alsa-sink] alsa-sink.c: setting avail_min=88189
(  47.572|   0.000) I: [alsa-sink] alsa-sink.c: Time scheduling watermark is 0,25ms
(  47.572|   0.000) I: [alsa-sink] alsa-sink.c: Resumed successfully...
(  47.572|   0.000) D: [pulseaudio] core-subscribe.c: Dropped redundant event due to change event.
(  47.572|   0.000) I: [alsa-sink] alsa-sink.c: Starting playback.
(  47.572|   0.000) I: [alsa-sink] alsa-sink.c: Increasing minimal latency to 1,00 ms
(  47.572|   0.000) D: [pulseaudio] core-subscribe.c: Dropped redundant event due to change event.
(  47.572|   0.000) D: [alsa-sink] alsa-sink.c: Latency set to 1,00ms
(  47.572|   0.000) D: [pulseaudio] module-suspend-on-idle.c: Sink alsa_output.pci-0000_00_1b.0.analog-stereo becomes busy.
(  47.572|   0.000) D: [alsa-sink] alsa-sink.c: hwbuf_unused=352608
(  47.572|   0.000) D: [alsa-sink] alsa-sink.c: setting avail_min=88177
(  47.572|   0.000) D: [alsa-sink] alsa-sink.c: Latency set to 1,00ms
(  47.572|   0.000) D: [alsa-sink] alsa-sink.c: hwbuf_unused=352608
(  47.573|   0.000) D: [alsa-sink] alsa-sink.c: setting avail_min=88177
(  47.573|   0.000) D: [pulseaudio] module-udev-detect.c: /dev/snd/controlC0 is accessible: yes
(  47.577|   0.004) D: [alsa-sink] protocol-native.c: Requesting rewind due to end of underrun.
(  47.577|   0.000) D: [alsa-sink] protocol-native.c: Requesting rewind due to end of underrun.
(  47.577|   0.000) D: [alsa-sink] protocol-native.c: Requesting rewind due to end of underrun.
(  47.577|   0.000) D: [alsa-sink] protocol-native.c: Requesting rewind due to end of underrun.
(  47.577|   0.000) D: [alsa-sink] protocol-native.c: Requesting rewind due to end of underrun.
(  47.578|   0.000) D: [alsa-sink] protocol-native.c: Requesting rewind due to end of underrun.
(  52.566|   4.988) D: [alsa-sink] ratelimit.c: 7516 events suppressed
(  52.566|   0.000) D: [alsa-sink] memblock.c: Pool full
(  52.567|   0.000) D: [alsa-sink] memblock.c: Pool full
(  52.567|   0.000) D: [alsa-sink] memblock.c: Pool full
(  52.568|   0.001) D: [alsa-sink] memblock.c: Pool full
(  52.569|   0.000) D: [alsa-sink] memblock.c: Pool full
(  52.570|   0.000) D: [alsa-sink] memblock.c: Pool full
(  52.570|   0.000) D: [alsa-sink] memblock.c: Pool full
(  52.571|   0.000) D: [alsa-sink] memblock.c: Pool full
(  52.572|   0.000) D: [alsa-sink] memblock.c: Pool full
(  52.573|   0.000) D: [alsa-sink] memblock.c: Pool full
(  52.574|   0.001) D: [alsa-sink] memblock.c: Pool full
(  52.649|   0.074) D: [alsa-sink] sink-input.c: Requesting rewind due to corking
(  52.649|   0.000) D: [pulseaudio] module-suspend-on-idle.c: Sink alsa_output.pci-0000_00_1b.0.analog-stereo becomes idle, timeout in 5 seconds.
(  52.651|   0.002) D: [alsa-sink] alsa-sink.c: hwbuf_unused=0
(  52.651|   0.000) D: [alsa-sink] alsa-sink.c: setting avail_min=88009
(  52.651|   0.000) D: [alsa-sink] alsa-sink.c: Requested volume: 0:  69% 1:  69%
(  52.651|   0.000) D: [alsa-sink] alsa-sink.c:            in dB: 0: -9,67 dB 1: -9,67 dB
(  52.651|   0.000) D: [alsa-sink] alsa-sink.c: Got hardware volume: 0:  69% 1:  69%
(  52.651|   0.000) D: [alsa-sink] alsa-sink.c:               in dB: 0: -9,60 dB 1: -9,60 dB
(  52.651|   0.000) D: [alsa-sink] alsa-sink.c: Calculated software volume: 0: 100% 1: 100% (accurate-enough=yes)
(  52.652|   0.000) D: [alsa-sink] alsa-sink.c:                      in dB: 0: -0,07 dB 1: -0,07 dB
(  52.652|   0.000) D: [alsa-sink] sink.c: Volume not changing
(  52.652|   0.000) D: [alsa-sink] alsa-sink.c: Requested to rewind 352800 bytes.
(  52.652|   0.000) D: [alsa-sink] alsa-sink.c: Mhmm, actually there is nothing to rewind.
(  52.652|   0.000) D: [pulseaudio] module-suspend-on-idle.c: Sink alsa_output.pci-0000_00_1b.0.analog-stereo becomes idle, timeout in 5 seconds.
(  52.652|   0.000) D: [pulseaudio] core.c: Hmm, no streams around, trying to vacuum.
(  52.653|   0.001) D: [pulseaudio] protocol-dbus.c: Interface org.PulseAudio.Core1.Stream removed from object /org/pulseaudio/core1/playback_stream2
(  52.653|   0.000) I: [pulseaudio] sink-input.c: Freeing input 2 "Event Sound"
^F(  57.657|   5.003) I: [pulseaudio] module-suspend-on-idle.c: Sink alsa_output.pci-0000_00_1b.0.analog-stereo idle for too long, suspending ...
(  57.657|   0.000) D: [pulseaudio] sink.c: Suspend cause of sink alsa_output.pci-0000_00_1b.0.analog-stereo is 0x0004, suspending
(  57.657|   0.000) D: [pulseaudio] ratelimit.c: 2622 events suppressed
(  57.657|   0.000) D: [pulseaudio] flist.c: pulsecore/hashmap.c: entries flist is full (don't worry)
(  57.658|   0.000) I: [alsa-sink] alsa-sink.c: Device suspended...
(  57.658|   0.000) D: [pulseaudio] core.c: Hmm, no streams around, trying to vacuum.
(  57.672|   0.013) D: [pulseaudio] module-udev-detect.c: /dev/snd/controlC0 is accessible: yes


More information about the pulseaudio-discuss mailing list