[BUG?] tracing/function_graph: set_graph_function was broken from 2.6.36-rc2

[BUG?] tracing/function_graph: set_graph_function was broken from 2.6.36-rc2

[wu zhangjin]

Hi, Steve

Zhiping Zhong reported a problem about set_graph_function: whenever
users configure the entries through the tracing/set_graph_function
interface, the tracing result always include the other functions which
are not configured through the interfaces, and most of the tracing
result we can see are the irq related functions, which means
set_graph_function doesn't work as expects.

I have done some investigation, in the *ftrace_graph_entry ->
trace_graph_entry() function, there is checking like this:

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

and:

static inline int ftrace_graph_ignore_irqs(void)
{
        if (!ftrace_graph_skip_irqs)
                return 0;

        return in_irq();
}

and:

/* When set, irq functions will be ignored */
static int ftrace_graph_skip_irqs;

As we can see above, ftrace_graph_skip_irqs is initialized as 0, then,
ftrace_graph_ignore_irqs() will return 0 by default, as a result, the
checking in trace_graph_entry() will always be false, then every
function will be traced whenever the set_graph_function is configured,
so, this may be the cause.

A quick fix looks like this:

        /* trace it when it is-nested-in or is a function enabled. */
-       if (!(trace->depth || ftrace_graph_addr(trace->func)) ||
-             ftrace_graph_ignore_irqs())
+       if (!(trace->depth || ftrace_graph_addr(trace->func) ||
+             !ftrace_graph_ignore_irqs()))
                return 0;

And as the git log shows, the ftrace_graph_ignore_irqs() function was
added from the following commit:

          tracing: Do not trace in irq when funcgraph-irq option is zero

Regards,
Wu Zhangjin

Re: [BUG?] tracing/function_graph: set_graph_function was broken from 2.6.36-rc2

[Steven Rostedt]

On Thu, 2011-01-20 at 02:55 +0800, wu zhangjin wrote:
> Hi, Steve
> 
> Zhiping Zhong reported a problem about set_graph_function: whenever
> users configure the entries through the tracing/set_graph_function
> interface, the tracing result always include the other functions which
> are not configured through the interfaces, and most of the tracing
> result we can see are the irq related functions, which means
> set_graph_function doesn't work as expects.

It does, but you need to disable irq tracing:

echo 0 > /debug/tracing/options/funcgraph-irqs

Perhaps I'll make this the default :-/

-- Steve

> 
> I have done some investigation, in the *ftrace_graph_entry ->
> trace_graph_entry() function, there is checking like this:
> 
>         [snip]
>         /* trace it when it is-nested-in or is a function enabled. */
>         if (!(trace->depth || ftrace_graph_addr(trace->func)) ||
>               ftrace_graph_ignore_irqs())
>                 return 0;
>         [snip]
> 
> and:
> 
> static inline int ftrace_graph_ignore_irqs(void)
> {
>         if (!ftrace_graph_skip_irqs)
>                 return 0;
> 
>         return in_irq();
> }
> 
> and:
> 
> /* When set, irq functions will be ignored */
> static int ftrace_graph_skip_irqs;
> 
> As we can see above, ftrace_graph_skip_irqs is initialized as 0, then,
> ftrace_graph_ignore_irqs() will return 0 by default, as a result, the
> checking in trace_graph_entry() will always be false, then every
> function will be traced whenever the set_graph_function is configured,
> so, this may be the cause.
> 
> A quick fix looks like this:
> 
>         /* trace it when it is-nested-in or is a function enabled. */
> -       if (!(trace->depth || ftrace_graph_addr(trace->func)) ||
> -             ftrace_graph_ignore_irqs())
> +       if (!(trace->depth || ftrace_graph_addr(trace->func) ||
> +             !ftrace_graph_ignore_irqs()))
>                 return 0;
> 
> And as the git log shows, the ftrace_graph_ignore_irqs() function was
> added from the following commit:
> 
>           tracing: Do not trace in irq when funcgraph-irq option is zero
> 
> Regards,
> Wu Zhangjin

Re: [BUG?] tracing/function_graph: set_graph_function was broken from 2.6.36-rc2

[wu zhangjin]

