Version:  2.0.40 2.2.26 2.4.37 3.10 3.11 3.12 3.13 3.14 3.15 3.16 3.17 3.18 3.19 4.0 4.1 4.2 4.3 4.4 4.5 4.6 4.7

Linux/Documentation/trace/ftrace.txt

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

This page was automatically generated by LXR 0.3.1 (source).  •  Linux is a registered trademark of Linus Torvalds  •  Contact us