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 set_ftrace_notrace: 159 160 This has an effect opposite to that of 161 set_ftrace_filter. Any function that is added here will not 162 be traced. If a function exists in both set_ftrace_filter 163 and set_ftrace_notrace, the function will _not_ be traced. 164 165 set_ftrace_pid: 166 167 Have the function tracer only trace a single thread. 168 169 set_graph_function: 170 171 Set a "trigger" function where tracing should start 172 with the function graph tracer (See the section 173 "dynamic ftrace" for more details). 174 175 available_filter_functions: 176 177 This lists the functions that ftrace 178 has processed and can trace. These are the function 179 names that you can pass to "set_ftrace_filter" or 180 "set_ftrace_notrace". (See the section "dynamic ftrace" 181 below for more details.) 182 183 184The Tracers 185----------- 186 187Here is the list of current tracers that may be configured. 188 189 "function" 190 191 Function call tracer to trace all kernel functions. 192 193 "function_graph" 194 195 Similar to the function tracer except that the 196 function tracer probes the functions on their entry 197 whereas the function graph tracer traces on both entry 198 and exit of the functions. It then provides the ability 199 to draw a graph of function calls similar to C code 200 source. 201 202 "sched_switch" 203 204 Traces the context switches and wakeups between tasks. 205 206 "irqsoff" 207 208 Traces the areas that disable interrupts and saves 209 the trace with the longest max latency. 210 See tracing_max_latency. When a new max is recorded, 211 it replaces the old trace. It is best to view this 212 trace with the latency-format option enabled. 213 214 "preemptoff" 215 216 Similar to irqsoff but traces and records the amount of 217 time for which preemption is disabled. 218 219 "preemptirqsoff" 220 221 Similar to irqsoff and preemptoff, but traces and 222 records the largest time for which irqs and/or preemption 223 is disabled. 224 225 "wakeup" 226 227 Traces and records the max latency that it takes for 228 the highest priority task to get scheduled after 229 it has been woken up. 230 231 "hw-branch-tracer" 232 233 Uses the BTS CPU feature on x86 CPUs to traces all 234 branches executed. 235 236 "nop" 237 238 This is the "trace nothing" tracer. To remove all 239 tracers from tracing simply echo "nop" into 240 current_tracer. 241 242 243Examples of using the tracer 244---------------------------- 245 246Here are typical examples of using the tracers when controlling 247them only with the debugfs interface (without using any 248user-land utilities). 249 250Output format: 251-------------- 252 253Here is an example of the output format of the file "trace" 254 255 -------- 256# tracer: function 257# 258# TASK-PID CPU# TIMESTAMP FUNCTION 259# | | | | | 260 bash-4251 [01] 10152.583854: path_put <-path_walk 261 bash-4251 [01] 10152.583855: dput <-path_put 262 bash-4251 [01] 10152.583855: _atomic_dec_and_lock <-dput 263 -------- 264 265A header is printed with the tracer name that is represented by 266the trace. In this case the tracer is "function". Then a header 267showing the format. Task name "bash", the task PID "4251", the 268CPU that it was running on "01", the timestamp in <secs>.<usecs> 269format, the function name that was traced "path_put" and the 270parent function that called this function "path_walk". The 271timestamp is the time at which the function was entered. 272 273The sched_switch tracer also includes tracing of task wakeups 274and context switches. 275 276 ksoftirqd/1-7 [01] 1453.070013: 7:115:R + 2916:115:S 277 ksoftirqd/1-7 [01] 1453.070013: 7:115:R + 10:115:S 278 ksoftirqd/1-7 [01] 1453.070013: 7:115:R ==> 10:115:R 279 events/1-10 [01] 1453.070013: 10:115:S ==> 2916:115:R 280 kondemand/1-2916 [01] 1453.070013: 2916:115:S ==> 7:115:R 281 ksoftirqd/1-7 [01] 1453.070013: 7:115:S ==> 0:140:R 282 283Wake ups are represented by a "+" and the context switches are 284shown as "==>". The format is: 285 286 Context switches: 287 288 Previous task Next Task 289 290 <pid>:<prio>:<state> ==> <pid>:<prio>:<state> 291 292 Wake ups: 293 294 Current task Task waking up 295 296 <pid>:<prio>:<state> + <pid>:<prio>:<state> 297 298The prio is the internal kernel priority, which is the inverse 299of the priority that is usually displayed by user-space tools. 300Zero represents the highest priority (99). Prio 100 starts the 301"nice" priorities with 100 being equal to nice -20 and 139 being 302nice 19. The prio "140" is reserved for the idle task which is 303the lowest priority thread (pid 0). 304 305 306Latency trace format 307-------------------- 308 309When the latency-format option is enabled, the trace file gives 310somewhat more information to see why a latency happened. 311Here is a typical trace. 312 313# tracer: irqsoff 314# 315irqsoff latency trace v1.1.5 on 2.6.26-rc8 316-------------------------------------------------------------------- 317 latency: 97 us, #3/3, CPU#0 | (M:preempt VP:0, KP:0, SP:0 HP:0 #P:2) 318 ----------------- 319 | task: swapper-0 (uid:0 nice:0 policy:0 rt_prio:0) 320 ----------------- 321 => started at: apic_timer_interrupt 322 => ended at: do_softirq 323 324# _------=> CPU# 325# / _-----=> irqs-off 326# | / _----=> need-resched 327# || / _---=> hardirq/softirq 328# ||| / _--=> preempt-depth 329# |||| / 330# ||||| delay 331# cmd pid ||||| time | caller 332# \ / ||||| \ | / 333 <idle>-0 0d..1 0us+: trace_hardirqs_off_thunk (apic_timer_interrupt) 334 <idle>-0 0d.s. 97us : __do_softirq (do_softirq) 335 <idle>-0 0d.s1 98us : trace_hardirqs_on (do_softirq) 336 337 338This shows that the current tracer is "irqsoff" tracing the time 339for which interrupts were disabled. It gives the trace version 340and the version of the kernel upon which this was executed on 341(2.6.26-rc8). Then it displays the max latency in microsecs (97 342us). The number of trace entries displayed and the total number 343recorded (both are three: #3/3). The type of preemption that was 344used (PREEMPT). VP, KP, SP, and HP are always zero and are 345reserved for later use. #P is the number of online CPUS (#P:2). 346 347The task is the process that was running when the latency 348occurred. (swapper pid: 0). 349 350The start and stop (the functions in which the interrupts were 351disabled and enabled respectively) that caused the latencies: 352 353 apic_timer_interrupt is where the interrupts were disabled. 354 do_softirq is where they were enabled again. 355 356The next lines after the header are the trace itself. The header 357explains which is which. 358 359 cmd: The name of the process in the trace. 360 361 pid: The PID of that process. 362 363 CPU#: The CPU which the process was running on. 364 365 irqs-off: 'd' interrupts are disabled. '.' otherwise. 366 Note: If the architecture does not support a way to 367 read the irq flags variable, an 'X' will always 368 be printed here. 369 370 need-resched: 'N' task need_resched is set, '.' otherwise. 371 372 hardirq/softirq: 373 'H' - hard irq occurred inside a softirq. 374 'h' - hard irq is running 375 's' - soft irq is running 376 '.' - normal context. 377 378 preempt-depth: The level of preempt_disabled 379 380The above is mostly meaningful for kernel developers. 381 382 time: When the latency-format option is enabled, the trace file 383 output includes a timestamp relative to the start of the 384 trace. This differs from the output when latency-format 385 is disabled, which includes an absolute timestamp. 386 387 delay: This is just to help catch your eye a bit better. And 388 needs to be fixed to be only relative to the same CPU. 389 The marks are determined by the difference between this 390 current trace and the next trace. 391 '!' - greater than preempt_mark_thresh (default 100) 392 '+' - greater than 1 microsecond 393 ' ' - less than or equal to 1 microsecond. 394 395 The rest is the same as the 'trace' file. 396 397 398trace_options 399------------- 400 401The trace_options file is used to control what gets printed in 402the trace output. To see what is available, simply cat the file: 403 404 cat trace_options 405 print-parent nosym-offset nosym-addr noverbose noraw nohex nobin \ 406 noblock nostacktrace nosched-tree nouserstacktrace nosym-userobj 407 408To disable one of the options, echo in the option prepended with 409"no". 410 411 echo noprint-parent > trace_options 412 413To enable an option, leave off the "no". 414 415 echo sym-offset > trace_options 416 417Here are the available options: 418 419 print-parent - On function traces, display the calling (parent) 420 function as well as the function being traced. 421 422 print-parent: 423 bash-4000 [01] 1477.606694: simple_strtoul <-strict_strtoul 424 425 noprint-parent: 426 bash-4000 [01] 1477.606694: simple_strtoul 427 428 429 sym-offset - Display not only the function name, but also the 430 offset in the function. For example, instead of 431 seeing just "ktime_get", you will see 432 "ktime_get+0xb/0x20". 433 434 sym-offset: 435 bash-4000 [01] 1477.606694: simple_strtoul+0x6/0xa0 436 437 sym-addr - this will also display the function address as well 438 as the function name. 439 440 sym-addr: 441 bash-4000 [01] 1477.606694: simple_strtoul <c0339346> 442 443 verbose - This deals with the trace file when the 444 latency-format option is enabled. 445 446 bash 4000 1 0 00000000 00010a95 [58127d26] 1720.415ms \ 447 (+0.000ms): simple_strtoul (strict_strtoul) 448 449 raw - This will display raw numbers. This option is best for 450 use with user applications that can translate the raw 451 numbers better than having it done in the kernel. 452 453 hex - Similar to raw, but the numbers will be in a hexadecimal 454 format. 455 456 bin - This will print out the formats in raw binary. 457 458 block - TBD (needs update) 459 460 stacktrace - This is one of the options that changes the trace 461 itself. When a trace is recorded, so is the stack 462 of functions. This allows for back traces of 463 trace sites. 464 465 userstacktrace - This option changes the trace. It records a 466 stacktrace of the current userspace thread. 467 468 sym-userobj - when user stacktrace are enabled, look up which 469 object the address belongs to, and print a 470 relative address. This is especially useful when 471 ASLR is on, otherwise you don't get a chance to 472 resolve the address to object/file/line after 473 the app is no longer running 474 475 The lookup is performed when you read 476 trace,trace_pipe. Example: 477 478 a.out-1623 [000] 40874.465068: /root/a.out[+0x480] <-/root/a.out[+0 479x494] <- /root/a.out[+0x4a8] <- /lib/libc-2.7.so[+0x1e1a6] 480 481 sched-tree - trace all tasks that are on the runqueue, at 482 every scheduling event. Will add overhead if 483 there's a lot of tasks running at once. 484 485 latency-format - This option changes the trace. When 486 it is enabled, the trace displays 487 additional information about the 488 latencies, as described in "Latency 489 trace format". 490 491sched_switch 492------------ 493 494This tracer simply records schedule switches. Here is an example 495of how to use it. 496 497 # echo sched_switch > current_tracer 498 # echo 1 > tracing_enabled 499 # sleep 1 500 # echo 0 > tracing_enabled 501 # cat trace 502 503# tracer: sched_switch 504# 505# TASK-PID CPU# TIMESTAMP FUNCTION 506# | | | | | 507 bash-3997 [01] 240.132281: 3997:120:R + 4055:120:R 508 bash-3997 [01] 240.132284: 3997:120:R ==> 4055:120:R 509 sleep-4055 [01] 240.132371: 4055:120:S ==> 3997:120:R 510 bash-3997 [01] 240.132454: 3997:120:R + 4055:120:S 511 bash-3997 [01] 240.132457: 3997:120:R ==> 4055:120:R 512 sleep-4055 [01] 240.132460: 4055:120:D ==> 3997:120:R 513 bash-3997 [01] 240.132463: 3997:120:R + 4055:120:D 514 bash-3997 [01] 240.132465: 3997:120:R ==> 4055:120:R 515 <idle>-0 [00] 240.132589: 0:140:R + 4:115:S 516 <idle>-0 [00] 240.132591: 0:140:R ==> 4:115:R 517 ksoftirqd/0-4 [00] 240.132595: 4:115:S ==> 0:140:R 518 <idle>-0 [00] 240.132598: 0:140:R + 4:115:S 519 <idle>-0 [00] 240.132599: 0:140:R ==> 4:115:R 520 ksoftirqd/0-4 [00] 240.132603: 4:115:S ==> 0:140:R 521 sleep-4055 [01] 240.133058: 4055:120:S ==> 3997:120:R 522 [...] 523 524 525As we have discussed previously about this format, the header 526shows the name of the trace and points to the options. The 527"FUNCTION" is a misnomer since here it represents the wake ups 528and context switches. 529 530The sched_switch file only lists the wake ups (represented with 531'+') and context switches ('==>') with the previous task or 532current task first followed by the next task or task waking up. 533The format for both of these is PID:KERNEL-PRIO:TASK-STATE. 534Remember that the KERNEL-PRIO is the inverse of the actual 535priority with zero (0) being the highest priority and the nice 536values starting at 100 (nice -20). Below is a quick chart to map 537the kernel priority to user land priorities. 538 539 Kernel Space User Space 540 =============================================================== 541 0(high) to 98(low) user RT priority 99(high) to 1(low) 542 with SCHED_RR or SCHED_FIFO 543 --------------------------------------------------------------- 544 99 sched_priority is not used in scheduling 545 decisions(it must be specified as 0) 546 --------------------------------------------------------------- 547 100(high) to 139(low) user nice -20(high) to 19(low) 548 --------------------------------------------------------------- 549 140 idle task priority 550 --------------------------------------------------------------- 551 552The task states are: 553 554 R - running : wants to run, may not actually be running 555 S - sleep : process is waiting to be woken up (handles signals) 556 D - disk sleep (uninterruptible sleep) : process must be woken up 557 (ignores signals) 558 T - stopped : process suspended 559 t - traced : process is being traced (with something like gdb) 560 Z - zombie : process waiting to be cleaned up 561 X - unknown 562 563 564ftrace_enabled 565-------------- 566 567The following tracers (listed below) give different output 568depending on whether or not the sysctl ftrace_enabled is set. To 569set ftrace_enabled, one can either use the sysctl function or 570set it via the proc file system interface. 571 572 sysctl kernel.ftrace_enabled=1 573 574 or 575 576 echo 1 > /proc/sys/kernel/ftrace_enabled 577 578To disable ftrace_enabled simply replace the '1' with '0' in the 579above commands. 580 581When ftrace_enabled is set the tracers will also record the 582functions that are within the trace. The descriptions of the 583tracers will also show an example with ftrace enabled. 584 585 586irqsoff 587------- 588 589When interrupts are disabled, the CPU can not react to any other 590external event (besides NMIs and SMIs). This prevents the timer 591interrupt from triggering or the mouse interrupt from letting 592the kernel know of a new mouse event. The result is a latency 593with the reaction time. 594 595The irqsoff tracer tracks the time for which interrupts are 596disabled. When a new maximum latency is hit, the tracer saves 597the trace leading up to that latency point so that every time a 598new maximum is reached, the old saved trace is discarded and the 599new trace is saved. 600 601To reset the maximum, echo 0 into tracing_max_latency. Here is 602an example: 603 604 # echo irqsoff > current_tracer 605 # echo latency-format > trace_options 606 # echo 0 > tracing_max_latency 607 # echo 1 > tracing_enabled 608 # ls -ltr 609 [...] 610 # echo 0 > tracing_enabled 611 # cat trace 612# tracer: irqsoff 613# 614irqsoff latency trace v1.1.5 on 2.6.26 615-------------------------------------------------------------------- 616 latency: 12 us, #3/3, CPU#1 | (M:preempt VP:0, KP:0, SP:0 HP:0 #P:2) 617 ----------------- 618 | task: bash-3730 (uid:0 nice:0 policy:0 rt_prio:0) 619 ----------------- 620 => started at: sys_setpgid 621 => ended at: sys_setpgid 622 623# _------=> CPU# 624# / _-----=> irqs-off 625# | / _----=> need-resched 626# || / _---=> hardirq/softirq 627# ||| / _--=> preempt-depth 628# |||| / 629# ||||| delay 630# cmd pid ||||| time | caller 631# \ / ||||| \ | / 632 bash-3730 1d... 0us : _write_lock_irq (sys_setpgid) 633 bash-3730 1d..1 1us+: _write_unlock_irq (sys_setpgid) 634 bash-3730 1d..2 14us : trace_hardirqs_on (sys_setpgid) 635 636 637Here we see that that we had a latency of 12 microsecs (which is 638very good). The _write_lock_irq in sys_setpgid disabled 639interrupts. The difference between the 12 and the displayed 640timestamp 14us occurred because the clock was incremented 641between the time of recording the max latency and the time of 642recording the function that had that latency. 643 644Note the above example had ftrace_enabled not set. If we set the 645ftrace_enabled, we get a much larger output: 646 647# tracer: irqsoff 648# 649irqsoff latency trace v1.1.5 on 2.6.26-rc8 650-------------------------------------------------------------------- 651 latency: 50 us, #101/101, CPU#0 | (M:preempt VP:0, KP:0, SP:0 HP:0 #P:2) 652 ----------------- 653 | task: ls-4339 (uid:0 nice:0 policy:0 rt_prio:0) 654 ----------------- 655 => started at: __alloc_pages_internal 656 => ended at: __alloc_pages_internal 657 658# _------=> CPU# 659# / _-----=> irqs-off 660# | / _----=> need-resched 661# || / _---=> hardirq/softirq 662# ||| / _--=> preempt-depth 663# |||| / 664# ||||| delay 665# cmd pid ||||| time | caller 666# \ / ||||| \ | / 667 ls-4339 0...1 0us+: get_page_from_freelist (__alloc_pages_internal) 668 ls-4339 0d..1 3us : rmqueue_bulk (get_page_from_freelist) 669 ls-4339 0d..1 3us : _spin_lock (rmqueue_bulk) 670 ls-4339 0d..1 4us : add_preempt_count (_spin_lock) 671 ls-4339 0d..2 4us : __rmqueue (rmqueue_bulk) 672 ls-4339 0d..2 5us : __rmqueue_smallest (__rmqueue) 673 ls-4339 0d..2 5us : __mod_zone_page_state (__rmqueue_smallest) 674 ls-4339 0d..2 6us : __rmqueue (rmqueue_bulk) 675 ls-4339 0d..2 6us : __rmqueue_smallest (__rmqueue) 676 ls-4339 0d..2 7us : __mod_zone_page_state (__rmqueue_smallest) 677 ls-4339 0d..2 7us : __rmqueue (rmqueue_bulk) 678 ls-4339 0d..2 8us : __rmqueue_smallest (__rmqueue) 679[...] 680 ls-4339 0d..2 46us : __rmqueue_smallest (__rmqueue) 681 ls-4339 0d..2 47us : __mod_zone_page_state (__rmqueue_smallest) 682 ls-4339 0d..2 47us : __rmqueue (rmqueue_bulk) 683 ls-4339 0d..2 48us : __rmqueue_smallest (__rmqueue) 684 ls-4339 0d..2 48us : __mod_zone_page_state (__rmqueue_smallest) 685 ls-4339 0d..2 49us : _spin_unlock (rmqueue_bulk) 686 ls-4339 0d..2 49us : sub_preempt_count (_spin_unlock) 687 ls-4339 0d..1 50us : get_page_from_freelist (__alloc_pages_internal) 688 ls-4339 0d..2 51us : trace_hardirqs_on (__alloc_pages_internal) 689 690 691 692Here we traced a 50 microsecond latency. But we also see all the 693functions that were called during that time. Note that by 694enabling function tracing, we incur an added overhead. This 695overhead may extend the latency times. But nevertheless, this 696trace has provided some very helpful debugging information. 697 698 699preemptoff 700---------- 701 702When preemption is disabled, we may be able to receive 703interrupts but the task cannot be preempted and a higher 704priority task must wait for preemption to be enabled again 705before it can preempt a lower priority task. 706 707The preemptoff tracer traces the places that disable preemption. 708Like the irqsoff tracer, it records the maximum latency for 709which preemption was disabled. The control of preemptoff tracer 710is much like the irqsoff tracer. 711 712 # echo preemptoff > current_tracer 713 # echo latency-format > trace_options 714 # echo 0 > tracing_max_latency 715 # echo 1 > tracing_enabled 716 # ls -ltr 717 [...] 718 # echo 0 > tracing_enabled 719 # cat trace 720# tracer: preemptoff 721# 722preemptoff latency trace v1.1.5 on 2.6.26-rc8 723-------------------------------------------------------------------- 724 latency: 29 us, #3/3, CPU#0 | (M:preempt VP:0, KP:0, SP:0 HP:0 #P:2) 725 ----------------- 726 | task: sshd-4261 (uid:0 nice:0 policy:0 rt_prio:0) 727 ----------------- 728 => started at: do_IRQ 729 => ended at: __do_softirq 730 731# _------=> CPU# 732# / _-----=> irqs-off 733# | / _----=> need-resched 734# || / _---=> hardirq/softirq 735# ||| / _--=> preempt-depth 736# |||| / 737# ||||| delay 738# cmd pid ||||| time | caller 739# \ / ||||| \ | / 740 sshd-4261 0d.h. 0us+: irq_enter (do_IRQ) 741 sshd-4261 0d.s. 29us : _local_bh_enable (__do_softirq) 742 sshd-4261 0d.s1 30us : trace_preempt_on (__do_softirq) 743 744 745This has some more changes. Preemption was disabled when an 746interrupt came in (notice the 'h'), and was enabled while doing 747a softirq. (notice the 's'). But we also see that interrupts 748have been disabled when entering the preempt off section and 749leaving it (the 'd'). We do not know if interrupts were enabled 750in the mean time. 751 752# tracer: preemptoff 753# 754preemptoff latency trace v1.1.5 on 2.6.26-rc8 755-------------------------------------------------------------------- 756 latency: 63 us, #87/87, CPU#0 | (M:preempt VP:0, KP:0, SP:0 HP:0 #P:2) 757 ----------------- 758 | task: sshd-4261 (uid:0 nice:0 policy:0 rt_prio:0) 759 ----------------- 760 => started at: remove_wait_queue 761 => ended at: __do_softirq 762 763# _------=> CPU# 764# / _-----=> irqs-off 765# | / _----=> need-resched 766# || / _---=> hardirq/softirq 767# ||| / _--=> preempt-depth 768# |||| / 769# ||||| delay 770# cmd pid ||||| time | caller 771# \ / ||||| \ | / 772 sshd-4261 0d..1 0us : _spin_lock_irqsave (remove_wait_queue) 773 sshd-4261 0d..1 1us : _spin_unlock_irqrestore (remove_wait_queue) 774 sshd-4261 0d..1 2us : do_IRQ (common_interrupt) 775 sshd-4261 0d..1 2us : irq_enter (do_IRQ) 776 sshd-4261 0d..1 2us : idle_cpu (irq_enter) 777 sshd-4261 0d..1 3us : add_preempt_count (irq_enter) 778 sshd-4261 0d.h1 3us : idle_cpu (irq_enter) 779 sshd-4261 0d.h. 4us : handle_fasteoi_irq (do_IRQ) 780[...] 781 sshd-4261 0d.h. 12us : add_preempt_count (_spin_lock) 782 sshd-4261 0d.h1 12us : ack_ioapic_quirk_irq (handle_fasteoi_irq) 783 sshd-4261 0d.h1 13us : move_native_irq (ack_ioapic_quirk_irq) 784 sshd-4261 0d.h1 13us : _spin_unlock (handle_fasteoi_irq) 785 sshd-4261 0d.h1 14us : sub_preempt_count (_spin_unlock) 786 sshd-4261 0d.h1 14us : irq_exit (do_IRQ) 787 sshd-4261 0d.h1 15us : sub_preempt_count (irq_exit) 788 sshd-4261 0d..2 15us : do_softirq (irq_exit) 789 sshd-4261 0d... 15us : __do_softirq (do_softirq) 790 sshd-4261 0d... 16us : __local_bh_disable (__do_softirq) 791 sshd-4261 0d... 16us+: add_preempt_count (__local_bh_disable) 792 sshd-4261 0d.s4 20us : add_preempt_count (__local_bh_disable) 793 sshd-4261 0d.s4 21us : sub_preempt_count (local_bh_enable) 794 sshd-4261 0d.s5 21us : sub_preempt_count (local_bh_enable) 795[...] 796 sshd-4261 0d.s6 41us : add_preempt_count (__local_bh_disable) 797 sshd-4261 0d.s6 42us : sub_preempt_count (local_bh_enable) 798 sshd-4261 0d.s7 42us : sub_preempt_count (local_bh_enable) 799 sshd-4261 0d.s5 43us : add_preempt_count (__local_bh_disable) 800 sshd-4261 0d.s5 43us : sub_preempt_count (local_bh_enable_ip) 801 sshd-4261 0d.s6 44us : sub_preempt_count (local_bh_enable_ip) 802 sshd-4261 0d.s5 44us : add_preempt_count (__local_bh_disable) 803 sshd-4261 0d.s5 45us : sub_preempt_count (local_bh_enable) 804[...] 805 sshd-4261 0d.s. 63us : _local_bh_enable (__do_softirq) 806 sshd-4261 0d.s1 64us : trace_preempt_on (__do_softirq) 807 808 809The above is an example of the preemptoff trace with 810ftrace_enabled set. Here we see that interrupts were disabled 811the entire time. The irq_enter code lets us know that we entered 812an interrupt 'h'. Before that, the functions being traced still 813show that it is not in an interrupt, but we can see from the 814functions themselves that this is not the case. 815 816Notice that __do_softirq when called does not have a 817preempt_count. It may seem that we missed a preempt enabling. 818What really happened is that the preempt count is held on the 819thread's stack and we switched to the softirq stack (4K stacks 820in effect). The code does not copy the preempt count, but 821because interrupts are disabled, we do not need to worry about 822it. Having a tracer like this is good for letting people know 823what really happens inside the kernel. 824 825 826preemptirqsoff 827-------------- 828 829Knowing the locations that have interrupts disabled or 830preemption disabled for the longest times is helpful. But 831sometimes we would like to know when either preemption and/or 832interrupts are disabled. 833 834Consider the following code: 835 836 local_irq_disable(); 837 call_function_with_irqs_off(); 838 preempt_disable(); 839 call_function_with_irqs_and_preemption_off(); 840 local_irq_enable(); 841 call_function_with_preemption_off(); 842 preempt_enable(); 843 844The irqsoff tracer will record the total length of 845call_function_with_irqs_off() and 846call_function_with_irqs_and_preemption_off(). 847 848The preemptoff tracer will record the total length of 849call_function_with_irqs_and_preemption_off() and 850call_function_with_preemption_off(). 851 852But neither will trace the time that interrupts and/or 853preemption is disabled. This total time is the time that we can 854not schedule. To record this time, use the preemptirqsoff 855tracer. 856 857Again, using this trace is much like the irqsoff and preemptoff 858tracers. 859 860 # echo preemptirqsoff > current_tracer 861 # echo latency-format > trace_options 862 # echo 0 > tracing_max_latency 863 # echo 1 > tracing_enabled 864 # ls -ltr 865 [...] 866 # echo 0 > tracing_enabled 867 # cat trace 868# tracer: preemptirqsoff 869# 870preemptirqsoff latency trace v1.1.5 on 2.6.26-rc8 871-------------------------------------------------------------------- 872 latency: 293 us, #3/3, CPU#0 | (M:preempt VP:0, KP:0, SP:0 HP:0 #P:2) 873 ----------------- 874 | task: ls-4860 (uid:0 nice:0 policy:0 rt_prio:0) 875 ----------------- 876 => started at: apic_timer_interrupt 877 => ended at: __do_softirq 878 879# _------=> CPU# 880# / _-----=> irqs-off 881# | / _----=> need-resched 882# || / _---=> hardirq/softirq 883# ||| / _--=> preempt-depth 884# |||| / 885# ||||| delay 886# cmd pid ||||| time | caller 887# \ / ||||| \ | / 888 ls-4860 0d... 0us!: trace_hardirqs_off_thunk (apic_timer_interrupt) 889 ls-4860 0d.s. 294us : _local_bh_enable (__do_softirq) 890 ls-4860 0d.s1 294us : trace_preempt_on (__do_softirq) 891 892 893 894The trace_hardirqs_off_thunk is called from assembly on x86 when 895interrupts are disabled in the assembly code. Without the 896function tracing, we do not know if interrupts were enabled 897within the preemption points. We do see that it started with 898preemption enabled. 899 900Here is a trace with ftrace_enabled set: 901 902 903# tracer: preemptirqsoff 904# 905preemptirqsoff latency trace v1.1.5 on 2.6.26-rc8 906-------------------------------------------------------------------- 907 latency: 105 us, #183/183, CPU#0 | (M:preempt VP:0, KP:0, SP:0 HP:0 #P:2) 908 ----------------- 909 | task: sshd-4261 (uid:0 nice:0 policy:0 rt_prio:0) 910 ----------------- 911 => started at: write_chan 912 => ended at: __do_softirq 913 914# _------=> CPU# 915# / _-----=> irqs-off 916# | / _----=> need-resched 917# || / _---=> hardirq/softirq 918# ||| / _--=> preempt-depth 919# |||| / 920# ||||| delay 921# cmd pid ||||| time | caller 922# \ / ||||| \ | / 923 ls-4473 0.N.. 0us : preempt_schedule (write_chan) 924 ls-4473 0dN.1 1us : _spin_lock (schedule) 925 ls-4473 0dN.1 2us : add_preempt_count (_spin_lock) 926 ls-4473 0d..2 2us : put_prev_task_fair (schedule) 927[...] 928 ls-4473 0d..2 13us : set_normalized_timespec (ktime_get_ts) 929 ls-4473 0d..2 13us : __switch_to (schedule) 930 sshd-4261 0d..2 14us : finish_task_switch (schedule) 931 sshd-4261 0d..2 14us : _spin_unlock_irq (finish_task_switch) 932 sshd-4261 0d..1 15us : add_preempt_count (_spin_lock_irqsave) 933 sshd-4261 0d..2 16us : _spin_unlock_irqrestore (hrtick_set) 934 sshd-4261 0d..2 16us : do_IRQ (common_interrupt) 935 sshd-4261 0d..2 17us : irq_enter (do_IRQ) 936 sshd-4261 0d..2 17us : idle_cpu (irq_enter) 937 sshd-4261 0d..2 18us : add_preempt_count (irq_enter) 938 sshd-4261 0d.h2 18us : idle_cpu (irq_enter) 939 sshd-4261 0d.h. 18us : handle_fasteoi_irq (do_IRQ) 940 sshd-4261 0d.h. 19us : _spin_lock (handle_fasteoi_irq) 941 sshd-4261 0d.h. 19us : add_preempt_count (_spin_lock) 942 sshd-4261 0d.h1 20us : _spin_unlock (handle_fasteoi_irq) 943 sshd-4261 0d.h1 20us : sub_preempt_count (_spin_unlock) 944[...] 945 sshd-4261 0d.h1 28us : _spin_unlock (handle_fasteoi_irq) 946 sshd-4261 0d.h1 29us : sub_preempt_count (_spin_unlock) 947 sshd-4261 0d.h2 29us : irq_exit (do_IRQ) 948 sshd-4261 0d.h2 29us : sub_preempt_count (irq_exit) 949 sshd-4261 0d..3 30us : do_softirq (irq_exit) 950 sshd-4261 0d... 30us : __do_softirq (do_softirq) 951 sshd-4261 0d... 31us : __local_bh_disable (__do_softirq) 952 sshd-4261 0d... 31us+: add_preempt_count (__local_bh_disable) 953 sshd-4261 0d.s4 34us : add_preempt_count (__local_bh_disable) 954[...] 955 sshd-4261 0d.s3 43us : sub_preempt_count (local_bh_enable_ip) 956 sshd-4261 0d.s4 44us : sub_preempt_count (local_bh_enable_ip) 957 sshd-4261 0d.s3 44us : smp_apic_timer_interrupt (apic_timer_interrupt) 958 sshd-4261 0d.s3 45us : irq_enter (smp_apic_timer_interrupt) 959 sshd-4261 0d.s3 45us : idle_cpu (irq_enter) 960 sshd-4261 0d.s3 46us : add_preempt_count (irq_enter) 961 sshd-4261 0d.H3 46us : idle_cpu (irq_enter) 962 sshd-4261 0d.H3 47us : hrtimer_interrupt (smp_apic_timer_interrupt) 963 sshd-4261 0d.H3 47us : ktime_get (hrtimer_interrupt) 964[...] 965 sshd-4261 0d.H3 81us : tick_program_event (hrtimer_interrupt) 966 sshd-4261 0d.H3 82us : ktime_get (tick_program_event) 967 sshd-4261 0d.H3 82us : ktime_get_ts (ktime_get) 968 sshd-4261 0d.H3 83us : getnstimeofday (ktime_get_ts) 969 sshd-4261 0d.H3 83us : set_normalized_timespec (ktime_get_ts) 970 sshd-4261 0d.H3 84us : clockevents_program_event (tick_program_event) 971 sshd-4261 0d.H3 84us : lapic_next_event (clockevents_program_event) 972 sshd-4261 0d.H3 85us : irq_exit (smp_apic_timer_interrupt) 973 sshd-4261 0d.H3 85us : sub_preempt_count (irq_exit) 974 sshd-4261 0d.s4 86us : sub_preempt_count (irq_exit) 975 sshd-4261 0d.s3 86us : add_preempt_count (__local_bh_disable) 976[...] 977 sshd-4261 0d.s1 98us : sub_preempt_count (net_rx_action) 978 sshd-4261 0d.s. 99us : add_preempt_count (_spin_lock_irq) 979 sshd-4261 0d.s1 99us+: _spin_unlock_irq (run_timer_softirq) 980 sshd-4261 0d.s. 104us : _local_bh_enable (__do_softirq) 981 sshd-4261 0d.s. 104us : sub_preempt_count (_local_bh_enable) 982 sshd-4261 0d.s. 105us : _local_bh_enable (__do_softirq) 983 sshd-4261 0d.s1 105us : trace_preempt_on (__do_softirq) 984 985 986This is a very interesting trace. It started with the preemption 987of the ls task. We see that the task had the "need_resched" bit 988set via the 'N' in the trace. Interrupts were disabled before 989the spin_lock at the beginning of the trace. We see that a 990schedule took place to run sshd. When the interrupts were 991enabled, we took an interrupt. On return from the interrupt 992handler, the softirq ran. We took another interrupt while 993running the softirq as we see from the capital 'H'. 994 995 996wakeup 997------ 998 999In a Real-Time environment it is very important to know the 1000wakeup time it takes for the highest priority task that is woken
1001up to the time that it executes. This is also known as "schedule 1002latency". I stress the point that this is about RT tasks. It is 1003also important to know the scheduling latency of non-RT tasks, 1004but the average schedule latency is better for non-RT tasks. 1005Tools like LatencyTop are more appropriate for such 1006measurements. 1007 1008Real-Time environments are interested in the worst case latency. 1009That is the longest latency it takes for something to happen, 1010and not the average. We can have a very fast scheduler that may 1011only have a large latency once in a while, but that would not 1012work well with Real-Time tasks. The wakeup tracer was designed 1013to record the worst case wakeups of RT tasks. Non-RT tasks are 1014not recorded because the tracer only records one worst case and 1015tracing non-RT tasks that are unpredictable will overwrite the 1016worst case latency of RT tasks. 1017 1018Since this tracer only deals with RT tasks, we will run this 1019slightly differently than we did with the previous tracers. 1020Instead of performing an 'ls', we will run 'sleep 1' under 1021'chrt' which changes the priority of the task. 1022 1023 # echo wakeup > current_tracer 1024 # echo latency-format > trace_options 1025 # echo 0 > tracing_max_latency 1026 # echo 1 > tracing_enabled 1027 # chrt -f 5 sleep 1 1028 # echo 0 > tracing_enabled 1029 # cat trace 1030# tracer: wakeup 1031# 1032wakeup latency trace v1.1.5 on 2.6.26-rc8 1033-------------------------------------------------------------------- 1034 latency: 4 us, #2/2, CPU#1 | (M:preempt VP:0, KP:0, SP:0 HP:0 #P:2) 1035 ----------------- 1036 | task: sleep-4901 (uid:0 nice:0 policy:1 rt_prio:5) 1037 ----------------- 1038 1039# _------=> CPU# 1040# / _-----=> irqs-off 1041# | / _----=> need-resched 1042# || / _---=> hardirq/softirq 1043# ||| / _--=> preempt-depth 1044# |||| / 1045# ||||| delay 1046# cmd pid ||||| time | caller 1047# \ / ||||| \ | / 1048 <idle>-0 1d.h4 0us+: try_to_wake_up (wake_up_process) 1049 <idle>-0 1d..4 4us : schedule (cpu_idle) 1050 1051 1052Running this on an idle system, we see that it only took 4 1053microseconds to perform the task switch. Note, since the trace 1054marker in the schedule is before the actual "switch", we stop 1055the tracing when the recorded task is about to schedule in. This 1056may change if we add a new marker at the end of the scheduler. 1057 1058Notice that the recorded task is 'sleep' with the PID of 4901 1059and it has an rt_prio of 5. This priority is user-space priority 1060and not the internal kernel priority. The policy is 1 for 1061SCHED_FIFO and 2 for SCHED_RR. 1062 1063Doing the same with chrt -r 5 and ftrace_enabled set. 1064 1065# tracer: wakeup 1066# 1067wakeup latency trace v1.1.5 on 2.6.26-rc8 1068-------------------------------------------------------------------- 1069 latency: 50 us, #60/60, CPU#1 | (M:preempt VP:0, KP:0, SP:0 HP:0 #P:2) 1070 ----------------- 1071 | task: sleep-4068 (uid:0 nice:0 policy:2 rt_prio:5) 1072 ----------------- 1073 1074# _------=> CPU# 1075# / _-----=> irqs-off 1076# | / _----=> need-resched 1077# || / _---=> hardirq/softirq 1078# ||| / _--=> preempt-depth 1079# |||| / 1080# ||||| delay 1081# cmd pid ||||| time | caller 1082# \ / ||||| \ | / 1083ksoftirq-7 1d.H3 0us : try_to_wake_up (wake_up_process) 1084ksoftirq-7 1d.H4 1us : sub_preempt_count (marker_probe_cb) 1085ksoftirq-7 1d.H3 2us : check_preempt_wakeup (try_to_wake_up) 1086ksoftirq-7 1d.H3 3us : update_curr (check_preempt_wakeup) 1087ksoftirq-7 1d.H3 4us : calc_delta_mine (update_curr) 1088ksoftirq-7 1d.H3 5us : __resched_task (check_preempt_wakeup) 1089ksoftirq-7 1d.H3 6us : task_wake_up_rt (try_to_wake_up) 1090ksoftirq-7 1d.H3 7us : _spin_unlock_irqrestore (try_to_wake_up) 1091[...] 1092ksoftirq-7 1d.H2 17us : irq_exit (smp_apic_timer_interrupt) 1093ksoftirq-7 1d.H2 18us : sub_preempt_count (irq_exit) 1094ksoftirq-7 1d.s3 19us : sub_preempt_count (irq_exit) 1095ksoftirq-7 1..s2 20us : rcu_process_callbacks (__do_softirq) 1096[...] 1097ksoftirq-7 1..s2 26us : __rcu_process_callbacks (rcu_process_callbacks) 1098ksoftirq-7 1d.s2 27us : _local_bh_enable (__do_softirq) 1099ksoftirq-7 1d.s2 28us : sub_preempt_count (_local_bh_enable) 1100ksoftirq-7 1.N.3 29us : sub_preempt_count (ksoftirqd) 1101ksoftirq-7 1.N.2 30us : _cond_resched (ksoftirqd) 1102ksoftirq-7 1.N.2 31us : __cond_resched (_cond_resched) 1103ksoftirq-7 1.N.2 32us : add_preempt_count (__cond_resched) 1104ksoftirq-7 1.N.2 33us : schedule (__cond_resched) 1105ksoftirq-7 1.N.2 33us : add_preempt_count (schedule) 1106ksoftirq-7 1.N.3 34us : hrtick_clear (schedule) 1107ksoftirq-7 1dN.3 35us : _spin_lock (schedule) 1108ksoftirq-7 1dN.3 36us : add_preempt_count (_spin_lock) 1109ksoftirq-7 1d..4 37us : put_prev_task_fair (schedule) 1110ksoftirq-7 1d..4 38us : update_curr (put_prev_task_fair) 1111[...] 1112ksoftirq-7 1d..5 47us : _spin_trylock (tracing_record_cmdline) 1113ksoftirq-7 1d..5 48us : add_preempt_count (_spin_trylock) 1114ksoftirq-7 1d..6 49us : _spin_unlock (tracing_record_cmdline) 1115ksoftirq-7 1d..6 49us : sub_preempt_count (_spin_unlock) 1116ksoftirq-7 1d..4 50us : schedule (__cond_resched) 1117 1118The interrupt went off while running ksoftirqd. This task runs 1119at SCHED_OTHER. Why did not we see the 'N' set early? This may 1120be a harmless bug with x86_32 and 4K stacks. On x86_32 with 4K 1121stacks configured, the interrupt and softirq run with their own 1122stack. Some information is held on the top of the task's stack 1123(need_resched and preempt_count are both stored there). The 1124setting of the NEED_RESCHED bit is done directly to the task's 1125stack, but the reading of the NEED_RESCHED is done by looking at 1126the current stack, which in this case is the stack for the hard 1127interrupt. This hides the fact that NEED_RESCHED has been set. 1128We do not see the 'N' until we switch back to the task's 1129assigned stack. 1130 1131function 1132-------- 1133 1134This tracer is the function tracer. Enabling the function tracer 1135can be done from the debug file system. Make sure the 1136ftrace_enabled is set; otherwise this tracer is a nop. 1137 1138 # sysctl kernel.ftrace_enabled=1 1139 # echo function > current_tracer 1140 # echo 1 > tracing_enabled 1141 # usleep 1 1142 # echo 0 > tracing_enabled 1143 # cat trace 1144# tracer: function 1145# 1146# TASK-PID CPU# TIMESTAMP FUNCTION 1147# | | | | | 1148 bash-4003 [00] 123.638713: finish_task_switch <-schedule 1149 bash-4003 [00] 123.638714: _spin_unlock_irq <-finish_task_switch 1150 bash-4003 [00] 123.638714: sub_preempt_count <-_spin_unlock_irq 1151 bash-4003 [00] 123.638715: hrtick_set <-schedule 1152 bash-4003 [00] 123.638715: _spin_lock_irqsave <-hrtick_set 1153 bash-4003 [00] 123.638716: add_preempt_count <-_spin_lock_irqsave 1154 bash-4003 [00] 123.638716: _spin_unlock_irqrestore <-hrtick_set 1155 bash-4003 [00] 123.638717: sub_preempt_count <-_spin_unlock_irqrestore 1156 bash-4003 [00] 123.638717: hrtick_clear <-hrtick_set 1157 bash-4003 [00] 123.638718: sub_preempt_count <-schedule 1158 bash-4003 [00] 123.638718: sub_preempt_count <-preempt_schedule 1159 bash-4003 [00] 123.638719: wait_for_completion <-__stop_machine_run 1160 bash-4003 [00] 123.638719: wait_for_common <-wait_for_completion 1161 bash-4003 [00] 123.638720: _spin_lock_irq <-wait_for_common 1162 bash-4003 [00] 123.638720: add_preempt_count <-_spin_lock_irq 1163[...] 1164 1165 1166Note: function tracer uses ring buffers to store the above 1167entries. The newest data may overwrite the oldest data. 1168Sometimes using echo to stop the trace is not sufficient because 1169the tracing could have overwritten the data that you wanted to 1170record. For this reason, it is sometimes better to disable 1171tracing directly from a program. This allows you to stop the 1172tracing at the point that you hit the part that you are 1173interested in. To disable the tracing directly from a C program, 1174something like following code snippet can be used: 1175 1176int trace_fd; 1177[...] 1178int main(int argc, char *argv[]) { 1179 [...] 1180 trace_fd = open(tracing_file("tracing_enabled"), O_WRONLY); 1181 [...] 1182 if (condition_hit()) { 1183 write(trace_fd, "0", 1); 1184 } 1185 [...] 1186} 1187 1188 1189Single thread tracing 1190--------------------- 1191 1192By writing into set_ftrace_pid you can trace a 1193single thread. For example: 1194 1195# cat set_ftrace_pid 1196no pid 1197# echo 3111 > set_ftrace_pid 1198# cat set_ftrace_pid 11993111 1200# echo function > current_tracer 1201# cat trace | head 1202 # tracer: function 1203 # 1204 # TASK-PID CPU# TIMESTAMP FUNCTION 1205 # | | | | | 1206 yum-updatesd-3111 [003] 1637.254676: finish_task_switch <-thread_return 1207 yum-updatesd-3111 [003] 1637.254681: hrtimer_cancel <-schedule_hrtimeout_range 1208 yum-updatesd-3111 [003] 1637.254682: hrtimer_try_to_cancel <-hrtimer_cancel 1209 yum-updatesd-3111 [003] 1637.254683: lock_hrtimer_base <-hrtimer_try_to_cancel 1210 yum-updatesd-3111 [003] 1637.254685: fget_light <-do_sys_poll 1211 yum-updatesd-3111 [003] 1637.254686: pipe_poll <-do_sys_poll 1212# echo -1 > set_ftrace_pid 1213# cat trace |head 1214 # tracer: function 1215 # 1216 # TASK-PID CPU# TIMESTAMP FUNCTION 1217 # | | | | | 1218 ##### CPU 3 buffer started #### 1219 yum-updatesd-3111 [003] 1701.957688: free_poll_entry <-poll_freewait 1220 yum-updatesd-3111 [003] 1701.957689: remove_wait_queue <-free_poll_entry 1221 yum-updatesd-3111 [003] 1701.957691: fput <-free_poll_entry 1222 yum-updatesd-3111 [003] 1701.957692: audit_syscall_exit <-sysret_audit 1223 yum-updatesd-3111 [003] 1701.957693: path_put <-audit_syscall_exit 1224 1225If you want to trace a function when executing, you could use 1226something like this simple program: 1227 1228#include <stdio.h> 1229#include <stdlib.h> 1230#include <sys/types.h> 1231#include <sys/stat.h> 1232#include <fcntl.h> 1233#include <unistd.h> 1234#include <string.h> 1235 1236#define _STR(x) #x 1237#define STR(x) _STR(x) 1238#define MAX_PATH 256 1239 1240const char *find_debugfs(void) 1241{ 1242 static char debugfs[MAX_PATH+1]; 1243 static int debugfs_found; 1244 char type[100]; 1245 FILE *fp; 1246 1247 if (debugfs_found) 1248 return debugfs; 1249 1250 if ((fp = fopen("/proc/mounts","r")) == NULL) { 1251 perror("/proc/mounts"); 1252 return NULL; 1253 } 1254 1255 while (fscanf(fp, "%*s %" 1256 STR(MAX_PATH) 1257 "s %99s %*s %*d %*d\n", 1258 debugfs, type) == 2) { 1259 if (strcmp(type, "debugfs") == 0) 1260 break; 1261 } 1262 fclose(fp); 1263 1264 if (strcmp(type, "debugfs") != 0) { 1265 fprintf(stderr, "debugfs not mounted"); 1266 return NULL; 1267 } 1268 1269 strcat(debugfs, "/tracing/"); 1270 debugfs_found = 1; 1271 1272 return debugfs; 1273} 1274 1275const char *tracing_file(const char *file_name) 1276{ 1277 static char trace_file[MAX_PATH+1]; 1278 snprintf(trace_file, MAX_PATH, "%s/%s", find_debugfs(), file_name); 1279 return trace_file; 1280} 1281 1282int main (int argc, char **argv) 1283{ 1284 if (argc < 1) 1285 exit(-1); 1286 1287 if (fork() > 0) { 1288 int fd, ffd; 1289 char line[64]; 1290 int s; 1291 1292 ffd = open(tracing_file("current_tracer"), O_WRONLY); 1293 if (ffd < 0) 1294 exit(-1); 1295 write(ffd, "nop", 3); 1296 1297 fd = open(tracing_file("set_ftrace_pid"), O_WRONLY); 1298 s = sprintf(line, "%d\n", getpid()); 1299 write(fd, line, s); 1300 1301 write(ffd, "function", 8); 1302 1303 close(fd); 1304 close(ffd); 1305 1306 execvp(argv[1], argv+1); 1307 } 1308 1309 return 0; 1310} 1311 1312 1313hw-branch-tracer (x86 only) 1314--------------------------- 1315 1316This tracer uses the x86 last branch tracing hardware feature to 1317collect a branch trace on all cpus with relatively low overhead. 1318 1319The tracer uses a fixed-size circular buffer per cpu and only 1320traces ring 0 branches. The trace file dumps that buffer in the 1321following format: 1322 1323# tracer: hw-branch-tracer 1324# 1325# CPU# TO <- FROM 1326 0 scheduler_tick+0xb5/0x1bf <- task_tick_idle+0x5/0x6 1327 2 run_posix_cpu_timers+0x2b/0x72a <- run_posix_cpu_timers+0x25/0x72a 1328 0 scheduler_tick+0x139/0x1bf <- scheduler_tick+0xed/0x1bf 1329 0 scheduler_tick+0x17c/0x1bf <- scheduler_tick+0x148/0x1bf 1330 2 run_posix_cpu_timers+0x9e/0x72a <- run_posix_cpu_timers+0x5e/0x72a 1331 0 scheduler_tick+0x1b6/0x1bf <- scheduler_tick+0x1aa/0x1bf 1332 1333 1334The tracer may be used to dump the trace for the oops'ing cpu on 1335a kernel oops into the system log. To enable this, 1336ftrace_dump_on_oops must be set. To set ftrace_dump_on_oops, one 1337can either use the sysctl function or set it via the proc system 1338interface. 1339 1340 sysctl kernel.ftrace_dump_on_oops=1 1341 1342or 1343 1344 echo 1 > /proc/sys/kernel/ftrace_dump_on_oops 1345 1346 1347Here's an example of such a dump after a null pointer 1348dereference in a kernel module: 1349 1350[57848.105921] BUG: unable to handle kernel NULL pointer dereference at 0000000000000000 1351[57848.106019] IP: [<ffffffffa0000006>] open+0x6/0x14 [oops] 1352[57848.106019] PGD 2354e9067 PUD 2375e7067 PMD 0 1353[57848.106019] Oops: 0002 [#1] SMP 1354[57848.106019] last sysfs file: /sys/devices/pci0000:00/0000:00:1e.0/0000:20:05.0/local_cpus 1355[57848.106019] Dumping ftrace buffer: 1356[57848.106019] --------------------------------- 1357[...] 1358[57848.106019] 0 chrdev_open+0xe6/0x165 <- cdev_put+0x23/0x24 1359[57848.106019] 0 chrdev_open+0x117/0x165 <- chrdev_open+0xfa/0x165 1360[57848.106019] 0 chrdev_open+0x120/0x165 <- chrdev_open+0x11c/0x165 1361[57848.106019] 0 chrdev_open+0x134/0x165 <- chrdev_open+0x12b/0x165 1362[57848.106019] 0 open+0x0/0x14 [oops] <- chrdev_open+0x144/0x165 1363[57848.106019] 0 page_fault+0x0/0x30 <- open+0x6/0x14 [oops] 1364[57848.106019] 0 error_entry+0x0/0x5b <- page_fault+0x4/0x30 1365[57848.106019] 0 error_kernelspace+0x0/0x31 <- error_entry+0x59/0x5b 1366[57848.106019] 0 error_sti+0x0/0x1 <- error_kernelspace+0x2d/0x31 1367[57848.106019] 0 page_fault+0x9/0x30 <- error_sti+0x0/0x1 1368[57848.106019] 0 do_page_fault+0x0/0x881 <- page_fault+0x1a/0x30 1369[...] 1370[57848.106019] 0 do_page_fault+0x66b/0x881 <- is_prefetch+0x1ee/0x1f2 1371[57848.106019] 0 do_page_fault+0x6e0/0x881 <- do_page_fault+0x67a/0x881 1372[57848.106019] 0 oops_begin+0x0/0x96 <- do_page_fault+0x6e0/0x881 1373[57848.106019] 0 trace_hw_branch_oops+0x0/0x2d <- oops_begin+0x9/0x96 1374[...] 1375[57848.106019] 0 ds_suspend_bts+0x2a/0xe3 <- ds_suspend_bts+0x1a/0xe3 1376[57848.106019] --------------------------------- 1377[57848.106019] CPU 0 1378[57848.106019] Modules linked in: oops 1379[57848.106019] Pid: 5542, comm: cat Tainted: G W 2.6.28 #23 1380[57848.106019] RIP: 0010:[<ffffffffa0000006>] [<ffffffffa0000006>] open+0x6/0x14 [oops] 1381[57848.106019] RSP: 0018:ffff880235457d48 EFLAGS: 00010246 1382[...] 1383 1384 1385function graph tracer 1386--------------------------- 1387 1388This tracer is similar to the function tracer except that it 1389probes a function on its entry and its exit. This is done by 1390using a dynamically allocated stack of return addresses in each 1391task_struct. On function entry the tracer overwrites the return 1392address of each function traced to set a custom probe. Thus the 1393original return address is stored on the stack of return address 1394in the task_struct. 1395 1396Probing on both ends of a function leads to special features 1397such as: 1398 1399- measure of a function's time execution 1400- having a reliable call stack to draw function calls graph 1401 1402This tracer is useful in several situations: 1403 1404- you want to find the reason of a strange kernel behavior and 1405 need to see what happens in detail on any areas (or specific 1406 ones). 1407 1408- you are experiencing weird latencies but it's difficult to 1409 find its origin. 1410 1411- you want to find quickly which path is taken by a specific 1412 function 1413 1414- you just want to peek inside a working kernel and want to see 1415 what happens there. 1416 1417# tracer: function_graph 1418# 1419# CPU DURATION FUNCTION CALLS 1420# | | | | | | | 1421 1422 0) | sys_open() { 1423 0) | do_sys_open() { 1424 0) | getname() { 1425 0) | kmem_cache_alloc() { 1426 0) 1.382 us | __might_sleep(); 1427 0) 2.478 us | } 1428 0) | strncpy_from_user() { 1429 0) | might_fault() { 1430 0) 1.389 us | __might_sleep(); 1431 0) 2.553 us | } 1432 0) 3.807 us | } 1433 0) 7.876 us | } 1434 0) | alloc_fd() { 1435 0) 0.668 us | _spin_lock(); 1436 0) 0.570 us | expand_files(); 1437 0) 0.586 us | _spin_unlock(); 1438 1439 1440There are several columns that can be dynamically 1441enabled/disabled. You can use every combination of options you 1442want, depending on your needs. 1443 1444- The cpu number on which the function executed is default 1445 enabled. It is sometimes better to only trace one cpu (see 1446 tracing_cpu_mask file) or you might sometimes see unordered 1447 function calls while cpu tracing switch. 1448 1449 hide: echo nofuncgraph-cpu > trace_options 1450 show: echo funcgraph-cpu > trace_options 1451 1452- The duration (function's time of execution) is displayed on 1453 the closing bracket line of a function or on the same line 1454 than the current function in case of a leaf one. It is default 1455 enabled. 1456 1457 hide: echo nofuncgraph-duration > trace_options 1458 show: echo funcgraph-duration > trace_options 1459 1460- The overhead field precedes the duration field in case of 1461 reached duration thresholds. 1462 1463 hide: echo nofuncgraph-overhead > trace_options 1464 show: echo funcgraph-overhead > trace_options 1465 depends on: funcgraph-duration 1466 1467 ie: 1468 1469 0) | up_write() { 1470 0) 0.646 us | _spin_lock_irqsave(); 1471 0) 0.684 us | _spin_unlock_irqrestore(); 1472 0) 3.123 us | } 1473 0) 0.548 us | fput(); 1474 0) + 58.628 us | } 1475 1476 [...] 1477 1478 0) | putname() { 1479 0) | kmem_cache_free() { 1480 0) 0.518 us | __phys_addr(); 1481 0) 1.757 us | } 1482 0) 2.861 us | } 1483 0) ! 115.305 us | } 1484 0) ! 116.402 us | } 1485 1486 + means that the function exceeded 10 usecs. 1487 ! means that the function exceeded 100 usecs. 1488 1489 1490- The task/pid field displays the thread cmdline and pid which 1491 executed the function. It is default disabled. 1492 1493 hide: echo nofuncgraph-proc > trace_options 1494 show: echo funcgraph-proc > trace_options 1495 1496 ie: 1497 1498 # tracer: function_graph 1499 # 1500 # CPU TASK/PID DURATION FUNCTION CALLS 1501 # | | | | | | | | | 1502 0) sh-4802 | | d_free() { 1503 0) sh-4802 | | call_rcu() { 1504 0) sh-4802 | | __call_rcu() { 1505 0) sh-4802 | 0.616 us | rcu_process_gp_end(); 1506 0) sh-4802 | 0.586 us | check_for_new_grace_period(); 1507 0) sh-4802 | 2.899 us | } 1508 0) sh-4802 | 4.040 us | } 1509 0) sh-4802 | 5.151 us | } 1510 0) sh-4802 | + 49.370 us | } 1511 1512 1513- The absolute time field is an absolute timestamp given by the 1514 system clock since it started. A snapshot of this time is 1515 given on each entry/exit of functions 1516 1517 hide: echo nofuncgraph-abstime > trace_options 1518 show: echo funcgraph-abstime > trace_options 1519 1520 ie: 1521 1522 # 1523 # TIME CPU DURATION FUNCTION CALLS 1524 # | | | | | | | | 1525 360.774522 | 1) 0.541 us | } 1526 360.774522 | 1) 4.663 us | } 1527 360.774523 | 1) 0.541 us | __wake_up_bit(); 1528 360.774524 | 1) 6.796 us | } 1529 360.774524 | 1) 7.952 us | } 1530 360.774525 | 1) 9.063 us | } 1531 360.774525 | 1) 0.615 us | journal_mark_dirty(); 1532 360.774527 | 1) 0.578 us | __brelse(); 1533 360.774528 | 1) | reiserfs_prepare_for_journal() { 1534 360.774528 | 1) | unlock_buffer() { 1535 360.774529 | 1) | wake_up_bit() { 1536 360.774529 | 1) | bit_waitqueue() { 1537 360.774530 | 1) 0.594 us | __phys_addr(); 1538 1539 1540You can put some comments on specific functions by using 1541trace_printk() For example, if you want to put a comment inside 1542the __might_sleep() function, you just have to include 1543<linux/ftrace.h> and call trace_printk() inside __might_sleep() 1544 1545trace_printk("I'm a comment!\n") 1546 1547will produce: 1548 1549 1) | __might_sleep() { 1550 1) | /* I'm a comment! */ 1551 1) 1.449 us | } 1552 1553 1554You might find other useful features for this tracer in the 1555following "dynamic ftrace" section such as tracing only specific 1556functions or tasks. 1557 1558dynamic ftrace 1559-------------- 1560 1561If CONFIG_DYNAMIC_FTRACE is set, the system will run with 1562virtually no overhead when function tracing is disabled. The way 1563this works is the mcount function call (placed at the start of 1564every kernel function, produced by the -pg switch in gcc), 1565starts of pointing to a simple return. (Enabling FTRACE will 1566include the -pg switch in the compiling of the kernel.) 1567 1568At compile time every C file object is run through the 1569recordmcount.pl script (located in the scripts directory). This 1570script will process the C object using objdump to find all the 1571locations in the .text section that call mcount. (Note, only the 1572.text section is processed, since processing other sections like 1573.init.text may cause races due to those sections being freed). 1574 1575A new section called "__mcount_loc" is created that holds 1576references to all the mcount call sites in the .text section. 1577This section is compiled back into the original object. The 1578final linker will add all these references into a single table. 1579 1580On boot up, before SMP is initialized, the dynamic ftrace code 1581scans this table and updates all the locations into nops. It 1582also records the locations, which are added to the 1583available_filter_functions list. Modules are processed as they 1584are loaded and before they are executed. When a module is 1585unloaded, it also removes its functions from the ftrace function 1586list. This is automatic in the module unload code, and the 1587module author does not need to worry about it. 1588 1589When tracing is enabled, kstop_machine is called to prevent 1590races with the CPUS executing code being modified (which can 1591cause the CPU to do undesireable things), and the nops are 1592patched back to calls. But this time, they do not call mcount 1593(which is just a function stub). They now call into the ftrace 1594infrastructure. 1595 1596One special side-effect to the recording of the functions being 1597traced is that we can now selectively choose which functions we 1598wish to trace and which ones we want the mcount calls to remain 1599as nops. 1600 1601Two files are used, one for enabling and one for disabling the 1602tracing of specified functions. They are: 1603 1604 set_ftrace_filter 1605 1606and 1607 1608 set_ftrace_notrace 1609 1610A list of available functions that you can add to these files is 1611listed in: 1612 1613 available_filter_functions 1614 1615 # cat available_filter_functions 1616put_prev_task_idle 1617kmem_cache_create 1618pick_next_task_rt 1619get_online_cpus 1620pick_next_task_fair 1621mutex_lock 1622[...] 1623 1624If I am only interested in sys_nanosleep and hrtimer_interrupt: 1625 1626 # echo sys_nanosleep hrtimer_interrupt \ 1627 > set_ftrace_filter 1628 # echo ftrace > current_tracer 1629 # echo 1 > tracing_enabled 1630 # usleep 1 1631 # echo 0 > tracing_enabled 1632 # cat trace 1633# tracer: ftrace 1634# 1635# TASK-PID CPU# TIMESTAMP FUNCTION 1636# | | | | | 1637 usleep-4134 [00] 1317.070017: hrtimer_interrupt <-smp_apic_timer_interrupt 1638 usleep-4134 [00] 1317.070111: sys_nanosleep <-syscall_call 1639 <idle>-0 [00] 1317.070115: hrtimer_interrupt <-smp_apic_timer_interrupt 1640 1641To see which functions are being traced, you can cat the file: 1642 1643 # cat set_ftrace_filter 1644hrtimer_interrupt 1645sys_nanosleep 1646 1647 1648Perhaps this is not enough. The filters also allow simple wild 1649cards. Only the following are currently available 1650 1651 <match>* - will match functions that begin with <match> 1652 *<match> - will match functions that end with <match> 1653 *<match>* - will match functions that have <match> in it 1654 1655These are the only wild cards which are supported. 1656 1657 <match>*<match> will not work. 1658 1659Note: It is better to use quotes to enclose the wild cards, 1660 otherwise the shell may expand the parameters into names 1661 of files in the local directory. 1662 1663 # echo 'hrtimer_*' > set_ftrace_filter 1664 1665Produces: 1666 1667# tracer: ftrace 1668# 1669# TASK-PID CPU# TIMESTAMP FUNCTION 1670# | | | | | 1671 bash-4003 [00] 1480.611794: hrtimer_init <-copy_process 1672 bash-4003 [00] 1480.611941: hrtimer_start <-hrtick_set 1673 bash-4003 [00] 1480.611956: hrtimer_cancel <-hrtick_clear 1674 bash-4003 [00] 1480.611956: hrtimer_try_to_cancel <-hrtimer_cancel 1675 <idle>-0 [00] 1480.612019: hrtimer_get_next_event <-get_next_timer_interrupt 1676 <idle>-0 [00] 1480.612025: hrtimer_get_next_event <-get_next_timer_interrupt 1677 <idle>-0 [00] 1480.612032: hrtimer_get_next_event <-get_next_timer_interrupt 1678 <idle>-0 [00] 1480.612037: hrtimer_get_next_event <-get_next_timer_interrupt 1679 <idle>-0 [00] 1480.612382: hrtimer_get_next_event <-get_next_timer_interrupt 1680 1681 1682Notice that we lost the sys_nanosleep. 1683 1684 # cat set_ftrace_filter 1685hrtimer_run_queues 1686hrtimer_run_pending 1687hrtimer_init 1688hrtimer_cancel 1689hrtimer_try_to_cancel 1690hrtimer_forward 1691hrtimer_start 1692hrtimer_reprogram 1693hrtimer_force_reprogram 1694hrtimer_get_next_event 1695hrtimer_interrupt 1696hrtimer_nanosleep 1697hrtimer_wakeup 1698hrtimer_get_remaining 1699hrtimer_get_res 1700hrtimer_init_sleeper 1701 1702 1703This is because the '>' and '>>' act just like they do in bash. 1704To rewrite the filters, use '>' 1705To append to the filters, use '>>' 1706 1707To clear out a filter so that all functions will be recorded 1708again: 1709 1710 # echo > set_ftrace_filter 1711 # cat set_ftrace_filter 1712 # 1713 1714Again, now we want to append. 1715 1716 # echo sys_nanosleep > set_ftrace_filter 1717 # cat set_ftrace_filter 1718sys_nanosleep 1719 # echo 'hrtimer_*' >> set_ftrace_filter 1720 # cat set_ftrace_filter 1721hrtimer_run_queues 1722hrtimer_run_pending 1723hrtimer_init 1724hrtimer_cancel 1725hrtimer_try_to_cancel 1726hrtimer_forward 1727hrtimer_start 1728hrtimer_reprogram 1729hrtimer_force_reprogram 1730hrtimer_get_next_event 1731hrtimer_interrupt 1732sys_nanosleep 1733hrtimer_nanosleep 1734hrtimer_wakeup 1735hrtimer_get_remaining 1736hrtimer_get_res 1737hrtimer_init_sleeper 1738 1739 1740The set_ftrace_notrace prevents those functions from being 1741traced. 1742 1743 # echo '*preempt*' '*lock*' > set_ftrace_notrace 1744 1745Produces: 1746 1747# tracer: ftrace 1748# 1749# TASK-PID CPU# TIMESTAMP FUNCTION 1750# | | | | | 1751 bash-4043 [01] 115.281644: finish_task_switch <-schedule 1752 bash-4043 [01] 115.281645: hrtick_set <-schedule 1753 bash-4043 [01] 115.281645: hrtick_clear <-hrtick_set 1754 bash-4043 [01] 115.281646: wait_for_completion <-__stop_machine_run 1755 bash-4043 [01] 115.281647: wait_for_common <-wait_for_completion 1756 bash-4043 [01] 115.281647: kthread_stop <-stop_machine_run 1757 bash-4043 [01] 115.281648: init_waitqueue_head <-kthread_stop 1758 bash-4043 [01] 115.281648: wake_up_process <-kthread_stop 1759 bash-4043 [01] 115.281649: try_to_wake_up <-wake_up_process 1760 1761We can see that there's no more lock or preempt tracing. 1762 1763 1764Dynamic ftrace with the function graph tracer 1765--------------------------------------------- 1766 1767Although what has been explained above concerns both the 1768function tracer and the function-graph-tracer, there are some 1769special features only available in the function-graph tracer. 1770 1771If you want to trace only one function and all of its children, 1772you just have to echo its name into set_graph_function: 1773 1774 echo __do_fault > set_graph_function 1775 1776will produce the following "expanded" trace of the __do_fault() 1777function: 1778 1779 0) | __do_fault() { 1780 0) | filemap_fault() { 1781 0) | find_lock_page() { 1782 0) 0.804 us | find_get_page(); 1783 0) | __might_sleep() { 1784 0) 1.329 us | } 1785 0) 3.904 us | } 1786 0) 4.979 us | } 1787 0) 0.653 us | _spin_lock(); 1788 0) 0.578 us | page_add_file_rmap(); 1789 0) 0.525 us | native_set_pte_at(); 1790 0) 0.585 us | _spin_unlock(); 1791 0) | unlock_page() { 1792 0) 0.541 us | page_waitqueue(); 1793 0) 0.639 us | __wake_up_bit(); 1794 0) 2.786 us | } 1795 0) + 14.237 us | } 1796 0) | __do_fault() { 1797 0) | filemap_fault() { 1798 0) | find_lock_page() { 1799 0) 0.698 us | find_get_page(); 1800 0) | __might_sleep() { 1801 0) 1.412 us | } 1802 0) 3.950 us | } 1803 0) 5.098 us | } 1804 0) 0.631 us | _spin_lock(); 1805 0) 0.571 us | page_add_file_rmap(); 1806 0) 0.526 us | native_set_pte_at(); 1807 0) 0.586 us | _spin_unlock(); 1808 0) | unlock_page() { 1809 0) 0.533 us | page_waitqueue(); 1810 0) 0.638 us | __wake_up_bit(); 1811 0) 2.793 us | } 1812 0) + 14.012 us | } 1813 1814You can also expand several functions at once: 1815 1816 echo sys_open > set_graph_function 1817 echo sys_close >> set_graph_function 1818 1819Now if you want to go back to trace all functions you can clear 1820this special filter via: 1821 1822 echo > set_graph_function 1823 1824 1825trace_pipe 1826---------- 1827 1828The trace_pipe outputs the same content as the trace file, but 1829the effect on the tracing is different. Every read from 1830trace_pipe is consumed. This means that subsequent reads will be 1831different. The trace is live. 1832 1833 # echo function > current_tracer 1834 # cat trace_pipe > /tmp/trace.out & 1835[1] 4153 1836 # echo 1 > tracing_enabled 1837 # usleep 1 1838 # echo 0 > tracing_enabled 1839 # cat trace 1840# tracer: function 1841# 1842# TASK-PID CPU# TIMESTAMP FUNCTION 1843# | | | | | 1844 1845 # 1846 # cat /tmp/trace.out 1847 bash-4043 [00] 41.267106: finish_task_switch <-schedule 1848 bash-4043 [00] 41.267106: hrtick_set <-schedule 1849 bash-4043 [00] 41.267107: hrtick_clear <-hrtick_set 1850 bash-4043 [00] 41.267108: wait_for_completion <-__stop_machine_run 1851 bash-4043 [00] 41.267108: wait_for_common <-wait_for_completion 1852 bash-4043 [00] 41.267109: kthread_stop <-stop_machine_run 1853 bash-4043 [00] 41.267109: init_waitqueue_head <-kthread_stop 1854 bash-4043 [00] 41.267110: wake_up_process <-kthread_stop 1855 bash-4043 [00] 41.267110: try_to_wake_up <-wake_up_process 1856 bash-4043 [00] 41.267111: select_task_rq_rt <-try_to_wake_up 1857 1858 1859Note, reading the trace_pipe file will block until more input is 1860added. By changing the tracer, trace_pipe will issue an EOF. We 1861needed to set the function tracer _before_ we "cat" the 1862trace_pipe file. 1863 1864 1865trace entries 1866------------- 1867 1868Having too much or not enough data can be troublesome in 1869diagnosing an issue in the kernel. The file buffer_size_kb is 1870used to modify the size of the internal trace buffers. The 1871number listed is the number of entries that can be recorded per 1872CPU. To know the full size, multiply the number of possible CPUS 1873with the number of entries. 1874 1875 # cat buffer_size_kb 18761408 (units kilobytes) 1877 1878Note, to modify this, you must have tracing completely disabled. 1879To do that, echo "nop" into the current_tracer. If the 1880current_tracer is not set to "nop", an EINVAL error will be 1881returned. 1882 1883 # echo nop > current_tracer 1884 # echo 10000 > buffer_size_kb 1885 # cat buffer_size_kb 188610000 (units kilobytes) 1887 1888The number of pages which will be allocated is limited to a 1889percentage of available memory. Allocating too much will produce 1890an error. 1891 1892 # echo 1000000000000 > buffer_size_kb 1893-bash: echo: write error: Cannot allocate memory 1894 # cat buffer_size_kb 189585 1896 1897----------- 1898 1899More details can be found in the source code, in the 1900kernel/trace/*.c files. 1901