ftrace minor updates

The following two patches help the latency tracers of ftrace.

-- Steve

The current ftrace clock uses the sched_clock.c code. This code tries to handle cases where the TSC is out of sync between different CPUs. Unfortunately, even with insync TSCs, due to drifts between the CPU clock and the GTOD clock, we might get some inaccuracy in a single CPU trace.

Some tracers (irqsoff, preemptoff, preempirqsoff) only care about a trace on a single CPU. This patch changes the ftrace_now (the clock reader) from a function call to a function variable. On initialization of a tracer, the tracer will be allowed to choose which type of clock to use.

Now the irqsoff, preemptoff and preemptirqs off tracers can have accurate traces with the local CPU clock without affecting the tracers that want the modified clock that tries to keep the different CPU clock reads in sync.

---
 kernel/trace/trace.c         |   15 ++++++++++++++-
 kernel/trace/trace.h         |    3 ++-
 kernel/trace/trace_irqsoff.c |    3 +++
 3 files changed, 19 insertions(+), 2 deletions(-)

Index: linux-tip.git/kernel/trace/trace.c
===================================================================
@@ -58,11 +58,18 @@ ns2usecs(cycle_t nsec)
 	return nsec;
 }
 
-cycle_t ftrace_now(int cpu)
+static cycle_t trace_local_now(int cpu)
+{
+	return sched_clock();
+}
+
+static cycle_t trace_global_now(int cpu)
 {
 	return cpu_clock(cpu);
 }
 
