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