ftrace: function tracer
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: Ingo 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: Steven Rostedt <srostedt@redhat.com>
Signed-off-by: Arnaldo Carvalho de Melo <acme@ghostprotocols.net>
Signed-off-by: Ingo Molnar <mingo@elte.hu>
Signed-off-by: Thomas Gleixner <tglx@linutronix.de>
2008-05-13 03:20:42 +08:00
|
|
|
/*
|
|
|
|
* ring buffer based function tracer
|
|
|
|
*
|
|
|
|
* Copyright (C) 2007-2008 Steven Rostedt <srostedt@redhat.com>
|
|
|
|
* Copyright (C) 2008 Ingo Molnar <mingo@redhat.com>
|
|
|
|
*
|
|
|
|
* Based on code from the latency_tracer, that is:
|
|
|
|
*
|
|
|
|
* Copyright (C) 2004-2006 Ingo Molnar
|
2012-12-06 17:39:54 +08:00
|
|
|
* Copyright (C) 2004 Nadia Yvette Chambers
|
ftrace: function tracer
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: Ingo 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: Steven Rostedt <srostedt@redhat.com>
Signed-off-by: Arnaldo Carvalho de Melo <acme@ghostprotocols.net>
Signed-off-by: Ingo Molnar <mingo@elte.hu>
Signed-off-by: Thomas Gleixner <tglx@linutronix.de>
2008-05-13 03:20:42 +08:00
|
|
|
*/
|
2009-02-15 08:04:24 +08:00
|
|
|
#include <linux/ring_buffer.h>
|
ftrace: function tracer
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: Ingo 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: Steven Rostedt <srostedt@redhat.com>
Signed-off-by: Arnaldo Carvalho de Melo <acme@ghostprotocols.net>
Signed-off-by: Ingo Molnar <mingo@elte.hu>
Signed-off-by: Thomas Gleixner <tglx@linutronix.de>
2008-05-13 03:20:42 +08:00
|
|
|
#include <linux/debugfs.h>
|
|
|
|
#include <linux/uaccess.h>
|
|
|
|
#include <linux/ftrace.h>
|
2013-11-08 09:08:58 +08:00
|
|
|
#include <linux/slab.h>
|
2008-05-13 03:20:49 +08:00
|
|
|
#include <linux/fs.h>
|
ftrace: function tracer
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: Ingo 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: Steven Rostedt <srostedt@redhat.com>
Signed-off-by: Arnaldo Carvalho de Melo <acme@ghostprotocols.net>
Signed-off-by: Ingo Molnar <mingo@elte.hu>
Signed-off-by: Thomas Gleixner <tglx@linutronix.de>
2008-05-13 03:20:42 +08:00
|
|
|
|
|
|
|
#include "trace.h"
|
|
|
|
|
2013-11-08 09:08:58 +08:00
|
|
|
static void tracing_start_function_trace(struct trace_array *tr);
|
|
|
|
static void tracing_stop_function_trace(struct trace_array *tr);
|
|
|
|
static void
|
|
|
|
function_trace_call(unsigned long ip, unsigned long parent_ip,
|
|
|
|
struct ftrace_ops *op, struct pt_regs *pt_regs);
|
|
|
|
static void
|
|
|
|
function_stack_trace_call(unsigned long ip, unsigned long parent_ip,
|
|
|
|
struct ftrace_ops *op, struct pt_regs *pt_regs);
|
|
|
|
static struct tracer_flags func_flags;
|
|
|
|
|
|
|
|
/* Our option */
|
|
|
|
enum {
|
|
|
|
TRACE_FUNC_OPT_STACK = 0x1,
|
|
|
|
};
|
|
|
|
|
|
|
|
static int allocate_ftrace_ops(struct trace_array *tr)
|
|
|
|
{
|
|
|
|
struct ftrace_ops *ops;
|
2009-01-16 12:06:03 +08:00
|
|
|
|
2013-11-08 09:08:58 +08:00
|
|
|
ops = kzalloc(sizeof(*ops), GFP_KERNEL);
|
|
|
|
if (!ops)
|
|
|
|
return -ENOMEM;
|
2009-01-16 08:12:40 +08:00
|
|
|
|
2013-11-08 09:08:58 +08:00
|
|
|
/* Currently only the non stack verision is supported */
|
|
|
|
ops->func = function_trace_call;
|
|
|
|
ops->flags = FTRACE_OPS_FL_RECURSION_SAFE;
|
|
|
|
|
|
|
|
tr->ops = ops;
|
|
|
|
ops->private = tr;
|
|
|
|
return 0;
|
|
|
|
}
|
2009-01-16 12:06:03 +08:00
|
|
|
|
2014-01-11 05:17:45 +08:00
|
|
|
|
|
|
|
int ftrace_create_function_files(struct trace_array *tr,
|
|
|
|
struct dentry *parent)
|
|
|
|
{
|
|
|
|
int ret;
|
|
|
|
|
2014-04-17 07:21:53 +08:00
|
|
|
/*
|
|
|
|
* The top level array uses the "global_ops", and the files are
|
|
|
|
* created on boot up.
|
|
|
|
*/
|
|
|
|
if (tr->flags & TRACE_ARRAY_FL_GLOBAL)
|
|
|
|
return 0;
|
|
|
|
|
|
|
|
ret = allocate_ftrace_ops(tr);
|
|
|
|
if (ret)
|
|
|
|
return ret;
|
2014-01-11 05:17:45 +08:00
|
|
|
|
|
|
|
ftrace_create_filter_files(tr->ops, parent);
|
|
|
|
|
|
|
|
return 0;
|
|
|
|
}
|
|
|
|
|
|
|
|
void ftrace_destroy_function_files(struct trace_array *tr)
|
|
|
|
{
|
|
|
|
ftrace_destroy_filter_files(tr->ops);
|
|
|
|
kfree(tr->ops);
|
|
|
|
tr->ops = NULL;
|
|
|
|
}
|
|
|
|
|
2009-02-06 04:02:00 +08:00
|
|
|
static int function_trace_init(struct trace_array *tr)
|
ftrace: function tracer
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: Ingo 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: Steven Rostedt <srostedt@redhat.com>
Signed-off-by: Arnaldo Carvalho de Melo <acme@ghostprotocols.net>
Signed-off-by: Ingo Molnar <mingo@elte.hu>
Signed-off-by: Thomas Gleixner <tglx@linutronix.de>
2008-05-13 03:20:42 +08:00
|
|
|
{
|
2014-01-11 06:01:58 +08:00
|
|
|
ftrace_func_t func;
|
2013-11-08 09:08:58 +08:00
|
|
|
|
2014-01-11 06:01:58 +08:00
|
|
|
/*
|
|
|
|
* Instance trace_arrays get their ops allocated
|
|
|
|
* at instance creation. Unless it failed
|
|
|
|
* the allocation.
|
|
|
|
*/
|
|
|
|
if (!tr->ops)
|
2014-01-11 05:17:45 +08:00
|
|
|
return -ENOMEM;
|
2014-01-11 06:01:58 +08:00
|
|
|
|
|
|
|
/* Currently only the global instance can do stack tracing */
|
|
|
|
if (tr->flags & TRACE_ARRAY_FL_GLOBAL &&
|
|
|
|
func_flags.val & TRACE_FUNC_OPT_STACK)
|
|
|
|
func = function_stack_trace_call;
|
|
|
|
else
|
|
|
|
func = function_trace_call;
|
|
|
|
|
|
|
|
ftrace_init_array_ops(tr, func);
|
2013-11-08 09:08:58 +08:00
|
|
|
|
tracing: Consolidate max_tr into main trace_array structure
Currently, the way the latency tracers and snapshot feature works
is to have a separate trace_array called "max_tr" that holds the
snapshot buffer. For latency tracers, this snapshot buffer is used
to swap the running buffer with this buffer to save the current max
latency.
The only items needed for the max_tr is really just a copy of the buffer
itself, the per_cpu data pointers, the time_start timestamp that states
when the max latency was triggered, and the cpu that the max latency
was triggered on. All other fields in trace_array are unused by the
max_tr, making the max_tr mostly bloat.
This change removes the max_tr completely, and adds a new structure
called trace_buffer, that holds the buffer pointer, the per_cpu data
pointers, the time_start timestamp, and the cpu where the latency occurred.
The trace_array, now has two trace_buffers, one for the normal trace and
one for the max trace or snapshot. By doing this, not only do we remove
the bloat from the max_trace but the instances of traces can now use
their own snapshot feature and not have just the top level global_trace have
the snapshot feature and latency tracers for itself.
Signed-off-by: Steven Rostedt <rostedt@goodmis.org>
2013-03-05 22:24:35 +08:00
|
|
|
tr->trace_buffer.cpu = get_cpu();
|
2008-07-11 08:58:14 +08:00
|
|
|
put_cpu();
|
|
|
|
|
2008-05-22 23:49:22 +08:00
|
|
|
tracing_start_cmdline_record();
|
2013-11-08 09:08:58 +08:00
|
|
|
tracing_start_function_trace(tr);
|
2008-11-16 12:57:26 +08:00
|
|
|
return 0;
|
ftrace: function tracer
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: Ingo 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: Steven Rostedt <srostedt@redhat.com>
Signed-off-by: Arnaldo Carvalho de Melo <acme@ghostprotocols.net>
Signed-off-by: Ingo Molnar <mingo@elte.hu>
Signed-off-by: Thomas Gleixner <tglx@linutronix.de>
2008-05-13 03:20:42 +08:00
|
|
|
}
|
|
|
|
|
2008-05-13 03:20:51 +08:00
|
|
|
static void function_trace_reset(struct trace_array *tr)
|
ftrace: function tracer
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: Ingo 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: Steven Rostedt <srostedt@redhat.com>
Signed-off-by: Arnaldo Carvalho de Melo <acme@ghostprotocols.net>
Signed-off-by: Ingo Molnar <mingo@elte.hu>
Signed-off-by: Thomas Gleixner <tglx@linutronix.de>
2008-05-13 03:20:42 +08:00
|
|
|
{
|
2013-11-08 09:08:58 +08:00
|
|
|
tracing_stop_function_trace(tr);
|
2009-02-06 04:02:00 +08:00
|
|
|
tracing_stop_cmdline_record();
|
2014-01-11 06:01:58 +08:00
|
|
|
ftrace_reset_array_ops(tr);
|
ftrace: function tracer
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: Ingo 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: Steven Rostedt <srostedt@redhat.com>
Signed-off-by: Arnaldo Carvalho de Melo <acme@ghostprotocols.net>
Signed-off-by: Ingo Molnar <mingo@elte.hu>
Signed-off-by: Thomas Gleixner <tglx@linutronix.de>
2008-05-13 03:20:42 +08:00
|
|
|
}
|
|
|
|
|
ftrace: restructure tracing start/stop infrastructure
Impact: change where tracing is started up and stopped
Currently, when a new tracer is selected via echo'ing a tracer name into
the current_tracer file, the startup is only done if tracing_enabled is
set to one. If tracing_enabled is changed to zero (by echo'ing 0 into
the tracing_enabled file) a full shutdown is performed.
The full startup and shutdown of a tracer can be expensive and the
user can lose out traces when echo'ing in 0 to the tracing_enabled file,
because the process takes too long. There can also be places that
the user would like to start and stop the tracer several times and
doing the full startup and shutdown of a tracer might be too expensive.
This patch performs the full startup and shutdown when a tracer is
selected. It also adds a way to do a quick start or stop of a tracer.
The quick version is just a flag that prevents the tracing from
taking place, but the overhead of the code is still there.
For example, the startup of a tracer may enable tracepoints, or enable
the function tracer. The stop and start will just set a flag to
have the tracer ignore the calls when the tracepoint or function trace
is called. The overhead of the tracer may still be present when
the tracer is stopped, but no tracing will occur. Setting the tracer
to the 'nop' tracer (or any other tracer) will perform the shutdown
of the tracer which will disable the tracepoint or disable the
function tracer.
The tracing_enabled file will simply start or stop tracing.
This change is all internal. The end result for the user should be the same
as before. If tracing_enabled is not set, no trace will happen.
If tracing_enabled is set, then the trace will happen. The tracing_enabled
variable is static between tracers. Enabling tracing_enabled and
going to another tracer will keep tracing_enabled enabled. Same
is true with disabling tracing_enabled.
This patch will now provide a fast start/stop method to the users
for enabling or disabling tracing.
Note: There were two methods to the struct tracer that were never
used: The methods start and stop. These were to be used as a hook
to the reading of the trace output, but ended up not being
necessary. These two methods are now used to enable the start
and stop of each tracer, in case the tracer needs to do more than
just not write into the buffer. For example, the irqsoff tracer
must stop recording max latencies when tracing is stopped.
Signed-off-by: Steven Rostedt <srostedt@redhat.com>
Signed-off-by: Ingo Molnar <mingo@elte.hu>
2008-11-06 05:05:44 +08:00
|
|
|
static void function_trace_start(struct trace_array *tr)
|
|
|
|
{
|
tracing: Consolidate max_tr into main trace_array structure
Currently, the way the latency tracers and snapshot feature works
is to have a separate trace_array called "max_tr" that holds the
snapshot buffer. For latency tracers, this snapshot buffer is used
to swap the running buffer with this buffer to save the current max
latency.
The only items needed for the max_tr is really just a copy of the buffer
itself, the per_cpu data pointers, the time_start timestamp that states
when the max latency was triggered, and the cpu that the max latency
was triggered on. All other fields in trace_array are unused by the
max_tr, making the max_tr mostly bloat.
This change removes the max_tr completely, and adds a new structure
called trace_buffer, that holds the buffer pointer, the per_cpu data
pointers, the time_start timestamp, and the cpu where the latency occurred.
The trace_array, now has two trace_buffers, one for the normal trace and
one for the max trace or snapshot. By doing this, not only do we remove
the bloat from the max_trace but the instances of traces can now use
their own snapshot feature and not have just the top level global_trace have
the snapshot feature and latency tracers for itself.
Signed-off-by: Steven Rostedt <rostedt@goodmis.org>
2013-03-05 22:24:35 +08:00
|
|
|
tracing_reset_online_cpus(&tr->trace_buffer);
|
ftrace: restructure tracing start/stop infrastructure
Impact: change where tracing is started up and stopped
Currently, when a new tracer is selected via echo'ing a tracer name into
the current_tracer file, the startup is only done if tracing_enabled is
set to one. If tracing_enabled is changed to zero (by echo'ing 0 into
the tracing_enabled file) a full shutdown is performed.
The full startup and shutdown of a tracer can be expensive and the
user can lose out traces when echo'ing in 0 to the tracing_enabled file,
because the process takes too long. There can also be places that
the user would like to start and stop the tracer several times and
doing the full startup and shutdown of a tracer might be too expensive.
This patch performs the full startup and shutdown when a tracer is
selected. It also adds a way to do a quick start or stop of a tracer.
The quick version is just a flag that prevents the tracing from
taking place, but the overhead of the code is still there.
For example, the startup of a tracer may enable tracepoints, or enable
the function tracer. The stop and start will just set a flag to
have the tracer ignore the calls when the tracepoint or function trace
is called. The overhead of the tracer may still be present when
the tracer is stopped, but no tracing will occur. Setting the tracer
to the 'nop' tracer (or any other tracer) will perform the shutdown
of the tracer which will disable the tracepoint or disable the
function tracer.
The tracing_enabled file will simply start or stop tracing.
This change is all internal. The end result for the user should be the same
as before. If tracing_enabled is not set, no trace will happen.
If tracing_enabled is set, then the trace will happen. The tracing_enabled
variable is static between tracers. Enabling tracing_enabled and
going to another tracer will keep tracing_enabled enabled. Same
is true with disabling tracing_enabled.
This patch will now provide a fast start/stop method to the users
for enabling or disabling tracing.
Note: There were two methods to the struct tracer that were never
used: The methods start and stop. These were to be used as a hook
to the reading of the trace output, but ended up not being
necessary. These two methods are now used to enable the start
and stop of each tracer, in case the tracer needs to do more than
just not write into the buffer. For example, the irqsoff tracer
must stop recording max latencies when tracing is stopped.
Signed-off-by: Steven Rostedt <srostedt@redhat.com>
Signed-off-by: Ingo Molnar <mingo@elte.hu>
2008-11-06 05:05:44 +08:00
|
|
|
}
|
|
|
|
|
2009-01-16 09:40:23 +08:00
|
|
|
static void
|
2011-08-09 04:57:47 +08:00
|
|
|
function_trace_call(unsigned long ip, unsigned long parent_ip,
|
2011-08-10 00:50:46 +08:00
|
|
|
struct ftrace_ops *op, struct pt_regs *pt_regs)
|
2009-01-16 09:40:23 +08:00
|
|
|
{
|
2013-11-08 09:08:58 +08:00
|
|
|
struct trace_array *tr = op->private;
|
2009-01-16 09:40:23 +08:00
|
|
|
struct trace_array_cpu *data;
|
|
|
|
unsigned long flags;
|
2013-01-24 20:52:34 +08:00
|
|
|
int bit;
|
2009-01-16 09:40:23 +08:00
|
|
|
int cpu;
|
|
|
|
int pc;
|
|
|
|
|
2013-11-08 09:08:58 +08:00
|
|
|
if (unlikely(!tr->function_enabled))
|
2009-01-16 09:40:23 +08:00
|
|
|
return;
|
|
|
|
|
2012-11-03 05:52:35 +08:00
|
|
|
pc = preempt_count();
|
|
|
|
preempt_disable_notrace();
|
2009-01-16 09:40:23 +08:00
|
|
|
|
2012-11-03 05:52:35 +08:00
|
|
|
bit = trace_test_and_set_recursion(TRACE_FTRACE_START, TRACE_FTRACE_MAX);
|
|
|
|
if (bit < 0)
|
|
|
|
goto out;
|
|
|
|
|
|
|
|
cpu = smp_processor_id();
|
tracing: Consolidate max_tr into main trace_array structure
Currently, the way the latency tracers and snapshot feature works
is to have a separate trace_array called "max_tr" that holds the
snapshot buffer. For latency tracers, this snapshot buffer is used
to swap the running buffer with this buffer to save the current max
latency.
The only items needed for the max_tr is really just a copy of the buffer
itself, the per_cpu data pointers, the time_start timestamp that states
when the max latency was triggered, and the cpu that the max latency
was triggered on. All other fields in trace_array are unused by the
max_tr, making the max_tr mostly bloat.
This change removes the max_tr completely, and adds a new structure
called trace_buffer, that holds the buffer pointer, the per_cpu data
pointers, the time_start timestamp, and the cpu where the latency occurred.
The trace_array, now has two trace_buffers, one for the normal trace and
one for the max trace or snapshot. By doing this, not only do we remove
the bloat from the max_trace but the instances of traces can now use
their own snapshot feature and not have just the top level global_trace have
the snapshot feature and latency tracers for itself.
Signed-off-by: Steven Rostedt <rostedt@goodmis.org>
2013-03-05 22:24:35 +08:00
|
|
|
data = per_cpu_ptr(tr->trace_buffer.data, cpu);
|
2012-11-03 05:52:35 +08:00
|
|
|
if (!atomic_read(&data->disabled)) {
|
|
|
|
local_save_flags(flags);
|
2009-02-05 14:13:37 +08:00
|
|
|
trace_function(tr, ip, parent_ip, flags, pc);
|
2009-01-16 09:40:23 +08:00
|
|
|
}
|
2012-11-03 05:52:35 +08:00
|
|
|
trace_clear_recursion(bit);
|
2009-01-16 09:40:23 +08:00
|
|
|
|
2012-11-03 05:52:35 +08:00
|
|
|
out:
|
|
|
|
preempt_enable_notrace();
|
2009-01-16 09:40:23 +08:00
|
|
|
}
|
|
|
|
|
2009-01-16 08:12:40 +08:00
|
|
|
static void
|
2011-08-09 04:57:47 +08:00
|
|
|
function_stack_trace_call(unsigned long ip, unsigned long parent_ip,
|
2011-08-10 00:50:46 +08:00
|
|
|
struct ftrace_ops *op, struct pt_regs *pt_regs)
|
2009-01-16 08:12:40 +08:00
|
|
|
{
|
2013-11-08 09:08:58 +08:00
|
|
|
struct trace_array *tr = op->private;
|
2009-01-16 08:12:40 +08:00
|
|
|
struct trace_array_cpu *data;
|
|
|
|
unsigned long flags;
|
|
|
|
long disabled;
|
|
|
|
int cpu;
|
|
|
|
int pc;
|
|
|
|
|
2013-11-08 09:08:58 +08:00
|
|
|
if (unlikely(!tr->function_enabled))
|
2009-01-16 08:12:40 +08:00
|
|
|
return;
|
|
|
|
|
|
|
|
/*
|
|
|
|
* Need to use raw, since this must be called before the
|
|
|
|
* recursive protection is performed.
|
|
|
|
*/
|
|
|
|
local_irq_save(flags);
|
|
|
|
cpu = raw_smp_processor_id();
|
tracing: Consolidate max_tr into main trace_array structure
Currently, the way the latency tracers and snapshot feature works
is to have a separate trace_array called "max_tr" that holds the
snapshot buffer. For latency tracers, this snapshot buffer is used
to swap the running buffer with this buffer to save the current max
latency.
The only items needed for the max_tr is really just a copy of the buffer
itself, the per_cpu data pointers, the time_start timestamp that states
when the max latency was triggered, and the cpu that the max latency
was triggered on. All other fields in trace_array are unused by the
max_tr, making the max_tr mostly bloat.
This change removes the max_tr completely, and adds a new structure
called trace_buffer, that holds the buffer pointer, the per_cpu data
pointers, the time_start timestamp, and the cpu where the latency occurred.
The trace_array, now has two trace_buffers, one for the normal trace and
one for the max trace or snapshot. By doing this, not only do we remove
the bloat from the max_trace but the instances of traces can now use
their own snapshot feature and not have just the top level global_trace have
the snapshot feature and latency tracers for itself.
Signed-off-by: Steven Rostedt <rostedt@goodmis.org>
2013-03-05 22:24:35 +08:00
|
|
|
data = per_cpu_ptr(tr->trace_buffer.data, cpu);
|
2009-01-16 08:12:40 +08:00
|
|
|
disabled = atomic_inc_return(&data->disabled);
|
|
|
|
|
|
|
|
if (likely(disabled == 1)) {
|
|
|
|
pc = preempt_count();
|
2009-02-05 14:13:37 +08:00
|
|
|
trace_function(tr, ip, parent_ip, flags, pc);
|
2009-01-16 08:12:40 +08:00
|
|
|
/*
|
|
|
|
* skip over 5 funcs:
|
|
|
|
* __ftrace_trace_stack,
|
|
|
|
* __trace_stack,
|
|
|
|
* function_stack_trace_call
|
|
|
|
* ftrace_list_func
|
|
|
|
* ftrace_call
|
|
|
|
*/
|
2009-02-05 14:13:37 +08:00
|
|
|
__trace_stack(tr, flags, 5, pc);
|
2009-01-16 08:12:40 +08:00
|
|
|
}
|
|
|
|
|
|
|
|
atomic_dec(&data->disabled);
|
|
|
|
local_irq_restore(flags);
|
|
|
|
}
|
|
|
|
|
|
|
|
static struct tracer_opt func_opts[] = {
|
|
|
|
#ifdef CONFIG_STACKTRACE
|
|
|
|
{ TRACER_OPT(func_stack_trace, TRACE_FUNC_OPT_STACK) },
|
|
|
|
#endif
|
|
|
|
{ } /* Always set a last empty entry */
|
|
|
|
};
|
|
|
|
|
|
|
|
static struct tracer_flags func_flags = {
|
|
|
|
.val = 0, /* By default: all flags disabled */
|
|
|
|
.opts = func_opts
|
|
|
|
};
|
|
|
|
|
2013-11-08 09:08:58 +08:00
|
|
|
static void tracing_start_function_trace(struct trace_array *tr)
|
2009-01-16 11:21:43 +08:00
|
|
|
{
|
2013-11-08 09:08:58 +08:00
|
|
|
tr->function_enabled = 0;
|
|
|
|
register_ftrace_function(tr->ops);
|
|
|
|
tr->function_enabled = 1;
|
2009-01-16 11:21:43 +08:00
|
|
|
}
|
|
|
|
|
2013-11-08 09:08:58 +08:00
|
|
|
static void tracing_stop_function_trace(struct trace_array *tr)
|
2009-01-16 11:21:43 +08:00
|
|
|
{
|
2013-11-08 09:08:58 +08:00
|
|
|
tr->function_enabled = 0;
|
|
|
|
unregister_ftrace_function(tr->ops);
|
2009-01-16 11:21:43 +08:00
|
|
|
}
|
|
|
|
|
2014-01-11 00:13:54 +08:00
|
|
|
static int
|
|
|
|
func_set_flag(struct trace_array *tr, u32 old_flags, u32 bit, int set)
|
2009-01-16 08:12:40 +08:00
|
|
|
{
|
2012-07-10 08:10:46 +08:00
|
|
|
switch (bit) {
|
|
|
|
case TRACE_FUNC_OPT_STACK:
|
2009-01-16 08:12:40 +08:00
|
|
|
/* do nothing if already set */
|
|
|
|
if (!!set == !!(func_flags.val & TRACE_FUNC_OPT_STACK))
|
2012-07-10 08:10:46 +08:00
|
|
|
break;
|
2009-01-16 08:12:40 +08:00
|
|
|
|
2013-11-08 09:08:58 +08:00
|
|
|
unregister_ftrace_function(tr->ops);
|
|
|
|
|
2009-01-16 11:21:43 +08:00
|
|
|
if (set) {
|
2014-01-11 06:01:58 +08:00
|
|
|
tr->ops->func = function_stack_trace_call;
|
2013-11-08 09:08:58 +08:00
|
|
|
register_ftrace_function(tr->ops);
|
2009-01-16 11:21:43 +08:00
|
|
|
} else {
|
2014-01-11 06:01:58 +08:00
|
|
|
tr->ops->func = function_trace_call;
|
2013-11-08 09:08:58 +08:00
|
|
|
register_ftrace_function(tr->ops);
|
2009-01-16 11:21:43 +08:00
|
|
|
}
|
2009-01-16 08:12:40 +08:00
|
|
|
|
2012-07-10 08:10:46 +08:00
|
|
|
break;
|
|
|
|
default:
|
|
|
|
return -EINVAL;
|
2009-01-16 08:12:40 +08:00
|
|
|
}
|
|
|
|
|
2012-07-10 08:10:46 +08:00
|
|
|
return 0;
|
2009-01-16 08:12:40 +08:00
|
|
|
}
|
|
|
|
|
2013-07-19 02:41:51 +08:00
|
|
|
static struct tracer function_trace __tracer_data =
|
ftrace: function tracer
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: Ingo 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: Steven Rostedt <srostedt@redhat.com>
Signed-off-by: Arnaldo Carvalho de Melo <acme@ghostprotocols.net>
Signed-off-by: Ingo Molnar <mingo@elte.hu>
Signed-off-by: Thomas Gleixner <tglx@linutronix.de>
2008-05-13 03:20:42 +08:00
|
|
|
{
|
2009-01-16 11:21:43 +08:00
|
|
|
.name = "function",
|
|
|
|
.init = function_trace_init,
|
|
|
|
.reset = function_trace_reset,
|
|
|
|
.start = function_trace_start,
|
2009-01-16 08:12:40 +08:00
|
|
|
.flags = &func_flags,
|
|
|
|
.set_flag = func_set_flag,
|
2013-11-08 09:08:58 +08:00
|
|
|
.allow_instances = true,
|
2008-05-13 03:20:44 +08:00
|
|
|
#ifdef CONFIG_FTRACE_SELFTEST
|
2009-01-16 11:21:43 +08:00
|
|
|
.selftest = trace_selftest_startup_function,
|
2008-05-13 03:20:44 +08:00
|
|
|
#endif
|
ftrace: function tracer
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: Ingo 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: Steven Rostedt <srostedt@redhat.com>
Signed-off-by: Arnaldo Carvalho de Melo <acme@ghostprotocols.net>
Signed-off-by: Ingo Molnar <mingo@elte.hu>
Signed-off-by: Thomas Gleixner <tglx@linutronix.de>
2008-05-13 03:20:42 +08:00
|
|
|
};
|
|
|
|
|
2009-02-15 08:04:24 +08:00
|
|
|
#ifdef CONFIG_DYNAMIC_FTRACE
|
2013-03-09 21:36:53 +08:00
|
|
|
static int update_count(void **data)
|
2009-02-15 08:04:24 +08:00
|
|
|
{
|
2013-03-09 21:36:53 +08:00
|
|
|
unsigned long *count = (long *)data;
|
2009-02-15 08:04:24 +08:00
|
|
|
|
|
|
|
if (!*count)
|
2013-03-09 21:36:53 +08:00
|
|
|
return 0;
|
2009-02-15 08:04:24 +08:00
|
|
|
|
|
|
|
if (*count != -1)
|
|
|
|
(*count)--;
|
|
|
|
|
2013-03-09 21:36:53 +08:00
|
|
|
return 1;
|
2009-02-15 08:04:24 +08:00
|
|
|
}
|
|
|
|
|
|
|
|
static void
|
2013-03-09 21:56:43 +08:00
|
|
|
ftrace_traceon_count(unsigned long ip, unsigned long parent_ip, void **data)
|
2009-02-15 08:04:24 +08:00
|
|
|
{
|
2013-03-09 21:36:53 +08:00
|
|
|
if (tracing_is_on())
|
2009-02-15 08:04:24 +08:00
|
|
|
return;
|
|
|
|
|
2013-03-09 21:36:53 +08:00
|
|
|
if (update_count(data))
|
|
|
|
tracing_on();
|
|
|
|
}
|
2009-02-15 08:04:24 +08:00
|
|
|
|
2013-03-09 21:36:53 +08:00
|
|
|
static void
|
2013-03-09 21:56:43 +08:00
|
|
|
ftrace_traceoff_count(unsigned long ip, unsigned long parent_ip, void **data)
|
2013-03-09 21:36:53 +08:00
|
|
|
{
|
|
|
|
if (!tracing_is_on())
|
|
|
|
return;
|
2009-02-15 08:04:24 +08:00
|
|
|
|
2013-03-09 21:36:53 +08:00
|
|
|
if (update_count(data))
|
|
|
|
tracing_off();
|
2009-02-15 08:04:24 +08:00
|
|
|
}
|
|
|
|
|
2013-03-09 21:56:43 +08:00
|
|
|
static void
|
|
|
|
ftrace_traceon(unsigned long ip, unsigned long parent_ip, void **data)
|
|
|
|
{
|
|
|
|
if (tracing_is_on())
|
|
|
|
return;
|
|
|
|
|
|
|
|
tracing_on();
|
|
|
|
}
|
|
|
|
|
|
|
|
static void
|
|
|
|
ftrace_traceoff(unsigned long ip, unsigned long parent_ip, void **data)
|
|
|
|
{
|
|
|
|
if (!tracing_is_on())
|
|
|
|
return;
|
|
|
|
|
|
|
|
tracing_off();
|
|
|
|
}
|
|
|
|
|
2013-03-13 22:17:50 +08:00
|
|
|
/*
|
|
|
|
* Skip 4:
|
|
|
|
* ftrace_stacktrace()
|
|
|
|
* function_trace_probe_call()
|
|
|
|
* ftrace_ops_list_func()
|
|
|
|
* ftrace_call()
|
|
|
|
*/
|
|
|
|
#define STACK_SKIP 4
|
|
|
|
|
|
|
|
static void
|
|
|
|
ftrace_stacktrace(unsigned long ip, unsigned long parent_ip, void **data)
|
|
|
|
{
|
|
|
|
trace_dump_stack(STACK_SKIP);
|
|
|
|
}
|
|
|
|
|
|
|
|
static void
|
|
|
|
ftrace_stacktrace_count(unsigned long ip, unsigned long parent_ip, void **data)
|
|
|
|
{
|
|
|
|
if (!tracing_is_on())
|
|
|
|
return;
|
|
|
|
|
|
|
|
if (update_count(data))
|
|
|
|
trace_dump_stack(STACK_SKIP);
|
|
|
|
}
|
|
|
|
|
2013-05-01 03:46:14 +08:00
|
|
|
static void
|
|
|
|
ftrace_dump_probe(unsigned long ip, unsigned long parent_ip, void **data)
|
|
|
|
{
|
|
|
|
if (update_count(data))
|
|
|
|
ftrace_dump(DUMP_ALL);
|
|
|
|
}
|
|
|
|
|
2013-05-01 07:00:46 +08:00
|
|
|
/* Only dump the current CPU buffer. */
|
|
|
|
static void
|
|
|
|
ftrace_cpudump_probe(unsigned long ip, unsigned long parent_ip, void **data)
|
|
|
|
{
|
|
|
|
if (update_count(data))
|
|
|
|
ftrace_dump(DUMP_ORIG);
|
|
|
|
}
|
|
|
|
|
2009-02-17 12:38:13 +08:00
|
|
|
static int
|
2013-03-13 22:17:50 +08:00
|
|
|
ftrace_probe_print(const char *name, struct seq_file *m,
|
|
|
|
unsigned long ip, void *data)
|
|
|
|
{
|
|
|
|
long count = (long)data;
|
|
|
|
|
|
|
|
seq_printf(m, "%ps:%s", (void *)ip, name);
|
|
|
|
|
|
|
|
if (count == -1)
|
2014-11-09 04:42:10 +08:00
|
|
|
seq_puts(m, ":unlimited\n");
|
2013-03-13 22:17:50 +08:00
|
|
|
else
|
|
|
|
seq_printf(m, ":count=%ld\n", count);
|
|
|
|
|
|
|
|
return 0;
|
|
|
|
}
|
|
|
|
|
|
|
|
static int
|
|
|
|
ftrace_traceon_print(struct seq_file *m, unsigned long ip,
|
|
|
|
struct ftrace_probe_ops *ops, void *data)
|
|
|
|
{
|
|
|
|
return ftrace_probe_print("traceon", m, ip, data);
|
|
|
|
}
|
|
|
|
|
|
|
|
static int
|
|
|
|
ftrace_traceoff_print(struct seq_file *m, unsigned long ip,
|
|
|
|
struct ftrace_probe_ops *ops, void *data)
|
|
|
|
{
|
|
|
|
return ftrace_probe_print("traceoff", m, ip, data);
|
|
|
|
}
|
|
|
|
|
|
|
|
static int
|
|
|
|
ftrace_stacktrace_print(struct seq_file *m, unsigned long ip,
|
|
|
|
struct ftrace_probe_ops *ops, void *data)
|
|
|
|
{
|
|
|
|
return ftrace_probe_print("stacktrace", m, ip, data);
|
|
|
|
}
|
2009-02-17 12:38:13 +08:00
|
|
|
|
2013-05-01 03:46:14 +08:00
|
|
|
static int
|
|
|
|
ftrace_dump_print(struct seq_file *m, unsigned long ip,
|
|
|
|
struct ftrace_probe_ops *ops, void *data)
|
|
|
|
{
|
|
|
|
return ftrace_probe_print("dump", m, ip, data);
|
|
|
|
}
|
|
|
|
|
2013-05-01 07:00:46 +08:00
|
|
|
static int
|
|
|
|
ftrace_cpudump_print(struct seq_file *m, unsigned long ip,
|
|
|
|
struct ftrace_probe_ops *ops, void *data)
|
|
|
|
{
|
|
|
|
return ftrace_probe_print("cpudump", m, ip, data);
|
|
|
|
}
|
|
|
|
|
2013-03-09 21:56:43 +08:00
|
|
|
static struct ftrace_probe_ops traceon_count_probe_ops = {
|
|
|
|
.func = ftrace_traceon_count,
|
2013-03-13 22:17:50 +08:00
|
|
|
.print = ftrace_traceon_print,
|
2013-03-09 21:56:43 +08:00
|
|
|
};
|
|
|
|
|
|
|
|
static struct ftrace_probe_ops traceoff_count_probe_ops = {
|
|
|
|
.func = ftrace_traceoff_count,
|
2013-03-13 22:17:50 +08:00
|
|
|
.print = ftrace_traceoff_print,
|
|
|
|
};
|
|
|
|
|
|
|
|
static struct ftrace_probe_ops stacktrace_count_probe_ops = {
|
|
|
|
.func = ftrace_stacktrace_count,
|
|
|
|
.print = ftrace_stacktrace_print,
|
2013-03-09 21:56:43 +08:00
|
|
|
};
|
|
|
|
|
2013-05-01 03:46:14 +08:00
|
|
|
static struct ftrace_probe_ops dump_probe_ops = {
|
|
|
|
.func = ftrace_dump_probe,
|
|
|
|
.print = ftrace_dump_print,
|
|
|
|
};
|
|
|
|
|
2013-05-01 07:00:46 +08:00
|
|
|
static struct ftrace_probe_ops cpudump_probe_ops = {
|
|
|
|
.func = ftrace_cpudump_probe,
|
|
|
|
.print = ftrace_cpudump_print,
|
|
|
|
};
|
|
|
|
|
2009-02-18 01:32:04 +08:00
|
|
|
static struct ftrace_probe_ops traceon_probe_ops = {
|
2009-02-15 08:04:24 +08:00
|
|
|
.func = ftrace_traceon,
|
2013-03-13 22:17:50 +08:00
|
|
|
.print = ftrace_traceon_print,
|
2009-02-15 08:04:24 +08:00
|
|
|
};
|
|
|
|
|
2009-02-18 01:32:04 +08:00
|
|
|
static struct ftrace_probe_ops traceoff_probe_ops = {
|
2009-02-15 08:04:24 +08:00
|
|
|
.func = ftrace_traceoff,
|
2013-03-13 22:17:50 +08:00
|
|
|
.print = ftrace_traceoff_print,
|
2009-02-15 08:04:24 +08:00
|
|
|
};
|
|
|
|
|
2013-03-13 22:17:50 +08:00
|
|
|
static struct ftrace_probe_ops stacktrace_probe_ops = {
|
|
|
|
.func = ftrace_stacktrace,
|
|
|
|
.print = ftrace_stacktrace_print,
|
|
|
|
};
|
2009-02-17 12:38:13 +08:00
|
|
|
|
2009-02-15 08:04:24 +08:00
|
|
|
static int
|
2013-03-13 22:17:50 +08:00
|
|
|
ftrace_trace_probe_callback(struct ftrace_probe_ops *ops,
|
|
|
|
struct ftrace_hash *hash, char *glob,
|
|
|
|
char *cmd, char *param, int enable)
|
2009-02-15 08:04:24 +08:00
|
|
|
{
|
|
|
|
void *count = (void *)-1;
|
|
|
|
char *number;
|
|
|
|
int ret;
|
|
|
|
|
|
|
|
/* hash funcs only work with set_ftrace_filter */
|
|
|
|
if (!enable)
|
|
|
|
return -EINVAL;
|
|
|
|
|
2013-03-12 21:25:00 +08:00
|
|
|
if (glob[0] == '!') {
|
|
|
|
unregister_ftrace_function_probe_func(glob+1, ops);
|
|
|
|
return 0;
|
|
|
|
}
|
|
|
|
|
2009-02-15 08:04:24 +08:00
|
|
|
if (!param)
|
|
|
|
goto out_reg;
|
|
|
|
|
|
|
|
number = strsep(¶m, ":");
|
|
|
|
|
|
|
|
if (!strlen(number))
|
|
|
|
goto out_reg;
|
|
|
|
|
|
|
|
/*
|
|
|
|
* We use the callback data field (which is a pointer)
|
|
|
|
* as our counter.
|
|
|
|
*/
|
2012-09-27 04:08:38 +08:00
|
|
|
ret = kstrtoul(number, 0, (unsigned long *)&count);
|
2009-02-15 08:04:24 +08:00
|
|
|
if (ret)
|
|
|
|
return ret;
|
|
|
|
|
|
|
|
out_reg:
|
2009-02-18 01:32:04 +08:00
|
|
|
ret = register_ftrace_function_probe(glob, ops, count);
|
2009-02-15 08:04:24 +08:00
|
|
|
|
2009-07-15 12:29:06 +08:00
|
|
|
return ret < 0 ? ret : 0;
|
2009-02-15 08:04:24 +08:00
|
|
|
}
|
|
|
|
|
2013-03-13 22:17:50 +08:00
|
|
|
static int
|
|
|
|
ftrace_trace_onoff_callback(struct ftrace_hash *hash,
|
|
|
|
char *glob, char *cmd, char *param, int enable)
|
|
|
|
{
|
|
|
|
struct ftrace_probe_ops *ops;
|
|
|
|
|
|
|
|
/* we register both traceon and traceoff to this callback */
|
|
|
|
if (strcmp(cmd, "traceon") == 0)
|
|
|
|
ops = param ? &traceon_count_probe_ops : &traceon_probe_ops;
|
|
|
|
else
|
|
|
|
ops = param ? &traceoff_count_probe_ops : &traceoff_probe_ops;
|
|
|
|
|
|
|
|
return ftrace_trace_probe_callback(ops, hash, glob, cmd,
|
|
|
|
param, enable);
|
|
|
|
}
|
|
|
|
|
|
|
|
static int
|
|
|
|
ftrace_stacktrace_callback(struct ftrace_hash *hash,
|
|
|
|
char *glob, char *cmd, char *param, int enable)
|
|
|
|
{
|
|
|
|
struct ftrace_probe_ops *ops;
|
|
|
|
|
|
|
|
ops = param ? &stacktrace_count_probe_ops : &stacktrace_probe_ops;
|
|
|
|
|
|
|
|
return ftrace_trace_probe_callback(ops, hash, glob, cmd,
|
|
|
|
param, enable);
|
|
|
|
}
|
|
|
|
|
2013-05-01 03:46:14 +08:00
|
|
|
static int
|
|
|
|
ftrace_dump_callback(struct ftrace_hash *hash,
|
|
|
|
char *glob, char *cmd, char *param, int enable)
|
|
|
|
{
|
|
|
|
struct ftrace_probe_ops *ops;
|
|
|
|
|
|
|
|
ops = &dump_probe_ops;
|
|
|
|
|
|
|
|
/* Only dump once. */
|
|
|
|
return ftrace_trace_probe_callback(ops, hash, glob, cmd,
|
|
|
|
"1", enable);
|
|
|
|
}
|
|
|
|
|
2013-05-01 07:00:46 +08:00
|
|
|
static int
|
|
|
|
ftrace_cpudump_callback(struct ftrace_hash *hash,
|
|
|
|
char *glob, char *cmd, char *param, int enable)
|
|
|
|
{
|
|
|
|
struct ftrace_probe_ops *ops;
|
|
|
|
|
|
|
|
ops = &cpudump_probe_ops;
|
|
|
|
|
|
|
|
/* Only dump once. */
|
|
|
|
return ftrace_trace_probe_callback(ops, hash, glob, cmd,
|
|
|
|
"1", enable);
|
|
|
|
}
|
|
|
|
|
2009-02-15 08:04:24 +08:00
|
|
|
static struct ftrace_func_command ftrace_traceon_cmd = {
|
|
|
|
.name = "traceon",
|
|
|
|
.func = ftrace_trace_onoff_callback,
|
|
|
|
};
|
|
|
|
|
|
|
|
static struct ftrace_func_command ftrace_traceoff_cmd = {
|
|
|
|
.name = "traceoff",
|
|
|
|
.func = ftrace_trace_onoff_callback,
|
|
|
|
};
|
|
|
|
|
2013-03-13 22:17:50 +08:00
|
|
|
static struct ftrace_func_command ftrace_stacktrace_cmd = {
|
|
|
|
.name = "stacktrace",
|
|
|
|
.func = ftrace_stacktrace_callback,
|
|
|
|
};
|
|
|
|
|
2013-05-01 03:46:14 +08:00
|
|
|
static struct ftrace_func_command ftrace_dump_cmd = {
|
|
|
|
.name = "dump",
|
|
|
|
.func = ftrace_dump_callback,
|
|
|
|
};
|
|
|
|
|
2013-05-01 07:00:46 +08:00
|
|
|
static struct ftrace_func_command ftrace_cpudump_cmd = {
|
|
|
|
.name = "cpudump",
|
|
|
|
.func = ftrace_cpudump_callback,
|
|
|
|
};
|
|
|
|
|
2009-02-15 08:04:24 +08:00
|
|
|
static int __init init_func_cmd_traceon(void)
|
|
|
|
{
|
|
|
|
int ret;
|
|
|
|
|
|
|
|
ret = register_ftrace_command(&ftrace_traceoff_cmd);
|
|
|
|
if (ret)
|
|
|
|
return ret;
|
|
|
|
|
|
|
|
ret = register_ftrace_command(&ftrace_traceon_cmd);
|
|
|
|
if (ret)
|
2013-05-01 03:46:14 +08:00
|
|
|
goto out_free_traceoff;
|
2013-03-13 22:17:50 +08:00
|
|
|
|
|
|
|
ret = register_ftrace_command(&ftrace_stacktrace_cmd);
|
2013-05-01 03:46:14 +08:00
|
|
|
if (ret)
|
|
|
|
goto out_free_traceon;
|
|
|
|
|
|
|
|
ret = register_ftrace_command(&ftrace_dump_cmd);
|
|
|
|
if (ret)
|
|
|
|
goto out_free_stacktrace;
|
|
|
|
|
2013-05-01 07:00:46 +08:00
|
|
|
ret = register_ftrace_command(&ftrace_cpudump_cmd);
|
|
|
|
if (ret)
|
|
|
|
goto out_free_dump;
|
|
|
|
|
2013-05-01 03:46:14 +08:00
|
|
|
return 0;
|
|
|
|
|
2013-05-01 07:00:46 +08:00
|
|
|
out_free_dump:
|
|
|
|
unregister_ftrace_command(&ftrace_dump_cmd);
|
2013-05-01 03:46:14 +08:00
|
|
|
out_free_stacktrace:
|
|
|
|
unregister_ftrace_command(&ftrace_stacktrace_cmd);
|
|
|
|
out_free_traceon:
|
|
|
|
unregister_ftrace_command(&ftrace_traceon_cmd);
|
|
|
|
out_free_traceoff:
|
|
|
|
unregister_ftrace_command(&ftrace_traceoff_cmd);
|
|
|
|
|
2009-02-15 08:04:24 +08:00
|
|
|
return ret;
|
|
|
|
}
|
|
|
|
#else
|
|
|
|
static inline int init_func_cmd_traceon(void)
|
|
|
|
{
|
|
|
|
return 0;
|
|
|
|
}
|
|
|
|
#endif /* CONFIG_DYNAMIC_FTRACE */
|
|
|
|
|
ftrace: function tracer
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: Ingo 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: Steven Rostedt <srostedt@redhat.com>
Signed-off-by: Arnaldo Carvalho de Melo <acme@ghostprotocols.net>
Signed-off-by: Ingo Molnar <mingo@elte.hu>
Signed-off-by: Thomas Gleixner <tglx@linutronix.de>
2008-05-13 03:20:42 +08:00
|
|
|
static __init int init_function_trace(void)
|
|
|
|
{
|
2009-02-15 08:04:24 +08:00
|
|
|
init_func_cmd_traceon();
|
ftrace: function tracer
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: Ingo 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: Steven Rostedt <srostedt@redhat.com>
Signed-off-by: Arnaldo Carvalho de Melo <acme@ghostprotocols.net>
Signed-off-by: Ingo Molnar <mingo@elte.hu>
Signed-off-by: Thomas Gleixner <tglx@linutronix.de>
2008-05-13 03:20:42 +08:00
|
|
|
return register_tracer(&function_trace);
|
|
|
|
}
|
2012-10-06 00:13:07 +08:00
|
|
|
core_initcall(init_function_trace);
|