+cycle_t (*ftrace_now)(int cpu) = trace_global_now;
+
 /*
  * The global_trace is the descriptor that holds the tracing
  * buffers for the live tracing. For each CPU, it contains

@@ -2378,6 +2385,12 @@ tracing_set_trace_write(struct file *fil
 		current_trace->reset(tr);
 
 	current_trace = t;
+
+	if (t->local_now)
+		ftrace_now = trace_local_now;
+	else
+		ftrace_now = trace_global_now;
+
 	if (t->init)
 		t->init(tr);
 

Index: linux-tip.git/kernel/trace/trace.h
===================================================================
@@ -155,6 +155,7 @@ struct tracer {
 	int			(*print_line)(struct trace_iterator *iter);
 	struct tracer		*next;
 	int			print_max;
+	int			local_now;
 };
 
 struct trace_seq {

@@ -237,7 +238,7 @@ void update_max_tr(struct trace_array *t
 void update_max_tr_single(struct trace_array *tr,
 			  struct task_struct *tsk, int cpu);
 
-extern cycle_t ftrace_now(int cpu);
+extern cycle_t (*ftrace_now)(int cpu);
 
 #ifdef CONFIG_FTRACE
 void tracing_start_function_trace(void);

Index: linux-tip.git/kernel/trace/trace_irqsoff.c
===================================================================
@@ -413,6 +413,7 @@ static struct tracer irqsoff_tracer __re
 	.close		= irqsoff_tracer_close,
 	.ctrl_update	= irqsoff_tracer_ctrl_update,
 	.print_max	= 1,
+	.local_now	= 1,
 #ifdef CONFIG_FTRACE_SELFTEST
 	.selftest    = trace_selftest_startup_irqsoff,
 #endif

@@ -439,6 +440,7 @@ static struct tracer preemptoff_tracer _
 	.close		= irqsoff_tracer_close,
 	.ctrl_update	= irqsoff_tracer_ctrl_update,
 	.print_max	= 1,
+	.local_now	= 1,
 #ifdef CONFIG_FTRACE_SELFTEST
 	.selftest    = trace_selftest_startup_preemptoff,
 #endif

@@ -467,6 +469,7 @@ static struct tracer preemptirqsoff_trac
 	.close		= irqsoff_tracer_close,
 	.ctrl_update	= irqsoff_tracer_ctrl_update,
 	.print_max	= 1,
+	.local_now	= 1,
 #ifdef CONFIG_FTRACE_SELFTEST
 	.selftest    = trace_selftest_startup_preemptirqsoff,
 #endif

this is not a good idea. We want to fix cpu_clock(), not work around any deficiencies it might have.

Ingo

[...]

cpu_clock currently is "sched_clock" when the CONFIG_HAVE_UNSTABLE_SCHED_CLOCK is not set. Which is done via configuration, and I noticed is set on my boxes with a stable TSC??

Perhaps we need to make cpu_clock change dynamically when an unstable sched_clock is detected.

Even in this case, forcing the tracers that are single CPU to use a clock source that modifies itself to try to look stable across CPUs still seems wrong to me. The goal of looking stable across CPUs will always be at odds with the irqsoff tracer that does not care about other CPUS but cares tremendously about accurate latencies.

-- Steve

define 'stable TSC' ;-)

other tracers care too - for example to have the right chronology of trace events. The scheduler cares too. What kind of worst-case cross-CPU effects have you observed?

Ingo

heh, OK they are insync across CPUS. They also give better times than running with the cpu_clock.

1:            bash-3498  [01]  5459.824565:      0:140:R   +  7971:120:R
2:          <idle>-0     [00]  5459.824836:      0:140:R ==>  7971:120:R
3:            bash-3498  [01]  5459.824984:   3498:120:S ==>     0:140:R
4:          <idle>-0     [01]  5459.825342:      0:140:R ==>  7971:120:R
5:              ls-7971  [00]  5459.825380:   7971:120:R   +     3:  0:S
6:              ls-7971  [00]  5459.825384:   7971:120:R ==>     3:  0:R
7:     migration/0-3     [00]  5459.825401:      3:  0:S ==>     0:140:R
8:              ls-7971  [01]  5459.825565:   7971:120:R   +   598:115:S

The above was from my tutorial at OLS. I added the annotated numbers at the beginning of the line. This is the sched_switch tracer.

Line 1, on CPU 1, bash wakes up process ls (pid 7971).
Line 2, on CPU 0, the idle task switches to the ls task.
Line 3, on CPU 1, bash switches back to idle
Line 4, on CPU 1, idle switches to the ls task??
Lines 5-7, on CPU 0, ls wakes up the migration task and the migration task runs Line 8, on CPU 1 we see ls running and waking up a task with pid 598.

This strange trace is because the clocks between CPU 0 and 1 are off. This box that ran this trace did have out of sync CPUS, so the numbers are much closer on this box than if I were to use sched_clock.

The proper trace should have looked like this:

1:            bash-3498  [01]  5459.824565:      0:140:R   +  7971:120:R
2:          <idle>-0     [00]  5459.824836:      0:140:R ==>  7971:120:R
3:            bash-3498  [01]  5459.824984:   3498:120:S ==>     0:140:R
5:              ls-7971  [00]  5459.825380:   7971:120:R   +     3:  0:S
6:              ls-7971  [00]  5459.825384:   7971:120:R ==>     3:  0:R
7:     migration/0-3     [00]  5459.825401:      3:  0:S ==>     0:140:R
4:          <idle>-0     [01]  5459.825342:      0:140:R ==>  7971:120:R
8:              ls-7971  [01]  5459.825565:   7971:120:R   +   598:115:S

I moved 4 between 7 and 8. The trace looks much better.

Another thing about the cpu_clock and the difficulties of using both the gtod and the tsc. I just found out that the gtod is affected by the NTP algorithm. Which means that the changes between making the TSC sync with the gtod, will have extra drifts since the TSC multiplier is now fighting with the NTP multiplier.

The cpu_clock when having an unstable TSC or out of sync TSCs does very well with keeping in sync. But it is very difficult to have it perfectly accurate. The above inaccurate trace was caused by having the TSCs out of sync by 60 usecs. Which is damn good accuracy. But as we see, can still show lack of integrity in the order of events.

-- Steve

so it's off by 60 usecs. That matters to the chronology of SMP events, and to the irqsoff and preemptoff tracers - if we update the clock incorrectly - i.e. if we modify the clock across CPUs so that a running CPU can see an 'involuntary' jump in local time.

that should be fixed then - and all tracers (and the scheduler) will improve - instead of having this special-case.

Ingo

Usually the jump is caused by the clock getting too far away from the gtod clock. The way the current code works is to look at the gtod at every tick and also record the TSC and jiffies. When we read the cpu_clock, it reads the TSC, calculates the delta from the last read (may be from the tick if it is the first read since tick), and adds the delta to the clock. To handle strange behaviours with TSC, if the TSC is too big we do not add the full delta but instead put the clock to the max allowable, or if we are already greater than or equal to the max, just add one nanosecond.

This causes some strange behaviour with the traces.

I added a multiplier to the tsc delta to try to keep it close to the gtod clock. But there's still issues. No multiplier is perfect and we still have drifts. The gtod itself is affected by the NTP and changes as well.

Two TSCs with different freqs on the same box will have an inaccuracy. This is a very difficult problem to solve, and I'm not sure we can do much better than the 60 microseconds that we currently have.

Even with insync TSCs, we see that the comparison to the GTOD causes jumps, due to drifts between the two clocks.

I still like to have the special cases for the per CPU tracers. We can get rid of it when (if) we fix the issues for the other tracers. Not adding the special case for those tracers wont make us work faster on this problem. But it will keep people from using those tracers because the results will be meaningless.

-- Steve

The acpi idle waits calls local_irq_save and then uses mwait to go into idle. The tracer gets reenabled at local_irq_save but does not detect that the idle allows for wake ups.

This patch adds code to disable the tracing when acpi puts the CPU to idle.

Index: linux-tip.git/drivers/acpi/processor_idle.c
===================================================================
@@ -272,6 +272,8 @@ static atomic_t c3_cpu_count;
 /* Common C-state entry for C2, C3, .. */
 static void acpi_cstate_enter(struct acpi_processor_cx *cstate)
 {
+	/* Don't trace irqs off for idle */
+	stop_critical_timings();
 	if (cstate->entry_method == ACPI_CSTATE_FFH) {
 		/* Call into architectural FFH based C-state */
 		acpi_processor_ffh_cstate_enter(cstate);

@@ -284,6 +286,7 @@ static void acpi_cstate_enter(struct acp
 		   gets asserted in time to freeze execution properly. */
 		unused = inl(acpi_gbl_FADT.xpm_timer_block.address);
 	}
+	start_critical_timings();
 }
 #endif /* !CONFIG_CPU_IDLE */
 

@@ -1418,6 +1421,8 @@ static inline void acpi_idle_update_bm_r
  */
 static inline void acpi_idle_do_entry(struct acpi_processor_cx *cx)
 {
+	/* Don't trace irqs off for idle */
+	stop_critical_timings();
 	if (cx->entry_method == ACPI_CSTATE_FFH) {
 		/* Call into architectural FFH based C-state */
 		acpi_processor_ffh_cstate_enter(cx);

@@ -1432,6 +1437,7 @@ static inline void acpi_idle_do_entry(st
 		   gets asserted in time to freeze execution properly. */
 		unused = inl(acpi_gbl_FADT.xpm_timer_block.address);
 	}
+	start_critical_timings();
 }
 
 /**

applied to tip/tracing/urgent - thanks Steve.

Ingo