[PATCH] ftrace: use a global counter for the global clock

[PATCH] ftrace: use a global counter for the global clock

[Peter Zijlstra]

no reason to muck about, just use a counter already.

Requested-by: Thomas Gleixner <tglx@linutronix.de>
Signed-off-by: Peter Zijlstra <a.p.zijlstra@chello.nl>
---
 kernel/trace/trace_clock.c |   44 +++-----------------------------------------
 1 files changed, 3 insertions(+), 41 deletions(-)

diff --git a/kernel/trace/trace_clock.c b/kernel/trace/trace_clock.c
index 6302747..1b79441 100644
--- a/kernel/trace/trace_clock.c
+++ b/kernel/trace/trace_clock.c
@@ -68,48 +68,10 @@ u64 notrace trace_clock(void)
  * Used by plugins that need globally coherent timestamps.
  */
 
-/* keep prev_time and lock in the same cacheline. */
-static struct {
-	u64 prev_time;
-	arch_spinlock_t lock;
-} trace_clock_struct ____cacheline_aligned_in_smp =
-	{
-		.lock = (arch_spinlock_t)__ARCH_SPIN_LOCK_UNLOCKED,
-	};
+
+static atomic64_t trace_counter;
 
 u64 notrace trace_clock_global(void)
 {
-	unsigned long flags;
-	int this_cpu;
-	u64 now;
-
-	local_irq_save(flags);
-
-	this_cpu = raw_smp_processor_id();
-	now = cpu_clock(this_cpu);
-	/*
-	 * If in an NMI context then dont risk lockups and return the
-	 * cpu_clock() time:
-	 */
-	if (unlikely(in_nmi()))
-		goto out;
-
-	arch_spin_lock(&trace_clock_struct.lock);
-
-	/*
-	 * TODO: if this happens often then maybe we should reset
-	 * my_scd->clock to prev_time+1, to make sure
-	 * we start ticking with the local clock from now on?
-	 */
-	if ((s64)(now - trace_clock_struct.prev_time) < 0)
-		now = trace_clock_struct.prev_time + 1;
-
-	trace_clock_struct.prev_time = now;
-
-	arch_spin_unlock(&trace_clock_struct.lock);
-
- out:
-	local_irq_restore(flags);
-
-	return now;
+	return atomic64_add_return(1, &trace_counter);
 }

Re: [PATCH] ftrace: use a global counter for the global clock

[Steven Rostedt]

On Fri, 2011-09-16 at 11:02 +0200, Peter Zijlstra wrote:
> no reason to muck about, just use a counter already.
> 

But some of us actually use the global clock as a clock ;)

How about this patch instead?

----

tracing: Add a counter clock for those that do not trust clocks

When debugging tight race conditions, it can be helpful to have a
synchronized tracing method. Although in most cases the global clock
provides this functionality, if timings is not the issue, it is more
comforting to know that the order of events really happened in a precise
order.

Instead of using a clock, add a "counter" that is simply an incrementing
atomic 64bit counter that orders the events as they are perceived to
happen.

The trace_clock_counter() is added from the attempt by Peter Zijlstra
trying to convert the trace_clock_global() to it. I took Peter's counter
code and made trace_clock_counter() instead, and added it to the choice
of clocks. Just echo counter > /debug/tracing/trace_clock to activate
it.

Requested-by: Thomas Gleixner <tglx@linutronix.de>
Requested-by: Peter Zijlstra <a.p.zijlstra@chello.nl>
Signed-off-by: Steven Rostedt <rostedt@goodmis.org>

diff --git a/include/linux/trace_clock.h b/include/linux/trace_clock.h
index 7a81303..4eb4902 100644
--- a/include/linux/trace_clock.h
+++ b/include/linux/trace_clock.h
@@ -15,5 +15,6 @@
 extern u64 notrace trace_clock_local(void);
 extern u64 notrace trace_clock(void);
 extern u64 notrace trace_clock_global(void);
+extern u64 notrace trace_clock_counter(void);
 
 #endif /* _LINUX_TRACE_CLOCK_H */
diff --git a/kernel/trace/trace.c b/kernel/trace/trace.c
index b419070..4b8df0d 100644
--- a/kernel/trace/trace.c
+++ b/kernel/trace/trace.c
@@ -435,6 +435,7 @@ static struct {
 } trace_clocks[] = {
 	{ trace_clock_local,	"local" },
 	{ trace_clock_global,	"global" },
+	{ trace_clock_counter,	"counter" },
 };
 
 int trace_clock_id;
diff --git a/kernel/trace/trace_clock.c b/kernel/trace/trace_clock.c
index 6302747..3947835 100644
--- a/kernel/trace/trace_clock.c
+++ b/kernel/trace/trace_clock.c
@@ -113,3 +113,15 @@ u64 notrace trace_clock_global(void)
 
 	return now;
 }
+
+static atomic64_t trace_counter;
+
+/*
+ * trace_clock_counter(): simply an atomic counter.
+ * Use the trace_counter "counter" for cases where you do not care
+ * about timings, but are interested in strict ordering.
+ */
+u64 notrace trace_clock_counter(void)
+{
+	return atomic64_add_return(1, &trace_counter);
+}

