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 buffer of the CPU that triggered the oops. 1351 1352Here's an example of such a dump after a null pointer 1353dereference 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 1390function graph tracer 1391--------------------------- 1392 1393This tracer is similar to the function tracer except that it 1394probes a function on its entry and its exit. This is done by 1395using a dynamically allocated stack of return addresses in each 1396task_struct. On function entry the tracer overwrites the return 1397address of each function traced to set a custom probe. Thus the 1398original return address is stored on the stack of return address 1399in the task_struct. 1400 1401Probing on both ends of a function leads to special features 1402such as: 1403 1404- measure of a function's time execution 1405- having a reliable call stack to draw function calls graph 1406 1407This 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 1445There are several columns that can be dynamically 1446enabled/disabled. You can use every combination of options you 1447want, 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 1545You can put some comments on specific functions by using 1546trace_printk() For example, if you want to put a comment inside 1547the __might_sleep() function, you just have to include 1548<linux/ftrace.h> and call trace_printk() inside __might_sleep() 1549 1550trace_printk("I'm a comment!\n") 1551 1552will produce: 1553 1554 1) | __might_sleep() { 1555 1) | /* I'm a comment! */ 1556 1) 1.449 us | } 1557 1558 1559You might find other useful features for this tracer in the 1560following "dynamic ftrace" section such as tracing only specific 1561functions or tasks. 1562 1563dynamic ftrace 1564-------------- 1565 1566If CONFIG_DYNAMIC_FTRACE is set, the system will run with 1567virtually no overhead when function tracing is disabled. The way 1568this works is the mcount function call (placed at the start of 1569every kernel function, produced by the -pg switch in gcc), 1570starts of pointing to a simple return. (Enabling FTRACE will 1571include the -pg switch in the compiling of the kernel.) 1572 1573At compile time every C file object is run through the 1574recordmcount.pl script (located in the scripts directory). This 1575script will process the C object using objdump to find all the 1576locations 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 1580A new section called "__mcount_loc" is created that holds 1581references to all the mcount call sites in the .text section. 1582This section is compiled back into the original object. The 1583final linker will add all these references into a single table. 1584 1585On boot up, before SMP is initialized, the dynamic ftrace code 1586scans this table and updates all the locations into nops. It 1587also records the locations, which are added to the 1588available_filter_functions list. Modules are processed as they 1589are loaded and before they are executed. When a module is 1590unloaded, it also removes its functions from the ftrace function 1591list. This is automatic in the module unload code, and the 1592module author does not need to worry about it. 1593 1594When tracing is enabled, kstop_machine is called to prevent 1595races with the CPUS executing code being modified (which can 1596cause the CPU to do undesirable things), and the nops are 1597patched back to calls. But this time, they do not call mcount 1598(which is just a function stub). They now call into the ftrace 1599infrastructure. 1600 1601One special side-effect to the recording of the functions being 1602traced is that we can now selectively choose which functions we 1603wish to trace and which ones we want the mcount calls to remain 1604as nops. 1605 1606Two files are used, one for enabling and one for disabling the 1607tracing of specified functions. They are: 1608 1609 set_ftrace_filter 1610 1611and 1612 1613 set_ftrace_notrace 1614 1615A list of available functions that you can add to these files is 1616listed in: 1617 1618 available_filter_functions 1619 1620 # cat available_filter_functions 1621put_prev_task_idle 1622kmem_cache_create 1623pick_next_task_rt 1624get_online_cpus 1625pick_next_task_fair 1626mutex_lock 1627[...] 1628 1629If 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 1646To see which functions are being traced, you can cat the file: 1647 1648 # cat set_ftrace_filter 1649hrtimer_interrupt 1650sys_nanosleep 1651 1652 1653Perhaps this is not enough. The filters also allow simple wild 1654cards. 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 1660These are the only wild cards which are supported. 1661 1662 <match>*<match> will not work. 1663 1664Note: 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 1670Produces: 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 1687Notice that we lost the sys_nanosleep. 1688 1689 # cat set_ftrace_filter 1690hrtimer_run_queues 1691hrtimer_run_pending 1692hrtimer_init 1693hrtimer_cancel 1694hrtimer_try_to_cancel 1695hrtimer_forward 1696hrtimer_start 1697hrtimer_reprogram 1698hrtimer_force_reprogram 1699hrtimer_get_next_event 1700hrtimer_interrupt 1701hrtimer_nanosleep 1702hrtimer_wakeup 1703hrtimer_get_remaining 1704hrtimer_get_res 1705hrtimer_init_sleeper 1706 1707 1708This is because the '>' and '>>' act just like they do in bash. 1709To rewrite the filters, use '>' 1710To append to the filters, use '>>' 1711 1712To clear out a filter so that all functions will be recorded 1713again: 1714 1715 # echo > set_ftrace_filter 1716 # cat set_ftrace_filter 1717 # 1718 1719Again, now we want to append. 1720 1721 # echo sys_nanosleep > set_ftrace_filter 1722 # cat set_ftrace_filter 1723sys_nanosleep 1724 # echo 'hrtimer_*' >> set_ftrace_filter 1725 # cat set_ftrace_filter 1726hrtimer_run_queues 1727hrtimer_run_pending 1728hrtimer_init 1729hrtimer_cancel 1730hrtimer_try_to_cancel 1731hrtimer_forward 1732hrtimer_start 1733hrtimer_reprogram 1734hrtimer_force_reprogram 1735hrtimer_get_next_event 1736hrtimer_interrupt 1737sys_nanosleep 1738hrtimer_nanosleep 1739hrtimer_wakeup 1740hrtimer_get_remaining 1741hrtimer_get_res 1742hrtimer_init_sleeper 1743 1744 1745The set_ftrace_notrace prevents those functions from being 1746traced. 1747 1748 # echo '*preempt*' '*lock*' > set_ftrace_notrace 1749 1750Produces: 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 1766We can see that there's no more lock or preempt tracing. 1767 1768 1769Dynamic ftrace with the function graph tracer 1770--------------------------------------------- 1771 1772Although what has been explained above concerns both the 1773function tracer and the function-graph-tracer, there are some 1774special features only available in the function-graph tracer. 1775 1776If you want to trace only one function and all of its children, 1777you just have to echo its name into set_graph_function: 1778 1779 echo __do_fault > set_graph_function 1780 1781will produce the following "expanded" trace of the __do_fault() 1782function: 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 1819You can also expand several functions at once: 1820 1821 echo sys_open > set_graph_function 1822 echo sys_close >> set_graph_function 1823 1824Now if you want to go back to trace all functions you can clear 1825this special filter via: 1826 1827 echo > set_graph_function 1828 1829 1830Filter commands 1831--------------- 1832 1833A few commands are supported by the set_ftrace_filter interface. 1834Trace commands have the following format: 1835 1836<function>:<command>:<parameter> 1837 1838The 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 1871trace_pipe 1872---------- 1873 1874The trace_pipe outputs the same content as the trace file, but 1875the effect on the tracing is different. Every read from 1876trace_pipe is consumed. This means that subsequent reads will be 1877different. 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 1905Note, reading the trace_pipe file will block until more input is 1906added. By changing the tracer, trace_pipe will issue an EOF. We 1907needed to set the function tracer _before_ we "cat" the 1908trace_pipe file. 1909 1910 1911trace entries 1912------------- 1913 1914Having too much or not enough data can be troublesome in 1915diagnosing an issue in the kernel. The file buffer_size_kb is 1916used to modify the size of the internal trace buffers. The 1917number listed is the number of entries that can be recorded per 1918CPU. To know the full size, multiply the number of possible CPUS 1919with the number of entries. 1920 1921 # cat buffer_size_kb 19221408 (units kilobytes) 1923 1924Note, to modify this, you must have tracing completely disabled. 1925To do that, echo "nop" into the current_tracer. If the 1926current_tracer is not set to "nop", an EINVAL error will be 1927returned. 1928 1929 # echo nop > current_tracer 1930 # echo 10000 > buffer_size_kb 1931 # cat buffer_size_kb 193210000 (units kilobytes) 1933 1934The number of pages which will be allocated is limited to a 1935percentage of available memory. Allocating too much will produce 1936an error. 1937 1938 # echo 1000000000000 > buffer_size_kb 1939-bash: echo: write error: Cannot allocate memory 1940 # cat buffer_size_kb 194185 1942 1943----------- 1944 1945More details can be found in the source code, in the 1946kernel/trace/*.c files. 1947