blob: 03485bfbd7975792f50d54dabf77533938f255c9 [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
Mike Frysinger555f3862009-09-14 20:10:15 -040029Implementation Details
30----------------------
31
32See ftrace-design.txt for details for arch porters and such.
33
34
Steven Rostedteb6d42e2008-07-10 12:46:01 -040035The File System
36---------------
37
Ingo Molnar57526742009-02-19 12:54:10 +010038Ftrace uses the debugfs file system to hold the control files as
39well as the files to display output.
Steven Rostedteb6d42e2008-07-10 12:46:01 -040040
GeunSik Lim156f5a72009-06-02 15:01:37 +090041When debugfs is configured into the kernel (which selecting any ftrace
42option will do) the directory /sys/kernel/debug will be created. To mount
43this directory, you can add to your /etc/fstab file:
Steven Rostedteb6d42e2008-07-10 12:46:01 -040044
GeunSik Lim156f5a72009-06-02 15:01:37 +090045 debugfs /sys/kernel/debug debugfs defaults 0 0
Steven Rostedteb6d42e2008-07-10 12:46:01 -040046
GeunSik Lim156f5a72009-06-02 15:01:37 +090047Or you can mount it at run time with:
48
49 mount -t debugfs nodev /sys/kernel/debug
50
51For quicker access to that directory you may want to make a soft link to
52it:
53
54 ln -s /sys/kernel/debug /debug
55
56Any selected ftrace option will also create a directory called tracing
57within the debugfs. The rest of the document will assume that you are in
58the ftrace directory (cd /sys/kernel/debug/tracing) and will only concentrate
59on the files within that directory and not distract from the content with
60the extended "/sys/kernel/debug/tracing" path name.
Steven Rostedteb6d42e2008-07-10 12:46:01 -040061
62That's it! (assuming that you have ftrace configured into your kernel)
63
64After mounting the debugfs, you can see a directory called
65"tracing". This directory contains the control and output files
66of ftrace. Here is a list of some of the key files:
67
68
69 Note: all time values are in microseconds.
70
Ingo Molnar57526742009-02-19 12:54:10 +010071 current_tracer:
Steven Rostedteb6d42e2008-07-10 12:46:01 -040072
Ingo Molnar57526742009-02-19 12:54:10 +010073 This is used to set or display the current tracer
74 that is configured.
Steven Rostedteb6d42e2008-07-10 12:46:01 -040075
Ingo Molnar57526742009-02-19 12:54:10 +010076 available_tracers:
Steven Rostedteb6d42e2008-07-10 12:46:01 -040077
Ingo Molnar57526742009-02-19 12:54:10 +010078 This holds the different types of tracers that
79 have been compiled into the kernel. The
80 tracers listed here can be configured by
81 echoing their name into current_tracer.
Steven Rostedteb6d42e2008-07-10 12:46:01 -040082
Ingo Molnar57526742009-02-19 12:54:10 +010083 tracing_enabled:
Steven Rostedteb6d42e2008-07-10 12:46:01 -040084
Ingo Molnar57526742009-02-19 12:54:10 +010085 This sets or displays whether the current_tracer
86 is activated and tracing or not. Echo 0 into this
87 file to disable the tracer or 1 to enable it.
Steven Rostedteb6d42e2008-07-10 12:46:01 -040088
Ingo Molnar57526742009-02-19 12:54:10 +010089 trace:
Steven Rostedteb6d42e2008-07-10 12:46:01 -040090
Ingo Molnar57526742009-02-19 12:54:10 +010091 This file holds the output of the trace in a human
92 readable format (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.
Albin Tonnerre4a88d442009-08-31 22:40:08 +020098 Reads from this file will block until new data is
99 retrieved. Unlike the "trace" file, this file is a
100 consumer. This means reading from this file causes
101 sequential reads to display more current data. Once
102 data is read from this file, it is consumed, and
103 will not be read again with a sequential read. The
104 "trace" file is static, and if the tracer is not
105 adding more data,they will display the same
106 information every time they are read.
Steven Rostedteb6d42e2008-07-10 12:46:01 -0400107
Ingo Molnar57526742009-02-19 12:54:10 +0100108 trace_options:
Steven Rostedteb6d42e2008-07-10 12:46:01 -0400109
Ingo Molnar57526742009-02-19 12:54:10 +0100110 This file lets the user control the amount of data
111 that is displayed in one of the above output
112 files.
Steven Rostedtdf4fc312008-11-26 00:16:23 -0500113
KOSAKI Motohiro42b40b32009-03-07 23:55:09 +0900114 tracing_max_latency:
Frederic Weisbecker985ec202009-02-18 06:35:34 +0100115
Ingo Molnar57526742009-02-19 12:54:10 +0100116 Some of the tracers record the max latency.
117 For example, the time interrupts are disabled.
118 This time is saved in this file. The max trace
Albin Tonnerre4a88d442009-08-31 22:40:08 +0200119 will also be stored, and displayed by "trace".
120 A new max trace will only be recorded if the
121 latency is greater than the value in this
122 file. (in microseconds)
Ingo Molnar57526742009-02-19 12:54:10 +0100123
124 buffer_size_kb:
125
126 This sets or displays the number of kilobytes each CPU
127 buffer can hold. The tracer buffers are the same size
128 for each CPU. The displayed number is the size of the
129 CPU buffer and not total size of all buffers. The
130 trace buffers are allocated in pages (blocks of memory
131 that the kernel uses for allocation, usually 4 KB in size).
132 If the last page allocated has room for more bytes
133 than requested, the rest of the page will be used,
134 making the actual allocation bigger than requested.
135 ( Note, the size may not be a multiple of the page size
Uwe Kleine-Koenig3dbda772009-07-23 08:31:31 +0200136 due to buffer management overhead. )
Ingo Molnar57526742009-02-19 12:54:10 +0100137
138 This can only be updated when the current_tracer
139 is set to "nop".
140
141 tracing_cpumask:
142
143 This is a mask that lets the user only trace
144 on specified CPUS. The format is a hex string
145 representing the CPUS.
146
147 set_ftrace_filter:
148
149 When dynamic ftrace is configured in (see the
150 section below "dynamic ftrace"), the code is dynamically
151 modified (code text rewrite) to disable calling of the
152 function profiler (mcount). This lets tracing be configured
153 in with practically no overhead in performance. This also
154 has a side effect of enabling or disabling specific functions
155 to be traced. Echoing names of functions into this file
156 will limit the trace to only those functions.
157
158 set_ftrace_notrace:
159
160 This has an effect opposite to that of
161 set_ftrace_filter. Any function that is added here will not
162 be traced. If a function exists in both set_ftrace_filter
163 and set_ftrace_notrace, the function will _not_ be traced.
164
165 set_ftrace_pid:
166
167 Have the function tracer only trace a single thread.
168
169 set_graph_function:
170
171 Set a "trigger" function where tracing should start
172 with the function graph tracer (See the section
173 "dynamic ftrace" for more details).
174
175 available_filter_functions:
176
177 This lists the functions that ftrace
178 has processed and can trace. These are the function
179 names that you can pass to "set_ftrace_filter" or
180 "set_ftrace_notrace". (See the section "dynamic ftrace"
181 below for more details.)
Steven Rostedteb6d42e2008-07-10 12:46:01 -0400182
183
184The Tracers
185-----------
186
Steven Rostedtf2d9c742008-07-15 10:57:33 -0400187Here is the list of current tracers that may be configured.
Steven Rostedteb6d42e2008-07-10 12:46:01 -0400188
Ingo Molnar57526742009-02-19 12:54:10 +0100189 "function"
Steven Rostedteb6d42e2008-07-10 12:46:01 -0400190
Ingo Molnar57526742009-02-19 12:54:10 +0100191 Function call tracer to trace all kernel functions.
Frederic Weisbecker985ec202009-02-18 06:35:34 +0100192
Mike Frysingerbc5c6c02009-06-10 04:48:41 -0400193 "function_graph"
Steven Rostedteb6d42e2008-07-10 12:46:01 -0400194
Ingo Molnar57526742009-02-19 12:54:10 +0100195 Similar to the function tracer except that the
196 function tracer probes the functions on their entry
197 whereas the function graph tracer traces on both entry
198 and exit of the functions. It then provides the ability
199 to draw a graph of function calls similar to C code
200 source.
Steven Rostedteb6d42e2008-07-10 12:46:01 -0400201
Ingo Molnar57526742009-02-19 12:54:10 +0100202 "sched_switch"
Steven Rostedteb6d42e2008-07-10 12:46:01 -0400203
Ingo Molnar57526742009-02-19 12:54:10 +0100204 Traces the context switches and wakeups between tasks.
Steven Rostedteb6d42e2008-07-10 12:46:01 -0400205
Ingo Molnar57526742009-02-19 12:54:10 +0100206 "irqsoff"
Steven Rostedteb6d42e2008-07-10 12:46:01 -0400207
Ingo Molnar57526742009-02-19 12:54:10 +0100208 Traces the areas that disable interrupts and saves
209 the trace with the longest max latency.
210 See tracing_max_latency. When a new max is recorded,
211 it replaces the old trace. It is best to view this
Albin Tonnerre4a88d442009-08-31 22:40:08 +0200212 trace with the latency-format option enabled.
Steven Rostedteb6d42e2008-07-10 12:46:01 -0400213
Ingo Molnar57526742009-02-19 12:54:10 +0100214 "preemptoff"
215
216 Similar to irqsoff but traces and records the amount of
217 time for which preemption is disabled.
218
219 "preemptirqsoff"
220
221 Similar to irqsoff and preemptoff, but traces and
222 records the largest time for which irqs and/or preemption
223 is disabled.
224
225 "wakeup"
226
227 Traces and records the max latency that it takes for
228 the highest priority task to get scheduled after
229 it has been woken up.
230
231 "hw-branch-tracer"
232
233 Uses the BTS CPU feature on x86 CPUs to traces all
234 branches executed.
235
236 "nop"
237
238 This is the "trace nothing" tracer. To remove all
239 tracers from tracing simply echo "nop" into
240 current_tracer.
Markus Metzgere2ea5392009-01-19 10:35:58 +0100241
Steven Rostedteb6d42e2008-07-10 12:46:01 -0400242
243Examples of using the tracer
244----------------------------
245
Ingo Molnar57526742009-02-19 12:54:10 +0100246Here are typical examples of using the tracers when controlling
247them only with the debugfs interface (without using any
248user-land utilities).
Steven Rostedteb6d42e2008-07-10 12:46:01 -0400249
250Output format:
251--------------
252
Steven Rostedtf2d9c742008-07-15 10:57:33 -0400253Here is an example of the output format of the file "trace"
Steven Rostedteb6d42e2008-07-10 12:46:01 -0400254
255 --------
Steven Rostedt9b803c02008-11-03 15:15:08 -0500256# tracer: function
Steven Rostedteb6d42e2008-07-10 12:46:01 -0400257#
258# TASK-PID CPU# TIMESTAMP FUNCTION
259# | | | | |
260 bash-4251 [01] 10152.583854: path_put <-path_walk
261 bash-4251 [01] 10152.583855: dput <-path_put
262 bash-4251 [01] 10152.583855: _atomic_dec_and_lock <-dput
263 --------
264
Ingo Molnar57526742009-02-19 12:54:10 +0100265A header is printed with the tracer name that is represented by
266the trace. In this case the tracer is "function". Then a header
267showing the format. Task name "bash", the task PID "4251", the
268CPU that it was running on "01", the timestamp in <secs>.<usecs>
269format, the function name that was traced "path_put" and the
270parent function that called this function "path_walk". The
271timestamp is the time at which the function was entered.
Steven Rostedteb6d42e2008-07-10 12:46:01 -0400272
Ingo Molnar57526742009-02-19 12:54:10 +0100273The sched_switch tracer also includes tracing of task wakeups
274and context switches.
Steven Rostedteb6d42e2008-07-10 12:46:01 -0400275
276 ksoftirqd/1-7 [01] 1453.070013: 7:115:R + 2916:115:S
277 ksoftirqd/1-7 [01] 1453.070013: 7:115:R + 10:115:S
278 ksoftirqd/1-7 [01] 1453.070013: 7:115:R ==> 10:115:R
279 events/1-10 [01] 1453.070013: 10:115:S ==> 2916:115:R
280 kondemand/1-2916 [01] 1453.070013: 2916:115:S ==> 7:115:R
281 ksoftirqd/1-7 [01] 1453.070013: 7:115:S ==> 0:140:R
282
Ingo Molnar57526742009-02-19 12:54:10 +0100283Wake ups are represented by a "+" and the context switches are
284shown as "==>". The format is:
Steven Rostedteb6d42e2008-07-10 12:46:01 -0400285
286 Context switches:
287
288 Previous task Next Task
289
290 <pid>:<prio>:<state> ==> <pid>:<prio>:<state>
291
292 Wake ups:
293
294 Current task Task waking up
295
296 <pid>:<prio>:<state> + <pid>:<prio>:<state>
297
Ingo Molnar57526742009-02-19 12:54:10 +0100298The prio is the internal kernel priority, which is the inverse
299of the priority that is usually displayed by user-space tools.
300Zero represents the highest priority (99). Prio 100 starts the
301"nice" priorities with 100 being equal to nice -20 and 139 being
302nice 19. The prio "140" is reserved for the idle task which is
303the lowest priority thread (pid 0).
Steven Rostedteb6d42e2008-07-10 12:46:01 -0400304
305
306Latency trace format
307--------------------
308
Albin Tonnerre4a88d442009-08-31 22:40:08 +0200309When the latency-format option is enabled, the trace file gives
310somewhat more information to see why a latency happened.
Ingo Molnar57526742009-02-19 12:54:10 +0100311Here is a typical trace.
Steven Rostedteb6d42e2008-07-10 12:46:01 -0400312
313# tracer: irqsoff
314#
315irqsoff latency trace v1.1.5 on 2.6.26-rc8
316--------------------------------------------------------------------
317 latency: 97 us, #3/3, CPU#0 | (M:preempt VP:0, KP:0, SP:0 HP:0 #P:2)
318 -----------------
319 | task: swapper-0 (uid:0 nice:0 policy:0 rt_prio:0)
320 -----------------
321 => started at: apic_timer_interrupt
322 => ended at: do_softirq
323
324# _------=> CPU#
325# / _-----=> irqs-off
326# | / _----=> need-resched
327# || / _---=> hardirq/softirq
328# ||| / _--=> preempt-depth
329# |||| /
330# ||||| delay
331# cmd pid ||||| time | caller
332# \ / ||||| \ | /
333 <idle>-0 0d..1 0us+: trace_hardirqs_off_thunk (apic_timer_interrupt)
334 <idle>-0 0d.s. 97us : __do_softirq (do_softirq)
335 <idle>-0 0d.s1 98us : trace_hardirqs_on (do_softirq)
336
337
Ingo Molnar57526742009-02-19 12:54:10 +0100338This shows that the current tracer is "irqsoff" tracing the time
339for which interrupts were disabled. It gives the trace version
340and the version of the kernel upon which this was executed on
341(2.6.26-rc8). Then it displays the max latency in microsecs (97
342us). The number of trace entries displayed and the total number
343recorded (both are three: #3/3). The type of preemption that was
344used (PREEMPT). VP, KP, SP, and HP are always zero and are
345reserved for later use. #P is the number of online CPUS (#P:2).
Steven Rostedteb6d42e2008-07-10 12:46:01 -0400346
Ingo Molnar57526742009-02-19 12:54:10 +0100347The task is the process that was running when the latency
348occurred. (swapper pid: 0).
Steven Rostedteb6d42e2008-07-10 12:46:01 -0400349
Ingo Molnar57526742009-02-19 12:54:10 +0100350The start and stop (the functions in which the interrupts were
351disabled and enabled respectively) that caused the latencies:
Steven Rostedteb6d42e2008-07-10 12:46:01 -0400352
353 apic_timer_interrupt is where the interrupts were disabled.
354 do_softirq is where they were enabled again.
355
356The next lines after the header are the trace itself. The header
357explains which is which.
358
359 cmd: The name of the process in the trace.
360
361 pid: The PID of that process.
362
Steven Rostedtf2d9c742008-07-15 10:57:33 -0400363 CPU#: The CPU which the process was running on.
Steven Rostedteb6d42e2008-07-10 12:46:01 -0400364
365 irqs-off: 'd' interrupts are disabled. '.' otherwise.
Steven Rostedt92444892008-10-24 09:42:59 -0400366 Note: If the architecture does not support a way to
367 read the irq flags variable, an 'X' will always
368 be printed here.
Steven Rostedteb6d42e2008-07-10 12:46:01 -0400369
370 need-resched: 'N' task need_resched is set, '.' otherwise.
371
372 hardirq/softirq:
Steven Rostedtf2d9c742008-07-15 10:57:33 -0400373 'H' - hard irq occurred inside a softirq.
Steven Rostedteb6d42e2008-07-10 12:46:01 -0400374 'h' - hard irq is running
375 's' - soft irq is running
376 '.' - normal context.
377
378 preempt-depth: The level of preempt_disabled
379
380The above is mostly meaningful for kernel developers.
381
Albin Tonnerre4a88d442009-08-31 22:40:08 +0200382 time: When the latency-format option is enabled, the trace file
383 output includes a timestamp relative to the start of the
384 trace. This differs from the output when latency-format
385 is disabled, which includes an absolute timestamp.
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
Albin Tonnerre4a88d442009-08-31 22:40:08 +0200443 verbose - This deals with the trace file when the
444 latency-format option is enabled.
Steven Rostedteb6d42e2008-07-10 12:46:01 -0400445
446 bash 4000 1 0 00000000 00010a95 [58127d26] 1720.415ms \
447 (+0.000ms): simple_strtoul (strict_strtoul)
448
Ingo Molnar57526742009-02-19 12:54:10 +0100449 raw - This will display raw numbers. This option is best for
450 use with user applications that can translate the raw
451 numbers better than having it done in the kernel.
Steven Rostedteb6d42e2008-07-10 12:46:01 -0400452
Ingo Molnar57526742009-02-19 12:54:10 +0100453 hex - Similar to raw, but the numbers will be in a hexadecimal
454 format.
Steven Rostedteb6d42e2008-07-10 12:46:01 -0400455
456 bin - This will print out the formats in raw binary.
457
458 block - TBD (needs update)
459
Ingo Molnar57526742009-02-19 12:54:10 +0100460 stacktrace - This is one of the options that changes the trace
461 itself. When a trace is recorded, so is the stack
462 of functions. This allows for back traces of
463 trace sites.
Steven Rostedteb6d42e2008-07-10 12:46:01 -0400464
Ingo Molnar57526742009-02-19 12:54:10 +0100465 userstacktrace - This option changes the trace. It records a
466 stacktrace of the current userspace thread.
Török Edwin02b67512008-11-22 13:28:47 +0200467
Ingo Molnar57526742009-02-19 12:54:10 +0100468 sym-userobj - when user stacktrace are enabled, look up which
469 object the address belongs to, and print a
470 relative address. This is especially useful when
471 ASLR is on, otherwise you don't get a chance to
472 resolve the address to object/file/line after
473 the app is no longer running
Török Edwinb54d3de2008-11-22 13:28:48 +0200474
Ingo Molnar57526742009-02-19 12:54:10 +0100475 The lookup is performed when you read
Albin Tonnerre4a88d442009-08-31 22:40:08 +0200476 trace,trace_pipe. Example:
Török Edwinb54d3de2008-11-22 13:28:48 +0200477
478 a.out-1623 [000] 40874.465068: /root/a.out[+0x480] <-/root/a.out[+0
479x494] <- /root/a.out[+0x4a8] <- /lib/libc-2.7.so[+0x1e1a6]
480
Ingo Molnar57526742009-02-19 12:54:10 +0100481 sched-tree - trace all tasks that are on the runqueue, at
482 every scheduling event. Will add overhead if
483 there's a lot of tasks running at once.
Steven Rostedteb6d42e2008-07-10 12:46:01 -0400484
Albin Tonnerre4a88d442009-08-31 22:40:08 +0200485 latency-format - This option changes the trace. When
486 it is enabled, the trace displays
487 additional information about the
488 latencies, as described in "Latency
489 trace format".
Steven Rostedteb6d42e2008-07-10 12:46:01 -0400490
491sched_switch
492------------
493
Steven Rostedtf2d9c742008-07-15 10:57:33 -0400494This tracer simply records schedule switches. Here is an example
Steven Rostedta41eeba2008-07-14 16:41:12 -0400495of how to use it.
Steven Rostedteb6d42e2008-07-10 12:46:01 -0400496
GeunSik Lim156f5a72009-06-02 15:01:37 +0900497 # echo sched_switch > current_tracer
498 # echo 1 > tracing_enabled
Steven Rostedteb6d42e2008-07-10 12:46:01 -0400499 # sleep 1
GeunSik Lim156f5a72009-06-02 15:01:37 +0900500 # echo 0 > tracing_enabled
501 # cat trace
Steven Rostedteb6d42e2008-07-10 12:46:01 -0400502
503# tracer: sched_switch
504#
505# TASK-PID CPU# TIMESTAMP FUNCTION
506# | | | | |
507 bash-3997 [01] 240.132281: 3997:120:R + 4055:120:R
508 bash-3997 [01] 240.132284: 3997:120:R ==> 4055:120:R
509 sleep-4055 [01] 240.132371: 4055:120:S ==> 3997:120:R
510 bash-3997 [01] 240.132454: 3997:120:R + 4055:120:S
511 bash-3997 [01] 240.132457: 3997:120:R ==> 4055:120:R
512 sleep-4055 [01] 240.132460: 4055:120:D ==> 3997:120:R
513 bash-3997 [01] 240.132463: 3997:120:R + 4055:120:D
514 bash-3997 [01] 240.132465: 3997:120:R ==> 4055:120:R
515 <idle>-0 [00] 240.132589: 0:140:R + 4:115:S
516 <idle>-0 [00] 240.132591: 0:140:R ==> 4:115:R
517 ksoftirqd/0-4 [00] 240.132595: 4:115:S ==> 0:140:R
518 <idle>-0 [00] 240.132598: 0:140:R + 4:115:S
519 <idle>-0 [00] 240.132599: 0:140:R ==> 4:115:R
520 ksoftirqd/0-4 [00] 240.132603: 4:115:S ==> 0:140:R
521 sleep-4055 [01] 240.133058: 4055:120:S ==> 3997:120:R
522 [...]
523
524
Ingo Molnar57526742009-02-19 12:54:10 +0100525As we have discussed previously about this format, the header
526shows the name of the trace and points to the options. The
527"FUNCTION" is a misnomer since here it represents the wake ups
528and context switches.
Steven Rostedteb6d42e2008-07-10 12:46:01 -0400529
Ingo Molnar57526742009-02-19 12:54:10 +0100530The sched_switch file only lists the wake ups (represented with
531'+') and context switches ('==>') with the previous task or
532current task first followed by the next task or task waking up.
533The format for both of these is PID:KERNEL-PRIO:TASK-STATE.
534Remember that the KERNEL-PRIO is the inverse of the actual
535priority with zero (0) being the highest priority and the nice
536values starting at 100 (nice -20). Below is a quick chart to map
537the kernel priority to user land priorities.
Steven Rostedteb6d42e2008-07-10 12:46:01 -0400538
GeunSik Lim294ae402009-05-28 10:36:11 +0900539 Kernel Space User Space
540 ===============================================================
541 0(high) to 98(low) user RT priority 99(high) to 1(low)
542 with SCHED_RR or SCHED_FIFO
543 ---------------------------------------------------------------
544 99 sched_priority is not used in scheduling
545 decisions(it must be specified as 0)
546 ---------------------------------------------------------------
547 100(high) to 139(low) user nice -20(high) to 19(low)
548 ---------------------------------------------------------------
549 140 idle task priority
550 ---------------------------------------------------------------
Steven Rostedteb6d42e2008-07-10 12:46:01 -0400551
552The task states are:
553
554 R - running : wants to run, may not actually be running
555 S - sleep : process is waiting to be woken up (handles signals)
Steven Rostedtf2d9c742008-07-15 10:57:33 -0400556 D - disk sleep (uninterruptible sleep) : process must be woken up
557 (ignores signals)
Steven Rostedteb6d42e2008-07-10 12:46:01 -0400558 T - stopped : process suspended
559 t - traced : process is being traced (with something like gdb)
560 Z - zombie : process waiting to be cleaned up
561 X - unknown
562
563
564ftrace_enabled
565--------------
566
Ingo Molnar57526742009-02-19 12:54:10 +0100567The following tracers (listed below) give different output
568depending on whether or not the sysctl ftrace_enabled is set. To
569set ftrace_enabled, one can either use the sysctl function or
570set it via the proc file system interface.
Steven Rostedteb6d42e2008-07-10 12:46:01 -0400571
572 sysctl kernel.ftrace_enabled=1
573
574 or
575
576 echo 1 > /proc/sys/kernel/ftrace_enabled
577
Ingo Molnar57526742009-02-19 12:54:10 +0100578To disable ftrace_enabled simply replace the '1' with '0' in the
579above commands.
Steven Rostedteb6d42e2008-07-10 12:46:01 -0400580
Ingo Molnar57526742009-02-19 12:54:10 +0100581When ftrace_enabled is set the tracers will also record the
582functions that are within the trace. The descriptions of the
583tracers will also show an example with ftrace enabled.
Steven Rostedteb6d42e2008-07-10 12:46:01 -0400584
585
586irqsoff
587-------
588
589When interrupts are disabled, the CPU can not react to any other
590external event (besides NMIs and SMIs). This prevents the timer
Ingo Molnar57526742009-02-19 12:54:10 +0100591interrupt from triggering or the mouse interrupt from letting
592the kernel know of a new mouse event. The result is a latency
593with the reaction time.
Steven Rostedteb6d42e2008-07-10 12:46:01 -0400594
Ingo Molnar57526742009-02-19 12:54:10 +0100595The irqsoff tracer tracks the time for which interrupts are
596disabled. When a new maximum latency is hit, the tracer saves
597the trace leading up to that latency point so that every time a
598new maximum is reached, the old saved trace is discarded and the
599new trace is saved.
Steven Rostedteb6d42e2008-07-10 12:46:01 -0400600
Ingo Molnar57526742009-02-19 12:54:10 +0100601To reset the maximum, echo 0 into tracing_max_latency. Here is
602an example:
Steven Rostedteb6d42e2008-07-10 12:46:01 -0400603
GeunSik Lim156f5a72009-06-02 15:01:37 +0900604 # echo irqsoff > current_tracer
Albin Tonnerre4a88d442009-08-31 22:40:08 +0200605 # echo latency-format > trace_options
GeunSik Lim156f5a72009-06-02 15:01:37 +0900606 # echo 0 > tracing_max_latency
607 # echo 1 > tracing_enabled
Steven Rostedteb6d42e2008-07-10 12:46:01 -0400608 # ls -ltr
609 [...]
GeunSik Lim156f5a72009-06-02 15:01:37 +0900610 # echo 0 > tracing_enabled
Albin Tonnerre4a88d442009-08-31 22:40:08 +0200611 # cat trace
Steven Rostedteb6d42e2008-07-10 12:46:01 -0400612# tracer: irqsoff
613#
Steven Rostedtf2d9c742008-07-15 10:57:33 -0400614irqsoff latency trace v1.1.5 on 2.6.26
Steven Rostedteb6d42e2008-07-10 12:46:01 -0400615--------------------------------------------------------------------
Steven Rostedtf2d9c742008-07-15 10:57:33 -0400616 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 -0400617 -----------------
Steven Rostedtf2d9c742008-07-15 10:57:33 -0400618 | task: bash-3730 (uid:0 nice:0 policy:0 rt_prio:0)
Steven Rostedteb6d42e2008-07-10 12:46:01 -0400619 -----------------
Steven Rostedtf2d9c742008-07-15 10:57:33 -0400620 => started at: sys_setpgid
621 => ended at: sys_setpgid
Steven Rostedteb6d42e2008-07-10 12:46:01 -0400622
623# _------=> CPU#
624# / _-----=> irqs-off
625# | / _----=> need-resched
626# || / _---=> hardirq/softirq
627# ||| / _--=> preempt-depth
628# |||| /
629# ||||| delay
630# cmd pid ||||| time | caller
631# \ / ||||| \ | /
Steven Rostedtf2d9c742008-07-15 10:57:33 -0400632 bash-3730 1d... 0us : _write_lock_irq (sys_setpgid)
633 bash-3730 1d..1 1us+: _write_unlock_irq (sys_setpgid)
634 bash-3730 1d..2 14us : trace_hardirqs_on (sys_setpgid)
Steven Rostedteb6d42e2008-07-10 12:46:01 -0400635
636
Steven Rostedtf2d9c742008-07-15 10:57:33 -0400637Here we see that that we had a latency of 12 microsecs (which is
Ingo Molnar57526742009-02-19 12:54:10 +0100638very good). The _write_lock_irq in sys_setpgid disabled
639interrupts. The difference between the 12 and the displayed
640timestamp 14us occurred because the clock was incremented
641between the time of recording the max latency and the time of
642recording the function that had that latency.
Steven Rostedteb6d42e2008-07-10 12:46:01 -0400643
Steven Rostedtf2d9c742008-07-15 10:57:33 -0400644Note the above example had ftrace_enabled not set. If we set the
645ftrace_enabled, we get a much larger output:
Steven Rostedteb6d42e2008-07-10 12:46:01 -0400646
647# tracer: irqsoff
648#
649irqsoff latency trace v1.1.5 on 2.6.26-rc8
650--------------------------------------------------------------------
651 latency: 50 us, #101/101, CPU#0 | (M:preempt VP:0, KP:0, SP:0 HP:0 #P:2)
652 -----------------
653 | task: ls-4339 (uid:0 nice:0 policy:0 rt_prio:0)
654 -----------------
655 => started at: __alloc_pages_internal
656 => ended at: __alloc_pages_internal
657
658# _------=> CPU#
659# / _-----=> irqs-off
660# | / _----=> need-resched
661# || / _---=> hardirq/softirq
662# ||| / _--=> preempt-depth
663# |||| /
664# ||||| delay
665# cmd pid ||||| time | caller
666# \ / ||||| \ | /
667 ls-4339 0...1 0us+: get_page_from_freelist (__alloc_pages_internal)
668 ls-4339 0d..1 3us : rmqueue_bulk (get_page_from_freelist)
669 ls-4339 0d..1 3us : _spin_lock (rmqueue_bulk)
670 ls-4339 0d..1 4us : add_preempt_count (_spin_lock)
671 ls-4339 0d..2 4us : __rmqueue (rmqueue_bulk)
672 ls-4339 0d..2 5us : __rmqueue_smallest (__rmqueue)
673 ls-4339 0d..2 5us : __mod_zone_page_state (__rmqueue_smallest)
674 ls-4339 0d..2 6us : __rmqueue (rmqueue_bulk)
675 ls-4339 0d..2 6us : __rmqueue_smallest (__rmqueue)
676 ls-4339 0d..2 7us : __mod_zone_page_state (__rmqueue_smallest)
677 ls-4339 0d..2 7us : __rmqueue (rmqueue_bulk)
678 ls-4339 0d..2 8us : __rmqueue_smallest (__rmqueue)
679[...]
680 ls-4339 0d..2 46us : __rmqueue_smallest (__rmqueue)
681 ls-4339 0d..2 47us : __mod_zone_page_state (__rmqueue_smallest)
682 ls-4339 0d..2 47us : __rmqueue (rmqueue_bulk)
683 ls-4339 0d..2 48us : __rmqueue_smallest (__rmqueue)
684 ls-4339 0d..2 48us : __mod_zone_page_state (__rmqueue_smallest)
685 ls-4339 0d..2 49us : _spin_unlock (rmqueue_bulk)
686 ls-4339 0d..2 49us : sub_preempt_count (_spin_unlock)
687 ls-4339 0d..1 50us : get_page_from_freelist (__alloc_pages_internal)
688 ls-4339 0d..2 51us : trace_hardirqs_on (__alloc_pages_internal)
689
690
Steven Rostedteb6d42e2008-07-10 12:46:01 -0400691
692Here we traced a 50 microsecond latency. But we also see all the
Ingo Molnar57526742009-02-19 12:54:10 +0100693functions that were called during that time. Note that by
694enabling function tracing, we incur an added overhead. This
695overhead may extend the latency times. But nevertheless, this
696trace has provided some very helpful debugging information.
Steven Rostedteb6d42e2008-07-10 12:46:01 -0400697
698
699preemptoff
700----------
701
Ingo Molnar57526742009-02-19 12:54:10 +0100702When preemption is disabled, we may be able to receive
703interrupts but the task cannot be preempted and a higher
704priority task must wait for preemption to be enabled again
705before it can preempt a lower priority task.
Steven Rostedteb6d42e2008-07-10 12:46:01 -0400706
Steven Rostedta41eeba2008-07-14 16:41:12 -0400707The preemptoff tracer traces the places that disable preemption.
Ingo Molnar57526742009-02-19 12:54:10 +0100708Like the irqsoff tracer, it records the maximum latency for
709which preemption was disabled. The control of preemptoff tracer
710is much like the irqsoff tracer.
Steven Rostedteb6d42e2008-07-10 12:46:01 -0400711
GeunSik Lim156f5a72009-06-02 15:01:37 +0900712 # echo preemptoff > current_tracer
Albin Tonnerre4a88d442009-08-31 22:40:08 +0200713 # echo latency-format > trace_options
GeunSik Lim156f5a72009-06-02 15:01:37 +0900714 # echo 0 > tracing_max_latency
715 # echo 1 > tracing_enabled
Steven Rostedteb6d42e2008-07-10 12:46:01 -0400716 # ls -ltr
717 [...]
GeunSik Lim156f5a72009-06-02 15:01:37 +0900718 # echo 0 > tracing_enabled
Albin Tonnerre4a88d442009-08-31 22:40:08 +0200719 # cat trace
Steven Rostedteb6d42e2008-07-10 12:46:01 -0400720# tracer: preemptoff
721#
722preemptoff latency trace v1.1.5 on 2.6.26-rc8
723--------------------------------------------------------------------
724 latency: 29 us, #3/3, CPU#0 | (M:preempt VP:0, KP:0, SP:0 HP:0 #P:2)
725 -----------------
726 | task: sshd-4261 (uid:0 nice:0 policy:0 rt_prio:0)
727 -----------------
728 => started at: do_IRQ
729 => ended at: __do_softirq
730
731# _------=> CPU#
732# / _-----=> irqs-off
733# | / _----=> need-resched
734# || / _---=> hardirq/softirq
735# ||| / _--=> preempt-depth
736# |||| /
737# ||||| delay
738# cmd pid ||||| time | caller
739# \ / ||||| \ | /
740 sshd-4261 0d.h. 0us+: irq_enter (do_IRQ)
741 sshd-4261 0d.s. 29us : _local_bh_enable (__do_softirq)
742 sshd-4261 0d.s1 30us : trace_preempt_on (__do_softirq)
743
744
Ingo Molnar57526742009-02-19 12:54:10 +0100745This has some more changes. Preemption was disabled when an
746interrupt came in (notice the 'h'), and was enabled while doing
747a softirq. (notice the 's'). But we also see that interrupts
748have been disabled when entering the preempt off section and
749leaving it (the 'd'). We do not know if interrupts were enabled
750in the mean time.
Steven Rostedteb6d42e2008-07-10 12:46:01 -0400751
752# tracer: preemptoff
753#
754preemptoff latency trace v1.1.5 on 2.6.26-rc8
755--------------------------------------------------------------------
756 latency: 63 us, #87/87, CPU#0 | (M:preempt VP:0, KP:0, SP:0 HP:0 #P:2)
757 -----------------
758 | task: sshd-4261 (uid:0 nice:0 policy:0 rt_prio:0)
759 -----------------
760 => started at: remove_wait_queue
761 => ended at: __do_softirq
762
763# _------=> CPU#
764# / _-----=> irqs-off
765# | / _----=> need-resched
766# || / _---=> hardirq/softirq
767# ||| / _--=> preempt-depth
768# |||| /
769# ||||| delay
770# cmd pid ||||| time | caller
771# \ / ||||| \ | /
772 sshd-4261 0d..1 0us : _spin_lock_irqsave (remove_wait_queue)
773 sshd-4261 0d..1 1us : _spin_unlock_irqrestore (remove_wait_queue)
774 sshd-4261 0d..1 2us : do_IRQ (common_interrupt)
775 sshd-4261 0d..1 2us : irq_enter (do_IRQ)
776 sshd-4261 0d..1 2us : idle_cpu (irq_enter)
777 sshd-4261 0d..1 3us : add_preempt_count (irq_enter)
778 sshd-4261 0d.h1 3us : idle_cpu (irq_enter)
779 sshd-4261 0d.h. 4us : handle_fasteoi_irq (do_IRQ)
780[...]
781 sshd-4261 0d.h. 12us : add_preempt_count (_spin_lock)
782 sshd-4261 0d.h1 12us : ack_ioapic_quirk_irq (handle_fasteoi_irq)
783 sshd-4261 0d.h1 13us : move_native_irq (ack_ioapic_quirk_irq)
784 sshd-4261 0d.h1 13us : _spin_unlock (handle_fasteoi_irq)
785 sshd-4261 0d.h1 14us : sub_preempt_count (_spin_unlock)
786 sshd-4261 0d.h1 14us : irq_exit (do_IRQ)
787 sshd-4261 0d.h1 15us : sub_preempt_count (irq_exit)
788 sshd-4261 0d..2 15us : do_softirq (irq_exit)
789 sshd-4261 0d... 15us : __do_softirq (do_softirq)
790 sshd-4261 0d... 16us : __local_bh_disable (__do_softirq)
791 sshd-4261 0d... 16us+: add_preempt_count (__local_bh_disable)
792 sshd-4261 0d.s4 20us : add_preempt_count (__local_bh_disable)
793 sshd-4261 0d.s4 21us : sub_preempt_count (local_bh_enable)
794 sshd-4261 0d.s5 21us : sub_preempt_count (local_bh_enable)
795[...]
796 sshd-4261 0d.s6 41us : add_preempt_count (__local_bh_disable)
797 sshd-4261 0d.s6 42us : sub_preempt_count (local_bh_enable)
798 sshd-4261 0d.s7 42us : sub_preempt_count (local_bh_enable)
799 sshd-4261 0d.s5 43us : add_preempt_count (__local_bh_disable)
800 sshd-4261 0d.s5 43us : sub_preempt_count (local_bh_enable_ip)
801 sshd-4261 0d.s6 44us : sub_preempt_count (local_bh_enable_ip)
802 sshd-4261 0d.s5 44us : add_preempt_count (__local_bh_disable)
803 sshd-4261 0d.s5 45us : sub_preempt_count (local_bh_enable)
804[...]
805 sshd-4261 0d.s. 63us : _local_bh_enable (__do_softirq)
806 sshd-4261 0d.s1 64us : trace_preempt_on (__do_softirq)
807
808
Ingo Molnar57526742009-02-19 12:54:10 +0100809The above is an example of the preemptoff trace with
810ftrace_enabled set. Here we see that interrupts were disabled
811the entire time. The irq_enter code lets us know that we entered
812an interrupt 'h'. Before that, the functions being traced still
813show that it is not in an interrupt, but we can see from the
814functions themselves that this is not the case.
Steven Rostedteb6d42e2008-07-10 12:46:01 -0400815
Ingo Molnar57526742009-02-19 12:54:10 +0100816Notice that __do_softirq when called does not have a
817preempt_count. It may seem that we missed a preempt enabling.
818What really happened is that the preempt count is held on the
819thread's stack and we switched to the softirq stack (4K stacks
820in effect). The code does not copy the preempt count, but
821because interrupts are disabled, we do not need to worry about
822it. Having a tracer like this is good for letting people know
823what really happens inside the kernel.
Steven Rostedteb6d42e2008-07-10 12:46:01 -0400824
825
826preemptirqsoff
827--------------
828
Ingo Molnar57526742009-02-19 12:54:10 +0100829Knowing the locations that have interrupts disabled or
830preemption disabled for the longest times is helpful. But
831sometimes we would like to know when either preemption and/or
832interrupts are disabled.
Steven Rostedteb6d42e2008-07-10 12:46:01 -0400833
Steven Rostedtf2d9c742008-07-15 10:57:33 -0400834Consider the following code:
Steven Rostedteb6d42e2008-07-10 12:46:01 -0400835
836 local_irq_disable();
837 call_function_with_irqs_off();
838 preempt_disable();
839 call_function_with_irqs_and_preemption_off();
840 local_irq_enable();
841 call_function_with_preemption_off();
842 preempt_enable();
843
844The irqsoff tracer will record the total length of
845call_function_with_irqs_off() and
846call_function_with_irqs_and_preemption_off().
847
848The preemptoff tracer will record the total length of
849call_function_with_irqs_and_preemption_off() and
850call_function_with_preemption_off().
851
Ingo Molnar57526742009-02-19 12:54:10 +0100852But neither will trace the time that interrupts and/or
853preemption is disabled. This total time is the time that we can
854not schedule. To record this time, use the preemptirqsoff
855tracer.
Steven Rostedteb6d42e2008-07-10 12:46:01 -0400856
Ingo Molnar57526742009-02-19 12:54:10 +0100857Again, using this trace is much like the irqsoff and preemptoff
858tracers.
Steven Rostedteb6d42e2008-07-10 12:46:01 -0400859
GeunSik Lim156f5a72009-06-02 15:01:37 +0900860 # echo preemptirqsoff > current_tracer
Albin Tonnerre4a88d442009-08-31 22:40:08 +0200861 # echo latency-format > trace_options
GeunSik Lim156f5a72009-06-02 15:01:37 +0900862 # echo 0 > tracing_max_latency
863 # echo 1 > tracing_enabled
Steven Rostedteb6d42e2008-07-10 12:46:01 -0400864 # ls -ltr
865 [...]
GeunSik Lim156f5a72009-06-02 15:01:37 +0900866 # echo 0 > tracing_enabled
Albin Tonnerre4a88d442009-08-31 22:40:08 +0200867 # cat trace
Steven Rostedteb6d42e2008-07-10 12:46:01 -0400868# tracer: preemptirqsoff
869#
870preemptirqsoff latency trace v1.1.5 on 2.6.26-rc8
871--------------------------------------------------------------------
872 latency: 293 us, #3/3, CPU#0 | (M:preempt VP:0, KP:0, SP:0 HP:0 #P:2)
873 -----------------
874 | task: ls-4860 (uid:0 nice:0 policy:0 rt_prio:0)
875 -----------------
876 => started at: apic_timer_interrupt
877 => ended at: __do_softirq
878
879# _------=> CPU#
880# / _-----=> irqs-off
881# | / _----=> need-resched
882# || / _---=> hardirq/softirq
883# ||| / _--=> preempt-depth
884# |||| /
885# ||||| delay
886# cmd pid ||||| time | caller
887# \ / ||||| \ | /
888 ls-4860 0d... 0us!: trace_hardirqs_off_thunk (apic_timer_interrupt)
889 ls-4860 0d.s. 294us : _local_bh_enable (__do_softirq)
890 ls-4860 0d.s1 294us : trace_preempt_on (__do_softirq)
891
892
Steven Rostedteb6d42e2008-07-10 12:46:01 -0400893
894The trace_hardirqs_off_thunk is called from assembly on x86 when
Ingo Molnar57526742009-02-19 12:54:10 +0100895interrupts are disabled in the assembly code. Without the
896function tracing, we do not know if interrupts were enabled
897within the preemption points. We do see that it started with
898preemption enabled.
Steven Rostedteb6d42e2008-07-10 12:46:01 -0400899
900Here is a trace with ftrace_enabled set:
901
902
903# tracer: preemptirqsoff
904#
905preemptirqsoff latency trace v1.1.5 on 2.6.26-rc8
906--------------------------------------------------------------------
907 latency: 105 us, #183/183, CPU#0 | (M:preempt VP:0, KP:0, SP:0 HP:0 #P:2)
908 -----------------
909 | task: sshd-4261 (uid:0 nice:0 policy:0 rt_prio:0)
910 -----------------
911 => started at: write_chan
912 => ended at: __do_softirq
913
914# _------=> CPU#
915# / _-----=> irqs-off
916# | / _----=> need-resched
917# || / _---=> hardirq/softirq
918# ||| / _--=> preempt-depth
919# |||| /
920# ||||| delay
921# cmd pid ||||| time | caller
922# \ / ||||| \ | /
923 ls-4473 0.N.. 0us : preempt_schedule (write_chan)
924 ls-4473 0dN.1 1us : _spin_lock (schedule)
925 ls-4473 0dN.1 2us : add_preempt_count (_spin_lock)
926 ls-4473 0d..2 2us : put_prev_task_fair (schedule)
927[...]
928 ls-4473 0d..2 13us : set_normalized_timespec (ktime_get_ts)
929 ls-4473 0d..2 13us : __switch_to (schedule)
930 sshd-4261 0d..2 14us : finish_task_switch (schedule)
931 sshd-4261 0d..2 14us : _spin_unlock_irq (finish_task_switch)
932 sshd-4261 0d..1 15us : add_preempt_count (_spin_lock_irqsave)
933 sshd-4261 0d..2 16us : _spin_unlock_irqrestore (hrtick_set)
934 sshd-4261 0d..2 16us : do_IRQ (common_interrupt)
935 sshd-4261 0d..2 17us : irq_enter (do_IRQ)
936 sshd-4261 0d..2 17us : idle_cpu (irq_enter)
937 sshd-4261 0d..2 18us : add_preempt_count (irq_enter)
938 sshd-4261 0d.h2 18us : idle_cpu (irq_enter)
939 sshd-4261 0d.h. 18us : handle_fasteoi_irq (do_IRQ)
940 sshd-4261 0d.h. 19us : _spin_lock (handle_fasteoi_irq)
941 sshd-4261 0d.h. 19us : add_preempt_count (_spin_lock)
942 sshd-4261 0d.h1 20us : _spin_unlock (handle_fasteoi_irq)
943 sshd-4261 0d.h1 20us : sub_preempt_count (_spin_unlock)
944[...]
945 sshd-4261 0d.h1 28us : _spin_unlock (handle_fasteoi_irq)
946 sshd-4261 0d.h1 29us : sub_preempt_count (_spin_unlock)
947 sshd-4261 0d.h2 29us : irq_exit (do_IRQ)
948 sshd-4261 0d.h2 29us : sub_preempt_count (irq_exit)
949 sshd-4261 0d..3 30us : do_softirq (irq_exit)
950 sshd-4261 0d... 30us : __do_softirq (do_softirq)
951 sshd-4261 0d... 31us : __local_bh_disable (__do_softirq)
952 sshd-4261 0d... 31us+: add_preempt_count (__local_bh_disable)
953 sshd-4261 0d.s4 34us : add_preempt_count (__local_bh_disable)
954[...]
955 sshd-4261 0d.s3 43us : sub_preempt_count (local_bh_enable_ip)
956 sshd-4261 0d.s4 44us : sub_preempt_count (local_bh_enable_ip)
957 sshd-4261 0d.s3 44us : smp_apic_timer_interrupt (apic_timer_interrupt)
958 sshd-4261 0d.s3 45us : irq_enter (smp_apic_timer_interrupt)
959 sshd-4261 0d.s3 45us : idle_cpu (irq_enter)
960 sshd-4261 0d.s3 46us : add_preempt_count (irq_enter)
961 sshd-4261 0d.H3 46us : idle_cpu (irq_enter)
962 sshd-4261 0d.H3 47us : hrtimer_interrupt (smp_apic_timer_interrupt)
963 sshd-4261 0d.H3 47us : ktime_get (hrtimer_interrupt)
964[...]
965 sshd-4261 0d.H3 81us : tick_program_event (hrtimer_interrupt)
966 sshd-4261 0d.H3 82us : ktime_get (tick_program_event)
967 sshd-4261 0d.H3 82us : ktime_get_ts (ktime_get)
968 sshd-4261 0d.H3 83us : getnstimeofday (ktime_get_ts)
969 sshd-4261 0d.H3 83us : set_normalized_timespec (ktime_get_ts)
970 sshd-4261 0d.H3 84us : clockevents_program_event (tick_program_event)
971 sshd-4261 0d.H3 84us : lapic_next_event (clockevents_program_event)
972 sshd-4261 0d.H3 85us : irq_exit (smp_apic_timer_interrupt)
973 sshd-4261 0d.H3 85us : sub_preempt_count (irq_exit)
974 sshd-4261 0d.s4 86us : sub_preempt_count (irq_exit)
975 sshd-4261 0d.s3 86us : add_preempt_count (__local_bh_disable)
976[...]
977 sshd-4261 0d.s1 98us : sub_preempt_count (net_rx_action)
978 sshd-4261 0d.s. 99us : add_preempt_count (_spin_lock_irq)
979 sshd-4261 0d.s1 99us+: _spin_unlock_irq (run_timer_softirq)
980 sshd-4261 0d.s. 104us : _local_bh_enable (__do_softirq)
981 sshd-4261 0d.s. 104us : sub_preempt_count (_local_bh_enable)
982 sshd-4261 0d.s. 105us : _local_bh_enable (__do_softirq)
983 sshd-4261 0d.s1 105us : trace_preempt_on (__do_softirq)
984
985
Ingo Molnar57526742009-02-19 12:54:10 +0100986This is a very interesting trace. It started with the preemption
987of the ls task. We see that the task had the "need_resched" bit
988set via the 'N' in the trace. Interrupts were disabled before
989the spin_lock at the beginning of the trace. We see that a
990schedule took place to run sshd. When the interrupts were
991enabled, we took an interrupt. On return from the interrupt
992handler, the softirq ran. We took another interrupt while
993running the softirq as we see from the capital 'H'.
Steven Rostedteb6d42e2008-07-10 12:46:01 -0400994
995
996wakeup
997------
998
Ingo Molnar57526742009-02-19 12:54:10 +0100999In a Real-Time environment it is very important to know the
1000wakeup time it takes for the highest priority task that is woken
1001up to the time that it executes. This is also known as "schedule
1002latency". I stress the point that this is about RT tasks. It is
1003also important to know the scheduling latency of non-RT tasks,
1004but the average schedule latency is better for non-RT tasks.
1005Tools like LatencyTop are more appropriate for such
1006measurements.
Steven Rostedteb6d42e2008-07-10 12:46:01 -04001007
Steven Rostedta41eeba2008-07-14 16:41:12 -04001008Real-Time environments are interested in the worst case latency.
Ingo Molnar57526742009-02-19 12:54:10 +01001009That is the longest latency it takes for something to happen,
1010and not the average. We can have a very fast scheduler that may
1011only have a large latency once in a while, but that would not
1012work well with Real-Time tasks. The wakeup tracer was designed
1013to record the worst case wakeups of RT tasks. Non-RT tasks are
1014not recorded because the tracer only records one worst case and
1015tracing non-RT tasks that are unpredictable will overwrite the
1016worst case latency of RT tasks.
Steven Rostedteb6d42e2008-07-10 12:46:01 -04001017
Ingo Molnar57526742009-02-19 12:54:10 +01001018Since this tracer only deals with RT tasks, we will run this
1019slightly differently than we did with the previous tracers.
1020Instead of performing an 'ls', we will run 'sleep 1' under
1021'chrt' which changes the priority of the task.
Steven Rostedteb6d42e2008-07-10 12:46:01 -04001022
GeunSik Lim156f5a72009-06-02 15:01:37 +09001023 # echo wakeup > current_tracer
Albin Tonnerre4a88d442009-08-31 22:40:08 +02001024 # echo latency-format > trace_options
GeunSik Lim156f5a72009-06-02 15:01:37 +09001025 # echo 0 > tracing_max_latency
1026 # echo 1 > tracing_enabled
Steven Rostedteb6d42e2008-07-10 12:46:01 -04001027 # chrt -f 5 sleep 1
GeunSik Lim156f5a72009-06-02 15:01:37 +09001028 # echo 0 > tracing_enabled
Albin Tonnerre4a88d442009-08-31 22:40:08 +02001029 # cat trace
Steven Rostedteb6d42e2008-07-10 12:46:01 -04001030# tracer: wakeup
1031#
1032wakeup latency trace v1.1.5 on 2.6.26-rc8
1033--------------------------------------------------------------------
1034 latency: 4 us, #2/2, CPU#1 | (M:preempt VP:0, KP:0, SP:0 HP:0 #P:2)
1035 -----------------
1036 | task: sleep-4901 (uid:0 nice:0 policy:1 rt_prio:5)
1037 -----------------
1038
1039# _------=> CPU#
1040# / _-----=> irqs-off
1041# | / _----=> need-resched
1042# || / _---=> hardirq/softirq
1043# ||| / _--=> preempt-depth
1044# |||| /
1045# ||||| delay
1046# cmd pid ||||| time | caller
1047# \ / ||||| \ | /
1048 <idle>-0 1d.h4 0us+: try_to_wake_up (wake_up_process)
1049 <idle>-0 1d..4 4us : schedule (cpu_idle)
1050
1051
Ingo Molnar57526742009-02-19 12:54:10 +01001052Running this on an idle system, we see that it only took 4
1053microseconds to perform the task switch. Note, since the trace
1054marker in the schedule is before the actual "switch", we stop
1055the tracing when the recorded task is about to schedule in. This
1056may change if we add a new marker at the end of the scheduler.
Steven Rostedteb6d42e2008-07-10 12:46:01 -04001057
Ingo Molnar57526742009-02-19 12:54:10 +01001058Notice that the recorded task is 'sleep' with the PID of 4901
1059and it has an rt_prio of 5. This priority is user-space priority
1060and not the internal kernel priority. The policy is 1 for
1061SCHED_FIFO and 2 for SCHED_RR.
Steven Rostedteb6d42e2008-07-10 12:46:01 -04001062
1063Doing the same with chrt -r 5 and ftrace_enabled set.
1064
1065# tracer: wakeup
1066#
1067wakeup latency trace v1.1.5 on 2.6.26-rc8
1068--------------------------------------------------------------------
1069 latency: 50 us, #60/60, CPU#1 | (M:preempt VP:0, KP:0, SP:0 HP:0 #P:2)
1070 -----------------
1071 | task: sleep-4068 (uid:0 nice:0 policy:2 rt_prio:5)
1072 -----------------
1073
1074# _------=> CPU#
1075# / _-----=> irqs-off
1076# | / _----=> need-resched
1077# || / _---=> hardirq/softirq
1078# ||| / _--=> preempt-depth
1079# |||| /
1080# ||||| delay
1081# cmd pid ||||| time | caller
1082# \ / ||||| \ | /
1083ksoftirq-7 1d.H3 0us : try_to_wake_up (wake_up_process)
1084ksoftirq-7 1d.H4 1us : sub_preempt_count (marker_probe_cb)
1085ksoftirq-7 1d.H3 2us : check_preempt_wakeup (try_to_wake_up)
1086ksoftirq-7 1d.H3 3us : update_curr (check_preempt_wakeup)
1087ksoftirq-7 1d.H3 4us : calc_delta_mine (update_curr)
1088ksoftirq-7 1d.H3 5us : __resched_task (check_preempt_wakeup)
1089ksoftirq-7 1d.H3 6us : task_wake_up_rt (try_to_wake_up)
1090ksoftirq-7 1d.H3 7us : _spin_unlock_irqrestore (try_to_wake_up)
1091[...]
1092ksoftirq-7 1d.H2 17us : irq_exit (smp_apic_timer_interrupt)
1093ksoftirq-7 1d.H2 18us : sub_preempt_count (irq_exit)
1094ksoftirq-7 1d.s3 19us : sub_preempt_count (irq_exit)
1095ksoftirq-7 1..s2 20us : rcu_process_callbacks (__do_softirq)
1096[...]
1097ksoftirq-7 1..s2 26us : __rcu_process_callbacks (rcu_process_callbacks)
1098ksoftirq-7 1d.s2 27us : _local_bh_enable (__do_softirq)
1099ksoftirq-7 1d.s2 28us : sub_preempt_count (_local_bh_enable)
1100ksoftirq-7 1.N.3 29us : sub_preempt_count (ksoftirqd)
1101ksoftirq-7 1.N.2 30us : _cond_resched (ksoftirqd)
1102ksoftirq-7 1.N.2 31us : __cond_resched (_cond_resched)
1103ksoftirq-7 1.N.2 32us : add_preempt_count (__cond_resched)
1104ksoftirq-7 1.N.2 33us : schedule (__cond_resched)
1105ksoftirq-7 1.N.2 33us : add_preempt_count (schedule)
1106ksoftirq-7 1.N.3 34us : hrtick_clear (schedule)
1107ksoftirq-7 1dN.3 35us : _spin_lock (schedule)
1108ksoftirq-7 1dN.3 36us : add_preempt_count (_spin_lock)
1109ksoftirq-7 1d..4 37us : put_prev_task_fair (schedule)
1110ksoftirq-7 1d..4 38us : update_curr (put_prev_task_fair)
1111[...]
1112ksoftirq-7 1d..5 47us : _spin_trylock (tracing_record_cmdline)
1113ksoftirq-7 1d..5 48us : add_preempt_count (_spin_trylock)
1114ksoftirq-7 1d..6 49us : _spin_unlock (tracing_record_cmdline)
1115ksoftirq-7 1d..6 49us : sub_preempt_count (_spin_unlock)
1116ksoftirq-7 1d..4 50us : schedule (__cond_resched)
1117
Ingo Molnar57526742009-02-19 12:54:10 +01001118The interrupt went off while running ksoftirqd. This task runs
1119at SCHED_OTHER. Why did not we see the 'N' set early? This may
1120be a harmless bug with x86_32 and 4K stacks. On x86_32 with 4K
1121stacks configured, the interrupt and softirq run with their own
1122stack. Some information is held on the top of the task's stack
1123(need_resched and preempt_count are both stored there). The
1124setting of the NEED_RESCHED bit is done directly to the task's
1125stack, but the reading of the NEED_RESCHED is done by looking at
1126the current stack, which in this case is the stack for the hard
1127interrupt. This hides the fact that NEED_RESCHED has been set.
1128We do not see the 'N' until we switch back to the task's
Steven Rostedta41eeba2008-07-14 16:41:12 -04001129assigned stack.
Steven Rostedteb6d42e2008-07-10 12:46:01 -04001130
Steven Rostedt9b803c02008-11-03 15:15:08 -05001131function
1132--------
Steven Rostedteb6d42e2008-07-10 12:46:01 -04001133
Steven Rostedt9b803c02008-11-03 15:15:08 -05001134This tracer is the function tracer. Enabling the function tracer
Ingo Molnar57526742009-02-19 12:54:10 +01001135can be done from the debug file system. Make sure the
1136ftrace_enabled is set; otherwise this tracer is a nop.
Steven Rostedteb6d42e2008-07-10 12:46:01 -04001137
1138 # sysctl kernel.ftrace_enabled=1
GeunSik Lim156f5a72009-06-02 15:01:37 +09001139 # echo function > current_tracer
1140 # echo 1 > tracing_enabled
Steven Rostedteb6d42e2008-07-10 12:46:01 -04001141 # usleep 1
GeunSik Lim156f5a72009-06-02 15:01:37 +09001142 # echo 0 > tracing_enabled
1143 # cat trace
Steven Rostedt9b803c02008-11-03 15:15:08 -05001144# tracer: function
Steven Rostedteb6d42e2008-07-10 12:46:01 -04001145#
1146# TASK-PID CPU# TIMESTAMP FUNCTION
1147# | | | | |
1148 bash-4003 [00] 123.638713: finish_task_switch <-schedule
1149 bash-4003 [00] 123.638714: _spin_unlock_irq <-finish_task_switch
1150 bash-4003 [00] 123.638714: sub_preempt_count <-_spin_unlock_irq
1151 bash-4003 [00] 123.638715: hrtick_set <-schedule
1152 bash-4003 [00] 123.638715: _spin_lock_irqsave <-hrtick_set
1153 bash-4003 [00] 123.638716: add_preempt_count <-_spin_lock_irqsave
1154 bash-4003 [00] 123.638716: _spin_unlock_irqrestore <-hrtick_set
1155 bash-4003 [00] 123.638717: sub_preempt_count <-_spin_unlock_irqrestore
1156 bash-4003 [00] 123.638717: hrtick_clear <-hrtick_set
1157 bash-4003 [00] 123.638718: sub_preempt_count <-schedule
1158 bash-4003 [00] 123.638718: sub_preempt_count <-preempt_schedule
1159 bash-4003 [00] 123.638719: wait_for_completion <-__stop_machine_run
1160 bash-4003 [00] 123.638719: wait_for_common <-wait_for_completion
1161 bash-4003 [00] 123.638720: _spin_lock_irq <-wait_for_common
1162 bash-4003 [00] 123.638720: add_preempt_count <-_spin_lock_irq
1163[...]
1164
1165
Ingo Molnar57526742009-02-19 12:54:10 +01001166Note: function tracer uses ring buffers to store the above
1167entries. The newest data may overwrite the oldest data.
1168Sometimes using echo to stop the trace is not sufficient because
1169the tracing could have overwritten the data that you wanted to
1170record. For this reason, it is sometimes better to disable
1171tracing directly from a program. This allows you to stop the
1172tracing at the point that you hit the part that you are
1173interested in. To disable the tracing directly from a C program,
1174something like following code snippet can be used:
Steven Rostedteb6d42e2008-07-10 12:46:01 -04001175
1176int trace_fd;
1177[...]
1178int main(int argc, char *argv[]) {
1179 [...]
GeunSik Lim156f5a72009-06-02 15:01:37 +09001180 trace_fd = open(tracing_file("tracing_enabled"), O_WRONLY);
Steven Rostedteb6d42e2008-07-10 12:46:01 -04001181 [...]
1182 if (condition_hit()) {
Steven Rostedtf2d9c742008-07-15 10:57:33 -04001183 write(trace_fd, "0", 1);
Steven Rostedteb6d42e2008-07-10 12:46:01 -04001184 }
1185 [...]
1186}
1187
Steven Rostedtdf4fc312008-11-26 00:16:23 -05001188
1189Single thread tracing
1190---------------------
1191
GeunSik Lim156f5a72009-06-02 15:01:37 +09001192By writing into set_ftrace_pid you can trace a
Steven Rostedtdf4fc312008-11-26 00:16:23 -05001193single thread. For example:
1194
GeunSik Lim156f5a72009-06-02 15:01:37 +09001195# cat set_ftrace_pid
Steven Rostedtdf4fc312008-11-26 00:16:23 -05001196no pid
GeunSik Lim156f5a72009-06-02 15:01:37 +09001197# echo 3111 > set_ftrace_pid
1198# cat set_ftrace_pid
Steven Rostedtdf4fc312008-11-26 00:16:23 -050011993111
GeunSik Lim156f5a72009-06-02 15:01:37 +09001200# echo function > current_tracer
1201# cat trace | head
Steven Rostedtdf4fc312008-11-26 00:16:23 -05001202 # tracer: function
1203 #
1204 # TASK-PID CPU# TIMESTAMP FUNCTION
1205 # | | | | |
1206 yum-updatesd-3111 [003] 1637.254676: finish_task_switch <-thread_return
1207 yum-updatesd-3111 [003] 1637.254681: hrtimer_cancel <-schedule_hrtimeout_range
1208 yum-updatesd-3111 [003] 1637.254682: hrtimer_try_to_cancel <-hrtimer_cancel
1209 yum-updatesd-3111 [003] 1637.254683: lock_hrtimer_base <-hrtimer_try_to_cancel
1210 yum-updatesd-3111 [003] 1637.254685: fget_light <-do_sys_poll
1211 yum-updatesd-3111 [003] 1637.254686: pipe_poll <-do_sys_poll
GeunSik Lim156f5a72009-06-02 15:01:37 +09001212# echo -1 > set_ftrace_pid
1213# cat trace |head
Steven Rostedtdf4fc312008-11-26 00:16:23 -05001214 # tracer: function
1215 #
1216 # TASK-PID CPU# TIMESTAMP FUNCTION
1217 # | | | | |
1218 ##### CPU 3 buffer started ####
1219 yum-updatesd-3111 [003] 1701.957688: free_poll_entry <-poll_freewait
1220 yum-updatesd-3111 [003] 1701.957689: remove_wait_queue <-free_poll_entry
1221 yum-updatesd-3111 [003] 1701.957691: fput <-free_poll_entry
1222 yum-updatesd-3111 [003] 1701.957692: audit_syscall_exit <-sysret_audit
1223 yum-updatesd-3111 [003] 1701.957693: path_put <-audit_syscall_exit
1224
1225If you want to trace a function when executing, you could use
1226something like this simple program:
1227
1228#include <stdio.h>
1229#include <stdlib.h>
1230#include <sys/types.h>
1231#include <sys/stat.h>
1232#include <fcntl.h>
1233#include <unistd.h>
Jiri Olsa67b394f2009-10-23 19:36:18 -04001234#include <string.h>
Steven Rostedtdf4fc312008-11-26 00:16:23 -05001235
GeunSik Lim156f5a72009-06-02 15:01:37 +09001236#define _STR(x) #x
1237#define STR(x) _STR(x)
1238#define MAX_PATH 256
1239
1240const char *find_debugfs(void)
1241{
1242 static char debugfs[MAX_PATH+1];
1243 static int debugfs_found;
1244 char type[100];
1245 FILE *fp;
1246
1247 if (debugfs_found)
1248 return debugfs;
1249
1250 if ((fp = fopen("/proc/mounts","r")) == NULL) {
1251 perror("/proc/mounts");
1252 return NULL;
1253 }
1254
1255 while (fscanf(fp, "%*s %"
1256 STR(MAX_PATH)
1257 "s %99s %*s %*d %*d\n",
1258 debugfs, type) == 2) {
1259 if (strcmp(type, "debugfs") == 0)
1260 break;
1261 }
1262 fclose(fp);
1263
1264 if (strcmp(type, "debugfs") != 0) {
1265 fprintf(stderr, "debugfs not mounted");
1266 return NULL;
1267 }
1268
Jiri Olsa67b394f2009-10-23 19:36:18 -04001269 strcat(debugfs, "/tracing/");
GeunSik Lim156f5a72009-06-02 15:01:37 +09001270 debugfs_found = 1;
1271
1272 return debugfs;
1273}
1274
1275const char *tracing_file(const char *file_name)
1276{
1277 static char trace_file[MAX_PATH+1];
1278 snprintf(trace_file, MAX_PATH, "%s/%s", find_debugfs(), file_name);
1279 return trace_file;
1280}
1281
Steven Rostedtdf4fc312008-11-26 00:16:23 -05001282int main (int argc, char **argv)
1283{
1284 if (argc < 1)
1285 exit(-1);
1286
1287 if (fork() > 0) {
1288 int fd, ffd;
1289 char line[64];
1290 int s;
1291
GeunSik Lim156f5a72009-06-02 15:01:37 +09001292 ffd = open(tracing_file("current_tracer"), O_WRONLY);
Steven Rostedtdf4fc312008-11-26 00:16:23 -05001293 if (ffd < 0)
1294 exit(-1);
1295 write(ffd, "nop", 3);
1296
GeunSik Lim156f5a72009-06-02 15:01:37 +09001297 fd = open(tracing_file("set_ftrace_pid"), O_WRONLY);
Steven Rostedtdf4fc312008-11-26 00:16:23 -05001298 s = sprintf(line, "%d\n", getpid());
1299 write(fd, line, s);
1300
1301 write(ffd, "function", 8);
1302
1303 close(fd);
1304 close(ffd);
1305
1306 execvp(argv[1], argv+1);
1307 }
1308
1309 return 0;
1310}
1311
Markus Metzgere2ea5392009-01-19 10:35:58 +01001312
1313hw-branch-tracer (x86 only)
1314---------------------------
1315
1316This tracer uses the x86 last branch tracing hardware feature to
1317collect a branch trace on all cpus with relatively low overhead.
1318
1319The tracer uses a fixed-size circular buffer per cpu and only
1320traces ring 0 branches. The trace file dumps that buffer in the
1321following format:
1322
1323# tracer: hw-branch-tracer
1324#
1325# CPU# TO <- FROM
1326 0 scheduler_tick+0xb5/0x1bf <- task_tick_idle+0x5/0x6
1327 2 run_posix_cpu_timers+0x2b/0x72a <- run_posix_cpu_timers+0x25/0x72a
1328 0 scheduler_tick+0x139/0x1bf <- scheduler_tick+0xed/0x1bf
1329 0 scheduler_tick+0x17c/0x1bf <- scheduler_tick+0x148/0x1bf
1330 2 run_posix_cpu_timers+0x9e/0x72a <- run_posix_cpu_timers+0x5e/0x72a
1331 0 scheduler_tick+0x1b6/0x1bf <- scheduler_tick+0x1aa/0x1bf
1332
1333
Ingo Molnar57526742009-02-19 12:54:10 +01001334The tracer may be used to dump the trace for the oops'ing cpu on
1335a kernel oops into the system log. To enable this,
1336ftrace_dump_on_oops must be set. To set ftrace_dump_on_oops, one
1337can either use the sysctl function or set it via the proc system
1338interface.
Markus Metzgere2ea5392009-01-19 10:35:58 +01001339
1340 sysctl kernel.ftrace_dump_on_oops=1
1341
1342or
1343
1344 echo 1 > /proc/sys/kernel/ftrace_dump_on_oops
1345
1346
Ingo Molnar57526742009-02-19 12:54:10 +01001347Here's an example of such a dump after a null pointer
1348dereference in a kernel module:
Markus Metzgere2ea5392009-01-19 10:35:58 +01001349
1350[57848.105921] BUG: unable to handle kernel NULL pointer dereference at 0000000000000000
1351[57848.106019] IP: [<ffffffffa0000006>] open+0x6/0x14 [oops]
1352[57848.106019] PGD 2354e9067 PUD 2375e7067 PMD 0
1353[57848.106019] Oops: 0002 [#1] SMP
1354[57848.106019] last sysfs file: /sys/devices/pci0000:00/0000:00:1e.0/0000:20:05.0/local_cpus
1355[57848.106019] Dumping ftrace buffer:
1356[57848.106019] ---------------------------------
1357[...]
1358[57848.106019] 0 chrdev_open+0xe6/0x165 <- cdev_put+0x23/0x24
1359[57848.106019] 0 chrdev_open+0x117/0x165 <- chrdev_open+0xfa/0x165
1360[57848.106019] 0 chrdev_open+0x120/0x165 <- chrdev_open+0x11c/0x165
1361[57848.106019] 0 chrdev_open+0x134/0x165 <- chrdev_open+0x12b/0x165
1362[57848.106019] 0 open+0x0/0x14 [oops] <- chrdev_open+0x144/0x165
1363[57848.106019] 0 page_fault+0x0/0x30 <- open+0x6/0x14 [oops]
1364[57848.106019] 0 error_entry+0x0/0x5b <- page_fault+0x4/0x30
1365[57848.106019] 0 error_kernelspace+0x0/0x31 <- error_entry+0x59/0x5b
1366[57848.106019] 0 error_sti+0x0/0x1 <- error_kernelspace+0x2d/0x31
1367[57848.106019] 0 page_fault+0x9/0x30 <- error_sti+0x0/0x1
1368[57848.106019] 0 do_page_fault+0x0/0x881 <- page_fault+0x1a/0x30
1369[...]
1370[57848.106019] 0 do_page_fault+0x66b/0x881 <- is_prefetch+0x1ee/0x1f2
1371[57848.106019] 0 do_page_fault+0x6e0/0x881 <- do_page_fault+0x67a/0x881
1372[57848.106019] 0 oops_begin+0x0/0x96 <- do_page_fault+0x6e0/0x881
1373[57848.106019] 0 trace_hw_branch_oops+0x0/0x2d <- oops_begin+0x9/0x96
1374[...]
1375[57848.106019] 0 ds_suspend_bts+0x2a/0xe3 <- ds_suspend_bts+0x1a/0xe3
1376[57848.106019] ---------------------------------
1377[57848.106019] CPU 0
1378[57848.106019] Modules linked in: oops
1379[57848.106019] Pid: 5542, comm: cat Tainted: G W 2.6.28 #23
1380[57848.106019] RIP: 0010:[<ffffffffa0000006>] [<ffffffffa0000006>] open+0x6/0x14 [oops]
1381[57848.106019] RSP: 0018:ffff880235457d48 EFLAGS: 00010246
1382[...]
1383
1384
Frederic Weisbecker985ec202009-02-18 06:35:34 +01001385function graph tracer
1386---------------------------
1387
Ingo Molnar57526742009-02-19 12:54:10 +01001388This tracer is similar to the function tracer except that it
1389probes a function on its entry and its exit. This is done by
1390using a dynamically allocated stack of return addresses in each
1391task_struct. On function entry the tracer overwrites the return
1392address of each function traced to set a custom probe. Thus the
1393original return address is stored on the stack of return address
1394in the task_struct.
Frederic Weisbecker985ec202009-02-18 06:35:34 +01001395
Ingo Molnar57526742009-02-19 12:54:10 +01001396Probing on both ends of a function leads to special features
1397such as:
Frederic Weisbecker985ec202009-02-18 06:35:34 +01001398
Ingo Molnar57526742009-02-19 12:54:10 +01001399- measure of a function's time execution
1400- having a reliable call stack to draw function calls graph
Frederic Weisbecker985ec202009-02-18 06:35:34 +01001401
1402This tracer is useful in several situations:
1403
Ingo Molnar57526742009-02-19 12:54:10 +01001404- you want to find the reason of a strange kernel behavior and
1405 need to see what happens in detail on any areas (or specific
1406 ones).
1407
1408- you are experiencing weird latencies but it's difficult to
1409 find its origin.
1410
1411- you want to find quickly which path is taken by a specific
1412 function
1413
1414- you just want to peek inside a working kernel and want to see
1415 what happens there.
Frederic Weisbecker985ec202009-02-18 06:35:34 +01001416
1417# tracer: function_graph
1418#
1419# CPU DURATION FUNCTION CALLS
1420# | | | | | | |
1421
1422 0) | sys_open() {
1423 0) | do_sys_open() {
1424 0) | getname() {
1425 0) | kmem_cache_alloc() {
1426 0) 1.382 us | __might_sleep();
1427 0) 2.478 us | }
1428 0) | strncpy_from_user() {
1429 0) | might_fault() {
1430 0) 1.389 us | __might_sleep();
1431 0) 2.553 us | }
1432 0) 3.807 us | }
1433 0) 7.876 us | }
1434 0) | alloc_fd() {
1435 0) 0.668 us | _spin_lock();
1436 0) 0.570 us | expand_files();
1437 0) 0.586 us | _spin_unlock();
1438
1439
Ingo Molnar57526742009-02-19 12:54:10 +01001440There are several columns that can be dynamically
1441enabled/disabled. You can use every combination of options you
1442want, depending on your needs.
Frederic Weisbecker985ec202009-02-18 06:35:34 +01001443
Ingo Molnar57526742009-02-19 12:54:10 +01001444- The cpu number on which the function executed is default
1445 enabled. It is sometimes better to only trace one cpu (see
1446 tracing_cpu_mask file) or you might sometimes see unordered
1447 function calls while cpu tracing switch.
Frederic Weisbecker985ec202009-02-18 06:35:34 +01001448
GeunSik Lim156f5a72009-06-02 15:01:37 +09001449 hide: echo nofuncgraph-cpu > trace_options
1450 show: echo funcgraph-cpu > trace_options
Frederic Weisbecker985ec202009-02-18 06:35:34 +01001451
Ingo Molnar57526742009-02-19 12:54:10 +01001452- The duration (function's time of execution) is displayed on
1453 the closing bracket line of a function or on the same line
1454 than the current function in case of a leaf one. It is default
1455 enabled.
Frederic Weisbecker985ec202009-02-18 06:35:34 +01001456
GeunSik Lim156f5a72009-06-02 15:01:37 +09001457 hide: echo nofuncgraph-duration > trace_options
1458 show: echo funcgraph-duration > trace_options
Frederic Weisbecker985ec202009-02-18 06:35:34 +01001459
Ingo Molnar57526742009-02-19 12:54:10 +01001460- The overhead field precedes the duration field in case of
1461 reached duration thresholds.
Frederic Weisbecker985ec202009-02-18 06:35:34 +01001462
GeunSik Lim156f5a72009-06-02 15:01:37 +09001463 hide: echo nofuncgraph-overhead > trace_options
1464 show: echo funcgraph-overhead > trace_options
Frederic Weisbecker985ec202009-02-18 06:35:34 +01001465 depends on: funcgraph-duration
1466
1467 ie:
1468
1469 0) | up_write() {
1470 0) 0.646 us | _spin_lock_irqsave();
1471 0) 0.684 us | _spin_unlock_irqrestore();
1472 0) 3.123 us | }
1473 0) 0.548 us | fput();
1474 0) + 58.628 us | }
1475
1476 [...]
1477
1478 0) | putname() {
1479 0) | kmem_cache_free() {
1480 0) 0.518 us | __phys_addr();
1481 0) 1.757 us | }
1482 0) 2.861 us | }
1483 0) ! 115.305 us | }
1484 0) ! 116.402 us | }
1485
1486 + means that the function exceeded 10 usecs.
1487 ! means that the function exceeded 100 usecs.
1488
1489
Ingo Molnar57526742009-02-19 12:54:10 +01001490- The task/pid field displays the thread cmdline and pid which
1491 executed the function. It is default disabled.
Frederic Weisbecker985ec202009-02-18 06:35:34 +01001492
GeunSik Lim156f5a72009-06-02 15:01:37 +09001493 hide: echo nofuncgraph-proc > trace_options
1494 show: echo funcgraph-proc > trace_options
Frederic Weisbecker985ec202009-02-18 06:35:34 +01001495
1496 ie:
1497
1498 # tracer: function_graph
1499 #
1500 # CPU TASK/PID DURATION FUNCTION CALLS
1501 # | | | | | | | | |
1502 0) sh-4802 | | d_free() {
1503 0) sh-4802 | | call_rcu() {
1504 0) sh-4802 | | __call_rcu() {
1505 0) sh-4802 | 0.616 us | rcu_process_gp_end();
1506 0) sh-4802 | 0.586 us | check_for_new_grace_period();
1507 0) sh-4802 | 2.899 us | }
1508 0) sh-4802 | 4.040 us | }
1509 0) sh-4802 | 5.151 us | }
1510 0) sh-4802 | + 49.370 us | }
1511
1512
Ingo Molnar57526742009-02-19 12:54:10 +01001513- The absolute time field is an absolute timestamp given by the
1514 system clock since it started. A snapshot of this time is
1515 given on each entry/exit of functions
Frederic Weisbecker985ec202009-02-18 06:35:34 +01001516
GeunSik Lim156f5a72009-06-02 15:01:37 +09001517 hide: echo nofuncgraph-abstime > trace_options
1518 show: echo funcgraph-abstime > trace_options
Frederic Weisbecker985ec202009-02-18 06:35:34 +01001519
1520 ie:
1521
1522 #
1523 # TIME CPU DURATION FUNCTION CALLS
1524 # | | | | | | | |
1525 360.774522 | 1) 0.541 us | }
1526 360.774522 | 1) 4.663 us | }
1527 360.774523 | 1) 0.541 us | __wake_up_bit();
1528 360.774524 | 1) 6.796 us | }
1529 360.774524 | 1) 7.952 us | }
1530 360.774525 | 1) 9.063 us | }
1531 360.774525 | 1) 0.615 us | journal_mark_dirty();
1532 360.774527 | 1) 0.578 us | __brelse();
1533 360.774528 | 1) | reiserfs_prepare_for_journal() {
1534 360.774528 | 1) | unlock_buffer() {
1535 360.774529 | 1) | wake_up_bit() {
1536 360.774529 | 1) | bit_waitqueue() {
1537 360.774530 | 1) 0.594 us | __phys_addr();
1538
1539
Ingo Molnar57526742009-02-19 12:54:10 +01001540You can put some comments on specific functions by using
Ingo Molnar5e1607a2009-03-05 10:24:48 +01001541trace_printk() For example, if you want to put a comment inside
Ingo Molnar57526742009-02-19 12:54:10 +01001542the __might_sleep() function, you just have to include
Ingo Molnar5e1607a2009-03-05 10:24:48 +01001543<linux/ftrace.h> and call trace_printk() inside __might_sleep()
Frederic Weisbecker985ec202009-02-18 06:35:34 +01001544
Ingo Molnar5e1607a2009-03-05 10:24:48 +01001545trace_printk("I'm a comment!\n")
Frederic Weisbecker985ec202009-02-18 06:35:34 +01001546
1547will produce:
1548
1549 1) | __might_sleep() {
1550 1) | /* I'm a comment! */
1551 1) 1.449 us | }
1552
1553
Ingo Molnar57526742009-02-19 12:54:10 +01001554You might find other useful features for this tracer in the
1555following "dynamic ftrace" section such as tracing only specific
1556functions or tasks.
Frederic Weisbecker985ec202009-02-18 06:35:34 +01001557
Steven Rostedteb6d42e2008-07-10 12:46:01 -04001558dynamic ftrace
1559--------------
1560
Steven Rostedtf2d9c742008-07-15 10:57:33 -04001561If CONFIG_DYNAMIC_FTRACE is set, the system will run with
Steven Rostedteb6d42e2008-07-10 12:46:01 -04001562virtually no overhead when function tracing is disabled. The way
1563this works is the mcount function call (placed at the start of
Ingo Molnar57526742009-02-19 12:54:10 +01001564every kernel function, produced by the -pg switch in gcc),
1565starts of pointing to a simple return. (Enabling FTRACE will
1566include the -pg switch in the compiling of the kernel.)
Steven Rostedteb6d42e2008-07-10 12:46:01 -04001567
Steven Rostedt9b803c02008-11-03 15:15:08 -05001568At compile time every C file object is run through the
1569recordmcount.pl script (located in the scripts directory). This
1570script will process the C object using objdump to find all the
Ingo Molnar57526742009-02-19 12:54:10 +01001571locations in the .text section that call mcount. (Note, only the
1572.text section is processed, since processing other sections like
1573.init.text may cause races due to those sections being freed).
Steven Rostedteb6d42e2008-07-10 12:46:01 -04001574
Ingo Molnar57526742009-02-19 12:54:10 +01001575A new section called "__mcount_loc" is created that holds
1576references to all the mcount call sites in the .text section.
1577This section is compiled back into the original object. The
1578final linker will add all these references into a single table.
Steven Rostedt9b803c02008-11-03 15:15:08 -05001579
1580On boot up, before SMP is initialized, the dynamic ftrace code
Ingo Molnar57526742009-02-19 12:54:10 +01001581scans this table and updates all the locations into nops. It
1582also records the locations, which are added to the
1583available_filter_functions list. Modules are processed as they
1584are loaded and before they are executed. When a module is
1585unloaded, it also removes its functions from the ftrace function
1586list. This is automatic in the module unload code, and the
1587module author does not need to worry about it.
Steven Rostedt9b803c02008-11-03 15:15:08 -05001588
Ingo Molnar57526742009-02-19 12:54:10 +01001589When tracing is enabled, kstop_machine is called to prevent
1590races with the CPUS executing code being modified (which can
Daniel Mack3ad2f3f2010-02-03 08:01:28 +08001591cause the CPU to do undesirable things), and the nops are
Ingo Molnar57526742009-02-19 12:54:10 +01001592patched back to calls. But this time, they do not call mcount
1593(which is just a function stub). They now call into the ftrace
1594infrastructure.
Steven Rostedteb6d42e2008-07-10 12:46:01 -04001595
1596One special side-effect to the recording of the functions being
Steven Rostedtf2d9c742008-07-15 10:57:33 -04001597traced is that we can now selectively choose which functions we
Ingo Molnar57526742009-02-19 12:54:10 +01001598wish to trace and which ones we want the mcount calls to remain
1599as nops.
Steven Rostedteb6d42e2008-07-10 12:46:01 -04001600
Ingo Molnar57526742009-02-19 12:54:10 +01001601Two files are used, one for enabling and one for disabling the
1602tracing of specified functions. They are:
Steven Rostedteb6d42e2008-07-10 12:46:01 -04001603
1604 set_ftrace_filter
1605
1606and
1607
1608 set_ftrace_notrace
1609
Ingo Molnar57526742009-02-19 12:54:10 +01001610A list of available functions that you can add to these files is
1611listed in:
Steven Rostedteb6d42e2008-07-10 12:46:01 -04001612
1613 available_filter_functions
1614
GeunSik Lim156f5a72009-06-02 15:01:37 +09001615 # cat available_filter_functions
Steven Rostedteb6d42e2008-07-10 12:46:01 -04001616put_prev_task_idle
1617kmem_cache_create
1618pick_next_task_rt
1619get_online_cpus
1620pick_next_task_fair
1621mutex_lock
1622[...]
1623
Steven Rostedtf2d9c742008-07-15 10:57:33 -04001624If I am only interested in sys_nanosleep and hrtimer_interrupt:
Steven Rostedteb6d42e2008-07-10 12:46:01 -04001625
1626 # echo sys_nanosleep hrtimer_interrupt \
GeunSik Lim156f5a72009-06-02 15:01:37 +09001627 > set_ftrace_filter
Yang Hongyang6993b1b2010-01-25 11:10:32 +08001628 # echo function > current_tracer
GeunSik Lim156f5a72009-06-02 15:01:37 +09001629 # echo 1 > tracing_enabled
Steven Rostedteb6d42e2008-07-10 12:46:01 -04001630 # usleep 1
GeunSik Lim156f5a72009-06-02 15:01:37 +09001631 # echo 0 > tracing_enabled
1632 # cat trace
Steven Rostedteb6d42e2008-07-10 12:46:01 -04001633# tracer: ftrace
1634#
1635# TASK-PID CPU# TIMESTAMP FUNCTION
1636# | | | | |
1637 usleep-4134 [00] 1317.070017: hrtimer_interrupt <-smp_apic_timer_interrupt
1638 usleep-4134 [00] 1317.070111: sys_nanosleep <-syscall_call
1639 <idle>-0 [00] 1317.070115: hrtimer_interrupt <-smp_apic_timer_interrupt
1640
Steven Rostedtf2d9c742008-07-15 10:57:33 -04001641To see which functions are being traced, you can cat the file:
Steven Rostedteb6d42e2008-07-10 12:46:01 -04001642
GeunSik Lim156f5a72009-06-02 15:01:37 +09001643 # cat set_ftrace_filter
Steven Rostedteb6d42e2008-07-10 12:46:01 -04001644hrtimer_interrupt
1645sys_nanosleep
1646
1647
Ingo Molnar57526742009-02-19 12:54:10 +01001648Perhaps this is not enough. The filters also allow simple wild
1649cards. Only the following are currently available
Steven Rostedteb6d42e2008-07-10 12:46:01 -04001650
Steven Rostedta41eeba2008-07-14 16:41:12 -04001651 <match>* - will match functions that begin with <match>
Steven Rostedteb6d42e2008-07-10 12:46:01 -04001652 *<match> - will match functions that end with <match>
1653 *<match>* - will match functions that have <match> in it
1654
Steven Rostedtf2d9c742008-07-15 10:57:33 -04001655These are the only wild cards which are supported.
Steven Rostedteb6d42e2008-07-10 12:46:01 -04001656
1657 <match>*<match> will not work.
1658
Ingo Molnar57526742009-02-19 12:54:10 +01001659Note: It is better to use quotes to enclose the wild cards,
1660 otherwise the shell may expand the parameters into names
1661 of files in the local directory.
walimisc072c242008-11-28 12:21:19 +08001662
GeunSik Lim156f5a72009-06-02 15:01:37 +09001663 # echo 'hrtimer_*' > set_ftrace_filter
Steven Rostedteb6d42e2008-07-10 12:46:01 -04001664
1665Produces:
1666
1667# tracer: ftrace
1668#
1669# TASK-PID CPU# TIMESTAMP FUNCTION
1670# | | | | |
1671 bash-4003 [00] 1480.611794: hrtimer_init <-copy_process
1672 bash-4003 [00] 1480.611941: hrtimer_start <-hrtick_set
1673 bash-4003 [00] 1480.611956: hrtimer_cancel <-hrtick_clear
1674 bash-4003 [00] 1480.611956: hrtimer_try_to_cancel <-hrtimer_cancel
1675 <idle>-0 [00] 1480.612019: hrtimer_get_next_event <-get_next_timer_interrupt
1676 <idle>-0 [00] 1480.612025: hrtimer_get_next_event <-get_next_timer_interrupt
1677 <idle>-0 [00] 1480.612032: hrtimer_get_next_event <-get_next_timer_interrupt
1678 <idle>-0 [00] 1480.612037: hrtimer_get_next_event <-get_next_timer_interrupt
1679 <idle>-0 [00] 1480.612382: hrtimer_get_next_event <-get_next_timer_interrupt
1680
1681
1682Notice that we lost the sys_nanosleep.
1683
GeunSik Lim156f5a72009-06-02 15:01:37 +09001684 # cat set_ftrace_filter
Steven Rostedteb6d42e2008-07-10 12:46:01 -04001685hrtimer_run_queues
1686hrtimer_run_pending
1687hrtimer_init
1688hrtimer_cancel
1689hrtimer_try_to_cancel
1690hrtimer_forward
1691hrtimer_start
1692hrtimer_reprogram
1693hrtimer_force_reprogram
1694hrtimer_get_next_event
1695hrtimer_interrupt
1696hrtimer_nanosleep
1697hrtimer_wakeup
1698hrtimer_get_remaining
1699hrtimer_get_res
1700hrtimer_init_sleeper
1701
1702
1703This is because the '>' and '>>' act just like they do in bash.
1704To rewrite the filters, use '>'
1705To append to the filters, use '>>'
1706
Ingo Molnar57526742009-02-19 12:54:10 +01001707To clear out a filter so that all functions will be recorded
1708again:
Steven Rostedteb6d42e2008-07-10 12:46:01 -04001709
GeunSik Lim156f5a72009-06-02 15:01:37 +09001710 # echo > set_ftrace_filter
1711 # cat set_ftrace_filter
Steven Rostedteb6d42e2008-07-10 12:46:01 -04001712 #
1713
1714Again, now we want to append.
1715
GeunSik Lim156f5a72009-06-02 15:01:37 +09001716 # echo sys_nanosleep > set_ftrace_filter
1717 # cat set_ftrace_filter
Steven Rostedteb6d42e2008-07-10 12:46:01 -04001718sys_nanosleep
GeunSik Lim156f5a72009-06-02 15:01:37 +09001719 # echo 'hrtimer_*' >> set_ftrace_filter
1720 # cat set_ftrace_filter
Steven Rostedteb6d42e2008-07-10 12:46:01 -04001721hrtimer_run_queues
1722hrtimer_run_pending
1723hrtimer_init
1724hrtimer_cancel
1725hrtimer_try_to_cancel
1726hrtimer_forward
1727hrtimer_start
1728hrtimer_reprogram
1729hrtimer_force_reprogram
1730hrtimer_get_next_event
1731hrtimer_interrupt
1732sys_nanosleep
1733hrtimer_nanosleep
1734hrtimer_wakeup
1735hrtimer_get_remaining
1736hrtimer_get_res
1737hrtimer_init_sleeper
1738
1739
Ingo Molnar57526742009-02-19 12:54:10 +01001740The set_ftrace_notrace prevents those functions from being
1741traced.
Steven Rostedteb6d42e2008-07-10 12:46:01 -04001742
GeunSik Lim156f5a72009-06-02 15:01:37 +09001743 # echo '*preempt*' '*lock*' > set_ftrace_notrace
Steven Rostedteb6d42e2008-07-10 12:46:01 -04001744
1745Produces:
1746
1747# tracer: ftrace
1748#
1749# TASK-PID CPU# TIMESTAMP FUNCTION
1750# | | | | |
1751 bash-4043 [01] 115.281644: finish_task_switch <-schedule
1752 bash-4043 [01] 115.281645: hrtick_set <-schedule
1753 bash-4043 [01] 115.281645: hrtick_clear <-hrtick_set
1754 bash-4043 [01] 115.281646: wait_for_completion <-__stop_machine_run
1755 bash-4043 [01] 115.281647: wait_for_common <-wait_for_completion
1756 bash-4043 [01] 115.281647: kthread_stop <-stop_machine_run
1757 bash-4043 [01] 115.281648: init_waitqueue_head <-kthread_stop
1758 bash-4043 [01] 115.281648: wake_up_process <-kthread_stop
1759 bash-4043 [01] 115.281649: try_to_wake_up <-wake_up_process
1760
1761We can see that there's no more lock or preempt tracing.
1762
Frederic Weisbecker985ec202009-02-18 06:35:34 +01001763
Ingo Molnar57526742009-02-19 12:54:10 +01001764Dynamic ftrace with the function graph tracer
1765---------------------------------------------
Frederic Weisbecker985ec202009-02-18 06:35:34 +01001766
Ingo Molnar57526742009-02-19 12:54:10 +01001767Although what has been explained above concerns both the
1768function tracer and the function-graph-tracer, there are some
1769special features only available in the function-graph tracer.
Frederic Weisbecker985ec202009-02-18 06:35:34 +01001770
Ingo Molnar57526742009-02-19 12:54:10 +01001771If you want to trace only one function and all of its children,
1772you just have to echo its name into set_graph_function:
Frederic Weisbecker985ec202009-02-18 06:35:34 +01001773
Ingo Molnar57526742009-02-19 12:54:10 +01001774 echo __do_fault > set_graph_function
Frederic Weisbecker985ec202009-02-18 06:35:34 +01001775
Ingo Molnar57526742009-02-19 12:54:10 +01001776will produce the following "expanded" trace of the __do_fault()
1777function:
Frederic Weisbecker985ec202009-02-18 06:35:34 +01001778
1779 0) | __do_fault() {
1780 0) | filemap_fault() {
1781 0) | find_lock_page() {
1782 0) 0.804 us | find_get_page();
1783 0) | __might_sleep() {
1784 0) 1.329 us | }
1785 0) 3.904 us | }
1786 0) 4.979 us | }
1787 0) 0.653 us | _spin_lock();
1788 0) 0.578 us | page_add_file_rmap();
1789 0) 0.525 us | native_set_pte_at();
1790 0) 0.585 us | _spin_unlock();
1791 0) | unlock_page() {
1792 0) 0.541 us | page_waitqueue();
1793 0) 0.639 us | __wake_up_bit();
1794 0) 2.786 us | }
1795 0) + 14.237 us | }
1796 0) | __do_fault() {
1797 0) | filemap_fault() {
1798 0) | find_lock_page() {
1799 0) 0.698 us | find_get_page();
1800 0) | __might_sleep() {
1801 0) 1.412 us | }
1802 0) 3.950 us | }
1803 0) 5.098 us | }
1804 0) 0.631 us | _spin_lock();
1805 0) 0.571 us | page_add_file_rmap();
1806 0) 0.526 us | native_set_pte_at();
1807 0) 0.586 us | _spin_unlock();
1808 0) | unlock_page() {
1809 0) 0.533 us | page_waitqueue();
1810 0) 0.638 us | __wake_up_bit();
1811 0) 2.793 us | }
1812 0) + 14.012 us | }
1813
Ingo Molnar57526742009-02-19 12:54:10 +01001814You can also expand several functions at once:
Frederic Weisbecker985ec202009-02-18 06:35:34 +01001815
Ingo Molnar57526742009-02-19 12:54:10 +01001816 echo sys_open > set_graph_function
1817 echo sys_close >> set_graph_function
Frederic Weisbecker985ec202009-02-18 06:35:34 +01001818
Ingo Molnar57526742009-02-19 12:54:10 +01001819Now if you want to go back to trace all functions you can clear
1820this special filter via:
Frederic Weisbecker985ec202009-02-18 06:35:34 +01001821
Ingo Molnar57526742009-02-19 12:54:10 +01001822 echo > set_graph_function
Frederic Weisbecker985ec202009-02-18 06:35:34 +01001823
1824
Steven Rostedteb6d42e2008-07-10 12:46:01 -04001825trace_pipe
1826----------
1827
Ingo Molnar57526742009-02-19 12:54:10 +01001828The trace_pipe outputs the same content as the trace file, but
1829the effect on the tracing is different. Every read from
1830trace_pipe is consumed. This means that subsequent reads will be
1831different. The trace is live.
Steven Rostedteb6d42e2008-07-10 12:46:01 -04001832
GeunSik Lim156f5a72009-06-02 15:01:37 +09001833 # echo function > current_tracer
1834 # cat trace_pipe > /tmp/trace.out &
Steven Rostedteb6d42e2008-07-10 12:46:01 -04001835[1] 4153
GeunSik Lim156f5a72009-06-02 15:01:37 +09001836 # echo 1 > tracing_enabled
Steven Rostedteb6d42e2008-07-10 12:46:01 -04001837 # usleep 1
GeunSik Lim156f5a72009-06-02 15:01:37 +09001838 # echo 0 > tracing_enabled
1839 # cat trace
Steven Rostedt9b803c02008-11-03 15:15:08 -05001840# tracer: function
Steven Rostedteb6d42e2008-07-10 12:46:01 -04001841#
1842# TASK-PID CPU# TIMESTAMP FUNCTION
1843# | | | | |
1844
1845 #
1846 # cat /tmp/trace.out
1847 bash-4043 [00] 41.267106: finish_task_switch <-schedule
1848 bash-4043 [00] 41.267106: hrtick_set <-schedule
1849 bash-4043 [00] 41.267107: hrtick_clear <-hrtick_set
1850 bash-4043 [00] 41.267108: wait_for_completion <-__stop_machine_run
1851 bash-4043 [00] 41.267108: wait_for_common <-wait_for_completion
1852 bash-4043 [00] 41.267109: kthread_stop <-stop_machine_run
1853 bash-4043 [00] 41.267109: init_waitqueue_head <-kthread_stop
1854 bash-4043 [00] 41.267110: wake_up_process <-kthread_stop
1855 bash-4043 [00] 41.267110: try_to_wake_up <-wake_up_process
1856 bash-4043 [00] 41.267111: select_task_rq_rt <-try_to_wake_up
1857
1858
Ingo Molnar57526742009-02-19 12:54:10 +01001859Note, reading the trace_pipe file will block until more input is
1860added. By changing the tracer, trace_pipe will issue an EOF. We
1861needed to set the function tracer _before_ we "cat" the
1862trace_pipe file.
Steven Rostedteb6d42e2008-07-10 12:46:01 -04001863
1864
1865trace entries
1866-------------
1867
Ingo Molnar57526742009-02-19 12:54:10 +01001868Having too much or not enough data can be troublesome in
1869diagnosing an issue in the kernel. The file buffer_size_kb is
1870used to modify the size of the internal trace buffers. The
1871number listed is the number of entries that can be recorded per
1872CPU. To know the full size, multiply the number of possible CPUS
1873with the number of entries.
Steven Rostedteb6d42e2008-07-10 12:46:01 -04001874
GeunSik Lim156f5a72009-06-02 15:01:37 +09001875 # cat buffer_size_kb
Steven Rostedt1696b2b2008-11-13 00:09:35 -050018761408 (units kilobytes)
Steven Rostedteb6d42e2008-07-10 12:46:01 -04001877
Ingo Molnar57526742009-02-19 12:54:10 +01001878Note, to modify this, you must have tracing completely disabled.
1879To do that, echo "nop" into the current_tracer. If the
1880current_tracer is not set to "nop", an EINVAL error will be
1881returned.
Steven Rostedteb6d42e2008-07-10 12:46:01 -04001882
GeunSik Lim156f5a72009-06-02 15:01:37 +09001883 # echo nop > current_tracer
1884 # echo 10000 > buffer_size_kb
1885 # cat buffer_size_kb
Steven Rostedt1696b2b2008-11-13 00:09:35 -0500188610000 (units kilobytes)
Steven Rostedteb6d42e2008-07-10 12:46:01 -04001887
Ingo Molnar57526742009-02-19 12:54:10 +01001888The number of pages which will be allocated is limited to a
1889percentage of available memory. Allocating too much will produce
1890an error.
Steven Rostedteb6d42e2008-07-10 12:46:01 -04001891
GeunSik Lim156f5a72009-06-02 15:01:37 +09001892 # echo 1000000000000 > buffer_size_kb
Steven Rostedteb6d42e2008-07-10 12:46:01 -04001893-bash: echo: write error: Cannot allocate memory
GeunSik Lim156f5a72009-06-02 15:01:37 +09001894 # cat buffer_size_kb
Steven Rostedteb6d42e2008-07-10 12:46:01 -0400189585
1896
Ingo Molnar57526742009-02-19 12:54:10 +01001897-----------
1898
1899More details can be found in the source code, in the
GeunSik Limbaf20b32009-06-01 10:49:41 +02001900kernel/trace/*.c files.