Loading...
1 ftrace - Function Tracer
2 ========================
3
4Copyright 2008 Red Hat Inc.
5 Author: Steven Rostedt <srostedt@redhat.com>
6 License: The GNU Free Documentation License, Version 1.2
7 (dual licensed under the GPL v2)
8Reviewers: Elias Oltmanns, Randy Dunlap, Andrew Morton,
9 John Kacur, and David Teigland.
10Written for: 2.6.28-rc2
11
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.
17It can be used for debugging or analyzing latencies and
18performance issues that take place outside of user-space.
19
20Although ftrace is the function tracer, it also includes an
21infrastructure 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).
27
28
29Implementation Details
30----------------------
31
32See ftrace-design.txt for details for arch porters and such.
33
34
35The File System
36---------------
37
38Ftrace uses the debugfs file system to hold the control files as
39well as the files to display output.
40
41When 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:
44
45 debugfs /sys/kernel/debug debugfs defaults 0 0
46
47Or 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.
61
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
71 current_tracer:
72
73 This is used to set or display the current tracer
74 that is configured.
75
76 available_tracers:
77
78 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.
82
83 tracing_on:
84
85 This sets or displays whether writing to the trace
86 ring buffer is enabled. Echo 0 into this file to disable
87 the tracer or 1 to enable it.
88
89 trace:
90
91 This file holds the output of the trace in a human
92 readable format (described below).
93
94 trace_pipe:
95
96 The output is the same as the "trace" file but this
97 file is meant to be streamed with live tracing.
98 Reads from this file will block until new data 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.
107
108 trace_options:
109
110 This file lets the user control the amount of data
111 that is displayed in one of the above output
112 files.
113
114 tracing_max_latency:
115
116 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
119 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)
123
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
136 due to buffer management overhead. )
137
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 This interface also allows for commands to be used. See the
159 "Filter commands" section for more details.
160
161 set_ftrace_notrace:
162
163 This has an effect opposite to that of
164 set_ftrace_filter. Any function that is added here will not
165 be traced. If a function exists in both set_ftrace_filter
166 and set_ftrace_notrace, the function will _not_ be traced.
167
168 set_ftrace_pid:
169
170 Have the function tracer only trace a single thread.
171
172 set_graph_function:
173
174 Set a "trigger" function where tracing should start
175 with the function graph tracer (See the section
176 "dynamic ftrace" for more details).
177
178 available_filter_functions:
179
180 This lists the functions that ftrace
181 has processed and can trace. These are the function
182 names that you can pass to "set_ftrace_filter" or
183 "set_ftrace_notrace". (See the section "dynamic ftrace"
184 below for more details.)
185
186
187The Tracers
188-----------
189
190Here is the list of current tracers that may be configured.
191
192 "function"
193
194 Function call tracer to trace all kernel functions.
195
196 "function_graph"
197
198 Similar to the function tracer except that the
199 function tracer probes the functions on their entry
200 whereas the function graph tracer traces on both entry
201 and exit of the functions. It then provides the ability
202 to draw a graph of function calls similar to C code
203 source.
204
205 "irqsoff"
206
207 Traces the areas that disable interrupts and saves
208 the trace with the longest max latency.
209 See tracing_max_latency. When a new max is recorded,
210 it replaces the old trace. It is best to view this
211 trace with the latency-format option enabled.
212
213 "preemptoff"
214
215 Similar to irqsoff but traces and records the amount of
216 time for which preemption is disabled.
217
218 "preemptirqsoff"
219
220 Similar to irqsoff and preemptoff, but traces and
221 records the largest time for which irqs and/or preemption
222 is disabled.
223
224 "wakeup"
225
226 Traces and records the max latency that it takes for
227 the highest priority task to get scheduled after
228 it has been woken up.
229
230 "hw-branch-tracer"
231
232 Uses the BTS CPU feature on x86 CPUs to traces all
233 branches executed.
234
235 "nop"
236
237 This is the "trace nothing" tracer. To remove all
238 tracers from tracing simply echo "nop" into
239 current_tracer.
240
241
242Examples of using the tracer
243----------------------------
244
245Here are typical examples of using the tracers when controlling
246them only with the debugfs interface (without using any
247user-land utilities).
248
249Output format:
250--------------
251
252Here is an example of the output format of the file "trace"
253
254 --------
255# tracer: function
256#
257# TASK-PID CPU# TIMESTAMP FUNCTION
258# | | | | |
259 bash-4251 [01] 10152.583854: path_put <-path_walk
260 bash-4251 [01] 10152.583855: dput <-path_put
261 bash-4251 [01] 10152.583855: _atomic_dec_and_lock <-dput
262 --------
263
264A header is printed with the tracer name that is represented by
265the trace. In this case the tracer is "function". Then a header
266showing the format. Task name "bash", the task PID "4251", the
267CPU that it was running on "01", the timestamp in <secs>.<usecs>
268format, the function name that was traced "path_put" and the
269parent function that called this function "path_walk". The
270timestamp is the time at which the function was entered.
271
272Latency trace format
273--------------------
274
275When the latency-format option is enabled, the trace file gives
276somewhat more information to see why a latency happened.
277Here is a typical trace.
278
279# tracer: irqsoff
280#
281irqsoff latency trace v1.1.5 on 2.6.26-rc8
282--------------------------------------------------------------------
283 latency: 97 us, #3/3, CPU#0 | (M:preempt VP:0, KP:0, SP:0 HP:0 #P:2)
284 -----------------
285 | task: swapper-0 (uid:0 nice:0 policy:0 rt_prio:0)
286 -----------------
287 => started at: apic_timer_interrupt
288 => ended at: do_softirq
289
290# _------=> CPU#
291# / _-----=> irqs-off
292# | / _----=> need-resched
293# || / _---=> hardirq/softirq
294# ||| / _--=> preempt-depth
295# |||| /
296# ||||| delay
297# cmd pid ||||| time | caller
298# \ / ||||| \ | /
299 <idle>-0 0d..1 0us+: trace_hardirqs_off_thunk (apic_timer_interrupt)
300 <idle>-0 0d.s. 97us : __do_softirq (do_softirq)
301 <idle>-0 0d.s1 98us : trace_hardirqs_on (do_softirq)
302
303
304This shows that the current tracer is "irqsoff" tracing the time
305for which interrupts were disabled. It gives the trace version
306and the version of the kernel upon which this was executed on
307(2.6.26-rc8). Then it displays the max latency in microsecs (97
308us). The number of trace entries displayed and the total number
309recorded (both are three: #3/3). The type of preemption that was
310used (PREEMPT). VP, KP, SP, and HP are always zero and are
311reserved for later use. #P is the number of online CPUS (#P:2).
312
313The task is the process that was running when the latency
314occurred. (swapper pid: 0).
315
316The start and stop (the functions in which the interrupts were
317disabled and enabled respectively) that caused the latencies:
318
319 apic_timer_interrupt is where the interrupts were disabled.
320 do_softirq is where they were enabled again.
321
322The next lines after the header are the trace itself. The header
323explains which is which.
324
325 cmd: The name of the process in the trace.
326
327 pid: The PID of that process.
328
329 CPU#: The CPU which the process was running on.
330
331 irqs-off: 'd' interrupts are disabled. '.' otherwise.
332 Note: If the architecture does not support a way to
333 read the irq flags variable, an 'X' will always
334 be printed here.
335
336 need-resched: 'N' task need_resched is set, '.' otherwise.
337
338 hardirq/softirq:
339 'H' - hard irq occurred inside a softirq.
340 'h' - hard irq is running
341 's' - soft irq is running
342 '.' - normal context.
343
344 preempt-depth: The level of preempt_disabled
345
346The above is mostly meaningful for kernel developers.
347
348 time: When the latency-format option is enabled, the trace file
349 output includes a timestamp relative to the start of the
350 trace. This differs from the output when latency-format
351 is disabled, which includes an absolute timestamp.
352
353 delay: This is just to help catch your eye a bit better. And
354 needs to be fixed to be only relative to the same CPU.
355 The marks are determined by the difference between this
356 current trace and the next trace.
357 '!' - greater than preempt_mark_thresh (default 100)
358 '+' - greater than 1 microsecond
359 ' ' - less than or equal to 1 microsecond.
360
361 The rest is the same as the 'trace' file.
362
363
364trace_options
365-------------
366
367The trace_options file is used to control what gets printed in
368the trace output. To see what is available, simply cat the file:
369
370 cat trace_options
371 print-parent nosym-offset nosym-addr noverbose noraw nohex nobin \
372 noblock nostacktrace nosched-tree nouserstacktrace nosym-userobj
373
374To disable one of the options, echo in the option prepended with
375"no".
376
377 echo noprint-parent > trace_options
378
379To enable an option, leave off the "no".
380
381 echo sym-offset > trace_options
382
383Here are the available options:
384
385 print-parent - On function traces, display the calling (parent)
386 function as well as the function being traced.
387
388 print-parent:
389 bash-4000 [01] 1477.606694: simple_strtoul <-strict_strtoul
390
391 noprint-parent:
392 bash-4000 [01] 1477.606694: simple_strtoul
393
394
395 sym-offset - Display not only the function name, but also the
396 offset in the function. For example, instead of
397 seeing just "ktime_get", you will see
398 "ktime_get+0xb/0x20".
399
400 sym-offset:
401 bash-4000 [01] 1477.606694: simple_strtoul+0x6/0xa0
402
403 sym-addr - this will also display the function address as well
404 as the function name.
405
406 sym-addr:
407 bash-4000 [01] 1477.606694: simple_strtoul <c0339346>
408
409 verbose - This deals with the trace file when the
410 latency-format option is enabled.
411
412 bash 4000 1 0 00000000 00010a95 [58127d26] 1720.415ms \
413 (+0.000ms): simple_strtoul (strict_strtoul)
414
415 raw - This will display raw numbers. This option is best for
416 use with user applications that can translate the raw
417 numbers better than having it done in the kernel.
418
419 hex - Similar to raw, but the numbers will be in a hexadecimal
420 format.
421
422 bin - This will print out the formats in raw binary.
423
424 block - TBD (needs update)
425
426 stacktrace - This is one of the options that changes the trace
427 itself. When a trace is recorded, so is the stack
428 of functions. This allows for back traces of
429 trace sites.
430
431 userstacktrace - This option changes the trace. It records a
432 stacktrace of the current userspace thread.
433
434 sym-userobj - when user stacktrace are enabled, look up which
435 object the address belongs to, and print a
436 relative address. This is especially useful when
437 ASLR is on, otherwise you don't get a chance to
438 resolve the address to object/file/line after
439 the app is no longer running
440
441 The lookup is performed when you read
442 trace,trace_pipe. Example:
443
444 a.out-1623 [000] 40874.465068: /root/a.out[+0x480] <-/root/a.out[+0
445x494] <- /root/a.out[+0x4a8] <- /lib/libc-2.7.so[+0x1e1a6]
446
447 sched-tree - trace all tasks that are on the runqueue, at
448 every scheduling event. Will add overhead if
449 there's a lot of tasks running at once.
450
451 latency-format - This option changes the trace. When
452 it is enabled, the trace displays
453 additional information about the
454 latencies, as described in "Latency
455 trace format".
456
457 overwrite - This controls what happens when the trace buffer is
458 full. If "1" (default), the oldest events are
459 discarded and overwritten. If "0", then the newest
460 events are discarded.
461
462ftrace_enabled
463--------------
464
465The following tracers (listed below) give different output
466depending on whether or not the sysctl ftrace_enabled is set. To
467set ftrace_enabled, one can either use the sysctl function or
468set it via the proc file system interface.
469
470 sysctl kernel.ftrace_enabled=1
471
472 or
473
474 echo 1 > /proc/sys/kernel/ftrace_enabled
475
476To disable ftrace_enabled simply replace the '1' with '0' in the
477above commands.
478
479When ftrace_enabled is set the tracers will also record the
480functions that are within the trace. The descriptions of the
481tracers will also show an example with ftrace enabled.
482
483
484irqsoff
485-------
486
487When interrupts are disabled, the CPU can not react to any other
488external event (besides NMIs and SMIs). This prevents the timer
489interrupt from triggering or the mouse interrupt from letting
490the kernel know of a new mouse event. The result is a latency
491with the reaction time.
492
493The irqsoff tracer tracks the time for which interrupts are
494disabled. When a new maximum latency is hit, the tracer saves
495the trace leading up to that latency point so that every time a
496new maximum is reached, the old saved trace is discarded and the
497new trace is saved.
498
499To reset the maximum, echo 0 into tracing_max_latency. Here is
500an example:
501
502 # echo irqsoff > current_tracer
503 # echo latency-format > trace_options
504 # echo 0 > tracing_max_latency
505 # echo 1 > tracing_on
506 # ls -ltr
507 [...]
508 # echo 0 > tracing_on
509 # cat trace
510# tracer: irqsoff
511#
512irqsoff latency trace v1.1.5 on 2.6.26
513--------------------------------------------------------------------
514 latency: 12 us, #3/3, CPU#1 | (M:preempt VP:0, KP:0, SP:0 HP:0 #P:2)
515 -----------------
516 | task: bash-3730 (uid:0 nice:0 policy:0 rt_prio:0)
517 -----------------
518 => started at: sys_setpgid
519 => ended at: sys_setpgid
520
521# _------=> CPU#
522# / _-----=> irqs-off
523# | / _----=> need-resched
524# || / _---=> hardirq/softirq
525# ||| / _--=> preempt-depth
526# |||| /
527# ||||| delay
528# cmd pid ||||| time | caller
529# \ / ||||| \ | /
530 bash-3730 1d... 0us : _write_lock_irq (sys_setpgid)
531 bash-3730 1d..1 1us+: _write_unlock_irq (sys_setpgid)
532 bash-3730 1d..2 14us : trace_hardirqs_on (sys_setpgid)
533
534
535Here we see that that we had a latency of 12 microsecs (which is
536very good). The _write_lock_irq in sys_setpgid disabled
537interrupts. The difference between the 12 and the displayed
538timestamp 14us occurred because the clock was incremented
539between the time of recording the max latency and the time of
540recording the function that had that latency.
541
542Note the above example had ftrace_enabled not set. If we set the
543ftrace_enabled, we get a much larger output:
544
545# tracer: irqsoff
546#
547irqsoff latency trace v1.1.5 on 2.6.26-rc8
548--------------------------------------------------------------------
549 latency: 50 us, #101/101, CPU#0 | (M:preempt VP:0, KP:0, SP:0 HP:0 #P:2)
550 -----------------
551 | task: ls-4339 (uid:0 nice:0 policy:0 rt_prio:0)
552 -----------------
553 => started at: __alloc_pages_internal
554 => ended at: __alloc_pages_internal
555
556# _------=> CPU#
557# / _-----=> irqs-off
558# | / _----=> need-resched
559# || / _---=> hardirq/softirq
560# ||| / _--=> preempt-depth
561# |||| /
562# ||||| delay
563# cmd pid ||||| time | caller
564# \ / ||||| \ | /
565 ls-4339 0...1 0us+: get_page_from_freelist (__alloc_pages_internal)
566 ls-4339 0d..1 3us : rmqueue_bulk (get_page_from_freelist)
567 ls-4339 0d..1 3us : _spin_lock (rmqueue_bulk)
568 ls-4339 0d..1 4us : add_preempt_count (_spin_lock)
569 ls-4339 0d..2 4us : __rmqueue (rmqueue_bulk)
570 ls-4339 0d..2 5us : __rmqueue_smallest (__rmqueue)
571 ls-4339 0d..2 5us : __mod_zone_page_state (__rmqueue_smallest)
572 ls-4339 0d..2 6us : __rmqueue (rmqueue_bulk)
573 ls-4339 0d..2 6us : __rmqueue_smallest (__rmqueue)
574 ls-4339 0d..2 7us : __mod_zone_page_state (__rmqueue_smallest)
575 ls-4339 0d..2 7us : __rmqueue (rmqueue_bulk)
576 ls-4339 0d..2 8us : __rmqueue_smallest (__rmqueue)
577[...]
578 ls-4339 0d..2 46us : __rmqueue_smallest (__rmqueue)
579 ls-4339 0d..2 47us : __mod_zone_page_state (__rmqueue_smallest)
580 ls-4339 0d..2 47us : __rmqueue (rmqueue_bulk)
581 ls-4339 0d..2 48us : __rmqueue_smallest (__rmqueue)
582 ls-4339 0d..2 48us : __mod_zone_page_state (__rmqueue_smallest)
583 ls-4339 0d..2 49us : _spin_unlock (rmqueue_bulk)
584 ls-4339 0d..2 49us : sub_preempt_count (_spin_unlock)
585 ls-4339 0d..1 50us : get_page_from_freelist (__alloc_pages_internal)
586 ls-4339 0d..2 51us : trace_hardirqs_on (__alloc_pages_internal)
587
588
589
590Here we traced a 50 microsecond latency. But we also see all the
591functions that were called during that time. Note that by
592enabling function tracing, we incur an added overhead. This
593overhead may extend the latency times. But nevertheless, this
594trace has provided some very helpful debugging information.
595
596
597preemptoff
598----------
599
600When preemption is disabled, we may be able to receive
601interrupts but the task cannot be preempted and a higher
602priority task must wait for preemption to be enabled again
603before it can preempt a lower priority task.
604
605The preemptoff tracer traces the places that disable preemption.
606Like the irqsoff tracer, it records the maximum latency for
607which preemption was disabled. The control of preemptoff tracer
608is much like the irqsoff tracer.
609
610 # echo preemptoff > current_tracer
611 # echo latency-format > trace_options
612 # echo 0 > tracing_max_latency
613 # echo 1 > tracing_on
614 # ls -ltr
615 [...]
616 # echo 0 > tracing_on
617 # cat trace
618# tracer: preemptoff
619#
620preemptoff latency trace v1.1.5 on 2.6.26-rc8
621--------------------------------------------------------------------
622 latency: 29 us, #3/3, CPU#0 | (M:preempt VP:0, KP:0, SP:0 HP:0 #P:2)
623 -----------------
624 | task: sshd-4261 (uid:0 nice:0 policy:0 rt_prio:0)
625 -----------------
626 => started at: do_IRQ
627 => ended at: __do_softirq
628
629# _------=> CPU#
630# / _-----=> irqs-off
631# | / _----=> need-resched
632# || / _---=> hardirq/softirq
633# ||| / _--=> preempt-depth
634# |||| /
635# ||||| delay
636# cmd pid ||||| time | caller
637# \ / ||||| \ | /
638 sshd-4261 0d.h. 0us+: irq_enter (do_IRQ)
639 sshd-4261 0d.s. 29us : _local_bh_enable (__do_softirq)
640 sshd-4261 0d.s1 30us : trace_preempt_on (__do_softirq)
641
642
643This has some more changes. Preemption was disabled when an
644interrupt came in (notice the 'h'), and was enabled while doing
645a softirq. (notice the 's'). But we also see that interrupts
646have been disabled when entering the preempt off section and
647leaving it (the 'd'). We do not know if interrupts were enabled
648in the mean time.
649
650# tracer: preemptoff
651#
652preemptoff latency trace v1.1.5 on 2.6.26-rc8
653--------------------------------------------------------------------
654 latency: 63 us, #87/87, CPU#0 | (M:preempt VP:0, KP:0, SP:0 HP:0 #P:2)
655 -----------------
656 | task: sshd-4261 (uid:0 nice:0 policy:0 rt_prio:0)
657 -----------------
658 => started at: remove_wait_queue
659 => ended at: __do_softirq
660
661# _------=> CPU#
662# / _-----=> irqs-off
663# | / _----=> need-resched
664# || / _---=> hardirq/softirq
665# ||| / _--=> preempt-depth
666# |||| /
667# ||||| delay
668# cmd pid ||||| time | caller
669# \ / ||||| \ | /
670 sshd-4261 0d..1 0us : _spin_lock_irqsave (remove_wait_queue)
671 sshd-4261 0d..1 1us : _spin_unlock_irqrestore (remove_wait_queue)
672 sshd-4261 0d..1 2us : do_IRQ (common_interrupt)
673 sshd-4261 0d..1 2us : irq_enter (do_IRQ)
674 sshd-4261 0d..1 2us : idle_cpu (irq_enter)
675 sshd-4261 0d..1 3us : add_preempt_count (irq_enter)
676 sshd-4261 0d.h1 3us : idle_cpu (irq_enter)
677 sshd-4261 0d.h. 4us : handle_fasteoi_irq (do_IRQ)
678[...]
679 sshd-4261 0d.h. 12us : add_preempt_count (_spin_lock)
680 sshd-4261 0d.h1 12us : ack_ioapic_quirk_irq (handle_fasteoi_irq)
681 sshd-4261 0d.h1 13us : move_native_irq (ack_ioapic_quirk_irq)
682 sshd-4261 0d.h1 13us : _spin_unlock (handle_fasteoi_irq)
683 sshd-4261 0d.h1 14us : sub_preempt_count (_spin_unlock)
684 sshd-4261 0d.h1 14us : irq_exit (do_IRQ)
685 sshd-4261 0d.h1 15us : sub_preempt_count (irq_exit)
686 sshd-4261 0d..2 15us : do_softirq (irq_exit)
687 sshd-4261 0d... 15us : __do_softirq (do_softirq)
688 sshd-4261 0d... 16us : __local_bh_disable (__do_softirq)
689 sshd-4261 0d... 16us+: add_preempt_count (__local_bh_disable)
690 sshd-4261 0d.s4 20us : add_preempt_count (__local_bh_disable)
691 sshd-4261 0d.s4 21us : sub_preempt_count (local_bh_enable)
692 sshd-4261 0d.s5 21us : sub_preempt_count (local_bh_enable)
693[...]
694 sshd-4261 0d.s6 41us : add_preempt_count (__local_bh_disable)
695 sshd-4261 0d.s6 42us : sub_preempt_count (local_bh_enable)
696 sshd-4261 0d.s7 42us : sub_preempt_count (local_bh_enable)
697 sshd-4261 0d.s5 43us : add_preempt_count (__local_bh_disable)
698 sshd-4261 0d.s5 43us : sub_preempt_count (local_bh_enable_ip)
699 sshd-4261 0d.s6 44us : sub_preempt_count (local_bh_enable_ip)
700 sshd-4261 0d.s5 44us : add_preempt_count (__local_bh_disable)
701 sshd-4261 0d.s5 45us : sub_preempt_count (local_bh_enable)
702[...]
703 sshd-4261 0d.s. 63us : _local_bh_enable (__do_softirq)
704 sshd-4261 0d.s1 64us : trace_preempt_on (__do_softirq)
705
706
707The above is an example of the preemptoff trace with
708ftrace_enabled set. Here we see that interrupts were disabled
709the entire time. The irq_enter code lets us know that we entered
710an interrupt 'h'. Before that, the functions being traced still
711show that it is not in an interrupt, but we can see from the
712functions themselves that this is not the case.
713
714Notice that __do_softirq when called does not have a
715preempt_count. It may seem that we missed a preempt enabling.
716What really happened is that the preempt count is held on the
717thread's stack and we switched to the softirq stack (4K stacks
718in effect). The code does not copy the preempt count, but
719because interrupts are disabled, we do not need to worry about
720it. Having a tracer like this is good for letting people know
721what really happens inside the kernel.
722
723
724preemptirqsoff
725--------------
726
727Knowing the locations that have interrupts disabled or
728preemption disabled for the longest times is helpful. But
729sometimes we would like to know when either preemption and/or
730interrupts are disabled.
731
732Consider the following code:
733
734 local_irq_disable();
735 call_function_with_irqs_off();
736 preempt_disable();
737 call_function_with_irqs_and_preemption_off();
738 local_irq_enable();
739 call_function_with_preemption_off();
740 preempt_enable();
741
742The irqsoff tracer will record the total length of
743call_function_with_irqs_off() and
744call_function_with_irqs_and_preemption_off().
745
746The preemptoff tracer will record the total length of
747call_function_with_irqs_and_preemption_off() and
748call_function_with_preemption_off().
749
750But neither will trace the time that interrupts and/or
751preemption is disabled. This total time is the time that we can
752not schedule. To record this time, use the preemptirqsoff
753tracer.
754
755Again, using this trace is much like the irqsoff and preemptoff
756tracers.
757
758 # echo preemptirqsoff > current_tracer
759 # echo latency-format > trace_options
760 # echo 0 > tracing_max_latency
761 # echo 1 > tracing_on
762 # ls -ltr
763 [...]
764 # echo 0 > tracing_on
765 # cat trace
766# tracer: preemptirqsoff
767#
768preemptirqsoff latency trace v1.1.5 on 2.6.26-rc8
769--------------------------------------------------------------------
770 latency: 293 us, #3/3, CPU#0 | (M:preempt VP:0, KP:0, SP:0 HP:0 #P:2)
771 -----------------
772 | task: ls-4860 (uid:0 nice:0 policy:0 rt_prio:0)
773 -----------------
774 => started at: apic_timer_interrupt
775 => ended at: __do_softirq
776
777# _------=> CPU#
778# / _-----=> irqs-off
779# | / _----=> need-resched
780# || / _---=> hardirq/softirq
781# ||| / _--=> preempt-depth
782# |||| /
783# ||||| delay
784# cmd pid ||||| time | caller
785# \ / ||||| \ | /
786 ls-4860 0d... 0us!: trace_hardirqs_off_thunk (apic_timer_interrupt)
787 ls-4860 0d.s. 294us : _local_bh_enable (__do_softirq)
788 ls-4860 0d.s1 294us : trace_preempt_on (__do_softirq)
789
790
791
792The trace_hardirqs_off_thunk is called from assembly on x86 when
793interrupts are disabled in the assembly code. Without the
794function tracing, we do not know if interrupts were enabled
795within the preemption points. We do see that it started with
796preemption enabled.
797
798Here is a trace with ftrace_enabled set:
799
800
801# tracer: preemptirqsoff
802#
803preemptirqsoff latency trace v1.1.5 on 2.6.26-rc8
804--------------------------------------------------------------------
805 latency: 105 us, #183/183, CPU#0 | (M:preempt VP:0, KP:0, SP:0 HP:0 #P:2)
806 -----------------
807 | task: sshd-4261 (uid:0 nice:0 policy:0 rt_prio:0)
808 -----------------
809 => started at: write_chan
810 => ended at: __do_softirq
811
812# _------=> CPU#
813# / _-----=> irqs-off
814# | / _----=> need-resched
815# || / _---=> hardirq/softirq
816# ||| / _--=> preempt-depth
817# |||| /
818# ||||| delay
819# cmd pid ||||| time | caller
820# \ / ||||| \ | /
821 ls-4473 0.N.. 0us : preempt_schedule (write_chan)
822 ls-4473 0dN.1 1us : _spin_lock (schedule)
823 ls-4473 0dN.1 2us : add_preempt_count (_spin_lock)
824 ls-4473 0d..2 2us : put_prev_task_fair (schedule)
825[...]
826 ls-4473 0d..2 13us : set_normalized_timespec (ktime_get_ts)
827 ls-4473 0d..2 13us : __switch_to (schedule)
828 sshd-4261 0d..2 14us : finish_task_switch (schedule)
829 sshd-4261 0d..2 14us : _spin_unlock_irq (finish_task_switch)
830 sshd-4261 0d..1 15us : add_preempt_count (_spin_lock_irqsave)
831 sshd-4261 0d..2 16us : _spin_unlock_irqrestore (hrtick_set)
832 sshd-4261 0d..2 16us : do_IRQ (common_interrupt)
833 sshd-4261 0d..2 17us : irq_enter (do_IRQ)
834 sshd-4261 0d..2 17us : idle_cpu (irq_enter)
835 sshd-4261 0d..2 18us : add_preempt_count (irq_enter)
836 sshd-4261 0d.h2 18us : idle_cpu (irq_enter)
837 sshd-4261 0d.h. 18us : handle_fasteoi_irq (do_IRQ)
838 sshd-4261 0d.h. 19us : _spin_lock (handle_fasteoi_irq)
839 sshd-4261 0d.h. 19us : add_preempt_count (_spin_lock)
840 sshd-4261 0d.h1 20us : _spin_unlock (handle_fasteoi_irq)
841 sshd-4261 0d.h1 20us : sub_preempt_count (_spin_unlock)
842[...]
843 sshd-4261 0d.h1 28us : _spin_unlock (handle_fasteoi_irq)
844 sshd-4261 0d.h1 29us : sub_preempt_count (_spin_unlock)
845 sshd-4261 0d.h2 29us : irq_exit (do_IRQ)
846 sshd-4261 0d.h2 29us : sub_preempt_count (irq_exit)
847 sshd-4261 0d..3 30us : do_softirq (irq_exit)
848 sshd-4261 0d... 30us : __do_softirq (do_softirq)
849 sshd-4261 0d... 31us : __local_bh_disable (__do_softirq)
850 sshd-4261 0d... 31us+: add_preempt_count (__local_bh_disable)
851 sshd-4261 0d.s4 34us : add_preempt_count (__local_bh_disable)
852[...]
853 sshd-4261 0d.s3 43us : sub_preempt_count (local_bh_enable_ip)
854 sshd-4261 0d.s4 44us : sub_preempt_count (local_bh_enable_ip)
855 sshd-4261 0d.s3 44us : smp_apic_timer_interrupt (apic_timer_interrupt)
856 sshd-4261 0d.s3 45us : irq_enter (smp_apic_timer_interrupt)
857 sshd-4261 0d.s3 45us : idle_cpu (irq_enter)
858 sshd-4261 0d.s3 46us : add_preempt_count (irq_enter)
859 sshd-4261 0d.H3 46us : idle_cpu (irq_enter)
860 sshd-4261 0d.H3 47us : hrtimer_interrupt (smp_apic_timer_interrupt)
861 sshd-4261 0d.H3 47us : ktime_get (hrtimer_interrupt)
862[...]
863 sshd-4261 0d.H3 81us : tick_program_event (hrtimer_interrupt)
864 sshd-4261 0d.H3 82us : ktime_get (tick_program_event)
865 sshd-4261 0d.H3 82us : ktime_get_ts (ktime_get)
866 sshd-4261 0d.H3 83us : getnstimeofday (ktime_get_ts)
867 sshd-4261 0d.H3 83us : set_normalized_timespec (ktime_get_ts)
868 sshd-4261 0d.H3 84us : clockevents_program_event (tick_program_event)
869 sshd-4261 0d.H3 84us : lapic_next_event (clockevents_program_event)
870 sshd-4261 0d.H3 85us : irq_exit (smp_apic_timer_interrupt)
871 sshd-4261 0d.H3 85us : sub_preempt_count (irq_exit)
872 sshd-4261 0d.s4 86us : sub_preempt_count (irq_exit)
873 sshd-4261 0d.s3 86us : add_preempt_count (__local_bh_disable)
874[...]
875 sshd-4261 0d.s1 98us : sub_preempt_count (net_rx_action)
876 sshd-4261 0d.s. 99us : add_preempt_count (_spin_lock_irq)
877 sshd-4261 0d.s1 99us+: _spin_unlock_irq (run_timer_softirq)
878 sshd-4261 0d.s. 104us : _local_bh_enable (__do_softirq)
879 sshd-4261 0d.s. 104us : sub_preempt_count (_local_bh_enable)
880 sshd-4261 0d.s. 105us : _local_bh_enable (__do_softirq)
881 sshd-4261 0d.s1 105us : trace_preempt_on (__do_softirq)
882
883
884This is a very interesting trace. It started with the preemption
885of the ls task. We see that the task had the "need_resched" bit
886set via the 'N' in the trace. Interrupts were disabled before
887the spin_lock at the beginning of the trace. We see that a
888schedule took place to run sshd. When the interrupts were
889enabled, we took an interrupt. On return from the interrupt
890handler, the softirq ran. We took another interrupt while
891running the softirq as we see from the capital 'H'.
892
893
894wakeup
895------
896
897In a Real-Time environment it is very important to know the
898wakeup time it takes for the highest priority task that is woken
899up to the time that it executes. This is also known as "schedule
900latency". I stress the point that this is about RT tasks. It is
901also important to know the scheduling latency of non-RT tasks,
902but the average schedule latency is better for non-RT tasks.
903Tools like LatencyTop are more appropriate for such
904measurements.
905
906Real-Time environments are interested in the worst case latency.
907That is the longest latency it takes for something to happen,
908and not the average. We can have a very fast scheduler that may
909only have a large latency once in a while, but that would not
910work well with Real-Time tasks. The wakeup tracer was designed
911to record the worst case wakeups of RT tasks. Non-RT tasks are
912not recorded because the tracer only records one worst case and
913tracing non-RT tasks that are unpredictable will overwrite the
914worst case latency of RT tasks.
915
916Since this tracer only deals with RT tasks, we will run this
917slightly differently than we did with the previous tracers.
918Instead of performing an 'ls', we will run 'sleep 1' under
919'chrt' which changes the priority of the task.
920
921 # echo wakeup > current_tracer
922 # echo latency-format > trace_options
923 # echo 0 > tracing_max_latency
924 # echo 1 > tracing_on
925 # chrt -f 5 sleep 1
926 # echo 0 > tracing_on
927 # cat trace
928# tracer: wakeup
929#
930wakeup latency trace v1.1.5 on 2.6.26-rc8
931--------------------------------------------------------------------
932 latency: 4 us, #2/2, CPU#1 | (M:preempt VP:0, KP:0, SP:0 HP:0 #P:2)
933 -----------------
934 | task: sleep-4901 (uid:0 nice:0 policy:1 rt_prio:5)
935 -----------------
936
937# _------=> CPU#
938# / _-----=> irqs-off
939# | / _----=> need-resched
940# || / _---=> hardirq/softirq
941# ||| / _--=> preempt-depth
942# |||| /
943# ||||| delay
944# cmd pid ||||| time | caller
945# \ / ||||| \ | /
946 <idle>-0 1d.h4 0us+: try_to_wake_up (wake_up_process)
947 <idle>-0 1d..4 4us : schedule (cpu_idle)
948
949
950Running this on an idle system, we see that it only took 4
951microseconds to perform the task switch. Note, since the trace
952marker in the schedule is before the actual "switch", we stop
953the tracing when the recorded task is about to schedule in. This
954may change if we add a new marker at the end of the scheduler.
955
956Notice that the recorded task is 'sleep' with the PID of 4901
957and it has an rt_prio of 5. This priority is user-space priority
958and not the internal kernel priority. The policy is 1 for
959SCHED_FIFO and 2 for SCHED_RR.
960
961Doing the same with chrt -r 5 and ftrace_enabled set.
962
963# tracer: wakeup
964#
965wakeup latency trace v1.1.5 on 2.6.26-rc8
966--------------------------------------------------------------------
967 latency: 50 us, #60/60, CPU#1 | (M:preempt VP:0, KP:0, SP:0 HP:0 #P:2)
968 -----------------
969 | task: sleep-4068 (uid:0 nice:0 policy:2 rt_prio:5)
970 -----------------
971
972# _------=> CPU#
973# / _-----=> irqs-off
974# | / _----=> need-resched
975# || / _---=> hardirq/softirq
976# ||| / _--=> preempt-depth
977# |||| /
978# ||||| delay
979# cmd pid ||||| time | caller
980# \ / ||||| \ | /
981ksoftirq-7 1d.H3 0us : try_to_wake_up (wake_up_process)
982ksoftirq-7 1d.H4 1us : sub_preempt_count (marker_probe_cb)
983ksoftirq-7 1d.H3 2us : check_preempt_wakeup (try_to_wake_up)
984ksoftirq-7 1d.H3 3us : update_curr (check_preempt_wakeup)
985ksoftirq-7 1d.H3 4us : calc_delta_mine (update_curr)
986ksoftirq-7 1d.H3 5us : __resched_task (check_preempt_wakeup)
987ksoftirq-7 1d.H3 6us : task_wake_up_rt (try_to_wake_up)
988ksoftirq-7 1d.H3 7us : _spin_unlock_irqrestore (try_to_wake_up)
989[...]
990ksoftirq-7 1d.H2 17us : irq_exit (smp_apic_timer_interrupt)
991ksoftirq-7 1d.H2 18us : sub_preempt_count (irq_exit)
992ksoftirq-7 1d.s3 19us : sub_preempt_count (irq_exit)
993ksoftirq-7 1..s2 20us : rcu_process_callbacks (__do_softirq)
994[...]
995ksoftirq-7 1..s2 26us : __rcu_process_callbacks (rcu_process_callbacks)
996ksoftirq-7 1d.s2 27us : _local_bh_enable (__do_softirq)
997ksoftirq-7 1d.s2 28us : sub_preempt_count (_local_bh_enable)
998ksoftirq-7 1.N.3 29us : sub_preempt_count (ksoftirqd)
999ksoftirq-7 1.N.2 30us : _cond_resched (ksoftirqd)
1000ksoftirq-7 1.N.2 31us : __cond_resched (_cond_resched)
1001ksoftirq-7 1.N.2 32us : add_preempt_count (__cond_resched)
1002ksoftirq-7 1.N.2 33us : schedule (__cond_resched)
1003ksoftirq-7 1.N.2 33us : add_preempt_count (schedule)
1004ksoftirq-7 1.N.3 34us : hrtick_clear (schedule)
1005ksoftirq-7 1dN.3 35us : _spin_lock (schedule)
1006ksoftirq-7 1dN.3 36us : add_preempt_count (_spin_lock)
1007ksoftirq-7 1d..4 37us : put_prev_task_fair (schedule)
1008ksoftirq-7 1d..4 38us : update_curr (put_prev_task_fair)
1009[...]
1010ksoftirq-7 1d..5 47us : _spin_trylock (tracing_record_cmdline)
1011ksoftirq-7 1d..5 48us : add_preempt_count (_spin_trylock)
1012ksoftirq-7 1d..6 49us : _spin_unlock (tracing_record_cmdline)
1013ksoftirq-7 1d..6 49us : sub_preempt_count (_spin_unlock)
1014ksoftirq-7 1d..4 50us : schedule (__cond_resched)
1015
1016The interrupt went off while running ksoftirqd. This task runs
1017at SCHED_OTHER. Why did not we see the 'N' set early? This may
1018be a harmless bug with x86_32 and 4K stacks. On x86_32 with 4K
1019stacks configured, the interrupt and softirq run with their own
1020stack. Some information is held on the top of the task's stack
1021(need_resched and preempt_count are both stored there). The
1022setting of the NEED_RESCHED bit is done directly to the task's
1023stack, but the reading of the NEED_RESCHED is done by looking at
1024the current stack, which in this case is the stack for the hard
1025interrupt. This hides the fact that NEED_RESCHED has been set.
1026We do not see the 'N' until we switch back to the task's
1027assigned stack.
1028
1029function
1030--------
1031
1032This tracer is the function tracer. Enabling the function tracer
1033can be done from the debug file system. Make sure the
1034ftrace_enabled is set; otherwise this tracer is a nop.
1035
1036 # sysctl kernel.ftrace_enabled=1
1037 # echo function > current_tracer
1038 # echo 1 > tracing_on
1039 # usleep 1
1040 # echo 0 > tracing_on
1041 # cat trace
1042# tracer: function
1043#
1044# TASK-PID CPU# TIMESTAMP FUNCTION
1045# | | | | |
1046 bash-4003 [00] 123.638713: finish_task_switch <-schedule
1047 bash-4003 [00] 123.638714: _spin_unlock_irq <-finish_task_switch
1048 bash-4003 [00] 123.638714: sub_preempt_count <-_spin_unlock_irq
1049 bash-4003 [00] 123.638715: hrtick_set <-schedule
1050 bash-4003 [00] 123.638715: _spin_lock_irqsave <-hrtick_set
1051 bash-4003 [00] 123.638716: add_preempt_count <-_spin_lock_irqsave
1052 bash-4003 [00] 123.638716: _spin_unlock_irqrestore <-hrtick_set
1053 bash-4003 [00] 123.638717: sub_preempt_count <-_spin_unlock_irqrestore
1054 bash-4003 [00] 123.638717: hrtick_clear <-hrtick_set
1055 bash-4003 [00] 123.638718: sub_preempt_count <-schedule
1056 bash-4003 [00] 123.638718: sub_preempt_count <-preempt_schedule
1057 bash-4003 [00] 123.638719: wait_for_completion <-__stop_machine_run
1058 bash-4003 [00] 123.638719: wait_for_common <-wait_for_completion
1059 bash-4003 [00] 123.638720: _spin_lock_irq <-wait_for_common
1060 bash-4003 [00] 123.638720: add_preempt_count <-_spin_lock_irq
1061[...]
1062
1063
1064Note: function tracer uses ring buffers to store the above
1065entries. The newest data may overwrite the oldest data.
1066Sometimes using echo to stop the trace is not sufficient because
1067the tracing could have overwritten the data that you wanted to
1068record. For this reason, it is sometimes better to disable
1069tracing directly from a program. This allows you to stop the
1070tracing at the point that you hit the part that you are
1071interested in. To disable the tracing directly from a C program,
1072something like following code snippet can be used:
1073
1074int trace_fd;
1075[...]
1076int main(int argc, char *argv[]) {
1077 [...]
1078 trace_fd = open(tracing_file("tracing_on"), O_WRONLY);
1079 [...]
1080 if (condition_hit()) {
1081 write(trace_fd, "0", 1);
1082 }
1083 [...]
1084}
1085
1086
1087Single thread tracing
1088---------------------
1089
1090By writing into set_ftrace_pid you can trace a
1091single thread. For example:
1092
1093# cat set_ftrace_pid
1094no pid
1095# echo 3111 > set_ftrace_pid
1096# cat set_ftrace_pid
10973111
1098# echo function > current_tracer
1099# cat trace | head
1100 # tracer: function
1101 #
1102 # TASK-PID CPU# TIMESTAMP FUNCTION
1103 # | | | | |
1104 yum-updatesd-3111 [003] 1637.254676: finish_task_switch <-thread_return
1105 yum-updatesd-3111 [003] 1637.254681: hrtimer_cancel <-schedule_hrtimeout_range
1106 yum-updatesd-3111 [003] 1637.254682: hrtimer_try_to_cancel <-hrtimer_cancel
1107 yum-updatesd-3111 [003] 1637.254683: lock_hrtimer_base <-hrtimer_try_to_cancel
1108 yum-updatesd-3111 [003] 1637.254685: fget_light <-do_sys_poll
1109 yum-updatesd-3111 [003] 1637.254686: pipe_poll <-do_sys_poll
1110# echo -1 > set_ftrace_pid
1111# cat trace |head
1112 # tracer: function
1113 #
1114 # TASK-PID CPU# TIMESTAMP FUNCTION
1115 # | | | | |
1116 ##### CPU 3 buffer started ####
1117 yum-updatesd-3111 [003] 1701.957688: free_poll_entry <-poll_freewait
1118 yum-updatesd-3111 [003] 1701.957689: remove_wait_queue <-free_poll_entry
1119 yum-updatesd-3111 [003] 1701.957691: fput <-free_poll_entry
1120 yum-updatesd-3111 [003] 1701.957692: audit_syscall_exit <-sysret_audit
1121 yum-updatesd-3111 [003] 1701.957693: path_put <-audit_syscall_exit
1122
1123If you want to trace a function when executing, you could use
1124something like this simple program:
1125
1126#include <stdio.h>
1127#include <stdlib.h>
1128#include <sys/types.h>
1129#include <sys/stat.h>
1130#include <fcntl.h>
1131#include <unistd.h>
1132#include <string.h>
1133
1134#define _STR(x) #x
1135#define STR(x) _STR(x)
1136#define MAX_PATH 256
1137
1138const char *find_debugfs(void)
1139{
1140 static char debugfs[MAX_PATH+1];
1141 static int debugfs_found;
1142 char type[100];
1143 FILE *fp;
1144
1145 if (debugfs_found)
1146 return debugfs;
1147
1148 if ((fp = fopen("/proc/mounts","r")) == NULL) {
1149 perror("/proc/mounts");
1150 return NULL;
1151 }
1152
1153 while (fscanf(fp, "%*s %"
1154 STR(MAX_PATH)
1155 "s %99s %*s %*d %*d\n",
1156 debugfs, type) == 2) {
1157 if (strcmp(type, "debugfs") == 0)
1158 break;
1159 }
1160 fclose(fp);
1161
1162 if (strcmp(type, "debugfs") != 0) {
1163 fprintf(stderr, "debugfs not mounted");
1164 return NULL;
1165 }
1166
1167 strcat(debugfs, "/tracing/");
1168 debugfs_found = 1;
1169
1170 return debugfs;
1171}
1172
1173const char *tracing_file(const char *file_name)
1174{
1175 static char trace_file[MAX_PATH+1];
1176 snprintf(trace_file, MAX_PATH, "%s/%s", find_debugfs(), file_name);
1177 return trace_file;
1178}
1179
1180int main (int argc, char **argv)
1181{
1182 if (argc < 1)
1183 exit(-1);
1184
1185 if (fork() > 0) {
1186 int fd, ffd;
1187 char line[64];
1188 int s;
1189
1190 ffd = open(tracing_file("current_tracer"), O_WRONLY);
1191 if (ffd < 0)
1192 exit(-1);
1193 write(ffd, "nop", 3);
1194
1195 fd = open(tracing_file("set_ftrace_pid"), O_WRONLY);
1196 s = sprintf(line, "%d\n", getpid());
1197 write(fd, line, s);
1198
1199 write(ffd, "function", 8);
1200
1201 close(fd);
1202 close(ffd);
1203
1204 execvp(argv[1], argv+1);
1205 }
1206
1207 return 0;
1208}
1209
1210
1211hw-branch-tracer (x86 only)
1212---------------------------
1213
1214This tracer uses the x86 last branch tracing hardware feature to
1215collect a branch trace on all cpus with relatively low overhead.
1216
1217The tracer uses a fixed-size circular buffer per cpu and only
1218traces ring 0 branches. The trace file dumps that buffer in the
1219following format:
1220
1221# tracer: hw-branch-tracer
1222#
1223# CPU# TO <- FROM
1224 0 scheduler_tick+0xb5/0x1bf <- task_tick_idle+0x5/0x6
1225 2 run_posix_cpu_timers+0x2b/0x72a <- run_posix_cpu_timers+0x25/0x72a
1226 0 scheduler_tick+0x139/0x1bf <- scheduler_tick+0xed/0x1bf
1227 0 scheduler_tick+0x17c/0x1bf <- scheduler_tick+0x148/0x1bf
1228 2 run_posix_cpu_timers+0x9e/0x72a <- run_posix_cpu_timers+0x5e/0x72a
1229 0 scheduler_tick+0x1b6/0x1bf <- scheduler_tick+0x1aa/0x1bf
1230
1231
1232The tracer may be used to dump the trace for the oops'ing cpu on
1233a kernel oops into the system log. To enable this,
1234ftrace_dump_on_oops must be set. To set ftrace_dump_on_oops, one
1235can either use the sysctl function or set it via the proc system
1236interface.
1237
1238 sysctl kernel.ftrace_dump_on_oops=n
1239
1240or
1241
1242 echo n > /proc/sys/kernel/ftrace_dump_on_oops
1243
1244If n = 1, ftrace will dump buffers of all CPUs, if n = 2 ftrace will
1245only dump the buffer of the CPU that triggered the oops.
1246
1247Here's an example of such a dump after a null pointer
1248dereference in a kernel module:
1249
1250[57848.105921] BUG: unable to handle kernel NULL pointer dereference at 0000000000000000
1251[57848.106019] IP: [<ffffffffa0000006>] open+0x6/0x14 [oops]
1252[57848.106019] PGD 2354e9067 PUD 2375e7067 PMD 0
1253[57848.106019] Oops: 0002 [#1] SMP
1254[57848.106019] last sysfs file: /sys/devices/pci0000:00/0000:00:1e.0/0000:20:05.0/local_cpus
1255[57848.106019] Dumping ftrace buffer:
1256[57848.106019] ---------------------------------
1257[...]
1258[57848.106019] 0 chrdev_open+0xe6/0x165 <- cdev_put+0x23/0x24
1259[57848.106019] 0 chrdev_open+0x117/0x165 <- chrdev_open+0xfa/0x165
1260[57848.106019] 0 chrdev_open+0x120/0x165 <- chrdev_open+0x11c/0x165
1261[57848.106019] 0 chrdev_open+0x134/0x165 <- chrdev_open+0x12b/0x165
1262[57848.106019] 0 open+0x0/0x14 [oops] <- chrdev_open+0x144/0x165
1263[57848.106019] 0 page_fault+0x0/0x30 <- open+0x6/0x14 [oops]
1264[57848.106019] 0 error_entry+0x0/0x5b <- page_fault+0x4/0x30
1265[57848.106019] 0 error_kernelspace+0x0/0x31 <- error_entry+0x59/0x5b
1266[57848.106019] 0 error_sti+0x0/0x1 <- error_kernelspace+0x2d/0x31
1267[57848.106019] 0 page_fault+0x9/0x30 <- error_sti+0x0/0x1
1268[57848.106019] 0 do_page_fault+0x0/0x881 <- page_fault+0x1a/0x30
1269[...]
1270[57848.106019] 0 do_page_fault+0x66b/0x881 <- is_prefetch+0x1ee/0x1f2
1271[57848.106019] 0 do_page_fault+0x6e0/0x881 <- do_page_fault+0x67a/0x881
1272[57848.106019] 0 oops_begin+0x0/0x96 <- do_page_fault+0x6e0/0x881
1273[57848.106019] 0 trace_hw_branch_oops+0x0/0x2d <- oops_begin+0x9/0x96
1274[...]
1275[57848.106019] 0 ds_suspend_bts+0x2a/0xe3 <- ds_suspend_bts+0x1a/0xe3
1276[57848.106019] ---------------------------------
1277[57848.106019] CPU 0
1278[57848.106019] Modules linked in: oops
1279[57848.106019] Pid: 5542, comm: cat Tainted: G W 2.6.28 #23
1280[57848.106019] RIP: 0010:[<ffffffffa0000006>] [<ffffffffa0000006>] open+0x6/0x14 [oops]
1281[57848.106019] RSP: 0018:ffff880235457d48 EFLAGS: 00010246
1282[...]
1283
1284
1285function graph tracer
1286---------------------------
1287
1288This tracer is similar to the function tracer except that it
1289probes a function on its entry and its exit. This is done by
1290using a dynamically allocated stack of return addresses in each
1291task_struct. On function entry the tracer overwrites the return
1292address of each function traced to set a custom probe. Thus the
1293original return address is stored on the stack of return address
1294in the task_struct.
1295
1296Probing on both ends of a function leads to special features
1297such as:
1298
1299- measure of a function's time execution
1300- having a reliable call stack to draw function calls graph
1301
1302This tracer is useful in several situations:
1303
1304- you want to find the reason of a strange kernel behavior and
1305 need to see what happens in detail on any areas (or specific
1306 ones).
1307
1308- you are experiencing weird latencies but it's difficult to
1309 find its origin.
1310
1311- you want to find quickly which path is taken by a specific
1312 function
1313
1314- you just want to peek inside a working kernel and want to see
1315 what happens there.
1316
1317# tracer: function_graph
1318#
1319# CPU DURATION FUNCTION CALLS
1320# | | | | | | |
1321
1322 0) | sys_open() {
1323 0) | do_sys_open() {
1324 0) | getname() {
1325 0) | kmem_cache_alloc() {
1326 0) 1.382 us | __might_sleep();
1327 0) 2.478 us | }
1328 0) | strncpy_from_user() {
1329 0) | might_fault() {
1330 0) 1.389 us | __might_sleep();
1331 0) 2.553 us | }
1332 0) 3.807 us | }
1333 0) 7.876 us | }
1334 0) | alloc_fd() {
1335 0) 0.668 us | _spin_lock();
1336 0) 0.570 us | expand_files();
1337 0) 0.586 us | _spin_unlock();
1338
1339
1340There are several columns that can be dynamically
1341enabled/disabled. You can use every combination of options you
1342want, depending on your needs.
1343
1344- The cpu number on which the function executed is default
1345 enabled. It is sometimes better to only trace one cpu (see
1346 tracing_cpu_mask file) or you might sometimes see unordered
1347 function calls while cpu tracing switch.
1348
1349 hide: echo nofuncgraph-cpu > trace_options
1350 show: echo funcgraph-cpu > trace_options
1351
1352- The duration (function's time of execution) is displayed on
1353 the closing bracket line of a function or on the same line
1354 than the current function in case of a leaf one. It is default
1355 enabled.
1356
1357 hide: echo nofuncgraph-duration > trace_options
1358 show: echo funcgraph-duration > trace_options
1359
1360- The overhead field precedes the duration field in case of
1361 reached duration thresholds.
1362
1363 hide: echo nofuncgraph-overhead > trace_options
1364 show: echo funcgraph-overhead > trace_options
1365 depends on: funcgraph-duration
1366
1367 ie:
1368
1369 0) | up_write() {
1370 0) 0.646 us | _spin_lock_irqsave();
1371 0) 0.684 us | _spin_unlock_irqrestore();
1372 0) 3.123 us | }
1373 0) 0.548 us | fput();
1374 0) + 58.628 us | }
1375
1376 [...]
1377
1378 0) | putname() {
1379 0) | kmem_cache_free() {
1380 0) 0.518 us | __phys_addr();
1381 0) 1.757 us | }
1382 0) 2.861 us | }
1383 0) ! 115.305 us | }
1384 0) ! 116.402 us | }
1385
1386 + means that the function exceeded 10 usecs.
1387 ! means that the function exceeded 100 usecs.
1388
1389
1390- The task/pid field displays the thread cmdline and pid which
1391 executed the function. It is default disabled.
1392
1393 hide: echo nofuncgraph-proc > trace_options
1394 show: echo funcgraph-proc > trace_options
1395
1396 ie:
1397
1398 # tracer: function_graph
1399 #
1400 # CPU TASK/PID DURATION FUNCTION CALLS
1401 # | | | | | | | | |
1402 0) sh-4802 | | d_free() {
1403 0) sh-4802 | | call_rcu() {
1404 0) sh-4802 | | __call_rcu() {
1405 0) sh-4802 | 0.616 us | rcu_process_gp_end();
1406 0) sh-4802 | 0.586 us | check_for_new_grace_period();
1407 0) sh-4802 | 2.899 us | }
1408 0) sh-4802 | 4.040 us | }
1409 0) sh-4802 | 5.151 us | }
1410 0) sh-4802 | + 49.370 us | }
1411
1412
1413- The absolute time field is an absolute timestamp given by the
1414 system clock since it started. A snapshot of this time is
1415 given on each entry/exit of functions
1416
1417 hide: echo nofuncgraph-abstime > trace_options
1418 show: echo funcgraph-abstime > trace_options
1419
1420 ie:
1421
1422 #
1423 # TIME CPU DURATION FUNCTION CALLS
1424 # | | | | | | | |
1425 360.774522 | 1) 0.541 us | }
1426 360.774522 | 1) 4.663 us | }
1427 360.774523 | 1) 0.541 us | __wake_up_bit();
1428 360.774524 | 1) 6.796 us | }
1429 360.774524 | 1) 7.952 us | }
1430 360.774525 | 1) 9.063 us | }
1431 360.774525 | 1) 0.615 us | journal_mark_dirty();
1432 360.774527 | 1) 0.578 us | __brelse();
1433 360.774528 | 1) | reiserfs_prepare_for_journal() {
1434 360.774528 | 1) | unlock_buffer() {
1435 360.774529 | 1) | wake_up_bit() {
1436 360.774529 | 1) | bit_waitqueue() {
1437 360.774530 | 1) 0.594 us | __phys_addr();
1438
1439
1440You can put some comments on specific functions by using
1441trace_printk() For example, if you want to put a comment inside
1442the __might_sleep() function, you just have to include
1443<linux/ftrace.h> and call trace_printk() inside __might_sleep()
1444
1445trace_printk("I'm a comment!\n")
1446
1447will produce:
1448
1449 1) | __might_sleep() {
1450 1) | /* I'm a comment! */
1451 1) 1.449 us | }
1452
1453
1454You might find other useful features for this tracer in the
1455following "dynamic ftrace" section such as tracing only specific
1456functions or tasks.
1457
1458dynamic ftrace
1459--------------
1460
1461If CONFIG_DYNAMIC_FTRACE is set, the system will run with
1462virtually no overhead when function tracing is disabled. The way
1463this works is the mcount function call (placed at the start of
1464every kernel function, produced by the -pg switch in gcc),
1465starts of pointing to a simple return. (Enabling FTRACE will
1466include the -pg switch in the compiling of the kernel.)
1467
1468At compile time every C file object is run through the
1469recordmcount.pl script (located in the scripts directory). This
1470script will process the C object using objdump to find all the
1471locations in the .text section that call mcount. (Note, only the
1472.text section is processed, since processing other sections like
1473.init.text may cause races due to those sections being freed).
1474
1475A new section called "__mcount_loc" is created that holds
1476references to all the mcount call sites in the .text section.
1477This section is compiled back into the original object. The
1478final linker will add all these references into a single table.
1479
1480On boot up, before SMP is initialized, the dynamic ftrace code
1481scans this table and updates all the locations into nops. It
1482also records the locations, which are added to the
1483available_filter_functions list. Modules are processed as they
1484are loaded and before they are executed. When a module is
1485unloaded, it also removes its functions from the ftrace function
1486list. This is automatic in the module unload code, and the
1487module author does not need to worry about it.
1488
1489When tracing is enabled, kstop_machine is called to prevent
1490races with the CPUS executing code being modified (which can
1491cause the CPU to do undesirable things), and the nops are
1492patched back to calls. But this time, they do not call mcount
1493(which is just a function stub). They now call into the ftrace
1494infrastructure.
1495
1496One special side-effect to the recording of the functions being
1497traced is that we can now selectively choose which functions we
1498wish to trace and which ones we want the mcount calls to remain
1499as nops.
1500
1501Two files are used, one for enabling and one for disabling the
1502tracing of specified functions. They are:
1503
1504 set_ftrace_filter
1505
1506and
1507
1508 set_ftrace_notrace
1509
1510A list of available functions that you can add to these files is
1511listed in:
1512
1513 available_filter_functions
1514
1515 # cat available_filter_functions
1516put_prev_task_idle
1517kmem_cache_create
1518pick_next_task_rt
1519get_online_cpus
1520pick_next_task_fair
1521mutex_lock
1522[...]
1523
1524If I am only interested in sys_nanosleep and hrtimer_interrupt:
1525
1526 # echo sys_nanosleep hrtimer_interrupt \
1527 > set_ftrace_filter
1528 # echo function > current_tracer
1529 # echo 1 > tracing_on
1530 # usleep 1
1531 # echo 0 > tracing_on
1532 # cat trace
1533# tracer: ftrace
1534#
1535# TASK-PID CPU# TIMESTAMP FUNCTION
1536# | | | | |
1537 usleep-4134 [00] 1317.070017: hrtimer_interrupt <-smp_apic_timer_interrupt
1538 usleep-4134 [00] 1317.070111: sys_nanosleep <-syscall_call
1539 <idle>-0 [00] 1317.070115: hrtimer_interrupt <-smp_apic_timer_interrupt
1540
1541To see which functions are being traced, you can cat the file:
1542
1543 # cat set_ftrace_filter
1544hrtimer_interrupt
1545sys_nanosleep
1546
1547
1548Perhaps this is not enough. The filters also allow simple wild
1549cards. Only the following are currently available
1550
1551 <match>* - will match functions that begin with <match>
1552 *<match> - will match functions that end with <match>
1553 *<match>* - will match functions that have <match> in it
1554
1555These are the only wild cards which are supported.
1556
1557 <match>*<match> will not work.
1558
1559Note: It is better to use quotes to enclose the wild cards,
1560 otherwise the shell may expand the parameters into names
1561 of files in the local directory.
1562
1563 # echo 'hrtimer_*' > set_ftrace_filter
1564
1565Produces:
1566
1567# tracer: ftrace
1568#
1569# TASK-PID CPU# TIMESTAMP FUNCTION
1570# | | | | |
1571 bash-4003 [00] 1480.611794: hrtimer_init <-copy_process
1572 bash-4003 [00] 1480.611941: hrtimer_start <-hrtick_set
1573 bash-4003 [00] 1480.611956: hrtimer_cancel <-hrtick_clear
1574 bash-4003 [00] 1480.611956: hrtimer_try_to_cancel <-hrtimer_cancel
1575 <idle>-0 [00] 1480.612019: hrtimer_get_next_event <-get_next_timer_interrupt
1576 <idle>-0 [00] 1480.612025: hrtimer_get_next_event <-get_next_timer_interrupt
1577 <idle>-0 [00] 1480.612032: hrtimer_get_next_event <-get_next_timer_interrupt
1578 <idle>-0 [00] 1480.612037: hrtimer_get_next_event <-get_next_timer_interrupt
1579 <idle>-0 [00] 1480.612382: hrtimer_get_next_event <-get_next_timer_interrupt
1580
1581
1582Notice that we lost the sys_nanosleep.
1583
1584 # cat set_ftrace_filter
1585hrtimer_run_queues
1586hrtimer_run_pending
1587hrtimer_init
1588hrtimer_cancel
1589hrtimer_try_to_cancel
1590hrtimer_forward
1591hrtimer_start
1592hrtimer_reprogram
1593hrtimer_force_reprogram
1594hrtimer_get_next_event
1595hrtimer_interrupt
1596hrtimer_nanosleep
1597hrtimer_wakeup
1598hrtimer_get_remaining
1599hrtimer_get_res
1600hrtimer_init_sleeper
1601
1602
1603This is because the '>' and '>>' act just like they do in bash.
1604To rewrite the filters, use '>'
1605To append to the filters, use '>>'
1606
1607To clear out a filter so that all functions will be recorded
1608again:
1609
1610 # echo > set_ftrace_filter
1611 # cat set_ftrace_filter
1612 #
1613
1614Again, now we want to append.
1615
1616 # echo sys_nanosleep > set_ftrace_filter
1617 # cat set_ftrace_filter
1618sys_nanosleep
1619 # echo 'hrtimer_*' >> set_ftrace_filter
1620 # cat set_ftrace_filter
1621hrtimer_run_queues
1622hrtimer_run_pending
1623hrtimer_init
1624hrtimer_cancel
1625hrtimer_try_to_cancel
1626hrtimer_forward
1627hrtimer_start
1628hrtimer_reprogram
1629hrtimer_force_reprogram
1630hrtimer_get_next_event
1631hrtimer_interrupt
1632sys_nanosleep
1633hrtimer_nanosleep
1634hrtimer_wakeup
1635hrtimer_get_remaining
1636hrtimer_get_res
1637hrtimer_init_sleeper
1638
1639
1640The set_ftrace_notrace prevents those functions from being
1641traced.
1642
1643 # echo '*preempt*' '*lock*' > set_ftrace_notrace
1644
1645Produces:
1646
1647# tracer: ftrace
1648#
1649# TASK-PID CPU# TIMESTAMP FUNCTION
1650# | | | | |
1651 bash-4043 [01] 115.281644: finish_task_switch <-schedule
1652 bash-4043 [01] 115.281645: hrtick_set <-schedule
1653 bash-4043 [01] 115.281645: hrtick_clear <-hrtick_set
1654 bash-4043 [01] 115.281646: wait_for_completion <-__stop_machine_run
1655 bash-4043 [01] 115.281647: wait_for_common <-wait_for_completion
1656 bash-4043 [01] 115.281647: kthread_stop <-stop_machine_run
1657 bash-4043 [01] 115.281648: init_waitqueue_head <-kthread_stop
1658 bash-4043 [01] 115.281648: wake_up_process <-kthread_stop
1659 bash-4043 [01] 115.281649: try_to_wake_up <-wake_up_process
1660
1661We can see that there's no more lock or preempt tracing.
1662
1663
1664Dynamic ftrace with the function graph tracer
1665---------------------------------------------
1666
1667Although what has been explained above concerns both the
1668function tracer and the function-graph-tracer, there are some
1669special features only available in the function-graph tracer.
1670
1671If you want to trace only one function and all of its children,
1672you just have to echo its name into set_graph_function:
1673
1674 echo __do_fault > set_graph_function
1675
1676will produce the following "expanded" trace of the __do_fault()
1677function:
1678
1679 0) | __do_fault() {
1680 0) | filemap_fault() {
1681 0) | find_lock_page() {
1682 0) 0.804 us | find_get_page();
1683 0) | __might_sleep() {
1684 0) 1.329 us | }
1685 0) 3.904 us | }
1686 0) 4.979 us | }
1687 0) 0.653 us | _spin_lock();
1688 0) 0.578 us | page_add_file_rmap();
1689 0) 0.525 us | native_set_pte_at();
1690 0) 0.585 us | _spin_unlock();
1691 0) | unlock_page() {
1692 0) 0.541 us | page_waitqueue();
1693 0) 0.639 us | __wake_up_bit();
1694 0) 2.786 us | }
1695 0) + 14.237 us | }
1696 0) | __do_fault() {
1697 0) | filemap_fault() {
1698 0) | find_lock_page() {
1699 0) 0.698 us | find_get_page();
1700 0) | __might_sleep() {
1701 0) 1.412 us | }
1702 0) 3.950 us | }
1703 0) 5.098 us | }
1704 0) 0.631 us | _spin_lock();
1705 0) 0.571 us | page_add_file_rmap();
1706 0) 0.526 us | native_set_pte_at();
1707 0) 0.586 us | _spin_unlock();
1708 0) | unlock_page() {
1709 0) 0.533 us | page_waitqueue();
1710 0) 0.638 us | __wake_up_bit();
1711 0) 2.793 us | }
1712 0) + 14.012 us | }
1713
1714You can also expand several functions at once:
1715
1716 echo sys_open > set_graph_function
1717 echo sys_close >> set_graph_function
1718
1719Now if you want to go back to trace all functions you can clear
1720this special filter via:
1721
1722 echo > set_graph_function
1723
1724
1725Filter commands
1726---------------
1727
1728A few commands are supported by the set_ftrace_filter interface.
1729Trace commands have the following format:
1730
1731<function>:<command>:<parameter>
1732
1733The following commands are supported:
1734
1735- mod
1736 This command enables function filtering per module. The
1737 parameter defines the module. For example, if only the write*
1738 functions in the ext3 module are desired, run:
1739
1740 echo 'write*:mod:ext3' > set_ftrace_filter
1741
1742 This command interacts with the filter in the same way as
1743 filtering based on function names. Thus, adding more functions
1744 in a different module is accomplished by appending (>>) to the
1745 filter file. Remove specific module functions by prepending
1746 '!':
1747
1748 echo '!writeback*:mod:ext3' >> set_ftrace_filter
1749
1750- traceon/traceoff
1751 These commands turn tracing on and off when the specified
1752 functions are hit. The parameter determines how many times the
1753 tracing system is turned on and off. If unspecified, there is
1754 no limit. For example, to disable tracing when a schedule bug
1755 is hit the first 5 times, run:
1756
1757 echo '__schedule_bug:traceoff:5' > set_ftrace_filter
1758
1759 These commands are cumulative whether or not they are appended
1760 to set_ftrace_filter. To remove a command, prepend it by '!'
1761 and drop the parameter:
1762
1763 echo '!__schedule_bug:traceoff' > set_ftrace_filter
1764
1765
1766trace_pipe
1767----------
1768
1769The trace_pipe outputs the same content as the trace file, but
1770the effect on the tracing is different. Every read from
1771trace_pipe is consumed. This means that subsequent reads will be
1772different. The trace is live.
1773
1774 # echo function > current_tracer
1775 # cat trace_pipe > /tmp/trace.out &
1776[1] 4153
1777 # echo 1 > tracing_on
1778 # usleep 1
1779 # echo 0 > tracing_on
1780 # cat trace
1781# tracer: function
1782#
1783# TASK-PID CPU# TIMESTAMP FUNCTION
1784# | | | | |
1785
1786 #
1787 # cat /tmp/trace.out
1788 bash-4043 [00] 41.267106: finish_task_switch <-schedule
1789 bash-4043 [00] 41.267106: hrtick_set <-schedule
1790 bash-4043 [00] 41.267107: hrtick_clear <-hrtick_set
1791 bash-4043 [00] 41.267108: wait_for_completion <-__stop_machine_run
1792 bash-4043 [00] 41.267108: wait_for_common <-wait_for_completion
1793 bash-4043 [00] 41.267109: kthread_stop <-stop_machine_run
1794 bash-4043 [00] 41.267109: init_waitqueue_head <-kthread_stop
1795 bash-4043 [00] 41.267110: wake_up_process <-kthread_stop
1796 bash-4043 [00] 41.267110: try_to_wake_up <-wake_up_process
1797 bash-4043 [00] 41.267111: select_task_rq_rt <-try_to_wake_up
1798
1799
1800Note, reading the trace_pipe file will block until more input is
1801added. By changing the tracer, trace_pipe will issue an EOF. We
1802needed to set the function tracer _before_ we "cat" the
1803trace_pipe file.
1804
1805
1806trace entries
1807-------------
1808
1809Having too much or not enough data can be troublesome in
1810diagnosing an issue in the kernel. The file buffer_size_kb is
1811used to modify the size of the internal trace buffers. The
1812number listed is the number of entries that can be recorded per
1813CPU. To know the full size, multiply the number of possible CPUS
1814with the number of entries.
1815
1816 # cat buffer_size_kb
18171408 (units kilobytes)
1818
1819Note, to modify this, you must have tracing completely disabled.
1820To do that, echo "nop" into the current_tracer. If the
1821current_tracer is not set to "nop", an EINVAL error will be
1822returned.
1823
1824 # echo nop > current_tracer
1825 # echo 10000 > buffer_size_kb
1826 # cat buffer_size_kb
182710000 (units kilobytes)
1828
1829The number of pages which will be allocated is limited to a
1830percentage of available memory. Allocating too much will produce
1831an error.
1832
1833 # echo 1000000000000 > buffer_size_kb
1834-bash: echo: write error: Cannot allocate memory
1835 # cat buffer_size_kb
183685
1837
1838-----------
1839
1840More details can be found in the source code, in the
1841kernel/trace/*.c files.
1 ftrace - Function Tracer
2 ========================
3
4Copyright 2008 Red Hat Inc.
5 Author: Steven Rostedt <srostedt@redhat.com>
6 License: The GNU Free Documentation License, Version 1.2
7 (dual licensed under the GPL v2)
8Reviewers: Elias Oltmanns, Randy Dunlap, Andrew Morton,
9 John Kacur, and David Teigland.
10Written for: 2.6.28-rc2
11Updated for: 3.10
12
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
19performance issues that take place outside of user-space.
20
21Although ftrace is typically considered the function tracer, it
22is really a frame work of several assorted tracing utilities.
23There's latency tracing to examine what occurs between interrupts
24disabled and enabled, as well as for preemption and from a time
25a task is woken to the task is actually scheduled in.
26
27One of the most common uses of ftrace is the event tracing.
28Through out the kernel is hundreds of static event points that
29can be enabled via the debugfs file system to see what is
30going on in certain parts of the kernel.
31
32
33Implementation Details
34----------------------
35
36See ftrace-design.txt for details for arch porters and such.
37
38
39The File System
40---------------
41
42Ftrace uses the debugfs file system to hold the control files as
43well as the files to display output.
44
45When debugfs is configured into the kernel (which selecting any ftrace
46option will do) the directory /sys/kernel/debug will be created. To mount
47this directory, you can add to your /etc/fstab file:
48
49 debugfs /sys/kernel/debug debugfs defaults 0 0
50
51Or you can mount it at run time with:
52
53 mount -t debugfs nodev /sys/kernel/debug
54
55For quicker access to that directory you may want to make a soft link to
56it:
57
58 ln -s /sys/kernel/debug /debug
59
60Any selected ftrace option will also create a directory called tracing
61within the debugfs. The rest of the document will assume that you are in
62the ftrace directory (cd /sys/kernel/debug/tracing) and will only concentrate
63on the files within that directory and not distract from the content with
64the extended "/sys/kernel/debug/tracing" path name.
65
66That's it! (assuming that you have ftrace configured into your kernel)
67
68After mounting debugfs, you can see a directory called
69"tracing". This directory contains the control and output files
70of ftrace. Here is a list of some of the key files:
71
72
73 Note: all time values are in microseconds.
74
75 current_tracer:
76
77 This is used to set or display the current tracer
78 that is configured.
79
80 available_tracers:
81
82 This holds the different types of tracers that
83 have been compiled into the kernel. The
84 tracers listed here can be configured by
85 echoing their name into current_tracer.
86
87 tracing_on:
88
89 This sets or displays whether writing to the trace
90 ring buffer is enabled. Echo 0 into this file to disable
91 the tracer or 1 to enable it. Note, this only disables
92 writing to the ring buffer, the tracing overhead may
93 still be occurring.
94
95 trace:
96
97 This file holds the output of the trace in a human
98 readable format (described below).
99
100 trace_pipe:
101
102 The output is the same as the "trace" file but this
103 file is meant to be streamed with live tracing.
104 Reads from this file will block until new data is
105 retrieved. Unlike the "trace" file, this file is a
106 consumer. This means reading from this file causes
107 sequential reads to display more current data. Once
108 data is read from this file, it is consumed, and
109 will not be read again with a sequential read. The
110 "trace" file is static, and if the tracer is not
111 adding more data, it will display the same
112 information every time it is read.
113
114 trace_options:
115
116 This file lets the user control the amount of data
117 that is displayed in one of the above output
118 files. Options also exist to modify how a tracer
119 or events work (stack traces, timestamps, etc).
120
121 options:
122
123 This is a directory that has a file for every available
124 trace option (also in trace_options). Options may also be set
125 or cleared by writing a "1" or "0" respectively into the
126 corresponding file with the option name.
127
128 tracing_max_latency:
129
130 Some of the tracers record the max latency.
131 For example, the time interrupts are disabled.
132 This time is saved in this file. The max trace
133 will also be stored, and displayed by "trace".
134 A new max trace will only be recorded if the
135 latency is greater than the value in this
136 file. (in microseconds)
137
138 tracing_thresh:
139
140 Some latency tracers will record a trace whenever the
141 latency is greater than the number in this file.
142 Only active when the file contains a number greater than 0.
143 (in microseconds)
144
145 buffer_size_kb:
146
147 This sets or displays the number of kilobytes each CPU
148 buffer holds. By default, the trace buffers are the same size
149 for each CPU. The displayed number is the size of the
150 CPU buffer and not total size of all buffers. The
151 trace buffers are allocated in pages (blocks of memory
152 that the kernel uses for allocation, usually 4 KB in size).
153 If the last page allocated has room for more bytes
154 than requested, the rest of the page will be used,
155 making the actual allocation bigger than requested.
156 ( Note, the size may not be a multiple of the page size
157 due to buffer management meta-data. )
158
159 buffer_total_size_kb:
160
161 This displays the total combined size of all the trace buffers.
162
163 free_buffer:
164
165 If a process is performing the tracing, and the ring buffer
166 should be shrunk "freed" when the process is finished, even
167 if it were to be killed by a signal, this file can be used
168 for that purpose. On close of this file, the ring buffer will
169 be resized to its minimum size. Having a process that is tracing
170 also open this file, when the process exits its file descriptor
171 for this file will be closed, and in doing so, the ring buffer
172 will be "freed".
173
174 It may also stop tracing if disable_on_free option is set.
175
176 tracing_cpumask:
177
178 This is a mask that lets the user only trace
179 on specified CPUs. The format is a hex string
180 representing the CPUs.
181
182 set_ftrace_filter:
183
184 When dynamic ftrace is configured in (see the
185 section below "dynamic ftrace"), the code is dynamically
186 modified (code text rewrite) to disable calling of the
187 function profiler (mcount). This lets tracing be configured
188 in with practically no overhead in performance. This also
189 has a side effect of enabling or disabling specific functions
190 to be traced. Echoing names of functions into this file
191 will limit the trace to only those functions.
192
193 This interface also allows for commands to be used. See the
194 "Filter commands" section for more details.
195
196 set_ftrace_notrace:
197
198 This has an effect opposite to that of
199 set_ftrace_filter. Any function that is added here will not
200 be traced. If a function exists in both set_ftrace_filter
201 and set_ftrace_notrace, the function will _not_ be traced.
202
203 set_ftrace_pid:
204
205 Have the function tracer only trace a single thread.
206
207 set_event_pid:
208
209 Have the events only trace a task with a PID listed in this file.
210 Note, sched_switch and sched_wake_up will also trace events
211 listed in this file.
212
213 set_graph_function:
214
215 Set a "trigger" function where tracing should start
216 with the function graph tracer (See the section
217 "dynamic ftrace" for more details).
218
219 available_filter_functions:
220
221 This lists the functions that ftrace
222 has processed and can trace. These are the function
223 names that you can pass to "set_ftrace_filter" or
224 "set_ftrace_notrace". (See the section "dynamic ftrace"
225 below for more details.)
226
227 enabled_functions:
228
229 This file is more for debugging ftrace, but can also be useful
230 in seeing if any function has a callback attached to it.
231 Not only does the trace infrastructure use ftrace function
232 trace utility, but other subsystems might too. This file
233 displays all functions that have a callback attached to them
234 as well as the number of callbacks that have been attached.
235 Note, a callback may also call multiple functions which will
236 not be listed in this count.
237
238 If the callback registered to be traced by a function with
239 the "save regs" attribute (thus even more overhead), a 'R'
240 will be displayed on the same line as the function that
241 is returning registers.
242
243 If the callback registered to be traced by a function with
244 the "ip modify" attribute (thus the regs->ip can be changed),
245 an 'I' will be displayed on the same line as the function that
246 can be overridden.
247
248 function_profile_enabled:
249
250 When set it will enable all functions with either the function
251 tracer, or if enabled, the function graph tracer. It will
252 keep a histogram of the number of functions that were called
253 and if run with the function graph tracer, it will also keep
254 track of the time spent in those functions. The histogram
255 content can be displayed in the files:
256
257 trace_stats/function<cpu> ( function0, function1, etc).
258
259 trace_stats:
260
261 A directory that holds different tracing stats.
262
263 kprobe_events:
264
265 Enable dynamic trace points. See kprobetrace.txt.
266
267 kprobe_profile:
268
269 Dynamic trace points stats. See kprobetrace.txt.
270
271 max_graph_depth:
272
273 Used with the function graph tracer. This is the max depth
274 it will trace into a function. Setting this to a value of
275 one will show only the first kernel function that is called
276 from user space.
277
278 printk_formats:
279
280 This is for tools that read the raw format files. If an event in
281 the ring buffer references a string (currently only trace_printk()
282 does this), only a pointer to the string is recorded into the buffer
283 and not the string itself. This prevents tools from knowing what
284 that string was. This file displays the string and address for
285 the string allowing tools to map the pointers to what the
286 strings were.
287
288 saved_cmdlines:
289
290 Only the pid of the task is recorded in a trace event unless
291 the event specifically saves the task comm as well. Ftrace
292 makes a cache of pid mappings to comms to try to display
293 comms for events. If a pid for a comm is not listed, then
294 "<...>" is displayed in the output.
295
296 snapshot:
297
298 This displays the "snapshot" buffer and also lets the user
299 take a snapshot of the current running trace.
300 See the "Snapshot" section below for more details.
301
302 stack_max_size:
303
304 When the stack tracer is activated, this will display the
305 maximum stack size it has encountered.
306 See the "Stack Trace" section below.
307
308 stack_trace:
309
310 This displays the stack back trace of the largest stack
311 that was encountered when the stack tracer is activated.
312 See the "Stack Trace" section below.
313
314 stack_trace_filter:
315
316 This is similar to "set_ftrace_filter" but it limits what
317 functions the stack tracer will check.
318
319 trace_clock:
320
321 Whenever an event is recorded into the ring buffer, a
322 "timestamp" is added. This stamp comes from a specified
323 clock. By default, ftrace uses the "local" clock. This
324 clock is very fast and strictly per cpu, but on some
325 systems it may not be monotonic with respect to other
326 CPUs. In other words, the local clocks may not be in sync
327 with local clocks on other CPUs.
328
329 Usual clocks for tracing:
330
331 # cat trace_clock
332 [local] global counter x86-tsc
333
334 local: Default clock, but may not be in sync across CPUs
335
336 global: This clock is in sync with all CPUs but may
337 be a bit slower than the local clock.
338
339 counter: This is not a clock at all, but literally an atomic
340 counter. It counts up one by one, but is in sync
341 with all CPUs. This is useful when you need to
342 know exactly the order events occurred with respect to
343 each other on different CPUs.
344
345 uptime: This uses the jiffies counter and the time stamp
346 is relative to the time since boot up.
347
348 perf: This makes ftrace use the same clock that perf uses.
349 Eventually perf will be able to read ftrace buffers
350 and this will help out in interleaving the data.
351
352 x86-tsc: Architectures may define their own clocks. For
353 example, x86 uses its own TSC cycle clock here.
354
355 ppc-tb: This uses the powerpc timebase register value.
356 This is in sync across CPUs and can also be used
357 to correlate events across hypervisor/guest if
358 tb_offset is known.
359
360 To set a clock, simply echo the clock name into this file.
361
362 echo global > trace_clock
363
364 trace_marker:
365
366 This is a very useful file for synchronizing user space
367 with events happening in the kernel. Writing strings into
368 this file will be written into the ftrace buffer.
369
370 It is useful in applications to open this file at the start
371 of the application and just reference the file descriptor
372 for the file.
373
374 void trace_write(const char *fmt, ...)
375 {
376 va_list ap;
377 char buf[256];
378 int n;
379
380 if (trace_fd < 0)
381 return;
382
383 va_start(ap, fmt);
384 n = vsnprintf(buf, 256, fmt, ap);
385 va_end(ap);
386
387 write(trace_fd, buf, n);
388 }
389
390 start:
391
392 trace_fd = open("trace_marker", WR_ONLY);
393
394 uprobe_events:
395
396 Add dynamic tracepoints in programs.
397 See uprobetracer.txt
398
399 uprobe_profile:
400
401 Uprobe statistics. See uprobetrace.txt
402
403 instances:
404
405 This is a way to make multiple trace buffers where different
406 events can be recorded in different buffers.
407 See "Instances" section below.
408
409 events:
410
411 This is the trace event directory. It holds event tracepoints
412 (also known as static tracepoints) that have been compiled
413 into the kernel. It shows what event tracepoints exist
414 and how they are grouped by system. There are "enable"
415 files at various levels that can enable the tracepoints
416 when a "1" is written to them.
417
418 See events.txt for more information.
419
420 per_cpu:
421
422 This is a directory that contains the trace per_cpu information.
423
424 per_cpu/cpu0/buffer_size_kb:
425
426 The ftrace buffer is defined per_cpu. That is, there's a separate
427 buffer for each CPU to allow writes to be done atomically,
428 and free from cache bouncing. These buffers may have different
429 size buffers. This file is similar to the buffer_size_kb
430 file, but it only displays or sets the buffer size for the
431 specific CPU. (here cpu0).
432
433 per_cpu/cpu0/trace:
434
435 This is similar to the "trace" file, but it will only display
436 the data specific for the CPU. If written to, it only clears
437 the specific CPU buffer.
438
439 per_cpu/cpu0/trace_pipe
440
441 This is similar to the "trace_pipe" file, and is a consuming
442 read, but it will only display (and consume) the data specific
443 for the CPU.
444
445 per_cpu/cpu0/trace_pipe_raw
446
447 For tools that can parse the ftrace ring buffer binary format,
448 the trace_pipe_raw file can be used to extract the data
449 from the ring buffer directly. With the use of the splice()
450 system call, the buffer data can be quickly transferred to
451 a file or to the network where a server is collecting the
452 data.
453
454 Like trace_pipe, this is a consuming reader, where multiple
455 reads will always produce different data.
456
457 per_cpu/cpu0/snapshot:
458
459 This is similar to the main "snapshot" file, but will only
460 snapshot the current CPU (if supported). It only displays
461 the content of the snapshot for a given CPU, and if
462 written to, only clears this CPU buffer.
463
464 per_cpu/cpu0/snapshot_raw:
465
466 Similar to the trace_pipe_raw, but will read the binary format
467 from the snapshot buffer for the given CPU.
468
469 per_cpu/cpu0/stats:
470
471 This displays certain stats about the ring buffer:
472
473 entries: The number of events that are still in the buffer.
474
475 overrun: The number of lost events due to overwriting when
476 the buffer was full.
477
478 commit overrun: Should always be zero.
479 This gets set if so many events happened within a nested
480 event (ring buffer is re-entrant), that it fills the
481 buffer and starts dropping events.
482
483 bytes: Bytes actually read (not overwritten).
484
485 oldest event ts: The oldest timestamp in the buffer
486
487 now ts: The current timestamp
488
489 dropped events: Events lost due to overwrite option being off.
490
491 read events: The number of events read.
492
493The Tracers
494-----------
495
496Here is the list of current tracers that may be configured.
497
498 "function"
499
500 Function call tracer to trace all kernel functions.
501
502 "function_graph"
503
504 Similar to the function tracer except that the
505 function tracer probes the functions on their entry
506 whereas the function graph tracer traces on both entry
507 and exit of the functions. It then provides the ability
508 to draw a graph of function calls similar to C code
509 source.
510
511 "irqsoff"
512
513 Traces the areas that disable interrupts and saves
514 the trace with the longest max latency.
515 See tracing_max_latency. When a new max is recorded,
516 it replaces the old trace. It is best to view this
517 trace with the latency-format option enabled.
518
519 "preemptoff"
520
521 Similar to irqsoff but traces and records the amount of
522 time for which preemption is disabled.
523
524 "preemptirqsoff"
525
526 Similar to irqsoff and preemptoff, but traces and
527 records the largest time for which irqs and/or preemption
528 is disabled.
529
530 "wakeup"
531
532 Traces and records the max latency that it takes for
533 the highest priority task to get scheduled after
534 it has been woken up.
535 Traces all tasks as an average developer would expect.
536
537 "wakeup_rt"
538
539 Traces and records the max latency that it takes for just
540 RT tasks (as the current "wakeup" does). This is useful
541 for those interested in wake up timings of RT tasks.
542
543 "nop"
544
545 This is the "trace nothing" tracer. To remove all
546 tracers from tracing simply echo "nop" into
547 current_tracer.
548
549
550Examples of using the tracer
551----------------------------
552
553Here are typical examples of using the tracers when controlling
554them only with the debugfs interface (without using any
555user-land utilities).
556
557Output format:
558--------------
559
560Here is an example of the output format of the file "trace"
561
562 --------
563# tracer: function
564#
565# entries-in-buffer/entries-written: 140080/250280 #P:4
566#
567# _-----=> irqs-off
568# / _----=> need-resched
569# | / _---=> hardirq/softirq
570# || / _--=> preempt-depth
571# ||| / delay
572# TASK-PID CPU# |||| TIMESTAMP FUNCTION
573# | | | |||| | |
574 bash-1977 [000] .... 17284.993652: sys_close <-system_call_fastpath
575 bash-1977 [000] .... 17284.993653: __close_fd <-sys_close
576 bash-1977 [000] .... 17284.993653: _raw_spin_lock <-__close_fd
577 sshd-1974 [003] .... 17284.993653: __srcu_read_unlock <-fsnotify
578 bash-1977 [000] .... 17284.993654: add_preempt_count <-_raw_spin_lock
579 bash-1977 [000] ...1 17284.993655: _raw_spin_unlock <-__close_fd
580 bash-1977 [000] ...1 17284.993656: sub_preempt_count <-_raw_spin_unlock
581 bash-1977 [000] .... 17284.993657: filp_close <-__close_fd
582 bash-1977 [000] .... 17284.993657: dnotify_flush <-filp_close
583 sshd-1974 [003] .... 17284.993658: sys_select <-system_call_fastpath
584 --------
585
586A header is printed with the tracer name that is represented by
587the trace. In this case the tracer is "function". Then it shows the
588number of events in the buffer as well as the total number of entries
589that were written. The difference is the number of entries that were
590lost due to the buffer filling up (250280 - 140080 = 110200 events
591lost).
592
593The header explains the content of the events. Task name "bash", the task
594PID "1977", the CPU that it was running on "000", the latency format
595(explained below), the timestamp in <secs>.<usecs> format, the
596function name that was traced "sys_close" and the parent function that
597called this function "system_call_fastpath". The timestamp is the time
598at which the function was entered.
599
600Latency trace format
601--------------------
602
603When the latency-format option is enabled or when one of the latency
604tracers is set, the trace file gives somewhat more information to see
605why a latency happened. Here is a typical trace.
606
607# tracer: irqsoff
608#
609# irqsoff latency trace v1.1.5 on 3.8.0-test+
610# --------------------------------------------------------------------
611# latency: 259 us, #4/4, CPU#2 | (M:preempt VP:0, KP:0, SP:0 HP:0 #P:4)
612# -----------------
613# | task: ps-6143 (uid:0 nice:0 policy:0 rt_prio:0)
614# -----------------
615# => started at: __lock_task_sighand
616# => ended at: _raw_spin_unlock_irqrestore
617#
618#
619# _------=> CPU#
620# / _-----=> irqs-off
621# | / _----=> need-resched
622# || / _---=> hardirq/softirq
623# ||| / _--=> preempt-depth
624# |||| / delay
625# cmd pid ||||| time | caller
626# \ / ||||| \ | /
627 ps-6143 2d... 0us!: trace_hardirqs_off <-__lock_task_sighand
628 ps-6143 2d..1 259us+: trace_hardirqs_on <-_raw_spin_unlock_irqrestore
629 ps-6143 2d..1 263us+: time_hardirqs_on <-_raw_spin_unlock_irqrestore
630 ps-6143 2d..1 306us : <stack trace>
631 => trace_hardirqs_on_caller
632 => trace_hardirqs_on
633 => _raw_spin_unlock_irqrestore
634 => do_task_stat
635 => proc_tgid_stat
636 => proc_single_show
637 => seq_read
638 => vfs_read
639 => sys_read
640 => system_call_fastpath
641
642
643This shows that the current tracer is "irqsoff" tracing the time
644for which interrupts were disabled. It gives the trace version (which
645never changes) and the version of the kernel upon which this was executed on
646(3.10). Then it displays the max latency in microseconds (259 us). The number
647of trace entries displayed and the total number (both are four: #4/4).
648VP, KP, SP, and HP are always zero and are reserved for later use.
649#P is the number of online CPUs (#P:4).
650
651The task is the process that was running when the latency
652occurred. (ps pid: 6143).
653
654The start and stop (the functions in which the interrupts were
655disabled and enabled respectively) that caused the latencies:
656
657 __lock_task_sighand is where the interrupts were disabled.
658 _raw_spin_unlock_irqrestore is where they were enabled again.
659
660The next lines after the header are the trace itself. The header
661explains which is which.
662
663 cmd: The name of the process in the trace.
664
665 pid: The PID of that process.
666
667 CPU#: The CPU which the process was running on.
668
669 irqs-off: 'd' interrupts are disabled. '.' otherwise.
670 Note: If the architecture does not support a way to
671 read the irq flags variable, an 'X' will always
672 be printed here.
673
674 need-resched:
675 'N' both TIF_NEED_RESCHED and PREEMPT_NEED_RESCHED is set,
676 'n' only TIF_NEED_RESCHED is set,
677 'p' only PREEMPT_NEED_RESCHED is set,
678 '.' otherwise.
679
680 hardirq/softirq:
681 'H' - hard irq occurred inside a softirq.
682 'h' - hard irq is running
683 's' - soft irq is running
684 '.' - normal context.
685
686 preempt-depth: The level of preempt_disabled
687
688The above is mostly meaningful for kernel developers.
689
690 time: When the latency-format option is enabled, the trace file
691 output includes a timestamp relative to the start of the
692 trace. This differs from the output when latency-format
693 is disabled, which includes an absolute timestamp.
694
695 delay: This is just to help catch your eye a bit better. And
696 needs to be fixed to be only relative to the same CPU.
697 The marks are determined by the difference between this
698 current trace and the next trace.
699 '$' - greater than 1 second
700 '@' - greater than 100 milisecond
701 '*' - greater than 10 milisecond
702 '#' - greater than 1000 microsecond
703 '!' - greater than 100 microsecond
704 '+' - greater than 10 microsecond
705 ' ' - less than or equal to 10 microsecond.
706
707 The rest is the same as the 'trace' file.
708
709 Note, the latency tracers will usually end with a back trace
710 to easily find where the latency occurred.
711
712trace_options
713-------------
714
715The trace_options file (or the options directory) is used to control
716what gets printed in the trace output, or manipulate the tracers.
717To see what is available, simply cat the file:
718
719 cat trace_options
720print-parent
721nosym-offset
722nosym-addr
723noverbose
724noraw
725nohex
726nobin
727noblock
728nostacktrace
729trace_printk
730noftrace_preempt
731nobranch
732annotate
733nouserstacktrace
734nosym-userobj
735noprintk-msg-only
736context-info
737latency-format
738sleep-time
739graph-time
740record-cmd
741overwrite
742nodisable_on_free
743irq-info
744markers
745function-trace
746
747To disable one of the options, echo in the option prepended with
748"no".
749
750 echo noprint-parent > trace_options
751
752To enable an option, leave off the "no".
753
754 echo sym-offset > trace_options
755
756Here are the available options:
757
758 print-parent - On function traces, display the calling (parent)
759 function as well as the function being traced.
760
761 print-parent:
762 bash-4000 [01] 1477.606694: simple_strtoul <-kstrtoul
763
764 noprint-parent:
765 bash-4000 [01] 1477.606694: simple_strtoul
766
767
768 sym-offset - Display not only the function name, but also the
769 offset in the function. For example, instead of
770 seeing just "ktime_get", you will see
771 "ktime_get+0xb/0x20".
772
773 sym-offset:
774 bash-4000 [01] 1477.606694: simple_strtoul+0x6/0xa0
775
776 sym-addr - this will also display the function address as well
777 as the function name.
778
779 sym-addr:
780 bash-4000 [01] 1477.606694: simple_strtoul <c0339346>
781
782 verbose - This deals with the trace file when the
783 latency-format option is enabled.
784
785 bash 4000 1 0 00000000 00010a95 [58127d26] 1720.415ms \
786 (+0.000ms): simple_strtoul (kstrtoul)
787
788 raw - This will display raw numbers. This option is best for
789 use with user applications that can translate the raw
790 numbers better than having it done in the kernel.
791
792 hex - Similar to raw, but the numbers will be in a hexadecimal
793 format.
794
795 bin - This will print out the formats in raw binary.
796
797 block - When set, reading trace_pipe will not block when polled.
798
799 stacktrace - This is one of the options that changes the trace
800 itself. When a trace is recorded, so is the stack
801 of functions. This allows for back traces of
802 trace sites.
803
804 trace_printk - Can disable trace_printk() from writing into the buffer.
805
806 branch - Enable branch tracing with the tracer.
807
808 annotate - It is sometimes confusing when the CPU buffers are full
809 and one CPU buffer had a lot of events recently, thus
810 a shorter time frame, were another CPU may have only had
811 a few events, which lets it have older events. When
812 the trace is reported, it shows the oldest events first,
813 and it may look like only one CPU ran (the one with the
814 oldest events). When the annotate option is set, it will
815 display when a new CPU buffer started:
816
817 <idle>-0 [001] dNs4 21169.031481: wake_up_idle_cpu <-add_timer_on
818 <idle>-0 [001] dNs4 21169.031482: _raw_spin_unlock_irqrestore <-add_timer_on
819 <idle>-0 [001] .Ns4 21169.031484: sub_preempt_count <-_raw_spin_unlock_irqrestore
820##### CPU 2 buffer started ####
821 <idle>-0 [002] .N.1 21169.031484: rcu_idle_exit <-cpu_idle
822 <idle>-0 [001] .Ns3 21169.031484: _raw_spin_unlock <-clocksource_watchdog
823 <idle>-0 [001] .Ns3 21169.031485: sub_preempt_count <-_raw_spin_unlock
824
825 userstacktrace - This option changes the trace. It records a
826 stacktrace of the current userspace thread.
827
828 sym-userobj - when user stacktrace are enabled, look up which
829 object the address belongs to, and print a
830 relative address. This is especially useful when
831 ASLR is on, otherwise you don't get a chance to
832 resolve the address to object/file/line after
833 the app is no longer running
834
835 The lookup is performed when you read
836 trace,trace_pipe. Example:
837
838 a.out-1623 [000] 40874.465068: /root/a.out[+0x480] <-/root/a.out[+0
839x494] <- /root/a.out[+0x4a8] <- /lib/libc-2.7.so[+0x1e1a6]
840
841
842 printk-msg-only - When set, trace_printk()s will only show the format
843 and not their parameters (if trace_bprintk() or
844 trace_bputs() was used to save the trace_printk()).
845
846 context-info - Show only the event data. Hides the comm, PID,
847 timestamp, CPU, and other useful data.
848
849 latency-format - This option changes the trace. When
850 it is enabled, the trace displays
851 additional information about the
852 latencies, as described in "Latency
853 trace format".
854
855 sleep-time - When running function graph tracer, to include
856 the time a task schedules out in its function.
857 When enabled, it will account time the task has been
858 scheduled out as part of the function call.
859
860 graph-time - When running function graph tracer, to include the
861 time to call nested functions. When this is not set,
862 the time reported for the function will only include
863 the time the function itself executed for, not the time
864 for functions that it called.
865
866 record-cmd - When any event or tracer is enabled, a hook is enabled
867 in the sched_switch trace point to fill comm cache
868 with mapped pids and comms. But this may cause some
869 overhead, and if you only care about pids, and not the
870 name of the task, disabling this option can lower the
871 impact of tracing.
872
873 overwrite - This controls what happens when the trace buffer is
874 full. If "1" (default), the oldest events are
875 discarded and overwritten. If "0", then the newest
876 events are discarded.
877 (see per_cpu/cpu0/stats for overrun and dropped)
878
879 disable_on_free - When the free_buffer is closed, tracing will
880 stop (tracing_on set to 0).
881
882 irq-info - Shows the interrupt, preempt count, need resched data.
883 When disabled, the trace looks like:
884
885# tracer: function
886#
887# entries-in-buffer/entries-written: 144405/9452052 #P:4
888#
889# TASK-PID CPU# TIMESTAMP FUNCTION
890# | | | | |
891 <idle>-0 [002] 23636.756054: ttwu_do_activate.constprop.89 <-try_to_wake_up
892 <idle>-0 [002] 23636.756054: activate_task <-ttwu_do_activate.constprop.89
893 <idle>-0 [002] 23636.756055: enqueue_task <-activate_task
894
895
896 markers - When set, the trace_marker is writable (only by root).
897 When disabled, the trace_marker will error with EINVAL
898 on write.
899
900
901 function-trace - The latency tracers will enable function tracing
902 if this option is enabled (default it is). When
903 it is disabled, the latency tracers do not trace
904 functions. This keeps the overhead of the tracer down
905 when performing latency tests.
906
907 Note: Some tracers have their own options. They only appear
908 when the tracer is active.
909
910
911
912irqsoff
913-------
914
915When interrupts are disabled, the CPU can not react to any other
916external event (besides NMIs and SMIs). This prevents the timer
917interrupt from triggering or the mouse interrupt from letting
918the kernel know of a new mouse event. The result is a latency
919with the reaction time.
920
921The irqsoff tracer tracks the time for which interrupts are
922disabled. When a new maximum latency is hit, the tracer saves
923the trace leading up to that latency point so that every time a
924new maximum is reached, the old saved trace is discarded and the
925new trace is saved.
926
927To reset the maximum, echo 0 into tracing_max_latency. Here is
928an example:
929
930 # echo 0 > options/function-trace
931 # echo irqsoff > current_tracer
932 # echo 1 > tracing_on
933 # echo 0 > tracing_max_latency
934 # ls -ltr
935 [...]
936 # echo 0 > tracing_on
937 # cat trace
938# tracer: irqsoff
939#
940# irqsoff latency trace v1.1.5 on 3.8.0-test+
941# --------------------------------------------------------------------
942# latency: 16 us, #4/4, CPU#0 | (M:preempt VP:0, KP:0, SP:0 HP:0 #P:4)
943# -----------------
944# | task: swapper/0-0 (uid:0 nice:0 policy:0 rt_prio:0)
945# -----------------
946# => started at: run_timer_softirq
947# => ended at: run_timer_softirq
948#
949#
950# _------=> CPU#
951# / _-----=> irqs-off
952# | / _----=> need-resched
953# || / _---=> hardirq/softirq
954# ||| / _--=> preempt-depth
955# |||| / delay
956# cmd pid ||||| time | caller
957# \ / ||||| \ | /
958 <idle>-0 0d.s2 0us+: _raw_spin_lock_irq <-run_timer_softirq
959 <idle>-0 0dNs3 17us : _raw_spin_unlock_irq <-run_timer_softirq
960 <idle>-0 0dNs3 17us+: trace_hardirqs_on <-run_timer_softirq
961 <idle>-0 0dNs3 25us : <stack trace>
962 => _raw_spin_unlock_irq
963 => run_timer_softirq
964 => __do_softirq
965 => call_softirq
966 => do_softirq
967 => irq_exit
968 => smp_apic_timer_interrupt
969 => apic_timer_interrupt
970 => rcu_idle_exit
971 => cpu_idle
972 => rest_init
973 => start_kernel
974 => x86_64_start_reservations
975 => x86_64_start_kernel
976
977Here we see that that we had a latency of 16 microseconds (which is
978very good). The _raw_spin_lock_irq in run_timer_softirq disabled
979interrupts. The difference between the 16 and the displayed
980timestamp 25us occurred because the clock was incremented
981between the time of recording the max latency and the time of
982recording the function that had that latency.
983
984Note the above example had function-trace not set. If we set
985function-trace, we get a much larger output:
986
987 with echo 1 > options/function-trace
988
989# tracer: irqsoff
990#
991# irqsoff latency trace v1.1.5 on 3.8.0-test+
992# --------------------------------------------------------------------
993# latency: 71 us, #168/168, CPU#3 | (M:preempt VP:0, KP:0, SP:0 HP:0 #P:4)
994# -----------------
995# | task: bash-2042 (uid:0 nice:0 policy:0 rt_prio:0)
996# -----------------
997# => started at: ata_scsi_queuecmd
998# => ended at: ata_scsi_queuecmd
999#
1000#
1001# _------=> CPU#
1002# / _-----=> irqs-off
1003# | / _----=> need-resched
1004# || / _---=> hardirq/softirq
1005# ||| / _--=> preempt-depth
1006# |||| / delay
1007# cmd pid ||||| time | caller
1008# \ / ||||| \ | /
1009 bash-2042 3d... 0us : _raw_spin_lock_irqsave <-ata_scsi_queuecmd
1010 bash-2042 3d... 0us : add_preempt_count <-_raw_spin_lock_irqsave
1011 bash-2042 3d..1 1us : ata_scsi_find_dev <-ata_scsi_queuecmd
1012 bash-2042 3d..1 1us : __ata_scsi_find_dev <-ata_scsi_find_dev
1013 bash-2042 3d..1 2us : ata_find_dev.part.14 <-__ata_scsi_find_dev
1014 bash-2042 3d..1 2us : ata_qc_new_init <-__ata_scsi_queuecmd
1015 bash-2042 3d..1 3us : ata_sg_init <-__ata_scsi_queuecmd
1016 bash-2042 3d..1 4us : ata_scsi_rw_xlat <-__ata_scsi_queuecmd
1017 bash-2042 3d..1 4us : ata_build_rw_tf <-ata_scsi_rw_xlat
1018[...]
1019 bash-2042 3d..1 67us : delay_tsc <-__delay
1020 bash-2042 3d..1 67us : add_preempt_count <-delay_tsc
1021 bash-2042 3d..2 67us : sub_preempt_count <-delay_tsc
1022 bash-2042 3d..1 67us : add_preempt_count <-delay_tsc
1023 bash-2042 3d..2 68us : sub_preempt_count <-delay_tsc
1024 bash-2042 3d..1 68us+: ata_bmdma_start <-ata_bmdma_qc_issue
1025 bash-2042 3d..1 71us : _raw_spin_unlock_irqrestore <-ata_scsi_queuecmd
1026 bash-2042 3d..1 71us : _raw_spin_unlock_irqrestore <-ata_scsi_queuecmd
1027 bash-2042 3d..1 72us+: trace_hardirqs_on <-ata_scsi_queuecmd
1028 bash-2042 3d..1 120us : <stack trace>
1029 => _raw_spin_unlock_irqrestore
1030 => ata_scsi_queuecmd
1031 => scsi_dispatch_cmd
1032 => scsi_request_fn
1033 => __blk_run_queue_uncond
1034 => __blk_run_queue
1035 => blk_queue_bio
1036 => generic_make_request
1037 => submit_bio
1038 => submit_bh
1039 => __ext3_get_inode_loc
1040 => ext3_iget
1041 => ext3_lookup
1042 => lookup_real
1043 => __lookup_hash
1044 => walk_component
1045 => lookup_last
1046 => path_lookupat
1047 => filename_lookup
1048 => user_path_at_empty
1049 => user_path_at
1050 => vfs_fstatat
1051 => vfs_stat
1052 => sys_newstat
1053 => system_call_fastpath
1054
1055
1056Here we traced a 71 microsecond latency. But we also see all the
1057functions that were called during that time. Note that by
1058enabling function tracing, we incur an added overhead. This
1059overhead may extend the latency times. But nevertheless, this
1060trace has provided some very helpful debugging information.
1061
1062
1063preemptoff
1064----------
1065
1066When preemption is disabled, we may be able to receive
1067interrupts but the task cannot be preempted and a higher
1068priority task must wait for preemption to be enabled again
1069before it can preempt a lower priority task.
1070
1071The preemptoff tracer traces the places that disable preemption.
1072Like the irqsoff tracer, it records the maximum latency for
1073which preemption was disabled. The control of preemptoff tracer
1074is much like the irqsoff tracer.
1075
1076 # echo 0 > options/function-trace
1077 # echo preemptoff > current_tracer
1078 # echo 1 > tracing_on
1079 # echo 0 > tracing_max_latency
1080 # ls -ltr
1081 [...]
1082 # echo 0 > tracing_on
1083 # cat trace
1084# tracer: preemptoff
1085#
1086# preemptoff latency trace v1.1.5 on 3.8.0-test+
1087# --------------------------------------------------------------------
1088# latency: 46 us, #4/4, CPU#1 | (M:preempt VP:0, KP:0, SP:0 HP:0 #P:4)
1089# -----------------
1090# | task: sshd-1991 (uid:0 nice:0 policy:0 rt_prio:0)
1091# -----------------
1092# => started at: do_IRQ
1093# => ended at: do_IRQ
1094#
1095#
1096# _------=> CPU#
1097# / _-----=> irqs-off
1098# | / _----=> need-resched
1099# || / _---=> hardirq/softirq
1100# ||| / _--=> preempt-depth
1101# |||| / delay
1102# cmd pid ||||| time | caller
1103# \ / ||||| \ | /
1104 sshd-1991 1d.h. 0us+: irq_enter <-do_IRQ
1105 sshd-1991 1d..1 46us : irq_exit <-do_IRQ
1106 sshd-1991 1d..1 47us+: trace_preempt_on <-do_IRQ
1107 sshd-1991 1d..1 52us : <stack trace>
1108 => sub_preempt_count
1109 => irq_exit
1110 => do_IRQ
1111 => ret_from_intr
1112
1113
1114This has some more changes. Preemption was disabled when an
1115interrupt came in (notice the 'h'), and was enabled on exit.
1116But we also see that interrupts have been disabled when entering
1117the preempt off section and leaving it (the 'd'). We do not know if
1118interrupts were enabled in the mean time or shortly after this
1119was over.
1120
1121# tracer: preemptoff
1122#
1123# preemptoff latency trace v1.1.5 on 3.8.0-test+
1124# --------------------------------------------------------------------
1125# latency: 83 us, #241/241, CPU#1 | (M:preempt VP:0, KP:0, SP:0 HP:0 #P:4)
1126# -----------------
1127# | task: bash-1994 (uid:0 nice:0 policy:0 rt_prio:0)
1128# -----------------
1129# => started at: wake_up_new_task
1130# => ended at: task_rq_unlock
1131#
1132#
1133# _------=> CPU#
1134# / _-----=> irqs-off
1135# | / _----=> need-resched
1136# || / _---=> hardirq/softirq
1137# ||| / _--=> preempt-depth
1138# |||| / delay
1139# cmd pid ||||| time | caller
1140# \ / ||||| \ | /
1141 bash-1994 1d..1 0us : _raw_spin_lock_irqsave <-wake_up_new_task
1142 bash-1994 1d..1 0us : select_task_rq_fair <-select_task_rq
1143 bash-1994 1d..1 1us : __rcu_read_lock <-select_task_rq_fair
1144 bash-1994 1d..1 1us : source_load <-select_task_rq_fair
1145 bash-1994 1d..1 1us : source_load <-select_task_rq_fair
1146[...]
1147 bash-1994 1d..1 12us : irq_enter <-smp_apic_timer_interrupt
1148 bash-1994 1d..1 12us : rcu_irq_enter <-irq_enter
1149 bash-1994 1d..1 13us : add_preempt_count <-irq_enter
1150 bash-1994 1d.h1 13us : exit_idle <-smp_apic_timer_interrupt
1151 bash-1994 1d.h1 13us : hrtimer_interrupt <-smp_apic_timer_interrupt
1152 bash-1994 1d.h1 13us : _raw_spin_lock <-hrtimer_interrupt
1153 bash-1994 1d.h1 14us : add_preempt_count <-_raw_spin_lock
1154 bash-1994 1d.h2 14us : ktime_get_update_offsets <-hrtimer_interrupt
1155[...]
1156 bash-1994 1d.h1 35us : lapic_next_event <-clockevents_program_event
1157 bash-1994 1d.h1 35us : irq_exit <-smp_apic_timer_interrupt
1158 bash-1994 1d.h1 36us : sub_preempt_count <-irq_exit
1159 bash-1994 1d..2 36us : do_softirq <-irq_exit
1160 bash-1994 1d..2 36us : __do_softirq <-call_softirq
1161 bash-1994 1d..2 36us : __local_bh_disable <-__do_softirq
1162 bash-1994 1d.s2 37us : add_preempt_count <-_raw_spin_lock_irq
1163 bash-1994 1d.s3 38us : _raw_spin_unlock <-run_timer_softirq
1164 bash-1994 1d.s3 39us : sub_preempt_count <-_raw_spin_unlock
1165 bash-1994 1d.s2 39us : call_timer_fn <-run_timer_softirq
1166[...]
1167 bash-1994 1dNs2 81us : cpu_needs_another_gp <-rcu_process_callbacks
1168 bash-1994 1dNs2 82us : __local_bh_enable <-__do_softirq
1169 bash-1994 1dNs2 82us : sub_preempt_count <-__local_bh_enable
1170 bash-1994 1dN.2 82us : idle_cpu <-irq_exit
1171 bash-1994 1dN.2 83us : rcu_irq_exit <-irq_exit
1172 bash-1994 1dN.2 83us : sub_preempt_count <-irq_exit
1173 bash-1994 1.N.1 84us : _raw_spin_unlock_irqrestore <-task_rq_unlock
1174 bash-1994 1.N.1 84us+: trace_preempt_on <-task_rq_unlock
1175 bash-1994 1.N.1 104us : <stack trace>
1176 => sub_preempt_count
1177 => _raw_spin_unlock_irqrestore
1178 => task_rq_unlock
1179 => wake_up_new_task
1180 => do_fork
1181 => sys_clone
1182 => stub_clone
1183
1184
1185The above is an example of the preemptoff trace with
1186function-trace set. Here we see that interrupts were not disabled
1187the entire time. The irq_enter code lets us know that we entered
1188an interrupt 'h'. Before that, the functions being traced still
1189show that it is not in an interrupt, but we can see from the
1190functions themselves that this is not the case.
1191
1192preemptirqsoff
1193--------------
1194
1195Knowing the locations that have interrupts disabled or
1196preemption disabled for the longest times is helpful. But
1197sometimes we would like to know when either preemption and/or
1198interrupts are disabled.
1199
1200Consider the following code:
1201
1202 local_irq_disable();
1203 call_function_with_irqs_off();
1204 preempt_disable();
1205 call_function_with_irqs_and_preemption_off();
1206 local_irq_enable();
1207 call_function_with_preemption_off();
1208 preempt_enable();
1209
1210The irqsoff tracer will record the total length of
1211call_function_with_irqs_off() and
1212call_function_with_irqs_and_preemption_off().
1213
1214The preemptoff tracer will record the total length of
1215call_function_with_irqs_and_preemption_off() and
1216call_function_with_preemption_off().
1217
1218But neither will trace the time that interrupts and/or
1219preemption is disabled. This total time is the time that we can
1220not schedule. To record this time, use the preemptirqsoff
1221tracer.
1222
1223Again, using this trace is much like the irqsoff and preemptoff
1224tracers.
1225
1226 # echo 0 > options/function-trace
1227 # echo preemptirqsoff > current_tracer
1228 # echo 1 > tracing_on
1229 # echo 0 > tracing_max_latency
1230 # ls -ltr
1231 [...]
1232 # echo 0 > tracing_on
1233 # cat trace
1234# tracer: preemptirqsoff
1235#
1236# preemptirqsoff latency trace v1.1.5 on 3.8.0-test+
1237# --------------------------------------------------------------------
1238# latency: 100 us, #4/4, CPU#3 | (M:preempt VP:0, KP:0, SP:0 HP:0 #P:4)
1239# -----------------
1240# | task: ls-2230 (uid:0 nice:0 policy:0 rt_prio:0)
1241# -----------------
1242# => started at: ata_scsi_queuecmd
1243# => ended at: ata_scsi_queuecmd
1244#
1245#
1246# _------=> CPU#
1247# / _-----=> irqs-off
1248# | / _----=> need-resched
1249# || / _---=> hardirq/softirq
1250# ||| / _--=> preempt-depth
1251# |||| / delay
1252# cmd pid ||||| time | caller
1253# \ / ||||| \ | /
1254 ls-2230 3d... 0us+: _raw_spin_lock_irqsave <-ata_scsi_queuecmd
1255 ls-2230 3...1 100us : _raw_spin_unlock_irqrestore <-ata_scsi_queuecmd
1256 ls-2230 3...1 101us+: trace_preempt_on <-ata_scsi_queuecmd
1257 ls-2230 3...1 111us : <stack trace>
1258 => sub_preempt_count
1259 => _raw_spin_unlock_irqrestore
1260 => ata_scsi_queuecmd
1261 => scsi_dispatch_cmd
1262 => scsi_request_fn
1263 => __blk_run_queue_uncond
1264 => __blk_run_queue
1265 => blk_queue_bio
1266 => generic_make_request
1267 => submit_bio
1268 => submit_bh
1269 => ext3_bread
1270 => ext3_dir_bread
1271 => htree_dirblock_to_tree
1272 => ext3_htree_fill_tree
1273 => ext3_readdir
1274 => vfs_readdir
1275 => sys_getdents
1276 => system_call_fastpath
1277
1278
1279The trace_hardirqs_off_thunk is called from assembly on x86 when
1280interrupts are disabled in the assembly code. Without the
1281function tracing, we do not know if interrupts were enabled
1282within the preemption points. We do see that it started with
1283preemption enabled.
1284
1285Here is a trace with function-trace set:
1286
1287# tracer: preemptirqsoff
1288#
1289# preemptirqsoff latency trace v1.1.5 on 3.8.0-test+
1290# --------------------------------------------------------------------
1291# latency: 161 us, #339/339, CPU#3 | (M:preempt VP:0, KP:0, SP:0 HP:0 #P:4)
1292# -----------------
1293# | task: ls-2269 (uid:0 nice:0 policy:0 rt_prio:0)
1294# -----------------
1295# => started at: schedule
1296# => ended at: mutex_unlock
1297#
1298#
1299# _------=> CPU#
1300# / _-----=> irqs-off
1301# | / _----=> need-resched
1302# || / _---=> hardirq/softirq
1303# ||| / _--=> preempt-depth
1304# |||| / delay
1305# cmd pid ||||| time | caller
1306# \ / ||||| \ | /
1307kworker/-59 3...1 0us : __schedule <-schedule
1308kworker/-59 3d..1 0us : rcu_preempt_qs <-rcu_note_context_switch
1309kworker/-59 3d..1 1us : add_preempt_count <-_raw_spin_lock_irq
1310kworker/-59 3d..2 1us : deactivate_task <-__schedule
1311kworker/-59 3d..2 1us : dequeue_task <-deactivate_task
1312kworker/-59 3d..2 2us : update_rq_clock <-dequeue_task
1313kworker/-59 3d..2 2us : dequeue_task_fair <-dequeue_task
1314kworker/-59 3d..2 2us : update_curr <-dequeue_task_fair
1315kworker/-59 3d..2 2us : update_min_vruntime <-update_curr
1316kworker/-59 3d..2 3us : cpuacct_charge <-update_curr
1317kworker/-59 3d..2 3us : __rcu_read_lock <-cpuacct_charge
1318kworker/-59 3d..2 3us : __rcu_read_unlock <-cpuacct_charge
1319kworker/-59 3d..2 3us : update_cfs_rq_blocked_load <-dequeue_task_fair
1320kworker/-59 3d..2 4us : clear_buddies <-dequeue_task_fair
1321kworker/-59 3d..2 4us : account_entity_dequeue <-dequeue_task_fair
1322kworker/-59 3d..2 4us : update_min_vruntime <-dequeue_task_fair
1323kworker/-59 3d..2 4us : update_cfs_shares <-dequeue_task_fair
1324kworker/-59 3d..2 5us : hrtick_update <-dequeue_task_fair
1325kworker/-59 3d..2 5us : wq_worker_sleeping <-__schedule
1326kworker/-59 3d..2 5us : kthread_data <-wq_worker_sleeping
1327kworker/-59 3d..2 5us : put_prev_task_fair <-__schedule
1328kworker/-59 3d..2 6us : pick_next_task_fair <-pick_next_task
1329kworker/-59 3d..2 6us : clear_buddies <-pick_next_task_fair
1330kworker/-59 3d..2 6us : set_next_entity <-pick_next_task_fair
1331kworker/-59 3d..2 6us : update_stats_wait_end <-set_next_entity
1332 ls-2269 3d..2 7us : finish_task_switch <-__schedule
1333 ls-2269 3d..2 7us : _raw_spin_unlock_irq <-finish_task_switch
1334 ls-2269 3d..2 8us : do_IRQ <-ret_from_intr
1335 ls-2269 3d..2 8us : irq_enter <-do_IRQ
1336 ls-2269 3d..2 8us : rcu_irq_enter <-irq_enter
1337 ls-2269 3d..2 9us : add_preempt_count <-irq_enter
1338 ls-2269 3d.h2 9us : exit_idle <-do_IRQ
1339[...]
1340 ls-2269 3d.h3 20us : sub_preempt_count <-_raw_spin_unlock
1341 ls-2269 3d.h2 20us : irq_exit <-do_IRQ
1342 ls-2269 3d.h2 21us : sub_preempt_count <-irq_exit
1343 ls-2269 3d..3 21us : do_softirq <-irq_exit
1344 ls-2269 3d..3 21us : __do_softirq <-call_softirq
1345 ls-2269 3d..3 21us+: __local_bh_disable <-__do_softirq
1346 ls-2269 3d.s4 29us : sub_preempt_count <-_local_bh_enable_ip
1347 ls-2269 3d.s5 29us : sub_preempt_count <-_local_bh_enable_ip
1348 ls-2269 3d.s5 31us : do_IRQ <-ret_from_intr
1349 ls-2269 3d.s5 31us : irq_enter <-do_IRQ
1350 ls-2269 3d.s5 31us : rcu_irq_enter <-irq_enter
1351[...]
1352 ls-2269 3d.s5 31us : rcu_irq_enter <-irq_enter
1353 ls-2269 3d.s5 32us : add_preempt_count <-irq_enter
1354 ls-2269 3d.H5 32us : exit_idle <-do_IRQ
1355 ls-2269 3d.H5 32us : handle_irq <-do_IRQ
1356 ls-2269 3d.H5 32us : irq_to_desc <-handle_irq
1357 ls-2269 3d.H5 33us : handle_fasteoi_irq <-handle_irq
1358[...]
1359 ls-2269 3d.s5 158us : _raw_spin_unlock_irqrestore <-rtl8139_poll
1360 ls-2269 3d.s3 158us : net_rps_action_and_irq_enable.isra.65 <-net_rx_action
1361 ls-2269 3d.s3 159us : __local_bh_enable <-__do_softirq
1362 ls-2269 3d.s3 159us : sub_preempt_count <-__local_bh_enable
1363 ls-2269 3d..3 159us : idle_cpu <-irq_exit
1364 ls-2269 3d..3 159us : rcu_irq_exit <-irq_exit
1365 ls-2269 3d..3 160us : sub_preempt_count <-irq_exit
1366 ls-2269 3d... 161us : __mutex_unlock_slowpath <-mutex_unlock
1367 ls-2269 3d... 162us+: trace_hardirqs_on <-mutex_unlock
1368 ls-2269 3d... 186us : <stack trace>
1369 => __mutex_unlock_slowpath
1370 => mutex_unlock
1371 => process_output
1372 => n_tty_write
1373 => tty_write
1374 => vfs_write
1375 => sys_write
1376 => system_call_fastpath
1377
1378This is an interesting trace. It started with kworker running and
1379scheduling out and ls taking over. But as soon as ls released the
1380rq lock and enabled interrupts (but not preemption) an interrupt
1381triggered. When the interrupt finished, it started running softirqs.
1382But while the softirq was running, another interrupt triggered.
1383When an interrupt is running inside a softirq, the annotation is 'H'.
1384
1385
1386wakeup
1387------
1388
1389One common case that people are interested in tracing is the
1390time it takes for a task that is woken to actually wake up.
1391Now for non Real-Time tasks, this can be arbitrary. But tracing
1392it none the less can be interesting.
1393
1394Without function tracing:
1395
1396 # echo 0 > options/function-trace
1397 # echo wakeup > current_tracer
1398 # echo 1 > tracing_on
1399 # echo 0 > tracing_max_latency
1400 # chrt -f 5 sleep 1
1401 # echo 0 > tracing_on
1402 # cat trace
1403# tracer: wakeup
1404#
1405# wakeup latency trace v1.1.5 on 3.8.0-test+
1406# --------------------------------------------------------------------
1407# latency: 15 us, #4/4, CPU#3 | (M:preempt VP:0, KP:0, SP:0 HP:0 #P:4)
1408# -----------------
1409# | task: kworker/3:1H-312 (uid:0 nice:-20 policy:0 rt_prio:0)
1410# -----------------
1411#
1412# _------=> CPU#
1413# / _-----=> irqs-off
1414# | / _----=> need-resched
1415# || / _---=> hardirq/softirq
1416# ||| / _--=> preempt-depth
1417# |||| / delay
1418# cmd pid ||||| time | caller
1419# \ / ||||| \ | /
1420 <idle>-0 3dNs7 0us : 0:120:R + [003] 312:100:R kworker/3:1H
1421 <idle>-0 3dNs7 1us+: ttwu_do_activate.constprop.87 <-try_to_wake_up
1422 <idle>-0 3d..3 15us : __schedule <-schedule
1423 <idle>-0 3d..3 15us : 0:120:R ==> [003] 312:100:R kworker/3:1H
1424
1425The tracer only traces the highest priority task in the system
1426to avoid tracing the normal circumstances. Here we see that
1427the kworker with a nice priority of -20 (not very nice), took
1428just 15 microseconds from the time it woke up, to the time it
1429ran.
1430
1431Non Real-Time tasks are not that interesting. A more interesting
1432trace is to concentrate only on Real-Time tasks.
1433
1434wakeup_rt
1435---------
1436
1437In a Real-Time environment it is very important to know the
1438wakeup time it takes for the highest priority task that is woken
1439up to the time that it executes. This is also known as "schedule
1440latency". I stress the point that this is about RT tasks. It is
1441also important to know the scheduling latency of non-RT tasks,
1442but the average schedule latency is better for non-RT tasks.
1443Tools like LatencyTop are more appropriate for such
1444measurements.
1445
1446Real-Time environments are interested in the worst case latency.
1447That is the longest latency it takes for something to happen,
1448and not the average. We can have a very fast scheduler that may
1449only have a large latency once in a while, but that would not
1450work well with Real-Time tasks. The wakeup_rt tracer was designed
1451to record the worst case wakeups of RT tasks. Non-RT tasks are
1452not recorded because the tracer only records one worst case and
1453tracing non-RT tasks that are unpredictable will overwrite the
1454worst case latency of RT tasks (just run the normal wakeup
1455tracer for a while to see that effect).
1456
1457Since this tracer only deals with RT tasks, we will run this
1458slightly differently than we did with the previous tracers.
1459Instead of performing an 'ls', we will run 'sleep 1' under
1460'chrt' which changes the priority of the task.
1461
1462 # echo 0 > options/function-trace
1463 # echo wakeup_rt > current_tracer
1464 # echo 1 > tracing_on
1465 # echo 0 > tracing_max_latency
1466 # chrt -f 5 sleep 1
1467 # echo 0 > tracing_on
1468 # cat trace
1469# tracer: wakeup
1470#
1471# tracer: wakeup_rt
1472#
1473# wakeup_rt latency trace v1.1.5 on 3.8.0-test+
1474# --------------------------------------------------------------------
1475# latency: 5 us, #4/4, CPU#3 | (M:preempt VP:0, KP:0, SP:0 HP:0 #P:4)
1476# -----------------
1477# | task: sleep-2389 (uid:0 nice:0 policy:1 rt_prio:5)
1478# -----------------
1479#
1480# _------=> CPU#
1481# / _-----=> irqs-off
1482# | / _----=> need-resched
1483# || / _---=> hardirq/softirq
1484# ||| / _--=> preempt-depth
1485# |||| / delay
1486# cmd pid ||||| time | caller
1487# \ / ||||| \ | /
1488 <idle>-0 3d.h4 0us : 0:120:R + [003] 2389: 94:R sleep
1489 <idle>-0 3d.h4 1us+: ttwu_do_activate.constprop.87 <-try_to_wake_up
1490 <idle>-0 3d..3 5us : __schedule <-schedule
1491 <idle>-0 3d..3 5us : 0:120:R ==> [003] 2389: 94:R sleep
1492
1493
1494Running this on an idle system, we see that it only took 5 microseconds
1495to perform the task switch. Note, since the trace point in the schedule
1496is before the actual "switch", we stop the tracing when the recorded task
1497is about to schedule in. This may change if we add a new marker at the
1498end of the scheduler.
1499
1500Notice that the recorded task is 'sleep' with the PID of 2389
1501and it has an rt_prio of 5. This priority is user-space priority
1502and not the internal kernel priority. The policy is 1 for
1503SCHED_FIFO and 2 for SCHED_RR.
1504
1505Note, that the trace data shows the internal priority (99 - rtprio).
1506
1507 <idle>-0 3d..3 5us : 0:120:R ==> [003] 2389: 94:R sleep
1508
1509The 0:120:R means idle was running with a nice priority of 0 (120 - 20)
1510and in the running state 'R'. The sleep task was scheduled in with
15112389: 94:R. That is the priority is the kernel rtprio (99 - 5 = 94)
1512and it too is in the running state.
1513
1514Doing the same with chrt -r 5 and function-trace set.
1515
1516 echo 1 > options/function-trace
1517
1518# tracer: wakeup_rt
1519#
1520# wakeup_rt latency trace v1.1.5 on 3.8.0-test+
1521# --------------------------------------------------------------------
1522# latency: 29 us, #85/85, CPU#3 | (M:preempt VP:0, KP:0, SP:0 HP:0 #P:4)
1523# -----------------
1524# | task: sleep-2448 (uid:0 nice:0 policy:1 rt_prio:5)
1525# -----------------
1526#
1527# _------=> CPU#
1528# / _-----=> irqs-off
1529# | / _----=> need-resched
1530# || / _---=> hardirq/softirq
1531# ||| / _--=> preempt-depth
1532# |||| / delay
1533# cmd pid ||||| time | caller
1534# \ / ||||| \ | /
1535 <idle>-0 3d.h4 1us+: 0:120:R + [003] 2448: 94:R sleep
1536 <idle>-0 3d.h4 2us : ttwu_do_activate.constprop.87 <-try_to_wake_up
1537 <idle>-0 3d.h3 3us : check_preempt_curr <-ttwu_do_wakeup
1538 <idle>-0 3d.h3 3us : resched_curr <-check_preempt_curr
1539 <idle>-0 3dNh3 4us : task_woken_rt <-ttwu_do_wakeup
1540 <idle>-0 3dNh3 4us : _raw_spin_unlock <-try_to_wake_up
1541 <idle>-0 3dNh3 4us : sub_preempt_count <-_raw_spin_unlock
1542 <idle>-0 3dNh2 5us : ttwu_stat <-try_to_wake_up
1543 <idle>-0 3dNh2 5us : _raw_spin_unlock_irqrestore <-try_to_wake_up
1544 <idle>-0 3dNh2 6us : sub_preempt_count <-_raw_spin_unlock_irqrestore
1545 <idle>-0 3dNh1 6us : _raw_spin_lock <-__run_hrtimer
1546 <idle>-0 3dNh1 6us : add_preempt_count <-_raw_spin_lock
1547 <idle>-0 3dNh2 7us : _raw_spin_unlock <-hrtimer_interrupt
1548 <idle>-0 3dNh2 7us : sub_preempt_count <-_raw_spin_unlock
1549 <idle>-0 3dNh1 7us : tick_program_event <-hrtimer_interrupt
1550 <idle>-0 3dNh1 7us : clockevents_program_event <-tick_program_event
1551 <idle>-0 3dNh1 8us : ktime_get <-clockevents_program_event
1552 <idle>-0 3dNh1 8us : lapic_next_event <-clockevents_program_event
1553 <idle>-0 3dNh1 8us : irq_exit <-smp_apic_timer_interrupt
1554 <idle>-0 3dNh1 9us : sub_preempt_count <-irq_exit
1555 <idle>-0 3dN.2 9us : idle_cpu <-irq_exit
1556 <idle>-0 3dN.2 9us : rcu_irq_exit <-irq_exit
1557 <idle>-0 3dN.2 10us : rcu_eqs_enter_common.isra.45 <-rcu_irq_exit
1558 <idle>-0 3dN.2 10us : sub_preempt_count <-irq_exit
1559 <idle>-0 3.N.1 11us : rcu_idle_exit <-cpu_idle
1560 <idle>-0 3dN.1 11us : rcu_eqs_exit_common.isra.43 <-rcu_idle_exit
1561 <idle>-0 3.N.1 11us : tick_nohz_idle_exit <-cpu_idle
1562 <idle>-0 3dN.1 12us : menu_hrtimer_cancel <-tick_nohz_idle_exit
1563 <idle>-0 3dN.1 12us : ktime_get <-tick_nohz_idle_exit
1564 <idle>-0 3dN.1 12us : tick_do_update_jiffies64 <-tick_nohz_idle_exit
1565 <idle>-0 3dN.1 13us : update_cpu_load_nohz <-tick_nohz_idle_exit
1566 <idle>-0 3dN.1 13us : _raw_spin_lock <-update_cpu_load_nohz
1567 <idle>-0 3dN.1 13us : add_preempt_count <-_raw_spin_lock
1568 <idle>-0 3dN.2 13us : __update_cpu_load <-update_cpu_load_nohz
1569 <idle>-0 3dN.2 14us : sched_avg_update <-__update_cpu_load
1570 <idle>-0 3dN.2 14us : _raw_spin_unlock <-update_cpu_load_nohz
1571 <idle>-0 3dN.2 14us : sub_preempt_count <-_raw_spin_unlock
1572 <idle>-0 3dN.1 15us : calc_load_exit_idle <-tick_nohz_idle_exit
1573 <idle>-0 3dN.1 15us : touch_softlockup_watchdog <-tick_nohz_idle_exit
1574 <idle>-0 3dN.1 15us : hrtimer_cancel <-tick_nohz_idle_exit
1575 <idle>-0 3dN.1 15us : hrtimer_try_to_cancel <-hrtimer_cancel
1576 <idle>-0 3dN.1 16us : lock_hrtimer_base.isra.18 <-hrtimer_try_to_cancel
1577 <idle>-0 3dN.1 16us : _raw_spin_lock_irqsave <-lock_hrtimer_base.isra.18
1578 <idle>-0 3dN.1 16us : add_preempt_count <-_raw_spin_lock_irqsave
1579 <idle>-0 3dN.2 17us : __remove_hrtimer <-remove_hrtimer.part.16
1580 <idle>-0 3dN.2 17us : hrtimer_force_reprogram <-__remove_hrtimer
1581 <idle>-0 3dN.2 17us : tick_program_event <-hrtimer_force_reprogram
1582 <idle>-0 3dN.2 18us : clockevents_program_event <-tick_program_event
1583 <idle>-0 3dN.2 18us : ktime_get <-clockevents_program_event
1584 <idle>-0 3dN.2 18us : lapic_next_event <-clockevents_program_event
1585 <idle>-0 3dN.2 19us : _raw_spin_unlock_irqrestore <-hrtimer_try_to_cancel
1586 <idle>-0 3dN.2 19us : sub_preempt_count <-_raw_spin_unlock_irqrestore
1587 <idle>-0 3dN.1 19us : hrtimer_forward <-tick_nohz_idle_exit
1588 <idle>-0 3dN.1 20us : ktime_add_safe <-hrtimer_forward
1589 <idle>-0 3dN.1 20us : ktime_add_safe <-hrtimer_forward
1590 <idle>-0 3dN.1 20us : hrtimer_start_range_ns <-hrtimer_start_expires.constprop.11
1591 <idle>-0 3dN.1 20us : __hrtimer_start_range_ns <-hrtimer_start_range_ns
1592 <idle>-0 3dN.1 21us : lock_hrtimer_base.isra.18 <-__hrtimer_start_range_ns
1593 <idle>-0 3dN.1 21us : _raw_spin_lock_irqsave <-lock_hrtimer_base.isra.18
1594 <idle>-0 3dN.1 21us : add_preempt_count <-_raw_spin_lock_irqsave
1595 <idle>-0 3dN.2 22us : ktime_add_safe <-__hrtimer_start_range_ns
1596 <idle>-0 3dN.2 22us : enqueue_hrtimer <-__hrtimer_start_range_ns
1597 <idle>-0 3dN.2 22us : tick_program_event <-__hrtimer_start_range_ns
1598 <idle>-0 3dN.2 23us : clockevents_program_event <-tick_program_event
1599 <idle>-0 3dN.2 23us : ktime_get <-clockevents_program_event
1600 <idle>-0 3dN.2 23us : lapic_next_event <-clockevents_program_event
1601 <idle>-0 3dN.2 24us : _raw_spin_unlock_irqrestore <-__hrtimer_start_range_ns
1602 <idle>-0 3dN.2 24us : sub_preempt_count <-_raw_spin_unlock_irqrestore
1603 <idle>-0 3dN.1 24us : account_idle_ticks <-tick_nohz_idle_exit
1604 <idle>-0 3dN.1 24us : account_idle_time <-account_idle_ticks
1605 <idle>-0 3.N.1 25us : sub_preempt_count <-cpu_idle
1606 <idle>-0 3.N.. 25us : schedule <-cpu_idle
1607 <idle>-0 3.N.. 25us : __schedule <-preempt_schedule
1608 <idle>-0 3.N.. 26us : add_preempt_count <-__schedule
1609 <idle>-0 3.N.1 26us : rcu_note_context_switch <-__schedule
1610 <idle>-0 3.N.1 26us : rcu_sched_qs <-rcu_note_context_switch
1611 <idle>-0 3dN.1 27us : rcu_preempt_qs <-rcu_note_context_switch
1612 <idle>-0 3.N.1 27us : _raw_spin_lock_irq <-__schedule
1613 <idle>-0 3dN.1 27us : add_preempt_count <-_raw_spin_lock_irq
1614 <idle>-0 3dN.2 28us : put_prev_task_idle <-__schedule
1615 <idle>-0 3dN.2 28us : pick_next_task_stop <-pick_next_task
1616 <idle>-0 3dN.2 28us : pick_next_task_rt <-pick_next_task
1617 <idle>-0 3dN.2 29us : dequeue_pushable_task <-pick_next_task_rt
1618 <idle>-0 3d..3 29us : __schedule <-preempt_schedule
1619 <idle>-0 3d..3 30us : 0:120:R ==> [003] 2448: 94:R sleep
1620
1621This isn't that big of a trace, even with function tracing enabled,
1622so I included the entire trace.
1623
1624The interrupt went off while when the system was idle. Somewhere
1625before task_woken_rt() was called, the NEED_RESCHED flag was set,
1626this is indicated by the first occurrence of the 'N' flag.
1627
1628Latency tracing and events
1629--------------------------
1630As function tracing can induce a much larger latency, but without
1631seeing what happens within the latency it is hard to know what
1632caused it. There is a middle ground, and that is with enabling
1633events.
1634
1635 # echo 0 > options/function-trace
1636 # echo wakeup_rt > current_tracer
1637 # echo 1 > events/enable
1638 # echo 1 > tracing_on
1639 # echo 0 > tracing_max_latency
1640 # chrt -f 5 sleep 1
1641 # echo 0 > tracing_on
1642 # cat trace
1643# tracer: wakeup_rt
1644#
1645# wakeup_rt latency trace v1.1.5 on 3.8.0-test+
1646# --------------------------------------------------------------------
1647# latency: 6 us, #12/12, CPU#2 | (M:preempt VP:0, KP:0, SP:0 HP:0 #P:4)
1648# -----------------
1649# | task: sleep-5882 (uid:0 nice:0 policy:1 rt_prio:5)
1650# -----------------
1651#
1652# _------=> CPU#
1653# / _-----=> irqs-off
1654# | / _----=> need-resched
1655# || / _---=> hardirq/softirq
1656# ||| / _--=> preempt-depth
1657# |||| / delay
1658# cmd pid ||||| time | caller
1659# \ / ||||| \ | /
1660 <idle>-0 2d.h4 0us : 0:120:R + [002] 5882: 94:R sleep
1661 <idle>-0 2d.h4 0us : ttwu_do_activate.constprop.87 <-try_to_wake_up
1662 <idle>-0 2d.h4 1us : sched_wakeup: comm=sleep pid=5882 prio=94 success=1 target_cpu=002
1663 <idle>-0 2dNh2 1us : hrtimer_expire_exit: hrtimer=ffff88007796feb8
1664 <idle>-0 2.N.2 2us : power_end: cpu_id=2
1665 <idle>-0 2.N.2 3us : cpu_idle: state=4294967295 cpu_id=2
1666 <idle>-0 2dN.3 4us : hrtimer_cancel: hrtimer=ffff88007d50d5e0
1667 <idle>-0 2dN.3 4us : hrtimer_start: hrtimer=ffff88007d50d5e0 function=tick_sched_timer expires=34311211000000 softexpires=34311211000000
1668 <idle>-0 2.N.2 5us : rcu_utilization: Start context switch
1669 <idle>-0 2.N.2 5us : rcu_utilization: End context switch
1670 <idle>-0 2d..3 6us : __schedule <-schedule
1671 <idle>-0 2d..3 6us : 0:120:R ==> [002] 5882: 94:R sleep
1672
1673
1674function
1675--------
1676
1677This tracer is the function tracer. Enabling the function tracer
1678can be done from the debug file system. Make sure the
1679ftrace_enabled is set; otherwise this tracer is a nop.
1680See the "ftrace_enabled" section below.
1681
1682 # sysctl kernel.ftrace_enabled=1
1683 # echo function > current_tracer
1684 # echo 1 > tracing_on
1685 # usleep 1
1686 # echo 0 > tracing_on
1687 # cat trace
1688# tracer: function
1689#
1690# entries-in-buffer/entries-written: 24799/24799 #P:4
1691#
1692# _-----=> irqs-off
1693# / _----=> need-resched
1694# | / _---=> hardirq/softirq
1695# || / _--=> preempt-depth
1696# ||| / delay
1697# TASK-PID CPU# |||| TIMESTAMP FUNCTION
1698# | | | |||| | |
1699 bash-1994 [002] .... 3082.063030: mutex_unlock <-rb_simple_write
1700 bash-1994 [002] .... 3082.063031: __mutex_unlock_slowpath <-mutex_unlock
1701 bash-1994 [002] .... 3082.063031: __fsnotify_parent <-fsnotify_modify
1702 bash-1994 [002] .... 3082.063032: fsnotify <-fsnotify_modify
1703 bash-1994 [002] .... 3082.063032: __srcu_read_lock <-fsnotify
1704 bash-1994 [002] .... 3082.063032: add_preempt_count <-__srcu_read_lock
1705 bash-1994 [002] ...1 3082.063032: sub_preempt_count <-__srcu_read_lock
1706 bash-1994 [002] .... 3082.063033: __srcu_read_unlock <-fsnotify
1707[...]
1708
1709
1710Note: function tracer uses ring buffers to store the above
1711entries. The newest data may overwrite the oldest data.
1712Sometimes using echo to stop the trace is not sufficient because
1713the tracing could have overwritten the data that you wanted to
1714record. For this reason, it is sometimes better to disable
1715tracing directly from a program. This allows you to stop the
1716tracing at the point that you hit the part that you are
1717interested in. To disable the tracing directly from a C program,
1718something like following code snippet can be used:
1719
1720int trace_fd;
1721[...]
1722int main(int argc, char *argv[]) {
1723 [...]
1724 trace_fd = open(tracing_file("tracing_on"), O_WRONLY);
1725 [...]
1726 if (condition_hit()) {
1727 write(trace_fd, "0", 1);
1728 }
1729 [...]
1730}
1731
1732
1733Single thread tracing
1734---------------------
1735
1736By writing into set_ftrace_pid you can trace a
1737single thread. For example:
1738
1739# cat set_ftrace_pid
1740no pid
1741# echo 3111 > set_ftrace_pid
1742# cat set_ftrace_pid
17433111
1744# echo function > current_tracer
1745# cat trace | head
1746 # tracer: function
1747 #
1748 # TASK-PID CPU# TIMESTAMP FUNCTION
1749 # | | | | |
1750 yum-updatesd-3111 [003] 1637.254676: finish_task_switch <-thread_return
1751 yum-updatesd-3111 [003] 1637.254681: hrtimer_cancel <-schedule_hrtimeout_range
1752 yum-updatesd-3111 [003] 1637.254682: hrtimer_try_to_cancel <-hrtimer_cancel
1753 yum-updatesd-3111 [003] 1637.254683: lock_hrtimer_base <-hrtimer_try_to_cancel
1754 yum-updatesd-3111 [003] 1637.254685: fget_light <-do_sys_poll
1755 yum-updatesd-3111 [003] 1637.254686: pipe_poll <-do_sys_poll
1756# echo > set_ftrace_pid
1757# cat trace |head
1758 # tracer: function
1759 #
1760 # TASK-PID CPU# TIMESTAMP FUNCTION
1761 # | | | | |
1762 ##### CPU 3 buffer started ####
1763 yum-updatesd-3111 [003] 1701.957688: free_poll_entry <-poll_freewait
1764 yum-updatesd-3111 [003] 1701.957689: remove_wait_queue <-free_poll_entry
1765 yum-updatesd-3111 [003] 1701.957691: fput <-free_poll_entry
1766 yum-updatesd-3111 [003] 1701.957692: audit_syscall_exit <-sysret_audit
1767 yum-updatesd-3111 [003] 1701.957693: path_put <-audit_syscall_exit
1768
1769If you want to trace a function when executing, you could use
1770something like this simple program:
1771
1772#include <stdio.h>
1773#include <stdlib.h>
1774#include <sys/types.h>
1775#include <sys/stat.h>
1776#include <fcntl.h>
1777#include <unistd.h>
1778#include <string.h>
1779
1780#define _STR(x) #x
1781#define STR(x) _STR(x)
1782#define MAX_PATH 256
1783
1784const char *find_debugfs(void)
1785{
1786 static char debugfs[MAX_PATH+1];
1787 static int debugfs_found;
1788 char type[100];
1789 FILE *fp;
1790
1791 if (debugfs_found)
1792 return debugfs;
1793
1794 if ((fp = fopen("/proc/mounts","r")) == NULL) {
1795 perror("/proc/mounts");
1796 return NULL;
1797 }
1798
1799 while (fscanf(fp, "%*s %"
1800 STR(MAX_PATH)
1801 "s %99s %*s %*d %*d\n",
1802 debugfs, type) == 2) {
1803 if (strcmp(type, "debugfs") == 0)
1804 break;
1805 }
1806 fclose(fp);
1807
1808 if (strcmp(type, "debugfs") != 0) {
1809 fprintf(stderr, "debugfs not mounted");
1810 return NULL;
1811 }
1812
1813 strcat(debugfs, "/tracing/");
1814 debugfs_found = 1;
1815
1816 return debugfs;
1817}
1818
1819const char *tracing_file(const char *file_name)
1820{
1821 static char trace_file[MAX_PATH+1];
1822 snprintf(trace_file, MAX_PATH, "%s/%s", find_debugfs(), file_name);
1823 return trace_file;
1824}
1825
1826int main (int argc, char **argv)
1827{
1828 if (argc < 1)
1829 exit(-1);
1830
1831 if (fork() > 0) {
1832 int fd, ffd;
1833 char line[64];
1834 int s;
1835
1836 ffd = open(tracing_file("current_tracer"), O_WRONLY);
1837 if (ffd < 0)
1838 exit(-1);
1839 write(ffd, "nop", 3);
1840
1841 fd = open(tracing_file("set_ftrace_pid"), O_WRONLY);
1842 s = sprintf(line, "%d\n", getpid());
1843 write(fd, line, s);
1844
1845 write(ffd, "function", 8);
1846
1847 close(fd);
1848 close(ffd);
1849
1850 execvp(argv[1], argv+1);
1851 }
1852
1853 return 0;
1854}
1855
1856Or this simple script!
1857
1858------
1859#!/bin/bash
1860
1861debugfs=`sed -ne 's/^debugfs \(.*\) debugfs.*/\1/p' /proc/mounts`
1862echo nop > $debugfs/tracing/current_tracer
1863echo 0 > $debugfs/tracing/tracing_on
1864echo $$ > $debugfs/tracing/set_ftrace_pid
1865echo function > $debugfs/tracing/current_tracer
1866echo 1 > $debugfs/tracing/tracing_on
1867exec "$@"
1868------
1869
1870
1871function graph tracer
1872---------------------------
1873
1874This tracer is similar to the function tracer except that it
1875probes a function on its entry and its exit. This is done by
1876using a dynamically allocated stack of return addresses in each
1877task_struct. On function entry the tracer overwrites the return
1878address of each function traced to set a custom probe. Thus the
1879original return address is stored on the stack of return address
1880in the task_struct.
1881
1882Probing on both ends of a function leads to special features
1883such as:
1884
1885- measure of a function's time execution
1886- having a reliable call stack to draw function calls graph
1887
1888This tracer is useful in several situations:
1889
1890- you want to find the reason of a strange kernel behavior and
1891 need to see what happens in detail on any areas (or specific
1892 ones).
1893
1894- you are experiencing weird latencies but it's difficult to
1895 find its origin.
1896
1897- you want to find quickly which path is taken by a specific
1898 function
1899
1900- you just want to peek inside a working kernel and want to see
1901 what happens there.
1902
1903# tracer: function_graph
1904#
1905# CPU DURATION FUNCTION CALLS
1906# | | | | | | |
1907
1908 0) | sys_open() {
1909 0) | do_sys_open() {
1910 0) | getname() {
1911 0) | kmem_cache_alloc() {
1912 0) 1.382 us | __might_sleep();
1913 0) 2.478 us | }
1914 0) | strncpy_from_user() {
1915 0) | might_fault() {
1916 0) 1.389 us | __might_sleep();
1917 0) 2.553 us | }
1918 0) 3.807 us | }
1919 0) 7.876 us | }
1920 0) | alloc_fd() {
1921 0) 0.668 us | _spin_lock();
1922 0) 0.570 us | expand_files();
1923 0) 0.586 us | _spin_unlock();
1924
1925
1926There are several columns that can be dynamically
1927enabled/disabled. You can use every combination of options you
1928want, depending on your needs.
1929
1930- The cpu number on which the function executed is default
1931 enabled. It is sometimes better to only trace one cpu (see
1932 tracing_cpu_mask file) or you might sometimes see unordered
1933 function calls while cpu tracing switch.
1934
1935 hide: echo nofuncgraph-cpu > trace_options
1936 show: echo funcgraph-cpu > trace_options
1937
1938- The duration (function's time of execution) is displayed on
1939 the closing bracket line of a function or on the same line
1940 than the current function in case of a leaf one. It is default
1941 enabled.
1942
1943 hide: echo nofuncgraph-duration > trace_options
1944 show: echo funcgraph-duration > trace_options
1945
1946- The overhead field precedes the duration field in case of
1947 reached duration thresholds.
1948
1949 hide: echo nofuncgraph-overhead > trace_options
1950 show: echo funcgraph-overhead > trace_options
1951 depends on: funcgraph-duration
1952
1953 ie:
1954
1955 3) # 1837.709 us | } /* __switch_to */
1956 3) | finish_task_switch() {
1957 3) 0.313 us | _raw_spin_unlock_irq();
1958 3) 3.177 us | }
1959 3) # 1889.063 us | } /* __schedule */
1960 3) ! 140.417 us | } /* __schedule */
1961 3) # 2034.948 us | } /* schedule */
1962 3) * 33998.59 us | } /* schedule_preempt_disabled */
1963
1964 [...]
1965
1966 1) 0.260 us | msecs_to_jiffies();
1967 1) 0.313 us | __rcu_read_unlock();
1968 1) + 61.770 us | }
1969 1) + 64.479 us | }
1970 1) 0.313 us | rcu_bh_qs();
1971 1) 0.313 us | __local_bh_enable();
1972 1) ! 217.240 us | }
1973 1) 0.365 us | idle_cpu();
1974 1) | rcu_irq_exit() {
1975 1) 0.417 us | rcu_eqs_enter_common.isra.47();
1976 1) 3.125 us | }
1977 1) ! 227.812 us | }
1978 1) ! 457.395 us | }
1979 1) @ 119760.2 us | }
1980
1981 [...]
1982
1983 2) | handle_IPI() {
1984 1) 6.979 us | }
1985 2) 0.417 us | scheduler_ipi();
1986 1) 9.791 us | }
1987 1) + 12.917 us | }
1988 2) 3.490 us | }
1989 1) + 15.729 us | }
1990 1) + 18.542 us | }
1991 2) $ 3594274 us | }
1992
1993 + means that the function exceeded 10 usecs.
1994 ! means that the function exceeded 100 usecs.
1995 # means that the function exceeded 1000 usecs.
1996 * means that the function exceeded 10 msecs.
1997 @ means that the function exceeded 100 msecs.
1998 $ means that the function exceeded 1 sec.
1999
2000
2001- The task/pid field displays the thread cmdline and pid which
2002 executed the function. It is default disabled.
2003
2004 hide: echo nofuncgraph-proc > trace_options
2005 show: echo funcgraph-proc > trace_options
2006
2007 ie:
2008
2009 # tracer: function_graph
2010 #
2011 # CPU TASK/PID DURATION FUNCTION CALLS
2012 # | | | | | | | | |
2013 0) sh-4802 | | d_free() {
2014 0) sh-4802 | | call_rcu() {
2015 0) sh-4802 | | __call_rcu() {
2016 0) sh-4802 | 0.616 us | rcu_process_gp_end();
2017 0) sh-4802 | 0.586 us | check_for_new_grace_period();
2018 0) sh-4802 | 2.899 us | }
2019 0) sh-4802 | 4.040 us | }
2020 0) sh-4802 | 5.151 us | }
2021 0) sh-4802 | + 49.370 us | }
2022
2023
2024- The absolute time field is an absolute timestamp given by the
2025 system clock since it started. A snapshot of this time is
2026 given on each entry/exit of functions
2027
2028 hide: echo nofuncgraph-abstime > trace_options
2029 show: echo funcgraph-abstime > trace_options
2030
2031 ie:
2032
2033 #
2034 # TIME CPU DURATION FUNCTION CALLS
2035 # | | | | | | | |
2036 360.774522 | 1) 0.541 us | }
2037 360.774522 | 1) 4.663 us | }
2038 360.774523 | 1) 0.541 us | __wake_up_bit();
2039 360.774524 | 1) 6.796 us | }
2040 360.774524 | 1) 7.952 us | }
2041 360.774525 | 1) 9.063 us | }
2042 360.774525 | 1) 0.615 us | journal_mark_dirty();
2043 360.774527 | 1) 0.578 us | __brelse();
2044 360.774528 | 1) | reiserfs_prepare_for_journal() {
2045 360.774528 | 1) | unlock_buffer() {
2046 360.774529 | 1) | wake_up_bit() {
2047 360.774529 | 1) | bit_waitqueue() {
2048 360.774530 | 1) 0.594 us | __phys_addr();
2049
2050
2051The function name is always displayed after the closing bracket
2052for a function if the start of that function is not in the
2053trace buffer.
2054
2055Display of the function name after the closing bracket may be
2056enabled for functions whose start is in the trace buffer,
2057allowing easier searching with grep for function durations.
2058It is default disabled.
2059
2060 hide: echo nofuncgraph-tail > trace_options
2061 show: echo funcgraph-tail > trace_options
2062
2063 Example with nofuncgraph-tail (default):
2064 0) | putname() {
2065 0) | kmem_cache_free() {
2066 0) 0.518 us | __phys_addr();
2067 0) 1.757 us | }
2068 0) 2.861 us | }
2069
2070 Example with funcgraph-tail:
2071 0) | putname() {
2072 0) | kmem_cache_free() {
2073 0) 0.518 us | __phys_addr();
2074 0) 1.757 us | } /* kmem_cache_free() */
2075 0) 2.861 us | } /* putname() */
2076
2077You can put some comments on specific functions by using
2078trace_printk() For example, if you want to put a comment inside
2079the __might_sleep() function, you just have to include
2080<linux/ftrace.h> and call trace_printk() inside __might_sleep()
2081
2082trace_printk("I'm a comment!\n")
2083
2084will produce:
2085
2086 1) | __might_sleep() {
2087 1) | /* I'm a comment! */
2088 1) 1.449 us | }
2089
2090
2091You might find other useful features for this tracer in the
2092following "dynamic ftrace" section such as tracing only specific
2093functions or tasks.
2094
2095dynamic ftrace
2096--------------
2097
2098If CONFIG_DYNAMIC_FTRACE is set, the system will run with
2099virtually no overhead when function tracing is disabled. The way
2100this works is the mcount function call (placed at the start of
2101every kernel function, produced by the -pg switch in gcc),
2102starts of pointing to a simple return. (Enabling FTRACE will
2103include the -pg switch in the compiling of the kernel.)
2104
2105At compile time every C file object is run through the
2106recordmcount program (located in the scripts directory). This
2107program will parse the ELF headers in the C object to find all
2108the locations in the .text section that call mcount. (Note, only
2109white listed .text sections are processed, since processing other
2110sections like .init.text may cause races due to those sections
2111being freed unexpectedly).
2112
2113A new section called "__mcount_loc" is created that holds
2114references to all the mcount call sites in the .text section.
2115The recordmcount program re-links this section back into the
2116original object. The final linking stage of the kernel will add all these
2117references into a single table.
2118
2119On boot up, before SMP is initialized, the dynamic ftrace code
2120scans this table and updates all the locations into nops. It
2121also records the locations, which are added to the
2122available_filter_functions list. Modules are processed as they
2123are loaded and before they are executed. When a module is
2124unloaded, it also removes its functions from the ftrace function
2125list. This is automatic in the module unload code, and the
2126module author does not need to worry about it.
2127
2128When tracing is enabled, the process of modifying the function
2129tracepoints is dependent on architecture. The old method is to use
2130kstop_machine to prevent races with the CPUs executing code being
2131modified (which can cause the CPU to do undesirable things, especially
2132if the modified code crosses cache (or page) boundaries), and the nops are
2133patched back to calls. But this time, they do not call mcount
2134(which is just a function stub). They now call into the ftrace
2135infrastructure.
2136
2137The new method of modifying the function tracepoints is to place
2138a breakpoint at the location to be modified, sync all CPUs, modify
2139the rest of the instruction not covered by the breakpoint. Sync
2140all CPUs again, and then remove the breakpoint with the finished
2141version to the ftrace call site.
2142
2143Some archs do not even need to monkey around with the synchronization,
2144and can just slap the new code on top of the old without any
2145problems with other CPUs executing it at the same time.
2146
2147One special side-effect to the recording of the functions being
2148traced is that we can now selectively choose which functions we
2149wish to trace and which ones we want the mcount calls to remain
2150as nops.
2151
2152Two files are used, one for enabling and one for disabling the
2153tracing of specified functions. They are:
2154
2155 set_ftrace_filter
2156
2157and
2158
2159 set_ftrace_notrace
2160
2161A list of available functions that you can add to these files is
2162listed in:
2163
2164 available_filter_functions
2165
2166 # cat available_filter_functions
2167put_prev_task_idle
2168kmem_cache_create
2169pick_next_task_rt
2170get_online_cpus
2171pick_next_task_fair
2172mutex_lock
2173[...]
2174
2175If I am only interested in sys_nanosleep and hrtimer_interrupt:
2176
2177 # echo sys_nanosleep hrtimer_interrupt > set_ftrace_filter
2178 # echo function > current_tracer
2179 # echo 1 > tracing_on
2180 # usleep 1
2181 # echo 0 > tracing_on
2182 # cat trace
2183# tracer: function
2184#
2185# entries-in-buffer/entries-written: 5/5 #P:4
2186#
2187# _-----=> irqs-off
2188# / _----=> need-resched
2189# | / _---=> hardirq/softirq
2190# || / _--=> preempt-depth
2191# ||| / delay
2192# TASK-PID CPU# |||| TIMESTAMP FUNCTION
2193# | | | |||| | |
2194 usleep-2665 [001] .... 4186.475355: sys_nanosleep <-system_call_fastpath
2195 <idle>-0 [001] d.h1 4186.475409: hrtimer_interrupt <-smp_apic_timer_interrupt
2196 usleep-2665 [001] d.h1 4186.475426: hrtimer_interrupt <-smp_apic_timer_interrupt
2197 <idle>-0 [003] d.h1 4186.475426: hrtimer_interrupt <-smp_apic_timer_interrupt
2198 <idle>-0 [002] d.h1 4186.475427: hrtimer_interrupt <-smp_apic_timer_interrupt
2199
2200To see which functions are being traced, you can cat the file:
2201
2202 # cat set_ftrace_filter
2203hrtimer_interrupt
2204sys_nanosleep
2205
2206
2207Perhaps this is not enough. The filters also allow simple wild
2208cards. Only the following are currently available
2209
2210 <match>* - will match functions that begin with <match>
2211 *<match> - will match functions that end with <match>
2212 *<match>* - will match functions that have <match> in it
2213
2214These are the only wild cards which are supported.
2215
2216 <match>*<match> will not work.
2217
2218Note: It is better to use quotes to enclose the wild cards,
2219 otherwise the shell may expand the parameters into names
2220 of files in the local directory.
2221
2222 # echo 'hrtimer_*' > set_ftrace_filter
2223
2224Produces:
2225
2226# tracer: function
2227#
2228# entries-in-buffer/entries-written: 897/897 #P:4
2229#
2230# _-----=> irqs-off
2231# / _----=> need-resched
2232# | / _---=> hardirq/softirq
2233# || / _--=> preempt-depth
2234# ||| / delay
2235# TASK-PID CPU# |||| TIMESTAMP FUNCTION
2236# | | | |||| | |
2237 <idle>-0 [003] dN.1 4228.547803: hrtimer_cancel <-tick_nohz_idle_exit
2238 <idle>-0 [003] dN.1 4228.547804: hrtimer_try_to_cancel <-hrtimer_cancel
2239 <idle>-0 [003] dN.2 4228.547805: hrtimer_force_reprogram <-__remove_hrtimer
2240 <idle>-0 [003] dN.1 4228.547805: hrtimer_forward <-tick_nohz_idle_exit
2241 <idle>-0 [003] dN.1 4228.547805: hrtimer_start_range_ns <-hrtimer_start_expires.constprop.11
2242 <idle>-0 [003] d..1 4228.547858: hrtimer_get_next_event <-get_next_timer_interrupt
2243 <idle>-0 [003] d..1 4228.547859: hrtimer_start <-__tick_nohz_idle_enter
2244 <idle>-0 [003] d..2 4228.547860: hrtimer_force_reprogram <-__rem
2245
2246Notice that we lost the sys_nanosleep.
2247
2248 # cat set_ftrace_filter
2249hrtimer_run_queues
2250hrtimer_run_pending
2251hrtimer_init
2252hrtimer_cancel
2253hrtimer_try_to_cancel
2254hrtimer_forward
2255hrtimer_start
2256hrtimer_reprogram
2257hrtimer_force_reprogram
2258hrtimer_get_next_event
2259hrtimer_interrupt
2260hrtimer_nanosleep
2261hrtimer_wakeup
2262hrtimer_get_remaining
2263hrtimer_get_res
2264hrtimer_init_sleeper
2265
2266
2267This is because the '>' and '>>' act just like they do in bash.
2268To rewrite the filters, use '>'
2269To append to the filters, use '>>'
2270
2271To clear out a filter so that all functions will be recorded
2272again:
2273
2274 # echo > set_ftrace_filter
2275 # cat set_ftrace_filter
2276 #
2277
2278Again, now we want to append.
2279
2280 # echo sys_nanosleep > set_ftrace_filter
2281 # cat set_ftrace_filter
2282sys_nanosleep
2283 # echo 'hrtimer_*' >> set_ftrace_filter
2284 # cat set_ftrace_filter
2285hrtimer_run_queues
2286hrtimer_run_pending
2287hrtimer_init
2288hrtimer_cancel
2289hrtimer_try_to_cancel
2290hrtimer_forward
2291hrtimer_start
2292hrtimer_reprogram
2293hrtimer_force_reprogram
2294hrtimer_get_next_event
2295hrtimer_interrupt
2296sys_nanosleep
2297hrtimer_nanosleep
2298hrtimer_wakeup
2299hrtimer_get_remaining
2300hrtimer_get_res
2301hrtimer_init_sleeper
2302
2303
2304The set_ftrace_notrace prevents those functions from being
2305traced.
2306
2307 # echo '*preempt*' '*lock*' > set_ftrace_notrace
2308
2309Produces:
2310
2311# tracer: function
2312#
2313# entries-in-buffer/entries-written: 39608/39608 #P:4
2314#
2315# _-----=> irqs-off
2316# / _----=> need-resched
2317# | / _---=> hardirq/softirq
2318# || / _--=> preempt-depth
2319# ||| / delay
2320# TASK-PID CPU# |||| TIMESTAMP FUNCTION
2321# | | | |||| | |
2322 bash-1994 [000] .... 4342.324896: file_ra_state_init <-do_dentry_open
2323 bash-1994 [000] .... 4342.324897: open_check_o_direct <-do_last
2324 bash-1994 [000] .... 4342.324897: ima_file_check <-do_last
2325 bash-1994 [000] .... 4342.324898: process_measurement <-ima_file_check
2326 bash-1994 [000] .... 4342.324898: ima_get_action <-process_measurement
2327 bash-1994 [000] .... 4342.324898: ima_match_policy <-ima_get_action
2328 bash-1994 [000] .... 4342.324899: do_truncate <-do_last
2329 bash-1994 [000] .... 4342.324899: should_remove_suid <-do_truncate
2330 bash-1994 [000] .... 4342.324899: notify_change <-do_truncate
2331 bash-1994 [000] .... 4342.324900: current_fs_time <-notify_change
2332 bash-1994 [000] .... 4342.324900: current_kernel_time <-current_fs_time
2333 bash-1994 [000] .... 4342.324900: timespec_trunc <-current_fs_time
2334
2335We can see that there's no more lock or preempt tracing.
2336
2337
2338Dynamic ftrace with the function graph tracer
2339---------------------------------------------
2340
2341Although what has been explained above concerns both the
2342function tracer and the function-graph-tracer, there are some
2343special features only available in the function-graph tracer.
2344
2345If you want to trace only one function and all of its children,
2346you just have to echo its name into set_graph_function:
2347
2348 echo __do_fault > set_graph_function
2349
2350will produce the following "expanded" trace of the __do_fault()
2351function:
2352
2353 0) | __do_fault() {
2354 0) | filemap_fault() {
2355 0) | find_lock_page() {
2356 0) 0.804 us | find_get_page();
2357 0) | __might_sleep() {
2358 0) 1.329 us | }
2359 0) 3.904 us | }
2360 0) 4.979 us | }
2361 0) 0.653 us | _spin_lock();
2362 0) 0.578 us | page_add_file_rmap();
2363 0) 0.525 us | native_set_pte_at();
2364 0) 0.585 us | _spin_unlock();
2365 0) | unlock_page() {
2366 0) 0.541 us | page_waitqueue();
2367 0) 0.639 us | __wake_up_bit();
2368 0) 2.786 us | }
2369 0) + 14.237 us | }
2370 0) | __do_fault() {
2371 0) | filemap_fault() {
2372 0) | find_lock_page() {
2373 0) 0.698 us | find_get_page();
2374 0) | __might_sleep() {
2375 0) 1.412 us | }
2376 0) 3.950 us | }
2377 0) 5.098 us | }
2378 0) 0.631 us | _spin_lock();
2379 0) 0.571 us | page_add_file_rmap();
2380 0) 0.526 us | native_set_pte_at();
2381 0) 0.586 us | _spin_unlock();
2382 0) | unlock_page() {
2383 0) 0.533 us | page_waitqueue();
2384 0) 0.638 us | __wake_up_bit();
2385 0) 2.793 us | }
2386 0) + 14.012 us | }
2387
2388You can also expand several functions at once:
2389
2390 echo sys_open > set_graph_function
2391 echo sys_close >> set_graph_function
2392
2393Now if you want to go back to trace all functions you can clear
2394this special filter via:
2395
2396 echo > set_graph_function
2397
2398
2399ftrace_enabled
2400--------------
2401
2402Note, the proc sysctl ftrace_enable is a big on/off switch for the
2403function tracer. By default it is enabled (when function tracing is
2404enabled in the kernel). If it is disabled, all function tracing is
2405disabled. This includes not only the function tracers for ftrace, but
2406also for any other uses (perf, kprobes, stack tracing, profiling, etc).
2407
2408Please disable this with care.
2409
2410This can be disable (and enabled) with:
2411
2412 sysctl kernel.ftrace_enabled=0
2413 sysctl kernel.ftrace_enabled=1
2414
2415 or
2416
2417 echo 0 > /proc/sys/kernel/ftrace_enabled
2418 echo 1 > /proc/sys/kernel/ftrace_enabled
2419
2420
2421Filter commands
2422---------------
2423
2424A few commands are supported by the set_ftrace_filter interface.
2425Trace commands have the following format:
2426
2427<function>:<command>:<parameter>
2428
2429The following commands are supported:
2430
2431- mod
2432 This command enables function filtering per module. The
2433 parameter defines the module. For example, if only the write*
2434 functions in the ext3 module are desired, run:
2435
2436 echo 'write*:mod:ext3' > set_ftrace_filter
2437
2438 This command interacts with the filter in the same way as
2439 filtering based on function names. Thus, adding more functions
2440 in a different module is accomplished by appending (>>) to the
2441 filter file. Remove specific module functions by prepending
2442 '!':
2443
2444 echo '!writeback*:mod:ext3' >> set_ftrace_filter
2445
2446 Mod command supports module globbing. Disable tracing for all
2447 functions except a specific module:
2448
2449 echo '!*:mod:!ext3' >> set_ftrace_filter
2450
2451 Disable tracing for all modules, but still trace kernel:
2452
2453 echo '!*:mod:*' >> set_ftrace_filter
2454
2455 Enable filter only for kernel:
2456
2457 echo '*write*:mod:!*' >> set_ftrace_filter
2458
2459 Enable filter for module globbing:
2460
2461 echo '*write*:mod:*snd*' >> set_ftrace_filter
2462
2463- traceon/traceoff
2464 These commands turn tracing on and off when the specified
2465 functions are hit. The parameter determines how many times the
2466 tracing system is turned on and off. If unspecified, there is
2467 no limit. For example, to disable tracing when a schedule bug
2468 is hit the first 5 times, run:
2469
2470 echo '__schedule_bug:traceoff:5' > set_ftrace_filter
2471
2472 To always disable tracing when __schedule_bug is hit:
2473
2474 echo '__schedule_bug:traceoff' > set_ftrace_filter
2475
2476 These commands are cumulative whether or not they are appended
2477 to set_ftrace_filter. To remove a command, prepend it by '!'
2478 and drop the parameter:
2479
2480 echo '!__schedule_bug:traceoff:0' > set_ftrace_filter
2481
2482 The above removes the traceoff command for __schedule_bug
2483 that have a counter. To remove commands without counters:
2484
2485 echo '!__schedule_bug:traceoff' > set_ftrace_filter
2486
2487- snapshot
2488 Will cause a snapshot to be triggered when the function is hit.
2489
2490 echo 'native_flush_tlb_others:snapshot' > set_ftrace_filter
2491
2492 To only snapshot once:
2493
2494 echo 'native_flush_tlb_others:snapshot:1' > set_ftrace_filter
2495
2496 To remove the above commands:
2497
2498 echo '!native_flush_tlb_others:snapshot' > set_ftrace_filter
2499 echo '!native_flush_tlb_others:snapshot:0' > set_ftrace_filter
2500
2501- enable_event/disable_event
2502 These commands can enable or disable a trace event. Note, because
2503 function tracing callbacks are very sensitive, when these commands
2504 are registered, the trace point is activated, but disabled in
2505 a "soft" mode. That is, the tracepoint will be called, but
2506 just will not be traced. The event tracepoint stays in this mode
2507 as long as there's a command that triggers it.
2508
2509 echo 'try_to_wake_up:enable_event:sched:sched_switch:2' > \
2510 set_ftrace_filter
2511
2512 The format is:
2513
2514 <function>:enable_event:<system>:<event>[:count]
2515 <function>:disable_event:<system>:<event>[:count]
2516
2517 To remove the events commands:
2518
2519
2520 echo '!try_to_wake_up:enable_event:sched:sched_switch:0' > \
2521 set_ftrace_filter
2522 echo '!schedule:disable_event:sched:sched_switch' > \
2523 set_ftrace_filter
2524
2525- dump
2526 When the function is hit, it will dump the contents of the ftrace
2527 ring buffer to the console. This is useful if you need to debug
2528 something, and want to dump the trace when a certain function
2529 is hit. Perhaps its a function that is called before a tripple
2530 fault happens and does not allow you to get a regular dump.
2531
2532- cpudump
2533 When the function is hit, it will dump the contents of the ftrace
2534 ring buffer for the current CPU to the console. Unlike the "dump"
2535 command, it only prints out the contents of the ring buffer for the
2536 CPU that executed the function that triggered the dump.
2537
2538trace_pipe
2539----------
2540
2541The trace_pipe outputs the same content as the trace file, but
2542the effect on the tracing is different. Every read from
2543trace_pipe is consumed. This means that subsequent reads will be
2544different. The trace is live.
2545
2546 # echo function > current_tracer
2547 # cat trace_pipe > /tmp/trace.out &
2548[1] 4153
2549 # echo 1 > tracing_on
2550 # usleep 1
2551 # echo 0 > tracing_on
2552 # cat trace
2553# tracer: function
2554#
2555# entries-in-buffer/entries-written: 0/0 #P:4
2556#
2557# _-----=> irqs-off
2558# / _----=> need-resched
2559# | / _---=> hardirq/softirq
2560# || / _--=> preempt-depth
2561# ||| / delay
2562# TASK-PID CPU# |||| TIMESTAMP FUNCTION
2563# | | | |||| | |
2564
2565 #
2566 # cat /tmp/trace.out
2567 bash-1994 [000] .... 5281.568961: mutex_unlock <-rb_simple_write
2568 bash-1994 [000] .... 5281.568963: __mutex_unlock_slowpath <-mutex_unlock
2569 bash-1994 [000] .... 5281.568963: __fsnotify_parent <-fsnotify_modify
2570 bash-1994 [000] .... 5281.568964: fsnotify <-fsnotify_modify
2571 bash-1994 [000] .... 5281.568964: __srcu_read_lock <-fsnotify
2572 bash-1994 [000] .... 5281.568964: add_preempt_count <-__srcu_read_lock
2573 bash-1994 [000] ...1 5281.568965: sub_preempt_count <-__srcu_read_lock
2574 bash-1994 [000] .... 5281.568965: __srcu_read_unlock <-fsnotify
2575 bash-1994 [000] .... 5281.568967: sys_dup2 <-system_call_fastpath
2576
2577
2578Note, reading the trace_pipe file will block until more input is
2579added.
2580
2581trace entries
2582-------------
2583
2584Having too much or not enough data can be troublesome in
2585diagnosing an issue in the kernel. The file buffer_size_kb is
2586used to modify the size of the internal trace buffers. The
2587number listed is the number of entries that can be recorded per
2588CPU. To know the full size, multiply the number of possible CPUs
2589with the number of entries.
2590
2591 # cat buffer_size_kb
25921408 (units kilobytes)
2593
2594Or simply read buffer_total_size_kb
2595
2596 # cat buffer_total_size_kb
25975632
2598
2599To modify the buffer, simple echo in a number (in 1024 byte segments).
2600
2601 # echo 10000 > buffer_size_kb
2602 # cat buffer_size_kb
260310000 (units kilobytes)
2604
2605It will try to allocate as much as possible. If you allocate too
2606much, it can cause Out-Of-Memory to trigger.
2607
2608 # echo 1000000000000 > buffer_size_kb
2609-bash: echo: write error: Cannot allocate memory
2610 # cat buffer_size_kb
261185
2612
2613The per_cpu buffers can be changed individually as well:
2614
2615 # echo 10000 > per_cpu/cpu0/buffer_size_kb
2616 # echo 100 > per_cpu/cpu1/buffer_size_kb
2617
2618When the per_cpu buffers are not the same, the buffer_size_kb
2619at the top level will just show an X
2620
2621 # cat buffer_size_kb
2622X
2623
2624This is where the buffer_total_size_kb is useful:
2625
2626 # cat buffer_total_size_kb
262712916
2628
2629Writing to the top level buffer_size_kb will reset all the buffers
2630to be the same again.
2631
2632Snapshot
2633--------
2634CONFIG_TRACER_SNAPSHOT makes a generic snapshot feature
2635available to all non latency tracers. (Latency tracers which
2636record max latency, such as "irqsoff" or "wakeup", can't use
2637this feature, since those are already using the snapshot
2638mechanism internally.)
2639
2640Snapshot preserves a current trace buffer at a particular point
2641in time without stopping tracing. Ftrace swaps the current
2642buffer with a spare buffer, and tracing continues in the new
2643current (=previous spare) buffer.
2644
2645The following debugfs files in "tracing" are related to this
2646feature:
2647
2648 snapshot:
2649
2650 This is used to take a snapshot and to read the output
2651 of the snapshot. Echo 1 into this file to allocate a
2652 spare buffer and to take a snapshot (swap), then read
2653 the snapshot from this file in the same format as
2654 "trace" (described above in the section "The File
2655 System"). Both reads snapshot and tracing are executable
2656 in parallel. When the spare buffer is allocated, echoing
2657 0 frees it, and echoing else (positive) values clear the
2658 snapshot contents.
2659 More details are shown in the table below.
2660
2661 status\input | 0 | 1 | else |
2662 --------------+------------+------------+------------+
2663 not allocated |(do nothing)| alloc+swap |(do nothing)|
2664 --------------+------------+------------+------------+
2665 allocated | free | swap | clear |
2666 --------------+------------+------------+------------+
2667
2668Here is an example of using the snapshot feature.
2669
2670 # echo 1 > events/sched/enable
2671 # echo 1 > snapshot
2672 # cat snapshot
2673# tracer: nop
2674#
2675# entries-in-buffer/entries-written: 71/71 #P:8
2676#
2677# _-----=> irqs-off
2678# / _----=> need-resched
2679# | / _---=> hardirq/softirq
2680# || / _--=> preempt-depth
2681# ||| / delay
2682# TASK-PID CPU# |||| TIMESTAMP FUNCTION
2683# | | | |||| | |
2684 <idle>-0 [005] d... 2440.603828: sched_switch: prev_comm=swapper/5 prev_pid=0 prev_prio=120 prev_state=R ==> next_comm=snapshot-test-2 next_pid=2242 next_prio=120
2685 sleep-2242 [005] d... 2440.603846: sched_switch: prev_comm=snapshot-test-2 prev_pid=2242 prev_prio=120 prev_state=R ==> next_comm=kworker/5:1 next_pid=60 next_prio=120
2686[...]
2687 <idle>-0 [002] d... 2440.707230: sched_switch: prev_comm=swapper/2 prev_pid=0 prev_prio=120 prev_state=R ==> next_comm=snapshot-test-2 next_pid=2229 next_prio=120
2688
2689 # cat trace
2690# tracer: nop
2691#
2692# entries-in-buffer/entries-written: 77/77 #P:8
2693#
2694# _-----=> irqs-off
2695# / _----=> need-resched
2696# | / _---=> hardirq/softirq
2697# || / _--=> preempt-depth
2698# ||| / delay
2699# TASK-PID CPU# |||| TIMESTAMP FUNCTION
2700# | | | |||| | |
2701 <idle>-0 [007] d... 2440.707395: sched_switch: prev_comm=swapper/7 prev_pid=0 prev_prio=120 prev_state=R ==> next_comm=snapshot-test-2 next_pid=2243 next_prio=120
2702 snapshot-test-2-2229 [002] d... 2440.707438: sched_switch: prev_comm=snapshot-test-2 prev_pid=2229 prev_prio=120 prev_state=S ==> next_comm=swapper/2 next_pid=0 next_prio=120
2703[...]
2704
2705
2706If you try to use this snapshot feature when current tracer is
2707one of the latency tracers, you will get the following results.
2708
2709 # echo wakeup > current_tracer
2710 # echo 1 > snapshot
2711bash: echo: write error: Device or resource busy
2712 # cat snapshot
2713cat: snapshot: Device or resource busy
2714
2715
2716Instances
2717---------
2718In the debugfs tracing directory is a directory called "instances".
2719This directory can have new directories created inside of it using
2720mkdir, and removing directories with rmdir. The directory created
2721with mkdir in this directory will already contain files and other
2722directories after it is created.
2723
2724 # mkdir instances/foo
2725 # ls instances/foo
2726buffer_size_kb buffer_total_size_kb events free_buffer per_cpu
2727set_event snapshot trace trace_clock trace_marker trace_options
2728trace_pipe tracing_on
2729
2730As you can see, the new directory looks similar to the tracing directory
2731itself. In fact, it is very similar, except that the buffer and
2732events are agnostic from the main director, or from any other
2733instances that are created.
2734
2735The files in the new directory work just like the files with the
2736same name in the tracing directory except the buffer that is used
2737is a separate and new buffer. The files affect that buffer but do not
2738affect the main buffer with the exception of trace_options. Currently,
2739the trace_options affect all instances and the top level buffer
2740the same, but this may change in future releases. That is, options
2741may become specific to the instance they reside in.
2742
2743Notice that none of the function tracer files are there, nor is
2744current_tracer and available_tracers. This is because the buffers
2745can currently only have events enabled for them.
2746
2747 # mkdir instances/foo
2748 # mkdir instances/bar
2749 # mkdir instances/zoot
2750 # echo 100000 > buffer_size_kb
2751 # echo 1000 > instances/foo/buffer_size_kb
2752 # echo 5000 > instances/bar/per_cpu/cpu1/buffer_size_kb
2753 # echo function > current_trace
2754 # echo 1 > instances/foo/events/sched/sched_wakeup/enable
2755 # echo 1 > instances/foo/events/sched/sched_wakeup_new/enable
2756 # echo 1 > instances/foo/events/sched/sched_switch/enable
2757 # echo 1 > instances/bar/events/irq/enable
2758 # echo 1 > instances/zoot/events/syscalls/enable
2759 # cat trace_pipe
2760CPU:2 [LOST 11745 EVENTS]
2761 bash-2044 [002] .... 10594.481032: _raw_spin_lock_irqsave <-get_page_from_freelist
2762 bash-2044 [002] d... 10594.481032: add_preempt_count <-_raw_spin_lock_irqsave
2763 bash-2044 [002] d..1 10594.481032: __rmqueue <-get_page_from_freelist
2764 bash-2044 [002] d..1 10594.481033: _raw_spin_unlock <-get_page_from_freelist
2765 bash-2044 [002] d..1 10594.481033: sub_preempt_count <-_raw_spin_unlock
2766 bash-2044 [002] d... 10594.481033: get_pageblock_flags_group <-get_pageblock_migratetype
2767 bash-2044 [002] d... 10594.481034: __mod_zone_page_state <-get_page_from_freelist
2768 bash-2044 [002] d... 10594.481034: zone_statistics <-get_page_from_freelist
2769 bash-2044 [002] d... 10594.481034: __inc_zone_state <-zone_statistics
2770 bash-2044 [002] d... 10594.481034: __inc_zone_state <-zone_statistics
2771 bash-2044 [002] .... 10594.481035: arch_dup_task_struct <-copy_process
2772[...]
2773
2774 # cat instances/foo/trace_pipe
2775 bash-1998 [000] d..4 136.676759: sched_wakeup: comm=kworker/0:1 pid=59 prio=120 success=1 target_cpu=000
2776 bash-1998 [000] dN.4 136.676760: sched_wakeup: comm=bash pid=1998 prio=120 success=1 target_cpu=000
2777 <idle>-0 [003] d.h3 136.676906: sched_wakeup: comm=rcu_preempt pid=9 prio=120 success=1 target_cpu=003
2778 <idle>-0 [003] d..3 136.676909: sched_switch: prev_comm=swapper/3 prev_pid=0 prev_prio=120 prev_state=R ==> next_comm=rcu_preempt next_pid=9 next_prio=120
2779 rcu_preempt-9 [003] d..3 136.676916: sched_switch: prev_comm=rcu_preempt prev_pid=9 prev_prio=120 prev_state=S ==> next_comm=swapper/3 next_pid=0 next_prio=120
2780 bash-1998 [000] d..4 136.677014: sched_wakeup: comm=kworker/0:1 pid=59 prio=120 success=1 target_cpu=000
2781 bash-1998 [000] dN.4 136.677016: sched_wakeup: comm=bash pid=1998 prio=120 success=1 target_cpu=000
2782 bash-1998 [000] d..3 136.677018: sched_switch: prev_comm=bash prev_pid=1998 prev_prio=120 prev_state=R+ ==> next_comm=kworker/0:1 next_pid=59 next_prio=120
2783 kworker/0:1-59 [000] d..4 136.677022: sched_wakeup: comm=sshd pid=1995 prio=120 success=1 target_cpu=001
2784 kworker/0:1-59 [000] d..3 136.677025: sched_switch: prev_comm=kworker/0:1 prev_pid=59 prev_prio=120 prev_state=S ==> next_comm=bash next_pid=1998 next_prio=120
2785[...]
2786
2787 # cat instances/bar/trace_pipe
2788 migration/1-14 [001] d.h3 138.732674: softirq_raise: vec=3 [action=NET_RX]
2789 <idle>-0 [001] dNh3 138.732725: softirq_raise: vec=3 [action=NET_RX]
2790 bash-1998 [000] d.h1 138.733101: softirq_raise: vec=1 [action=TIMER]
2791 bash-1998 [000] d.h1 138.733102: softirq_raise: vec=9 [action=RCU]
2792 bash-1998 [000] ..s2 138.733105: softirq_entry: vec=1 [action=TIMER]
2793 bash-1998 [000] ..s2 138.733106: softirq_exit: vec=1 [action=TIMER]
2794 bash-1998 [000] ..s2 138.733106: softirq_entry: vec=9 [action=RCU]
2795 bash-1998 [000] ..s2 138.733109: softirq_exit: vec=9 [action=RCU]
2796 sshd-1995 [001] d.h1 138.733278: irq_handler_entry: irq=21 name=uhci_hcd:usb4
2797 sshd-1995 [001] d.h1 138.733280: irq_handler_exit: irq=21 ret=unhandled
2798 sshd-1995 [001] d.h1 138.733281: irq_handler_entry: irq=21 name=eth0
2799 sshd-1995 [001] d.h1 138.733283: irq_handler_exit: irq=21 ret=handled
2800[...]
2801
2802 # cat instances/zoot/trace
2803# tracer: nop
2804#
2805# entries-in-buffer/entries-written: 18996/18996 #P:4
2806#
2807# _-----=> irqs-off
2808# / _----=> need-resched
2809# | / _---=> hardirq/softirq
2810# || / _--=> preempt-depth
2811# ||| / delay
2812# TASK-PID CPU# |||| TIMESTAMP FUNCTION
2813# | | | |||| | |
2814 bash-1998 [000] d... 140.733501: sys_write -> 0x2
2815 bash-1998 [000] d... 140.733504: sys_dup2(oldfd: a, newfd: 1)
2816 bash-1998 [000] d... 140.733506: sys_dup2 -> 0x1
2817 bash-1998 [000] d... 140.733508: sys_fcntl(fd: a, cmd: 1, arg: 0)
2818 bash-1998 [000] d... 140.733509: sys_fcntl -> 0x1
2819 bash-1998 [000] d... 140.733510: sys_close(fd: a)
2820 bash-1998 [000] d... 140.733510: sys_close -> 0x0
2821 bash-1998 [000] d... 140.733514: sys_rt_sigprocmask(how: 0, nset: 0, oset: 6e2768, sigsetsize: 8)
2822 bash-1998 [000] d... 140.733515: sys_rt_sigprocmask -> 0x0
2823 bash-1998 [000] d... 140.733516: sys_rt_sigaction(sig: 2, act: 7fff718846f0, oact: 7fff71884650, sigsetsize: 8)
2824 bash-1998 [000] d... 140.733516: sys_rt_sigaction -> 0x0
2825
2826You can see that the trace of the top most trace buffer shows only
2827the function tracing. The foo instance displays wakeups and task
2828switches.
2829
2830To remove the instances, simply delete their directories:
2831
2832 # rmdir instances/foo
2833 # rmdir instances/bar
2834 # rmdir instances/zoot
2835
2836Note, if a process has a trace file open in one of the instance
2837directories, the rmdir will fail with EBUSY.
2838
2839
2840Stack trace
2841-----------
2842Since the kernel has a fixed sized stack, it is important not to
2843waste it in functions. A kernel developer must be conscience of
2844what they allocate on the stack. If they add too much, the system
2845can be in danger of a stack overflow, and corruption will occur,
2846usually leading to a system panic.
2847
2848There are some tools that check this, usually with interrupts
2849periodically checking usage. But if you can perform a check
2850at every function call that will become very useful. As ftrace provides
2851a function tracer, it makes it convenient to check the stack size
2852at every function call. This is enabled via the stack tracer.
2853
2854CONFIG_STACK_TRACER enables the ftrace stack tracing functionality.
2855To enable it, write a '1' into /proc/sys/kernel/stack_tracer_enabled.
2856
2857 # echo 1 > /proc/sys/kernel/stack_tracer_enabled
2858
2859You can also enable it from the kernel command line to trace
2860the stack size of the kernel during boot up, by adding "stacktrace"
2861to the kernel command line parameter.
2862
2863After running it for a few minutes, the output looks like:
2864
2865 # cat stack_max_size
28662928
2867
2868 # cat stack_trace
2869 Depth Size Location (18 entries)
2870 ----- ---- --------
2871 0) 2928 224 update_sd_lb_stats+0xbc/0x4ac
2872 1) 2704 160 find_busiest_group+0x31/0x1f1
2873 2) 2544 256 load_balance+0xd9/0x662
2874 3) 2288 80 idle_balance+0xbb/0x130
2875 4) 2208 128 __schedule+0x26e/0x5b9
2876 5) 2080 16 schedule+0x64/0x66
2877 6) 2064 128 schedule_timeout+0x34/0xe0
2878 7) 1936 112 wait_for_common+0x97/0xf1
2879 8) 1824 16 wait_for_completion+0x1d/0x1f
2880 9) 1808 128 flush_work+0xfe/0x119
2881 10) 1680 16 tty_flush_to_ldisc+0x1e/0x20
2882 11) 1664 48 input_available_p+0x1d/0x5c
2883 12) 1616 48 n_tty_poll+0x6d/0x134
2884 13) 1568 64 tty_poll+0x64/0x7f
2885 14) 1504 880 do_select+0x31e/0x511
2886 15) 624 400 core_sys_select+0x177/0x216
2887 16) 224 96 sys_select+0x91/0xb9
2888 17) 128 128 system_call_fastpath+0x16/0x1b
2889
2890Note, if -mfentry is being used by gcc, functions get traced before
2891they set up the stack frame. This means that leaf level functions
2892are not tested by the stack tracer when -mfentry is used.
2893
2894Currently, -mfentry is used by gcc 4.6.0 and above on x86 only.
2895
2896---------
2897
2898More details can be found in the source code, in the
2899kernel/trace/*.c files.