tracing/function-return-tracer: Make the function return tracer lockless

Impact: remove spinlocks and irq disabling in function return tracer.

I've tried to figure out all of the race condition that could happen when the tracer pushes or pops a return address trace to/from the current thread_info.

Theory:

_ One thread can only execute on one cpu at a time. So this code doesn't need
to be SMP-safe. Just drop the spinlock.
_ The only race could happen between the current thread and an interrupt. If an
interrupt is raised, it will increase the index of the return stack storage and then execute until the end of the tracing to finally free the index it used. We don't need to disable irqs.

This is theorical. In practice, I've tested it with a two-core SMP and had no problem at all. Perhaps -tip testing could confirm it.

Signed-off-by Frederic Weisbecker <[email protected]>

Cc Steven Rostedt <[email protected]>

Quoted 19 lines

Impact: remove spinlocks and irq disabling in function return tracer.

I've tried to figure out all of the race condition that could happen when the tracer pushes or pops a return address trace to/from the current thread_info.

Theory:

_ One thread can only execute on one cpu at a time. So this code doesn't need
to be SMP-safe. Just drop the spinlock.
_ The only race could happen between the current thread and an interrupt. If an
interrupt is raised, it will increase the index of the return stack storage and then execute until the end of the tracing to finally free the index it used. We don't need to disable irqs.

This is theorical. In practice, I've tested it with a two-core SMP and had no problem at all. Perhaps -tip testing could confirm it.

Quoted 2 lines

Signed-off-by Frederic Weisbecker <[email protected]>

Cc Steven Rostedt <[email protected]>

applied to tip/tracing/function-return-tracer, thanks Frederic!

Ingo

BTW I'm wondering about consistency in time capturing. When I look into kernel/sched_clock.c I see this in introduction:

"The clock: sched_clock_cpu() is monotonic per cpu, and should be somewhat consistent between cpus (never more than 2 jiffies difference)."

Two Jiffies, that could result in a lot of inconsistency in the way of nanosec capturing. The current task can be preempted between the call time and the return time and I'm doing a cpu_clock(raw_smp_processor_id) on these two times. Should I keep the same processor_id for these two captures? But what would happen if this cpu is shut down between these two times? One other solution would be to plan time capture in usec but I would mostly lose the interest of function cost measuring....

What do you think?

Quoted 17 lines

BTW I'm wondering about consistency in time capturing. When I look into kernel/sched_clock.c I see this in introduction:

"The clock: sched_clock_cpu() is monotonic per cpu, and should be somewhat consistent between cpus (never more than 2 jiffies difference)."

Two Jiffies, that could result in a lot of inconsistency in the way of nanosec capturing. The current task can be preempted between the call time and the return time and I'm doing a cpu_clock(raw_smp_processor_id) on these two times. Should I keep the same processor_id for these two captures? But what would happen if this cpu is shut down between these two times? One other solution would be to plan time capture in usec but I would mostly lose the interest of function cost measuring....

Quoted 1 line

What do you think?

in practice the jitter is much lower - a couple of microseconds - up to a few dozen at most.

But it's a possibility, and i think the best solution is something that Steve suggested yesterday: a /debug/tracing/trace_options flag that turns on global ordering for tracing timestamps. Something like:

echo global_timestamps > /debug/tracing/trace_options

tracers could also change the default of this flag. The function-cost tracer will probably want to default to globally synchronous timestamps, while the preempt and irqsoff tracers want to default to local timestamps only.

Would something like this work for you?

Ingo

2008/11/13 Ingo Molnar <[email protected]>:

Quoted 37 lines · Frédéric Weisbecker

Quoted 17 lines

BTW I'm wondering about consistency in time capturing. When I look into kernel/sched_clock.c I see this in introduction:

"The clock: sched_clock_cpu() is monotonic per cpu, and should be somewhat consistent between cpus (never more than 2 jiffies difference)."

Two Jiffies, that could result in a lot of inconsistency in the way of nanosec capturing. The current task can be preempted between the call time and the return time and I'm doing a cpu_clock(raw_smp_processor_id) on these two times. Should I keep the same processor_id for these two captures? But what would happen if this cpu is shut down between these two times? One other solution would be to plan time capture in usec but I would mostly lose the interest of function cost measuring....

Quoted 1 line

What do you think?

in practice the jitter is much lower - a couple of microseconds - up to a few dozen at most.

But it's a possibility, and i think the best solution is something that Steve suggested yesterday: a /debug/tracing/trace_options flag that turns on global ordering for tracing timestamps. Something like:

echo global_timestamps > /debug/tracing/trace_options

tracers could also change the default of this flag. The function-cost tracer will probably want to default to globally synchronous timestamps, while the preempt and irqsoff tracers want to default to local timestamps only.

Would something like this work for you?

