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 <[email protected]>
Cc: Steven Rostedt (VMware) <[email protected]>
---
v2: Tell the user what's happening and what they can do to correct it.
---
kernel/trace/trace.c | 19 +++++++++++++++++++
1 file changed, 19 insertions(+)
diff --git a/kernel/trace/trace.c b/kernel/trace/trace.c
index 13baf85b27d8..7c155fa879e1 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,21 @@ __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()) {
+ printk(KERN_WARNING
+ "Unstable clock detected, switching default tracing clock to \"global\"\n"
+ "If you want to keep using the local clock, then add:\n"
+ " \"trace_clock=local\"\n"
+ "on the kernel command line\n");
+ tracing_set_clock(&global_trace, "global");
+ }
+
+ return 0;
+}
+late_initcall_sync(tracing_set_default_clock);
+#endif
--
2.16.3
Mention the alternative of adding trace_clock=global to the kernel
command line when we detect that we've used an unstable clock across a
suspend/resume cycle.
Signed-off-by: Chris Wilson <[email protected]>
Cc: Steven Rostedt <[email protected]>
---
kernel/trace/ring_buffer.c | 3 ++-
1 file changed, 2 insertions(+), 1 deletion(-)
diff --git a/kernel/trace/ring_buffer.c b/kernel/trace/ring_buffer.c
index dcf1c4dd3efe..88098d7fac06 100644
--- a/kernel/trace/ring_buffer.c
+++ b/kernel/trace/ring_buffer.c
@@ -2637,7 +2637,8 @@ rb_handle_timestamp(struct ring_buffer_per_cpu *cpu_buffer,
sched_clock_stable() ? "" :
"If you just came from a suspend/resume,\n"
"please switch to the trace global clock:\n"
- " echo global > /sys/kernel/debug/tracing/trace_clock\n");
+ " echo global > /sys/kernel/debug/tracing/trace_clock\n"
+ "or add trace_clock=global to the kernel command line\n");
info->add_timestamp = 1;
}
--
2.16.3
On Fri, 30 Mar 2018 16:01:31 +0100
Chris Wilson <[email protected]> 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
>
> Signed-off-by: Chris Wilson <[email protected]>
> Cc: Steven Rostedt (VMware) <[email protected]>
> ---
> v2: Tell the user what's happening and what they can do to correct it.
>
Thanks, I pulled them in. I'll start testing them before I post to git.
-- Steve
Quoting Chris Wilson (2018-03-30 16:01:31)
> 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 <[email protected]>
> Cc: Steven Rostedt (VMware) <[email protected]>
> ---
> v2: Tell the user what's happening and what they can do to correct it.
> ---
> kernel/trace/trace.c | 19 +++++++++++++++++++
> 1 file changed, 19 insertions(+)
>
> diff --git a/kernel/trace/trace.c b/kernel/trace/trace.c
> index 13baf85b27d8..7c155fa879e1 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,21 @@ __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()) {
Oh flip, I reversed the logic from v1.
I was going to do an early return:
if (trace_boot_clock || sched_clock_stable())
return;
to shift the message to the left slightly, at left it half way.
(I was wondering why CI didn't show the same results as v1!)
-Chris
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 <[email protected]>
Cc: Steven Rostedt (VMware) <[email protected]>
---
v2: Tell the user what's happening and what they can do to correct it.
v3: Restore the correct logic to switch only if the default trace clock
(no override) is found to be *not* stable.
---
kernel/trace/trace.c | 19 +++++++++++++++++++
1 file changed, 19 insertions(+)
diff --git a/kernel/trace/trace.c b/kernel/trace/trace.c
index 13baf85b27d8..a1810b053f65 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,21 @@ __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()) {
+ printk(KERN_WARNING
+ "Unstable clock detected, switching default tracing clock to \"global\"\n"
+ "If you want to keep using the local clock, then add:\n"
+ " \"trace_clock=local\"\n"
+ "on the kernel command line\n");
+ tracing_set_clock(&global_trace, "global");
+ }
+
+ return 0;
+}
+late_initcall_sync(tracing_set_default_clock);
+#endif
--
2.16.3
Can you add a patch on top. I already added your patch to my tree.
See branch ftrace/core
git://git.kernel.org/pub/scm/linux/kernel/git/rostedt/linux-trace.git
-- Steve
On April 4, 2018 4:51:02 PM EDT, Chris Wilson <[email protected]> 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
>
>Signed-off-by: Chris Wilson <[email protected]>
>Cc: Steven Rostedt (VMware) <[email protected]>
>---
>v2: Tell the user what's happening and what they can do to correct it.
>v3: Restore the correct logic to switch only if the default trace clock
>(no override) is found to be *not* stable.
>---
> kernel/trace/trace.c | 19 +++++++++++++++++++
> 1 file changed, 19 insertions(+)
>
>diff --git a/kernel/trace/trace.c b/kernel/trace/trace.c
>index 13baf85b27d8..a1810b053f65 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,21 @@ __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()) {
>+ printk(KERN_WARNING
>+ "Unstable clock detected, switching default tracing clock to
>\"global\"\n"
>+ "If you want to keep using the local clock, then add:\n"
>+ " \"trace_clock=local\"\n"
>+ "on the kernel command line\n");
>+ tracing_set_clock(&global_trace, "global");
>+ }
>+
>+ return 0;
>+}
>+late_initcall_sync(tracing_set_default_clock);
>+#endif
--
Sent from my Android device with K-9 Mail. Please excuse my brevity.
In commit 932066a15335 ("tracing: Default to using trace_global_clock if
sched_clock is unstable"), the logic for deciding to override the
default clock if unstable was reversed from the earlier posting. I was
trying to reduce the width of the message by using an early return
rather than a if-block, but reverted back to using the if-block and
accidentally left the predicate inverted.
Fixes: 932066a15335 ("tracing: Default to using trace_global_clock if sched_clock is unstable")
Signed-off-by: Chris Wilson <[email protected]>
Cc: Steven Rostedt (VMware) <[email protected]>
---
kernel/trace/trace.c | 2 +-
1 file changed, 1 insertion(+), 1 deletion(-)
diff --git a/kernel/trace/trace.c b/kernel/trace/trace.c
index 0f47e653ffd8..e18e69183c9a 100644
--- a/kernel/trace/trace.c
+++ b/kernel/trace/trace.c
@@ -8602,7 +8602,7 @@ late_initcall_sync(clear_boot_tracer);
__init static int tracing_set_default_clock(void)
{
/* sched_clock_stable() is determined in late_initcall */
- if (trace_boot_clock || sched_clock_stable()) {
+ if (!trace_boot_clock && !sched_clock_stable()) {
printk(KERN_WARNING
"Unstable clock detected, switching default tracing clock to \"global\"\n"
"If you want to keep using the local clock, then add:\n"
--
2.16.3
On Wed, 4 Apr 2018 22:24:50 +0100
Chris Wilson <[email protected]> wrote:
> In commit 932066a15335 ("tracing: Default to using trace_global_clock if
> sched_clock is unstable"), the logic for deciding to override the
> default clock if unstable was reversed from the earlier posting. I was
> trying to reduce the width of the message by using an early return
> rather than a if-block, but reverted back to using the if-block and
> accidentally left the predicate inverted.
Hey, the inversion found some issues with global clock interacting with
lockdep, so it was a good bug to have ;-)
-- Steve