ftrace.txt 68.0 KB
Newer Older
S
Steven Rostedt 已提交
1 2 3 4
		ftrace - Function Tracer
		========================

Copyright 2008 Red Hat Inc.
S
Steven Rostedt 已提交
5 6
   Author:   Steven Rostedt <srostedt@redhat.com>
  License:   The GNU Free Documentation License, Version 1.2
S
Steven Rostedt 已提交
7
               (dual licensed under the GPL v2)
S
Steven Rostedt 已提交
8 9
Reviewers:   Elias Oltmanns, Randy Dunlap, Andrew Morton,
	     John Kacur, and David Teigland.
S
Steven Rostedt 已提交
10
Written for: 2.6.28-rc2
S
Steven Rostedt 已提交
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.
I
Ingo Molnar 已提交
17 18
It can be used for debugging or analyzing latencies and
performance issues that take place outside of user-space.
S
Steven Rostedt 已提交
19 20

Although ftrace is the function tracer, it also includes an
I
Ingo Molnar 已提交
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).
S
Steven Rostedt 已提交
27 28


29 30 31 32 33 34
Implementation Details
----------------------

See ftrace-design.txt for details for arch porters and such.


S
Steven Rostedt 已提交
35 36 37
The File System
---------------

I
Ingo Molnar 已提交
38 39
Ftrace uses the debugfs file system to hold the control files as
well as the files to display output.
S
Steven Rostedt 已提交
40

41 42 43 44 45 46 47 48 49
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
S
Steven Rostedt 已提交
50

51 52
For quicker access to that directory you may want to make a soft link to
it:
S
Steven Rostedt 已提交
53

54 55 56 57 58 59 60
 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.
S
Steven Rostedt 已提交
61 62 63 64 65 66 67 68 69 70

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.

I
Ingo Molnar 已提交
71 72 73 74 75 76 77 78 79 80 81 82 83 84 85 86 87 88 89 90 91 92 93 94 95 96 97
  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.
98 99 100 101 102 103 104 105 106
	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.
I
Ingo Molnar 已提交
107 108 109 110 111 112 113

  trace_options:

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

114
  tracing_max_latency:
I
Ingo Molnar 已提交
115 116 117 118

	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
119 120 121 122
	will also be stored, and displayed by "trace".
	A new max trace will only be recorded if the
	latency is greater than the value in this
	file. (in microseconds)
I
Ingo Molnar 已提交
123 124 125 126 127 128 129 130 131 132 133 134 135

  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
136
	  due to buffer management overhead. )
I
Ingo Molnar 已提交
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 181

	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.)
S
Steven Rostedt 已提交
182 183 184 185 186


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

S
Steven Rostedt 已提交
187
Here is the list of current tracers that may be configured.
S
Steven Rostedt 已提交
188

I
Ingo Molnar 已提交
189 190 191 192
  "function"

	Function call tracer to trace all kernel functions.

193
  "function_graph"
I
Ingo Molnar 已提交
194 195 196 197 198 199 200 201 202 203 204 205 206 207 208 209 210 211

	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
212
	trace with the latency-format option enabled.
S
Steven Rostedt 已提交
213

I
Ingo Molnar 已提交
214
  "preemptoff"
215

I
Ingo Molnar 已提交
216 217
	Similar to irqsoff but traces and records the amount of
	time for which preemption is disabled.
S
Steven Rostedt 已提交
218

I
Ingo Molnar 已提交
219
  "preemptirqsoff"
S
Steven Rostedt 已提交
220

I
Ingo Molnar 已提交
221 222 223
	Similar to irqsoff and preemptoff, but traces and
	records the largest time for which irqs and/or preemption
	is disabled.
S
Steven Rostedt 已提交
224

I
Ingo Molnar 已提交
225
  "wakeup"
S
Steven Rostedt 已提交
226

I
Ingo Molnar 已提交
227 228 229
	Traces and records the max latency that it takes for
	the highest priority task to get scheduled after
	it has been woken up.
S
Steven Rostedt 已提交
230

