Skip to contentSkip to conversation

trace: adding unstable sched clock note to the warning

PATCH Superseded Jiri Olsa 3 participants 9 messages Feb 2, 2011 – Mar 11, 2011

Subsystems (2)
Tracing Tracing ring buffer
lore
Share & tools
lore

Jiri Olsa

author
#0 lore raw

PATCH 1/1 trace: adding unstable sched clock note to the warning

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 <[email protected]>
---
 kernel/trace/ring_buffer.c |    8 ++++++--
 1 files changed, 6 insertions(+), 2 deletions(-)
kernel/trace/ring_buffer.c +6 -2
index bd1c35a..7739893 100644
@@ -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;
 		}
 	}
author
#1 lore raw

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

Commit-ID:  5e38ca8f3ea423442eaafe1b7e206084aa38120a
Gitweb:     http://git.kernel.org/tip/5e38ca8f3ea423442eaafe1b7e206084aa38120a
Author:     Jiri Olsa <[email protected]>
AuthorDate: Wed, 2 Feb 2011 13:28:18 +0100
Committer:  Steven Rostedt <[email protected]>
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 <[email protected]>

LKML-Reference: <[email protected]>

Signed-off-by Steven Rostedt <[email protected]>
---
 kernel/trace/ring_buffer.c |    8 ++++++--
 1 files changed, 6 insertions(+), 2 deletions(-)
kernel/trace/ring_buffer.c +6 -2
index bd1c35a..7739893 100644
@@ -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;
 		}
 	}
maintainer
#2 lore raw

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

Quoted 9 lines · tip-bot for Jiri Olsa
Commit-ID:  5e38ca8f3ea423442eaafe1b7e206084aa38120a
Gitweb:     http://git.kernel.org/tip/5e38ca8f3ea423442eaafe1b7e206084aa38120a
Author:     Jiri Olsa <[email protected]>
AuthorDate: Wed, 2 Feb 2011 13:28:18 +0100
Committer:  Steven Rostedt <[email protected]>
CommitDate: Tue, 8 Feb 2011 11:57:22 -0500

tracing: Add unstable sched clock note to the warning

Quoted 8 lines

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

Quoted 28 lines
Signed-off-by Jiri Olsa <[email protected]>

LKML-Reference: <[email protected]>

Signed-off-by Steven Rostedt <[email protected]>
---
 kernel/trace/ring_buffer.c |    8 ++++++--
 1 files changed, 6 insertions(+), 2 deletions(-)
kernel/trace/ring_buffer.c +6 -2
index bd1c35a..7739893 100644
@@ -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;
 		}
 	}
#3 lore raw

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

Quoted 29 lines · Steven Rostedt
Quoted 9 lines · tip-bot for Jiri Olsa
Commit-ID:  5e38ca8f3ea423442eaafe1b7e206084aa38120a
Gitweb:     http://git.kernel.org/tip/5e38ca8f3ea423442eaafe1b7e206084aa38120a
Author:     Jiri Olsa <[email protected]>
AuthorDate: Wed, 2 Feb 2011 13:28:18 +0100
Committer:  Steven Rostedt <[email protected]>
CommitDate: Tue, 8 Feb 2011 11:57:22 -0500

tracing: Add unstable sched clock note to the warning

Quoted 8 lines

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.

Quoted 6 lines

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

maintainer
#4 lore raw

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

Quoted 35 lines · Ingo Molnar
Quoted 33 lines · Steven Rostedt
Quoted 9 lines · tip-bot for Jiri Olsa
Commit-ID:  5e38ca8f3ea423442eaafe1b7e206084aa38120a
Gitweb:     http://git.kernel.org/tip/5e38ca8f3ea423442eaafe1b7e206084aa38120a
Author:     Jiri Olsa <[email protected]>
AuthorDate: Wed, 2 Feb 2011 13:28:18 +0100
Committer:  Steven Rostedt <[email protected]>
CommitDate: Tue, 8 Feb 2011 11:57:22 -0500

tracing: Add unstable sched clock note to the warning

Quoted 8 lines

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.

Quoted 8 lines
Quoted 2 lines

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

author
#5 lore raw

PATCH v2 1/1 trace: adding unstable sched clock note to the warning

In reply to 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 <[email protected]>
---
 kernel/trace/ring_buffer.c |   12 ++++++++++--
 1 files changed, 10 insertions(+), 2 deletions(-)
kernel/trace/ring_buffer.c +10 -2
index bd1c35a..37c4d3e 100644
@@ -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;
 		}
 	}
Signature · 1 line
1.7.1
author
#6 lore raw

hi,
any feedback?

thanks,
jirka

Quoted 55 lines · 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 <[email protected]>
---
 kernel/trace/ring_buffer.c |   12 ++++++++++--
 1 files changed, 10 insertions(+), 2 deletions(-)
kernel/trace/ring_buffer.c +10 -2
index bd1c35a..37c4d3e 100644
@@ -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;
 		}
 	}
Signature · 6 lines
1.7.1
--
To unsubscribe from this list: send the line "unsubscribe linux-kernel" in
the body of a message to [email protected]
More majordomo info at  http://vger.kernel.org/majordomo-info.html
Please read the FAQ at  http://www.tux.org/lkml/
maintainer
#7 lore raw
Quoted 2 lines · Jiri Olsa

hi,
any feedback?

I could pull it in.

Thanks,

-- Steve

Quoted 60 lines

thanks,
jirka

Quoted 55 lines · 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 <[email protected]>
---
 kernel/trace/ring_buffer.c |   12 ++++++++++--
 1 files changed, 10 insertions(+), 2 deletions(-)
kernel/trace/ring_buffer.c +10 -2
index bd1c35a..37c4d3e 100644
@@ -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;
 		}
 	}
Signature · 6 lines
1.7.1
--
To unsubscribe from this list: send the line "unsubscribe linux-kernel" in
the body of a message to [email protected]
More majordomo info at  http://vger.kernel.org/majordomo-info.html
Please read the FAQ at  http://www.tux.org/lkml/
author
#8 lore raw

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

In reply to Jiri Olsa
Commit-ID:  31274d72f01604f4b02d933b4f3cac84d2c201fd
Gitweb:     http://git.kernel.org/tip/31274d72f01604f4b02d933b4f3cac84d2c201fd
Author:     Jiri Olsa <[email protected]>
AuthorDate: Fri, 18 Feb 2011 15:52:19 +0100
Committer:  Steven Rostedt <[email protected]>
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 <[email protected]>

LKML-Reference: <[email protected]>

Signed-off-by Steven Rostedt <[email protected]>
---
 kernel/trace/ring_buffer.c |   12 ++++++++++--
 1 files changed, 10 insertions(+), 2 deletions(-)
kernel/trace/ring_buffer.c +10 -2
index 3237d96..db7b439 100644
@@ -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;
 		}
 	}