ftrace.txt 67.9 KB
Newer Older
Steven Rostedt's avatar
Steven Rostedt committed
1 2 3 4
		ftrace - Function Tracer
		========================

Copyright 2008 Red Hat Inc.
Steven Rostedt's avatar
Steven Rostedt committed
5 6
   Author:   Steven Rostedt <srostedt@redhat.com>
  License:   The GNU Free Documentation License, Version 1.2
Steven Rostedt's avatar
Steven Rostedt committed
7
               (dual licensed under the GPL v2)
Steven Rostedt's avatar
Steven Rostedt committed
8 9
Reviewers:   Elias Oltmanns, Randy Dunlap, Andrew Morton,
	     John Kacur, and David Teigland.
10
Written for: 2.6.28-rc2
Steven Rostedt's avatar
Steven Rostedt committed
11 12 13 14 15 16

Introduction
------------

Ftrace is an internal tracer designed to help out developers and
designers of systems to find what is going on inside the kernel.
17 18
It can be used for debugging or analyzing latencies and
performance issues that take place outside of user-space.
Steven Rostedt's avatar
Steven Rostedt committed
19 20

Although ftrace is the function tracer, it also includes an
21 22 23 24 25 26
infrastructure that allows for other types of tracing. Some of
the tracers that are currently in ftrace include a tracer to
trace context switches, the time it takes for a high priority
task to run after it was woken up, the time interrupts are
disabled, and more (ftrace allows for tracer plugins, which
means that the list of tracers can always grow).
Steven Rostedt's avatar
Steven Rostedt committed
27 28 29 30 31


The File System
---------------

32 33
Ftrace uses the debugfs file system to hold the control files as
well as the files to display output.
Steven Rostedt's avatar
Steven Rostedt committed
34

35 36 37 38 39 40 41 42 43
When debugfs is configured into the kernel (which selecting any ftrace
option will do) the directory /sys/kernel/debug will be created. To mount
this directory, you can add to your /etc/fstab file:

 debugfs       /sys/kernel/debug          debugfs defaults        0       0

Or you can mount it at run time with:

 mount -t debugfs nodev /sys/kernel/debug
Steven Rostedt's avatar
Steven Rostedt committed
44

45 46
For quicker access to that directory you may want to make a soft link to
it:
Steven Rostedt's avatar
Steven Rostedt committed
47

48 49 50 51 52 53 54
 ln -s /sys/kernel/debug /debug

Any selected ftrace option will also create a directory called tracing
within the debugfs. The rest of the document will assume that you are in
the ftrace directory (cd /sys/kernel/debug/tracing) and will only concentrate
on the files within that directory and not distract from the content with
the extended "/sys/kernel/debug/tracing" path name.
Steven Rostedt's avatar
Steven Rostedt committed
55 56 57 58 59 60 61 62 63 64

That's it! (assuming that you have ftrace configured into your kernel)

After mounting the debugfs, you can see a directory called
"tracing".  This directory contains the control and output files
of ftrace. Here is a list of some of the key files:


 Note: all time values are in microseconds.

65 66 67 68 69 70 71 72 73 74 75 76 77 78 79 80 81 82 83 84 85 86 87 88 89 90 91
  current_tracer:

	This is used to set or display the current tracer
	that is configured.

  available_tracers:

	This holds the different types of tracers that
	have been compiled into the kernel. The
	tracers listed here can be configured by
	echoing their name into current_tracer.

  tracing_enabled:

	This sets or displays whether the current_tracer
	is activated and tracing or not. Echo 0 into this
	file to disable the tracer or 1 to enable it.

  trace:

	This file holds the output of the trace in a human
	readable format (described below).

  trace_pipe:

	The output is the same as the "trace" file but this
	file is meant to be streamed with live tracing.
92 93 94 95 96 97 98 99 100
	Reads from this file will block until new data is
	retrieved.  Unlike the "trace" file, this file is a
	consumer. This means reading from this file causes
	sequential reads to display more current data. Once
	data is read from this file, it is consumed, and
	will not be read again with a sequential read. The
	"trace" file is static, and if the tracer is not
	adding more data,they will display the same
	information every time they are read.
101 102 103 104 105 106 107

  trace_options:

	This file lets the user control the amount of data
	that is displayed in one of the above output
	files.

108
  tracing_max_latency:
109 110 111 112

	Some of the tracers record the max latency.
	For example, the time interrupts are disabled.
	This time is saved in this file. The max trace
113
	will also be stored, and displayed by "trace".
114
	A new max trace will only be recorded, if the
115
	latency is greater than the value in this
116 117 118 119 120 121
	file (in microseconds). Note that the max latency
	recorded by the wakeup and the wakeup_rt tracer
	do not necessarily reflect the worst-case latency
	of the system, but may be erroneously high in
	case two or more processes share the maximum
	priority of the system.
122 123 124 125 126 127 128 129 130 131 132 133 134 135 136 137 138 139 140 141 142 143 144 145 146 147 148 149 150 151 152 153 154 155 156 157 158 159 160 161 162 163 164 165 166 167 168 169 170 171 172 173 174 175 176 177 178 179 180

  buffer_size_kb:

	This sets or displays the number of kilobytes each CPU
	buffer can hold. The tracer buffers are the same size
	for each CPU. The displayed number is the size of the
	CPU buffer and not total size of all buffers. The
	trace buffers are allocated in pages (blocks of memory
	that the kernel uses for allocation, usually 4 KB in size).
	If the last page allocated has room for more bytes
	than requested, the rest of the page will be used,
	making the actual allocation bigger than requested.
	( Note, the size may not be a multiple of the page size
	  due to buffer managment overhead. )

	This can only be updated when the current_tracer
	is set to "nop".

  tracing_cpumask:

	This is a mask that lets the user only trace
	on specified CPUS. The format is a hex string
	representing the CPUS.

  set_ftrace_filter:

	When dynamic ftrace is configured in (see the
	section below "dynamic ftrace"), the code is dynamically
	modified (code text rewrite) to disable calling of the
	function profiler (mcount). This lets tracing be configured
	in with practically no overhead in performance.  This also
	has a side effect of enabling or disabling specific functions
	to be traced. Echoing names of functions into this file
	will limit the trace to only those functions.

  set_ftrace_notrace:

	This has an effect opposite to that of
	set_ftrace_filter. Any function that is added here will not
	be traced. If a function exists in both set_ftrace_filter
	and set_ftrace_notrace,	the function will _not_ be traced.

  set_ftrace_pid:

	Have the function tracer only trace a single thread.

  set_graph_function:

	Set a "trigger" function where tracing should start
	with the function graph tracer (See the section
	"dynamic ftrace" for more details).

  available_filter_functions:

	This lists the functions that ftrace
	has processed and can trace. These are the function
	names that you can pass to "set_ftrace_filter" or
	"set_ftrace_notrace". (See the section "dynamic ftrace"
	below for more details.)
Steven Rostedt's avatar
Steven Rostedt committed
181 182 183 184 185


The Tracers
-----------

Steven Rostedt's avatar
Steven Rostedt committed
186
Here is the list of current tracers that may be configured.
Steven Rostedt's avatar
Steven Rostedt committed
187

188 189 190 191
  "function"

	Function call tracer to trace all kernel functions.

192
  "function_graph"
193 194 195 196 197 198 199 200 201 202 203 204 205 206 207 208 209 210

	Similar to the function tracer except that the
	function tracer probes the functions on their entry
	whereas the function graph tracer traces on both entry
	and exit of the functions. It then provides the ability
	to draw a graph of function calls similar to C code
	source.

  "sched_switch"

	Traces the context switches and wakeups between tasks.

  "irqsoff"

	Traces the areas that disable interrupts and saves
	the trace with the longest max latency.
	See tracing_max_latency. When a new max is recorded,
	it replaces the old trace. It is best to view this
211
	trace with the latency-format option enabled.
Steven Rostedt's avatar
Steven Rostedt committed
212

213
  "preemptoff"
214

215 216
	Similar to irqsoff but traces and records the amount of
	time for which preemption is disabled.
Steven Rostedt's avatar
Steven Rostedt committed
217

218
  "preemptirqsoff"
Steven Rostedt's avatar
Steven Rostedt committed
219

220 221 222
	Similar to irqsoff and preemptoff, but traces and
	records the largest time for which irqs and/or preemption
	is disabled.
Steven Rostedt's avatar
Steven Rostedt committed
223

224
  "wakeup"
Steven Rostedt's avatar
Steven Rostedt committed
225

226 227 228
	Traces and records the max latency that it takes for
	the highest priority task to get scheduled after
	it has been woken up.
Steven Rostedt's avatar
Steven Rostedt committed
229

230
  "hw-branch-tracer"
Steven Rostedt's avatar
Steven Rostedt committed
231

232 233 234 235 236 237 238 239
	Uses the BTS CPU feature on x86 CPUs to traces all
	branches executed.

  "nop"

	This is the "trace nothing" tracer. To remove all
	tracers from tracing simply echo "nop" into
	current_tracer.
240

Steven Rostedt's avatar
Steven Rostedt committed
241 242 243 244

Examples of using the tracer
----------------------------

245 246 247
Here are typical examples of using the tracers when controlling
them only with the debugfs interface (without using any
user-land utilities).
Steven Rostedt's avatar
Steven Rostedt committed
248 249 250 251

Output format:
--------------

Steven Rostedt's avatar
Steven Rostedt committed
252
Here is an example of the output format of the file "trace"
Steven Rostedt's avatar
Steven Rostedt committed
253 254

                             --------
Steven Rostedt's avatar
Steven Rostedt committed
255
# tracer: function
Steven Rostedt's avatar
Steven Rostedt committed
256 257 258 259 260 261 262 263
#
#           TASK-PID   CPU#    TIMESTAMP  FUNCTION
#              | |      |          |         |
            bash-4251  [01] 10152.583854: path_put <-path_walk
            bash-4251  [01] 10152.583855: dput <-path_put
            bash-4251  [01] 10152.583855: _atomic_dec_and_lock <-dput
                             --------

264 265 266 267 268 269 270
A header is printed with the tracer name that is represented by
the trace. In this case the tracer is "function". Then a header
showing the format. Task name "bash", the task PID "4251", the
CPU that it was running on "01", the timestamp in <secs>.<usecs>
format, the function name that was traced "path_put" and the
parent function that called this function "path_walk". The
timestamp is the time at which the function was entered.
Steven Rostedt's avatar
Steven Rostedt committed
271

272 273
The sched_switch tracer also includes tracing of task wakeups
and context switches.
Steven Rostedt's avatar
Steven Rostedt committed
274 275 276 277 278 279 280 281

     ksoftirqd/1-7     [01]  1453.070013:      7:115:R   +  2916:115:S
     ksoftirqd/1-7     [01]  1453.070013:      7:115:R   +    10:115:S
     ksoftirqd/1-7     [01]  1453.070013:      7:115:R ==>    10:115:R
        events/1-10    [01]  1453.070013:     10:115:S ==>  2916:115:R
     kondemand/1-2916  [01]  1453.070013:   2916:115:S ==>     7:115:R
     ksoftirqd/1-7     [01]  1453.070013:      7:115:S ==>     0:140:R

282 283
Wake ups are represented by a "+" and the context switches are
shown as "==>".  The format is:
Steven Rostedt's avatar
Steven Rostedt committed
284 285 286 287 288 289 290 291 292 293 294 295 296

 Context switches:

       Previous task              Next Task

  <pid>:<prio>:<state>  ==>  <pid>:<prio>:<state>

 Wake ups:

       Current task               Task waking up

  <pid>:<prio>:<state>    +  <pid>:<prio>:<state>

