[PATCH 0/2] ftrace minor updates

[PATCH 0/2] ftrace minor updates

[Steven Rostedt]

The following two patches help the latency tracers of ftrace.

-- Steve

[PATCH 1/2] ftrace: single CPU tracers use CPU clock

[Steven Rostedt]

[-- Attachment #1: ftrace-local-cpu-clock-use.patch --]
[-- Type: text/plain, Size: 3807 bytes --]

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.

Signed-off-by: Steven Rostedt <srostedt@redhat.com>

---
 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
===================================================================
--- linux-tip.git.orig/kernel/trace/trace.c	2008-07-25 17:55:49.000000000 -0400
+++ linux-tip.git/kernel/trace/trace.c	2008-07-25 17:55:50.000000000 -0400
@@ -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
===================================================================
--- linux-tip.git.orig/kernel/trace/trace.h	2008-07-25 17:55:49.000000000 -0400
+++ linux-tip.git/kernel/trace/trace.h	2008-07-25 17:55:50.000000000 -0400
@@ -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
===================================================================
--- linux-tip.git.orig/kernel/trace/trace_irqsoff.c	2008-07-25 17:55:49.000000000 -0400
+++ linux-tip.git/kernel/trace/trace_irqsoff.c	2008-07-25 17:55:50.000000000 -0400
@@ -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

-- 

[PATCH 2/2] ftrace: disable tracing on acpi idle calls

[Steven Rostedt]

[-- Attachment #1: ftrace-stop-tracing-acpi-mwait.patch --]
[-- Type: text/plain, Size: 1712 bytes --]

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.

Signed-off-by: Steven Rostedt <srostedt@redhat.com>

Index: linux-tip.git/drivers/acpi/processor_idle.c
===================================================================
--- linux-tip.git.orig/drivers/acpi/processor_idle.c
+++ 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();
 }
 
 /**

-- 

Re: [PATCH 1/2] ftrace: single CPU tracers use CPU clock

[Ingo Molnar]

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

> 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.

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

	Ingo

Re: [PATCH 2/2] ftrace: disable tracing on acpi idle calls

[Ingo Molnar]

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

> 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.

applied to tip/tracing/urgent - thanks Steve.

	Ingo

Re: [PATCH 1/2] ftrace: single CPU tracers use CPU clock

[Steven Rostedt]

On Sat, 26 Jul 2008, Ingo Molnar wrote:

>
> * Steven Rostedt <rostedt@goodmis.org> wrote:
>
> > 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.
> >

[...]

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

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

Re: [PATCH 1/2] ftrace: single CPU tracers use CPU clock

[Ingo Molnar]

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

> > this is not a good idea. We want to fix cpu_clock(), not work around 
> > any deficiencies it might have.
> 
> 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??

define '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.

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

Re: [PATCH 1/2] ftrace: single CPU tracers use CPU clock

[Steven Rostedt]

On Sat, 26 Jul 2008, Ingo Molnar wrote:

>
> * Steven Rostedt <rostedt@goodmis.org> wrote:
>
> > > this is not a good idea. We want to fix cpu_clock(), not work around
> > > any deficiencies it might have.
> >
> > 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??
>
> define 'stable TSC' ;-)

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


>
> > 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.
>
> 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?

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

Re: [PATCH 1/2] ftrace: single CPU tracers use CPU clock

[Ingo Molnar]

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

> > 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?
> 
> 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.

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

Re: [PATCH 1/2] ftrace: single CPU tracers use CPU clock

[Steven Rostedt]

On Sat, 26 Jul 2008, Ingo Molnar wrote:
>
> 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.

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.


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

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