On Fri, Jan 21, 2011 at 1:30 AM, Steven Rostedt <srostedt@redhat.com> wrote:
> On Thu, 2011-01-20 at 02:55 +0800, wu zhangjin wrote:
>> Hi, Steve
>>
>> Zhiping Zhong reported a problem about set_graph_function: whenever
>> users configure the entries through the tracing/set_graph_function
>> interface, the tracing result always include the other functions which
>> are not configured through the interfaces, and most of the tracing
>> result we can see are the irq related functions, which means
>> set_graph_function doesn't work as expects.
>
> It does, but you need to disable irq tracing:
>
> echo 0 > /debug/tracing/options/funcgraph-irqs
>
> Perhaps I'll make this the default :-/
>

Yeah, only If we put 0 to /debug/tracing/options/funcgraph-irqs,
otherwise, every function will be traced whenever we set the entries
through the tracing/set_graph_function interface, this may be not that
we expected ;-) set_graph_function interface should work as-is
whenever /debug/tracing/options/funcgraph-irqs is set, the cause may
be the following "if" statement:

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

By default, ftrace_graph_ignore_irqs() is false, then, if we don't put
0 to /debug/tracing/options/funcgraph-irqs, it will not return even if
we have specified some entries through the tracing/set_graph_function
interface, as a result, every function will be traced and it doesn't
work as we expected, the expected result is only the specified
functions are reserved in the tracing result.

>> A quick fix looks like this:
>>
>>         /* trace it when it is-nested-in or is a function enabled. */
>> -       if (!(trace->depth || ftrace_graph_addr(trace->func)) ||
>> -             ftrace_graph_ignore_irqs())
>> +       if (!(trace->depth || ftrace_graph_addr(trace->func) ||
>> +             !ftrace_graph_ignore_irqs()))
>>                 return 0;
>>
>> And as the git log shows, the ftrace_graph_ignore_irqs() function was
>> added from the following commit:
>>
>>           tracing: Do not trace in irq when funcgraph-irq option is zero

Regards,
Wu Zhangjin

Re: [BUG?] tracing/function_graph: set_graph_function was broken from 2.6.36-rc2

[Steven Rostedt]

On Fri, 2011-01-21 at 17:27 +0800, wu zhangjin wrote:
> On Fri, Jan 21, 2011 at 1:30 AM, Steven Rostedt <srostedt@redhat.com> wrote:

> >> trace_graph_entry():
> >>
> >>         [snip]
> >>         /* trace it when it is-nested-in or is a function enabled. */
> >>         if (!(trace->depth || ftrace_graph_addr(trace->func)) ||
> >>               ftrace_graph_ignore_irqs())
> >>                 return 0;
> >>         [snip]
> >>
> 
> By default, ftrace_graph_ignore_irqs() is false, then, if we don't put
> 0 to /debug/tracing/options/funcgraph-irqs, it will not return even if
> we have specified some entries through the tracing/set_graph_function
> interface, as a result, every function will be traced and it doesn't
> work as we expected, the expected result is only the specified
> functions are reserved in the tracing result.
> 

???

It's an or, if the first case is true:

  !(trace->depth || ftrace_graph_addr(trace->func))

then we return and do not trace. Regardless of what
ftrace_graph_ignore_irqs() is set to.

Can you show me an example of what you are having a problem with?

-- Steve

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

[zhiping zhong]