297 298 299 300 301 302
The prio is the internal kernel priority, which is the inverse
of the priority that is usually displayed by user-space tools.
Zero represents the highest priority (99). Prio 100 starts the
"nice" priorities with 100 being equal to nice -20 and 139 being
nice 19. The prio "140" is reserved for the idle task which is
the lowest priority thread (pid 0).
Steven Rostedt's avatar
Steven Rostedt committed
303 304 305 306 307


Latency trace format
--------------------

308 309
When the latency-format option is enabled, the trace file gives
somewhat more information to see why a latency happened.
310
Here is a typical trace.
Steven Rostedt's avatar
Steven Rostedt committed
311 312 313 314 315 316 317 318 319 320 321 322 323 324 325 326 327 328 329 330 331 332 333 334 335 336

# tracer: irqsoff
#
irqsoff latency trace v1.1.5 on 2.6.26-rc8
--------------------------------------------------------------------
 latency: 97 us, #3/3, CPU#0 | (M:preempt VP:0, KP:0, SP:0 HP:0 #P:2)
    -----------------
    | task: swapper-0 (uid:0 nice:0 policy:0 rt_prio:0)
    -----------------
 => started at: apic_timer_interrupt
 => ended at:   do_softirq

#                _------=> CPU#
#               / _-----=> irqs-off
#              | / _----=> need-resched
#              || / _---=> hardirq/softirq
#              ||| / _--=> preempt-depth
#              |||| /
#              |||||     delay
#  cmd     pid ||||| time  |   caller
#     \   /    |||||   \   |   /
  <idle>-0     0d..1    0us+: trace_hardirqs_off_thunk (apic_timer_interrupt)
  <idle>-0     0d.s.   97us : __do_softirq (do_softirq)
  <idle>-0     0d.s1   98us : trace_hardirqs_on (do_softirq)


