[PATCH v3] tracing/hwlat: Do the latency calculations in nanoseconds

[PATCH v3] tracing/hwlat: Do the latency calculations in nanoseconds

[Wenwu Hou]

tr->max_latency is expected to hold nanoseconds: tracing_max_lat_read()
converts it with nsecs_to_usecs() to print the usecs documented in
hwlat_detector.rst, and the other latency tracers store nanoseconds there
too.

Do all the latency calculations in nanoseconds instead, and only convert
the durations to microseconds when recording the hwlat event.

This also makes the backward-clock error paths reachable.
Previously, time_to_us() passed the delta through unsigned div_u64(),
so a negative delta became a positive value after division. These
error paths jumped to out without clearing trace_hwlat_callback_enabled.
Fix this as well.

Fixes: e7c15cd8a1133 ("tracing: Added hardware latency tracer")
Fixes: 7b2c86250122d ("tracing: Add NMI tracing in hwlat detector")
Suggested-by: Steven Rostedt <rostedt@goodmis.org>
Signed-off-by: Wenwu Hou <hwenwur@gmail.com>
---
Tested in a 4-vCPU KVM guest; all three hwlat modes worked as expected.

v2: https://lore.kernel.org/linux-trace-kernel/avW1t81WLQ9YrylB@gmail.com/T/#t

Changes in v3:
- Fix trace_hwlat_callback_enabled remaining set on the backward-clock
  error paths, as pointed out by Sashiko AI.
- Add a Fixes tag for the commit that introduced NMI tracing.

Changes in v2:
- Perform the latency calculations in nanoseconds instead of converting
  only the maximum latency, as suggested by Steven Rostedt.
- Convert the durations to microseconds only when recording the hwlat event
  to preserve the existing event format.

 kernel/trace/trace_hwlat.c | 28 +++++++++++++---------------
 1 file changed, 13 insertions(+), 15 deletions(-)

diff --git a/kernel/trace/trace_hwlat.c b/kernel/trace/trace_hwlat.c
index 65e184d800ff1..ed1199a6a9e8f 100644
--- a/kernel/trace/trace_hwlat.c
+++ b/kernel/trace/trace_hwlat.c
@@ -203,14 +203,12 @@ static int get_sample(void)
 	time_type start, t1, t2, last_t2;
 	s64 diff, outer_diff, total, last_total = 0;
 	u64 sample = 0;
-	u64 sample_width = READ_ONCE(hwlat_data.sample_width);
+	u64 sample_width = READ_ONCE(hwlat_data.sample_width) * NSEC_PER_USEC;
 	u64 thresh = tracing_thresh;
 	u64 outer_sample = 0;
-	int ret = -1;
+	int ret = 0;
 	unsigned int count = 0;
 
-	do_div(thresh, NSEC_PER_USEC); /* modifies interval value */
-
 	kdata->nmi_total_ts = 0;
 	kdata->nmi_count = 0;
 	/* Make sure NMIs see this first */
@@ -229,18 +227,19 @@ static int get_sample(void)
 
 		if (time_u64(last_t2)) {
 			/* Check the delta from outer loop (t2 to next t1) */
-			outer_diff = time_to_us(time_sub(t1, last_t2));
+			outer_diff = time_sub(t1, last_t2);
 			/* This shouldn't happen */
 			if (outer_diff < 0) {
 				hwlat_err(BANNER "time running backwards\n");
-				goto out;
+				ret = -1;
+				break;
 			}
 			if (outer_diff > outer_sample)
 				outer_sample = outer_diff;
 		}
 		last_t2 = t2;
 
-		total = time_to_us(time_sub(t2, start)); /* sample width */
+		total = time_sub(t2, start); /* sample width */
 
 		/* Check for possible overflows */
 		if (total < last_total) {
@@ -250,7 +249,7 @@ static int get_sample(void)
 		last_total = total;
 
 		/* This checks the inner loop (t1 to t2) */
-		diff = time_to_us(time_sub(t2, t1));     /* current diff */
+		diff = time_sub(t2, t1);     /* current diff */
 
 		if (diff > thresh || outer_diff > thresh) {
 			if (!count)
@@ -261,7 +260,8 @@ static int get_sample(void)
 		/* This shouldn't happen */
 		if (diff < 0) {
 			hwlat_err(BANNER "time running backwards\n");
-			goto out;
+			ret = -1;
+			break;
 		}
 
 		if (diff > sample)
@@ -273,7 +273,8 @@ static int get_sample(void)
 	trace_hwlat_callback_enabled = false;
 	barrier(); /* Make sure nmi_total_ts is no longer updated */
 
-	ret = 0;
+	if (ret)
+		return ret;
 
 	/* If we exceed the threshold value, we have found a hardware latency */
 	if (sample > thresh || outer_sample > thresh) {
@@ -286,8 +287,8 @@ static int get_sample(void)
 			do_div(kdata->nmi_total_ts, NSEC_PER_USEC);
 
 		s.seqnum = atomic64_inc_return(&hwlat_data.count);
-		s.duration = sample;
-		s.outer_duration = outer_sample;
+		s.duration = time_to_us(sample);
+		s.outer_duration = time_to_us(outer_sample);
 		s.nmi_total_ts = kdata->nmi_total_ts;
 		s.nmi_count = kdata->nmi_count;
 		s.count = count;
@@ -301,8 +302,6 @@ static int get_sample(void)
 			latency_fsnotify(tr);
 		}
 	}
-
-out:
 	return ret;
 }
 
@@ -839,7 +838,6 @@ static int hwlat_tracer_init(struct trace_array *tr)
 	tr->max_latency = 0;
 	save_tracing_thresh = tracing_thresh;
 
-	/* tracing_thresh is in nsecs, we speak in usecs */
 	if (!tracing_thresh)
 		tracing_thresh = last_tracing_thresh;
 
-- 
2.43.0