lkml.org 
[lkml]   [2011]   [Jan]   [23]   [last100]   RSS Feed
Views: [wrap][no wrap]   [headers]  [forward] 
 
Messages in this thread
/
From
SubjectRe: [BUG?] tracing/function_graph: set_graph_function was broken
Date
Hi, Steve

Here is the example:
We use the tracer "function_graph",set the graph function as "sys_nanosleep",then do nathing just wait.
$ echo 0 > tracing_enable
$ echo function_graph > current_tracer
$ echo sys_nanosleep > set_graph_function
$ echo "" > trace
$ echo 1 > tracing_enable
[ ... wait a few second ]
$ echo 0 > tracing_enable
$ cat trace
[ now, we kan saw the function "plat_irq_dispatch" was traced ]
[ I did this on a platform based on jz4760 which is a MIPS compatible cpu ]

I append the full shell information at the tail of this letter.

The cause of this problem is:
----------------------- key code ------------------------
[snip] in prepare_ftrace_return()
<1> if (ftrace_push_return_trace(old, self_addr, &trace.depth, fp) ==
-EBUSY) {
*parent = old;
return;
}

trace.func = self_addr;

/* Only trace if the calling function expects to */
<2> if (!ftrace_graph_entry(&trace)) {
current->curr_ret_stack--;
*parent = old;
}
[snip]

[snip] in trace_graph_entry()
/* trace it when it is-nested-in or is a function enabled. */
<3> if (!(trace->depth || ftrace_graph_addr(trace->func)) ||
ftrace_graph_ignore_irqs())
return 0;
[snip]
------------------ code end -------------------------

when a interruption occured between <1> and <2>, the interruption entry function "plat_irq_dispatch"
will get the trace.depth = 1, because the function which was interrupted take the trace.depth = 0(trace.depth
was initialized with value -1), then the "plat_irq_dispatch" function reached <3>, because it takes trace->depth=1,
so the two condition followed utterly useless, function "plat_irq_dispatch" will be traceed completely.

In the old kernel version like 2.6.31, you use function set_tsk_trace_graph() and clear_tsk_trace_graph()
to start and end tracing, but in 2.6.36(or earlier) version, you use trace->depth instead, and cause this problem.


My English is not good, but please bear with me.

Regards,
zhong zhiping