Re: [PATCH] ftrace: use a global counter for the global clock

[Peter Zijlstra]

On Fri, 2011-09-16 at 08:18 -0400, Steven Rostedt wrote:
> On Fri, 2011-09-16 at 11:02 +0200, Peter Zijlstra wrote:
> > no reason to muck about, just use a counter already.
> > 
> 
> But some of us actually use the global clock as a clock ;)
> 
> How about this patch instead?

Very much fine by me. Thanks!

Re: [PATCH] ftrace: use a global counter for the global clock

[Peter Zijlstra]

On Fri, 2011-09-16 at 08:18 -0400, Steven Rostedt wrote:
> +       return atomic64_add_return(1, &trace_counter);

Oh, fwiw I modified mine to increment by 1000 because we're showing us
in the trace output, 1000 lines with the same 'time'-stamp is slightly
confusing even though you know the order is absolutely right...

Re: [PATCH] ftrace: use a global counter for the global clock

[Steven Rostedt]

On Fri, 2011-09-16 at 14:36 +0200, Peter Zijlstra wrote:
> On Fri, 2011-09-16 at 08:18 -0400, Steven Rostedt wrote:
> > +       return atomic64_add_return(1, &trace_counter);
> 
> Oh, fwiw I modified mine to increment by 1000 because we're showing us
> in the trace output, 1000 lines with the same 'time'-stamp is slightly
> confusing even though you know the order is absolutely right...


Or I could change it so that if counter clock is set, just show that
field as a counter too.

-- Steve

Re: [PATCH] ftrace: use a global counter for the global clock

[Steven Rostedt]

On Fri, 2011-09-16 at 09:23 -0400, Steven Rostedt wrote:
> On Fri, 2011-09-16 at 14:36 +0200, Peter Zijlstra wrote:
> > On Fri, 2011-09-16 at 08:18 -0400, Steven Rostedt wrote:
> > > +       return atomic64_add_return(1, &trace_counter);
> > 
> > Oh, fwiw I modified mine to increment by 1000 because we're showing us
> > in the trace output, 1000 lines with the same 'time'-stamp is slightly
> > confusing even though you know the order is absolutely right...
> 
> 
> Or I could change it so that if counter clock is set, just show that
> field as a counter too.
> 

Hmm, as I have other things to work on. I think I'll take your
suggestion of the 1000 increment for now ;)

-- Steve

Re: [PATCH] ftrace: use a global counter for the global clock

[Valdis.Kletnieks]

[-- Attachment #1: Type: text/plain, Size: 950 bytes --]

On Fri, 16 Sep 2011 08:18:26 EDT, Steven Rostedt said:

> +	return atomic64_add_return(1, &trace_counter);

Given that the usefulness of this is probably directly proportional to the
number of cores on the box, is this subject to cache line ping-ponging on
systems with many cores?

> When debugging tight race conditions, it can be helpful to have a
> synchronized tracing method. Although in most cases the global clock
> provides this functionality, if timings is not the issue, it is more
> comforting to know that the order of events really happened in a precise
> order.

One wonders if the overhead can end up being enough to change the
ordering, and possibly cause a heisenbug (most likely if the race condition
involves one CPU doing something we're tracing, and another CPU doing
something we are *not* tracing)...

If that's considered not an issue, feel free to stick this on it:
Reviewed-By: Valdis Kletnieks <valdis.kletnieks@vt.edu>



[-- Attachment #2: Type: application/pgp-signature, Size: 227 bytes --]

Re: [PATCH] ftrace: use a global counter for the global clock

[Steven Rostedt]

On Fri, 2011-09-16 at 17:14 -0400, Valdis.Kletnieks@vt.edu wrote:
> On Fri, 16 Sep 2011 08:18:26 EDT, Steven Rostedt said:
> 
> > +	return atomic64_add_return(1, &trace_counter);
> 
> Given that the usefulness of this is probably directly proportional to the
> number of cores on the box, is this subject to cache line ping-ponging on
> systems with many cores?

It will cause hickups, but shouldn't really change much of the ordering.
If anything, it may synchronize more.

> 
> > When debugging tight race conditions, it can be helpful to have a
> > synchronized tracing method. Although in most cases the global clock
> > provides this functionality, if timings is not the issue, it is more
> > comforting to know that the order of events really happened in a precise
> > order.
> 
> One wonders if the overhead can end up being enough to change the
> ordering, and possibly cause a heisenbug (most likely if the race condition
> involves one CPU doing something we're tracing, and another CPU doing
> something we are *not* tracing)...

My use of logdev synchronized traces like this. But it actually caught a
lot of race conditions. Really, it's about catching the ordering of what
happens in a race condition, and having the tracer actually introduce
synchronization helped in analysis. But true, as a heisenbug effect,
enabling this tracer may make the bug go away.

> 
> If that's considered not an issue, feel free to stick this on it:
> Reviewed-By: Valdis Kletnieks <valdis.kletnieks@vt.edu>

Thanks, and yes, it is not too much of a concern. It just adds another
option developers can use. Thus, if you are worried about cache line
bouncing, just use the global or local clock, otherwise use the counter.
Which I plan on documenting this side effect.

-- Steve