Skip to content
  • Steven Rostedt's avatar
    ftrace: function tracer · 1b29b018
    Steven Rostedt authored
    
    
    This is a simple trace that uses the ftrace infrastructure. It is
    designed to be fast and small, and easy to use. It is useful to
    record things that happen over a very short period of time, and
    not to analyze the system in general.
    
     Updates:
    
      available_tracers
         "function" is added to this file.
    
      current_tracer
        To enable the function tracer:
    
          echo function > /debugfs/tracing/current_tracer
    
         To disable the tracer:
    
           echo disable > /debugfs/tracing/current_tracer
    
    The output of the function_trace file is as follows
    
      "echo noverbose > /debugfs/tracing/iter_ctrl"
    
    preemption latency trace v1.1.5 on 2.6.24-rc7-tst
    Signed-off-by: default avatarIngo Molnar <mingo@elte.hu>
    --------------------------------------------------------------------
     latency: 0 us, #419428/4361791, CPU#1 | (M:desktop VP:0, KP:0, SP:0 HP:0 #P:4)
        -----------------
        | task: -0 (uid:0 nice:0 policy:0 rt_prio:0)
        -----------------
    
                     _------=> CPU#
                    / _-----=> irqs-off
                   | / _----=> need-resched
                   || / _---=> hardirq/softirq
                   ||| / _--=> preempt-depth
                   |||| /
                   |||||     delay
       cmd     pid ||||| time  |   caller
          \   /    |||||   \   |   /
     swapper-0     0d.h. 1595128us+: set_normalized_timespec+0x8/0x2d <c043841d> (ktime_get_ts+0x4a/0x4e <c04499d4>)
     swapper-0     0d.h. 1595131us+: _spin_lock+0x8/0x18 <c0630690> (hrtimer_interrupt+0x6e/0x1b0 <c0449c56>)
    
    Or with verbose turned on:
    
      "echo verbose > /debugfs/tracing/iter_ctrl"
    
    preemption latency trace v1.1.5 on 2.6.24-rc7-tst
    --------------------------------------------------------------------
     latency: 0 us, #419428/4361791, CPU#1 | (M:desktop VP:0, KP:0, SP:0 HP:0 #P:4)
        -----------------
        | task: -0 (uid:0 nice:0 policy:0 rt_prio:0)
        -----------------
    
             swapper     0 0 9 00000000 00000000 [f3675f41] 1595.128ms (+0.003ms): set_normalized_timespec+0x8/0x2d <c043841d> (ktime_get_ts+0x4a/0x4e <c04499d4>)
             swapper     0 0 9 00000000 00000001 [f3675f45] 1595.131ms (+0.003ms): _spin_lock+0x8/0x18 <c0630690> (hrtimer_interrupt+0x6e/0x1b0 <c0449c56>)
             swapper     0 0 9 00000000 00000002 [f3675f48] 1595.135ms (+0.003ms): _spin_lock+0x8/0x18 <c0630690> (hrtimer_interrupt+0x6e/0x1b0 <c0449c56>)
    
    The "trace" file is not affected by the verbose mode, but is by the symonly.
    
     echo "nosymonly" > /debugfs/tracing/iter_ctrl
    
    tracer:
    [   81.479967] CPU 0: bash:3154 register_ftrace_function+0x5f/0x66 <ffffffff80337a4d> <-- _spin_unlock_irqrestore+0xe/0x5a <ffffffff8048cc8f>
    [   81.479967] CPU 0: bash:3154 _spin_unlock_irqrestore+0x3e/0x5a <ffffffff8048ccbf> <-- sub_preempt_count+0xc/0x7a <ffffffff80233d7b>
    [   81.479968] CPU 0: bash:3154 sub_preempt_count+0x30/0x7a <ffffffff80233d9f> <-- in_lock_functions+0x9/0x24 <ffffffff8025a75d>
    [   81.479968] CPU 0: bash:3154 vfs_write+0x11d/0x155 <ffffffff8029a043> <-- dnotify_parent+0x12/0x78 <ffffffff802d54fb>
    [   81.479968] CPU 0: bash:3154 dnotify_parent+0x2d/0x78 <ffffffff802d5516> <-- _spin_lock+0xe/0x70 <ffffffff8048c910>
    [   81.479969] CPU 0: bash:3154 _spin_lock+0x1b/0x70 <ffffffff8048c91d> <-- add_preempt_count+0xe/0x77 <ffffffff80233df7>
    [   81.479969] CPU 0: bash:3154 add_preempt_count+0x3e/0x77 <ffffffff80233e27> <-- in_lock_functions+0x9/0x24 <ffffffff8025a75d>
    
     echo "symonly" > /debugfs/tracing/iter_ctrl
    
    tracer:
    [   81.479913] CPU 0: bash:3154 register_ftrace_function+0x5f/0x66 <-- _spin_unlock_irqrestore+0xe/0x5a
    [   81.479913] CPU 0: bash:3154 _spin_unlock_irqrestore+0x3e/0x5a <-- sub_preempt_count+0xc/0x7a
    [   81.479913] CPU 0: bash:3154 sub_preempt_count+0x30/0x7a <-- in_lock_functions+0x9/0x24
    [   81.479914] CPU 0: bash:3154 vfs_write+0x11d/0x155 <-- dnotify_parent+0x12/0x78
    [   81.479914] CPU 0: bash:3154 dnotify_parent+0x2d/0x78 <-- _spin_lock+0xe/0x70
    [   81.479914] CPU 0: bash:3154 _spin_lock+0x1b/0x70 <-- add_preempt_count+0xe/0x77
    [   81.479914] CPU 0: bash:3154 add_preempt_count+0x3e/0x77 <-- in_lock_functions+0x9/0x24
    
    Signed-off-by: default avatarSteven Rostedt <srostedt@redhat.com>
    Signed-off-by: default avatarArnaldo Carvalho de Melo <acme@ghostprotocols.net>
    Signed-off-by: default avatarIngo Molnar <mingo@elte.hu>
    Signed-off-by: default avatarThomas Gleixner <tglx@linutronix.de>
    1b29b018