search

charlie-foxtrot / RTLSDR-Airband

Multichannel AM/NFM demodulator
GNU General Public License v3.0
759 stars 135 forks source link

Stream plays silence between transmissions using pulseaudio #110

Closed barjac closed 5 years ago

barjac commented 5 years ago

I use RPi running rtl_airband with pulse output. The machine running the PA server also runs pulseeffects to filter the audio. I am seeing very high cpu usage in pulseeffects between transmissions which I have reported to the pulseeffects developer here: https://github.com/wwmm/pulseeffects/issues/423#issuecomment-459575012 It seems from his last comment that the stream should not be playing silence between transmissions. I will cross link to this bug report in that one so he will see your reply. Thanks, Barry

szpajder commented 5 years ago

Try using "continuous = true;" option in the pulse output configuration. Then it won't pause when squelch is closed.

barjac commented 5 years ago

Is that valid for 2.4.0, as it makes no difference that I can see. Corked is still 'no' with either continuous = true; (or false as that seemed more logical so I tried it!). I did re-boot between tests. I will build 3.0.1 if that is likely to fix it, but current running version is 2.4.0.

szpajder commented 5 years ago

2.4.0 and 3.0.1 work the same way. You have two options:

Choose the behavior which suits you better. To see the difference, you may monitor the network traffic between rtl_airband and the server. With the option set to true, you should see a continuous stream of traffic, and with false there will be no traffic when the squelch closes.

barjac commented 5 years ago

OK understood, I have updated to 3.0.1 anyway, and with continuous set to false I can see that there is traffic only during transmissions, and with it set true the traffic is continuous at the same level. (38kB/s) However this has no effect on the high cpu usage experienced, so maybe this is unrelated. The pulseeffects developer is expecting 'Corked: yes' to be set when the squelch is closed, and seems to think this should be controlled by rtl_airband. What are your thoughts on that?

szpajder commented 5 years ago

I can't reproduce this problem. The CPU usage of pulseeffects process is the same, regardless of squelch state and continuous option setting. The exact value depends on the number of effects enabled, but it's no higher than 20% on a i5-6600K CPU. I checked both 8 ksps and 16 ksps stream (ie. NFM support disabled and enabled). Therefore I think the way rtl_airband drives the pulse stream is irrelevant.

Maybe it's related to a particular effect or effect combination? Or a specific version of pulseeffects, pulseaudio or some library? My setup:

I tried auto gain, filter, equalizer, bass enhancer, crystalizer and reverberation. No issues.

wwmm commented 5 years ago

If I am not mistaken @barjac is running both softwares in a raspberry. So I would expect a high cpu usage when audio processing is done with heavy effects or too many equalizer bands. The default number of 30 bands may be too much for a raspberry. In my opinion the only significant optimization that can be done here is not doing audio processing when the audio application (Airband in this case) is paused.

In order to pause/unpause PulseEffects Gstreamer pipeline I need to know if there is at least one audio app playing audio. The only way I found to get this info from Pulseaudio was reading the corked property of Pulseaudio's sink inputs (audio app). Corked = yes means that the sink input stream is not running. If it is not corked the stream is running. Open a video or song in an app like mpv and you will see the corked state changing with every pause/unpause in the output of this command pactl list sink-inputs.

Based on what @szpajder explained above it seems to me that he is using pa_stream_cork to pause/unpause the stream. So everything should be fine. The corked property should be being updated. Could it be that this information is lost when you interact with Pulseaudio remotely?

wwmm commented 5 years ago

Reading @barjac email again it seems that only Airband is in the raspberry... In any case the cpu usage will reflect the selected effects. The general idea explained above remains...

barjac commented 5 years ago

I am using the equalizer in PE to pass a typical speech spectrum, nothing else. rtl_airband is running on a RPi2 and the PA server and PE are on a 4 core 3GHz desktop machine with 8GB ram. PE is run as a daemon from boot and the cpu use in top is low until the first transmission is received then it jumps to around 20% and 50% (or 65% if the GUI is started as well) after the transmission stops. It then drops during each transmission to 20%. I will check versions of all related packages listed above and report back.