337 338 339 340 341 342 343 344
This shows that the current tracer is "irqsoff" tracing the time
for which interrupts were disabled. It gives the trace version
and the version of the kernel upon which this was executed on
(2.6.26-rc8). Then it displays the max latency in microsecs (97
us). The number of trace entries displayed and the total number
recorded (both are three: #3/3). The type of preemption that was
used (PREEMPT). VP, KP, SP, and HP are always zero and are
reserved for later use. #P is the number of online CPUS (#P:2).
Steven Rostedt's avatar
Steven Rostedt committed
345

346 347
The task is the process that was running when the latency
occurred. (swapper pid: 0).
Steven Rostedt's avatar
Steven Rostedt committed
348

349 350
The start and stop (the functions in which the interrupts were
disabled and enabled respectively) that caused the latencies:
Steven Rostedt's avatar
Steven Rostedt committed
351 352 353 354 355 356 357 358 359 360 361

  apic_timer_interrupt is where the interrupts were disabled.
  do_softirq is where they were enabled again.

The next lines after the header are the trace itself. The header
explains which is which.

  cmd: The name of the process in the trace.

  pid: The PID of that process.

Steven Rostedt's avatar
Steven Rostedt committed
362
  CPU#: The CPU which the process was running on.
Steven Rostedt's avatar
Steven Rostedt committed
363 364

  irqs-off: 'd' interrupts are disabled. '.' otherwise.
365 366 367
	    Note: If the architecture does not support a way to
		  read the irq flags variable, an 'X' will always
		  be printed here.
Steven Rostedt's avatar
Steven Rostedt committed
368 369 370 371

  need-resched: 'N' task need_resched is set, '.' otherwise.

  hardirq/softirq:
Steven Rostedt's avatar
Steven Rostedt committed
372
	'H' - hard irq occurred inside a softirq.
Steven Rostedt's avatar
Steven Rostedt committed
373 374 375 376 377 378 379 380
	'h' - hard irq is running
	's' - soft irq is running
	'.' - normal context.

  preempt-depth: The level of preempt_disabled

The above is mostly meaningful for kernel developers.

381 382 383 384
  time: When the latency-format option is enabled, the trace file
	output includes a timestamp relative to the start of the
	trace. This differs from the output when latency-format
	is disabled, which includes an absolute timestamp.
Steven Rostedt's avatar
Steven Rostedt committed
385 386

  delay: This is just to help catch your eye a bit better. And
387 388 389 390 391 392
	 needs to be fixed to be only relative to the same CPU.
	 The marks are determined by the difference between this
	 current trace and the next trace.
	  '!' - greater than preempt_mark_thresh (default 100)
	  '+' - greater than 1 microsecond
	  ' ' - less than or equal to 1 microsecond.
Steven Rostedt's avatar
Steven Rostedt committed
393 394 395 396

  The rest is the same as the 'trace' file.


397 398
trace_options
-------------
Steven Rostedt's avatar
Steven Rostedt committed
399

400 401
The trace_options file is used to control what gets printed in
the trace output. To see what is available, simply cat the file:
Steven Rostedt's avatar
Steven Rostedt committed
402

403
  cat trace_options
Steven Rostedt's avatar
Steven Rostedt committed
404
  print-parent nosym-offset nosym-addr noverbose noraw nohex nobin \
405
  noblock nostacktrace nosched-tree nouserstacktrace nosym-userobj
Steven Rostedt's avatar
Steven Rostedt committed
406

407 408
To disable one of the options, echo in the option prepended with
"no".
Steven Rostedt's avatar
Steven Rostedt committed
409

410
  echo noprint-parent > trace_options
Steven Rostedt's avatar
Steven Rostedt committed
411 412 413

To enable an option, leave off the "no".

414
  echo sym-offset > trace_options
Steven Rostedt's avatar
Steven Rostedt committed
415 416 417

Here are the available options:

418 419
  print-parent - On function traces, display the calling (parent)
		 function as well as the function being traced.
Steven Rostedt's avatar
Steven Rostedt committed
420 421 422 423 424 425 426 427

  print-parent:
   bash-4000  [01]  1477.606694: simple_strtoul <-strict_strtoul

  noprint-parent:
   bash-4000  [01]  1477.606694: simple_strtoul


428 429 430 431
  sym-offset - Display not only the function name, but also the
	       offset in the function. For example, instead of
	       seeing just "ktime_get", you will see
	       "ktime_get+0xb/0x20".
Steven Rostedt's avatar
Steven Rostedt committed
432 433 434 435

  sym-offset:
   bash-4000  [01]  1477.606694: simple_strtoul+0x6/0xa0

436 437
  sym-addr - this will also display the function address as well
	     as the function name.
Steven Rostedt's avatar
Steven Rostedt committed
438 439 440 441

  sym-addr:
   bash-4000  [01]  1477.606694: simple_strtoul <c0339346>

442 443
  verbose - This deals with the trace file when the
            latency-format option is enabled.
Steven Rostedt's avatar
Steven Rostedt committed
444 445 446 447

    bash  4000 1 0 00000000 00010a95 [58127d26] 1720.415ms \
    (+0.000ms): simple_strtoul (strict_strtoul)

448 449 450
  raw - This will display raw numbers. This option is best for
	use with user applications that can translate the raw
	numbers better than having it done in the kernel.
Steven Rostedt's avatar
Steven Rostedt committed
451

452 453
  hex - Similar to raw, but the numbers will be in a hexadecimal
	format.
Steven Rostedt's avatar
Steven Rostedt committed
454 455 456 457 458

  bin - This will print out the formats in raw binary.

  block - TBD (needs update)

459 460 461 462
  stacktrace - This is one of the options that changes the trace
	       itself. When a trace is recorded, so is the stack
	       of functions. This allows for back traces of
	       trace sites.
Steven Rostedt's avatar
Steven Rostedt committed
463

464 465
  userstacktrace - This option changes the trace. It records a
		   stacktrace of the current userspace thread.
466

467 468 469 470 471 472
  sym-userobj - when user stacktrace are enabled, look up which
		object the address belongs to, and print a
		relative address. This is especially useful when
		ASLR is on, otherwise you don't get a chance to
		resolve the address to object/file/line after
		the app is no longer running
473

474
		The lookup is performed when you read
475
		trace,trace_pipe. Example:
476 477 478 479

		a.out-1623  [000] 40874.465068: /root/a.out[+0x480] <-/root/a.out[+0
x494] <- /root/a.out[+0x4a8] <- /lib/libc-2.7.so[+0x1e1a6]

480 481 482
  sched-tree - trace all tasks that are on the runqueue, at
	       every scheduling event. Will add overhead if
	       there's a lot of tasks running at once.
Steven Rostedt's avatar
Steven Rostedt committed
483

484 485 486 487 488
  latency-format - This option changes the trace. When
                   it is enabled, the trace displays
                   additional information about the
                   latencies, as described in "Latency
                   trace format".
Steven Rostedt's avatar
Steven Rostedt committed
489 490 491 492

sched_switch
------------

Steven Rostedt's avatar
Steven Rostedt committed
493
This tracer simply records schedule switches. Here is an example
Steven Rostedt's avatar
Steven Rostedt committed
494
of how to use it.
Steven Rostedt's avatar
Steven Rostedt committed
495

496 497
 # echo sched_switch > current_tracer
 # echo 1 > tracing_enabled
Steven Rostedt's avatar
Steven Rostedt committed
498
 # sleep 1
499 500
 # echo 0 > tracing_enabled
 # cat trace
Steven Rostedt's avatar
Steven Rostedt committed
501 502 503 504 505 506 507 508 509 510 511 512 513 514 515 516 517 518 519 520 521 522 523

# tracer: sched_switch
#
#           TASK-PID   CPU#    TIMESTAMP  FUNCTION
#              | |      |          |         |
            bash-3997  [01]   240.132281:   3997:120:R   +  4055:120:R
            bash-3997  [01]   240.132284:   3997:120:R ==>  4055:120:R
           sleep-4055  [01]   240.132371:   4055:120:S ==>  3997:120:R
            bash-3997  [01]   240.132454:   3997:120:R   +  4055:120:S
            bash-3997  [01]   240.132457:   3997:120:R ==>  4055:120:R
           sleep-4055  [01]   240.132460:   4055:120:D ==>  3997:120:R
            bash-3997  [01]   240.132463:   3997:120:R   +  4055:120:D
            bash-3997  [01]   240.132465:   3997:120:R ==>  4055:120:R
          <idle>-0     [00]   240.132589:      0:140:R   +     4:115:S
          <idle>-0     [00]   240.132591:      0:140:R ==>     4:115:R
     ksoftirqd/0-4     [00]   240.132595:      4:115:S ==>     0:140:R
          <idle>-0     [00]   240.132598:      0:140:R   +     4:115:S
          <idle>-0     [00]   240.132599:      0:140:R ==>     4:115:R
     ksoftirqd/0-4     [00]   240.132603:      4:115:S ==>     0:140:R
           sleep-4055  [01]   240.133058:   4055:120:S ==>  3997:120:R
 [...]


524 525 526 527
As we have discussed previously about this format, the header
shows the name of the trace and points to the options. The
"FUNCTION" is a misnomer since here it represents the wake ups
and context switches.
Steven Rostedt's avatar
Steven Rostedt committed
528

529 530 531 532 533 534 535 536
The sched_switch file only lists the wake ups (represented with
'+') and context switches ('==>') with the previous task or
current task first followed by the next task or task waking up.
The format for both of these is PID:KERNEL-PRIO:TASK-STATE.
Remember that the KERNEL-PRIO is the inverse of the actual
priority with zero (0) being the highest priority and the nice
values starting at 100 (nice -20). Below is a quick chart to map
the kernel priority to user land priorities.
Steven Rostedt's avatar
Steven Rostedt committed
537

538 539 540 541 542 543 544 545 546 547 548 549
   Kernel Space                     User Space
 ===============================================================
   0(high) to  98(low)     user RT priority 99(high) to 1(low)
                           with SCHED_RR or SCHED_FIFO
 ---------------------------------------------------------------
  99                       sched_priority is not used in scheduling
                           decisions(it must be specified as 0)
 ---------------------------------------------------------------
 100(high) to 139(low)     user nice -20(high) to 19(low)
 ---------------------------------------------------------------
 140                       idle task priority
 ---------------------------------------------------------------
Steven Rostedt's avatar
Steven Rostedt committed
550 551 552 553 554

The task states are:

 R - running : wants to run, may not actually be running
 S - sleep   : process is waiting to be woken up (handles signals)
Steven Rostedt's avatar
Steven Rostedt committed
555 556
 D - disk sleep (uninterruptible sleep) : process must be woken up
					(ignores signals)
Steven Rostedt's avatar
Steven Rostedt committed
557 558 559 560 561 562 563 564 565
 T - stopped : process suspended
 t - traced  : process is being traced (with something like gdb)
 Z - zombie  : process waiting to be cleaned up
 X - unknown


ftrace_enabled
--------------

566 567 568 569
The following tracers (listed below) give different output
depending on whether or not the sysctl ftrace_enabled is set. To
set ftrace_enabled, one can either use the sysctl function or
set it via the proc file system interface.
Steven Rostedt's avatar
Steven Rostedt committed
570 571 572 573 574 575 576

  sysctl kernel.ftrace_enabled=1

 or

  echo 1 > /proc/sys/kernel/ftrace_enabled

577 578
To disable ftrace_enabled simply replace the '1' with '0' in the
above commands.
Steven Rostedt's avatar
Steven Rostedt committed
579

580 581 582
When ftrace_enabled is set the tracers will also record the
functions that are within the trace. The descriptions of the
tracers will also show an example with ftrace enabled.
Steven Rostedt's avatar
Steven Rostedt committed
583 584 585 586 587 588 589


irqsoff
-------

When interrupts are disabled, the CPU can not react to any other
external event (besides NMIs and SMIs). This prevents the timer
590 591 592
interrupt from triggering or the mouse interrupt from letting
the kernel know of a new mouse event. The result is a latency
with the reaction time.
Steven Rostedt's avatar
Steven Rostedt committed
593

594 595 596 597 598
The irqsoff tracer tracks the time for which interrupts are
disabled. When a new maximum latency is hit, the tracer saves
the trace leading up to that latency point so that every time a
new maximum is reached, the old saved trace is discarded and the
new trace is saved.
Steven Rostedt's avatar
Steven Rostedt committed
599

600 601
To reset the maximum, echo 0 into tracing_max_latency. Here is
an example:
Steven Rostedt's avatar
Steven Rostedt committed
602

603
 # echo irqsoff > current_tracer
604
 # echo latency-format > trace_options
605 606
 # echo 0 > tracing_max_latency
 # echo 1 > tracing_enabled
Steven Rostedt's avatar
Steven Rostedt committed
607 608
 # ls -ltr
 [...]
609
 # echo 0 > tracing_enabled
610
 # cat trace
Steven Rostedt's avatar
Steven Rostedt committed
611 612
# tracer: irqsoff
#
Steven Rostedt's avatar
Steven Rostedt committed
613
irqsoff latency trace v1.1.5 on 2.6.26
Steven Rostedt's avatar
Steven Rostedt committed
614
--------------------------------------------------------------------
Steven Rostedt's avatar
Steven Rostedt committed
615
 latency: 12 us, #3/3, CPU#1 | (M:preempt VP:0, KP:0, SP:0 HP:0 #P:2)
Steven Rostedt's avatar
Steven Rostedt committed
616
    -----------------
Steven Rostedt's avatar
Steven Rostedt committed
617
    | task: bash-3730 (uid:0 nice:0 policy:0 rt_prio:0)
Steven Rostedt's avatar
Steven Rostedt committed
618
    -----------------
Steven Rostedt's avatar
Steven Rostedt committed
619 620
 => started at: sys_setpgid
 => ended at:   sys_setpgid
Steven Rostedt's avatar
Steven Rostedt committed
621 622 623 624 625 626 627 628 629 630

#                _------=> CPU#
#               / _-----=> irqs-off
#              | / _----=> need-resched
#              || / _---=> hardirq/softirq
#              ||| / _--=> preempt-depth
#              |||| /
#              |||||     delay
#  cmd     pid ||||| time  |   caller
#     \   /    |||||   \   |   /
Steven Rostedt's avatar
Steven Rostedt committed
631 632 633
    bash-3730  1d...    0us : _write_lock_irq (sys_setpgid)
    bash-3730  1d..1    1us+: _write_unlock_irq (sys_setpgid)
    bash-3730  1d..2   14us : trace_hardirqs_on (sys_setpgid)
Steven Rostedt's avatar
Steven Rostedt committed
634 635


Steven Rostedt's avatar
Steven Rostedt committed
636
Here we see that that we had a latency of 12 microsecs (which is
637 638 639 640 641
very good). The _write_lock_irq in sys_setpgid disabled
interrupts. The difference between the 12 and the displayed
timestamp 14us occurred because the clock was incremented
between the time of recording the max latency and the time of
recording the function that had that latency.
Steven Rostedt's avatar
Steven Rostedt committed
642

Steven Rostedt's avatar
Steven Rostedt committed
643 644
Note the above example had ftrace_enabled not set. If we set the
ftrace_enabled, we get a much larger output:
Steven Rostedt's avatar
Steven Rostedt committed
645 646 647 648 649 650 651 652 653 654 655 656 657 658 659 660 661 662 663 664 665 666 667 668 669 670 671 672 673 674 675 676 677 678 679 680 681 682 683 684 685 686 687 688 689 690 691

# tracer: irqsoff
#
irqsoff latency trace v1.1.5 on 2.6.26-rc8
--------------------------------------------------------------------
 latency: 50 us, #101/101, CPU#0 | (M:preempt VP:0, KP:0, SP:0 HP:0 #P:2)
    -----------------
    | task: ls-4339 (uid:0 nice:0 policy:0 rt_prio:0)
    -----------------
 => started at: __alloc_pages_internal
 => ended at:   __alloc_pages_internal

#                _------=> CPU#
#               / _-----=> irqs-off
#              | / _----=> need-resched
#              || / _---=> hardirq/softirq
#              ||| / _--=> preempt-depth
#              |||| /
#              |||||     delay
#  cmd     pid ||||| time  |   caller
#     \   /    |||||   \   |   /
      ls-4339  0...1    0us+: get_page_from_freelist (__alloc_pages_internal)
      ls-4339  0d..1    3us : rmqueue_bulk (get_page_from_freelist)
      ls-4339  0d..1    3us : _spin_lock (rmqueue_bulk)
      ls-4339  0d..1    4us : add_preempt_count (_spin_lock)
      ls-4339  0d..2    4us : __rmqueue (rmqueue_bulk)
      ls-4339  0d..2    5us : __rmqueue_smallest (__rmqueue)
      ls-4339  0d..2    5us : __mod_zone_page_state (__rmqueue_smallest)
      ls-4339  0d..2    6us : __rmqueue (rmqueue_bulk)
      ls-4339  0d..2    6us : __rmqueue_smallest (__rmqueue)
      ls-4339  0d..2    7us : __mod_zone_page_state (__rmqueue_smallest)
      ls-4339  0d..2    7us : __rmqueue (rmqueue_bulk)
      ls-4339  0d..2    8us : __rmqueue_smallest (__rmqueue)
[...]
      ls-4339  0d..2   46us : __rmqueue_smallest (__rmqueue)
      ls-4339  0d..2   47us : __mod_zone_page_state (__rmqueue_smallest)
      ls-4339  0d..2   47us : __rmqueue (rmqueue_bulk)
      ls-4339  0d..2   48us : __rmqueue_smallest (__rmqueue)
      ls-4339  0d..2   48us : __mod_zone_page_state (__rmqueue_smallest)
      ls-4339  0d..2   49us : _spin_unlock (rmqueue_bulk)
      ls-4339  0d..2   49us : sub_preempt_count (_spin_unlock)
      ls-4339  0d..1   50us : get_page_from_freelist (__alloc_pages_internal)
      ls-4339  0d..2   51us : trace_hardirqs_on (__alloc_pages_internal)



Here we traced a 50 microsecond latency. But we also see all the
692 693 694 695
functions that were called during that time. Note that by
enabling function tracing, we incur an added overhead. This
overhead may extend the latency times. But nevertheless, this
trace has provided some very helpful debugging information.
Steven Rostedt's avatar
Steven Rostedt committed
696 697 698 699 700


preemptoff
----------

701 702 703 704
When preemption is disabled, we may be able to receive
interrupts but the task cannot be preempted and a higher
priority task must wait for preemption to be enabled again
before it can preempt a lower priority task.
Steven Rostedt's avatar
Steven Rostedt committed
705

Steven Rostedt's avatar
Steven Rostedt committed
706
The preemptoff tracer traces the places that disable preemption.
707 708 709
Like the irqsoff tracer, it records the maximum latency for
which preemption was disabled. The control of preemptoff tracer
is much like the irqsoff tracer.
Steven Rostedt's avatar
Steven Rostedt committed
710

711
 # echo preemptoff > current_tracer
712
 # echo latency-format > trace_options
713 714
 # echo 0 > tracing_max_latency
 # echo 1 > tracing_enabled
Steven Rostedt's avatar
Steven Rostedt committed
715 716
 # ls -ltr
 [...]
717
 # echo 0 > tracing_enabled
718
 # cat trace
Steven Rostedt's avatar
Steven Rostedt committed
719 720 721 722 723 724 725 726 727 728 729 730 731 732 733 734 735 736 737 738 739 740 741 742 743
# tracer: preemptoff
#
preemptoff latency trace v1.1.5 on 2.6.26-rc8
--------------------------------------------------------------------
 latency: 29 us, #3/3, CPU#0 | (M:preempt VP:0, KP:0, SP:0 HP:0 #P:2)
    -----------------
    | task: sshd-4261 (uid:0 nice:0 policy:0 rt_prio:0)
    -----------------
 => started at: do_IRQ
 => ended at:   __do_softirq

#                _------=> CPU#
#               / _-----=> irqs-off
#              | / _----=> need-resched
#              || / _---=> hardirq/softirq
#              ||| / _--=> preempt-depth
#              |||| /
#              |||||     delay
#  cmd     pid ||||| time  |   caller
#     \   /    |||||   \   |   /
    sshd-4261  0d.h.    0us+: irq_enter (do_IRQ)
    sshd-4261  0d.s.   29us : _local_bh_enable (__do_softirq)
    sshd-4261  0d.s1   30us : trace_preempt_on (__do_softirq)


744 745 746 747 748 749
This has some more changes. Preemption was disabled when an
interrupt came in (notice the 'h'), and was enabled while doing
a softirq. (notice the 's'). But we also see that interrupts
have been disabled when entering the preempt off section and
leaving it (the 'd'). We do not know if interrupts were enabled
in the mean time.
Steven Rostedt's avatar
Steven Rostedt committed
750 751 752 753 754 755 756 757 758 759 760 761 762 763 764 765 766 767 768 769 770 771 772 773 774 775 776 777 778 779 780 781 782 783 784 785 786 787 788 789 790 791 792 793 794 795 796 797 798 799 800 801 802 803 804 805 806 807

# tracer: preemptoff
#
preemptoff latency trace v1.1.5 on 2.6.26-rc8
--------------------------------------------------------------------
 latency: 63 us, #87/87, CPU#0 | (M:preempt VP:0, KP:0, SP:0 HP:0 #P:2)
    -----------------
    | task: sshd-4261 (uid:0 nice:0 policy:0 rt_prio:0)
    -----------------
 => started at: remove_wait_queue
 => ended at:   __do_softirq

#                _------=> CPU#
#               / _-----=> irqs-off
#              | / _----=> need-resched
#              || / _---=> hardirq/softirq
#              ||| / _--=> preempt-depth
#              |||| /
#              |||||     delay
#  cmd     pid ||||| time  |   caller
#     \   /    |||||   \   |   /
    sshd-4261  0d..1    0us : _spin_lock_irqsave (remove_wait_queue)
    sshd-4261  0d..1    1us : _spin_unlock_irqrestore (remove_wait_queue)
    sshd-4261  0d..1    2us : do_IRQ (common_interrupt)
    sshd-4261  0d..1    2us : irq_enter (do_IRQ)
    sshd-4261  0d..1    2us : idle_cpu (irq_enter)
    sshd-4261  0d..1    3us : add_preempt_count (irq_enter)
    sshd-4261  0d.h1    3us : idle_cpu (irq_enter)
    sshd-4261  0d.h.    4us : handle_fasteoi_irq (do_IRQ)
[...]
    sshd-4261  0d.h.   12us : add_preempt_count (_spin_lock)
    sshd-4261  0d.h1   12us : ack_ioapic_quirk_irq (handle_fasteoi_irq)
    sshd-4261  0d.h1   13us : move_native_irq (ack_ioapic_quirk_irq)
    sshd-4261  0d.h1   13us : _spin_unlock (handle_fasteoi_irq)
    sshd-4261  0d.h1   14us : sub_preempt_count (_spin_unlock)
    sshd-4261  0d.h1   14us : irq_exit (do_IRQ)
    sshd-4261  0d.h1   15us : sub_preempt_count (irq_exit)
    sshd-4261  0d..2   15us : do_softirq (irq_exit)
    sshd-4261  0d...   15us : __do_softirq (do_softirq)
    sshd-4261  0d...   16us : __local_bh_disable (__do_softirq)
    sshd-4261  0d...   16us+: add_preempt_count (__local_bh_disable)
    sshd-4261  0d.s4   20us : add_preempt_count (__local_bh_disable)
    sshd-4261  0d.s4   21us : sub_preempt_count (local_bh_enable)
    sshd-4261  0d.s5   21us : sub_preempt_count (local_bh_enable)
[...]
    sshd-4261  0d.s6   41us : add_preempt_count (__local_bh_disable)
    sshd-4261  0d.s6   42us : sub_preempt_count (local_bh_enable)
    sshd-4261  0d.s7   42us : sub_preempt_count (local_bh_enable)
    sshd-4261  0d.s5   43us : add_preempt_count (__local_bh_disable)
    sshd-4261  0d.s5   43us : sub_preempt_count (local_bh_enable_ip)
    sshd-4261  0d.s6   44us : sub_preempt_count (local_bh_enable_ip)
    sshd-4261  0d.s5   44us : add_preempt_count (__local_bh_disable)
    sshd-4261  0d.s5   45us : sub_preempt_count (local_bh_enable)
[...]
    sshd-4261  0d.s.   63us : _local_bh_enable (__do_softirq)
    sshd-4261  0d.s1   64us : trace_preempt_on (__do_softirq)


808 809 810 811 812 813
The above is an example of the preemptoff trace with
ftrace_enabled set. Here we see that interrupts were disabled
the entire time. The irq_enter code lets us know that we entered
an interrupt 'h'. Before that, the functions being traced still
show that it is not in an interrupt, but we can see from the
functions themselves that this is not the case.
Steven Rostedt's avatar
Steven Rostedt committed
814

815 816 817 818 819 820 821 822
Notice that __do_softirq when called does not have a
preempt_count. It may seem that we missed a preempt enabling.
What really happened is that the preempt count is held on the
thread's stack and we switched to the softirq stack (4K stacks
in effect). The code does not copy the preempt count, but
because interrupts are disabled, we do not need to worry about
it. Having a tracer like this is good for letting people know
what really happens inside the kernel.
Steven Rostedt's avatar
Steven Rostedt committed
823 824 825 826 827