I
Ingo Molnar 已提交
231
  "hw-branch-tracer"
S
Steven Rostedt 已提交
232

I
Ingo Molnar 已提交
233 234 235 236 237 238 239 240
	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.
241

S
Steven Rostedt 已提交
242 243 244 245

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

I
Ingo Molnar 已提交
246 247 248
Here are typical examples of using the tracers when controlling
them only with the debugfs interface (without using any
user-land utilities).
S
Steven Rostedt 已提交
249 250 251 252

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

S
Steven Rostedt 已提交
253
Here is an example of the output format of the file "trace"
S
Steven Rostedt 已提交
254 255

                             --------
S
Steven Rostedt 已提交
256
# tracer: function
S
Steven Rostedt 已提交
257 258 259 260 261 262 263 264
#
#           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
                             --------

I
Ingo Molnar 已提交
265 266 267 268 269 270 271
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.
S
Steven Rostedt 已提交
272

I
Ingo Molnar 已提交
273 274
The sched_switch tracer also includes tracing of task wakeups
and context switches.
S
Steven Rostedt 已提交
275 276 277 278 279 280 281 282

     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

I
Ingo Molnar 已提交
283 284
Wake ups are represented by a "+" and the context switches are
shown as "==>".  The format is:
S
Steven Rostedt 已提交
285 286 287 288 289 290 291 292 293 294 295 296 297

 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>

I
Ingo Molnar 已提交
298 299 300 301 302 303
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).
S
Steven Rostedt 已提交
304 305 306 307 308


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

309 310
When the latency-format option is enabled, the trace file gives
somewhat more information to see why a latency happened.
I
Ingo Molnar 已提交
311
Here is a typical trace.
S
Steven Rostedt 已提交
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 337

# 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)


I
Ingo Molnar 已提交
338 339 340 341 342 343 344 345
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).
S
Steven Rostedt 已提交
346

I
Ingo Molnar 已提交
347 348
The task is the process that was running when the latency
occurred. (swapper pid: 0).
S
Steven Rostedt 已提交
349

I
Ingo Molnar 已提交
350 351
The start and stop (the functions in which the interrupts were
disabled and enabled respectively) that caused the latencies:
S
Steven Rostedt 已提交
352 353 354 355 356 357 358 359 360 361 362

  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.

S
Steven Rostedt 已提交
363
  CPU#: The CPU which the process was running on.
S
Steven Rostedt 已提交
364 365

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

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

  hardirq/softirq:
S
Steven Rostedt 已提交
373
	'H' - hard irq occurred inside a softirq.
S
Steven Rostedt 已提交
374 375 376 377 378 379 380 381
	'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.

382 383 384 385
  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.
S
Steven Rostedt 已提交
386 387

  delay: This is just to help catch your eye a bit better. And
I
Ingo Molnar 已提交
388 389 390 391 392 393
	 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.
S
Steven Rostedt 已提交
394 395 396 397

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


398 399
trace_options
-------------
S
Steven Rostedt 已提交
400

I
Ingo Molnar 已提交
401 402
The trace_options file is used to control what gets printed in
the trace output. To see what is available, simply cat the file:
S
Steven Rostedt 已提交
403

404
  cat trace_options
S
Steven Rostedt 已提交
405
  print-parent nosym-offset nosym-addr noverbose noraw nohex nobin \
I
Ingo Molnar 已提交
406
  noblock nostacktrace nosched-tree nouserstacktrace nosym-userobj
S
Steven Rostedt 已提交
407

I
Ingo Molnar 已提交
408 409
To disable one of the options, echo in the option prepended with
"no".
S
Steven Rostedt 已提交
410

411
  echo noprint-parent > trace_options
S
Steven Rostedt 已提交
412 413 414

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

415
  echo sym-offset > trace_options
S
Steven Rostedt 已提交
416 417 418

Here are the available options:

I
Ingo Molnar 已提交
419 420
  print-parent - On function traces, display the calling (parent)
		 function as well as the function being traced.
