[PATCH 2/2] tracing/function-graph-tracer: use the more lightweight local clock

[PATCH 2/2] tracing/function-graph-tracer: use the more lightweight local clock

[Frederic Weisbecker]

Impact: decrease hangs risks with the graph tracer on slow systems

Since the function graph tracer can spend too much time on timer interrupts,
it's better now to use the more lightweight local clock. Anyway, the function graph
traces are more reliable on a per cpu trace.

Signed-off-by: Frederic Weisbecker <fweisbec@gmail.com>
---
 arch/x86/kernel/ftrace.c             |    2 +-
 kernel/trace/trace_functions_graph.c |    2 +-
 2 files changed, 2 insertions(+), 2 deletions(-)

diff --git a/arch/x86/kernel/ftrace.c b/arch/x86/kernel/ftrace.c
index 3925ec0..40960c2 100644
--- a/arch/x86/kernel/ftrace.c
+++ b/arch/x86/kernel/ftrace.c
@@ -436,7 +436,7 @@ void prepare_ftrace_return(unsigned long *parent, unsigned long self_addr)
 		return;
 	}
 
-	calltime = cpu_clock(raw_smp_processor_id());
+	calltime = sched_clock();
 
 	if (ftrace_push_return_trace(old, calltime,
 				self_addr, &trace.depth) == -EBUSY) {
diff --git a/kernel/trace/trace_functions_graph.c b/kernel/trace/trace_functions_graph.c
index 2461732..c5038f4 100644
--- a/kernel/trace/trace_functions_graph.c
+++ b/kernel/trace/trace_functions_graph.c
@@ -112,7 +112,7 @@ unsigned long ftrace_return_to_handler(void)
 	unsigned long ret;
 
 	ftrace_pop_return_trace(&trace, &ret);
-	trace.rettime = cpu_clock(raw_smp_processor_id());
+	trace.rettime = sched_clock();
 	ftrace_graph_return(&trace);
 
 	if (unlikely(!ret)) {
-- 
1.6.1

Re: [PATCH 2/2] tracing/function-graph-tracer: use the more lightweight local clock

[Frederic Weisbecker]

On Thu, Mar 05, 2009 at 01:49:22AM +0100, Frederic Weisbecker wrote:
> Impact: decrease hangs risks with the graph tracer on slow systems
> 
> Since the function graph tracer can spend too much time on timer interrupts,
> it's better now to use the more lightweight local clock. Anyway, the function graph
> traces are more reliable on a per cpu trace.
> 
> Signed-off-by: Frederic Weisbecker <fweisbec@gmail.com>
> ---
>  arch/x86/kernel/ftrace.c             |    2 +-
>  kernel/trace/trace_functions_graph.c |    2 +-
>  2 files changed, 2 insertions(+), 2 deletions(-)
> 
> diff --git a/arch/x86/kernel/ftrace.c b/arch/x86/kernel/ftrace.c
> index 3925ec0..40960c2 100644
> --- a/arch/x86/kernel/ftrace.c
> +++ b/arch/x86/kernel/ftrace.c
> @@ -436,7 +436,7 @@ void prepare_ftrace_return(unsigned long *parent, unsigned long self_addr)
>  		return;
>  	}
>  
> -	calltime = cpu_clock(raw_smp_processor_id());
> +	calltime = sched_clock();
>  
>  	if (ftrace_push_return_trace(old, calltime,
>  				self_addr, &trace.depth) == -EBUSY) {
> diff --git a/kernel/trace/trace_functions_graph.c b/kernel/trace/trace_functions_graph.c
> index 2461732..c5038f4 100644
> --- a/kernel/trace/trace_functions_graph.c
> +++ b/kernel/trace/trace_functions_graph.c
> @@ -112,7 +112,7 @@ unsigned long ftrace_return_to_handler(void)
>  	unsigned long ret;
>  
>  	ftrace_pop_return_trace(&trace, &ret);
> -	trace.rettime = cpu_clock(raw_smp_processor_id());
> +	trace.rettime = sched_clock();
>  	ftrace_graph_return(&trace);
>  
>  	if (unlikely(!ret)) {
> -- 
> 1.6.1
> 
> 


Note that these two patches solve the function graph tracer hangs you reported.
But there are still sometimes large latencies (which can reach 4 seconds) and
the reason seems to me obviously come from the timer interrupt tracing.
If you look at the following timer interrupt trace:

 0)   ==========> |
 0)               |          smp_apic_timer_interrupt() {
 0)               |            ack_APIC_irq() {
 0)               |              apic_write() {
 0)   3.597 us    |                native_apic_mem_write();
 0) + 13.203 us   |              }
 0) + 22.573 us   |            }
 0)               |            irq_enter() {
 0)   3.749 us    |              idle_cpu();
 0) + 14.016 us   |            }
 0)               |            tick_handle_periodic() {
 0)               |              tick_periodic() {
 0)   8.882 us    |                _spin_lock();
 0)               |                do_timer() {
 0)               |                  update_wall_time() {
 0)   3.720 us    |                    clocksource_read();
 0)   3.621 us    |                    update_xtime_cache();
 0)               |                    clocksource_get_next() {
 0)   6.355 us    |                      _spin_lock_irqsave();
 0)   5.862 us    |                      _spin_unlock_irqrestore();
 0) + 28.665 us   |                    }
 0) + 60.193 us   |                  }
 0) + 70.076 us   |                }
 0)   4.299 us    |                _spin_unlock();
 0)               |                update_process_times() {
 0)               |                  account_process_tick() {
 0)   4.603 us    |                    account_system_time();
 0) + 14.154 us   |                  }
 0)               |                  run_local_timers() {
 0)               |                    hrtimer_run_queues() {
 0)   3.784 us    |                      current_kernel_time();
 0)               |                      timespec_to_ktime() {
 0)   3.360 us    |                        ktime_set();
 0) + 12.532 us   |                      }
 0)               |                      timespec_to_ktime() {
 0)   3.216 us    |                        ktime_set();
 0) + 12.342 us   |                      }
 0)   6.177 us    |                      _spin_lock();
 0)   4.258 us    |                      _spin_unlock();
 0) + 74.455 us   |                    }
 0)               |                    raise_softirq() {
 0)               |                      raise_softirq_irqoff() {
 0) + 13.328 us   |                    }
 0)               |                    softlockup_tick() {
 0)   6.376 us    |                      get_timestamp();
 0) + 16.665 us   |                    }
 0) ! 126.019 us  |                  }
 0)               |                  rcu_pending() {
 0)               |                    __rcu_pending() {
 0)   3.753 us    |                      cpumask_check();
 0) + 14.203 us   |                    }
 0) + 23.865 us   |                  }
 0)               |                  rcu_check_callbacks() {
 0)   3.552 us    |                    idle_cpu();
 0)               |                    raise_rcu_softirq() {
 0)               |                      raise_softirq() {
 0)   3.340 us    |                        raise_softirq_irqoff();
 0) + 13.029 us   |                      }
 0) + 22.580 us   |                    }
 0) + 41.989 us   |                  }
 0)   3.597 us    |                  printk_tick();
 0)               |                  scheduler_tick() {
 0)               |                    ktime_get() {
 0)               |                      ktime_get_ts() {
 0)               |                        getnstimeofday() {
 0)   3.742 us    |                          clocksource_read();
 0) + 14.141 us   |                        }
 0)   3.291 us    |                        set_normalized_timespec();
 0) + 75.737 us   |                      }
 0)               |                      timespec_to_ktime() {
 0)   3.122 us    |                        ktime_set();
 0) + 12.275 us   |                      }
 0) ! 103.588 us  |                    }
 0)   6.814 us    |                    _spin_lock();
 0)   4.347 us    |                    update_rq_clock();
 0)               |                    task_tick_fair() {
 0)               |                      update_curr() {
 0)   3.280 us    |                        calc_delta_fair();
 0)               |                        update_min_vruntime() {
 0)   3.164 us    |                          max_vruntime();
 0) + 12.409 us   |                        }
 0)   3.415 us    |                        account_group_exec_runtime();
 0) + 40.947 us   |                      }
 0) + 50.545 us   |                    }
 0)               |                    perf_counter_task_tick() {
 0)               |                      perf_counter_task_sched_out() {
 0)               |                        __perf_counter_sched_out() {
 0)   6.940 us    |                          _spin_lock();
 0)   4.804 us    |                          _spin_unlock();
 0) + 28.069 us   |                        }
 0) + 37.414 us   |                      }
 0)               |                      perf_counter_task_sched_in() {
 0)   5.857 us    |                        _spin_lock();
 0)   4.405 us    |                        _spin_unlock();
 0) + 26.177 us   |                      }
 0) + 78.616 us   |                    }
 0)   4.018 us    |                    _spin_unlock();
 0)   3.187 us    |                    idle_cpu();
 0) ! 299.382 us  |                  }
 0)               |                  run_posix_cpu_timers() {
 0)   3.300 us    |                    task_cputime_zero();
 0)   3.256 us    |                    task_cputime_zero();
 0) + 21.977 us   |                  }
 0) ! 577.188 us  |                }
 0)   3.425 us    |                profile_tick();
 0) ! 698.681 us  |              }
 0) ! 707.982 us  |            }
 0)   3.275 us    |            perf_counter_unthrottle();
 0)               |            irq_exit() {
 0)               |              do_softirq() {
 0)               |                __do_softirq() {
 0)   4.372 us    |                  __local_bh_disable();
 0)               |                  run_timer_softirq() {
 0)   3.677 us    |                    hrtimer_run_pending();
 0)   7.721 us    |                    _spin_lock_irq();
 0)   3.441 us    |                    list_replace_init();
 0)   5.117 us    |                    _spin_unlock_irq();
 0) + 49.610 us   |                  }
 0)               |                  rcu_process_callbacks() {
 0)   5.340 us    |                    __rcu_process_callbacks();
 0)   3.695 us    |                    __rcu_process_callbacks();
 0) + 25.576 us   |                  }
 0)   4.666 us    |                  _local_bh_enable();
 0) ! 115.634 us  |                }
 0) ! 126.637 us  |              }
 0) ! 136.176 us  |            }
 0) ! 918.236 us  |          }
 0)   <========== |
 0) ! 1392.029 us |        }