preemptirqsoff
--------------

828 829 830 831
Knowing the locations that have interrupts disabled or
preemption disabled for the longest times is helpful. But
sometimes we would like to know when either preemption and/or
interrupts are disabled.
Steven Rostedt's avatar
Steven Rostedt committed
832

Steven Rostedt's avatar
Steven Rostedt committed
833
Consider the following code:
Steven Rostedt's avatar
Steven Rostedt committed
834 835 836 837 838 839 840 841 842 843 844 845 846 847 848 849 850

    local_irq_disable();
    call_function_with_irqs_off();
    preempt_disable();
    call_function_with_irqs_and_preemption_off();
    local_irq_enable();
    call_function_with_preemption_off();
    preempt_enable();

The irqsoff tracer will record the total length of
call_function_with_irqs_off() and
call_function_with_irqs_and_preemption_off().

The preemptoff tracer will record the total length of
call_function_with_irqs_and_preemption_off() and
call_function_with_preemption_off().

851 852 853 854
But neither will trace the time that interrupts and/or
preemption is disabled. This total time is the time that we can
not schedule. To record this time, use the preemptirqsoff
tracer.
Steven Rostedt's avatar
Steven Rostedt committed
855

856 857
Again, using this trace is much like the irqsoff and preemptoff
tracers.
Steven Rostedt's avatar
Steven Rostedt committed
858

859
 # echo preemptirqsoff > current_tracer
860
 # echo latency-format > trace_options
861 862
 # echo 0 > tracing_max_latency
 # echo 1 > tracing_enabled
Steven Rostedt's avatar
Steven Rostedt committed
863 864
 # ls -ltr
 [...]
865
 # echo 0 > tracing_enabled
866
 # cat trace
Steven Rostedt's avatar
Steven Rostedt committed
867 868 869 870 871 872 873 874 875 876 877 878 879 880 881 882 883 884 885 886 887 888 889 890 891 892 893
# tracer: preemptirqsoff
#
preemptirqsoff latency trace v1.1.5 on 2.6.26-rc8
--------------------------------------------------------------------
 latency: 293 us, #3/3, CPU#0 | (M:preempt VP:0, KP:0, SP:0 HP:0 #P:2)
    -----------------
    | task: ls-4860 (uid:0 nice:0 policy:0 rt_prio:0)
    -----------------
 => started at: apic_timer_interrupt
 => ended at:   __do_softirq

#                _------=> CPU#
#               / _-----=> irqs-off
#              | / _----=> need-resched
#              || / _---=> hardirq/softirq
#              ||| / _--=> preempt-depth
#              |||| /
#              |||||     delay
#  cmd     pid ||||| time  |   caller
#     \   /    |||||   \   |   /
      ls-4860  0d...    0us!: trace_hardirqs_off_thunk (apic_timer_interrupt)
      ls-4860  0d.s.  294us : _local_bh_enable (__do_softirq)
      ls-4860  0d.s1  294us : trace_preempt_on (__do_softirq)



The trace_hardirqs_off_thunk is called from assembly on x86 when
894 895 896 897
interrupts are disabled in the assembly code. Without the
function tracing, we do not know if interrupts were enabled
within the preemption points. We do see that it started with
preemption enabled.
Steven Rostedt's avatar
Steven Rostedt committed
898 899 900 901 902 903 904 905 906 907 908 909 910 911 912 913 914 915 916 917 918 919 920 921 922 923 924 925 926 927 928 929 930 931 932 933 934 935 936 937 938 939 940 941 942 943 944 945 946 947 948 949 950 951 952 953 954 955 956 957 958 959 960 961 962 963 964 965 966 967 968 969 970 971 972 973 974 975 976 977 978 979 980 981 982 983 984

Here is a trace with ftrace_enabled set:


# tracer: preemptirqsoff
#
preemptirqsoff latency trace v1.1.5 on 2.6.26-rc8
--------------------------------------------------------------------
 latency: 105 us, #183/183, CPU#0 | (M:preempt VP:0, KP:0, SP:0 HP:0 #P:2)
    -----------------
    | task: sshd-4261 (uid:0 nice:0 policy:0 rt_prio:0)
    -----------------
 => started at: write_chan
 => ended at:   __do_softirq

#                _------=> CPU#
#               / _-----=> irqs-off
#              | / _----=> need-resched
#              || / _---=> hardirq/softirq
#              ||| / _--=> preempt-depth
#              |||| /
#              |||||     delay
#  cmd     pid ||||| time  |   caller
#     \   /    |||||   \   |   /
      ls-4473  0.N..    0us : preempt_schedule (write_chan)
      ls-4473  0dN.1    1us : _spin_lock (schedule)
      ls-4473  0dN.1    2us : add_preempt_count (_spin_lock)
      ls-4473  0d..2    2us : put_prev_task_fair (schedule)
[...]
      ls-4473  0d..2   13us : set_normalized_timespec (ktime_get_ts)
      ls-4473  0d..2   13us : __switch_to (schedule)
    sshd-4261  0d..2   14us : finish_task_switch (schedule)
    sshd-4261  0d..2   14us : _spin_unlock_irq (finish_task_switch)
    sshd-4261  0d..1   15us : add_preempt_count (_spin_lock_irqsave)
    sshd-4261  0d..2   16us : _spin_unlock_irqrestore (hrtick_set)
    sshd-4261  0d..2   16us : do_IRQ (common_interrupt)
    sshd-4261  0d..2   17us : irq_enter (do_IRQ)
    sshd-4261  0d..2   17us : idle_cpu (irq_enter)
    sshd-4261  0d..2   18us : add_preempt_count (irq_enter)
    sshd-4261  0d.h2   18us : idle_cpu (irq_enter)
    sshd-4261  0d.h.   18us : handle_fasteoi_irq (do_IRQ)
    sshd-4261  0d.h.   19us : _spin_lock (handle_fasteoi_irq)
    sshd-4261  0d.h.   19us : add_preempt_count (_spin_lock)
    sshd-4261  0d.h1   20us : _spin_unlock (handle_fasteoi_irq)
    sshd-4261  0d.h1   20us : sub_preempt_count (_spin_unlock)
[...]
    sshd-4261  0d.h1   28us : _spin_unlock (handle_fasteoi_irq)
    sshd-4261  0d.h1   29us : sub_preempt_count (_spin_unlock)
    sshd-4261  0d.h2   29us : irq_exit (do_IRQ)
    sshd-4261  0d.h2   29us : sub_preempt_count (irq_exit)
    sshd-4261  0d..3   30us : do_softirq (irq_exit)
    sshd-4261  0d...   30us : __do_softirq (do_softirq)
    sshd-4261  0d...   31us : __local_bh_disable (__do_softirq)
    sshd-4261  0d...   31us+: add_preempt_count (__local_bh_disable)
    sshd-4261  0d.s4   34us : add_preempt_count (__local_bh_disable)
[...]
    sshd-4261  0d.s3   43us : sub_preempt_count (local_bh_enable_ip)
    sshd-4261  0d.s4   44us : sub_preempt_count (local_bh_enable_ip)
    sshd-4261  0d.s3   44us : smp_apic_timer_interrupt (apic_timer_interrupt)
    sshd-4261  0d.s3   45us : irq_enter (smp_apic_timer_interrupt)
    sshd-4261  0d.s3   45us : idle_cpu (irq_enter)
    sshd-4261  0d.s3   46us : add_preempt_count (irq_enter)
    sshd-4261  0d.H3   46us : idle_cpu (irq_enter)
    sshd-4261  0d.H3   47us : hrtimer_interrupt (smp_apic_timer_interrupt)
    sshd-4261  0d.H3   47us : ktime_get (hrtimer_interrupt)
