x86, delay: tsc based udelay should have rdtsc_barrier
[linux-2.6/mini2440.git] / Documentation / trace / ftrace.txt
bloba39b3c749de58c12129d80d0ffad738f9a7836f0
1                 ftrace - Function Tracer
2                 ========================
4 Copyright 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)
8 Reviewers:   Elias Oltmanns, Randy Dunlap, Andrew Morton,
9              John Kacur, and David Teigland.
10 Written for: 2.6.28-rc2
12 Introduction
13 ------------
15 Ftrace is an internal tracer designed to help out developers and
16 designers of systems to find what is going on inside the kernel.
17 It can be used for debugging or analyzing latencies and
18 performance issues that take place outside of user-space.
20 Although ftrace is the function tracer, it also includes an
21 infrastructure that allows for other types of tracing. Some of
22 the tracers that are currently in ftrace include a tracer to
23 trace context switches, the time it takes for a high priority
24 task to run after it was woken up, the time interrupts are
25 disabled, and more (ftrace allows for tracer plugins, which
26 means that the list of tracers can always grow).
29 The File System
30 ---------------
32 Ftrace uses the debugfs file system to hold the control files as
33 well as the files to display output.
35 When debugfs is configured into the kernel (which selecting any ftrace
36 option will do) the directory /sys/kernel/debug will be created. To mount
37 this directory, you can add to your /etc/fstab file:
39  debugfs       /sys/kernel/debug          debugfs defaults        0       0
41 Or you can mount it at run time with:
43  mount -t debugfs nodev /sys/kernel/debug
45 For quicker access to that directory you may want to make a soft link to
46 it:
48  ln -s /sys/kernel/debug /debug
50 Any selected ftrace option will also create a directory called tracing
51 within the debugfs. The rest of the document will assume that you are in
52 the ftrace directory (cd /sys/kernel/debug/tracing) and will only concentrate
53 on the files within that directory and not distract from the content with
54 the extended "/sys/kernel/debug/tracing" path name.
56 That's it! (assuming that you have ftrace configured into your kernel)
58 After mounting the debugfs, you can see a directory called
59 "tracing".  This directory contains the control and output files
60 of ftrace. Here is a list of some of the key files:
63  Note: all time values are in microseconds.
65   current_tracer:
67         This is used to set or display the current tracer
68         that is configured.
70   available_tracers:
72         This holds the different types of tracers that
73         have been compiled into the kernel. The
74         tracers listed here can be configured by
75         echoing their name into current_tracer.
77   tracing_enabled:
79         This sets or displays whether the current_tracer
80         is activated and tracing or not. Echo 0 into this
81         file to disable the tracer or 1 to enable it.
83   trace:
85         This file holds the output of the trace in a human
86         readable format (described below).
88   latency_trace:
90         This file shows the same trace but the information
91         is organized more to display possible latencies
92         in the system (described below).
94   trace_pipe:
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
99         is retrieved. Unlike the "trace" and "latency_trace"
100         files, this file is a consumer. This means reading
101         from this file causes sequential reads to display
102         more current data. Once data is read from this
103         file, it is consumed, and will not be read
104         again with a sequential read. The "trace" and
105         "latency_trace" files are static, and if the
106         tracer is not adding more data, they will display
107         the same information every time they are read.
109   trace_options:
111         This file lets the user control the amount of data
112         that is displayed in one of the above output
113         files.
115   tracing_max_latency:
117         Some of the tracers record the max latency.
118         For example, the time interrupts are disabled.
119         This time is saved in this file. The max trace
120         will also be stored, and displayed by either
121         "trace" or "latency_trace".  A new max trace will
122         only be recorded if the latency is greater than
123         the value in this file. (in microseconds)
125   buffer_size_kb:
127         This sets or displays the number of kilobytes each CPU
128         buffer can hold. The tracer buffers are the same size
129         for each CPU. The displayed number is the size of the
130         CPU buffer and not total size of all buffers. The
131         trace buffers are allocated in pages (blocks of memory
132         that the kernel uses for allocation, usually 4 KB in size).
133         If the last page allocated has room for more bytes
134         than requested, the rest of the page will be used,
135         making the actual allocation bigger than requested.
136         ( Note, the size may not be a multiple of the page size
137           due to buffer managment overhead. )
139         This can only be updated when the current_tracer
140         is set to "nop".
142   tracing_cpumask:
144         This is a mask that lets the user only trace
145         on specified CPUS. The format is a hex string
146         representing the CPUS.
148   set_ftrace_filter:
150         When dynamic ftrace is configured in (see the
151         section below "dynamic ftrace"), the code is dynamically
152         modified (code text rewrite) to disable calling of the
153         function profiler (mcount). This lets tracing be configured
154         in with practically no overhead in performance.  This also
155         has a side effect of enabling or disabling specific functions
156         to be traced. Echoing names of functions into this file
157         will limit the trace to only those functions.
159   set_ftrace_notrace:
161         This has an effect opposite to that of
162         set_ftrace_filter. Any function that is added here will not
163         be traced. If a function exists in both set_ftrace_filter
164         and set_ftrace_notrace, the function will _not_ be traced.
166   set_ftrace_pid:
168         Have the function tracer only trace a single thread.
170   set_graph_function:
172         Set a "trigger" function where tracing should start
173         with the function graph tracer (See the section
174         "dynamic ftrace" for more details).
176   available_filter_functions:
178         This lists the functions that ftrace
179         has processed and can trace. These are the function
180         names that you can pass to "set_ftrace_filter" or
181         "set_ftrace_notrace". (See the section "dynamic ftrace"
182         below for more details.)
185 The Tracers
186 -----------
188 Here is the list of current tracers that may be configured.
190   "function"
192         Function call tracer to trace all kernel functions.
194   "function_graph"
196         Similar to the function tracer except that the
197         function tracer probes the functions on their entry
198         whereas the function graph tracer traces on both entry
199         and exit of the functions. It then provides the ability
200         to draw a graph of function calls similar to C code
201         source.
203   "sched_switch"
205         Traces the context switches and wakeups between tasks.
207   "irqsoff"
209         Traces the areas that disable interrupts and saves
210         the trace with the longest max latency.
211         See tracing_max_latency. When a new max is recorded,
212         it replaces the old trace. It is best to view this
213         trace via the latency_trace file.
215   "preemptoff"
217         Similar to irqsoff but traces and records the amount of
218         time for which preemption is disabled.
220   "preemptirqsoff"
222         Similar to irqsoff and preemptoff, but traces and
223         records the largest time for which irqs and/or preemption
224         is disabled.
226   "wakeup"
228         Traces and records the max latency that it takes for
229         the highest priority task to get scheduled after
230         it has been woken up.
232   "hw-branch-tracer"
234         Uses the BTS CPU feature on x86 CPUs to traces all
235         branches executed.
237   "nop"
239         This is the "trace nothing" tracer. To remove all
240         tracers from tracing simply echo "nop" into
241         current_tracer.
244 Examples of using the tracer
245 ----------------------------
247 Here are typical examples of using the tracers when controlling
248 them only with the debugfs interface (without using any
249 user-land utilities).
251 Output format:
252 --------------
254 Here is an example of the output format of the file "trace"
256                              --------
257 # tracer: function
259 #           TASK-PID   CPU#    TIMESTAMP  FUNCTION
260 #              | |      |          |         |
261             bash-4251  [01] 10152.583854: path_put <-path_walk
262             bash-4251  [01] 10152.583855: dput <-path_put
263             bash-4251  [01] 10152.583855: _atomic_dec_and_lock <-dput
264                              --------
266 A header is printed with the tracer name that is represented by
267 the trace. In this case the tracer is "function". Then a header
268 showing the format. Task name "bash", the task PID "4251", the
269 CPU that it was running on "01", the timestamp in <secs>.<usecs>
270 format, the function name that was traced "path_put" and the
271 parent function that called this function "path_walk". The
272 timestamp is the time at which the function was entered.
274 The sched_switch tracer also includes tracing of task wakeups
275 and context switches.
277      ksoftirqd/1-7     [01]  1453.070013:      7:115:R   +  2916:115:S
278      ksoftirqd/1-7     [01]  1453.070013:      7:115:R   +    10:115:S
279      ksoftirqd/1-7     [01]  1453.070013:      7:115:R ==>    10:115:R
280         events/1-10    [01]  1453.070013:     10:115:S ==>  2916:115:R
281      kondemand/1-2916  [01]  1453.070013:   2916:115:S ==>     7:115:R
282      ksoftirqd/1-7     [01]  1453.070013:      7:115:S ==>     0:140:R
284 Wake ups are represented by a "+" and the context switches are
285 shown as "==>".  The format is:
287  Context switches:
289        Previous task              Next Task
291   <pid>:<prio>:<state>  ==>  <pid>:<prio>:<state>
293  Wake ups:
295        Current task               Task waking up
297   <pid>:<prio>:<state>    +  <pid>:<prio>:<state>
299 The prio is the internal kernel priority, which is the inverse
300 of the priority that is usually displayed by user-space tools.
301 Zero represents the highest priority (99). Prio 100 starts the
302 "nice" priorities with 100 being equal to nice -20 and 139 being
303 nice 19. The prio "140" is reserved for the idle task which is
304 the lowest priority thread (pid 0).
307 Latency trace format
308 --------------------
310 For traces that display latency times, the latency_trace file
311 gives somewhat more information to see why a latency happened.
312 Here is a typical trace.
314 # tracer: irqsoff
316 irqsoff latency trace v1.1.5 on 2.6.26-rc8
317 --------------------------------------------------------------------
318  latency: 97 us, #3/3, CPU#0 | (M:preempt VP:0, KP:0, SP:0 HP:0 #P:2)
319     -----------------
320     | task: swapper-0 (uid:0 nice:0 policy:0 rt_prio:0)
321     -----------------
322  => started at: apic_timer_interrupt
323  => ended at:   do_softirq
325 #                _------=> CPU#
326 #               / _-----=> irqs-off
327 #              | / _----=> need-resched
328 #              || / _---=> hardirq/softirq
329 #              ||| / _--=> preempt-depth
330 #              |||| /
331 #              |||||     delay
332 #  cmd     pid ||||| time  |   caller
333 #     \   /    |||||   \   |   /
334   <idle>-0     0d..1    0us+: trace_hardirqs_off_thunk (apic_timer_interrupt)
335   <idle>-0     0d.s.   97us : __do_softirq (do_softirq)
336   <idle>-0     0d.s1   98us : trace_hardirqs_on (do_softirq)
339 This shows that the current tracer is "irqsoff" tracing the time
340 for which interrupts were disabled. It gives the trace version
341 and the version of the kernel upon which this was executed on
342 (2.6.26-rc8). Then it displays the max latency in microsecs (97
343 us). The number of trace entries displayed and the total number
344 recorded (both are three: #3/3). The type of preemption that was
345 used (PREEMPT). VP, KP, SP, and HP are always zero and are
346 reserved for later use. #P is the number of online CPUS (#P:2).
348 The task is the process that was running when the latency
349 occurred. (swapper pid: 0).
351 The start and stop (the functions in which the interrupts were
352 disabled and enabled respectively) that caused the latencies:
354   apic_timer_interrupt is where the interrupts were disabled.
355   do_softirq is where they were enabled again.
357 The next lines after the header are the trace itself. The header
358 explains which is which.
360   cmd: The name of the process in the trace.
362   pid: The PID of that process.
364   CPU#: The CPU which the process was running on.
366   irqs-off: 'd' interrupts are disabled. '.' otherwise.
367             Note: If the architecture does not support a way to
368                   read the irq flags variable, an 'X' will always
369                   be printed here.
371   need-resched: 'N' task need_resched is set, '.' otherwise.
373   hardirq/softirq:
374         'H' - hard irq occurred inside a softirq.
375         'h' - hard irq is running
376         's' - soft irq is running
377         '.' - normal context.
379   preempt-depth: The level of preempt_disabled
381 The above is mostly meaningful for kernel developers.
383   time: This differs from the trace file output. The trace file output
384         includes an absolute timestamp. The timestamp used by the
385         latency_trace file is relative to the start of the trace.
387   delay: This is just to help catch your eye a bit better. And
388          needs to be fixed to be only relative to the same CPU.
389          The marks are determined by the difference between this
390          current trace and the next trace.
391           '!' - greater than preempt_mark_thresh (default 100)
392           '+' - greater than 1 microsecond
393           ' ' - less than or equal to 1 microsecond.
395   The rest is the same as the 'trace' file.
398 trace_options
399 -------------
401 The trace_options file is used to control what gets printed in
402 the trace output. To see what is available, simply cat the file:
404   cat trace_options
405   print-parent nosym-offset nosym-addr noverbose noraw nohex nobin \
406   noblock nostacktrace nosched-tree nouserstacktrace nosym-userobj
408 To disable one of the options, echo in the option prepended with
409 "no".
411   echo noprint-parent > trace_options
413 To enable an option, leave off the "no".
415   echo sym-offset > trace_options
417 Here are the available options:
419   print-parent - On function traces, display the calling (parent)
420                  function as well as the function being traced.
422   print-parent:
423    bash-4000  [01]  1477.606694: simple_strtoul <-strict_strtoul
425   noprint-parent:
426    bash-4000  [01]  1477.606694: simple_strtoul
429   sym-offset - Display not only the function name, but also the
430                offset in the function. For example, instead of
431                seeing just "ktime_get", you will see
432                "ktime_get+0xb/0x20".
434   sym-offset:
435    bash-4000  [01]  1477.606694: simple_strtoul+0x6/0xa0
437   sym-addr - this will also display the function address as well
438              as the function name.
440   sym-addr:
441    bash-4000  [01]  1477.606694: simple_strtoul <c0339346>
443   verbose - This deals with the latency_trace file.
445     bash  4000 1 0 00000000 00010a95 [58127d26] 1720.415ms \
446     (+0.000ms): simple_strtoul (strict_strtoul)
448   raw - This will display raw numbers. This option is best for
449         use with user applications that can translate the raw
450         numbers better than having it done in the kernel.
452   hex - Similar to raw, but the numbers will be in a hexadecimal
453         format.
455   bin - This will print out the formats in raw binary.
457   block - TBD (needs update)
459   stacktrace - This is one of the options that changes the trace
460                itself. When a trace is recorded, so is the stack
461                of functions. This allows for back traces of
462                trace sites.
464   userstacktrace - This option changes the trace. It records a
465                    stacktrace of the current userspace thread.
467   sym-userobj - when user stacktrace are enabled, look up which
468                 object the address belongs to, and print a
469                 relative address. This is especially useful when
470                 ASLR is on, otherwise you don't get a chance to
471                 resolve the address to object/file/line after
472                 the app is no longer running
474                 The lookup is performed when you read
475                 trace,trace_pipe,latency_trace. Example:
477                 a.out-1623  [000] 40874.465068: /root/a.out[+0x480] <-/root/a.out[+0
478 x494] <- /root/a.out[+0x4a8] <- /lib/libc-2.7.so[+0x1e1a6]
480   sched-tree - trace all tasks that are on the runqueue, at
481                every scheduling event. Will add overhead if
482                there's a lot of tasks running at once.
485 sched_switch
486 ------------
488 This tracer simply records schedule switches. Here is an example
489 of how to use it.
491  # echo sched_switch > current_tracer
492  # echo 1 > tracing_enabled
493  # sleep 1
494  # echo 0 > tracing_enabled
495  # cat trace
497 # tracer: sched_switch
499 #           TASK-PID   CPU#    TIMESTAMP  FUNCTION
500 #              | |      |          |         |
501             bash-3997  [01]   240.132281:   3997:120:R   +  4055:120:R
502             bash-3997  [01]   240.132284:   3997:120:R ==>  4055:120:R
503            sleep-4055  [01]   240.132371:   4055:120:S ==>  3997:120:R
504             bash-3997  [01]   240.132454:   3997:120:R   +  4055:120:S
505             bash-3997  [01]   240.132457:   3997:120:R ==>  4055:120:R
506            sleep-4055  [01]   240.132460:   4055:120:D ==>  3997:120:R
507             bash-3997  [01]   240.132463:   3997:120:R   +  4055:120:D
508             bash-3997  [01]   240.132465:   3997:120:R ==>  4055:120:R
509           <idle>-0     [00]   240.132589:      0:140:R   +     4:115:S
510           <idle>-0     [00]   240.132591:      0:140:R ==>     4:115:R
511      ksoftirqd/0-4     [00]   240.132595:      4:115:S ==>     0:140:R
512           <idle>-0     [00]   240.132598:      0:140:R   +     4:115:S
513           <idle>-0     [00]   240.132599:      0:140:R ==>     4:115:R
514      ksoftirqd/0-4     [00]   240.132603:      4:115:S ==>     0:140:R
515            sleep-4055  [01]   240.133058:   4055:120:S ==>  3997:120:R
516  [...]
519 As we have discussed previously about this format, the header
520 shows the name of the trace and points to the options. The
521 "FUNCTION" is a misnomer since here it represents the wake ups
522 and context switches.
524 The sched_switch file only lists the wake ups (represented with
525 '+') and context switches ('==>') with the previous task or
526 current task first followed by the next task or task waking up.
527 The format for both of these is PID:KERNEL-PRIO:TASK-STATE.
528 Remember that the KERNEL-PRIO is the inverse of the actual
529 priority with zero (0) being the highest priority and the nice
530 values starting at 100 (nice -20). Below is a quick chart to map
531 the kernel priority to user land priorities.
533    Kernel Space                     User Space
534  ===============================================================
535    0(high) to  98(low)     user RT priority 99(high) to 1(low)
536                            with SCHED_RR or SCHED_FIFO
537  ---------------------------------------------------------------
538   99                       sched_priority is not used in scheduling
539                            decisions(it must be specified as 0)
540  ---------------------------------------------------------------
541  100(high) to 139(low)     user nice -20(high) to 19(low)
542  ---------------------------------------------------------------
543  140                       idle task priority
544  ---------------------------------------------------------------
546 The task states are:
548  R - running : wants to run, may not actually be running
549  S - sleep   : process is waiting to be woken up (handles signals)
550  D - disk sleep (uninterruptible sleep) : process must be woken up
551                                         (ignores signals)
552  T - stopped : process suspended
553  t - traced  : process is being traced (with something like gdb)
554  Z - zombie  : process waiting to be cleaned up
555  X - unknown
558 ftrace_enabled
559 --------------
561 The following tracers (listed below) give different output
562 depending on whether or not the sysctl ftrace_enabled is set. To
563 set ftrace_enabled, one can either use the sysctl function or
564 set it via the proc file system interface.
566   sysctl kernel.ftrace_enabled=1
568  or
570   echo 1 > /proc/sys/kernel/ftrace_enabled
572 To disable ftrace_enabled simply replace the '1' with '0' in the
573 above commands.
575 When ftrace_enabled is set the tracers will also record the
576 functions that are within the trace. The descriptions of the
577 tracers will also show an example with ftrace enabled.
580 irqsoff
581 -------
583 When interrupts are disabled, the CPU can not react to any other
584 external event (besides NMIs and SMIs). This prevents the timer
585 interrupt from triggering or the mouse interrupt from letting
586 the kernel know of a new mouse event. The result is a latency
587 with the reaction time.
589 The irqsoff tracer tracks the time for which interrupts are
590 disabled. When a new maximum latency is hit, the tracer saves
591 the trace leading up to that latency point so that every time a
592 new maximum is reached, the old saved trace is discarded and the
593 new trace is saved.
595 To reset the maximum, echo 0 into tracing_max_latency. Here is
596 an example:
598  # echo irqsoff > current_tracer
599  # echo 0 > tracing_max_latency
600  # echo 1 > tracing_enabled
601  # ls -ltr
602  [...]
603  # echo 0 > tracing_enabled
604  # cat latency_trace
605 # tracer: irqsoff
607 irqsoff latency trace v1.1.5 on 2.6.26
608 --------------------------------------------------------------------
609  latency: 12 us, #3/3, CPU#1 | (M:preempt VP:0, KP:0, SP:0 HP:0 #P:2)
610     -----------------
611     | task: bash-3730 (uid:0 nice:0 policy:0 rt_prio:0)
612     -----------------
613  => started at: sys_setpgid
614  => ended at:   sys_setpgid
616 #                _------=> CPU#
617 #               / _-----=> irqs-off
618 #              | / _----=> need-resched
619 #              || / _---=> hardirq/softirq
620 #              ||| / _--=> preempt-depth
621 #              |||| /
622 #              |||||     delay
623 #  cmd     pid ||||| time  |   caller
624 #     \   /    |||||   \   |   /
625     bash-3730  1d...    0us : _write_lock_irq (sys_setpgid)
626     bash-3730  1d..1    1us+: _write_unlock_irq (sys_setpgid)
627     bash-3730  1d..2   14us : trace_hardirqs_on (sys_setpgid)
630 Here we see that that we had a latency of 12 microsecs (which is
631 very good). The _write_lock_irq in sys_setpgid disabled
632 interrupts. The difference between the 12 and the displayed
633 timestamp 14us occurred because the clock was incremented
634 between the time of recording the max latency and the time of
635 recording the function that had that latency.
637 Note the above example had ftrace_enabled not set. If we set the
638 ftrace_enabled, we get a much larger output:
640 # tracer: irqsoff
642 irqsoff latency trace v1.1.5 on 2.6.26-rc8
643 --------------------------------------------------------------------
644  latency: 50 us, #101/101, CPU#0 | (M:preempt VP:0, KP:0, SP:0 HP:0 #P:2)
645     -----------------
646     | task: ls-4339 (uid:0 nice:0 policy:0 rt_prio:0)
647     -----------------
648  => started at: __alloc_pages_internal
649  => ended at:   __alloc_pages_internal
651 #                _------=> CPU#
652 #               / _-----=> irqs-off
653 #              | / _----=> need-resched
654 #              || / _---=> hardirq/softirq
655 #              ||| / _--=> preempt-depth
656 #              |||| /
657 #              |||||     delay
658 #  cmd     pid ||||| time  |   caller
659 #     \   /    |||||   \   |   /
660       ls-4339  0...1    0us+: get_page_from_freelist (__alloc_pages_internal)
661       ls-4339  0d..1    3us : rmqueue_bulk (get_page_from_freelist)
662       ls-4339  0d..1    3us : _spin_lock (rmqueue_bulk)
663       ls-4339  0d..1    4us : add_preempt_count (_spin_lock)
664       ls-4339  0d..2    4us : __rmqueue (rmqueue_bulk)
665       ls-4339  0d..2    5us : __rmqueue_smallest (__rmqueue)
666       ls-4339  0d..2    5us : __mod_zone_page_state (__rmqueue_smallest)
667       ls-4339  0d..2    6us : __rmqueue (rmqueue_bulk)
668       ls-4339  0d..2    6us : __rmqueue_smallest (__rmqueue)
669       ls-4339  0d..2    7us : __mod_zone_page_state (__rmqueue_smallest)
670       ls-4339  0d..2    7us : __rmqueue (rmqueue_bulk)
671       ls-4339  0d..2    8us : __rmqueue_smallest (__rmqueue)
672 [...]
673       ls-4339  0d..2   46us : __rmqueue_smallest (__rmqueue)
674       ls-4339  0d..2   47us : __mod_zone_page_state (__rmqueue_smallest)
675       ls-4339  0d..2   47us : __rmqueue (rmqueue_bulk)
676       ls-4339  0d..2   48us : __rmqueue_smallest (__rmqueue)
677       ls-4339  0d..2   48us : __mod_zone_page_state (__rmqueue_smallest)
678       ls-4339  0d..2   49us : _spin_unlock (rmqueue_bulk)
679       ls-4339  0d..2   49us : sub_preempt_count (_spin_unlock)
680       ls-4339  0d..1   50us : get_page_from_freelist (__alloc_pages_internal)
681       ls-4339  0d..2   51us : trace_hardirqs_on (__alloc_pages_internal)
685 Here we traced a 50 microsecond latency. But we also see all the
686 functions that were called during that time. Note that by
687 enabling function tracing, we incur an added overhead. This
688 overhead may extend the latency times. But nevertheless, this
689 trace has provided some very helpful debugging information.
692 preemptoff
693 ----------
695 When preemption is disabled, we may be able to receive
696 interrupts but the task cannot be preempted and a higher
697 priority task must wait for preemption to be enabled again
698 before it can preempt a lower priority task.
700 The preemptoff tracer traces the places that disable preemption.
701 Like the irqsoff tracer, it records the maximum latency for
702 which preemption was disabled. The control of preemptoff tracer
703 is much like the irqsoff tracer.
705  # echo preemptoff > current_tracer
706  # echo 0 > tracing_max_latency
707  # echo 1 > tracing_enabled
708  # ls -ltr
709  [...]
710  # echo 0 > tracing_enabled
711  # cat latency_trace
712 # tracer: preemptoff
714 preemptoff latency trace v1.1.5 on 2.6.26-rc8
715 --------------------------------------------------------------------
716  latency: 29 us, #3/3, CPU#0 | (M:preempt VP:0, KP:0, SP:0 HP:0 #P:2)
717     -----------------
718     | task: sshd-4261 (uid:0 nice:0 policy:0 rt_prio:0)
719     -----------------
720  => started at: do_IRQ
721  => ended at:   __do_softirq
723 #                _------=> CPU#
724 #               / _-----=> irqs-off
725 #              | / _----=> need-resched
726 #              || / _---=> hardirq/softirq
727 #              ||| / _--=> preempt-depth
728 #              |||| /
729 #              |||||     delay
730 #  cmd     pid ||||| time  |   caller
731 #     \   /    |||||   \   |   /
732     sshd-4261  0d.h.    0us+: irq_enter (do_IRQ)
733     sshd-4261  0d.s.   29us : _local_bh_enable (__do_softirq)
734     sshd-4261  0d.s1   30us : trace_preempt_on (__do_softirq)
737 This has some more changes. Preemption was disabled when an
738 interrupt came in (notice the 'h'), and was enabled while doing
739 a softirq. (notice the 's'). But we also see that interrupts
740 have been disabled when entering the preempt off section and
741 leaving it (the 'd'). We do not know if interrupts were enabled
742 in the mean time.
744 # tracer: preemptoff
746 preemptoff latency trace v1.1.5 on 2.6.26-rc8
747 --------------------------------------------------------------------
748  latency: 63 us, #87/87, CPU#0 | (M:preempt VP:0, KP:0, SP:0 HP:0 #P:2)
749     -----------------
750     | task: sshd-4261 (uid:0 nice:0 policy:0 rt_prio:0)
751     -----------------
752  => started at: remove_wait_queue
753  => ended at:   __do_softirq
755 #                _------=> CPU#
756 #               / _-----=> irqs-off
757 #              | / _----=> need-resched
758 #              || / _---=> hardirq/softirq
759 #              ||| / _--=> preempt-depth
760 #              |||| /
761 #              |||||     delay
762 #  cmd     pid ||||| time  |   caller
763 #     \   /    |||||   \   |   /
764     sshd-4261  0d..1    0us : _spin_lock_irqsave (remove_wait_queue)
765     sshd-4261  0d..1    1us : _spin_unlock_irqrestore (remove_wait_queue)
766     sshd-4261  0d..1    2us : do_IRQ (common_interrupt)
767     sshd-4261  0d..1    2us : irq_enter (do_IRQ)
768     sshd-4261  0d..1    2us : idle_cpu (irq_enter)
769     sshd-4261  0d..1    3us : add_preempt_count (irq_enter)
770     sshd-4261  0d.h1    3us : idle_cpu (irq_enter)
771     sshd-4261  0d.h.    4us : handle_fasteoi_irq (do_IRQ)
772 [...]
773     sshd-4261  0d.h.   12us : add_preempt_count (_spin_lock)
774     sshd-4261  0d.h1   12us : ack_ioapic_quirk_irq (handle_fasteoi_irq)
775     sshd-4261  0d.h1   13us : move_native_irq (ack_ioapic_quirk_irq)
776     sshd-4261  0d.h1   13us : _spin_unlock (handle_fasteoi_irq)
777     sshd-4261  0d.h1   14us : sub_preempt_count (_spin_unlock)
778     sshd-4261  0d.h1   14us : irq_exit (do_IRQ)
779     sshd-4261  0d.h1   15us : sub_preempt_count (irq_exit)
780     sshd-4261  0d..2   15us : do_softirq (irq_exit)
781     sshd-4261  0d...   15us : __do_softirq (do_softirq)
782     sshd-4261  0d...   16us : __local_bh_disable (__do_softirq)
783     sshd-4261  0d...   16us+: add_preempt_count (__local_bh_disable)
784     sshd-4261  0d.s4   20us : add_preempt_count (__local_bh_disable)
785     sshd-4261  0d.s4   21us : sub_preempt_count (local_bh_enable)
786     sshd-4261  0d.s5   21us : sub_preempt_count (local_bh_enable)
787 [...]
788     sshd-4261  0d.s6   41us : add_preempt_count (__local_bh_disable)
789     sshd-4261  0d.s6   42us : sub_preempt_count (local_bh_enable)
790     sshd-4261  0d.s7   42us : sub_preempt_count (local_bh_enable)
791     sshd-4261  0d.s5   43us : add_preempt_count (__local_bh_disable)
792     sshd-4261  0d.s5   43us : sub_preempt_count (local_bh_enable_ip)
793     sshd-4261  0d.s6   44us : sub_preempt_count (local_bh_enable_ip)
794     sshd-4261  0d.s5   44us : add_preempt_count (__local_bh_disable)
795     sshd-4261  0d.s5   45us : sub_preempt_count (local_bh_enable)
796 [...]
797     sshd-4261  0d.s.   63us : _local_bh_enable (__do_softirq)
798     sshd-4261  0d.s1   64us : trace_preempt_on (__do_softirq)
801 The above is an example of the preemptoff trace with
802 ftrace_enabled set. Here we see that interrupts were disabled
803 the entire time. The irq_enter code lets us know that we entered
804 an interrupt 'h'. Before that, the functions being traced still
805 show that it is not in an interrupt, but we can see from the
806 functions themselves that this is not the case.
808 Notice that __do_softirq when called does not have a
809 preempt_count. It may seem that we missed a preempt enabling.
810 What really happened is that the preempt count is held on the
811 thread's stack and we switched to the softirq stack (4K stacks
812 in effect). The code does not copy the preempt count, but
813 because interrupts are disabled, we do not need to worry about
814 it. Having a tracer like this is good for letting people know
815 what really happens inside the kernel.
818 preemptirqsoff
819 --------------
821 Knowing the locations that have interrupts disabled or
822 preemption disabled for the longest times is helpful. But
823 sometimes we would like to know when either preemption and/or
824 interrupts are disabled.
826 Consider the following code:
828     local_irq_disable();
829     call_function_with_irqs_off();
830     preempt_disable();
831     call_function_with_irqs_and_preemption_off();
832     local_irq_enable();
833     call_function_with_preemption_off();
834     preempt_enable();
836 The irqsoff tracer will record the total length of
837 call_function_with_irqs_off() and
838 call_function_with_irqs_and_preemption_off().
840 The preemptoff tracer will record the total length of
841 call_function_with_irqs_and_preemption_off() and
842 call_function_with_preemption_off().
844 But neither will trace the time that interrupts and/or
845 preemption is disabled. This total time is the time that we can
846 not schedule. To record this time, use the preemptirqsoff
847 tracer.
849 Again, using this trace is much like the irqsoff and preemptoff
850 tracers.
852  # echo preemptirqsoff > current_tracer
853  # echo 0 > tracing_max_latency
854  # echo 1 > tracing_enabled
855  # ls -ltr
856  [...]
857  # echo 0 > tracing_enabled
858  # cat latency_trace
859 # tracer: preemptirqsoff
861 preemptirqsoff latency trace v1.1.5 on 2.6.26-rc8
862 --------------------------------------------------------------------
863  latency: 293 us, #3/3, CPU#0 | (M:preempt VP:0, KP:0, SP:0 HP:0 #P:2)
864     -----------------
865     | task: ls-4860 (uid:0 nice:0 policy:0 rt_prio:0)
866     -----------------
867  => started at: apic_timer_interrupt
868  => ended at:   __do_softirq
870 #                _------=> CPU#
871 #               / _-----=> irqs-off
872 #              | / _----=> need-resched
873 #              || / _---=> hardirq/softirq
874 #              ||| / _--=> preempt-depth
875 #              |||| /
876 #              |||||     delay
877 #  cmd     pid ||||| time  |   caller
878 #     \   /    |||||   \   |   /
879       ls-4860  0d...    0us!: trace_hardirqs_off_thunk (apic_timer_interrupt)
880       ls-4860  0d.s.  294us : _local_bh_enable (__do_softirq)
881       ls-4860  0d.s1  294us : trace_preempt_on (__do_softirq)
885 The trace_hardirqs_off_thunk is called from assembly on x86 when
886 interrupts are disabled in the assembly code. Without the
887 function tracing, we do not know if interrupts were enabled
888 within the preemption points. We do see that it started with
889 preemption enabled.
891 Here is a trace with ftrace_enabled set:
894 # tracer: preemptirqsoff
896 preemptirqsoff latency trace v1.1.5 on 2.6.26-rc8
897 --------------------------------------------------------------------
898  latency: 105 us, #183/183, CPU#0 | (M:preempt VP:0, KP:0, SP:0 HP:0 #P:2)
899     -----------------
900     | task: sshd-4261 (uid:0 nice:0 policy:0 rt_prio:0)
901     -----------------
902  => started at: write_chan
903  => ended at:   __do_softirq
905 #                _------=> CPU#
906 #               / _-----=> irqs-off
907 #              | / _----=> need-resched
908 #              || / _---=> hardirq/softirq
909 #              ||| / _--=> preempt-depth
910 #              |||| /
911 #              |||||     delay
912 #  cmd     pid ||||| time  |   caller
913 #     \   /    |||||   \   |   /
914       ls-4473  0.N..    0us : preempt_schedule (write_chan)
915       ls-4473  0dN.1    1us : _spin_lock (schedule)
916       ls-4473  0dN.1    2us : add_preempt_count (_spin_lock)
917       ls-4473  0d..2    2us : put_prev_task_fair (schedule)
918 [...]
919       ls-4473  0d..2   13us : set_normalized_timespec (ktime_get_ts)
920       ls-4473  0d..2   13us : __switch_to (schedule)
921     sshd-4261  0d..2   14us : finish_task_switch (schedule)
922     sshd-4261  0d..2   14us : _spin_unlock_irq (finish_task_switch)
923     sshd-4261  0d..1   15us : add_preempt_count (_spin_lock_irqsave)
924     sshd-4261  0d..2   16us : _spin_unlock_irqrestore (hrtick_set)
925     sshd-4261  0d..2   16us : do_IRQ (common_interrupt)
926     sshd-4261  0d..2   17us : irq_enter (do_IRQ)
927     sshd-4261  0d..2   17us : idle_cpu (irq_enter)
928     sshd-4261  0d..2   18us : add_preempt_count (irq_enter)
929     sshd-4261  0d.h2   18us : idle_cpu (irq_enter)
930     sshd-4261  0d.h.   18us : handle_fasteoi_irq (do_IRQ)
931     sshd-4261  0d.h.   19us : _spin_lock (handle_fasteoi_irq)
932     sshd-4261  0d.h.   19us : add_preempt_count (_spin_lock)
933     sshd-4261  0d.h1   20us : _spin_unlock (handle_fasteoi_irq)
934     sshd-4261  0d.h1   20us : sub_preempt_count (_spin_unlock)
935 [...]
936     sshd-4261  0d.h1   28us : _spin_unlock (handle_fasteoi_irq)
937     sshd-4261  0d.h1   29us : sub_preempt_count (_spin_unlock)
938     sshd-4261  0d.h2   29us : irq_exit (do_IRQ)
939     sshd-4261  0d.h2   29us : sub_preempt_count (irq_exit)
940     sshd-4261  0d..3   30us : do_softirq (irq_exit)
941     sshd-4261  0d...   30us : __do_softirq (do_softirq)
942     sshd-4261  0d...   31us : __local_bh_disable (__do_softirq)
943     sshd-4261  0d...   31us+: add_preempt_count (__local_bh_disable)
944     sshd-4261  0d.s4   34us : add_preempt_count (__local_bh_disable)
945 [...]
946     sshd-4261  0d.s3   43us : sub_preempt_count (local_bh_enable_ip)
947     sshd-4261  0d.s4   44us : sub_preempt_count (local_bh_enable_ip)
948     sshd-4261  0d.s3   44us : smp_apic_timer_interrupt (apic_timer_interrupt)
949     sshd-4261  0d.s3   45us : irq_enter (smp_apic_timer_interrupt)
950     sshd-4261  0d.s3   45us : idle_cpu (irq_enter)
951     sshd-4261  0d.s3   46us : add_preempt_count (irq_enter)
952     sshd-4261  0d.H3   46us : idle_cpu (irq_enter)
953     sshd-4261  0d.H3   47us : hrtimer_interrupt (smp_apic_timer_interrupt)
954     sshd-4261  0d.H3   47us : ktime_get (hrtimer_interrupt)
955 [...]
956     sshd-4261  0d.H3   81us : tick_program_event (hrtimer_interrupt)
957     sshd-4261  0d.H3   82us : ktime_get (tick_program_event)
958     sshd-4261  0d.H3   82us : ktime_get_ts (ktime_get)
959     sshd-4261  0d.H3   83us : getnstimeofday (ktime_get_ts)
960     sshd-4261  0d.H3   83us : set_normalized_timespec (ktime_get_ts)
961     sshd-4261  0d.H3   84us : clockevents_program_event (tick_program_event)
962     sshd-4261  0d.H3   84us : lapic_next_event (clockevents_program_event)
963     sshd-4261  0d.H3   85us : irq_exit (smp_apic_timer_interrupt)
964     sshd-4261  0d.H3   85us : sub_preempt_count (irq_exit)
965     sshd-4261  0d.s4   86us : sub_preempt_count (irq_exit)
966     sshd-4261  0d.s3   86us : add_preempt_count (__local_bh_disable)
967 [...]
968     sshd-4261  0d.s1   98us : sub_preempt_count (net_rx_action)
969     sshd-4261  0d.s.   99us : add_preempt_count (_spin_lock_irq)
970     sshd-4261  0d.s1   99us+: _spin_unlock_irq (run_timer_softirq)
971     sshd-4261  0d.s.  104us : _local_bh_enable (__do_softirq)
972     sshd-4261  0d.s.  104us : sub_preempt_count (_local_bh_enable)
973     sshd-4261  0d.s.  105us : _local_bh_enable (__do_softirq)
974     sshd-4261  0d.s1  105us : trace_preempt_on (__do_softirq)
977 This is a very interesting trace. It started with the preemption
978 of the ls task. We see that the task had the "need_resched" bit
979 set via the 'N' in the trace.  Interrupts were disabled before
980 the spin_lock at the beginning of the trace. We see that a
981 schedule took place to run sshd.  When the interrupts were
982 enabled, we took an interrupt. On return from the interrupt
983 handler, the softirq ran. We took another interrupt while
984 running the softirq as we see from the capital 'H'.
987 wakeup
988 ------
990 In a Real-Time environment it is very important to know the
991 wakeup time it takes for the highest priority task that is woken
992 up to the time that it executes. This is also known as "schedule
993 latency". I stress the point that this is about RT tasks. It is
994 also important to know the scheduling latency of non-RT tasks,
995 but the average schedule latency is better for non-RT tasks.
996 Tools like LatencyTop are more appropriate for such
997 measurements.
999 Real-Time environments are interested in the worst case latency.
1000 That is the longest latency it takes for something to happen,
1001 and not the average. We can have a very fast scheduler that may
1002 only have a large latency once in a while, but that would not
1003 work well with Real-Time tasks.  The wakeup tracer was designed
1004 to record the worst case wakeups of RT tasks. Non-RT tasks are
1005 not recorded because the tracer only records one worst case and
1006 tracing non-RT tasks that are unpredictable will overwrite the
1007 worst case latency of RT tasks.
1009 Since this tracer only deals with RT tasks, we will run this
1010 slightly differently than we did with the previous tracers.
1011 Instead of performing an 'ls', we will run 'sleep 1' under
1012 'chrt' which changes the priority of the task.
1014  # echo wakeup > current_tracer
1015  # echo 0 > tracing_max_latency
1016  # echo 1 > tracing_enabled
1017  # chrt -f 5 sleep 1
1018  # echo 0 > tracing_enabled
1019  # cat latency_trace
1020 # tracer: wakeup
1022 wakeup latency trace v1.1.5 on 2.6.26-rc8
1023 --------------------------------------------------------------------
1024  latency: 4 us, #2/2, CPU#1 | (M:preempt VP:0, KP:0, SP:0 HP:0 #P:2)
1025     -----------------
1026     | task: sleep-4901 (uid:0 nice:0 policy:1 rt_prio:5)
1027     -----------------
1029 #                _------=> CPU#
1030 #               / _-----=> irqs-off
1031 #              | / _----=> need-resched
1032 #              || / _---=> hardirq/softirq
1033 #              ||| / _--=> preempt-depth
1034 #              |||| /
1035 #              |||||     delay
1036 #  cmd     pid ||||| time  |   caller
1037 #     \   /    |||||   \   |   /
1038   <idle>-0     1d.h4    0us+: try_to_wake_up (wake_up_process)
1039   <idle>-0     1d..4    4us : schedule (cpu_idle)
1042 Running this on an idle system, we see that it only took 4
1043 microseconds to perform the task switch.  Note, since the trace
1044 marker in the schedule is before the actual "switch", we stop
1045 the tracing when the recorded task is about to schedule in. This
1046 may change if we add a new marker at the end of the scheduler.
1048 Notice that the recorded task is 'sleep' with the PID of 4901
1049 and it has an rt_prio of 5. This priority is user-space priority
1050 and not the internal kernel priority. The policy is 1 for
1051 SCHED_FIFO and 2 for SCHED_RR.
1053 Doing the same with chrt -r 5 and ftrace_enabled set.
1055 # tracer: wakeup
1057 wakeup latency trace v1.1.5 on 2.6.26-rc8
1058 --------------------------------------------------------------------
1059  latency: 50 us, #60/60, CPU#1 | (M:preempt VP:0, KP:0, SP:0 HP:0 #P:2)
1060     -----------------
1061     | task: sleep-4068 (uid:0 nice:0 policy:2 rt_prio:5)
1062     -----------------
1064 #                _------=> CPU#
1065 #               / _-----=> irqs-off
1066 #              | / _----=> need-resched
1067 #              || / _---=> hardirq/softirq
1068 #              ||| / _--=> preempt-depth
1069 #              |||| /
1070 #              |||||     delay
1071 #  cmd     pid ||||| time  |   caller
1072 #     \   /    |||||   \   |   /
1073 ksoftirq-7     1d.H3    0us : try_to_wake_up (wake_up_process)
1074 ksoftirq-7     1d.H4    1us : sub_preempt_count (marker_probe_cb)
1075 ksoftirq-7     1d.H3    2us : check_preempt_wakeup (try_to_wake_up)
1076 ksoftirq-7     1d.H3    3us : update_curr (check_preempt_wakeup)
1077 ksoftirq-7     1d.H3    4us : calc_delta_mine (update_curr)
1078 ksoftirq-7     1d.H3    5us : __resched_task (check_preempt_wakeup)
1079 ksoftirq-7     1d.H3    6us : task_wake_up_rt (try_to_wake_up)
1080 ksoftirq-7     1d.H3    7us : _spin_unlock_irqrestore (try_to_wake_up)
1081 [...]
1082 ksoftirq-7     1d.H2   17us : irq_exit (smp_apic_timer_interrupt)
1083 ksoftirq-7     1d.H2   18us : sub_preempt_count (irq_exit)
1084 ksoftirq-7     1d.s3   19us : sub_preempt_count (irq_exit)
1085 ksoftirq-7     1..s2   20us : rcu_process_callbacks (__do_softirq)
1086 [...]
1087 ksoftirq-7     1..s2   26us : __rcu_process_callbacks (rcu_process_callbacks)
1088 ksoftirq-7     1d.s2   27us : _local_bh_enable (__do_softirq)
1089 ksoftirq-7     1d.s2   28us : sub_preempt_count (_local_bh_enable)
1090 ksoftirq-7     1.N.3   29us : sub_preempt_count (ksoftirqd)
1091 ksoftirq-7     1.N.2   30us : _cond_resched (ksoftirqd)
1092 ksoftirq-7     1.N.2   31us : __cond_resched (_cond_resched)
1093 ksoftirq-7     1.N.2   32us : add_preempt_count (__cond_resched)
1094 ksoftirq-7     1.N.2   33us : schedule (__cond_resched)
1095 ksoftirq-7     1.N.2   33us : add_preempt_count (schedule)
1096 ksoftirq-7     1.N.3   34us : hrtick_clear (schedule)
1097 ksoftirq-7     1dN.3   35us : _spin_lock (schedule)
1098 ksoftirq-7     1dN.3   36us : add_preempt_count (_spin_lock)
1099 ksoftirq-7     1d..4   37us : put_prev_task_fair (schedule)
1100 ksoftirq-7     1d..4   38us : update_curr (put_prev_task_fair)
1101 [...]
1102 ksoftirq-7     1d..5   47us : _spin_trylock (tracing_record_cmdline)
1103 ksoftirq-7     1d..5   48us : add_preempt_count (_spin_trylock)
1104 ksoftirq-7     1d..6   49us : _spin_unlock (tracing_record_cmdline)
1105 ksoftirq-7     1d..6   49us : sub_preempt_count (_spin_unlock)
1106 ksoftirq-7     1d..4   50us : schedule (__cond_resched)
1108 The interrupt went off while running ksoftirqd. This task runs
1109 at SCHED_OTHER. Why did not we see the 'N' set early? This may
1110 be a harmless bug with x86_32 and 4K stacks. On x86_32 with 4K
1111 stacks configured, the interrupt and softirq run with their own
1112 stack. Some information is held on the top of the task's stack
1113 (need_resched and preempt_count are both stored there). The
1114 setting of the NEED_RESCHED bit is done directly to the task's
1115 stack, but the reading of the NEED_RESCHED is done by looking at
1116 the current stack, which in this case is the stack for the hard
1117 interrupt. This hides the fact that NEED_RESCHED has been set.
1118 We do not see the 'N' until we switch back to the task's
1119 assigned stack.
1121 function
1122 --------
1124 This tracer is the function tracer. Enabling the function tracer
1125 can be done from the debug file system. Make sure the
1126 ftrace_enabled is set; otherwise this tracer is a nop.
1128  # sysctl kernel.ftrace_enabled=1
1129  # echo function > current_tracer
1130  # echo 1 > tracing_enabled
1131  # usleep 1
1132  # echo 0 > tracing_enabled
1133  # cat trace
1134 # tracer: function
1136 #           TASK-PID   CPU#    TIMESTAMP  FUNCTION
1137 #              | |      |          |         |
1138             bash-4003  [00]   123.638713: finish_task_switch <-schedule
1139             bash-4003  [00]   123.638714: _spin_unlock_irq <-finish_task_switch
1140             bash-4003  [00]   123.638714: sub_preempt_count <-_spin_unlock_irq
1141             bash-4003  [00]   123.638715: hrtick_set <-schedule
1142             bash-4003  [00]   123.638715: _spin_lock_irqsave <-hrtick_set
1143             bash-4003  [00]   123.638716: add_preempt_count <-_spin_lock_irqsave
1144             bash-4003  [00]   123.638716: _spin_unlock_irqrestore <-hrtick_set
1145             bash-4003  [00]   123.638717: sub_preempt_count <-_spin_unlock_irqrestore
1146             bash-4003  [00]   123.638717: hrtick_clear <-hrtick_set
1147             bash-4003  [00]   123.638718: sub_preempt_count <-schedule
1148             bash-4003  [00]   123.638718: sub_preempt_count <-preempt_schedule
1149             bash-4003  [00]   123.638719: wait_for_completion <-__stop_machine_run
1150             bash-4003  [00]   123.638719: wait_for_common <-wait_for_completion
1151             bash-4003  [00]   123.638720: _spin_lock_irq <-wait_for_common
1152             bash-4003  [00]   123.638720: add_preempt_count <-_spin_lock_irq
1153 [...]
1156 Note: function tracer uses ring buffers to store the above
1157 entries. The newest data may overwrite the oldest data.
1158 Sometimes using echo to stop the trace is not sufficient because
1159 the tracing could have overwritten the data that you wanted to
1160 record. For this reason, it is sometimes better to disable
1161 tracing directly from a program. This allows you to stop the
1162 tracing at the point that you hit the part that you are
1163 interested in. To disable the tracing directly from a C program,
1164 something like following code snippet can be used:
1166 int trace_fd;
1167 [...]
1168 int main(int argc, char *argv[]) {
1169         [...]
1170         trace_fd = open(tracing_file("tracing_enabled"), O_WRONLY);
1171         [...]
1172         if (condition_hit()) {
1173                 write(trace_fd, "0", 1);
1174         }
1175         [...]
1179 Single thread tracing
1180 ---------------------
1182 By writing into set_ftrace_pid you can trace a
1183 single thread. For example:
1185 # cat set_ftrace_pid
1186 no pid
1187 # echo 3111 > set_ftrace_pid
1188 # cat set_ftrace_pid
1189 3111
1190 # echo function > current_tracer
1191 # cat trace | head
1192  # tracer: function
1194  #           TASK-PID    CPU#    TIMESTAMP  FUNCTION
1195  #              | |       |          |         |
1196      yum-updatesd-3111  [003]  1637.254676: finish_task_switch <-thread_return
1197      yum-updatesd-3111  [003]  1637.254681: hrtimer_cancel <-schedule_hrtimeout_range
1198      yum-updatesd-3111  [003]  1637.254682: hrtimer_try_to_cancel <-hrtimer_cancel
1199      yum-updatesd-3111  [003]  1637.254683: lock_hrtimer_base <-hrtimer_try_to_cancel
1200      yum-updatesd-3111  [003]  1637.254685: fget_light <-do_sys_poll
1201      yum-updatesd-3111  [003]  1637.254686: pipe_poll <-do_sys_poll
1202 # echo -1 > set_ftrace_pid
1203 # cat trace |head
1204  # tracer: function
1206  #           TASK-PID    CPU#    TIMESTAMP  FUNCTION
1207  #              | |       |          |         |
1208  ##### CPU 3 buffer started ####
1209      yum-updatesd-3111  [003]  1701.957688: free_poll_entry <-poll_freewait
1210      yum-updatesd-3111  [003]  1701.957689: remove_wait_queue <-free_poll_entry
1211      yum-updatesd-3111  [003]  1701.957691: fput <-free_poll_entry
1212      yum-updatesd-3111  [003]  1701.957692: audit_syscall_exit <-sysret_audit
1213      yum-updatesd-3111  [003]  1701.957693: path_put <-audit_syscall_exit
1215 If you want to trace a function when executing, you could use
1216 something like this simple program:
1218 #include <stdio.h>
1219 #include <stdlib.h>
1220 #include <sys/types.h>
1221 #include <sys/stat.h>
1222 #include <fcntl.h>
1223 #include <unistd.h>
1225 #define _STR(x) #x
1226 #define STR(x) _STR(x)
1227 #define MAX_PATH 256
1229 const char *find_debugfs(void)
1231        static char debugfs[MAX_PATH+1];
1232        static int debugfs_found;
1233        char type[100];
1234        FILE *fp;
1236        if (debugfs_found)
1237                return debugfs;
1239        if ((fp = fopen("/proc/mounts","r")) == NULL) {
1240                perror("/proc/mounts");
1241                return NULL;
1242        }
1244        while (fscanf(fp, "%*s %"
1245                      STR(MAX_PATH)
1246                      "s %99s %*s %*d %*d\n",
1247                      debugfs, type) == 2) {
1248                if (strcmp(type, "debugfs") == 0)
1249                        break;
1250        }
1251        fclose(fp);
1253        if (strcmp(type, "debugfs") != 0) {
1254                fprintf(stderr, "debugfs not mounted");
1255                return NULL;
1256        }
1258        debugfs_found = 1;
1260        return debugfs;
1263 const char *tracing_file(const char *file_name)
1265        static char trace_file[MAX_PATH+1];
1266        snprintf(trace_file, MAX_PATH, "%s/%s", find_debugfs(), file_name);
1267        return trace_file;
1270 int main (int argc, char **argv)
1272         if (argc < 1)
1273                 exit(-1);
1275         if (fork() > 0) {
1276                 int fd, ffd;
1277                 char line[64];
1278                 int s;
1280                 ffd = open(tracing_file("current_tracer"), O_WRONLY);
1281                 if (ffd < 0)
1282                         exit(-1);
1283                 write(ffd, "nop", 3);
1285                 fd = open(tracing_file("set_ftrace_pid"), O_WRONLY);
1286                 s = sprintf(line, "%d\n", getpid());
1287                 write(fd, line, s);
1289                 write(ffd, "function", 8);
1291                 close(fd);
1292                 close(ffd);
1294                 execvp(argv[1], argv+1);
1295         }
1297         return 0;
1301 hw-branch-tracer (x86 only)
1302 ---------------------------
1304 This tracer uses the x86 last branch tracing hardware feature to
1305 collect a branch trace on all cpus with relatively low overhead.
1307 The tracer uses a fixed-size circular buffer per cpu and only
1308 traces ring 0 branches. The trace file dumps that buffer in the
1309 following format:
1311 # tracer: hw-branch-tracer
1313 # CPU#        TO  <-  FROM
1314    0  scheduler_tick+0xb5/0x1bf   <-  task_tick_idle+0x5/0x6
1315    2  run_posix_cpu_timers+0x2b/0x72a     <-  run_posix_cpu_timers+0x25/0x72a
1316    0  scheduler_tick+0x139/0x1bf          <-  scheduler_tick+0xed/0x1bf
1317    0  scheduler_tick+0x17c/0x1bf          <-  scheduler_tick+0x148/0x1bf
1318    2  run_posix_cpu_timers+0x9e/0x72a     <-  run_posix_cpu_timers+0x5e/0x72a
1319    0  scheduler_tick+0x1b6/0x1bf          <-  scheduler_tick+0x1aa/0x1bf
1322 The tracer may be used to dump the trace for the oops'ing cpu on
1323 a kernel oops into the system log. To enable this,
1324 ftrace_dump_on_oops must be set. To set ftrace_dump_on_oops, one
1325 can either use the sysctl function or set it via the proc system
1326 interface.
1328   sysctl kernel.ftrace_dump_on_oops=1
1332   echo 1 > /proc/sys/kernel/ftrace_dump_on_oops
1335 Here's an example of such a dump after a null pointer
1336 dereference in a kernel module:
1338 [57848.105921] BUG: unable to handle kernel NULL pointer dereference at 0000000000000000
1339 [57848.106019] IP: [<ffffffffa0000006>] open+0x6/0x14 [oops]
1340 [57848.106019] PGD 2354e9067 PUD 2375e7067 PMD 0
1341 [57848.106019] Oops: 0002 [#1] SMP
1342 [57848.106019] last sysfs file: /sys/devices/pci0000:00/0000:00:1e.0/0000:20:05.0/local_cpus
1343 [57848.106019] Dumping ftrace buffer:
1344 [57848.106019] ---------------------------------
1345 [...]
1346 [57848.106019]    0  chrdev_open+0xe6/0x165       <-  cdev_put+0x23/0x24
1347 [57848.106019]    0  chrdev_open+0x117/0x165      <-  chrdev_open+0xfa/0x165
1348 [57848.106019]    0  chrdev_open+0x120/0x165      <-  chrdev_open+0x11c/0x165
1349 [57848.106019]    0  chrdev_open+0x134/0x165      <-  chrdev_open+0x12b/0x165
1350 [57848.106019]    0  open+0x0/0x14 [oops]         <-  chrdev_open+0x144/0x165
1351 [57848.106019]    0  page_fault+0x0/0x30          <-  open+0x6/0x14 [oops]
1352 [57848.106019]    0  error_entry+0x0/0x5b         <-  page_fault+0x4/0x30
1353 [57848.106019]    0  error_kernelspace+0x0/0x31   <-  error_entry+0x59/0x5b
1354 [57848.106019]    0  error_sti+0x0/0x1    <-  error_kernelspace+0x2d/0x31
1355 [57848.106019]    0  page_fault+0x9/0x30          <-  error_sti+0x0/0x1
1356 [57848.106019]    0  do_page_fault+0x0/0x881      <-  page_fault+0x1a/0x30
1357 [...]
1358 [57848.106019]    0  do_page_fault+0x66b/0x881    <-  is_prefetch+0x1ee/0x1f2
1359 [57848.106019]    0  do_page_fault+0x6e0/0x881    <-  do_page_fault+0x67a/0x881
1360 [57848.106019]    0  oops_begin+0x0/0x96          <-  do_page_fault+0x6e0/0x881
1361 [57848.106019]    0  trace_hw_branch_oops+0x0/0x2d        <-  oops_begin+0x9/0x96
1362 [...]
1363 [57848.106019]    0  ds_suspend_bts+0x2a/0xe3     <-  ds_suspend_bts+0x1a/0xe3
1364 [57848.106019] ---------------------------------
1365 [57848.106019] CPU 0
1366 [57848.106019] Modules linked in: oops
1367 [57848.106019] Pid: 5542, comm: cat Tainted: G        W  2.6.28 #23
1368 [57848.106019] RIP: 0010:[<ffffffffa0000006>]  [<ffffffffa0000006>] open+0x6/0x14 [oops]
1369 [57848.106019] RSP: 0018:ffff880235457d48  EFLAGS: 00010246
1370 [...]
1373 function graph tracer
1374 ---------------------------
1376 This tracer is similar to the function tracer except that it
1377 probes a function on its entry and its exit. This is done by
1378 using a dynamically allocated stack of return addresses in each
1379 task_struct. On function entry the tracer overwrites the return
1380 address of each function traced to set a custom probe. Thus the
1381 original return address is stored on the stack of return address
1382 in the task_struct.
1384 Probing on both ends of a function leads to special features
1385 such as:
1387 - measure of a function's time execution
1388 - having a reliable call stack to draw function calls graph
1390 This tracer is useful in several situations:
1392 - you want to find the reason of a strange kernel behavior and
1393   need to see what happens in detail on any areas (or specific
1394   ones).
1396 - you are experiencing weird latencies but it's difficult to
1397   find its origin.
1399 - you want to find quickly which path is taken by a specific
1400   function
1402 - you just want to peek inside a working kernel and want to see
1403   what happens there.
1405 # tracer: function_graph
1407 # CPU  DURATION                  FUNCTION CALLS
1408 # |     |   |                     |   |   |   |
1410  0)               |  sys_open() {
1411  0)               |    do_sys_open() {
1412  0)               |      getname() {
1413  0)               |        kmem_cache_alloc() {
1414  0)   1.382 us    |          __might_sleep();
1415  0)   2.478 us    |        }
1416  0)               |        strncpy_from_user() {
1417  0)               |          might_fault() {
1418  0)   1.389 us    |            __might_sleep();
1419  0)   2.553 us    |          }
1420  0)   3.807 us    |        }
1421  0)   7.876 us    |      }
1422  0)               |      alloc_fd() {
1423  0)   0.668 us    |        _spin_lock();
1424  0)   0.570 us    |        expand_files();
1425  0)   0.586 us    |        _spin_unlock();
1428 There are several columns that can be dynamically
1429 enabled/disabled. You can use every combination of options you
1430 want, depending on your needs.
1432 - The cpu number on which the function executed is default
1433   enabled.  It is sometimes better to only trace one cpu (see
1434   tracing_cpu_mask file) or you might sometimes see unordered
1435   function calls while cpu tracing switch.
1437         hide: echo nofuncgraph-cpu > trace_options
1438         show: echo funcgraph-cpu > trace_options
1440 - The duration (function's time of execution) is displayed on
1441   the closing bracket line of a function or on the same line
1442   than the current function in case of a leaf one. It is default
1443   enabled.
1445         hide: echo nofuncgraph-duration > trace_options
1446         show: echo funcgraph-duration > trace_options
1448 - The overhead field precedes the duration field in case of
1449   reached duration thresholds.
1451         hide: echo nofuncgraph-overhead > trace_options
1452         show: echo funcgraph-overhead > trace_options
1453         depends on: funcgraph-duration
1455   ie:
1457   0)               |    up_write() {
1458   0)   0.646 us    |      _spin_lock_irqsave();
1459   0)   0.684 us    |      _spin_unlock_irqrestore();
1460   0)   3.123 us    |    }
1461   0)   0.548 us    |    fput();
1462   0) + 58.628 us   |  }
1464   [...]
1466   0)               |      putname() {
1467   0)               |        kmem_cache_free() {
1468   0)   0.518 us    |          __phys_addr();
1469   0)   1.757 us    |        }
1470   0)   2.861 us    |      }
1471   0) ! 115.305 us  |    }
1472   0) ! 116.402 us  |  }
1474   + means that the function exceeded 10 usecs.
1475   ! means that the function exceeded 100 usecs.
1478 - The task/pid field displays the thread cmdline and pid which
1479   executed the function. It is default disabled.
1481         hide: echo nofuncgraph-proc > trace_options
1482         show: echo funcgraph-proc > trace_options
1484   ie:
1486   # tracer: function_graph
1487   #
1488   # CPU  TASK/PID        DURATION                  FUNCTION CALLS
1489   # |    |    |           |   |                     |   |   |   |
1490   0)    sh-4802     |               |                  d_free() {
1491   0)    sh-4802     |               |                    call_rcu() {
1492   0)    sh-4802     |               |                      __call_rcu() {
1493   0)    sh-4802     |   0.616 us    |                        rcu_process_gp_end();
1494   0)    sh-4802     |   0.586 us    |                        check_for_new_grace_period();
1495   0)    sh-4802     |   2.899 us    |                      }
1496   0)    sh-4802     |   4.040 us    |                    }
1497   0)    sh-4802     |   5.151 us    |                  }
1498   0)    sh-4802     | + 49.370 us   |                }
1501 - The absolute time field is an absolute timestamp given by the
1502   system clock since it started. A snapshot of this time is
1503   given on each entry/exit of functions
1505         hide: echo nofuncgraph-abstime > trace_options
1506         show: echo funcgraph-abstime > trace_options
1508   ie:
1510   #
1511   #      TIME       CPU  DURATION                  FUNCTION CALLS
1512   #       |         |     |   |                     |   |   |   |
1513   360.774522 |   1)   0.541 us    |                                          }
1514   360.774522 |   1)   4.663 us    |                                        }
1515   360.774523 |   1)   0.541 us    |                                        __wake_up_bit();
1516   360.774524 |   1)   6.796 us    |                                      }
1517   360.774524 |   1)   7.952 us    |                                    }
1518   360.774525 |   1)   9.063 us    |                                  }
1519   360.774525 |   1)   0.615 us    |                                  journal_mark_dirty();
1520   360.774527 |   1)   0.578 us    |                                  __brelse();
1521   360.774528 |   1)               |                                  reiserfs_prepare_for_journal() {
1522   360.774528 |   1)               |                                    unlock_buffer() {
1523   360.774529 |   1)               |                                      wake_up_bit() {
1524   360.774529 |   1)               |                                        bit_waitqueue() {
1525   360.774530 |   1)   0.594 us    |                                          __phys_addr();
1528 You can put some comments on specific functions by using
1529 trace_printk() For example, if you want to put a comment inside
1530 the __might_sleep() function, you just have to include
1531 <linux/ftrace.h> and call trace_printk() inside __might_sleep()
1533 trace_printk("I'm a comment!\n")
1535 will produce:
1537  1)               |             __might_sleep() {
1538  1)               |                /* I'm a comment! */
1539  1)   1.449 us    |             }
1542 You might find other useful features for this tracer in the
1543 following "dynamic ftrace" section such as tracing only specific
1544 functions or tasks.
1546 dynamic ftrace
1547 --------------
1549 If CONFIG_DYNAMIC_FTRACE is set, the system will run with
1550 virtually no overhead when function tracing is disabled. The way
1551 this works is the mcount function call (placed at the start of
1552 every kernel function, produced by the -pg switch in gcc),
1553 starts of pointing to a simple return. (Enabling FTRACE will
1554 include the -pg switch in the compiling of the kernel.)
1556 At compile time every C file object is run through the
1557 recordmcount.pl script (located in the scripts directory). This
1558 script will process the C object using objdump to find all the
1559 locations in the .text section that call mcount. (Note, only the
1560 .text section is processed, since processing other sections like
1561 .init.text may cause races due to those sections being freed).
1563 A new section called "__mcount_loc" is created that holds
1564 references to all the mcount call sites in the .text section.
1565 This section is compiled back into the original object. The
1566 final linker will add all these references into a single table.
1568 On boot up, before SMP is initialized, the dynamic ftrace code
1569 scans this table and updates all the locations into nops. It
1570 also records the locations, which are added to the
1571 available_filter_functions list.  Modules are processed as they
1572 are loaded and before they are executed.  When a module is
1573 unloaded, it also removes its functions from the ftrace function
1574 list. This is automatic in the module unload code, and the
1575 module author does not need to worry about it.
1577 When tracing is enabled, kstop_machine is called to prevent
1578 races with the CPUS executing code being modified (which can
1579 cause the CPU to do undesireable things), and the nops are
1580 patched back to calls. But this time, they do not call mcount
1581 (which is just a function stub). They now call into the ftrace
1582 infrastructure.
1584 One special side-effect to the recording of the functions being
1585 traced is that we can now selectively choose which functions we
1586 wish to trace and which ones we want the mcount calls to remain
1587 as nops.
1589 Two files are used, one for enabling and one for disabling the
1590 tracing of specified functions. They are:
1592   set_ftrace_filter
1596   set_ftrace_notrace
1598 A list of available functions that you can add to these files is
1599 listed in:
1601    available_filter_functions
1603  # cat available_filter_functions
1604 put_prev_task_idle
1605 kmem_cache_create
1606 pick_next_task_rt
1607 get_online_cpus
1608 pick_next_task_fair
1609 mutex_lock
1610 [...]
1612 If I am only interested in sys_nanosleep and hrtimer_interrupt:
1614  # echo sys_nanosleep hrtimer_interrupt \
1615                 > set_ftrace_filter
1616  # echo ftrace > current_tracer
1617  # echo 1 > tracing_enabled
1618  # usleep 1
1619  # echo 0 > tracing_enabled
1620  # cat trace
1621 # tracer: ftrace
1623 #           TASK-PID   CPU#    TIMESTAMP  FUNCTION
1624 #              | |      |          |         |
1625           usleep-4134  [00]  1317.070017: hrtimer_interrupt <-smp_apic_timer_interrupt
1626           usleep-4134  [00]  1317.070111: sys_nanosleep <-syscall_call
1627           <idle>-0     [00]  1317.070115: hrtimer_interrupt <-smp_apic_timer_interrupt
1629 To see which functions are being traced, you can cat the file:
1631  # cat set_ftrace_filter
1632 hrtimer_interrupt
1633 sys_nanosleep
1636 Perhaps this is not enough. The filters also allow simple wild
1637 cards. Only the following are currently available
1639   <match>*  - will match functions that begin with <match>
1640   *<match>  - will match functions that end with <match>
1641   *<match>* - will match functions that have <match> in it
1643 These are the only wild cards which are supported.
1645   <match>*<match> will not work.
1647 Note: It is better to use quotes to enclose the wild cards,
1648       otherwise the shell may expand the parameters into names
1649       of files in the local directory.
1651  # echo 'hrtimer_*' > set_ftrace_filter
1653 Produces:
1655 # tracer: ftrace
1657 #           TASK-PID   CPU#    TIMESTAMP  FUNCTION
1658 #              | |      |          |         |
1659             bash-4003  [00]  1480.611794: hrtimer_init <-copy_process
1660             bash-4003  [00]  1480.611941: hrtimer_start <-hrtick_set
1661             bash-4003  [00]  1480.611956: hrtimer_cancel <-hrtick_clear
1662             bash-4003  [00]  1480.611956: hrtimer_try_to_cancel <-hrtimer_cancel
1663           <idle>-0     [00]  1480.612019: hrtimer_get_next_event <-get_next_timer_interrupt
1664           <idle>-0     [00]  1480.612025: hrtimer_get_next_event <-get_next_timer_interrupt
1665           <idle>-0     [00]  1480.612032: hrtimer_get_next_event <-get_next_timer_interrupt
1666           <idle>-0     [00]  1480.612037: hrtimer_get_next_event <-get_next_timer_interrupt
1667           <idle>-0     [00]  1480.612382: hrtimer_get_next_event <-get_next_timer_interrupt
1670 Notice that we lost the sys_nanosleep.
1672  # cat set_ftrace_filter
1673 hrtimer_run_queues
1674 hrtimer_run_pending
1675 hrtimer_init
1676 hrtimer_cancel
1677 hrtimer_try_to_cancel
1678 hrtimer_forward
1679 hrtimer_start
1680 hrtimer_reprogram
1681 hrtimer_force_reprogram
1682 hrtimer_get_next_event
1683 hrtimer_interrupt
1684 hrtimer_nanosleep
1685 hrtimer_wakeup
1686 hrtimer_get_remaining
1687 hrtimer_get_res
1688 hrtimer_init_sleeper
1691 This is because the '>' and '>>' act just like they do in bash.
1692 To rewrite the filters, use '>'
1693 To append to the filters, use '>>'
1695 To clear out a filter so that all functions will be recorded
1696 again:
1698  # echo > set_ftrace_filter
1699  # cat set_ftrace_filter
1702 Again, now we want to append.
1704  # echo sys_nanosleep > set_ftrace_filter
1705  # cat set_ftrace_filter
1706 sys_nanosleep
1707  # echo 'hrtimer_*' >> set_ftrace_filter
1708  # cat set_ftrace_filter
1709 hrtimer_run_queues
1710 hrtimer_run_pending
1711 hrtimer_init
1712 hrtimer_cancel
1713 hrtimer_try_to_cancel
1714 hrtimer_forward
1715 hrtimer_start
1716 hrtimer_reprogram
1717 hrtimer_force_reprogram
1718 hrtimer_get_next_event
1719 hrtimer_interrupt
1720 sys_nanosleep
1721 hrtimer_nanosleep
1722 hrtimer_wakeup
1723 hrtimer_get_remaining
1724 hrtimer_get_res
1725 hrtimer_init_sleeper
1728 The set_ftrace_notrace prevents those functions from being
1729 traced.
1731  # echo '*preempt*' '*lock*' > set_ftrace_notrace
1733 Produces:
1735 # tracer: ftrace
1737 #           TASK-PID   CPU#    TIMESTAMP  FUNCTION
1738 #              | |      |          |         |
1739             bash-4043  [01]   115.281644: finish_task_switch <-schedule
1740             bash-4043  [01]   115.281645: hrtick_set <-schedule
1741             bash-4043  [01]   115.281645: hrtick_clear <-hrtick_set
1742             bash-4043  [01]   115.281646: wait_for_completion <-__stop_machine_run
1743             bash-4043  [01]   115.281647: wait_for_common <-wait_for_completion
1744             bash-4043  [01]   115.281647: kthread_stop <-stop_machine_run
1745             bash-4043  [01]   115.281648: init_waitqueue_head <-kthread_stop
1746             bash-4043  [01]   115.281648: wake_up_process <-kthread_stop
1747             bash-4043  [01]   115.281649: try_to_wake_up <-wake_up_process
1749 We can see that there's no more lock or preempt tracing.
1752 Dynamic ftrace with the function graph tracer
1753 ---------------------------------------------
1755 Although what has been explained above concerns both the
1756 function tracer and the function-graph-tracer, there are some
1757 special features only available in the function-graph tracer.
1759 If you want to trace only one function and all of its children,
1760 you just have to echo its name into set_graph_function:
1762  echo __do_fault > set_graph_function
1764 will produce the following "expanded" trace of the __do_fault()
1765 function:
1767  0)               |  __do_fault() {
1768  0)               |    filemap_fault() {
1769  0)               |      find_lock_page() {
1770  0)   0.804 us    |        find_get_page();
1771  0)               |        __might_sleep() {
1772  0)   1.329 us    |        }
1773  0)   3.904 us    |      }
1774  0)   4.979 us    |    }
1775  0)   0.653 us    |    _spin_lock();
1776  0)   0.578 us    |    page_add_file_rmap();
1777  0)   0.525 us    |    native_set_pte_at();
1778  0)   0.585 us    |    _spin_unlock();
1779  0)               |    unlock_page() {
1780  0)   0.541 us    |      page_waitqueue();
1781  0)   0.639 us    |      __wake_up_bit();
1782  0)   2.786 us    |    }
1783  0) + 14.237 us   |  }
1784  0)               |  __do_fault() {
1785  0)               |    filemap_fault() {
1786  0)               |      find_lock_page() {
1787  0)   0.698 us    |        find_get_page();
1788  0)               |        __might_sleep() {
1789  0)   1.412 us    |        }
1790  0)   3.950 us    |      }
1791  0)   5.098 us    |    }
1792  0)   0.631 us    |    _spin_lock();
1793  0)   0.571 us    |    page_add_file_rmap();
1794  0)   0.526 us    |    native_set_pte_at();
1795  0)   0.586 us    |    _spin_unlock();
1796  0)               |    unlock_page() {
1797  0)   0.533 us    |      page_waitqueue();
1798  0)   0.638 us    |      __wake_up_bit();
1799  0)   2.793 us    |    }
1800  0) + 14.012 us   |  }
1802 You can also expand several functions at once:
1804  echo sys_open > set_graph_function
1805  echo sys_close >> set_graph_function
1807 Now if you want to go back to trace all functions you can clear
1808 this special filter via:
1810  echo > set_graph_function
1813 trace_pipe
1814 ----------
1816 The trace_pipe outputs the same content as the trace file, but
1817 the effect on the tracing is different. Every read from
1818 trace_pipe is consumed. This means that subsequent reads will be
1819 different. The trace is live.
1821  # echo function > current_tracer
1822  # cat trace_pipe > /tmp/trace.out &
1823 [1] 4153
1824  # echo 1 > tracing_enabled
1825  # usleep 1
1826  # echo 0 > tracing_enabled
1827  # cat trace
1828 # tracer: function
1830 #           TASK-PID   CPU#    TIMESTAMP  FUNCTION
1831 #              | |      |          |         |
1834  # cat /tmp/trace.out
1835             bash-4043  [00] 41.267106: finish_task_switch <-schedule
1836             bash-4043  [00] 41.267106: hrtick_set <-schedule
1837             bash-4043  [00] 41.267107: hrtick_clear <-hrtick_set
1838             bash-4043  [00] 41.267108: wait_for_completion <-__stop_machine_run
1839             bash-4043  [00] 41.267108: wait_for_common <-wait_for_completion
1840             bash-4043  [00] 41.267109: kthread_stop <-stop_machine_run
1841             bash-4043  [00] 41.267109: init_waitqueue_head <-kthread_stop
1842             bash-4043  [00] 41.267110: wake_up_process <-kthread_stop
1843             bash-4043  [00] 41.267110: try_to_wake_up <-wake_up_process
1844             bash-4043  [00] 41.267111: select_task_rq_rt <-try_to_wake_up
1847 Note, reading the trace_pipe file will block until more input is
1848 added. By changing the tracer, trace_pipe will issue an EOF. We
1849 needed to set the function tracer _before_ we "cat" the
1850 trace_pipe file.
1853 trace entries
1854 -------------
1856 Having too much or not enough data can be troublesome in
1857 diagnosing an issue in the kernel. The file buffer_size_kb is
1858 used to modify the size of the internal trace buffers. The
1859 number listed is the number of entries that can be recorded per
1860 CPU. To know the full size, multiply the number of possible CPUS
1861 with the number of entries.
1863  # cat buffer_size_kb
1864 1408 (units kilobytes)
1866 Note, to modify this, you must have tracing completely disabled.
1867 To do that, echo "nop" into the current_tracer. If the
1868 current_tracer is not set to "nop", an EINVAL error will be
1869 returned.
1871  # echo nop > current_tracer
1872  # echo 10000 > buffer_size_kb
1873  # cat buffer_size_kb
1874 10000 (units kilobytes)
1876 The number of pages which will be allocated is limited to a
1877 percentage of available memory. Allocating too much will produce
1878 an error.
1880  # echo 1000000000000 > buffer_size_kb
1881 -bash: echo: write error: Cannot allocate memory
1882  # cat buffer_size_kb
1885 -----------
1887 More details can be found in the source code, in the
1888 kernel/trace/*.c files.