S
Steven Rostedt 已提交
421 422 423 424 425 426 427 428

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

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


I
Ingo Molnar 已提交
429 430 431 432
  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".
S
Steven Rostedt 已提交
433 434 435 436

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

I
Ingo Molnar 已提交
437 438
  sym-addr - this will also display the function address as well
	     as the function name.
S
Steven Rostedt 已提交
439 440 441 442

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

443 444
  verbose - This deals with the trace file when the
            latency-format option is enabled.
S
Steven Rostedt 已提交
445 446 447 448

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

I
Ingo Molnar 已提交
449 450 451
  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.
S
Steven Rostedt 已提交
452

I
Ingo Molnar 已提交
453 454
  hex - Similar to raw, but the numbers will be in a hexadecimal
	format.
S
Steven Rostedt 已提交
455 456 457 458 459

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

  block - TBD (needs update)

I
Ingo Molnar 已提交
460 461 462 463
  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.
S
Steven Rostedt 已提交
464

I
Ingo Molnar 已提交
465 466
  userstacktrace - This option changes the trace. It records a
		   stacktrace of the current userspace thread.
467

I
Ingo Molnar 已提交
468 469 470 471 472 473
  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
474

I
Ingo Molnar 已提交
475
		The lookup is performed when you read
476
		trace,trace_pipe. Example:
477 478 479 480

		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]

I
Ingo Molnar 已提交
481 482 483
  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.
S
Steven Rostedt 已提交
484

485 486 487 488 489
  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".
S
Steven Rostedt 已提交
490 491 492 493

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

S
Steven Rostedt 已提交
494
This tracer simply records schedule switches. Here is an example
S
Steven Rostedt 已提交
495
of how to use it.
S
Steven Rostedt 已提交
496

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

# 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
 [...]


I
Ingo Molnar 已提交
525 526 527 528
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.
S
Steven Rostedt 已提交
529

I
Ingo Molnar 已提交
530 531 532 533 534 535 536 537
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.
S
Steven Rostedt 已提交
538

539 540 541 542 543 544 545 546 547 548 549 550
   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
 ---------------------------------------------------------------
S
Steven Rostedt 已提交
551 552 553 554 555

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)
S
Steven Rostedt 已提交
556 557
 D - disk sleep (uninterruptible sleep) : process must be woken up
					(ignores signals)
S
Steven Rostedt 已提交
558 559 560 561 562 563 564 565 566
 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
--------------

I
Ingo Molnar 已提交
567 568 569 570
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.
S
Steven Rostedt 已提交
571 572 573 574 575 576 577

  sysctl kernel.ftrace_enabled=1

 or

  echo 1 > /proc/sys/kernel/ftrace_enabled

I
Ingo Molnar 已提交
578 579
To disable ftrace_enabled simply replace the '1' with '0' in the
above commands.
S
Steven Rostedt 已提交
580

I
Ingo Molnar 已提交
581 582 583
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.
S
Steven Rostedt 已提交
584 585 586 587 588 589 590


irqsoff
-------

When interrupts are disabled, the CPU can not react to any other
external event (besides NMIs and SMIs). This prevents the timer
I
Ingo Molnar 已提交
591 592 593
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.
S
Steven Rostedt 已提交
594

I
Ingo Molnar 已提交
595 596 597 598 599
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.
S
Steven Rostedt 已提交
600

I
Ingo Molnar 已提交
601 602
To reset the maximum, echo 0 into tracing_max_latency. Here is
an example:
S
Steven Rostedt 已提交
603

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

#                _------=> CPU#
#               / _-----=> irqs-off
#              | / _----=> need-resched
#              || / _---=> hardirq/softirq
#              ||| / _--=> preempt-depth
#              |||| /
#              |||||     delay
#  cmd     pid ||||| time  |   caller
#     \   /    |||||   \   |   /
S
Steven Rostedt 已提交
632 633 634
    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)
S
Steven Rostedt 已提交
635 636


