* Re: [PATCH 2/2] tracing/function-graph-tracer: use the more lightweight local clock
2009-03-05 0:49 [PATCH 2/2] tracing/function-graph-tracer: use the more lightweight local clock Frederic Weisbecker
@ 2009-03-05 1:19 ` Frederic Weisbecker
2009-03-05 7:30 ` Peter Zijlstra
2009-03-05 11:03 ` [tip:tracing/function-graph-tracer] " Frederic Weisbecker
` (2 subsequent siblings)
3 siblings, 1 reply; 14+ messages in thread
From: Frederic Weisbecker @ 2009-03-05 1:19 UTC (permalink / raw)
To: Ingo Molnar; +Cc: Steven Rostedt, Peter Zijlstra, linux-kernel
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.
^ permalink raw reply [flat|nested] 14+ messages in thread* Re: [PATCH 2/2] tracing/function-graph-tracer: use the more lightweight local clock
2009-03-05 1:19 ` Frederic Weisbecker
@ 2009-03-05 7:30 ` Peter Zijlstra
2009-03-05 8:46 ` Frederic Weisbecker
0 siblings, 1 reply; 14+ messages in thread
From: Peter Zijlstra @ 2009-03-05 7:30 UTC (permalink / raw)
To: Frederic Weisbecker; +Cc: Ingo Molnar, Steven Rostedt, linux-kernel
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?
^ permalink raw reply [flat|nested] 14+ messages in thread
* Re: [PATCH 2/2] tracing/function-graph-tracer: use the more lightweight local clock
2009-03-05 7:30 ` Peter Zijlstra
@ 2009-03-05 8:46 ` Frederic Weisbecker
2009-03-05 10:56 ` Ingo Molnar
0 siblings, 1 reply; 14+ messages in thread
From: Frederic Weisbecker @ 2009-03-05 8:46 UTC (permalink / raw)
To: Peter Zijlstra; +Cc: Ingo Molnar, Steven Rostedt, linux-kernel
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?
^ permalink raw reply [flat|nested] 14+ messages in thread* Re: [PATCH 2/2] tracing/function-graph-tracer: use the more lightweight local clock
2009-03-05 8:46 ` Frederic Weisbecker
@ 2009-03-05 10:56 ` Ingo Molnar
2009-03-05 11:16 ` Frederic Weisbecker
0 siblings, 1 reply; 14+ messages in thread
From: Ingo Molnar @ 2009-03-05 10:56 UTC (permalink / raw)
To: Frederic Weisbecker; +Cc: Peter Zijlstra, Steven Rostedt, linux-kernel
* 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
^ permalink raw reply [flat|nested] 14+ messages in thread* Re: [PATCH 2/2] tracing/function-graph-tracer: use the more lightweight local clock
2009-03-05 10:56 ` Ingo Molnar
@ 2009-03-05 11:16 ` Frederic Weisbecker
2009-03-05 11:56 ` Ingo Molnar
0 siblings, 1 reply; 14+ messages in thread
From: Frederic Weisbecker @ 2009-03-05 11:16 UTC (permalink / raw)
To: Ingo Molnar; +Cc: Peter Zijlstra, Steven Rostedt, linux-kernel
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.
^ permalink raw reply [flat|nested] 14+ messages in thread* Re: [PATCH 2/2] tracing/function-graph-tracer: use the more lightweight local clock
2009-03-05 11:16 ` Frederic Weisbecker
@ 2009-03-05 11:56 ` Ingo Molnar
2009-03-05 14:01 ` Frederic Weisbecker
0 siblings, 1 reply; 14+ messages in thread
From: Ingo Molnar @ 2009-03-05 11:56 UTC (permalink / raw)
To: Frederic Weisbecker; +Cc: Peter Zijlstra, Steven Rostedt, linux-kernel
* 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
^ permalink raw reply [flat|nested] 14+ messages in thread* Re: [PATCH 2/2] tracing/function-graph-tracer: use the more lightweight local clock
2009-03-05 11:56 ` Ingo Molnar
@ 2009-03-05 14:01 ` Frederic Weisbecker
2009-03-05 14:22 ` Ingo Molnar
0 siblings, 1 reply; 14+ messages in thread
From: Frederic Weisbecker @ 2009-03-05 14:01 UTC (permalink / raw)
To: Ingo Molnar; +Cc: Peter Zijlstra, Steven Rostedt, linux-kernel
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...
^ permalink raw reply [flat|nested] 14+ messages in thread* Re: [PATCH 2/2] tracing/function-graph-tracer: use the more lightweight local clock
2009-03-05 14:01 ` Frederic Weisbecker
@ 2009-03-05 14:22 ` Ingo Molnar
0 siblings, 0 replies; 14+ messages in thread
From: Ingo Molnar @ 2009-03-05 14:22 UTC (permalink / raw)
To: Frederic Weisbecker; +Cc: Peter Zijlstra, Steven Rostedt, linux-kernel
* 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
^ permalink raw reply [flat|nested] 14+ messages in thread
* [tip:tracing/function-graph-tracer] tracing/function-graph-tracer: use the more lightweight local clock
2009-03-05 0:49 [PATCH 2/2] tracing/function-graph-tracer: use the more lightweight local clock Frederic Weisbecker
2009-03-05 1:19 ` Frederic Weisbecker
@ 2009-03-05 11:03 ` Frederic Weisbecker
2009-03-05 11:04 ` [PATCH 2/2] " Ingo Molnar
2009-03-05 11:18 ` [tip:tracing/function-graph-tracer] " Frederic Weisbecker
3 siblings, 0 replies; 14+ messages in thread
From: Frederic Weisbecker @ 2009-03-05 11:03 UTC (permalink / raw)
To: linux-tip-commits
Cc: linux-kernel, hpa, mingo, fweisbec, rostedt, peterz, tglx, mingo
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)) {
^ permalink raw reply related [flat|nested] 14+ messages in thread* Re: [PATCH 2/2] tracing/function-graph-tracer: use the more lightweight local clock
2009-03-05 0:49 [PATCH 2/2] tracing/function-graph-tracer: use the more lightweight local clock Frederic Weisbecker
2009-03-05 1:19 ` Frederic Weisbecker
2009-03-05 11:03 ` [tip:tracing/function-graph-tracer] " Frederic Weisbecker
@ 2009-03-05 11:04 ` Ingo Molnar
2009-03-05 11:23 ` Frederic Weisbecker
2009-03-05 11:18 ` [tip:tracing/function-graph-tracer] " Frederic Weisbecker
3 siblings, 1 reply; 14+ messages in thread
From: Ingo Molnar @ 2009-03-05 11:04 UTC (permalink / raw)
To: Frederic Weisbecker; +Cc: Steven Rostedt, Peter Zijlstra, linux-kernel
* 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
^ permalink raw reply [flat|nested] 14+ messages in thread
* Re: [PATCH 2/2] tracing/function-graph-tracer: use the more lightweight local clock
2009-03-05 11:04 ` [PATCH 2/2] " Ingo Molnar
@ 2009-03-05 11:23 ` Frederic Weisbecker
2009-03-05 11:38 ` Ingo Molnar
0 siblings, 1 reply; 14+ messages in thread
From: Frederic Weisbecker @ 2009-03-05 11:23 UTC (permalink / raw)
To: Ingo Molnar; +Cc: Steven Rostedt, Peter Zijlstra, linux-kernel
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
^ permalink raw reply [flat|nested] 14+ messages in thread
* Re: [PATCH 2/2] tracing/function-graph-tracer: use the more lightweight local clock
2009-03-05 11:23 ` Frederic Weisbecker
@ 2009-03-05 11:38 ` Ingo Molnar
0 siblings, 0 replies; 14+ messages in thread
From: Ingo Molnar @ 2009-03-05 11:38 UTC (permalink / raw)
To: Frederic Weisbecker; +Cc: Steven Rostedt, Peter Zijlstra, linux-kernel
* 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
^ permalink raw reply [flat|nested] 14+ messages in thread
* [tip:tracing/function-graph-tracer] tracing/function-graph-tracer: use the more lightweight local clock
2009-03-05 0:49 [PATCH 2/2] tracing/function-graph-tracer: use the more lightweight local clock Frederic Weisbecker
` (2 preceding siblings ...)
2009-03-05 11:04 ` [PATCH 2/2] " Ingo Molnar
@ 2009-03-05 11:18 ` Frederic Weisbecker
3 siblings, 0 replies; 14+ messages in thread
From: Frederic Weisbecker @ 2009-03-05 11:18 UTC (permalink / raw)
To: linux-tip-commits
Cc: linux-kernel, hpa, mingo, fweisbec, rostedt, peterz, tglx, mingo
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)) {
^ permalink raw reply related [flat|nested] 14+ messages in thread