[PATCH] trace: adding unstable sched clock note to the warning

[PATCH] trace: adding unstable sched clock note to the warning

[Jiri Olsa]

hi,

warning "Delta way too big" warning might appear on a system with
unstable shed clock right after the system is resumed and tracing
was enabled during the suspend.

Since it's not realy bug, and the unstable sched clock is working
fast and reliable otherwise, Steven suggested to keep using the
sched clock in any case and just to make note in the warning itself.

wbr,
jirka


Signed-off-by: Jiri Olsa <jolsa@redhat.com>
---
 kernel/trace/ring_buffer.c |    8 ++++++--
 1 files changed, 6 insertions(+), 2 deletions(-)

diff --git a/kernel/trace/ring_buffer.c b/kernel/trace/ring_buffer.c
index bd1c35a..7739893 100644
--- a/kernel/trace/ring_buffer.c
+++ b/kernel/trace/ring_buffer.c
@@ -2163,10 +2163,14 @@ rb_reserve_next_event(struct ring_buffer *buffer,
 		delta = diff;
 		if (unlikely(test_time_stamp(delta))) {
 			WARN_ONCE(delta > (1ULL << 59),
-				  KERN_WARNING "Delta way too big! %llu ts=%llu write stamp = %llu\n",
+				  KERN_WARNING "Delta way too big! %llu ts=%llu write stamp = %llu\n%s",
 				  (unsigned long long)delta,
 				  (unsigned long long)ts,
-				  (unsigned long long)cpu_buffer->write_stamp);
+				  (unsigned long long)cpu_buffer->write_stamp,
+				  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");
 			add_timestamp = 1;
 		}
 	}

[tip:perf/core] tracing: Add unstable sched clock note to the warning

[tip-bot for Jiri Olsa]

Commit-ID:  5e38ca8f3ea423442eaafe1b7e206084aa38120a
Gitweb:     http://git.kernel.org/tip/5e38ca8f3ea423442eaafe1b7e206084aa38120a
Author:     Jiri Olsa <jolsa@redhat.com>
AuthorDate: Wed, 2 Feb 2011 13:28:18 +0100
Committer:  Steven Rostedt <rostedt@goodmis.org>
CommitDate: Tue, 8 Feb 2011 11:57:22 -0500

tracing: Add unstable sched clock note to the warning

The warning "Delta way too big" warning might appear on a system with
unstable shed clock right after the system is resumed and tracing
was enabled during the suspend.

Since it's not realy bug, and the unstable sched clock is working
fast and reliable otherwise, Steven suggested to keep using the
sched clock in any case and just to make note in the warning itself.

Signed-off-by: Jiri Olsa <jolsa@redhat.com>
LKML-Reference: <1296649698-6003-1-git-send-email-jolsa@redhat.com>
Signed-off-by: Steven Rostedt <rostedt@goodmis.org>
---
 kernel/trace/ring_buffer.c |    8 ++++++--
 1 files changed, 6 insertions(+), 2 deletions(-)

diff --git a/kernel/trace/ring_buffer.c b/kernel/trace/ring_buffer.c
index bd1c35a..7739893 100644
--- a/kernel/trace/ring_buffer.c
+++ b/kernel/trace/ring_buffer.c
@@ -2163,10 +2163,14 @@ rb_reserve_next_event(struct ring_buffer *buffer,
 		delta = diff;
 		if (unlikely(test_time_stamp(delta))) {
 			WARN_ONCE(delta > (1ULL << 59),
-				  KERN_WARNING "Delta way too big! %llu ts=%llu write stamp = %llu\n",
+				  KERN_WARNING "Delta way too big! %llu ts=%llu write stamp = %llu\n%s",
 				  (unsigned long long)delta,
 				  (unsigned long long)ts,
-				  (unsigned long long)cpu_buffer->write_stamp);
+				  (unsigned long long)cpu_buffer->write_stamp,
+				  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");
 			add_timestamp = 1;
 		}
 	}

Re: [tip:perf/core] tracing: Add unstable sched clock note to the warning

[Steven Rostedt]

