About Kernel Documentation Linux Kernel Contact Linux Resources Linux Blog

Documentation / trace / ftrace.txt




Custom Search

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