07 Jul, 2011
1 commit
-
The new code that allows different utilities to pick and choose
what functions they trace broke the :mod: hook that allows users
to trace only functions of a particular module.The reason is that the :mod: hook bypasses the hash that is setup
to allow individual users to trace their own functions and uses
the global hash directly. But if the global hash has not been
set up, it will cause a bug:echo '*:mod:radeon' > /sys/kernel/debug/set_ftrace_filter
produces:
[drm:drm_mode_getfb] *ERROR* invalid framebuffer id
[drm:radeon_crtc_page_flip] *ERROR* failed to reserve new rbo buffer before flip
BUG: unable to handle kernel paging request at ffffffff8160ec90
IP: [] add_hash_entry+0x66/0xd0
PGD 1a05067 PUD 1a09063 PMD 80000000016001e1
Oops: 0003 [#1] SMP Jul 7 04:02:28 phyllis kernel: [55303.858604] CPU 1
Modules linked in: cryptd aes_x86_64 aes_generic binfmt_misc rfcomm bnep ip6table_filter hid radeon r8169 ahci libahci mii ttm drm_kms_helper drm video i2c_algo_bit intel_agp intel_gttPid: 10344, comm: bash Tainted: G WC 3.0.0-rc5 #1 Dell Inc. Inspiron N5010/0YXXJJ
RIP: 0010:[] [] add_hash_entry+0x66/0xd0
RSP: 0018:ffff88003a96bda8 EFLAGS: 00010246
RAX: ffff8801301735c0 RBX: ffffffff8160ec80 RCX: 0000000000306ee0
RDX: 0000000000000000 RSI: 0000000000000000 RDI: ffff880137c92940
RBP: ffff88003a96bdb8 R08: ffff880137c95680 R09: 0000000000000000
R10: 0000000000000001 R11: 0000000000000000 R12: ffffffff81c9df78
R13: ffff8801153d1000 R14: 0000000000000000 R15: 0000000000000000
FS: 00007f329c18a700(0000) GS:ffff880137c80000(0000) knlGS:0000000000000000
CS: 0010 DS: 0000 ES: 0000 CR0: 0000000080050033
CR2: ffffffff8160ec90 CR3: 000000003002b000 CR4: 00000000000006e0
DR0: 0000000000000000 DR1: 0000000000000000 DR2: 0000000000000000
DR3: 0000000000000000 DR6: 00000000ffff0ff0 DR7: 0000000000000400
Process bash (pid: 10344, threadinfo ffff88003a96a000, task ffff88012fcfc470)
Stack:
0000000000000fd0 00000000000000fc ffff88003a96be38 ffffffff810d92f5
ffff88011c4c4e00 ffff880000000000 000000000b69f4d0 ffffffff8160ec80
ffff8800300e6f06 0000000081130295 0000000000000282 ffff8800300e6f00
Call Trace:
[] match_records+0x155/0x1b0
[] ftrace_mod_callback+0xbc/0x100
[] ftrace_regex_write+0x16f/0x210
[] ftrace_filter_write+0xf/0x20
[] vfs_write+0xc8/0x190
[] sys_write+0x51/0x90
[] system_call_fastpath+0x16/0x1b
Code: 48 8b 33 31 d2 48 85 f6 75 33 49 89 d4 4c 03 63 08 49 8b 14 24 48 85 d2 48 89 10 74 04 48 89 42 08 49 89 04 24 4c 89 60 08 31 d2
RIP [] add_hash_entry+0x66/0xd0
RSP
CR2: ffffffff8160ec90
---[ end trace a5d031828efdd88e ]---Reported-by: Brian Marete
Signed-off-by: Steven Rostedt
19 May, 2011
1 commit
-
ftrace_ops that are registered to trace functions can now be
agnostic to each other in respect to what functions they trace.
Each ops has their own hash of the functions they want to trace
and a hash to what they do not want to trace. A empty hash for
the functions they want to trace denotes all functions should
be traced that are not in the notrace hash.Cc: Paul E. McKenney
Signed-off-by: Steven Rostedt
04 Jun, 2010
1 commit
-
The ftrace_preempt_disable/enable functions were to address a
recursive race caused by the function tracer. The function tracer
traces all functions which makes it easily susceptible to recursion.
One area was preempt_enable(). This would call the scheduler and
the schedulre would call the function tracer and loop.
(So was it thought).The ftrace_preempt_disable/enable was made to protect against recursion
inside the scheduler by storing the NEED_RESCHED flag. If it was
set before the ftrace_preempt_disable() it would not call schedule
on ftrace_preempt_enable(), thinking that if it was set before then
it would have already scheduled unless it was already in the scheduler.This worked fine except in the case of SMP, where another task would set
the NEED_RESCHED flag for a task on another CPU, and then kick off an
IPI to trigger it. This could cause the NEED_RESCHED to be saved at
ftrace_preempt_disable() but the IPI to arrive in the the preempt
disabled section. The ftrace_preempt_enable() would not call the scheduler
because the flag was already set before entring the section.This bug would cause a missed preemption check and cause lower latencies.
Investigating further, I found that the recusion caused by the function
tracer was not due to schedule(), but due to preempt_schedule(). Now
that preempt_schedule is completely annotated with notrace, the recusion
no longer is an issue.Reported-by: Thomas Gleixner
Signed-off-by: Steven Rostedt
18 Sep, 2009
1 commit
-
For direct function pointers (like what mcount provides) PowerPC64
requires the use of %ps, otherwise nothing is printed.This patch converts all prints of functions retrieved through mcount
to use the %ps format from the %pf.Signed-off-by: Steven Rostedt
18 Jul, 2009
1 commit
-
Merge reason: tracing/core was on an older, pre-rc1 base.
Signed-off-by: Ingo Molnar
17 Jul, 2009
2 commits
-
We can directly use %pf input format instead of kallsyms_lookup()
and %s input formatSigned-off-by: Xiao Guangrong
Reviewed-by: Li Zefan
Signed-off-by: Frederic Weisbecker -
ftrace_trace_onoff_callback() will return an error even if we do the
right operation, for example:# echo _spin_*:traceon:10 > set_ftrace_filter
-bash: echo: write error: Invalid argument
# cat set_ftrace_filter
#### all functions enabled ####
_spin_trylock_bh:traceon:count=10
_spin_unlock_irq:traceon:count=10
_spin_unlock_bh:traceon:count=10
_spin_lock_irq:traceon:count=10
_spin_unlock:traceon:count=10
_spin_trylock:traceon:count=10
_spin_unlock_irqrestore:traceon:count=10
_spin_lock_irqsave:traceon:count=10
_spin_lock_bh:traceon:count=10
_spin_lock:traceon:count=10We want to set _spin_*:traceon:10 to set_ftrace_filter, it complains
with "Invalid argument", but the operation is successful.This is because ftrace_process_regex() returns the number of functions that
matched the pattern. If the number is not 0, this value is returned
by ftrace_regex_write() whereas we want to return the number of bytes
virtually written.
Also the file offset pointer is not updated in this case.If the number of matched functions is lower than the number of bytes written
by the user, this results to a reprocessing of the string given by the user with
a lower size, leading to a malformed ftrace regex and then a -EINVAL returned.So, this patch fixes it by returning 0 if no error occured.
The fix also applies on 2.6.30Signed-off-by: Xiao Guangrong
Reviewed-by: Li Zefan
Cc: stable@kernel.org
Signed-off-by: Frederic Weisbecker
25 Jun, 2009
1 commit
-
Before:
# echo 'sys_open:traceon:' > set_ftrace_filter
# echo 'sys_close:traceoff:5' > set_ftrace_filter
# cat set_ftrace_filter
#### all functions enabled ####
sys_open:traceon:unlimitedsys_close:traceoff:count=0
After:
# cat set_ftrace_filter
#### all functions enabled ####
sys_open:traceon:unlimited
sys_close:traceoff:count=0Signed-off-by: Li Zefan
Cc: Steven Rostedt
Cc: Frederic Weisbecker
LKML-Reference:
Signed-off-by: Ingo Molnar
20 Jun, 2009
1 commit
-
Perfcounter reports the following stats for a wide system
profiling:#
# (2364 samples)
#
# Overhead Symbol
# ........ ......
#
15.40% [k] mwait_idle_with_hints
8.29% [k] read_hpet
5.75% [k] ftrace_caller
3.60% [k] ftrace_call
[...]This snapshot has been taken while neither the function tracer nor
the function graph tracer was running.
With dynamic ftrace, such results show a wrong ftrace behaviour
because all calls to ftrace_caller or ftrace_graph_caller (the patched
calls to mcount) are supposed to be patched into nop if none of those
tracers are running.The problem occurs after the first run of the function tracer. Once we
launch it a second time, the callsites will never be nopped back,
unless you set custom filters.
For example it happens during the self tests at boot time.
The function tracer selftest runs, and then the dynamic tracing is
tested too. After that, the callsites are left un-nopped.This is because the reset callback of the function tracer tries to
unregister two ftrace callbacks in once: the common function tracer
and the function tracer with stack backtrace, regardless of which
one is currently in use.
It then creates an unbalance on ftrace_start_up value which is expected
to be zero when the last ftrace callback is unregistered. When it
reaches zero, the FTRACE_DISABLE_CALLS is set on the next ftrace
command, triggering the patching into nop. But since it becomes
unbalanced, ie becomes lower than zero, if the kernel functions
are patched again (as in every further function tracer runs), they
won't ever be nopped back.Note that ftrace_call and ftrace_graph_call are still patched back
to ftrace_stub in the off case, but not the callers of ftrace_call
and ftrace_graph_caller. It means that the tracing is well deactivated
but we waste a useless call into every kernel function.This patch just unregisters the right ftrace_ops for the function
tracer on its reset callback and ignores the other one which is
not registered, fixing the unbalance. The problem also happens
is .30Signed-off-by: Frederic Weisbecker
Cc: Steven Rostedt
Cc: stable@kernel.org
18 Feb, 2009
4 commits
-
Impact: api and pipe waiting change
Currently, the waiting used in tracing_read_pipe() is done through a
100 msecs schedule_timeout() loop which periodically check if there
are traces on the buffer.This can cause small latencies for programs which are reading the incoming
events.This patch makes the reader waiting for the trace_wait waitqueue except
for few tracers such as the sched and functions tracers which might be
already hold the runqueue lock while waking up the reader.This is performed through a new callback wait_pipe() on struct tracer.
If none is implemented on a specific tracer, the default waiting for
trace_wait queue is attached.Signed-off-by: Frederic Weisbecker
Signed-off-by: Ingo Molnar -
Impact: clean up
The traceon and traceoff function probes are confusing to developers
to what happens when a counter is not specified. This should help
clear things up.# echo "*:traceoff" > set_ftrace_filter
# cat /debug/tracing/set_ftrace_filter#### all functions enabled ####
do_fork:traceoff:unlimitedSigned-off-by: Steven Rostedt
-
Impact: clean up
Ingo Molnar did not like the _hook naming convention used by the
select function tracer. Luis Claudio R. Goncalves suggested using
the "_probe" extension. This patch implements the change of
calling the functions and variables "_hook" and replacing them
with "_probe".Signed-off-by: Steven Rostedt
-
Ingo Molnar pointed out some coding style issues with the recent ftrace
updates. This patch cleans them up.Signed-off-by: Steven Rostedt
17 Feb, 2009
2 commits
-
This patch adds a pretty print version of traceon and traceoff
output for set_ftrace_filter.# echo 'sys_open:traceon:4' > set_ftrace_filter
# cat set_ftrace_filter#### all functions enabled ####
sys_open:traceon:count=4Signed-off-by: Steven Rostedt
-
This patch adds the new function selection commands traceon and
traceoff. traceon sets the function to enable the ring buffers
while traceoff disables the ring buffers. You can pass in the
number of times you want the command to be executed when the function
is hit. It will only execute if the state of the buffers are not
already in that state.Example:
# echo do_fork:traceon:4
Will enable the ring buffers if they are disabled every time it
hits do_fork, up to 4 times.# echo sys_close:traceoff
This will disable the ring buffers every time (unlimited) when
sys_close is called.Signed-off-by: Steven Rostedt
06 Feb, 2009
1 commit
-
Impact: cleanup
To make it easy for ftrace plugin writers, as this was open coded in
the existing pluginsSigned-off-by: Arnaldo Carvalho de Melo
Acked-by: Frédéric Weisbecker
Signed-off-by: Ingo Molnar
05 Feb, 2009
1 commit
-
Impact: cleanup
Signed-off-by: Arnaldo Carvalho de Melo
Signed-off-by: Steven Rostedt
Signed-off-by: Ingo Molnar
16 Jan, 2009
4 commits
-
Impact: clean up
After reorganizing the functions in trace.c and trace_function.c,
they no longer need to be in global context. This patch makes the
functions and one variable into static.Signed-off-by: Steven Rostedt
Signed-off-by: Ingo Molnar -
Impact: less likely to interleave function and stack traces
This patch does replaces the separate stack trace on function with
a record function and stack trace together. This will switch between
the function only recording to a function and stack recording.Also some whitespace fix ups as well.
Signed-off-by: Steven Rostedt
Signed-off-by: Ingo Molnar -
Impact: clean up of trace.c
The function tracer functions were put in trace.c because it needed
to share static variables that were in trace.c. Since then, those
variables have become global for various reasons. This patch moves
the function tracer functions into trace_function.c where they belong.Signed-off-by: Steven Rostedt
Signed-off-by: Ingo Molnar -
Impact: new feature to stack trace any function
Chris Mason asked about being able to pick and choose a function
and get a stack trace from it. This feature enables his request.# echo io_schedule > /debug/tracing/set_ftrace_filter
# echo function > /debug/tracing/current_tracer
# echo func_stack_trace > /debug/tracing/trace_optionsProduces the following in /debug/tracing/trace:
kjournald-702 [001] 135.673060: io_schedule
Signed-off-by: Ingo Molnar
19 Dec, 2008
1 commit
-
Impact: cleanup
This patch factors out common code from multiple tracers into a
tracing_reset_online_cpus() function and converts the tracers to use it.Signed-off-by: Pekka Enberg
Signed-off-by: Ingo Molnar
16 Nov, 2008
1 commit
-
Impact: extend the ->init() method with the ability to fail
This bring a way to know if the initialization of a tracer successed.
A tracer must return 0 on success and a traditional error (ie:
-ENOMEM) if it fails.If a tracer fails to init, it is free to print a detailed warn. The
tracing api will not and switch to a new tracer will just return the
error from the init callback.Note: this will be used for the return tracer.
Signed-off-by: Frederic Weisbecker
Signed-off-by: Ingo Molnar
08 Nov, 2008
2 commits
-
Impact: remove obsolete variable in trace_array structure
With the new start / stop method of ftrace, the ctrl variable
in the trace_array structure is now obsolete. Remove it.Signed-off-by: Steven Rostedt
Signed-off-by: Ingo Molnar -
Impact: Remove the ctrl_update tracer method
With the new quick start/stop method of tracing, the ctrl_update
method is out of date.Signed-off-by: Steven Rostedt
Signed-off-by: Ingo Molnar
06 Nov, 2008
1 commit
-
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
Signed-off-by: Ingo Molnar
21 Oct, 2008
1 commit
-
To avoid further confusion between the ftrace infrastructure and the
function tracer. This patch renames the "ftrace" function tracer
to "function".Now in available_tracers, instead of "ftrace" there will be "function".
This makes more sense, since people will not know exactly what the
"ftrace" tracer does.Signed-off-by: Steven Rostedt
Signed-off-by: Ingo Molnar
14 Oct, 2008
1 commit
-
This patch ports ftrace over to the new ring buffer.
Signed-off-by: Steven Rostedt
Signed-off-by: Ingo Molnar
11 Jul, 2008
1 commit
-
This is more of a clean up. Currently the function tracer initializes the
tracer with which ever CPU was last used for tracing. This value isn't
realy useful for function tracing, but at least it should be something other
than a random number.Signed-off-by: Steven Rostedt
Cc: Steven Rostedt
Cc: Peter Zijlstra
Cc: Andrew Morton
Signed-off-by: Ingo Molnar
27 May, 2008
1 commit
-
The new work with converting the trace hooks over to markers broke the
command line recording of ftrace. This patch fixes it again.Signed-off-by: Steven Rostedt
Cc: Peter Zijlstra
Cc: Mathieu Desnoyers
Signed-off-by: Thomas Gleixner
24 May, 2008
6 commits
-
In cleaning up of the sched_switch code, the function trace recording
of task comms was removed. This patch adds back the recording of comms
for function trace. The output of ftrace now has the task comm instead
of .Signed-off-by: Steven Rostedt
Signed-off-by: Ingo Molnar
Signed-off-by: Thomas Gleixner -
now that we have a kbuild method for notrace, no need to pollute the
C code with the annotations.Signed-off-by: Ingo Molnar
Signed-off-by: Thomas Gleixner -
Signed-off-by: Ingo Molnar
Signed-off-by: Thomas Gleixner -
rename and uninline now() to ftrace_now().
Signed-off-by: Ingo Molnar
Signed-off-by: Thomas Gleixner -
Signed-off-by: Ingo Molnar
Signed-off-by: Thomas Gleixner -
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
--------------------------------------------------------------------
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 (ktime_get_ts+0x4a/0x4e )
swapper-0 0d.h. 1595131us+: _spin_lock+0x8/0x18 (hrtimer_interrupt+0x6e/0x1b0 )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 (ktime_get_ts+0x4a/0x4e )
swapper 0 0 9 00000000 00000001 [f3675f45] 1595.131ms (+0.003ms): _spin_lock+0x8/0x18 (hrtimer_interrupt+0x6e/0x1b0 )
swapper 0 0 9 00000000 00000002 [f3675f48] 1595.135ms (+0.003ms): _spin_lock+0x8/0x18 (hrtimer_interrupt+0x6e/0x1b0 )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
[ 81.479967] CPU 0: bash:3154 _spin_unlock_irqrestore+0x3e/0x5a
[ 81.479968] CPU 0: bash:3154 sub_preempt_count+0x30/0x7a
[ 81.479968] CPU 0: bash:3154 vfs_write+0x11d/0x155
[ 81.479968] CPU 0: bash:3154 dnotify_parent+0x2d/0x78
[ 81.479969] CPU 0: bash:3154 _spin_lock+0x1b/0x70
[ 81.479969] CPU 0: bash:3154 add_preempt_count+0x3e/0x77echo "symonly" > /debugfs/tracing/iter_ctrl
tracer:
[ 81.479913] CPU 0: bash:3154 register_ftrace_function+0x5f/0x66
Signed-off-by: Arnaldo Carvalho de Melo
Signed-off-by: Ingo Molnar
Signed-off-by: Thomas Gleixner