Skip to content

perf: move per-packet datapath logging to DEBUG - #30

Open
kedimuzafer wants to merge 1 commit into
CamM2325:mainfrom
kedimuzafer:perf/datapath-logging
Open

perf: move per-packet datapath logging to DEBUG#30
kedimuzafer wants to merge 1 commit into
CamM2325:mainfrom
kedimuzafer:perf/datapath-logging

Conversation

@kedimuzafer

Copy link
Copy Markdown

Problem

A handful of log statements on the WireGuard/DISCO datapath are at ESP_LOGI, and two are plain printf(). On a default build they therefore fire once per packet.

At 115200 baud a ~70-character line takes ~6 ms to write, and the UART write blocks the task that issues it. ml_net_io.c's UDP RX: line is emitted from the socket receive task before the packet is even queued, so the cost lands directly in the receive path.

Measurement

ESP32-S3 (8 MB PSRAM) running MicroLink as a Tailscale SOCKS5 proxy, peer on the same LAN, direct path:

before after
sustained packet rate before loss (1000 B ICMP) ~20 pps, then 18% loss at 50 pps 100 pps, 0% loss
tunnel RTT 20–235 ms, mdev 58 ms 6.2 ms, mdev 0.8 ms

Before the change, any TCP transfer larger than a few tens of KB through the tunnel stalled, and the node stopped answering ICMP for the duration — the UART was holding the receive task while the lwIP UDP mailbox (CONFIG_LWIP_UDP_RECVMBOX_SIZE, 6 by default) overflowed behind it.

Change

Demoted to ESP_LOGD / WG_DEBUG so they compile out at the default log level and remain available by raising it:

  • ml_net_io.cUDP RX: ..., once per received packet
  • wireguardif.c[WG_RX] type=..., once per received packet, a raw printf
  • ml_wg_mgr.cDISCO RX/PING/PONG, WG RX/WG UDP TX, the WG INIT hex dump, and the wireguardif_periodic / disco_periodic_probes timing lines
  • ml_derp.cDERP RecvPacket/SendPacket/PeerGone, HEARTBEAT

Also removes the [TAI64N] uptime printf in wireguard_tai64n_now(). It is rate-limited to every 5 s, but it sits on the handshake path and reports nothing actionable.

Nothing changes except log verbosity. Everything demoted is still reachable with esp_log_level_set() or a higher CONFIG_LOG_MAXIMUM_LEVEL.

Several log statements on the WireGuard/DISCO datapath run at INFO, so they
are emitted for every packet on a default build. Two are unconditional
printf() calls. At 115200 baud each of these lines blocks the task that
writes it for roughly 6 ms, and they sit in the receive path itself.

Measured on an ESP32-S3 acting as a Tailscale SOCKS5 proxy: with these at
INFO the node could not sustain more than ~20 packets/s before the lwIP UDP
mailbox backed up behind the UART and TCP through the tunnel collapsed. ICMP
to the node stopped answering for the duration of any transfer.

Demoted to ESP_LOGD / WG_DEBUG, so they compile out at the default log level
and are still available by raising it:

  ml_net_io.c   "UDP RX: ..."            - once per received packet
  wireguardif.c "[WG_RX] type=..."       - once per received packet, printf
  ml_wg_mgr.c   DISCO RX/PING/PONG, WG RX/TX, the WG INIT hex dump,
                wireguardif_periodic and disco_periodic_probes timings
  ml_derp.c     DERP RecvPacket/SendPacket/PeerGone, HEARTBEAT

Also drops the [TAI64N] uptime printf from wireguard_tai64n_now(): it is
rate-limited to every 5 s but sits on the handshake path and logs nothing
actionable.

No behaviour changes beyond log verbosity.

Co-Authored-By: Claude Opus 5 (1M context) <noreply@anthropic.com>
Claude-Session: https://claude.ai/code/session_016bqLmUG7wJ7p9ya2Vp4A9J
Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment

Labels

None yet

Projects

None yet

Development

Successfully merging this pull request may close these issues.

1 participant