100% cpu usage with I2C audio hats

[craigerl]

I'm observing direwolf with 100% cpu usage when using I2C audio boards, specifically

• FE-Pi audio hat
• Audio Injector Z hat

observed on Pi 3A+, Pi Zero2W, Raspberry Pi OS bullseye
not observed on the original Pi Zero.
not observed with USB audio dongle
arecord and mpg123 do not generate significant cpu usage with the above i2c boards
observed on direwolf 1.6 and 1.7-dev-A

-craig
KM6LYW

[dranch]

Are you using 32bit or 64bit Raspberry Pi OS? Can you please post your Direwolf configuration? Can you also please try the newest version of Direwolf from the Dev branch as Dev-A is rather old now

[craigerl]

Hey David,

32bit Bullseye
Not using any configuration file
Observed with dev branch direwolf as of this posting

thanks,
-craig

[craigerl]

Using "-n 2" on the direwolf command line with no other options and no config file fixes the problem. cpu usage is normal (17%)

related unresolved thread, which also uses an i2c sound device ,

#131

[dranch]

Generally speaking, Direwolf really wants a configuration file to read so I recommend you enable that. Without specifying the "-n 2" item, can you copy/paste in what you're seeing when you start Direwolf from the command line and we can see what it's assuming?

[craigerl]

replicated on Buster, direwolf 1.6
using "-n 2" or "ACHANNELS 2" is a fix in this case as well

[craigerl]

  PID USER      PR  NI    VIRT    RES    SHR S  %CPU  %MEM     TIME+ COMMAND    
  580 pi        20   0  139440  10744   7812 S 100.0   2.2   3:38.49 direwolf 

MYCALL KM6LYW-2
IGSERVER noam.aprs2.net
IGLOGIN KM6LYW-2 000000
PBEACON sendto=IG compress=1 delay=00:10 every=30:00 symbol="igate" overlay=R lat=38.9919N long=120.9956W comment=" DigiPi http://craiger.org/digipi/"
DCD GPIO 16
DWAIT 0
TXDELAY 30
TXTAIL 10
AGWPORT 8000
KISSPORT 8001

export ALSA_CARD=0
direwolf -d t -p -q d -t 0 -c /run/direwolf.tnc.conf | tee /home/pi/direwolf.log &

Dire Wolf version 1.6
Includes optional support for: gpsd hamlib cm108-ptt

Reading config file /run/direwolf.tnc.conf
Audio device for both receive and transmit: default (channel 0)
Channel 0: 1200 baud, AFSK 1200 & 2200 Hz, E+, 44100 sample rate / 3.
KM6LYW_Fix: waiting 500ms before intializing gpio because of udev lag.
KM6LYW_Fix: waiting 500ms before intializing gpio because of udev lag.
Ready to accept AGW client application 0 on port 8000 ...
Virtual KISS TNC is available on /dev/pts/1
Created symlink /tmp/kisstnc -> /dev/pts/1
Ready to accept KISS TCP client application 0 on port 8001 ...
Can't get address for IGate server noam.aprs2.net, Temporary failure in name resolution
Can't get address for IGate server noam.aprs2.net, Temporary failure in name resolution
[ig] KM6LYW-2>APDW16:!R:l%i/uLi& ! DigiPi http://craiger.org/digipi/
Can't get address for IGate server noam.aprs2.net, Temporary failure in name resolution

Now connected to IGate server noam.aprs2.net (44.25.16.4)
Check server status here http://44.25.16.4:14501

[ig] # aprsc 2.1.14-g5e22b37
[ig] # logresp KM6LYW-2 verified, server T2USANW

[craigerl]

Using "-r 22000" also fixes the 100% cpu thread.

  PID USER      PR  NI    VIRT    RES    SHR S  %CPU  %MEM     TIME+ COMMAND    
 1962 pi        20   0  132268  11372   7900 S  13.6   2.3   0:33.53 direwolf 

Channel 0: 1200 baud, AFSK 1200 & 2200 Hz, E+, 22000 sample rate.

