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.

(cherry picked from commit 5e6a02b3902ac98b327eca281ae70fa2bb9a9598)

diff --git a/NEWS b/NEWS
index efe74baae1785dd0bf9b56fcc4a1900673e49461..4b17d8b5bf01680921c19ac764f52d28d5e36d60 100644 (file)
--- a/NEWS
+++ b/NEWS
@@ -10,6 +10,10 @@ Improvements
 - tests: disable problematic config.http test (#925, !1678)
 - validator: accept a confusing NODATA proof with insecure delegation (!1678)
 
+Bugfixes
+--------
+- stats: request latency was very incorrect in some cases (!1678)
+
 
 Knot Resolver 5.7.4 (2024-07-23)
 ================================

diff --git a/lib/rplan.c b/lib/rplan.c
index 0bedd8a732796797ff306c015197483b29b7a8be..3d56e2bf4c239e29ab90d273a911ed5d13b6543a 100644 (file)
--- 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 3b57c57b19624444ac2b7c2244868bd8656e027b..074f7e534f1cd2ef7a878ed0b3115e0074924838 100644 (file)
--- a/modules/stats/stats.c
+++ b/modules/stats/stats.c
@@ -248,8 +248,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);