From 5e6a02b3902ac98b327eca281ae70fa2bb9a9598 Mon Sep 17 00:00:00 2001 From: =?utf8?q?Vladim=C3=ADr=20=C4=8Cun=C3=A1t?= Date: Mon, 14 Apr 2025 11:13:32 +0200 Subject: [PATCH] modules/stats: further improve latency measurements libuv's updating the stamp just once per event loop might be too coarse, as processing multiple packets (e.g. DNSSEC validation) may take milliseconds together. Of course we still don't measure e.g. the time when incoming client requests stay in OS buffers. --- NEWS | 1 + lib/rplan.c | 2 ++ modules/stats/stats.c | 8 +++++++- 3 files changed, 10 insertions(+), 1 deletion(-) diff --git a/NEWS b/NEWS index b53ed68d4..1107b88db 100644 --- a/NEWS +++ b/NEWS @@ -5,6 +5,7 @@ Bugfixes -------- - /management/unix-socket: revert to absolute path (#926, !1664) - fix `tags` when used in /local-data/rules/*/records (!1670) +- stats: request latency was very incorrect in some cases (!1676) Improvements ------------ diff --git a/lib/rplan.c b/lib/rplan.c index 0bedd8a73..3d56e2bf4 100644 --- a/lib/rplan.c +++ b/lib/rplan.c @@ -157,6 +157,8 @@ static struct kr_query *kr_rplan_push_query(struct kr_rplan *rplan, qry->request = rplan->request; gettimeofday(&qry->timestamp, NULL); + if (!parent) // start of kr_request; let's make the stamp more precise + uv_update_time(uv_default_loop()); qry->timestamp_mono = kr_now(); qry->creation_time_mono = parent ? parent->creation_time_mono : qry->timestamp_mono; kr_zonecut_init(&qry->zone_cut, (const uint8_t *)"", rplan->pool); diff --git a/modules/stats/stats.c b/modules/stats/stats.c index 343b8c50a..6538ae4f4 100644 --- a/modules/stats/stats.c +++ b/modules/stats/stats.c @@ -262,8 +262,14 @@ static int collect(kr_layer_t *ctx) collect_answer(data, param->answer); /* Count cached and unresolved */ if (rplan->resolved.len > 0) { - /* Histogram of answer latency. */ + /* Histogram of answer latency. + * + * We update the notion of time. Once per .finish isn't that expensive. + * defer_* also updates this if active, but not in ideal moment for stats. + */ + uv_update_time(uv_default_loop()); uint64_t elapsed = kr_now() - rplan->initial->creation_time_mono; + stat_const_add(data, metric_answer_sum_ms, elapsed); if (elapsed <= 1) { stat_const_add(data, metric_answer_1ms, 1); -- 2.47.2