PageRenderTime 26ms CodeModel.GetById 8ms app.highlight 10ms RepoModel.GetById 0ms app.codeStats 0ms

/Documentation/trace/ftrace.txt

https://bitbucket.org/sammyz/iscream_thunderc-2.6.35-rebase
Plain Text | 1946 lines | 1558 code | 388 blank | 0 comment | 0 complexity | dcf3f528e237b56b0eeeb66bce092168 MD5 | raw file
Possible License(s): GPL-2.0, LGPL-2.0, AGPL-1.0

Large files files are truncated, but you can click here to view the full file

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

Large files files are truncated, but you can click here to view the full file