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