aboutsummaryrefslogtreecommitdiffstats
path: root/Documentation/trace/ftrace.txt
diff options
context:
space:
mode:
Diffstat (limited to 'Documentation/trace/ftrace.txt')
-rw-r--r--Documentation/trace/ftrace.txt148
1 files changed, 19 insertions, 129 deletions
diff --git a/Documentation/trace/ftrace.txt b/Documentation/trace/ftrace.txt
index 557c1edeccaf..67f1cc473257 100644
--- a/Documentation/trace/ftrace.txt
+++ b/Documentation/trace/ftrace.txt
@@ -80,11 +80,11 @@ of ftrace. Here is a list of some of the key files:
80 tracers listed here can be configured by 80 tracers listed here can be configured by
81 echoing their name into current_tracer. 81 echoing their name into current_tracer.
82 82
83 tracing_enabled: 83 tracing_on:
84 84
85 This sets or displays whether the current_tracer 85 This sets or displays whether writing to the trace
86 is activated and tracing or not. Echo 0 into this 86 ring buffer is enabled. Echo 0 into this file to disable
87 file to disable the tracer or 1 to enable it. 87 the tracer or 1 to enable it.
88 88
89 trace: 89 trace:
90 90
@@ -202,10 +202,6 @@ Here is the list of current tracers that may be configured.
202 to draw a graph of function calls similar to C code 202 to draw a graph of function calls similar to C code
203 source. 203 source.
204 204
205 "sched_switch"
206
207 Traces the context switches and wakeups between tasks.
208
209 "irqsoff" 205 "irqsoff"
210 206
211 Traces the areas that disable interrupts and saves 207 Traces the areas that disable interrupts and saves
@@ -273,39 +269,6 @@ format, the function name that was traced "path_put" and the
273parent function that called this function "path_walk". The 269parent function that called this function "path_walk". The
274timestamp is the time at which the function was entered. 270timestamp is the time at which the function was entered.
275 271
276The sched_switch tracer also includes tracing of task wakeups
277and context switches.
278
279 ksoftirqd/1-7 [01] 1453.070013: 7:115:R + 2916:115:S
280 ksoftirqd/1-7 [01] 1453.070013: 7:115:R + 10:115:S
281 ksoftirqd/1-7 [01] 1453.070013: 7:115:R ==> 10:115:R
282 events/1-10 [01] 1453.070013: 10:115:S ==> 2916:115:R
283 kondemand/1-2916 [01] 1453.070013: 2916:115:S ==> 7:115:R
284 ksoftirqd/1-7 [01] 1453.070013: 7:115:S ==> 0:140:R
285
286Wake ups are represented by a "+" and the context switches are
287shown as "==>". The format is:
288
289 Context switches:
290
291 Previous task Next Task
292
293 <pid>:<prio>:<state> ==> <pid>:<prio>:<state>
294
295 Wake ups:
296
297 Current task Task waking up
298
299 <pid>:<prio>:<state> + <pid>:<prio>:<state>
300
301The prio is the internal kernel priority, which is the inverse
302of the priority that is usually displayed by user-space tools.
303Zero represents the highest priority (99). Prio 100 starts the
304"nice" priorities with 100 being equal to nice -20 and 139 being
305nice 19. The prio "140" is reserved for the idle task which is
306the lowest priority thread (pid 0).
307
308
309Latency trace format 272Latency trace format
310-------------------- 273--------------------
311 274
@@ -491,79 +454,6 @@ x494] <- /root/a.out[+0x4a8] <- /lib/libc-2.7.so[+0x1e1a6]
491 latencies, as described in "Latency 454 latencies, as described in "Latency
492 trace format". 455 trace format".
493 456
494sched_switch
495------------
496
497This tracer simply records schedule switches. Here is an example
498of how to use it.
499
500 # echo sched_switch > current_tracer
501 # echo 1 > tracing_enabled
502 # sleep 1
503 # echo 0 > tracing_enabled
504 # cat trace
505
506# tracer: sched_switch
507#
508# TASK-PID CPU# TIMESTAMP FUNCTION
509# | | | | |
510 bash-3997 [01] 240.132281: 3997:120:R + 4055:120:R
511 bash-3997 [01] 240.132284: 3997:120:R ==> 4055:120:R
512 sleep-4055 [01] 240.132371: 4055:120:S ==> 3997:120:R
513 bash-3997 [01] 240.132454: 3997:120:R + 4055:120:S
514 bash-3997 [01] 240.132457: 3997:120:R ==> 4055:120:R
515 sleep-4055 [01] 240.132460: 4055:120:D ==> 3997:120:R
516 bash-3997 [01] 240.132463: 3997:120:R + 4055:120:D
517 bash-3997 [01] 240.132465: 3997:120:R ==> 4055:120:R
518 <idle>-0 [00] 240.132589: 0:140:R + 4:115:S
519 <idle>-0 [00] 240.132591: 0:140:R ==> 4:115:R
520 ksoftirqd/0-4 [00] 240.132595: 4:115:S ==> 0:140:R
521 <idle>-0 [00] 240.132598: 0:140:R + 4:115:S
522 <idle>-0 [00] 240.132599: 0:140:R ==> 4:115:R
523 ksoftirqd/0-4 [00] 240.132603: 4:115:S ==> 0:140:R
524 sleep-4055 [01] 240.133058: 4055:120:S ==> 3997:120:R
525 [...]
526
527
528As we have discussed previously about this format, the header
529shows the name of the trace and points to the options. The
530"FUNCTION" is a misnomer since here it represents the wake ups
531and context switches.
532
533The sched_switch file only lists the wake ups (represented with
534'+') and context switches ('==>') with the previous task or
535current task first followed by the next task or task waking up.
536The format for both of these is PID:KERNEL-PRIO:TASK-STATE.
537Remember that the KERNEL-PRIO is the inverse of the actual
538priority with zero (0) being the highest priority and the nice
539values starting at 100 (nice -20). Below is a quick chart to map
540the kernel priority to user land priorities.
541
542 Kernel Space User Space
543 ===============================================================
544 0(high) to 98(low) user RT priority 99(high) to 1(low)
545 with SCHED_RR or SCHED_FIFO
546 ---------------------------------------------------------------
547 99 sched_priority is not used in scheduling
548 decisions(it must be specified as 0)
549 ---------------------------------------------------------------
550 100(high) to 139(low) user nice -20(high) to 19(low)
551 ---------------------------------------------------------------
552 140 idle task priority
553 ---------------------------------------------------------------
554
555The task states are:
556
557 R - running : wants to run, may not actually be running
558 S - sleep : process is waiting to be woken up (handles signals)
559 D - disk sleep (uninterruptible sleep) : process must be woken up
560 (ignores signals)
561 T - stopped : process suspended
562 t - traced : process is being traced (with something like gdb)
563 Z - zombie : process waiting to be cleaned up
564 X - unknown
565
566
567ftrace_enabled 457ftrace_enabled
568-------------- 458--------------
569 459
@@ -607,10 +497,10 @@ an example:
607 # echo irqsoff > current_tracer 497 # echo irqsoff > current_tracer
608 # echo latency-format > trace_options 498 # echo latency-format > trace_options
609 # echo 0 > tracing_max_latency 499 # echo 0 > tracing_max_latency
610 # echo 1 > tracing_enabled 500 # echo 1 > tracing_on
611 # ls -ltr 501 # ls -ltr
612 [...] 502 [...]
613 # echo 0 > tracing_enabled 503 # echo 0 > tracing_on
614 # cat trace 504 # cat trace
615# tracer: irqsoff 505# tracer: irqsoff
616# 506#
@@ -715,10 +605,10 @@ is much like the irqsoff tracer.
715 # echo preemptoff > current_tracer 605 # echo preemptoff > current_tracer
716 # echo latency-format > trace_options 606 # echo latency-format > trace_options
717 # echo 0 > tracing_max_latency 607 # echo 0 > tracing_max_latency
718 # echo 1 > tracing_enabled 608 # echo 1 > tracing_on
719 # ls -ltr 609 # ls -ltr
720 [...] 610 [...]
721 # echo 0 > tracing_enabled 611 # echo 0 > tracing_on
722 # cat trace 612 # cat trace
723# tracer: preemptoff 613# tracer: preemptoff
724# 614#
@@ -863,10 +753,10 @@ tracers.
863 # echo preemptirqsoff > current_tracer 753 # echo preemptirqsoff > current_tracer
864 # echo latency-format > trace_options 754 # echo latency-format > trace_options
865 # echo 0 > tracing_max_latency 755 # echo 0 > tracing_max_latency
866 # echo 1 > tracing_enabled 756 # echo 1 > tracing_on
867 # ls -ltr 757 # ls -ltr
868 [...] 758 [...]
869 # echo 0 > tracing_enabled 759 # echo 0 > tracing_on
870 # cat trace 760 # cat trace
871# tracer: preemptirqsoff 761# tracer: preemptirqsoff
872# 762#
@@ -1026,9 +916,9 @@ Instead of performing an 'ls', we will run 'sleep 1' under
1026 # echo wakeup > current_tracer 916 # echo wakeup > current_tracer
1027 # echo latency-format > trace_options 917 # echo latency-format > trace_options
1028 # echo 0 > tracing_max_latency 918 # echo 0 > tracing_max_latency
1029 # echo 1 > tracing_enabled 919 # echo 1 > tracing_on
1030 # chrt -f 5 sleep 1 920 # chrt -f 5 sleep 1
1031 # echo 0 > tracing_enabled 921 # echo 0 > tracing_on
1032 # cat trace 922 # cat trace
1033# tracer: wakeup 923# tracer: wakeup
1034# 924#
@@ -1140,9 +1030,9 @@ ftrace_enabled is set; otherwise this tracer is a nop.
1140 1030
1141 # sysctl kernel.ftrace_enabled=1 1031 # sysctl kernel.ftrace_enabled=1
1142 # echo function > current_tracer 1032 # echo function > current_tracer
1143 # echo 1 > tracing_enabled 1033 # echo 1 > tracing_on
1144 # usleep 1 1034 # usleep 1
1145 # echo 0 > tracing_enabled 1035 # echo 0 > tracing_on
1146 # cat trace 1036 # cat trace
1147# tracer: function 1037# tracer: function
1148# 1038#
@@ -1180,7 +1070,7 @@ int trace_fd;
1180[...] 1070[...]
1181int main(int argc, char *argv[]) { 1071int main(int argc, char *argv[]) {
1182 [...] 1072 [...]
1183 trace_fd = open(tracing_file("tracing_enabled"), O_WRONLY); 1073 trace_fd = open(tracing_file("tracing_on"), O_WRONLY);
1184 [...] 1074 [...]
1185 if (condition_hit()) { 1075 if (condition_hit()) {
1186 write(trace_fd, "0", 1); 1076 write(trace_fd, "0", 1);
@@ -1631,9 +1521,9 @@ If I am only interested in sys_nanosleep and hrtimer_interrupt:
1631 # echo sys_nanosleep hrtimer_interrupt \ 1521 # echo sys_nanosleep hrtimer_interrupt \
1632 > set_ftrace_filter 1522 > set_ftrace_filter
1633 # echo function > current_tracer 1523 # echo function > current_tracer
1634 # echo 1 > tracing_enabled 1524 # echo 1 > tracing_on
1635 # usleep 1 1525 # usleep 1
1636 # echo 0 > tracing_enabled 1526 # echo 0 > tracing_on
1637 # cat trace 1527 # cat trace
1638# tracer: ftrace 1528# tracer: ftrace
1639# 1529#
@@ -1879,9 +1769,9 @@ different. The trace is live.
1879 # echo function > current_tracer 1769 # echo function > current_tracer
1880 # cat trace_pipe > /tmp/trace.out & 1770 # cat trace_pipe > /tmp/trace.out &
1881[1] 4153 1771[1] 4153
1882 # echo 1 > tracing_enabled 1772 # echo 1 > tracing_on
1883 # usleep 1 1773 # usleep 1
1884 # echo 0 > tracing_enabled 1774 # echo 0 > tracing_on
1885 # cat trace 1775 # cat trace
1886# tracer: function 1776# tracer: function
1887# 1777#