On Thu, 2011-02-17 at 15:00 +0000, tip-bot for Jiri Olsa wrote:
> Commit-ID:  5e38ca8f3ea423442eaafe1b7e206084aa38120a
> Gitweb:     http://git.kernel.org/tip/5e38ca8f3ea423442eaafe1b7e206084aa38120a
> Author:     Jiri Olsa <jolsa@redhat.com>
> AuthorDate: Wed, 2 Feb 2011 13:28:18 +0100
> Committer:  Steven Rostedt <rostedt@goodmis.org>
> CommitDate: Tue, 8 Feb 2011 11:57:22 -0500
> 
> tracing: Add unstable sched clock note to the warning
> 
> The warning "Delta way too big" warning might appear on a system with
> unstable shed clock right after the system is resumed and tracing
> was enabled during the suspend.
> 
> Since it's not realy bug, and the unstable sched clock is working
> fast and reliable otherwise, Steven suggested to keep using the
> sched clock in any case and just to make note in the warning itself.
> 


Peter Zijlstra just informed me on IRC that the commit:

cd7240c0b900eb6d690ccee088a6c9b46dae815a
x86, tsc, sched: Recompute cyc2ns_offset's during resume from sleep
states

Prevents the clock from going backwards triggering the warn on. If this
is the case, I think we can revert this patch.

I'll wait on the original reporters of the bug to find out. If the clock
does not go backwards when the above commit is applied, then this patch
is not needed.

If this is the case, do you want me to rebase without it, or should we
just revert it?

-- Steve

> Signed-off-by: Jiri Olsa <jolsa@redhat.com>
> LKML-Reference: <1296649698-6003-1-git-send-email-jolsa@redhat.com>
> Signed-off-by: Steven Rostedt <rostedt@goodmis.org>
> ---
>  kernel/trace/ring_buffer.c |    8 ++++++--
>  1 files changed, 6 insertions(+), 2 deletions(-)
> 
> diff --git a/kernel/trace/ring_buffer.c b/kernel/trace/ring_buffer.c
> index bd1c35a..7739893 100644
> --- a/kernel/trace/ring_buffer.c
> +++ b/kernel/trace/ring_buffer.c
> @@ -2163,10 +2163,14 @@ rb_reserve_next_event(struct ring_buffer *buffer,
>  		delta = diff;
>  		if (unlikely(test_time_stamp(delta))) {
>  			WARN_ONCE(delta > (1ULL << 59),
> -				  KERN_WARNING "Delta way too big! %llu ts=%llu write stamp = %llu\n",
> +				  KERN_WARNING "Delta way too big! %llu ts=%llu write stamp = %llu\n%s",
>  				  (unsigned long long)delta,
>  				  (unsigned long long)ts,
> -				  (unsigned long long)cpu_buffer->write_stamp);
> +				  (unsigned long long)cpu_buffer->write_stamp,
> +				  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");
>  			add_timestamp = 1;
>  		}
>  	}

Re: [tip:perf/core] tracing: Add unstable sched clock note to the warning

[Ingo Molnar]

* Steven Rostedt <rostedt@goodmis.org> wrote:

> On Thu, 2011-02-17 at 15:00 +0000, tip-bot for Jiri Olsa wrote:
> > Commit-ID:  5e38ca8f3ea423442eaafe1b7e206084aa38120a
> > Gitweb:     http://git.kernel.org/tip/5e38ca8f3ea423442eaafe1b7e206084aa38120a
> > Author:     Jiri Olsa <jolsa@redhat.com>
> > AuthorDate: Wed, 2 Feb 2011 13:28:18 +0100
> > Committer:  Steven Rostedt <rostedt@goodmis.org>
> > CommitDate: Tue, 8 Feb 2011 11:57:22 -0500
> > 
> > tracing: Add unstable sched clock note to the warning
> > 
> > The warning "Delta way too big" warning might appear on a system with
> > unstable shed clock right after the system is resumed and tracing
> > was enabled during the suspend.
> > 
> > Since it's not realy bug, and the unstable sched clock is working
> > fast and reliable otherwise, Steven suggested to keep using the
> > sched clock in any case and just to make note in the warning itself.
> > 
> 
> 
> Peter Zijlstra just informed me on IRC that the commit:
> 
> cd7240c0b900eb6d690ccee088a6c9b46dae815a
> x86, tsc, sched: Recompute cyc2ns_offset's during resume from sleep
> states
> 
> Prevents the clock from going backwards triggering the warn on. If this
> is the case, I think we can revert this patch.
> 
> I'll wait on the original reporters of the bug to find out. If the clock
> does not go backwards when the above commit is applied, then this patch
> is not needed.
> 
> If this is the case, do you want me to rebase without it, or should we
> just revert it?

