[pulseaudio-discuss] Failed to drain stream: Timeout
D K
dspgro at gmail.com
Thu Jun 6 20:13:33 PDT 2013
I think the problem is coming from underruns and then rewinds.
Somehow i can see the audio coming with a latency of about 12 seconds ..
and then PA crashed .
I: [alsa-sink] alsa-sink.c: Starting playback.
I: [alsa-sink] pcm_hw.c: SNDRV_PCM_IOCTL_START failed (-77)
D: [pulseaudio] module-suspend-on-idle.c: Sink alsa_output.default becomes
busy.
I: [pulseaudio] resampler.c: Forcing resampler 'copy', because of fixed,
identical sample rates.
D: [pulseaudio] resampler.c: Channel matrix:
D: [pulseaudio] resampler.c: I00
D: [pulseaudio] resampler.c: +------
D: [pulseaudio] resampler.c: O00 | 1.000
D: [pulseaudio] resampler.c: O01 | 1.000
I: [pulseaudio] remap.c: Using mono to stereo remapping
I: [pulseaudio] resampler.c: Using resampler 'copy'
I: [pulseaudio] resampler.c: Using s16le as working format.
D: [pulseaudio] memblockq.c: memblockq requested: maxlength=33554432,
tlength=0, base=4, prebuf=0, minreq=1 maxrewind=0
D: [pulseaudio] memblockq.c: memblockq sanitized: maxlength=33554432,
tlength=33554432, base=4, prebuf=0, minreq=4 maxrewind=0
I: [pulseaudio] sink-input.c: Created input 0
"/usr/share/sounds/alsa/Front_Center.wav" on alsa_output.default with
sample spec s16le 1ch 48000Hz and channel map mono
I: [pulseaudio] sink-input.c: media.format = "WAV (Microsoft)"
I: [pulseaudio] sink-input.c: application.name = "paplay"
I: [pulseaudio] sink-input.c: media.name =
"/usr/share/sounds/alsa/Front_Center.wav"
I: [pulseaudio] sink-input.c: native-protocol.peer = "UNIX socket
client"
I: [pulseaudio] sink-input.c: native-protocol.version = "26"
I: [pulseaudio] sink-input.c: application.process.id = "1649"
I: [pulseaudio] sink-input.c: application.process.user = "root"
I: [pulseaudio] sink-input.c: application.process.host =
"10.195.245.138"
I: [pulseaudio] sink-input.c: application.process.binary = "pacat"
I: [pulseaudio] sink-input.c: application.language = "C"
I: [pulseaudio] sink-input.c: application.process.machine_id =
"10.195.245.138"
I: [pulseaudio] sink-input.c: module-stream-restore.id =
"sink-input-by-application-name:paplay"
I: [pulseaudio] protocol-native.c: Requested tlength=2000.00 ms,
minreq=20.00 ms
D: [pulseaudio] protocol-native.c: Traditional mode enabled, modifying sink
usec only for compat with minreq.
D: [pulseaudio] protocol-native.c: Requested latency=1960.00 ms, Received
latency=185.76 ms
D: [pulseaudio] memblockq.c: memblockq requested: maxlength=4194304,
tlength=192000, base=2, prebuf=190082, minreq=1920 maxrewind=0
D: [pulseaudio] memblockq.c: memblockq sanitized: maxlength=4194304,
tlength=192000, base=2, prebuf=190082, minreq=1920 maxrewind=0
I: [pulseaudio] protocol-native.c: Final latency 2185.76 ms = 1960.00 ms +
2*20.00 ms + 185.76 ms
D: [pulseaudio] core-subscribe.c: Dropped redundant event due to change
event.
D: [alsa-sink] protocol-native.c: Requesting rewind due to end of underrun.
D: [alsa-sink] sink-input.c: Do not do any rewind requests, seems to cause
loss of audio samples
On Tue, Jun 4, 2013 at 8:01 PM, David Henningsson <
david.henningsson at canonical.com> wrote:
> On 06/05/2013 12:24 AM, D K wrote:
>
>> I am getting following error when i try to to paplay
>>
>> # paplay /usr/share/sounds/alsa/Front_**Center.wav
>> Failed to drain stream: Timeout
>>
>> Here PA is connected to alsa-driver for playback of sound.
>> I am not sure about the problem here any pointers would be helpful.
>>
>> thanks,
>> KD
>>
>> The detailed log is below.
>>
>> I: [pulseaudio] protocol-native.c: Got crede[ 421.525807] audio ]
>> 1154_dai_hw_params is completed.
>> ntials: uid=0 gid=0 success=1
>> D: [pulseaudio] p[ 421.534996] audio ] 1154_pcm_hw_params is completed.
>> rotocol-native.c: SHM possible: yes
>> D: [pulseau[ 421.545005] audio ] 1154_pcm_prepare is
>> completed(ch:2)(bs:16)(sr:**48000)(free:318644)(diff:**285876).
>> dio] protocol-native.c: Negotiated SHM: yes
>> I: [ 421.558994] audio ] 1154_pcm_prepare is
>> completed(ch:2)(bs:16)(sr:**48000)(free:318644)(diff:**285876).
>> [pulseaudio] sink-input.c: Trying to change sample rate
>> I: [pulseaudio] alsa-sink.c: Updating rate for device d[ 421.578020]
>> BUG: scheduling while atomic: alsa-sink/4669/0x00000003
>> [ 421.585948] Modules linked in: tntfs(PO) venc_hxenc(PO) vdec_vdu(PO)
>> dc_gm(O) pvrsrvkm(O) kdrv_lg115x(O) logfunnel(O) hma(O)
>> [ 421.597232] [<800197b8>] (unwind_backtrace+0x0/0xf8) from
>> [<8043458c>] (__schedule+0x49c/0x4fc)
>> [ 421.605933] [<8043458c>] (__schedule+0x49c/0x4fc) from [<80432d70>]
>> (schedule_timeout+0x138/0x1c8)
>> [ 421.614901] [<80432d70>] (schedule_timeout+0x138/0x1c8) from
>> [<8002d5a8>] (msleep_interruptible+0x34/**0x44)
>> [ 421.625106] [<8002d5a8>] (msleep_interruptible+0x34/**0x44) from
>> [<7f050da8>] (1154_pcm_trigger+0x74/0xf4 [kdrv_lg115x])
>> [ 421.636319] [<7f050da8>] (1154_pcm_trigger+0x74/0xf4 [kdrv_lg115x])
>> from [<8035bee8>] (soc_pcm_trigger+0x64/0xa0)
>> [ 421.646761] [<8035bee8>] (soc_pcm_trigger+0x64/0xa0) from
>> [<803339f0>] (snd_pcm_do_start+0x2c/0x30)
>> [ 421.655806] [<803339f0>] (snd_pcm_do_start+0x2c/0x30) from
>> [<80333698>] (snd_pcm_action_single+0x38/**0x78)
>> [ 421.665372] [<80333698>] (snd_pcm_action_single+0x38/**0x78) from
>> [<80338bb0>] (snd_pcm_lib_write1+0x2c8/**0x314)
>> [ 421.675284] [<80338bb0>] (snd_pcm_lib_write1+0x2c8/**0x314) from
>> [<80338ca4>] (snd_pcm_lib_write+0x50/0x5c)
>> [ 421.684849] [<80338ca4>] (snd_pcm_lib_write+0x50/0x5c) from
>> [<80335630>] (snd_pcm_playback_ioctl1+**0x1a0/0x3e0)
>> [ 421.694853] [<80335630>] (snd_pcm_playback_ioctl1+**0x1a0/0x3e0) from
>> [<800bc9d0>] (vfs_ioctl+0x30/0x70)
>> [ 421.704157] [<800bc9d0>] (vfs_ioctl+0x30/0x70) from [<800bcb70>]
>> (do_vfs_ioctl+0x68/0x524)
>> [ 421.712418] [<800bcb70>] (do_vfs_ioctl+0x68/0x524) from [<800bd064>]
>> (sys_ioctl+0x38/0x5c)
>> [ 421.720688] [<800bd064>] (sys_ioctl+0x38/0x5c) from [<800135c0>]
>> (ret_fast_syscall+0x0/0x30)
>>
>
> Whenever you get backtraces from the kernel like the lines above (starting
> with "BUG: scheduling while atomic") show you, you are looking at a kernel
> bug. You seem to be using some ASoC driver, so that's where I would look
> first.
>
> Aplay and PulseAudio are sometimes using the driver in slightly different
> ways, so even if aplay works that is not a guarantee that the fault is in
> PulseAudio.
>
>
>
>
> efault, new rate is 48000
>> I: [p[ 421.730381] audio ] 1154_pcm_trigger is completed(cmd:1).
>> ulseaudio] sink.c: Changed sampl[ 421.737677] audio ] 1154_dai_trigger
>> is completed.
>> ing rate successfully
>> I: [pulseaudio] sink-input.c: Rate changed to 48000 Hz
>> D: [pulseaudio] sink.c: Suspend cause of sink alsa_output.default is
>> 0x0000, resuming
>> I: [alsa-sink] alsa-sink.c: Trying resume...
>> D: [alsa-sink] alsa-util.c: Maximum hw buffer size is 170 ms
>> D: [alsa-sink] alsa-util.c: Set buffer size first (to 8192 samples),
>> period size second (to 1024 samples).
>> D: [alsa-sink] alsa-sink.c: hwbuf_unused=0
>> D: [alsa-sink] alsa-sink.c: setting avail_min=1
>> I: [alsa-sink] alsa-sink.c: Resumed successfully...
>> D: [pulseaudio] module-suspend-on-idle.c: Sink alsa_output.default
>> becomes idle, timeout in 5 seconds.
>> I: [alsa-sink] alsa-sink.c: Starting playback.
>> I: [alsa-sink] pcm_hw.c: SNDRV_PCM_IOCTL_START failed (-77)
>>
>
> It is also a bit weird that this error does not seem to propagate up and
> cause follow-up errors, but that's likely not the root cause here.
>
> D: [pulseaudio] module-suspend-on-idle.c: Sink alsa_output.default
>> becomes busy.
>> I: [pulseaudio] resampler.c: Forcing resampler 'copy', because of fixed,
>> identical sample rates.
>> D: [pulseaudio] resampler.c: Channel matrix:
>> D: [pulseaudio] resampler.c: I00
>> D: [pulseaudio] resampler.c: +------
>> D: [pulseaudio] resampler.c: O00 | 1.000
>> D: [pulseaudio] resampler.c: O01 | 1.000
>> I: [pulseaudio] remap.c: Using mono to stereo remapping
>> I: [pulseaudio] resampler.c: Using resampler 'copy'
>> I: [pulseaudio] resampler.c: Using s16le as working format.
>> D: [pulseaudio] memblockq.c: memblockq requested: maxlength=33554432,
>> tlength=0, base=4, prebuf=0, minreq=1 maxrewind=0
>> D: [pulseaudio] memblockq.c: memblockq sanitized: maxlength=33554432,
>> tlength=33554432, base=4, prebuf=0, minreq=4 maxrewind=0
>> I: [pulseaudio] sink-input.c: Created input 0
>> "/usr/share/sounds/alsa/Front_**Center.wav" on alsa_output.default with
>> sample spec s16le 1ch 48000Hz and channel map mono
>> I: [pulseaudio] sink-input.c: media.format = "WAV (Microsoft)"
>> I: [pulseaudio] sink-input.c: application.name <http://application.name>
>> = "paplay"
>> I: [pulseaudio] sink-input.c: media.name <http://media.name> =
>>
>> "/usr/share/sounds/alsa/Front_**Center.wav"
>> I: [pulseaudio] sink-input.c: native-protocol.peer = "UNIX socket
>> client"
>> I: [pulseaudio] sink-input.c: native-protocol.version = "26"
>> I: [pulseaudio] sink-input.c: application.process.id
>> <http://application.process.id**> = "4735"
>>
>> I: [pulseaudio] sink-input.c: application.process.user = "root"
>> I: [pulseaudio] sink-input.c: application.process.host =
>> "10.195.245.138"
>> I: [pulseaudio] sink-input.c: application.process.binary = "pacat"
>> I: [pulseaudio] sink-input.c: application.language = "C"
>> I: [pulseaudio] sink-input.c: application.process.machine_id =
>> "10.195.245.138"
>> I: [pulseaudio] sink-input.c: module-stream-restore.id
>> <http://module-stream-restore.**id <http://module-stream-restore.id>> =
>> "sink-input-by-application-**name:paplay"
>>
>> I: [pulseaudio] protocol-native.c: Requested tlength=2000.00 ms,
>> minreq=20.00 ms
>> D: [pulseaudio] protocol-native.c: Traditional mode enabled, modifying
>> sink usec only for compat with minreq.
>> D: [pulseaudio] protocol-native.c: Requested latency=1960.00 ms,
>> Received latency=185.76 ms
>> D: [pulseaudio] memblockq.c: memblockq requested: maxlength=4194304,
>> tlength=192000, base=2, prebuf=190082, minreq=1920 maxrewind=0
>> D: [pulseaudio] memblockq.c: memblockq sanitized: maxlength=4194304,
>> tlength=192000, base=2, prebuf=190082, minreq=1920 maxrewind=0
>> I: [pulseaudio] protocol-native.c: Final latency 2185.76 ms = 1960.00 ms
>> + 2*20.00 ms + 185.76 ms
>> D: [pulseaudio] core-subscribe.c: Dropped redundant event due to change
>> event.
>> D: [alsa-sink] protocol-native.c: Requesting rewind due to end of
>> underrun.
>> D: [alsa-sink] sink-input.c: Do not do any rewind requests, seems to
>> cause loss of audio samples
>> D: [alsa-sink] alsa-sink.c: Requested to rewind 32768 bytes.
>> D: [alsa-sink] alsa-sink.c: Limited to 30976 bytes.
>> D: [alsa-sink] alsa-sink.c: before: 7744
>> D: [alsa-sink] alsa-sink.c: after: 7744
>> D: [alsa-sink] alsa-sink.c: Rewound 30976 bytes.
>> D: [alsa-sink] sink.c: Processing rewind...
>> D: [alsa-sink] source.c: Processing rewind...
>> D: [pulseaudio] module-suspend-on-idle.c: Sink alsa_output.default
>> becomes idle, timeout in 5 seconds.
>> D: [pulseaudio] module-suspend-on-idle.c: Sink alsa_output.default
>> becomes idle, timeout in 5 seconds.
>> D: [pulseaudio] core.c: Hmm, no streams around, trying to vacuum.
>> I: [pulseaudio] sink-input.c: Freeing input 0
>> "/usr/share/sounds/alsa/Front_**Center.wav"
>> I: [pulseaudio] client.c: Freed 0 "paplay"
>> I: [pulseaudio] protocol-native.c: Connection died.
>>
>>
>>
>> ______________________________**_________________
>> pulseaudio-discuss mailing list
>> pulseaudio-discuss at lists.**freedesktop.org<pulseaudio-discuss at lists.freedesktop.org>
>> http://lists.freedesktop.org/**mailman/listinfo/pulseaudio-**discuss<http://lists.freedesktop.org/mailman/listinfo/pulseaudio-discuss>
>>
>>
>
>
> --
> David Henningsson, Canonical Ltd.
> https://launchpad.net/~diwic
>
-------------- next part --------------
An HTML attachment was scrubbed...
URL: <http://lists.freedesktop.org/archives/pulseaudio-discuss/attachments/20130606/a28d441c/attachment.html>
More information about the pulseaudio-discuss
mailing list