Re: [BUG?] tracing/function_graph: set_graph_function was broken

From: zhiping zhong
Date: Sun Jan 23 2011 - 22:06:51 EST

Next message: Yong Zhang: "Re: [PATCH] sched: fix autogroup nice tune on UP"
Previous message: Guan Xuetao: "RE: Request (2nd) for unicore32 architecture codes to merge into linux-next"
In reply to: Steven Rostedt: "Re: [BUG?] tracing/function_graph: set_graph_function was brokenfrom 2.6.36-rc2"
Messages sorted by: [ date ] [ thread ] [ subject ] [ author ]

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# ¢éì®&Þ~º&¶¬–+-±éÝ¥Šw®žË±Êâmébžìdz¹Þ)í…æèw*jg¬±¨¶‰šŽŠÝj/êäz¹ÞŠà2ŠÞ¨èÚ&¢)ß«a¶Úþø®G«éh®æj:+v‰¨Šwè†Ù>Wš±êÞiÛaxPjØm¶ŸÿÃ-»+ƒùdš_

Next message: Yong Zhang: "Re: [PATCH] sched: fix autogroup nice tune on UP"
Previous message: Guan Xuetao: "RE: Request (2nd) for unicore32 architecture codes to merge into linux-next"
In reply to: Steven Rostedt: "Re: [BUG?] tracing/function_graph: set_graph_function was brokenfrom 2.6.36-rc2"
Messages sorted by: [ date ] [ thread ] [ subject ] [ author ]