[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

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

[sashiko-bot]

Thank you for your contribution! Sashiko AI review found 1 potential
issue to consider:
- [Medium] tracing/hwlat: broken backward-clock check order in
  get_sample()
--

commit e1ff23abe0f3e347e9f8fcfd5d38bde48773198a
Author: Wenwu Hou <hwenwur@gmail.com>

tracing/hwlat: Do the latency calculations in nanoseconds

This commit changes get_sample() to compute latency deltas in nanoseconds
and fixes the backward-clock error paths to clear
trace_hwlat_callback_enabled before returning.

> diff --git a/kernel/trace/trace_hwlat.c b/kernel/trace/trace_hwlat.c
> index 3fe274b84f1c2..d8540c24b1ca3 100644
> --- a/kernel/trace/trace_hwlat.c
> +++ b/kernel/trace/trace_hwlat.c
> @@ -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;
>  		}

[Severity: Medium]
Can a backward clock jump between t1 and t2 bypass the diff < 0 check and
record uninitialized stack memory in s.timestamp?

Because total < last_total is checked before diff = time_sub(t2, t1), any
backward jump between t1 and t2 where t2 drops below the previous t2 (or
below start on the first iteration) trips total < last_total first.  That
logs "Time total overflowed" instead of "time running backwards" and breaks
out of the loop with ret == 0 before ktime_get_real_ts64(&s.timestamp) runs.
If outer_diff exceeded thresh earlier in the same iteration while count was
still 0, outer_sample > thresh then causes trace_hwlat_sample(&s) to copy
an uninitialized s.timestamp from the stack into the ring buffer.

Also, diff > thresh is evaluated before diff < 0, which converts a negative
s64 diff to a large u64 when comparing against unsigned u64 thresh.

-- 
Sashiko AI review · https://sashiko.dev/#/patchset/20261113094918.2402297-1-hwenwur@gmail.com?part=1