S
Steven Rostedt 已提交
637
Here we see that that we had a latency of 12 microsecs (which is
I
Ingo Molnar 已提交
638 639 640 641 642
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.
S
Steven Rostedt 已提交
643

S
Steven Rostedt 已提交
644 645
Note the above example had ftrace_enabled not set. If we set the
ftrace_enabled, we get a much larger output:
S
Steven Rostedt 已提交
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 692

# 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
I
Ingo Molnar 已提交
693 694 695 696
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.
S
Steven Rostedt 已提交
697 698 699 700 701


preemptoff
----------

I
Ingo Molnar 已提交
702 703 704 705
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.
S
Steven Rostedt 已提交
706

S
Steven Rostedt 已提交
707
The preemptoff tracer traces the places that disable preemption.
I
Ingo Molnar 已提交
708 709 710
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.
S
Steven Rostedt 已提交
711

712
 # echo preemptoff > current_tracer
713
 # echo latency-format > trace_options
714 715
 # echo 0 > tracing_max_latency
 # echo 1 > tracing_enabled
S
Steven Rostedt 已提交
716 717
 # ls -ltr
 [...]
718
 # echo 0 > tracing_enabled
719
 # cat trace
S
Steven Rostedt 已提交
720 721 722 723 724 725 726 727 728 729 730 731 732 733 734 735 736 737 738 739 740 741 742 743 744
# 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)


I
Ingo Molnar 已提交
745 746 747 748 749 750
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.
S
Steven Rostedt 已提交
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 808

# 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)


I
Ingo Molnar 已提交
809 810 811 812 813 814
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.
S
Steven Rostedt 已提交
815

I
Ingo Molnar 已提交
816 817 818 819 820 821 822 823
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.
S
Steven Rostedt 已提交
824 825 826 827 828


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

I
Ingo Molnar 已提交
829 830 831 832
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.
S
Steven Rostedt 已提交
833

S
Steven Rostedt 已提交
834
Consider the following code:
S
Steven Rostedt 已提交
835 836 837 838 839 840 841 842 843 844 845 846 847 848 849 850 851

    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().

I
Ingo Molnar 已提交
852 853 854 855
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.
S
Steven Rostedt 已提交
856

I
Ingo Molnar 已提交
857 858
Again, using this trace is much like the irqsoff and preemptoff
tracers.
S
Steven Rostedt 已提交
859

860
 # echo preemptirqsoff > current_tracer
861
 # echo latency-format > trace_options
862 863
 # echo 0 > tracing_max_latency
 # echo 1 > tracing_enabled
S
Steven Rostedt 已提交
864 865
 # ls -ltr
 [...]
866
 # echo 0 > tracing_enabled
867
 # cat trace
S
Steven Rostedt 已提交
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 894
# 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
I
Ingo Molnar 已提交
895 896 897 898
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.
S
Steven Rostedt 已提交
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 985

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)


I
Ingo Molnar 已提交
986 987 988 989 990 991 992 993
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'.
S
Steven Rostedt 已提交
994 995 996 997 998


wakeup
------

I
Ingo Molnar 已提交
999 1000 1001 1002 1003 1004 1005 1006
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.
S
Steven Rostedt 已提交
1007

S
Steven Rostedt 已提交
1008
Real-Time environments are interested in the worst case latency.
I
Ingo Molnar 已提交
1009 1010 1011 1012 1013 1014 1015 1016 1017 1018 1019 1020 1021
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.
S
Steven Rostedt 已提交
1022

1023
 # echo wakeup > current_tracer
1024
 # echo latency-format > trace_options
1025 1026
 # echo 0 > tracing_max_latency
 # echo 1 > tracing_enabled
S
Steven Rostedt 已提交
1027
 # chrt -f 5 sleep 1
1028
 # echo 0 > tracing_enabled
1029
 # cat trace
S
Steven Rostedt 已提交
1030 1031 1032 1033 1034 1035 1036 1037 1038 1039 1040 1041 1042 1043 1044 1045 1046 1047 1048 1049 1050 1051
# 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)


I
Ingo Molnar 已提交
1052 1053 1054 1055 1056
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.
S
Steven Rostedt 已提交
1057