[...]
    sshd-4261  0d.H3   81us : tick_program_event (hrtimer_interrupt)
    sshd-4261  0d.H3   82us : ktime_get (tick_program_event)
    sshd-4261  0d.H3   82us : ktime_get_ts (ktime_get)
    sshd-4261  0d.H3   83us : getnstimeofday (ktime_get_ts)
    sshd-4261  0d.H3   83us : set_normalized_timespec (ktime_get_ts)
    sshd-4261  0d.H3   84us : clockevents_program_event (tick_program_event)
    sshd-4261  0d.H3   84us : lapic_next_event (clockevents_program_event)
    sshd-4261  0d.H3   85us : irq_exit (smp_apic_timer_interrupt)
    sshd-4261  0d.H3   85us : sub_preempt_count (irq_exit)
    sshd-4261  0d.s4   86us : sub_preempt_count (irq_exit)
    sshd-4261  0d.s3   86us : add_preempt_count (__local_bh_disable)
[...]
    sshd-4261  0d.s1   98us : sub_preempt_count (net_rx_action)
    sshd-4261  0d.s.   99us : add_preempt_count (_spin_lock_irq)
    sshd-4261  0d.s1   99us+: _spin_unlock_irq (run_timer_softirq)
    sshd-4261  0d.s.  104us : _local_bh_enable (__do_softirq)
    sshd-4261  0d.s.  104us : sub_preempt_count (_local_bh_enable)
    sshd-4261  0d.s.  105us : _local_bh_enable (__do_softirq)
    sshd-4261  0d.s1  105us : trace_preempt_on (__do_softirq)


985 986 987 988 989 990 991 992
This is a very interesting trace. It started with the preemption
of the ls task. We see that the task had the "need_resched" bit
set via the 'N' in the trace.  Interrupts were disabled before
the spin_lock at the beginning of the trace. We see that a
schedule took place to run sshd.  When the interrupts were
enabled, we took an interrupt. On return from the interrupt
handler, the softirq ran. We took another interrupt while
running the softirq as we see from the capital 'H'.
Steven Rostedt's avatar
Steven Rostedt committed
993 994 995 996 997


wakeup
------

998 999 1000 1001 1002 1003 1004 1005
In a Real-Time environment it is very important to know the
wakeup time it takes for the highest priority task that is woken
up to the time that it executes. This is also known as "schedule
latency". I stress the point that this is about RT tasks. It is
also important to know the scheduling latency of non-RT tasks,
but the average schedule latency is better for non-RT tasks.
Tools like LatencyTop are more appropriate for such
measurements.
Steven Rostedt's avatar
Steven Rostedt committed
1006

Steven Rostedt's avatar
Steven Rostedt committed
1007
Real-Time environments are interested in the worst case latency.
1008 1009 1010 1011 1012 1013 1014 1015 1016 1017 1018 1019 1020
That is the longest latency it takes for something to happen,
and not the average. We can have a very fast scheduler that may
only have a large latency once in a while, but that would not
work well with Real-Time tasks.  The wakeup tracer was designed
to record the worst case wakeups of RT tasks. Non-RT tasks are
not recorded because the tracer only records one worst case and
tracing non-RT tasks that are unpredictable will overwrite the
worst case latency of RT tasks.

Since this tracer only deals with RT tasks, we will run this
slightly differently than we did with the previous tracers.
Instead of performing an 'ls', we will run 'sleep 1' under
'chrt' which changes the priority of the task.
Steven Rostedt's avatar
Steven Rostedt committed
1021

1022
 # echo wakeup > current_tracer
1023
 # echo latency-format > trace_options
1024 1025
 # echo 0 > tracing_max_latency
 # echo 1 > tracing_enabled
Steven Rostedt's avatar
Steven Rostedt committed
1026
 # chrt -f 5 sleep 1
1027
 # echo 0 > tracing_enabled
1028
 # cat trace
Steven Rostedt's avatar
Steven Rostedt committed
1029 1030 1031 1032 1033 1034 1035 1036 1037 1038 1039 1040 1041 1042 1043 1044 1045 1046 1047 1048 1049 1050
# tracer: wakeup
#
wakeup latency trace v1.1.5 on 2.6.26-rc8
--------------------------------------------------------------------
 latency: 4 us, #2/2, CPU#1 | (M:preempt VP:0, KP:0, SP:0 HP:0 #P:2)
    -----------------
    | task: sleep-4901 (uid:0 nice:0 policy:1 rt_prio:5)
    -----------------

#                _------=> CPU#
#               / _-----=> irqs-off
#              | / _----=> need-resched
#              || / _---=> hardirq/softirq
#              ||| / _--=> preempt-depth
#              |||| /
#              |||||     delay
#  cmd     pid ||||| time  |   caller
#     \   /    |||||   \   |   /
  <idle>-0     1d.h4    0us+: try_to_wake_up (wake_up_process)
  <idle>-0     1d..4    4us : schedule (cpu_idle)


1051 1052 1053 1054 1055
Running this on an idle system, we see that it only took 4
microseconds to perform the task switch.  Note, since the trace
marker in the schedule is before the actual "switch", we stop
the tracing when the recorded task is about to schedule in. This
may change if we add a new marker at the end of the scheduler.
Steven Rostedt's avatar
Steven Rostedt committed
1056

1057 1058 1059 1060
Notice that the recorded task is 'sleep' with the PID of 4901
and it has an rt_prio of 5. This priority is user-space priority
and not the internal kernel priority. The policy is 1 for
SCHED_FIFO and 2 for SCHED_RR.
Steven Rostedt's avatar
Steven Rostedt committed
1061 1062 1063 1064 1065 1066 1067 1068 1069 1070 1071 1072 1073 1074 1075 1076 1077 1078 1079 1080 1081 1082 1083 1084 1085 1086 1087 1088 1089 1090 1091 1092 1093 1094 1095 1096 1097 1098 1099 1100 1101 1102 1103 1104 1105 1106 1107 1108 1109 1110 1111 1112 1113 1114 1115 1116

Doing the same with chrt -r 5 and ftrace_enabled set.

# tracer: wakeup
#
wakeup latency trace v1.1.5 on 2.6.26-rc8
--------------------------------------------------------------------
 latency: 50 us, #60/60, CPU#1 | (M:preempt VP:0, KP:0, SP:0 HP:0 #P:2)
    -----------------
    | task: sleep-4068 (uid:0 nice:0 policy:2 rt_prio:5)
    -----------------

#                _------=> CPU#
#               / _-----=> irqs-off
#              | / _----=> need-resched
#              || / _---=> hardirq/softirq
#              ||| / _--=> preempt-depth
#              |||| /
#              |||||     delay
#  cmd     pid ||||| time  |   caller
#     \   /    |||||   \   |   /
ksoftirq-7     1d.H3    0us : try_to_wake_up (wake_up_process)
ksoftirq-7     1d.H4    1us : sub_preempt_count (marker_probe_cb)
ksoftirq-7     1d.H3    2us : check_preempt_wakeup (try_to_wake_up)
ksoftirq-7     1d.H3    3us : update_curr (check_preempt_wakeup)
ksoftirq-7     1d.H3    4us : calc_delta_mine (update_curr)
ksoftirq-7     1d.H3    5us : __resched_task (check_preempt_wakeup)
ksoftirq-7     1d.H3    6us : task_wake_up_rt (try_to_wake_up)
ksoftirq-7     1d.H3    7us : _spin_unlock_irqrestore (try_to_wake_up)
[...]
ksoftirq-7     1d.H2   17us : irq_exit (smp_apic_timer_interrupt)
ksoftirq-7     1d.H2   18us : sub_preempt_count (irq_exit)
ksoftirq-7     1d.s3   19us : sub_preempt_count (irq_exit)
ksoftirq-7     1..s2   20us : rcu_process_callbacks (__do_softirq)
[...]
ksoftirq-7     1..s2   26us : __rcu_process_callbacks (rcu_process_callbacks)
ksoftirq-7     1d.s2   27us : _local_bh_enable (__do_softirq)
ksoftirq-7     1d.s2   28us : sub_preempt_count (_local_bh_enable)
ksoftirq-7     1.N.3   29us : sub_preempt_count (ksoftirqd)
ksoftirq-7     1.N.2   30us : _cond_resched (ksoftirqd)
ksoftirq-7     1.N.2   31us : __cond_resched (_cond_resched)
ksoftirq-7     1.N.2   32us : add_preempt_count (__cond_resched)
ksoftirq-7     1.N.2   33us : schedule (__cond_resched)
ksoftirq-7     1.N.2   33us : add_preempt_count (schedule)
ksoftirq-7     1.N.3   34us : hrtick_clear (schedule)
ksoftirq-7     1dN.3   35us : _spin_lock (schedule)
ksoftirq-7     1dN.3   36us : add_preempt_count (_spin_lock)
ksoftirq-7     1d..4   37us : put_prev_task_fair (schedule)
ksoftirq-7     1d..4   38us : update_curr (put_prev_task_fair)
[...]
ksoftirq-7     1d..5   47us : _spin_trylock (tracing_record_cmdline)
ksoftirq-7     1d..5   48us : add_preempt_count (_spin_trylock)
ksoftirq-7     1d..6   49us : _spin_unlock (tracing_record_cmdline)
ksoftirq-7     1d..6   49us : sub_preempt_count (_spin_unlock)
ksoftirq-7     1d..4   50us : schedule (__cond_resched)

1117 1118 1119 1120 1121 1122 1123 1124 1125 1126 1127
The interrupt went off while running ksoftirqd. This task runs
at SCHED_OTHER. Why did not we see the 'N' set early? This may
be a harmless bug with x86_32 and 4K stacks. On x86_32 with 4K
stacks configured, the interrupt and softirq run with their own
stack. Some information is held on the top of the task's stack
(need_resched and preempt_count are both stored there). The
setting of the NEED_RESCHED bit is done directly to the task's
stack, but the reading of the NEED_RESCHED is done by looking at
the current stack, which in this case is the stack for the hard
interrupt. This hides the fact that NEED_RESCHED has been set.
We do not see the 'N' until we switch back to the task's
Steven Rostedt's avatar
Steven Rostedt committed
1128
assigned stack.
Steven Rostedt's avatar
Steven Rostedt committed
1129

Steven Rostedt's avatar
Steven Rostedt committed
1130 1131
function
--------
Steven Rostedt's avatar
Steven Rostedt committed
1132

Steven Rostedt's avatar
Steven Rostedt committed
1133
This tracer is the function tracer. Enabling the function tracer
1134 1135
can be done from the debug file system. Make sure the
ftrace_enabled is set; otherwise this tracer is a nop.
Steven Rostedt's avatar
Steven Rostedt committed
1136 1137

 # sysctl kernel.ftrace_enabled=1
1138 1139
 # echo function > current_tracer
 # echo 1 > tracing_enabled
Steven Rostedt's avatar
Steven Rostedt committed
1140
 # usleep 1
1141 1142
 # echo 0 > tracing_enabled
 # cat trace
