|
|
@@ -7,7 +7,6 @@ Copyright 2008 Red Hat Inc.
|
|
|
(dual licensed under the GPL v2)
|
|
|
Reviewers: Elias Oltmanns, Randy Dunlap, Andrew Morton,
|
|
|
John Kacur, and David Teigland.
|
|
|
-
|
|
|
Written for: 2.6.28-rc2
|
|
|
|
|
|
Introduction
|
|
|
@@ -33,13 +32,26 @@ The File System
|
|
|
Ftrace uses the debugfs file system to hold the control files as
|
|
|
well as the files to display output.
|
|
|
|
|
|
-To mount the debugfs system:
|
|
|
+When debugfs is configured into the kernel (which selecting any ftrace
|
|
|
+option will do) the directory /sys/kernel/debug will be created. To mount
|
|
|
+this directory, you can add to your /etc/fstab file:
|
|
|
+
|
|
|
+ debugfs /sys/kernel/debug debugfs defaults 0 0
|
|
|
+
|
|
|
+Or you can mount it at run time with:
|
|
|
+
|
|
|
+ mount -t debugfs nodev /sys/kernel/debug
|
|
|
|
|
|
- # mkdir /debug
|
|
|
- # mount -t debugfs nodev /debug
|
|
|
+For quicker access to that directory you may want to make a soft link to
|
|
|
+it:
|
|
|
|
|
|
-( Note: it is more common to mount at /sys/kernel/debug, but for
|
|
|
- simplicity this document will use /debug)
|
|
|
+ ln -s /sys/kernel/debug /debug
|
|
|
+
|
|
|
+Any selected ftrace option will also create a directory called tracing
|
|
|
+within the debugfs. The rest of the document will assume that you are in
|
|
|
+the ftrace directory (cd /sys/kernel/debug/tracing) and will only concentrate
|
|
|
+on the files within that directory and not distract from the content with
|
|
|
+the extended "/sys/kernel/debug/tracing" path name.
|
|
|
|
|
|
That's it! (assuming that you have ftrace configured into your kernel)
|
|
|
|
|
|
@@ -389,18 +401,18 @@ trace_options
|
|
|
The trace_options file is used to control what gets printed in
|
|
|
the trace output. To see what is available, simply cat the file:
|
|
|
|
|
|
- cat /debug/tracing/trace_options
|
|
|
+ cat trace_options
|
|
|
print-parent nosym-offset nosym-addr noverbose noraw nohex nobin \
|
|
|
noblock nostacktrace nosched-tree nouserstacktrace nosym-userobj
|
|
|
|
|
|
To disable one of the options, echo in the option prepended with
|
|
|
"no".
|
|
|
|
|
|
- echo noprint-parent > /debug/tracing/trace_options
|
|
|
+ echo noprint-parent > trace_options
|
|
|
|
|
|
To enable an option, leave off the "no".
|
|
|
|
|
|
- echo sym-offset > /debug/tracing/trace_options
|
|
|
+ echo sym-offset > trace_options
|
|
|
|
|
|
Here are the available options:
|
|
|
|
|
|
@@ -476,11 +488,11 @@ sched_switch
|
|
|
This tracer simply records schedule switches. Here is an example
|
|
|
of how to use it.
|
|
|
|
|
|
- # echo sched_switch > /debug/tracing/current_tracer
|
|
|
- # echo 1 > /debug/tracing/tracing_enabled
|
|
|
+ # echo sched_switch > current_tracer
|
|
|
+ # echo 1 > tracing_enabled
|
|
|
# sleep 1
|
|
|
- # echo 0 > /debug/tracing/tracing_enabled
|
|
|
- # cat /debug/tracing/trace
|
|
|
+ # echo 0 > tracing_enabled
|
|
|
+ # cat trace
|
|
|
|
|
|
# tracer: sched_switch
|
|
|
#
|
|
|
@@ -583,13 +595,13 @@ new trace is saved.
|
|
|
To reset the maximum, echo 0 into tracing_max_latency. Here is
|
|
|
an example:
|
|
|
|
|
|
- # echo irqsoff > /debug/tracing/current_tracer
|
|
|
- # echo 0 > /debug/tracing/tracing_max_latency
|
|
|
- # echo 1 > /debug/tracing/tracing_enabled
|
|
|
+ # echo irqsoff > current_tracer
|
|
|
+ # echo 0 > tracing_max_latency
|
|
|
+ # echo 1 > tracing_enabled
|
|
|
# ls -ltr
|
|
|
[...]
|
|
|
- # echo 0 > /debug/tracing/tracing_enabled
|
|
|
- # cat /debug/tracing/latency_trace
|
|
|
+ # echo 0 > tracing_enabled
|
|
|
+ # cat latency_trace
|
|
|
# tracer: irqsoff
|
|
|
#
|
|
|
irqsoff latency trace v1.1.5 on 2.6.26
|
|
|
@@ -690,13 +702,13 @@ Like the irqsoff tracer, it records the maximum latency for
|
|
|
which preemption was disabled. The control of preemptoff tracer
|
|
|
is much like the irqsoff tracer.
|
|
|
|
|
|
- # echo preemptoff > /debug/tracing/current_tracer
|
|
|
- # echo 0 > /debug/tracing/tracing_max_latency
|
|
|
- # echo 1 > /debug/tracing/tracing_enabled
|
|
|
+ # echo preemptoff > current_tracer
|
|
|
+ # echo 0 > tracing_max_latency
|
|
|
+ # echo 1 > tracing_enabled
|
|
|
# ls -ltr
|
|
|
[...]
|
|
|
- # echo 0 > /debug/tracing/tracing_enabled
|
|
|
- # cat /debug/tracing/latency_trace
|
|
|
+ # echo 0 > tracing_enabled
|
|
|
+ # cat latency_trace
|
|
|
# tracer: preemptoff
|
|
|
#
|
|
|
preemptoff latency trace v1.1.5 on 2.6.26-rc8
|
|
|
@@ -837,13 +849,13 @@ tracer.
|
|
|
Again, using this trace is much like the irqsoff and preemptoff
|
|
|
tracers.
|
|
|
|
|
|
- # echo preemptirqsoff > /debug/tracing/current_tracer
|
|
|
- # echo 0 > /debug/tracing/tracing_max_latency
|
|
|
- # echo 1 > /debug/tracing/tracing_enabled
|
|
|
+ # echo preemptirqsoff > current_tracer
|
|
|
+ # echo 0 > tracing_max_latency
|
|
|
+ # echo 1 > tracing_enabled
|
|
|
# ls -ltr
|
|
|
[...]
|
|
|
- # echo 0 > /debug/tracing/tracing_enabled
|
|
|
- # cat /debug/tracing/latency_trace
|
|
|
+ # echo 0 > tracing_enabled
|
|
|
+ # cat latency_trace
|
|
|
# tracer: preemptirqsoff
|
|
|
#
|
|
|
preemptirqsoff latency trace v1.1.5 on 2.6.26-rc8
|
|
|
@@ -999,12 +1011,12 @@ slightly differently than we did with the previous tracers.
|
|
|
Instead of performing an 'ls', we will run 'sleep 1' under
|
|
|
'chrt' which changes the priority of the task.
|
|
|
|
|
|
- # echo wakeup > /debug/tracing/current_tracer
|
|
|
- # echo 0 > /debug/tracing/tracing_max_latency
|
|
|
- # echo 1 > /debug/tracing/tracing_enabled
|
|
|
+ # echo wakeup > current_tracer
|
|
|
+ # echo 0 > tracing_max_latency
|
|
|
+ # echo 1 > tracing_enabled
|
|
|
# chrt -f 5 sleep 1
|
|
|
- # echo 0 > /debug/tracing/tracing_enabled
|
|
|
- # cat /debug/tracing/latency_trace
|
|
|
+ # echo 0 > tracing_enabled
|
|
|
+ # cat latency_trace
|
|
|
# tracer: wakeup
|
|
|
#
|
|
|
wakeup latency trace v1.1.5 on 2.6.26-rc8
|
|
|
@@ -1114,11 +1126,11 @@ can be done from the debug file system. Make sure the
|
|
|
ftrace_enabled is set; otherwise this tracer is a nop.
|
|
|
|
|
|
# sysctl kernel.ftrace_enabled=1
|
|
|
- # echo function > /debug/tracing/current_tracer
|
|
|
- # echo 1 > /debug/tracing/tracing_enabled
|
|
|
+ # echo function > current_tracer
|
|
|
+ # echo 1 > tracing_enabled
|
|
|
# usleep 1
|
|
|
- # echo 0 > /debug/tracing/tracing_enabled
|
|
|
- # cat /debug/tracing/trace
|
|
|
+ # echo 0 > tracing_enabled
|
|
|
+ # cat trace
|
|
|
# tracer: function
|
|
|
#
|
|
|
# TASK-PID CPU# TIMESTAMP FUNCTION
|
|
|
@@ -1155,7 +1167,7 @@ int trace_fd;
|
|
|
[...]
|
|
|
int main(int argc, char *argv[]) {
|
|
|
[...]
|
|
|
- trace_fd = open("/debug/tracing/tracing_enabled", O_WRONLY);
|
|
|
+ trace_fd = open(tracing_file("tracing_enabled"), O_WRONLY);
|
|
|
[...]
|
|
|
if (condition_hit()) {
|
|
|
write(trace_fd, "0", 1);
|
|
|
@@ -1163,26 +1175,20 @@ int main(int argc, char *argv[]) {
|
|
|
[...]
|
|
|
}
|
|
|
|
|
|
-Note: Here we hard coded the path name. The debugfs mount is not
|
|
|
-guaranteed to be at /debug (and is more commonly at
|
|
|
-/sys/kernel/debug). For simple one time traces, the above is
|
|
|
-sufficent. For anything else, a search through /proc/mounts may
|
|
|
-be needed to find where the debugfs file-system is mounted.
|
|
|
-
|
|
|
|
|
|
Single thread tracing
|
|
|
---------------------
|
|
|
|
|
|
-By writing into /debug/tracing/set_ftrace_pid you can trace a
|
|
|
+By writing into set_ftrace_pid you can trace a
|
|
|
single thread. For example:
|
|
|
|
|
|
-# cat /debug/tracing/set_ftrace_pid
|
|
|
+# cat set_ftrace_pid
|
|
|
no pid
|
|
|
-# echo 3111 > /debug/tracing/set_ftrace_pid
|
|
|
-# cat /debug/tracing/set_ftrace_pid
|
|
|
+# echo 3111 > set_ftrace_pid
|
|
|
+# cat set_ftrace_pid
|
|
|
3111
|
|
|
-# echo function > /debug/tracing/current_tracer
|
|
|
-# cat /debug/tracing/trace | head
|
|
|
+# echo function > current_tracer
|
|
|
+# cat trace | head
|
|
|
# tracer: function
|
|
|
#
|
|
|
# TASK-PID CPU# TIMESTAMP FUNCTION
|
|
|
@@ -1193,8 +1199,8 @@ no pid
|
|
|
yum-updatesd-3111 [003] 1637.254683: lock_hrtimer_base <-hrtimer_try_to_cancel
|
|
|
yum-updatesd-3111 [003] 1637.254685: fget_light <-do_sys_poll
|
|
|
yum-updatesd-3111 [003] 1637.254686: pipe_poll <-do_sys_poll
|
|
|
-# echo -1 > /debug/tracing/set_ftrace_pid
|
|
|
-# cat /debug/tracing/trace |head
|
|
|
+# echo -1 > set_ftrace_pid
|
|
|
+# cat trace |head
|
|
|
# tracer: function
|
|
|
#
|
|
|
# TASK-PID CPU# TIMESTAMP FUNCTION
|
|
|
@@ -1216,6 +1222,51 @@ something like this simple program:
|
|
|
#include <fcntl.h>
|
|
|
#include <unistd.h>
|
|
|
|
|
|
+#define _STR(x) #x
|
|
|
+#define STR(x) _STR(x)
|
|
|
+#define MAX_PATH 256
|
|
|
+
|
|
|
+const char *find_debugfs(void)
|
|
|
+{
|
|
|
+ static char debugfs[MAX_PATH+1];
|
|
|
+ static int debugfs_found;
|
|
|
+ char type[100];
|
|
|
+ FILE *fp;
|
|
|
+
|
|
|
+ if (debugfs_found)
|
|
|
+ return debugfs;
|
|
|
+
|
|
|
+ if ((fp = fopen("/proc/mounts","r")) == NULL) {
|
|
|
+ perror("/proc/mounts");
|
|
|
+ return NULL;
|
|
|
+ }
|
|
|
+
|
|
|
+ while (fscanf(fp, "%*s %"
|
|
|
+ STR(MAX_PATH)
|
|
|
+ "s %99s %*s %*d %*d\n",
|
|
|
+ debugfs, type) == 2) {
|
|
|
+ if (strcmp(type, "debugfs") == 0)
|
|
|
+ break;
|
|
|
+ }
|
|
|
+ fclose(fp);
|
|
|
+
|
|
|
+ if (strcmp(type, "debugfs") != 0) {
|
|
|
+ fprintf(stderr, "debugfs not mounted");
|
|
|
+ return NULL;
|
|
|
+ }
|
|
|
+
|
|
|
+ debugfs_found = 1;
|
|
|
+
|
|
|
+ return debugfs;
|
|
|
+}
|
|
|
+
|
|
|
+const char *tracing_file(const char *file_name)
|
|
|
+{
|
|
|
+ static char trace_file[MAX_PATH+1];
|
|
|
+ snprintf(trace_file, MAX_PATH, "%s/%s", find_debugfs(), file_name);
|
|
|
+ return trace_file;
|
|
|
+}
|
|
|
+
|
|
|
int main (int argc, char **argv)
|
|
|
{
|
|
|
if (argc < 1)
|
|
|
@@ -1226,12 +1277,12 @@ int main (int argc, char **argv)
|
|
|
char line[64];
|
|
|
int s;
|
|
|
|
|
|
- ffd = open("/debug/tracing/current_tracer", O_WRONLY);
|
|
|
+ ffd = open(tracing_file("current_tracer"), O_WRONLY);
|
|
|
if (ffd < 0)
|
|
|
exit(-1);
|
|
|
write(ffd, "nop", 3);
|
|
|
|
|
|
- fd = open("/debug/tracing/set_ftrace_pid", O_WRONLY);
|
|
|
+ fd = open(tracing_file("set_ftrace_pid"), O_WRONLY);
|
|
|
s = sprintf(line, "%d\n", getpid());
|
|
|
write(fd, line, s);
|
|
|
|
|
|
@@ -1383,22 +1434,22 @@ want, depending on your needs.
|
|
|
tracing_cpu_mask file) or you might sometimes see unordered
|
|
|
function calls while cpu tracing switch.
|
|
|
|
|
|
- hide: echo nofuncgraph-cpu > /debug/tracing/trace_options
|
|
|
- show: echo funcgraph-cpu > /debug/tracing/trace_options
|
|
|
+ hide: echo nofuncgraph-cpu > trace_options
|
|
|
+ show: echo funcgraph-cpu > trace_options
|
|
|
|
|
|
- The duration (function's time of execution) is displayed on
|
|
|
the closing bracket line of a function or on the same line
|
|
|
than the current function in case of a leaf one. It is default
|
|
|
enabled.
|
|
|
|
|
|
- hide: echo nofuncgraph-duration > /debug/tracing/trace_options
|
|
|
- show: echo funcgraph-duration > /debug/tracing/trace_options
|
|
|
+ hide: echo nofuncgraph-duration > trace_options
|
|
|
+ show: echo funcgraph-duration > trace_options
|
|
|
|
|
|
- The overhead field precedes the duration field in case of
|
|
|
reached duration thresholds.
|
|
|
|
|
|
- hide: echo nofuncgraph-overhead > /debug/tracing/trace_options
|
|
|
- show: echo funcgraph-overhead > /debug/tracing/trace_options
|
|
|
+ hide: echo nofuncgraph-overhead > trace_options
|
|
|
+ show: echo funcgraph-overhead > trace_options
|
|
|
depends on: funcgraph-duration
|
|
|
|
|
|
ie:
|
|
|
@@ -1427,8 +1478,8 @@ want, depending on your needs.
|
|
|
- The task/pid field displays the thread cmdline and pid which
|
|
|
executed the function. It is default disabled.
|
|
|
|
|
|
- hide: echo nofuncgraph-proc > /debug/tracing/trace_options
|
|
|
- show: echo funcgraph-proc > /debug/tracing/trace_options
|
|
|
+ hide: echo nofuncgraph-proc > trace_options
|
|
|
+ show: echo funcgraph-proc > trace_options
|
|
|
|
|
|
ie:
|
|
|
|
|
|
@@ -1451,8 +1502,8 @@ want, depending on your needs.
|
|
|
system clock since it started. A snapshot of this time is
|
|
|
given on each entry/exit of functions
|
|
|
|
|
|
- hide: echo nofuncgraph-abstime > /debug/tracing/trace_options
|
|
|
- show: echo funcgraph-abstime > /debug/tracing/trace_options
|
|
|
+ hide: echo nofuncgraph-abstime > trace_options
|
|
|
+ show: echo funcgraph-abstime > trace_options
|
|
|
|
|
|
ie:
|
|
|
|
|
|
@@ -1549,7 +1600,7 @@ listed in:
|
|
|
|
|
|
available_filter_functions
|
|
|
|
|
|
- # cat /debug/tracing/available_filter_functions
|
|
|
+ # cat available_filter_functions
|
|
|
put_prev_task_idle
|
|
|
kmem_cache_create
|
|
|
pick_next_task_rt
|
|
|
@@ -1561,12 +1612,12 @@ mutex_lock
|
|
|
If I am only interested in sys_nanosleep and hrtimer_interrupt:
|
|
|
|
|
|
# echo sys_nanosleep hrtimer_interrupt \
|
|
|
- > /debug/tracing/set_ftrace_filter
|
|
|
- # echo ftrace > /debug/tracing/current_tracer
|
|
|
- # echo 1 > /debug/tracing/tracing_enabled
|
|
|
+ > set_ftrace_filter
|
|
|
+ # echo ftrace > current_tracer
|
|
|
+ # echo 1 > tracing_enabled
|
|
|
# usleep 1
|
|
|
- # echo 0 > /debug/tracing/tracing_enabled
|
|
|
- # cat /debug/tracing/trace
|
|
|
+ # echo 0 > tracing_enabled
|
|
|
+ # cat trace
|
|
|
# tracer: ftrace
|
|
|
#
|
|
|
# TASK-PID CPU# TIMESTAMP FUNCTION
|
|
|
@@ -1577,7 +1628,7 @@ If I am only interested in sys_nanosleep and hrtimer_interrupt:
|
|
|
|
|
|
To see which functions are being traced, you can cat the file:
|
|
|
|
|
|
- # cat /debug/tracing/set_ftrace_filter
|
|
|
+ # cat set_ftrace_filter
|
|
|
hrtimer_interrupt
|
|
|
sys_nanosleep
|
|
|
|
|
|
@@ -1597,7 +1648,7 @@ Note: It is better to use quotes to enclose the wild cards,
|
|
|
otherwise the shell may expand the parameters into names
|
|
|
of files in the local directory.
|
|
|
|
|
|
- # echo 'hrtimer_*' > /debug/tracing/set_ftrace_filter
|
|
|
+ # echo 'hrtimer_*' > set_ftrace_filter
|
|
|
|
|
|
Produces:
|
|
|
|
|
|
@@ -1618,7 +1669,7 @@ Produces:
|
|
|
|
|
|
Notice that we lost the sys_nanosleep.
|
|
|
|
|
|
- # cat /debug/tracing/set_ftrace_filter
|
|
|
+ # cat set_ftrace_filter
|
|
|
hrtimer_run_queues
|
|
|
hrtimer_run_pending
|
|
|
hrtimer_init
|
|
|
@@ -1644,17 +1695,17 @@ To append to the filters, use '>>'
|
|
|
To clear out a filter so that all functions will be recorded
|
|
|
again:
|
|
|
|
|
|
- # echo > /debug/tracing/set_ftrace_filter
|
|
|
- # cat /debug/tracing/set_ftrace_filter
|
|
|
+ # echo > set_ftrace_filter
|
|
|
+ # cat set_ftrace_filter
|
|
|
#
|
|
|
|
|
|
Again, now we want to append.
|
|
|
|
|
|
- # echo sys_nanosleep > /debug/tracing/set_ftrace_filter
|
|
|
- # cat /debug/tracing/set_ftrace_filter
|
|
|
+ # echo sys_nanosleep > set_ftrace_filter
|
|
|
+ # cat set_ftrace_filter
|
|
|
sys_nanosleep
|
|
|
- # echo 'hrtimer_*' >> /debug/tracing/set_ftrace_filter
|
|
|
- # cat /debug/tracing/set_ftrace_filter
|
|
|
+ # echo 'hrtimer_*' >> set_ftrace_filter
|
|
|
+ # cat set_ftrace_filter
|
|
|
hrtimer_run_queues
|
|
|
hrtimer_run_pending
|
|
|
hrtimer_init
|
|
|
@@ -1677,7 +1728,7 @@ hrtimer_init_sleeper
|
|
|
The set_ftrace_notrace prevents those functions from being
|
|
|
traced.
|
|
|
|
|
|
- # echo '*preempt*' '*lock*' > /debug/tracing/set_ftrace_notrace
|
|
|
+ # echo '*preempt*' '*lock*' > set_ftrace_notrace
|
|
|
|
|
|
Produces:
|
|
|
|
|
|
@@ -1767,13 +1818,13 @@ the effect on the tracing is different. Every read from
|
|
|
trace_pipe is consumed. This means that subsequent reads will be
|
|
|
different. The trace is live.
|
|
|
|
|
|
- # echo function > /debug/tracing/current_tracer
|
|
|
- # cat /debug/tracing/trace_pipe > /tmp/trace.out &
|
|
|
+ # echo function > current_tracer
|
|
|
+ # cat trace_pipe > /tmp/trace.out &
|
|
|
[1] 4153
|
|
|
- # echo 1 > /debug/tracing/tracing_enabled
|
|
|
+ # echo 1 > tracing_enabled
|
|
|
# usleep 1
|
|
|
- # echo 0 > /debug/tracing/tracing_enabled
|
|
|
- # cat /debug/tracing/trace
|
|
|
+ # echo 0 > tracing_enabled
|
|
|
+ # cat trace
|
|
|
# tracer: function
|
|
|
#
|
|
|
# TASK-PID CPU# TIMESTAMP FUNCTION
|
|
|
@@ -1809,7 +1860,7 @@ number listed is the number of entries that can be recorded per
|
|
|
CPU. To know the full size, multiply the number of possible CPUS
|
|
|
with the number of entries.
|
|
|
|
|
|
- # cat /debug/tracing/buffer_size_kb
|
|
|
+ # cat buffer_size_kb
|
|
|
1408 (units kilobytes)
|
|
|
|
|
|
Note, to modify this, you must have tracing completely disabled.
|
|
|
@@ -1817,18 +1868,18 @@ To do that, echo "nop" into the current_tracer. If the
|
|
|
current_tracer is not set to "nop", an EINVAL error will be
|
|
|
returned.
|
|
|
|
|
|
- # echo nop > /debug/tracing/current_tracer
|
|
|
- # echo 10000 > /debug/tracing/buffer_size_kb
|
|
|
- # cat /debug/tracing/buffer_size_kb
|
|
|
+ # echo nop > current_tracer
|
|
|
+ # echo 10000 > buffer_size_kb
|
|
|
+ # cat buffer_size_kb
|
|
|
10000 (units kilobytes)
|
|
|
|
|
|
The number of pages which will be allocated is limited to a
|
|
|
percentage of available memory. Allocating too much will produce
|
|
|
an error.
|
|
|
|
|
|
- # echo 1000000000000 > /debug/tracing/buffer_size_kb
|
|
|
+ # echo 1000000000000 > buffer_size_kb
|
|
|
-bash: echo: write error: Cannot allocate memory
|
|
|
- # cat /debug/tracing/buffer_size_kb
|
|
|
+ # cat buffer_size_kb
|
|
|
85
|
|
|
|
|
|
-----------
|
GeunSik Lim