I
Ingo Molnar 已提交
1058 1059 1060 1061
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.
S
Steven Rostedt 已提交
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 1117

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)

I
Ingo Molnar 已提交
1118 1119 1120 1121 1122 1123 1124 1125 1126 1127 1128
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
S
Steven Rostedt 已提交
1129
assigned stack.
S
Steven Rostedt 已提交
1130

S
Steven Rostedt 已提交
1131 1132
function
--------
S
Steven Rostedt 已提交
1133

S
Steven Rostedt 已提交
1134
This tracer is the function tracer. Enabling the function tracer
I
Ingo Molnar 已提交
1135 1136
can be done from the debug file system. Make sure the
ftrace_enabled is set; otherwise this tracer is a nop.
S
Steven Rostedt 已提交
1137 1138

 # sysctl kernel.ftrace_enabled=1
1139 1140
 # echo function > current_tracer
 # echo 1 > tracing_enabled
S
Steven Rostedt 已提交
1141
 # usleep 1
1142 1143
 # echo 0 > tracing_enabled
 # cat trace
S
Steven Rostedt 已提交
1144
# tracer: function
S
Steven Rostedt 已提交
1145 1146 1147 1148 1149 1150 1151 1152 1153 1154 1155 1156 1157 1158 1159 1160 1161 1162 1163 1164 1165
#
#           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
[...]


I
Ingo Molnar 已提交
1166 1167 1168 1169 1170 1171 1172 1173 1174
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:
S
Steven Rostedt 已提交
1175 1176 1177 1178 1179

int trace_fd;
[...]
int main(int argc, char *argv[]) {
	[...]
1180
	trace_fd = open(tracing_file("tracing_enabled"), O_WRONLY);
S
Steven Rostedt 已提交
1181 1182
	[...]
	if (condition_hit()) {
S
Steven Rostedt 已提交
1183
		write(trace_fd, "0", 1);
S
Steven Rostedt 已提交
1184 1185 1186 1187
	}
	[...]
}

1188 1189 1190 1191

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

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

1195
# cat set_ftrace_pid
1196
no pid
1197 1198
# echo 3111 > set_ftrace_pid
# cat set_ftrace_pid
1199
3111
1200 1201
# echo function > current_tracer
# cat trace | head
1202 1203 1204 1205 1206 1207 1208 1209 1210 1211
 # 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
1212 1213
# echo -1 > set_ftrace_pid
# cat trace |head
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
#include <string.h>
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
#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;
       }

1269
       strcat(debugfs, "/tracing/");
1270 1271 1272 1273 1274 1275 1276 1277 1278 1279 1280 1281
       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;
}

1282 1283 1284 1285 1286 1287 1288 1289 1290 1291
int main (int argc, char **argv)
{
        if (argc < 1)
                exit(-1);

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

1292
                ffd = open(tracing_file("current_tracer"), O_WRONLY);
1293 1294 1295 1296
                if (ffd < 0)
                        exit(-1);
                write(ffd, "nop", 3);

1297
                fd = open(tracing_file("set_ftrace_pid"), O_WRONLY);
1298 1299 1300 1301 1302 1303 1304 1305 1306 1307 1308 1309 1310 1311
                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;
}

1312 1313 1314 1315 1316 1317 1318 1319 1320 1321 1322 1323 1324 1325 1326 1327 1328 1329 1330 1331 1332 1333

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


I
Ingo Molnar 已提交
1334 1335 1336 1337 1338
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.
1339

1340
  sysctl kernel.ftrace_dump_on_oops=n
1341 1342 1343

or

1344
  echo n > /proc/sys/kernel/ftrace_dump_on_oops
1345

1346 1347
If n = 1, ftrace will dump buffers of all CPUs, if n = 2 ftrace will
only dump the buffer of the CPU that triggered the oops.
1348

I
Ingo Molnar 已提交
1349 1350
Here's an example of such a dump after a null pointer
dereference in a kernel module:
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 1382 1383 1384 1385 1386

