[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