It takes 1 ms to execute while tracing.
Considering my frequency is 250 Hz, it means 1/4 of the system is used
on timer interrupt while tracing.

For now the hang is fixed, but not the awful latency. And I'm just too frightened
to test it on 1000 Hz.

But I plan to add a kind of watchdog to check how many time we spent inside an
interrupt while graph tracing.
By checking this time against the current Hz value, I could decide to abort the tracing
for all irq.

Re: [PATCH 2/2] tracing/function-graph-tracer: use the more lightweight local clock

[Peter Zijlstra]

On Thu, 2009-03-05 at 02:19 +0100, Frederic Weisbecker wrote:

> It takes 1 ms to execute while tracing.
> Considering my frequency is 250 Hz, it means 1/4 of the system is used
> on timer interrupt while tracing.
> 
> For now the hang is fixed, but not the awful latency. And I'm just too frightened
> to test it on 1000 Hz.
> 
> But I plan to add a kind of watchdog to check how many time we spent inside an
> interrupt while graph tracing.
> By checking this time against the current Hz value, I could decide to abort the tracing
> for all irq.

That would basically render the thing useless :-(

Is it specifically function_graph that is so expensive? If so, is that
because of the function exit hook?

Re: [PATCH 2/2] tracing/function-graph-tracer: use the more lightweight local clock

[Frederic Weisbecker]

On Thu, Mar 05, 2009 at 08:30:13AM +0100, Peter Zijlstra wrote:
> On Thu, 2009-03-05 at 02:19 +0100, Frederic Weisbecker wrote:
> 
> > It takes 1 ms to execute while tracing.
> > Considering my frequency is 250 Hz, it means 1/4 of the system is used
> > on timer interrupt while tracing.
> > 
> > For now the hang is fixed, but not the awful latency. And I'm just too frightened
> > to test it on 1000 Hz.
> > 
> > But I plan to add a kind of watchdog to check how many time we spent inside an
> > interrupt while graph tracing.
> > By checking this time against the current Hz value, I could decide to abort the tracing
> > for all irq.
> 
> That would basically render the thing useless :-(


It would be only for slow machines :-)
I'm talking about something that happened on a Pentium II.

 
> Is it specifically function_graph that is so expensive? If so, is that
> because of the function exit hook?


Yes, specifically the function_graph, the function tracer is not concerned.
The function graph tracer takes more than double overhead compared to the function
tracer.

Usually the function tracer hooks directly the the function that insert the event, it's
pretty straightforward.

The function graph does much more work: 

entry: basic checks, take the time, push the infos on the stack, insert an event
       on the ring-buffer, hook the return value.
return: pop the infos from stack, insert an event on the ring-buffer, jump
        to the original caller.

It has a high cost... which makes me sad because I plan to port it in on Arm and I fear
the little Arm boad I recently purshased will not let me trace the interrupts without hanging...
:-(

I guess I should start thinking on some optimizations, perhaps using perfcounter?

Re: [PATCH 2/2] tracing/function-graph-tracer: use the more lightweight local clock

[Ingo Molnar]

* Frederic Weisbecker <fweisbec@gmail.com> wrote:

> On Thu, Mar 05, 2009 at 08:30:13AM +0100, Peter Zijlstra wrote:
> > On Thu, 2009-03-05 at 02:19 +0100, Frederic Weisbecker wrote:
> > 
> > > It takes 1 ms to execute while tracing.
> > > Considering my frequency is 250 Hz, it means 1/4 of the system is used
> > > on timer interrupt while tracing.
> > > 
> > > For now the hang is fixed, but not the awful latency. And I'm just too frightened
> > > to test it on 1000 Hz.
> > > 
> > > But I plan to add a kind of watchdog to check how many time we spent inside an
> > > interrupt while graph tracing.
> > > By checking this time against the current Hz value, I could decide to abort the tracing
> > > for all irq.
> > 
> > That would basically render the thing useless :-(
> 
> 
> It would be only for slow machines :-)
> I'm talking about something that happened on a Pentium II.
> 
>  
> > Is it specifically function_graph that is so expensive? If so, is that
> > because of the function exit hook?
> 
> 
> Yes, specifically the function_graph, the function tracer is 
> not concerned. The function graph tracer takes more than 
> double overhead compared to the function tracer.
> 
> Usually the function tracer hooks directly the the function 
> that insert the event, it's pretty straightforward.
> 
> The function graph does much more work: 
> 
> entry: basic checks, take the time, push the infos on the stack, insert an event
>        on the ring-buffer, hook the return value.
> return: pop the infos from stack, insert an event on the ring-buffer, jump
>         to the original caller.
> 
> It has a high cost... which makes me sad because I plan to 
> port it in on Arm and I fear the little Arm boad I recently 
> purshased will not let me trace the interrupts without 
> hanging...
> :-(
> 
> I guess I should start thinking on some optimizations, perhaps 
> using perfcounter?

yeah. perfcounters and KernelTop might not work on a PII CPU out 
of box though.

But hacking perfcounters and looking at perfstat/kerneltop 
output is serious amount of fun so if you are interested you 
could try to implement support for it. Do you have any box where 
perfcounters work? (that would be Core2 Intel boxes or pretty 
much any AMD box)

You could have a look at how oprofile works on your box - the 
code for PII CPUs should be in 
arch/x86/oprofile/op_model_ppro.c.

There's also hardcoded support for a single perfcounter in the 
nmi_watchdog=2 code, in arch/x86/kernel/cpu/perfctr-watchdog.c, 
for pretty much any x86 CPU that has a PMU.

Plus there's also the CPU documentation on Intel's site. It's 
quite well written and pretty well structured. The URL for the 
CPU's PMU ("Performance Monitoring") should be:

  http://download.intel.com/design/processor/manuals/253669.pdf

As a last resort ;-)

	Ingo

[tip:tracing/function-graph-tracer] tracing/function-graph-tracer: use the more lightweight local clock

[Frederic Weisbecker]

Commit-ID:  bf467399b5f6301e7a6dc21460e66b1f40e16c7e
Gitweb:     http://git.kernel.org/tip/bf467399b5f6301e7a6dc21460e66b1f40e16c7e
Author:     "Frederic Weisbecker" <fweisbec@gmail.com>
AuthorDate: Thu, 5 Mar 2009 01:49:22 +0100
Commit:     Ingo Molnar <mingo@elte.hu>
CommitDate: Thu, 5 Mar 2009 12:01:52 +0100

tracing/function-graph-tracer: use the more lightweight local clock

Impact: decrease hangs risks with the graph tracer on slow systems

Since the function graph tracer can spend too much time on timer
interrupts, it's better now to use the more lightweight local
clock. Anyway, the function graph traces are more reliable on a
per cpu trace.

Signed-off-by: Frederic Weisbecker <fweisbec@gmail.com>
Cc: Steven Rostedt <rostedt@goodmis.org>
Cc: Peter Zijlstra <peterz@infradead.org>
LKML-Reference: <49af243d.06e9300a.53ad.ffff840c@mx.google.com>
Signed-off-by: Ingo Molnar <mingo@elte.hu>


---
 arch/x86/kernel/ftrace.c             |    2 +-
 kernel/trace/trace_functions_graph.c |    2 +-
 2 files changed, 2 insertions(+), 2 deletions(-)

diff --git a/arch/x86/kernel/ftrace.c b/arch/x86/kernel/ftrace.c
index 3925ec0..a85da17 100644
--- a/arch/x86/kernel/ftrace.c
+++ b/arch/x86/kernel/ftrace.c
@@ -436,7 +436,7 @@ void prepare_ftrace_return(unsigned long *parent, unsigned long self_addr)
 		return;
 	}
 
-	calltime = cpu_clock(raw_smp_processor_id());
+	calltime = trace_clock_local();
 
 	if (ftrace_push_return_trace(old, calltime,
 				self_addr, &trace.depth) == -EBUSY) {
diff --git a/kernel/trace/trace_functions_graph.c b/kernel/trace/trace_functions_graph.c
index c009553..e527f2f 100644
--- a/kernel/trace/trace_functions_graph.c
+++ b/kernel/trace/trace_functions_graph.c
@@ -112,7 +112,7 @@ unsigned long ftrace_return_to_handler(void)
 	unsigned long ret;
 
 	ftrace_pop_return_trace(&trace, &ret);
-	trace.rettime = cpu_clock(raw_smp_processor_id());
+	trace.rettime = trace_clock_local();
 	ftrace_graph_return(&trace);
 
 	if (unlikely(!ret)) {

Re: [PATCH 2/2] tracing/function-graph-tracer: use the more lightweight local clock

[Ingo Molnar]

* Frederic Weisbecker <fweisbec@gmail.com> wrote:

> Impact: decrease hangs risks with the graph tracer on slow systems
> 
> Since the function graph tracer can spend too much time on 
> timer interrupts, it's better now to use the more lightweight 
> local clock. Anyway, the function graph traces are more 
> reliable on a per cpu trace.
> 
> Signed-off-by: Frederic Weisbecker <fweisbec@gmail.com>
> ---
>  arch/x86/kernel/ftrace.c             |    2 +-
>  kernel/trace/trace_functions_graph.c |    2 +-
>  2 files changed, 2 insertions(+), 2 deletions(-)
> 
> diff --git a/arch/x86/kernel/ftrace.c b/arch/x86/kernel/ftrace.c
> index 3925ec0..40960c2 100644
> --- a/arch/x86/kernel/ftrace.c
> +++ b/arch/x86/kernel/ftrace.c
> @@ -436,7 +436,7 @@ void prepare_ftrace_return(unsigned long *parent, unsigned long self_addr)
>  		return;
>  	}
>  
> -	calltime = cpu_clock(raw_smp_processor_id());
> +	calltime = sched_clock();

I changed this to trace_clock_local() :-)

(btw, we should turn trace_clock_local() into an inline 
function)

There will be one problem though: function trace elapsed time 
measurements across idle. Those are not correctly measured by 
the local clock.

	Ingo

Re: [PATCH 2/2] tracing/function-graph-tracer: use the more lightweight local clock

[Frederic Weisbecker]

On Thu, Mar 05, 2009 at 11:56:52AM +0100, Ingo Molnar wrote:
> 
> * Frederic Weisbecker <fweisbec@gmail.com> wrote:
> 
> > On Thu, Mar 05, 2009 at 08:30:13AM +0100, Peter Zijlstra wrote:
> > > On Thu, 2009-03-05 at 02:19 +0100, Frederic Weisbecker wrote:
> > > 
> > > > It takes 1 ms to execute while tracing.
> > > > Considering my frequency is 250 Hz, it means 1/4 of the system is used
> > > > on timer interrupt while tracing.
> > > > 
> > > > For now the hang is fixed, but not the awful latency. And I'm just too frightened
> > > > to test it on 1000 Hz.
> > > > 
> > > > But I plan to add a kind of watchdog to check how many time we spent inside an
> > > > interrupt while graph tracing.
> > > > By checking this time against the current Hz value, I could decide to abort the tracing
> > > > for all irq.
> > > 
> > > That would basically render the thing useless :-(
> > 
> > 
> > It would be only for slow machines :-)
> > I'm talking about something that happened on a Pentium II.
> > 
> >  
> > > Is it specifically function_graph that is so expensive? If so, is that
> > > because of the function exit hook?
> > 
> > 
> > Yes, specifically the function_graph, the function tracer is 
> > not concerned. The function graph tracer takes more than 
> > double overhead compared to the function tracer.
> > 
> > Usually the function tracer hooks directly the the function 
> > that insert the event, it's pretty straightforward.
> > 
> > The function graph does much more work: 
> > 
> > entry: basic checks, take the time, push the infos on the stack, insert an event
> >        on the ring-buffer, hook the return value.
> > return: pop the infos from stack, insert an event on the ring-buffer, jump
> >         to the original caller.
> > 
> > It has a high cost... which makes me sad because I plan to 
> > port it in on Arm and I fear the little Arm boad I recently 
> > purshased will not let me trace the interrupts without 
> > hanging...
> > :-(
> > 
> > I guess I should start thinking on some optimizations, perhaps 
> > using perfcounter?
> 
> yeah. perfcounters and KernelTop might not work on a PII CPU out 
> of box though.
> 
> But hacking perfcounters and looking at perfstat/kerneltop 
> output is serious amount of fun so if you are interested you 
> could try to implement support for it. Do you have any box where 
> perfcounters work? (that would be Core2 Intel boxes or pretty 
> much any AMD box)
> 
> You could have a look at how oprofile works on your box - the 
> code for PII CPUs should be in 
> arch/x86/oprofile/op_model_ppro.c.
> 
> There's also hardcoded support for a single perfcounter in the 
> nmi_watchdog=2 code, in arch/x86/kernel/cpu/perfctr-watchdog.c, 
> for pretty much any x86 CPU that has a PMU.
> 
> Plus there's also the CPU documentation on Intel's site. It's 
> quite well written and pretty well structured. The URL for the 
> CPU's PMU ("Performance Monitoring") should be:
> 
>   http://download.intel.com/design/processor/manuals/253669.pdf
> 
> As a last resort ;-)
> 
> 	Ingo

Ah yes, That could be fun!
So, by reading your description, it should work on my labtop I guess?

-> Intel(R) Pentium(R) Dual  CPU  T2310  @ 1.46GHz

Anyway, I will give it a try and see what I can do.
Thanks for the pointers.

[tip:tracing/function-graph-tracer] tracing/function-graph-tracer: use the more lightweight local clock

[Frederic Weisbecker]

Commit-ID:  0012693ad4f636c720fed3802027f9427962f540
Gitweb:     http://git.kernel.org/tip/0012693ad4f636c720fed3802027f9427962f540
Author:     "Frederic Weisbecker" <fweisbec@gmail.com>
AuthorDate: Thu, 5 Mar 2009 01:49:22 +0100
Commit:     Ingo Molnar <mingo@elte.hu>
CommitDate: Thu, 5 Mar 2009 12:14:41 +0100

tracing/function-graph-tracer: use the more lightweight local clock

Impact: decrease hangs risks with the graph tracer on slow systems

Since the function graph tracer can spend too much time on timer
interrupts, it's better now to use the more lightweight local
clock. Anyway, the function graph traces are more reliable on a
per cpu trace.

Signed-off-by: Frederic Weisbecker <fweisbec@gmail.com>
Cc: Steven Rostedt <rostedt@goodmis.org>
Cc: Peter Zijlstra <peterz@infradead.org>
LKML-Reference: <49af243d.06e9300a.53ad.ffff840c@mx.google.com>
Signed-off-by: Ingo Molnar <mingo@elte.hu>


---
 arch/x86/kernel/ftrace.c             |    2 +-
 include/linux/ftrace.h               |   13 +++++++------
 kernel/trace/trace_functions_graph.c |    2 +-
 3 files changed, 9 insertions(+), 8 deletions(-)

diff --git a/arch/x86/kernel/ftrace.c b/arch/x86/kernel/ftrace.c
index 3925ec0..a85da17 100644
--- a/arch/x86/kernel/ftrace.c
+++ b/arch/x86/kernel/ftrace.c
@@ -436,7 +436,7 @@ void prepare_ftrace_return(unsigned long *parent, unsigned long self_addr)
 		return;
 	}
 