[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
[...]


1387 1388 1389
function graph tracer
---------------------------

I
Ingo Molnar 已提交
1390 1391 1392 1393 1394 1395 1396
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.
1397

I
Ingo Molnar 已提交
1398 1399
Probing on both ends of a function leads to special features
such as:
1400

I
Ingo Molnar 已提交
1401 1402
- measure of a function's time execution
- having a reliable call stack to draw function calls graph
1403 1404 1405

This tracer is useful in several situations:

I
Ingo Molnar 已提交
1406 1407 1408 1409 1410 1411 1412 1413 1414 1415 1416 1417
- 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.
1418 1419 1420 1421 1422 1423 1424 1425 1426 1427 1428 1429 1430 1431 1432 1433 1434 1435 1436 1437 1438 1439 1440 1441

# 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();


I
Ingo Molnar 已提交
1442 1443 1444
There are several columns that can be dynamically
enabled/disabled. You can use every combination of options you
want, depending on your needs.
1445

I
Ingo Molnar 已提交
1446 1447 1448 1449
- 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.
1450

1451 1452
	hide: echo nofuncgraph-cpu > trace_options
	show: echo funcgraph-cpu > trace_options
1453

I
Ingo Molnar 已提交
1454 1455 1456 1457
- 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.
1458

1459 1460
	hide: echo nofuncgraph-duration > trace_options
	show: echo funcgraph-duration > trace_options
1461

I
Ingo Molnar 已提交
1462 1463
- The overhead field precedes the duration field in case of
  reached duration thresholds.
1464

1465 1466
	hide: echo nofuncgraph-overhead > trace_options
	show: echo funcgraph-overhead > trace_options
1467 1468 1469 1470 1471 1472 1473 1474 1475 1476 1477 1478 1479 1480 1481 1482 1483 1484 1485 1486 1487 1488 1489 1490 1491
	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.


I
Ingo Molnar 已提交
1492 1493
- The task/pid field displays the thread cmdline and pid which
  executed the function. It is default disabled.
1494

1495 1496
	hide: echo nofuncgraph-proc > trace_options
	show: echo funcgraph-proc > trace_options
1497 1498 1499 1500 1501 1502 1503 1504 1505 1506 1507 1508 1509 1510 1511 1512 1513 1514

  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   |                }


I
Ingo Molnar 已提交
1515 1516 1517
- 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
1518

1519 1520
	hide: echo nofuncgraph-abstime > trace_options
	show: echo funcgraph-abstime > trace_options
1521 1522 1523 1524 1525 1526 1527 1528 1529 1530 1531 1532 1533 1534 1535 1536 1537 1538 1539 1540 1541

  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();


I
Ingo Molnar 已提交
1542
You can put some comments on specific functions by using
1543
trace_printk() For example, if you want to put a comment inside
I
Ingo Molnar 已提交
1544
the __might_sleep() function, you just have to include
1545
<linux/ftrace.h> and call trace_printk() inside __might_sleep()
1546

1547
trace_printk("I'm a comment!\n")
1548 1549 1550 1551 1552 1553 1554 1555

will produce:

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


I
Ingo Molnar 已提交
1556 1557 1558
You might find other useful features for this tracer in the
following "dynamic ftrace" section such as tracing only specific
functions or tasks.
1559

S
Steven Rostedt 已提交
1560 1561 1562
dynamic ftrace
--------------

S
Steven Rostedt 已提交
1563
If CONFIG_DYNAMIC_FTRACE is set, the system will run with
S
Steven Rostedt 已提交
1564 1565
virtually no overhead when function tracing is disabled. The way
this works is the mcount function call (placed at the start of
I
Ingo Molnar 已提交
1566 1567 1568
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.)
S
Steven Rostedt 已提交
1569

S
Steven Rostedt 已提交
1570 1571 1572
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
I
Ingo Molnar 已提交
1573 1574 1575
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).
S
Steven Rostedt 已提交
1576

I
Ingo Molnar 已提交
1577 1578 1579 1580
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.
S
Steven Rostedt 已提交
1581 1582

