aboutsummaryrefslogtreecommitdiffstats
path: root/Documentation/trace
diff options
context:
space:
mode:
authorLinus Torvalds <torvalds@linux-foundation.org>2009-12-31 14:52:01 -0500
committerLinus Torvalds <torvalds@linux-foundation.org>2009-12-31 14:52:01 -0500
commitb21c07040304b8716e38a4a0e4ab60f386357e61 (patch)
treeeb2cf03ec35b9a5090c0adaab659a766e02c3b10 /Documentation/trace
parent4e58fb7305449cf8c5a86dd97dfc1812221be77c (diff)
parentfb7ae981cb9fe8665b9da97e8734745e030c151d (diff)
Merge branch 'tracing-fixes-for-linus' of git://git.kernel.org/pub/scm/linux/kernel/git/tip/linux-2.6-tip
* 'tracing-fixes-for-linus' of git://git.kernel.org/pub/scm/linux/kernel/git/tip/linux-2.6-tip: tracing: Fix sign fields in ftrace_define_fields_##call() tracing/syscalls: Fix typo in SYSCALL_DEFINE0 tracing/kprobe: Show sign of fields in trace_kprobe format files ksym_tracer: Remove trace_stat ksym_tracer: Fix race when incrementing count ksym_tracer: Fix to allow writing newline to ksym_trace_filter ksym_tracer: Fix to make the tracer work tracing: Kconfig spelling fixes and cleanups tracing: Fix setting tracer specific options Documentation: Update ftrace-design.txt Documentation: Update tracepoint-analysis.txt Documentation: Update mmiotrace.txt
Diffstat (limited to 'Documentation/trace')
-rw-r--r--Documentation/trace/ftrace-design.txt14
-rw-r--r--Documentation/trace/mmiotrace.txt15
-rw-r--r--Documentation/trace/tracepoint-analysis.txt60
3 files changed, 45 insertions, 44 deletions
diff --git a/Documentation/trace/ftrace-design.txt b/Documentation/trace/ftrace-design.txt
index 641a1ef2a7ff..239f14b2b55a 100644
--- a/Documentation/trace/ftrace-design.txt
+++ b/Documentation/trace/ftrace-design.txt
@@ -53,14 +53,14 @@ size of the mcount call that is embedded in the function).
53For example, if the function foo() calls bar(), when the bar() function calls 53For example, if the function foo() calls bar(), when the bar() function calls
54mcount(), the arguments mcount() will pass to the tracer are: 54mcount(), the arguments mcount() will pass to the tracer are:
55 "frompc" - the address bar() will use to return to foo() 55 "frompc" - the address bar() will use to return to foo()
56 "selfpc" - the address bar() (with _mcount() size adjustment) 56 "selfpc" - the address bar() (with mcount() size adjustment)
57 57
58Also keep in mind that this mcount function will be called *a lot*, so 58Also keep in mind that this mcount function will be called *a lot*, so
59optimizing for the default case of no tracer will help the smooth running of 59optimizing for the default case of no tracer will help the smooth running of
60your system when tracing is disabled. So the start of the mcount function is 60your system when tracing is disabled. So the start of the mcount function is
61typically the bare min with checking things before returning. That also means 61typically the bare minimum with checking things before returning. That also
62the code flow should usually kept linear (i.e. no branching in the nop case). 62means the code flow should usually be kept linear (i.e. no branching in the nop
63This is of course an optimization and not a hard requirement. 63case). This is of course an optimization and not a hard requirement.
64 64
65Here is some pseudo code that should help (these functions should actually be 65Here is some pseudo code that should help (these functions should actually be
66implemented in assembly): 66implemented in assembly):
@@ -131,10 +131,10 @@ some functions to save (hijack) and restore the return address.
131 131
132The mcount function should check the function pointers ftrace_graph_return 132The mcount function should check the function pointers ftrace_graph_return
133(compare to ftrace_stub) and ftrace_graph_entry (compare to 133(compare to ftrace_stub) and ftrace_graph_entry (compare to
134ftrace_graph_entry_stub). If either of those are not set to the relevant stub 134ftrace_graph_entry_stub). If either of those is not set to the relevant stub
135function, call the arch-specific function ftrace_graph_caller which in turn 135function, call the arch-specific function ftrace_graph_caller which in turn
136calls the arch-specific function prepare_ftrace_return. Neither of these 136calls the arch-specific function prepare_ftrace_return. Neither of these
137function names are strictly required, but you should use them anyways to stay 137function names is strictly required, but you should use them anyway to stay
138consistent across the architecture ports -- easier to compare & contrast 138consistent across the architecture ports -- easier to compare & contrast
139things. 139things.
140 140
@@ -144,7 +144,7 @@ but the first argument should be a pointer to the "frompc". Typically this is
144located on the stack. This allows the function to hijack the return address 144located on the stack. This allows the function to hijack the return address
145temporarily to have it point to the arch-specific function return_to_handler. 145temporarily to have it point to the arch-specific function return_to_handler.
146That function will simply call the common ftrace_return_to_handler function and 146That function will simply call the common ftrace_return_to_handler function and
147that will return the original return address with which, you can return to the 147that will return the original return address with which you can return to the
148original call site. 148original call site.
149 149
150Here is the updated mcount pseudo code: 150Here is the updated mcount pseudo code:
diff --git a/Documentation/trace/mmiotrace.txt b/Documentation/trace/mmiotrace.txt
index 162effbfbdec..664e7386d89e 100644
--- a/Documentation/trace/mmiotrace.txt
+++ b/Documentation/trace/mmiotrace.txt
@@ -44,7 +44,8 @@ Check for lost events.
44Usage 44Usage
45----- 45-----
46 46
47Make sure debugfs is mounted to /sys/kernel/debug. If not, (requires root privileges) 47Make sure debugfs is mounted to /sys/kernel/debug.
48If not (requires root privileges):
48$ mount -t debugfs debugfs /sys/kernel/debug 49$ mount -t debugfs debugfs /sys/kernel/debug
49 50
50Check that the driver you are about to trace is not loaded. 51Check that the driver you are about to trace is not loaded.
@@ -91,7 +92,7 @@ $ dmesg > dmesg.txt
91$ tar zcf pciid-nick-mmiotrace.tar.gz mydump.txt lspci.txt dmesg.txt 92$ tar zcf pciid-nick-mmiotrace.tar.gz mydump.txt lspci.txt dmesg.txt
92and then send the .tar.gz file. The trace compresses considerably. Replace 93and then send the .tar.gz file. The trace compresses considerably. Replace
93"pciid" and "nick" with the PCI ID or model name of your piece of hardware 94"pciid" and "nick" with the PCI ID or model name of your piece of hardware
94under investigation and your nick name. 95under investigation and your nickname.
95 96
96 97
97How Mmiotrace Works 98How Mmiotrace Works
@@ -100,7 +101,7 @@ How Mmiotrace Works
100Access to hardware IO-memory is gained by mapping addresses from PCI bus by 101Access to hardware IO-memory is gained by mapping addresses from PCI bus by
101calling one of the ioremap_*() functions. Mmiotrace is hooked into the 102calling one of the ioremap_*() functions. Mmiotrace is hooked into the
102__ioremap() function and gets called whenever a mapping is created. Mapping is 103__ioremap() function and gets called whenever a mapping is created. Mapping is
103an event that is recorded into the trace log. Note, that ISA range mappings 104an event that is recorded into the trace log. Note that ISA range mappings
104are not caught, since the mapping always exists and is returned directly. 105are not caught, since the mapping always exists and is returned directly.
105 106
106MMIO accesses are recorded via page faults. Just before __ioremap() returns, 107MMIO accesses are recorded via page faults. Just before __ioremap() returns,
@@ -122,11 +123,11 @@ Trace Log Format
122---------------- 123----------------
123 124
124The raw log is text and easily filtered with e.g. grep and awk. One record is 125The raw log is text and easily filtered with e.g. grep and awk. One record is
125one line in the log. A record starts with a keyword, followed by keyword 126one line in the log. A record starts with a keyword, followed by keyword-
126dependant arguments. Arguments are separated by a space, or continue until the 127dependent arguments. Arguments are separated by a space, or continue until the
127end of line. The format for version 20070824 is as follows: 128end of line. The format for version 20070824 is as follows:
128 129
129Explanation Keyword Space separated arguments 130Explanation Keyword Space-separated arguments
130--------------------------------------------------------------------------- 131---------------------------------------------------------------------------
131 132
132read event R width, timestamp, map id, physical, value, PC, PID 133read event R width, timestamp, map id, physical, value, PC, PID
@@ -136,7 +137,7 @@ iounmap event UNMAP timestamp, map id, PC, PID
136marker MARK timestamp, text 137marker MARK timestamp, text
137version VERSION the string "20070824" 138version VERSION the string "20070824"
138info for reader LSPCI one line from lspci -v 139info for reader LSPCI one line from lspci -v
139PCI address map PCIDEV space separated /proc/bus/pci/devices data 140PCI address map PCIDEV space-separated /proc/bus/pci/devices data
140unk. opcode UNKNOWN timestamp, map id, physical, data, PC, PID 141unk. opcode UNKNOWN timestamp, map id, physical, data, PC, PID
141 142
142Timestamp is in seconds with decimals. Physical is a PCI bus address, virtual 143Timestamp is in seconds with decimals. Physical is a PCI bus address, virtual
diff --git a/Documentation/trace/tracepoint-analysis.txt b/Documentation/trace/tracepoint-analysis.txt
index 5eb4e487e667..87bee3c129ba 100644
--- a/Documentation/trace/tracepoint-analysis.txt
+++ b/Documentation/trace/tracepoint-analysis.txt
@@ -10,8 +10,8 @@ Tracepoints (see Documentation/trace/tracepoints.txt) can be used without
10creating custom kernel modules to register probe functions using the event 10creating custom kernel modules to register probe functions using the event
11tracing infrastructure. 11tracing infrastructure.
12 12
13Simplistically, tracepoints will represent an important event that when can 13Simplistically, tracepoints represent important events that can be
14be taken in conjunction with other tracepoints to build a "Big Picture" of 14taken in conjunction with other tracepoints to build a "Big Picture" of
15what is going on within the system. There are a large number of methods for 15what is going on within the system. There are a large number of methods for
16gathering and interpreting these events. Lacking any current Best Practises, 16gathering and interpreting these events. Lacking any current Best Practises,
17this document describes some of the methods that can be used. 17this document describes some of the methods that can be used.
@@ -33,12 +33,12 @@ calling
33 33
34will give a fair indication of the number of events available. 34will give a fair indication of the number of events available.
35 35
362.2 PCL 362.2 PCL (Performance Counters for Linux)
37------- 37-------
38 38
39Discovery and enumeration of all counters and events, including tracepoints 39Discovery and enumeration of all counters and events, including tracepoints,
40are available with the perf tool. Getting a list of available events is a 40are available with the perf tool. Getting a list of available events is a
41simple case of 41simple case of:
42 42
43 $ perf list 2>&1 | grep Tracepoint 43 $ perf list 2>&1 | grep Tracepoint
44 ext4:ext4_free_inode [Tracepoint event] 44 ext4:ext4_free_inode [Tracepoint event]
@@ -49,19 +49,19 @@ simple case of
49 [ .... remaining output snipped .... ] 49 [ .... remaining output snipped .... ]
50 50
51 51
522. Enabling Events 523. Enabling Events
53================== 53==================
54 54
552.1 System-Wide Event Enabling 553.1 System-Wide Event Enabling
56------------------------------ 56------------------------------
57 57
58See Documentation/trace/events.txt for a proper description on how events 58See Documentation/trace/events.txt for a proper description on how events
59can be enabled system-wide. A short example of enabling all events related 59can be enabled system-wide. A short example of enabling all events related
60to page allocation would look something like 60to page allocation would look something like:
61 61
62 $ for i in `find /sys/kernel/debug/tracing/events -name "enable" | grep mm_`; do echo 1 > $i; done 62 $ for i in `find /sys/kernel/debug/tracing/events -name "enable" | grep mm_`; do echo 1 > $i; done
63 63
642.2 System-Wide Event Enabling with SystemTap 643.2 System-Wide Event Enabling with SystemTap
65--------------------------------------------- 65---------------------------------------------
66 66
67In SystemTap, tracepoints are accessible using the kernel.trace() function 67In SystemTap, tracepoints are accessible using the kernel.trace() function
@@ -86,7 +86,7 @@ were allocating the pages.
86 print_count() 86 print_count()
87 } 87 }
88 88
892.3 System-Wide Event Enabling with PCL 893.3 System-Wide Event Enabling with PCL
90--------------------------------------- 90---------------------------------------
91 91
92By specifying the -a switch and analysing sleep, the system-wide events 92By specifying the -a switch and analysing sleep, the system-wide events
@@ -107,16 +107,16 @@ for a duration of time can be examined.
107Similarly, one could execute a shell and exit it as desired to get a report 107Similarly, one could execute a shell and exit it as desired to get a report
108at that point. 108at that point.
109 109
1102.4 Local Event Enabling 1103.4 Local Event Enabling
111------------------------ 111------------------------
112 112
113Documentation/trace/ftrace.txt describes how to enable events on a per-thread 113Documentation/trace/ftrace.txt describes how to enable events on a per-thread
114basis using set_ftrace_pid. 114basis using set_ftrace_pid.
115 115
1162.5 Local Event Enablement with PCL 1163.5 Local Event Enablement with PCL
117----------------------------------- 117-----------------------------------
118 118
119Events can be activate and tracked for the duration of a process on a local 119Events can be activated and tracked for the duration of a process on a local
120basis using PCL such as follows. 120basis using PCL such as follows.
121 121
122 $ perf stat -e kmem:mm_page_alloc -e kmem:mm_page_free_direct \ 122 $ perf stat -e kmem:mm_page_alloc -e kmem:mm_page_free_direct \
@@ -131,18 +131,18 @@ basis using PCL such as follows.
131 131
132 0.973913387 seconds time elapsed 132 0.973913387 seconds time elapsed
133 133
1343. Event Filtering 1344. Event Filtering
135================== 135==================
136 136
137Documentation/trace/ftrace.txt covers in-depth how to filter events in 137Documentation/trace/ftrace.txt covers in-depth how to filter events in
138ftrace. Obviously using grep and awk of trace_pipe is an option as well 138ftrace. Obviously using grep and awk of trace_pipe is an option as well
139as any script reading trace_pipe. 139as any script reading trace_pipe.
140 140
1414. Analysing Event Variances with PCL 1415. Analysing Event Variances with PCL
142===================================== 142=====================================
143 143
144Any workload can exhibit variances between runs and it can be important 144Any workload can exhibit variances between runs and it can be important
145to know what the standard deviation in. By and large, this is left to the 145to know what the standard deviation is. By and large, this is left to the
146performance analyst to do it by hand. In the event that the discrete event 146performance analyst to do it by hand. In the event that the discrete event
147occurrences are useful to the performance analyst, then perf can be used. 147occurrences are useful to the performance analyst, then perf can be used.
148 148
@@ -166,7 +166,7 @@ In the event that some higher-level event is required that depends on some
166aggregation of discrete events, then a script would need to be developed. 166aggregation of discrete events, then a script would need to be developed.
167 167
168Using --repeat, it is also possible to view how events are fluctuating over 168Using --repeat, it is also possible to view how events are fluctuating over
169time on a system wide basis using -a and sleep. 169time on a system-wide basis using -a and sleep.
170 170
171 $ perf stat -e kmem:mm_page_alloc -e kmem:mm_page_free_direct \ 171 $ perf stat -e kmem:mm_page_alloc -e kmem:mm_page_free_direct \
172 -e kmem:mm_pagevec_free \ 172 -e kmem:mm_pagevec_free \
@@ -180,7 +180,7 @@ time on a system wide basis using -a and sleep.
180 180
181 1.002251757 seconds time elapsed ( +- 0.005% ) 181 1.002251757 seconds time elapsed ( +- 0.005% )
182 182
1835. Higher-Level Analysis with Helper Scripts 1836. Higher-Level Analysis with Helper Scripts
184============================================ 184============================================
185 185
186When events are enabled the events that are triggering can be read from 186When events are enabled the events that are triggering can be read from
@@ -190,11 +190,11 @@ be gathered on-line as appropriate. Examples of post-processing might include
190 190
191 o Reading information from /proc for the PID that triggered the event 191 o Reading information from /proc for the PID that triggered the event
192 o Deriving a higher-level event from a series of lower-level events. 192 o Deriving a higher-level event from a series of lower-level events.
193 o Calculate latencies between two events 193 o Calculating latencies between two events
194 194
195Documentation/trace/postprocess/trace-pagealloc-postprocess.pl is an example 195Documentation/trace/postprocess/trace-pagealloc-postprocess.pl is an example
196script that can read trace_pipe from STDIN or a copy of a trace. When used 196script that can read trace_pipe from STDIN or a copy of a trace. When used
197on-line, it can be interrupted once to generate a report without existing 197on-line, it can be interrupted once to generate a report without exiting
198and twice to exit. 198and twice to exit.
199 199
200Simplistically, the script just reads STDIN and counts up events but it 200Simplistically, the script just reads STDIN and counts up events but it
@@ -212,12 +212,12 @@ also can do more such as
212 processes, the parent process responsible for creating all the helpers 212 processes, the parent process responsible for creating all the helpers
213 can be identified 213 can be identified
214 214
2156. Lower-Level Analysis with PCL 2157. Lower-Level Analysis with PCL
216================================ 216================================
217 217
218There may also be a requirement to identify what functions with a program 218There may also be a requirement to identify what functions within a program
219were generating events within the kernel. To begin this sort of analysis, the 219were generating events within the kernel. To begin this sort of analysis, the
220data must be recorded. At the time of writing, this required root 220data must be recorded. At the time of writing, this required root:
221 221
222 $ perf record -c 1 \ 222 $ perf record -c 1 \
223 -e kmem:mm_page_alloc -e kmem:mm_page_free_direct \ 223 -e kmem:mm_page_alloc -e kmem:mm_page_free_direct \
@@ -253,11 +253,11 @@ perf report.
253 # (For more details, try: perf report --sort comm,dso,symbol) 253 # (For more details, try: perf report --sort comm,dso,symbol)
254 # 254 #
255 255
256According to this, the vast majority of events occured triggered on events 256According to this, the vast majority of events triggered on events
257within the VDSO. With simple binaries, this will often be the case so lets 257within the VDSO. With simple binaries, this will often be the case so let's
258take a slightly different example. In the course of writing this, it was 258take a slightly different example. In the course of writing this, it was
259noticed that X was generating an insane amount of page allocations so lets look 259noticed that X was generating an insane amount of page allocations so let's look
260at it 260at it:
261 261
262 $ perf record -c 1 -f \ 262 $ perf record -c 1 -f \
263 -e kmem:mm_page_alloc -e kmem:mm_page_free_direct \ 263 -e kmem:mm_page_alloc -e kmem:mm_page_free_direct \
@@ -280,8 +280,8 @@ This was interrupted after a few seconds and
280 # (For more details, try: perf report --sort comm,dso,symbol) 280 # (For more details, try: perf report --sort comm,dso,symbol)
281 # 281 #
282 282
283So, almost half of the events are occuring in a library. To get an idea which 283So, almost half of the events are occurring in a library. To get an idea which
284symbol. 284symbol:
285 285
286 $ perf report --sort comm,dso,symbol 286 $ perf report --sort comm,dso,symbol
287 # Samples: 27666 287 # Samples: 27666
@@ -297,7 +297,7 @@ symbol.
297 0.01% Xorg /opt/gfx-test/lib/libpixman-1.so.0.13.1 [.] get_fast_path 297 0.01% Xorg /opt/gfx-test/lib/libpixman-1.so.0.13.1 [.] get_fast_path
298 0.00% Xorg [kernel] [k] ftrace_trace_userstack 298 0.00% Xorg [kernel] [k] ftrace_trace_userstack
299 299
300To see where within the function pixmanFillsse2 things are going wrong 300To see where within the function pixmanFillsse2 things are going wrong:
301 301
302 $ perf annotate pixmanFillsse2 302 $ perf annotate pixmanFillsse2
303 [ ... ] 303 [ ... ]