From: Lukáš Ondráček <lukas.ondracek@nic.cz>
Date: Tue, 14 May 2024 11:53:16 +0000 (+0200)
Subject: rrl WIP: increase precision of cpu work estimate using RDTSC
X-Git-Url: http://git.ipfire.org/cgi-bin/gitweb.cgi?a=commitdiff_plain;h=refs%2Fenvironments%2Fdocs-develop-rrl-l16r8o%2Fdeployments%2F4077;p=thirdparty%2Fknot-resolver.git

rrl WIP: increase precision of cpu work estimate using RDTSC
---

diff --git a/daemon/rrl/api.h b/daemon/rrl/api.h
index c0aa1c16a..72c690b44 100644
--- a/daemon/rrl/api.h
+++ b/daemon/rrl/api.h
@@ -21,17 +21,32 @@ void kr_rrl_deinit(void);
 
 // TODO: reconsider `static inline` cases below
 
+#define USE_RDTSC  // TODO: determine somehow, probably on runtime
+#ifdef USE_RDTSC
+#include "x86intrin.h"
+#endif
+
+typedef struct {
+	uint64_t ns; /// monotonic nanoseconds, probably won't wrap
+#ifdef USE_RDTSC
+	uint64_t ticks; // TSC ticks, may be desynchronized on different cpus
+#endif
+} kr_rrl_stamp_t;
 
 typedef struct {
 	bool do_sample; /// whether to sample; could be important if _COARSE isn't available
 	int8_t is_accounting; /// whether currently accounting the time to someone; should be 0/1
 	union kr_sockaddr addr; /// request source (to which we account) or AF_UNSPEC if unknown yet
-	uint64_t stamp; /// monotonic nanoseconds, probably won't wrap
+	kr_rrl_stamp_t stamp; /// timestamp when accounting started
+#ifdef USE_RDTSC
+	kr_rrl_stamp_t total; /// sum of all accounted timediffs
+	uint64_t ns_res; // resolution of ns stamp
+#endif
 } kr_rrl_sample_state_t;
 extern kr_rrl_sample_state_t kr_rrl_sample_state;
 
 #include <time.h>
-static inline uint64_t get_stamp(void)
+static inline void get_stamp(kr_rrl_stamp_t *stamp)
 {
 	/* TODO:
 	    * think of strategies for non-Linux
@@ -48,10 +63,37 @@ static inline uint64_t get_stamp(void)
 
 	struct timespec now_ts = {0};
 	clock_gettime(CLOCK_MONOTONIC_COARSE, &now_ts);
-	return now_ts.tv_nsec + 1000*1000*1000 * (uint64_t)now_ts.tv_sec;
+
 	/* Note: kr_now() call would be similarly cheap and typically more precise,
 	 * but it gets updated exactly in moments when we don't want,
 	 * so the _COARSE stamp is be much better in this case. */
+	stamp->ns = now_ts.tv_nsec + 1000*1000*1000 * (uint64_t)now_ts.tv_sec;
+#ifdef USE_RDTSC
+	stamp->ticks = _rdtsc();
+#endif
+}
+static inline uint64_t get_stamp_diff_ns(kr_rrl_stamp_t *stamp_end, kr_rrl_stamp_t *stamp_begin) {
+	uint64_t ns = stamp_end->ns - stamp_begin->ns;
+#ifdef USE_RDTSC
+	if (stamp_end->ticks <= stamp_begin->ticks) {
+		return ns;
+	}
+	uint64_t ticks = stamp_end->ticks - stamp_begin->ticks;
+	kr_rrl_sample_state.total.ns += ns;
+	kr_rrl_sample_state.total.ticks += ticks;
+	uint64_t ticks_ns = ticks * ((double)kr_rrl_sample_state.total.ns / kr_rrl_sample_state.total.ticks);
+
+	if (kr_rrl_sample_state.ns_res == 0) {
+		struct timespec res = {0};
+		clock_getres(CLOCK_MONOTONIC_COARSE, &res);
+		kr_rrl_sample_state.ns_res = res.tv_nsec;
+		kr_log_notice(DEVEL, "%5.3f ms res\n", kr_rrl_sample_state.ns_res / 1000000.0); // TODO drop
+	}
+	if ((ns + kr_rrl_sample_state.ns_res >= ticks_ns) && (ticks_ns + kr_rrl_sample_state.ns_res >= ns)) {
+		return ticks_ns;
+	}
+#endif
+	return ns;
 }
 
 /// Start accounting work, if not doing it already.
@@ -60,7 +102,7 @@ static inline void kr_rrl_sample_start(void)
 	if (!kr_rrl_sample_state.do_sample) return;
 	kr_assert(!kr_rrl_sample_state.is_accounting);
 	++kr_rrl_sample_state.is_accounting;
-	kr_rrl_sample_state.stamp = get_stamp();
+	get_stamp(&kr_rrl_sample_state.stamp);
 	kr_rrl_sample_state.addr.ip.sa_family = AF_UNSPEC;
 }
 
@@ -97,12 +139,15 @@ static inline void kr_rrl_sample_stop(void)
 	if (kr_fails_assert(kr_rrl_sample_state.is_accounting > 0)) return; // weird
 	if (--kr_rrl_sample_state.is_accounting) return;
 
-	const uint64_t elapsed = get_stamp() - kr_rrl_sample_state.stamp;
-	if (!elapsed) return;
+	kr_rrl_stamp_t stamp;
+	get_stamp(&stamp);
+	const uint64_t elapsed = get_stamp_diff_ns(&stamp, &kr_rrl_sample_state.stamp);
+	const uint64_t elapsed_coarse = stamp.ns - kr_rrl_sample_state.stamp.ns;  // TODO drop
+	if ((elapsed < 1000) && !elapsed_coarse) return;
 
 	// we accounted something
 	// FIXME: drop the log, add KRU, etc.
-	kr_log_notice(DEVEL, "%5.1f ms for %s\n", elapsed / 1000000.0,
+	kr_log_notice(DEVEL, "%5.3f ms (%5.3f ms _COARSE) for %s\n", elapsed / 1000000.0, elapsed_coarse / 1000000.0,
 			kr_straddr(&kr_rrl_sample_state.addr.ip));
 	// TODO: some queries of internal origin have suspicioiusly high numbers.
 	// We won't be really accounting those, but it might suggest some other issue.