Quoted 2 lines

Ingo

But I guess this flag would apply on the timestamp inserted by the ring-buffer. Unfortunately I can't use it since I have to capture the clock for two times and not only during insertion in the ring-buffer.

Quoted 39 lines

2008/11/13 Ingo Molnar <[email protected]>:

Quoted 37 lines · Frédéric Weisbecker

Quoted 17 lines

BTW I'm wondering about consistency in time capturing. When I look into kernel/sched_clock.c I see this in introduction:

"The clock: sched_clock_cpu() is monotonic per cpu, and should be somewhat consistent between cpus (never more than 2 jiffies difference)."

Two Jiffies, that could result in a lot of inconsistency in the way of nanosec capturing. The current task can be preempted between the call time and the return time and I'm doing a cpu_clock(raw_smp_processor_id) on these two times. Should I keep the same processor_id for these two captures? But what would happen if this cpu is shut down between these two times? One other solution would be to plan time capture in usec but I would mostly lose the interest of function cost measuring....

Quoted 1 line

What do you think?

in practice the jitter is much lower - a couple of microseconds - up to a few dozen at most.

But it's a possibility, and i think the best solution is something that Steve suggested yesterday: a /debug/tracing/trace_options flag that turns on global ordering for tracing timestamps. Something like:

echo global_timestamps > /debug/tracing/trace_options

tracers could also change the default of this flag. The function-cost tracer will probably want to default to globally synchronous timestamps, while the preempt and irqsoff tracers want to default to local timestamps only.

Would something like this work for you?

Quoted 8 lines

Quoted 2 lines

Ingo

But I guess this flag would apply on the timestamp inserted by the ring-buffer. Unfortunately I can't use it since I have to capture the clock for two times and not only during insertion in the ring-buffer.

i think the clock should be a property of the tracer, not of the ring buffer. Hence if a tracer has the option set, it will get coherent timestamps - including ringbuffer insertion timestamps.

Ingo

If so that would be suitable. And for his purpose, the ring-buffer would propose a function for time snapshot adapted to the current flags and that rely on sched_clock?

yeah - and it would be all means by a global entity in the beginning - i.e. we'd just generalize the code around ring_buffer_time_stamp() to listen to the "globally coherent" flag, and allow it to be used for callgraph cost measurement code too.

If the "globally coherent" flag is set, then the implementation would be something like:

A simple "last global timestamp" value combined with a "last local timestamp" value, and the global timestamp is only ever moved forward. It is updated via cmpxchg loop. This gives coherency and a monotonic clock. The local timestamp would be taken from cpu_clock(cpu), and a global timestamp would be constructed out of it. Or something like that.

Would that work? [ Would you be interested in sending patches? :-) ]

Ingo

Ok, so correct me if I'm wrong. Global timestamp would be captured by using sched_clock(). That's what is done currently in ring_buffer_time_stamp() And the global timestamp would be combination of a last global timestamp and a relative position from now to this last at each insertion in the ring-buffer (or tracing time capture). Am I right? I don't really understand why you want to update with a cmpxchg loop...

Quoted 7 lines · Frédéric Weisbecker

Ok, so correct me if I'm wrong. Global timestamp would be captured by using sched_clock(). That's what is done currently in ring_buffer_time_stamp() And the global timestamp would be combination of a last global timestamp and a relative position from now to this last at each insertion in the ring-buffer (or tracing time capture). Am I right? I don't really understand why you want to update with a cmpxchg loop...

the cmpxchg loop would be needed to ensure timestamp monotonicity:
every new "global time" is cmpxchg-ed with the "previous global time" (and is first monotonicity checked).

"prev_global_time" also acts as a global serializer: it ensures that events are timestamped in a monotonic and ordered way.

i.e. something like this (pseudocode, without the cmpxchg):

u64 prev_global_time;

DEFINE_PER_CPU(prev_local_time);

u64 global_time()

 {
	u64 now, delta, now_global;

	prev_global = prev_global_time;
	now = sched_clock();
	delta = now - per_cpu(prev_local_time, this_cpu);
	per_cpu(prev_local_time, this_cpu) = now;

	now_global = prev_global + delta;
	prev_global = now_global;

	return now_global;

}

note how we build "global time" out of "local time".

Quoted 35 lines · Ingo Molnar

Quoted 7 lines · Frédéric Weisbecker

Ok, so correct me if I'm wrong. Global timestamp would be captured by using sched_clock(). That's what is done currently in ring_buffer_time_stamp() And the global timestamp would be combination of a last global timestamp and a relative position from now to this last at each insertion in the ring-buffer (or tracing time capture). Am I right? I don't really understand why you want to update with a cmpxchg loop...

the cmpxchg loop would be needed to ensure timestamp monotonicity:
every new "global time" is cmpxchg-ed with the "previous global time" (and is first monotonicity checked).

