About Kernel Documentation Linux Kernel Contact Linux Resources Linux Blog

Documentation / trace / ftrace.txt




Custom Search

Based on kernel version 4.3. Page generated on 2015-11-02 12:51 EST.

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

Information is copyright its respective author. All material is available from the Linux Kernel Source distributed under a GPL License. This page is provided as a free service by mjmwired.net.