-	calltime = cpu_clock(raw_smp_processor_id());
+	calltime = trace_clock_local();
 
 	if (ftrace_push_return_trace(old, calltime,
 				self_addr, &trace.depth) == -EBUSY) {
diff --git a/include/linux/ftrace.h b/include/linux/ftrace.h
index 1f69ac7..6ea62ac 100644
--- a/include/linux/ftrace.h
+++ b/include/linux/ftrace.h
@@ -1,15 +1,16 @@
 #ifndef _LINUX_FTRACE_H
 #define _LINUX_FTRACE_H
 
-#include <linux/linkage.h>
-#include <linux/fs.h>
-#include <linux/ktime.h>
-#include <linux/init.h>
-#include <linux/types.h>
-#include <linux/module.h>
+#include <linux/trace_clock.h>
 #include <linux/kallsyms.h>
+#include <linux/linkage.h>
 #include <linux/bitops.h>
+#include <linux/module.h>
+#include <linux/ktime.h>
 #include <linux/sched.h>
+#include <linux/types.h>
+#include <linux/init.h>
+#include <linux/fs.h>
 
 #include <asm/ftrace.h>
 
diff --git a/kernel/trace/trace_functions_graph.c b/kernel/trace/trace_functions_graph.c
index c009553..e527f2f 100644
--- a/kernel/trace/trace_functions_graph.c
+++ b/kernel/trace/trace_functions_graph.c
@@ -112,7 +112,7 @@ unsigned long ftrace_return_to_handler(void)
 	unsigned long ret;
 
 	ftrace_pop_return_trace(&trace, &ret);
-	trace.rettime = cpu_clock(raw_smp_processor_id());
+	trace.rettime = trace_clock_local();
 	ftrace_graph_return(&trace);
 
 	if (unlikely(!ret)) {

Re: [PATCH 2/2] tracing/function-graph-tracer: use the more lightweight local clock

[Frederic Weisbecker]

On Thu, Mar 05, 2009 at 12:04:33PM +0100, Ingo Molnar wrote:
> 
> * Frederic Weisbecker <fweisbec@gmail.com> wrote:
> 
> > Impact: decrease hangs risks with the graph tracer on slow systems
> > 
> > Since the function graph tracer can spend too much time on 
> > timer interrupts, it's better now to use the more lightweight 
> > local clock. Anyway, the function graph traces are more 
> > reliable on a per cpu trace.
> > 
> > Signed-off-by: Frederic Weisbecker <fweisbec@gmail.com>
> > ---
> >  arch/x86/kernel/ftrace.c             |    2 +-
> >  kernel/trace/trace_functions_graph.c |    2 +-
> >  2 files changed, 2 insertions(+), 2 deletions(-)
> > 
> > diff --git a/arch/x86/kernel/ftrace.c b/arch/x86/kernel/ftrace.c
> > index 3925ec0..40960c2 100644
> > --- a/arch/x86/kernel/ftrace.c
> > +++ b/arch/x86/kernel/ftrace.c
> > @@ -436,7 +436,7 @@ void prepare_ftrace_return(unsigned long *parent, unsigned long self_addr)
> >  		return;
> >  	}
> >  
> > -	calltime = cpu_clock(raw_smp_processor_id());
> > +	calltime = sched_clock();
> 
> I changed this to trace_clock_local() :-)
> 
> (btw, we should turn trace_clock_local() into an inline 
> function)


