Delays in audio_stream() plugin function

[aaknitt]

I'm doing some testing with the plugin interface to try to put together a plugin that will do live audio streaming. I've set up a very simple plugin that implements the int audio_stream(Recorder *recorder, float *samples, int sampleCount) function.

It looks like each time this function gets called, trunk-recorder is sending it 3456 bytes of audio data, which is in 32 bit float format at 8 kHz. This works out to .108 seconds of audio per function call. However, the function calls are only taking place every 0.17 to 0.19 seconds, resulting in broken audio on the receiving end if played back in real time.

If I write the received data to a WAV file on the receiving end it sounds perfect, so no audio is being lost, but it seems like it's not being sent fast enough for real time streaming. I've tried this on both a Pi 4 and an Ubuntu machine and the ~0.18 second spacing between function calls seems pretty consistent between those two different platforms.

I did try buffering but the audio player was sucking data out of the buffer faster than it was getting put in. So it would make the audio "listenable" but there would still be breaks between when the buffer emptied out and it got enough samples to start playing again...basically just changed it from very frequent short breaks to less frequent longer breaks.

Minimal plugin code to test with is attached. This looks for a single TGID (to keep the debugging printouts constrained to a single recorder) in the plugins config.json area as follows:
"plugins":[{"library":"libsimplestream.so","name":"simplestream","TGID":58914}]
Whenever the audio_stream() function gets called for the specified talkgroup, it will print out the number of bytes received by the function. Timestamps of the print statements can be compared to get the delta time between function calls. As posted, this plugin doesn't actually do anything with the audio, it's just spitting out print statements for debugging the timing issue.
simplestream.zip

[JoeGilkey]

Put the audio samples into a ring buffer as they are received. Read the available samples in a separate thread to upload them. If you do the upload in the stream call itself, that slows down the whole GnuRadio chain. You may want to look into converting those raw wave samples into MP3 or similar compressed format before sending. The packet size would be smaller, reducing network latency.

[aaknitt]

@JoeGilkey the part that has me confused is that I'm seeing ~0.18 seconds between function calls even when I don't do anything at all with the audio samples...no streaming, no uploading, nothing. Just printing out the number of bytes available during each function call (which equals 1.08 seconds of audio).

[JoeGilkey]

@aaknitt I’ll look into this a little closer. When you ran into this, was there continuous audio or points of silence? Also, is the numbers you are seeing consistent? What was the CPU usage at this point on the machines you tried it on?

[aaknitt]

It seems like it's happening throughout a recording, even if there are lulls in the audio between transmissions. The numbers seem pretty consistent, in the 0.17 to 0.19 second range, with 0.18 seemingly about average. CPU usage is all over the place depending on how busy the system is at the time (from about 50% to about 120% as reported by top on a Pi 4), but the numbers listed above seem fairly consistent across CPU usage (and on both a Pi 4 and an older Ubuntu box). Screenshot below is on a Pi 4, so the 111% CPU usage for trunk-recorder is actually about 27% if I understand how top reports usage.

This screenshot shows a bunch of audio_stream() function calls with 864 samples (1.08 seconds) of audio each, followed by one function call with 288 samples (last snippet at the end of the transmission). It then shows a bunch of function calls each reporting a single sample. I've notice those single-sample function calls happening a lot at the start and end of transmissions but not yet sure why.

On a tangent @JoeGilkey are you the author of the "streamer" plugin that's in the trunk-recorder code already? I think that plugin could work for what I'm trying to do but haven't figured out how to use it quite yet.

[JoeGilkey]

Thank you, I’ll take a look into this. One thing off the bat would be to reduce the bandwidth on each SDR. That would reduce CPU and memory usage. You’re not getting overflows reading from the SDR, so increasing the number of samples into the GnuRadio pipeline may help fill in the audio some.

And yes, I had created the “streamer” plugin, and the initial plugin system. I had used it to feed multiple audio streams from RaspberryPi 3 units using KerberosSDR modules into a single RaspberryPi 3 which re-broadcasted a single stream over Bluetooth audio with the single stream selected using a BLE GATT interface. I’m going to pick that code apart and make some enhancements that others might find helpful (i.e. ring buffers so the streams don’t affect the GnuRadio pipeline).

[robotastic]

OK!! @aaknitt I think I may have found the problem. When I updated to the latest version of OP25 - they had removed a forecast() call, so I did too. This forecast call lets you know the ratio of packets coming in, to what is going out. With audio, it looks like it should be 0.6 vs the default of 1.0.... which lines up pretty closely to what you were seeing! I just reverted and set this back.

Let me know what this does.

I could also switch things around and have it dump out chunks of audio as they come, which could help prevent any samples from being stuck in the queue... do you have buffering on the playback side?

[aaknitt]

Sounds good, thanks @robotastic . I just did a quick test by just grabbing those two files and rebuilding, but for some reason the audio_stream() function in the plugin is never getting called (call_start() and call_end() are getting called). I can't imagine that's due to the change you made...I may have something else messed up since I'm off on my own branch at the moment. I'll need to get back to master and try it but that may not be for a day or two.

[aaknitt]

Merged with Master and I'm still not seeing audio_stream() getting called...bizarre. I'll dig further.

[aaknitt]

I'm an idiot...forgot about the new config setting already, even after you reminded me...stand by

[aaknitt]

Ok, I added the new setting to the JSON and I'm still not seeing calls being made to audio_stream(). I added a debugging statement in p25_recorder_decode.cc here:

  bool use_streaming = d_recorder->get_enable_audio_streaming();
  BOOST_LOG_TRIVIAL(info) << "^^^^^^^^^^^^^^^^^  use_streaming is set to " << use_streaming;

When trunk-recorder starts up I get a number of these statements printed out telling me that use_streaming is false and then I get the printout showing all the config file info where it's showing that audio streaming is enabled.

So perhaps p25_recorder_decode.cc is initializing and setting that value before the config file is actually read in?

I'll try hard-coding audio streaming on so that I can test this fix but there may be an issue with pull #559 @JoeGilkey

[aaknitt]

After hard-coding audio streaming on, this is working great! No more delays, thanks @robotastic !

[robotastic]

I am just re-opening this issue until I figure out what is up with that config setting. Good to hear this fixes things! If you have a chance, could you try pulling the latest version from the master branch? I changed how audio gets queued up. It will now dump out everything it decodes. This works fine for a file, I am curious what it looks like for streaming.

[robotastic]

Ok - fixed things so the audioStreaming flag should work. It was reading in the flag after it had already setup the recorders.

[aaknitt]

I am just re-opening this issue until I figure out what is up with that config setting. Good to hear this fixes things! If you have a chance, could you try pulling the latest version from the master branch? I changed how audio gets queued up. It will now dump out everything it decodes. This works fine for a file, I am curious what it looks like for streaming.

Seems to be working fine. It changed the number of bytes being sent with each call to audio_stream() (more bytes per call now) and I'm no longer seeing a smaller number of bytes in the last call of a transmission (all seem to contain 5760 bytes), presumably because it's now sending full frames so there's nothing to break up. I'm still a little curious about what causes the sequence of function calls with a single sample (4 bytes) before and after the calls with the audio data (5760 bytes). They don't seem to be hurting anything (I just ignore them), but not sure what's causing them.

Ok - fixed things so the audioStreaming flag should work. It was reading in the flag after it had already setup the recorders.

This is working fine now, thanks!

[aaknitt]

Been working well for some time now - closing.