beginning of audio files truncated
The setup is: pulseaudio 13.0 using alsa-lib 1.1.7, happening on both an i.MX6 as well as an amd64 embedded target.
Pulseaudio is started with:
/usr/bin/pulseaudio --system=false --exit-idle-time=-1 --log-level=4 --log-meta --log-target=file:/tmp/pa.log
When playing wav files using paplay I see this output:
I: [pulseaudio][../../pulseaudio/src/pulsecore/client.c:74 pa_client_new()] Created 43 "Native client (UNIX socket client)"
D: [pulseaudio][../../pulseaudio/src/pulsecore/protocol-native.c:2598 command_auth()] Protocol version: remote 33, local 33
I: [pulseaudio][../../pulseaudio/src/pulsecore/protocol-native.c:2631 command_auth()] Got credentials: uid=500 gid=500 success=1
D: [pulseaudio][../../pulseaudio/src/pulsecore/protocol-native.c:2661 command_auth()] SHM possible: yes
D: [pulseaudio][../../pulseaudio/src/pulsecore/protocol-native.c:2679 command_auth()] Negotiated SHM: yes
D: [pulseaudio][../../pulseaudio/src/pulsecore/protocol-native.c:2699 command_auth()] Memfd possible: yes
D: [pulseaudio][../../pulseaudio/src/pulsecore/protocol-native.c:2700 command_auth()] Negotiated SHM type: shared memfd
D: [pulseaudio][../../pulseaudio/src/pulsecore/memblock.c:859 pa_mempool_new()] Using shared memfd memory pool with 1024 slots of size 64.0 KiB each, total size is 64.0 MiB, maximum usable slot size is 65472
D: [pulseaudio][../../pulseaudio/src/pulsecore/srbchannel.c:249 pa_srbchannel_new()] SHM block is 65472 bytes, ringbuffer capacity is 2 * 32712 bytes
D: [pulseaudio][../../pulseaudio/src/pulsecore/protocol-native.c:2518 setup_srbchannel()] Enabling srbchannel...
D: [pulseaudio][../../pulseaudio/src/modules/module-augment-properties.c:299 process()] Looking for .desktop file for pacat
D: [pulseaudio][../../pulseaudio/src/pulsecore/protocol-native.c:2553 command_enable_srbchannel()] Client enabled srbchannel.
D: [pulseaudio][../../pulseaudio/src/modules/module-intended-roles.c:88 sink_input_new_hook_callback()] Not setting device for stream /tmp/bcl.wav, because it lacks role.
D: [pulseaudio][../../pulseaudio/src/pulsecore/sink-input.c:348 pa_sink_input_new()] Negotiated format: pcm, format.sample_format = "\"s16le\"" format.rate = "44100" format.channels = "2" format.channel_map = "\"front-left,front-right\""
I: [pulseaudio][../../pulseaudio/src/pulsecore/sink-input.c:423 pa_sink_input_new()] Trying to change sample spec
D: [pulseaudio][../../pulseaudio/src/pulsecore/sink.c:1466 pa_sink_reconfigure()] Default and alternate sample rates are the same, so there is no point in switching.
D: [pulseaudio][../../pulseaudio/src/pulsecore/resampler.c:417 pa_resampler_new()] Resampler:
D: [pulseaudio][../../pulseaudio/src/pulsecore/resampler.c:418 pa_resampler_new()] rate 44100 -> 48000 (method speex-float-1)
D: [pulseaudio][../../pulseaudio/src/pulsecore/resampler.c:420 pa_resampler_new()] format s16le -> s32le (intermediate float32le)
D: [pulseaudio][../../pulseaudio/src/pulsecore/resampler.c:421 pa_resampler_new()] channels 2 -> 2 (resampling 2)
I: [pulseaudio][../../pulseaudio/src/pulsecore/resampler/speex.c:170 pa_resampler_speex_init()] Choosing speex quality setting 1.
D: [pulseaudio][../../pulseaudio/src/pulsecore/memblockq.c:85 pa_memblockq_new()] memblockq requested: maxlength=33554432, tlength=0, base=8, prebuf=0, minreq=1 maxrewind=0
D: [pulseaudio][../../pulseaudio/src/pulsecore/memblockq.c:96 pa_memblockq_new()] memblockq sanitized: maxlength=33554432, tlength=33554432, base=8, prebuf=0, minreq=8 maxrewind=0
I: [pulseaudio][../../pulseaudio/src/pulsecore/sink-input.c:582 pa_sink_input_new()] Created input 43 "/tmp/bcl.wav" on alsa_output.default with sample spec s16le 2ch 44100Hz and channel map front-left,front-right
I: [pulseaudio][../../pulseaudio/src/pulsecore/sink-input.c:582 pa_sink_input_new()] media.format = "WAV (Microsoft)"
I: [pulseaudio][../../pulseaudio/src/pulsecore/sink-input.c:582 pa_sink_input_new()] application.name = "paplay"
I: [pulseaudio][../../pulseaudio/src/pulsecore/sink-input.c:582 pa_sink_input_new()] media.name = "/tmp/bcl.wav"
I: [pulseaudio][../../pulseaudio/src/pulsecore/sink-input.c:582 pa_sink_input_new()] native-protocol.peer = "UNIX socket client"
I: [pulseaudio][../../pulseaudio/src/pulsecore/sink-input.c:582 pa_sink_input_new()] native-protocol.version = "33"
I: [pulseaudio][../../pulseaudio/src/pulsecore/sink-input.c:582 pa_sink_input_new()] application.process.id = "1883"
I: [pulseaudio][../../pulseaudio/src/pulsecore/sink-input.c:582 pa_sink_input_new()] application.process.user = "someuser"
I: [pulseaudio][../../pulseaudio/src/pulsecore/sink-input.c:582 pa_sink_input_new()] application.process.host = "(none)"
I: [pulseaudio][../../pulseaudio/src/pulsecore/sink-input.c:582 pa_sink_input_new()] application.process.binary = "pacat"
I: [pulseaudio][../../pulseaudio/src/pulsecore/sink-input.c:582 pa_sink_input_new()] application.language = "C"
I: [pulseaudio][../../pulseaudio/src/pulsecore/sink-input.c:582 pa_sink_input_new()] application.process.machine_id = "dfe70e0d469e62641afb25475d4407a3"
I: [pulseaudio][../../pulseaudio/src/pulsecore/sink-input.c:582 pa_sink_input_new()] module-stream-restore.id = "sink-input-by-application-name:paplay"
I: [pulseaudio][../../pulseaudio/src/pulsecore/protocol-native.c:831 fix_playback_buffer_attr()] Requested tlength=2000.00 ms, minreq=20.00 ms
D: [pulseaudio][../../pulseaudio/src/pulsecore/protocol-native.c:882 fix_playback_buffer_attr()] Traditional mode enabled, modifying sink usec only for compat with minreq.
D: [pulseaudio][../../pulseaudio/src/pulsecore/protocol-native.c:908 fix_playback_buffer_attr()] Requested latency=1960.00 ms, Received latency=170.67 ms
D: [pulseaudio][../../pulseaudio/src/pulsecore/memblockq.c:85 pa_memblockq_new()] memblockq requested: maxlength=4194304, tlength=352800, base=4, prebuf=349276, minreq=3528 maxrewind=0
D: [pulseaudio][../../pulseaudio/src/pulsecore/memblockq.c:96 pa_memblockq_new()] memblockq sanitized: maxlength=4194304, tlength=352800, base=4, prebuf=349276, minreq=3528 maxrewind=0
I: [pulseaudio][../../pulseaudio/src/pulsecore/protocol-native.c:1104 playback_stream_new()] Final latency 2170.67 ms = 1960.00 ms + 2*20.00 ms + 170.67 ms
D: [alsa-sink-ALC887-VD Analog][../../pulseaudio/src/modules/alsa/alsa-sink.c:1072 update_sw_params()] Latency set to 170.67ms
D: [alsa-sink-ALC887-VD Analog][../../pulseaudio/src/modules/alsa/alsa-sink.c:1088 update_sw_params()] hwbuf_unused=8
D: [alsa-sink-ALC887-VD Analog][../../pulseaudio/src/modules/alsa/alsa-sink.c:1100 update_sw_params()] setting avail_min=7751
D: [alsa-sink-ALC887-VD Analog][../../pulseaudio/src/modules/alsa/alsa-sink.c:1115 update_sw_params()] Requesting rewind due to latency change.
D: [alsa-sink-ALC887-VD Analog][../../pulseaudio/src/modules/alsa/alsa-sink.c:1801 process_rewind()] Requested to rewind 65536 bytes.
D: [alsa-sink-ALC887-VD Analog][../../pulseaudio/src/modules/alsa/alsa-sink.c:1828 process_rewind()] Limited to 62592 bytes.
D: [alsa-sink-ALC887-VD Analog][../../pulseaudio/src/modules/alsa/alsa-sink.c:1831 process_rewind()] before: 7824
D: [alsa-sink-ALC887-VD Analog][../../pulseaudio/src/modules/alsa/alsa-sink.c:1841 process_rewind()] after: 7824
D: [alsa-sink-ALC887-VD Analog][../../pulseaudio/src/modules/alsa/alsa-sink.c:1849 process_rewind()] Rewound 62592 bytes.
D: [alsa-sink-ALC887-VD Analog][../../pulseaudio/src/pulsecore/sink.c:1052 pa_sink_process_rewind()] Processing rewind...
D: [alsa-sink-ALC887-VD Analog][../../pulseaudio/src/pulsecore/sink-input.c:1082 pa_sink_input_process_rewind()] Have to rewind 62592 bytes on render memblockq.
D: [alsa-sink-ALC887-VD Analog][../../pulseaudio/src/pulsecore/source.c:949 pa_source_process_rewind()] Processing rewind...
D: [pulseaudio][../../pulseaudio/src/pulsecore/sink.c:487 sink_set_state()] alsa_output.default: state: IDLE -> RUNNING
D: [alsa-sink-ALC887-VD Analog][../../pulseaudio/src/pulsecore/protocol-native.c:1289 handle_seek()] Requesting rewind due to end of underrun.
D: [alsa-sink-ALC887-VD Analog][../../pulseaudio/src/modules/alsa/alsa-sink.c:1801 process_rewind()] Requested to rewind 65528 bytes.
D: [alsa-sink-ALC887-VD Analog][../../pulseaudio/src/modules/alsa/alsa-sink.c:1828 process_rewind()] Limited to 64824 bytes.
D: [alsa-sink-ALC887-VD Analog][../../pulseaudio/src/modules/alsa/alsa-sink.c:1831 process_rewind()] before: 8103
D: [alsa-sink-ALC887-VD Analog][../../pulseaudio/src/modules/alsa/alsa-sink.c:1841 process_rewind()] after: 8103
D: [alsa-sink-ALC887-VD Analog][../../pulseaudio/src/modules/alsa/alsa-sink.c:1849 process_rewind()] Rewound 64824 bytes.
D: [alsa-sink-ALC887-VD Analog][../../pulseaudio/src/pulsecore/sink.c:1052 pa_sink_process_rewind()] Processing rewind...
D: [alsa-sink-ALC887-VD Analog][../../pulseaudio/src/pulsecore/sink-input.c:1082 pa_sink_input_process_rewind()] Have to rewind 64824 bytes on render memblockq.
D: [alsa-sink-ALC887-VD Analog][../../pulseaudio/src/pulsecore/source.c:949 pa_source_process_rewind()] Processing rewind...
D: [alsa-sink-ALC887-VD Analog][../../pulseaudio/src/pulsecore/protocol-native.c:1476 handle_input_underrun()] Implicit drain of '/tmp/bcl.wav'
D: [alsa-sink-ALC887-VD Analog][../../pulseaudio/src/pulsecore/sink.c:1028 pa_sink_process_input_underruns()] alsa_output.default: Found underrun 1680 bytes ago (63272 bytes ahead in playback buffer)
D: [alsa-sink-ALC887-VD Analog][../../pulseaudio/src/pulsecore/sink.c:1028 pa_sink_process_input_underruns()] alsa_output.default: Found underrun 1680 bytes ago (58920 bytes ahead in playback buffer)
D: [alsa-sink-ALC887-VD Analog][../../pulseaudio/src/pulsecore/sink.c:1028 pa_sink_process_input_underruns()] alsa_output.default: Found underrun 1680 bytes ago (50792 bytes ahead in playback buffer)
D: [alsa-sink-ALC887-VD Analog][../../pulseaudio/src/pulsecore/sink.c:1028 pa_sink_process_input_underruns()] alsa_output.default: Found underrun 1680 bytes ago (42600 bytes ahead in playback buffer)
D: [alsa-sink-ALC887-VD Analog][../../pulseaudio/src/pulsecore/sink.c:1028 pa_sink_process_input_underruns()] alsa_output.default: Found underrun 1680 bytes ago (34472 bytes ahead in playback buffer)
D: [alsa-sink-ALC887-VD Analog][../../pulseaudio/src/pulsecore/sink.c:1028 pa_sink_process_input_underruns()] alsa_output.default: Found underrun 39248 bytes ago (26152 bytes ahead in playback buffer)
D: [alsa-sink-ALC887-VD Analog][../../pulseaudio/src/pulsecore/sink.c:1028 pa_sink_process_input_underruns()] alsa_output.default: Found underrun 39248 bytes ago (17896 bytes ahead in playback buffer)
D: [alsa-sink-ALC887-VD Analog][../../pulseaudio/src/pulsecore/sink.c:1028 pa_sink_process_input_underruns()] alsa_output.default: Found underrun 39248 bytes ago (9768 bytes ahead in playback buffer)
D: [alsa-sink-ALC887-VD Analog][../../pulseaudio/src/pulsecore/sink.c:1028 pa_sink_process_input_underruns()] alsa_output.default: Found underrun 39248 bytes ago (1640 bytes ahead in playback buffer)
D: [alsa-sink-ALC887-VD Analog][../../pulseaudio/src/pulsecore/protocol-native.c:1483 handle_input_underrun()] Drain acknowledged of '/tmp/bcl.wav'
D: [alsa-sink-ALC887-VD Analog][../../pulseaudio/src/modules/alsa/alsa-sink.c:1088 update_sw_params()] hwbuf_unused=0
D: [alsa-sink-ALC887-VD Analog][../../pulseaudio/src/modules/alsa/alsa-sink.c:1100 update_sw_params()] setting avail_min=7750
D: [alsa-sink-ALC887-VD Analog][../../pulseaudio/src/modules/alsa/alsa-sink.c:1801 process_rewind()] Requested to rewind 65536 bytes.
D: [alsa-sink-ALC887-VD Analog][../../pulseaudio/src/modules/alsa/alsa-sink.c:1828 process_rewind()] Limited to 38520 bytes.
D: [alsa-sink-ALC887-VD Analog][../../pulseaudio/src/modules/alsa/alsa-sink.c:1831 process_rewind()] before: 4815
D: [alsa-sink-ALC887-VD Analog][../../pulseaudio/src/modules/alsa/alsa-sink.c:1841 process_rewind()] after: 4815
D: [alsa-sink-ALC887-VD Analog][../../pulseaudio/src/modules/alsa/alsa-sink.c:1849 process_rewind()] Rewound 38520 bytes.
D: [alsa-sink-ALC887-VD Analog][../../pulseaudio/src/pulsecore/sink.c:1052 pa_sink_process_rewind()] Processing rewind...
D: [alsa-sink-ALC887-VD Analog][../../pulseaudio/src/pulsecore/source.c:949 pa_source_process_rewind()] Processing rewind...
D: [pulseaudio][../../pulseaudio/src/pulsecore/sink.c:487 sink_set_state()] alsa_output.default: state: RUNNING -> IDLE
D: [pulseaudio][../../pulseaudio/src/pulsecore/core.c:482 pa_core_maybe_vacuum()] Hmm, no streams around, trying to vacuum.
I: [pulseaudio][../../pulseaudio/src/pulsecore/sink-input.c:748 sink_input_free()] Freeing input 43 "/tmp/bcl.wav"
I: [pulseaudio][../../pulseaudio/src/pulsecore/client.c:96 pa_client_free()] Freed 43 "paplay"
I: [pulseaudio][../../pulseaudio/src/pulsecore/protocol-native.c:5066 pstream_die_callback()] Connection died.
The beginning of the audio files is damaged, i.e. something in the first ~0.2 seconds sees random sample drop, so when I play short sounds I sometimes hear nothing of that. I usually have another stream playing in the background, normally coming from Gstreamer 1.12.2 either playing a video or just some mp3 files. I see the underrun warnings in both cases, and the audio problems are also present in both cases.