Raspberry Pi4 100% cpu, RX backlog exceeded

[craigerl]

Hi guys, I just checked out the devel branch. Looking at 100% cpu and frame timing/lag issues during connections, and it looks like you have some neat flushing to catchup, but we're still not in sync.

Connecting to KO0OOO (sort of) here in the USA! we have MERCURY winlink servers online! GREAT work!

-craig
KM6LYW
digipi.org

VERSION_CODENAME=trixie
DEBIAN_VERSION_FULL=13.4

Raspberry Pi 4 Model B Rev 1.5

Linux digipi7 6.12.75+rpt-rpi-v8 #1 SMP PREEMPT Debian 1:6.12.75-1+rpt1 (2026-03-11) aarch64 GNU/Linux

  PID USER      PR  NI    VIRT    RES    SHR S  %CPU  %MEM      
 2876 pi        20   0  185108  17856   9512 S 101.3   0.5   0:55.27 mercury  

pi@digipi7:~/git/mercury $ ./mercury
Rhizomatica Mercury Version 1.9.11 (git bf7d546)
Loaded configuration from mercury.ini
18:05:29.385 [+0.000s] [INF] [main] Async logger initialized (min_level=INFO)
18:05:29.385 [+0.000s] [INF] [arq] ARQ no-progress timeout: 180s
18:05:29.385 [+0.000s] [INF] [arq] ARQ disconnect drain timeout: 30s
18:05:29.385 [+0.000s] [INF] [arq] Data retry slots: 10
18:05:29.385 [+0.000s] [INF] [arq] mode_hold_after_downgrade_s = 6
18:05:29.385 [+0.000s] [INF] [arq] ladder_up_successes = 2
18:05:29.385 [+0.000s] [INF] [arq] retry_downgrade_threshold = 2
18:05:29.385 [+0.000s] [INF] [arq] channel_guard_ms = 700
18:05:29.385 [+0.000s] [INF] [arq] iss_post_ack_guard_ms = 900
18:05:29.385 [+0.000s] [INF] [arq] keepalive_interval_s = 20
18:05:29.385 [+0.000s] [INF] [arq] keepalive_miss_limit = 5
18:05:29.385 [+0.000s] [INF] [arq] peer_payload_hold_s = 15
18:05:29.385 [+0.000s] [INF] [arq] startup_max_s = 10
18:05:29.385 [+0.000s] [INF] [engine] Logger initialised (min_level=INFO)
18:05:29.385 [+0.000s] [INF] [engine] Initialising audio I/O (subsystem=0)
18:05:29.388 [+0.003s] [INF] [radio-io] Initializing radio (type=3073, device=/dev/ttyUSB0, hamlib_log_level=0, serial_speed=19200)
18:05:29.388 [+0.004s] [INF] [radio-io] Serial speed overridden to 19200 baud
18:05:29.392 [+0.007s] [INF] [audio-play] I/O playback (plughw:0,0 'USB Audio CODEC USB Audio') int32 / 48000Hz / 2ch / 30ms buffer
18:05:29.395 [+0.010s] [INF] [audio-cap] I/O capture (plughw:0,0 'USB Audio CODEC USB Audio') int32 / 48000Hz / 2ch / 30ms buffer
18:05:29.696 [+0.311s] [INF] [radio-io] Radio control: HAMLIB (model 3073, device /dev/ttyUSB0)
18:05:29.696 [+0.311s] [INF] [radio-io] hamlib runtime: Hamlib 4.6.2 2025-02-09T21:03:50Z SHA=870364 32-bit
18:05:29.696 [+0.311s] [INF] [radio-io] rig reports post_ptt_delay=0 ms (informational -- mercury's keying wait is independent of it)
18:05:29.696 [+0.311s] [INF] [engine] Initialising modem (mode=12)
18:05:29.696 [+0.312s] [INF] [modem] Created data buffers for ARQ and BROADCAST datalink, tx/rx paths.
18:05:29.709 [+0.324s] [INF] [modem] Initialized persistent FreeDV mode pool (DATAC16/DATAC15/DATAC13/DATAC4/DATAC3/DATAC1/DATAC17/QAM16C2), frames per burst: 1
18:05:29.709 [+0.324s] [INF] [modem] Active FreeDV mode at startup: 12 (DATAC3), verbosity: 0
18:05:29.709 [+0.324s] [INF] [modem] Modem expects sample rate: 8000 Hz
18:05:29.709 [+0.324s] [INF] [modem] Modem payload bytes per frame: 126
18:05:29.709 [+0.324s] [INF] [modem] Split control/data mode switching: ENABLED
18:05:29.709 [+0.324s] [INF] [arq-bus] Initialized channel bus
18:05:29.709 [+0.325s] [INF] [arq] Event loop started
18:05:29.709 [+0.325s] [INF] [arq] ARQ initialized (frame=126 mode=12)
18:05:29.709 [+0.325s] [INF] [bcast] Starting broadcast system...
18:05:29.709 [+0.325s] [INF] [bcast] Broadcast frame alignment OK (FreeDV mode 12, hermes mode 1): 126 bytes.
18:05:29.709 [+0.325s] [INF] [engine] Initialising TCP interfaces (arq=8300, bc=8100)
18:05:29.710 [+0.325s] [INF] [tcp-bcast] Waiting for a client to connect...
18:05:29.710 [+0.325s] [INF] [engine] Initialising UI websocket (port=10000, tls=0, waterfall=1)
18:05:29.710 [+0.325s] [INF] [tcp-ctl] Listening on TCP port 8300
18:05:29.710 [+0.325s] [INF] [tcp-data] Listening on TCP port 8301
18:05:29.710 [+0.325s] [INF] [websocket] Initialized (url=ws://0.0.0.0:10000)
18:05:29.710 [+0.325s] [INF] [ui-comm] WebSocket server ready on port 10000
18:05:29.710 [+0.325s] [INF] [ui-comm] Publisher thread started
18:05:29.710 [+0.325s] [INF] [ui-comm] Spectrum publisher thread started
18:05:29.710 [+0.325s] [INF] [engine] Mercury engine initialised
18:05:29.710 [+0.325s] [INF] [websocket] Server listening on ws://0.0.0.0:10000
18:05:29.710 [+0.326s] [INF] [ui-comm] Publisher started - sending status every 500ms via WebSocket (port 10000)
18:05:29.710 [+0.326s] [INF] [ui-comm] Spectrum publisher started - sending spectrum every 50 ms via WebSocket
18:05:29.921 [+0.536s] [INF] [modem-rx] Spectrum FFT active: nin=512 sr=8000 dB[0]=-36.9
18:05:33.427 [+4.042s] [WRN] [modem-rx] RX backlog exceeded ~2 s cap; flushing stale audio to catch up
18:05:37.646 [+8.261s] [WRN] [modem-rx] RX backlog exceeded ~2 s cap; flushing stale audio to catch up
18:05:38.379 [+8.995s] [INF] [tcp-ctl] Control client connected
18:05:38.380 [+8.995s] [INF] [tcp-data] Data client connected
18:05:38.380 [+8.995s] [INF] [tcp-ctl] Command received: PUBLIC ON
18:05:38.380 [+8.996s] [INF] [tcp-ctl] Command received: CWID ON
18:05:38.380 [+8.996s] [WRN] [tcp-ctl] Unknown command: CWID ON
18:05:38.380 [+8.996s] [INF] [tcp-ctl] Command received: COMPRESSION TEXT
18:05:38.380 [+8.996s] [INF] [tcp-ctl] Command received: MYCALL KM6LYW
18:05:38.380 [+8.996s] [INF] [tcp-ctl] Command received: LISTEN OFF
18:05:38.380 [+8.996s] [INF] [tcp-ctl] Command received: VERSION
18:05:38.380 [+8.996s] [INF] [tcp-ctl] Command received: BW2300
18:05:38.381 [+8.996s] [INF] [tcp-ctl] Command received: BW2300
18:05:38.381 [+8.996s] [INF] [tcp-ctl] Command received: WINLINK SESSION
18:05:38.381 [+8.996s] [WRN] [tcp-ctl] Unknown command: WINLINK SESSION
18:05:38.381 [+8.996s] [INF] [tcp-ctl] Command received: CONNECT KM6LYW KO0OOO
18:05:38.381 [+8.996s] [INF] [arq] My callsign: KM6LYW
18:05:38.623 [+9.239s] [INF] [radio] TX enabled (PTT ON)
18:05:42.405 [+13.020s] [INF] [radio] TX disabled (PTT OFF)
18:05:46.599 [+17.215s] [INF] [radio] TX enabled (PTT ON)
18:05:50.381 [+20.996s] [INF] [radio] TX disabled (PTT OFF)
18:05:54.467 [+25.083s] [INF] [radio] TX enabled (PTT ON)
18:05:58.249 [+28.864s] [INF] [radio] TX disabled (PTT OFF)
18:06:02.580 [+33.195s] [INF] [radio] TX enabled (PTT ON)
18:06:06.362 [+36.977s] [INF] [radio] TX disabled (PTT OFF)
18:06:10.518 [+41.134s] [INF] [radio] TX enabled (PTT ON)
18:06:14.300 [+44.915s] [INF] [radio] TX disabled (PTT OFF)
18:06:18.381 [+48.997s] [INF] [arq] Disconnected
18:06:18.437 [+49.053s] [INF] [tcp-ctl] Command received: BW2300
18:06:18.653 [+49.269s] [WRN] [modem-rx] RX backlog exceeded ~2 s cap; flushing stale audio to catch up
18:06:22.584 [+53.199s] [WRN] [modem-rx] RX backlog exceeded ~2 s cap; flushing stale audio to catch up
18:06:26.840 [+57.455s] [WRN] [modem-rx] RX backlog exceeded ~2 s cap; flushing stale audio to catch up
18:06:31.089 [+61.705s] [WRN] [modem-rx] RX backlog exceeded ~2 s cap; flushing stale audio to catch up
18:06:35.373 [+65.989s] [WRN] [modem-rx] RX backlog exceeded ~2 s cap; flushing stale audio to catch up
18:06:39.668 [+70.283s] [WRN] [modem-rx] RX backlog exceeded ~2 s cap; flushing stale audio to catch up

[craigerl]

I tried opening the alsa device at 24000 to lower the cpu usage, which the radio accepts, but,

18:32:49.575 [+0.003s] [INF] [radio-io] Initializing radio (type=3073, device=/dev/ttyUSB0, hamlib_log_level=0, serial_speed=19200)
18:32:49.575 [+0.003s] [INF] [radio-io] Serial speed overridden to 19200 baud
18:32:49.580 [+0.008s] [INF] [audio-cap] I/O capture (plughw:0,0 'USB Audio CODEC USB Audio') int32 / 24000Hz / 2ch / 30ms buffer
18:32:49.580 [+0.008s] [WRN] [audio-cap] device negotiated 24000 Hz (not the requested 48000); decimating 3:1
18:32:49.582 [+0.010s] [INF] [audio-play] I/O playback (plughw:0,0 'USB Audio CODEC USB Audio') int32 / 24000Hz / 2ch / 30ms buffer
18:32:49.582 [+0.010s] [WRN] [audio-play] device negotiated 24000 Hz (not the requested 48000); resampling 1:3


18:33:11.569 [+21.997s] [WRN] [modem-rx] RX backlog exceeded ~2 s cap; flushing stale audio to catch up
18:33:17.134 [+27.562s] [WRN] [modem-rx] RX backlog exceeded ~2 s cap; flushing stale audio to catch up
18:33:22.582 [+33.010s] [WRN] [modem-rx] RX backlog exceeded ~2 s cap; flushing stale audio to catch up
18:33:28.174 [+38.602s] [WRN] [modem-rx] RX backlog exceeded ~2 s cap; flushing stale audio to catch up
18:33:33.740 [+44.168s] [WRN] [modem-rx] RX backlog exceeded ~2 s cap; flushing stale audio to catch up

[rafael2k]

Thanks Craig — and congratulations on getting Mercury Winlink servers on the air in the USA, that's great to see.

Two separate problems in your log. I've measured both; one has a fix in flight, the other I can now explain but haven't fixed yet.

1. Your connect could not have succeeded — arithmetic, not propagation

Your PTT timestamps tell the whole story:

CALL	TX length	listening window before the next CALL
1	3.781 s	4.195 s
2	3.781 s	4.087 s
3	3.781 s	4.331 s
4	3.782 s	4.157 s

The CALL retry period is ~8.0 s measured PTT-ON to PTT-ON, because the retry timer was started when the frame was queued rather than when it finished transmitting. The CALL itself eats 3.78 s of that, leaving you ~4.1–4.3 s of listening.

KO0OOO needs 4.44 s to answer: 0.70 s channel guard + 3.74 s of DATAC16 ACCEPT. So you key up ~0.2–0.35 s before the reply can finish arriving — every time, five times, then "Disconnected". Even on a perfect link with KO0OOO answering instantly, that ACCEPT never completes before you transmit over the top of it.

Fixed in #161 (arq/fsm: anchor the CALL retry to PTT-OFF, not to enqueue): the retry interval is now measured from PTT-OFF, which gives the far end a full turnaround. fsm_accepting already did this for the ACCEPT side; fsm_calling had simply never got the same treatment. Your log is the first real-link confirmation of it — we'd only seen it in simulation. Thank you, that's genuinely useful.

2. The 100 % CPU is the dual decoder, not the audio path

Your backlog warnings start at +4.0 s, before your client connects at +9.0 s and before any session exists — so it's the idle capture path.

My first guess was the 48 kHz→8 kHz resampler, since it shifted its whole 180-tap history once per input sample (8.6 M word-moves/sec at 48 kHz). Convincing on paper, wrong in practice: measured at 0.31 % of one core. I've made it a circular buffer anyway (now 0.21 %, bit-identical output, in #161) but that is not your problem.

The real cost is that split control/data mode switching runs two decoders continuously over the same samples, and a decoder that never syncs does the most search work. Measured per mode on x86, on noise:

  DATAC16   6.61 %      DATAC4   6.54 %
  DATAC15   6.99 %      DATAC3   6.81 %
  DATAC13   6.72 %      DATAC1   7.00 %

  DATAC16 control + DATAC3 payload = 13.4 % of one x86 core

A Pi 4 core is roughly 5–10× slower than the machine I measured on, which puts that at 67–134 % of one core — doing nothing but hunting for a preamble that isn't there. That matches your 101 % and the pre-connection backlog.

Both instruments are in #161 (utils/rxcost_bench, utils/resampler_bench) so this is reproducible rather than my word for it.

A quick check that would confirm it on your hardware, if you have a moment:

top -H -p $(pgrep -x mercury)

If a single thread is sitting near 100 %, that's the modem RX thread and it confirms the diagnosis. Also worth trying -W 0 (or whatever disables the waterfall in your setup) to take the spectrum FFT out of the picture — I expect it to make little difference, which would further point at the decoders.

The likely fix is to not run the payload decoder while disconnected: until a session exists, only the control mode can bring you a CALL, so that's roughly half the idle cost for free. The catch is that LISTENING currently keeps the payload decoder alive so a station can receive broadcast frames, and you have PUBLIC ON. So it needs a proper decision about broadcast-while-idle rather than a quiet change — I didn't want to slip that in unmeasured. Tracking it as the next piece of work.

On versions

You're on bf7d546, which is current mercuryv2 tip. #161 isn't merged yet, so none of the above fixes are in your build. Once it lands, a rebuild should fix the connect problem outright; the CPU issue will still need the decoder-gating work.

[craigerl]

You guys are amazing! Do you ever sleep ?

It breaks during long listening periods, not so much when actively transmitting, but it still happens during a connection, but I think you know this.

[craigerl]

SUCCESS! If I don't get any RX backlog errors during an RX packet, i'm able to complete a connection, this is my first and only connection so far...

pat VARA-HF 2300 (btw, i asked the pat guys to implement a proper mercury API)

2026/08/09 19:05:39 RigCtl Radio ready. Dial frequency is 7.101.00 MHz.
2026/08/09 19:05:39 Starting HTTP service (http://0.0.0.0:8080)...
2026/08/09 19:09:45 ARDOP TNC initialization failed: dial tcp [::1]:8515: connect: connection refused
2026/08/09 19:10:35 VARA modem () initialized
2026/08/09 19:10:35 Connecting to KO0OOO (varahf)...
2026/08/09 19:10:35 VARA full speed available, registered to KM6LYW
2026/08/09 19:10:55 Connected to KO0OOO (vara)
=======================================================
[SYS_ID: KO0OOO] -- GATEWAY // ADULT DAYCARE & SALOON
=======================================================
* RF_FREQ : 7.101.5 - PTC / RPR / VARA / ARDOP / Mercury HF
* RF_FREQ : 14.110.0 - VARA / RPR
* MODE    : A mechanical mystery wrapped in an oil leak
* MOTTO   : 'I pet cats.  I read books.  I know things.'
-------------------------------------------------------
[CONNECTING] Validando acceso a Winlink CMS...
*** KM6LYW Connected to CMS
[WL2K-5.0-B2FWIHJM$]
;PQ: 28867315
CMS via KO0OOO >
>FF
FQ
2026/08/09 19:12:35 Disconnected.

pi@digipi7:~/git/mercury $ ./mercury -W 0
Rhizomatica Mercury Version 1.9.11 (git bf7d546)
Loaded configuration from mercury.ini
19:10:27.518 [+0.000s] [INF] [main] Async logger initialized (min_level=INFO)
19:10:27.518 [+0.000s] [INF] [arq] ARQ no-progress timeout: 180s
19:10:27.518 [+0.000s] [INF] [arq] ARQ disconnect drain timeout: 30s
19:10:27.518 [+0.000s] [INF] [arq] Data retry slots: 10
19:10:27.518 [+0.000s] [INF] [arq] mode_hold_after_downgrade_s = 6
19:10:27.518 [+0.000s] [INF] [arq] ladder_up_successes = 2
19:10:27.518 [+0.000s] [INF] [arq] retry_downgrade_threshold = 2
19:10:27.518 [+0.000s] [INF] [arq] channel_guard_ms = 700
19:10:27.518 [+0.000s] [INF] [arq] iss_post_ack_guard_ms = 900
19:10:27.518 [+0.000s] [INF] [arq] keepalive_interval_s = 20
19:10:27.518 [+0.000s] [INF] [arq] keepalive_miss_limit = 5
19:10:27.518 [+0.000s] [INF] [arq] peer_payload_hold_s = 15
19:10:27.518 [+0.000s] [INF] [arq] startup_max_s = 10
19:10:27.518 [+0.000s] [INF] [engine] Logger initialised (min_level=INFO)
19:10:27.518 [+0.000s] [INF] [engine] Initialising audio I/O (subsystem=0)
19:10:27.521 [+0.003s] [INF] [radio-io] Initializing radio (type=3073, device=/dev/ttyUSB0, hamlib_log_level=0, serial_speed=19200)
19:10:27.521 [+0.003s] [INF] [radio-io] Serial speed overridden to 19200 baud
19:10:27.525 [+0.007s] [INF] [audio-play] I/O playback (plughw:0,0 'USB Audio CODEC USB Audio') int32 / 48000Hz / 2ch / 30ms buffer
19:10:27.528 [+0.010s] [INF] [audio-cap] I/O capture (plughw:0,0 'USB Audio CODEC USB Audio') int32 / 48000Hz / 2ch / 30ms buffer
19:10:27.825 [+0.307s] [INF] [radio-io] Radio control: HAMLIB (model 3073, device /dev/ttyUSB0)
19:10:27.825 [+0.307s] [INF] [radio-io] hamlib runtime: Hamlib 4.6.2 2025-02-09T21:03:50Z SHA=870364 32-bit
19:10:27.825 [+0.307s] [INF] [radio-io] rig reports post_ptt_delay=0 ms (informational -- mercury's keying wait is independent of it)
19:10:27.825 [+0.307s] [INF] [engine] Initialising modem (mode=12)
19:10:27.825 [+0.307s] [INF] [modem] Created data buffers for ARQ and BROADCAST datalink, tx/rx paths.
19:10:27.838 [+0.319s] [INF] [modem] Initialized persistent FreeDV mode pool (DATAC16/DATAC15/DATAC13/DATAC4/DATAC3/DATAC1/DATAC17/QAM16C2), frames per burst: 1
19:10:27.838 [+0.320s] [INF] [modem] Active FreeDV mode at startup: 12 (DATAC3), verbosity: 0
19:10:27.838 [+0.320s] [INF] [modem] Modem expects sample rate: 8000 Hz
19:10:27.838 [+0.320s] [INF] [modem] Modem payload bytes per frame: 126
19:10:27.838 [+0.320s] [INF] [modem] Split control/data mode switching: ENABLED
19:10:27.838 [+0.320s] [INF] [arq-bus] Initialized channel bus
19:10:27.838 [+0.320s] [INF] [arq] Event loop started
19:10:27.838 [+0.320s] [INF] [arq] ARQ initialized (frame=126 mode=12)
19:10:27.838 [+0.320s] [INF] [bcast] Starting broadcast system...
19:10:27.838 [+0.320s] [INF] [bcast] Broadcast frame alignment OK (FreeDV mode 12, hermes mode 1): 126 bytes.
19:10:27.838 [+0.320s] [INF] [engine] Initialising TCP interfaces (arq=8300, bc=8100)
19:10:27.839 [+0.321s] [INF] [tcp-bcast] Waiting for a client to connect...
19:10:27.839 [+0.321s] [INF] [tcp-ctl] Listening on TCP port 8300
19:10:27.839 [+0.321s] [INF] [tcp-data] Listening on TCP port 8301
19:10:27.839 [+0.321s] [INF] [engine] Initialising UI websocket (port=10000, tls=0, waterfall=0)
19:10:27.839 [+0.321s] [INF] [websocket] Initialized (url=ws://0.0.0.0:10000)
19:10:27.839 [+0.321s] [INF] [ui-comm] WebSocket server ready on port 10000
19:10:27.839 [+0.321s] [INF] [ui-comm] Publisher thread started
19:10:27.839 [+0.321s] [INF] [engine] Mercury engine initialised
19:10:27.839 [+0.321s] [INF] [ui-comm] Publisher started - sending status every 500ms via WebSocket (port 10000)
19:10:27.839 [+0.321s] [INF] [websocket] Server listening on ws://0.0.0.0:10000
19:10:32.637 [+5.119s] [WRN] [modem-rx] RX backlog exceeded ~2 s cap; flushing stale audio to catch up
19:10:35.717 [+8.199s] [INF] [tcp-ctl] Control client connected
19:10:35.717 [+8.199s] [INF] [tcp-data] Data client connected
19:10:35.717 [+8.199s] [INF] [tcp-ctl] Command received: PUBLIC ON
19:10:35.717 [+8.199s] [INF] [tcp-ctl] Command received: CWID ON
19:10:35.717 [+8.199s] [WRN] [tcp-ctl] Unknown command: CWID ON
19:10:35.717 [+8.199s] [INF] [tcp-ctl] Command received: COMPRESSION TEXT
19:10:35.717 [+8.199s] [INF] [tcp-ctl] Command received: MYCALL KM6LYW
19:10:35.718 [+8.200s] [INF] [tcp-ctl] Command received: LISTEN OFF
19:10:35.718 [+8.200s] [INF] [tcp-ctl] Command received: VERSION
19:10:35.718 [+8.200s] [INF] [arq] My callsign: KM6LYW
19:10:35.718 [+8.200s] [INF] [tcp-ctl] Command received: BW2300
19:10:35.718 [+8.200s] [INF] [tcp-ctl] Command received: BW2300
19:10:35.718 [+8.200s] [INF] [tcp-ctl] Command received: WINLINK SESSION
19:10:35.718 [+8.200s] [WRN] [tcp-ctl] Unknown command: WINLINK SESSION
19:10:35.718 [+8.200s] [INF] [tcp-ctl] Command received: CONNECT KM6LYW KO0OOO
19:10:35.876 [+8.358s] [INF] [radio] TX enabled (PTT ON)
19:10:39.656 [+12.138s] [INF] [radio] TX disabled (PTT OFF)
19:10:44.336 [+16.818s] [INF] [radio] TX enabled (PTT ON)
19:10:48.117 [+20.599s] [INF] [radio] TX disabled (PTT OFF)
19:10:51.762 [+24.244s] [INF] [radio] TX enabled (PTT ON)
19:10:55.544 [+28.026s] [INF] [radio] TX disabled (PTT OFF)
19:10:55.822 [+28.304s] [INF] [arq] Connected to KO0OOO
19:10:57.322 [+29.804s] [INF] [radio] TX enabled (PTT ON)
19:11:01.104 [+33.586s] [INF] [radio] TX disabled (PTT OFF)
19:11:05.307 [+37.789s] [INF] [radio] TX enabled (PTT ON)
19:11:09.088 [+41.570s] [INF] [radio] TX disabled (PTT OFF)
19:11:15.267 [+47.749s] [INF] [radio] TX enabled (PTT ON)
19:11:19.049 [+51.531s] [INF] [radio] TX disabled (PTT OFF)
19:11:24.686 [+57.168s] [WRN] [modem-rx] RX backlog exceeded ~2 s cap; flushing stale audio to catch up
19:11:30.722 [+63.204s] [INF] [radio] TX enabled (PTT ON)
19:11:34.503 [+66.985s] [INF] [radio] TX disabled (PTT OFF)
19:11:37.853 [+70.335s] [INF] [arq-fsm] MODE_REQ: peer TX mode 22 -> 10 (my TX mode 22 unchanged)
19:11:38.688 [+71.170s] [INF] [radio] TX enabled (PTT ON)
19:11:42.469 [+74.951s] [INF] [radio] TX disabled (PTT OFF)
19:11:49.212 [+81.694s] [INF] [radio] TX enabled (PTT ON)
19:11:52.994 [+85.476s] [INF] [radio] TX disabled (PTT OFF)
19:11:59.571 [+92.053s] [INF] [radio] TX enabled (PTT ON)
19:12:03.352 [+95.834s] [INF] [radio] TX disabled (PTT OFF)
19:12:03.353 [+95.835s] [INF] [arq-fsm] OLLA-state: payload_mode=22 peer_snr=6.0 local_snr=6.2 olla=+0.0 retries=0 backlog=75 startup_rem=-57531ms
19:12:03.353 [+95.835s] [INF] [arq-fsm] Mode negotiation: 22 -> 12 (peer_snr=6.0 olla=+0.0 eff=6.0 dB, backlog=75)
19:12:03.775 [+96.257s] [INF] [radio] TX enabled (PTT ON)
19:12:07.556 [+100.038s] [INF] [radio] TX disabled (PTT OFF)
19:12:11.521 [+104.003s] [INF] [arq-fsm] MODE_ACK: payload mode 22 -> 12
19:12:11.521 [+104.003s] [INF] [arq-fsm] OLLA-state: payload_mode=12 peer_snr=6.0 local_snr=6.2 olla=+0.0 retries=0 backlog=75 startup_rem=-65699ms
19:12:12.684 [+105.166s] [INF] [radio] TX enabled (PTT ON)
19:12:16.575 [+109.057s] [INF] [radio] TX disabled (PTT OFF)
19:12:20.732 [+113.214s] [INF] [radio] TX enabled (PTT ON)
19:12:24.623 [+117.105s] [INF] [radio] TX disabled (PTT OFF)
19:12:34.709 [+127.191s] [INF] [tcp-ctl] Command received: DISCONNECT
19:12:34.752 [+127.234s] [INF] [tcp-ctl] Command received: BW2300
19:12:35.714 [+128.196s] [INF] [radio] TX enabled (PTT ON)
19:12:39.494 [+131.976s] [INF] [radio] TX disabled (PTT OFF)
19:12:42.860 [+135.342s] [INF] [arq-fsm] Disconnect finalized (peer ack)
19:12:42.860 [+135.342s] [INF] [arq] Disconnected
19:12:42.864 [+135.346s] [INF] [tcp-ctl] Command received: BW2300
19:12:48.271 [+140.753s] [WRN] [modem-rx] RX backlog exceeded ~2 s cap; flushing stale audio to catch up

CPU with -W 0 brought us to the very edge of success, but just barely.

pi@digipi7:~ $ top -H -p $(pgrep -x mercury)

top - 19:18:21 up 30 min,  2 users,  load average: 0.99, 0.89, 0.62
Threads:  15 total,   1 running,  14 sleeping,   0 stopped,   0 zombie
%Cpu(s): 25.3 us,  0.1 sy,  0.0 ni, 74.6 id,  0.0 wa,  0.0 hi,  0.0 si,  0.0 st 
MiB Mem :   3840.6 total,   3458.4 free,    207.7 used,    260.4 buff/cache     
MiB Swap:      0.0 total,      0.0 free,      0.0 used.   3632.9 avail Mem 

  PID USER      PR  NI    VIRT    RES    SHR S  %CPU  %MEM     TIME+ COMMAND                    
 1327 pi        20   0  176912  21920   9928 R  99.9   0.6   5:50.25 mercury                    
 1322 pi        20   0  176912  21920   9928 S   1.3   0.6   0:08.46 mercury                    
 1323 pi        20   0  176912  21920   9928 S   0.3   0.6   0:01.75 mercury                    
 1320 pi        20   0  176912  21920   9928 S   0.0   0.6   0:00.06 mercury                    
 1321 pi        20   0  176912  21920   9928 S   0.0   0.6   0:00.00 mercury                    
 1324 pi        20   0  176912  21920   9928 S   0.0   0.6   0:00.12 mercury                    
 1325 pi        20   0  176912  21920   9928 S   0.0   0.6   0:00.24 mercury                    
 1326 pi        20   0  176912  21920   9928 S   0.0   0.6   0:00.61 mercury                    
 1328 pi        20   0  176912  21920   9928 S   0.0   0.6   0:00.02 mercury                    
 1329 pi        20   0  176912  21920   9928 S   0.0   0.6   0:00.00 mercury                    
 1330 pi        20   0  176912  21920   9928 S   0.0   0.6   0:00.00 mercury                    
 1331 pi        20   0  176912  21920   9928 S   0.0   0.6   0:00.14 mercury                    
 1332 pi        20   0  176912  21920   9928 S   0.0   0.6   0:00.00 mercury                    
 1333 pi        20   0  176912  21920   9928 S   0.0   0.6   0:00.19 mercury                    
 1334 pi        20   0  176912  21920   9928 S   0.0   0.6   0:00.04 mercury    

[rafael2k]

Follow-up on the CPU half, with a profile — and a correction to what I suggested above.

Scratch the "don't run the payload decoder while disconnected" idea. RX has to stay on for broadcast frames, so that decoder can't be gated off while idle. Good thing, but it means the cost has to come out of the decoding itself.

So I profiled the idle path (gprof, 12 s of noise, one decoder):

  %time  cumulative   calls        function
  90.08     3.72s     6,172,320    ofdm_complex_dot_product
   6.78     4.00s         2,640    est_timing_and_freq
   2.91     4.12s           440    quisk_ccfFilter

90 % of idle CPU is one function, called ~514,000 times per second of audio. It comes from est_timing_and_freq inside the burst acquisition detector, which is a brute-force 2-D search: for every coarse frequency hypothesis × every timing offset, one full-length complex dot product against the preamble template (~2,338 of them per call). That is also why every mode measured the same ~6.6 % earlier — the search cost depends on the preamble and the search grid, not on the mode's bandwidth or code size.

Two consequences worth stating plainly:

• It is not the audio path and it is not ARQ. It is preamble acquisition, running continuously because that is its job.
• The cheap-looking win isn't one. The inner loop calls cabsf() (a square root) per iteration and the result is only ever used squared, so that can go — but it lives in the 6.78 % line, not the 90 % one. A few percent, in exchange for patching vendored codec2 acquisition code. Not a good trade for a point release.

The real fix is to stop doing the correlation by brute force: a sliding correlation over N offsets is O(N log N) via FFT instead of O(N × Npsam) directly, which is where the factor-of-many lives. That is a proper piece of work with a hard constraint — acquisition sensitivity at the fringe must not move, and we have instruments to prove it either way (utils/acquire_vs_decode measures the acquire/decode split per mode). It is not something to rush into 1.9.12.

For now, on your Pi 4, the honest status is that a single decoder costs ~6.6 % of one modern x86 core and you are running two, on a core roughly 5–10× slower. That is the 100 %. The top -H check from my previous comment would still be useful confirmation, and if you can tell us whether disabling the waterfall changes anything it would help rule the spectrum FFT in or out.

The connect-timing fix in #161 is unaffected by any of this and should get your connects working.

[craigerl]

If you'd like to see this happen from my end,

https://www.youtube.com/watch?v=SDeZhU51sz4&t=109s)

[rafael2k]

#161 is merged to mercuryv2 (57a4543). Craig — please pull and rebuild.

What this fixes for you: the connect. The CALL retry is now anchored to PTT-OFF instead of to when the frame was queued, so after your 3.78 s CALL the far end gets a full turnaround instead of the ~4.1–4.3 s it had. On your log that window was consistently ~0.2–0.35 s shorter than the 4.44 s KO0OOO needs to answer (0.70 s guard + 3.74 s ACCEPT), which is why five attempts in a row failed. That should now work.

What this does NOT fix: the 100 % CPU. Being straight with you, since I got this wrong twice before landing on the answer:

• I first blamed the 48 kHz→8 kHz resampler. It shifted its whole 180-tap history per input sample — 8.6 M word-moves/sec, damning on paper. Measured: 0.31 % of one core. Not it. (Fixed anyway in this merge, now 0.21 %, output bit-identical — a 6× waste in the only path touching every captured sample shouldn't stay, but don't expect to notice it.)
• I then suggested not running the payload decoder while disconnected. Rafael pointed out that RX has to stay on for broadcast frames, so that's off the table.

The profile settles it: 90 % of idle RX CPU is ofdm_complex_dot_product, ~514,000 calls per second of audio, from the brute-force 2-D timing×frequency preamble search in the burst acquisition detector. One decoder costs ~6.6 % of one modern x86 core; you run two (control + payload) on a Pi 4 core roughly 5–10× slower. That is your 101 %, and it explains why the backlog starts before you even connect.

Fixing it properly means replacing brute-force correlation with FFT-based correlation — O(N log N) instead of O(N × Npsam) — in vendored codec2 acquisition code, under a hard constraint that fringe sensitivity must not move. That is a real piece of work, not a point release, and we have the instrument to prove it either way (utils/acquire_vs_decode measures the acquire-vs-decode split per mode).

Still useful if you have a minute, to confirm on your actual hardware:

• top -H -p $(pgrep -x mercury) — expect one thread near 100 %; that's the modem RX thread.
• Whether disabling the waterfall changes anything. I expect little, which would rule the spectrum FFT out.

Leaving this open for the acquisition work. Thanks again for the report and the log — the PTT timestamps in it were the first real-link confirmation of the connect bug, which we'd only ever seen in simulation.

[rafael2k]

Craig, I'm investigating the issue.

[rafael2k]

One key issue: why are you using 22050 of samplerate?
Could you try running this?

cat /proc/asound/card0/pcm0c/sub0/hw_params    # while mercury is running

[craigerl]

Hi guys,

ignore the 22500 sample - that was an attempt to reduce cpu load.
Also, i see two channels open, are we running decode on both?

git pull
make

pi@digipi7:~ $ cat /proc/asound/card0/pcm0c/sub0/hw_params
access: MMAP_INTERLEAVED
format: S16_LE
subformat: STD
channels: 2
rate: 48000 (48000/1)
period_size: 241
buffer_size: 1440

pi@digipi7:~/git/mercury $ ./mercury -W 0
Rhizomatica Mercury Version 1.9.11 (git 57a4543)
Loaded configuration from mercury.ini
15:22:22.256 [+0.000s] [INF] [main] Async logger initialized (min_level=INFO)
15:22:22.256 [+0.000s] [INF] [arq] ARQ no-progress timeout: 180s
15:22:22.256 [+0.000s] [INF] [arq] ARQ disconnect drain timeout: 30s
15:22:22.256 [+0.000s] [INF] [arq] Data retry slots: 10
15:22:22.256 [+0.000s] [INF] [arq] mode_hold_after_downgrade_s = 6
15:22:22.256 [+0.000s] [INF] [arq] ladder_up_successes = 2
15:22:22.256 [+0.000s] [INF] [arq] retry_downgrade_threshold = 2
15:22:22.256 [+0.000s] [INF] [arq] channel_guard_ms = 700
15:22:22.256 [+0.000s] [INF] [arq] iss_post_ack_guard_ms = 900
15:22:22.256 [+0.000s] [INF] [arq] keepalive_interval_s = 20
15:22:22.256 [+0.000s] [INF] [arq] keepalive_miss_limit = 5
15:22:22.256 [+0.000s] [INF] [arq] peer_payload_hold_s = 15
15:22:22.256 [+0.000s] [INF] [arq] startup_max_s = 10
15:22:22.256 [+0.000s] [INF] [engine] Logger initialised (min_level=INFO)
15:22:22.256 [+0.000s] [INF] [engine] Initialising audio I/O (subsystem=0)
15:22:22.261 [+0.006s] [INF] [radio-io] Initializing radio (type=3073, device=/dev/ttyUSB0, hamlib_log_level=0, serial_speed=19200)
15:22:22.262 [+0.007s] [INF] [radio-io] Serial speed overridden to 19200 baud
15:22:22.266 [+0.011s] [INF] [audio-cap] I/O capture (plughw:0,0 'USB Audio CODEC USB Audio') int32 / 48000Hz / 2ch / 30ms buffer
15:22:22.269 [+0.013s] [INF] [audio-play] I/O playback (plughw:0,0 'USB Audio CODEC USB Audio') int32 / 48000Hz / 2ch / 30ms buffer
15:22:22.568 [+0.313s] [INF] [radio-io] Radio control: HAMLIB (model 3073, device /dev/ttyUSB0)
15:22:22.568 [+0.313s] [INF] [radio-io] hamlib runtime: Hamlib 4.6.2 2025-02-09T21:03:50Z SHA=870364 32-bit
15:22:22.568 [+0.313s] [INF] [radio-io] rig reports post_ptt_delay=0 ms (informational -- mercury's keying wait is independent of it)
15:22:22.568 [+0.313s] [INF] [engine] Initialising modem (mode=12)
15:22:22.569 [+0.313s] [INF] [modem] Created data buffers for ARQ and BROADCAST datalink, tx/rx paths.
15:22:22.581 [+0.326s] [INF] [modem] Initialized persistent FreeDV mode pool (DATAC16/DATAC15/DATAC13/DATAC4/DATAC3/DATAC1/DATAC17/QAM16C2), frames per burst: 1
15:22:22.581 [+0.326s] [INF] [modem] Active FreeDV mode at startup: 12 (DATAC3), verbosity: 0
15:22:22.581 [+0.326s] [INF] [modem] Modem expects sample rate: 8000 Hz
15:22:22.581 [+0.326s] [INF] [modem] Modem payload bytes per frame: 126
15:22:22.581 [+0.326s] [INF] [modem] Split control/data mode switching: ENABLED
15:22:22.582 [+0.326s] [INF] [arq-bus] Initialized channel bus
15:22:22.582 [+0.327s] [INF] [arq] Event loop started
15:22:22.582 [+0.327s] [INF] [arq] ARQ initialized (frame=126 mode=12)
15:22:22.582 [+0.327s] [INF] [bcast] Starting broadcast system...
15:22:22.582 [+0.327s] [INF] [bcast] Broadcast frame alignment OK (FreeDV mode 12, hermes mode 1): 126 bytes.
15:22:22.582 [+0.327s] [INF] [engine] Initialising TCP interfaces (arq=8300, bc=8100)
15:22:22.583 [+0.327s] [INF] [engine] Initialising UI websocket (port=10000, tls=0, waterfall=0)
15:22:22.583 [+0.327s] [INF] [tcp-ctl] Listening on TCP port 8300
15:22:22.583 [+0.327s] [INF] [tcp-data] Listening on TCP port 8301
15:22:22.583 [+0.327s] [INF] [websocket] Initialized (url=ws://0.0.0.0:10000)
15:22:22.583 [+0.327s] [INF] [ui-comm] WebSocket server ready on port 10000
15:22:22.583 [+0.327s] [INF] [ui-comm] Publisher thread started
15:22:22.583 [+0.327s] [INF] [engine] Mercury engine initialised
15:22:22.583 [+0.327s] [INF] [tcp-bcast] Waiting for a client to connect...
15:22:22.583 [+0.327s] [INF] [websocket] Server listening on ws://0.0.0.0:10000
15:22:22.583 [+0.327s] [INF] [ui-comm] Publisher started - sending status every 500ms via WebSocket (port 10000)
15:22:27.191 [+4.935s] [WRN] [modem-rx] RX backlog exceeded ~2 s cap; flushing stale audio to catch up
15:22:32.277 [+10.021s] [WRN] [modem-rx] RX backlog exceeded ~2 s cap; flushing stale audio to catch up
15:22:37.531 [+15.276s] [WRN] [modem-rx] RX backlog exceeded ~2 s cap; flushing stale audio to catch up
15:22:42.788 [+20.533s] [WRN] [modem-rx] RX backlog exceeded ~2 s cap; flushing stale audio to catch up
15:22:48.039 [+25.783s] [WRN] [modem-rx] RX backlog exceeded ~2 s cap; flushing stale audio to catch up
15:22:53.121 [+30.866s] [WRN] [modem-rx] RX backlog exceeded ~2 s cap; flushing stale audio to catch up
15:22:58.376 [+36.120s] [WRN] [modem-rx] RX backlog exceeded ~2 s cap; flushing stale audio to catch up
15:23:03.464 [+41.208s] [WRN] [modem-rx] RX backlog exceeded ~2 s cap; flushing stale audio to catch up
15:23:08.716 [+46.460s] [WRN] [modem-rx] RX backlog exceeded ~2 s cap; flushing stale audio to catch up
15:23:13.972 [+51.716s] [WRN] [modem-rx] RX backlog exceeded ~2 s cap; flushing stale audio to catch up
15:23:19.067 [+56.811s] [WRN] [modem-rx] RX backlog exceeded ~2 s cap; flushing stale audio to catch up
15:23:24.193 [+61.938s] [WRN] [modem-rx] RX backlog exceeded ~2 s cap; flushing stale audio to catch up
...
15:26:15.190 [+232.934s] [WRN] [modem-rx] RX backlog exceeded ~2 s cap; flushing stale audio to catch up
15:26:20.279 [+238.023s] [WRN] [modem-rx] RX backlog exceeded ~2 s cap; flushing stale audio to catch up
15:26:25.527 [+243.271s] [WRN] [modem-rx] RX backlog exceeded ~2 s cap; flushing stale audio to catch up
15:26:25.677 [+243.422s] [INF] [tcp-ctl] Control client connected
15:26:25.678 [+243.423s] [INF] [tcp-data] Data client connected
15:26:25.678 [+243.423s] [INF] [tcp-ctl] Command received: PUBLIC ON
15:26:25.679 [+243.423s] [INF] [tcp-ctl] Command received: CWID ON
15:26:25.679 [+243.423s] [WRN] [tcp-ctl] Unknown command: CWID ON
15:26:25.679 [+243.423s] [INF] [tcp-ctl] Command received: COMPRESSION TEXT
15:26:25.680 [+243.424s] [INF] [tcp-ctl] Command received: MYCALL KM6LYW
15:26:25.680 [+243.424s] [INF] [tcp-ctl] Command received: LISTEN OFF
15:26:25.680 [+243.424s] [INF] [tcp-ctl] Command received: VERSION
15:26:25.680 [+243.424s] [INF] [tcp-ctl] Command received: BW2300
15:26:25.680 [+243.424s] [INF] [tcp-ctl] Command received: BW2300
15:26:25.680 [+243.424s] [INF] [arq] My callsign: KM6LYW
15:26:25.681 [+243.426s] [INF] [tcp-ctl] Command received: WINLINK SESSION
15:26:25.681 [+243.426s] [WRN] [tcp-ctl] Unknown command: WINLINK SESSION
15:26:25.681 [+243.426s] [INF] [tcp-ctl] Command received: CONNECT KM6LYW KO0OOO
15:26:26.035 [+243.779s] [INF] [radio] TX enabled (PTT ON)
15:26:29.814 [+247.559s] [INF] [radio] TX disabled (PTT OFF)
15:26:33.817 [+251.561s] [INF] [arq] Connected to KO0OOO
15:26:34.973 [+252.718s] [INF] [radio] TX enabled (PTT ON)
15:26:38.752 [+256.496s] [INF] [radio] TX disabled (PTT OFF)
15:26:43.095 [+260.840s] [INF] [radio] TX enabled (PTT ON)
15:26:46.877 [+264.621s] [INF] [radio] TX disabled (PTT OFF)
15:26:53.372 [+271.117s] [INF] [radio] TX enabled (PTT ON)
15:26:57.154 [+274.898s] [INF] [radio] TX disabled (PTT OFF)
15:27:00.475 [+278.220s] [INF] [arq-fsm] MODE_REQ: peer TX mode 22 -> 10 (my TX mode 22 unchanged)
15:27:01.496 [+279.241s] [INF] [radio] TX enabled (PTT ON)
15:27:05.278 [+283.022s] [INF] [radio] TX disabled (PTT OFF)
15:27:12.013 [+289.757s] [INF] [radio] TX enabled (PTT ON)
15:27:15.793 [+293.537s] [INF] [radio] TX disabled (PTT OFF)
15:27:15.793 [+293.537s] [INF] [arq-fsm] OLLA-state: payload_mode=22 peer_snr=7.0 local_snr=11.1 olla=+0.0 retries=0 backlog=75 startup_rem=-31976ms
15:27:15.793 [+293.537s] [INF] [arq-fsm] Mode negotiation: 22 -> 12 (peer_snr=7.0 olla=+0.0 eff=7.0 dB, backlog=75)
15:27:16.587 [+294.332s] [INF] [radio] TX enabled (PTT ON)
15:27:20.369 [+298.113s] [INF] [radio] TX disabled (PTT OFF)
15:27:24.367 [+302.111s] [INF] [arq-fsm] MODE_ACK: payload mode 22 -> 12
15:27:24.367 [+302.111s] [INF] [arq-fsm] OLLA-state: payload_mode=12 peer_snr=7.0 local_snr=11.1 olla=+0.0 retries=0 backlog=75 startup_rem=-40550ms
15:27:25.728 [+303.472s] [INF] [radio] TX enabled (PTT ON)
15:27:29.619 [+307.363s] [INF] [radio] TX disabled (PTT OFF)
15:27:33.768 [+311.513s] [INF] [radio] TX enabled (PTT ON)
15:27:37.548 [+315.293s] [INF] [radio] TX disabled (PTT OFF)
15:27:42.403 [+320.148s] [WRN] [modem-rx] RX backlog exceeded ~2 s cap; flushing stale audio to catch up
15:27:45.886 [+323.631s] [INF] [radio] TX enabled (PTT ON)
15:27:49.666 [+327.410s] [INF] [radio] TX disabled (PTT OFF)
15:27:53.789 [+331.534s] [INF] [arq-fsm] OLLA-state: payload_mode=12 peer_snr=10.0 local_snr=9.8 olla=+0.4 retries=0 backlog=3 startup_rem=-69973ms
15:27:54.983 [+332.727s] [INF] [radio] TX enabled (PTT ON)
15:27:58.874 [+336.619s] [INF] [radio] TX disabled (PTT OFF)
15:28:13.457 [+351.201s] [WRN] [modem-rx] RX backlog exceeded ~2 s cap; flushing stale audio to catch up
15:28:18.785 [+356.530s] [WRN] [modem-rx] RX backlog exceeded ~2 s cap; flushing stale audio to catch up
15:28:28.945 [+366.689s] [WRN] [modem-rx] RX backlog exceeded ~2 s cap; flushing stale audio to catch up
15:28:34.273 [+372.017s] [WRN] [modem-rx] RX backlog exceeded ~2 s cap; flushing stale audio to catch up
15:28:39.605 [+377.350s] [WRN] [modem-rx] RX backlog exceeded ~2 s cap; flushing stale audio to catch up
15:28:45.018 [+382.762s] [WRN] [modem-rx] RX backlog exceeded ~2 s cap; flushing stale audio to catch up
15:28:50.353 [+388.098s] [WRN] [modem-rx] RX backlog exceeded ~2 s cap; flushing stale audio to catch up
15:28:55.687 [+393.432s] [WRN] [modem-rx] RX backlog exceeded ~2 s cap; flushing stale audio to catch up
15:29:01.033 [+398.778s] [WRN] [modem-rx] RX backlog exceeded ~2 s cap; flushing stale audio to catch up
15:29:06.353 [+404.097s] [WRN] [modem-rx] RX backlog exceeded ~2 s cap; flushing stale audio to catch up
15:29:11.695 [+409.440s] [WRN] [modem-rx] RX backlog exceeded ~2 s cap; flushing stale audio to catch up
15:29:17.324 [+415.069s] [INF] [radio] TX enabled (PTT ON)
15:29:21.106 [+418.850s] [INF] [radio] TX disabled (PTT OFF)
15:29:27.777 [+425.521s] [INF] [radio] TX enabled (PTT ON)
15:29:31.558 [+429.302s] [INF] [radio] TX disabled (PTT OFF)
15:29:31.558 [+429.303s] [INF] [arq-fsm] OLLA-state: payload_mode=12 peer_snr=10.0 local_snr=9.4 olla=+0.9 retries=0 backlog=6 startup_rem=-167742ms
15:29:32.685 [+430.429s] [INF] [radio] TX enabled (PTT ON)
15:29:36.575 [+434.319s] [INF] [radio] TX disabled (PTT OFF)
15:29:45.924 [+443.668s] [WRN] [modem-rx] RX backlog exceeded ~2 s cap; flushing stale audio to catch up
15:29:50.407 [+448.152s] [INF] [radio] TX enabled (PTT ON)
15:29:54.189 [+451.933s] [INF] [radio] TX disabled (PTT OFF)
15:30:00.494 [+458.238s] [INF] [radio] TX enabled (PTT ON)
15:30:04.275 [+462.020s] [INF] [radio] TX disabled (PTT OFF)
15:30:10.812 [+468.557s] [INF] [radio] TX enabled (PTT ON)
15:30:14.593 [+472.338s] [INF] [radio] TX disabled (PTT OFF)
15:30:14.594 [+472.338s] [INF] [arq-fsm] OLLA-state: payload_mode=12 peer_snr=7.0 local_snr=9.4 olla=+1.3 retries=0 backlog=3 startup_rem=-210777ms
15:30:15.644 [+473.389s] [INF] [radio] TX enabled (PTT ON)
15:30:19.536 [+477.280s] [INF] [radio] TX disabled (PTT OFF)
15:30:28.983 [+486.727s] [WRN] [modem-rx] RX backlog exceeded ~2 s cap; flushing stale audio to catch up
15:30:34.301 [+492.045s] [WRN] [modem-rx] RX backlog exceeded ~2 s cap; flushing stale audio to catch up
15:30:39.617 [+497.361s] [WRN] [modem-rx] RX backlog exceeded ~2 s cap; flushing stale audio to catch up
15:30:44.866 [+502.611s] [WRN] [modem-rx] RX backlog exceeded ~2 s cap; flushing stale audio to catch up
15:30:51.880 [+509.624s] [INF] [radio] TX enabled (PTT ON)
15:30:55.661 [+513.406s] [INF] [radio] TX disabled (PTT OFF)
15:30:55.661 [+513.406s] [INF] [arq] Disconnected
15:30:55.678 [+513.423s] [INF] [tcp-ctl] Command received: BW2300
15:31:00.845 [+518.590s] [WRN] [modem-rx] RX backlog exceeded ~2 s cap; flushing stale audio to catch up
15:31:06.091 [+523.836s] [WRN] [modem-rx] RX backlog exceeded ~2 s cap; flushing stale audio to catch up
15:31:11.338 [+529.083s] [WRN] [modem-rx] RX backlog exceeded ~2 s cap; flushing stale audio to catch up
15:31:16.585 [+534.330s] [WRN] [modem-rx] RX backlog exceeded ~2 s cap; flushing stale audio to catch up

top - 15:29:40 up 10 min,  2 users,  load average: 0.99, 0.80, 0.45
Threads:  15 total,   3 running,  12 sleeping,   0 stopped,   0 zombie
%Cpu(s): 24.2 us,  0.3 sy,  0.0 ni, 75.5 id,  0.0 wa,  0.0 hi,  0.0 si,  0.0 st 
MiB Mem :   3840.6 total,   3397.6 free,    204.6 used,    325.0 buff/cache     
MiB Swap:      0.0 total,      0.0 free,      0.0 used.   3636.0 avail Mem 

  PID USER      PR  NI    VIRT    RES    SHR S  %CPU  %MEM     TIME+ COMMAND    
 1282 pi        20   0  176912  20512   9768 R  96.3   0.5   6:07.57 mercury    
 1277 pi        20   0  176912  20512   9768 S   0.7   0.5   0:04.43 mercury    
 1275 pi        20   0  176912  20512   9768 S   0.0   0.5   0:00.06 mercury    
 1276 pi        20   0  176912  20512   9768 S   0.0   0.5   0:00.00 mercury    
 1278 pi        20   0  176912  20512   9768 R   0.0   0.5   0:01.09 mercury    
 1279 pi        20   0  176912  20512   9768 S   0.0   0.5   0:00.10 mercury    
 1280 pi        20   0  176912  20512   9768 R   0.0   0.5   0:00.22 mercury    
 1281 pi        20   0  176912  20512   9768 S   0.0   0.5   0:00.39 mercury    
 1283 pi        20   0  176912  20512   9768 S   0.0   0.5   0:00.02 mercury    
 1284 pi        20   0  176912  20512   9768 S   0.0   0.5   0:00.00 mercury    
 1285 pi        20   0  176912  20512   9768 S   0.0   0.5   0:00.00 mercury    
 1286 pi        20   0  176912  20512   9768 S   0.0   0.5   0:00.09 mercury    
 1287 pi        20   0  176912  20512   9768 S   0.0   0.5   0:00.00 mercury    
 1288 pi        20   0  176912  20512   9768 S   0.0   0.5   0:00.16 mercury    
 1289 pi        20   0  176912  20512   9768 S   0.0   0.5   0:00.04 mercury    

[rafael2k]

CPU issue. I' m working on it.
btw, are you using 32 or 64 bits system (which Linux are you using too)?