[-- Warning: decoded text below may be mangled, UTF-8 assumed --]
[-- Attachment #1: Type: text/plain; charset="UTF-8", Size: 11679 bytes --]

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# ÿôèº{.nÇ+‰·Ÿ®‰­†+%ŠËÿ±éݶ\x17¥Šwÿº{.nÇ+‰·¥Š{±þG«éÿŠ{ayº\x1dʇڙë,j\a­¢f£¢·hšïêÿ‘êçz_è®\x03(­éšŽŠÝ¢j"ú\x1a¶^[m§ÿÿ¾\a«þG«éÿ¢¸?™¨è­Ú&£ø§~á¶iO•æ¬z·švØ^\x14\x04\x1a¶^[m§ÿÿÃ\fÿ¶ìÿ¢¸?–I¥

Re: [BUG?] tracing/function_graph: set_graph_function was broken from 2.6.36-rc2

[Steven Rostedt]

On Mon, 2011-01-24 at 11:30 +0800, wu zhangjin wrote:
> On Sat, Jan 22, 2011 at 2:40 AM, Steven Rostedt <srostedt@redhat.com> wrote:
> > On Fri, 2011-01-21 at 17:27 +0800, wu zhangjin wrote:
> >> On Fri, Jan 21, 2011 at 1:30 AM, Steven Rostedt <srostedt@redhat.com> wrote:
> >
> >> >> trace_graph_entry():
> >> >>
> >> >>         [snip]
> >> >>         /* trace it when it is-nested-in or is a function enabled. */
> >> >>         if (!(trace->depth || ftrace_graph_addr(trace->func)) ||
> >> >>               ftrace_graph_ignore_irqs())
> >> >>                 return 0;
> >> >>         [snip]
> >> >>
> >>
> >> By default, ftrace_graph_ignore_irqs() is false, then, if we don't put
> >> 0 to /debug/tracing/options/funcgraph-irqs, it will not return even if
> >> we have specified some entries through the tracing/set_graph_function
> >> interface, as a result, every function will be traced and it doesn't
> >> work as we expected, the expected result is only the specified
> >> functions are reserved in the tracing result.
> >>
> >
> > ???
> >
> > It's an or, if the first case is true:
> >
> >  !(trace->depth || ftrace_graph_addr(trace->func))
> >
> > then we return and do not trace. Regardless of what
> > ftrace_graph_ignore_irqs() is set to.
> 
> Sorry, I was falling into a stupid trap, OR from left to right ;-)

I found the reason for the traced interrupts. It looks like its been
there for a while. Here's the patch I'll be sending to mainline:

-- Steve

commit 2271425ed6ce77b271749544cd6117ceccb6369c
Author: Steven Rostedt <srostedt@redhat.com>
Date:   Fri Feb 11 20:36:02 2011 -0500

    ftrace/graph: Trace function entry before updating index
    
    Currently the index to the ret_stack is updated and the real return address
    is saved in the ret_stack. Then we call the trace function. The trace
    function could decide that it doesn't want to trace this function
    (ex. set_graph_function does not match) and it will return 0 which means
    not to trace this call.
    
    The normal function graph tracer has this code:
    
    	if (!(trace->depth || ftrace_graph_addr(trace->func)) ||
    	      ftrace_graph_ignore_irqs())
    		return 0;
    
    What this states is, if the trace depth (which is curr_ret_stack)
    is zero (top of nested functions) then test if we want to trace this
    function. If this function is not to be traced, then return  0 and
    the rest of the function graph tracer logic will not trace this function.
    
    The problem arises when an interrupt comes in after we updated the
    curr_ret_stack. The next function that gets called will have a trace->depth
    of 1. Which fools this trace code into thinking that we are in a nested
    function, and that we should trace. This causes interrupts to be traced
    when they should not be.
    
    The solution is to trace the function first and then update the ret_stack.
    
    Reported-by: zhiping zhong <xzhong86@163.com>
    Reported-by: wu zhangjin <wuzhangjin@gmail.com>
    Signed-off-by: Steven Rostedt <rostedt@goodmis.org>

diff --git a/arch/x86/kernel/ftrace.c b/arch/x86/kernel/ftrace.c
index 382eb29..a93742a 100644
--- a/arch/x86/kernel/ftrace.c
+++ b/arch/x86/kernel/ftrace.c
@@ -437,18 +437,19 @@ void prepare_ftrace_return(unsigned long *parent, unsigned long self_addr,
 		return;
 	}
 
-	if (ftrace_push_return_trace(old, self_addr, &trace.depth,
-		    frame_pointer) == -EBUSY) {
-		*parent = old;
-		return;
-	}
-
 	trace.func = self_addr;
+	trace.depth = current->curr_ret_stack + 1;
 
 	/* Only trace if the calling function expects to */
 	if (!ftrace_graph_entry(&trace)) {
-		current->curr_ret_stack--;
 		*parent = old;
+		return;
+	}
+
+	if (ftrace_push_return_trace(old, self_addr, &trace.depth,
+		    frame_pointer) == -EBUSY) {
+		*parent = old;
+		return;
 	}
 }
 #endif /* CONFIG_FUNCTION_GRAPH_TRACER */