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.

Author: vcunat

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
 ------------

lib/rplan.c

@@ -157,6 +157,7 @@ static struct kr_query *kr_rplan_push_query(struct kr_rplan *rplan,
 	qry->request = rplan->request;
 
 	gettimeofday(&qry->timestamp, NULL);
+	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);

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);