Bug: radio reception is sometimes choppy #72

hbeni · 2021-02-05T22:28:54Z

Reported by mill-j:

Received audio is choppy when the plugin is on.
This is also testable with the 910 test, and still true when using radioGUI.
The problem does not occur if the plugin is inactive (but still loaded).
Audio processing functions seem not to be the problem.
It looks like a cpu bottleneck problem, because with two radioguis mumble uses 100% of one core alone
Machine: lenovo G50-45 Quad core amd 8gb ram

Identified mumble branch state:

commit 9a4b659f4242e892f5686185e78fd18fcc93f84a
Author: Robert Adam <[email protected]>
Date:   Fri Dec 25 18:50:22 2020 +0100

    Fix copy&paste error

FGCom-mumble commit is 4b3ed22

I could not reproduce this here on my box (on mumble commit deb74a66348 "FIX: C&P error in API implementation" with 4b3ed22).
maybe this is a side effect of client version mismatch?

(This may have been introduced by mumbles commit c7ebe95030 "Synchronized API calls")
may be related to #58 as there are restructuring tips

The text was updated successfully, but these errors were encountered:

hbeni · 2021-02-07T21:43:23Z

mill-j reported that he mostly got it working now.
It seems to be a combination of network, mumble-settings and also if you compile mumble and/or the plugin in debug mode.

(debug mode for the plugin is always on with <1.0 versions, so must be manually turned off in the makefile)

hbeni · 2021-02-12T19:48:13Z

One reason for choppy audio may be that the audio processing is too slow.

@mill-j, you might look at the timestamps in the logfile when receiving audio. You can deduce if the time it takes to process takes longer than allowed (PCM frame spacing / 20ms), probably we need to optimize the code there.

mill-j · 2021-02-12T21:27:53Z

I'll see what I can find. Just noticed if I start two RadioGUI instances and have only one radio in each then audio is great. If i add three it's worse than two.

hbeni · 2021-02-12T21:48:02Z

That would also suggest something "too slow" in the audio loop (mumble_onAudioSourceFetched).
For each sample, the remote state is inspected to see if we can receive the radio signal. That loop gets longer with each client and also with each radio.

