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