/Documentation/trace/ftrace.txt
Plain Text | 1946 lines | 1558 code | 388 blank | 0 comment | 0 complexity | dcf3f528e237b56b0eeeb66bce092168 MD5 | raw file
Possible License(s): GPL-2.0, LGPL-2.0, AGPL-1.0
Large files files are truncated, but you can click here to view the full file
1 ftrace - Function Tracer
2 ========================
3
4Copyright 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)
8Reviewers: Elias Oltmanns, Randy Dunlap, Andrew Morton,
9 John Kacur, and David Teigland.
10Written for: 2.6.28-rc2
11
12Introduction
13------------
14
15Ftrace is an internal tracer designed to help out developers and
16designers of systems to find what is going on inside the kernel.
17It can be used for debugging or analyzing latencies and
18performance issues that take place outside of user-space.
19
20Although ftrace is the function tracer, it also includes an
21infrastructure that allows for other types of tracing. Some of
22the tracers that are currently in ftrace include a tracer to
23trace context switches, the time it takes for a high priority
24task to run after it was woken up, the time interrupts are
25disabled, and more (ftrace allows for tracer plugins, which
26means that the list of tracers can always grow).
27
28
29Implementation Details
30----------------------
31
32See ftrace-design.txt for details for arch porters and such.
33
34
35The File System
36---------------
37
38Ftrace uses the debugfs file system to hold the control files as
39well as the files to display output.
40
41When debugfs is configured into the kernel (which selecting any ftrace
42option will do) the directory /sys/kernel/debug will be created. To mount
43this directory, you can add to your /etc/fstab file:
44
45 debugfs /sys/kernel/debug debugfs defaults 0 0
46
47Or you can mount it at run time with:
48
49 mount -t debugfs nodev /sys/kernel/debug
50
51For quicker access to that directory you may want to make a soft link to
52it:
53
54 ln -s /sys/kernel/debug /debug
55
56Any selected ftrace option will also create a directory called tracing
57within the debugfs. The rest of the document will assume that you are in
58the ftrace directory (cd /sys/kernel/debug/tracing) and will only concentrate
59on the files within that directory and not distract from the content with
60the extended "/sys/kernel/debug/tracing" path name.
61
62That's it! (assuming that you have ftrace configured into your kernel)
63
64After mounting the debugfs, you can see a directory called
65"tracing". This directory contains the control and output files
66of ftrace. Here is a list of some of the key files:
67
68
69 Note: all time values are in microseconds.
70
71 current_tracer:
72
73 This is used to set or display the current tracer
74 that is configured.
75
76 available_tracers:
77
78 This holds the different types of tracers that
79 have been compiled into the kernel. The
80 tracers listed here can be configured by
81 echoing their name into current_tracer.
82
83 tracing_enabled:
84
85 This sets or displays whether the current_tracer
86 is activated and tracing or not. Echo 0 into this
87 file to disable the tracer or 1 to enable it.
88
89 trace:
90
91 This file holds the output of the trace in a human
92 readable format (described below).
93
94 trace_pipe:
95
96 The output is the same as the "trace" file but this
97 file is meant to be streamed with live tracing.
98 Reads from this file will block until new data is
99 retrieved. Unlike the "trace" file, this file is a
100 consumer. This means reading from this file causes
101 sequential reads to display more current data. Once
102 data is read from this file, it is consumed, and
103 will not be read again with a sequential read. The
104 "trace" file is static, and if the tracer is not
105 adding more data,they will display the same
106 information every time they are read.
107
108 trace_options:
109
110 This file lets the user control the amount of data
111 that is displayed in one of the above output
112 files.
113
114 tracing_max_latency:
115
116 Some of the tracers record the max latency.
117 For example, the time interrupts are disabled.
118 This time is saved in this file. The max trace
119 will also be stored, and displayed by "trace".
120 A new max trace will only be recorded if the
121 latency is greater than the value in this
122 file. (in microseconds)
123
124 buffer_size_kb:
125
126 This sets or displays the number of kilobytes each CPU
127 buffer can hold. The tracer buffers are the same size
128 for each CPU. The displayed number is the size of the
129 CPU buffer and not total size of all buffers. The
130 trace buffers are allocated in pages (blocks of memory
131 that the kernel uses for allocation, usually 4 KB in size).
132 If the last page allocated has room for more bytes
133 than requested, the rest of the page will be used,
134 making the actual allocation bigger than requested.
135 ( Note, the size may not be a multiple of the page size
136 due to buffer management overhead. )
137
138 This can only be updated when the current_tracer
139 is set to "nop".
140
141 tracing_cpumask:
142
143 This is a mask that lets the user only trace
144 on specified CPUS. The format is a hex string
145 representing the CPUS.
146
147 set_ftrace_filter:
148
149 When dynamic ftrace is configured in (see the
150 section below "dynamic ftrace"), the code is dynamically
151 modified (code text rewrite) to disable calling of the
152 function profiler (mcount). This lets tracing be configured
153 in with practically no overhead in performance. This also
154 has a side effect of enabling or disabling specific functions
155 to be traced. Echoing names of functions into this file
156 will limit the trace to only those functions.
157
158 This interface also allows for commands to be used. See the
159 "Filter commands" section for more details.
160
161 set_ftrace_notrace:
162
163 This has an effect opposite to that of
164 set_ftrace_filter. Any function that is added here will not
165 be traced. If a function exists in both set_ftrace_filter
166 and set_ftrace_notrace, the function will _not_ be traced.
167
168 set_ftrace_pid:
169
170 Have the function tracer only trace a single thread.
171
172 set_graph_function:
173
174 Set a "trigger" function where tracing should start
175 with the function graph tracer (See the section
176 "dynamic ftrace" for more details).
177
178 available_filter_functions:
179
180 This lists the functions that ftrace
181 has processed and can trace. These are the function
182 names that you can pass to "set_ftrace_filter" or
183 "set_ftrace_notrace". (See the section "dynamic ftrace"
184 below for more details.)
185
186
187The Tracers
188-----------
189
190Here is the list of current tracers that may be configured.
191
192 "function"
193
194 Function call tracer to trace all kernel functions.
195
196 "function_graph"
197
198 Similar to the function tracer except that the
199 function tracer probes the functions on their entry
200 whereas the function graph tracer traces on both entry
201 and exit of the functions. It then provides the ability
202 to draw a graph of function calls similar to C code
203 source.
204
205 "sched_switch"
206
207 Traces the context switches and wakeups between tasks.
208
209 "irqsoff"
210
211 Traces the areas that disable interrupts and saves
212 the trace with the longest max latency.
213 See tracing_max_latency. When a new max is recorded,
214 it replaces the old trace. It is best to view this
215 trace with the latency-format option enabled.
216
217 "preemptoff"
218
219 Similar to irqsoff but traces and records the amount of
220 time for which preemption is disabled.
221
222 "preemptirqsoff"
223
224 Similar to irqsoff and preemptoff, but traces and
225 records the largest time for which irqs and/or preemption
226 is disabled.
227
228 "wakeup"
229
230 Traces and records the max latency that it takes for
231 the highest priority task to get scheduled after
232 it has been woken up.
233
234 "hw-branch-tracer"
235
236 Uses the BTS CPU feature on x86 CPUs to traces all
237 branches executed.
238
239 "nop"
240
241 This is the "trace nothing" tracer. To remove all
242 tracers from tracing simply echo "nop" into
243 current_tracer.
244
245
246Examples of using the tracer
247----------------------------
248
249Here are typical examples of using the tracers when controlling
250them only with the debugfs interface (without using any
251user-land utilities).
252
253Output format:
254--------------
255
256Here is an example of the output format of the file "trace"
257
258 --------
259# tracer: function
260#
261# TASK-PID CPU# TIMESTAMP FUNCTION
262# | | | | |
263 bash-4251 [01] 10152.583854: path_put <-path_walk
264 bash-4251 [01] 10152.583855: dput <-path_put
265 bash-4251 [01] 10152.583855: _atomic_dec_and_lock <-dput
266 --------
267
268A header is printed with the tracer name that is represented by
269the trace. In this case the tracer is "function". Then a header
270showing the format. Task name "bash", the task PID "4251", the
271CPU that it was running on "01", the timestamp in <secs>.<usecs>
272format, the function name that was traced "path_put" and the
273parent function that called this function "path_walk". The
274timestamp is the time at which the function was entered.
275
276The sched_switch tracer also includes tracing of task wakeups
277and context switches.
278
279 ksoftirqd/1-7 [01] 1453.070013: 7:115:R + 2916:115:S
280 ksoftirqd/1-7 [01] 1453.070013: 7:115:R + 10:115:S
281 ksoftirqd/1-7 [01] 1453.070013: 7:115:R ==> 10:115:R
282 events/1-10 [01] 1453.070013: 10:115:S ==> 2916:115:R
283 kondemand/1-2916 [01] 1453.070013: 2916:115:S ==> 7:115:R
284 ksoftirqd/1-7 [01] 1453.070013: 7:115:S ==> 0:140:R
285
286Wake ups are represented by a "+" and the context switches are
287shown as "==>". The format is:
288
289 Context switches:
290
291 Previous task Next Task
292
293 <pid>:<prio>:<state> ==> <pid>:<prio>:<state>
294
295 Wake ups:
296
297 Current task Task waking up
298
299 <pid>:<prio>:<state> + <pid>:<prio>:<state>
300
301The prio is the internal kernel priority, which is the inverse
302of the priority that is usually displayed by user-space tools.
303Zero represents the highest priority (99). Prio 100 starts the
304"nice" priorities with 100 being equal to nice -20 and 139 being
305nice 19. The prio "140" is reserved for the idle task which is
306the lowest priority thread (pid 0).
307
308
309Latency trace format
310--------------------
311
312When the latency-format option is enabled, the trace file gives
313somewhat more information to see why a latency happened.
314Here is a typical trace.
315
316# tracer: irqsoff
317#
318irqsoff latency trace v1.1.5 on 2.6.26-rc8
319--------------------------------------------------------------------
320 latency: 97 us, #3/3, CPU#0 | (M:preempt VP:0, KP:0, SP:0 HP:0 #P:2)
321 -----------------
322 | task: swapper-0 (uid:0 nice:0 policy:0 rt_prio:0)
323 -----------------
324 => started at: apic_timer_interrupt
325 => ended at: do_softirq
326
327# _------=> CPU#
328# / _-----=> irqs-off
329# | / _----=> need-resched
330# || / _---=> hardirq/softirq
331# ||| / _--=> preempt-depth
332# |||| /
333# ||||| delay
334# cmd pid ||||| time | caller
335# \ / ||||| \ | /
336 <idle>-0 0d..1 0us+: trace_hardirqs_off_thunk (apic_timer_interrupt)
337 <idle>-0 0d.s. 97us : __do_softirq (do_softirq)
338 <idle>-0 0d.s1 98us : trace_hardirqs_on (do_softirq)
339
340
341This shows that the current tracer is "irqsoff" tracing the time
342for which interrupts were disabled. It gives the trace version
343and the version of the kernel upon which this was executed on
344(2.6.26-rc8). Then it displays the max latency in microsecs (97
345us). The number of trace entries displayed and the total number
346recorded (both are three: #3/3). The type of preemption that was
347used (PREEMPT). VP, KP, SP, and HP are always zero and are
348reserved for later use. #P is the number of online CPUS (#P:2).
349
350The task is the process that was running when the latency
351occurred. (swapper pid: 0).
352
353The start and stop (the functions in which the interrupts were
354disabled and enabled respectively) that caused the latencies:
355
356 apic_timer_interrupt is where the interrupts were disabled.
357 do_softirq is where they were enabled again.
358
359The next lines after the header are the trace itself. The header
360explains which is which.
361
362 cmd: The name of the process in the trace.
363
364 pid: The PID of that process.
365
366 CPU#: The CPU which the process was running on.
367
368 irqs-off: 'd' interrupts are disabled. '.' otherwise.
369 Note: If the architecture does not support a way to
370 read the irq flags variable, an 'X' will always
371 be printed here.
372
373 need-resched: 'N' task need_resched is set, '.' otherwise.
374
375 hardirq/softirq:
376 'H' - hard irq occurred inside a softirq.
377 'h' - hard irq is running
378 's' - soft irq is running
379 '.' - normal context.
380
381 preempt-depth: The level of preempt_disabled
382
383The above is mostly meaningful for kernel developers.
384
385 time: When the latency-format option is enabled, the trace file
386 output includes a timestamp relative to the start of the
387 trace. This differs from the output when latency-format
388 is disabled, which includes an absolute timestamp.
389
390 delay: This is just to help catch your eye a bit better. And
391 needs to be fixed to be only relative to the same CPU.
392 The marks are determined by the difference between this
393 current trace and the next trace.
394 '!' - greater than preempt_mark_thresh (default 100)
395 '+' - greater than 1 microsecond
396 ' ' - less than or equal to 1 microsecond.
397
398 The rest is the same as the 'trace' file.
399
400
401trace_options
402-------------
403
404The trace_options file is used to control what gets printed in
405the trace output. To see what is available, simply cat the file:
406
407 cat trace_options
408 print-parent nosym-offset nosym-addr noverbose noraw nohex nobin \
409 noblock nostacktrace nosched-tree nouserstacktrace nosym-userobj
410
411To disable one of the options, echo in the option prepended with
412"no".
413
414 echo noprint-parent > trace_options
415
416To enable an option, leave off the "no".
417
418 echo sym-offset > trace_options
419
420Here are the available options:
421
422 print-parent - On function traces, display the calling (parent)
423 function as well as the function being traced.
424
425 print-parent:
426 bash-4000 [01] 1477.606694: simple_strtoul <-strict_strtoul
427
428 noprint-parent:
429 bash-4000 [01] 1477.606694: simple_strtoul
430
431
432 sym-offset - Display not only the function name, but also the
433 offset in the function. For example, instead of
434 seeing just "ktime_get", you will see
435 "ktime_get+0xb/0x20".
436
437 sym-offset:
438 bash-4000 [01] 1477.606694: simple_strtoul+0x6/0xa0
439
440 sym-addr - this will also display the function address as well
441 as the function name.
442
443 sym-addr:
444 bash-4000 [01] 1477.606694: simple_strtoul <c0339346>
445
446 verbose - This deals with the trace file when the
447 latency-format option is enabled.
448
449 bash 4000 1 0 00000000 00010a95 [58127d26] 1720.415ms \
450 (+0.000ms): simple_strtoul (strict_strtoul)
451
452 raw - This will display raw numbers. This option is best for
453 use with user applications that can translate the raw
454 numbers better than having it done in the kernel.
455
456 hex - Similar to raw, but the numbers will be in a hexadecimal
457 format.
458
459 bin - This will print out the formats in raw binary.
460
461 block - TBD (needs update)
462
463 stacktrace - This is one of the options that changes the trace
464 itself. When a trace is recorded, so is the stack
465 of functions. This allows for back traces of
466 trace sites.
467
468 userstacktrace - This option changes the trace. It records a
469 stacktrace of the current userspace thread.
470
471 sym-userobj - when user stacktrace are enabled, look up which
472 object the address belongs to, and print a
473 relative address. This is especially useful when
474 ASLR is on, otherwise you don't get a chance to
475 resolve the address to object/file/line after
476 the app is no longer running
477
478 The lookup is performed when you read
479 trace,trace_pipe. Example:
480
481 a.out-1623 [000] 40874.465068: /root/a.out[+0x480] <-/root/a.out[+0
482x494] <- /root/a.out[+0x4a8] <- /lib/libc-2.7.so[+0x1e1a6]
483
484 sched-tree - trace all tasks that are on the runqueue, at
485 every scheduling event. Will add overhead if
486 there's a lot of tasks running at once.
487
488 latency-format - This option changes the trace. When
489 it is enabled, the trace displays
490 additional information about the
491 latencies, as described in "Latency
492 trace format".
493
494sched_switch
495------------
496
497This tracer simply records schedule switches. Here is an example
498of how to use it.
499
500 # echo sched_switch > current_tracer
501 # echo 1 > tracing_enabled
502 # sleep 1
503 # echo 0 > tracing_enabled
504 # cat trace
505
506# tracer: sched_switch
507#
508# TASK-PID CPU# TIMESTAMP FUNCTION
509# | | | | |
510 bash-3997 [01] 240.132281: 3997:120:R + 4055:120:R
511 bash-3997 [01] 240.132284: 3997:120:R ==> 4055:120:R
512 sleep-4055 [01] 240.132371: 4055:120:S ==> 3997:120:R
513 bash-3997 [01] 240.132454: 3997:120:R + 4055:120:S
514 bash-3997 [01] 240.132457: 3997:120:R ==> 4055:120:R
515 sleep-4055 [01] 240.132460: 4055:120:D ==> 3997:120:R
516 bash-3997 [01] 240.132463: 3997:120:R + 4055:120:D
517 bash-3997 [01] 240.132465: 3997:120:R ==> 4055:120:R
518 <idle>-0 [00] 240.132589: 0:140:R + 4:115:S
519 <idle>-0 [00] 240.132591: 0:140:R ==> 4:115:R
520 ksoftirqd/0-4 [00] 240.132595: 4:115:S ==> 0:140:R
521 <idle>-0 [00] 240.132598: 0:140:R + 4:115:S
522 <idle>-0 [00] 240.132599: 0:140:R ==> 4:115:R
523 ksoftirqd/0-4 [00] 240.132603: 4:115:S ==> 0:140:R
524 sleep-4055 [01] 240.133058: 4055:120:S ==> 3997:120:R
525 [...]
526
527
528As we have discussed previously about this format, the header
529shows the name of the trace and points to the options. The
530"FUNCTION" is a misnomer since here it represents the wake ups
531and context switches.
532
533The sched_switch file only lists the wake ups (represented with
534'+') and context switches ('==>') with the previous task or
535current task first followed by the next task or task waking up.
536The format for both of these is PID:KERNEL-PRIO:TASK-STATE.
537Remember that the KERNEL-PRIO is the inverse of the actual
538priority with zero (0) being the highest priority and the nice
539values starting at 100 (nice -20). Below is a quick chart to map
540the kernel priority to user land priorities.
541
542 Kernel Space User Space
543 ===============================================================
544 0(high) to 98(low) user RT priority 99(high) to 1(low)
545 with SCHED_RR or SCHED_FIFO
546 ---------------------------------------------------------------
547 99 sched_priority is not used in scheduling
548 decisions(it must be specified as 0)
549 ---------------------------------------------------------------
550 100(high) to 139(low) user nice -20(high) to 19(low)
551 ---------------------------------------------------------------
552 140 idle task priority
553 ---------------------------------------------------------------
554
555The task states are:
556
557 R - running : wants to run, may not actually be running
558 S - sleep : process is waiting to be woken up (handles signals)
559 D - disk sleep (uninterruptible sleep) : process must be woken up
560 (ignores signals)
561 T - stopped : process suspended
562 t - traced : process is being traced (with something like gdb)
563 Z - zombie : process waiting to be cleaned up
564 X - unknown
565
566
567ftrace_enabled
568--------------
569
570The following tracers (listed below) give different output
571depending on whether or not the sysctl ftrace_enabled is set. To
572set ftrace_enabled, one can either use the sysctl function or
573set it via the proc file system interface.
574
575 sysctl kernel.ftrace_enabled=1
576
577 or
578
579 echo 1 > /proc/sys/kernel/ftrace_enabled
580
581To disable ftrace_enabled simply replace the '1' with '0' in the
582above commands.
583
584When ftrace_enabled is set the tracers will also record the
585functions that are within the trace. The descriptions of the
586tracers will also show an example with ftrace enabled.
587
588
589irqsoff
590-------
591
592When interrupts are disabled, the CPU can not react to any other
593external event (besides NMIs and SMIs). This prevents the timer
594interrupt from triggering or the mouse interrupt from letting
595the kernel know of a new mouse event. The result is a latency
596with the reaction time.
597
598The irqsoff tracer tracks the time for which interrupts are
599disabled. When a new maximum latency is hit, the tracer saves
600the trace leading up to that latency point so that every time a
601new maximum is reached, the old saved trace is discarded and the
602new trace is saved.
603
604To reset the maximum, echo 0 into tracing_max_latency. Here is
605an example:
606
607 # echo irqsoff > current_tracer
608 # echo latency-format > trace_options
609 # echo 0 > tracing_max_latency
610 # echo 1 > tracing_enabled
611 # ls -ltr
612 [...]
613 # echo 0 > tracing_enabled
614 # cat trace
615# tracer: irqsoff
616#
617irqsoff latency trace v1.1.5 on 2.6.26
618--------------------------------------------------------------------
619 latency: 12 us, #3/3, CPU#1 | (M:preempt VP:0, KP:0, SP:0 HP:0 #P:2)
620 -----------------
621 | task: bash-3730 (uid:0 nice:0 policy:0 rt_prio:0)
622 -----------------
623 => started at: sys_setpgid
624 => ended at: sys_setpgid
625
626# _------=> CPU#
627# / _-----=> irqs-off
628# | / _----=> need-resched
629# || / _---=> hardirq/softirq
630# ||| / _--=> preempt-depth
631# |||| /
632# ||||| delay
633# cmd pid ||||| time | caller
634# \ / ||||| \ | /
635 bash-3730 1d... 0us : _write_lock_irq (sys_setpgid)
636 bash-3730 1d..1 1us+: _write_unlock_irq (sys_setpgid)
637 bash-3730 1d..2 14us : trace_hardirqs_on (sys_setpgid)
638
639
640Here we see that that we had a latency of 12 microsecs (which is
641very good). The _write_lock_irq in sys_setpgid disabled
642interrupts. The difference between the 12 and the displayed
643timestamp 14us occurred because the clock was incremented
644between the time of recording the max latency and the time of
645recording the function that had that latency.
646
647Note the above example had ftrace_enabled not set. If we set the
648ftrace_enabled, we get a much larger output:
649
650# tracer: irqsoff
651#
652irqsoff latency trace v1.1.5 on 2.6.26-rc8
653--------------------------------------------------------------------
654 latency: 50 us, #101/101, CPU#0 | (M:preempt VP:0, KP:0, SP:0 HP:0 #P:2)
655 -----------------
656 | task: ls-4339 (uid:0 nice:0 policy:0 rt_prio:0)
657 -----------------
658 => started at: __alloc_pages_internal
659 => ended at: __alloc_pages_internal
660
661# _------=> CPU#
662# / _-----=> irqs-off
663# | / _----=> need-resched
664# || / _---=> hardirq/softirq
665# ||| / _--=> preempt-depth
666# |||| /
667# ||||| delay
668# cmd pid ||||| time | caller
669# \ / ||||| \ | /
670 ls-4339 0...1 0us+: get_page_from_freelist (__alloc_pages_internal)
671 ls-4339 0d..1 3us : rmqueue_bulk (get_page_from_freelist)
672 ls-4339 0d..1 3us : _spin_lock (rmqueue_bulk)
673 ls-4339 0d..1 4us : add_preempt_count (_spin_lock)
674 ls-4339 0d..2 4us : __rmqueue (rmqueue_bulk)
675 ls-4339 0d..2 5us : __rmqueue_smallest (__rmqueue)
676 ls-4339 0d..2 5us : __mod_zone_page_state (__rmqueue_smallest)
677 ls-4339 0d..2 6us : __rmqueue (rmqueue_bulk)
678 ls-4339 0d..2 6us : __rmqueue_smallest (__rmqueue)
679 ls-4339 0d..2 7us : __mod_zone_page_state (__rmqueue_smallest)
680 ls-4339 0d..2 7us : __rmqueue (rmqueue_bulk)
681 ls-4339 0d..2 8us : __rmqueue_smallest (__rmqueue)
682[...]
683 ls-4339 0d..2 46us : __rmqueue_smallest (__rmqueue)
684 ls-4339 0d..2 47us : __mod_zone_page_state (__rmqueue_smallest)
685 ls-4339 0d..2 47us : __rmqueue (rmqueue_bulk)
686 ls-4339 0d..2 48us : __rmqueue_smallest (__rmqueue)
687 ls-4339 0d..2 48us : __mod_zone_page_state (__rmqueue_smallest)
688 ls-4339 0d..2 49us : _spin_unlock (rmqueue_bulk)
689 ls-4339 0d..2 49us : sub_preempt_count (_spin_unlock)
690 ls-4339 0d..1 50us : get_page_from_freelist (__alloc_pages_internal)
691 ls-4339 0d..2 51us : trace_hardirqs_on (__alloc_pages_internal)
692
693
694
695Here we traced a 50 microsecond latency. But we also see all the
696functions that were called during that time. Note that by
697enabling function tracing, we incur an added overhead. This
698overhead may extend the latency times. But nevertheless, this
699trace has provided some very helpful debugging information.
700
701
702preemptoff
703----------
704
705When preemption is disabled, we may be able to receive
706interrupts but the task cannot be preempted and a higher
707priority task must wait for preemption to be enabled again
708before it can preempt a lower priority task.
709
710The preemptoff tracer traces the places that disable preemption.
711Like the irqsoff tracer, it records the maximum latency for
712which preemption was disabled. The control of preemptoff tracer
713is much like the irqsoff tracer.
714
715 # echo preemptoff > current_tracer
716 # echo latency-format > trace_options
717 # echo 0 > tracing_max_latency
718 # echo 1 > tracing_enabled
719 # ls -ltr
720 [...]
721 # echo 0 > tracing_enabled
722 # cat trace
723# tracer: preemptoff
724#
725preemptoff latency trace v1.1.5 on 2.6.26-rc8
726--------------------------------------------------------------------
727 latency: 29 us, #3/3, CPU#0 | (M:preempt VP:0, KP:0, SP:0 HP:0 #P:2)
728 -----------------
729 | task: sshd-4261 (uid:0 nice:0 policy:0 rt_prio:0)
730 -----------------
731 => started at: do_IRQ
732 => ended at: __do_softirq
733
734# _------=> CPU#
735# / _-----=> irqs-off
736# | / _----=> need-resched
737# || / _---=> hardirq/softirq
738# ||| / _--=> preempt-depth
739# |||| /
740# ||||| delay
741# cmd pid ||||| time | caller
742# \ / ||||| \ | /
743 sshd-4261 0d.h. 0us+: irq_enter (do_IRQ)
744 sshd-4261 0d.s. 29us : _local_bh_enable (__do_softirq)
745 sshd-4261 0d.s1 30us : trace_preempt_on (__do_softirq)
746
747
748This has some more changes. Preemption was disabled when an
749interrupt came in (notice the 'h'), and was enabled while doing
750a softirq. (notice the 's'). But we also see that interrupts
751have been disabled when entering the preempt off section and
752leaving it (the 'd'). We do not know if interrupts were enabled
753in the mean time.
754
755# tracer: preemptoff
756#
757preemptoff latency trace v1.1.5 on 2.6.26-rc8
758--------------------------------------------------------------------
759 latency: 63 us, #87/87, CPU#0 | (M:preempt VP:0, KP:0, SP:0 HP:0 #P:2)
760 -----------------
761 | task: sshd-4261 (uid:0 nice:0 policy:0 rt_prio:0)
762 -----------------
763 => started at: remove_wait_queue
764 => ended at: __do_softirq
765
766# _------=> CPU#
767# / _-----=> irqs-off
768# | / _----=> need-resched
769# || / _---=> hardirq/softirq
770# ||| / _--=> preempt-depth
771# |||| /
772# ||||| delay
773# cmd pid ||||| time | caller
774# \ / ||||| \ | /
775 sshd-4261 0d..1 0us : _spin_lock_irqsave (remove_wait_queue)
776 sshd-4261 0d..1 1us : _spin_unlock_irqrestore (remove_wait_queue)
777 sshd-4261 0d..1 2us : do_IRQ (common_interrupt)
778 sshd-4261 0d..1 2us : irq_enter (do_IRQ)
779 sshd-4261 0d..1 2us : idle_cpu (irq_enter)
780 sshd-4261 0d..1 3us : add_preempt_count (irq_enter)
781 sshd-4261 0d.h1 3us : idle_cpu (irq_enter)
782 sshd-4261 0d.h. 4us : handle_fasteoi_irq (do_IRQ)
783[...]
784 sshd-4261 0d.h. 12us : add_preempt_count (_spin_lock)
785 sshd-4261 0d.h1 12us : ack_ioapic_quirk_irq (handle_fasteoi_irq)
786 sshd-4261 0d.h1 13us : move_native_irq (ack_ioapic_quirk_irq)
787 sshd-4261 0d.h1 13us : _spin_unlock (handle_fasteoi_irq)
788 sshd-4261 0d.h1 14us : sub_preempt_count (_spin_unlock)
789 sshd-4261 0d.h1 14us : irq_exit (do_IRQ)
790 sshd-4261 0d.h1 15us : sub_preempt_count (irq_exit)
791 sshd-4261 0d..2 15us : do_softirq (irq_exit)
792 sshd-4261 0d... 15us : __do_softirq (do_softirq)
793 sshd-4261 0d... 16us : __local_bh_disable (__do_softirq)
794 sshd-4261 0d... 16us+: add_preempt_count (__local_bh_disable)
795 sshd-4261 0d.s4 20us : add_preempt_count (__local_bh_disable)
796 sshd-4261 0d.s4 21us : sub_preempt_count (local_bh_enable)
797 sshd-4261 0d.s5 21us : sub_preempt_count (local_bh_enable)
798[...]
799 sshd-4261 0d.s6 41us : add_preempt_count (__local_bh_disable)
800 sshd-4261 0d.s6 42us : sub_preempt_count (local_bh_enable)
801 sshd-4261 0d.s7 42us : sub_preempt_count (local_bh_enable)
802 sshd-4261 0d.s5 43us : add_preempt_count (__local_bh_disable)
803 sshd-4261 0d.s5 43us : sub_preempt_count (local_bh_enable_ip)
804 sshd-4261 0d.s6 44us : sub_preempt_count (local_bh_enable_ip)
805 sshd-4261 0d.s5 44us : add_preempt_count (__local_bh_disable)
806 sshd-4261 0d.s5 45us : sub_preempt_count (local_bh_enable)
807[...]
808 sshd-4261 0d.s. 63us : _local_bh_enable (__do_softirq)
809 sshd-4261 0d.s1 64us : trace_preempt_on (__do_softirq)
810
811
812The above is an example of the preemptoff trace with
813ftrace_enabled set. Here we see that interrupts were disabled
814the entire time. The irq_enter code lets us know that we entered
815an interrupt 'h'. Before that, the functions being traced still
816show that it is not in an interrupt, but we can see from the
817functions themselves that this is not the case.
818
819Notice that __do_softirq when called does not have a
820preempt_count. It may seem that we missed a preempt enabling.
821What really happened is that the preempt count is held on the
822thread's stack and we switched to the softirq stack (4K stacks
823in effect). The code does not copy the preempt count, but
824because interrupts are disabled, we do not need to worry about
825it. Having a tracer like this is good for letting people know
826what really happens inside the kernel.
827
828
829preemptirqsoff
830--------------
831
832Knowing the locations that have interrupts disabled or
833preemption disabled for the longest times is helpful. But
834sometimes we would like to know when either preemption and/or
835interrupts are disabled.
836
837Consider the following code:
838
839 local_irq_disable();
840 call_function_with_irqs_off();
841 preempt_disable();
842 call_function_with_irqs_and_preemption_off();
843 local_irq_enable();
844 call_function_with_preemption_off();
845 preempt_enable();
846
847The irqsoff tracer will record the total length of
848call_function_with_irqs_off() and
849call_function_with_irqs_and_preemption_off().
850
851The preemptoff tracer will record the total length of
852call_function_with_irqs_and_preemption_off() and
853call_function_with_preemption_off().
854
855But neither will trace the time that interrupts and/or
856preemption is disabled. This total time is the time that we can
857not schedule. To record this time, use the preemptirqsoff
858tracer.
859
860Again, using this trace is much like the irqsoff and preemptoff
861tracers.
862
863 # echo preemptirqsoff > current_tracer
864 # echo latency-format > trace_options
865 # echo 0 > tracing_max_latency
866 # echo 1 > tracing_enabled
867 # ls -ltr
868 [...]
869 # echo 0 > tracing_enabled
870 # cat trace
871# tracer: preemptirqsoff
872#
873preemptirqsoff latency trace v1.1.5 on 2.6.26-rc8
874--------------------------------------------------------------------
875 latency: 293 us, #3/3, CPU#0 | (M:preempt VP:0, KP:0, SP:0 HP:0 #P:2)
876 -----------------
877 | task: ls-4860 (uid:0 nice:0 policy:0 rt_prio:0)
878 -----------------
879 => started at: apic_timer_interrupt
880 => ended at: __do_softirq
881
882# _------=> CPU#
883# / _-----=> irqs-off
884# | / _----=> need-resched
885# || / _---=> hardirq/softirq
886# ||| / _--=> preempt-depth
887# |||| /
888# ||||| delay
889# cmd pid ||||| time | caller
890# \ / ||||| \ | /
891 ls-4860 0d... 0us!: trace_hardirqs_off_thunk (apic_timer_interrupt)
892 ls-4860 0d.s. 294us : _local_bh_enable (__do_softirq)
893 ls-4860 0d.s1 294us : trace_preempt_on (__do_softirq)
894
895
896
897The trace_hardirqs_off_thunk is called from assembly on x86 when
898interrupts are disabled in the assembly code. Without the
899function tracing, we do not know if interrupts were enabled
900within the preemption points. We do see that it started with
901preemption enabled.
902
903Here is a trace with ftrace_enabled set:
904
905
906# tracer: preemptirqsoff
907#
908preemptirqsoff latency trace v1.1.5 on 2.6.26-rc8
909--------------------------------------------------------------------
910 latency: 105 us, #183/183, CPU#0 | (M:preempt VP:0, KP:0, SP:0 HP:0 #P:2)
911 -----------------
912 | task: sshd-4261 (uid:0 nice:0 policy:0 rt_prio:0)
913 -----------------
914 => started at: write_chan
915 => ended at: __do_softirq
916
917# _------=> CPU#
918# / _-----=> irqs-off
919# | / _----=> need-resched
920# || / _---=> hardirq/softirq
921# ||| / _--=> preempt-depth
922# |||| /
923# ||||| delay
924# cmd pid ||||| time | caller
925# \ / ||||| \ | /
926 ls-4473 0.N.. 0us : preempt_schedule (write_chan)
927 ls-4473 0dN.1 1us : _spin_lock (schedule)
928 ls-4473 0dN.1 2us : add_preempt_count (_spin_lock)
929 ls-4473 0d..2 2us : put_prev_task_fair (schedule)
930[...]
931 ls-4473 0d..2 13us : set_normalized_timespec (ktime_get_ts)
932 ls-4473 0d..2 13us : __switch_to (schedule)
933 sshd-4261 0d..2 14us : finish_task_switch (schedule)
934 sshd-4261 0d..2 14us : _spin_unlock_irq (finish_task_switch)
935 sshd-4261 0d..1 15us : add_preempt_count (_spin_lock_irqsave)
936 sshd-4261 0d..2 16us : _spin_unlock_irqrestore (hrtick_set)
937 sshd-4261 0d..2 16us : do_IRQ (common_interrupt)
938 sshd-4261 0d..2 17us : irq_enter (do_IRQ)
939 sshd-4261 0d..2 17us : idle_cpu (irq_enter)
940 sshd-4261 0d..2 18us : add_preempt_count (irq_enter)
941 sshd-4261 0d.h2 18us : idle_cpu (irq_enter)
942 sshd-4261 0d.h. 18us : handle_fasteoi_irq (do_IRQ)
943 sshd-4261 0d.h. 19us : _spin_lock (handle_fasteoi_irq)
944 sshd-4261 0d.h. 19us : add_preempt_count (_spin_lock)
945 sshd-4261 0d.h1 20us : _spin_unlock (handle_fasteoi_irq)
946 sshd-4261 0d.h1 20us : sub_preempt_count (_spin_unlock)
947[...]
948 sshd-4261 0d.h1 28us : _spin_unlock (handle_fasteoi_irq)
949 sshd-4261 0d.h1 29us : sub_preempt_count (_spin_unlock)
950 sshd-4261 0d.h2 29us : irq_exit (do_IRQ)
951 sshd-4261 0d.h2 29us : sub_preempt_count (irq_exit)
952 sshd-4261 0d..3 30us : do_softirq (irq_exit)
953 sshd-4261 0d... 30us : __do_softirq (do_softirq)
954 sshd-4261 0d... 31us : __local_bh_disable (__do_softirq)
955 sshd-4261 0d... 31us+: add_preempt_count (__local_bh_disable)
956 sshd-4261 0d.s4 34us : add_preempt_count (__local_bh_disable)
957[...]
958 sshd-4261 0d.s3 43us : sub_preempt_count (local_bh_enable_ip)
959 sshd-4261 0d.s4 44us : sub_preempt_count (local_bh_enable_ip)
960 sshd-4261 0d.s3 44us : smp_apic_timer_interrupt (apic_timer_interrupt)
961 sshd-4261 0d.s3 45us : irq_enter (smp_apic_timer_interrupt)
962 sshd-4261 0d.s3 45us : idle_cpu (irq_enter)
963 sshd-4261 0d.s3 46us : add_preempt_count (irq_enter)
964 sshd-4261 0d.H3 46us : idle_cpu (irq_enter)
965 sshd-4261 0d.H3 47us : hrtimer_interrupt (smp_apic_timer_interrupt)
966 sshd-4261 0d.H3 47us : ktime_get (hrtimer_interrupt)
967[...]
968 sshd-4261 0d.H3 81us : tick_program_event (hrtimer_interrupt)
969 sshd-4261 0d.H3 82us : ktime_get (tick_program_event)
970 sshd-4261 0d.H3 82us : ktime_get_ts (ktime_get)
971 sshd-4261 0d.H3 83us : getnstimeofday (ktime_get_ts)
972 sshd-4261 0d.H3 83us : set_normalized_timespec (ktime_get_ts)
973 sshd-4261 0d.H3 84us : clockevents_program_event (tick_program_event)
974 sshd-4261 0d.H3 84us : lapic_next_event (clockevents_program_event)
975 sshd-4261 0d.H3 85us : irq_exit (smp_apic_timer_interrupt)
976 sshd-4261 0d.H3 85us : sub_preempt_count (irq_exit)
977 sshd-4261 0d.s4 86us : sub_preempt_count (irq_exit)
978 sshd-4261 0d.s3 86us : add_preempt_count (__local_bh_disable)
979[...]
980 sshd-4261 0d.s1 98us : sub_preempt_count (net_rx_action)
981 sshd-4261 0d.s. 99us : add_preempt_count (_spin_lock_irq)
982 sshd-4261 0d.s1 99us+: _spin_unlock_irq (run_timer_softirq)
983 sshd-4261 0d.s. 104us : _local_bh_enable (__do_softirq)
984 sshd-4261 0d.s. 104us : sub_preempt_count (_local_bh_enable)
985 sshd-4261 0d.s. 105us : _local_bh_enable (__do_softirq)
986 sshd-4261 0d.s1 105us : trace_preempt_on (__do_softirq)
987
988
989This is a very interesting trace. It started with the preemption
990of the ls task. We see that the task had the "need_resched" bit
991set via the 'N' in the trace. Interrupts were disabled before
992the spin_lock at the beginning of the trace. We see that a
993schedule took place to run sshd. When the interrupts were
994enabled, we took an interrupt. On return from the interrupt
995handler, the softirq ran. We took another interrupt while
996running the softirq as we see from the capital 'H'.
997
998
999wakeup
1000------
1001
1002In a Real-Time environment it is very important to know the
1003wakeup time it takes for the highest priority task that is woken
1004up to the time that it executes. This is also known as "schedule
1005latency". I stress the point that this is about RT tasks. It is
1006also important to know the scheduling latency of non-RT tasks,
1007but the average schedule latency is better for non-RT tasks.
1008Tools like LatencyTop are more appropriate for such
1009measurements.
1010
1011Real-Time environments are interested in the worst case latency.
1012That is the longest latency it takes for something to happen,
1013and not the average. We can have a very fast scheduler that may
1014only have a large latency once in a while, but that would not
1015work well with Real-Time tasks. The wakeup tracer was designed
1016to record the worst case wakeups of RT tasks. Non-RT tasks are
1017not recorded because the tracer only records one worst case and
1018tracing non-RT tasks that are unpredictable will overwrite the
1019worst case latency of RT tasks.
1020
1021Since this tracer only deals with RT tasks, we will run this
1022slightly differently than we did with the previous tracers.
1023Instead of performing an 'ls', we will run 'sleep 1' under
1024'chrt' which changes the priority of the task.
1025
1026 # echo wakeup > current_tracer
1027 # echo latency-format > trace_options
1028 # echo 0 > tracing_max_latency
1029 # echo 1 > tracing_enabled
1030 # chrt -f 5 sleep 1
1031 # echo 0 > tracing_enabled
1032 # cat trace
1033# tracer: wakeup
1034#
1035wakeup latency trace v1.1.5 on 2.6.26-rc8
1036--------------------------------------------------------------------
1037 latency: 4 us, #2/2, CPU#1 | (M:preempt VP:0, KP:0, SP:0 HP:0 #P:2)
1038 -----------------
1039 | task: sleep-4901 (uid:0 nice:0 policy:1 rt_prio:5)
1040 -----------------
1041
1042# _------=> CPU#
1043# / _-----=> irqs-off
1044# | / _----=> need-resched
1045# || / _---=> hardirq/softirq
1046# ||| / _--=> preempt-depth
1047# |||| /
1048# ||||| delay
1049# cmd pid ||||| time | caller
1050# \ / ||||| \ | /
1051 <idle>-0 1d.h4 0us+: try_to_wake_up (wake_up_process)
1052 <idle>-0 1d..4 4us : schedule (cpu_idle)
1053
1054
1055Running this on an idle system, we see that it only took 4
1056microseconds to perform the task switch. Note, since the trace
1057marker in the schedule is before the actual "switch", we stop
1058the tracing when the recorded task is about to schedule in. This
1059may change if we add a new marker at the end of the scheduler.
1060
1061Notice that the recorded task is 'sleep' with the PID of 4901
1062and it has an rt_prio of 5. This priority is user-space priority
1063and not the internal kernel priority. The policy is 1 for
1064SCHED_FIFO and 2 for SCHED_RR.
1065
1066Doing the same with chrt -r 5 and ftrace_enabled set.
1067
1068# tracer: wakeup
1069#
1070wakeup latency trace v1.1.5 on 2.6.26-rc8
1071--------------------------------------------------------------------
1072 latency: 50 us, #60/60, CPU#1 | (M:preempt VP:0, KP:0, SP:0 HP:0 #P:2)
1073 -----------------
1074 | task: sleep-4068 (uid:0 nice:0 policy:2 rt_prio:5)
1075 -----------------
1076
1077# _------=> CPU#
1078# / _-----=> irqs-off
1079# | / _----=> need-resched
1080# || / _---=> hardirq/softirq
1081# ||| / _--=> preempt-depth
1082# |||| /
1083# ||||| delay
1084# cmd pid ||||| time | caller
1085# \ / ||||| \ | /
1086ksoftirq-7 1d.H3 0us : try_to_wake_up (wake_up_process)
1087ksoftirq-7 1d.H4 1us : sub_preempt_count (marker_probe_cb)
1088ksoftirq-7 1d.H3 2us : check_preempt_wakeup (try_to_wake_up)
1089ksoftirq-7 1d.H3 3us : update_curr (check_preempt_wakeup)
1090ksoftirq-7 1d.H3 4us : calc_delta_mine (update_curr)
1091ksoftirq-7 1d.H3 5us : __resched_task (check_preempt_wakeup)
1092ksoftirq-7 1d.H3 6us : task_wake_up_rt (try_to_wake_up)
1093ksoftirq-7 1d.H3 7us : _spin_unlock_irqrestore (try_to_wake_up)
1094[...]
1095ksoftirq-7 1d.H2 17us : irq_exit (smp_apic_timer_interrupt)
1096ksoftirq-7 1d.H2 18us : sub_preempt_count (irq_exit)
1097ksoftirq-7 1d.s3 19us : sub_preempt_count (irq_exit)
1098ksoftirq-7 1..s2 20us : rcu_process_callbacks (__do_softirq)
1099[...]
1100ksoftirq-7 1..s2 26us : __rcu_process_callbacks (rcu_process_callbacks)
1101ksoftirq-7 1d.s2 27us : _local_bh_enable (__do_softirq)
1102ksoftirq-7 1d.s2 28us : sub_preempt_count (_local_bh_enable)
1103ksoftirq-7 1.N.3 29us : sub_preempt_count (ksoftirqd)
1104ksoftirq-7 1.N.2 30us : _cond_resched (ksoftirqd)
1105ksoftirq-7 1.N.2 31us : __cond_resched (_cond_resched)
1106ksoftirq-7 1.N.2 32us : add_preempt_count (__cond_resched)
1107ksoftirq-7 1.N.2 33us : schedule (__cond_resched)
1108ksoftirq-7 1.N.2 33us : add_preempt_count (schedule)
1109ksoftirq-7 1.N.3 34us : hrtick_clear (schedule)
1110ksoftirq-7 1dN.3 35us : _spin_lock (schedule)
1111ksoftirq-7 1dN.3 36us : add_preempt_count (_spin_lock)
1112ksoftirq-7 1d..4 37us : put_prev_task_fair (schedule)
1113ksoftirq-7 1d..4 38us : update_curr (put_prev_task_fair)
1114[...]
1115ksoftirq-7 1d..5 47us : _spin_trylock (tracing_record_cmdline)
1116ksoftirq-7 1d..5 48us : add_preempt_count (_spin_trylock)
1117ksoftirq-7 1d..6 49us : _spin_unlock (tracing_record_cmdline)
1118ksoftirq-7 1d..6 49us : sub_preempt_count (_spin_unlock)
1119ksoftirq-7 1d..4 50us : schedule (__cond_resched)
1120
1121The interrupt went off while running ksoftirqd. This task runs
1122at SCHED_OTHER. Why did not we see the 'N' set early? This may
1123be a harmless bug with x86_32 and 4K stacks. On x86_32 with 4K
1124stacks configured, the interrupt and softirq run with their own
1125stack. Some information is held on the top of the task's stack
1126(need_resched and preempt_count are both stored there). The
1127setting of the NEED_RESCHED bit is done directly to the task's
1128stack, but the reading of the NEED_RESCHED is done by looking at
1129the current stack, which in this case is the stack for the hard
1130interrupt. This hides the fact that NEED_RESCHED has been set.
1131We do not see the 'N' until we switch back to the task's
1132assigned stack.
1133
1134function
1135--------
1136
1137This tracer is the function tracer. Enabling the function tracer
1138can be done from the debug file system. Make sure the
1139ftrace_enabled is set; otherwise this tracer is a nop.
1140
1141 # sysctl kernel.ftrace_enabled=1
1142 # echo function > current_tracer
1143 # echo 1 > tracing_enabled
1144 # usleep 1
1145 # echo 0 > tracing_enabled
1146 # cat trace
1147# tracer: function
1148#
1149# TASK-PID CPU# TIMESTAMP FUNCTION
1150# | | | | |
1151 bash-4003 [00] 123.638713: finish_task_switch <-schedule
1152 bash-4003 [00] 123.638714: _spin_unlock_irq <-finish_task_switch
1153 bash-4003 [00] 123.638714: sub_preempt_count <-_spin_unlock_irq
1154 bash-4003 [00] 123.638715: hrtick_set <-schedule
1155 bash-4003 [00] 123.638715: _spin_lock_irqsave <-hrtick_set
1156 bash-4003 [00] 123.638716: add_preempt_count <-_spin_lock_irqsave
1157 bash-4003 [00] 123.638716: _spin_unlock_irqrestore <-hrtick_set
1158 bash-4003 [00] 123.638717: sub_preempt_count <-_spin_unlock_irqrestore
1159 bash-4003 [00] 123.638717: hrtick_clear <-hrtick_set
1160 bash-4003 [00] 123.638718: sub_preempt_count <-schedule
1161 bash-4003 [00] 123.638718: sub_preempt_count <-preempt_schedule
1162 bash-4003 [00] 123.638719: wait_for_completion <-__stop_machine_run
1163 bash-4003 [00] 123.638719: wait_for_common <-wait_for_completion
1164 bash-4003 [00] 123.638720: _spin_lock_irq <-wait_for_common
1165 bash-4003 [00] 123.638720: add_preempt_count <-_spin_lock_irq
1166[...]
1167
1168
1169Note: function tracer uses ring buffers to store the above
1170entries. The newest data may overwrite the oldest data.
1171Sometimes using echo to stop the trace is not sufficient because
1172the tracing could have overwritten the data that you wanted to
1173record. For this reason, it is sometimes better to disable
1174tracing directly from a program. This allows you to stop the
1175tracing at the point that you hit the part that you are
1176interested in. To disable the tracing directly from a C program,
1177something like following code snippet can be used:
1178
1179int trace_fd;
1180[...]
1181int main(int argc, char *argv[]) {
1182 [...]
1183 trace_fd = open(tracing_file("tracing_enabled"), O_WRONLY);
1184 [...]
1185 if (condition_hit()) {
1186 write(trace_fd, "0", 1);
1187 }
1188 [...]
1189}
1190
1191
1192Single thread tracing
1193---------------------
1194
1195By writing into set_ftrace_pid you can trace a
1196single thread. For example:
1197
1198# cat set_ftrace_pid
1199no pid
1200# echo 3111 > set_ftrace_pid
1201# cat set_ftrace_pid
12023111
1203# echo function > current_tracer
1204# cat trace | head
1205 # tracer: function
1206 #
1207 # TASK-PID CPU# TIMESTAMP FUNCTION
1208 # | | | | |
1209 yum-updatesd-3111 [003] 1637.254676: finish_task_switch <-thread_return
1210 yum-updatesd-3111 [003] 1637.254681: hrtimer_cancel <-schedule_hrtimeout_range
1211 yum-updatesd-3111 [003] 1637.254682: hrtimer_try_to_cancel <-hrtimer_cancel
1212 yum-updatesd-3111 [003] 1637.254683: lock_hrtimer_base <-hrtimer_try_to_cancel
1213 yum-updatesd-3111 [003] 1637.254685: fget_light <-do_sys_poll
1214 yum-updatesd-3111 [003] 1637.254686: pipe_poll <-do_sys_poll
1215# echo -1 > set_ftrace_pid
1216# cat trace |head
1217 # tracer: function
1218 #
1219 # TASK-PID CPU# TIMESTAMP FUNCTION
1220 # | | | | |
1221 ##### CPU 3 buffer started ####
1222 yum-updatesd-3111 [003] 1701.957688: free_poll_entry <-poll_freewait
1223 yum-updatesd-3111 [003] 1701.957689: remove_wait_queue <-free_poll_entry
1224 yum-updatesd-3111 [003] 1701.957691: fput <-free_poll_entry
1225 yum-updatesd-3111 [003] 1701.957692: audit_syscall_exit <-sysret_audit
1226 yum-updatesd-3111 [003] 1701.957693: path_put <-audit_syscall_exit
1227
1228If you want to trace a function when executing, you could use
1229something like this simple program:
1230
1231#include <stdio.h>
1232#include <stdlib.h>
1233#include <sys/types.h>
1234#include <sys/stat.h>
1235#include <fcntl.h>
1236#include <unistd.h>
1237#include <string.h>
1238
1239#define _STR(x) #x
1240#define STR(x) _STR(x)
1241#define MAX_PATH 256
1242
1243const char *find_debugfs(void)
1244{
1245 static char debugfs[MAX_PATH+1];
1246 static int debugfs_found;
1247 char type[100];
1248 FILE *fp;
1249
1250 if (debugfs_found)
1251 return debugfs;
1252
1253 if ((fp = fopen("/proc/mounts","r")) == NULL) {
1254 perror("/proc/mounts");
1255 return NULL;
1256 }
1257
1258 while (fscanf(fp, "%*s %"
1259 STR(MAX_PATH)
1260 "s %99s %*s %*d %*d\n",
1261 debugfs, type) == 2) {
1262 if (strcmp(type, "debugfs") == 0)
1263 break;
1264 }
1265 fclose(fp);
1266
1267 if (strcmp(type, "debugfs") != 0) {
1268 fprintf(stderr, "debugfs not mounted");
1269 return NULL;
1270 }
1271
1272 strcat(debugfs, "/tracing/");
1273 debugfs_found = 1;
1274
1275 return debugfs;
1276}
1277
1278const char *tracing_file(const char *file_name)
1279{
1280 static char trace_file[MAX_PATH+1];
1281 snprintf(trace_file, MAX_PATH, "%s/%s", find_debugfs(), file_name);
1282 return trace_file;
1283}
1284
1285int main (int argc, char **argv)
1286{
1287 if (argc < 1)
1288 exit(-1);
1289
1290 if (fork() > 0) {
1291 int fd, ffd;
1292 char line[64];
1293 int s;
1294
1295 ffd = open(tracing_file("current_tracer"), O_WRONLY);
1296 if (ffd < 0)
1297 exit(-1);
1298 write(ffd, "nop", 3);
1299
1300 fd = open(tracing_file("set_ftrace_pid"), O_WRONLY);
1301 s = sprintf(line, "%d\n", getpid());
1302 write(fd, line, s);
1303
1304 write(ffd, "function", 8);
1305
1306 close(fd);
1307 close(ffd);
1308
1309 execvp(argv[1], argv+1);
1310 }
1311
1312 return 0;
1313}
1314
1315
1316hw-branch-tracer (x86 only)
1317---------------------------
1318
1319This tracer uses the x86 last branch tracing hardware feature to
1320collect a branch trace on all cpus with relatively low overhead.
1321
1322The tracer uses a fixed-size circular buffer per cpu and only
1323traces ring 0 branches. The trace file dumps that buffer in the
1324following format:
1325
1326# tracer: hw-branch-tracer
1327#
1328# CPU# TO <- FROM
1329 0 scheduler_tick+0xb5/0x1bf <- task_tick_idle+0x5/0x6
1330 2 run_posix_cpu_timers+0x2b/0x72a <- run_posix_cpu_timers+0x25/0x72a
1331 0 scheduler_tick+0x139/0x1bf <- scheduler_tick+0xed/0x1bf
1332 0 scheduler_tick+0x17c/0x1bf <- scheduler_tick+0x148/0x1bf
1333 2 run_posix_cpu_timers+0x9e/0x72a <- run_posix_cpu_timers+0x5e/0x72a
1334 0 scheduler_tick+0x1b6/0x1bf <- scheduler_tick+0x1aa/0x1bf
1335
1336
1337The tracer may be used to dump the trace for the oops'ing cpu on
1338a kernel oops into the system log. To enable this,
1339ftrace_dump_on_oops must be set. To set ftrace_dump_on_oops, one
1340can either use the sysctl function or set it via the proc system
1341interface.
1342
1343 sysctl kernel.ftrace_dump_on_oops=n
1344
1345or
1346
1347 echo n > /proc/sys/kernel/ftrace_dump_on_oops
1348
1349If n = 1, ftrace will dump buffers of all CPUs, if n = 2 ftrace will
1350only dump the bu…Large files files are truncated, but you can click here to view the full file