diff options
Diffstat (limited to 'Documentation/trace/ftrace.txt')
-rw-r--r-- | Documentation/trace/ftrace.txt | 76 |
1 files changed, 43 insertions, 33 deletions
diff --git a/Documentation/trace/ftrace.txt b/Documentation/trace/ftrace.txt index a39b3c749de5..957b22fde2df 100644 --- a/Documentation/trace/ftrace.txt +++ b/Documentation/trace/ftrace.txt | |||
@@ -26,6 +26,12 @@ disabled, and more (ftrace allows for tracer plugins, which | |||
26 | means that the list of tracers can always grow). | 26 | means that the list of tracers can always grow). |
27 | 27 | ||
28 | 28 | ||
29 | Implementation Details | ||
30 | ---------------------- | ||
31 | |||
32 | See ftrace-design.txt for details for arch porters and such. | ||
33 | |||
34 | |||
29 | The File System | 35 | The File System |
30 | --------------- | 36 | --------------- |
31 | 37 | ||
@@ -85,26 +91,19 @@ of ftrace. Here is a list of some of the key files: | |||
85 | This file holds the output of the trace in a human | 91 | This file holds the output of the trace in a human |
86 | readable format (described below). | 92 | readable format (described below). |
87 | 93 | ||
88 | latency_trace: | ||
89 | |||
90 | This file shows the same trace but the information | ||
91 | is organized more to display possible latencies | ||
92 | in the system (described below). | ||
93 | |||
94 | trace_pipe: | 94 | trace_pipe: |
95 | 95 | ||
96 | The output is the same as the "trace" file but this | 96 | The output is the same as the "trace" file but this |
97 | file is meant to be streamed with live tracing. | 97 | file is meant to be streamed with live tracing. |
98 | Reads from this file will block until new data | 98 | Reads from this file will block until new data is |
99 | is retrieved. Unlike the "trace" and "latency_trace" | 99 | retrieved. Unlike the "trace" file, this file is a |
100 | files, this file is a consumer. This means reading | 100 | consumer. This means reading from this file causes |
101 | from this file causes sequential reads to display | 101 | sequential reads to display more current data. Once |
102 | more current data. Once data is read from this | 102 | data is read from this file, it is consumed, and |
103 | file, it is consumed, and will not be read | 103 | will not be read again with a sequential read. The |
104 | again with a sequential read. The "trace" and | 104 | "trace" file is static, and if the tracer is not |
105 | "latency_trace" files are static, and if the | 105 | adding more data,they will display the same |
106 | tracer is not adding more data, they will display | 106 | information every time they are read. |
107 | the same information every time they are read. | ||
108 | 107 | ||
109 | trace_options: | 108 | trace_options: |
110 | 109 | ||
@@ -117,10 +116,10 @@ of ftrace. Here is a list of some of the key files: | |||
117 | Some of the tracers record the max latency. | 116 | Some of the tracers record the max latency. |
118 | For example, the time interrupts are disabled. | 117 | For example, the time interrupts are disabled. |
119 | This time is saved in this file. The max trace | 118 | This time is saved in this file. The max trace |
120 | will also be stored, and displayed by either | 119 | will also be stored, and displayed by "trace". |
121 | "trace" or "latency_trace". A new max trace will | 120 | A new max trace will only be recorded if the |
122 | only be recorded if the latency is greater than | 121 | latency is greater than the value in this |
123 | the value in this file. (in microseconds) | 122 | file. (in microseconds) |
124 | 123 | ||
125 | buffer_size_kb: | 124 | buffer_size_kb: |
126 | 125 | ||
@@ -134,7 +133,7 @@ of ftrace. Here is a list of some of the key files: | |||
134 | than requested, the rest of the page will be used, | 133 | than requested, the rest of the page will be used, |
135 | making the actual allocation bigger than requested. | 134 | making the actual allocation bigger than requested. |
136 | ( Note, the size may not be a multiple of the page size | 135 | ( Note, the size may not be a multiple of the page size |
137 | due to buffer managment overhead. ) | 136 | due to buffer management overhead. ) |
138 | 137 | ||
139 | This can only be updated when the current_tracer | 138 | This can only be updated when the current_tracer |
140 | is set to "nop". | 139 | is set to "nop". |
@@ -210,7 +209,7 @@ Here is the list of current tracers that may be configured. | |||
210 | the trace with the longest max latency. | 209 | the trace with the longest max latency. |
211 | See tracing_max_latency. When a new max is recorded, | 210 | See tracing_max_latency. When a new max is recorded, |
212 | it replaces the old trace. It is best to view this | 211 | it replaces the old trace. It is best to view this |
213 | trace via the latency_trace file. | 212 | trace with the latency-format option enabled. |
214 | 213 | ||
215 | "preemptoff" | 214 | "preemptoff" |
216 | 215 | ||
@@ -307,8 +306,8 @@ the lowest priority thread (pid 0). | |||
307 | Latency trace format | 306 | Latency trace format |
308 | -------------------- | 307 | -------------------- |
309 | 308 | ||
310 | For traces that display latency times, the latency_trace file | 309 | When the latency-format option is enabled, the trace file gives |
311 | gives somewhat more information to see why a latency happened. | 310 | somewhat more information to see why a latency happened. |
312 | Here is a typical trace. | 311 | Here is a typical trace. |
313 | 312 | ||
314 | # tracer: irqsoff | 313 | # tracer: irqsoff |
@@ -380,9 +379,10 @@ explains which is which. | |||
380 | 379 | ||
381 | The above is mostly meaningful for kernel developers. | 380 | The above is mostly meaningful for kernel developers. |
382 | 381 | ||
383 | time: This differs from the trace file output. The trace file output | 382 | time: When the latency-format option is enabled, the trace file |
384 | includes an absolute timestamp. The timestamp used by the | 383 | output includes a timestamp relative to the start of the |
385 | latency_trace file is relative to the start of the trace. | 384 | trace. This differs from the output when latency-format |
385 | is disabled, which includes an absolute timestamp. | ||
386 | 386 | ||
387 | delay: This is just to help catch your eye a bit better. And | 387 | delay: This is just to help catch your eye a bit better. And |
388 | needs to be fixed to be only relative to the same CPU. | 388 | needs to be fixed to be only relative to the same CPU. |
@@ -440,7 +440,8 @@ Here are the available options: | |||
440 | sym-addr: | 440 | sym-addr: |
441 | bash-4000 [01] 1477.606694: simple_strtoul <c0339346> | 441 | bash-4000 [01] 1477.606694: simple_strtoul <c0339346> |
442 | 442 | ||
443 | verbose - This deals with the latency_trace file. | 443 | verbose - This deals with the trace file when the |
444 | latency-format option is enabled. | ||
444 | 445 | ||
445 | bash 4000 1 0 00000000 00010a95 [58127d26] 1720.415ms \ | 446 | bash 4000 1 0 00000000 00010a95 [58127d26] 1720.415ms \ |
446 | (+0.000ms): simple_strtoul (strict_strtoul) | 447 | (+0.000ms): simple_strtoul (strict_strtoul) |
@@ -472,7 +473,7 @@ Here are the available options: | |||
472 | the app is no longer running | 473 | the app is no longer running |
473 | 474 | ||
474 | The lookup is performed when you read | 475 | The lookup is performed when you read |
475 | trace,trace_pipe,latency_trace. Example: | 476 | trace,trace_pipe. Example: |
476 | 477 | ||
477 | a.out-1623 [000] 40874.465068: /root/a.out[+0x480] <-/root/a.out[+0 | 478 | a.out-1623 [000] 40874.465068: /root/a.out[+0x480] <-/root/a.out[+0 |
478 | x494] <- /root/a.out[+0x4a8] <- /lib/libc-2.7.so[+0x1e1a6] | 479 | x494] <- /root/a.out[+0x4a8] <- /lib/libc-2.7.so[+0x1e1a6] |
@@ -481,6 +482,11 @@ x494] <- /root/a.out[+0x4a8] <- /lib/libc-2.7.so[+0x1e1a6] | |||
481 | every scheduling event. Will add overhead if | 482 | every scheduling event. Will add overhead if |
482 | there's a lot of tasks running at once. | 483 | there's a lot of tasks running at once. |
483 | 484 | ||
485 | latency-format - This option changes the trace. When | ||
486 | it is enabled, the trace displays | ||
487 | additional information about the | ||
488 | latencies, as described in "Latency | ||
489 | trace format". | ||
484 | 490 | ||
485 | sched_switch | 491 | sched_switch |
486 | ------------ | 492 | ------------ |
@@ -596,12 +602,13 @@ To reset the maximum, echo 0 into tracing_max_latency. Here is | |||
596 | an example: | 602 | an example: |
597 | 603 | ||
598 | # echo irqsoff > current_tracer | 604 | # echo irqsoff > current_tracer |
605 | # echo latency-format > trace_options | ||
599 | # echo 0 > tracing_max_latency | 606 | # echo 0 > tracing_max_latency |
600 | # echo 1 > tracing_enabled | 607 | # echo 1 > tracing_enabled |
601 | # ls -ltr | 608 | # ls -ltr |
602 | [...] | 609 | [...] |
603 | # echo 0 > tracing_enabled | 610 | # echo 0 > tracing_enabled |
604 | # cat latency_trace | 611 | # cat trace |
605 | # tracer: irqsoff | 612 | # tracer: irqsoff |
606 | # | 613 | # |
607 | irqsoff latency trace v1.1.5 on 2.6.26 | 614 | irqsoff latency trace v1.1.5 on 2.6.26 |
@@ -703,12 +710,13 @@ which preemption was disabled. The control of preemptoff tracer | |||
703 | is much like the irqsoff tracer. | 710 | is much like the irqsoff tracer. |
704 | 711 | ||
705 | # echo preemptoff > current_tracer | 712 | # echo preemptoff > current_tracer |
713 | # echo latency-format > trace_options | ||
706 | # echo 0 > tracing_max_latency | 714 | # echo 0 > tracing_max_latency |
707 | # echo 1 > tracing_enabled | 715 | # echo 1 > tracing_enabled |
708 | # ls -ltr | 716 | # ls -ltr |
709 | [...] | 717 | [...] |
710 | # echo 0 > tracing_enabled | 718 | # echo 0 > tracing_enabled |
711 | # cat latency_trace | 719 | # cat trace |
712 | # tracer: preemptoff | 720 | # tracer: preemptoff |
713 | # | 721 | # |
714 | preemptoff latency trace v1.1.5 on 2.6.26-rc8 | 722 | preemptoff latency trace v1.1.5 on 2.6.26-rc8 |
@@ -850,12 +858,13 @@ Again, using this trace is much like the irqsoff and preemptoff | |||
850 | tracers. | 858 | tracers. |
851 | 859 | ||
852 | # echo preemptirqsoff > current_tracer | 860 | # echo preemptirqsoff > current_tracer |
861 | # echo latency-format > trace_options | ||
853 | # echo 0 > tracing_max_latency | 862 | # echo 0 > tracing_max_latency |
854 | # echo 1 > tracing_enabled | 863 | # echo 1 > tracing_enabled |
855 | # ls -ltr | 864 | # ls -ltr |
856 | [...] | 865 | [...] |
857 | # echo 0 > tracing_enabled | 866 | # echo 0 > tracing_enabled |
858 | # cat latency_trace | 867 | # cat trace |
859 | # tracer: preemptirqsoff | 868 | # tracer: preemptirqsoff |
860 | # | 869 | # |
861 | preemptirqsoff latency trace v1.1.5 on 2.6.26-rc8 | 870 | preemptirqsoff latency trace v1.1.5 on 2.6.26-rc8 |
@@ -1012,11 +1021,12 @@ Instead of performing an 'ls', we will run 'sleep 1' under | |||
1012 | 'chrt' which changes the priority of the task. | 1021 | 'chrt' which changes the priority of the task. |
1013 | 1022 | ||
1014 | # echo wakeup > current_tracer | 1023 | # echo wakeup > current_tracer |
1024 | # echo latency-format > trace_options | ||
1015 | # echo 0 > tracing_max_latency | 1025 | # echo 0 > tracing_max_latency |
1016 | # echo 1 > tracing_enabled | 1026 | # echo 1 > tracing_enabled |
1017 | # chrt -f 5 sleep 1 | 1027 | # chrt -f 5 sleep 1 |
1018 | # echo 0 > tracing_enabled | 1028 | # echo 0 > tracing_enabled |
1019 | # cat latency_trace | 1029 | # cat trace |
1020 | # tracer: wakeup | 1030 | # tracer: wakeup |
1021 | # | 1031 | # |
1022 | wakeup latency trace v1.1.5 on 2.6.26-rc8 | 1032 | wakeup latency trace v1.1.5 on 2.6.26-rc8 |