Ok.
 
> There will be one problem though: function trace elapsed time 
> measurements across idle. Those are not correctly measured by 
> the local clock.

Oh, why? If I'm not wrong it uses sched_clock() which uses tsc on x86.
And this register always goes forward at the same rate. Unless some
Cpu decrease their frequency while beeing idle for some time and then
become unreliable?

> 	Ingo

Re: [PATCH 2/2] tracing/function-graph-tracer: use the more lightweight local clock

[Ingo Molnar]

* Frederic Weisbecker <fweisbec@gmail.com> wrote:

> > There will be one problem though: function trace elapsed 
> > time measurements across idle. Those are not correctly 
> > measured by the local clock.
> 
> Oh, why? If I'm not wrong it uses sched_clock() which uses tsc 
> on x86. And this register always goes forward at the same 
> rate. Unless some Cpu decrease their frequency while beeing 
> idle for some time and then become unreliable?

TSC stops in idle on many CPUs.

	Ingo

Re: [PATCH 2/2] tracing/function-graph-tracer: use the more lightweight local clock

[Ingo Molnar]

* Frederic Weisbecker <fweisbec@gmail.com> wrote:

> On Thu, Mar 05, 2009 at 11:56:52AM +0100, Ingo Molnar wrote:
> > 
> > * Frederic Weisbecker <fweisbec@gmail.com> wrote:
> > 
> > > On Thu, Mar 05, 2009 at 08:30:13AM +0100, Peter Zijlstra wrote:
> > > > On Thu, 2009-03-05 at 02:19 +0100, Frederic Weisbecker wrote:
> > > > 
> > > > > It takes 1 ms to execute while tracing.
> > > > > Considering my frequency is 250 Hz, it means 1/4 of the system is used
> > > > > on timer interrupt while tracing.
> > > > > 
> > > > > For now the hang is fixed, but not the awful latency. And I'm just too frightened
> > > > > to test it on 1000 Hz.
> > > > > 
> > > > > But I plan to add a kind of watchdog to check how many time we spent inside an
> > > > > interrupt while graph tracing.
> > > > > By checking this time against the current Hz value, I could decide to abort the tracing
> > > > > for all irq.
> > > > 
> > > > That would basically render the thing useless :-(
> > > 
> > > 
> > > It would be only for slow machines :-)
> > > I'm talking about something that happened on a Pentium II.
> > > 
> > >  
> > > > Is it specifically function_graph that is so expensive? If so, is that
> > > > because of the function exit hook?
> > > 
> > > 
> > > Yes, specifically the function_graph, the function tracer is 
> > > not concerned. The function graph tracer takes more than 
> > > double overhead compared to the function tracer.
> > > 
> > > Usually the function tracer hooks directly the the function 
> > > that insert the event, it's pretty straightforward.
> > > 
> > > The function graph does much more work: 
> > > 
> > > entry: basic checks, take the time, push the infos on the stack, insert an event
> > >        on the ring-buffer, hook the return value.
> > > return: pop the infos from stack, insert an event on the ring-buffer, jump
> > >         to the original caller.
> > > 
> > > It has a high cost... which makes me sad because I plan to 
> > > port it in on Arm and I fear the little Arm boad I recently 
> > > purshased will not let me trace the interrupts without 
> > > hanging...
> > > :-(
> > > 
> > > I guess I should start thinking on some optimizations, perhaps 
> > > using perfcounter?
> > 
> > yeah. perfcounters and KernelTop might not work on a PII CPU out 
> > of box though.
> > 
> > But hacking perfcounters and looking at perfstat/kerneltop 
> > output is serious amount of fun so if you are interested you 
> > could try to implement support for it. Do you have any box where 
> > perfcounters work? (that would be Core2 Intel boxes or pretty 
> > much any AMD box)
> > 
> > You could have a look at how oprofile works on your box - the 
> > code for PII CPUs should be in 
> > arch/x86/oprofile/op_model_ppro.c.
> > 
> > There's also hardcoded support for a single perfcounter in the 
> > nmi_watchdog=2 code, in arch/x86/kernel/cpu/perfctr-watchdog.c, 
> > for pretty much any x86 CPU that has a PMU.
> > 
> > Plus there's also the CPU documentation on Intel's site. It's 
> > quite well written and pretty well structured. The URL for the 
> > CPU's PMU ("Performance Monitoring") should be:
> > 
> >   http://download.intel.com/design/processor/manuals/253669.pdf
> > 
> > As a last resort ;-)
> > 
> > 	Ingo
> 
> Ah yes, That could be fun!
> So, by reading your description, it should work on my labtop I guess?
>
> -> Intel(R) Pentium(R) Dual  CPU  T2310  @ 1.46GHz

