diff mbox

trace: Default to using trace_global_clock if sched_clock is unstable

Message ID 20180329222557.6274-1-chris@chris-wilson.co.uk (mailing list archive)
State New, archived
Headers show

Commit Message

Chris Wilson March 29, 2018, 10:25 p.m. UTC
Across suspend, we may see a very large drift in timestamps if the sched
clock is unstable, prompting the global trace's ringbuffer code to warn
and suggest switching to the global clock. Preempt this request by
detecting when the sched clock is unstable (determined during
late_initcall) and automatically switching the default clock over to
trace_global_clock.

This should prevent requiring user interaction to resolve warnings such
as:

    Delta way too big! 18446743856563626466 ts=18446744054496180323 write stamp = 197932553857
    If you just came from a suspend/resume,
    please switch to the trace global clock:
    echo global > /sys/kernel/debug/tracing/trace_clock

Signed-off-by: Chris Wilson <chris@chris-wilson.co.uk>
Cc: Steven Rostedt (VMware) <rostedt@goodmis.org>
---
 kernel/trace/trace.c | 13 +++++++++++++
 1 file changed, 13 insertions(+)

Comments

Steven Rostedt March 30, 2018, 1:48 p.m. UTC | #1
On Thu, 29 Mar 2018 23:25:57 +0100
Chris Wilson <chris@chris-wilson.co.uk> wrote:

> Across suspend, we may see a very large drift in timestamps if the sched
> clock is unstable, prompting the global trace's ringbuffer code to warn
> and suggest switching to the global clock. Preempt this request by
> detecting when the sched clock is unstable (determined during
> late_initcall) and automatically switching the default clock over to
> trace_global_clock.
> 
> This should prevent requiring user interaction to resolve warnings such
> as:
> 
>     Delta way too big! 18446743856563626466 ts=18446744054496180323 write stamp = 197932553857
>     If you just came from a suspend/resume,
>     please switch to the trace global clock:
>     echo global > /sys/kernel/debug/tracing/trace_clock

global clock has a much higher overhead than the local clock. I rather
not have it automatically switch even when there's no stable TSC. That
will be annoying to myself as I have boxes that this would switch on
and I prefer to keep the local clock.

One can also decide the clock with the kernel command line. Should we
update that message to also say:

  Or set the global clock via the kernel command line with
  "trace_clock=global"

?

-- Steve


> 
> Signed-off-by: Chris Wilson <chris@chris-wilson.co.uk>
> Cc: Steven Rostedt (VMware) <rostedt@goodmis.org>
> ---
>  kernel/trace/trace.c | 13 +++++++++++++
>  1 file changed, 13 insertions(+)
> 
> diff --git a/kernel/trace/trace.c b/kernel/trace/trace.c
> index 13baf85b27d8..c5462513db90 100644
> --- a/kernel/trace/trace.c
> +++ b/kernel/trace/trace.c
> @@ -41,6 +41,7 @@
>  #include <linux/nmi.h>
>  #include <linux/fs.h>
>  #include <linux/trace.h>
> +#include <linux/sched/clock.h>
>  #include <linux/sched/rt.h>
>  
>  #include "trace.h"
> @@ -8505,3 +8506,15 @@ __init static int clear_boot_tracer(void)
>  
>  fs_initcall(tracer_init_tracefs);
>  late_initcall_sync(clear_boot_tracer);
> +
> +#ifdef CONFIG_HAVE_UNSTABLE_SCHED_CLOCK
> +__init static int tracing_set_default_clock(void)
> +{
> +	/* sched_clock_stable() is determined in late_initcall */
> +	if (!trace_boot_clock && !sched_clock_stable())
> +		tracing_set_clock(&global_trace, "global");
> +
> +	return 0;
> +}
> +late_initcall_sync(tracing_set_default_clock);
> +#endif
Chris Wilson March 30, 2018, 2:07 p.m. UTC | #2
Quoting Steven Rostedt (2018-03-30 14:48:45)
> On Thu, 29 Mar 2018 23:25:57 +0100
> Chris Wilson <chris@chris-wilson.co.uk> wrote:
> 
> > Across suspend, we may see a very large drift in timestamps if the sched
> > clock is unstable, prompting the global trace's ringbuffer code to warn
> > and suggest switching to the global clock. Preempt this request by
> > detecting when the sched clock is unstable (determined during
> > late_initcall) and automatically switching the default clock over to
> > trace_global_clock.
> > 
> > This should prevent requiring user interaction to resolve warnings such
> > as:
> > 
> >     Delta way too big! 18446743856563626466 ts=18446744054496180323 write stamp = 197932553857
> >     If you just came from a suspend/resume,
> >     please switch to the trace global clock:
> >     echo global > /sys/kernel/debug/tracing/trace_clock
> 
> global clock has a much higher overhead than the local clock. I rather
> not have it automatically switch even when there's no stable TSC. That
> will be annoying to myself as I have boxes that this would switch on
> and I prefer to keep the local clock.

My counter argument would be that it comes as a bit of a shock to the
user to find out their debugging session was rendered invalid because
the tracer chose to use a clock that it knew was unsuitable for the job. :)

> One can also decide the clock with the kernel command line. Should we
> update that message to also say:
> 
>   Or set the global clock via the kernel command line with
>   "trace_clock=global"
> 
> ?

Sure, I was mainly floating the idea of trying to pick sensible
defaults. Unstable clocks are quite rare nowadays, the ones we have in
the lab are a pair of Core2 Duo.
-Chris
Steven Rostedt March 30, 2018, 2:37 p.m. UTC | #3
On Fri, 30 Mar 2018 15:07:53 +0100
Chris Wilson <chris@chris-wilson.co.uk> wrote:


> Sure, I was mainly floating the idea of trying to pick sensible
> defaults. Unstable clocks are quite rare nowadays, the ones we have in
> the lab are a pair of Core2 Duo.

I still have a box too ;-)

I'm not so against having global_clock become default if the TSC is
unstable. But there needs to be a printk warning (not a WARN, but
something like: 

 Warning: TSC unstable, switching tracing_clock default to "global"
 If you want to keep local, then add "trace_clock=local" on the
  kernel command line.

-- Steve
diff mbox

Patch

diff --git a/kernel/trace/trace.c b/kernel/trace/trace.c
index 13baf85b27d8..c5462513db90 100644
--- a/kernel/trace/trace.c
+++ b/kernel/trace/trace.c
@@ -41,6 +41,7 @@ 
 #include <linux/nmi.h>
 #include <linux/fs.h>
 #include <linux/trace.h>
+#include <linux/sched/clock.h>
 #include <linux/sched/rt.h>
 
 #include "trace.h"
@@ -8505,3 +8506,15 @@  __init static int clear_boot_tracer(void)
 
 fs_initcall(tracer_init_tracefs);
 late_initcall_sync(clear_boot_tracer);
+
+#ifdef CONFIG_HAVE_UNSTABLE_SCHED_CLOCK
+__init static int tracing_set_default_clock(void)
+{
+	/* sched_clock_stable() is determined in late_initcall */
+	if (!trace_boot_clock && !sched_clock_stable())
+		tracing_set_clock(&global_trace, "global");
+
+	return 0;
+}
+late_initcall_sync(tracing_set_default_clock);
+#endif