edit:
44000 works (14% cpu)
44200 works (14% cpu)
56000 works (18% cpu)
192000 works (60%cpu)
44100 fails (100%cpu)
48000 fails (100% cpu)
48001 works (16% cpu)

anything but 44100 and 48000 seems to keep direwolf from consuming an entire cpu core
no correlation between frequency divider ( / 3 )

[dranch]

Interesting.. btw, the Fe-Pi now the wb7fhc Nexus DR-X sound hat offers more sampling rates than most sound devices. You can get a full list of it's sampling rates by running:

sudo lsusb -vv | grep -e Audio -e tSamFreq | grep -v -e Descriptor -e bInterfaceClass

Anyway.. it's strange that the common sampling rates create high load for you on this truly stereo input / output sound device. We will have to wait to hear back from WB2OSZ on this one.

[craigerl]

Thanks David, this isn't a USB device (I2C device), and yah, it has something to do with the supported hardware rates for sure.

32K seems to be a hardware rate as well
32000 (41% cpu)
32001 (23% cpu)

Running stack trace on the audio thread is even more revealing,

During normal cpu usage (44001 for example) we see device polling
poll([{fd=4, events=POLLIN|POLLERR|POLLNVAL}], 1, -1) = 1 ([{fd=4, revents=POLLIN}]) <0.007488>