szpajder commented 5 years ago

Based on what @szpajder explained above it seems to me that he is using pa_stream_cork to pause/unpause the stream.

I don't use pa_stream_cork. rtl_airband does not have a pause nor a stop button. When the received radio channel is silent, it can either:

I agree that the first behavior might confuse some applications (from their perspective it looks like a stream underrun). However with the current architecture of the program I can't do much about it. Corking and uncorking the stream should be a result of some event (like pressing the pause button), while in this scenario no such event exists. There is a flag for each stream which indicates whether squelch is currently open or not, however there is no mechanism which tracks changes of this flag. It might be introduced in a future release, though.

What I fail to understand is @barjac's statement that flipping "continuous" flag does not make any difference to the CPU usage. Silence is a signal like any else - it's just a bit special, because it's a stream of all-zeros, however I don't get why processing it in pulseeffects would cost significantly more CPU than processing a non-silent signal. Does it make any sense?

@barjac, it would be valuable if you could find out where the CPU time is actually spent. You can do this with "perf" tool (depending on your distro, it may be packaged under different names, for example in Gentoo it's just "perf", while in Debian it's AFAIK "linux-tools". Install it and run as root:

perf top -p <pulseeffects_pid>

and observe the top-like output showing which libraries and system calls consume the most CPU time - when the stream is silent and when there is some sound.

wwmm commented 5 years ago

I see. This explains why we are not able to pause the pipeline.

I agree. CPU usage should be the same playing silence. Unless there is a significant difference in buffer size when playing silence. At least the auto volume plugin consumes way more cpu when small buffers are used. This happens because libebur128 functions will be called more often than they would be with larger buffers. And those functions are heavy.

I don't think that buffer size should make much different to the other plugins. But I wouldn't rule out the possibility that something similar happens deep inside GStreamer. Maybe it has to send more buffers per second when they are small and this could lead to something eating more cpu.

wwmm commented 5 years ago

Forget what I said. A difference in Airband buffer size would matter to pulseaudio but not to PulseEffects. Our buffer would remain the same unless some settings like buffer, latency and block size where changed in the settings menu...

barjac commented 5 years ago

I have run perf as requested and as far as I can tell it is libgstequalizer.so that is loading the cpu, however I see no correlation between the load shown in perf top and in top. Using the PE GUI to switch off the equalizer causes the load to drop right down in top to ~5%, switching on the equalizer with no sound playing raises it to ~10% when a transmission comes along the load does not change, it is only when that first transmission finishes that the load increases to ~60%. During the above the many listings of libgstequalizer.so in perf top change in level but just randomly, then after a while perf (in top) jumps from <1% to 100% and the kernel then tops the perf list until it is stopped and re-started. I took some screen shots which may help or perhaps just confuse :\ After re-starting perf with no sound playing: after_restart_perf-no_sound Equalizer off with no sound: equalizer_off_no_sound Perf output with no sound: perf_top After switching on the equalizer with no sound: switch_on_equalizer-with no stream

barjac commented 5 years ago

Having just looked back at the above it seems that instances of libgstequalizer start only when sound starts, but are not killed when it stops. Could this be the issue?

wwmm commented 5 years ago

There are only two ways to stop the equalizer. Using the switch to turn it off or putting the whole pipeline in the paused state. But this last possibility relies on the corked property

barjac commented 5 years ago

Comparison of installed pkg versions:

pulseeffects_pkgs.txt

barjac commented 5 years ago

There are 13 repeating calls to libgstequalizer.so that go on for ever after the first transmission is received. Adding up a random 13 they total 71% [baz@localhost ~]$ perf top -p 11269 | grep libgstequalizer 10.69% libgstequalizer.so [.] 0x00000000000025f1 10.61% libgstequalizer.so [.] 0x00000000000025dc 10.49% libgstequalizer.so [.] 0x00000000000025af 10.23% libgstequalizer.so [.] 0x0000000000002602 9.67% libgstequalizer.so [.] 0x00000000000025c8 3.81% libgstequalizer.so [.] 0x0000000000002607 3.63% libgstequalizer.so [.] 0x00000000000025f5 3.61% libgstequalizer.so [.] 0x00000000000025cc 3.33% libgstequalizer.so [.] 0x00000000000025e1 2.59% libgstequalizer.so [.] 0x00000000000025b3 0.95% libgstequalizer.so [.] 0x00000000000025c0 0.75% libgstequalizer.so [.] 0x000000000000261e 0.53% libgstequalizer.so [.] 0x00000000000025fa 0.43% libgstequalizer.so [.] 0x0000000000002622 10.78% libgstequalizer.so [.] 0x00000000000025dc 10.45% libgstequalizer.so [.] 0x00000000000025f1 10.32% libgstequalizer.so [.] 0x0000000000002602 10.32% libgstequalizer.so [.] 0x00000000000025af 9.70% libgstequalizer.so [.] 0x00000000000025c8 3.68% libgstequalizer.so [.] 0x00000000000025cc 3.65% libgstequalizer.so [.] 0x0000000000002607 3.43% libgstequalizer.so [.] 0x00000000000025f5 3.42% libgstequalizer.so [.] 0x00000000000025e1 2.66% libgstequalizer.so [.] 0x00000000000025b3 1.08% libgstequalizer.so [.] 0x00000000000025c0 0.76% libgstequalizer.so [.] 0x000000000000261e 0.49% libgstequalizer.so [.] 0x00000000000025fa 0.48% libgstequalizer.so [.] 0x00000000000025a3 10.54% libgstequalizer.so [.] 0x0000000000002602 10.52% libgstequalizer.so [.] 0x00000000000025f1 10.38% libgstequalizer.so [.] 0x00000000000025dc 10.16% libgstequalizer.so [.] 0x00000000000025af 9.89% libgstequalizer.so [.] 0x00000000000025c8 3.69% libgstequalizer.so [.] 0x00000000000025cc 3.65% libgstequalizer.so [.] 0x0000000000002607 3.40% libgstequalizer.so [.] 0x00000000000025f5 3.25% libgstequalizer.so [.] 0x00000000000025e1 2.75% libgstequalizer.so [.] 0x00000000000025b3 1.15% libgstequalizer.so [.] 0x00000000000025c0 0.63% libgstequalizer.so [.] 0x000000000000261e 0.55% libgstequalizer.so [.] 0x00000000000025d4 0.44% libgstequalizer.so [.] 0x00000000000025fa .......... --------------snip---------------

szpajder commented 5 years ago

I have run perf as requested and as far as I can tell it is libgstequalizer.so that is loading the cpu, however I see no correlation between the load shown in perf top and in top.

top shows percentages relative to the total CPU time available, while perf references them to the current CPU busy time.

Using the PE GUI to switch off the equalizer causes the load to drop right down in top to ~5%, switching on the equalizer with no sound playing raises it to ~10% when a transmission comes along the load does not change, it is only when that first transmission finishes that the load increases to ~60%.

And just to be 100% sure: if you set "continuous = true" in the pulse output section in rtl_airband.conf, does the load also jump to ~60% after first transmission?

barjac commented 5 years ago

Thanks for the explanation - I never had cause to use perf before.

And just to be 100% sure: if you set "continuous = true" in the pulse output section in rtl_airband.conf, > does the load also jump to ~60% after first transmission?

Yes it makes no noticeable difference. I now have it set true and have re-started the rtl_airband service. (Also rebooted the RPi2 to be sure) With the equalizer OFF pulseeffects runs at 0.3% With PE equalizer ON and no transmission PE sits at 6% During the first transmission it rises to ~8% When first transmission or any susbsequent ones stop it rises to ~70% During any subsequent transmission it drops to ~8%

Note that rtl_airband has several pulse outputs pointed at different IP addresses, I am only changing the one applicable to the machine on which I am testing - the others are not receiving. None of the others have PE installed either, as I only packaged it for Mageia 7 (pre-release) the other machines run Mageia 6. Edit: As a test I removed the other pulse entries and it made no difference.

wwmm commented 5 years ago

I did a few tests with gst-launch-1.0 and I think I found the source of the problem. Something odd happens when GStreamer is handling a buffer full of zero values. This command shows the behavior you are seeing

gst-launch-1.0 fakesrc format=3 sizetype=2 filltype=zero ! audio/x-raw,format=F32LE,channels=2,rate=44100 ! audioconvert ! equalizer-10bands band0=1.0 band1=1.0 band2=1.0 band3=1.0 band4=1.0 band5=1.0 band6=1.0 band7=1.0 band8=1.0 band9=1.0 ! pulsesink

Now change the filltype to random instead of zeros and the output of perf changes

gst-launch-1.0 fakesrc format=3 sizetype=2 filltype=random ! audio/x-raw,format=F32LE,channels=2,rate=44100 ! audioconvert ! equalizer-10bands band0=1.0 band1=1.0 band2=1.0 band3=1.0 band4=1.0 band5=1.0 band6=1.0 band7=1.0 band8=1.0 band9=1.0 ! pulsesink

The equalizer is not the one with the highest cpu usage anymore. libglib-2.0.so nows consumes more cpu.

Considering that the only difference between the commands is if the buffer is filled with zeros or not I'd say that this is the cause of the difference in cpu usage. But I don't know yet why GStreamer is handling zero filled buffers this way. It may be worth ask questions in GStreamer mailing list.

barjac commented 5 years ago

I think you need to re-start perf after starting/changing the streams to get reliable readings. I just did the same tests and took these screen shots, but re-started perf after starting the streams in each case. Zeros: gst_zero Random: gst_random

wwmm commented 5 years ago

Yes I restarted perf in every test. And I also killed pulseeffects process pulseeffects -q before the tests so I could look only at GStreamer. Just give gst-launch-1.0 pid to perf.

In any case your screenshots tell the same story. GStreamer's equalizer behaves differently when given a zero filled buffer. And not in a good way... It makes no sense...

barjac commented 5 years ago

OK understood, I have repeated as you did and there is indeed something strange. I will put two screen shots here for reference in a gstreamer bug report. random stream: gstequalizer_random zero fill: gstequalizer_zeros

Would you like to report it or shall I? You can probably explain it better ;)