------------ The full shell info, please copy into notepad for more readability --------------
bash-3.2# cat current_tracer
function_graph
bash-3.2# cat set_graph_function
sys_nanosleep
bash-3.2# echo "" > tracing
bash: tracing: Permission denied
bash-3.2# echo "" > trace
bash-3.2# cat trace
# tracer: function_graph
#
# CPU DURATION FUNCTION CALLS
# | | | | | | |
bash-3.2# echo 1 > tracing_enabled
bash-3.2# echo 0 > tracing_enabled
bash-3.2# cat trace
# tracer: function_graph
#
# CPU DURATION FUNCTION CALLS
# | | | | | | |
0) | plat_irq_dispatch() {
0) ==========> |
0) | do_IRQ() {
0) | irq_enter() {
0) 0.000 us | idle_cpu();
0) 0.000 us | }
0) 0.000 us | irq_to_desc();
0) | handle_level_irq() {
0) 0.000 us | disable_intc_irq();
0) 0.000 us | mask_and_ack_intc_irq();
0) | handle_IRQ_event() {
0) | jz_timer_interrupt() {
0) 0.000 us | f4760_timer_callback();
0) | tick_handle_periodic() {
0) | tick_periodic() {
0) | do_timer() {
0) | update_wall_time() {
0) 0.000 us | jz_get_cycles();
0) 0.000 us | }
0) 0.000 us | calc_global_load();
0) ! 10000.00 us | }
0) | update_process_times() {
0) | account_process_tick() {
0) 0.000 us | account_system_time();
0) 0.000 us | }
0) | run_local_timers() {
0) 0.000 us | hrtimer_run_queues();
0) 0.000 us | raise_softirq();
0) 0.000 us | }
0) | rcu_check_callbacks() {
0) 0.000 us | idle_cpu();
0) | __rcu_pending() {
0) 0.000 us | cpu_has_callbacks_ready_to_invoke();
0) 0.000 us | cpu_needs_another_gp();
0) 0.000 us | rcu_gp_in_progress();
0) 0.000 us | }
0) | __rcu_pending() {
0) 0.000 us | cpu_has_callbacks_ready_to_invoke();
0) 0.000 us | cpu_needs_another_gp();
0) 0.000 us | rcu_gp_in_progress();
0) 0.000 us | }
0) 0.000 us | }
0) 0.000 us | printk_tick();
0) | scheduler_tick() {
0) 0.000 us | task_tick_idle();
0) 0.000 us | }
0) 0.000 us | run_posix_cpu_timers();
0) 0.000 us | }
0) ! 10000.00 us | }
0) ! 10000.00 us | }
0) ! 10000.00 us | }
0) ! 10000.00 us | }
0) 0.000 us | note_interrupt();
0) 0.000 us | enable_intc_irq();
0) ! 10000.00 us | }
0) 0.000 us | irq_exit();
0) ! 10000.00 us | }
0) <========== |
0) ! 10000.00 us | }
0) | plat_irq_dispatch() {
0) ==========> |
0) | do_IRQ() {
0) | irq_enter() {
0) 0.000 us | idle_cpu();
0) 0.000 us | }
0) 0.000 us | irq_to_desc();
0) | handle_level_irq() {
0) 0.000 us | disable_gpio_irq();
0) 0.000 us | mask_and_ack_gpio_irq();
0) | handle_IRQ_event() {
0) | cirrus_interrupt() {
0) | dev_alloc_skb() {
0) | __alloc_skb() {
0) 0.000 us | kmem_cache_alloc();
0) | __kmalloc_track_caller() {
0) 0.000 us | get_slab();
0) 0.000 us | }
0) 0.000 us | }
0) 0.000 us | }
0) 0.000 us | skb_put();
0) 0.000 us | eth_type_trans();
0) 0.000 us | netif_rx();
0) 0.000 us | }
0) 0.000 us | }
0) 0.000 us | note_interrupt();
0) | enable_gpio_irq() {
0) 0.000 us | enable_intc_irq();
0) 0.000 us | }
0) 0.000 us | }
0) 0.000 us | irq_exit();
0) 0.000 us | }
0) <========== |
0) 0.000 us | }
0) | plat_irq_dispatch() {
0) ==========> |
0) | do_IRQ() {
0) | irq_enter() {
0) 0.000 us | idle_cpu();
0) 0.000 us | }
0) 0.000 us | irq_to_desc();
0) | handle_level_irq() {
0) 0.000 us | disable_intc_irq();
0) 0.000 us | mask_and_ack_intc_irq();
0) | handle_IRQ_event() {
0) | jz_timer_interrupt() {
0) 0.000 us | f4760_timer_callback();
0) | tick_handle_periodic() {
0) | tick_periodic() {
0) | do_timer() {
0) | update_wall_time() {
0) 0.000 us | jz_get_cycles();
0) 0.000 us | }
0) 0.000 us | calc_global_load();
0) ! 10000.00 us | }
0) | update_process_times() {
0) | account_process_tick() {
0) 0.000 us | account_system_time();
0) 0.000 us | }
0) | run_local_timers() {
0) 0.000 us | hrtimer_run_queues();
0) 0.000 us | raise_softirq();
0) 0.000 us | }
0) | rcu_check_callbacks() {
0) 0.000 us | idle_cpu();
0) | __rcu_pending() {
0) 0.000 us | cpu_has_callbacks_ready_to_invoke();
0) 0.000 us | cpu_needs_another_gp();
0) 0.000 us | rcu_gp_in_progress();
0) 0.000 us | }
0) | __rcu_pending() {
0) 0.000 us | cpu_has_callbacks_ready_to_invoke();
0) 0.000 us | cpu_needs_another_gp();
0) 0.000 us | rcu_gp_in_progress();
0) 0.000 us | }
0) 0.000 us | }
0) 0.000 us | printk_tick();
0) | scheduler_tick() {
0) 0.000 us | task_tick_idle();
0) 0.000 us | }
0) 0.000 us | run_posix_cpu_timers();
0) 0.000 us | }
0) ! 10000.00 us | }
0) ! 10000.00 us | }
0) ! 10000.00 us | }
0) ! 10000.00 us | }
0) 0.000 us | note_interrupt();
0) 0.000 us | enable_intc_irq();
0) ! 10000.00 us | }
0) 0.000 us | irq_exit();
0) ! 10000.00 us | }
0) <========== |
0) ! 10000.00 us | }
0) | plat_irq_dispatch() {
0) ==========> |
0) | do_IRQ() {
0) | irq_enter() {
0) 0.000 us | idle_cpu();
0) 0.000 us | }
0) 0.000 us | irq_to_desc();
0) | handle_level_irq() {
0) 0.000 us | disable_gpio_irq();
0) 0.000 us | mask_and_ack_gpio_irq();
0) | handle_IRQ_event() {
0) | cirrus_interrupt() {
0) | dev_alloc_skb() {
0) | __alloc_skb() {
0) 0.000 us | kmem_cache_alloc();
0) | __kmalloc_track_caller() {
0) 0.000 us | get_slab();
0) 0.000 us | }
0) 0.000 us | }
0) 0.000 us | }
0) 0.000 us | skb_put();
0) 0.000 us | eth_type_trans();
0) 0.000 us | netif_rx();
0) 0.000 us | }
0) 0.000 us | }
0) 0.000 us | note_interrupt();
0) | enable_gpio_irq() {
0) 0.000 us | enable_intc_irq();
0) 0.000 us | }
0) 0.000 us | }
0) 0.000 us | irq_exit();
0) 0.000 us | }
0) <========== |
0) 0.000 us | }
bash-3.2#
\
 
 \ /
  Last update: 2011-01-24 04:09    [W:0.067 / U:8.556 seconds]
©2003-2018 Jasper Spaans|hosted at Digital Ocean and TransIP|Read the blog|Advertise on this site