"prev_global_time" also acts as a global serializer: it ensures that events are timestamped in a monotonic and ordered way.

i.e. something like this (pseudocode, without the cmpxchg):

u64 prev_global_time;

DEFINE_PER_CPU(prev_local_time);

u64 global_time()

 {
	u64 now, delta, now_global;

	prev_global = prev_global_time;
	now = sched_clock();
	delta = now - per_cpu(prev_local_time, this_cpu);
	per_cpu(prev_local_time, this_cpu) = now;

	now_global = prev_global + delta;
	prev_global = now_global;

Quoted 4 lines

	return now_global;

}

note how we build "global time" out of "local time".

This goes down shit-creek real fast if the TSC goes funny and jumps fwd or something.

"prev_global_time" also acts as a global serializer: it ensures that events are timestamped in a monotonic and ordered way.

i.e. something like this (pseudocode, without the cmpxchg):

u64 prev_global_time;

DEFINE_PER_CPU(prev_local_time);

u64 global_time()

 {
       u64 now, delta, now_global;

       prev_global = prev_global_time;
       now = sched_clock();
       delta = now - per_cpu(prev_local_time, this_cpu);
       per_cpu(prev_local_time, this_cpu) = now;

       now_global = prev_global + delta;
       prev_global = now_global;

       return now_global;

}

note how we build "global time" out of "local time".

The cmpxchg would be used to put the above one into a loop, and instead of updating the global time in a racy way:

       prev_global = now_global;

We'd update it via the cmpxchg:

       atomic64_t prev_global_time;

       ...

       while (atomic64_cmpxchg(&prev_global_time,
                                prev_global, now_global) != prev_global) {
               [...]
       }

To make sure the global time goes monotonic. (this way we also avoid a spinlock - locks are fragile for instrumentation)

2008/11/13 Ingo Molnar <[email protected]>:

Quoted 42 lines

"prev_global_time" also acts as a global serializer: it ensures that events are timestamped in a monotonic and ordered way.

i.e. something like this (pseudocode, without the cmpxchg):

u64 prev_global_time;

DEFINE_PER_CPU(prev_local_time);

u64 global_time()

 {
       u64 now, delta, now_global;

       prev_global = prev_global_time;
       now = sched_clock();
       delta = now - per_cpu(prev_local_time, this_cpu);
       per_cpu(prev_local_time, this_cpu) = now;

       now_global = prev_global + delta;
       prev_global = now_global;

       return now_global;

}

note how we build "global time" out of "local time".

The cmpxchg would be used to put the above one into a loop, and instead of updating the global time in a racy way:

       prev_global = now_global;

We'd update it via the cmpxchg:

       atomic64_t prev_global_time;

       ...

       while (atomic64_cmpxchg(&prev_global_time,
                                prev_global, now_global) != prev_global) {
               [...]
       }

Quoted 2 lines

To make sure the global time goes monotonic. (this way we also avoid a spinlock - locks are fragile for instrumentation)

Ok, I understand better.
But consider the following:

u64 global_time()

 {
       u64 now, delta, now_global;
       prev_global = prev_global_time;

       while (atomic64_cmpxchg(&prev_global_time,
                                 prev_global, now_global) != prev_global) {

           now = sched_clock();
           delta = now - per_cpu(prev_local_time, this_cpu);
           per_cpu(prev_local_time, this_cpu) = now;
           now_global = prev_global + delta;
           prev_global = now_global;
       }
       return now_global;

}

Sarting with prev_global_time = 0 If we have two cpu and the above function is executed 5 times on the first cpu. We couldl have per_cpu(prev_local_time) = 50 for example. And so prev_global_time will be equal to 50.

Just after that, almost at the same time, cpu2 calls global_time()

delta will be equal to 50 (sched_clock() - per_cpu(prev_local_time) which is 0) and prev_global_time will be 50 + 50 = 100. This is not consistent. I don't know where but I'm pretty sure I missed something....

you are right - it needs a bit more logic.

I think the simplest would be something like this:

atomic64_t global_clock = INIT_ATOMIC64(0);

u64 global_time()

 {
       u64 now, delta, now_global, prev_global;

       do {
               prev_global = atomic64_read(&global_clock);
               now = cpu_clock(raw_smp_processor_id());

               if ((s64)(now - prev_global) < 0) {
                       now = prev_global;
                       break;
               }
       } while (atomic64_cmpxchg(&global_clock,
                                  prev_global, now) != prev_global);

       return now;

}

This is the simplest way of implementing monotonic time: we only allow global_clock to go forwards. If all cpu_clock()s are perfectly in sync, we've got no problem: then "now - prev_global" will never be negative and we can return the local clock as the latest global time.