Steven Rostedt's avatar
Steven Rostedt committed
1143
# tracer: function
Steven Rostedt's avatar
Steven Rostedt committed
1144 1145 1146 1147 1148 1149 1150 1151 1152 1153 1154 1155 1156 1157 1158 1159 1160 1161 1162 1163 1164
#
#           TASK-PID   CPU#    TIMESTAMP  FUNCTION
#              | |      |          |         |
            bash-4003  [00]   123.638713: finish_task_switch <-schedule
            bash-4003  [00]   123.638714: _spin_unlock_irq <-finish_task_switch
            bash-4003  [00]   123.638714: sub_preempt_count <-_spin_unlock_irq
            bash-4003  [00]   123.638715: hrtick_set <-schedule
            bash-4003  [00]   123.638715: _spin_lock_irqsave <-hrtick_set
            bash-4003  [00]   123.638716: add_preempt_count <-_spin_lock_irqsave
            bash-4003  [00]   123.638716: _spin_unlock_irqrestore <-hrtick_set
            bash-4003  [00]   123.638717: sub_preempt_count <-_spin_unlock_irqrestore
            bash-4003  [00]   123.638717: hrtick_clear <-hrtick_set
            bash-4003  [00]   123.638718: sub_preempt_count <-schedule
            bash-4003  [00]   123.638718: sub_preempt_count <-preempt_schedule
            bash-4003  [00]   123.638719: wait_for_completion <-__stop_machine_run
            bash-4003  [00]   123.638719: wait_for_common <-wait_for_completion
            bash-4003  [00]   123.638720: _spin_lock_irq <-wait_for_common
            bash-4003  [00]   123.638720: add_preempt_count <-_spin_lock_irq
[...]


1165 1166 1167 1168 1169 1170 1171 1172 1173
Note: function tracer uses ring buffers to store the above
entries. The newest data may overwrite the oldest data.
Sometimes using echo to stop the trace is not sufficient because
the tracing could have overwritten the data that you wanted to
record. For this reason, it is sometimes better to disable
tracing directly from a program. This allows you to stop the
tracing at the point that you hit the part that you are
interested in. To disable the tracing directly from a C program,
something like following code snippet can be used:
Steven Rostedt's avatar
Steven Rostedt committed
1174 1175 1176 1177 1178

int trace_fd;
[...]
int main(int argc, char *argv[]) {
	[...]
1179
	trace_fd = open(tracing_file("tracing_enabled"), O_WRONLY);
Steven Rostedt's avatar
Steven Rostedt committed
1180 1181
	[...]
	if (condition_hit()) {
Steven Rostedt's avatar
Steven Rostedt committed
1182
		write(trace_fd, "0", 1);
Steven Rostedt's avatar
Steven Rostedt committed
1183 1184 1185 1186
	}
	[...]
}

1187 1188 1189 1190

Single thread tracing
---------------------

1191
By writing into set_ftrace_pid you can trace a
1192 1193
single thread. For example:

1194
# cat set_ftrace_pid
1195
no pid
1196 1197
# echo 3111 > set_ftrace_pid
# cat set_ftrace_pid
1198
3111
1199 1200
# echo function > current_tracer
# cat trace | head
1201 1202 1203 1204 1205 1206 1207 1208 1209 1210
 # tracer: function
 #
 #           TASK-PID    CPU#    TIMESTAMP  FUNCTION
 #              | |       |          |         |
     yum-updatesd-3111  [003]  1637.254676: finish_task_switch <-thread_return
     yum-updatesd-3111  [003]  1637.254681: hrtimer_cancel <-schedule_hrtimeout_range
     yum-updatesd-3111  [003]  1637.254682: hrtimer_try_to_cancel <-hrtimer_cancel
     yum-updatesd-3111  [003]  1637.254683: lock_hrtimer_base <-hrtimer_try_to_cancel
     yum-updatesd-3111  [003]  1637.254685: fget_light <-do_sys_poll
     yum-updatesd-3111  [003]  1637.254686: pipe_poll <-do_sys_poll
1211 1212
# echo -1 > set_ftrace_pid
# cat trace |head
1213 1214 1215 1216 1217 1218 1219 1220 1221 1222 1223 1224 1225 1226 1227 1228 1229 1230 1231 1232 1233
 # tracer: function
 #
 #           TASK-PID    CPU#    TIMESTAMP  FUNCTION
 #              | |       |          |         |
 ##### CPU 3 buffer started ####
     yum-updatesd-3111  [003]  1701.957688: free_poll_entry <-poll_freewait
     yum-updatesd-3111  [003]  1701.957689: remove_wait_queue <-free_poll_entry
     yum-updatesd-3111  [003]  1701.957691: fput <-free_poll_entry
     yum-updatesd-3111  [003]  1701.957692: audit_syscall_exit <-sysret_audit
     yum-updatesd-3111  [003]  1701.957693: path_put <-audit_syscall_exit

If you want to trace a function when executing, you could use
something like this simple program:

#include <stdio.h>
#include <stdlib.h>
#include <sys/types.h>
#include <sys/stat.h>
#include <fcntl.h>
#include <unistd.h>

1234 1235 1236 1237 1238 1239 1240 1241 1242 1243 1244 1245 1246 1247 1248 1249 1250 1251 1252 1253 1254 1255 1256 1257 1258 1259 1260 1261 1262 1263 1264 1265 1266 1267 1268 1269 1270 1271 1272 1273 1274 1275 1276 1277 1278
#define _STR(x) #x
#define STR(x) _STR(x)
#define MAX_PATH 256

const char *find_debugfs(void)
{
       static char debugfs[MAX_PATH+1];
       static int debugfs_found;
       char type[100];
       FILE *fp;

       if (debugfs_found)
               return debugfs;

       if ((fp = fopen("/proc/mounts","r")) == NULL) {
               perror("/proc/mounts");
               return NULL;
       }

       while (fscanf(fp, "%*s %"
                     STR(MAX_PATH)
                     "s %99s %*s %*d %*d\n",
                     debugfs, type) == 2) {
               if (strcmp(type, "debugfs") == 0)
                       break;
       }
       fclose(fp);

       if (strcmp(type, "debugfs") != 0) {
               fprintf(stderr, "debugfs not mounted");
               return NULL;
       }

       debugfs_found = 1;

       return debugfs;
}

const char *tracing_file(const char *file_name)
{
       static char trace_file[MAX_PATH+1];
       snprintf(trace_file, MAX_PATH, "%s/%s", find_debugfs(), file_name);
       return trace_file;
}

1279 1280 1281 1282 1283 1284 1285 1286 1287 1288
int main (int argc, char **argv)
{
        if (argc < 1)
                exit(-1);

        if (fork() > 0) {
                int fd, ffd;
                char line[64];
                int s;

1289
                ffd = open(tracing_file("current_tracer"), O_WRONLY);
1290 1291 1292 1293
                if (ffd < 0)
                        exit(-1);
                write(ffd, "nop", 3);

1294
                fd = open(tracing_file("set_ftrace_pid"), O_WRONLY);
1295 1296 1297 1298 1299 1300 1301 1302 1303 1304 1305 1306 1307 1308
                s = sprintf(line, "%d\n", getpid());
                write(fd, line, s);

                write(ffd, "function", 8);

                close(fd);
                close(ffd);

                execvp(argv[1], argv+1);
        }

        return 0;
}

1309 1310 1311 1312 1313 1314 1315 1316 1317 1318 1319 1320 1321 1322 1323 1324 1325 1326 1327 1328 1329 1330

hw-branch-tracer (x86 only)
---------------------------

This tracer uses the x86 last branch tracing hardware feature to
collect a branch trace on all cpus with relatively low overhead.

The tracer uses a fixed-size circular buffer per cpu and only
traces ring 0 branches. The trace file dumps that buffer in the
following format:

# tracer: hw-branch-tracer
#
# CPU#        TO  <-  FROM
   0  scheduler_tick+0xb5/0x1bf	  <-  task_tick_idle+0x5/0x6
   2  run_posix_cpu_timers+0x2b/0x72a	  <-  run_posix_cpu_timers+0x25/0x72a
   0  scheduler_tick+0x139/0x1bf	  <-  scheduler_tick+0xed/0x1bf
   0  scheduler_tick+0x17c/0x1bf	  <-  scheduler_tick+0x148/0x1bf
   2  run_posix_cpu_timers+0x9e/0x72a	  <-  run_posix_cpu_timers+0x5e/0x72a
   0  scheduler_tick+0x1b6/0x1bf	  <-  scheduler_tick+0x1aa/0x1bf


1331 1332 1333 1334 1335
The tracer may be used to dump the trace for the oops'ing cpu on
a kernel oops into the system log. To enable this,
ftrace_dump_on_oops must be set. To set ftrace_dump_on_oops, one
can either use the sysctl function or set it via the proc system
interface.
1336 1337 1338 1339 1340 1341 1342 1343

  sysctl kernel.ftrace_dump_on_oops=1

or

  echo 1 > /proc/sys/kernel/ftrace_dump_on_oops


1344 1345
Here's an example of such a dump after a null pointer
dereference in a kernel module:
1346 1347 1348 1349 1350 1351 1352 1353 1354 1355 1356 1357 1358 1359 1360 1361 1362 1363 1364 1365 1366 1367 1368 1369 1370 1371 1372 1373 1374 1375 1376 1377 1378 1379 1380 1381

[57848.105921] BUG: unable to handle kernel NULL pointer dereference at 0000000000000000
[57848.106019] IP: [<ffffffffa0000006>] open+0x6/0x14 [oops]
[57848.106019] PGD 2354e9067 PUD 2375e7067 PMD 0
[57848.106019] Oops: 0002 [#1] SMP
[57848.106019] last sysfs file: /sys/devices/pci0000:00/0000:00:1e.0/0000:20:05.0/local_cpus
[57848.106019] Dumping ftrace buffer:
[57848.106019] ---------------------------------
[...]
[57848.106019]    0  chrdev_open+0xe6/0x165	  <-  cdev_put+0x23/0x24
[57848.106019]    0  chrdev_open+0x117/0x165	  <-  chrdev_open+0xfa/0x165
[57848.106019]    0  chrdev_open+0x120/0x165	  <-  chrdev_open+0x11c/0x165
[57848.106019]    0  chrdev_open+0x134/0x165	  <-  chrdev_open+0x12b/0x165
[57848.106019]    0  open+0x0/0x14 [oops]	  <-  chrdev_open+0x144/0x165
[57848.106019]    0  page_fault+0x0/0x30	  <-  open+0x6/0x14 [oops]
[57848.106019]    0  error_entry+0x0/0x5b	  <-  page_fault+0x4/0x30
[57848.106019]    0  error_kernelspace+0x0/0x31	  <-  error_entry+0x59/0x5b
[57848.106019]    0  error_sti+0x0/0x1	  <-  error_kernelspace+0x2d/0x31
[57848.106019]    0  page_fault+0x9/0x30	  <-  error_sti+0x0/0x1
[57848.106019]    0  do_page_fault+0x0/0x881	  <-  page_fault+0x1a/0x30
[...]
[57848.106019]    0  do_page_fault+0x66b/0x881	  <-  is_prefetch+0x1ee/0x1f2
[57848.106019]    0  do_page_fault+0x6e0/0x881	  <-  do_page_fault+0x67a/0x881
[57848.106019]    0  oops_begin+0x0/0x96	  <-  do_page_fault+0x6e0/0x881
[57848.106019]    0  trace_hw_branch_oops+0x0/0x2d	  <-  oops_begin+0x9/0x96
[...]
[57848.106019]    0  ds_suspend_bts+0x2a/0xe3	  <-  ds_suspend_bts+0x1a/0xe3
[57848.106019] ---------------------------------
[57848.106019] CPU 0
[57848.106019] Modules linked in: oops
[57848.106019] Pid: 5542, comm: cat Tainted: G        W  2.6.28 #23
[57848.106019] RIP: 0010:[<ffffffffa0000006>]  [<ffffffffa0000006>] open+0x6/0x14 [oops]
[57848.106019] RSP: 0018:ffff880235457d48  EFLAGS: 00010246
[...]


1382 1383 1384
function graph tracer
---------------------------

1385 1386 1387 1388 1389 1390 1391
This tracer is similar to the function tracer except that it
probes a function on its entry and its exit. This is done by
using a dynamically allocated stack of return addresses in each
task_struct. On function entry the tracer overwrites the return
address of each function traced to set a custom probe. Thus the
original return address is stored on the stack of return address
in the task_struct.
1392

1393 1394
Probing on both ends of a function leads to special features
such as:
1395

1396 1397
- measure of a function's time execution
- having a reliable call stack to draw function calls graph
1398 1399 1400

This tracer is useful in several situations:

1401 1402 1403 1404 1405 1406 1407 1408 1409 1410 1411 1412
- you want to find the reason of a strange kernel behavior and
  need to see what happens in detail on any areas (or specific
  ones).

- you are experiencing weird latencies but it's difficult to
  find its origin.

- you want to find quickly which path is taken by a specific
  function

- you just want to peek inside a working kernel and want to see
  what happens there.
1413 1414 1415 1416 1417 1418 1419 1420 1421 1422 1423 1424 1425 1426 1427 1428 1429 1430 1431 1432 1433 1434 1435 1436

# tracer: function_graph
#
# CPU  DURATION                  FUNCTION CALLS
# |     |   |                     |   |   |   |

 0)               |  sys_open() {
 0)               |    do_sys_open() {
 0)               |      getname() {
 0)               |        kmem_cache_alloc() {
 0)   1.382 us    |          __might_sleep();
 0)   2.478 us    |        }
 0)               |        strncpy_from_user() {
 0)               |          might_fault() {
 0)   1.389 us    |            __might_sleep();
 0)   2.553 us    |          }
 0)   3.807 us    |        }
 0)   7.876 us    |      }
 0)               |      alloc_fd() {
 0)   0.668 us    |        _spin_lock();
 0)   0.570 us    |        expand_files();
 0)   0.586 us    |        _spin_unlock();