A revert would be nicer (with an explanation in it), as i've already pushed out the 
perc/core tree.

If you do the revert today against the current perf/core tip (bee96907383e) then i 
can pull it in a fast-forward way and we'd minimalize the window.

Thanks,

	Ingo

Re: [tip:perf/core] tracing: Add unstable sched clock note to the warning

[Steven Rostedt]

On Thu, 2011-02-17 at 18:18 +0100, Ingo Molnar wrote:
> * Steven Rostedt <rostedt@goodmis.org> wrote:
> 
> > On Thu, 2011-02-17 at 15:00 +0000, tip-bot for Jiri Olsa wrote:
> > > Commit-ID:  5e38ca8f3ea423442eaafe1b7e206084aa38120a
> > > Gitweb:     http://git.kernel.org/tip/5e38ca8f3ea423442eaafe1b7e206084aa38120a
> > > Author:     Jiri Olsa <jolsa@redhat.com>
> > > AuthorDate: Wed, 2 Feb 2011 13:28:18 +0100
> > > Committer:  Steven Rostedt <rostedt@goodmis.org>
> > > CommitDate: Tue, 8 Feb 2011 11:57:22 -0500
> > > 
> > > tracing: Add unstable sched clock note to the warning
> > > 
> > > The warning "Delta way too big" warning might appear on a system with
> > > unstable shed clock right after the system is resumed and tracing
> > > was enabled during the suspend.
> > > 
> > > Since it's not realy bug, and the unstable sched clock is working
> > > fast and reliable otherwise, Steven suggested to keep using the
> > > sched clock in any case and just to make note in the warning itself.
> > > 
> > 
> > 
> > Peter Zijlstra just informed me on IRC that the commit:
> > 
> > cd7240c0b900eb6d690ccee088a6c9b46dae815a
> > x86, tsc, sched: Recompute cyc2ns_offset's during resume from sleep
> > states
> > 
> > Prevents the clock from going backwards triggering the warn on. If this
> > is the case, I think we can revert this patch.
> > 
> > I'll wait on the original reporters of the bug to find out. If the clock
> > does not go backwards when the above commit is applied, then this patch
> > is not needed.
> > 
> > If this is the case, do you want me to rebase without it, or should we
> > just revert it?
> 
> A revert would be nicer (with an explanation in it), as i've already pushed out the 
> perc/core tree.
> 
> If you do the revert today against the current perf/core tip (bee96907383e) then i 
> can pull it in a fast-forward way and we'd minimalize the window.

I've just been informed that even with this patch, the clock still goes
backwards after resume.

-- Steve

[PATCHv2] trace: adding unstable sched clock note to the warning

[Jiri Olsa]

hi,

warning "Delta way too big" warning might appear on a system with
unstable shed clock right after the system is resumed and tracing
was enabled during the suspend.

Since it's not realy bug, and the unstable sched clock is working
fast and reliable otherwise, Steven suggested to keep using the
sched clock in any case and just to make note in the warning itself.

v2 changes:
- added CONFIG_HAVE_UNSTABLE_SCHED_CLOCK dependency

wbr,
jirka


Signed-off-by: Jiri Olsa <jolsa@redhat.com>
---
 kernel/trace/ring_buffer.c |   12 ++++++++++--
 1 files changed, 10 insertions(+), 2 deletions(-)

