blob: a39b3c749de58c12129d80d0ffad738f9a7836f0 [file] [log] [blame]
Steven Rostedteb6d42e2008-07-10 12:46:01 -04001 ftrace - Function Tracer
2 ========================
3
4Copyright 2008 Red Hat Inc.
Steven Rostedta41eeba2008-07-14 16:41:12 -04005 Author: Steven Rostedt <srostedt@redhat.com>
6 License: The GNU Free Documentation License, Version 1.2
Steven Rostedta97762a2008-07-31 12:40:52 -04007 (dual licensed under the GPL v2)
Steven Rostedtf2d9c742008-07-15 10:57:33 -04008Reviewers: Elias Oltmanns, Randy Dunlap, Andrew Morton,
9 John Kacur, and David Teigland.
Steven Rostedt42ec6322008-11-03 15:18:56 -050010Written for: 2.6.28-rc2
Steven Rostedteb6d42e2008-07-10 12:46:01 -040011
12Introduction
13------------
14
15Ftrace is an internal tracer designed to help out developers and
16designers of systems to find what is going on inside the kernel.
Ingo Molnar57526742009-02-19 12:54:10 +010017It can be used for debugging or analyzing latencies and
18performance issues that take place outside of user-space.
Steven Rostedteb6d42e2008-07-10 12:46:01 -040019
20Although ftrace is the function tracer, it also includes an
Ingo Molnar57526742009-02-19 12:54:10 +010021infrastructure that allows for other types of tracing. Some of
22the tracers that are currently in ftrace include a tracer to
23trace context switches, the time it takes for a high priority
24task to run after it was woken up, the time interrupts are
25disabled, and more (ftrace allows for tracer plugins, which
26means that the list of tracers can always grow).
Steven Rostedteb6d42e2008-07-10 12:46:01 -040027
28
29The File System
30---------------
31
Ingo Molnar57526742009-02-19 12:54:10 +010032Ftrace uses the debugfs file system to hold the control files as
33well as the files to display output.
Steven Rostedteb6d42e2008-07-10 12:46:01 -040034
GeunSik Lim156f5a72009-06-02 15:01:37 +090035When debugfs is configured into the kernel (which selecting any ftrace
36option will do) the directory /sys/kernel/debug will be created. To mount
37this directory, you can add to your /etc/fstab file:
Steven Rostedteb6d42e2008-07-10 12:46:01 -040038
GeunSik Lim156f5a72009-06-02 15:01:37 +090039 debugfs /sys/kernel/debug debugfs defaults 0 0
Steven Rostedteb6d42e2008-07-10 12:46:01 -040040
GeunSik Lim156f5a72009-06-02 15:01:37 +090041Or you can mount it at run time with:
42
43 mount -t debugfs nodev /sys/kernel/debug
44
45For quicker access to that directory you may want to make a soft link to
46it:
47
48 ln -s /sys/kernel/debug /debug
49
50Any selected ftrace option will also create a directory called tracing
51within the debugfs. The rest of the document will assume that you are in
52the ftrace directory (cd /sys/kernel/debug/tracing) and will only concentrate
53on the files within that directory and not distract from the content with
54the extended "/sys/kernel/debug/tracing" path name.
Steven Rostedteb6d42e2008-07-10 12:46:01 -040055
56That's it! (assuming that you have ftrace configured into your kernel)
57
58After mounting the debugfs, you can see a directory called
59"tracing". This directory contains the control and output files
60of ftrace. Here is a list of some of the key files:
61
62
63 Note: all time values are in microseconds.
64
Ingo Molnar57526742009-02-19 12:54:10 +010065 current_tracer:
Steven Rostedteb6d42e2008-07-10 12:46:01 -040066
Ingo Molnar57526742009-02-19 12:54:10 +010067 This is used to set or display the current tracer
68 that is configured.
Steven Rostedteb6d42e2008-07-10 12:46:01 -040069
Ingo Molnar57526742009-02-19 12:54:10 +010070 available_tracers:
Steven Rostedteb6d42e2008-07-10 12:46:01 -040071
Ingo Molnar57526742009-02-19 12:54:10 +010072 This holds the different types of tracers that
73 have been compiled into the kernel. The
74 tracers listed here can be configured by
75 echoing their name into current_tracer.
Steven Rostedteb6d42e2008-07-10 12:46:01 -040076
Ingo Molnar57526742009-02-19 12:54:10 +010077 tracing_enabled:
Steven Rostedteb6d42e2008-07-10 12:46:01 -040078
Ingo Molnar57526742009-02-19 12:54:10 +010079 This sets or displays whether the current_tracer
80 is activated and tracing or not. Echo 0 into this
81 file to disable the tracer or 1 to enable it.
Steven Rostedteb6d42e2008-07-10 12:46:01 -040082
Ingo Molnar57526742009-02-19 12:54:10 +010083 trace:
Steven Rostedteb6d42e2008-07-10 12:46:01 -040084
Ingo Molnar57526742009-02-19 12:54:10 +010085 This file holds the output of the trace in a human
86 readable format (described below).
Steven Rostedteb6d42e2008-07-10 12:46:01 -040087
Ingo Molnar57526742009-02-19 12:54:10 +010088 latency_trace:
Steven Rostedteb6d42e2008-07-10 12:46:01 -040089
Ingo Molnar57526742009-02-19 12:54:10 +010090 This file shows the same trace but the information
91 is organized more to display possible latencies
92 in the system (described below).
Steven Rostedteb6d42e2008-07-10 12:46:01 -040093
Ingo Molnar57526742009-02-19 12:54:10 +010094 trace_pipe:
Steven Rostedteb6d42e2008-07-10 12:46:01 -040095
Ingo Molnar57526742009-02-19 12:54:10 +010096 The output is the same as the "trace" file but this
97 file is meant to be streamed with live tracing.
98 Reads from this file will block until new data
99 is retrieved. Unlike the "trace" and "latency_trace"
100 files, this file is a consumer. This means reading
101 from this file causes sequential reads to display
102 more current data. Once data is read from this
103 file, it is consumed, and will not be read
104 again with a sequential read. The "trace" and
105 "latency_trace" files are static, and if the
106 tracer is not adding more data, they will display
107 the same information every time they are read.
Steven Rostedteb6d42e2008-07-10 12:46:01 -0400108
Ingo Molnar57526742009-02-19 12:54:10 +0100109 trace_options:
Steven Rostedteb6d42e2008-07-10 12:46:01 -0400110
Ingo Molnar57526742009-02-19 12:54:10 +0100111 This file lets the user control the amount of data
112 that is displayed in one of the above output
113 files.
Steven Rostedtdf4fc312008-11-26 00:16:23 -0500114
KOSAKI Motohiro42b40b32009-03-07 23:55:09 +0900115 tracing_max_latency:
Frederic Weisbecker985ec202009-02-18 06:35:34 +0100116
Ingo Molnar57526742009-02-19 12:54:10 +0100117 Some of the tracers record the max latency.
118 For example, the time interrupts are disabled.
119 This time is saved in this file. The max trace
120 will also be stored, and displayed by either
121 "trace" or "latency_trace". A new max trace will
122 only be recorded if the latency is greater than
123 the value in this file. (in microseconds)
124
125 buffer_size_kb:
126
127 This sets or displays the number of kilobytes each CPU
128 buffer can hold. The tracer buffers are the same size
129 for each CPU. The displayed number is the size of the
130 CPU buffer and not total size of all buffers. The
131 trace buffers are allocated in pages (blocks of memory
132 that the kernel uses for allocation, usually 4 KB in size).
133 If the last page allocated has room for more bytes
134 than requested, the rest of the page will be used,
135 making the actual allocation bigger than requested.
136 ( Note, the size may not be a multiple of the page size
137 due to buffer managment overhead. )
138
139 This can only be updated when the current_tracer
140 is set to "nop".
141
142 tracing_cpumask:
143
144 This is a mask that lets the user only trace
145 on specified CPUS. The format is a hex string
146 representing the CPUS.
147
148 set_ftrace_filter:
149
150 When dynamic ftrace is configured in (see the
151 section below "dynamic ftrace"), the code is dynamically
152 modified (code text rewrite) to disable calling of the
153 function profiler (mcount). This lets tracing be configured
154 in with practically no overhead in performance. This also
155 has a side effect of enabling or disabling specific functions
156 to be traced. Echoing names of functions into this file
157 will limit the trace to only those functions.
158
159 set_ftrace_notrace:
160
161 This has an effect opposite to that of
162 set_ftrace_filter. Any function that is added here will not
163 be traced. If a function exists in both set_ftrace_filter
164 and set_ftrace_notrace, the function will _not_ be traced.
165
166 set_ftrace_pid:
167
168 Have the function tracer only trace a single thread.
169
170 set_graph_function:
171
172 Set a "trigger" function where tracing should start
173 with the function graph tracer (See the section
174 "dynamic ftrace" for more details).
175
176 available_filter_functions:
177
178 This lists the functions that ftrace
179 has processed and can trace. These are the function
180 names that you can pass to "set_ftrace_filter" or
181 "set_ftrace_notrace". (See the section "dynamic ftrace"
182 below for more details.)
Steven Rostedteb6d42e2008-07-10 12:46:01 -0400183
184
185The Tracers
186-----------
187
Steven Rostedtf2d9c742008-07-15 10:57:33 -0400188Here is the list of current tracers that may be configured.
Steven Rostedteb6d42e2008-07-10 12:46:01 -0400189
Ingo Molnar57526742009-02-19 12:54:10 +0100190 "function"
Steven Rostedteb6d42e2008-07-10 12:46:01 -0400191
Ingo Molnar57526742009-02-19 12:54:10 +0100192 Function call tracer to trace all kernel functions.
Frederic Weisbecker985ec202009-02-18 06:35:34 +0100193
Mike Frysingerbc5c6c02009-06-10 04:48:41 -0400194 "function_graph"
Steven Rostedteb6d42e2008-07-10 12:46:01 -0400195
Ingo Molnar57526742009-02-19 12:54:10 +0100196 Similar to the function tracer except that the
197 function tracer probes the functions on their entry
198 whereas the function graph tracer traces on both entry
199 and exit of the functions. It then provides the ability
200 to draw a graph of function calls similar to C code
201 source.
Steven Rostedteb6d42e2008-07-10 12:46:01 -0400202
Ingo Molnar57526742009-02-19 12:54:10 +0100203 "sched_switch"
Steven Rostedteb6d42e2008-07-10 12:46:01 -0400204
Ingo Molnar57526742009-02-19 12:54:10 +0100205 Traces the context switches and wakeups between tasks.
Steven Rostedteb6d42e2008-07-10 12:46:01 -0400206
Ingo Molnar57526742009-02-19 12:54:10 +0100207 "irqsoff"
Steven Rostedteb6d42e2008-07-10 12:46:01 -0400208
Ingo Molnar57526742009-02-19 12:54:10 +0100209 Traces the areas that disable interrupts and saves
210 the trace with the longest max latency.
211 See tracing_max_latency. When a new max is recorded,
212 it replaces the old trace. It is best to view this
213 trace via the latency_trace file.
Steven Rostedteb6d42e2008-07-10 12:46:01 -0400214
Ingo Molnar57526742009-02-19 12:54:10 +0100215 "preemptoff"
216
217 Similar to irqsoff but traces and records the amount of
218 time for which preemption is disabled.
219
220 "preemptirqsoff"
221
222 Similar to irqsoff and preemptoff, but traces and
223 records the largest time for which irqs and/or preemption
224 is disabled.
225
226 "wakeup"
227
228 Traces and records the max latency that it takes for
229 the highest priority task to get scheduled after
230 it has been woken up.
231
232 "hw-branch-tracer"
233
234 Uses the BTS CPU feature on x86 CPUs to traces all
235 branches executed.
236
237 "nop"
238
239 This is the "trace nothing" tracer. To remove all
240 tracers from tracing simply echo "nop" into
241 current_tracer.
Markus Metzgere2ea5392009-01-19 10:35:58 +0100242
Steven Rostedteb6d42e2008-07-10 12:46:01 -0400243
244Examples of using the tracer
245----------------------------
246
Ingo Molnar57526742009-02-19 12:54:10 +0100247Here are typical examples of using the tracers when controlling
248them only with the debugfs interface (without using any
249user-land utilities).
Steven Rostedteb6d42e2008-07-10 12:46:01 -0400250
251Output format:
252--------------
253
Steven Rostedtf2d9c742008-07-15 10:57:33 -0400254Here is an example of the output format of the file "trace"
Steven Rostedteb6d42e2008-07-10 12:46:01 -0400255
256 --------
Steven Rostedt9b803c02008-11-03 15:15:08 -0500257# tracer: function
Steven Rostedteb6d42e2008-07-10 12:46:01 -0400258#
259# TASK-PID CPU# TIMESTAMP FUNCTION
260# | | | | |
261 bash-4251 [01] 10152.583854: path_put <-path_walk
262 bash-4251 [01] 10152.583855: dput <-path_put
263 bash-4251 [01] 10152.583855: _atomic_dec_and_lock <-dput
264 --------
265
Ingo Molnar57526742009-02-19 12:54:10 +0100266A header is printed with the tracer name that is represented by
267the trace. In this case the tracer is "function". Then a header
268showing the format. Task name "bash", the task PID "4251", the
269CPU that it was running on "01", the timestamp in <secs>.<usecs>
270format, the function name that was traced "path_put" and the
271parent function that called this function "path_walk". The
272timestamp is the time at which the function was entered.
Steven Rostedteb6d42e2008-07-10 12:46:01 -0400273
Ingo Molnar57526742009-02-19 12:54:10 +0100274The sched_switch tracer also includes tracing of task wakeups
275and context switches.
Steven Rostedteb6d42e2008-07-10 12:46:01 -0400276
277 ksoftirqd/1-7 [01] 1453.070013: 7:115:R + 2916:115:S
278 ksoftirqd/1-7 [01] 1453.070013: 7:115:R + 10:115:S
279 ksoftirqd/1-7 [01] 1453.070013: 7:115:R ==> 10:115:R
280 events/1-10 [01] 1453.070013: 10:115:S ==> 2916:115:R
281 kondemand/1-2916 [01] 1453.070013: 2916:115:S ==> 7:115:R
282 ksoftirqd/1-7 [01] 1453.070013: 7:115:S ==> 0:140:R
283
Ingo Molnar57526742009-02-19 12:54:10 +0100284Wake ups are represented by a "+" and the context switches are
285shown as "==>". The format is:
Steven Rostedteb6d42e2008-07-10 12:46:01 -0400286
287 Context switches:
288
289 Previous task Next Task
290
291 <pid>:<prio>:<state> ==> <pid>:<prio>:<state>
292
293 Wake ups:
294
295 Current task Task waking up
296
297 <pid>:<prio>:<state> + <pid>:<prio>:<state>
298
Ingo Molnar57526742009-02-19 12:54:10 +0100299The prio is the internal kernel priority, which is the inverse
300of the priority that is usually displayed by user-space tools.
301Zero represents the highest priority (99). Prio 100 starts the
302"nice" priorities with 100 being equal to nice -20 and 139 being
303nice 19. The prio "140" is reserved for the idle task which is
304the lowest priority thread (pid 0).
Steven Rostedteb6d42e2008-07-10 12:46:01 -0400305
306
307Latency trace format
308--------------------
309
Ingo Molnar57526742009-02-19 12:54:10 +0100310For traces that display latency times, the latency_trace file
311gives somewhat more information to see why a latency happened.
312Here is a typical trace.
Steven Rostedteb6d42e2008-07-10 12:46:01 -0400313
314# tracer: irqsoff
315#
316irqsoff latency trace v1.1.5 on 2.6.26-rc8
317--------------------------------------------------------------------
318 latency: 97 us, #3/3, CPU#0 | (M:preempt VP:0, KP:0, SP:0 HP:0 #P:2)
319 -----------------
320 | task: swapper-0 (uid:0 nice:0 policy:0 rt_prio:0)
321 -----------------
322 => started at: apic_timer_interrupt
323 => ended at: do_softirq
324
325# _------=> CPU#
326# / _-----=> irqs-off
327# | / _----=> need-resched
328# || / _---=> hardirq/softirq
329# ||| / _--=> preempt-depth
330# |||| /
331# ||||| delay
332# cmd pid ||||| time | caller
333# \ / ||||| \ | /
334 <idle>-0 0d..1 0us+: trace_hardirqs_off_thunk (apic_timer_interrupt)
335 <idle>-0 0d.s. 97us : __do_softirq (do_softirq)
336 <idle>-0 0d.s1 98us : trace_hardirqs_on (do_softirq)
337
338
Ingo Molnar57526742009-02-19 12:54:10 +0100339This shows that the current tracer is "irqsoff" tracing the time
340for which interrupts were disabled. It gives the trace version
341and the version of the kernel upon which this was executed on
342(2.6.26-rc8). Then it displays the max latency in microsecs (97
343us). The number of trace entries displayed and the total number
344recorded (both are three: #3/3). The type of preemption that was
345used (PREEMPT). VP, KP, SP, and HP are always zero and are
346reserved for later use. #P is the number of online CPUS (#P:2).
Steven Rostedteb6d42e2008-07-10 12:46:01 -0400347
Ingo Molnar57526742009-02-19 12:54:10 +0100348The task is the process that was running when the latency
349occurred. (swapper pid: 0).
Steven Rostedteb6d42e2008-07-10 12:46:01 -0400350
Ingo Molnar57526742009-02-19 12:54:10 +0100351The start and stop (the functions in which the interrupts were
352disabled and enabled respectively) that caused the latencies:
Steven Rostedteb6d42e2008-07-10 12:46:01 -0400353
354 apic_timer_interrupt is where the interrupts were disabled.
355 do_softirq is where they were enabled again.
356
357The next lines after the header are the trace itself. The header
358explains which is which.
359
360 cmd: The name of the process in the trace.
361
362 pid: The PID of that process.
363
Steven Rostedtf2d9c742008-07-15 10:57:33 -0400364 CPU#: The CPU which the process was running on.
Steven Rostedteb6d42e2008-07-10 12:46:01 -0400365
366 irqs-off: 'd' interrupts are disabled. '.' otherwise.
Steven Rostedt92444892008-10-24 09:42:59 -0400367 Note: If the architecture does not support a way to
368 read the irq flags variable, an 'X' will always
369 be printed here.
Steven Rostedteb6d42e2008-07-10 12:46:01 -0400370
371 need-resched: 'N' task need_resched is set, '.' otherwise.
372
373 hardirq/softirq:
Steven Rostedtf2d9c742008-07-15 10:57:33 -0400374 'H' - hard irq occurred inside a softirq.
Steven Rostedteb6d42e2008-07-10 12:46:01 -0400375 'h' - hard irq is running
376 's' - soft irq is running
377 '.' - normal context.
378
379 preempt-depth: The level of preempt_disabled
380
381The above is mostly meaningful for kernel developers.
382
Steven Rostedta41eeba2008-07-14 16:41:12 -0400383 time: This differs from the trace file output. The trace file output
Steven Rostedtf2d9c742008-07-15 10:57:33 -0400384 includes an absolute timestamp. The timestamp used by the
Steven Rostedta41eeba2008-07-14 16:41:12 -0400385 latency_trace file is relative to the start of the trace.
Steven Rostedteb6d42e2008-07-10 12:46:01 -0400386
387 delay: This is just to help catch your eye a bit better. And
Ingo Molnar57526742009-02-19 12:54:10 +0100388 needs to be fixed to be only relative to the same CPU.
389 The marks are determined by the difference between this
390 current trace and the next trace.
391 '!' - greater than preempt_mark_thresh (default 100)
392 '+' - greater than 1 microsecond
393 ' ' - less than or equal to 1 microsecond.
Steven Rostedteb6d42e2008-07-10 12:46:01 -0400394
395 The rest is the same as the 'trace' file.
396
397
Steven Rostedtee6bce52008-11-12 17:52:37 -0500398trace_options
399-------------
Steven Rostedteb6d42e2008-07-10 12:46:01 -0400400
Ingo Molnar57526742009-02-19 12:54:10 +0100401The trace_options file is used to control what gets printed in
402the trace output. To see what is available, simply cat the file:
Steven Rostedteb6d42e2008-07-10 12:46:01 -0400403
GeunSik Lim156f5a72009-06-02 15:01:37 +0900404 cat trace_options
Steven Rostedteb6d42e2008-07-10 12:46:01 -0400405 print-parent nosym-offset nosym-addr noverbose noraw nohex nobin \
Ingo Molnar57526742009-02-19 12:54:10 +0100406 noblock nostacktrace nosched-tree nouserstacktrace nosym-userobj
Steven Rostedteb6d42e2008-07-10 12:46:01 -0400407
Ingo Molnar57526742009-02-19 12:54:10 +0100408To disable one of the options, echo in the option prepended with
409"no".
Steven Rostedteb6d42e2008-07-10 12:46:01 -0400410
GeunSik Lim156f5a72009-06-02 15:01:37 +0900411 echo noprint-parent > trace_options
Steven Rostedteb6d42e2008-07-10 12:46:01 -0400412
413To enable an option, leave off the "no".
414
GeunSik Lim156f5a72009-06-02 15:01:37 +0900415 echo sym-offset > trace_options
Steven Rostedteb6d42e2008-07-10 12:46:01 -0400416
417Here are the available options:
418
Ingo Molnar57526742009-02-19 12:54:10 +0100419 print-parent - On function traces, display the calling (parent)
420 function as well as the function being traced.
Steven Rostedteb6d42e2008-07-10 12:46:01 -0400421
422 print-parent:
423 bash-4000 [01] 1477.606694: simple_strtoul <-strict_strtoul
424
425 noprint-parent:
426 bash-4000 [01] 1477.606694: simple_strtoul
427
428
Ingo Molnar57526742009-02-19 12:54:10 +0100429 sym-offset - Display not only the function name, but also the
430 offset in the function. For example, instead of
431 seeing just "ktime_get", you will see
432 "ktime_get+0xb/0x20".
Steven Rostedteb6d42e2008-07-10 12:46:01 -0400433
434 sym-offset:
435 bash-4000 [01] 1477.606694: simple_strtoul+0x6/0xa0
436
Ingo Molnar57526742009-02-19 12:54:10 +0100437 sym-addr - this will also display the function address as well
438 as the function name.
Steven Rostedteb6d42e2008-07-10 12:46:01 -0400439
440 sym-addr:
441 bash-4000 [01] 1477.606694: simple_strtoul <c0339346>
442
443 verbose - This deals with the latency_trace file.
444
445 bash 4000 1 0 00000000 00010a95 [58127d26] 1720.415ms \
446 (+0.000ms): simple_strtoul (strict_strtoul)
447
Ingo Molnar57526742009-02-19 12:54:10 +0100448 raw - This will display raw numbers. This option is best for
449 use with user applications that can translate the raw
450 numbers better than having it done in the kernel.
Steven Rostedteb6d42e2008-07-10 12:46:01 -0400451
Ingo Molnar57526742009-02-19 12:54:10 +0100452 hex - Similar to raw, but the numbers will be in a hexadecimal
453 format.
Steven Rostedteb6d42e2008-07-10 12:46:01 -0400454
455 bin - This will print out the formats in raw binary.
456
457 block - TBD (needs update)
458
Ingo Molnar57526742009-02-19 12:54:10 +0100459 stacktrace - This is one of the options that changes the trace
460 itself. When a trace is recorded, so is the stack
461 of functions. This allows for back traces of
462 trace sites.
Steven Rostedteb6d42e2008-07-10 12:46:01 -0400463
Ingo Molnar57526742009-02-19 12:54:10 +0100464 userstacktrace - This option changes the trace. It records a
465 stacktrace of the current userspace thread.
Török Edwin02b67512008-11-22 13:28:47 +0200466
Ingo Molnar57526742009-02-19 12:54:10 +0100467 sym-userobj - when user stacktrace are enabled, look up which
468 object the address belongs to, and print a
469 relative address. This is especially useful when
470 ASLR is on, otherwise you don't get a chance to
471 resolve the address to object/file/line after
472 the app is no longer running
Török Edwinb54d3de2008-11-22 13:28:48 +0200473
Ingo Molnar57526742009-02-19 12:54:10 +0100474 The lookup is performed when you read
475 trace,trace_pipe,latency_trace. Example:
Török Edwinb54d3de2008-11-22 13:28:48 +0200476
477 a.out-1623 [000] 40874.465068: /root/a.out[+0x480] <-/root/a.out[+0
478x494] <- /root/a.out[+0x4a8] <- /lib/libc-2.7.so[+0x1e1a6]
479
Ingo Molnar57526742009-02-19 12:54:10 +0100480 sched-tree - trace all tasks that are on the runqueue, at
481 every scheduling event. Will add overhead if
482 there's a lot of tasks running at once.
Steven Rostedteb6d42e2008-07-10 12:46:01 -0400483
484
485sched_switch
486------------
487
Steven Rostedtf2d9c742008-07-15 10:57:33 -0400488This tracer simply records schedule switches. Here is an example
Steven Rostedta41eeba2008-07-14 16:41:12 -0400489of how to use it.
Steven Rostedteb6d42e2008-07-10 12:46:01 -0400490
GeunSik Lim156f5a72009-06-02 15:01:37 +0900491 # echo sched_switch > current_tracer
492 # echo 1 > tracing_enabled
Steven Rostedteb6d42e2008-07-10 12:46:01 -0400493 # sleep 1
GeunSik Lim156f5a72009-06-02 15:01:37 +0900494 # echo 0 > tracing_enabled
495 # cat trace
Steven Rostedteb6d42e2008-07-10 12:46:01 -0400496
497# tracer: sched_switch
498#
499# TASK-PID CPU# TIMESTAMP FUNCTION
500# | | | | |
501 bash-3997 [01] 240.132281: 3997:120:R + 4055:120:R
502 bash-3997 [01] 240.132284: 3997:120:R ==> 4055:120:R
503 sleep-4055 [01] 240.132371: 4055:120:S ==> 3997:120:R
504 bash-3997 [01] 240.132454: 3997:120:R + 4055:120:S
505 bash-3997 [01] 240.132457: 3997:120:R ==> 4055:120:R
506 sleep-4055 [01] 240.132460: 4055:120:D ==> 3997:120:R
507 bash-3997 [01] 240.132463: 3997:120:R + 4055:120:D
508 bash-3997 [01] 240.132465: 3997:120:R ==> 4055:120:R
509 <idle>-0 [00] 240.132589: 0:140:R + 4:115:S
510 <idle>-0 [00] 240.132591: 0:140:R ==> 4:115:R
511 ksoftirqd/0-4 [00] 240.132595: 4:115:S ==> 0:140:R
512 <idle>-0 [00] 240.132598: 0:140:R + 4:115:S
513 <idle>-0 [00] 240.132599: 0:140:R ==> 4:115:R
514 ksoftirqd/0-4 [00] 240.132603: 4:115:S ==> 0:140:R
515 sleep-4055 [01] 240.133058: 4055:120:S ==> 3997:120:R
516 [...]
517
518
Ingo Molnar57526742009-02-19 12:54:10 +0100519As we have discussed previously about this format, the header
520shows the name of the trace and points to the options. The
521"FUNCTION" is a misnomer since here it represents the wake ups
522and context switches.
Steven Rostedteb6d42e2008-07-10 12:46:01 -0400523
Ingo Molnar57526742009-02-19 12:54:10 +0100524The sched_switch file only lists the wake ups (represented with
525'+') and context switches ('==>') with the previous task or
526current task first followed by the next task or task waking up.
527The format for both of these is PID:KERNEL-PRIO:TASK-STATE.
528Remember that the KERNEL-PRIO is the inverse of the actual
529priority with zero (0) being the highest priority and the nice
530values starting at 100 (nice -20). Below is a quick chart to map
531the kernel priority to user land priorities.
Steven Rostedteb6d42e2008-07-10 12:46:01 -0400532
GeunSik Lim294ae402009-05-28 10:36:11 +0900533 Kernel Space User Space
534 ===============================================================
535 0(high) to 98(low) user RT priority 99(high) to 1(low)
536 with SCHED_RR or SCHED_FIFO
537 ---------------------------------------------------------------
538 99 sched_priority is not used in scheduling
539 decisions(it must be specified as 0)
540 ---------------------------------------------------------------
541 100(high) to 139(low) user nice -20(high) to 19(low)
542 ---------------------------------------------------------------
543 140 idle task priority
544 ---------------------------------------------------------------
Steven Rostedteb6d42e2008-07-10 12:46:01 -0400545
546The task states are:
547
548 R - running : wants to run, may not actually be running
549 S - sleep : process is waiting to be woken up (handles signals)
Steven Rostedtf2d9c742008-07-15 10:57:33 -0400550 D - disk sleep (uninterruptible sleep) : process must be woken up
551 (ignores signals)
Steven Rostedteb6d42e2008-07-10 12:46:01 -0400552 T - stopped : process suspended
553 t - traced : process is being traced (with something like gdb)
554 Z - zombie : process waiting to be cleaned up
555 X - unknown
556
557
558ftrace_enabled
559--------------
560
Ingo Molnar57526742009-02-19 12:54:10 +0100561The following tracers (listed below) give different output
562depending on whether or not the sysctl ftrace_enabled is set. To
563set ftrace_enabled, one can either use the sysctl function or
564set it via the proc file system interface.
Steven Rostedteb6d42e2008-07-10 12:46:01 -0400565
566 sysctl kernel.ftrace_enabled=1
567
568 or
569
570 echo 1 > /proc/sys/kernel/ftrace_enabled
571
Ingo Molnar57526742009-02-19 12:54:10 +0100572To disable ftrace_enabled simply replace the '1' with '0' in the
573above commands.
Steven Rostedteb6d42e2008-07-10 12:46:01 -0400574
Ingo Molnar57526742009-02-19 12:54:10 +0100575When ftrace_enabled is set the tracers will also record the
576functions that are within the trace. The descriptions of the
577tracers will also show an example with ftrace enabled.
Steven Rostedteb6d42e2008-07-10 12:46:01 -0400578
579
580irqsoff
581-------
582
583When interrupts are disabled, the CPU can not react to any other
584external event (besides NMIs and SMIs). This prevents the timer
Ingo Molnar57526742009-02-19 12:54:10 +0100585interrupt from triggering or the mouse interrupt from letting
586the kernel know of a new mouse event. The result is a latency
587with the reaction time.
Steven Rostedteb6d42e2008-07-10 12:46:01 -0400588
Ingo Molnar57526742009-02-19 12:54:10 +0100589The irqsoff tracer tracks the time for which interrupts are
590disabled. When a new maximum latency is hit, the tracer saves
591the trace leading up to that latency point so that every time a
592new maximum is reached, the old saved trace is discarded and the
593new trace is saved.
Steven Rostedteb6d42e2008-07-10 12:46:01 -0400594
Ingo Molnar57526742009-02-19 12:54:10 +0100595To reset the maximum, echo 0 into tracing_max_latency. Here is
596an example:
Steven Rostedteb6d42e2008-07-10 12:46:01 -0400597
GeunSik Lim156f5a72009-06-02 15:01:37 +0900598 # echo irqsoff > current_tracer
599 # echo 0 > tracing_max_latency
600 # echo 1 > tracing_enabled
Steven Rostedteb6d42e2008-07-10 12:46:01 -0400601 # ls -ltr
602 [...]
GeunSik Lim156f5a72009-06-02 15:01:37 +0900603 # echo 0 > tracing_enabled
604 # cat latency_trace
Steven Rostedteb6d42e2008-07-10 12:46:01 -0400605# tracer: irqsoff
606#
Steven Rostedtf2d9c742008-07-15 10:57:33 -0400607irqsoff latency trace v1.1.5 on 2.6.26
Steven Rostedteb6d42e2008-07-10 12:46:01 -0400608--------------------------------------------------------------------
Steven Rostedtf2d9c742008-07-15 10:57:33 -0400609 latency: 12 us, #3/3, CPU#1 | (M:preempt VP:0, KP:0, SP:0 HP:0 #P:2)
Steven Rostedteb6d42e2008-07-10 12:46:01 -0400610 -----------------
Steven Rostedtf2d9c742008-07-15 10:57:33 -0400611 | task: bash-3730 (uid:0 nice:0 policy:0 rt_prio:0)
Steven Rostedteb6d42e2008-07-10 12:46:01 -0400612 -----------------
Steven Rostedtf2d9c742008-07-15 10:57:33 -0400613 => started at: sys_setpgid
614 => ended at: sys_setpgid
Steven Rostedteb6d42e2008-07-10 12:46:01 -0400615
616# _------=> CPU#
617# / _-----=> irqs-off
618# | / _----=> need-resched
619# || / _---=> hardirq/softirq
620# ||| / _--=> preempt-depth
621# |||| /
622# ||||| delay
623# cmd pid ||||| time | caller
624# \ / ||||| \ | /
Steven Rostedtf2d9c742008-07-15 10:57:33 -0400625 bash-3730 1d... 0us : _write_lock_irq (sys_setpgid)
626 bash-3730 1d..1 1us+: _write_unlock_irq (sys_setpgid)
627 bash-3730 1d..2 14us : trace_hardirqs_on (sys_setpgid)
Steven Rostedteb6d42e2008-07-10 12:46:01 -0400628
629
Steven Rostedtf2d9c742008-07-15 10:57:33 -0400630Here we see that that we had a latency of 12 microsecs (which is
Ingo Molnar57526742009-02-19 12:54:10 +0100631very good). The _write_lock_irq in sys_setpgid disabled
632interrupts. The difference between the 12 and the displayed
633timestamp 14us occurred because the clock was incremented
634between the time of recording the max latency and the time of
635recording the function that had that latency.
Steven Rostedteb6d42e2008-07-10 12:46:01 -0400636
Steven Rostedtf2d9c742008-07-15 10:57:33 -0400637Note the above example had ftrace_enabled not set. If we set the
638ftrace_enabled, we get a much larger output:
Steven Rostedteb6d42e2008-07-10 12:46:01 -0400639
640# tracer: irqsoff
641#
642irqsoff latency trace v1.1.5 on 2.6.26-rc8
643--------------------------------------------------------------------
644 latency: 50 us, #101/101, CPU#0 | (M:preempt VP:0, KP:0, SP:0 HP:0 #P:2)
645 -----------------
646 | task: ls-4339 (uid:0 nice:0 policy:0 rt_prio:0)
647 -----------------
648 => started at: __alloc_pages_internal
649 => ended at: __alloc_pages_internal
650
651# _------=> CPU#
652# / _-----=> irqs-off
653# | / _----=> need-resched
654# || / _---=> hardirq/softirq
655# ||| / _--=> preempt-depth
656# |||| /
657# ||||| delay
658# cmd pid ||||| time | caller
659# \ / ||||| \ | /
660 ls-4339 0...1 0us+: get_page_from_freelist (__alloc_pages_internal)
661 ls-4339 0d..1 3us : rmqueue_bulk (get_page_from_freelist)
662 ls-4339 0d..1 3us : _spin_lock (rmqueue_bulk)
663 ls-4339 0d..1 4us : add_preempt_count (_spin_lock)
664 ls-4339 0d..2 4us : __rmqueue (rmqueue_bulk)
665 ls-4339 0d..2 5us : __rmqueue_smallest (__rmqueue)
666 ls-4339 0d..2 5us : __mod_zone_page_state (__rmqueue_smallest)
667 ls-4339 0d..2 6us : __rmqueue (rmqueue_bulk)
668 ls-4339 0d..2 6us : __rmqueue_smallest (__rmqueue)
669 ls-4339 0d..2 7us : __mod_zone_page_state (__rmqueue_smallest)
670 ls-4339 0d..2 7us : __rmqueue (rmqueue_bulk)
671 ls-4339 0d..2 8us : __rmqueue_smallest (__rmqueue)
672[...]
673 ls-4339 0d..2 46us : __rmqueue_smallest (__rmqueue)
674 ls-4339 0d..2 47us : __mod_zone_page_state (__rmqueue_smallest)
675 ls-4339 0d..2 47us : __rmqueue (rmqueue_bulk)
676 ls-4339 0d..2 48us : __rmqueue_smallest (__rmqueue)
677 ls-4339 0d..2 48us : __mod_zone_page_state (__rmqueue_smallest)
678 ls-4339 0d..2 49us : _spin_unlock (rmqueue_bulk)
679 ls-4339 0d..2 49us : sub_preempt_count (_spin_unlock)
680 ls-4339 0d..1 50us : get_page_from_freelist (__alloc_pages_internal)
681 ls-4339 0d..2 51us : trace_hardirqs_on (__alloc_pages_internal)
682
683
Steven Rostedteb6d42e2008-07-10 12:46:01 -0400684
685Here we traced a 50 microsecond latency. But we also see all the
Ingo Molnar57526742009-02-19 12:54:10 +0100686functions that were called during that time. Note that by
687enabling function tracing, we incur an added overhead. This
688overhead may extend the latency times. But nevertheless, this
689trace has provided some very helpful debugging information.
Steven Rostedteb6d42e2008-07-10 12:46:01 -0400690
691
692preemptoff
693----------
694
Ingo Molnar57526742009-02-19 12:54:10 +0100695When preemption is disabled, we may be able to receive
696interrupts but the task cannot be preempted and a higher
697priority task must wait for preemption to be enabled again
698before it can preempt a lower priority task.
Steven Rostedteb6d42e2008-07-10 12:46:01 -0400699
Steven Rostedta41eeba2008-07-14 16:41:12 -0400700The preemptoff tracer traces the places that disable preemption.
Ingo Molnar57526742009-02-19 12:54:10 +0100701Like the irqsoff tracer, it records the maximum latency for
702which preemption was disabled. The control of preemptoff tracer
703is much like the irqsoff tracer.
Steven Rostedteb6d42e2008-07-10 12:46:01 -0400704
GeunSik Lim156f5a72009-06-02 15:01:37 +0900705 # echo preemptoff > current_tracer
706 # echo 0 > tracing_max_latency
707 # echo 1 > tracing_enabled
Steven Rostedteb6d42e2008-07-10 12:46:01 -0400708 # ls -ltr
709 [...]
GeunSik Lim156f5a72009-06-02 15:01:37 +0900710 # echo 0 > tracing_enabled
711 # cat latency_trace
Steven Rostedteb6d42e2008-07-10 12:46:01 -0400712# tracer: preemptoff
713#
714preemptoff latency trace v1.1.5 on 2.6.26-rc8
715--------------------------------------------------------------------
716 latency: 29 us, #3/3, CPU#0 | (M:preempt VP:0, KP:0, SP:0 HP:0 #P:2)
717 -----------------
718 | task: sshd-4261 (uid:0 nice:0 policy:0 rt_prio:0)
719 -----------------
720 => started at: do_IRQ
721 => ended at: __do_softirq
722
723# _------=> CPU#
724# / _-----=> irqs-off
725# | / _----=> need-resched
726# || / _---=> hardirq/softirq
727# ||| / _--=> preempt-depth
728# |||| /
729# ||||| delay
730# cmd pid ||||| time | caller
731# \ / ||||| \ | /
732 sshd-4261 0d.h. 0us+: irq_enter (do_IRQ)
733 sshd-4261 0d.s. 29us : _local_bh_enable (__do_softirq)
734 sshd-4261 0d.s1 30us : trace_preempt_on (__do_softirq)
735
736
Ingo Molnar57526742009-02-19 12:54:10 +0100737This has some more changes. Preemption was disabled when an
738interrupt came in (notice the 'h'), and was enabled while doing
739a softirq. (notice the 's'). But we also see that interrupts
740have been disabled when entering the preempt off section and
741leaving it (the 'd'). We do not know if interrupts were enabled
742in the mean time.
Steven Rostedteb6d42e2008-07-10 12:46:01 -0400743
744# tracer: preemptoff
745#
746preemptoff latency trace v1.1.5 on 2.6.26-rc8
747--------------------------------------------------------------------
748 latency: 63 us, #87/87, CPU#0 | (M:preempt VP:0, KP:0, SP:0 HP:0 #P:2)
749 -----------------
750 | task: sshd-4261 (uid:0 nice:0 policy:0 rt_prio:0)
751 -----------------
752 => started at: remove_wait_queue
753 => ended at: __do_softirq
754
755# _------=> CPU#
756# / _-----=> irqs-off
757# | / _----=> need-resched
758# || / _---=> hardirq/softirq
759# ||| / _--=> preempt-depth
760# |||| /
761# ||||| delay
762# cmd pid ||||| time | caller
763# \ / ||||| \ | /
764 sshd-4261 0d..1 0us : _spin_lock_irqsave (remove_wait_queue)
765 sshd-4261 0d..1 1us : _spin_unlock_irqrestore (remove_wait_queue)
766 sshd-4261 0d..1 2us : do_IRQ (common_interrupt)
767 sshd-4261 0d..1 2us : irq_enter (do_IRQ)
768 sshd-4261 0d..1 2us : idle_cpu (irq_enter)
769 sshd-4261 0d..1 3us : add_preempt_count (irq_enter)
770 sshd-4261 0d.h1 3us : idle_cpu (irq_enter)
771 sshd-4261 0d.h. 4us : handle_fasteoi_irq (do_IRQ)
772[...]
773 sshd-4261 0d.h. 12us : add_preempt_count (_spin_lock)
774 sshd-4261 0d.h1 12us : ack_ioapic_quirk_irq (handle_fasteoi_irq)
775 sshd-4261 0d.h1 13us : move_native_irq (ack_ioapic_quirk_irq)
776 sshd-4261 0d.h1 13us : _spin_unlock (handle_fasteoi_irq)
777 sshd-4261 0d.h1 14us : sub_preempt_count (_spin_unlock)
778 sshd-4261 0d.h1 14us : irq_exit (do_IRQ)
779 sshd-4261 0d.h1 15us : sub_preempt_count (irq_exit)
780 sshd-4261 0d..2 15us : do_softirq (irq_exit)
781 sshd-4261 0d... 15us : __do_softirq (do_softirq)
782 sshd-4261 0d... 16us : __local_bh_disable (__do_softirq)
783 sshd-4261 0d... 16us+: add_preempt_count (__local_bh_disable)
784 sshd-4261 0d.s4 20us : add_preempt_count (__local_bh_disable)
785 sshd-4261 0d.s4 21us : sub_preempt_count (local_bh_enable)
786 sshd-4261 0d.s5 21us : sub_preempt_count (local_bh_enable)
787[...]
788 sshd-4261 0d.s6 41us : add_preempt_count (__local_bh_disable)
789 sshd-4261 0d.s6 42us : sub_preempt_count (local_bh_enable)
790 sshd-4261 0d.s7 42us : sub_preempt_count (local_bh_enable)
791 sshd-4261 0d.s5 43us : add_preempt_count (__local_bh_disable)
792 sshd-4261 0d.s5 43us : sub_preempt_count (local_bh_enable_ip)
793 sshd-4261 0d.s6 44us : sub_preempt_count (local_bh_enable_ip)
794 sshd-4261 0d.s5 44us : add_preempt_count (__local_bh_disable)
795 sshd-4261 0d.s5 45us : sub_preempt_count (local_bh_enable)
796[...]
797 sshd-4261 0d.s. 63us : _local_bh_enable (__do_softirq)
798 sshd-4261 0d.s1 64us : trace_preempt_on (__do_softirq)
799
800
Ingo Molnar57526742009-02-19 12:54:10 +0100801The above is an example of the preemptoff trace with
802ftrace_enabled set. Here we see that interrupts were disabled
803the entire time. The irq_enter code lets us know that we entered
804an interrupt 'h'. Before that, the functions being traced still
805show that it is not in an interrupt, but we can see from the
806functions themselves that this is not the case.
Steven Rostedteb6d42e2008-07-10 12:46:01 -0400807
Ingo Molnar57526742009-02-19 12:54:10 +0100808Notice that __do_softirq when called does not have a
809preempt_count. It may seem that we missed a preempt enabling.
810What really happened is that the preempt count is held on the
811thread's stack and we switched to the softirq stack (4K stacks
812in effect). The code does not copy the preempt count, but
813because interrupts are disabled, we do not need to worry about
814it. Having a tracer like this is good for letting people know
815what really happens inside the kernel.
Steven Rostedteb6d42e2008-07-10 12:46:01 -0400816
817
818preemptirqsoff
819--------------
820
Ingo Molnar57526742009-02-19 12:54:10 +0100821Knowing the locations that have interrupts disabled or
822preemption disabled for the longest times is helpful. But
823sometimes we would like to know when either preemption and/or
824interrupts are disabled.
Steven Rostedteb6d42e2008-07-10 12:46:01 -0400825
Steven Rostedtf2d9c742008-07-15 10:57:33 -0400826Consider the following code:
Steven Rostedteb6d42e2008-07-10 12:46:01 -0400827
828 local_irq_disable();
829 call_function_with_irqs_off();
830 preempt_disable();
831 call_function_with_irqs_and_preemption_off();
832 local_irq_enable();
833 call_function_with_preemption_off();
834 preempt_enable();
835
836The irqsoff tracer will record the total length of
837call_function_with_irqs_off() and
838call_function_with_irqs_and_preemption_off().
839
840The preemptoff tracer will record the total length of
841call_function_with_irqs_and_preemption_off() and
842call_function_with_preemption_off().
843
Ingo Molnar57526742009-02-19 12:54:10 +0100844But neither will trace the time that interrupts and/or
845preemption is disabled. This total time is the time that we can
846not schedule. To record this time, use the preemptirqsoff
847tracer.
Steven Rostedteb6d42e2008-07-10 12:46:01 -0400848
Ingo Molnar57526742009-02-19 12:54:10 +0100849Again, using this trace is much like the irqsoff and preemptoff
850tracers.
Steven Rostedteb6d42e2008-07-10 12:46:01 -0400851
GeunSik Lim156f5a72009-06-02 15:01:37 +0900852 # echo preemptirqsoff > current_tracer
853 # echo 0 > tracing_max_latency
854 # echo 1 > tracing_enabled
Steven Rostedteb6d42e2008-07-10 12:46:01 -0400855 # ls -ltr
856 [...]
GeunSik Lim156f5a72009-06-02 15:01:37 +0900857 # echo 0 > tracing_enabled
858 # cat latency_trace
Steven Rostedteb6d42e2008-07-10 12:46:01 -0400859# tracer: preemptirqsoff
860#
861preemptirqsoff latency trace v1.1.5 on 2.6.26-rc8
862--------------------------------------------------------------------
863 latency: 293 us, #3/3, CPU#0 | (M:preempt VP:0, KP:0, SP:0 HP:0 #P:2)
864 -----------------
865 | task: ls-4860 (uid:0 nice:0 policy:0 rt_prio:0)
866 -----------------
867 => started at: apic_timer_interrupt
868 => ended at: __do_softirq
869
870# _------=> CPU#
871# / _-----=> irqs-off
872# | / _----=> need-resched
873# || / _---=> hardirq/softirq
874# ||| / _--=> preempt-depth
875# |||| /
876# ||||| delay
877# cmd pid ||||| time | caller
878# \ / ||||| \ | /
879 ls-4860 0d... 0us!: trace_hardirqs_off_thunk (apic_timer_interrupt)
880 ls-4860 0d.s. 294us : _local_bh_enable (__do_softirq)
881 ls-4860 0d.s1 294us : trace_preempt_on (__do_softirq)
882
883
Steven Rostedteb6d42e2008-07-10 12:46:01 -0400884
885The trace_hardirqs_off_thunk is called from assembly on x86 when
Ingo Molnar57526742009-02-19 12:54:10 +0100886interrupts are disabled in the assembly code. Without the
887function tracing, we do not know if interrupts were enabled
888within the preemption points. We do see that it started with
889preemption enabled.
Steven Rostedteb6d42e2008-07-10 12:46:01 -0400890
891Here is a trace with ftrace_enabled set:
892
893
894# tracer: preemptirqsoff
895#
896preemptirqsoff latency trace v1.1.5 on 2.6.26-rc8
897--------------------------------------------------------------------
898 latency: 105 us, #183/183, CPU#0 | (M:preempt VP:0, KP:0, SP:0 HP:0 #P:2)
899 -----------------
900 | task: sshd-4261 (uid:0 nice:0 policy:0 rt_prio:0)
901 -----------------
902 => started at: write_chan
903 => ended at: __do_softirq
904
905# _------=> CPU#
906# / _-----=> irqs-off
907# | / _----=> need-resched
908# || / _---=> hardirq/softirq
909# ||| / _--=> preempt-depth
910# |||| /
911# ||||| delay
912# cmd pid ||||| time | caller
913# \ / ||||| \ | /
914 ls-4473 0.N.. 0us : preempt_schedule (write_chan)
915 ls-4473 0dN.1 1us : _spin_lock (schedule)
916 ls-4473 0dN.1 2us : add_preempt_count (_spin_lock)
917 ls-4473 0d..2 2us : put_prev_task_fair (schedule)
918[...]
919 ls-4473 0d..2 13us : set_normalized_timespec (ktime_get_ts)
920 ls-4473 0d..2 13us : __switch_to (schedule)
921 sshd-4261 0d..2 14us : finish_task_switch (schedule)
922 sshd-4261 0d..2 14us : _spin_unlock_irq (finish_task_switch)
923 sshd-4261 0d..1 15us : add_preempt_count (_spin_lock_irqsave)
924 sshd-4261 0d..2 16us : _spin_unlock_irqrestore (hrtick_set)
925 sshd-4261 0d..2 16us : do_IRQ (common_interrupt)
926 sshd-4261 0d..2 17us : irq_enter (do_IRQ)
927 sshd-4261 0d..2 17us : idle_cpu (irq_enter)
928 sshd-4261 0d..2 18us : add_preempt_count (irq_enter)
929 sshd-4261 0d.h2 18us : idle_cpu (irq_enter)
930 sshd-4261 0d.h. 18us : handle_fasteoi_irq (do_IRQ)
931 sshd-4261 0d.h. 19us : _spin_lock (handle_fasteoi_irq)
932 sshd-4261 0d.h. 19us : add_preempt_count (_spin_lock)
933 sshd-4261 0d.h1 20us : _spin_unlock (handle_fasteoi_irq)
934 sshd-4261 0d.h1 20us : sub_preempt_count (_spin_unlock)
935[...]
936 sshd-4261 0d.h1 28us : _spin_unlock (handle_fasteoi_irq)
937 sshd-4261 0d.h1 29us : sub_preempt_count (_spin_unlock)
938 sshd-4261 0d.h2 29us : irq_exit (do_IRQ)
939 sshd-4261 0d.h2 29us : sub_preempt_count (irq_exit)
940 sshd-4261 0d..3 30us : do_softirq (irq_exit)
941 sshd-4261 0d... 30us : __do_softirq (do_softirq)
942 sshd-4261 0d... 31us : __local_bh_disable (__do_softirq)
943 sshd-4261 0d... 31us+: add_preempt_count (__local_bh_disable)
944 sshd-4261 0d.s4 34us : add_preempt_count (__local_bh_disable)
945[...]
946 sshd-4261 0d.s3 43us : sub_preempt_count (local_bh_enable_ip)
947 sshd-4261 0d.s4 44us : sub_preempt_count (local_bh_enable_ip)
948 sshd-4261 0d.s3 44us : smp_apic_timer_interrupt (apic_timer_interrupt)
949 sshd-4261 0d.s3 45us : irq_enter (smp_apic_timer_interrupt)
950 sshd-4261 0d.s3 45us : idle_cpu (irq_enter)
951 sshd-4261 0d.s3 46us : add_preempt_count (irq_enter)
952 sshd-4261 0d.H3 46us : idle_cpu (irq_enter)
953 sshd-4261 0d.H3 47us : hrtimer_interrupt (smp_apic_timer_interrupt)
954 sshd-4261 0d.H3 47us : ktime_get (hrtimer_interrupt)
955[...]
956 sshd-4261 0d.H3 81us : tick_program_event (hrtimer_interrupt)
957 sshd-4261 0d.H3 82us : ktime_get (tick_program_event)
958 sshd-4261 0d.H3 82us : ktime_get_ts (ktime_get)
959 sshd-4261 0d.H3 83us : getnstimeofday (ktime_get_ts)
960 sshd-4261 0d.H3 83us : set_normalized_timespec (ktime_get_ts)
961 sshd-4261 0d.H3 84us : clockevents_program_event (tick_program_event)
962 sshd-4261 0d.H3 84us : lapic_next_event (clockevents_program_event)
963 sshd-4261 0d.H3 85us : irq_exit (smp_apic_timer_interrupt)
964 sshd-4261 0d.H3 85us : sub_preempt_count (irq_exit)
965 sshd-4261 0d.s4 86us : sub_preempt_count (irq_exit)
966 sshd-4261 0d.s3 86us : add_preempt_count (__local_bh_disable)
967[...]
968 sshd-4261 0d.s1 98us : sub_preempt_count (net_rx_action)
969 sshd-4261 0d.s. 99us : add_preempt_count (_spin_lock_irq)
970 sshd-4261 0d.s1 99us+: _spin_unlock_irq (run_timer_softirq)
971 sshd-4261 0d.s. 104us : _local_bh_enable (__do_softirq)
972 sshd-4261 0d.s. 104us : sub_preempt_count (_local_bh_enable)
973 sshd-4261 0d.s. 105us : _local_bh_enable (__do_softirq)
974 sshd-4261 0d.s1 105us : trace_preempt_on (__do_softirq)
975
976
Ingo Molnar57526742009-02-19 12:54:10 +0100977This is a very interesting trace. It started with the preemption
978of the ls task. We see that the task had the "need_resched" bit
979set via the 'N' in the trace. Interrupts were disabled before
980the spin_lock at the beginning of the trace. We see that a
981schedule took place to run sshd. When the interrupts were
982enabled, we took an interrupt. On return from the interrupt
983handler, the softirq ran. We took another interrupt while
984running the softirq as we see from the capital 'H'.
Steven Rostedteb6d42e2008-07-10 12:46:01 -0400985
986
987wakeup
988------
989
Ingo Molnar57526742009-02-19 12:54:10 +0100990In a Real-Time environment it is very important to know the
991wakeup time it takes for the highest priority task that is woken
992up to the time that it executes. This is also known as "schedule
993latency". I stress the point that this is about RT tasks. It is
994also important to know the scheduling latency of non-RT tasks,
995but the average schedule latency is better for non-RT tasks.
996Tools like LatencyTop are more appropriate for such
997measurements.
Steven Rostedteb6d42e2008-07-10 12:46:01 -0400998
Steven Rostedta41eeba2008-07-14 16:41:12 -0400999Real-Time environments are interested in the worst case latency.
Ingo Molnar57526742009-02-19 12:54:10 +01001000That is the longest latency it takes for something to happen,
1001and not the average. We can have a very fast scheduler that may
1002only have a large latency once in a while, but that would not
1003work well with Real-Time tasks. The wakeup tracer was designed
1004to record the worst case wakeups of RT tasks. Non-RT tasks are
1005not recorded because the tracer only records one worst case and
1006tracing non-RT tasks that are unpredictable will overwrite the
1007worst case latency of RT tasks.
Steven Rostedteb6d42e2008-07-10 12:46:01 -04001008
Ingo Molnar57526742009-02-19 12:54:10 +01001009Since this tracer only deals with RT tasks, we will run this
1010slightly differently than we did with the previous tracers.
1011Instead of performing an 'ls', we will run 'sleep 1' under
1012'chrt' which changes the priority of the task.
Steven Rostedteb6d42e2008-07-10 12:46:01 -04001013
GeunSik Lim156f5a72009-06-02 15:01:37 +09001014 # echo wakeup > current_tracer
1015 # echo 0 > tracing_max_latency
1016 # echo 1 > tracing_enabled
Steven Rostedteb6d42e2008-07-10 12:46:01 -04001017 # chrt -f 5 sleep 1
GeunSik Lim156f5a72009-06-02 15:01:37 +09001018 # echo 0 > tracing_enabled
1019 # cat latency_trace
Steven Rostedteb6d42e2008-07-10 12:46:01 -04001020# tracer: wakeup
1021#
1022wakeup latency trace v1.1.5 on 2.6.26-rc8
1023--------------------------------------------------------------------
1024 latency: 4 us, #2/2, CPU#1 | (M:preempt VP:0, KP:0, SP:0 HP:0 #P:2)
1025 -----------------
1026 | task: sleep-4901 (uid:0 nice:0 policy:1 rt_prio:5)
1027 -----------------
1028
1029# _------=> CPU#
1030# / _-----=> irqs-off
1031# | / _----=> need-resched
1032# || / _---=> hardirq/softirq
1033# ||| / _--=> preempt-depth
1034# |||| /
1035# ||||| delay
1036# cmd pid ||||| time | caller
1037# \ / ||||| \ | /
1038 <idle>-0 1d.h4 0us+: try_to_wake_up (wake_up_process)
1039 <idle>-0 1d..4 4us : schedule (cpu_idle)
1040
1041
Ingo Molnar57526742009-02-19 12:54:10 +01001042Running this on an idle system, we see that it only took 4
1043microseconds to perform the task switch. Note, since the trace
1044marker in the schedule is before the actual "switch", we stop
1045the tracing when the recorded task is about to schedule in. This
1046may change if we add a new marker at the end of the scheduler.
Steven Rostedteb6d42e2008-07-10 12:46:01 -04001047
Ingo Molnar57526742009-02-19 12:54:10 +01001048Notice that the recorded task is 'sleep' with the PID of 4901
1049and it has an rt_prio of 5. This priority is user-space priority
1050and not the internal kernel priority. The policy is 1 for
1051SCHED_FIFO and 2 for SCHED_RR.
Steven Rostedteb6d42e2008-07-10 12:46:01 -04001052
1053Doing the same with chrt -r 5 and ftrace_enabled set.
1054
1055# tracer: wakeup
1056#
1057wakeup latency trace v1.1.5 on 2.6.26-rc8
1058--------------------------------------------------------------------
1059 latency: 50 us, #60/60, CPU#1 | (M:preempt VP:0, KP:0, SP:0 HP:0 #P:2)
1060 -----------------
1061 | task: sleep-4068 (uid:0 nice:0 policy:2 rt_prio:5)
1062 -----------------
1063
1064# _------=> CPU#
1065# / _-----=> irqs-off
1066# | / _----=> need-resched
1067# || / _---=> hardirq/softirq
1068# ||| / _--=> preempt-depth
1069# |||| /
1070# ||||| delay
1071# cmd pid ||||| time | caller
1072# \ / ||||| \ | /
1073ksoftirq-7 1d.H3 0us : try_to_wake_up (wake_up_process)
1074ksoftirq-7 1d.H4 1us : sub_preempt_count (marker_probe_cb)
1075ksoftirq-7 1d.H3 2us : check_preempt_wakeup (try_to_wake_up)
1076ksoftirq-7 1d.H3 3us : update_curr (check_preempt_wakeup)
1077ksoftirq-7 1d.H3 4us : calc_delta_mine (update_curr)
1078ksoftirq-7 1d.H3 5us : __resched_task (check_preempt_wakeup)
1079ksoftirq-7 1d.H3 6us : task_wake_up_rt (try_to_wake_up)
1080ksoftirq-7 1d.H3 7us : _spin_unlock_irqrestore (try_to_wake_up)
1081[...]
1082ksoftirq-7 1d.H2 17us : irq_exit (smp_apic_timer_interrupt)
1083ksoftirq-7 1d.H2 18us : sub_preempt_count (irq_exit)
1084ksoftirq-7 1d.s3 19us : sub_preempt_count (irq_exit)
1085ksoftirq-7 1..s2 20us : rcu_process_callbacks (__do_softirq)
1086[...]
1087ksoftirq-7 1..s2 26us : __rcu_process_callbacks (rcu_process_callbacks)
1088ksoftirq-7 1d.s2 27us : _local_bh_enable (__do_softirq)
1089ksoftirq-7 1d.s2 28us : sub_preempt_count (_local_bh_enable)
1090ksoftirq-7 1.N.3 29us : sub_preempt_count (ksoftirqd)
1091ksoftirq-7 1.N.2 30us : _cond_resched (ksoftirqd)
1092ksoftirq-7 1.N.2 31us : __cond_resched (_cond_resched)
1093ksoftirq-7 1.N.2 32us : add_preempt_count (__cond_resched)
1094ksoftirq-7 1.N.2 33us : schedule (__cond_resched)
1095ksoftirq-7 1.N.2 33us : add_preempt_count (schedule)
1096ksoftirq-7 1.N.3 34us : hrtick_clear (schedule)
1097ksoftirq-7 1dN.3 35us : _spin_lock (schedule)
1098ksoftirq-7 1dN.3 36us : add_preempt_count (_spin_lock)
1099ksoftirq-7 1d..4 37us : put_prev_task_fair (schedule)
1100ksoftirq-7 1d..4 38us : update_curr (put_prev_task_fair)
1101[...]
1102ksoftirq-7 1d..5 47us : _spin_trylock (tracing_record_cmdline)
1103ksoftirq-7 1d..5 48us : add_preempt_count (_spin_trylock)
1104ksoftirq-7 1d..6 49us : _spin_unlock (tracing_record_cmdline)
1105ksoftirq-7 1d..6 49us : sub_preempt_count (_spin_unlock)
1106ksoftirq-7 1d..4 50us : schedule (__cond_resched)
1107
Ingo Molnar57526742009-02-19 12:54:10 +01001108The interrupt went off while running ksoftirqd. This task runs
1109at SCHED_OTHER. Why did not we see the 'N' set early? This may
1110be a harmless bug with x86_32 and 4K stacks. On x86_32 with 4K
1111stacks configured, the interrupt and softirq run with their own
1112stack. Some information is held on the top of the task's stack
1113(need_resched and preempt_count are both stored there). The
1114setting of the NEED_RESCHED bit is done directly to the task's
1115stack, but the reading of the NEED_RESCHED is done by looking at
1116the current stack, which in this case is the stack for the hard
1117interrupt. This hides the fact that NEED_RESCHED has been set.
1118We do not see the 'N' until we switch back to the task's
Steven Rostedta41eeba2008-07-14 16:41:12 -04001119assigned stack.
Steven Rostedteb6d42e2008-07-10 12:46:01 -04001120
Steven Rostedt9b803c02008-11-03 15:15:08 -05001121function
1122--------
Steven Rostedteb6d42e2008-07-10 12:46:01 -04001123
Steven Rostedt9b803c02008-11-03 15:15:08 -05001124This tracer is the function tracer. Enabling the function tracer
Ingo Molnar57526742009-02-19 12:54:10 +01001125can be done from the debug file system. Make sure the
1126ftrace_enabled is set; otherwise this tracer is a nop.
Steven Rostedteb6d42e2008-07-10 12:46:01 -04001127
1128 # sysctl kernel.ftrace_enabled=1
GeunSik Lim156f5a72009-06-02 15:01:37 +09001129 # echo function > current_tracer
1130 # echo 1 > tracing_enabled
Steven Rostedteb6d42e2008-07-10 12:46:01 -04001131 # usleep 1
GeunSik Lim156f5a72009-06-02 15:01:37 +09001132 # echo 0 > tracing_enabled
1133 # cat trace
Steven Rostedt9b803c02008-11-03 15:15:08 -05001134# tracer: function
Steven Rostedteb6d42e2008-07-10 12:46:01 -04001135#
1136# TASK-PID CPU# TIMESTAMP FUNCTION
1137# | | | | |
1138 bash-4003 [00] 123.638713: finish_task_switch <-schedule
1139 bash-4003 [00] 123.638714: _spin_unlock_irq <-finish_task_switch
1140 bash-4003 [00] 123.638714: sub_preempt_count <-_spin_unlock_irq
1141 bash-4003 [00] 123.638715: hrtick_set <-schedule
1142 bash-4003 [00] 123.638715: _spin_lock_irqsave <-hrtick_set
1143 bash-4003 [00] 123.638716: add_preempt_count <-_spin_lock_irqsave
1144 bash-4003 [00] 123.638716: _spin_unlock_irqrestore <-hrtick_set
1145 bash-4003 [00] 123.638717: sub_preempt_count <-_spin_unlock_irqrestore
1146 bash-4003 [00] 123.638717: hrtick_clear <-hrtick_set
1147 bash-4003 [00] 123.638718: sub_preempt_count <-schedule
1148 bash-4003 [00] 123.638718: sub_preempt_count <-preempt_schedule
1149 bash-4003 [00] 123.638719: wait_for_completion <-__stop_machine_run
1150 bash-4003 [00] 123.638719: wait_for_common <-wait_for_completion
1151 bash-4003 [00] 123.638720: _spin_lock_irq <-wait_for_common
1152 bash-4003 [00] 123.638720: add_preempt_count <-_spin_lock_irq
1153[...]
1154
1155
Ingo Molnar57526742009-02-19 12:54:10 +01001156Note: function tracer uses ring buffers to store the above
1157entries. The newest data may overwrite the oldest data.
1158Sometimes using echo to stop the trace is not sufficient because
1159the tracing could have overwritten the data that you wanted to
1160record. For this reason, it is sometimes better to disable
1161tracing directly from a program. This allows you to stop the
1162tracing at the point that you hit the part that you are
1163interested in. To disable the tracing directly from a C program,
1164something like following code snippet can be used:
Steven Rostedteb6d42e2008-07-10 12:46:01 -04001165
1166int trace_fd;
1167[...]
1168int main(int argc, char *argv[]) {
1169 [...]
GeunSik Lim156f5a72009-06-02 15:01:37 +09001170 trace_fd = open(tracing_file("tracing_enabled"), O_WRONLY);
Steven Rostedteb6d42e2008-07-10 12:46:01 -04001171 [...]
1172 if (condition_hit()) {
Steven Rostedtf2d9c742008-07-15 10:57:33 -04001173 write(trace_fd, "0", 1);
Steven Rostedteb6d42e2008-07-10 12:46:01 -04001174 }
1175 [...]
1176}
1177
Steven Rostedtdf4fc312008-11-26 00:16:23 -05001178
1179Single thread tracing
1180---------------------
1181
GeunSik Lim156f5a72009-06-02 15:01:37 +09001182By writing into set_ftrace_pid you can trace a
Steven Rostedtdf4fc312008-11-26 00:16:23 -05001183single thread. For example:
1184
GeunSik Lim156f5a72009-06-02 15:01:37 +09001185# cat set_ftrace_pid
Steven Rostedtdf4fc312008-11-26 00:16:23 -05001186no pid
GeunSik Lim156f5a72009-06-02 15:01:37 +09001187# echo 3111 > set_ftrace_pid
1188# cat set_ftrace_pid
Steven Rostedtdf4fc312008-11-26 00:16:23 -050011893111
GeunSik Lim156f5a72009-06-02 15:01:37 +09001190# echo function > current_tracer
1191# cat trace | head
Steven Rostedtdf4fc312008-11-26 00:16:23 -05001192 # tracer: function
1193 #
1194 # TASK-PID CPU# TIMESTAMP FUNCTION
1195 # | | | | |
1196 yum-updatesd-3111 [003] 1637.254676: finish_task_switch <-thread_return
1197 yum-updatesd-3111 [003] 1637.254681: hrtimer_cancel <-schedule_hrtimeout_range
1198 yum-updatesd-3111 [003] 1637.254682: hrtimer_try_to_cancel <-hrtimer_cancel
1199 yum-updatesd-3111 [003] 1637.254683: lock_hrtimer_base <-hrtimer_try_to_cancel
1200 yum-updatesd-3111 [003] 1637.254685: fget_light <-do_sys_poll
1201 yum-updatesd-3111 [003] 1637.254686: pipe_poll <-do_sys_poll
GeunSik Lim156f5a72009-06-02 15:01:37 +09001202# echo -1 > set_ftrace_pid
1203# cat trace |head
Steven Rostedtdf4fc312008-11-26 00:16:23 -05001204 # tracer: function
1205 #
1206 # TASK-PID CPU# TIMESTAMP FUNCTION
1207 # | | | | |
1208 ##### CPU 3 buffer started ####
1209 yum-updatesd-3111 [003] 1701.957688: free_poll_entry <-poll_freewait
1210 yum-updatesd-3111 [003] 1701.957689: remove_wait_queue <-free_poll_entry
1211 yum-updatesd-3111 [003] 1701.957691: fput <-free_poll_entry
1212 yum-updatesd-3111 [003] 1701.957692: audit_syscall_exit <-sysret_audit
1213 yum-updatesd-3111 [003] 1701.957693: path_put <-audit_syscall_exit
1214
1215If you want to trace a function when executing, you could use
1216something like this simple program:
1217
1218#include <stdio.h>
1219#include <stdlib.h>
1220#include <sys/types.h>
1221#include <sys/stat.h>
1222#include <fcntl.h>
1223#include <unistd.h>
1224
GeunSik Lim156f5a72009-06-02 15:01:37 +09001225#define _STR(x) #x
1226#define STR(x) _STR(x)
1227#define MAX_PATH 256
1228
1229const char *find_debugfs(void)
1230{
1231 static char debugfs[MAX_PATH+1];
1232 static int debugfs_found;
1233 char type[100];
1234 FILE *fp;
1235
1236 if (debugfs_found)
1237 return debugfs;
1238
1239 if ((fp = fopen("/proc/mounts","r")) == NULL) {
1240 perror("/proc/mounts");
1241 return NULL;
1242 }
1243
1244 while (fscanf(fp, "%*s %"
1245 STR(MAX_PATH)
1246 "s %99s %*s %*d %*d\n",
1247 debugfs, type) == 2) {
1248 if (strcmp(type, "debugfs") == 0)
1249 break;
1250 }
1251 fclose(fp);
1252
1253 if (strcmp(type, "debugfs") != 0) {
1254 fprintf(stderr, "debugfs not mounted");
1255 return NULL;
1256 }
1257
1258 debugfs_found = 1;
1259
1260 return debugfs;
1261}
1262
1263const char *tracing_file(const char *file_name)
1264{
1265 static char trace_file[MAX_PATH+1];
1266 snprintf(trace_file, MAX_PATH, "%s/%s", find_debugfs(), file_name);
1267 return trace_file;
1268}
1269
Steven Rostedtdf4fc312008-11-26 00:16:23 -05001270int main (int argc, char **argv)
1271{
1272 if (argc < 1)
1273 exit(-1);
1274
1275 if (fork() > 0) {
1276 int fd, ffd;
1277 char line[64];
1278 int s;
1279
GeunSik Lim156f5a72009-06-02 15:01:37 +09001280 ffd = open(tracing_file("current_tracer"), O_WRONLY);
Steven Rostedtdf4fc312008-11-26 00:16:23 -05001281 if (ffd < 0)
1282 exit(-1);
1283 write(ffd, "nop", 3);
1284
GeunSik Lim156f5a72009-06-02 15:01:37 +09001285 fd = open(tracing_file("set_ftrace_pid"), O_WRONLY);
Steven Rostedtdf4fc312008-11-26 00:16:23 -05001286 s = sprintf(line, "%d\n", getpid());
1287 write(fd, line, s);
1288
1289 write(ffd, "function", 8);
1290
1291 close(fd);
1292 close(ffd);
1293
1294 execvp(argv[1], argv+1);
1295 }
1296
1297 return 0;
1298}
1299
Markus Metzgere2ea5392009-01-19 10:35:58 +01001300
1301hw-branch-tracer (x86 only)
1302---------------------------
1303
1304This tracer uses the x86 last branch tracing hardware feature to
1305collect a branch trace on all cpus with relatively low overhead.
1306
1307The tracer uses a fixed-size circular buffer per cpu and only
1308traces ring 0 branches. The trace file dumps that buffer in the
1309following format:
1310
1311# tracer: hw-branch-tracer
1312#
1313# CPU# TO <- FROM
1314 0 scheduler_tick+0xb5/0x1bf <- task_tick_idle+0x5/0x6
1315 2 run_posix_cpu_timers+0x2b/0x72a <- run_posix_cpu_timers+0x25/0x72a
1316 0 scheduler_tick+0x139/0x1bf <- scheduler_tick+0xed/0x1bf
1317 0 scheduler_tick+0x17c/0x1bf <- scheduler_tick+0x148/0x1bf
1318 2 run_posix_cpu_timers+0x9e/0x72a <- run_posix_cpu_timers+0x5e/0x72a
1319 0 scheduler_tick+0x1b6/0x1bf <- scheduler_tick+0x1aa/0x1bf
1320
1321
Ingo Molnar57526742009-02-19 12:54:10 +01001322The tracer may be used to dump the trace for the oops'ing cpu on
1323a kernel oops into the system log. To enable this,
1324ftrace_dump_on_oops must be set. To set ftrace_dump_on_oops, one
1325can either use the sysctl function or set it via the proc system
1326interface.
Markus Metzgere2ea5392009-01-19 10:35:58 +01001327
1328 sysctl kernel.ftrace_dump_on_oops=1
1329
1330or
1331
1332 echo 1 > /proc/sys/kernel/ftrace_dump_on_oops
1333
1334
Ingo Molnar57526742009-02-19 12:54:10 +01001335Here's an example of such a dump after a null pointer
1336dereference in a kernel module:
Markus Metzgere2ea5392009-01-19 10:35:58 +01001337
1338[57848.105921] BUG: unable to handle kernel NULL pointer dereference at 0000000000000000
1339[57848.106019] IP: [<ffffffffa0000006>] open+0x6/0x14 [oops]
1340[57848.106019] PGD 2354e9067 PUD 2375e7067 PMD 0
1341[57848.106019] Oops: 0002 [#1] SMP
1342[57848.106019] last sysfs file: /sys/devices/pci0000:00/0000:00:1e.0/0000:20:05.0/local_cpus
1343[57848.106019] Dumping ftrace buffer:
1344[57848.106019] ---------------------------------
1345[...]
1346[57848.106019] 0 chrdev_open+0xe6/0x165 <- cdev_put+0x23/0x24
1347[57848.106019] 0 chrdev_open+0x117/0x165 <- chrdev_open+0xfa/0x165
1348[57848.106019] 0 chrdev_open+0x120/0x165 <- chrdev_open+0x11c/0x165
1349[57848.106019] 0 chrdev_open+0x134/0x165 <- chrdev_open+0x12b/0x165
1350[57848.106019] 0 open+0x0/0x14 [oops] <- chrdev_open+0x144/0x165
1351[57848.106019] 0 page_fault+0x0/0x30 <- open+0x6/0x14 [oops]
1352[57848.106019] 0 error_entry+0x0/0x5b <- page_fault+0x4/0x30
1353[57848.106019] 0 error_kernelspace+0x0/0x31 <- error_entry+0x59/0x5b
1354[57848.106019] 0 error_sti+0x0/0x1 <- error_kernelspace+0x2d/0x31
1355[57848.106019] 0 page_fault+0x9/0x30 <- error_sti+0x0/0x1
1356[57848.106019] 0 do_page_fault+0x0/0x881 <- page_fault+0x1a/0x30
1357[...]
1358[57848.106019] 0 do_page_fault+0x66b/0x881 <- is_prefetch+0x1ee/0x1f2
1359[57848.106019] 0 do_page_fault+0x6e0/0x881 <- do_page_fault+0x67a/0x881
1360[57848.106019] 0 oops_begin+0x0/0x96 <- do_page_fault+0x6e0/0x881
1361[57848.106019] 0 trace_hw_branch_oops+0x0/0x2d <- oops_begin+0x9/0x96
1362[...]
1363[57848.106019] 0 ds_suspend_bts+0x2a/0xe3 <- ds_suspend_bts+0x1a/0xe3
1364[57848.106019] ---------------------------------
1365[57848.106019] CPU 0
1366[57848.106019] Modules linked in: oops
1367[57848.106019] Pid: 5542, comm: cat Tainted: G W 2.6.28 #23
1368[57848.106019] RIP: 0010:[<ffffffffa0000006>] [<ffffffffa0000006>] open+0x6/0x14 [oops]
1369[57848.106019] RSP: 0018:ffff880235457d48 EFLAGS: 00010246
1370[...]
1371
1372
Frederic Weisbecker985ec202009-02-18 06:35:34 +01001373function graph tracer
1374---------------------------
1375
Ingo Molnar57526742009-02-19 12:54:10 +01001376This tracer is similar to the function tracer except that it
1377probes a function on its entry and its exit. This is done by
1378using a dynamically allocated stack of return addresses in each
1379task_struct. On function entry the tracer overwrites the return
1380address of each function traced to set a custom probe. Thus the
1381original return address is stored on the stack of return address
1382in the task_struct.
Frederic Weisbecker985ec202009-02-18 06:35:34 +01001383
Ingo Molnar57526742009-02-19 12:54:10 +01001384Probing on both ends of a function leads to special features
1385such as:
Frederic Weisbecker985ec202009-02-18 06:35:34 +01001386
Ingo Molnar57526742009-02-19 12:54:10 +01001387- measure of a function's time execution
1388- having a reliable call stack to draw function calls graph
Frederic Weisbecker985ec202009-02-18 06:35:34 +01001389
1390This tracer is useful in several situations:
1391
Ingo Molnar57526742009-02-19 12:54:10 +01001392- you want to find the reason of a strange kernel behavior and
1393 need to see what happens in detail on any areas (or specific
1394 ones).
1395
1396- you are experiencing weird latencies but it's difficult to
1397 find its origin.
1398
1399- you want to find quickly which path is taken by a specific
1400 function
1401
1402- you just want to peek inside a working kernel and want to see
1403 what happens there.
Frederic Weisbecker985ec202009-02-18 06:35:34 +01001404
1405# tracer: function_graph
1406#
1407# CPU DURATION FUNCTION CALLS
1408# | | | | | | |
1409
1410 0) | sys_open() {
1411 0) | do_sys_open() {
1412 0) | getname() {
1413 0) | kmem_cache_alloc() {
1414 0) 1.382 us | __might_sleep();
1415 0) 2.478 us | }
1416 0) | strncpy_from_user() {
1417 0) | might_fault() {
1418 0) 1.389 us | __might_sleep();
1419 0) 2.553 us | }
1420 0) 3.807 us | }
1421 0) 7.876 us | }
1422 0) | alloc_fd() {
1423 0) 0.668 us | _spin_lock();
1424 0) 0.570 us | expand_files();
1425 0) 0.586 us | _spin_unlock();
1426
1427
Ingo Molnar57526742009-02-19 12:54:10 +01001428There are several columns that can be dynamically
1429enabled/disabled. You can use every combination of options you
1430want, depending on your needs.
Frederic Weisbecker985ec202009-02-18 06:35:34 +01001431
Ingo Molnar57526742009-02-19 12:54:10 +01001432- The cpu number on which the function executed is default
1433 enabled. It is sometimes better to only trace one cpu (see
1434 tracing_cpu_mask file) or you might sometimes see unordered
1435 function calls while cpu tracing switch.
Frederic Weisbecker985ec202009-02-18 06:35:34 +01001436
GeunSik Lim156f5a72009-06-02 15:01:37 +09001437 hide: echo nofuncgraph-cpu > trace_options
1438 show: echo funcgraph-cpu > trace_options
Frederic Weisbecker985ec202009-02-18 06:35:34 +01001439
Ingo Molnar57526742009-02-19 12:54:10 +01001440- The duration (function's time of execution) is displayed on
1441 the closing bracket line of a function or on the same line
1442 than the current function in case of a leaf one. It is default
1443 enabled.
Frederic Weisbecker985ec202009-02-18 06:35:34 +01001444
GeunSik Lim156f5a72009-06-02 15:01:37 +09001445 hide: echo nofuncgraph-duration > trace_options
1446 show: echo funcgraph-duration > trace_options
Frederic Weisbecker985ec202009-02-18 06:35:34 +01001447
Ingo Molnar57526742009-02-19 12:54:10 +01001448- The overhead field precedes the duration field in case of
1449 reached duration thresholds.
Frederic Weisbecker985ec202009-02-18 06:35:34 +01001450
GeunSik Lim156f5a72009-06-02 15:01:37 +09001451 hide: echo nofuncgraph-overhead > trace_options
1452 show: echo funcgraph-overhead > trace_options
Frederic Weisbecker985ec202009-02-18 06:35:34 +01001453 depends on: funcgraph-duration
1454
1455 ie:
1456
1457 0) | up_write() {
1458 0) 0.646 us | _spin_lock_irqsave();
1459 0) 0.684 us | _spin_unlock_irqrestore();
1460 0) 3.123 us | }
1461 0) 0.548 us | fput();
1462 0) + 58.628 us | }
1463
1464 [...]
1465
1466 0) | putname() {
1467 0) | kmem_cache_free() {
1468 0) 0.518 us | __phys_addr();
1469 0) 1.757 us | }
1470 0) 2.861 us | }
1471 0) ! 115.305 us | }
1472 0) ! 116.402 us | }
1473
1474 + means that the function exceeded 10 usecs.
1475 ! means that the function exceeded 100 usecs.
1476
1477
Ingo Molnar57526742009-02-19 12:54:10 +01001478- The task/pid field displays the thread cmdline and pid which
1479 executed the function. It is default disabled.
Frederic Weisbecker985ec202009-02-18 06:35:34 +01001480
GeunSik Lim156f5a72009-06-02 15:01:37 +09001481 hide: echo nofuncgraph-proc > trace_options
1482 show: echo funcgraph-proc > trace_options
Frederic Weisbecker985ec202009-02-18 06:35:34 +01001483
1484 ie:
1485
1486 # tracer: function_graph
1487 #
1488 # CPU TASK/PID DURATION FUNCTION CALLS
1489 # | | | | | | | | |
1490 0) sh-4802 | | d_free() {
1491 0) sh-4802 | | call_rcu() {
1492 0) sh-4802 | | __call_rcu() {
1493 0) sh-4802 | 0.616 us | rcu_process_gp_end();
1494 0) sh-4802 | 0.586 us | check_for_new_grace_period();
1495 0) sh-4802 | 2.899 us | }
1496 0) sh-4802 | 4.040 us | }
1497 0) sh-4802 | 5.151 us | }
1498 0) sh-4802 | + 49.370 us | }
1499
1500
Ingo Molnar57526742009-02-19 12:54:10 +01001501- The absolute time field is an absolute timestamp given by the
1502 system clock since it started. A snapshot of this time is
1503 given on each entry/exit of functions
Frederic Weisbecker985ec202009-02-18 06:35:34 +01001504
GeunSik Lim156f5a72009-06-02 15:01:37 +09001505 hide: echo nofuncgraph-abstime > trace_options
1506 show: echo funcgraph-abstime > trace_options
Frederic Weisbecker985ec202009-02-18 06:35:34 +01001507
1508 ie:
1509
1510 #
1511 # TIME CPU DURATION FUNCTION CALLS
1512 # | | | | | | | |
1513 360.774522 | 1) 0.541 us | }
1514 360.774522 | 1) 4.663 us | }
1515 360.774523 | 1) 0.541 us | __wake_up_bit();
1516 360.774524 | 1) 6.796 us | }
1517 360.774524 | 1) 7.952 us | }
1518 360.774525 | 1) 9.063 us | }
1519 360.774525 | 1) 0.615 us | journal_mark_dirty();
1520 360.774527 | 1) 0.578 us | __brelse();
1521 360.774528 | 1) | reiserfs_prepare_for_journal() {
1522 360.774528 | 1) | unlock_buffer() {
1523 360.774529 | 1) | wake_up_bit() {
1524 360.774529 | 1) | bit_waitqueue() {
1525 360.774530 | 1) 0.594 us | __phys_addr();
1526
1527
Ingo Molnar57526742009-02-19 12:54:10 +01001528You can put some comments on specific functions by using
Ingo Molnar5e1607a2009-03-05 10:24:48 +01001529trace_printk() For example, if you want to put a comment inside
Ingo Molnar57526742009-02-19 12:54:10 +01001530the __might_sleep() function, you just have to include
Ingo Molnar5e1607a2009-03-05 10:24:48 +01001531<linux/ftrace.h> and call trace_printk() inside __might_sleep()
Frederic Weisbecker985ec202009-02-18 06:35:34 +01001532
Ingo Molnar5e1607a2009-03-05 10:24:48 +01001533trace_printk("I'm a comment!\n")
Frederic Weisbecker985ec202009-02-18 06:35:34 +01001534
1535will produce:
1536
1537 1) | __might_sleep() {
1538 1) | /* I'm a comment! */
1539 1) 1.449 us | }
1540
1541
Ingo Molnar57526742009-02-19 12:54:10 +01001542You might find other useful features for this tracer in the
1543following "dynamic ftrace" section such as tracing only specific
1544functions or tasks.
Frederic Weisbecker985ec202009-02-18 06:35:34 +01001545
Steven Rostedteb6d42e2008-07-10 12:46:01 -04001546dynamic ftrace
1547--------------
1548
Steven Rostedtf2d9c742008-07-15 10:57:33 -04001549If CONFIG_DYNAMIC_FTRACE is set, the system will run with
Steven Rostedteb6d42e2008-07-10 12:46:01 -04001550virtually no overhead when function tracing is disabled. The way
1551this works is the mcount function call (placed at the start of
Ingo Molnar57526742009-02-19 12:54:10 +01001552every kernel function, produced by the -pg switch in gcc),
1553starts of pointing to a simple return. (Enabling FTRACE will
1554include the -pg switch in the compiling of the kernel.)
Steven Rostedteb6d42e2008-07-10 12:46:01 -04001555
Steven Rostedt9b803c02008-11-03 15:15:08 -05001556At compile time every C file object is run through the
1557recordmcount.pl script (located in the scripts directory). This
1558script will process the C object using objdump to find all the
Ingo Molnar57526742009-02-19 12:54:10 +01001559locations in the .text section that call mcount. (Note, only the
1560.text section is processed, since processing other sections like
1561.init.text may cause races due to those sections being freed).
Steven Rostedteb6d42e2008-07-10 12:46:01 -04001562
Ingo Molnar57526742009-02-19 12:54:10 +01001563A new section called "__mcount_loc" is created that holds
1564references to all the mcount call sites in the .text section.
1565This section is compiled back into the original object. The
1566final linker will add all these references into a single table.
Steven Rostedt9b803c02008-11-03 15:15:08 -05001567
1568On boot up, before SMP is initialized, the dynamic ftrace code
Ingo Molnar57526742009-02-19 12:54:10 +01001569scans this table and updates all the locations into nops. It
1570also records the locations, which are added to the
1571available_filter_functions list. Modules are processed as they
1572are loaded and before they are executed. When a module is
1573unloaded, it also removes its functions from the ftrace function
1574list. This is automatic in the module unload code, and the
1575module author does not need to worry about it.
Steven Rostedt9b803c02008-11-03 15:15:08 -05001576
Ingo Molnar57526742009-02-19 12:54:10 +01001577When tracing is enabled, kstop_machine is called to prevent
1578races with the CPUS executing code being modified (which can
1579cause the CPU to do undesireable things), and the nops are
1580patched back to calls. But this time, they do not call mcount
1581(which is just a function stub). They now call into the ftrace
1582infrastructure.
Steven Rostedteb6d42e2008-07-10 12:46:01 -04001583
1584One special side-effect to the recording of the functions being
Steven Rostedtf2d9c742008-07-15 10:57:33 -04001585traced is that we can now selectively choose which functions we
Ingo Molnar57526742009-02-19 12:54:10 +01001586wish to trace and which ones we want the mcount calls to remain
1587as nops.
Steven Rostedteb6d42e2008-07-10 12:46:01 -04001588
Ingo Molnar57526742009-02-19 12:54:10 +01001589Two files are used, one for enabling and one for disabling the
1590tracing of specified functions. They are:
Steven Rostedteb6d42e2008-07-10 12:46:01 -04001591
1592 set_ftrace_filter
1593
1594and
1595
1596 set_ftrace_notrace
1597
Ingo Molnar57526742009-02-19 12:54:10 +01001598A list of available functions that you can add to these files is
1599listed in:
Steven Rostedteb6d42e2008-07-10 12:46:01 -04001600
1601 available_filter_functions
1602
GeunSik Lim156f5a72009-06-02 15:01:37 +09001603 # cat available_filter_functions
Steven Rostedteb6d42e2008-07-10 12:46:01 -04001604put_prev_task_idle
1605kmem_cache_create
1606pick_next_task_rt
1607get_online_cpus
1608pick_next_task_fair
1609mutex_lock
1610[...]
1611
Steven Rostedtf2d9c742008-07-15 10:57:33 -04001612If I am only interested in sys_nanosleep and hrtimer_interrupt:
Steven Rostedteb6d42e2008-07-10 12:46:01 -04001613
1614 # echo sys_nanosleep hrtimer_interrupt \
GeunSik Lim156f5a72009-06-02 15:01:37 +09001615 > set_ftrace_filter
1616 # echo ftrace > current_tracer
1617 # echo 1 > tracing_enabled
Steven Rostedteb6d42e2008-07-10 12:46:01 -04001618 # usleep 1
GeunSik Lim156f5a72009-06-02 15:01:37 +09001619 # echo 0 > tracing_enabled
1620 # cat trace
Steven Rostedteb6d42e2008-07-10 12:46:01 -04001621# tracer: ftrace
1622#
1623# TASK-PID CPU# TIMESTAMP FUNCTION
1624# | | | | |
1625 usleep-4134 [00] 1317.070017: hrtimer_interrupt <-smp_apic_timer_interrupt
1626 usleep-4134 [00] 1317.070111: sys_nanosleep <-syscall_call
1627 <idle>-0 [00] 1317.070115: hrtimer_interrupt <-smp_apic_timer_interrupt
1628
Steven Rostedtf2d9c742008-07-15 10:57:33 -04001629To see which functions are being traced, you can cat the file:
Steven Rostedteb6d42e2008-07-10 12:46:01 -04001630
GeunSik Lim156f5a72009-06-02 15:01:37 +09001631 # cat set_ftrace_filter
Steven Rostedteb6d42e2008-07-10 12:46:01 -04001632hrtimer_interrupt
1633sys_nanosleep
1634
1635
Ingo Molnar57526742009-02-19 12:54:10 +01001636Perhaps this is not enough. The filters also allow simple wild
1637cards. Only the following are currently available
Steven Rostedteb6d42e2008-07-10 12:46:01 -04001638
Steven Rostedta41eeba2008-07-14 16:41:12 -04001639 <match>* - will match functions that begin with <match>
Steven Rostedteb6d42e2008-07-10 12:46:01 -04001640 *<match> - will match functions that end with <match>
1641 *<match>* - will match functions that have <match> in it
1642
Steven Rostedtf2d9c742008-07-15 10:57:33 -04001643These are the only wild cards which are supported.
Steven Rostedteb6d42e2008-07-10 12:46:01 -04001644
1645 <match>*<match> will not work.
1646
Ingo Molnar57526742009-02-19 12:54:10 +01001647Note: It is better to use quotes to enclose the wild cards,
1648 otherwise the shell may expand the parameters into names
1649 of files in the local directory.
walimisc072c242008-11-28 12:21:19 +08001650
GeunSik Lim156f5a72009-06-02 15:01:37 +09001651 # echo 'hrtimer_*' > set_ftrace_filter
Steven Rostedteb6d42e2008-07-10 12:46:01 -04001652
1653Produces:
1654
1655# tracer: ftrace
1656#
1657# TASK-PID CPU# TIMESTAMP FUNCTION
1658# | | | | |
1659 bash-4003 [00] 1480.611794: hrtimer_init <-copy_process
1660 bash-4003 [00] 1480.611941: hrtimer_start <-hrtick_set
1661 bash-4003 [00] 1480.611956: hrtimer_cancel <-hrtick_clear
1662 bash-4003 [00] 1480.611956: hrtimer_try_to_cancel <-hrtimer_cancel
1663 <idle>-0 [00] 1480.612019: hrtimer_get_next_event <-get_next_timer_interrupt
1664 <idle>-0 [00] 1480.612025: hrtimer_get_next_event <-get_next_timer_interrupt
1665 <idle>-0 [00] 1480.612032: hrtimer_get_next_event <-get_next_timer_interrupt
1666 <idle>-0 [00] 1480.612037: hrtimer_get_next_event <-get_next_timer_interrupt
1667 <idle>-0 [00] 1480.612382: hrtimer_get_next_event <-get_next_timer_interrupt
1668
1669
1670Notice that we lost the sys_nanosleep.
1671
GeunSik Lim156f5a72009-06-02 15:01:37 +09001672 # cat set_ftrace_filter
Steven Rostedteb6d42e2008-07-10 12:46:01 -04001673hrtimer_run_queues
1674hrtimer_run_pending
1675hrtimer_init
1676hrtimer_cancel
1677hrtimer_try_to_cancel
1678hrtimer_forward
1679hrtimer_start
1680hrtimer_reprogram
1681hrtimer_force_reprogram
1682hrtimer_get_next_event
1683hrtimer_interrupt
1684hrtimer_nanosleep
1685hrtimer_wakeup
1686hrtimer_get_remaining
1687hrtimer_get_res
1688hrtimer_init_sleeper
1689
1690
1691This is because the '>' and '>>' act just like they do in bash.
1692To rewrite the filters, use '>'
1693To append to the filters, use '>>'
1694
Ingo Molnar57526742009-02-19 12:54:10 +01001695To clear out a filter so that all functions will be recorded
1696again:
Steven Rostedteb6d42e2008-07-10 12:46:01 -04001697
GeunSik Lim156f5a72009-06-02 15:01:37 +09001698 # echo > set_ftrace_filter
1699 # cat set_ftrace_filter
Steven Rostedteb6d42e2008-07-10 12:46:01 -04001700 #
1701
1702Again, now we want to append.
1703
GeunSik Lim156f5a72009-06-02 15:01:37 +09001704 # echo sys_nanosleep > set_ftrace_filter
1705 # cat set_ftrace_filter
Steven Rostedteb6d42e2008-07-10 12:46:01 -04001706sys_nanosleep
GeunSik Lim156f5a72009-06-02 15:01:37 +09001707 # echo 'hrtimer_*' >> set_ftrace_filter
1708 # cat set_ftrace_filter
Steven Rostedteb6d42e2008-07-10 12:46:01 -04001709hrtimer_run_queues
1710hrtimer_run_pending
1711hrtimer_init
1712hrtimer_cancel
1713hrtimer_try_to_cancel
1714hrtimer_forward
1715hrtimer_start
1716hrtimer_reprogram
1717hrtimer_force_reprogram
1718hrtimer_get_next_event
1719hrtimer_interrupt
1720sys_nanosleep
1721hrtimer_nanosleep
1722hrtimer_wakeup
1723hrtimer_get_remaining
1724hrtimer_get_res
1725hrtimer_init_sleeper
1726
1727
Ingo Molnar57526742009-02-19 12:54:10 +01001728The set_ftrace_notrace prevents those functions from being
1729traced.
Steven Rostedteb6d42e2008-07-10 12:46:01 -04001730
GeunSik Lim156f5a72009-06-02 15:01:37 +09001731 # echo '*preempt*' '*lock*' > set_ftrace_notrace
Steven Rostedteb6d42e2008-07-10 12:46:01 -04001732
1733Produces:
1734
1735# tracer: ftrace
1736#
1737# TASK-PID CPU# TIMESTAMP FUNCTION
1738# | | | | |
1739 bash-4043 [01] 115.281644: finish_task_switch <-schedule
1740 bash-4043 [01] 115.281645: hrtick_set <-schedule
1741 bash-4043 [01] 115.281645: hrtick_clear <-hrtick_set
1742 bash-4043 [01] 115.281646: wait_for_completion <-__stop_machine_run
1743 bash-4043 [01] 115.281647: wait_for_common <-wait_for_completion
1744 bash-4043 [01] 115.281647: kthread_stop <-stop_machine_run
1745 bash-4043 [01] 115.281648: init_waitqueue_head <-kthread_stop
1746 bash-4043 [01] 115.281648: wake_up_process <-kthread_stop
1747 bash-4043 [01] 115.281649: try_to_wake_up <-wake_up_process
1748
1749We can see that there's no more lock or preempt tracing.
1750
Frederic Weisbecker985ec202009-02-18 06:35:34 +01001751
Ingo Molnar57526742009-02-19 12:54:10 +01001752Dynamic ftrace with the function graph tracer
1753---------------------------------------------
Frederic Weisbecker985ec202009-02-18 06:35:34 +01001754
Ingo Molnar57526742009-02-19 12:54:10 +01001755Although what has been explained above concerns both the
1756function tracer and the function-graph-tracer, there are some
1757special features only available in the function-graph tracer.
Frederic Weisbecker985ec202009-02-18 06:35:34 +01001758
Ingo Molnar57526742009-02-19 12:54:10 +01001759If you want to trace only one function and all of its children,
1760you just have to echo its name into set_graph_function:
Frederic Weisbecker985ec202009-02-18 06:35:34 +01001761
Ingo Molnar57526742009-02-19 12:54:10 +01001762 echo __do_fault > set_graph_function
Frederic Weisbecker985ec202009-02-18 06:35:34 +01001763
Ingo Molnar57526742009-02-19 12:54:10 +01001764will produce the following "expanded" trace of the __do_fault()
1765function:
Frederic Weisbecker985ec202009-02-18 06:35:34 +01001766
1767 0) | __do_fault() {
1768 0) | filemap_fault() {
1769 0) | find_lock_page() {
1770 0) 0.804 us | find_get_page();
1771 0) | __might_sleep() {
1772 0) 1.329 us | }
1773 0) 3.904 us | }
1774 0) 4.979 us | }
1775 0) 0.653 us | _spin_lock();
1776 0) 0.578 us | page_add_file_rmap();
1777 0) 0.525 us | native_set_pte_at();
1778 0) 0.585 us | _spin_unlock();
1779 0) | unlock_page() {
1780 0) 0.541 us | page_waitqueue();
1781 0) 0.639 us | __wake_up_bit();
1782 0) 2.786 us | }
1783 0) + 14.237 us | }
1784 0) | __do_fault() {
1785 0) | filemap_fault() {
1786 0) | find_lock_page() {
1787 0) 0.698 us | find_get_page();
1788 0) | __might_sleep() {
1789 0) 1.412 us | }
1790 0) 3.950 us | }
1791 0) 5.098 us | }
1792 0) 0.631 us | _spin_lock();
1793 0) 0.571 us | page_add_file_rmap();
1794 0) 0.526 us | native_set_pte_at();
1795 0) 0.586 us | _spin_unlock();
1796 0) | unlock_page() {
1797 0) 0.533 us | page_waitqueue();
1798 0) 0.638 us | __wake_up_bit();
1799 0) 2.793 us | }
1800 0) + 14.012 us | }
1801
Ingo Molnar57526742009-02-19 12:54:10 +01001802You can also expand several functions at once:
Frederic Weisbecker985ec202009-02-18 06:35:34 +01001803
Ingo Molnar57526742009-02-19 12:54:10 +01001804 echo sys_open > set_graph_function
1805 echo sys_close >> set_graph_function
Frederic Weisbecker985ec202009-02-18 06:35:34 +01001806
Ingo Molnar57526742009-02-19 12:54:10 +01001807Now if you want to go back to trace all functions you can clear
1808this special filter via:
Frederic Weisbecker985ec202009-02-18 06:35:34 +01001809
Ingo Molnar57526742009-02-19 12:54:10 +01001810 echo > set_graph_function
Frederic Weisbecker985ec202009-02-18 06:35:34 +01001811
1812
Steven Rostedteb6d42e2008-07-10 12:46:01 -04001813trace_pipe
1814----------
1815
Ingo Molnar57526742009-02-19 12:54:10 +01001816The trace_pipe outputs the same content as the trace file, but
1817the effect on the tracing is different. Every read from
1818trace_pipe is consumed. This means that subsequent reads will be
1819different. The trace is live.
Steven Rostedteb6d42e2008-07-10 12:46:01 -04001820
GeunSik Lim156f5a72009-06-02 15:01:37 +09001821 # echo function > current_tracer
1822 # cat trace_pipe > /tmp/trace.out &
Steven Rostedteb6d42e2008-07-10 12:46:01 -04001823[1] 4153
GeunSik Lim156f5a72009-06-02 15:01:37 +09001824 # echo 1 > tracing_enabled
Steven Rostedteb6d42e2008-07-10 12:46:01 -04001825 # usleep 1
GeunSik Lim156f5a72009-06-02 15:01:37 +09001826 # echo 0 > tracing_enabled
1827 # cat trace
Steven Rostedt9b803c02008-11-03 15:15:08 -05001828# tracer: function
Steven Rostedteb6d42e2008-07-10 12:46:01 -04001829#
1830# TASK-PID CPU# TIMESTAMP FUNCTION
1831# | | | | |
1832
1833 #
1834 # cat /tmp/trace.out
1835 bash-4043 [00] 41.267106: finish_task_switch <-schedule
1836 bash-4043 [00] 41.267106: hrtick_set <-schedule
1837 bash-4043 [00] 41.267107: hrtick_clear <-hrtick_set
1838 bash-4043 [00] 41.267108: wait_for_completion <-__stop_machine_run
1839 bash-4043 [00] 41.267108: wait_for_common <-wait_for_completion
1840 bash-4043 [00] 41.267109: kthread_stop <-stop_machine_run
1841 bash-4043 [00] 41.267109: init_waitqueue_head <-kthread_stop
1842 bash-4043 [00] 41.267110: wake_up_process <-kthread_stop
1843 bash-4043 [00] 41.267110: try_to_wake_up <-wake_up_process
1844 bash-4043 [00] 41.267111: select_task_rq_rt <-try_to_wake_up
1845
1846
Ingo Molnar57526742009-02-19 12:54:10 +01001847Note, reading the trace_pipe file will block until more input is
1848added. By changing the tracer, trace_pipe will issue an EOF. We
1849needed to set the function tracer _before_ we "cat" the
1850trace_pipe file.
Steven Rostedteb6d42e2008-07-10 12:46:01 -04001851
1852
1853trace entries
1854-------------
1855
Ingo Molnar57526742009-02-19 12:54:10 +01001856Having too much or not enough data can be troublesome in
1857diagnosing an issue in the kernel. The file buffer_size_kb is
1858used to modify the size of the internal trace buffers. The
1859number listed is the number of entries that can be recorded per
1860CPU. To know the full size, multiply the number of possible CPUS
1861with the number of entries.
Steven Rostedteb6d42e2008-07-10 12:46:01 -04001862
GeunSik Lim156f5a72009-06-02 15:01:37 +09001863 # cat buffer_size_kb
Steven Rostedt1696b2b2008-11-13 00:09:35 -050018641408 (units kilobytes)
Steven Rostedteb6d42e2008-07-10 12:46:01 -04001865
Ingo Molnar57526742009-02-19 12:54:10 +01001866Note, to modify this, you must have tracing completely disabled.
1867To do that, echo "nop" into the current_tracer. If the
1868current_tracer is not set to "nop", an EINVAL error will be
1869returned.
Steven Rostedteb6d42e2008-07-10 12:46:01 -04001870
GeunSik Lim156f5a72009-06-02 15:01:37 +09001871 # echo nop > current_tracer
1872 # echo 10000 > buffer_size_kb
1873 # cat buffer_size_kb
Steven Rostedt1696b2b2008-11-13 00:09:35 -0500187410000 (units kilobytes)
Steven Rostedteb6d42e2008-07-10 12:46:01 -04001875
Ingo Molnar57526742009-02-19 12:54:10 +01001876The number of pages which will be allocated is limited to a
1877percentage of available memory. Allocating too much will produce
1878an error.
Steven Rostedteb6d42e2008-07-10 12:46:01 -04001879
GeunSik Lim156f5a72009-06-02 15:01:37 +09001880 # echo 1000000000000 > buffer_size_kb
Steven Rostedteb6d42e2008-07-10 12:46:01 -04001881-bash: echo: write error: Cannot allocate memory
GeunSik Lim156f5a72009-06-02 15:01:37 +09001882 # cat buffer_size_kb
Steven Rostedteb6d42e2008-07-10 12:46:01 -0400188385
1884
Ingo Molnar57526742009-02-19 12:54:10 +01001885-----------
1886
1887More details can be found in the source code, in the
GeunSik Limbaf20b32009-06-01 10:49:41 +02001888kernel/trace/*.c files.