1437 1438 1439
There are several columns that can be dynamically
enabled/disabled. You can use every combination of options you
want, depending on your needs.
1440

1441 1442 1443 1444
- The cpu number on which the function executed is default
  enabled.  It is sometimes better to only trace one cpu (see
  tracing_cpu_mask file) or you might sometimes see unordered
  function calls while cpu tracing switch.
1445

1446 1447
	hide: echo nofuncgraph-cpu > trace_options
	show: echo funcgraph-cpu > trace_options
1448

1449 1450 1451 1452
- The duration (function's time of execution) is displayed on
  the closing bracket line of a function or on the same line
  than the current function in case of a leaf one. It is default
  enabled.
1453

1454 1455
	hide: echo nofuncgraph-duration > trace_options
	show: echo funcgraph-duration > trace_options
1456

1457 1458
- The overhead field precedes the duration field in case of
  reached duration thresholds.
1459

1460 1461
	hide: echo nofuncgraph-overhead > trace_options
	show: echo funcgraph-overhead > trace_options
1462 1463 1464 1465 1466 1467 1468 1469 1470 1471 1472 1473 1474 1475 1476 1477 1478 1479 1480 1481 1482 1483 1484 1485 1486
	depends on: funcgraph-duration

  ie:

  0)               |    up_write() {
  0)   0.646 us    |      _spin_lock_irqsave();
  0)   0.684 us    |      _spin_unlock_irqrestore();
  0)   3.123 us    |    }
  0)   0.548 us    |    fput();
  0) + 58.628 us   |  }

  [...]

  0)               |      putname() {
  0)               |        kmem_cache_free() {
  0)   0.518 us    |          __phys_addr();
  0)   1.757 us    |        }
  0)   2.861 us    |      }
  0) ! 115.305 us  |    }
  0) ! 116.402 us  |  }

  + means that the function exceeded 10 usecs.
  ! means that the function exceeded 100 usecs.


1487 1488
- The task/pid field displays the thread cmdline and pid which
  executed the function. It is default disabled.
1489

1490 1491
	hide: echo nofuncgraph-proc > trace_options
	show: echo funcgraph-proc > trace_options
1492 1493 1494 1495 1496 1497 1498 1499 1500 1501 1502 1503 1504 1505 1506 1507 1508 1509

  ie:

  # tracer: function_graph
  #
  # CPU  TASK/PID        DURATION                  FUNCTION CALLS
  # |    |    |           |   |                     |   |   |   |
  0)    sh-4802     |               |                  d_free() {
  0)    sh-4802     |               |                    call_rcu() {
  0)    sh-4802     |               |                      __call_rcu() {
  0)    sh-4802     |   0.616 us    |                        rcu_process_gp_end();
  0)    sh-4802     |   0.586 us    |                        check_for_new_grace_period();
  0)    sh-4802     |   2.899 us    |                      }
  0)    sh-4802     |   4.040 us    |                    }
  0)    sh-4802     |   5.151 us    |                  }
  0)    sh-4802     | + 49.370 us   |                }


1510 1511 1512
- The absolute time field is an absolute timestamp given by the
  system clock since it started. A snapshot of this time is
  given on each entry/exit of functions
1513

1514 1515
	hide: echo nofuncgraph-abstime > trace_options
	show: echo funcgraph-abstime > trace_options
1516 1517 1518 1519 1520 1521 1522 1523 1524 1525 1526 1527 1528 1529 1530 1531 1532 1533 1534 1535 1536

  ie:

  #
  #      TIME       CPU  DURATION                  FUNCTION CALLS
  #       |         |     |   |                     |   |   |   |
  360.774522 |   1)   0.541 us    |                                          }
  360.774522 |   1)   4.663 us    |                                        }
  360.774523 |   1)   0.541 us    |                                        __wake_up_bit();
  360.774524 |   1)   6.796 us    |                                      }
  360.774524 |   1)   7.952 us    |                                    }
  360.774525 |   1)   9.063 us    |                                  }
  360.774525 |   1)   0.615 us    |                                  journal_mark_dirty();
  360.774527 |   1)   0.578 us    |                                  __brelse();
  360.774528 |   1)               |                                  reiserfs_prepare_for_journal() {
  360.774528 |   1)               |                                    unlock_buffer() {
  360.774529 |   1)               |                                      wake_up_bit() {
  360.774529 |   1)               |                                        bit_waitqueue() {
  360.774530 |   1)   0.594 us    |                                          __phys_addr();


1537
You can put some comments on specific functions by using
1538
trace_printk() For example, if you want to put a comment inside
1539
the __might_sleep() function, you just have to include
1540
<linux/ftrace.h> and call trace_printk() inside __might_sleep()
1541

1542
trace_printk("I'm a comment!\n")
1543 1544 1545 1546 1547 1548 1549 1550

will produce:

 1)               |             __might_sleep() {
 1)               |                /* I'm a comment! */
 1)   1.449 us    |             }


1551 1552 1553
You might find other useful features for this tracer in the
following "dynamic ftrace" section such as tracing only specific
functions or tasks.
1554

Steven Rostedt's avatar
Steven Rostedt committed
1555 1556 1557
dynamic ftrace
--------------

Steven Rostedt's avatar
Steven Rostedt committed
1558
If CONFIG_DYNAMIC_FTRACE is set, the system will run with
Steven Rostedt's avatar
Steven Rostedt committed
1559 1560
virtually no overhead when function tracing is disabled. The way
this works is the mcount function call (placed at the start of
1561 1562 1563
every kernel function, produced by the -pg switch in gcc),
starts of pointing to a simple return. (Enabling FTRACE will
include the -pg switch in the compiling of the kernel.)
Steven Rostedt's avatar
Steven Rostedt committed
1564

Steven Rostedt's avatar
Steven Rostedt committed
1565 1566 1567
At compile time every C file object is run through the
recordmcount.pl script (located in the scripts directory). This
script will process the C object using objdump to find all the
1568 1569 1570
locations in the .text section that call mcount. (Note, only the
.text section is processed, since processing other sections like
.init.text may cause races due to those sections being freed).
Steven Rostedt's avatar
Steven Rostedt committed
1571

1572 1573 1574 1575
A new section called "__mcount_loc" is created that holds
references to all the mcount call sites in the .text section.
This section is compiled back into the original object. The
final linker will add all these references into a single table.
Steven Rostedt's avatar
Steven Rostedt committed
1576 1577

On boot up, before SMP is initialized, the dynamic ftrace code
1578 1579 1580 1581 1582 1583 1584 1585 1586 1587 1588 1589 1590 1591
scans this table and updates all the locations into nops. It
also records the locations, which are added to the
available_filter_functions list.  Modules are processed as they
are loaded and before they are executed.  When a module is
unloaded, it also removes its functions from the ftrace function
list. This is automatic in the module unload code, and the
module author does not need to worry about it.

When tracing is enabled, kstop_machine is called to prevent
races with the CPUS executing code being modified (which can
cause the CPU to do undesireable things), and the nops are
patched back to calls. But this time, they do not call mcount
(which is just a function stub). They now call into the ftrace
infrastructure.
Steven Rostedt's avatar
Steven Rostedt committed
1592 1593

One special side-effect to the recording of the functions being
Steven Rostedt's avatar
Steven Rostedt committed
1594
traced is that we can now selectively choose which functions we
1595 1596
wish to trace and which ones we want the mcount calls to remain
as nops.
Steven Rostedt's avatar
Steven Rostedt committed
1597

1598 1599
Two files are used, one for enabling and one for disabling the
tracing of specified functions. They are:
Steven Rostedt's avatar
Steven Rostedt committed
1600 1601 1602 1603 1604 1605 1606

  set_ftrace_filter

and

  set_ftrace_notrace

1607 1608
A list of available functions that you can add to these files is
listed in:
Steven Rostedt's avatar
Steven Rostedt committed
1609 1610 1611

   available_filter_functions

1612
 # cat available_filter_functions
Steven Rostedt's avatar
Steven Rostedt committed
1613 1614 1615 1616 1617 1618 1619 1620
put_prev_task_idle
kmem_cache_create
pick_next_task_rt
get_online_cpus
pick_next_task_fair
mutex_lock
[...]

Steven Rostedt's avatar
Steven Rostedt committed
1621
If I am only interested in sys_nanosleep and hrtimer_interrupt:
Steven Rostedt's avatar
Steven Rostedt committed
1622 1623

 # echo sys_nanosleep hrtimer_interrupt \
1624 1625 1626
		> set_ftrace_filter
 # echo ftrace > current_tracer
 # echo 1 > tracing_enabled
Steven Rostedt's avatar
Steven Rostedt committed
1627
 # usleep 1
1628 1629
 # echo 0 > tracing_enabled
 # cat trace
Steven Rostedt's avatar
Steven Rostedt committed
1630 1631 1632 1633 1634 1635 1636 1637
# tracer: ftrace
#
#           TASK-PID   CPU#    TIMESTAMP  FUNCTION
#              | |      |          |         |
          usleep-4134  [00]  1317.070017: hrtimer_interrupt <-smp_apic_timer_interrupt
          usleep-4134  [00]  1317.070111: sys_nanosleep <-syscall_call
          <idle>-0     [00]  1317.070115: hrtimer_interrupt <-smp_apic_timer_interrupt

Steven Rostedt's avatar
Steven Rostedt committed
1638
To see which functions are being traced, you can cat the file:
Steven Rostedt's avatar
Steven Rostedt committed
1639

1640
 # cat set_ftrace_filter
Steven Rostedt's avatar
Steven Rostedt committed
1641 1642 1643 1644
hrtimer_interrupt
sys_nanosleep


1645 1646
Perhaps this is not enough. The filters also allow simple wild
cards. Only the following are currently available
Steven Rostedt's avatar
Steven Rostedt committed
1647

Steven Rostedt's avatar
Steven Rostedt committed
1648
  <match>*  - will match functions that begin with <match>
