2018-10-16 13:41:05

by Steven Rostedt

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

From: "Steven Rostedt (VMware)" <[email protected]>

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) <[email protected]>
Cc: [email protected]
Fixes: f96e8577da102 ("lib: Add module for testing preemptoff/irqsoff latency tracers")
Signed-off-by: Steven Rostedt (VMware) <[email protected]>
---
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) <[email protected]>
*/

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



2018-10-16 13:43:35

by Steven Rostedt

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


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 <[email protected]> wrote:

> From: "Steven Rostedt (VMware)" <[email protected]>
>
> 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) <[email protected]>
> Cc: [email protected]
> Fixes: f96e8577da102 ("lib: Add module for testing preemptoff/irqsoff latency tracers")
> Signed-off-by: Steven Rostedt (VMware) <[email protected]>
> ---
> 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) <[email protected]>
> */
>
> +#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)


2018-10-16 20:03:52

by Joel Fernandes

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

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 <[email protected]> wrote:
>
> > From: "Steven Rostedt (VMware)" <[email protected]>
> >
> > 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) <[email protected]>
> > Cc: [email protected]
> > Fixes: f96e8577da102 ("lib: Add module for testing preemptoff/irqsoff latency tracers")
> > Signed-off-by: Steven Rostedt (VMware) <[email protected]>

Looks good to me!

Acked-by: Joel Fernandes (Google) <[email protected]>

thanks,

- Joel