However the contrary: I was able to receive radio from about 100 fake clients (lua bots, but from the perspective of your own plugin, that's not known and they behave like normal clients) without choppy audio...

hbeni · 2021-02-12T22:17:30Z

Another cause could be:
mumble_onAudioSourceFetched aquires a lock to radiofgcom_remotecfg_mtx. That is written to by the intern plugin IO, so when receiving much changing information, this will cause the lock to be not available for the audio callback. Writing the remote state is a fast operation, however it may not be fast enough...

This may possibly be solved by introducing a priority locking scheme favoring the audio callback, proposed here: https://stackoverflow.com/a/11673600
If the audio callback thread would have priority, it would get ahead of the data writer thread. That may however lead to the situation that for the duration of the current voice stream no updates are performed (no more signal degregation near the radio horizon and stop of the current transmission when over it - only the next transmission would be affected?).
Maybe also a std::shared_mutex is enough here too, if the audio thread aquires a exclusive lock before the data is written.
Finally, I also really do not know if we really need a lock here - we are just reading from the state, so that should not cause harm; the writer thread has atomic writes to the data. however the GC thread probably needs to share a lock with the audio thread, but GC is running not often.

hbeni · 2021-02-12T22:45:50Z

@mill-j to quickly try out if its a locking issue, just remove the lock statements in the audio callback.

If that helps, we probably need a exclusive locking at least in the writer (and gc thread) where the structure or the data changes (like adding/removing clients or radios).
Probably also a good optimization would be to just lock the affected client data, not the entire store.

mill-j · 2021-02-13T04:19:23Z

Removing the lock fgcom_remotecfg_mtx.lock(); and fgcom_remotecfg_mtx.unlock(); from mumble_onAudioSourceFetched does not seem to make any difference in audio.

hbeni · 2021-02-13T08:21:33Z

Hm then it’s probably something else.
Can you attach a full log (please don’t truncate) of the process when you received the choppiness?

hbeni · 2021-02-13T19:29:51Z

@mill-j Aside from the log: can you please try to do the following:

make fgcom_audio_addNoise a noop by returning in the first line of client/mumble-plugin/lib/audio.cpp.
Then, if that didn't change anything, make fgcom_audio_applyVolume a noop the same way.
Then, the same with fgcom_audio_makeMono
Finally fgcom_audio_filter

If we deduce by this which function introduces it, reenable the other functions to see if it can be isolated this way.

Thanks!

mill-j · 2021-02-14T01:32:53Z

StutterLog.txt
Hope this is what you want. This is a log of me testing two RadioGUI/Mumble instances with two radios each and testing all four PTT buttons and they all had choppy audio.

I had already tested without fgcom_audio_makeMono several days ago. I still haven't got around to testing the rest.

mill-j · 2021-02-14T02:09:04Z

After disabling the functions in audio.cpp it is no better. I do know the stuttering is the result from low resources: With two RadioGui Instances with 3 radios each. The two mumble clients are each maxing out a cpu core at 100%. Disconnecting only RadioGUI and not doing anything wth mumble will get the cpu uasge down to normal. So somehow we need to optimize for lower end computers.

hbeni · 2021-02-14T10:29:40Z

This is a very good finding. The question is where recently all this cpu is burned.
If you disable all the audio processing, it is not there.

hbeni · 2021-02-14T11:07:46Z

Hm, we already found out sometime so that the audio receiving callback is too slow.

fgcom-mumble/client/mumble-plugin/fgcom-mumble.cpp

Line 812 in 88e74b8

    
           bool mumble_onAudioSourceFetched(float *outputPCM, uint32_t sampleCount, uint16_t channelCount, uint32_t sampleRate, bool isSpeech, mumble_userid_t userID) {

So a probable solution may be to decouple that from the data processing and just let it work on results gained in another thread:

add some cache that holds the final needed data (signal quality for a given client, more?)
In the plugin-io data receive function, add a bool that signifies if the client data need to be updated
There at the end of the internal data update, recalculate the signal cache for that client if necessary

that way we should save alot of processing while retaining nearly instant change updates: the update of the signal cache would only occur when needed (radio state change, location change, frequency, ptt etc), not like now where we calculate that for every voice packet!
It will also pay into #58

mill-j · 2021-02-14T15:52:46Z

Sounds like a great idea. We should probably create an AudioOptimization branch. Testing on low end hardware will be no problem for me ;) My lenovo is fast compared to any of my other machines.

hbeni · 2021-02-14T19:25:53Z

Hm, i currently try to rewrite that.
However the quasi-asynchronous type of the checks open a whole can of worms...

Let's see if i can deal with that.

hbeni · 2021-02-14T20:40:29Z

Maybe as an alternative - i think you already experimented with the update rate of the incoming packets, didn't you?
If you make RadioGUI transmit with a lower Hz frequency, does that ease the stuttering?

fgcom-mumble/client/radioGUI/src/main/java/hbeni/fgcom_mumble/radioGUI.java

Line 99 in 88e74b8

Thread.sleep(100); // try 10 times per second

Maybe this helps:

Thread.sleep(1000); // try 1 times per second

This will ease the processing of the UDP server, because he tries to consume packets as fast as possible.

That would be a whole lot easier than the rewrite.

hbeni · 2021-02-14T21:55:02Z

Aside from the idea with throttling the RadioGUI UDP thread, i found the following based on your log.

FGCom [2021-02-13 19:24:31.022]: [DBG] mumble_onAudioSourceFetched():       volume='1.000000'
[...] slow in between, UPD thread also says stuff [...]
FGCom [2021-02-13 19:24:31.042]: [DBG] mumble_onAudioSourceFetched():       local_radio=0  frequency 121.0000 matches!

The slow is between the following lines, maybe also the radio model calculations are slow too.
@mill-j We could see if you drop some more messages into these lines, to see if that really is the case?

fgcom-mumble/client/mumble-plugin/fgcom-mumble.cpp

Lines 884 to 916 in 88e74b8

    
           // calculate frequency match 
        
           float signalMatchFilter; 
        
           fgcom_radiowave_freqConvRes rmt_frq_p = FGCom_radiowaveModel::splitFreqString(rmt.radios[ri].frequency); 
        
           std::unique_ptr<FGCom_radiowaveModel> radio_model_lcl(FGCom_radiowaveModel::selectModel(lcl.radios[lri].frequency)); 
        
           std::unique_ptr<FGCom_radiowaveModel> radio_model_rmt(FGCom_radiowaveModel::selectModel(rmt.radios[ri].frequency)); 
        
           if (radio_model_lcl->isCompatible(radio_model_rmt.get())) { 
        
               signalMatchFilter = radio_model_lcl->getFrqMatch(lcl.radios[lri], rmt.radios[ri]); 
        
           } else { 
        
               pluginDbg("mumble_onAudioSourceFetched():       radio models not compatible: lcl_type="+radio_model_lcl->getType()+"; rmt_type="+radio_model_rmt->getType()); 
        
               continue; 
        
           } 
        
           /* detect landline/intercom */ 
        
           if (lcl.radios[lri].frequency.substr(0, 5) == "PHONE" 
        
               && lcl.radios[lri].frequency == rmt.radios[ri].frequency  
        
               && fgcom_radio_isOperable(lcl.radios[lri])) { 
        
               pluginDbg("mumble_onAudioSourceFetched():       local_radio="+std::to_string(lri)+"  PHONE mode detected"); 
        
               // Best quality, full-duplex mode 
        
               matchedLocalRadio = lcl.radios[lri]; 
        
               bestSignalStrength = 1.0; 
        
               isLandline = true; 
        
               break; // no point in searching more 
        
           /* normal radio operation */ 
        
           // (prefixed special frequencies never should be recieved!) 
        
           } else if (signalMatchFilter > 0.0  
        
               && fgcom_radio_isOperable(lcl.radios[lri]) 
        
               && !lcl.radios[lri].ptt   // halfduplex! 
        
               && rmt_frq_p.prefix.length() == 0) { 
        
               pluginDbg("mumble_onAudioSourceFetched():       local_radio="+std::to_string(lri)+"  frequency "+lcl.radios[lri].frequency+" matches!");

mill-j · 2021-02-15T01:37:08Z

I think you are correct, it seems the delay is still right after volume='1.000000'

<D>2021-02-14 19:28:43.202 Is speech
FGCom [2021-02-14 19:28:43.202]: [DBG] mumble_onAudioSourceFetched(): plugin active=1; isSpeech=1
FGCom [2021-02-14 19:28:43.202]: [DBG] mumble_onAudioSourceFetched():   plugin active+speech detected from id=76
FGCom [2021-02-14 19:28:43.202]: [DBG] mumble_onAudioSourceFetched():   sender callsign=Test
FGCom [2021-02-14 19:28:43.202]: [DBG] mumble_onAudioSourceFetched():   sender registered rmt-radios: 3
FGCom [2021-02-14 19:28:43.202]: [DBG] mumble_onAudioSourceFetched():   check remote radio #0
FGCom [2021-02-14 19:28:43.203]: [DBG] mumble_onAudioSourceFetched():    frequency='121.0000'
FGCom [2021-02-14 19:28:43.203]: [DBG] mumble_onAudioSourceFetched():    ptt='0'
FGCom [2021-02-14 19:28:43.203]: [DBG] mumble_onAudioSourceFetched():    txpwr='10.000000'
FGCom [2021-02-14 19:28:43.203]: [DBG] mumble_onAudioSourceFetched():     remote PTT OFF
FGCom [2021-02-14 19:28:43.203]: [DBG] mumble_onAudioSourceFetched():   check remote radio #1
FGCom [2021-02-14 19:28:43.203]: [DBG] mumble_onAudioSourceFetched():    frequency='122.54167'
FGCom [2021-02-14 19:28:43.203]: [DBG] mumble_onAudioSourceFetched():    ptt='1'
FGCom [2021-02-14 19:28:43.203]: [DBG] mumble_onAudioSourceFetched():    txpwr='10.000000'
FGCom [2021-02-14 19:28:43.203]: [DBG] mumble_onAudioSourceFetched():     PTT detected
FGCom [2021-02-14 19:28:43.203]: [DBG] mumble_onAudioSourceFetched():     check local radios for frequency match (local iid=0)
FGCom [2021-02-14 19:28:43.203]: [DBG] mumble_onAudioSourceFetched():     checking local radio #0
FGCom [2021-02-14 19:28:43.203]: [DBG] mumble_onAudioSourceFetched():       frequency='121.0000'
FGCom [2021-02-14 19:28:43.203]: [DBG] mumble_onAudioSourceFetched():       operable='1'
FGCom [2021-02-14 19:28:43.203]: [DBG] mumble_onAudioSourceFetched():       RDF='0'
FGCom [2021-02-14 19:28:43.203]: [DBG] mumble_onAudioSourceFetched():       ptt='0'
FGCom [2021-02-14 19:28:43.203]: [DBG] mumble_onAudioSourceFetched():       volume='1.000000'
FGCom [2021-02-14 19:28:43.219]: [DBG] mumble_onAudioSourceFetched():     nomatch
FGCom [2021-02-14 19:28:43.219]: [DBG] mumble_onAudioSourceFetched():     checking local radio #1
FGCom [2021-02-14 19:28:43.219]: [DBG] mumble_onAudioSourceFetched():       frequency='123.0000'
FGCom [2021-02-14 19:28:43.219]: [DBG] mumble_onAudioSourceFetched():       operable='1'
FGCom [2021-02-14 19:28:43.219]: [DBG] mumble_onAudioSourceFetched():       RDF='0'
FGCom [2021-02-14 19:28:43.219]: [DBG] mumble_onAudioSourceFetched():       ptt='0'
FGCom [2021-02-14 19:28:43.219]: [DBG] mumble_onAudioSourceFetched():       volume='1.000000'
FGCom [2021-02-14 19:28:43.236]: [DBG] mumble_onAudioSourceFetched():     nomatch
FGCom [2021-02-14 19:28:43.236]: [DBG] mumble_onAudioSourceFetched():     checking local radio #2
FGCom [2021-02-14 19:28:43.236]: [DBG] mumble_onAudioSourceFetched():       frequency=''
FGCom [2021-02-14 19:28:43.236]: [DBG] mumble_onAudioSourceFetched():       operable='1'
FGCom [2021-02-14 19:28:43.237]: [DBG] mumble_onAudioSourceFetched():       RDF='0'
FGCom [2021-02-14 19:28:43.237]: [DBG] mumble_onAudioSourceFetched():       ptt='0'
FGCom [2021-02-14 19:28:43.237]: [DBG] mumble_onAudioSourceFetched():       volume='1.000000'
FGCom [2021-02-14 19:28:43.246]: [DBG] mumble_onAudioSourceFetched():       radio models not compatible: lcl_type=STRING; rmt_type=VHF
FGCom [2021-02-14 19:28:43.246]: [DBG] mumble_onAudioSourceFetched():   check remote radio #2
FGCom [2021-02-14 19:28:43.246]: [DBG] mumble_onAudioSourceFetched():    frequency='123.0000'
FGCom [2021-02-14 19:28:43.246]: [DBG] mumble_onAudioSourceFetched():    ptt='0'
FGCom [2021-02-14 19:28:43.246]: [DBG] mumble_onAudioSourceFetched():    txpwr='10.000000'
FGCom [2021-02-14 19:28:43.246]: [DBG] mumble_onAudioSourceFetched():     remote PTT OFF
FGCom [2021-02-14 19:28:43.246]: [DBG] mumble_onAudioSourceFetched():   no connection, bestSignalStrength=-1.000000

Slowing the send rate in RadioGUI had no affect on the audio. It does make the ptt less responsive, however it appears to be much easier on the cpu. We might need to tweek to for optimal balance.

Edit: I added several more debug messages:

float signalMatchFilter; 
fgcom_radiowave_freqConvRes rmt_frq_p = FGCom_radiowaveModel::splitFreqString(rmt.radios[ri].frequency); 
pluginDbg("mumble_onAudioSourceFetched():		Ping 1");
std::unique_ptr<FGCom_radiowaveModel> radio_model_lcl(FGCom_radiowaveModel::selectModel(lcl.radios[lri].frequency)); 
pluginDbg("mumble_onAudioSourceFetched():		Ping 2");
std::unique_ptr<FGCom_radiowaveModel> radio_model_rmt(FGCom_radiowaveModel::selectModel(rmt.radios[ri].frequency)); 
pluginDbg("mumble_onAudioSourceFetched():		Ping 3");

The results show a little closer where the time is lost:

FGCom [2021-02-14 22:39:09.543]: [DBG] mumble_onAudioSourceFetched():       volume='1.000000'
FGCom [2021-02-14 22:39:09.546]: [DBG] mumble_onAudioSourceFetched():		Ping 1
FGCom [2021-02-14 22:39:09.549]: [DBG] mumble_onAudioSourceFetched():		Ping 2
FGCom [2021-02-14 22:39:09.552]: [DBG] mumble_onAudioSourceFetched():		Ping 3
FGCom [2021-02-14 22:39:09.558]: [DBG] mumble_onAudioSourceFetched():       local_radio=0  frequency 121.0000 matches!

hbeni · 2021-02-15T07:43:55Z

We might need to tweek to for optimal balance.

Just added commit to master, which lets user tweak easily (fgfs protocol can be tweaked at the protocol invocation at fgfs launcher): ae64242 (in the Options dialog)

EDIT: as it turns out this is quite cool. Tuning the radioGUI down to 1Hz makes the debug log way more readable.

hbeni · 2021-02-15T09:48:34Z

Hey, @mill-j
I finally have a small optimization ready, that is not as invasive as my other two attempts: See branch Issue-72_audioOptimization.

The basic idea was, based on your findings, to optimize around the frequency matching. Because of the internal data structures (and the need to support arbitary strings as "frequency") we need to do alot of string mangling.
Because most of the frequencies should be real numbers, the frequency matching is now changed:

The input args (UDP-Server, io-plugin messages) are now checked if numerical, and if so, we store the number directly
(this moves most of the conversion stuff with the string mangling to parse-time instead compare-time)
the frequency matcher for the UHF/VHF/HF radio modules now uses directly the number

With old code it takes 4ms here on my machine to calculate the match:

FGCom [2021-02-15 10:33:27.830]: [DBG] mumble_onAudioSourceFetched():       volume='1.000000'
FGCom [2021-02-15 10:33:27.834]: [DBG] mumble_onAudioSourceFetched():       local_radio=0  frequency 121.0000 matches!

With the new code, it takes 2ms, so this might be a small step forward.

FGCom [2021-02-15 10:35:49.722]: [DBG] mumble_onAudioSourceFetched():       volume='1.000000'
FGCom [2021-02-15 10:35:49.724]: [DBG] mumble_onAudioSourceFetched():       local_radio=0  frequency 121.0000 matches!

Can you try this branch, if it helps? What are the times now at your box?
If it's still not enough, you may also give profiling a shot using the gprof tool.
Could it also maybe be the case that this is libc specific, that the string implementation in the older libc is slower than my newer libc?

hbeni · 2021-02-15T11:00:49Z

Oh and while playing with gprof, i found out that because we currently don't compile with compiler optimizations, the code is at least 10 times slower that it has to be.

As a result, i changed the makefile so we have -O3 as default now, and also we don't build debug builds anymore automatically.

make now builds optimized production code (-O3, no symbols)
make all-debug will build debug code as we were used before the change (resolved to DEBUG+="-g3 -DDEBUG -Og).

I now really wonder:

How does the current master code run when compiling with optimizations and without debug symbols on your box (aka make plugin)?
How does the branch here run with the same (make plugin)?
And how does the branch here runs with make all-debug?

mill-j · 2021-02-15T17:12:21Z

Built master with make plugin. Results are perfect. Even with 4 radios in each RadioGUI and send rate 10mhz. The same is true about the Issue-72_audioOptimization branch built with make all-debug. Although the debug version seemed to take more cpu, it did not stutter or chop audio. I also tested with flightgear. It now works with my favorite plane, the new Piper Warrior II! Audio sounds amazing.

hbeni · 2021-02-15T17:23:31Z

Wow, now THAT are good news!

It turned out it was not a problem with the code per se, but a missing compile optimizing flag.
What a difference.

Before we close this, what do you think?

should we integrate the optimization in the branch?
or do we let master as-is because it’s good already?

I would vote for „abandon the branch“ because i could not measure a significant gain, but the code is more complicated and harder to maintain.

mill-j · 2021-02-15T18:12:26Z

I'm fine with master the way it is. I see no performance difference between master and branch.

hbeni added bug Something isn't working mumble-plugin Affecting mumble plugin Audio effects Affecting audio effects labels Feb 5, 2021

hbeni added this to the 1.0 milestone Feb 5, 2021

hbeni added help wanted Extra attention is needed high prio Do this first labels Feb 5, 2021

hbeni assigned hbeni and unassigned hbeni Feb 7, 2021

hbeni changed the title ~~Bug: radio reception is choppy~~ Bug: radio reception is sometimes choppy Feb 9, 2021

hbeni self-assigned this Feb 15, 2021

hbeni closed this as completed Feb 15, 2021

Provide feedback

Saved searches

Use saved searches to filter your results more quickly

Bug: radio reception is sometimes choppy #72

Bug: radio reception is sometimes choppy #72

hbeni commented Feb 5, 2021 •

edited

Loading

hbeni commented Feb 7, 2021

hbeni commented Feb 12, 2021

mill-j commented Feb 12, 2021

hbeni commented Feb 12, 2021

hbeni commented Feb 12, 2021

hbeni commented Feb 12, 2021

mill-j commented Feb 13, 2021

hbeni commented Feb 13, 2021

hbeni commented Feb 13, 2021

mill-j commented Feb 14, 2021

mill-j commented Feb 14, 2021

hbeni commented Feb 14, 2021

hbeni commented Feb 14, 2021 •

edited

Loading

mill-j commented Feb 14, 2021 •

edited

Loading

hbeni commented Feb 14, 2021

hbeni commented Feb 14, 2021

hbeni commented Feb 14, 2021 •

edited

Loading

mill-j commented Feb 15, 2021 •

edited

Loading

hbeni commented Feb 15, 2021 •

edited

Loading

hbeni commented Feb 15, 2021

hbeni commented Feb 15, 2021 •

edited

Loading

mill-j commented Feb 15, 2021

hbeni commented Feb 15, 2021

mill-j commented Feb 15, 2021

Bug: radio reception is sometimes choppy #72

Bug: radio reception is sometimes choppy #72

Comments

hbeni commented Feb 5, 2021 • edited Loading

hbeni commented Feb 7, 2021

hbeni commented Feb 12, 2021

mill-j commented Feb 12, 2021

hbeni commented Feb 12, 2021

hbeni commented Feb 12, 2021

hbeni commented Feb 12, 2021

mill-j commented Feb 13, 2021

hbeni commented Feb 13, 2021

hbeni commented Feb 13, 2021

mill-j commented Feb 14, 2021

mill-j commented Feb 14, 2021

hbeni commented Feb 14, 2021

hbeni commented Feb 14, 2021 • edited Loading

mill-j commented Feb 14, 2021 • edited Loading

hbeni commented Feb 14, 2021

hbeni commented Feb 14, 2021

hbeni commented Feb 14, 2021 • edited Loading

mill-j commented Feb 15, 2021 • edited Loading

hbeni commented Feb 15, 2021 • edited Loading

hbeni commented Feb 15, 2021

hbeni commented Feb 15, 2021 • edited Loading

mill-j commented Feb 15, 2021

hbeni commented Feb 15, 2021

mill-j commented Feb 15, 2021

hbeni commented Feb 5, 2021 •

edited

Loading

hbeni commented Feb 14, 2021 •

edited

Loading

mill-j commented Feb 14, 2021 •

edited

Loading

hbeni commented Feb 14, 2021 •

edited

Loading

mill-j commented Feb 15, 2021 •

edited

Loading

hbeni commented Feb 15, 2021 •

edited

Loading

hbeni commented Feb 15, 2021 •

edited

Loading