Steven Rostedt's avatar
Steven Rostedt committed
1649 1650 1651
  *<match>  - will match functions that end with <match>
  *<match>* - will match functions that have <match> in it

Steven Rostedt's avatar
Steven Rostedt committed
1652
These are the only wild cards which are supported.
Steven Rostedt's avatar
Steven Rostedt committed
1653 1654 1655

  <match>*<match> will not work.

1656 1657 1658
Note: It is better to use quotes to enclose the wild cards,
      otherwise the shell may expand the parameters into names
      of files in the local directory.
walimis's avatar
walimis committed
1659

1660
 # echo 'hrtimer_*' > set_ftrace_filter
Steven Rostedt's avatar
Steven Rostedt committed
1661 1662 1663 1664 1665 1666 1667 1668 1669 1670 1671 1672 1673 1674 1675 1676 1677 1678 1679 1680

Produces:

# tracer: ftrace
#
#           TASK-PID   CPU#    TIMESTAMP  FUNCTION
#              | |      |          |         |
            bash-4003  [00]  1480.611794: hrtimer_init <-copy_process
            bash-4003  [00]  1480.611941: hrtimer_start <-hrtick_set
            bash-4003  [00]  1480.611956: hrtimer_cancel <-hrtick_clear
            bash-4003  [00]  1480.611956: hrtimer_try_to_cancel <-hrtimer_cancel
          <idle>-0     [00]  1480.612019: hrtimer_get_next_event <-get_next_timer_interrupt
          <idle>-0     [00]  1480.612025: hrtimer_get_next_event <-get_next_timer_interrupt
          <idle>-0     [00]  1480.612032: hrtimer_get_next_event <-get_next_timer_interrupt
          <idle>-0     [00]  1480.612037: hrtimer_get_next_event <-get_next_timer_interrupt
          <idle>-0     [00]  1480.612382: hrtimer_get_next_event <-get_next_timer_interrupt


Notice that we lost the sys_nanosleep.

1681
 # cat set_ftrace_filter
Steven Rostedt's avatar
Steven Rostedt committed
1682 1683 1684 1685 1686 1687 1688 1689 1690 1691 1692 1693 1694 1695 1696 1697 1698 1699 1700 1701 1702 1703
hrtimer_run_queues
hrtimer_run_pending
hrtimer_init
hrtimer_cancel
hrtimer_try_to_cancel
hrtimer_forward
hrtimer_start
hrtimer_reprogram
hrtimer_force_reprogram
hrtimer_get_next_event
hrtimer_interrupt
hrtimer_nanosleep
hrtimer_wakeup
hrtimer_get_remaining
hrtimer_get_res
hrtimer_init_sleeper


This is because the '>' and '>>' act just like they do in bash.
To rewrite the filters, use '>'
To append to the filters, use '>>'

1704 1705
To clear out a filter so that all functions will be recorded
again:
Steven Rostedt's avatar
Steven Rostedt committed
1706

1707 1708
 # echo > set_ftrace_filter
 # cat set_ftrace_filter
Steven Rostedt's avatar
Steven Rostedt committed
1709 1710 1711 1712
 #

Again, now we want to append.

1713 1714
 # echo sys_nanosleep > set_ftrace_filter
 # cat set_ftrace_filter
Steven Rostedt's avatar
Steven Rostedt committed
1715
sys_nanosleep
1716 1717
 # echo 'hrtimer_*' >> set_ftrace_filter
 # cat set_ftrace_filter
Steven Rostedt's avatar
Steven Rostedt committed
1718 1719 1720 1721 1722 1723 1724 1725 1726 1727 1728 1729 1730 1731 1732 1733 1734 1735 1736
hrtimer_run_queues
hrtimer_run_pending
hrtimer_init
hrtimer_cancel
hrtimer_try_to_cancel
hrtimer_forward
hrtimer_start
hrtimer_reprogram
hrtimer_force_reprogram
hrtimer_get_next_event
hrtimer_interrupt
sys_nanosleep
hrtimer_nanosleep
hrtimer_wakeup
hrtimer_get_remaining
hrtimer_get_res
hrtimer_init_sleeper


1737 1738
The set_ftrace_notrace prevents those functions from being
traced.
Steven Rostedt's avatar
Steven Rostedt committed
1739

1740
 # echo '*preempt*' '*lock*' > set_ftrace_notrace
Steven Rostedt's avatar
Steven Rostedt committed
1741 1742 1743 1744 1745 1746 1747 1748 1749 1750 1751 1752 1753 1754 1755 1756 1757 1758 1759

Produces:

# tracer: ftrace
#
#           TASK-PID   CPU#    TIMESTAMP  FUNCTION
#              | |      |          |         |
            bash-4043  [01]   115.281644: finish_task_switch <-schedule
            bash-4043  [01]   115.281645: hrtick_set <-schedule
            bash-4043  [01]   115.281645: hrtick_clear <-hrtick_set
            bash-4043  [01]   115.281646: wait_for_completion <-__stop_machine_run
            bash-4043  [01]   115.281647: wait_for_common <-wait_for_completion
            bash-4043  [01]   115.281647: kthread_stop <-stop_machine_run
            bash-4043  [01]   115.281648: init_waitqueue_head <-kthread_stop
            bash-4043  [01]   115.281648: wake_up_process <-kthread_stop
            bash-4043  [01]   115.281649: try_to_wake_up <-wake_up_process

We can see that there's no more lock or preempt tracing.

1760

1761 1762
Dynamic ftrace with the function graph tracer
---------------------------------------------
1763

1764 1765 1766
Although what has been explained above concerns both the
function tracer and the function-graph-tracer, there are some
special features only available in the function-graph tracer.
1767

1768 1769
If you want to trace only one function and all of its children,
you just have to echo its name into set_graph_function:
1770

1771
 echo __do_fault > set_graph_function
1772

1773 1774
will produce the following "expanded" trace of the __do_fault()
function:
1775 1776 1777 1778 1779 1780 1781 1782 1783 1784 1785 1786 1787 1788 1789 1790 1791 1792 1793 1794 1795 1796 1797 1798 1799 1800 1801 1802 1803 1804 1805 1806 1807 1808 1809 1810

 0)               |  __do_fault() {
 0)               |    filemap_fault() {
 0)               |      find_lock_page() {
 0)   0.804 us    |        find_get_page();
 0)               |        __might_sleep() {
 0)   1.329 us    |        }
 0)   3.904 us    |      }
 0)   4.979 us    |    }
 0)   0.653 us    |    _spin_lock();
 0)   0.578 us    |    page_add_file_rmap();
 0)   0.525 us    |    native_set_pte_at();
 0)   0.585 us    |    _spin_unlock();
 0)               |    unlock_page() {
 0)   0.541 us    |      page_waitqueue();
 0)   0.639 us    |      __wake_up_bit();
 0)   2.786 us    |    }
 0) + 14.237 us   |  }
 0)               |  __do_fault() {
 0)               |    filemap_fault() {
 0)               |      find_lock_page() {
 0)   0.698 us    |        find_get_page();
 0)               |        __might_sleep() {
 0)   1.412 us    |        }
 0)   3.950 us    |      }
 0)   5.098 us    |    }
 0)   0.631 us    |    _spin_lock();
 0)   0.571 us    |    page_add_file_rmap();
 0)   0.526 us    |    native_set_pte_at();
 0)   0.586 us    |    _spin_unlock();
 0)               |    unlock_page() {
 0)   0.533 us    |      page_waitqueue();
 0)   0.638 us    |      __wake_up_bit();
 0)   2.793 us    |    }
 0) + 14.012 us   |  }

1811
You can also expand several functions at once:
1812

1813 1814
 echo sys_open > set_graph_function
 echo sys_close >> set_graph_function
1815

1816 1817
Now if you want to go back to trace all functions you can clear
this special filter via:
1818

1819
 echo > set_graph_function
1820 1821


Steven Rostedt's avatar
Steven Rostedt committed
1822 1823 1824
trace_pipe
----------

1825 1826 1827 1828
The trace_pipe outputs the same content as the trace file, but
the effect on the tracing is different. Every read from
trace_pipe is consumed. This means that subsequent reads will be
different. The trace is live.
Steven Rostedt's avatar
Steven Rostedt committed
1829

1830 1831
 # echo function > current_tracer
 # cat trace_pipe > /tmp/trace.out &
Steven Rostedt's avatar
Steven Rostedt committed
1832
[1] 4153
1833
 # echo 1 > tracing_enabled
Steven Rostedt's avatar
Steven Rostedt committed
1834
 # usleep 1
1835 1836
 # echo 0 > tracing_enabled
 # cat trace
Steven Rostedt's avatar
Steven Rostedt committed
1837
# tracer: function
Steven Rostedt's avatar
Steven Rostedt committed
1838 1839 1840 1841 1842 1843 1844 1845 1846 1847 1848 1849 1850 1851 1852 1853 1854 1855
#
#           TASK-PID   CPU#    TIMESTAMP  FUNCTION
#              | |      |          |         |

 #
 # cat /tmp/trace.out
            bash-4043  [00] 41.267106: finish_task_switch <-schedule
            bash-4043  [00] 41.267106: hrtick_set <-schedule
            bash-4043  [00] 41.267107: hrtick_clear <-hrtick_set
            bash-4043  [00] 41.267108: wait_for_completion <-__stop_machine_run
            bash-4043  [00] 41.267108: wait_for_common <-wait_for_completion
            bash-4043  [00] 41.267109: kthread_stop <-stop_machine_run
            bash-4043  [00] 41.267109: init_waitqueue_head <-kthread_stop
            bash-4043  [00] 41.267110: wake_up_process <-kthread_stop
            bash-4043  [00] 41.267110: try_to_wake_up <-wake_up_process
            bash-4043  [00] 41.267111: select_task_rq_rt <-try_to_wake_up


1856 1857 1858 1859
Note, reading the trace_pipe file will block until more input is
added. By changing the tracer, trace_pipe will issue an EOF. We
needed to set the function tracer _before_ we "cat" the
trace_pipe file.
Steven Rostedt's avatar
Steven Rostedt committed
1860 1861 1862 1863 1864


trace entries
-------------

1865 1866 1867 1868 1869 1870
Having too much or not enough data can be troublesome in
diagnosing an issue in the kernel. The file buffer_size_kb is
used to modify the size of the internal trace buffers. The
number listed is the number of entries that can be recorded per
CPU. To know the full size, multiply the number of possible CPUS
with the number of entries.
Steven Rostedt's avatar
Steven Rostedt committed
1871

1872
 # cat buffer_size_kb
1873
1408 (units kilobytes)
Steven Rostedt's avatar
Steven Rostedt committed
1874

1875 1876 1877 1878
Note, to modify this, you must have tracing completely disabled.
To do that, echo "nop" into the current_tracer. If the
current_tracer is not set to "nop", an EINVAL error will be
returned.
Steven Rostedt's avatar
Steven Rostedt committed
1879

1880 1881 1882
 # echo nop > current_tracer
 # echo 10000 > buffer_size_kb
 # cat buffer_size_kb
1883
10000 (units kilobytes)
Steven Rostedt's avatar
Steven Rostedt committed
1884

1885 1886 1887
The number of pages which will be allocated is limited to a
percentage of available memory. Allocating too much will produce
an error.
Steven Rostedt's avatar
Steven Rostedt committed
1888

1889
 # echo 1000000000000 > buffer_size_kb
Steven Rostedt's avatar
Steven Rostedt committed
1890
-bash: echo: write error: Cannot allocate memory
1891
 # cat buffer_size_kb
Steven Rostedt's avatar
Steven Rostedt committed
1892 1893
85

1894 1895 1896
-----------

More details can be found in the source code, in the
1897
kernel/trace/*.c files.