During high cpu usage (44100, 48000, 32000) we don't see the poll call at all, and we see a nanosleep instead
[pid 18648] 08:38:11 <... clock_nanosleep_time64 resumed>0x72dffd48) = 0 <1.000189>
[pid 18651] 08:38:11 <... ioctl resumed>, 0x1168080) = 0 <0.000179>
[pid 18648] 08:38:11 clock_nanosleep_time64(CLOCK_REALTIME, 0, {tv_sec=1, tv_nsec=0}, <unfinished ...>

[dranch]

One thing I noticed here is that the direwolf startup output is using the "default" audio device which is a PulseAudio device which I don't recommend. PulseAudio can do all kinds of unwanted audio processing things to the audio as well as doing silent resampling for non-native sound device sampling rates which will increase CPU load. In your direwolf.conf file, instead try specifying a native ALSA device name such as "ADEVICE plughw:1,0". Btw, also in your startup, I see you're using the shell environment variable "export ALSA_CARD=0" but I don't believe Direwolf uses that at all. If you're doing other ALSA tricks using DMIX, etc. please disable all of this and retest to see if that might be impacting Direwolf. Ultimately, Direwolf is a ALSA-native application and while it works, it's not a PulseAudio or PIpewire native application.

[craigerl]

Understood.

No Pulse Audio -- ever.

libasound2 honors "ALSA_CARD", so direwolf does by extension.

I get the same result when specifying an audio device in direwolf.conf (ADEVICE plughw:0,0)

no dmix afaik

[craigerl]

Increasing frames per period in audio.c resolves the issue.

        fpp = buf_size_in_bytes / (pa->adev[a].num_channels * pa->adev[a].bits_per_sample / 8);
//craiger - this normally comes out to 512
        fpp = 1024;

Unintended consequences, besides latency, unknown.

./src/direwolf -t 0 -r 44100
Dire Wolf version 1.7 (Oct 18 2023) BETA TEST 7
Includes optional support for: gpsd hamlib cm108-ptt

Reading config file direwolf.conf
Audio device for both receive and transmit: default (channel 0)
audio_open: calcbufsize (rate=44100, chans=1, bits=16) calc size=882, round up to 1024
suggest period size of 1024 frames
audio buffer size = 2 (bytes per frame) x 1024 (frames per period) = 2048
audio_open: calcbufsize (rate=44100, chans=1, bits=16) calc size=882, round up to 1024
suggest period size of 1024 frames
audio buffer size = 2 (bytes per frame) x 1024 (frames per period) = 2048
Channel 0: 1200 baud, AFSK 1200 & 2200 Hz, A+, 44100 sample rate / 3.
Note: PTT not configured for channel 0. (Ignore this if using VOX.)
Ready to accept AGW client application 0 on port 8000 ...
Ready to accept KISS TCP client application 0 on port 8001 ...

  PID USER      PR  NI    VIRT    RES    SHR S  %CPU  %MEM     TIME+ COMMAND    
31592 pi        20   0  105260  10716   7824 S  13.2   2.2   0:02.78 direwolf  

[wb2osz]

I don't have one of these devices so I can't do any experiments. All I know is what is found here. https://github.com/NexusDR-X/nexus-audio/blob/main/README.md

Your test results are very perplexing.

44000 works (14% cpu)
44200 works (14% cpu)
56000 works (18% cpu)
192000 works (60%cpu)
44100 fails (100%cpu)
48000 fails (100% cpu)
48001 works (16% cpu)

direwolf treats the sound device very simplistically. I picked the default of 44100 because that is the CD rate and seems to be supported by all hardware. The USB audio devices also do 48000, which I believe is the DVD rate.

I don't know the internals of the audio device driver, but one might reasonably expect that it would instruct the hardware to operate at the requested sample rate if available. That would be most efficient with no rate conversion necessary. If the desired rate is not available in hardware, it would pick some higher rate, possibly an integer multiple or at least a rational number, if possible, to make rate conversion easier/more efficient.

That's not what we see at all in the test results. It could be something weird going on in the device driver.

I added a hack, oops, I mean heuristic, for ARM processors on the assumption they would be much much slower than x86 machines. Downsampling/decimation by a factor of 3 is applied if the sample rate is much higher than needed for good AFSK decoding. Nothing fancy; it just averages 'n' incoming samples together. An old single core RPi model 1 is more than adequate with this little trick and the user not having to do anything special. You will see this change to -D2 or disapear as the incoming rate decreases.

Trying to use ALSA to map two independent virtual mono audio channels adds another layer of complexity and strange possible cases. What happens if the two derived virtual channels want different rates. Would they fight over the hardware rates or it just use 96000 and burn up CPU resources downsampling it.

The buffer size is a tradeoff.
small buffer = rapid transfers =lower latency = more overhead.
and the opposite.
If the receive latency is too long, you will transmit on top of other people because recently started transmissions take too long to reach the decoder.

The specific direwolf version shouldn't matter. I don't think the audio input processing has been touched for a long time.

You mentioned bullseye. Have you tried bookworm. direwolf compiles OK (newer compile usually means new warnings) on the 64 bit version on an RPi 3 and passes the self tests. That's as far as I got. Maybe it has a better I2C audio driver.

Steve Magnuson, AG7GN should be brought into this conversation.

73,
john WB2OSZ

[craigerl]

Thanks for the info.

If we're dividing sample rate by 3 on ARM, is there a downside to simply specifying a rate of "14700"? That yields 10% cpu on a Pi3 and would not introduce latency.

New observation, 90 percent of CPU time is spent in a system call (not user time) when using 44100/48000.

I'm still curious about nanosleep vs polling in the audio thread. Nanosleep is only seen when using 44100/4800 rates. We see poll() otherwise. It's like nanosleep doesn't sleep.

[craigerl]

Bookworm observations. 32bit/lite, Direwolf 1.6, Linux 6.1.0

CPU usage is much better than bullseye, but significantly higher when using 44100 or 48000

44101 12% (10.0user, 2.3sys)
44100 20% ( 6.3user 12sys)
48000 20% (7.4user 12.8sys)
48001 16% (18user 0.3sys)

time direwolf -r44100
real 0m21.496s
user 0m1.348s
sys 0m2.736s

time direwolf -r 44101
real 0m21.922s
user 0m2.324s
sys 0m0.438s

Like with bullseye we still see nanosleeps when using 44100/48000, and we see polling with any other rate
strace -Ttf direwolf -r 44100
[pid 1147] 17:41:30 clock_nanosleep(CLOCK_REALTIME, 0, {tv_sec=7, tv_nsec=0}, <unfinished ...>

strace -Ttf direwolf -r 44101
poll([{fd=6, events=POLLIN|POLLERR|POLLNVAL}], 1, -1) = 1 ([{fd=6, revents=POLLIN}])

Bullseye invokes clock_nanosleep_time64()
Bookworm invokes clock_nanosleep()

[craigerl]

dbgsym version of alsa-libs compiled, this is where the direwolf process is spending time, still need to see which driver the "sys" time is being spent...

22.82% direwolf direwolf [.] demod_afsk_process_sample
20.77% direwolf libasound.so.2.0.0 [.] snd_pcm_route_convert1_many
7.64% direwolf libarmmem-v7l.so [.] memmove
6.29% direwolf direwolf [.] multi_modem_process_sample
4.53% direwolf direwolf [.] nudge_pll
3.62% direwolf direwolf [.] demod_process_sample
2.62% direwolf direwolf [.] audio_get

[craigerl]

time being spent in snd_pcm driver, function snd_pcm_stream_unlock_irq()

44101

  18.49%  direwolf                  [.] demod_afsk_process_sample
  12.44%  libasound.so.2.0.0        [.] snd_pcm_route_convert1_many
  11.49%  [snd_pcm]                 [k] snd_pcm_stream_unlock_irq
   6.07%  libarmmem-v7l.so          [.] memmove
   5.22%  [kernel]                  [k] _raw_spin_unlock_irqrestore
   5.00%  direwolf                  [.] multi_modem_process_sample


44100

  78.11%  [snd_pcm]                 [k] snd_pcm_stream_unlock_irq
   2.83%  libasound.so.2.0.0        [.] snd_pcm_route_convert1_many
   2.66%  direwolf                  [.] demod_afsk_process_sample
   0.92%  libarmmem-v7l.so          [.] memmove
   0.82%  [snd_pcm]                 [k] snd_pcm_ioctl
   0.77%  [kernel]                  [k] _raw_spin_unlock_irqrestor

[craigerl]

patch for audio.c, testing okay at this point. Bumping up the frames per period seems alleviate the snd_pcm driver problem with a minimal increase in latency. In fact, the buffer/period is similar to what it comes up with for a USB/ic705 device. CPU usage goes from 100% to 16% on Raspberry Pi Zero 2W with this patch.

pi@digipi4:~/git/direwolf/clean/direwolf/build $ ./src/direwolf -t 0 -r 48000
Dire Wolf version 1.7 (Oct 25 2023) BETA TEST 7
Includes optional support for: gpsd hamlib cm108-ptt dns-sd

Reading config file direwolf.conf
Audio device for both receive and transmit: default (channel 0)
audio_open: calcbufsize (rate=48000, chans=1, bits=16) calc size=1152, round up to 2048
suggest period size of 1024 frames
audio buffer size = 2 (bytes per frame) x 1024 (frames per period) = 2048
audio_open: calcbufsize (rate=48000, chans=1, bits=16) calc size=1152, round up to 2048
suggest period size of 1024 frames
audio buffer size = 2 (bytes per frame) x 1024 (frames per period) = 2048
Channel 0: 1200 baud, AFSK 1200 & 2200 Hz, A+, 48000 sample rate / 3.
Note: PTT not configured for channel 0. (Ignore this if using VOX.)
Ready to accept AGW client application 0 on port 8000 ...
Ready to accept KISS TCP client application 0 on port 8001 ...
DNS-SD: Avahi: Announcing KISS TCP on port 8001 as 'Dire Wolf on digipi4'
DNS-SD: Avahi: Service 'Dire Wolf on digipi4' successfully registered.

pi@digipi4:~/git/direwolf/direwolf/build $ sudo cat /proc/asound/card0/pcm0p/sub0/hw_params
access: MMAP_INTERLEAVED
format: S16_LE
subformat: STD
channels: 2
rate: 48000 (48000/1)
period_size: 1024
buffer_size: 131072

audio.c

//craiger nudge up buffer size until frames per period hits 1024 for i2s cards
//#define ONE_BUF_TIME 10
#define ONE_BUF_TIME 12

#if __arm__
        /* Ugly hack for RPi. */
        /* Reducing buffer size is fine for input but not so good for output. */

//craiger don't inflate output buffer size
//      if (*inout == 'o') {
//        buf_size_in_bytes = buf_size_in_bytes * 4;
//      }
#endif