On boot up, before SMP is initialized, the dynamic ftrace code
I
Ingo Molnar 已提交
1583 1584 1585 1586 1587 1588 1589 1590 1591 1592
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
D
Daniel Mack 已提交
1593
cause the CPU to do undesirable things), and the nops are
I
Ingo Molnar 已提交
1594 1595 1596
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.
S
Steven Rostedt 已提交
1597 1598

One special side-effect to the recording of the functions being
S
Steven Rostedt 已提交
1599
traced is that we can now selectively choose which functions we
I
Ingo Molnar 已提交
1600 1601
wish to trace and which ones we want the mcount calls to remain
as nops.
S
Steven Rostedt 已提交
1602

I
Ingo Molnar 已提交
1603 1604
Two files are used, one for enabling and one for disabling the
tracing of specified functions. They are:
S
Steven Rostedt 已提交
1605 1606 1607 1608 1609 1610 1611

  set_ftrace_filter

and

  set_ftrace_notrace

I
Ingo Molnar 已提交
1612 1613
A list of available functions that you can add to these files is
listed in:
S
Steven Rostedt 已提交
1614 1615 1616

   available_filter_functions

1617
 # cat available_filter_functions
S
Steven Rostedt 已提交
1618 1619 1620 1621 1622 1623 1624 1625
put_prev_task_idle
kmem_cache_create
pick_next_task_rt
get_online_cpus
pick_next_task_fair
mutex_lock
[...]

S
Steven Rostedt 已提交
1626
If I am only interested in sys_nanosleep and hrtimer_interrupt:
S
Steven Rostedt 已提交
1627 1628

 # echo sys_nanosleep hrtimer_interrupt \
1629
		> set_ftrace_filter
1630
 # echo function > current_tracer
1631
 # echo 1 > tracing_enabled
S
Steven Rostedt 已提交
1632
 # usleep 1
1633 1634
 # echo 0 > tracing_enabled
 # cat trace
S
Steven Rostedt 已提交
1635 1636 1637 1638 1639 1640 1641 1642
# 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

S
Steven Rostedt 已提交
1643
To see which functions are being traced, you can cat the file:
S
Steven Rostedt 已提交
1644

1645
 # cat set_ftrace_filter
S
Steven Rostedt 已提交
1646 1647 1648 1649
hrtimer_interrupt
sys_nanosleep


I
Ingo Molnar 已提交
1650 1651
Perhaps this is not enough. The filters also allow simple wild
cards. Only the following are currently available
S
Steven Rostedt 已提交
1652

S
Steven Rostedt 已提交
1653
  <match>*  - will match functions that begin with <match>
S
Steven Rostedt 已提交
1654 1655 1656
  *<match>  - will match functions that end with <match>
  *<match>* - will match functions that have <match> in it

S
Steven Rostedt 已提交
1657
These are the only wild cards which are supported.
S
Steven Rostedt 已提交
1658 1659 1660

  <match>*<match> will not work.

I
Ingo Molnar 已提交
1661 1662 1663
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.
W
walimis 已提交
1664

1665
 # echo 'hrtimer_*' > set_ftrace_filter
S
Steven Rostedt 已提交
1666 1667 1668 1669 1670 1671 1672 1673 1674 1675 1676 1677 1678 1679 1680 1681 1682 1683 1684 1685

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.

1686
 # cat set_ftrace_filter
S
Steven Rostedt 已提交
1687 1688 1689 1690 1691 1692 1693 1694 1695 1696 1697 1698 1699 1700 1701 1702 1703 1704 1705 1706 1707 1708
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 '>>'

I
Ingo Molnar 已提交
1709 1710
To clear out a filter so that all functions will be recorded
again:
S
Steven Rostedt 已提交
1711

1712 1713
 # echo > set_ftrace_filter
 # cat set_ftrace_filter
S
Steven Rostedt 已提交
1714 1715 1716 1717
 #

Again, now we want to append.

