Re: [pulseaudio-discuss] Failed to drain stream: Timeout
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.hennings...@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/0x0003 [ 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
Re: [pulseaudio-discuss] Failed to drain stream: Timeout
i was able to play this file from aplay so i guess alsa driver is working fine. On Tue, Jun 4, 2013 at 3:24 PM, D K dsp...@gmail.com 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/0x0003 [ 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) 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 0x, 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) 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:
Re: [pulseaudio-discuss] Failed to drain stream: Timeout
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/0x0003 [ 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 0x, 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
