2008-05-12 13:20:42 -06:00
|
|
|
#
|
|
|
|
# Architectures that offer an FTRACE implementation should select HAVE_FTRACE:
|
|
|
|
#
|
|
|
|
config HAVE_FTRACE
|
|
|
|
bool
|
2008-05-12 13:20:42 -06:00
|
|
|
|
2008-05-12 13:20:42 -06:00
|
|
|
config TRACER_MAX_TRACE
|
|
|
|
bool
|
|
|
|
|
2008-05-12 13:20:42 -06:00
|
|
|
config TRACING
|
|
|
|
bool
|
|
|
|
select DEBUG_FS
|
|
|
|
|
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-12 13:20:42 -06:00
|
|
|
config FTRACE
|
|
|
|
bool "Kernel Function Tracer"
|
|
|
|
depends on DEBUG_KERNEL && HAVE_FTRACE
|
|
|
|
select FRAME_POINTER
|
|
|
|
select TRACING
|
2008-05-12 13:20:42 -06:00
|
|
|
select CONTEXT_SWITCH_TRACER
|
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-12 13:20:42 -06:00
|
|
|
help
|
|
|
|
Enable the kernel to trace every kernel function. This is done
|
|
|
|
by using a compiler feature to insert a small, 5-byte No-Operation
|
|
|
|
instruction to the beginning of every kernel function, which NOP
|
|
|
|
sequence is then dynamically patched into a tracer call when
|
|
|
|
tracing is enabled by the administrator. If it's runtime disabled
|
|
|
|
(the bootup default), then the overhead of the instructions is very
|
|
|
|
small and not measurable even in micro-benchmarks.
|
2008-05-12 13:20:42 -06:00
|
|
|
|
2008-05-12 13:20:42 -06:00
|
|
|
config IRQSOFF_TRACER
|
|
|
|
bool "Interrupts-off Latency Tracer"
|
|
|
|
default n
|
|
|
|
depends on TRACE_IRQFLAGS_SUPPORT
|
|
|
|
depends on GENERIC_TIME
|
|
|
|
select TRACE_IRQFLAGS
|
|
|
|
select TRACING
|
|
|
|
select TRACER_MAX_TRACE
|
|
|
|
help
|
|
|
|
This option measures the time spent in irqs-off critical
|
|
|
|
sections, with microsecond accuracy.
|
|
|
|
|
|
|
|
The default measurement method is a maximum search, which is
|
|
|
|
disabled by default and can be runtime (re-)started
|
|
|
|
via:
|
|
|
|
|
|
|
|
echo 0 > /debugfs/tracing/tracing_max_latency
|
|
|
|
|
2008-05-12 13:20:42 -06:00
|
|
|
(Note that kernel size and overhead increases with this option
|
|
|
|
enabled. This option and the preempt-off timing option can be
|
|
|
|
used together or separately.)
|
|
|
|
|
|
|
|
config PREEMPT_TRACER
|
|
|
|
bool "Preemption-off Latency Tracer"
|
|
|
|
default n
|
|
|
|
depends on GENERIC_TIME
|
|
|
|
depends on PREEMPT
|
|
|
|
select TRACING
|
|
|
|
select TRACER_MAX_TRACE
|
|
|
|
help
|
|
|
|
This option measures the time spent in preemption off critical
|
|
|
|
sections, with microsecond accuracy.
|
|
|
|
|
|
|
|
The default measurement method is a maximum search, which is
|
|
|
|
disabled by default and can be runtime (re-)started
|
|
|
|
via:
|
|
|
|
|
|
|
|
echo 0 > /debugfs/tracing/tracing_max_latency
|
|
|
|
|
|
|
|
(Note that kernel size and overhead increases with this option
|
|
|
|
enabled. This option and the irqs-off timing option can be
|
|
|
|
used together or separately.)
|
|
|
|
|
2008-05-12 13:20:42 -06:00
|
|
|
config SCHED_TRACER
|
|
|
|
bool "Scheduling Latency Tracer"
|
|
|
|
depends on DEBUG_KERNEL
|
|
|
|
select TRACING
|
|
|
|
select CONTEXT_SWITCH_TRACER
|
|
|
|
select TRACER_MAX_TRACE
|
|
|
|
help
|
|
|
|
This tracer tracks the latency of the highest priority task
|
|
|
|
to be scheduled in, starting from the point it has woken up.
|
|
|
|
|
2008-05-12 13:20:42 -06:00
|
|
|
config CONTEXT_SWITCH_TRACER
|
|
|
|
bool "Trace process context switches"
|
|
|
|
depends on DEBUG_KERNEL
|
|
|
|
select TRACING
|
|
|
|
select MARKERS
|
|
|
|
help
|
|
|
|
This tracer gets called from the context switch and records
|
|
|
|
all switching of tasks.
|
|
|
|
|
ftrace: dynamic enabling/disabling of function calls
This patch adds a feature to dynamically replace the ftrace code
with the jmps to allow a kernel with ftrace configured to run
as fast as it can without it configured.
The way this works, is on bootup (if ftrace is enabled), a ftrace
function is registered to record the instruction pointer of all
places that call the function.
Later, if there's still any code to patch, a kthread is awoken
(rate limited to at most once a second) that performs a stop_machine,
and replaces all the code that was called with a jmp over the call
to ftrace. It only replaces what was found the previous time. Typically
the system reaches equilibrium quickly after bootup and there's no code
patching needed at all.
e.g.
call ftrace /* 5 bytes */
is replaced with
jmp 3f /* jmp is 2 bytes and we jump 3 forward */
3:
When we want to enable ftrace for function tracing, the IP recording
is removed, and stop_machine is called again to replace all the locations
of that were recorded back to the call of ftrace. When it is disabled,
we replace the code back to the jmp.
Allocation is done by the kthread. If the ftrace recording function is
called, and we don't have any record slots available, then we simply
skip that call. Once a second a new page (if needed) is allocated for
recording new ftrace function calls. A large batch is allocated at
boot up to get most of the calls there.
Because we do this via stop_machine, we don't have to worry about another
CPU executing a ftrace call as we modify it. But we do need to worry
about NMI's so all functions that might be called via nmi must be
annotated with notrace_nmi. When this code is configured in, the NMI code
will not call notrace.
Signed-off-by: Steven Rostedt <srostedt@redhat.com>
Signed-off-by: Ingo Molnar <mingo@elte.hu>
Signed-off-by: Thomas Gleixner <tglx@linutronix.de>
2008-05-12 13:20:42 -06:00
|
|
|
config DYNAMIC_FTRACE
|
|
|
|
bool "enable/disable ftrace tracepoints dynamically"
|
|
|
|
depends on FTRACE
|
|
|
|
default y
|
|
|
|
help
|
|
|
|
This option will modify all the calls to ftrace dynamically
|
|
|
|
(will patch them out of the binary image and replaces them
|
|
|
|
with a No-Op instruction) as they are called. A table is
|
|
|
|
created to dynamically enable them again.
|
|
|
|
|
|
|
|
This way a CONFIG_FTRACE kernel is slightly larger, but otherwise
|
|
|
|
has native performance as long as no tracing is active.
|
|
|
|
|
|
|
|
The changes to the code are done by a kernel thread that
|
|
|
|
wakes up once a second and checks to see if any ftrace calls
|
|
|
|
were made. If so, it runs stop_machine (stops all CPUS)
|
|
|
|
and modifies the code to jump over the call to ftrace.
|