[PATCH] tracing: Use trace_clock_local() for looping in preemptirq_delay_test.c

[PATCH] tracing: Use trace_clock_local() for looping in preemptirq_delay_test.c

[Steven Rostedt]

From: "Steven Rostedt (VMware)" <rostedt@goodmis.org>

The preemptirq_delay_test module is used for the ftrace selftest code that
tests the latency tracers. The problem is that it uses ktime for the delay
loop, and then checks the tracer to see if the delay loop is caught, but the
tracer uses trace_clock_local() which uses various different other clocks to
measure the latency. As ktime uses the clock cycles, and the code then
converts that to nanoseconds, it causes rounding errors, and the preemptirq
latency tests are failing due to being off by 1 (it expects to see a delay
of 500000 us, but the delay is only 499999 us). This is happening due to a
rounding error in the ktime (which is totally legit). The purpose of the
test is to see if it can catch the delay, not to test the accuracy between
trace_clock_local() and ktime_get(). Best to use apples to apples, and have
the delay loop use the same clock as the latency tracer does.

Cc: Joel Fernandes (Google) <joel@joelfernandes.org>
Cc: stable@vger.kernel.org
Fixes: f96e8577da102 ("lib: Add module for testing preemptoff/irqsoff latency tracers")
Signed-off-by: Steven Rostedt (VMware) <rostedt@goodmis.org>
---
 kernel/trace/preemptirq_delay_test.c | 10 +++++-----
 1 file changed, 5 insertions(+), 5 deletions(-)

diff --git a/kernel/trace/preemptirq_delay_test.c b/kernel/trace/preemptirq_delay_test.c
index f704390db9fc..d8765c952fab 100644
--- a/kernel/trace/preemptirq_delay_test.c
+++ b/kernel/trace/preemptirq_delay_test.c
@@ -5,12 +5,12 @@
  * Copyright (C) 2018 Joel Fernandes (Google) <joel@joelfernandes.org>
  */
 
+#include <linux/trace_clock.h>
 #include <linux/delay.h>
 #include <linux/interrupt.h>
 #include <linux/irq.h>
 #include <linux/kernel.h>
 #include <linux/kthread.h>
-#include <linux/ktime.h>
 #include <linux/module.h>
 #include <linux/printk.h>
 #include <linux/string.h>
@@ -25,13 +25,13 @@ MODULE_PARM_DESC(test_mode, "Mode of the test such as preempt or irq (default ir
 
 static void busy_wait(ulong time)
 {
-	ktime_t start, end;
-	start = ktime_get();
+	u64 start, end;
+	start = trace_clock_local();
 	do {
-		end = ktime_get();
+		end = trace_clock_local();
 		if (kthread_should_stop())
 			break;
-	} while (ktime_to_ns(ktime_sub(end, start)) < (time * 1000));
+	} while ((end - start) < (time * 1000));
 }
 
 static int preemptirq_delay_run(void *data)
-- 
2.13.6

Re: [PATCH] tracing: Use trace_clock_local() for looping in preemptirq_delay_test.c

[Steven Rostedt]

Joel,

Can you Ack this patch. I want to push it upstream as without it, your
preemptirq latency test fails on one of my boxes. Causing my automated
tests to fail (I get by with removing the test from the automation).

-- Steve


On Tue, 16 Oct 2018 09:40:05 -0400
Steven Rostedt <rostedt@goodmis.org> wrote:

> From: "Steven Rostedt (VMware)" <rostedt@goodmis.org>
> 
> The preemptirq_delay_test module is used for the ftrace selftest code that
> tests the latency tracers. The problem is that it uses ktime for the delay
> loop, and then checks the tracer to see if the delay loop is caught, but the
> tracer uses trace_clock_local() which uses various different other clocks to
> measure the latency. As ktime uses the clock cycles, and the code then
> converts that to nanoseconds, it causes rounding errors, and the preemptirq
> latency tests are failing due to being off by 1 (it expects to see a delay
> of 500000 us, but the delay is only 499999 us). This is happening due to a
> rounding error in the ktime (which is totally legit). The purpose of the
> test is to see if it can catch the delay, not to test the accuracy between
> trace_clock_local() and ktime_get(). Best to use apples to apples, and have
> the delay loop use the same clock as the latency tracer does.
> 
> Cc: Joel Fernandes (Google) <joel@joelfernandes.org>
> Cc: stable@vger.kernel.org
> Fixes: f96e8577da102 ("lib: Add module for testing preemptoff/irqsoff latency tracers")
> Signed-off-by: Steven Rostedt (VMware) <rostedt@goodmis.org>
> ---
>  kernel/trace/preemptirq_delay_test.c | 10 +++++-----
>  1 file changed, 5 insertions(+), 5 deletions(-)
> 
> diff --git a/kernel/trace/preemptirq_delay_test.c b/kernel/trace/preemptirq_delay_test.c
> index f704390db9fc..d8765c952fab 100644
> --- a/kernel/trace/preemptirq_delay_test.c
> +++ b/kernel/trace/preemptirq_delay_test.c
> @@ -5,12 +5,12 @@
>   * Copyright (C) 2018 Joel Fernandes (Google) <joel@joelfernandes.org>
>   */
>  
> +#include <linux/trace_clock.h>
>  #include <linux/delay.h>
>  #include <linux/interrupt.h>
>  #include <linux/irq.h>
>  #include <linux/kernel.h>
>  #include <linux/kthread.h>
> -#include <linux/ktime.h>
>  #include <linux/module.h>
>  #include <linux/printk.h>
>  #include <linux/string.h>
> @@ -25,13 +25,13 @@ MODULE_PARM_DESC(test_mode, "Mode of the test such as preempt or irq (default ir
>  
>  static void busy_wait(ulong time)
>  {
> -	ktime_t start, end;
> -	start = ktime_get();
> +	u64 start, end;
> +	start = trace_clock_local();
>  	do {
> -		end = ktime_get();
> +		end = trace_clock_local();
>  		if (kthread_should_stop())
>  			break;
> -	} while (ktime_to_ns(ktime_sub(end, start)) < (time * 1000));
> +	} while ((end - start) < (time * 1000));
>  }
>  
>  static int preemptirq_delay_run(void *data)

Re: [PATCH] tracing: Use trace_clock_local() for looping in preemptirq_delay_test.c

[Joel Fernandes]

On Tue, Oct 16, 2018 at 09:42:04AM -0400, Steven Rostedt wrote:
> 
> Joel,
> 
> Can you Ack this patch. I want to push it upstream as without it, your
> preemptirq latency test fails on one of my boxes. Causing my automated
> tests to fail (I get by with removing the test from the automation).
> 
> -- Steve
> 
> 
> On Tue, 16 Oct 2018 09:40:05 -0400
> Steven Rostedt <rostedt@goodmis.org> wrote:
> 
> > From: "Steven Rostedt (VMware)" <rostedt@goodmis.org>
> > 
> > The preemptirq_delay_test module is used for the ftrace selftest code that
> > tests the latency tracers. The problem is that it uses ktime for the delay
> > loop, and then checks the tracer to see if the delay loop is caught, but the
> > tracer uses trace_clock_local() which uses various different other clocks to
> > measure the latency. As ktime uses the clock cycles, and the code then
> > converts that to nanoseconds, it causes rounding errors, and the preemptirq
> > latency tests are failing due to being off by 1 (it expects to see a delay
> > of 500000 us, but the delay is only 499999 us). This is happening due to a
> > rounding error in the ktime (which is totally legit). The purpose of the
> > test is to see if it can catch the delay, not to test the accuracy between
> > trace_clock_local() and ktime_get(). Best to use apples to apples, and have
> > the delay loop use the same clock as the latency tracer does.
> > 
> > Cc: Joel Fernandes (Google) <joel@joelfernandes.org>
> > Cc: stable@vger.kernel.org
> > Fixes: f96e8577da102 ("lib: Add module for testing preemptoff/irqsoff latency tracers")
> > Signed-off-by: Steven Rostedt (VMware) <rostedt@goodmis.org>

Looks good to me!

Acked-by: Joel Fernandes (Google) <joel@joelfernandes.org>

thanks,

 - Joel