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
( 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
_______________________________________________ pulseaudio-discuss mailing list [email protected] http://lists.freedesktop.org/mailman/listinfo/pulseaudio-discuss
