From 118c03cb34f494641e5f9aa9939d3ff083cbe473 Mon Sep 17 00:00:00 2001 From: kedimuzafer Date: Sat, 29 Aug 2026 20:01:54 +0300 Subject: [PATCH] perf: move per-packet datapath logging to DEBUG 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) Claude-Session: https://claude.ai/code/session_016bqLmUG7wJ7p9ya2Vp4A9J --- .../src/wireguard-platform-esp32.c | 7 ---- .../wireguard_lwip/src/wireguardif.c | 5 ++- components/microlink/src/ml_derp.c | 8 ++-- components/microlink/src/ml_net_io.c | 7 +++- components/microlink/src/ml_wg_mgr.c | 42 +++++++++---------- 5 files changed, 33 insertions(+), 36 deletions(-) diff --git a/components/microlink/components/wireguard_lwip/src/wireguard-platform-esp32.c b/components/microlink/components/wireguard_lwip/src/wireguard-platform-esp32.c index f974c67..4ed3aeb 100644 --- a/components/microlink/components/wireguard_lwip/src/wireguard-platform-esp32.c +++ b/components/microlink/components/wireguard_lwip/src/wireguard-platform-esp32.c @@ -25,13 +25,6 @@ void wireguard_tai64n_now(uint8_t *output) { uint64_t seconds = now_us / 1000000ULL; uint32_t nanoseconds = (now_us % 1000000ULL) * 1000; - // Log raw uptime before TAI offset (only every ~5s to avoid spam) - static uint64_t last_log_s = 0; - if (seconds - last_log_s >= 5) { - printf("[TAI64N] uptime=%llu s, nano=%lu\n", (unsigned long long)seconds, (unsigned long)nanoseconds); - last_log_s = seconds; - } - // TAI64 starts at 1970-01-01 00:00:10 TAI (Unix epoch + 10 seconds) // Add TAI offset: 2^62 + Unix time seconds += 0x400000000000000AULL; diff --git a/components/microlink/components/wireguard_lwip/src/wireguardif.c b/components/microlink/components/wireguard_lwip/src/wireguardif.c index 6627fd0..668b5ee 100644 --- a/components/microlink/components/wireguard_lwip/src/wireguardif.c +++ b/components/microlink/components/wireguard_lwip/src/wireguardif.c @@ -755,8 +755,9 @@ void wireguardif_network_rx(void *arg, struct udp_pcb *pcb, struct pbuf *p, cons uint8_t type = wireguard_get_message_type(data, len); - // Always log incoming WG packets (critical for debugging handshake issues) - printf("[WG_RX] type=%d (%s) len=%u from %s:%u\n", + // Per-packet trace. This must stay compiled out by default: a raw printf + // here blocks the datapath on the UART for every single packet received. + WG_DEBUG("[WG_RX] type=%d (%s) len=%u from %s:%u\n", type, type == 1 ? "INIT" : type == 2 ? "RESP" : type == 3 ? "COOKIE" : type == 4 ? "DATA" : "?", (unsigned)len, diff --git a/components/microlink/src/ml_derp.c b/components/microlink/src/ml_derp.c index c57fd0f..f2cd9b4 100644 --- a/components/microlink/src/ml_derp.c +++ b/components/microlink/src/ml_derp.c @@ -299,7 +299,7 @@ static void dispatch_derp_frame(microlink_t *ml, uint8_t frame_type, switch (frame_type) { case DERP_FRAME_RECV_PACKET: if (payload) { - ESP_LOGI(TAG, "DERP RecvPacket: %d bytes from %02x%02x%02x%02x, hdr=%02x", + ESP_LOGD(TAG, "DERP RecvPacket: %d bytes from %02x%02x%02x%02x, hdr=%02x", (int)payload_len, src_key[0], src_key[1], src_key[2], src_key[3], payload_len > 0 ? payload[0] : 0xFF); @@ -326,7 +326,7 @@ static void dispatch_derp_frame(microlink_t *ml, uint8_t frame_type, case DERP_FRAME_PEER_GONE: if (payload && payload_len >= 32) { - ESP_LOGI(TAG, "DERP PeerGone: %02x%02x%02x%02x (len=%d)", + ESP_LOGD(TAG, "DERP PeerGone: %02x%02x%02x%02x (len=%d)", payload[0], payload[1], payload[2], payload[3], (int)payload_len); } @@ -499,7 +499,7 @@ void ml_derp_tx_task(void *arg) { /* Unconditional heartbeat - proves task is alive */ if (loop_start - last_heartbeat_ms > 5000) { - ESP_LOGW(TAG, "HEARTBEAT: loop=%lu conn=%d rx=%lu tx=%lu stack_free=%lu", + ESP_LOGD(TAG, "HEARTBEAT: loop=%lu conn=%d rx=%lu tx=%lu stack_free=%lu", (unsigned long)loop_count, ml->derp.connected, (unsigned long)frames_rx, (unsigned long)frames_tx, (unsigned long)uxTaskGetStackHighWaterMark(NULL)); @@ -586,7 +586,7 @@ void ml_derp_tx_task(void *arg) { } int ret; if (item.frame_type == DERP_FRAME_SEND_PACKET) { - ESP_LOGI(TAG, "DERP TX: SendPacket %d bytes, dest=%02x%02x%02x%02x, hdr=%02x", + ESP_LOGD(TAG, "DERP TX: SendPacket %d bytes, dest=%02x%02x%02x%02x, hdr=%02x", (int)item.len, item.dest_pubkey[0], item.dest_pubkey[1], item.dest_pubkey[2], item.dest_pubkey[3], item.data[0]); diff --git a/components/microlink/src/ml_net_io.c b/components/microlink/src/ml_net_io.c index f8b6799..905b1bd 100644 --- a/components/microlink/src/ml_net_io.c +++ b/components/microlink/src/ml_net_io.c @@ -53,8 +53,11 @@ static void route_udp_packet(microlink_t *ml, uint8_t *data, size_t len, uint32_t src_ip, uint16_t src_port) { pkt_type_t type = classify_packet(data, len); - /* Log ALL direct UDP packets for debugging */ - ESP_LOGI(TAG, "UDP RX: %d bytes from %d.%d.%d.%d:%d type=%s hdr=%02x", + /* Per-packet trace, kept at DEBUG. At INFO this line is emitted for every + * tunnelled packet, and the UART write blocks the receive task for roughly + * 6 ms per packet at 115200 baud — on its own that caps the datapath at + * ~165 pps and backs the lwIP UDP mailbox up behind it. */ + ESP_LOGD(TAG, "UDP RX: %d bytes from %d.%d.%d.%d:%d type=%s hdr=%02x", (int)len, (int)((src_ip >> 24) & 0xFF), (int)((src_ip >> 16) & 0xFF), (int)((src_ip >> 8) & 0xFF), (int)(src_ip & 0xFF), diff --git a/components/microlink/src/ml_wg_mgr.c b/components/microlink/src/ml_wg_mgr.c index ed40942..757debb 100644 --- a/components/microlink/src/ml_wg_mgr.c +++ b/components/microlink/src/ml_wg_mgr.c @@ -138,7 +138,7 @@ static err_t wg_derp_output_cb(const uint8_t *peer_public_key, break; } } - ESP_LOGI(TAG, "WG INIT -> %s len=%d key=%02x%02x%02x%02x%02x%02x%02x%02x", + ESP_LOGD(TAG, "WG INIT -> %s len=%d key=%02x%02x%02x%02x%02x%02x%02x%02x", hostname, (int)len, peer_public_key[0], peer_public_key[1], peer_public_key[2], peer_public_key[3], @@ -150,18 +150,18 @@ static err_t wg_derp_output_cb(const uint8_t *peer_public_key, init_dump_count++; /* WG handshake init: type(1) reserved(3) sender(4) ephemeral(32) * enc_static(48) enc_timestamp(28) mac1(16) mac2(16) = 148 */ - ESP_LOGI(TAG, " type=%02x res=%02x%02x%02x sender=%02x%02x%02x%02x", + ESP_LOGD(TAG, " type=%02x res=%02x%02x%02x sender=%02x%02x%02x%02x", data[0], data[1], data[2], data[3], data[4], data[5], data[6], data[7]); - ESP_LOGI(TAG, " ephemeral=%02x%02x%02x%02x...%02x%02x%02x%02x", + ESP_LOGD(TAG, " ephemeral=%02x%02x%02x%02x...%02x%02x%02x%02x", data[8], data[9], data[10], data[11], data[36], data[37], data[38], data[39]); - ESP_LOGI(TAG, " mac1=%02x%02x%02x%02x%02x%02x%02x%02x%02x%02x%02x%02x%02x%02x%02x%02x", + ESP_LOGD(TAG, " mac1=%02x%02x%02x%02x%02x%02x%02x%02x%02x%02x%02x%02x%02x%02x%02x%02x", data[116], data[117], data[118], data[119], data[120], data[121], data[122], data[123], data[124], data[125], data[126], data[127], data[128], data[129], data[130], data[131]); - ESP_LOGI(TAG, " mac2=%02x%02x%02x%02x%02x%02x%02x%02x%02x%02x%02x%02x%02x%02x%02x%02x", + ESP_LOGD(TAG, " mac2=%02x%02x%02x%02x%02x%02x%02x%02x%02x%02x%02x%02x%02x%02x%02x%02x", data[132], data[133], data[134], data[135], data[136], data[137], data[138], data[139], data[140], data[141], data[142], data[143], @@ -188,7 +188,7 @@ static err_t wg_udp_output_cb(uint32_t dest_ip, uint16_t dest_port, /* Log WG packets sent via direct UDP */ uint32_t ip_host = ntohl(dest_ip); - ESP_LOGI(TAG, "WG UDP TX: %d bytes -> %d.%d.%d.%d:%d type=%d", + ESP_LOGD(TAG, "WG UDP TX: %d bytes -> %d.%d.%d.%d:%d type=%d", (int)len, (int)((ip_host >> 24) & 0xFF), (int)((ip_host >> 16) & 0xFF), (int)((ip_host >> 8) & 0xFF), (int)(ip_host & 0xFF), @@ -692,7 +692,7 @@ static void disco_build_ping(microlink_t *ml, int peer_idx, pending_probes[i].sent_ms = ml_get_time_ms(); pending_probes[i].active = true; registered = true; - ESP_LOGI(TAG, "Probe registered slot=%d peer=%s txid=%02x%02x%02x%02x", + ESP_LOGD(TAG, "Probe registered slot=%d peer=%s txid=%02x%02x%02x%02x", i, p->hostname, txid[0], txid[1], txid[2], txid[3]); break; } @@ -781,7 +781,7 @@ static void disco_send_ping_to_peer(microlink_t *ml, int peer_idx, bool force) { p->endpoints[i].port == p->best_port) continue; int ret = disco_udp_sendto(ml, pkt, pkt_len, p->endpoints[i].ip, p->endpoints[i].port); if (!direct_sent) { /* Log only first direct send per peer */ - ESP_LOGI(TAG, " direct probe -> %d.%d.%d.%d:%d (%d eps, ret=%d)", + ESP_LOGD(TAG, " direct probe -> %d.%d.%d.%d:%d (%d eps, ret=%d)", (int)((p->endpoints[i].ip >> 24) & 0xFF), (int)((p->endpoints[i].ip >> 16) & 0xFF), (int)((p->endpoints[i].ip >> 8) & 0xFF), @@ -805,9 +805,9 @@ static void disco_send_ping_to_peer(microlink_t *ml, int peer_idx, bool force) { * DERP pong stealing the probe match from the direct pong. */ if (!p->has_direct_path || !direct_sent) { ml_derp_queue_send(ml, p->public_key, pkt, pkt_len); - ESP_LOGI(TAG, "DISCO PING -> %s via DERP", p->hostname); + ESP_LOGD(TAG, "DISCO PING -> %s via DERP", p->hostname); } else { - ESP_LOGI(TAG, "DISCO PING -> %s via direct %d.%d.%d.%d:%d", + ESP_LOGD(TAG, "DISCO PING -> %s via direct %d.%d.%d.%d:%d", p->hostname, (int)((p->best_ip >> 24) & 0xFF), (int)((p->best_ip >> 16) & 0xFF), (int)((p->best_ip >> 8) & 0xFF), (int)(p->best_ip & 0xFF), @@ -834,7 +834,7 @@ static void process_disco_ping(microlink_t *ml, const ml_rx_packet_t *pkt, ml_peer_t *p = &ml->peers[peer_idx]; - ESP_LOGI(TAG, "DISCO PING from %s (via %s)", + ESP_LOGD(TAG, "DISCO PING from %s (via %s)", p->hostname, pkt->via_derp ? "DERP" : "direct"); /* Build PONG */ @@ -887,7 +887,7 @@ static void process_disco_ping(microlink_t *ml, const ml_rx_packet_t *pkt, /* 3. ALWAYS send via DERP (guaranteed delivery, even if direct worked) */ ml_derp_queue_send(ml, p->public_key, pong, pong_len); - ESP_LOGI(TAG, "PONG sent to %s (direct=%s, DERP=yes)", + ESP_LOGD(TAG, "PONG sent to %s (direct=%s, DERP=yes)", p->hostname, direct_sent ? "yes" : "no"); } @@ -914,7 +914,7 @@ static void process_disco_pong(microlink_t *ml, const ml_rx_packet_t *pkt, ml_peer_t *p = &ml->peers[peer_idx]; uint64_t rtt_ms = now - pending_probes[i].sent_ms; - ESP_LOGI(TAG, "DISCO PONG from %s: RTT=%llu ms (via %s)", + ESP_LOGD(TAG, "DISCO PONG from %s: RTT=%llu ms (via %s)", p->hostname, (unsigned long long)rtt_ms, pkt->via_derp ? "DERP" : "direct"); @@ -1006,7 +1006,7 @@ static void process_disco_pong(microlink_t *ml, const ml_rx_packet_t *pkt, for (int i = 0; i < MAX_PENDING_PROBES; i++) { if (pending_probes[i].active) active_count++; } - ESP_LOGW(TAG, "DISCO PONG unmatched from %s (via %s) txid=%02x%02x%02x%02x, active_probes=%d", + ESP_LOGD(TAG, "DISCO PONG unmatched from %s (via %s) txid=%02x%02x%02x%02x, active_probes=%d", name, pkt->via_derp ? "DERP" : "direct", txid[0], txid[1], txid[2], txid[3], active_count); } @@ -1018,7 +1018,7 @@ static void process_disco_packet(microlink_t *ml, const ml_rx_packet_t *pkt) { /* Verify DISCO magic */ if (memcmp(pkt->data, DISCO_MAGIC, 6) != 0) return; - ESP_LOGI(TAG, "DISCO RX: %d bytes via %s, disco_key=%02x%02x%02x%02x", + ESP_LOGD(TAG, "DISCO RX: %d bytes via %s, disco_key=%02x%02x%02x%02x", (int)pkt->len, pkt->via_derp ? "DERP" : "direct", pkt->data[6], pkt->data[7], pkt->data[8], pkt->data[9]); @@ -1072,7 +1072,7 @@ static void process_disco_packet(microlink_t *ml, const ml_rx_packet_t *pkt) { size_t ep_data_len = plaintext_len - 2; int ep_count = ep_data_len / 18; - ESP_LOGI(TAG, "CallMeMaybe from %s: %d endpoints (udp_path=%d, at_sock=%d)", + ESP_LOGD(TAG, "CallMeMaybe from %s: %d endpoints (udp_path=%d, at_sock=%d)", ml->peers[peer_idx].hostname, ep_count, disco_has_udp_path(ml), ml_at_socket_is_ready()); @@ -1095,7 +1095,7 @@ static void process_disco_packet(microlink_t *ml, const ml_rx_packet_t *pkt) { } if (entry[10] != 0xff || entry[11] != 0xff) is_v4_mapped = false; - ESP_LOGI(TAG, " CMM ep[%d]: v4mapped=%d port=%d bytes=%02x%02x%02x%02x%02x%02x%02x%02x%02x%02x%02x%02x%02x%02x%02x%02x", + ESP_LOGD(TAG, " CMM ep[%d]: v4mapped=%d port=%d bytes=%02x%02x%02x%02x%02x%02x%02x%02x%02x%02x%02x%02x%02x%02x%02x%02x", i, is_v4_mapped, port, entry[0], entry[1], entry[2], entry[3], entry[4], entry[5], entry[6], entry[7], @@ -1117,7 +1117,7 @@ static void process_disco_packet(microlink_t *ml, const ml_rx_packet_t *pkt) { if (ping_len > 0) { int ret = disco_udp_sendto(ml, ping_pkt, ping_len, ip, port); - ESP_LOGI(TAG, "CMM probe -> %d.%d.%d.%d:%d (%d bytes, ret=%d)", + ESP_LOGD(TAG, "CMM probe -> %d.%d.%d.%d:%d (%d bytes, ret=%d)", (int)((ip >> 24) & 0xFF), (int)((ip >> 16) & 0xFF), (int)((ip >> 8) & 0xFF), (int)(ip & 0xFF), (int)port, (int)ping_len, ret); @@ -1145,7 +1145,7 @@ static void process_disco_packet(microlink_t *ml, const ml_rx_packet_t *pkt) { * ========================================================================== */ static void process_wg_packet(microlink_t *ml, const ml_rx_packet_t *pkt) { - ESP_LOGI(TAG, "WG RX: %d bytes, via_derp=%d, type=%d, from=%02x%02x%02x%02x", + ESP_LOGD(TAG, "WG RX: %d bytes, via_derp=%d, type=%d, from=%02x%02x%02x%02x", (int)pkt->len, pkt->via_derp, pkt->len >= 4 ? pkt->data[0] : -1, pkt->src_pubkey[0], pkt->src_pubkey[1], pkt->src_pubkey[2], pkt->src_pubkey[3]); @@ -1621,7 +1621,7 @@ void ml_wg_mgr_task(void *arg) { wireguardif_periodic((struct netif *)ml->wg_netif); uint64_t dt = ml_get_time_ms() - t0; last_wg_periodic_ms = now; - ESP_LOGI(TAG, "wireguardif_periodic: %llu ms", (unsigned long long)dt); + ESP_LOGD(TAG, "wireguardif_periodic: %llu ms", (unsigned long long)dt); } /* Periodic DISCO probes (every 1s check) */ @@ -1631,7 +1631,7 @@ void ml_wg_mgr_task(void *arg) { disco_periodic_probes(ml); uint64_t dt = ml_get_time_ms() - t0; last_disco_probe_ms = now; - ESP_LOGI(TAG, "disco_periodic_probes: %llu ms", (unsigned long long)dt); + ESP_LOGD(TAG, "disco_periodic_probes: %llu ms", (unsigned long long)dt); } /* Yield - 10ms loop rate for minimum packet processing latency.