From a67b4cda4ab913522b087409f604b75624b44362 Mon Sep 17 00:00:00 2001 From: Your Name Date: Thu, 5 Mar 2026 11:15:17 -0400 Subject: [PATCH] debug: add poll latency instrumentation --- src/nostr_handler.c | 29 +++++++++++++++++++++++++++++ 1 file changed, 29 insertions(+) diff --git a/src/nostr_handler.c b/src/nostr_handler.c index ff24bb2..754fd17 100644 --- a/src/nostr_handler.c +++ b/src/nostr_handler.c @@ -2041,9 +2041,38 @@ int nostr_handler_poll(int timeout_ms) { return -1; } + double start_ms = -1.0; + struct timespec ts_start; + if (clock_gettime(CLOCK_MONOTONIC, &ts_start) == 0) { + start_ms = ts_start.tv_sec * 1000.0 + ts_start.tv_nsec / 1000000.0; + } + int rc = nostr_relay_pool_poll(g_pool, timeout_ms); g_poll_counter++; + if (start_ms >= 0.0) { + struct timespec ts_end; + if (clock_gettime(CLOCK_MONOTONIC, &ts_end) == 0) { + const double end_ms = ts_end.tv_sec * 1000.0 + ts_end.tv_nsec / 1000000.0; + const double elapsed_ms = end_ms - start_ms; + const double expected_ms = timeout_ms > 0 ? (double)timeout_ms : 0.0; + + if (elapsed_ms > expected_ms + 250.0) { + DEBUG_WARN("[didactyl] poll latency spike: nostr_relay_pool_poll(timeout=%d) took %.1fms rc=%d count=%llu", + timeout_ms, + elapsed_ms, + rc, + (unsigned long long)g_poll_counter); + } else if ((g_poll_counter % 200ULL) == 0ULL) { + DEBUG_TRACE("[didactyl] poll heartbeat: timeout=%d elapsed=%.1fms rc=%d count=%llu", + timeout_ms, + elapsed_ms, + rc, + (unsigned long long)g_poll_counter); + } + } + } + log_relay_state_changes(); return rc;