Skip to content

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

New issue

Have a question about this project? Sign up for a free GitHub account to open an issue and contact its maintainers and the community.

Sign up for GitHub

By clicking “Sign up for GitHub”, you agree to our terms of service and privacy statement. We’ll occasionally send you account related emails.

Already on GitHub? Sign in to your account

Open
kedimuzafer wants to merge 1 commit into
base: main
Choose a base branch
from
Open

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

Show file tree
Hide file tree
Changes from all commits
Commits
Show all changes
1 commit
Select commit
File filter

Filter by extension

Filter by extension
Conversations
Failed to load comments.
Loading
Jump to
Jump to file
Failed to load files.
Loading
Diff view
Diff view
7 changes: 0 additions & 7 deletions components/microlink/components/wireguard_lwip/src/wireguard-platform-esp32.c
View file
Open in desktop
Original file line number Diff line number Diff line change
Expand Up @@ -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;
Expand Down
5 changes: 3 additions & 2 deletions components/microlink/components/wireguard_lwip/src/wireguardif.c
View file
Open in desktop
Original file line number Diff line number Diff line change
Expand Up @@ -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,
Expand Down
8 changes: 4 additions & 4 deletions components/microlink/src/ml_derp.c
View file
Open in desktop
Original file line number Diff line number Diff line change
Expand Up @@ -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);
Expand All @@ -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);
}
Expand Down Expand Up @@ -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));
Expand Down Expand Up @@ -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]);
Expand Down
7 changes: 5 additions & 2 deletions components/microlink/src/ml_net_io.c
View file
Open in desktop
Original file line number Diff line number Diff line change
Expand Up @@ -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),
Expand Down
42 changes: 21 additions & 21 deletions components/microlink/src/ml_wg_mgr.c
View file
Open in desktop
Original file line number Diff line number Diff line change
Expand Up @@ -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],
Expand All @@ -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],
Expand All @@ -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),
Expand Down Expand Up @@ -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;
}
Expand Down Expand Up @@ -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),
Expand All @@ -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),
Expand All @@ -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 */
Expand Down Expand Up @@ -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");
}

Expand All @@ -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");

Expand Down Expand Up @@ -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);
}
Expand All @@ -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]);

Expand Down Expand Up @@ -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());

Expand All @@ -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],
Expand All @@ -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);
Expand Down Expand Up @@ -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]);
Expand Down Expand Up @@ -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) */
Expand All @@ -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.
Expand Down