blob: ea5a827395dd31a6c34e91da54a6d81367be077a [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 Rostedteb6d42e2008-07-10 12:46:01 -040010
Steven Rostedtf2d9c742008-07-15 10:57:33 -040011Written for: 2.6.27-rc1
Steven Rostedteb6d42e2008-07-10 12:46:01 -040012
13Introduction
14------------
15
16Ftrace is an internal tracer designed to help out developers and
17designers of systems to find what is going on inside the kernel.
18It can be used for debugging or analyzing latencies and performance
19issues that take place outside of user-space.
20
21Although ftrace is the function tracer, it also includes an
22infrastructure that allows for other types of tracing. Some of the
Steven Rostedtf2d9c742008-07-15 10:57:33 -040023tracers that are currently in ftrace include a tracer to trace
Steven Rostedteb6d42e2008-07-10 12:46:01 -040024context switches, the time it takes for a high priority task to
25run after it was woken up, the time interrupts are disabled, and
Steven Rostedtf2d9c742008-07-15 10:57:33 -040026more (ftrace allows for tracer plugins, which means that the list of
27tracers can always grow).
Steven Rostedteb6d42e2008-07-10 12:46:01 -040028
29
30The File System
31---------------
32
33Ftrace uses the debugfs file system to hold the control files as well
34as the files to display output.
35
36To mount the debugfs system:
37
38 # mkdir /debug
39 # mount -t debugfs nodev /debug
40
Steven Rostedtf2d9c742008-07-15 10:57:33 -040041(Note: it is more common to mount at /sys/kernel/debug, but for simplicity
42 this document will use /debug)
Steven Rostedteb6d42e2008-07-10 12:46:01 -040043
44That's it! (assuming that you have ftrace configured into your kernel)
45
46After mounting the debugfs, you can see a directory called
47"tracing". This directory contains the control and output files
48of ftrace. Here is a list of some of the key files:
49
50
51 Note: all time values are in microseconds.
52
53 current_tracer : This is used to set or display the current tracer
54 that is configured.
55
56 available_tracers : This holds the different types of tracers that
Steven Rostedta41eeba2008-07-14 16:41:12 -040057 have been compiled into the kernel. The tracers
Steven Rostedtf2d9c742008-07-15 10:57:33 -040058 listed here can be configured by echoing their name
59 into current_tracer.
Steven Rostedteb6d42e2008-07-10 12:46:01 -040060
61 tracing_enabled : This sets or displays whether the current_tracer
62 is activated and tracing or not. Echo 0 into this
Steven Rostedtf2d9c742008-07-15 10:57:33 -040063 file to disable the tracer or 1 to enable it.
Steven Rostedteb6d42e2008-07-10 12:46:01 -040064
65 trace : This file holds the output of the trace in a human readable
Steven Rostedtf2d9c742008-07-15 10:57:33 -040066 format (described below).
Steven Rostedteb6d42e2008-07-10 12:46:01 -040067
68 latency_trace : This file shows the same trace but the information
69 is organized more to display possible latencies
Steven Rostedtf2d9c742008-07-15 10:57:33 -040070 in the system (described below).
Steven Rostedteb6d42e2008-07-10 12:46:01 -040071
72 trace_pipe : The output is the same as the "trace" file but this
73 file is meant to be streamed with live tracing.
74 Reads from this file will block until new data
75 is retrieved. Unlike the "trace" and "latency_trace"
76 files, this file is a consumer. This means reading
77 from this file causes sequential reads to display
78 more current data. Once data is read from this
79 file, it is consumed, and will not be read
80 again with a sequential read. The "trace" and
81 "latency_trace" files are static, and if the
Steven Rostedtf2d9c742008-07-15 10:57:33 -040082 tracer is not adding more data, they will display
Steven Rostedteb6d42e2008-07-10 12:46:01 -040083 the same information every time they are read.
84
85 iter_ctrl : This file lets the user control the amount of data
86 that is displayed in one of the above output
87 files.
88
89 trace_max_latency : Some of the tracers record the max latency.
90 For example, the time interrupts are disabled.
91 This time is saved in this file. The max trace
92 will also be stored, and displayed by either
93 "trace" or "latency_trace". A new max trace will
94 only be recorded if the latency is greater than
95 the value in this file. (in microseconds)
96
97 trace_entries : This sets or displays the number of trace
98 entries each CPU buffer can hold. The tracer buffers
Steven Rostedtf2d9c742008-07-15 10:57:33 -040099 are the same size for each CPU. The displayed number
100 is the size of the CPU buffer and not total size. The
101 trace buffers are allocated in pages (blocks of memory
102 that the kernel uses for allocation, usually 4 KB in size).
Steven Rostedta41eeba2008-07-14 16:41:12 -0400103 Since each entry is smaller than a page, if the last
104 allocated page has room for more entries than were
105 requested, the rest of the page is used to allocate
106 entries.
Steven Rostedteb6d42e2008-07-10 12:46:01 -0400107
108 This can only be updated when the current_tracer
109 is set to "none".
110
111 NOTE: It is planned on changing the allocated buffers
112 from being the number of possible CPUS to
113 the number of online CPUS.
114
115 tracing_cpumask : This is a mask that lets the user only trace
116 on specified CPUS. The format is a hex string
117 representing the CPUS.
118
Steven Rostedtf2d9c742008-07-15 10:57:33 -0400119 set_ftrace_filter : When dynamic ftrace is configured in (see the
120 section below "dynamic ftrace"), the code is dynamically
121 modified (code text rewrite) to disable calling of the
122 function profiler (mcount). This lets tracing be configured
123 in with practically no overhead in performance. This also
124 has a side effect of enabling or disabling specific functions
125 to be traced. Echoing names of functions into this file
126 will limit the trace to only those functions.
Steven Rostedteb6d42e2008-07-10 12:46:01 -0400127
Steven Rostedtf2d9c742008-07-15 10:57:33 -0400128 set_ftrace_notrace: This has an effect opposite to that of
129 set_ftrace_filter. Any function that is added here will not
130 be traced. If a function exists in both set_ftrace_filter
131 and set_ftrace_notrace, the function will _not_ be traced.
Steven Rostedteb6d42e2008-07-10 12:46:01 -0400132
133 available_filter_functions : When a function is encountered the first
134 time by the dynamic tracer, it is recorded and
135 later the call is converted into a nop. This file
136 lists the functions that have been recorded
137 by the dynamic tracer and these functions can
138 be used to set the ftrace filter by the above
Steven Rostedtf2d9c742008-07-15 10:57:33 -0400139 "set_ftrace_filter" file. (See the section "dynamic ftrace"
140 below for more details).
Steven Rostedteb6d42e2008-07-10 12:46:01 -0400141
142
143The Tracers
144-----------
145
Steven Rostedtf2d9c742008-07-15 10:57:33 -0400146Here is the list of current tracers that may be configured.
Steven Rostedteb6d42e2008-07-10 12:46:01 -0400147
148 ftrace - function tracer that uses mcount to trace all functions.
Steven Rostedteb6d42e2008-07-10 12:46:01 -0400149
150 sched_switch - traces the context switches between tasks.
151
Steven Rostedtf2d9c742008-07-15 10:57:33 -0400152 irqsoff - traces the areas that disable interrupts and saves
Steven Rostedteb6d42e2008-07-10 12:46:01 -0400153 the trace with the longest max latency.
154 See tracing_max_latency. When a new max is recorded,
155 it replaces the old trace. It is best to view this
Steven Rostedtf2d9c742008-07-15 10:57:33 -0400156 trace via the latency_trace file.
Steven Rostedteb6d42e2008-07-10 12:46:01 -0400157
Steven Rostedtf2d9c742008-07-15 10:57:33 -0400158 preemptoff - Similar to irqsoff but traces and records the amount of
159 time for which preemption is disabled.
Steven Rostedteb6d42e2008-07-10 12:46:01 -0400160
161 preemptirqsoff - Similar to irqsoff and preemptoff, but traces and
Steven Rostedtf2d9c742008-07-15 10:57:33 -0400162 records the largest time for which irqs and/or preemption
163 is disabled.
Steven Rostedteb6d42e2008-07-10 12:46:01 -0400164
165 wakeup - Traces and records the max latency that it takes for
166 the highest priority task to get scheduled after
167 it has been woken up.
168
169 none - This is not a tracer. To remove all tracers from tracing
170 simply echo "none" into current_tracer.
171
172
173Examples of using the tracer
174----------------------------
175
Steven Rostedtf2d9c742008-07-15 10:57:33 -0400176Here are typical examples of using the tracers when controlling them only
177with the debugfs interface (without using any user-land utilities).
Steven Rostedteb6d42e2008-07-10 12:46:01 -0400178
179Output format:
180--------------
181
Steven Rostedtf2d9c742008-07-15 10:57:33 -0400182Here is an example of the output format of the file "trace"
Steven Rostedteb6d42e2008-07-10 12:46:01 -0400183
184 --------
185# tracer: ftrace
186#
187# TASK-PID CPU# TIMESTAMP FUNCTION
188# | | | | |
189 bash-4251 [01] 10152.583854: path_put <-path_walk
190 bash-4251 [01] 10152.583855: dput <-path_put
191 bash-4251 [01] 10152.583855: _atomic_dec_and_lock <-dput
192 --------
193
Steven Rostedtf2d9c742008-07-15 10:57:33 -0400194A header is printed with the tracer name that is represented by the trace.
195In this case the tracer is "ftrace". Then a header showing the format. Task
196name "bash", the task PID "4251", the CPU that it was running on
Steven Rostedteb6d42e2008-07-10 12:46:01 -0400197"01", the timestamp in <secs>.<usecs> format, the function name that was
198traced "path_put" and the parent function that called this function
Steven Rostedtf2d9c742008-07-15 10:57:33 -0400199"path_walk". The timestamp is the time at which the function was
200entered.
Steven Rostedteb6d42e2008-07-10 12:46:01 -0400201
Steven Rostedtf2d9c742008-07-15 10:57:33 -0400202The sched_switch tracer also includes tracing of task wakeups and
Steven Rostedteb6d42e2008-07-10 12:46:01 -0400203context switches.
204
205 ksoftirqd/1-7 [01] 1453.070013: 7:115:R + 2916:115:S
206 ksoftirqd/1-7 [01] 1453.070013: 7:115:R + 10:115:S
207 ksoftirqd/1-7 [01] 1453.070013: 7:115:R ==> 10:115:R
208 events/1-10 [01] 1453.070013: 10:115:S ==> 2916:115:R
209 kondemand/1-2916 [01] 1453.070013: 2916:115:S ==> 7:115:R
210 ksoftirqd/1-7 [01] 1453.070013: 7:115:S ==> 0:140:R
211
Steven Rostedtf2d9c742008-07-15 10:57:33 -0400212Wake ups are represented by a "+" and the context switches are shown as
Steven Rostedteb6d42e2008-07-10 12:46:01 -0400213"==>". The format is:
214
215 Context switches:
216
217 Previous task Next Task
218
219 <pid>:<prio>:<state> ==> <pid>:<prio>:<state>
220
221 Wake ups:
222
223 Current task Task waking up
224
225 <pid>:<prio>:<state> + <pid>:<prio>:<state>
226
Steven Rostedtf2d9c742008-07-15 10:57:33 -0400227The prio is the internal kernel priority, which is the inverse of the
Steven Rostedteb6d42e2008-07-10 12:46:01 -0400228priority that is usually displayed by user-space tools. Zero represents
229the highest priority (99). Prio 100 starts the "nice" priorities with
230100 being equal to nice -20 and 139 being nice 19. The prio "140" is
231reserved for the idle task which is the lowest priority thread (pid 0).
232
233
234Latency trace format
235--------------------
236
237For traces that display latency times, the latency_trace file gives
Steven Rostedtf2d9c742008-07-15 10:57:33 -0400238somewhat more information to see why a latency happened. Here is a typical
Steven Rostedteb6d42e2008-07-10 12:46:01 -0400239trace.
240
241# tracer: irqsoff
242#
243irqsoff latency trace v1.1.5 on 2.6.26-rc8
244--------------------------------------------------------------------
245 latency: 97 us, #3/3, CPU#0 | (M:preempt VP:0, KP:0, SP:0 HP:0 #P:2)
246 -----------------
247 | task: swapper-0 (uid:0 nice:0 policy:0 rt_prio:0)
248 -----------------
249 => started at: apic_timer_interrupt
250 => ended at: do_softirq
251
252# _------=> CPU#
253# / _-----=> irqs-off
254# | / _----=> need-resched
255# || / _---=> hardirq/softirq
256# ||| / _--=> preempt-depth
257# |||| /
258# ||||| delay
259# cmd pid ||||| time | caller
260# \ / ||||| \ | /
261 <idle>-0 0d..1 0us+: trace_hardirqs_off_thunk (apic_timer_interrupt)
262 <idle>-0 0d.s. 97us : __do_softirq (do_softirq)
263 <idle>-0 0d.s1 98us : trace_hardirqs_on (do_softirq)
264
265
Steven Rostedteb6d42e2008-07-10 12:46:01 -0400266
Steven Rostedtf2d9c742008-07-15 10:57:33 -0400267This shows that the current tracer is "irqsoff" tracing the time for which
268interrupts were disabled. It gives the trace version and the version
269of the kernel upon which this was executed on (2.6.26-rc8). Then it displays
270the max latency in microsecs (97 us). The number of trace entries displayed
271and the total number recorded (both are three: #3/3). The type of
Steven Rostedteb6d42e2008-07-10 12:46:01 -0400272preemption that was used (PREEMPT). VP, KP, SP, and HP are always zero
Steven Rostedtf2d9c742008-07-15 10:57:33 -0400273and are reserved for later use. #P is the number of online CPUS (#P:2).
Steven Rostedteb6d42e2008-07-10 12:46:01 -0400274
Steven Rostedtf2d9c742008-07-15 10:57:33 -0400275The task is the process that was running when the latency occurred.
Steven Rostedteb6d42e2008-07-10 12:46:01 -0400276(swapper pid: 0).
277
Steven Rostedtf2d9c742008-07-15 10:57:33 -0400278The start and stop (the functions in which the interrupts were disabled and
279enabled respectively) that caused the latencies:
Steven Rostedteb6d42e2008-07-10 12:46:01 -0400280
281 apic_timer_interrupt is where the interrupts were disabled.
282 do_softirq is where they were enabled again.
283
284The next lines after the header are the trace itself. The header
285explains which is which.
286
287 cmd: The name of the process in the trace.
288
289 pid: The PID of that process.
290
Steven Rostedtf2d9c742008-07-15 10:57:33 -0400291 CPU#: The CPU which the process was running on.
Steven Rostedteb6d42e2008-07-10 12:46:01 -0400292
293 irqs-off: 'd' interrupts are disabled. '.' otherwise.
Steven Rostedt92444892008-10-24 09:42:59 -0400294 Note: If the architecture does not support a way to
295 read the irq flags variable, an 'X' will always
296 be printed here.
Steven Rostedteb6d42e2008-07-10 12:46:01 -0400297
298 need-resched: 'N' task need_resched is set, '.' otherwise.
299
300 hardirq/softirq:
Steven Rostedtf2d9c742008-07-15 10:57:33 -0400301 'H' - hard irq occurred inside a softirq.
Steven Rostedteb6d42e2008-07-10 12:46:01 -0400302 'h' - hard irq is running
303 's' - soft irq is running
304 '.' - normal context.
305
306 preempt-depth: The level of preempt_disabled
307
308The above is mostly meaningful for kernel developers.
309
Steven Rostedta41eeba2008-07-14 16:41:12 -0400310 time: This differs from the trace file output. The trace file output
Steven Rostedtf2d9c742008-07-15 10:57:33 -0400311 includes an absolute timestamp. The timestamp used by the
Steven Rostedta41eeba2008-07-14 16:41:12 -0400312 latency_trace file is relative to the start of the trace.
Steven Rostedteb6d42e2008-07-10 12:46:01 -0400313
314 delay: This is just to help catch your eye a bit better. And
315 needs to be fixed to be only relative to the same CPU.
Steven Rostedta41eeba2008-07-14 16:41:12 -0400316 The marks are determined by the difference between this
Steven Rostedteb6d42e2008-07-10 12:46:01 -0400317 current trace and the next trace.
318 '!' - greater than preempt_mark_thresh (default 100)
319 '+' - greater than 1 microsecond
320 ' ' - less than or equal to 1 microsecond.
321
322 The rest is the same as the 'trace' file.
323
324
325iter_ctrl
326---------
327
328The iter_ctrl file is used to control what gets printed in the trace
329output. To see what is available, simply cat the file:
330
331 cat /debug/tracing/iter_ctrl
332 print-parent nosym-offset nosym-addr noverbose noraw nohex nobin \
333 noblock nostacktrace nosched-tree
334
Steven Rostedta41eeba2008-07-14 16:41:12 -0400335To disable one of the options, echo in the option prepended with "no".
Steven Rostedteb6d42e2008-07-10 12:46:01 -0400336
337 echo noprint-parent > /debug/tracing/iter_ctrl
338
339To enable an option, leave off the "no".
340
Steven Rostedta41eeba2008-07-14 16:41:12 -0400341 echo sym-offset > /debug/tracing/iter_ctrl
Steven Rostedteb6d42e2008-07-10 12:46:01 -0400342
343Here are the available options:
344
345 print-parent - On function traces, display the calling function
346 as well as the function being traced.
347
348 print-parent:
349 bash-4000 [01] 1477.606694: simple_strtoul <-strict_strtoul
350
351 noprint-parent:
352 bash-4000 [01] 1477.606694: simple_strtoul
353
354
355 sym-offset - Display not only the function name, but also the offset
356 in the function. For example, instead of seeing just
Steven Rostedta41eeba2008-07-14 16:41:12 -0400357 "ktime_get", you will see "ktime_get+0xb/0x20".
Steven Rostedteb6d42e2008-07-10 12:46:01 -0400358
359 sym-offset:
360 bash-4000 [01] 1477.606694: simple_strtoul+0x6/0xa0
361
362 sym-addr - this will also display the function address as well as
363 the function name.
364
365 sym-addr:
366 bash-4000 [01] 1477.606694: simple_strtoul <c0339346>
367
368 verbose - This deals with the latency_trace file.
369
370 bash 4000 1 0 00000000 00010a95 [58127d26] 1720.415ms \
371 (+0.000ms): simple_strtoul (strict_strtoul)
372
373 raw - This will display raw numbers. This option is best for use with
374 user applications that can translate the raw numbers better than
375 having it done in the kernel.
376
Steven Rostedta41eeba2008-07-14 16:41:12 -0400377 hex - Similar to raw, but the numbers will be in a hexadecimal format.
Steven Rostedteb6d42e2008-07-10 12:46:01 -0400378
379 bin - This will print out the formats in raw binary.
380
381 block - TBD (needs update)
382
383 stacktrace - This is one of the options that changes the trace itself.
384 When a trace is recorded, so is the stack of functions.
385 This allows for back traces of trace sites.
386
387 sched-tree - TBD (any users??)
388
389
390sched_switch
391------------
392
Steven Rostedtf2d9c742008-07-15 10:57:33 -0400393This tracer simply records schedule switches. Here is an example
Steven Rostedta41eeba2008-07-14 16:41:12 -0400394of how to use it.
Steven Rostedteb6d42e2008-07-10 12:46:01 -0400395
396 # echo sched_switch > /debug/tracing/current_tracer
397 # echo 1 > /debug/tracing/tracing_enabled
398 # sleep 1
399 # echo 0 > /debug/tracing/tracing_enabled
400 # cat /debug/tracing/trace
401
402# tracer: sched_switch
403#
404# TASK-PID CPU# TIMESTAMP FUNCTION
405# | | | | |
406 bash-3997 [01] 240.132281: 3997:120:R + 4055:120:R
407 bash-3997 [01] 240.132284: 3997:120:R ==> 4055:120:R
408 sleep-4055 [01] 240.132371: 4055:120:S ==> 3997:120:R
409 bash-3997 [01] 240.132454: 3997:120:R + 4055:120:S
410 bash-3997 [01] 240.132457: 3997:120:R ==> 4055:120:R
411 sleep-4055 [01] 240.132460: 4055:120:D ==> 3997:120:R
412 bash-3997 [01] 240.132463: 3997:120:R + 4055:120:D
413 bash-3997 [01] 240.132465: 3997:120:R ==> 4055:120:R
414 <idle>-0 [00] 240.132589: 0:140:R + 4:115:S
415 <idle>-0 [00] 240.132591: 0:140:R ==> 4:115:R
416 ksoftirqd/0-4 [00] 240.132595: 4:115:S ==> 0:140:R
417 <idle>-0 [00] 240.132598: 0:140:R + 4:115:S
418 <idle>-0 [00] 240.132599: 0:140:R ==> 4:115:R
419 ksoftirqd/0-4 [00] 240.132603: 4:115:S ==> 0:140:R
420 sleep-4055 [01] 240.133058: 4055:120:S ==> 3997:120:R
421 [...]
422
423
424As we have discussed previously about this format, the header shows
425the name of the trace and points to the options. The "FUNCTION"
426is a misnomer since here it represents the wake ups and context
427switches.
428
Steven Rostedtf2d9c742008-07-15 10:57:33 -0400429The sched_switch file only lists the wake ups (represented with '+')
430and context switches ('==>') with the previous task or current task
Steven Rostedteb6d42e2008-07-10 12:46:01 -0400431first followed by the next task or task waking up. The format for both
432of these is PID:KERNEL-PRIO:TASK-STATE. Remember that the KERNEL-PRIO
433is the inverse of the actual priority with zero (0) being the highest
434priority and the nice values starting at 100 (nice -20). Below is
435a quick chart to map the kernel priority to user land priorities.
436
437 Kernel priority: 0 to 99 ==> user RT priority 99 to 0
438 Kernel priority: 100 to 139 ==> user nice -20 to 19
439 Kernel priority: 140 ==> idle task priority
440
441The task states are:
442
443 R - running : wants to run, may not actually be running
444 S - sleep : process is waiting to be woken up (handles signals)
Steven Rostedtf2d9c742008-07-15 10:57:33 -0400445 D - disk sleep (uninterruptible sleep) : process must be woken up
446 (ignores signals)
Steven Rostedteb6d42e2008-07-10 12:46:01 -0400447 T - stopped : process suspended
448 t - traced : process is being traced (with something like gdb)
449 Z - zombie : process waiting to be cleaned up
450 X - unknown
451
452
453ftrace_enabled
454--------------
455
Steven Rostedtf2d9c742008-07-15 10:57:33 -0400456The following tracers (listed below) give different output depending
457on whether or not the sysctl ftrace_enabled is set. To set ftrace_enabled,
Steven Rostedteb6d42e2008-07-10 12:46:01 -0400458one can either use the sysctl function or set it via the proc
459file system interface.
460
461 sysctl kernel.ftrace_enabled=1
462
463 or
464
465 echo 1 > /proc/sys/kernel/ftrace_enabled
466
467To disable ftrace_enabled simply replace the '1' with '0' in
468the above commands.
469
470When ftrace_enabled is set the tracers will also record the functions
471that are within the trace. The descriptions of the tracers
472will also show an example with ftrace enabled.
473
474
475irqsoff
476-------
477
478When interrupts are disabled, the CPU can not react to any other
479external event (besides NMIs and SMIs). This prevents the timer
480interrupt from triggering or the mouse interrupt from letting the
481kernel know of a new mouse event. The result is a latency with the
482reaction time.
483
Steven Rostedtf2d9c742008-07-15 10:57:33 -0400484The irqsoff tracer tracks the time for which interrupts are disabled.
485When a new maximum latency is hit, the tracer saves the trace leading up
486to that latency point so that every time a new maximum is reached, the old
487saved trace is discarded and the new trace is saved.
Steven Rostedteb6d42e2008-07-10 12:46:01 -0400488
Steven Rostedtf2d9c742008-07-15 10:57:33 -0400489To reset the maximum, echo 0 into tracing_max_latency. Here is an
Steven Rostedteb6d42e2008-07-10 12:46:01 -0400490example:
491
492 # echo irqsoff > /debug/tracing/current_tracer
493 # echo 0 > /debug/tracing/tracing_max_latency
494 # echo 1 > /debug/tracing/tracing_enabled
495 # ls -ltr
496 [...]
497 # echo 0 > /debug/tracing/tracing_enabled
498 # cat /debug/tracing/latency_trace
499# tracer: irqsoff
500#
Steven Rostedtf2d9c742008-07-15 10:57:33 -0400501irqsoff latency trace v1.1.5 on 2.6.26
Steven Rostedteb6d42e2008-07-10 12:46:01 -0400502--------------------------------------------------------------------
Steven Rostedtf2d9c742008-07-15 10:57:33 -0400503 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 -0400504 -----------------
Steven Rostedtf2d9c742008-07-15 10:57:33 -0400505 | task: bash-3730 (uid:0 nice:0 policy:0 rt_prio:0)
Steven Rostedteb6d42e2008-07-10 12:46:01 -0400506 -----------------
Steven Rostedtf2d9c742008-07-15 10:57:33 -0400507 => started at: sys_setpgid
508 => ended at: sys_setpgid
Steven Rostedteb6d42e2008-07-10 12:46:01 -0400509
510# _------=> CPU#
511# / _-----=> irqs-off
512# | / _----=> need-resched
513# || / _---=> hardirq/softirq
514# ||| / _--=> preempt-depth
515# |||| /
516# ||||| delay
517# cmd pid ||||| time | caller
518# \ / ||||| \ | /
Steven Rostedtf2d9c742008-07-15 10:57:33 -0400519 bash-3730 1d... 0us : _write_lock_irq (sys_setpgid)
520 bash-3730 1d..1 1us+: _write_unlock_irq (sys_setpgid)
521 bash-3730 1d..2 14us : trace_hardirqs_on (sys_setpgid)
Steven Rostedteb6d42e2008-07-10 12:46:01 -0400522
523
Steven Rostedtf2d9c742008-07-15 10:57:33 -0400524Here we see that that we had a latency of 12 microsecs (which is
525very good). The _write_lock_irq in sys_setpgid disabled interrupts.
526The difference between the 12 and the displayed timestamp 14us occurred
527because the clock was incremented between the time of recording the max
528latency and the time of recording the function that had that latency.
Steven Rostedteb6d42e2008-07-10 12:46:01 -0400529
Steven Rostedtf2d9c742008-07-15 10:57:33 -0400530Note the above example had ftrace_enabled not set. If we set the
531ftrace_enabled, we get a much larger output:
Steven Rostedteb6d42e2008-07-10 12:46:01 -0400532
533# tracer: irqsoff
534#
535irqsoff latency trace v1.1.5 on 2.6.26-rc8
536--------------------------------------------------------------------
537 latency: 50 us, #101/101, CPU#0 | (M:preempt VP:0, KP:0, SP:0 HP:0 #P:2)
538 -----------------
539 | task: ls-4339 (uid:0 nice:0 policy:0 rt_prio:0)
540 -----------------
541 => started at: __alloc_pages_internal
542 => ended at: __alloc_pages_internal
543
544# _------=> CPU#
545# / _-----=> irqs-off
546# | / _----=> need-resched
547# || / _---=> hardirq/softirq
548# ||| / _--=> preempt-depth
549# |||| /
550# ||||| delay
551# cmd pid ||||| time | caller
552# \ / ||||| \ | /
553 ls-4339 0...1 0us+: get_page_from_freelist (__alloc_pages_internal)
554 ls-4339 0d..1 3us : rmqueue_bulk (get_page_from_freelist)
555 ls-4339 0d..1 3us : _spin_lock (rmqueue_bulk)
556 ls-4339 0d..1 4us : add_preempt_count (_spin_lock)
557 ls-4339 0d..2 4us : __rmqueue (rmqueue_bulk)
558 ls-4339 0d..2 5us : __rmqueue_smallest (__rmqueue)
559 ls-4339 0d..2 5us : __mod_zone_page_state (__rmqueue_smallest)
560 ls-4339 0d..2 6us : __rmqueue (rmqueue_bulk)
561 ls-4339 0d..2 6us : __rmqueue_smallest (__rmqueue)
562 ls-4339 0d..2 7us : __mod_zone_page_state (__rmqueue_smallest)
563 ls-4339 0d..2 7us : __rmqueue (rmqueue_bulk)
564 ls-4339 0d..2 8us : __rmqueue_smallest (__rmqueue)
565[...]
566 ls-4339 0d..2 46us : __rmqueue_smallest (__rmqueue)
567 ls-4339 0d..2 47us : __mod_zone_page_state (__rmqueue_smallest)
568 ls-4339 0d..2 47us : __rmqueue (rmqueue_bulk)
569 ls-4339 0d..2 48us : __rmqueue_smallest (__rmqueue)
570 ls-4339 0d..2 48us : __mod_zone_page_state (__rmqueue_smallest)
571 ls-4339 0d..2 49us : _spin_unlock (rmqueue_bulk)
572 ls-4339 0d..2 49us : sub_preempt_count (_spin_unlock)
573 ls-4339 0d..1 50us : get_page_from_freelist (__alloc_pages_internal)
574 ls-4339 0d..2 51us : trace_hardirqs_on (__alloc_pages_internal)
575
576
Steven Rostedteb6d42e2008-07-10 12:46:01 -0400577
578Here we traced a 50 microsecond latency. But we also see all the
Steven Rostedta41eeba2008-07-14 16:41:12 -0400579functions that were called during that time. Note that by enabling
Steven Rostedtf2d9c742008-07-15 10:57:33 -0400580function tracing, we incur an added overhead. This overhead may
Steven Rostedta41eeba2008-07-14 16:41:12 -0400581extend the latency times. But nevertheless, this trace has provided
582some very helpful debugging information.
Steven Rostedteb6d42e2008-07-10 12:46:01 -0400583
584
585preemptoff
586----------
587
Steven Rostedta41eeba2008-07-14 16:41:12 -0400588When preemption is disabled, we may be able to receive interrupts but
589the task cannot be preempted and a higher priority task must wait
Steven Rostedteb6d42e2008-07-10 12:46:01 -0400590for preemption to be enabled again before it can preempt a lower
591priority task.
592
Steven Rostedta41eeba2008-07-14 16:41:12 -0400593The preemptoff tracer traces the places that disable preemption.
Steven Rostedtf2d9c742008-07-15 10:57:33 -0400594Like the irqsoff tracer, it records the maximum latency for which preemption
595was disabled. The control of preemptoff tracer is much like the irqsoff
596tracer.
Steven Rostedteb6d42e2008-07-10 12:46:01 -0400597
598 # echo preemptoff > /debug/tracing/current_tracer
599 # echo 0 > /debug/tracing/tracing_max_latency
600 # echo 1 > /debug/tracing/tracing_enabled
601 # ls -ltr
602 [...]
603 # echo 0 > /debug/tracing/tracing_enabled
604 # cat /debug/tracing/latency_trace
605# tracer: preemptoff
606#
607preemptoff latency trace v1.1.5 on 2.6.26-rc8
608--------------------------------------------------------------------
609 latency: 29 us, #3/3, CPU#0 | (M:preempt VP:0, KP:0, SP:0 HP:0 #P:2)
610 -----------------
611 | task: sshd-4261 (uid:0 nice:0 policy:0 rt_prio:0)
612 -----------------
613 => started at: do_IRQ
614 => ended at: __do_softirq
615
616# _------=> CPU#
617# / _-----=> irqs-off
618# | / _----=> need-resched
619# || / _---=> hardirq/softirq
620# ||| / _--=> preempt-depth
621# |||| /
622# ||||| delay
623# cmd pid ||||| time | caller
624# \ / ||||| \ | /
625 sshd-4261 0d.h. 0us+: irq_enter (do_IRQ)
626 sshd-4261 0d.s. 29us : _local_bh_enable (__do_softirq)
627 sshd-4261 0d.s1 30us : trace_preempt_on (__do_softirq)
628
629
Steven Rostedteb6d42e2008-07-10 12:46:01 -0400630This has some more changes. Preemption was disabled when an interrupt
631came in (notice the 'h'), and was enabled while doing a softirq.
632(notice the 's'). But we also see that interrupts have been disabled
633when entering the preempt off section and leaving it (the 'd').
634We do not know if interrupts were enabled in the mean time.
635
636# tracer: preemptoff
637#
638preemptoff latency trace v1.1.5 on 2.6.26-rc8
639--------------------------------------------------------------------
640 latency: 63 us, #87/87, CPU#0 | (M:preempt VP:0, KP:0, SP:0 HP:0 #P:2)
641 -----------------
642 | task: sshd-4261 (uid:0 nice:0 policy:0 rt_prio:0)
643 -----------------
644 => started at: remove_wait_queue
645 => ended at: __do_softirq
646
647# _------=> CPU#
648# / _-----=> irqs-off
649# | / _----=> need-resched
650# || / _---=> hardirq/softirq
651# ||| / _--=> preempt-depth
652# |||| /
653# ||||| delay
654# cmd pid ||||| time | caller
655# \ / ||||| \ | /
656 sshd-4261 0d..1 0us : _spin_lock_irqsave (remove_wait_queue)
657 sshd-4261 0d..1 1us : _spin_unlock_irqrestore (remove_wait_queue)
658 sshd-4261 0d..1 2us : do_IRQ (common_interrupt)
659 sshd-4261 0d..1 2us : irq_enter (do_IRQ)
660 sshd-4261 0d..1 2us : idle_cpu (irq_enter)
661 sshd-4261 0d..1 3us : add_preempt_count (irq_enter)
662 sshd-4261 0d.h1 3us : idle_cpu (irq_enter)
663 sshd-4261 0d.h. 4us : handle_fasteoi_irq (do_IRQ)
664[...]
665 sshd-4261 0d.h. 12us : add_preempt_count (_spin_lock)
666 sshd-4261 0d.h1 12us : ack_ioapic_quirk_irq (handle_fasteoi_irq)
667 sshd-4261 0d.h1 13us : move_native_irq (ack_ioapic_quirk_irq)
668 sshd-4261 0d.h1 13us : _spin_unlock (handle_fasteoi_irq)
669 sshd-4261 0d.h1 14us : sub_preempt_count (_spin_unlock)
670 sshd-4261 0d.h1 14us : irq_exit (do_IRQ)
671 sshd-4261 0d.h1 15us : sub_preempt_count (irq_exit)
672 sshd-4261 0d..2 15us : do_softirq (irq_exit)
673 sshd-4261 0d... 15us : __do_softirq (do_softirq)
674 sshd-4261 0d... 16us : __local_bh_disable (__do_softirq)
675 sshd-4261 0d... 16us+: add_preempt_count (__local_bh_disable)
676 sshd-4261 0d.s4 20us : add_preempt_count (__local_bh_disable)
677 sshd-4261 0d.s4 21us : sub_preempt_count (local_bh_enable)
678 sshd-4261 0d.s5 21us : sub_preempt_count (local_bh_enable)
679[...]
680 sshd-4261 0d.s6 41us : add_preempt_count (__local_bh_disable)
681 sshd-4261 0d.s6 42us : sub_preempt_count (local_bh_enable)
682 sshd-4261 0d.s7 42us : sub_preempt_count (local_bh_enable)
683 sshd-4261 0d.s5 43us : add_preempt_count (__local_bh_disable)
684 sshd-4261 0d.s5 43us : sub_preempt_count (local_bh_enable_ip)
685 sshd-4261 0d.s6 44us : sub_preempt_count (local_bh_enable_ip)
686 sshd-4261 0d.s5 44us : add_preempt_count (__local_bh_disable)
687 sshd-4261 0d.s5 45us : sub_preempt_count (local_bh_enable)
688[...]
689 sshd-4261 0d.s. 63us : _local_bh_enable (__do_softirq)
690 sshd-4261 0d.s1 64us : trace_preempt_on (__do_softirq)
691
692
693The above is an example of the preemptoff trace with ftrace_enabled
694set. Here we see that interrupts were disabled the entire time.
695The irq_enter code lets us know that we entered an interrupt 'h'.
696Before that, the functions being traced still show that it is not
Steven Rostedtf2d9c742008-07-15 10:57:33 -0400697in an interrupt, but we can see from the functions themselves that
Steven Rostedteb6d42e2008-07-10 12:46:01 -0400698this is not the case.
699
Steven Rostedtf2d9c742008-07-15 10:57:33 -0400700Notice that __do_softirq when called does not have a preempt_count.
701It may seem that we missed a preempt enabling. What really happened
702is that the preempt count is held on the thread's stack and we
Steven Rostedteb6d42e2008-07-10 12:46:01 -0400703switched to the softirq stack (4K stacks in effect). The code
Steven Rostedta41eeba2008-07-14 16:41:12 -0400704does not copy the preempt count, but because interrupts are disabled,
Steven Rostedtf2d9c742008-07-15 10:57:33 -0400705we do not need to worry about it. Having a tracer like this is good
706for letting people know what really happens inside the kernel.
Steven Rostedteb6d42e2008-07-10 12:46:01 -0400707
708
709preemptirqsoff
710--------------
711
712Knowing the locations that have interrupts disabled or preemption
713disabled for the longest times is helpful. But sometimes we would
714like to know when either preemption and/or interrupts are disabled.
715
Steven Rostedtf2d9c742008-07-15 10:57:33 -0400716Consider the following code:
Steven Rostedteb6d42e2008-07-10 12:46:01 -0400717
718 local_irq_disable();
719 call_function_with_irqs_off();
720 preempt_disable();
721 call_function_with_irqs_and_preemption_off();
722 local_irq_enable();
723 call_function_with_preemption_off();
724 preempt_enable();
725
726The irqsoff tracer will record the total length of
727call_function_with_irqs_off() and
728call_function_with_irqs_and_preemption_off().
729
730The preemptoff tracer will record the total length of
731call_function_with_irqs_and_preemption_off() and
732call_function_with_preemption_off().
733
734But neither will trace the time that interrupts and/or preemption
735is disabled. This total time is the time that we can not schedule.
736To record this time, use the preemptirqsoff tracer.
737
738Again, using this trace is much like the irqsoff and preemptoff tracers.
739
Steven Rostedta41eeba2008-07-14 16:41:12 -0400740 # echo preemptirqsoff > /debug/tracing/current_tracer
Steven Rostedteb6d42e2008-07-10 12:46:01 -0400741 # echo 0 > /debug/tracing/tracing_max_latency
742 # echo 1 > /debug/tracing/tracing_enabled
743 # ls -ltr
744 [...]
745 # echo 0 > /debug/tracing/tracing_enabled
746 # cat /debug/tracing/latency_trace
747# tracer: preemptirqsoff
748#
749preemptirqsoff latency trace v1.1.5 on 2.6.26-rc8
750--------------------------------------------------------------------
751 latency: 293 us, #3/3, CPU#0 | (M:preempt VP:0, KP:0, SP:0 HP:0 #P:2)
752 -----------------
753 | task: ls-4860 (uid:0 nice:0 policy:0 rt_prio:0)
754 -----------------
755 => started at: apic_timer_interrupt
756 => ended at: __do_softirq
757
758# _------=> CPU#
759# / _-----=> irqs-off
760# | / _----=> need-resched
761# || / _---=> hardirq/softirq
762# ||| / _--=> preempt-depth
763# |||| /
764# ||||| delay
765# cmd pid ||||| time | caller
766# \ / ||||| \ | /
767 ls-4860 0d... 0us!: trace_hardirqs_off_thunk (apic_timer_interrupt)
768 ls-4860 0d.s. 294us : _local_bh_enable (__do_softirq)
769 ls-4860 0d.s1 294us : trace_preempt_on (__do_softirq)
770
771
Steven Rostedteb6d42e2008-07-10 12:46:01 -0400772
773The trace_hardirqs_off_thunk is called from assembly on x86 when
774interrupts are disabled in the assembly code. Without the function
Steven Rostedtf2d9c742008-07-15 10:57:33 -0400775tracing, we do not know if interrupts were enabled within the preemption
Steven Rostedteb6d42e2008-07-10 12:46:01 -0400776points. We do see that it started with preemption enabled.
777
778Here is a trace with ftrace_enabled set:
779
780
781# tracer: preemptirqsoff
782#
783preemptirqsoff latency trace v1.1.5 on 2.6.26-rc8
784--------------------------------------------------------------------
785 latency: 105 us, #183/183, CPU#0 | (M:preempt VP:0, KP:0, SP:0 HP:0 #P:2)
786 -----------------
787 | task: sshd-4261 (uid:0 nice:0 policy:0 rt_prio:0)
788 -----------------
789 => started at: write_chan
790 => ended at: __do_softirq
791
792# _------=> CPU#
793# / _-----=> irqs-off
794# | / _----=> need-resched
795# || / _---=> hardirq/softirq
796# ||| / _--=> preempt-depth
797# |||| /
798# ||||| delay
799# cmd pid ||||| time | caller
800# \ / ||||| \ | /
801 ls-4473 0.N.. 0us : preempt_schedule (write_chan)
802 ls-4473 0dN.1 1us : _spin_lock (schedule)
803 ls-4473 0dN.1 2us : add_preempt_count (_spin_lock)
804 ls-4473 0d..2 2us : put_prev_task_fair (schedule)
805[...]
806 ls-4473 0d..2 13us : set_normalized_timespec (ktime_get_ts)
807 ls-4473 0d..2 13us : __switch_to (schedule)
808 sshd-4261 0d..2 14us : finish_task_switch (schedule)
809 sshd-4261 0d..2 14us : _spin_unlock_irq (finish_task_switch)
810 sshd-4261 0d..1 15us : add_preempt_count (_spin_lock_irqsave)
811 sshd-4261 0d..2 16us : _spin_unlock_irqrestore (hrtick_set)
812 sshd-4261 0d..2 16us : do_IRQ (common_interrupt)
813 sshd-4261 0d..2 17us : irq_enter (do_IRQ)
814 sshd-4261 0d..2 17us : idle_cpu (irq_enter)
815 sshd-4261 0d..2 18us : add_preempt_count (irq_enter)
816 sshd-4261 0d.h2 18us : idle_cpu (irq_enter)
817 sshd-4261 0d.h. 18us : handle_fasteoi_irq (do_IRQ)
818 sshd-4261 0d.h. 19us : _spin_lock (handle_fasteoi_irq)
819 sshd-4261 0d.h. 19us : add_preempt_count (_spin_lock)
820 sshd-4261 0d.h1 20us : _spin_unlock (handle_fasteoi_irq)
821 sshd-4261 0d.h1 20us : sub_preempt_count (_spin_unlock)
822[...]
823 sshd-4261 0d.h1 28us : _spin_unlock (handle_fasteoi_irq)
824 sshd-4261 0d.h1 29us : sub_preempt_count (_spin_unlock)
825 sshd-4261 0d.h2 29us : irq_exit (do_IRQ)
826 sshd-4261 0d.h2 29us : sub_preempt_count (irq_exit)
827 sshd-4261 0d..3 30us : do_softirq (irq_exit)
828 sshd-4261 0d... 30us : __do_softirq (do_softirq)
829 sshd-4261 0d... 31us : __local_bh_disable (__do_softirq)
830 sshd-4261 0d... 31us+: add_preempt_count (__local_bh_disable)
831 sshd-4261 0d.s4 34us : add_preempt_count (__local_bh_disable)
832[...]
833 sshd-4261 0d.s3 43us : sub_preempt_count (local_bh_enable_ip)
834 sshd-4261 0d.s4 44us : sub_preempt_count (local_bh_enable_ip)
835 sshd-4261 0d.s3 44us : smp_apic_timer_interrupt (apic_timer_interrupt)
836 sshd-4261 0d.s3 45us : irq_enter (smp_apic_timer_interrupt)
837 sshd-4261 0d.s3 45us : idle_cpu (irq_enter)
838 sshd-4261 0d.s3 46us : add_preempt_count (irq_enter)
839 sshd-4261 0d.H3 46us : idle_cpu (irq_enter)
840 sshd-4261 0d.H3 47us : hrtimer_interrupt (smp_apic_timer_interrupt)
841 sshd-4261 0d.H3 47us : ktime_get (hrtimer_interrupt)
842[...]
843 sshd-4261 0d.H3 81us : tick_program_event (hrtimer_interrupt)
844 sshd-4261 0d.H3 82us : ktime_get (tick_program_event)
845 sshd-4261 0d.H3 82us : ktime_get_ts (ktime_get)
846 sshd-4261 0d.H3 83us : getnstimeofday (ktime_get_ts)
847 sshd-4261 0d.H3 83us : set_normalized_timespec (ktime_get_ts)
848 sshd-4261 0d.H3 84us : clockevents_program_event (tick_program_event)
849 sshd-4261 0d.H3 84us : lapic_next_event (clockevents_program_event)
850 sshd-4261 0d.H3 85us : irq_exit (smp_apic_timer_interrupt)
851 sshd-4261 0d.H3 85us : sub_preempt_count (irq_exit)
852 sshd-4261 0d.s4 86us : sub_preempt_count (irq_exit)
853 sshd-4261 0d.s3 86us : add_preempt_count (__local_bh_disable)
854[...]
855 sshd-4261 0d.s1 98us : sub_preempt_count (net_rx_action)
856 sshd-4261 0d.s. 99us : add_preempt_count (_spin_lock_irq)
857 sshd-4261 0d.s1 99us+: _spin_unlock_irq (run_timer_softirq)
858 sshd-4261 0d.s. 104us : _local_bh_enable (__do_softirq)
859 sshd-4261 0d.s. 104us : sub_preempt_count (_local_bh_enable)
860 sshd-4261 0d.s. 105us : _local_bh_enable (__do_softirq)
861 sshd-4261 0d.s1 105us : trace_preempt_on (__do_softirq)
862
863
864This is a very interesting trace. It started with the preemption of
865the ls task. We see that the task had the "need_resched" bit set
Steven Rostedtf2d9c742008-07-15 10:57:33 -0400866via the 'N' in the trace. Interrupts were disabled before the spin_lock
867at the beginning of the trace. We see that a schedule took place to run
Steven Rostedta41eeba2008-07-14 16:41:12 -0400868sshd. When the interrupts were enabled, we took an interrupt.
869On return from the interrupt handler, the softirq ran. We took another
Steven Rostedtf2d9c742008-07-15 10:57:33 -0400870interrupt while running the softirq as we see from the capital 'H'.
Steven Rostedteb6d42e2008-07-10 12:46:01 -0400871
872
873wakeup
874------
875
Steven Rostedtf2d9c742008-07-15 10:57:33 -0400876In a Real-Time environment it is very important to know the wakeup
877time it takes for the highest priority task that is woken up to the
878time that it executes. This is also known as "schedule latency".
Steven Rostedteb6d42e2008-07-10 12:46:01 -0400879I stress the point that this is about RT tasks. It is also important
880to know the scheduling latency of non-RT tasks, but the average
881schedule latency is better for non-RT tasks. Tools like
Steven Rostedta41eeba2008-07-14 16:41:12 -0400882LatencyTop are more appropriate for such measurements.
Steven Rostedteb6d42e2008-07-10 12:46:01 -0400883
Steven Rostedta41eeba2008-07-14 16:41:12 -0400884Real-Time environments are interested in the worst case latency.
Steven Rostedteb6d42e2008-07-10 12:46:01 -0400885That is the longest latency it takes for something to happen, and
886not the average. We can have a very fast scheduler that may only
887have a large latency once in a while, but that would not work well
888with Real-Time tasks. The wakeup tracer was designed to record
889the worst case wakeups of RT tasks. Non-RT tasks are not recorded
890because the tracer only records one worst case and tracing non-RT
891tasks that are unpredictable will overwrite the worst case latency
892of RT tasks.
893
894Since this tracer only deals with RT tasks, we will run this slightly
Steven Rostedta41eeba2008-07-14 16:41:12 -0400895differently than we did with the previous tracers. Instead of performing
896an 'ls', we will run 'sleep 1' under 'chrt' which changes the
Steven Rostedteb6d42e2008-07-10 12:46:01 -0400897priority of the task.
898
899 # echo wakeup > /debug/tracing/current_tracer
900 # echo 0 > /debug/tracing/tracing_max_latency
901 # echo 1 > /debug/tracing/tracing_enabled
902 # chrt -f 5 sleep 1
903 # echo 0 > /debug/tracing/tracing_enabled
904 # cat /debug/tracing/latency_trace
905# tracer: wakeup
906#
907wakeup latency trace v1.1.5 on 2.6.26-rc8
908--------------------------------------------------------------------
909 latency: 4 us, #2/2, CPU#1 | (M:preempt VP:0, KP:0, SP:0 HP:0 #P:2)
910 -----------------
911 | task: sleep-4901 (uid:0 nice:0 policy:1 rt_prio:5)
912 -----------------
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 <idle>-0 1d.h4 0us+: try_to_wake_up (wake_up_process)
924 <idle>-0 1d..4 4us : schedule (cpu_idle)
925
926
Steven Rostedteb6d42e2008-07-10 12:46:01 -0400927
Steven Rostedta41eeba2008-07-14 16:41:12 -0400928Running this on an idle system, we see that it only took 4 microseconds
Steven Rostedteb6d42e2008-07-10 12:46:01 -0400929to perform the task switch. Note, since the trace marker in the
Steven Rostedta41eeba2008-07-14 16:41:12 -0400930schedule is before the actual "switch", we stop the tracing when
Steven Rostedteb6d42e2008-07-10 12:46:01 -0400931the recorded task is about to schedule in. This may change if
932we add a new marker at the end of the scheduler.
933
934Notice that the recorded task is 'sleep' with the PID of 4901 and it
935has an rt_prio of 5. This priority is user-space priority and not
936the internal kernel priority. The policy is 1 for SCHED_FIFO and 2
937for SCHED_RR.
938
939Doing the same with chrt -r 5 and ftrace_enabled set.
940
941# tracer: wakeup
942#
943wakeup latency trace v1.1.5 on 2.6.26-rc8
944--------------------------------------------------------------------
945 latency: 50 us, #60/60, CPU#1 | (M:preempt VP:0, KP:0, SP:0 HP:0 #P:2)
946 -----------------
947 | task: sleep-4068 (uid:0 nice:0 policy:2 rt_prio:5)
948 -----------------
949
950# _------=> CPU#
951# / _-----=> irqs-off
952# | / _----=> need-resched
953# || / _---=> hardirq/softirq
954# ||| / _--=> preempt-depth
955# |||| /
956# ||||| delay
957# cmd pid ||||| time | caller
958# \ / ||||| \ | /
959ksoftirq-7 1d.H3 0us : try_to_wake_up (wake_up_process)
960ksoftirq-7 1d.H4 1us : sub_preempt_count (marker_probe_cb)
961ksoftirq-7 1d.H3 2us : check_preempt_wakeup (try_to_wake_up)
962ksoftirq-7 1d.H3 3us : update_curr (check_preempt_wakeup)
963ksoftirq-7 1d.H3 4us : calc_delta_mine (update_curr)
964ksoftirq-7 1d.H3 5us : __resched_task (check_preempt_wakeup)
965ksoftirq-7 1d.H3 6us : task_wake_up_rt (try_to_wake_up)
966ksoftirq-7 1d.H3 7us : _spin_unlock_irqrestore (try_to_wake_up)
967[...]
968ksoftirq-7 1d.H2 17us : irq_exit (smp_apic_timer_interrupt)
969ksoftirq-7 1d.H2 18us : sub_preempt_count (irq_exit)
970ksoftirq-7 1d.s3 19us : sub_preempt_count (irq_exit)
971ksoftirq-7 1..s2 20us : rcu_process_callbacks (__do_softirq)
972[...]
973ksoftirq-7 1..s2 26us : __rcu_process_callbacks (rcu_process_callbacks)
974ksoftirq-7 1d.s2 27us : _local_bh_enable (__do_softirq)
975ksoftirq-7 1d.s2 28us : sub_preempt_count (_local_bh_enable)
976ksoftirq-7 1.N.3 29us : sub_preempt_count (ksoftirqd)
977ksoftirq-7 1.N.2 30us : _cond_resched (ksoftirqd)
978ksoftirq-7 1.N.2 31us : __cond_resched (_cond_resched)
979ksoftirq-7 1.N.2 32us : add_preempt_count (__cond_resched)
980ksoftirq-7 1.N.2 33us : schedule (__cond_resched)
981ksoftirq-7 1.N.2 33us : add_preempt_count (schedule)
982ksoftirq-7 1.N.3 34us : hrtick_clear (schedule)
983ksoftirq-7 1dN.3 35us : _spin_lock (schedule)
984ksoftirq-7 1dN.3 36us : add_preempt_count (_spin_lock)
985ksoftirq-7 1d..4 37us : put_prev_task_fair (schedule)
986ksoftirq-7 1d..4 38us : update_curr (put_prev_task_fair)
987[...]
988ksoftirq-7 1d..5 47us : _spin_trylock (tracing_record_cmdline)
989ksoftirq-7 1d..5 48us : add_preempt_count (_spin_trylock)
990ksoftirq-7 1d..6 49us : _spin_unlock (tracing_record_cmdline)
991ksoftirq-7 1d..6 49us : sub_preempt_count (_spin_unlock)
992ksoftirq-7 1d..4 50us : schedule (__cond_resched)
993
994The interrupt went off while running ksoftirqd. This task runs at
Steven Rostedtf2d9c742008-07-15 10:57:33 -0400995SCHED_OTHER. Why did not we see the 'N' set early? This may be
Steven Rostedta41eeba2008-07-14 16:41:12 -0400996a harmless bug with x86_32 and 4K stacks. On x86_32 with 4K stacks
Steven Rostedtf2d9c742008-07-15 10:57:33 -0400997configured, the interrupt and softirq run with their own stack.
Steven Rostedta41eeba2008-07-14 16:41:12 -0400998Some information is held on the top of the task's stack (need_resched
999and preempt_count are both stored there). The setting of the NEED_RESCHED
1000bit is done directly to the task's stack, but the reading of the
1001NEED_RESCHED is done by looking at the current stack, which in this case
1002is the stack for the hard interrupt. This hides the fact that NEED_RESCHED
Steven Rostedtf2d9c742008-07-15 10:57:33 -04001003has been set. We do not see the 'N' until we switch back to the task's
Steven Rostedta41eeba2008-07-14 16:41:12 -04001004assigned stack.
Steven Rostedteb6d42e2008-07-10 12:46:01 -04001005
1006ftrace
1007------
1008
1009ftrace is not only the name of the tracing infrastructure, but it
1010is also a name of one of the tracers. The tracer is the function
1011tracer. Enabling the function tracer can be done from the
1012debug file system. Make sure the ftrace_enabled is set otherwise
1013this tracer is a nop.
1014
1015 # sysctl kernel.ftrace_enabled=1
1016 # echo ftrace > /debug/tracing/current_tracer
1017 # echo 1 > /debug/tracing/tracing_enabled
1018 # usleep 1
1019 # echo 0 > /debug/tracing/tracing_enabled
1020 # cat /debug/tracing/trace
1021# tracer: ftrace
1022#
1023# TASK-PID CPU# TIMESTAMP FUNCTION
1024# | | | | |
1025 bash-4003 [00] 123.638713: finish_task_switch <-schedule
1026 bash-4003 [00] 123.638714: _spin_unlock_irq <-finish_task_switch
1027 bash-4003 [00] 123.638714: sub_preempt_count <-_spin_unlock_irq
1028 bash-4003 [00] 123.638715: hrtick_set <-schedule
1029 bash-4003 [00] 123.638715: _spin_lock_irqsave <-hrtick_set
1030 bash-4003 [00] 123.638716: add_preempt_count <-_spin_lock_irqsave
1031 bash-4003 [00] 123.638716: _spin_unlock_irqrestore <-hrtick_set
1032 bash-4003 [00] 123.638717: sub_preempt_count <-_spin_unlock_irqrestore
1033 bash-4003 [00] 123.638717: hrtick_clear <-hrtick_set
1034 bash-4003 [00] 123.638718: sub_preempt_count <-schedule
1035 bash-4003 [00] 123.638718: sub_preempt_count <-preempt_schedule
1036 bash-4003 [00] 123.638719: wait_for_completion <-__stop_machine_run
1037 bash-4003 [00] 123.638719: wait_for_common <-wait_for_completion
1038 bash-4003 [00] 123.638720: _spin_lock_irq <-wait_for_common
1039 bash-4003 [00] 123.638720: add_preempt_count <-_spin_lock_irq
1040[...]
1041
1042
Steven Rostedtf2d9c742008-07-15 10:57:33 -04001043Note: ftrace uses ring buffers to store the above entries. The newest data
1044may overwrite the oldest data. Sometimes using echo to stop the trace
1045is not sufficient because the tracing could have overwritten the data
1046that you wanted to record. For this reason, it is sometimes better to
1047disable tracing directly from a program. This allows you to stop the
1048tracing at the point that you hit the part that you are interested in.
1049To disable the tracing directly from a C program, something like following
1050code snippet can be used:
Steven Rostedteb6d42e2008-07-10 12:46:01 -04001051
1052int trace_fd;
1053[...]
1054int main(int argc, char *argv[]) {
1055 [...]
1056 trace_fd = open("/debug/tracing/tracing_enabled", O_WRONLY);
1057 [...]
1058 if (condition_hit()) {
Steven Rostedtf2d9c742008-07-15 10:57:33 -04001059 write(trace_fd, "0", 1);
Steven Rostedteb6d42e2008-07-10 12:46:01 -04001060 }
1061 [...]
1062}
1063
Steven Rostedtf2d9c742008-07-15 10:57:33 -04001064Note: Here we hard coded the path name. The debugfs mount is not
1065guaranteed to be at /debug (and is more commonly at /sys/kernel/debug).
1066For simple one time traces, the above is sufficent. For anything else,
1067a search through /proc/mounts may be needed to find where the debugfs
1068file-system is mounted.
Steven Rostedteb6d42e2008-07-10 12:46:01 -04001069
1070dynamic ftrace
1071--------------
1072
Steven Rostedtf2d9c742008-07-15 10:57:33 -04001073If CONFIG_DYNAMIC_FTRACE is set, the system will run with
Steven Rostedteb6d42e2008-07-10 12:46:01 -04001074virtually no overhead when function tracing is disabled. The way
1075this works is the mcount function call (placed at the start of
1076every kernel function, produced by the -pg switch in gcc), starts
Steven Rostedtf2d9c742008-07-15 10:57:33 -04001077of pointing to a simple return. (Enabling FTRACE will include the
1078-pg switch in the compiling of the kernel.)
Steven Rostedteb6d42e2008-07-10 12:46:01 -04001079
Steven Rostedta41eeba2008-07-14 16:41:12 -04001080When dynamic ftrace is initialized, it calls kstop_machine to make
1081the machine act like a uniprocessor so that it can freely modify code
1082without worrying about other processors executing that same code. At
1083initialization, the mcount calls are changed to call a "record_ip"
Steven Rostedteb6d42e2008-07-10 12:46:01 -04001084function. After this, the first time a kernel function is called,
1085it has the calling address saved in a hash table.
1086
1087Later on the ftraced kernel thread is awoken and will again call
1088kstop_machine if new functions have been recorded. The ftraced thread
1089will change all calls to mcount to "nop". Just calling mcount
1090and having mcount return has shown a 10% overhead. By converting
Steven Rostedtf2d9c742008-07-15 10:57:33 -04001091it to a nop, there is no measurable overhead to the system.
Steven Rostedteb6d42e2008-07-10 12:46:01 -04001092
1093One special side-effect to the recording of the functions being
Steven Rostedtf2d9c742008-07-15 10:57:33 -04001094traced is that we can now selectively choose which functions we
1095wish to trace and which ones we want the mcount calls to remain as
Steven Rostedteb6d42e2008-07-10 12:46:01 -04001096nops.
1097
Steven Rostedta41eeba2008-07-14 16:41:12 -04001098Two files are used, one for enabling and one for disabling the tracing
Steven Rostedtf2d9c742008-07-15 10:57:33 -04001099of specified functions. They are:
Steven Rostedteb6d42e2008-07-10 12:46:01 -04001100
1101 set_ftrace_filter
1102
1103and
1104
1105 set_ftrace_notrace
1106
Steven Rostedta41eeba2008-07-14 16:41:12 -04001107A list of available functions that you can add to these files is listed
Steven Rostedteb6d42e2008-07-10 12:46:01 -04001108in:
1109
1110 available_filter_functions
1111
1112 # cat /debug/tracing/available_filter_functions
1113put_prev_task_idle
1114kmem_cache_create
1115pick_next_task_rt
1116get_online_cpus
1117pick_next_task_fair
1118mutex_lock
1119[...]
1120
Steven Rostedtf2d9c742008-07-15 10:57:33 -04001121If I am only interested in sys_nanosleep and hrtimer_interrupt:
Steven Rostedteb6d42e2008-07-10 12:46:01 -04001122
1123 # echo sys_nanosleep hrtimer_interrupt \
1124 > /debug/tracing/set_ftrace_filter
1125 # echo ftrace > /debug/tracing/current_tracer
1126 # echo 1 > /debug/tracing/tracing_enabled
1127 # usleep 1
1128 # echo 0 > /debug/tracing/tracing_enabled
1129 # cat /debug/tracing/trace
1130# tracer: ftrace
1131#
1132# TASK-PID CPU# TIMESTAMP FUNCTION
1133# | | | | |
1134 usleep-4134 [00] 1317.070017: hrtimer_interrupt <-smp_apic_timer_interrupt
1135 usleep-4134 [00] 1317.070111: sys_nanosleep <-syscall_call
1136 <idle>-0 [00] 1317.070115: hrtimer_interrupt <-smp_apic_timer_interrupt
1137
Steven Rostedtf2d9c742008-07-15 10:57:33 -04001138To see which functions are being traced, you can cat the file:
Steven Rostedteb6d42e2008-07-10 12:46:01 -04001139
1140 # cat /debug/tracing/set_ftrace_filter
1141hrtimer_interrupt
1142sys_nanosleep
1143
1144
Steven Rostedtf2d9c742008-07-15 10:57:33 -04001145Perhaps this is not enough. The filters also allow simple wild cards.
Steven Rostedta41eeba2008-07-14 16:41:12 -04001146Only the following are currently available
Steven Rostedteb6d42e2008-07-10 12:46:01 -04001147
Steven Rostedta41eeba2008-07-14 16:41:12 -04001148 <match>* - will match functions that begin with <match>
Steven Rostedteb6d42e2008-07-10 12:46:01 -04001149 *<match> - will match functions that end with <match>
1150 *<match>* - will match functions that have <match> in it
1151
Steven Rostedtf2d9c742008-07-15 10:57:33 -04001152These are the only wild cards which are supported.
Steven Rostedteb6d42e2008-07-10 12:46:01 -04001153
1154 <match>*<match> will not work.
1155
1156 # echo hrtimer_* > /debug/tracing/set_ftrace_filter
1157
1158Produces:
1159
1160# tracer: ftrace
1161#
1162# TASK-PID CPU# TIMESTAMP FUNCTION
1163# | | | | |
1164 bash-4003 [00] 1480.611794: hrtimer_init <-copy_process
1165 bash-4003 [00] 1480.611941: hrtimer_start <-hrtick_set
1166 bash-4003 [00] 1480.611956: hrtimer_cancel <-hrtick_clear
1167 bash-4003 [00] 1480.611956: hrtimer_try_to_cancel <-hrtimer_cancel
1168 <idle>-0 [00] 1480.612019: hrtimer_get_next_event <-get_next_timer_interrupt
1169 <idle>-0 [00] 1480.612025: hrtimer_get_next_event <-get_next_timer_interrupt
1170 <idle>-0 [00] 1480.612032: hrtimer_get_next_event <-get_next_timer_interrupt
1171 <idle>-0 [00] 1480.612037: hrtimer_get_next_event <-get_next_timer_interrupt
1172 <idle>-0 [00] 1480.612382: hrtimer_get_next_event <-get_next_timer_interrupt
1173
1174
1175Notice that we lost the sys_nanosleep.
1176
1177 # cat /debug/tracing/set_ftrace_filter
1178hrtimer_run_queues
1179hrtimer_run_pending
1180hrtimer_init
1181hrtimer_cancel
1182hrtimer_try_to_cancel
1183hrtimer_forward
1184hrtimer_start
1185hrtimer_reprogram
1186hrtimer_force_reprogram
1187hrtimer_get_next_event
1188hrtimer_interrupt
1189hrtimer_nanosleep
1190hrtimer_wakeup
1191hrtimer_get_remaining
1192hrtimer_get_res
1193hrtimer_init_sleeper
1194
1195
1196This is because the '>' and '>>' act just like they do in bash.
1197To rewrite the filters, use '>'
1198To append to the filters, use '>>'
1199
Steven Rostedta41eeba2008-07-14 16:41:12 -04001200To clear out a filter so that all functions will be recorded again:
Steven Rostedteb6d42e2008-07-10 12:46:01 -04001201
1202 # echo > /debug/tracing/set_ftrace_filter
1203 # cat /debug/tracing/set_ftrace_filter
1204 #
1205
1206Again, now we want to append.
1207
1208 # echo sys_nanosleep > /debug/tracing/set_ftrace_filter
1209 # cat /debug/tracing/set_ftrace_filter
1210sys_nanosleep
1211 # echo hrtimer_* >> /debug/tracing/set_ftrace_filter
1212 # cat /debug/tracing/set_ftrace_filter
1213hrtimer_run_queues
1214hrtimer_run_pending
1215hrtimer_init
1216hrtimer_cancel
1217hrtimer_try_to_cancel
1218hrtimer_forward
1219hrtimer_start
1220hrtimer_reprogram
1221hrtimer_force_reprogram
1222hrtimer_get_next_event
1223hrtimer_interrupt
1224sys_nanosleep
1225hrtimer_nanosleep
1226hrtimer_wakeup
1227hrtimer_get_remaining
1228hrtimer_get_res
1229hrtimer_init_sleeper
1230
1231
1232The set_ftrace_notrace prevents those functions from being traced.
1233
1234 # echo '*preempt*' '*lock*' > /debug/tracing/set_ftrace_notrace
1235
1236Produces:
1237
1238# tracer: ftrace
1239#
1240# TASK-PID CPU# TIMESTAMP FUNCTION
1241# | | | | |
1242 bash-4043 [01] 115.281644: finish_task_switch <-schedule
1243 bash-4043 [01] 115.281645: hrtick_set <-schedule
1244 bash-4043 [01] 115.281645: hrtick_clear <-hrtick_set
1245 bash-4043 [01] 115.281646: wait_for_completion <-__stop_machine_run
1246 bash-4043 [01] 115.281647: wait_for_common <-wait_for_completion
1247 bash-4043 [01] 115.281647: kthread_stop <-stop_machine_run
1248 bash-4043 [01] 115.281648: init_waitqueue_head <-kthread_stop
1249 bash-4043 [01] 115.281648: wake_up_process <-kthread_stop
1250 bash-4043 [01] 115.281649: try_to_wake_up <-wake_up_process
1251
1252We can see that there's no more lock or preempt tracing.
1253
1254ftraced
1255-------
1256
1257As mentioned above, when dynamic ftrace is configured in, a kernel
1258thread wakes up once a second and checks to see if there are mcount
Steven Rostedta41eeba2008-07-14 16:41:12 -04001259calls that need to be converted into nops. If there are not any, then
1260it simply goes back to sleep. But if there are some, it will call
Steven Rostedteb6d42e2008-07-10 12:46:01 -04001261kstop_machine to convert the calls to nops.
1262
Steven Rostedtf2d9c742008-07-15 10:57:33 -04001263There may be a case in which you do not want this added latency.
Steven Rostedteb6d42e2008-07-10 12:46:01 -04001264Perhaps you are doing some audio recording and this activity might
1265cause skips in the playback. There is an interface to disable
Steven Rostedtf2d9c742008-07-15 10:57:33 -04001266and enable the "ftraced" kernel thread.
Steven Rostedteb6d42e2008-07-10 12:46:01 -04001267
1268 # echo 0 > /debug/tracing/ftraced_enabled
1269
Steven Rostedtf2d9c742008-07-15 10:57:33 -04001270This will disable the calling of kstop_machine to update the
1271mcount calls to nops. Remember that there is a large overhead
Steven Rostedteb6d42e2008-07-10 12:46:01 -04001272to calling mcount. Without this kernel thread, that overhead will
1273exist.
1274
Steven Rostedta41eeba2008-07-14 16:41:12 -04001275If there are recorded calls to mcount, any write to the ftraced_enabled
1276file will cause the kstop_machine to run. This means that a
Steven Rostedteb6d42e2008-07-10 12:46:01 -04001277user can manually perform the updates when they want to by simply
1278echoing a '0' into the ftraced_enabled file.
1279
1280The updates are also done at the beginning of enabling a tracer
1281that uses ftrace function recording.
1282
1283
1284trace_pipe
1285----------
1286
Steven Rostedtf2d9c742008-07-15 10:57:33 -04001287The trace_pipe outputs the same content as the trace file, but the effect
1288on the tracing is different. Every read from trace_pipe is consumed.
Steven Rostedteb6d42e2008-07-10 12:46:01 -04001289This means that subsequent reads will be different. The trace
1290is live.
1291
1292 # echo ftrace > /debug/tracing/current_tracer
1293 # cat /debug/tracing/trace_pipe > /tmp/trace.out &
1294[1] 4153
1295 # echo 1 > /debug/tracing/tracing_enabled
1296 # usleep 1
1297 # echo 0 > /debug/tracing/tracing_enabled
1298 # cat /debug/tracing/trace
1299# tracer: ftrace
1300#
1301# TASK-PID CPU# TIMESTAMP FUNCTION
1302# | | | | |
1303
1304 #
1305 # cat /tmp/trace.out
1306 bash-4043 [00] 41.267106: finish_task_switch <-schedule
1307 bash-4043 [00] 41.267106: hrtick_set <-schedule
1308 bash-4043 [00] 41.267107: hrtick_clear <-hrtick_set
1309 bash-4043 [00] 41.267108: wait_for_completion <-__stop_machine_run
1310 bash-4043 [00] 41.267108: wait_for_common <-wait_for_completion
1311 bash-4043 [00] 41.267109: kthread_stop <-stop_machine_run
1312 bash-4043 [00] 41.267109: init_waitqueue_head <-kthread_stop
1313 bash-4043 [00] 41.267110: wake_up_process <-kthread_stop
1314 bash-4043 [00] 41.267110: try_to_wake_up <-wake_up_process
1315 bash-4043 [00] 41.267111: select_task_rq_rt <-try_to_wake_up
1316
1317
Steven Rostedtf2d9c742008-07-15 10:57:33 -04001318Note, reading the trace_pipe file will block until more input is added.
Steven Rostedteb6d42e2008-07-10 12:46:01 -04001319By changing the tracer, trace_pipe will issue an EOF. We needed
1320to set the ftrace tracer _before_ cating the trace_pipe file.
1321
1322
1323trace entries
1324-------------
1325
1326Having too much or not enough data can be troublesome in diagnosing
Steven Rostedtf2d9c742008-07-15 10:57:33 -04001327an issue in the kernel. The file trace_entries is used to modify
Steven Rostedta41eeba2008-07-14 16:41:12 -04001328the size of the internal trace buffers. The number listed
Steven Rostedteb6d42e2008-07-10 12:46:01 -04001329is the number of entries that can be recorded per CPU. To know
1330the full size, multiply the number of possible CPUS with the
1331number of entries.
1332
1333 # cat /debug/tracing/trace_entries
133465620
1335
Steven Rostedta41eeba2008-07-14 16:41:12 -04001336Note, to modify this, you must have tracing completely disabled. To do that,
Steven Rostedtf2d9c742008-07-15 10:57:33 -04001337echo "none" into the current_tracer. If the current_tracer is not set
1338to "none", an EINVAL error will be returned.
Steven Rostedteb6d42e2008-07-10 12:46:01 -04001339
1340 # echo none > /debug/tracing/current_tracer
1341 # echo 100000 > /debug/tracing/trace_entries
1342 # cat /debug/tracing/trace_entries
1343100045
1344
1345
1346Notice that we echoed in 100,000 but the size is 100,045. The entries
Steven Rostedtf2d9c742008-07-15 10:57:33 -04001347are held in individual pages. It allocates the number of pages it takes
Steven Rostedteb6d42e2008-07-10 12:46:01 -04001348to fulfill the request. If more entries may fit on the last page
Steven Rostedtf2d9c742008-07-15 10:57:33 -04001349then they will be added.
Steven Rostedteb6d42e2008-07-10 12:46:01 -04001350
1351 # echo 1 > /debug/tracing/trace_entries
1352 # cat /debug/tracing/trace_entries
135385
1354
Steven Rostedtf2d9c742008-07-15 10:57:33 -04001355This shows us that 85 entries can fit in a single page.
Steven Rostedteb6d42e2008-07-10 12:46:01 -04001356
Steven Rostedtf2d9c742008-07-15 10:57:33 -04001357The number of pages which will be allocated is limited to a percentage
1358of available memory. Allocating too much will produce an error.
Steven Rostedteb6d42e2008-07-10 12:46:01 -04001359
1360 # echo 1000000000000 > /debug/tracing/trace_entries
1361-bash: echo: write error: Cannot allocate memory
1362 # cat /debug/tracing/trace_entries
136385
1364