Yeah, should work fine there - so that should be a good 
reference point to start off. Let me know if you see any 
bugs/problems.

> Anyway, I will give it a try and see what I can do.
> Thanks for the pointers.

You are welcome.

	Ingo

Re: [PATCH 2/2] tracing/function-graph-tracer: use the more lightweight local clock

[Frederic Weisbecker]

On Thu, Mar 05, 2009 at 12:56:52PM +0100, Ingo Molnar wrote:
> 
> * Frederic Weisbecker <fweisbec@gmail.com> wrote:
> 
> > On Thu, Mar 05, 2009 at 11:56:52AM +0100, Ingo Molnar wrote:
> > > 
> > > * Frederic Weisbecker <fweisbec@gmail.com> wrote:
> > > 
> > > > On Thu, Mar 05, 2009 at 08:30:13AM +0100, Peter Zijlstra wrote:
> > > > > On Thu, 2009-03-05 at 02:19 +0100, Frederic Weisbecker wrote:
> > > > > 
> > > > > > It takes 1 ms to execute while tracing.
> > > > > > Considering my frequency is 250 Hz, it means 1/4 of the system is used
> > > > > > on timer interrupt while tracing.
> > > > > > 
> > > > > > For now the hang is fixed, but not the awful latency. And I'm just too frightened
> > > > > > to test it on 1000 Hz.
> > > > > > 
> > > > > > But I plan to add a kind of watchdog to check how many time we spent inside an
> > > > > > interrupt while graph tracing.
> > > > > > By checking this time against the current Hz value, I could decide to abort the tracing
> > > > > > for all irq.
> > > > > 
> > > > > That would basically render the thing useless :-(
> > > > 
> > > > 
> > > > It would be only for slow machines :-)
> > > > I'm talking about something that happened on a Pentium II.
> > > > 
> > > >  
> > > > > Is it specifically function_graph that is so expensive? If so, is that
> > > > > because of the function exit hook?
> > > > 
> > > > 
> > > > Yes, specifically the function_graph, the function tracer is 
> > > > not concerned. The function graph tracer takes more than 
> > > > double overhead compared to the function tracer.
> > > > 
> > > > Usually the function tracer hooks directly the the function 
> > > > that insert the event, it's pretty straightforward.
> > > > 
> > > > The function graph does much more work: 
> > > > 
> > > > entry: basic checks, take the time, push the infos on the stack, insert an event
> > > >        on the ring-buffer, hook the return value.
> > > > return: pop the infos from stack, insert an event on the ring-buffer, jump
> > > >         to the original caller.
> > > > 
> > > > It has a high cost... which makes me sad because I plan to 
> > > > port it in on Arm and I fear the little Arm boad I recently 
> > > > purshased will not let me trace the interrupts without 
> > > > hanging...
> > > > :-(
> > > > 
> > > > I guess I should start thinking on some optimizations, perhaps 
> > > > using perfcounter?
> > > 
> > > yeah. perfcounters and KernelTop might not work on a PII CPU out 
> > > of box though.
> > > 
> > > But hacking perfcounters and looking at perfstat/kerneltop 
> > > output is serious amount of fun so if you are interested you 
> > > could try to implement support for it. Do you have any box where 
> > > perfcounters work? (that would be Core2 Intel boxes or pretty 
> > > much any AMD box)
> > > 
> > > You could have a look at how oprofile works on your box - the 
> > > code for PII CPUs should be in 
> > > arch/x86/oprofile/op_model_ppro.c.
> > > 
> > > There's also hardcoded support for a single perfcounter in the 
> > > nmi_watchdog=2 code, in arch/x86/kernel/cpu/perfctr-watchdog.c, 
> > > for pretty much any x86 CPU that has a PMU.
> > > 
> > > Plus there's also the CPU documentation on Intel's site. It's 
> > > quite well written and pretty well structured. The URL for the 
> > > CPU's PMU ("Performance Monitoring") should be:
> > > 
> > >   http://download.intel.com/design/processor/manuals/253669.pdf
> > > 
> > > As a last resort ;-)
> > > 
> > > 	Ingo
> > 
> > Ah yes, That could be fun!
> > So, by reading your description, it should work on my labtop I guess?
> >
> > -> Intel(R) Pentium(R) Dual  CPU  T2310  @ 1.46GHz
> 
> Yeah, should work fine there - so that should be a good 
> reference point to start off. Let me know if you see any 
> bugs/problems.
> 
> > Anyway, I will give it a try and see what I can do.
> > Thanks for the pointers.
> 
> You are welcome.
> 
> 	Ingo

