Documentation/trace/ftrace.txt

   1                 ftrace - Function Tracer
   2                 ========================
   3
   4 Copyright 2008 Red Hat Inc.
   5    Author:   Steven Rostedt <srostedt@redhat.com>
   6   License:   The GNU Free Documentation License, Version 1.2
   7                (dual licensed under the GPL v2)
   8 Reviewers:   Elias Oltmanns, Randy Dunlap, Andrew Morton,
   9              John Kacur, and David Teigland.
  10 Written for: 2.6.28-rc2
  11
  12 Introduction
  13 ------------
  14
  15 Ftrace is an internal tracer designed to help out developers and
  16 designers of systems to find what is going on inside the kernel.
  17 It can be used for debugging or analyzing latencies and
  18 performance issues that take place outside of user-space.
  19
  20 Although ftrace is the function tracer, it also includes an
  21 infrastructure that allows for other types of tracing. Some of
  22 the tracers that are currently in ftrace include a tracer to
  23 trace context switches, the time it takes for a high priority
  24 task to run after it was woken up, the time interrupts are
  25 disabled, and more (ftrace allows for tracer plugins, which
  26 means that the list of tracers can always grow).
  27
  28
  29 Implementation Details
  30 ----------------------
  31
  32 See ftrace-design.txt for details for arch porters and such.
  33
  34
  35 The File System
  36 ---------------
  37
  38 Ftrace uses the debugfs file system to hold the control files as
  39 well as the files to display output.
  40
  41 When debugfs is configured into the kernel (which selecting any ftrace
  42 option will do) the directory /sys/kernel/debug will be created. To mount
  43 this directory, you can add to your /etc/fstab file:
  44
  45  debugfs       /sys/kernel/debug          debugfs defaults        0       0
  46
  47 Or you can mount it at run time with:
  48
  49  mount -t debugfs nodev /sys/kernel/debug
  50
  51 For quicker access to that directory you may want to make a soft link to
  52 it:
  53
  54  ln -s /sys/kernel/debug /debug
  55
  56 Any selected ftrace option will also create a directory called tracing
  57 within the debugfs. The rest of the document will assume that you are in
  58 the ftrace directory (cd /sys/kernel/debug/tracing) and will only concentrate
  59 on the files within that directory and not distract from the content with
  60 the extended "/sys/kernel/debug/tracing" path name.
  61
  62 That's it! (assuming that you have ftrace configured into your kernel)
  63
  64 After mounting the debugfs, you can see a directory called
  65 "tracing".  This directory contains the control and output files
  66 of 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
 187 The Tracers
 188 -----------
 189
 190 Here 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
 246 Examples of using the tracer
 247 ----------------------------
 248
 249 Here are typical examples of using the tracers when controlling
 250 them only with the debugfs interface (without using any
 251 user-land utilities).
 252
 253 Output format:
 254 --------------
 255
 256 Here 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
 268 A header is printed with the tracer name that is represented by
 269 the trace. In this case the tracer is "function". Then a header
 270 showing the format. Task name "bash", the task PID "4251", the
 271 CPU that it was running on "01", the timestamp in <secs>.<usecs>
 272 format, the function name that was traced "path_put" and the
 273 parent function that called this function "path_walk". The
 274 timestamp is the time at which the function was entered.
 275
 276 The sched_switch tracer also includes tracing of task wakeups
 277 and 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
 286 Wake ups are represented by a "+" and the context switches are
 287 shown 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
 301 The prio is the internal kernel priority, which is the inverse
 302 of the priority that is usually displayed by user-space tools.
 303 Zero represents the highest priority (99). Prio 100 starts the
 304 "nice" priorities with 100 being equal to nice -20 and 139 being
 305 nice 19. The prio "140" is reserved for the idle task which is
 306 the lowest priority thread (pid 0).
 307
 308
 309 Latency trace format
 310 --------------------
 311
 312 When the latency-format option is enabled, the trace file gives
 313 somewhat more information to see why a latency happened.
 314 Here is a typical trace.
 315
 316 # tracer: irqsoff
 317 #
 318 irqsoff 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
 341 This shows that the current tracer is "irqsoff" tracing the time
 342 for which interrupts were disabled. It gives the trace version
 343 and 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
 345 us). The number of trace entries displayed and the total number
 346 recorded (both are three: #3/3). The type of preemption that was
 347 used (PREEMPT). VP, KP, SP, and HP are always zero and are
 348 reserved for later use. #P is the number of online CPUS (#P:2).
 349
 350 The task is the process that was running when the latency
 351 occurred. (swapper pid: 0).
 352
 353 The start and stop (the functions in which the interrupts were
 354 disabled 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
 359 The next lines after the header are the trace itself. The header
 360 explains 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
 383 The 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
 401 trace_options
 402 -------------
 403
 404 The trace_options file is used to control what gets printed in
 405 the 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
 411 To disable one of the options, echo in the option prepended with
 412 "no".
 413
 414   echo noprint-parent > trace_options
 415
 416 To enable an option, leave off the "no".
 417
 418   echo sym-offset > trace_options
 419
 420 Here 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
 482 x494] <- /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
 494 sched_switch
 495 ------------
 496
 497 This tracer simply records schedule switches. Here is an example
 498 of 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
 528 As we have discussed previously about this format, the header
 529 shows the name of the trace and points to the options. The
 530 "FUNCTION" is a misnomer since here it represents the wake ups
 531 and context switches.
 532
 533 The sched_switch file only lists the wake ups (represented with
 534 '+') and context switches ('==>') with the previous task or
 535 current task first followed by the next task or task waking up.
 536 The format for both of these is PID:KERNEL-PRIO:TASK-STATE.
 537 Remember that the KERNEL-PRIO is the inverse of the actual
 538 priority with zero (0) being the highest priority and the nice
 539 values starting at 100 (nice -20). Below is a quick chart to map
 540 the 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
 555 The 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
 567 ftrace_enabled
 568 --------------
 569
 570 The following tracers (listed below) give different output
 571 depending on whether or not the sysctl ftrace_enabled is set. To
 572 set ftrace_enabled, one can either use the sysctl function or
 573 set 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
 581 To disable ftrace_enabled simply replace the '1' with '0' in the
 582 above commands.
 583
 584 When ftrace_enabled is set the tracers will also record the
 585 functions that are within the trace. The descriptions of the
 586 tracers will also show an example with ftrace enabled.
 587
 588
 589 irqsoff
 590 -------
 591
 592 When interrupts are disabled, the CPU can not react to any other
 593 external event (besides NMIs and SMIs). This prevents the timer
 594 interrupt from triggering or the mouse interrupt from letting
 595 the kernel know of a new mouse event. The result is a latency
 596 with the reaction time.
 597
 598 The irqsoff tracer tracks the time for which interrupts are
 599 disabled. When a new maximum latency is hit, the tracer saves
 600 the trace leading up to that latency point so that every time a
 601 new maximum is reached, the old saved trace is discarded and the
 602 new trace is saved.
 603
 604 To reset the maximum, echo 0 into tracing_max_latency. Here is
 605 an 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 #
 617 irqsoff 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
 640 Here we see that that we had a latency of 12 microsecs (which is
 641 very good). The _write_lock_irq in sys_setpgid disabled
 642 interrupts. The difference between the 12 and the displayed
 643 timestamp 14us occurred because the clock was incremented
 644 between the time of recording the max latency and the time of
 645 recording the function that had that latency.
 646
 647 Note the above example had ftrace_enabled not set. If we set the
 648 ftrace_enabled, we get a much larger output:
 649
 650 # tracer: irqsoff
 651 #
 652 irqsoff 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
 695 Here we traced a 50 microsecond latency. But we also see all the
 696 functions that were called during that time. Note that by
 697 enabling function tracing, we incur an added overhead. This
 698 overhead may extend the latency times. But nevertheless, this
 699 trace has provided some very helpful debugging information.
 700
 701
 702 preemptoff
 703 ----------
 704
 705 When preemption is disabled, we may be able to receive
 706 interrupts but the task cannot be preempted and a higher
 707 priority task must wait for preemption to be enabled again
 708 before it can preempt a lower priority task.
 709
 710 The preemptoff tracer traces the places that disable preemption.
 711 Like the irqsoff tracer, it records the maximum latency for
 712 which preemption was disabled. The control of preemptoff tracer
 713 is 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 #
 725 preemptoff 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
 748 This has some more changes. Preemption was disabled when an
 749 interrupt came in (notice the 'h'), and was enabled while doing
 750 a softirq. (notice the 's'). But we also see that interrupts
 751 have been disabled when entering the preempt off section and
 752 leaving it (the 'd'). We do not know if interrupts were enabled
 753 in the mean time.
 754
 755 # tracer: preemptoff
 756 #
 757 preemptoff 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
 812 The above is an example of the preemptoff trace with
 813 ftrace_enabled set. Here we see that interrupts were disabled
 814 the entire time. The irq_enter code lets us know that we entered
 815 an interrupt 'h'. Before that, the functions being traced still
 816 show that it is not in an interrupt, but we can see from the
 817 functions themselves that this is not the case.
 818
 819 Notice that __do_softirq when called does not have a
 820 preempt_count. It may seem that we missed a preempt enabling.
 821 What really happened is that the preempt count is held on the
 822 thread's stack and we switched to the softirq stack (4K stacks
 823 in effect). The code does not copy the preempt count, but
 824 because interrupts are disabled, we do not need to worry about
 825 it. Having a tracer like this is good for letting people know
 826 what really happens inside the kernel.
 827
 828
 829 preemptirqsoff
 830 --------------
 831
 832 Knowing the locations that have interrupts disabled or
 833 preemption disabled for the longest times is helpful. But
 834 sometimes we would like to know when either preemption and/or
 835 interrupts are disabled.
 836
 837 Consider 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
 847 The irqsoff tracer will record the total length of
 848 call_function_with_irqs_off() and
 849 call_function_with_irqs_and_preemption_off().
 850
 851 The preemptoff tracer will record the total length of
 852 call_function_with_irqs_and_preemption_off() and
 853 call_function_with_preemption_off().
 854
 855 But neither will trace the time that interrupts and/or
 856 preemption is disabled. This total time is the time that we can
 857 not schedule. To record this time, use the preemptirqsoff
 858 tracer.
 859
 860 Again, using this trace is much like the irqsoff and preemptoff
 861 tracers.
 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 #
 873 preemptirqsoff 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
 897 The trace_hardirqs_off_thunk is called from assembly on x86 when
 898 interrupts are disabled in the assembly code. Without the
 899 function tracing, we do not know if interrupts were enabled
 900 within the preemption points. We do see that it started with
 901 preemption enabled.
 902
 903 Here is a trace with ftrace_enabled set:
 904
 905
 906 # tracer: preemptirqsoff
 907 #
 908 preemptirqsoff 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
 989 This is a very interesting trace. It started with the preemption
 990 of the ls task. We see that the task had the "need_resched" bit
 991 set via the 'N' in the trace.  Interrupts were disabled before
 992 the spin_lock at the beginning of the trace. We see that a
 993 schedule took place to run sshd.  When the interrupts were
 994 enabled, we took an interrupt. On return from the interrupt
 995 handler, the softirq ran. We took another interrupt while
 996 running the softirq as we see from the capital 'H'.
 997
 998
 999 wakeup
