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