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.

diff --git a/NEWS b/NEWS
index b53ed68d4023fd5b5c9333cc439850efc3077c0b..1107b88db3b1f4b3ff506cb1d7a33ab4fdd9e976 100644 (file)
--- 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 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 343b8c50a57e6daf29854a7908663bb461b64b9b..6538ae4f49d8005027dcff6a658a0d1ac35702c9 100644 (file)
--- 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);