1000 ------
1001
1002 In a Real-Time environment it is very important to know the
1003 wakeup time it takes for the highest priority task that is woken
1004 up to the time that it executes. This is also known as "schedule
1005 latency". I stress the point that this is about RT tasks. It is
1006 also important to know the scheduling latency of non-RT tasks,
1007 but the average schedule latency is better for non-RT tasks.
1008 Tools like LatencyTop are more appropriate for such
1009 measurements.
1010
1011 Real-Time environments are interested in the worst case latency.
1012 That is the longest latency it takes for something to happen,
1013 and not the average. We can have a very fast scheduler that may
1014 only have a large latency once in a while, but that would not
1015 work well with Real-Time tasks.  The wakeup tracer was designed
1016 to record the worst case wakeups of RT tasks. Non-RT tasks are
1017 not recorded because the tracer only records one worst case and
1018 tracing non-RT tasks that are unpredictable will overwrite the
1019 worst case latency of RT tasks.
1020
1021 Since this tracer only deals with RT tasks, we will run this
1022 slightly differently than we did with the previous tracers.
1023 Instead 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 #
1035 wakeup 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
1055 Running this on an idle system, we see that it only took 4
1056 microseconds to perform the task switch.  Note, since the trace
1057 marker in the schedule is before the actual "switch", we stop
1058 the tracing when the recorded task is about to schedule in. This
1059 may change if we add a new marker at the end of the scheduler.
1060
1061 Notice that the recorded task is 'sleep' with the PID of 4901
1062 and it has an rt_prio of 5. This priority is user-space priority
1063 and not the internal kernel priority. The policy is 1 for
1064 SCHED_FIFO and 2 for SCHED_RR.
1065
1066 Doing the same with chrt -r 5 and ftrace_enabled set.
1067
1068 # tracer: wakeup
1069 #
1070 wakeup 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 #     \   /    |||||   \   |   /
1086 ksoftirq-7     1d.H3    0us : try_to_wake_up (wake_up_process)
1087 ksoftirq-7     1d.H4    1us : sub_preempt_count (marker_probe_cb)
1088 ksoftirq-7     1d.H3    2us : check_preempt_wakeup (try_to_wake_up)
1089 ksoftirq-7     1d.H3    3us : update_curr (check_preempt_wakeup)
1090 ksoftirq-7     1d.H3    4us : calc_delta_mine (update_curr)
1091 ksoftirq-7     1d.H3    5us : __resched_task (check_preempt_wakeup)
1092 ksoftirq-7     1d.H3    6us : task_wake_up_rt (try_to_wake_up)
1093 ksoftirq-7     1d.H3    7us : _spin_unlock_irqrestore (try_to_wake_up)
1094 [...]
1095 ksoftirq-7     1d.H2   17us : irq_exit (smp_apic_timer_interrupt)
1096 ksoftirq-7     1d.H2   18us : sub_preempt_count (irq_exit)
1097 ksoftirq-7     1d.s3   19us : sub_preempt_count (irq_exit)
1098 ksoftirq-7     1..s2   20us : rcu_process_callbacks (__do_softirq)
1099 [...]
1100 ksoftirq-7     1..s2   26us : __rcu_process_callbacks (rcu_process_callbacks)
1101 ksoftirq-7     1d.s2   27us : _local_bh_enable (__do_softirq)
1102 ksoftirq-7     1d.s2   28us : sub_preempt_count (_local_bh_enable)
1103 ksoftirq-7     1.N.3   29us : sub_preempt_count (ksoftirqd)
1104 ksoftirq-7     1.N.2   30us : _cond_resched (ksoftirqd)
1105 ksoftirq-7     1.N.2   31us : __cond_resched (_cond_resched)
1106 ksoftirq-7     1.N.2   32us : add_preempt_count (__cond_resched)
1107 ksoftirq-7     1.N.2   33us : schedule (__cond_resched)
1108 ksoftirq-7     1.N.2   33us : add_preempt_count (schedule)
1109 ksoftirq-7     1.N.3   34us : hrtick_clear (schedule)
1110 ksoftirq-7     1dN.3   35us : _spin_lock (schedule)
1111 ksoftirq-7     1dN.3   36us : add_preempt_count (_spin_lock)
1112 ksoftirq-7     1d..4   37us : put_prev_task_fair (schedule)
1113 ksoftirq-7     1d..4   38us : update_curr (put_prev_task_fair)
1114 [...]
1115 ksoftirq-7     1d..5   47us : _spin_trylock (tracing_record_cmdline)
1116 ksoftirq-7     1d..5   48us : add_preempt_count (_spin_trylock)
1117 ksoftirq-7     1d..6   49us : _spin_unlock (tracing_record_cmdline)
1118 ksoftirq-7     1d..6   49us : sub_preempt_count (_spin_unlock)
1119 ksoftirq-7     1d..4   50us : schedule (__cond_resched)
1120
1121 The interrupt went off while running ksoftirqd. This task runs
1122 at SCHED_OTHER. Why did not we see the 'N' set early? This may
1123 be a harmless bug with x86_32 and 4K stacks. On x86_32 with 4K
1124 stacks configured, the interrupt and softirq run with their own
1125 stack. Some information is held on the top of the task's stack
1126 (need_resched and preempt_count are both stored there). The
1127 setting of the NEED_RESCHED bit is done directly to the task's
1128 stack, but the reading of the NEED_RESCHED is done by looking at
1129 the current stack, which in this case is the stack for the hard
1130 interrupt. This hides the fact that NEED_RESCHED has been set.
1131 We do not see the 'N' until we switch back to the task's
1132 assigned stack.
1133
1134 function
1135 --------
1136
1137 This tracer is the function tracer. Enabling the function tracer
1138 can be done from the debug file system. Make sure the
1139 ftrace_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
1169 Note: function tracer uses ring buffers to store the above
1170 entries. The newest data may overwrite the oldest data.
1171 Sometimes using echo to stop the trace is not sufficient because
1172 the tracing could have overwritten the data that you wanted to
1173 record. For this reason, it is sometimes better to disable
1174 tracing directly from a program. This allows you to stop the
1175 tracing at the point that you hit the part that you are
1176 interested in. To disable the tracing directly from a C program,
1177 something like following code snippet can be used:
1178
1179 int trace_fd;
1180 [...]
1181 int 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
1192 Single thread tracing
1193 ---------------------
1194
1195 By writing into set_ftrace_pid you can trace a
1196 single thread. For example:
1197
1198 # cat set_ftrace_pid
1199 no pid
1200 # echo 3111 > set_ftrace_pid
1201 # cat set_ftrace_pid
1202 3111
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
1228 If you want to trace a function when executing, you could use
1229 something 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
1243 const 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
1278 const 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
1285 int 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
1316 hw-branch-tracer (x86 only)
1317 ---------------------------
1318
1319 This tracer uses the x86 last branch tracing hardware feature to
1320 collect a branch trace on all cpus with relatively low overhead.
1321
1322 The tracer uses a fixed-size circular buffer per cpu and only
1323 traces ring 0 branches. The trace file dumps that buffer in the
1324 following 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
1337 The tracer may be used to dump the trace for the oops'ing cpu on
1338 a kernel oops into the system log. To enable this,
1339 ftrace_dump_on_oops must be set. To set ftrace_dump_on_oops, one
1340 can either use the sysctl function or set it via the proc system
1341 interface.
1342
1343   sysctl kernel.ftrace_dump_on_oops=n
1344
1345 or
1346
1347   echo n > /proc/sys/kernel/ftrace_dump_on_oops
1348
1349 If n = 1, ftrace will dump buffers of all CPUs, if n = 2 ftrace will
1350 only dump the buffer of the CPU that triggered the oops.
1351
1352 Here's an example of such a dump after a null pointer
1353 dereference in a kernel module:
1354
1355 [57848.105921] BUG: unable to handle kernel NULL pointer dereference at 0000000000000000
1356 [57848.106019] IP: [<ffffffffa0000006>] open+0x6/0x14 [oops]
1357 [57848.106019] PGD 2354e9067 PUD 2375e7067 PMD 0
1358 [57848.106019] Oops: 0002 [#1] SMP
1359 [57848.106019] last sysfs file: /sys/devices/pci0000:00/0000:00:1e.0/0000:20:05.0/local_cpus
1360 [57848.106019] Dumping ftrace buffer:
1361 [57848.106019] ---------------------------------
1362 [...]
1363 [57848.106019]    0  chrdev_open+0xe6/0x165       <-  cdev_put+0x23/0x24
1364 [57848.106019]    0  chrdev_open+0x117/0x165      <-  chrdev_open+0xfa/0x165
1365 [57848.106019]    0  chrdev_open+0x120/0x165      <-  chrdev_open+0x11c/0x165
1366 [57848.106019]    0  chrdev_open+0x134/0x165      <-  chrdev_open+0x12b/0x165
1367 [57848.106019]    0  open+0x0/0x14 [oops]         <-  chrdev_open+0x144/0x165
1368 [57848.106019]    0  page_fault+0x0/0x30          <-  open+0x6/0x14 [oops]
1369 [57848.106019]    0  error_entry+0x0/0x5b         <-  page_fault+0x4/0x30
1370 [57848.106019]    0  error_kernelspace+0x0/0x31   <-  error_entry+0x59/0x5b
1371 [57848.106019]    0  error_sti+0x0/0x1    <-  error_kernelspace+0x2d/0x31
1372 [57848.106019]    0  page_fault+0x9/0x30          <-  error_sti+0x0/0x1
1373 [57848.106019]    0  do_page_fault+0x0/0x881      <-  page_fault+0x1a/0x30
1374 [...]
1375 [57848.106019]    0  do_page_fault+0x66b/0x881    <-  is_prefetch+0x1ee/0x1f2
1376 [57848.106019]    0  do_page_fault+0x6e0/0x881    <-  do_page_fault+0x67a/0x881
1377 [57848.106019]    0  oops_begin+0x0/0x96          <-  do_page_fault+0x6e0/0x881
1378 [57848.106019]    0  trace_hw_branch_oops+0x0/0x2d        <-  oops_begin+0x9/0x96
1379 [...]
1380 [57848.106019]    0  ds_suspend_bts+0x2a/0xe3     <-  ds_suspend_bts+0x1a/0xe3
1381 [57848.106019] ---------------------------------
1382 [57848.106019] CPU 0
1383 [57848.106019] Modules linked in: oops
1384 [57848.106019] Pid: 5542, comm: cat Tainted: G        W  2.6.28 #23
1385 [57848.106019] RIP: 0010:[<ffffffffa0000006>]  [<ffffffffa0000006>] open+0x6/0x14 [oops]
1386 [57848.106019] RSP: 0018:ffff880235457d48  EFLAGS: 00010246
1387 [...]
1388
1389
1390 function graph tracer
1391 ---------------------------
1392
1393 This tracer is similar to the function tracer except that it
1394 probes a function on its entry and its exit. This is done by
1395 using a dynamically allocated stack of return addresses in each
1396 task_struct. On function entry the tracer overwrites the return
1397 address of each function traced to set a custom probe. Thus the
1398 original return address is stored on the stack of return address
1399 in the task_struct.
1400
1401 Probing on both ends of a function leads to special features
1402 such as:
1403
1404 - measure of a function's time execution
1405 - having a reliable call stack to draw function calls graph
1406
1407 This tracer is useful in several situations:
1408
1409 - you want to find the reason of a strange kernel behavior and
1410   need to see what happens in detail on any areas (or specific
1411   ones).
1412
1413 - you are experiencing weird latencies but it's difficult to
1414   find its origin.
1415
1416 - you want to find quickly which path is taken by a specific
1417   function
1418
1419 - you just want to peek inside a working kernel and want to see
1420   what happens there.
1421
1422 # tracer: function_graph
1423 #
1424 # CPU  DURATION                  FUNCTION CALLS
1425 # |     |   |                     |   |   |   |
1426
1427  0)               |  sys_open() {
1428  0)               |    do_sys_open() {
1429  0)               |      getname() {
1430  0)               |        kmem_cache_alloc() {
1431  0)   1.382 us    |          __might_sleep();
1432  0)   2.478 us    |        }
1433  0)               |        strncpy_from_user() {
1434  0)               |          might_fault() {
1435  0)   1.389 us    |            __might_sleep();
1436  0)   2.553 us    |          }
1437  0)   3.807 us    |        }
1438  0)   7.876 us    |      }
1439  0)               |      alloc_fd() {
1440  0)   0.668 us    |        _spin_lock();
1441  0)   0.570 us    |        expand_files();
1442  0)   0.586 us    |        _spin_unlock();
1443
1444
1445 There are several columns that can be dynamically
1446 enabled/disabled. You can use every combination of options you
1447 want, depending on your needs.
1448
1449 - The cpu number on which the function executed is default
1450   enabled.  It is sometimes better to only trace one cpu (see
1451   tracing_cpu_mask file) or you might sometimes see unordered
1452   function calls while cpu tracing switch.
1453
1454         hide: echo nofuncgraph-cpu > trace_options
1455         show: echo funcgraph-cpu > trace_options
1456
1457 - The duration (function's time of execution) is displayed on
1458   the closing bracket line of a function or on the same line
1459   than the current function in case of a leaf one. It is default
1460   enabled.
1461
1462         hide: echo nofuncgraph-duration > trace_options
1463         show: echo funcgraph-duration > trace_options
1464
1465 - The overhead field precedes the duration field in case of
1466   reached duration thresholds.
1467
1468         hide: echo nofuncgraph-overhead > trace_options
1469         show: echo funcgraph-overhead > trace_options
1470         depends on: funcgraph-duration
1471
1472   ie:
1473
1474   0)               |    up_write() {
1475   0)   0.646 us    |      _spin_lock_irqsave();
1476   0)   0.684 us    |      _spin_unlock_irqrestore();
1477   0)   3.123 us    |    }
1478   0)   0.548 us    |    fput();
1479   0) + 58.628 us   |  }
1480
1481   [...]
1482
1483   0)               |      putname() {
1484   0)               |        kmem_cache_free() {
1485   0)   0.518 us    |          __phys_addr();
1486   0)   1.757 us    |        }
1487   0)   2.861 us    |      }
1488   0) ! 115.305 us  |    }
1489   0) ! 116.402 us  |  }
1490
1491   + means that the function exceeded 10 usecs.
1492   ! means that the function exceeded 100 usecs.
1493
1494
1495 - The task/pid field displays the thread cmdline and pid which
1496   executed the function. It is default disabled.
1497
1498         hide: echo nofuncgraph-proc > trace_options
1499         show: echo funcgraph-proc > trace_options
1500
1501   ie:
1502
1503   # tracer: function_graph
1504   #
1505   # CPU  TASK/PID        DURATION                  FUNCTION CALLS
1506   # |    |    |           |   |                     |   |   |   |
1507   0)    sh-4802     |               |                  d_free() {
1508   0)    sh-4802     |               |                    call_rcu() {
1509   0)    sh-4802     |               |                      __call_rcu() {
1510   0)    sh-4802     |   0.616 us    |                        rcu_process_gp_end();
1511   0)    sh-4802     |   0.586 us    |                        check_for_new_grace_period();
1512   0)    sh-4802     |   2.899 us    |                      }
1513   0)    sh-4802     |   4.040 us    |                    }
1514   0)    sh-4802     |   5.151 us    |                  }
1515   0)    sh-4802     | + 49.370 us   |                }
1516
1517
1518 - The absolute time field is an absolute timestamp given by the
1519   system clock since it started. A snapshot of this time is
1520   given on each entry/exit of functions
1521
1522         hide: echo nofuncgraph-abstime > trace_options
1523         show: echo funcgraph-abstime > trace_options
1524
1525   ie:
1526
1527   #
1528   #      TIME       CPU  DURATION                  FUNCTION CALLS
1529   #       |         |     |   |                     |   |   |   |
1530   360.774522 |   1)   0.541 us    |                                          }
1531   360.774522 |   1)   4.663 us    |                                        }
1532   360.774523 |   1)   0.541 us    |                                        __wake_up_bit();
1533   360.774524 |   1)   6.796 us    |                                      }
1534   360.774524 |   1)   7.952 us    |                                    }
1535   360.774525 |   1)   9.063 us    |                                  }
1536   360.774525 |   1)   0.615 us    |                                  journal_mark_dirty();
1537   360.774527 |   1)   0.578 us    |                                  __brelse();
1538   360.774528 |   1)               |                                  reiserfs_prepare_for_journal() {
1539   360.774528 |   1)               |                                    unlock_buffer() {
1540   360.774529 |   1)               |                                      wake_up_bit() {
1541   360.774529 |   1)               |                                        bit_waitqueue() {
1542   360.774530 |   1)   0.594 us    |                                          __phys_addr();
1543
1544
1545 You can put some comments on specific functions by using
1546 trace_printk() For example, if you want to put a comment inside
1547 the __might_sleep() function, you just have to include
1548 <linux/ftrace.h> and call trace_printk() inside __might_sleep()
1549
1550 trace_printk("I'm a comment!\n")
1551
1552 will produce:
1553
1554  1)               |             __might_sleep() {
1555  1)               |                /* I'm a comment! */
1556  1)   1.449 us    |             }
1557
1558
1559 You might find other useful features for this tracer in the
1560 following "dynamic ftrace" section such as tracing only specific
1561 functions or tasks.
1562
1563 dynamic ftrace
1564 --------------
1565
1566 If CONFIG_DYNAMIC_FTRACE is set, the system will run with
1567 virtually no overhead when function tracing is disabled. The way
1568 this works is the mcount function call (placed at the start of
1569 every kernel function, produced by the -pg switch in gcc),
1570 starts of pointing to a simple return. (Enabling FTRACE will
1571 include the -pg switch in the compiling of the kernel.)
1572
1573 At compile time every C file object is run through the
1574 recordmcount.pl script (located in the scripts directory). This
1575 script will process the C object using objdump to find all the
1576 locations in the .text section that call mcount. (Note, only the
1577 .text section is processed, since processing other sections like
1578 .init.text may cause races due to those sections being freed).
1579
1580 A new section called "__mcount_loc" is created that holds
1581 references to all the mcount call sites in the .text section.
1582 This section is compiled back into the original object. The
1583 final linker will add all these references into a single table.
1584
1585 On boot up, before SMP is initialized, the dynamic ftrace code
1586 scans this table and updates all the locations into nops. It
1587 also records the locations, which are added to the
1588 available_filter_functions list.  Modules are processed as they
1589 are loaded and before they are executed.  When a module is
1590 unloaded, it also removes its functions from the ftrace function
1591 list. This is automatic in the module unload code, and the
1592 module author does not need to worry about it.
1593
1594 When tracing is enabled, kstop_machine is called to prevent
1595 races with the CPUS executing code being modified (which can
1596 cause the CPU to do undesirable things), and the nops are
1597 patched back to calls. But this time, they do not call mcount
1598 (which is just a function stub). They now call into the ftrace
1599 infrastructure.
1600
1601 One special side-effect to the recording of the functions being
1602 traced is that we can now selectively choose which functions we
1603 wish to trace and which ones we want the mcount calls to remain
1604 as nops.
1605
1606 Two files are used, one for enabling and one for disabling the
1607 tracing of specified functions. They are:
1608
1609   set_ftrace_filter
1610
1611 and
1612
1613   set_ftrace_notrace
1614
1615 A list of available functions that you can add to these files is
1616 listed in:
1617
1618    available_filter_functions
1619
1620  # cat available_filter_functions
1621 put_prev_task_idle
1622 kmem_cache_create
1623 pick_next_task_rt
1624 get_online_cpus
1625 pick_next_task_fair
1626 mutex_lock
1627 [...]
1628
1629 If I am only interested in sys_nanosleep and hrtimer_interrupt:
1630
1631  # echo sys_nanosleep hrtimer_interrupt \
1632                 > set_ftrace_filter
1633  # echo function > current_tracer
1634  # echo 1 > tracing_enabled
1635  # usleep 1
1636  # echo 0 > tracing_enabled
1637  # cat trace
1638 # tracer: ftrace
1639 #
1640 #           TASK-PID   CPU#    TIMESTAMP  FUNCTION
1641 #              | |      |          |         |
1642           usleep-4134  [00]  1317.070017: hrtimer_interrupt <-smp_apic_timer_interrupt
1643           usleep-4134  [00]  1317.070111: sys_nanosleep <-syscall_call
1644           <idle>-0     [00]  1317.070115: hrtimer_interrupt <-smp_apic_timer_interrupt
1645
1646 To see which functions are being traced, you can cat the file:
1647
1648  # cat set_ftrace_filter
1649 hrtimer_interrupt
1650 sys_nanosleep
1651
1652
1653 Perhaps this is not enough. The filters also allow simple wild
1654 cards. Only the following are currently available
1655
1656   <match>*  - will match functions that begin with <match>
1657   *<match>  - will match functions that end with <match>
1658   *<match>* - will match functions that have <match> in it
1659
1660 These are the only wild cards which are supported.
1661
1662   <match>*<match> will not work.
1663
1664 Note: It is better to use quotes to enclose the wild cards,
1665       otherwise the shell may expand the parameters into names
1666       of files in the local directory.
1667
1668  # echo 'hrtimer_*' > set_ftrace_filter
1669
1670 Produces:
1671
1672 # tracer: ftrace
1673 #
1674 #           TASK-PID   CPU#    TIMESTAMP  FUNCTION
1675 #              | |      |          |         |
1676             bash-4003  [00]  1480.611794: hrtimer_init <-copy_process
1677             bash-4003  [00]  1480.611941: hrtimer_start <-hrtick_set
1678             bash-4003  [00]  1480.611956: hrtimer_cancel <-hrtick_clear
1679             bash-4003  [00]  1480.611956: hrtimer_try_to_cancel <-hrtimer_cancel
1680           <idle>-0     [00]  1480.612019: hrtimer_get_next_event <-get_next_timer_interrupt
1681           <idle>-0     [00]  1480.612025: hrtimer_get_next_event <-get_next_timer_interrupt
1682           <idle>-0     [00]  1480.612032: hrtimer_get_next_event <-get_next_timer_interrupt
1683           <idle>-0     [00]  1480.612037: hrtimer_get_next_event <-get_next_timer_interrupt
1684           <idle>-0     [00]  1480.612382: hrtimer_get_next_event <-get_next_timer_interrupt
1685
1686
1687 Notice that we lost the sys_nanosleep.
1688
1689  # cat set_ftrace_filter
1690 hrtimer_run_queues
1691 hrtimer_run_pending
1692 hrtimer_init
1693 hrtimer_cancel
1694 hrtimer_try_to_cancel
1695 hrtimer_forward
1696 hrtimer_start
1697 hrtimer_reprogram
1698 hrtimer_force_reprogram
1699 hrtimer_get_next_event
1700 hrtimer_interrupt
1701 hrtimer_nanosleep
1702 hrtimer_wakeup
1703 hrtimer_get_remaining
1704 hrtimer_get_res
1705 hrtimer_init_sleeper
1706
1707
1708 This is because the '>' and '>>' act just like they do in bash.
1709 To rewrite the filters, use '>'
1710 To append to the filters, use '>>'
1711
1712 To clear out a filter so that all functions will be recorded
1713 again:
1714
1715  # echo > set_ftrace_filter
1716  # cat set_ftrace_filter
1717  #
1718
1719 Again, now we want to append.
1720
1721  # echo sys_nanosleep > set_ftrace_filter
1722  # cat set_ftrace_filter
1723 sys_nanosleep
1724  # echo 'hrtimer_*' >> set_ftrace_filter
1725  # cat set_ftrace_filter
1726 hrtimer_run_queues
1727 hrtimer_run_pending
1728 hrtimer_init
1729 hrtimer_cancel
1730 hrtimer_try_to_cancel
1731 hrtimer_forward
1732 hrtimer_start
1733 hrtimer_reprogram
1734 hrtimer_force_reprogram
1735 hrtimer_get_next_event
1736 hrtimer_interrupt
1737 sys_nanosleep
1738 hrtimer_nanosleep
1739 hrtimer_wakeup
1740 hrtimer_get_remaining
1741 hrtimer_get_res
1742 hrtimer_init_sleeper
1743
1744
1745 The set_ftrace_notrace prevents those functions from being
1746 traced.
1747
1748  # echo '*preempt*' '*lock*' > set_ftrace_notrace
1749
1750 Produces:
1751
1752 # tracer: ftrace
1753 #
1754 #           TASK-PID   CPU#    TIMESTAMP  FUNCTION
1755 #              | |      |          |         |
1756             bash-4043  [01]   115.281644: finish_task_switch <-schedule
1757             bash-4043  [01]   115.281645: hrtick_set <-schedule
1758             bash-4043  [01]   115.281645: hrtick_clear <-hrtick_set
1759             bash-4043  [01]   115.281646: wait_for_completion <-__stop_machine_run
1760             bash-4043  [01]   115.281647: wait_for_common <-wait_for_completion
1761             bash-4043  [01]   115.281647: kthread_stop <-stop_machine_run
1762             bash-4043  [01]   115.281648: init_waitqueue_head <-kthread_stop
1763             bash-4043  [01]   115.281648: wake_up_process <-kthread_stop
1764             bash-4043  [01]   115.281649: try_to_wake_up <-wake_up_process
1765
1766 We can see that there's no more lock or preempt tracing.
1767
1768
1769 Dynamic ftrace with the function graph tracer
1770 ---------------------------------------------
1771
1772 Although what has been explained above concerns both the
1773 function tracer and the function-graph-tracer, there are some
1774 special features only available in the function-graph tracer.
1775
1776 If you want to trace only one function and all of its children,
1777 you just have to echo its name into set_graph_function:
1778
1779  echo __do_fault > set_graph_function
1780
1781 will produce the following "expanded" trace of the __do_fault()
1782 function:
1783
1784  0)               |  __do_fault() {
1785  0)               |    filemap_fault() {
1786  0)               |      find_lock_page() {
1787  0)   0.804 us    |        find_get_page();
1788  0)               |        __might_sleep() {
1789  0)   1.329 us    |        }
1790  0)   3.904 us    |      }
1791  0)   4.979 us    |    }
1792  0)   0.653 us    |    _spin_lock();
1793  0)   0.578 us    |    page_add_file_rmap();
1794  0)   0.525 us    |    native_set_pte_at();
1795  0)   0.585 us    |    _spin_unlock();
1796  0)               |    unlock_page() {
1797  0)   0.541 us    |      page_waitqueue();
1798  0)   0.639 us    |      __wake_up_bit();
1799  0)   2.786 us    |    }
1800  0) + 14.237 us   |  }
1801  0)               |  __do_fault() {
1802  0)               |    filemap_fault() {
1803  0)               |      find_lock_page() {
1804  0)   0.698 us    |        find_get_page();
1805  0)               |        __might_sleep() {
1806  0)   1.412 us    |        }
1807  0)   3.950 us    |      }
1808  0)   5.098 us    |    }
1809  0)   0.631 us    |    _spin_lock();
1810  0)   0.571 us    |    page_add_file_rmap();
1811  0)   0.526 us    |    native_set_pte_at();
1812  0)   0.586 us    |    _spin_unlock();
1813  0)               |    unlock_page() {
1814  0)   0.533 us    |      page_waitqueue();
1815  0)   0.638 us    |      __wake_up_bit();
1816  0)   2.793 us    |    }
1817  0) + 14.012 us   |  }
1818
1819 You can also expand several functions at once:
1820
1821  echo sys_open > set_graph_function
1822  echo sys_close >> set_graph_function
1823
1824 Now if you want to go back to trace all functions you can clear
1825 this special filter via:
1826
1827  echo > set_graph_function
1828
1829
1830 Filter commands
1831 ---------------
1832
1833 A few commands are supported by the set_ftrace_filter interface.
1834 Trace commands have the following format:
1835
1836 <function>:<command>:<parameter>
1837
1838 The following commands are supported:
1839
1840 - mod
1841   This command enables function filtering per module. The
1842   parameter defines the module. For example, if only the write*
1843   functions in the ext3 module are desired, run:
1844
1845    echo 'write*:mod:ext3' > set_ftrace_filter
1846
1847   This command interacts with the filter in the same way as
1848   filtering based on function names. Thus, adding more functions
1849   in a different module is accomplished by appending (>>) to the
1850   filter file. Remove specific module functions by prepending
1851   '!':
1852
1853    echo '!writeback*:mod:ext3' >> set_ftrace_filter
1854
1855 - traceon/traceoff
1856   These commands turn tracing on and off when the specified
1857   functions are hit. The parameter determines how many times the
1858   tracing system is turned on and off. If unspecified, there is
1859   no limit. For example, to disable tracing when a schedule bug
1860   is hit the first 5 times, run:
1861
1862    echo '__schedule_bug:traceoff:5' > set_ftrace_filter
1863
1864   These commands are cumulative whether or not they are appended
1865   to set_ftrace_filter. To remove a command, prepend it by '!'
1866   and drop the parameter:
1867
1868    echo '!__schedule_bug:traceoff' > set_ftrace_filter
1869
1870
1871 trace_pipe
1872 ----------
1873
1874 The trace_pipe outputs the same content as the trace file, but
1875 the effect on the tracing is different. Every read from
1876 trace_pipe is consumed. This means that subsequent reads will be
1877 different. The trace is live.
1878
1879  # echo function > current_tracer
1880  # cat trace_pipe > /tmp/trace.out &
1881 [1] 4153
1882  # echo 1 > tracing_enabled
1883  # usleep 1
1884  # echo 0 > tracing_enabled
1885  # cat trace
1886 # tracer: function
1887 #
1888 #           TASK-PID   CPU#    TIMESTAMP  FUNCTION
1889 #              | |      |          |         |
1890
1891  #
1892  # cat /tmp/trace.out
1893             bash-4043  [00] 41.267106: finish_task_switch <-schedule
1894             bash-4043  [00] 41.267106: hrtick_set <-schedule
1895             bash-4043  [00] 41.267107: hrtick_clear <-hrtick_set
1896             bash-4043  [00] 41.267108: wait_for_completion <-__stop_machine_run
1897             bash-4043  [00] 41.267108: wait_for_common <-wait_for_completion
1898             bash-4043  [00] 41.267109: kthread_stop <-stop_machine_run
1899             bash-4043  [00] 41.267109: init_waitqueue_head <-kthread_stop
1900             bash-4043  [00] 41.267110: wake_up_process <-kthread_stop
1901             bash-4043  [00] 41.267110: try_to_wake_up <-wake_up_process
1902             bash-4043  [00] 41.267111: select_task_rq_rt <-try_to_wake_up
1903
1904
1905 Note, reading the trace_pipe file will block until more input is
1906 added. By changing the tracer, trace_pipe will issue an EOF. We
1907 needed to set the function tracer _before_ we "cat" the
1908 trace_pipe file.
1909
1910
1911 trace entries
1912 -------------
1913
1914 Having too much or not enough data can be troublesome in
1915 diagnosing an issue in the kernel. The file buffer_size_kb is
1916 used to modify the size of the internal trace buffers. The
1917 number listed is the number of entries that can be recorded per
1918 CPU. To know the full size, multiply the number of possible CPUS
1919 with the number of entries.
1920
1921  # cat buffer_size_kb
1922 1408 (units kilobytes)
1923
1924 Note, to modify this, you must have tracing completely disabled.
1925 To do that, echo "nop" into the current_tracer. If the
1926 current_tracer is not set to "nop", an EINVAL error will be
1927 returned.
1928
1929  # echo nop > current_tracer
1930  # echo 10000 > buffer_size_kb
1931  # cat buffer_size_kb
1932 10000 (units kilobytes)
1933
1934 The number of pages which will be allocated is limited to a
1935 percentage of available memory. Allocating too much will produce
1936 an error.
1937
1938  # echo 1000000000000 > buffer_size_kb
1939 -bash: echo: write error: Cannot allocate memory
1940  # cat buffer_size_kb
1941 85
1942
1943 -----------
1944
1945 More details can be found in the source code, in the
1946 kernel/trace/*.c files.