Hello list, I need some help. When running GRC 3.6.1 I am getting a problem with occasional choppiness in my audio output. Details:
* The choppiness sounds like only part of the buffer is filling, similar to the sound you get when a filmstrip's playback gets unstable and you get that 'jitter' * The issue usually does not immediately occur however occurs a few minutes into use. * Sometimes computer activity such as un-minimizing a window will trigger the problem. Sometimes the same will fix it. * Input is Funcube Dongle Pro+ 192khz on alsa hw:3 * Occurs regardless of using FCDPP+ Block or the Audio Input block. * Output is pulse, originally set to 192khz (pulse resamples it), brought it down to native 48khz and used Rational Resampler block to bring the 192 to 48. Did not resolve, however the issue occurred less often. (still intolerable) * Turned on Realtime Scheduling and then adapted the JACK instructions for enabling system realtime scheduling permissions ( http://jackaudio.org/linux_rt_config). Afterward confirmed the python process to have a nice of -30 which is realtime. Issue did not resolve but again, it happened less often. (still intolerable) * Occurs regardless of graph complexity. Simple in->out arrangement will reproduce issue. * Sometimes you can hear it get worse as time goes by, and sometimes it will just as randomly fix itself, only to occur again later. * I am using pulse as my audio output. * When the issue occurs, the console output in GRC fills rapidly with "aUaU" * When the issue occurs, looking into pavucontrol playback tab shows "ALSA plug-in [python 2.7]" entry flickering rapidly, as if it is resetting its connection over and over in an unreasonable manner. * When the issue occurs, the realtime python process on core 2 shows no change in core usage, however the non-realtime gnuradio-companion process, also on core 2, spikes from its usual 0.9% usage to 93%. The only way I can see a high-priority process being pushed out by a low-priority process is if the high-priority process is waiting on the low-priority process for some operation to complete (this is a DSP no-no). * When the issue occurs, pulseaudio's verbose log fills rapidly. attached is a snippet of what repeatedly fills the log. * There is chatter about similar underrun issues with mozilla and pulse. However the fixes appear to be occurring in mozilla only so there wasn't much help from that. (https://bugzilla.mozilla.org/show_bug.cgi?id=779392) * When attempting to specify 'pulse' as signal input in GRC and then specify FCDPP as its input in pavucontrol, GRC gives silence and a stream of "aU" * pulseaudio 4.0 * Xubuntu 13.10 AMD64. There was a similar issue posted earlier however it was different in nature in the sense that the underruns occurred immediately instead of on occasion, implying a consistent sample rate mismatch. https://lists.gnu.org/archive/html/discuss-gnuradio/2013-08/msg00516.html It is reasonable to rule out sample-rate mismatch in my case as the issue occurs only on occasion and sometimes fixes on its own, a mismatch would be expected to immediately fail. It would be mathematically impossible for a mismatched sample rate to cause such cascading underruns after minutes of proper functioning except for clock drift, which would be expected to be solved with a single buffer reset (a slight "blip"). This is not what is happening. It is thousands of consecutive blips after a while of proper functioning. Thanks for reading. Log dump attached.
( 82.498| 0.000) D: [alsa-sink-ALC889A Analog] protocol-native.c: Implicit underrun of 'ALSA Playback' ( 82.498| 0.000) D: [alsa-sink-ALC889A Analog] sink.c: Found underrun 944 bytes ago (3948 bytes ahead in playback buffer) ( 82.499| 0.000) D: [alsa-sink-ALC889A Analog] sink.c: Found underrun 944 bytes ago (3884 bytes ahead in playback buffer) ( 82.499| 0.000) D: [alsa-sink-ALC889A Analog] sink.c: Found underrun 944 bytes ago (3872 bytes ahead in playback buffer) ( 82.499| 0.000) D: [alsa-sink-ALC889A Analog] sink.c: Found underrun 944 bytes ago (3764 bytes ahead in playback buffer) ( 82.499| 0.000) D: [alsa-sink-ALC889A Analog] sink.c: Found underrun 944 bytes ago (3756 bytes ahead in playback buffer) ( 82.500| 0.000) D: [alsa-sink-ALC889A Analog] sink.c: Found underrun 944 bytes ago (3716 bytes ahead in playback buffer) ( 82.500| 0.000) D: [alsa-sink-ALC889A Analog] sink.c: Found underrun 944 bytes ago (3708 bytes ahead in playback buffer) ( 82.500| 0.000) D: [alsa-sink-ALC889A Analog] sink.c: Found underrun 944 bytes ago (3672 bytes ahead in playback buffer) ( 82.500| 0.000) D: [alsa-sink-ALC889A Analog] sink.c: Found underrun 944 bytes ago (3664 bytes ahead in playback buffer) ( 82.500| 0.000) D: [alsa-sink-ALC889A Analog] sink.c: Found underrun 944 bytes ago (3628 bytes ahead in playback buffer) ( 82.500| 0.000) D: [alsa-sink-ALC889A Analog] sink.c: Found underrun 944 bytes ago (3620 bytes ahead in playback buffer) ( 82.500| 0.000) D: [alsa-sink-ALC889A Analog] sink.c: Found underrun 944 bytes ago (3576 bytes ahead in playback buffer) ( 82.500| 0.000) D: [alsa-sink-ALC889A Analog] sink.c: Found underrun 944 bytes ago (3568 bytes ahead in playback buffer) ( 82.501| 0.000) D: [alsa-sink-ALC889A Analog] sink.c: Found underrun 944 bytes ago (3532 bytes ahead in playback buffer) ( 82.501| 0.000) D: [alsa-sink-ALC889A Analog] sink.c: Found underrun 944 bytes ago (3524 bytes ahead in playback buffer) ( 82.508| 0.007) D: [alsa-sink-ALC889A Analog] sink.c: Found underrun 2808 bytes ago (2176 bytes ahead in playback buffer) ( 82.508| 0.000) D: [alsa-sink-ALC889A Analog] alsa-sink.c: hwbuf_unused=0 ( 82.508| 0.000) D: [alsa-sink-ALC889A Analog] alsa-sink.c: setting avail_min=16000 ( 82.508| 0.000) D: [alsa-sink-ALC889A Analog] alsa-sink.c: Requested volume: 0: 95% 1: 95% ( 82.508| 0.000) D: [alsa-sink-ALC889A Analog] alsa-sink.c: in dB: 0: -1.34 dB 1: -1.34 dB ( 82.508| 0.000) D: [alsa-sink-ALC889A Analog] alsa-sink.c: Got hardware volume: 0: 96% 1: 96% ( 82.508| 0.000) D: [alsa-sink-ALC889A Analog] alsa-sink.c: in dB: 0: -1.20 dB 1: -1.20 dB ( 82.508| 0.000) D: [alsa-sink-ALC889A Analog] alsa-sink.c: Calculated software volume: 0: 99% 1: 99% (accurate-enough=yes) ( 82.508| 0.000) D: [alsa-sink-ALC889A Analog] alsa-sink.c: in dB: 0: -0.14 dB 1: -0.14 dB ( 82.508| 0.000) D: [alsa-sink-ALC889A Analog] sink.c: Volume not changing ( 82.508| 0.000) D: [alsa-sink-ALC889A Analog] alsa-sink.c: Requested to rewind 65536 bytes. ( 82.508| 0.000) D: [alsa-sink-ALC889A Analog] alsa-sink.c: Limited to 4596 bytes. ( 82.508| 0.000) D: [alsa-sink-ALC889A Analog] alsa-sink.c: before: 1149 ( 82.508| 0.000) D: [alsa-sink-ALC889A Analog] alsa-sink.c: after: 1149 ( 82.508| 0.000) D: [alsa-sink-ALC889A Analog] alsa-sink.c: Rewound 4596 bytes. ( 82.509| 0.000) D: [alsa-sink-ALC889A Analog] sink.c: Processing rewind... ( 82.509| 0.000) D: [alsa-sink-ALC889A Analog] sink.c: latency = 1128 ( 82.509| 0.000) D: [alsa-sink-ALC889A Analog] source.c: Processing rewind... ( 82.508| 0.000) D: [pulseaudio] module-suspend-on-idle.c: Sink alsa_output.pci-0000_00_14.2.analog-stereo becomes idle, timeout in 5 seconds. ( 82.509| 0.000) D: [pulseaudio] module-suspend-on-idle.c: Sink alsa_output.pci-0000_00_14.2.analog-stereo becomes idle, timeout in 5 seconds. ( 82.509| 0.000) D: [pulseaudio] core.c: Hmm, no streams around, trying to vacuum. ( 82.510| 0.001) I: [pulseaudio] sink-input.c: Freeing input 245 "ALSA Playback" ( 82.511| 0.001) D: [pulseaudio] module-intended-roles.c: Not setting device for stream ALSA Playback, because it lacks role. ( 82.520| 0.009) I: [pulseaudio] sink-input.c: Trying to change sample rate ( 82.520| 0.000) I: [pulseaudio] module-stream-restore.c: Restoring volume for sink input sink-input-by-application-name:ALSA plug-in [python2.7]. ( 82.520| 0.000) D: [pulseaudio] module-suspend-on-idle.c: Sink alsa_output.pci-0000_00_14.2.analog-stereo becomes busy, resuming. ( 82.520| 0.000) I: [pulseaudio] resampler.c: Using resampler 'speex-float-1' ( 82.521| 0.000) I: [pulseaudio] resampler.c: Using float32le as working format. ( 82.521| 0.000) D: [pulseaudio] resampler.c: Resampler: ( 82.521| 0.000) D: [pulseaudio] resampler.c: rate 192000 -> 48000 (method speex-float-1), ( 82.521| 0.000) D: [pulseaudio] resampler.c: format s32le -> s16le (intermediate float32le), ( 82.521| 0.000) D: [pulseaudio] resampler.c: channels 2 -> 2 (resampling 2) ( 82.521| 0.000) I: [pulseaudio] resampler.c: Choosing speex quality setting 1. ( 82.521| 0.000) D: [pulseaudio] memblockq.c: memblockq requested: maxlength=33554432, tlength=0, base=4, prebuf=0, minreq=1 maxrewind=0 ( 82.521| 0.000) D: [pulseaudio] memblockq.c: memblockq sanitized: maxlength=33554432, tlength=33554432, base=4, prebuf=0, minreq=4 maxrewind=0 ( 82.521| 0.000) I: [pulseaudio] sink-input.c: Created input 246 "ALSA Playback" on alsa_output.pci-0000_00_14.2.analog-stereo with sample spec s32le 2ch 192000Hz and channel map front-left,front-right ( 82.521| 0.000) I: [pulseaudio] sink-input.c: media.name = "ALSA Playback" ( 82.521| 0.000) I: [pulseaudio] sink-input.c: application.name = "ALSA plug-in [python2.7]" ( 82.521| 0.000) I: [pulseaudio] sink-input.c: native-protocol.peer = "UNIX socket client" ( 82.521| 0.000) I: [pulseaudio] sink-input.c: native-protocol.version = "28" ( 82.521| 0.000) I: [pulseaudio] sink-input.c: application.process.id = "7219" ( 82.521| 0.000) I: [pulseaudio] sink-input.c: application.process.user = "user" ( 82.521| 0.000) I: [pulseaudio] sink-input.c: application.process.host = "machine" ( 82.521| 0.000) I: [pulseaudio] sink-input.c: application.process.binary = "python2.7" ( 82.521| 0.000) I: [pulseaudio] sink-input.c: application.language = "en_US.UTF-8" ( 82.521| 0.000) I: [pulseaudio] sink-input.c: window.x11.display = ":0.0" ( 82.521| 0.000) I: [pulseaudio] sink-input.c: application.process.machine_id = "72038a314a8f5db7e631630f00000008" ( 82.521| 0.000) I: [pulseaudio] sink-input.c: application.process.session_id = "c4" ( 82.521| 0.000) I: [pulseaudio] sink-input.c: application.icon_name = "/usr/share/pixmaps/python2.7.xpm" ( 82.521| 0.000) I: [pulseaudio] sink-input.c: module-stream-restore.id = "sink-input-by-application-name:ALSA plug-in [python2.7]" ( 82.521| 0.000) I: [pulseaudio] protocol-native.c: Requested tlength=40.00 ms, minreq=10.00 ms ( 82.521| 0.000) D: [pulseaudio] protocol-native.c: Early requests mode enabled, configuring sink latency to minreq. ( 82.521| 0.000) D: [pulseaudio] protocol-native.c: Requested latency=10.00 ms, Received latency=26.00 ms ( 82.521| 0.000) D: [pulseaudio] memblockq.c: memblockq requested: maxlength=4194304, tlength=119808, base=8, prebuf=30720, minreq=39936 maxrewind=0 ( 82.521| 0.000) D: [pulseaudio] memblockq.c: memblockq sanitized: maxlength=4194304, tlength=119808, base=8, prebuf=30720, minreq=39936 maxrewind=0 ( 82.521| 0.000) I: [pulseaudio] protocol-native.c: Final latency 104.00 ms = 26.00 ms + 2*26.00 ms + 26.00 ms ( 82.522| 0.000) D: [alsa-sink-ALC889A Analog] alsa-sink.c: Latency set to 26.00ms ( 82.522| 0.000) D: [alsa-sink-ALC889A Analog] alsa-sink.c: hwbuf_unused=60544 ( 82.522| 0.000) D: [alsa-sink-ALC889A Analog] alsa-sink.c: setting avail_min=16001 ( 82.522| 0.000) D: [alsa-sink-ALC889A Analog] alsa-sink.c: Requesting rewind due to latency change. ( 82.522| 0.000) D: [alsa-sink-ALC889A Analog] alsa-sink.c: Requested volume: 0: 95% 1: 95% ( 82.522| 0.000) D: [alsa-sink-ALC889A Analog] alsa-sink.c: in dB: 0: -1.34 dB 1: -1.34 dB ( 82.522| 0.000) D: [alsa-sink-ALC889A Analog] alsa-sink.c: Got hardware volume: 0: 96% 1: 96% ( 82.522| 0.000) D: [alsa-sink-ALC889A Analog] alsa-sink.c: in dB: 0: -1.20 dB 1: -1.20 dB ( 82.522| 0.000) D: [alsa-sink-ALC889A Analog] alsa-sink.c: Calculated software volume: 0: 99% 1: 99% (accurate-enough=yes) ( 82.522| 0.000) D: [alsa-sink-ALC889A Analog] alsa-sink.c: in dB: 0: -0.14 dB 1: -0.14 dB ( 82.522| 0.000) D: [alsa-sink-ALC889A Analog] sink.c: Volume not changing ( 82.522| 0.000) D: [alsa-sink-ALC889A Analog] alsa-sink.c: Requested to rewind 65536 bytes. ( 82.522| 0.000) D: [alsa-sink-ALC889A Analog] alsa-sink.c: Limited to 62700 bytes. ( 82.522| 0.000) D: [alsa-sink-ALC889A Analog] alsa-sink.c: before: 15675 ( 82.522| 0.000) D: [alsa-sink-ALC889A Analog] alsa-sink.c: after: 15675 ( 82.522| 0.000) D: [alsa-sink-ALC889A Analog] alsa-sink.c: Rewound 62700 bytes. ( 82.522| 0.000) D: [alsa-sink-ALC889A Analog] sink.c: Processing rewind... ( 82.522| 0.000) D: [alsa-sink-ALC889A Analog] sink.c: latency = 1200 ( 82.522| 0.000) D: [alsa-sink-ALC889A Analog] sink-input.c: Have to rewind 62700 bytes on render memblockq. ( 82.522| 0.000) D: [alsa-sink-ALC889A Analog] source.c: Processing rewind... ( 82.524| 0.001) D: [alsa-sink-ALC889A Analog] protocol-native.c: Requesting rewind due to end of underrun. ( 82.524| 0.000) D: [alsa-sink-ALC889A Analog] alsa-sink.c: Requested to rewind 65536 bytes. ( 82.524| 0.000) D: [alsa-sink-ALC889A Analog] alsa-sink.c: Limited to 4456 bytes. ( 82.524| 0.000) D: [alsa-sink-ALC889A Analog] alsa-sink.c: before: 1114 ( 82.524| 0.000) D: [alsa-sink-ALC889A Analog] alsa-sink.c: after: 1114 ( 82.524| 0.000) D: [alsa-sink-ALC889A Analog] alsa-sink.c: Rewound 4456 bytes. ( 82.524| 0.000) D: [alsa-sink-ALC889A Analog] sink.c: Processing rewind... ( 82.524| 0.000) D: [alsa-sink-ALC889A Analog] sink.c: latency = 1196 ( 82.524| 0.000) D: [alsa-sink-ALC889A Analog] sink-input.c: Have to rewind 4456 bytes on render memblockq. ( 82.524| 0.000) D: [alsa-sink-ALC889A Analog] source.c: Processing rewind... ( 82.524| 0.000) D: [alsa-sink-ALC889A Analog] protocol-native.c: Implicit underrun of 'ALSA Playback' ( 82.524| 0.000) D: [alsa-sink-ALC889A Analog] sink.c: Found underrun 936 bytes ago (3968 bytes ahead in playback buffer) ( 82.525| 0.000) D: [alsa-sink-ALC889A Analog] sink.c: Found underrun 936 bytes ago (3920 bytes ahead in playback buffer) ( 82.525| 0.000) D: [alsa-sink-ALC889A Analog] sink.c: Found underrun 936 bytes ago (3908 bytes ahead in playback buffer) ( 82.525| 0.000) D: [alsa-sink-ALC889A Analog] sink.c: Found underrun 936 bytes ago (3856 bytes ahead in playback buffer) ( 82.525| 0.000) D: [alsa-sink-ALC889A Analog] sink.c: Found underrun 936 bytes ago (3848 bytes ahead in playback buffer) ( 82.525| 0.000) D: [alsa-sink-ALC889A Analog] sink.c: Found underrun 936 bytes ago (3776 bytes ahead in playback buffer) ( 82.525| 0.000) D: [alsa-sink-ALC889A Analog] sink.c: Found underrun 936 bytes ago (3764 bytes ahead in playback buffer)
_______________________________________________ Discuss-gnuradio mailing list Discuss-gnuradio@gnu.org https://lists.gnu.org/mailman/listinfo/discuss-gnuradio