1718 1719
 # echo sys_nanosleep > set_ftrace_filter
 # cat set_ftrace_filter
S
Steven Rostedt 已提交
1720
sys_nanosleep
1721 1722
 # echo 'hrtimer_*' >> set_ftrace_filter
 # cat set_ftrace_filter
S
Steven Rostedt 已提交
1723 1724 1725 1726 1727 1728 1729 1730 1731 1732 1733 1734 1735 1736 1737 1738 1739 1740 1741
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


I
Ingo Molnar 已提交
1742 1743
The set_ftrace_notrace prevents those functions from being
traced.
S
Steven Rostedt 已提交
1744

1745
 # echo '*preempt*' '*lock*' > set_ftrace_notrace
S
Steven Rostedt 已提交
1746 1747 1748 1749 1750 1751 1752 1753 1754 1755 1756 1757 1758 1759 1760 1761 1762 1763 1764

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.

1765

I
Ingo Molnar 已提交
1766 1767
Dynamic ftrace with the function graph tracer
---------------------------------------------
1768

I
Ingo Molnar 已提交
1769 1770 1771
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.
1772

I
Ingo Molnar 已提交
1773 1774
If you want to trace only one function and all of its children,
you just have to echo its name into set_graph_function:
1775

I
Ingo Molnar 已提交
1776
 echo __do_fault > set_graph_function
1777

I
Ingo Molnar 已提交
1778 1779
will produce the following "expanded" trace of the __do_fault()
function:
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 1811 1812 1813 1814 1815

 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   |  }

I
Ingo Molnar 已提交
1816
You can also expand several functions at once:
1817

I
Ingo Molnar 已提交
1818 1819
 echo sys_open > set_graph_function
 echo sys_close >> set_graph_function
1820

I
Ingo Molnar 已提交
1821 1822
Now if you want to go back to trace all functions you can clear
this special filter via:
1823

I
Ingo Molnar 已提交
1824
 echo > set_graph_function
1825 1826


S
Steven Rostedt 已提交
1827 1828 1829
trace_pipe
----------

I
Ingo Molnar 已提交
1830 1831 1832 1833
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.
S
Steven Rostedt 已提交
1834

1835 1836
 # echo function > current_tracer
 # cat trace_pipe > /tmp/trace.out &
S
Steven Rostedt 已提交
1837
[1] 4153
1838
 # echo 1 > tracing_enabled
S
Steven Rostedt 已提交
1839
 # usleep 1
1840 1841
 # echo 0 > tracing_enabled
 # cat trace
S
Steven Rostedt 已提交
1842
# tracer: function
S
Steven Rostedt 已提交
1843 1844 1845 1846 1847 1848 1849 1850 1851 1852 1853 1854 1855 1856 1857 1858 1859 1860
#
#           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


I
Ingo Molnar 已提交
1861 1862 1863 1864
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.
S
Steven Rostedt 已提交
1865 1866 1867 1868 1869


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

I
Ingo Molnar 已提交
1870 1871 1872 1873 1874 1875
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.
S
Steven Rostedt 已提交
1876

1877
 # cat buffer_size_kb
1878
1408 (units kilobytes)
S
Steven Rostedt 已提交
1879

I
Ingo Molnar 已提交
1880 1881 1882 1883
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.
S
Steven Rostedt 已提交
1884

1885 1886 1887
 # echo nop > current_tracer
 # echo 10000 > buffer_size_kb
 # cat buffer_size_kb
1888
10000 (units kilobytes)
S
Steven Rostedt 已提交
1889

I
Ingo Molnar 已提交
1890 1891 1892
The number of pages which will be allocated is limited to a
percentage of available memory. Allocating too much will produce
an error.
S
Steven Rostedt 已提交
1893

1894
 # echo 1000000000000 > buffer_size_kb
S
Steven Rostedt 已提交
1895
-bash: echo: write error: Cannot allocate memory
1896
 # cat buffer_size_kb
S
Steven Rostedt 已提交
1897 1898
85

I
Ingo Molnar 已提交
1899 1900 1901
-----------

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