But if one of the CPU clocks is "behind", the function returns the latest global time up until the local clock catches up. Time wont be allowed to jump around by going back. If the clock is behind for a long time, then we get a lot of timestamps with the same value -

Would that work? [ Would you be interested in sending patches? :-) ]

that
will be very visible in the trace and we'll then work in improving the cpu_clock() implementation.

So i think we could start with this simplest approach, and see how often we get the same timestamp for a long time (indication of the clocks being not perfectly in sync).

_ The only race could happen between the current thread and an interrupt. If an
interrupt is raised, it will increase the index of the return stack storage and then execute until the end of the tracing to finally free the index it used. We don't need to disable irqs.

This is theorical. In practice, I've tested it with a two-core SMP and had no problem at all. Perhaps -tip testing could confirm it.

The problem I think is that you assume the ++ is atomic against interrupts, which is not guaranteed by the C compiler. e.g. it would be perfectly legal for the compiler to generate code like

local register i
i = index;
write to index'ed array using i
<--------- interrupt here would overwrite data
...
index = i + 1;

Quoted 6 lines

local register i
i = index;
write to index'ed array using i
<--------- interrupt here would overwrite data
...
index = i + 1;

Yes in the common case that would be a danger. But here, if an interrupt is raised, it will increment
the counter and then decrement it at return time without dropping the cpu. So after the interrupt, the
value will remain the same...

Quoted 8 lines

Quoted 6 lines

local register i
i = index;
write to index'ed array using i
<--------- interrupt here would overwrite data
...
index = i + 1;

Quoted 5 lines

Yes in the common case that would be a danger. But here, if an interrupt is raised, it will increment
the counter and then decrement it at return time without dropping the cpu. So after the interrupt, the
value will remain the same...

The buffer contents will not be necessarily
the same. See the scenario above. The interrupt would use the same i as the current function and would overwrite the partially written entry.

So the answer to this is:

  i = index++;
  barrier();
  write to index i (not index);

Quoted 5 lines

So the answer to this is:

  i = index++;
  barrier();
  write to index i (not index);

That was my first thought when I wrote the original email, but the disadvantage is that barrier() is a big hammer that flushes everything and can make the code much worse. That is why I suggested local_add_return() instead.

Quoted 11 lines

Quoted 6 lines

So the answer to this is:

  i = index++;
  barrier();
  write to index i (not index);

That was my first thought when I wrote the original email, but the disadvantage is that barrier() is a big hammer that flushes everything and can make the code much worse. That is why I suggested local_add_return() instead.

barrier() is a compiler barrier, does nothing with the caches, and is quite cheap. We only need a compiler barrier because we are only protecting ourselves from things that happen on the current CPU. No other devices or other CPUs are involved.

Quoted 6 lines · Andi Kleen

Quoted 5 lines

So the answer to this is:

  i = index++;
  barrier();
  write to index i (not index);

Quoted 4 lines

That was my first thought when I wrote the original email, but the disadvantage is that barrier() is a big hammer that flushes everything and can make the code much worse. That is why I suggested local_add_return() instead.

barrier() is a compiler barrier, does nothing with the caches, and is quite cheap. We only need a compiler barrier because we are only

Quoted 14 lines · Steven Rostedt

Quoted 10 lines · Andi Kleen

Quoted 5 lines

So the answer to this is:

  i = index++;
  barrier();
  write to index i (not index);

That was my first thought when I wrote the original email, but the disadvantage is that barrier() is a big hammer that flushes everything and can make the code much worse. That is why I suggested local_add_return() instead.

Quoted 2 lines

barrier() is a compiler barrier, does nothing with the caches, and is quite cheap. We only need a compiler barrier because we are only

I did not refer to CPU caches, but the compiler's register allocation [ok if you want the registers are the "level 0 cache"]. A memory barrier all messes it up. That is why it is better to only clobber specific memory regions, which is what local_* does.

Now tell me again how local_* is more efficient than barrier?

Quoted 6 lines

Quoted 6 lines

I did not refer to CPU caches, but the compiler's register allocation [ok if you want the registers are the "level 0 cache"]. A memory barrier all messes it up. That is why it is better to only clobber specific memory regions, which is what local_* does.

Quoted 1 line

Now tell me again how local_* is more efficient than barrier?

Look at the generated assembler, not the source. The M386 check is two instructions with the i386 stuff just moved away somewhere out of line that is about never taken. The rest is short and straight forward in asm too. And a lot of kernels are not compiled with 386 support anyways.

barrier:

	__asm__ __volatile__("": : :"memory")

local_add_return:

	asm volatile(_ASM_XADD "%0, %1;"
		     : "+r" (i), "+m" (l->a.counter)
		     : : "memory");

Your argument was that barrier clobbers memory, but it looks like the local_add_return does the same.

I don't see any major gain in switching to local_add_return.