diff options
Diffstat (limited to 'Documentation/trace/ftrace.txt')
-rw-r--r-- | Documentation/trace/ftrace.txt | 148 |
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 | |||
273 | parent function that called this function "path_walk". The | 269 | parent function that called this function "path_walk". The |
274 | timestamp is the time at which the function was entered. | 270 | timestamp is the time at which the function was entered. |
275 | 271 | ||
276 | The sched_switch tracer also includes tracing of task wakeups | ||
277 | and 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 | |||
286 | Wake ups are represented by a "+" and the context switches are | ||
287 | shown 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 | |||
301 | The prio is the internal kernel priority, which is the inverse | ||
302 | of the priority that is usually displayed by user-space tools. | ||
303 | Zero represents the highest priority (99). Prio 100 starts the | ||
304 | "nice" priorities with 100 being equal to nice -20 and 139 being | ||
305 | nice 19. The prio "140" is reserved for the idle task which is | ||
306 | the lowest priority thread (pid 0). | ||
307 | |||
308 | |||
309 | Latency trace format | 272 | Latency 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 | ||
494 | sched_switch | ||
495 | ------------ | ||
496 | |||
497 | This tracer simply records schedule switches. Here is an example | ||
498 | of 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 | |||
528 | As we have discussed previously about this format, the header | ||
529 | shows the name of the trace and points to the options. The | ||
530 | "FUNCTION" is a misnomer since here it represents the wake ups | ||
531 | and context switches. | ||
532 | |||
533 | The sched_switch file only lists the wake ups (represented with | ||
534 | '+') and context switches ('==>') with the previous task or | ||
535 | current task first followed by the next task or task waking up. | ||
536 | The format for both of these is PID:KERNEL-PRIO:TASK-STATE. | ||
537 | Remember that the KERNEL-PRIO is the inverse of the actual | ||
538 | priority with zero (0) being the highest priority and the nice | ||
539 | values starting at 100 (nice -20). Below is a quick chart to map | ||
540 | the 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 | |||
555 | The 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 | |||
567 | ftrace_enabled | 457 | ftrace_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 | [...] |
1181 | int main(int argc, char *argv[]) { | 1071 | int 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 | # |