Loading Documentation/trace/ftrace.txt +36 −32 Original line number Original line Diff line number Diff line Loading @@ -85,26 +85,19 @@ of ftrace. Here is a list of some of the key files: This file holds the output of the trace in a human This file holds the output of the trace in a human readable format (described below). readable format (described below). latency_trace: This file shows the same trace but the information is organized more to display possible latencies in the system (described below). trace_pipe: trace_pipe: The output is the same as the "trace" file but this The output is the same as the "trace" file but this file is meant to be streamed with live tracing. file is meant to be streamed with live tracing. Reads from this file will block until new data Reads from this file will block until new data is is retrieved. Unlike the "trace" and "latency_trace" retrieved. Unlike the "trace" file, this file is a files, this file is a consumer. This means reading consumer. This means reading from this file causes from this file causes sequential reads to display sequential reads to display more current data. Once more current data. Once data is read from this data is read from this file, it is consumed, and file, it is consumed, and will not be read will not be read again with a sequential read. The again with a sequential read. The "trace" and "trace" file is static, and if the tracer is not "latency_trace" files are static, and if the adding more data,they will display the same tracer is not adding more data, they will display information every time they are read. the same information every time they are read. trace_options: trace_options: Loading @@ -117,10 +110,10 @@ of ftrace. Here is a list of some of the key files: Some of the tracers record the max latency. Some of the tracers record the max latency. For example, the time interrupts are disabled. For example, the time interrupts are disabled. This time is saved in this file. The max trace This time is saved in this file. The max trace will also be stored, and displayed by either will also be stored, and displayed by "trace". "trace" or "latency_trace". A new max trace will A new max trace will only be recorded if the only be recorded if the latency is greater than latency is greater than the value in this the value in this file. (in microseconds) file. (in microseconds) buffer_size_kb: buffer_size_kb: Loading Loading @@ -210,7 +203,7 @@ Here is the list of current tracers that may be configured. the trace with the longest max latency. the trace with the longest max latency. See tracing_max_latency. When a new max is recorded, See tracing_max_latency. When a new max is recorded, it replaces the old trace. It is best to view this it replaces the old trace. It is best to view this trace via the latency_trace file. trace with the latency-format option enabled. "preemptoff" "preemptoff" Loading Loading @@ -307,8 +300,8 @@ the lowest priority thread (pid 0). Latency trace format Latency trace format -------------------- -------------------- For traces that display latency times, the latency_trace file When the latency-format option is enabled, the trace file gives gives somewhat more information to see why a latency happened. somewhat more information to see why a latency happened. Here is a typical trace. Here is a typical trace. # tracer: irqsoff # tracer: irqsoff Loading Loading @@ -380,9 +373,10 @@ explains which is which. The above is mostly meaningful for kernel developers. The above is mostly meaningful for kernel developers. time: This differs from the trace file output. The trace file output time: When the latency-format option is enabled, the trace file includes an absolute timestamp. The timestamp used by the output includes a timestamp relative to the start of the latency_trace file is relative to the start of the trace. trace. This differs from the output when latency-format is disabled, which includes an absolute timestamp. delay: This is just to help catch your eye a bit better. And delay: This is just to help catch your eye a bit better. And needs to be fixed to be only relative to the same CPU. needs to be fixed to be only relative to the same CPU. Loading Loading @@ -440,7 +434,8 @@ Here are the available options: sym-addr: sym-addr: bash-4000 [01] 1477.606694: simple_strtoul <c0339346> bash-4000 [01] 1477.606694: simple_strtoul <c0339346> verbose - This deals with the latency_trace file. verbose - This deals with the trace file when the latency-format option is enabled. bash 4000 1 0 00000000 00010a95 [58127d26] 1720.415ms \ bash 4000 1 0 00000000 00010a95 [58127d26] 1720.415ms \ (+0.000ms): simple_strtoul (strict_strtoul) (+0.000ms): simple_strtoul (strict_strtoul) Loading Loading @@ -472,7 +467,7 @@ Here are the available options: the app is no longer running the app is no longer running The lookup is performed when you read The lookup is performed when you read trace,trace_pipe,latency_trace. Example: trace,trace_pipe. Example: a.out-1623 [000] 40874.465068: /root/a.out[+0x480] <-/root/a.out[+0 a.out-1623 [000] 40874.465068: /root/a.out[+0x480] <-/root/a.out[+0 x494] <- /root/a.out[+0x4a8] <- /lib/libc-2.7.so[+0x1e1a6] x494] <- /root/a.out[+0x4a8] <- /lib/libc-2.7.so[+0x1e1a6] Loading @@ -481,6 +476,11 @@ x494] <- /root/a.out[+0x4a8] <- /lib/libc-2.7.so[+0x1e1a6] every scheduling event. Will add overhead if every scheduling event. Will add overhead if there's a lot of tasks running at once. there's a lot of tasks running at once. latency-format - This option changes the trace. When it is enabled, the trace displays additional information about the latencies, as described in "Latency trace format". sched_switch sched_switch ------------ ------------ Loading Loading @@ -596,12 +596,13 @@ To reset the maximum, echo 0 into tracing_max_latency. Here is an example: an example: # echo irqsoff > current_tracer # echo irqsoff > current_tracer # echo latency-format > trace_options # echo 0 > tracing_max_latency # echo 0 > tracing_max_latency # echo 1 > tracing_enabled # echo 1 > tracing_enabled # ls -ltr # ls -ltr [...] [...] # echo 0 > tracing_enabled # echo 0 > tracing_enabled # cat latency_trace # cat trace # tracer: irqsoff # tracer: irqsoff # # irqsoff latency trace v1.1.5 on 2.6.26 irqsoff latency trace v1.1.5 on 2.6.26 Loading Loading @@ -703,12 +704,13 @@ which preemption was disabled. The control of preemptoff tracer is much like the irqsoff tracer. is much like the irqsoff tracer. # echo preemptoff > current_tracer # echo preemptoff > current_tracer # echo latency-format > trace_options # echo 0 > tracing_max_latency # echo 0 > tracing_max_latency # echo 1 > tracing_enabled # echo 1 > tracing_enabled # ls -ltr # ls -ltr [...] [...] # echo 0 > tracing_enabled # echo 0 > tracing_enabled # cat latency_trace # cat trace # tracer: preemptoff # tracer: preemptoff # # preemptoff latency trace v1.1.5 on 2.6.26-rc8 preemptoff latency trace v1.1.5 on 2.6.26-rc8 Loading Loading @@ -850,12 +852,13 @@ Again, using this trace is much like the irqsoff and preemptoff tracers. tracers. # echo preemptirqsoff > current_tracer # echo preemptirqsoff > current_tracer # echo latency-format > trace_options # echo 0 > tracing_max_latency # echo 0 > tracing_max_latency # echo 1 > tracing_enabled # echo 1 > tracing_enabled # ls -ltr # ls -ltr [...] [...] # echo 0 > tracing_enabled # echo 0 > tracing_enabled # cat latency_trace # cat trace # tracer: preemptirqsoff # tracer: preemptirqsoff # # preemptirqsoff latency trace v1.1.5 on 2.6.26-rc8 preemptirqsoff latency trace v1.1.5 on 2.6.26-rc8 Loading Loading @@ -1012,11 +1015,12 @@ Instead of performing an 'ls', we will run 'sleep 1' under 'chrt' which changes the priority of the task. 'chrt' which changes the priority of the task. # echo wakeup > current_tracer # echo wakeup > current_tracer # echo latency-format > trace_options # echo 0 > tracing_max_latency # echo 0 > tracing_max_latency # echo 1 > tracing_enabled # echo 1 > tracing_enabled # chrt -f 5 sleep 1 # chrt -f 5 sleep 1 # echo 0 > tracing_enabled # echo 0 > tracing_enabled # cat latency_trace # cat trace # tracer: wakeup # tracer: wakeup # # wakeup latency trace v1.1.5 on 2.6.26-rc8 wakeup latency trace v1.1.5 on 2.6.26-rc8 Loading kernel/trace/trace_events_filter.c +6 −5 Original line number Original line Diff line number Diff line Loading @@ -409,6 +409,9 @@ static int init_preds(struct ftrace_event_call *call) struct filter_pred *pred; struct filter_pred *pred; int i; int i; if (call->filter) return 0; filter = call->filter = kzalloc(sizeof(*filter), GFP_KERNEL); filter = call->filter = kzalloc(sizeof(*filter), GFP_KERNEL); if (!call->filter) if (!call->filter) return -ENOMEM; return -ENOMEM; Loading Loading @@ -447,12 +450,10 @@ static int init_subsystem_preds(struct event_subsystem *system) if (strcmp(call->system, system->name) != 0) if (strcmp(call->system, system->name) != 0) continue; continue; if (!call->filter) { err = init_preds(call); err = init_preds(call); if (err) if (err) return err; return err; } } } return 0; return 0; } } Loading Loading
Documentation/trace/ftrace.txt +36 −32 Original line number Original line Diff line number Diff line Loading @@ -85,26 +85,19 @@ of ftrace. Here is a list of some of the key files: This file holds the output of the trace in a human This file holds the output of the trace in a human readable format (described below). readable format (described below). latency_trace: This file shows the same trace but the information is organized more to display possible latencies in the system (described below). trace_pipe: trace_pipe: The output is the same as the "trace" file but this The output is the same as the "trace" file but this file is meant to be streamed with live tracing. file is meant to be streamed with live tracing. Reads from this file will block until new data Reads from this file will block until new data is is retrieved. Unlike the "trace" and "latency_trace" retrieved. Unlike the "trace" file, this file is a files, this file is a consumer. This means reading consumer. This means reading from this file causes from this file causes sequential reads to display sequential reads to display more current data. Once more current data. Once data is read from this data is read from this file, it is consumed, and file, it is consumed, and will not be read will not be read again with a sequential read. The again with a sequential read. The "trace" and "trace" file is static, and if the tracer is not "latency_trace" files are static, and if the adding more data,they will display the same tracer is not adding more data, they will display information every time they are read. the same information every time they are read. trace_options: trace_options: Loading @@ -117,10 +110,10 @@ of ftrace. Here is a list of some of the key files: Some of the tracers record the max latency. Some of the tracers record the max latency. For example, the time interrupts are disabled. For example, the time interrupts are disabled. This time is saved in this file. The max trace This time is saved in this file. The max trace will also be stored, and displayed by either will also be stored, and displayed by "trace". "trace" or "latency_trace". A new max trace will A new max trace will only be recorded if the only be recorded if the latency is greater than latency is greater than the value in this the value in this file. (in microseconds) file. (in microseconds) buffer_size_kb: buffer_size_kb: Loading Loading @@ -210,7 +203,7 @@ Here is the list of current tracers that may be configured. the trace with the longest max latency. the trace with the longest max latency. See tracing_max_latency. When a new max is recorded, See tracing_max_latency. When a new max is recorded, it replaces the old trace. It is best to view this it replaces the old trace. It is best to view this trace via the latency_trace file. trace with the latency-format option enabled. "preemptoff" "preemptoff" Loading Loading @@ -307,8 +300,8 @@ the lowest priority thread (pid 0). Latency trace format Latency trace format -------------------- -------------------- For traces that display latency times, the latency_trace file When the latency-format option is enabled, the trace file gives gives somewhat more information to see why a latency happened. somewhat more information to see why a latency happened. Here is a typical trace. Here is a typical trace. # tracer: irqsoff # tracer: irqsoff Loading Loading @@ -380,9 +373,10 @@ explains which is which. The above is mostly meaningful for kernel developers. The above is mostly meaningful for kernel developers. time: This differs from the trace file output. The trace file output time: When the latency-format option is enabled, the trace file includes an absolute timestamp. The timestamp used by the output includes a timestamp relative to the start of the latency_trace file is relative to the start of the trace. trace. This differs from the output when latency-format is disabled, which includes an absolute timestamp. delay: This is just to help catch your eye a bit better. And delay: This is just to help catch your eye a bit better. And needs to be fixed to be only relative to the same CPU. needs to be fixed to be only relative to the same CPU. Loading Loading @@ -440,7 +434,8 @@ Here are the available options: sym-addr: sym-addr: bash-4000 [01] 1477.606694: simple_strtoul <c0339346> bash-4000 [01] 1477.606694: simple_strtoul <c0339346> verbose - This deals with the latency_trace file. verbose - This deals with the trace file when the latency-format option is enabled. bash 4000 1 0 00000000 00010a95 [58127d26] 1720.415ms \ bash 4000 1 0 00000000 00010a95 [58127d26] 1720.415ms \ (+0.000ms): simple_strtoul (strict_strtoul) (+0.000ms): simple_strtoul (strict_strtoul) Loading Loading @@ -472,7 +467,7 @@ Here are the available options: the app is no longer running the app is no longer running The lookup is performed when you read The lookup is performed when you read trace,trace_pipe,latency_trace. Example: trace,trace_pipe. Example: a.out-1623 [000] 40874.465068: /root/a.out[+0x480] <-/root/a.out[+0 a.out-1623 [000] 40874.465068: /root/a.out[+0x480] <-/root/a.out[+0 x494] <- /root/a.out[+0x4a8] <- /lib/libc-2.7.so[+0x1e1a6] x494] <- /root/a.out[+0x4a8] <- /lib/libc-2.7.so[+0x1e1a6] Loading @@ -481,6 +476,11 @@ x494] <- /root/a.out[+0x4a8] <- /lib/libc-2.7.so[+0x1e1a6] every scheduling event. Will add overhead if every scheduling event. Will add overhead if there's a lot of tasks running at once. there's a lot of tasks running at once. latency-format - This option changes the trace. When it is enabled, the trace displays additional information about the latencies, as described in "Latency trace format". sched_switch sched_switch ------------ ------------ Loading Loading @@ -596,12 +596,13 @@ To reset the maximum, echo 0 into tracing_max_latency. Here is an example: an example: # echo irqsoff > current_tracer # echo irqsoff > current_tracer # echo latency-format > trace_options # echo 0 > tracing_max_latency # echo 0 > tracing_max_latency # echo 1 > tracing_enabled # echo 1 > tracing_enabled # ls -ltr # ls -ltr [...] [...] # echo 0 > tracing_enabled # echo 0 > tracing_enabled # cat latency_trace # cat trace # tracer: irqsoff # tracer: irqsoff # # irqsoff latency trace v1.1.5 on 2.6.26 irqsoff latency trace v1.1.5 on 2.6.26 Loading Loading @@ -703,12 +704,13 @@ which preemption was disabled. The control of preemptoff tracer is much like the irqsoff tracer. is much like the irqsoff tracer. # echo preemptoff > current_tracer # echo preemptoff > current_tracer # echo latency-format > trace_options # echo 0 > tracing_max_latency # echo 0 > tracing_max_latency # echo 1 > tracing_enabled # echo 1 > tracing_enabled # ls -ltr # ls -ltr [...] [...] # echo 0 > tracing_enabled # echo 0 > tracing_enabled # cat latency_trace # cat trace # tracer: preemptoff # tracer: preemptoff # # preemptoff latency trace v1.1.5 on 2.6.26-rc8 preemptoff latency trace v1.1.5 on 2.6.26-rc8 Loading Loading @@ -850,12 +852,13 @@ Again, using this trace is much like the irqsoff and preemptoff tracers. tracers. # echo preemptirqsoff > current_tracer # echo preemptirqsoff > current_tracer # echo latency-format > trace_options # echo 0 > tracing_max_latency # echo 0 > tracing_max_latency # echo 1 > tracing_enabled # echo 1 > tracing_enabled # ls -ltr # ls -ltr [...] [...] # echo 0 > tracing_enabled # echo 0 > tracing_enabled # cat latency_trace # cat trace # tracer: preemptirqsoff # tracer: preemptirqsoff # # preemptirqsoff latency trace v1.1.5 on 2.6.26-rc8 preemptirqsoff latency trace v1.1.5 on 2.6.26-rc8 Loading Loading @@ -1012,11 +1015,12 @@ Instead of performing an 'ls', we will run 'sleep 1' under 'chrt' which changes the priority of the task. 'chrt' which changes the priority of the task. # echo wakeup > current_tracer # echo wakeup > current_tracer # echo latency-format > trace_options # echo 0 > tracing_max_latency # echo 0 > tracing_max_latency # echo 1 > tracing_enabled # echo 1 > tracing_enabled # chrt -f 5 sleep 1 # chrt -f 5 sleep 1 # echo 0 > tracing_enabled # echo 0 > tracing_enabled # cat latency_trace # cat trace # tracer: wakeup # tracer: wakeup # # wakeup latency trace v1.1.5 on 2.6.26-rc8 wakeup latency trace v1.1.5 on 2.6.26-rc8 Loading
kernel/trace/trace_events_filter.c +6 −5 Original line number Original line Diff line number Diff line Loading @@ -409,6 +409,9 @@ static int init_preds(struct ftrace_event_call *call) struct filter_pred *pred; struct filter_pred *pred; int i; int i; if (call->filter) return 0; filter = call->filter = kzalloc(sizeof(*filter), GFP_KERNEL); filter = call->filter = kzalloc(sizeof(*filter), GFP_KERNEL); if (!call->filter) if (!call->filter) return -ENOMEM; return -ENOMEM; Loading Loading @@ -447,12 +450,10 @@ static int init_subsystem_preds(struct event_subsystem *system) if (strcmp(call->system, system->name) != 0) if (strcmp(call->system, system->name) != 0) continue; continue; if (!call->filter) { err = init_preds(call); err = init_preds(call); if (err) if (err) return err; return err; } } } return 0; return 0; } } Loading