blob: 957b22fde2dfddac0bcf061d7af84259384f32f2 [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>
1234
GeunSik Lim156f5a72009-06-02 15:01:37 +09001235#define _STR(x) #x
1236#define STR(x) _STR(x)
1237#define MAX_PATH 256
1238
1239const char *find_debugfs(void)
1240{
1241 static char debugfs[MAX_PATH+1];
1242 static int debugfs_found;
1243 char type[100];
1244 FILE *fp;
1245
1246 if (debugfs_found)
1247 return debugfs;
1248
1249 if ((fp = fopen("/proc/mounts","r")) == NULL) {
1250 perror("/proc/mounts");
1251 return NULL;
1252 }
1253
1254 while (fscanf(fp, "%*s %"
1255 STR(MAX_PATH)
1256 "s %99s %*s %*d %*d\n",
1257 debugfs, type) == 2) {
1258 if (strcmp(type, "debugfs") == 0)
1259 break;
1260 }
1261 fclose(fp);
1262
1263 if (strcmp(type, "debugfs") != 0) {
1264 fprintf(stderr, "debugfs not mounted");
1265 return NULL;
1266 }
1267
1268 debugfs_found = 1;
1269
1270 return debugfs;
1271}
1272
1273const char *tracing_file(const char *file_name)
1274{
1275 static char trace_file[MAX_PATH+1];
1276 snprintf(trace_file, MAX_PATH, "%s/%s", find_debugfs(), file_name);
1277 return trace_file;
1278}
1279
Steven Rostedtdf4fc312008-11-26 00:16:23 -05001280int main (int argc, char **argv)
1281{
1282 if (argc < 1)
1283 exit(-1);
1284
1285 if (fork() > 0) {
1286 int fd, ffd;
1287 char line[64];
1288 int s;
1289
GeunSik Lim156f5a72009-06-02 15:01:37 +09001290 ffd = open(tracing_file("current_tracer"), O_WRONLY);
Steven Rostedtdf4fc312008-11-26 00:16:23 -05001291 if (ffd < 0)
1292 exit(-1);
1293 write(ffd, "nop", 3);
1294
GeunSik Lim156f5a72009-06-02 15:01:37 +09001295 fd = open(tracing_file("set_ftrace_pid"), O_WRONLY);
Steven Rostedtdf4fc312008-11-26 00:16:23 -05001296 s = sprintf(line, "%d\n", getpid());
1297 write(fd, line, s);
1298
1299 write(ffd, "function", 8);
1300
1301 close(fd);
1302 close(ffd);
1303
1304 execvp(argv[1], argv+1);
1305 }
1306
1307 return 0;
1308}
1309
Markus Metzgere2ea5392009-01-19 10:35:58 +01001310
1311hw-branch-tracer (x86 only)
1312---------------------------
1313
1314This tracer uses the x86 last branch tracing hardware feature to
1315collect a branch trace on all cpus with relatively low overhead.
1316
1317The tracer uses a fixed-size circular buffer per cpu and only
1318traces ring 0 branches. The trace file dumps that buffer in the
1319following format:
1320
1321# tracer: hw-branch-tracer
1322#
1323# CPU# TO <- FROM
1324 0 scheduler_tick+0xb5/0x1bf <- task_tick_idle+0x5/0x6
1325 2 run_posix_cpu_timers+0x2b/0x72a <- run_posix_cpu_timers+0x25/0x72a
1326 0 scheduler_tick+0x139/0x1bf <- scheduler_tick+0xed/0x1bf
1327 0 scheduler_tick+0x17c/0x1bf <- scheduler_tick+0x148/0x1bf
1328 2 run_posix_cpu_timers+0x9e/0x72a <- run_posix_cpu_timers+0x5e/0x72a
1329 0 scheduler_tick+0x1b6/0x1bf <- scheduler_tick+0x1aa/0x1bf
1330
1331
Ingo Molnar57526742009-02-19 12:54:10 +01001332The tracer may be used to dump the trace for the oops'ing cpu on
1333a kernel oops into the system log. To enable this,
1334ftrace_dump_on_oops must be set. To set ftrace_dump_on_oops, one
1335can either use the sysctl function or set it via the proc system
1336interface.
Markus Metzgere2ea5392009-01-19 10:35:58 +01001337
1338 sysctl kernel.ftrace_dump_on_oops=1
1339
1340or
1341
1342 echo 1 > /proc/sys/kernel/ftrace_dump_on_oops
1343
1344
Ingo Molnar57526742009-02-19 12:54:10 +01001345Here's an example of such a dump after a null pointer
1346dereference in a kernel module:
Markus Metzgere2ea5392009-01-19 10:35:58 +01001347
1348[57848.105921] BUG: unable to handle kernel NULL pointer dereference at 0000000000000000
1349[57848.106019] IP: [<ffffffffa0000006>] open+0x6/0x14 [oops]
1350[57848.106019] PGD 2354e9067 PUD 2375e7067 PMD 0
1351[57848.106019] Oops: 0002 [#1] SMP
1352[57848.106019] last sysfs file: /sys/devices/pci0000:00/0000:00:1e.0/0000:20:05.0/local_cpus
1353[57848.106019] Dumping ftrace buffer:
1354[57848.106019] ---------------------------------
1355[...]
1356[57848.106019] 0 chrdev_open+0xe6/0x165 <- cdev_put+0x23/0x24
1357[57848.106019] 0 chrdev_open+0x117/0x165 <- chrdev_open+0xfa/0x165
1358[57848.106019] 0 chrdev_open+0x120/0x165 <- chrdev_open+0x11c/0x165
1359[57848.106019] 0 chrdev_open+0x134/0x165 <- chrdev_open+0x12b/0x165
1360[57848.106019] 0 open+0x0/0x14 [oops] <- chrdev_open+0x144/0x165
1361[57848.106019] 0 page_fault+0x0/0x30 <- open+0x6/0x14 [oops]
1362[57848.106019] 0 error_entry+0x0/0x5b <- page_fault+0x4/0x30
1363[57848.106019] 0 error_kernelspace+0x0/0x31 <- error_entry+0x59/0x5b
1364[57848.106019] 0 error_sti+0x0/0x1 <- error_kernelspace+0x2d/0x31
1365[57848.106019] 0 page_fault+0x9/0x30 <- error_sti+0x0/0x1
1366[57848.106019] 0 do_page_fault+0x0/0x881 <- page_fault+0x1a/0x30
1367[...]
1368[57848.106019] 0 do_page_fault+0x66b/0x881 <- is_prefetch+0x1ee/0x1f2
1369[57848.106019] 0 do_page_fault+0x6e0/0x881 <- do_page_fault+0x67a/0x881
1370[57848.106019] 0 oops_begin+0x0/0x96 <- do_page_fault+0x6e0/0x881
1371[57848.106019] 0 trace_hw_branch_oops+0x0/0x2d <- oops_begin+0x9/0x96
1372[...]
1373[57848.106019] 0 ds_suspend_bts+0x2a/0xe3 <- ds_suspend_bts+0x1a/0xe3
1374[57848.106019] ---------------------------------
1375[57848.106019] CPU 0
1376[57848.106019] Modules linked in: oops
1377[57848.106019] Pid: 5542, comm: cat Tainted: G W 2.6.28 #23
1378[57848.106019] RIP: 0010:[<ffffffffa0000006>] [<ffffffffa0000006>] open+0x6/0x14 [oops]
1379[57848.106019] RSP: 0018:ffff880235457d48 EFLAGS: 00010246
1380[...]
1381
1382
Frederic Weisbecker985ec202009-02-18 06:35:34 +01001383function graph tracer
1384---------------------------
1385
Ingo Molnar57526742009-02-19 12:54:10 +01001386This tracer is similar to the function tracer except that it
1387probes a function on its entry and its exit. This is done by
1388using a dynamically allocated stack of return addresses in each
1389task_struct. On function entry the tracer overwrites the return
1390address of each function traced to set a custom probe. Thus the
1391original return address is stored on the stack of return address
1392in the task_struct.
Frederic Weisbecker985ec202009-02-18 06:35:34 +01001393
Ingo Molnar57526742009-02-19 12:54:10 +01001394Probing on both ends of a function leads to special features
1395such as:
Frederic Weisbecker985ec202009-02-18 06:35:34 +01001396
Ingo Molnar57526742009-02-19 12:54:10 +01001397- measure of a function's time execution
1398- having a reliable call stack to draw function calls graph
Frederic Weisbecker985ec202009-02-18 06:35:34 +01001399
1400This tracer is useful in several situations:
1401
Ingo Molnar57526742009-02-19 12:54:10 +01001402- you want to find the reason of a strange kernel behavior and
1403 need to see what happens in detail on any areas (or specific
1404 ones).
1405
1406- you are experiencing weird latencies but it's difficult to
1407 find its origin.
1408
1409- you want to find quickly which path is taken by a specific
1410 function
1411
1412- you just want to peek inside a working kernel and want to see
1413 what happens there.
Frederic Weisbecker985ec202009-02-18 06:35:34 +01001414
1415# tracer: function_graph
1416#
1417# CPU DURATION FUNCTION CALLS
1418# | | | | | | |
1419
1420 0) | sys_open() {
1421 0) | do_sys_open() {
1422 0) | getname() {
1423 0) | kmem_cache_alloc() {
1424 0) 1.382 us | __might_sleep();
1425 0) 2.478 us | }
1426 0) | strncpy_from_user() {
1427 0) | might_fault() {
1428 0) 1.389 us | __might_sleep();
1429 0) 2.553 us | }
1430 0) 3.807 us | }
1431 0) 7.876 us | }
1432 0) | alloc_fd() {
1433 0) 0.668 us | _spin_lock();
1434 0) 0.570 us | expand_files();
1435 0) 0.586 us | _spin_unlock();
1436
1437
Ingo Molnar57526742009-02-19 12:54:10 +01001438There are several columns that can be dynamically
1439enabled/disabled. You can use every combination of options you
1440want, depending on your needs.
Frederic Weisbecker985ec202009-02-18 06:35:34 +01001441
Ingo Molnar57526742009-02-19 12:54:10 +01001442- The cpu number on which the function executed is default
1443 enabled. It is sometimes better to only trace one cpu (see
1444 tracing_cpu_mask file) or you might sometimes see unordered
1445 function calls while cpu tracing switch.
Frederic Weisbecker985ec202009-02-18 06:35:34 +01001446
GeunSik Lim156f5a72009-06-02 15:01:37 +09001447 hide: echo nofuncgraph-cpu > trace_options
1448 show: echo funcgraph-cpu > trace_options
Frederic Weisbecker985ec202009-02-18 06:35:34 +01001449
Ingo Molnar57526742009-02-19 12:54:10 +01001450- The duration (function's time of execution) is displayed on
1451 the closing bracket line of a function or on the same line
1452 than the current function in case of a leaf one. It is default
1453 enabled.
Frederic Weisbecker985ec202009-02-18 06:35:34 +01001454
GeunSik Lim156f5a72009-06-02 15:01:37 +09001455 hide: echo nofuncgraph-duration > trace_options
1456 show: echo funcgraph-duration > trace_options
Frederic Weisbecker985ec202009-02-18 06:35:34 +01001457
Ingo Molnar57526742009-02-19 12:54:10 +01001458- The overhead field precedes the duration field in case of
1459 reached duration thresholds.
Frederic Weisbecker985ec202009-02-18 06:35:34 +01001460
GeunSik Lim156f5a72009-06-02 15:01:37 +09001461 hide: echo nofuncgraph-overhead > trace_options
1462 show: echo funcgraph-overhead > trace_options
Frederic Weisbecker985ec202009-02-18 06:35:34 +01001463 depends on: funcgraph-duration
1464
1465 ie:
1466
1467 0) | up_write() {
1468 0) 0.646 us | _spin_lock_irqsave();
1469 0) 0.684 us | _spin_unlock_irqrestore();
1470 0) 3.123 us | }
1471 0) 0.548 us | fput();
1472 0) + 58.628 us | }
1473
1474 [...]
1475
1476 0) | putname() {
1477 0) | kmem_cache_free() {
1478 0) 0.518 us | __phys_addr();
1479 0) 1.757 us | }
1480 0) 2.861 us | }
1481 0) ! 115.305 us | }
1482 0) ! 116.402 us | }
1483
1484 + means that the function exceeded 10 usecs.
1485 ! means that the function exceeded 100 usecs.
1486
1487
Ingo Molnar57526742009-02-19 12:54:10 +01001488- The task/pid field displays the thread cmdline and pid which
1489 executed the function. It is default disabled.
Frederic Weisbecker985ec202009-02-18 06:35:34 +01001490
GeunSik Lim156f5a72009-06-02 15:01:37 +09001491 hide: echo nofuncgraph-proc > trace_options
1492 show: echo funcgraph-proc > trace_options
Frederic Weisbecker985ec202009-02-18 06:35:34 +01001493
1494 ie:
1495
1496 # tracer: function_graph
1497 #
1498 # CPU TASK/PID DURATION FUNCTION CALLS
1499 # | | | | | | | | |
1500 0) sh-4802 | | d_free() {
1501 0) sh-4802 | | call_rcu() {
1502 0) sh-4802 | | __call_rcu() {
1503 0) sh-4802 | 0.616 us | rcu_process_gp_end();
1504 0) sh-4802 | 0.586 us | check_for_new_grace_period();
1505 0) sh-4802 | 2.899 us | }
1506 0) sh-4802 | 4.040 us | }
1507 0) sh-4802 | 5.151 us | }
1508 0) sh-4802 | + 49.370 us | }
1509
1510
Ingo Molnar57526742009-02-19 12:54:10 +01001511- The absolute time field is an absolute timestamp given by the
1512 system clock since it started. A snapshot of this time is
1513 given on each entry/exit of functions
Frederic Weisbecker985ec202009-02-18 06:35:34 +01001514
GeunSik Lim156f5a72009-06-02 15:01:37 +09001515 hide: echo nofuncgraph-abstime > trace_options
1516 show: echo funcgraph-abstime > trace_options
Frederic Weisbecker985ec202009-02-18 06:35:34 +01001517
1518 ie:
1519
1520 #
1521 # TIME CPU DURATION FUNCTION CALLS
1522 # | | | | | | | |
1523 360.774522 | 1) 0.541 us | }
1524 360.774522 | 1) 4.663 us | }
1525 360.774523 | 1) 0.541 us | __wake_up_bit();
1526 360.774524 | 1) 6.796 us | }
1527 360.774524 | 1) 7.952 us | }
1528 360.774525 | 1) 9.063 us | }
1529 360.774525 | 1) 0.615 us | journal_mark_dirty();
1530 360.774527 | 1) 0.578 us | __brelse();
1531 360.774528 | 1) | reiserfs_prepare_for_journal() {
1532 360.774528 | 1) | unlock_buffer() {
1533 360.774529 | 1) | wake_up_bit() {
1534 360.774529 | 1) | bit_waitqueue() {
1535 360.774530 | 1) 0.594 us | __phys_addr();
1536
1537
Ingo Molnar57526742009-02-19 12:54:10 +01001538You can put some comments on specific functions by using
Ingo Molnar5e1607a2009-03-05 10:24:48 +01001539trace_printk() For example, if you want to put a comment inside
Ingo Molnar57526742009-02-19 12:54:10 +01001540the __might_sleep() function, you just have to include
Ingo Molnar5e1607a2009-03-05 10:24:48 +01001541<linux/ftrace.h> and call trace_printk() inside __might_sleep()
Frederic Weisbecker985ec202009-02-18 06:35:34 +01001542
Ingo Molnar5e1607a2009-03-05 10:24:48 +01001543trace_printk("I'm a comment!\n")
Frederic Weisbecker985ec202009-02-18 06:35:34 +01001544
1545will produce:
1546
1547 1) | __might_sleep() {
1548 1) | /* I'm a comment! */
1549 1) 1.449 us | }
1550
1551
Ingo Molnar57526742009-02-19 12:54:10 +01001552You might find other useful features for this tracer in the
1553following "dynamic ftrace" section such as tracing only specific
1554functions or tasks.
Frederic Weisbecker985ec202009-02-18 06:35:34 +01001555
Steven Rostedteb6d42e2008-07-10 12:46:01 -04001556dynamic ftrace
1557--------------
1558
Steven Rostedtf2d9c742008-07-15 10:57:33 -04001559If CONFIG_DYNAMIC_FTRACE is set, the system will run with
Steven Rostedteb6d42e2008-07-10 12:46:01 -04001560virtually no overhead when function tracing is disabled. The way
1561this works is the mcount function call (placed at the start of
Ingo Molnar57526742009-02-19 12:54:10 +01001562every kernel function, produced by the -pg switch in gcc),
1563starts of pointing to a simple return. (Enabling FTRACE will
1564include the -pg switch in the compiling of the kernel.)
Steven Rostedteb6d42e2008-07-10 12:46:01 -04001565
Steven Rostedt9b803c02008-11-03 15:15:08 -05001566At compile time every C file object is run through the
1567recordmcount.pl script (located in the scripts directory). This
1568script will process the C object using objdump to find all the
Ingo Molnar57526742009-02-19 12:54:10 +01001569locations in the .text section that call mcount. (Note, only the
1570.text section is processed, since processing other sections like
1571.init.text may cause races due to those sections being freed).
Steven Rostedteb6d42e2008-07-10 12:46:01 -04001572
Ingo Molnar57526742009-02-19 12:54:10 +01001573A new section called "__mcount_loc" is created that holds
1574references to all the mcount call sites in the .text section.
1575This section is compiled back into the original object. The
1576final linker will add all these references into a single table.
Steven Rostedt9b803c02008-11-03 15:15:08 -05001577
1578On boot up, before SMP is initialized, the dynamic ftrace code
Ingo Molnar57526742009-02-19 12:54:10 +01001579scans this table and updates all the locations into nops. It
1580also records the locations, which are added to the
1581available_filter_functions list. Modules are processed as they
1582are loaded and before they are executed. When a module is
1583unloaded, it also removes its functions from the ftrace function
1584list. This is automatic in the module unload code, and the
1585module author does not need to worry about it.
Steven Rostedt9b803c02008-11-03 15:15:08 -05001586
Ingo Molnar57526742009-02-19 12:54:10 +01001587When tracing is enabled, kstop_machine is called to prevent
1588races with the CPUS executing code being modified (which can
1589cause the CPU to do undesireable things), and the nops are
1590patched back to calls. But this time, they do not call mcount
1591(which is just a function stub). They now call into the ftrace
1592infrastructure.
Steven Rostedteb6d42e2008-07-10 12:46:01 -04001593
1594One special side-effect to the recording of the functions being
Steven Rostedtf2d9c742008-07-15 10:57:33 -04001595traced is that we can now selectively choose which functions we
Ingo Molnar57526742009-02-19 12:54:10 +01001596wish to trace and which ones we want the mcount calls to remain
1597as nops.
Steven Rostedteb6d42e2008-07-10 12:46:01 -04001598
Ingo Molnar57526742009-02-19 12:54:10 +01001599Two files are used, one for enabling and one for disabling the
1600tracing of specified functions. They are:
Steven Rostedteb6d42e2008-07-10 12:46:01 -04001601
1602 set_ftrace_filter
1603
1604and
1605
1606 set_ftrace_notrace
1607
Ingo Molnar57526742009-02-19 12:54:10 +01001608A list of available functions that you can add to these files is
1609listed in:
Steven Rostedteb6d42e2008-07-10 12:46:01 -04001610
1611 available_filter_functions
1612
GeunSik Lim156f5a72009-06-02 15:01:37 +09001613 # cat available_filter_functions
Steven Rostedteb6d42e2008-07-10 12:46:01 -04001614put_prev_task_idle
1615kmem_cache_create
1616pick_next_task_rt
1617get_online_cpus
1618pick_next_task_fair
1619mutex_lock
1620[...]
1621
Steven Rostedtf2d9c742008-07-15 10:57:33 -04001622If I am only interested in sys_nanosleep and hrtimer_interrupt:
Steven Rostedteb6d42e2008-07-10 12:46:01 -04001623
1624 # echo sys_nanosleep hrtimer_interrupt \
GeunSik Lim156f5a72009-06-02 15:01:37 +09001625 > set_ftrace_filter
1626 # echo ftrace > current_tracer
1627 # echo 1 > tracing_enabled
Steven Rostedteb6d42e2008-07-10 12:46:01 -04001628 # usleep 1
GeunSik Lim156f5a72009-06-02 15:01:37 +09001629 # echo 0 > tracing_enabled
1630 # cat trace
Steven Rostedteb6d42e2008-07-10 12:46:01 -04001631# tracer: ftrace
1632#
1633# TASK-PID CPU# TIMESTAMP FUNCTION
1634# | | | | |
1635 usleep-4134 [00] 1317.070017: hrtimer_interrupt <-smp_apic_timer_interrupt
1636 usleep-4134 [00] 1317.070111: sys_nanosleep <-syscall_call
1637 <idle>-0 [00] 1317.070115: hrtimer_interrupt <-smp_apic_timer_interrupt
1638
Steven Rostedtf2d9c742008-07-15 10:57:33 -04001639To see which functions are being traced, you can cat the file:
Steven Rostedteb6d42e2008-07-10 12:46:01 -04001640
GeunSik Lim156f5a72009-06-02 15:01:37 +09001641 # cat set_ftrace_filter
Steven Rostedteb6d42e2008-07-10 12:46:01 -04001642hrtimer_interrupt
1643sys_nanosleep
1644
1645
Ingo Molnar57526742009-02-19 12:54:10 +01001646Perhaps this is not enough. The filters also allow simple wild
1647cards. Only the following are currently available
Steven Rostedteb6d42e2008-07-10 12:46:01 -04001648
Steven Rostedta41eeba2008-07-14 16:41:12 -04001649 <match>* - will match functions that begin with <match>
Steven Rostedteb6d42e2008-07-10 12:46:01 -04001650 *<match> - will match functions that end with <match>
1651 *<match>* - will match functions that have <match> in it
1652
Steven Rostedtf2d9c742008-07-15 10:57:33 -04001653These are the only wild cards which are supported.
Steven Rostedteb6d42e2008-07-10 12:46:01 -04001654
1655 <match>*<match> will not work.
1656
Ingo Molnar57526742009-02-19 12:54:10 +01001657Note: It is better to use quotes to enclose the wild cards,
1658 otherwise the shell may expand the parameters into names
1659 of files in the local directory.
walimisc072c242008-11-28 12:21:19 +08001660
GeunSik Lim156f5a72009-06-02 15:01:37 +09001661 # echo 'hrtimer_*' > set_ftrace_filter
Steven Rostedteb6d42e2008-07-10 12:46:01 -04001662
1663Produces:
1664
1665# tracer: ftrace
1666#
1667# TASK-PID CPU# TIMESTAMP FUNCTION
1668# | | | | |
1669 bash-4003 [00] 1480.611794: hrtimer_init <-copy_process
1670 bash-4003 [00] 1480.611941: hrtimer_start <-hrtick_set
1671 bash-4003 [00] 1480.611956: hrtimer_cancel <-hrtick_clear
1672 bash-4003 [00] 1480.611956: hrtimer_try_to_cancel <-hrtimer_cancel
1673 <idle>-0 [00] 1480.612019: hrtimer_get_next_event <-get_next_timer_interrupt
1674 <idle>-0 [00] 1480.612025: hrtimer_get_next_event <-get_next_timer_interrupt
1675 <idle>-0 [00] 1480.612032: hrtimer_get_next_event <-get_next_timer_interrupt
1676 <idle>-0 [00] 1480.612037: hrtimer_get_next_event <-get_next_timer_interrupt
1677 <idle>-0 [00] 1480.612382: hrtimer_get_next_event <-get_next_timer_interrupt
1678
1679
1680Notice that we lost the sys_nanosleep.
1681
GeunSik Lim156f5a72009-06-02 15:01:37 +09001682 # cat set_ftrace_filter
Steven Rostedteb6d42e2008-07-10 12:46:01 -04001683hrtimer_run_queues
1684hrtimer_run_pending
1685hrtimer_init
1686hrtimer_cancel
1687hrtimer_try_to_cancel
1688hrtimer_forward
1689hrtimer_start
1690hrtimer_reprogram
1691hrtimer_force_reprogram
1692hrtimer_get_next_event
1693hrtimer_interrupt
1694hrtimer_nanosleep
1695hrtimer_wakeup
1696hrtimer_get_remaining
1697hrtimer_get_res
1698hrtimer_init_sleeper
1699
1700
1701This is because the '>' and '>>' act just like they do in bash.
1702To rewrite the filters, use '>'
1703To append to the filters, use '>>'
1704
Ingo Molnar57526742009-02-19 12:54:10 +01001705To clear out a filter so that all functions will be recorded
1706again:
Steven Rostedteb6d42e2008-07-10 12:46:01 -04001707
GeunSik Lim156f5a72009-06-02 15:01:37 +09001708 # echo > set_ftrace_filter
1709 # cat set_ftrace_filter
Steven Rostedteb6d42e2008-07-10 12:46:01 -04001710 #
1711
1712Again, now we want to append.
1713
GeunSik Lim156f5a72009-06-02 15:01:37 +09001714 # echo sys_nanosleep > set_ftrace_filter
1715 # cat set_ftrace_filter
Steven Rostedteb6d42e2008-07-10 12:46:01 -04001716sys_nanosleep
GeunSik Lim156f5a72009-06-02 15:01:37 +09001717 # echo 'hrtimer_*' >> set_ftrace_filter
1718 # cat set_ftrace_filter
Steven Rostedteb6d42e2008-07-10 12:46:01 -04001719hrtimer_run_queues
1720hrtimer_run_pending
1721hrtimer_init
1722hrtimer_cancel
1723hrtimer_try_to_cancel
1724hrtimer_forward
1725hrtimer_start
1726hrtimer_reprogram
1727hrtimer_force_reprogram
1728hrtimer_get_next_event
1729hrtimer_interrupt
1730sys_nanosleep
1731hrtimer_nanosleep
1732hrtimer_wakeup
1733hrtimer_get_remaining
1734hrtimer_get_res
1735hrtimer_init_sleeper
1736
1737
Ingo Molnar57526742009-02-19 12:54:10 +01001738The set_ftrace_notrace prevents those functions from being
1739traced.
Steven Rostedteb6d42e2008-07-10 12:46:01 -04001740
GeunSik Lim156f5a72009-06-02 15:01:37 +09001741 # echo '*preempt*' '*lock*' > set_ftrace_notrace
Steven Rostedteb6d42e2008-07-10 12:46:01 -04001742
1743Produces:
1744
1745# tracer: ftrace
1746#
1747# TASK-PID CPU# TIMESTAMP FUNCTION
1748# | | | | |
1749 bash-4043 [01] 115.281644: finish_task_switch <-schedule
1750 bash-4043 [01] 115.281645: hrtick_set <-schedule
1751 bash-4043 [01] 115.281645: hrtick_clear <-hrtick_set
1752 bash-4043 [01] 115.281646: wait_for_completion <-__stop_machine_run
1753 bash-4043 [01] 115.281647: wait_for_common <-wait_for_completion
1754 bash-4043 [01] 115.281647: kthread_stop <-stop_machine_run
1755 bash-4043 [01] 115.281648: init_waitqueue_head <-kthread_stop
1756 bash-4043 [01] 115.281648: wake_up_process <-kthread_stop
1757 bash-4043 [01] 115.281649: try_to_wake_up <-wake_up_process
1758
1759We can see that there's no more lock or preempt tracing.
1760
Frederic Weisbecker985ec202009-02-18 06:35:34 +01001761
Ingo Molnar57526742009-02-19 12:54:10 +01001762Dynamic ftrace with the function graph tracer
1763---------------------------------------------
Frederic Weisbecker985ec202009-02-18 06:35:34 +01001764
Ingo Molnar57526742009-02-19 12:54:10 +01001765Although what has been explained above concerns both the
1766function tracer and the function-graph-tracer, there are some
1767special features only available in the function-graph tracer.
Frederic Weisbecker985ec202009-02-18 06:35:34 +01001768
Ingo Molnar57526742009-02-19 12:54:10 +01001769If you want to trace only one function and all of its children,
1770you just have to echo its name into set_graph_function:
Frederic Weisbecker985ec202009-02-18 06:35:34 +01001771
Ingo Molnar57526742009-02-19 12:54:10 +01001772 echo __do_fault > set_graph_function
Frederic Weisbecker985ec202009-02-18 06:35:34 +01001773
Ingo Molnar57526742009-02-19 12:54:10 +01001774will produce the following "expanded" trace of the __do_fault()
1775function:
Frederic Weisbecker985ec202009-02-18 06:35:34 +01001776
1777 0) | __do_fault() {
1778 0) | filemap_fault() {
1779 0) | find_lock_page() {
1780 0) 0.804 us | find_get_page();
1781 0) | __might_sleep() {
1782 0) 1.329 us | }
1783 0) 3.904 us | }
1784 0) 4.979 us | }
1785 0) 0.653 us | _spin_lock();
1786 0) 0.578 us | page_add_file_rmap();
1787 0) 0.525 us | native_set_pte_at();
1788 0) 0.585 us | _spin_unlock();
1789 0) | unlock_page() {
1790 0) 0.541 us | page_waitqueue();
1791 0) 0.639 us | __wake_up_bit();
1792 0) 2.786 us | }
1793 0) + 14.237 us | }
1794 0) | __do_fault() {
1795 0) | filemap_fault() {
1796 0) | find_lock_page() {
1797 0) 0.698 us | find_get_page();
1798 0) | __might_sleep() {
1799 0) 1.412 us | }
1800 0) 3.950 us | }
1801 0) 5.098 us | }
1802 0) 0.631 us | _spin_lock();
1803 0) 0.571 us | page_add_file_rmap();
1804 0) 0.526 us | native_set_pte_at();
1805 0) 0.586 us | _spin_unlock();
1806 0) | unlock_page() {
1807 0) 0.533 us | page_waitqueue();
1808 0) 0.638 us | __wake_up_bit();
1809 0) 2.793 us | }
1810 0) + 14.012 us | }
1811
Ingo Molnar57526742009-02-19 12:54:10 +01001812You can also expand several functions at once:
Frederic Weisbecker985ec202009-02-18 06:35:34 +01001813
Ingo Molnar57526742009-02-19 12:54:10 +01001814 echo sys_open > set_graph_function
1815 echo sys_close >> set_graph_function
Frederic Weisbecker985ec202009-02-18 06:35:34 +01001816
Ingo Molnar57526742009-02-19 12:54:10 +01001817Now if you want to go back to trace all functions you can clear
1818this special filter via:
Frederic Weisbecker985ec202009-02-18 06:35:34 +01001819
Ingo Molnar57526742009-02-19 12:54:10 +01001820 echo > set_graph_function
Frederic Weisbecker985ec202009-02-18 06:35:34 +01001821
1822
Steven Rostedteb6d42e2008-07-10 12:46:01 -04001823trace_pipe
1824----------
1825
Ingo Molnar57526742009-02-19 12:54:10 +01001826The trace_pipe outputs the same content as the trace file, but
1827the effect on the tracing is different. Every read from
1828trace_pipe is consumed. This means that subsequent reads will be
1829different. The trace is live.
Steven Rostedteb6d42e2008-07-10 12:46:01 -04001830
GeunSik Lim156f5a72009-06-02 15:01:37 +09001831 # echo function > current_tracer
1832 # cat trace_pipe > /tmp/trace.out &
Steven Rostedteb6d42e2008-07-10 12:46:01 -04001833[1] 4153
GeunSik Lim156f5a72009-06-02 15:01:37 +09001834 # echo 1 > tracing_enabled
Steven Rostedteb6d42e2008-07-10 12:46:01 -04001835 # usleep 1
GeunSik Lim156f5a72009-06-02 15:01:37 +09001836 # echo 0 > tracing_enabled
1837 # cat trace
Steven Rostedt9b803c02008-11-03 15:15:08 -05001838# tracer: function
Steven Rostedteb6d42e2008-07-10 12:46:01 -04001839#
1840# TASK-PID CPU# TIMESTAMP FUNCTION
1841# | | | | |
1842
1843 #
1844 # cat /tmp/trace.out
1845 bash-4043 [00] 41.267106: finish_task_switch <-schedule
1846 bash-4043 [00] 41.267106: hrtick_set <-schedule
1847 bash-4043 [00] 41.267107: hrtick_clear <-hrtick_set
1848 bash-4043 [00] 41.267108: wait_for_completion <-__stop_machine_run
1849 bash-4043 [00] 41.267108: wait_for_common <-wait_for_completion
1850 bash-4043 [00] 41.267109: kthread_stop <-stop_machine_run
1851 bash-4043 [00] 41.267109: init_waitqueue_head <-kthread_stop
1852 bash-4043 [00] 41.267110: wake_up_process <-kthread_stop
1853 bash-4043 [00] 41.267110: try_to_wake_up <-wake_up_process
1854 bash-4043 [00] 41.267111: select_task_rq_rt <-try_to_wake_up
1855
1856
Ingo Molnar57526742009-02-19 12:54:10 +01001857Note, reading the trace_pipe file will block until more input is
1858added. By changing the tracer, trace_pipe will issue an EOF. We
1859needed to set the function tracer _before_ we "cat" the
1860trace_pipe file.
Steven Rostedteb6d42e2008-07-10 12:46:01 -04001861
1862
1863trace entries
1864-------------
1865
Ingo Molnar57526742009-02-19 12:54:10 +01001866Having too much or not enough data can be troublesome in
1867diagnosing an issue in the kernel. The file buffer_size_kb is
1868used to modify the size of the internal trace buffers. The
1869number listed is the number of entries that can be recorded per
1870CPU. To know the full size, multiply the number of possible CPUS
1871with the number of entries.
Steven Rostedteb6d42e2008-07-10 12:46:01 -04001872
GeunSik Lim156f5a72009-06-02 15:01:37 +09001873 # cat buffer_size_kb
Steven Rostedt1696b2b2008-11-13 00:09:35 -050018741408 (units kilobytes)
Steven Rostedteb6d42e2008-07-10 12:46:01 -04001875
Ingo Molnar57526742009-02-19 12:54:10 +01001876Note, to modify this, you must have tracing completely disabled.
1877To do that, echo "nop" into the current_tracer. If the
1878current_tracer is not set to "nop", an EINVAL error will be
1879returned.
Steven Rostedteb6d42e2008-07-10 12:46:01 -04001880
GeunSik Lim156f5a72009-06-02 15:01:37 +09001881 # echo nop > current_tracer
1882 # echo 10000 > buffer_size_kb
1883 # cat buffer_size_kb
Steven Rostedt1696b2b2008-11-13 00:09:35 -0500188410000 (units kilobytes)
Steven Rostedteb6d42e2008-07-10 12:46:01 -04001885
Ingo Molnar57526742009-02-19 12:54:10 +01001886The number of pages which will be allocated is limited to a
1887percentage of available memory. Allocating too much will produce
1888an error.
Steven Rostedteb6d42e2008-07-10 12:46:01 -04001889
GeunSik Lim156f5a72009-06-02 15:01:37 +09001890 # echo 1000000000000 > buffer_size_kb
Steven Rostedteb6d42e2008-07-10 12:46:01 -04001891-bash: echo: write error: Cannot allocate memory
GeunSik Lim156f5a72009-06-02 15:01:37 +09001892 # cat buffer_size_kb
Steven Rostedteb6d42e2008-07-10 12:46:01 -0400189385
1894
Ingo Molnar57526742009-02-19 12:54:10 +01001895-----------
1896
1897More details can be found in the source code, in the
GeunSik Limbaf20b32009-06-01 10:49:41 +02001898kernel/trace/*.c files.