Ho, that's impressive:

$ ./perfstat /bin/echo 1
1

 Performance counter stats for '/bin/echo':

       5.681909  task clock ticks     (msecs)

              2  CPU migrations       (events)
              9  context switches     (events)
            422  pagefaults           (events)
        4986950  CPU cycles           (events)
        4870587  instructions         (events)
          62881  cache references     (events)
           4882  cache misses         (events)

 Wall-clock time elapsed:     9.046821 msecs


So I guess that for it to be useful on fine grained profiling,
it's better to include the percounters syscalls inside the application
to profile a single function for example?

I've parsed a bit the intel documentation and perfcounters source code.
It looks like the current implementation for intel and amd share enough similar
properties so that they have been factorized in a single file.

This similar property is the use of an msr, while P6 family use the pmc.

Perhaps I can expand the struct pmc_x86_ops to guess whether we want to use
rdmsr or rdpmc.

Hmm it seems the implementation would be enough different to deserve a new file for
P6.
Will see...

Re: [PATCH 2/2] tracing/function-graph-tracer: use the more lightweight local clock

[Ingo Molnar]

* Frederic Weisbecker <fweisbec@gmail.com> wrote:

> On Thu, Mar 05, 2009 at 12:56:52PM +0100, Ingo Molnar wrote:
> > 
> > * Frederic Weisbecker <fweisbec@gmail.com> wrote:
> > 
> > > On Thu, Mar 05, 2009 at 11:56:52AM +0100, Ingo Molnar wrote:
> > > > 
> > > > * Frederic Weisbecker <fweisbec@gmail.com> wrote:
> > > > 
> > > > > On Thu, Mar 05, 2009 at 08:30:13AM +0100, Peter Zijlstra wrote:
> > > > > > On Thu, 2009-03-05 at 02:19 +0100, Frederic Weisbecker wrote:
> > > > > > 
> > > > > > > It takes 1 ms to execute while tracing.
> > > > > > > Considering my frequency is 250 Hz, it means 1/4 of the system is used
> > > > > > > on timer interrupt while tracing.
> > > > > > > 
> > > > > > > For now the hang is fixed, but not the awful latency. And I'm just too frightened
> > > > > > > to test it on 1000 Hz.
> > > > > > > 
> > > > > > > But I plan to add a kind of watchdog to check how many time we spent inside an
> > > > > > > interrupt while graph tracing.
> > > > > > > By checking this time against the current Hz value, I could decide to abort the tracing
> > > > > > > for all irq.
> > > > > > 
> > > > > > That would basically render the thing useless :-(
> > > > > 
> > > > > 
> > > > > It would be only for slow machines :-)
> > > > > I'm talking about something that happened on a Pentium II.
> > > > > 
> > > > >  
> > > > > > Is it specifically function_graph that is so expensive? If so, is that
> > > > > > because of the function exit hook?
> > > > > 
> > > > > 
> > > > > Yes, specifically the function_graph, the function tracer is 
> > > > > not concerned. The function graph tracer takes more than 
> > > > > double overhead compared to the function tracer.
> > > > > 
> > > > > Usually the function tracer hooks directly the the function 
> > > > > that insert the event, it's pretty straightforward.
> > > > > 
> > > > > The function graph does much more work: 
> > > > > 
> > > > > entry: basic checks, take the time, push the infos on the stack, insert an event
> > > > >        on the ring-buffer, hook the return value.
> > > > > return: pop the infos from stack, insert an event on the ring-buffer, jump
> > > > >         to the original caller.
> > > > > 
> > > > > It has a high cost... which makes me sad because I plan to 
> > > > > port it in on Arm and I fear the little Arm boad I recently 
> > > > > purshased will not let me trace the interrupts without 
> > > > > hanging...
> > > > > :-(
> > > > > 
> > > > > I guess I should start thinking on some optimizations, perhaps 
> > > > > using perfcounter?
> > > > 
> > > > yeah. perfcounters and KernelTop might not work on a PII CPU out 
> > > > of box though.
> > > > 
> > > > But hacking perfcounters and looking at perfstat/kerneltop 
> > > > output is serious amount of fun so if you are interested you 
> > > > could try to implement support for it. Do you have any box where 
> > > > perfcounters work? (that would be Core2 Intel boxes or pretty 
> > > > much any AMD box)
> > > > 
> > > > You could have a look at how oprofile works on your box - the 
> > > > code for PII CPUs should be in 
> > > > arch/x86/oprofile/op_model_ppro.c.
> > > > 
> > > > There's also hardcoded support for a single perfcounter in the 
> > > > nmi_watchdog=2 code, in arch/x86/kernel/cpu/perfctr-watchdog.c, 
> > > > for pretty much any x86 CPU that has a PMU.
> > > > 
> > > > Plus there's also the CPU documentation on Intel's site. It's 
> > > > quite well written and pretty well structured. The URL for the 
> > > > CPU's PMU ("Performance Monitoring") should be:
> > > > 
> > > >   http://download.intel.com/design/processor/manuals/253669.pdf
> > > > 
> > > > As a last resort ;-)
> > > > 
> > > > 	Ingo
> > > 
> > > Ah yes, That could be fun!
> > > So, by reading your description, it should work on my labtop I guess?
> > >
> > > -> Intel(R) Pentium(R) Dual  CPU  T2310  @ 1.46GHz
> > 
> > Yeah, should work fine there - so that should be a good 
> > reference point to start off. Let me know if you see any 
> > bugs/problems.
> > 
> > > Anyway, I will give it a try and see what I can do.
> > > Thanks for the pointers.
> > 
> > You are welcome.
> > 
> > 	Ingo
> 
> Ho, that's impressive:
> 
> $ ./perfstat /bin/echo 1
> 1
> 
>  Performance counter stats for '/bin/echo':
> 
>        5.681909  task clock ticks     (msecs)
> 
>               2  CPU migrations       (events)
>               9  context switches     (events)
>             422  pagefaults           (events)
>         4986950  CPU cycles           (events)
>         4870587  instructions         (events)
>           62881  cache references     (events)
>            4882  cache misses         (events)
> 
>  Wall-clock time elapsed:     9.046821 msecs
> 
> So I guess that for it to be useful on fine grained profiling, 
> it's better to include the percounters syscalls inside the 
> application to profile a single function for example?

Correct, it takes 4.8 million instructions to execute a simple 
shell script on Linux ...

For your purposes to profile the function tracer, kerneltop is a 
much more natural choice.

perfstat is best when used for performance/behavioral 
comparisons of a given workload. It gives a flat number for the 
metrics it follows, that does not give you much of an idea about 
exactly where those extra instructions and the extra cost comes 
from.

> I've parsed a bit the intel documentation and perfcounters 
> source code. It looks like the current implementation for 
> intel and amd share enough similar properties so that they 
> have been factorized in a single file.
> 
> This similar property is the use of an msr, while P6 family 
> use the pmc.
> 
> Perhaps I can expand the struct pmc_x86_ops to guess whether 
> we want to use rdmsr or rdpmc.
> 
> Hmm it seems the implementation would be enough different to 
> deserve a new file for P6. Will see...

Yeah, if there's not enough similarities then you can go for a 
separate perf_counters_p6.c file.

	Ingo