diff --git a/kernel/trace/ring_buffer.c b/kernel/trace/ring_buffer.c
index bd1c35a..37c4d3e 100644
--- a/kernel/trace/ring_buffer.c
+++ b/kernel/trace/ring_buffer.c
@@ -2162,11 +2162,19 @@ rb_reserve_next_event(struct ring_buffer *buffer,
 	if (likely(ts >= cpu_buffer->write_stamp)) {
 		delta = diff;
 		if (unlikely(test_time_stamp(delta))) {
+			int local_clock_stable = 1;
+#ifdef CONFIG_HAVE_UNSTABLE_SCHED_CLOCK
+			local_clock_stable = sched_clock_stable;
+#endif
 			WARN_ONCE(delta > (1ULL << 59),
-				  KERN_WARNING "Delta way too big! %llu ts=%llu write stamp = %llu\n",
+				  KERN_WARNING "Delta way too big! %llu ts=%llu write stamp = %llu\n%s",
 				  (unsigned long long)delta,
 				  (unsigned long long)ts,
-				  (unsigned long long)cpu_buffer->write_stamp);
+				  (unsigned long long)cpu_buffer->write_stamp,
+				  local_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");
 			add_timestamp = 1;
 		}
 	}
-- 
1.7.1

Re: [PATCHv2] trace: adding unstable sched clock note to the warning

[Jiri Olsa]

hi,
any feedback?

thanks,
jirka

On Fri, Feb 18, 2011 at 03:52:19PM +0100, Jiri Olsa wrote:
> hi,
> 
> warning "Delta way too big" warning might appear on a system with
> unstable shed clock right after the system is resumed and tracing
> was enabled during the suspend.
> 
> Since it's not realy bug, and the unstable sched clock is working
> fast and reliable otherwise, Steven suggested to keep using the
> sched clock in any case and just to make note in the warning itself.
> 
> v2 changes:
> - added CONFIG_HAVE_UNSTABLE_SCHED_CLOCK dependency
> 
> wbr,
> jirka
> 
> 
> Signed-off-by: Jiri Olsa <jolsa@redhat.com>
> ---
>  kernel/trace/ring_buffer.c |   12 ++++++++++--
>  1 files changed, 10 insertions(+), 2 deletions(-)
> 
> diff --git a/kernel/trace/ring_buffer.c b/kernel/trace/ring_buffer.c
> index bd1c35a..37c4d3e 100644
> --- a/kernel/trace/ring_buffer.c
> +++ b/kernel/trace/ring_buffer.c
> @@ -2162,11 +2162,19 @@ rb_reserve_next_event(struct ring_buffer *buffer,
>  	if (likely(ts >= cpu_buffer->write_stamp)) {
>  		delta = diff;
>  		if (unlikely(test_time_stamp(delta))) {
> +			int local_clock_stable = 1;
> +#ifdef CONFIG_HAVE_UNSTABLE_SCHED_CLOCK
> +			local_clock_stable = sched_clock_stable;
> +#endif
>  			WARN_ONCE(delta > (1ULL << 59),
> -				  KERN_WARNING "Delta way too big! %llu ts=%llu write stamp = %llu\n",
> +				  KERN_WARNING "Delta way too big! %llu ts=%llu write stamp = %llu\n%s",
>  				  (unsigned long long)delta,
>  				  (unsigned long long)ts,
> -				  (unsigned long long)cpu_buffer->write_stamp);
> +				  (unsigned long long)cpu_buffer->write_stamp,
> +				  local_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");
>  			add_timestamp = 1;
>  		}
>  	}
> -- 
> 1.7.1
> --
> To unsubscribe from this list: send the line "unsubscribe linux-kernel" in
> the body of a message to majordomo@vger.kernel.org
> More majordomo info at  http://vger.kernel.org/majordomo-info.html
> Please read the FAQ at  http://www.tux.org/lkml/

Re: [PATCHv2] trace: adding unstable sched clock note to the warning

[Steven Rostedt]

On Mon, 2011-03-07 at 11:45 +0100, Jiri Olsa wrote:
> hi,
> any feedback?

I could pull it in.

Thanks,

-- Steve

> 
> thanks,
> jirka
> 
> On Fri, Feb 18, 2011 at 03:52:19PM +0100, Jiri Olsa wrote:
> > hi,
> > 
> > warning "Delta way too big" warning might appear on a system with
> > unstable shed clock right after the system is resumed and tracing
> > was enabled during the suspend.
> > 
> > Since it's not realy bug, and the unstable sched clock is working
> > fast and reliable otherwise, Steven suggested to keep using the
> > sched clock in any case and just to make note in the warning itself.
> > 
> > v2 changes:
> > - added CONFIG_HAVE_UNSTABLE_SCHED_CLOCK dependency
> > 
> > wbr,
> > jirka
> > 
> > 
> > Signed-off-by: Jiri Olsa <jolsa@redhat.com>
> > ---
> >  kernel/trace/ring_buffer.c |   12 ++++++++++--
> >  1 files changed, 10 insertions(+), 2 deletions(-)
> > 
> > diff --git a/kernel/trace/ring_buffer.c b/kernel/trace/ring_buffer.c
> > index bd1c35a..37c4d3e 100644
> > --- a/kernel/trace/ring_buffer.c
> > +++ b/kernel/trace/ring_buffer.c
> > @@ -2162,11 +2162,19 @@ rb_reserve_next_event(struct ring_buffer *buffer,
> >  	if (likely(ts >= cpu_buffer->write_stamp)) {
> >  		delta = diff;
> >  		if (unlikely(test_time_stamp(delta))) {
> > +			int local_clock_stable = 1;
> > +#ifdef CONFIG_HAVE_UNSTABLE_SCHED_CLOCK
> > +			local_clock_stable = sched_clock_stable;
> > +#endif
> >  			WARN_ONCE(delta > (1ULL << 59),
> > -				  KERN_WARNING "Delta way too big! %llu ts=%llu write stamp = %llu\n",
> > +				  KERN_WARNING "Delta way too big! %llu ts=%llu write stamp = %llu\n%s",
> >  				  (unsigned long long)delta,
> >  				  (unsigned long long)ts,
> > -				  (unsigned long long)cpu_buffer->write_stamp);
> > +				  (unsigned long long)cpu_buffer->write_stamp,
> > +				  local_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");
> >  			add_timestamp = 1;
> >  		}
> >  	}
> > -- 
> > 1.7.1
> > --
> > To unsubscribe from this list: send the line "unsubscribe linux-kernel" in
> > the body of a message to majordomo@vger.kernel.org
> > More majordomo info at  http://vger.kernel.org/majordomo-info.html
> > Please read the FAQ at  http://www.tux.org/lkml/

[tip:perf/core] tracing: Explain about unstable clock on resume with ring buffer warning

[tip-bot for Jiri Olsa]

Commit-ID:  31274d72f01604f4b02d933b4f3cac84d2c201fd
Gitweb:     http://git.kernel.org/tip/31274d72f01604f4b02d933b4f3cac84d2c201fd
Author:     Jiri Olsa <jolsa@redhat.com>
AuthorDate: Fri, 18 Feb 2011 15:52:19 +0100
Committer:  Steven Rostedt <rostedt@goodmis.org>
CommitDate: Thu, 10 Mar 2011 10:34:47 -0500

tracing: Explain about unstable clock on resume with ring buffer warning

The "Delta way too big" warning might appear on a system with a
unstable shed clock right after the system is resumed and tracing
was enabled at time of suspend.

Since it's not realy a bug, and the unstable sched clock is working
fast and reliable otherwise, Steven suggested to keep using the
sched clock in any case and just to make note in the warning itself.

v2 changes:
- added #ifdef CONFIG_HAVE_UNSTABLE_SCHED_CLOCK

Signed-off-by: Jiri Olsa <jolsa@redhat.com>
LKML-Reference: <20110218145219.GD2604@jolsa.brq.redhat.com>
Signed-off-by: Steven Rostedt <rostedt@goodmis.org>
---
 kernel/trace/ring_buffer.c |   12 ++++++++++--
 1 files changed, 10 insertions(+), 2 deletions(-)

diff --git a/kernel/trace/ring_buffer.c b/kernel/trace/ring_buffer.c
index 3237d96..db7b439 100644
--- a/kernel/trace/ring_buffer.c
+++ b/kernel/trace/ring_buffer.c
@@ -2172,11 +2172,19 @@ rb_reserve_next_event(struct ring_buffer *buffer,
 	if (likely(ts >= cpu_buffer->write_stamp)) {
 		delta = diff;
 		if (unlikely(test_time_stamp(delta))) {
+			int local_clock_stable = 1;
+#ifdef CONFIG_HAVE_UNSTABLE_SCHED_CLOCK
+			local_clock_stable = sched_clock_stable;
+#endif
 			WARN_ONCE(delta > (1ULL << 59),
-				  KERN_WARNING "Delta way too big! %llu ts=%llu write stamp = %llu\n",
+				  KERN_WARNING "Delta way too big! %llu ts=%llu write stamp = %llu\n%s",
 				  (unsigned long long)delta,
 				  (unsigned long long)ts,
-				  (unsigned long long)cpu_buffer->write_stamp);
+				  (unsigned long long)cpu_buffer->write_stamp,
+				  local_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");
 			add_timestamp = 1;
 		}
 	}