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