szpajder commented 5 years ago

But this is nowhere near the 60% CPU usage which you get when equalizing rtl_airband's stream. And actually the allzero stream seems to cause lower CPU usage than random, which is exactly the opposite of what you are trying to show here. I guess the original bug hasn't been triggered in this demonstration.

wwmm commented 5 years ago

In my computer both cases have the same low cpu usage in top. Only in perf there is any difference.

wwmm commented 5 years ago

I am out of ideas. The only difference I see in his reports between the high and normal cpu usage are the zero filled buffers. But it doesn't matter what I try I can't get any difference in top. Even running PulseEffects and processing gst-launch output. Only perf shows any change... But this is not enough to open a bug report in GStreamer in my opinion

barjac commented 5 years ago

I have just made a clean net installation of Mageia 7 from the current repo to rule out any issues with my rather old updated installation that I was using for test. It is even worse. pulseeffects_mga7beta1 I am now wondering whether we are missing some essential dependency, e.g. we don't currently have zita-convolver packaged: Library zita-convolver found: NO Message: Missing dependency zita-convolver = 3.x.x or zita-convolver = 4.x.x Message: Convolver plugin will not be built. Maybe you could look though the rest of the log for any clues? http://mtf.duckdns.org/pub/linux/barjac/distrib/cauldron/x86_64/log/pulseeffects-4.4.7-3.mga7.src.rpm/build.0.20190131211017.log

wwmm commented 5 years ago

I see nothing strange in your log. zita-convolver is used only by the convolver.

barjac commented 5 years ago

There is now no issue with our most recent packaging that pulls in all the plugins. So closing. Thanks for your help.