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 11Updated for: 3.10 12 13Introduction 14------------ 15 16Ftrace is an internal tracer designed to help out developers and 17designers of systems to find what is going on inside the kernel. 18It can be used for debugging or analyzing latencies and 19performance issues that take place outside of user-space. 20 21Although ftrace is typically considered the function tracer, it 22is really a frame work of several assorted tracing utilities. 23There's latency tracing to examine what occurs between interrupts 24disabled and enabled, as well as for preemption and from a time 25a task is woken to the task is actually scheduled in. 26 27One of the most common uses of ftrace is the event tracing. 28Through out the kernel is hundreds of static event points that 29can be enabled via the debugfs file system to see what is 30going on in certain parts of the kernel. 31 32 33Implementation Details 34---------------------- 35 36See ftrace-design.txt for details for arch porters and such. 37 38 39The File System 40--------------- 41 42Ftrace uses the debugfs file system to hold the control files as 43well as the files to display output. 44 45When debugfs is configured into the kernel (which selecting any ftrace 46option will do) the directory /sys/kernel/debug will be created. To mount 47this directory, you can add to your /etc/fstab file: 48 49 debugfs /sys/kernel/debug debugfs defaults 0 0 50 51Or you can mount it at run time with: 52 53 mount -t debugfs nodev /sys/kernel/debug 54 55For quicker access to that directory you may want to make a soft link to 56it: 57 58 ln -s /sys/kernel/debug /debug 59 60Any selected ftrace option will also create a directory called tracing 61within the debugfs. The rest of the document will assume that you are in 62the ftrace directory (cd /sys/kernel/debug/tracing) and will only concentrate 63on the files within that directory and not distract from the content with 64the extended "/sys/kernel/debug/tracing" path name. 65 66That's it! (assuming that you have ftrace configured into your kernel) 67 68After mounting debugfs, you can see a directory called 69"tracing". This directory contains the control and output files 70of ftrace. Here is a list of some of the key files: 71 72 73 Note: all time values are in microseconds. 74 75 current_tracer: 76 77 This is used to set or display the current tracer 78 that is configured. 79 80 available_tracers: 81 82 This holds the different types of tracers that 83 have been compiled into the kernel. The 84 tracers listed here can be configured by 85 echoing their name into current_tracer. 86 87 tracing_on: 88 89 This sets or displays whether writing to the trace 90 ring buffer is enabled. Echo 0 into this file to disable 91 the tracer or 1 to enable it. Note, this only disables 92 writing to the ring buffer, the tracing overhead may 93 still be occurring. 94 95 trace: 96 97 This file holds the output of the trace in a human 98 readable format (described below). 99 100 trace_pipe: 101 102 The output is the same as the "trace" file but this 103 file is meant to be streamed with live tracing. 104 Reads from this file will block until new data is 105 retrieved. Unlike the "trace" file, this file is a 106 consumer. This means reading from this file causes 107 sequential reads to display more current data. Once 108 data is read from this file, it is consumed, and 109 will not be read again with a sequential read. The 110 "trace" file is static, and if the tracer is not 111 adding more data, it will display the same 112 information every time it is read. 113 114 trace_options: 115 116 This file lets the user control the amount of data 117 that is displayed in one of the above output 118 files. Options also exist to modify how a tracer 119 or events work (stack traces, timestamps, etc). 120 121 options: 122 123 This is a directory that has a file for every available 124 trace option (also in trace_options). Options may also be set 125 or cleared by writing a "1" or "0" respectively into the 126 corresponding file with the option name. 127 128 tracing_max_latency: 129 130 Some of the tracers record the max latency. 131 For example, the time interrupts are disabled. 132 This time is saved in this file. The max trace 133 will also be stored, and displayed by "trace". 134 A new max trace will only be recorded if the 135 latency is greater than the value in this 136 file. (in microseconds) 137 138 tracing_thresh: 139 140 Some latency tracers will record a trace whenever the 141 latency is greater than the number in this file. 142 Only active when the file contains a number greater than 0. 143 (in microseconds) 144 145 buffer_size_kb: 146 147 This sets or displays the number of kilobytes each CPU 148 buffer holds. By default, the trace buffers are the same size 149 for each CPU. The displayed number is the size of the 150 CPU buffer and not total size of all buffers. The 151 trace buffers are allocated in pages (blocks of memory 152 that the kernel uses for allocation, usually 4 KB in size). 153 If the last page allocated has room for more bytes 154 than requested, the rest of the page will be used, 155 making the actual allocation bigger than requested. 156 ( Note, the size may not be a multiple of the page size 157 due to buffer management meta-data. ) 158 159 buffer_total_size_kb: 160 161 This displays the total combined size of all the trace buffers. 162 163 free_buffer: 164 165 If a process is performing the tracing, and the ring buffer 166 should be shrunk "freed" when the process is finished, even 167 if it were to be killed by a signal, this file can be used 168 for that purpose. On close of this file, the ring buffer will 169 be resized to its minimum size. Having a process that is tracing 170 also open this file, when the process exits its file descriptor 171 for this file will be closed, and in doing so, the ring buffer 172 will be "freed". 173 174 It may also stop tracing if disable_on_free option is set. 175 176 tracing_cpumask: 177 178 This is a mask that lets the user only trace 179 on specified CPUs. The format is a hex string 180 representing the CPUs. 181 182 set_ftrace_filter: 183 184 When dynamic ftrace is configured in (see the 185 section below "dynamic ftrace"), the code is dynamically 186 modified (code text rewrite) to disable calling of the 187 function profiler (mcount). This lets tracing be configured 188 in with practically no overhead in performance. This also 189 has a side effect of enabling or disabling specific functions 190 to be traced. Echoing names of functions into this file 191 will limit the trace to only those functions. 192 193 This interface also allows for commands to be used. See the 194 "Filter commands" section for more details. 195 196 set_ftrace_notrace: 197 198 This has an effect opposite to that of 199 set_ftrace_filter. Any function that is added here will not 200 be traced. If a function exists in both set_ftrace_filter 201 and set_ftrace_notrace, the function will _not_ be traced. 202 203 set_ftrace_pid: 204 205 Have the function tracer only trace a single thread. 206 207 set_event_pid: 208 209 Have the events only trace a task with a PID listed in this file. 210 Note, sched_switch and sched_wake_up will also trace events 211 listed in this file. 212 213 set_graph_function: 214 215 Set a "trigger" function where tracing should start 216 with the function graph tracer (See the section 217 "dynamic ftrace" for more details). 218 219 available_filter_functions: 220 221 This lists the functions that ftrace 222 has processed and can trace. These are the function 223 names that you can pass to "set_ftrace_filter" or 224 "set_ftrace_notrace". (See the section "dynamic ftrace" 225 below for more details.) 226 227 enabled_functions: 228 229 This file is more for debugging ftrace, but can also be useful 230 in seeing if any function has a callback attached to it. 231 Not only does the trace infrastructure use ftrace function 232 trace utility, but other subsystems might too. This file 233 displays all functions that have a callback attached to them 234 as well as the number of callbacks that have been attached. 235 Note, a callback may also call multiple functions which will 236 not be listed in this count. 237 238 If the callback registered to be traced by a function with 239 the "save regs" attribute (thus even more overhead), a 'R' 240 will be displayed on the same line as the function that 241 is returning registers. 242 243 If the callback registered to be traced by a function with 244 the "ip modify" attribute (thus the regs->ip can be changed), 245 an 'I' will be displayed on the same line as the function that 246 can be overridden. 247 248 function_profile_enabled: 249 250 When set it will enable all functions with either the function 251 tracer, or if enabled, the function graph tracer. It will 252 keep a histogram of the number of functions that were called 253 and if run with the function graph tracer, it will also keep 254 track of the time spent in those functions. The histogram 255 content can be displayed in the files: 256 257 trace_stats/function<cpu> ( function0, function1, etc). 258 259 trace_stats: 260 261 A directory that holds different tracing stats. 262 263 kprobe_events: 264 265 Enable dynamic trace points. See kprobetrace.txt. 266 267 kprobe_profile: 268 269 Dynamic trace points stats. See kprobetrace.txt. 270 271 max_graph_depth: 272 273 Used with the function graph tracer. This is the max depth 274 it will trace into a function. Setting this to a value of 275 one will show only the first kernel function that is called 276 from user space. 277 278 printk_formats: 279 280 This is for tools that read the raw format files. If an event in 281 the ring buffer references a string (currently only trace_printk() 282 does this), only a pointer to the string is recorded into the buffer 283 and not the string itself. This prevents tools from knowing what 284 that string was. This file displays the string and address for 285 the string allowing tools to map the pointers to what the 286 strings were. 287 288 saved_cmdlines: 289 290 Only the pid of the task is recorded in a trace event unless 291 the event specifically saves the task comm as well. Ftrace 292 makes a cache of pid mappings to comms to try to display 293 comms for events. If a pid for a comm is not listed, then 294 "<...>" is displayed in the output. 295 296 snapshot: 297 298 This displays the "snapshot" buffer and also lets the user 299 take a snapshot of the current running trace. 300 See the "Snapshot" section below for more details. 301 302 stack_max_size: 303 304 When the stack tracer is activated, this will display the 305 maximum stack size it has encountered. 306 See the "Stack Trace" section below. 307 308 stack_trace: 309 310 This displays the stack back trace of the largest stack 311 that was encountered when the stack tracer is activated. 312 See the "Stack Trace" section below. 313 314 stack_trace_filter: 315 316 This is similar to "set_ftrace_filter" but it limits what 317 functions the stack tracer will check. 318 319 trace_clock: 320 321 Whenever an event is recorded into the ring buffer, a 322 "timestamp" is added. This stamp comes from a specified 323 clock. By default, ftrace uses the "local" clock. This 324 clock is very fast and strictly per cpu, but on some 325 systems it may not be monotonic with respect to other 326 CPUs. In other words, the local clocks may not be in sync 327 with local clocks on other CPUs. 328 329 Usual clocks for tracing: 330 331 # cat trace_clock 332 [local] global counter x86-tsc 333 334 local: Default clock, but may not be in sync across CPUs 335 336 global: This clock is in sync with all CPUs but may 337 be a bit slower than the local clock. 338 339 counter: This is not a clock at all, but literally an atomic 340 counter. It counts up one by one, but is in sync 341 with all CPUs. This is useful when you need to 342 know exactly the order events occurred with respect to 343 each other on different CPUs. 344 345 uptime: This uses the jiffies counter and the time stamp 346 is relative to the time since boot up. 347 348 perf: This makes ftrace use the same clock that perf uses. 349 Eventually perf will be able to read ftrace buffers 350 and this will help out in interleaving the data. 351 352 x86-tsc: Architectures may define their own clocks. For 353 example, x86 uses its own TSC cycle clock here. 354 355 ppc-tb: This uses the powerpc timebase register value. 356 This is in sync across CPUs and can also be used 357 to correlate events across hypervisor/guest if 358 tb_offset is known. 359 360 To set a clock, simply echo the clock name into this file. 361 362 echo global > trace_clock 363 364 trace_marker: 365 366 This is a very useful file for synchronizing user space 367 with events happening in the kernel. Writing strings into 368 this file will be written into the ftrace buffer. 369 370 It is useful in applications to open this file at the start 371 of the application and just reference the file descriptor 372 for the file. 373 374 void trace_write(const char *fmt, ...) 375 { 376 va_list ap; 377 char buf[256]; 378 int n; 379 380 if (trace_fd < 0) 381 return; 382 383 va_start(ap, fmt); 384 n = vsnprintf(buf, 256, fmt, ap); 385 va_end(ap); 386 387 write(trace_fd, buf, n); 388 } 389 390 start: 391 392 trace_fd = open("trace_marker", WR_ONLY); 393 394 uprobe_events: 395 396 Add dynamic tracepoints in programs. 397 See uprobetracer.txt 398 399 uprobe_profile: 400 401 Uprobe statistics. See uprobetrace.txt 402 403 instances: 404 405 This is a way to make multiple trace buffers where different 406 events can be recorded in different buffers. 407 See "Instances" section below. 408 409 events: 410 411 This is the trace event directory. It holds event tracepoints 412 (also known as static tracepoints) that have been compiled 413 into the kernel. It shows what event tracepoints exist 414 and how they are grouped by system. There are "enable" 415 files at various levels that can enable the tracepoints 416 when a "1" is written to them. 417 418 See events.txt for more information. 419 420 per_cpu: 421 422 This is a directory that contains the trace per_cpu information. 423 424 per_cpu/cpu0/buffer_size_kb: 425 426 The ftrace buffer is defined per_cpu. That is, there's a separate 427 buffer for each CPU to allow writes to be done atomically, 428 and free from cache bouncing. These buffers may have different 429 size buffers. This file is similar to the buffer_size_kb 430 file, but it only displays or sets the buffer size for the 431 specific CPU. (here cpu0). 432 433 per_cpu/cpu0/trace: 434 435 This is similar to the "trace" file, but it will only display 436 the data specific for the CPU. If written to, it only clears 437 the specific CPU buffer. 438 439 per_cpu/cpu0/trace_pipe 440 441 This is similar to the "trace_pipe" file, and is a consuming 442 read, but it will only display (and consume) the data specific 443 for the CPU. 444 445 per_cpu/cpu0/trace_pipe_raw 446 447 For tools that can parse the ftrace ring buffer binary format, 448 the trace_pipe_raw file can be used to extract the data 449 from the ring buffer directly. With the use of the splice() 450 system call, the buffer data can be quickly transferred to 451 a file or to the network where a server is collecting the 452 data. 453 454 Like trace_pipe, this is a consuming reader, where multiple 455 reads will always produce different data. 456 457 per_cpu/cpu0/snapshot: 458 459 This is similar to the main "snapshot" file, but will only 460 snapshot the current CPU (if supported). It only displays 461 the content of the snapshot for a given CPU, and if 462 written to, only clears this CPU buffer. 463 464 per_cpu/cpu0/snapshot_raw: 465 466 Similar to the trace_pipe_raw, but will read the binary format 467 from the snapshot buffer for the given CPU. 468 469 per_cpu/cpu0/stats: 470 471 This displays certain stats about the ring buffer: 472 473 entries: The number of events that are still in the buffer. 474 475 overrun: The number of lost events due to overwriting when 476 the buffer was full. 477 478 commit overrun: Should always be zero. 479 This gets set if so many events happened within a nested 480 event (ring buffer is re-entrant), that it fills the 481 buffer and starts dropping events. 482 483 bytes: Bytes actually read (not overwritten). 484 485 oldest event ts: The oldest timestamp in the buffer 486 487 now ts: The current timestamp 488 489 dropped events: Events lost due to overwrite option being off. 490 491 read events: The number of events read. 492 493The Tracers 494----------- 495 496Here is the list of current tracers that may be configured. 497 498 "function" 499 500 Function call tracer to trace all kernel functions. 501 502 "function_graph" 503 504 Similar to the function tracer except that the 505 function tracer probes the functions on their entry 506 whereas the function graph tracer traces on both entry 507 and exit of the functions. It then provides the ability 508 to draw a graph of function calls similar to C code 509 source. 510 511 "irqsoff" 512 513 Traces the areas that disable interrupts and saves 514 the trace with the longest max latency. 515 See tracing_max_latency. When a new max is recorded, 516 it replaces the old trace. It is best to view this 517 trace with the latency-format option enabled. 518 519 "preemptoff" 520 521 Similar to irqsoff but traces and records the amount of 522 time for which preemption is disabled. 523 524 "preemptirqsoff" 525 526 Similar to irqsoff and preemptoff, but traces and 527 records the largest time for which irqs and/or preemption 528 is disabled. 529 530 "wakeup" 531 532 Traces and records the max latency that it takes for 533 the highest priority task to get scheduled after 534 it has been woken up. 535 Traces all tasks as an average developer would expect. 536 537 "wakeup_rt" 538 539 Traces and records the max latency that it takes for just 540 RT tasks (as the current "wakeup" does). This is useful 541 for those interested in wake up timings of RT tasks. 542 543 "nop" 544 545 This is the "trace nothing" tracer. To remove all 546 tracers from tracing simply echo "nop" into 547 current_tracer. 548 549 550Examples of using the tracer 551---------------------------- 552 553Here are typical examples of using the tracers when controlling 554them only with the debugfs interface (without using any 555user-land utilities). 556 557Output format: 558-------------- 559 560Here is an example of the output format of the file "trace" 561 562 -------- 563# tracer: function 564# 565# entries-in-buffer/entries-written: 140080/250280 #P:4 566# 567# _-----=> irqs-off 568# / _----=> need-resched 569# | / _---=> hardirq/softirq 570# || / _--=> preempt-depth 571# ||| / delay 572# TASK-PID CPU# |||| TIMESTAMP FUNCTION 573# | | | |||| | | 574 bash-1977 [000] .... 17284.993652: sys_close <-system_call_fastpath 575 bash-1977 [000] .... 17284.993653: __close_fd <-sys_close 576 bash-1977 [000] .... 17284.993653: _raw_spin_lock <-__close_fd 577 sshd-1974 [003] .... 17284.993653: __srcu_read_unlock <-fsnotify 578 bash-1977 [000] .... 17284.993654: add_preempt_count <-_raw_spin_lock 579 bash-1977 [000] ...1 17284.993655: _raw_spin_unlock <-__close_fd 580 bash-1977 [000] ...1 17284.993656: sub_preempt_count <-_raw_spin_unlock 581 bash-1977 [000] .... 17284.993657: filp_close <-__close_fd 582 bash-1977 [000] .... 17284.993657: dnotify_flush <-filp_close 583 sshd-1974 [003] .... 17284.993658: sys_select <-system_call_fastpath 584 -------- 585 586A header is printed with the tracer name that is represented by 587the trace. In this case the tracer is "function". Then it shows the 588number of events in the buffer as well as the total number of entries 589that were written. The difference is the number of entries that were 590lost due to the buffer filling up (250280 - 140080 = 110200 events 591lost). 592 593The header explains the content of the events. Task name "bash", the task 594PID "1977", the CPU that it was running on "000", the latency format 595(explained below), the timestamp in <secs>.<usecs> format, the 596function name that was traced "sys_close" and the parent function that 597called this function "system_call_fastpath". The timestamp is the time 598at which the function was entered. 599 600Latency trace format 601-------------------- 602 603When the latency-format option is enabled or when one of the latency 604tracers is set, the trace file gives somewhat more information to see 605why a latency happened. Here is a typical trace. 606 607# tracer: irqsoff 608# 609# irqsoff latency trace v1.1.5 on 3.8.0-test+ 610# -------------------------------------------------------------------- 611# latency: 259 us, #4/4, CPU#2 | (M:preempt VP:0, KP:0, SP:0 HP:0 #P:4) 612# ----------------- 613# | task: ps-6143 (uid:0 nice:0 policy:0 rt_prio:0) 614# ----------------- 615# => started at: __lock_task_sighand 616# => ended at: _raw_spin_unlock_irqrestore 617# 618# 619# _------=> CPU# 620# / _-----=> irqs-off 621# | / _----=> need-resched 622# || / _---=> hardirq/softirq 623# ||| / _--=> preempt-depth 624# |||| / delay 625# cmd pid ||||| time | caller 626# \ / ||||| \ | / 627 ps-6143 2d... 0us!: trace_hardirqs_off <-__lock_task_sighand 628 ps-6143 2d..1 259us+: trace_hardirqs_on <-_raw_spin_unlock_irqrestore 629 ps-6143 2d..1 263us+: time_hardirqs_on <-_raw_spin_unlock_irqrestore 630 ps-6143 2d..1 306us : <stack trace> 631 => trace_hardirqs_on_caller 632 => trace_hardirqs_on 633 => _raw_spin_unlock_irqrestore 634 => do_task_stat 635 => proc_tgid_stat 636 => proc_single_show 637 => seq_read 638 => vfs_read 639 => sys_read 640 => system_call_fastpath 641 642 643This shows that the current tracer is "irqsoff" tracing the time 644for which interrupts were disabled. It gives the trace version (which 645never changes) and the version of the kernel upon which this was executed on 646(3.10). Then it displays the max latency in microseconds (259 us). The number 647of trace entries displayed and the total number (both are four: #4/4). 648VP, KP, SP, and HP are always zero and are reserved for later use. 649#P is the number of online CPUs (#P:4). 650 651The task is the process that was running when the latency 652occurred. (ps pid: 6143). 653 654The start and stop (the functions in which the interrupts were 655disabled and enabled respectively) that caused the latencies: 656 657 __lock_task_sighand is where the interrupts were disabled. 658 _raw_spin_unlock_irqrestore is where they were enabled again. 659 660The next lines after the header are the trace itself. The header 661explains which is which. 662 663 cmd: The name of the process in the trace. 664 665 pid: The PID of that process. 666 667 CPU#: The CPU which the process was running on. 668 669 irqs-off: 'd' interrupts are disabled. '.' otherwise. 670 Note: If the architecture does not support a way to 671 read the irq flags variable, an 'X' will always 672 be printed here. 673 674 need-resched: 675 'N' both TIF_NEED_RESCHED and PREEMPT_NEED_RESCHED is set, 676 'n' only TIF_NEED_RESCHED is set, 677 'p' only PREEMPT_NEED_RESCHED is set, 678 '.' otherwise. 679 680 hardirq/softirq: 681 'H' - hard irq occurred inside a softirq. 682 'h' - hard irq is running 683 's' - soft irq is running 684 '.' - normal context. 685 686 preempt-depth: The level of preempt_disabled 687 688The above is mostly meaningful for kernel developers. 689 690 time: When the latency-format option is enabled, the trace file 691 output includes a timestamp relative to the start of the 692 trace. This differs from the output when latency-format 693 is disabled, which includes an absolute timestamp. 694 695 delay: This is just to help catch your eye a bit better. And 696 needs to be fixed to be only relative to the same CPU. 697 The marks are determined by the difference between this 698 current trace and the next trace. 699 '$' - greater than 1 second 700 '@' - greater than 100 milisecond 701 '*' - greater than 10 milisecond 702 '#' - greater than 1000 microsecond 703 '!' - greater than 100 microsecond 704 '+' - greater than 10 microsecond 705 ' ' - less than or equal to 10 microsecond. 706 707 The rest is the same as the 'trace' file. 708 709 Note, the latency tracers will usually end with a back trace 710 to easily find where the latency occurred. 711 712trace_options 713------------- 714 715The trace_options file (or the options directory) is used to control 716what gets printed in the trace output, or manipulate the tracers. 717To see what is available, simply cat the file: 718 719 cat trace_options 720print-parent 721nosym-offset 722nosym-addr 723noverbose 724noraw 725nohex 726nobin 727noblock 728nostacktrace 729trace_printk 730noftrace_preempt 731nobranch 732annotate 733nouserstacktrace 734nosym-userobj 735noprintk-msg-only 736context-info 737latency-format 738sleep-time 739graph-time 740record-cmd 741overwrite 742nodisable_on_free 743irq-info 744markers 745function-trace 746 747To disable one of the options, echo in the option prepended with 748"no". 749 750 echo noprint-parent > trace_options 751 752To enable an option, leave off the "no". 753 754 echo sym-offset > trace_options 755 756Here are the available options: 757 758 print-parent - On function traces, display the calling (parent) 759 function as well as the function being traced. 760 761 print-parent: 762 bash-4000 [01] 1477.606694: simple_strtoul <-kstrtoul 763 764 noprint-parent: 765 bash-4000 [01] 1477.606694: simple_strtoul 766 767 768 sym-offset - Display not only the function name, but also the 769 offset in the function. For example, instead of 770 seeing just "ktime_get", you will see 771 "ktime_get+0xb/0x20". 772 773 sym-offset: 774 bash-4000 [01] 1477.606694: simple_strtoul+0x6/0xa0 775 776 sym-addr - this will also display the function address as well 777 as the function name. 778 779 sym-addr: 780 bash-4000 [01] 1477.606694: simple_strtoul <c0339346> 781 782 verbose - This deals with the trace file when the 783 latency-format option is enabled. 784 785 bash 4000 1 0 00000000 00010a95 [58127d26] 1720.415ms \ 786 (+0.000ms): simple_strtoul (kstrtoul) 787 788 raw - This will display raw numbers. This option is best for 789 use with user applications that can translate the raw 790 numbers better than having it done in the kernel. 791 792 hex - Similar to raw, but the numbers will be in a hexadecimal 793 format. 794 795 bin - This will print out the formats in raw binary. 796 797 block - When set, reading trace_pipe will not block when polled. 798 799 stacktrace - This is one of the options that changes the trace 800 itself. When a trace is recorded, so is the stack 801 of functions. This allows for back traces of 802 trace sites. 803 804 trace_printk - Can disable trace_printk() from writing into the buffer. 805 806 branch - Enable branch tracing with the tracer. 807 808 annotate - It is sometimes confusing when the CPU buffers are full 809 and one CPU buffer had a lot of events recently, thus 810 a shorter time frame, were another CPU may have only had 811 a few events, which lets it have older events. When 812 the trace is reported, it shows the oldest events first, 813 and it may look like only one CPU ran (the one with the 814 oldest events). When the annotate option is set, it will 815 display when a new CPU buffer started: 816 817 <idle>-0 [001] dNs4 21169.031481: wake_up_idle_cpu <-add_timer_on 818 <idle>-0 [001] dNs4 21169.031482: _raw_spin_unlock_irqrestore <-add_timer_on 819 <idle>-0 [001] .Ns4 21169.031484: sub_preempt_count <-_raw_spin_unlock_irqrestore 820##### CPU 2 buffer started #### 821 <idle>-0 [002] .N.1 21169.031484: rcu_idle_exit <-cpu_idle 822 <idle>-0 [001] .Ns3 21169.031484: _raw_spin_unlock <-clocksource_watchdog 823 <idle>-0 [001] .Ns3 21169.031485: sub_preempt_count <-_raw_spin_unlock 824 825 userstacktrace - This option changes the trace. It records a 826 stacktrace of the current userspace thread. 827 828 sym-userobj - when user stacktrace are enabled, look up which 829 object the address belongs to, and print a 830 relative address. This is especially useful when 831 ASLR is on, otherwise you don't get a chance to 832 resolve the address to object/file/line after 833 the app is no longer running 834 835 The lookup is performed when you read 836 trace,trace_pipe. Example: 837 838 a.out-1623 [000] 40874.465068: /root/a.out[+0x480] <-/root/a.out[+0 839x494] <- /root/a.out[+0x4a8] <- /lib/libc-2.7.so[+0x1e1a6] 840 841 842 printk-msg-only - When set, trace_printk()s will only show the format 843 and not their parameters (if trace_bprintk() or 844 trace_bputs() was used to save the trace_printk()). 845 846 context-info - Show only the event data. Hides the comm, PID, 847 timestamp, CPU, and other useful data. 848 849 latency-format - This option changes the trace. When 850 it is enabled, the trace displays 851 additional information about the 852 latencies, as described in "Latency 853 trace format". 854 855 sleep-time - When running function graph tracer, to include 856 the time a task schedules out in its function. 857 When enabled, it will account time the task has been 858 scheduled out as part of the function call. 859 860 graph-time - When running function graph tracer, to include the 861 time to call nested functions. When this is not set, 862 the time reported for the function will only include 863 the time the function itself executed for, not the time 864 for functions that it called. 865 866 record-cmd - When any event or tracer is enabled, a hook is enabled 867 in the sched_switch trace point to fill comm cache 868 with mapped pids and comms. But this may cause some 869 overhead, and if you only care about pids, and not the 870 name of the task, disabling this option can lower the 871 impact of tracing. 872 873 overwrite - This controls what happens when the trace buffer is 874 full. If "1" (default), the oldest events are 875 discarded and overwritten. If "0", then the newest 876 events are discarded. 877 (see per_cpu/cpu0/stats for overrun and dropped) 878 879 disable_on_free - When the free_buffer is closed, tracing will 880 stop (tracing_on set to 0). 881 882 irq-info - Shows the interrupt, preempt count, need resched data. 883 When disabled, the trace looks like: 884 885# tracer: function 886# 887# entries-in-buffer/entries-written: 144405/9452052 #P:4 888# 889# TASK-PID CPU# TIMESTAMP FUNCTION 890# | | | | | 891 <idle>-0 [002] 23636.756054: ttwu_do_activate.constprop.89 <-try_to_wake_up 892 <idle>-0 [002] 23636.756054: activate_task <-ttwu_do_activate.constprop.89 893 <idle>-0 [002] 23636.756055: enqueue_task <-activate_task 894 895 896 markers - When set, the trace_marker is writable (only by root). 897 When disabled, the trace_marker will error with EINVAL 898 on write. 899 900 901 function-trace - The latency tracers will enable function tracing 902 if this option is enabled (default it is). When 903 it is disabled, the latency tracers do not trace 904 functions. This keeps the overhead of the tracer down 905 when performing latency tests. 906 907 Note: Some tracers have their own options. They only appear 908 when the tracer is active. 909 910 911 912irqsoff 913------- 914 915When interrupts are disabled, the CPU can not react to any other 916external event (besides NMIs and SMIs). This prevents the timer 917interrupt from triggering or the mouse interrupt from letting 918the kernel know of a new mouse event. The result is a latency 919with the reaction time. 920 921The irqsoff tracer tracks the time for which interrupts are 922disabled. When a new maximum latency is hit, the tracer saves 923the trace leading up to that latency point so that every time a 924new maximum is reached, the old saved trace is discarded and the 925new trace is saved. 926 927To reset the maximum, echo 0 into tracing_max_latency. Here is 928an example: 929 930 # echo 0 > options/function-trace 931 # echo irqsoff > current_tracer 932 # echo 1 > tracing_on 933 # echo 0 > tracing_max_latency 934 # ls -ltr 935 [...] 936 # echo 0 > tracing_on 937 # cat trace 938# tracer: irqsoff 939# 940# irqsoff latency trace v1.1.5 on 3.8.0-test+ 941# -------------------------------------------------------------------- 942# latency: 16 us, #4/4, CPU#0 | (M:preempt VP:0, KP:0, SP:0 HP:0 #P:4) 943# ----------------- 944# | task: swapper/0-0 (uid:0 nice:0 policy:0 rt_prio:0) 945# ----------------- 946# => started at: run_timer_softirq 947# => ended at: run_timer_softirq 948# 949# 950# _------=> CPU# 951# / _-----=> irqs-off 952# | / _----=> need-resched 953# || / _---=> hardirq/softirq 954# ||| / _--=> preempt-depth 955# |||| / delay 956# cmd pid ||||| time | caller 957# \ / ||||| \ | / 958 <idle>-0 0d.s2 0us+: _raw_spin_lock_irq <-run_timer_softirq 959 <idle>-0 0dNs3 17us : _raw_spin_unlock_irq <-run_timer_softirq 960 <idle>-0 0dNs3 17us+: trace_hardirqs_on <-run_timer_softirq 961 <idle>-0 0dNs3 25us : <stack trace> 962 => _raw_spin_unlock_irq 963 => run_timer_softirq 964 => __do_softirq 965 => call_softirq 966 => do_softirq 967 => irq_exit 968 => smp_apic_timer_interrupt 969 => apic_timer_interrupt 970 => rcu_idle_exit 971 => cpu_idle 972 => rest_init 973 => start_kernel 974 => x86_64_start_reservations 975 => x86_64_start_kernel 976 977Here we see that that we had a latency of 16 microseconds (which is 978very good). The _raw_spin_lock_irq in run_timer_softirq disabled 979interrupts. The difference between the 16 and the displayed 980timestamp 25us occurred because the clock was incremented 981between the time of recording the max latency and the time of 982recording the function that had that latency. 983 984Note the above example had function-trace not set. If we set 985function-trace, we get a much larger output: 986 987 with echo 1 > options/function-trace 988 989# tracer: irqsoff 990# 991# irqsoff latency trace v1.1.5 on 3.8.0-test+ 992# -------------------------------------------------------------------- 993# latency: 71 us, #168/168, CPU#3 | (M:preempt VP:0, KP:0, SP:0 HP:0 #P:4) 994# ----------------- 995# | task: bash-2042 (uid:0 nice:0 policy:0 rt_prio:0) 996# ----------------- 997# => started at: ata_scsi_queuecmd 998# => ended at: ata_scsi_queuecmd 999# 1000# 1001# _------=> CPU# 1002# / _-----=> irqs-off 1003# | / _----=> need-resched 1004# || / _---=> hardirq/softirq 1005# ||| / _--=> preempt-depth 1006# |||| / delay 1007# cmd pid ||||| time | caller 1008# \ / ||||| \ | / 1009 bash-2042 3d... 0us : _raw_spin_lock_irqsave <-ata_scsi_queuecmd 1010 bash-2042 3d... 0us : add_preempt_count <-_raw_spin_lock_irqsave 1011 bash-2042 3d..1 1us : ata_scsi_find_dev <-ata_scsi_queuecmd 1012 bash-2042 3d..1 1us : __ata_scsi_find_dev <-ata_scsi_find_dev 1013 bash-2042 3d..1 2us : ata_find_dev.part.14 <-__ata_scsi_find_dev 1014 bash-2042 3d..1 2us : ata_qc_new_init <-__ata_scsi_queuecmd 1015 bash-2042 3d..1 3us : ata_sg_init <-__ata_scsi_queuecmd 1016 bash-2042 3d..1 4us : ata_scsi_rw_xlat <-__ata_scsi_queuecmd 1017 bash-2042 3d..1 4us : ata_build_rw_tf <-ata_scsi_rw_xlat 1018[...] 1019 bash-2042 3d..1 67us : delay_tsc <-__delay 1020 bash-2042 3d..1 67us : add_preempt_count <-delay_tsc 1021 bash-2042 3d..2 67us : sub_preempt_count <-delay_tsc 1022 bash-2042 3d..1 67us : add_preempt_count <-delay_tsc 1023 bash-2042 3d..2 68us : sub_preempt_count <-delay_tsc 1024 bash-2042 3d..1 68us+: ata_bmdma_start <-ata_bmdma_qc_issue 1025 bash-2042 3d..1 71us : _raw_spin_unlock_irqrestore <-ata_scsi_queuecmd 1026 bash-2042 3d..1 71us : _raw_spin_unlock_irqrestore <-ata_scsi_queuecmd 1027 bash-2042 3d..1 72us+: trace_hardirqs_on <-ata_scsi_queuecmd 1028 bash-2042 3d..1 120us : <stack trace> 1029 => _raw_spin_unlock_irqrestore 1030 => ata_scsi_queuecmd 1031 => scsi_dispatch_cmd 1032 => scsi_request_fn 1033 => __blk_run_queue_uncond 1034 => __blk_run_queue 1035 => blk_queue_bio 1036 => generic_make_request 1037 => submit_bio 1038 => submit_bh 1039 => __ext3_get_inode_loc 1040 => ext3_iget 1041 => ext3_lookup 1042 => lookup_real 1043 => __lookup_hash 1044 => walk_component 1045 => lookup_last 1046 => path_lookupat 1047 => filename_lookup 1048 => user_path_at_empty 1049 => user_path_at 1050 => vfs_fstatat 1051 => vfs_stat 1052 => sys_newstat 1053 => system_call_fastpath 1054 1055 1056Here we traced a 71 microsecond latency. But we also see all the 1057functions that were called during that time. Note that by 1058enabling function tracing, we incur an added overhead. This 1059overhead may extend the latency times. But nevertheless, this 1060trace has provided some very helpful debugging information. 1061 1062 1063preemptoff 1064---------- 1065 1066When preemption is disabled, we may be able to receive 1067interrupts but the task cannot be preempted and a higher 1068priority task must wait for preemption to be enabled again 1069before it can preempt a lower priority task. 1070 1071The preemptoff tracer traces the places that disable preemption. 1072Like the irqsoff tracer, it records the maximum latency for 1073which preemption was disabled. The control of preemptoff tracer 1074is much like the irqsoff tracer. 1075 1076 # echo 0 > options/function-trace 1077 # echo preemptoff > current_tracer 1078 # echo 1 > tracing_on 1079 # echo 0 > tracing_max_latency 1080 # ls -ltr 1081 [...] 1082 # echo 0 > tracing_on 1083 # cat trace 1084# tracer: preemptoff 1085# 1086# preemptoff latency trace v1.1.5 on 3.8.0-test+ 1087# -------------------------------------------------------------------- 1088# latency: 46 us, #4/4, CPU#1 | (M:preempt VP:0, KP:0, SP:0 HP:0 #P:4) 1089# ----------------- 1090# | task: sshd-1991 (uid:0 nice:0 policy:0 rt_prio:0) 1091# ----------------- 1092# => started at: do_IRQ 1093# => ended at: do_IRQ 1094# 1095# 1096# _------=> CPU# 1097# / _-----=> irqs-off 1098# | / _----=> need-resched 1099# || / _---=> hardirq/softirq 1100# ||| / _--=> preempt-depth 1101# |||| / delay 1102# cmd pid ||||| time | caller 1103# \ / ||||| \ | / 1104 sshd-1991 1d.h. 0us+: irq_enter <-do_IRQ 1105 sshd-1991 1d..1 46us : irq_exit <-do_IRQ 1106 sshd-1991 1d..1 47us+: trace_preempt_on <-do_IRQ 1107 sshd-1991 1d..1 52us : <stack trace> 1108 => sub_preempt_count 1109 => irq_exit 1110 => do_IRQ 1111 => ret_from_intr 1112 1113 1114This has some more changes. Preemption was disabled when an 1115interrupt came in (notice the 'h'), and was enabled on exit. 1116But we also see that interrupts have been disabled when entering 1117the preempt off section and leaving it (the 'd'). We do not know if 1118interrupts were enabled in the mean time or shortly after this 1119was over. 1120 1121# tracer: preemptoff 1122# 1123# preemptoff latency trace v1.1.5 on 3.8.0-test+ 1124# -------------------------------------------------------------------- 1125# latency: 83 us, #241/241, CPU#1 | (M:preempt VP:0, KP:0, SP:0 HP:0 #P:4) 1126# ----------------- 1127# | task: bash-1994 (uid:0 nice:0 policy:0 rt_prio:0) 1128# ----------------- 1129# => started at: wake_up_new_task 1130# => ended at: task_rq_unlock 1131# 1132# 1133# _------=> CPU# 1134# / _-----=> irqs-off 1135# | / _----=> need-resched 1136# || / _---=> hardirq/softirq 1137# ||| / _--=> preempt-depth 1138# |||| / delay 1139# cmd pid ||||| time | caller 1140# \ / ||||| \ | / 1141 bash-1994 1d..1 0us : _raw_spin_lock_irqsave <-wake_up_new_task 1142 bash-1994 1d..1 0us : select_task_rq_fair <-select_task_rq 1143 bash-1994 1d..1 1us : __rcu_read_lock <-select_task_rq_fair 1144 bash-1994 1d..1 1us : source_load <-select_task_rq_fair 1145 bash-1994 1d..1 1us : source_load <-select_task_rq_fair 1146[...] 1147 bash-1994 1d..1 12us : irq_enter <-smp_apic_timer_interrupt 1148 bash-1994 1d..1 12us : rcu_irq_enter <-irq_enter 1149 bash-1994 1d..1 13us : add_preempt_count <-irq_enter 1150 bash-1994 1d.h1 13us : exit_idle <-smp_apic_timer_interrupt 1151 bash-1994 1d.h1 13us : hrtimer_interrupt <-smp_apic_timer_interrupt 1152 bash-1994 1d.h1 13us : _raw_spin_lock <-hrtimer_interrupt 1153 bash-1994 1d.h1 14us : add_preempt_count <-_raw_spin_lock 1154 bash-1994 1d.h2 14us : ktime_get_update_offsets <-hrtimer_interrupt 1155[...] 1156 bash-1994 1d.h1 35us : lapic_next_event <-clockevents_program_event 1157 bash-1994 1d.h1 35us : irq_exit <-smp_apic_timer_interrupt 1158 bash-1994 1d.h1 36us : sub_preempt_count <-irq_exit 1159 bash-1994 1d..2 36us : do_softirq <-irq_exit 1160 bash-1994 1d..2 36us : __do_softirq <-call_softirq 1161 bash-1994 1d..2 36us : __local_bh_disable <-__do_softirq 1162 bash-1994 1d.s2 37us : add_preempt_count <-_raw_spin_lock_irq 1163 bash-1994 1d.s3 38us : _raw_spin_unlock <-run_timer_softirq 1164 bash-1994 1d.s3 39us : sub_preempt_count <-_raw_spin_unlock 1165 bash-1994 1d.s2 39us : call_timer_fn <-run_timer_softirq 1166[...] 1167 bash-1994 1dNs2 81us : cpu_needs_another_gp <-rcu_process_callbacks 1168 bash-1994 1dNs2 82us : __local_bh_enable <-__do_softirq 1169 bash-1994 1dNs2 82us : sub_preempt_count <-__local_bh_enable 1170 bash-1994 1dN.2 82us : idle_cpu <-irq_exit 1171 bash-1994 1dN.2 83us : rcu_irq_exit <-irq_exit 1172 bash-1994 1dN.2 83us : sub_preempt_count <-irq_exit 1173 bash-1994 1.N.1 84us : _raw_spin_unlock_irqrestore <-task_rq_unlock 1174 bash-1994 1.N.1 84us+: trace_preempt_on <-task_rq_unlock 1175 bash-1994 1.N.1 104us : <stack trace> 1176 => sub_preempt_count 1177 => _raw_spin_unlock_irqrestore 1178 => task_rq_unlock 1179 => wake_up_new_task 1180 => do_fork 1181 => sys_clone 1182 => stub_clone 1183 1184 1185The above is an example of the preemptoff trace with 1186function-trace set. Here we see that interrupts were not disabled 1187the entire time. The irq_enter code lets us know that we entered 1188an interrupt 'h'. Before that, the functions being traced still 1189show that it is not in an interrupt, but we can see from the 1190functions themselves that this is not the case. 1191 1192preemptirqsoff 1193-------------- 1194 1195Knowing the locations that have interrupts disabled or 1196preemption disabled for the longest times is helpful. But 1197sometimes we would like to know when either preemption and/or 1198interrupts are disabled. 1199 1200Consider the following code: 1201 1202 local_irq_disable(); 1203 call_function_with_irqs_off(); 1204 preempt_disable(); 1205 call_function_with_irqs_and_preemption_off(); 1206 local_irq_enable(); 1207 call_function_with_preemption_off(); 1208 preempt_enable(); 1209 1210The irqsoff tracer will record the total length of 1211call_function_with_irqs_off() and 1212call_function_with_irqs_and_preemption_off(). 1213 1214The preemptoff tracer will record the total length of 1215call_function_with_irqs_and_preemption_off() and 1216call_function_with_preemption_off(). 1217 1218But neither will trace the time that interrupts and/or 1219preemption is disabled. This total time is the time that we can 1220not schedule. To record this time, use the preemptirqsoff 1221tracer. 1222 1223Again, using this trace is much like the irqsoff and preemptoff 1224tracers. 1225 1226 # echo 0 > options/function-trace 1227 # echo preemptirqsoff > current_tracer 1228 # echo 1 > tracing_on 1229 # echo 0 > tracing_max_latency 1230 # ls -ltr 1231 [...] 1232 # echo 0 > tracing_on 1233 # cat trace 1234# tracer: preemptirqsoff 1235# 1236# preemptirqsoff latency trace v1.1.5 on 3.8.0-test+ 1237# -------------------------------------------------------------------- 1238# latency: 100 us, #4/4, CPU#3 | (M:preempt VP:0, KP:0, SP:0 HP:0 #P:4) 1239# ----------------- 1240# | task: ls-2230 (uid:0 nice:0 policy:0 rt_prio:0) 1241# ----------------- 1242# => started at: ata_scsi_queuecmd 1243# => ended at: ata_scsi_queuecmd 1244# 1245# 1246# _------=> CPU# 1247# / _-----=> irqs-off 1248# | / _----=> need-resched 1249# || / _---=> hardirq/softirq 1250# ||| / _--=> preempt-depth 1251# |||| / delay 1252# cmd pid ||||| time | caller 1253# \ / ||||| \ | / 1254 ls-2230 3d... 0us+: _raw_spin_lock_irqsave <-ata_scsi_queuecmd 1255 ls-2230 3...1 100us : _raw_spin_unlock_irqrestore <-ata_scsi_queuecmd 1256 ls-2230 3...1 101us+: trace_preempt_on <-ata_scsi_queuecmd 1257 ls-2230 3...1 111us : <stack trace> 1258 => sub_preempt_count 1259 => _raw_spin_unlock_irqrestore 1260 => ata_scsi_queuecmd 1261 => scsi_dispatch_cmd 1262 => scsi_request_fn 1263 => __blk_run_queue_uncond 1264 => __blk_run_queue 1265 => blk_queue_bio 1266 => generic_make_request 1267 => submit_bio 1268 => submit_bh 1269 => ext3_bread 1270 => ext3_dir_bread 1271 => htree_dirblock_to_tree 1272 => ext3_htree_fill_tree 1273 => ext3_readdir 1274 => vfs_readdir 1275 => sys_getdents 1276 => system_call_fastpath 1277 1278 1279The trace_hardirqs_off_thunk is called from assembly on x86 when 1280interrupts are disabled in the assembly code. Without the 1281function tracing, we do not know if interrupts were enabled 1282within the preemption points. We do see that it started with 1283preemption enabled. 1284 1285Here is a trace with function-trace set: 1286 1287# tracer: preemptirqsoff 1288# 1289# preemptirqsoff latency trace v1.1.5 on 3.8.0-test+ 1290# -------------------------------------------------------------------- 1291# latency: 161 us, #339/339, CPU#3 | (M:preempt VP:0, KP:0, SP:0 HP:0 #P:4) 1292# ----------------- 1293# | task: ls-2269 (uid:0 nice:0 policy:0 rt_prio:0) 1294# ----------------- 1295# => started at: schedule 1296# => ended at: mutex_unlock 1297# 1298# 1299# _------=> CPU# 1300# / _-----=> irqs-off 1301# | / _----=> need-resched 1302# || / _---=> hardirq/softirq 1303# ||| / _--=> preempt-depth 1304# |||| / delay 1305# cmd pid ||||| time | caller 1306# \ / ||||| \ | / 1307kworker/-59 3...1 0us : __schedule <-schedule 1308kworker/-59 3d..1 0us : rcu_preempt_qs <-rcu_note_context_switch 1309kworker/-59 3d..1 1us : add_preempt_count <-_raw_spin_lock_irq 1310kworker/-59 3d..2 1us : deactivate_task <-__schedule 1311kworker/-59 3d..2 1us : dequeue_task <-deactivate_task 1312kworker/-59 3d..2 2us : update_rq_clock <-dequeue_task 1313kworker/-59 3d..2 2us : dequeue_task_fair <-dequeue_task 1314kworker/-59 3d..2 2us : update_curr <-dequeue_task_fair 1315kworker/-59 3d..2 2us : update_min_vruntime <-update_curr 1316kworker/-59 3d..2 3us : cpuacct_charge <-update_curr 1317kworker/-59 3d..2 3us : __rcu_read_lock <-cpuacct_charge 1318kworker/-59 3d..2 3us : __rcu_read_unlock <-cpuacct_charge 1319kworker/-59 3d..2 3us : update_cfs_rq_blocked_load <-dequeue_task_fair 1320kworker/-59 3d..2 4us : clear_buddies <-dequeue_task_fair 1321kworker/-59 3d..2 4us : account_entity_dequeue <-dequeue_task_fair 1322kworker/-59 3d..2 4us : update_min_vruntime <-dequeue_task_fair 1323kworker/-59 3d..2 4us : update_cfs_shares <-dequeue_task_fair 1324kworker/-59 3d..2 5us : hrtick_update <-dequeue_task_fair 1325kworker/-59 3d..2 5us : wq_worker_sleeping <-__schedule 1326kworker/-59 3d..2 5us : kthread_data <-wq_worker_sleeping 1327kworker/-59 3d..2 5us : put_prev_task_fair <-__schedule 1328kworker/-59 3d..2 6us : pick_next_task_fair <-pick_next_task 1329kworker/-59 3d..2 6us : clear_buddies <-pick_next_task_fair 1330kworker/-59 3d..2 6us : set_next_entity <-pick_next_task_fair 1331kworker/-59 3d..2 6us : update_stats_wait_end <-set_next_entity 1332 ls-2269 3d..2 7us : finish_task_switch <-__schedule 1333 ls-2269 3d..2 7us : _raw_spin_unlock_irq <-finish_task_switch 1334 ls-2269 3d..2 8us : do_IRQ <-ret_from_intr 1335 ls-2269 3d..2 8us : irq_enter <-do_IRQ 1336 ls-2269 3d..2 8us : rcu_irq_enter <-irq_enter 1337 ls-2269 3d..2 9us : add_preempt_count <-irq_enter 1338 ls-2269 3d.h2 9us : exit_idle <-do_IRQ 1339[...] 1340 ls-2269 3d.h3 20us : sub_preempt_count <-_raw_spin_unlock 1341 ls-2269 3d.h2 20us : irq_exit <-do_IRQ 1342 ls-2269 3d.h2 21us : sub_preempt_count <-irq_exit 1343 ls-2269 3d..3 21us : do_softirq <-irq_exit 1344 ls-2269 3d..3 21us : __do_softirq <-call_softirq 1345 ls-2269 3d..3 21us+: __local_bh_disable <-__do_softirq 1346 ls-2269 3d.s4 29us : sub_preempt_count <-_local_bh_enable_ip 1347 ls-2269 3d.s5 29us : sub_preempt_count <-_local_bh_enable_ip 1348 ls-2269 3d.s5 31us : do_IRQ <-ret_from_intr 1349 ls-2269 3d.s5 31us : irq_enter <-do_IRQ 1350 ls-2269 3d.s5 31us : rcu_irq_enter <-irq_enter 1351[...] 1352 ls-2269 3d.s5 31us : rcu_irq_enter <-irq_enter 1353 ls-2269 3d.s5 32us : add_preempt_count <-irq_enter 1354 ls-2269 3d.H5 32us : exit_idle <-do_IRQ 1355 ls-2269 3d.H5 32us : handle_irq <-do_IRQ 1356 ls-2269 3d.H5 32us : irq_to_desc <-handle_irq 1357 ls-2269 3d.H5 33us : handle_fasteoi_irq <-handle_irq 1358[...] 1359 ls-2269 3d.s5 158us : _raw_spin_unlock_irqrestore <-rtl8139_poll 1360 ls-2269 3d.s3 158us : net_rps_action_and_irq_enable.isra.65 <-net_rx_action 1361 ls-2269 3d.s3 159us : __local_bh_enable <-__do_softirq 1362 ls-2269 3d.s3 159us : sub_preempt_count <-__local_bh_enable 1363 ls-2269 3d..3 159us : idle_cpu <-irq_exit 1364 ls-2269 3d..3 159us : rcu_irq_exit <-irq_exit 1365 ls-2269 3d..3 160us : sub_preempt_count <-irq_exit 1366 ls-2269 3d... 161us : __mutex_unlock_slowpath <-mutex_unlock 1367 ls-2269 3d... 162us+: trace_hardirqs_on <-mutex_unlock 1368 ls-2269 3d... 186us : <stack trace> 1369 => __mutex_unlock_slowpath 1370 => mutex_unlock 1371 => process_output 1372 => n_tty_write 1373 => tty_write 1374 => vfs_write 1375 => sys_write 1376 => system_call_fastpath 1377 1378This is an interesting trace. It started with kworker running and 1379scheduling out and ls taking over. But as soon as ls released the 1380rq lock and enabled interrupts (but not preemption) an interrupt 1381triggered. When the interrupt finished, it started running softirqs. 1382But while the softirq was running, another interrupt triggered. 1383When an interrupt is running inside a softirq, the annotation is 'H'. 1384 1385 1386wakeup 1387------ 1388 1389One common case that people are interested in tracing is the 1390time it takes for a task that is woken to actually wake up. 1391Now for non Real-Time tasks, this can be arbitrary. But tracing 1392it none the less can be interesting. 1393 1394Without function tracing: 1395 1396 # echo 0 > options/function-trace 1397 # echo wakeup > current_tracer 1398 # echo 1 > tracing_on 1399 # echo 0 > tracing_max_latency 1400 # chrt -f 5 sleep 1 1401 # echo 0 > tracing_on 1402 # cat trace 1403# tracer: wakeup 1404# 1405# wakeup latency trace v1.1.5 on 3.8.0-test+ 1406# -------------------------------------------------------------------- 1407# latency: 15 us, #4/4, CPU#3 | (M:preempt VP:0, KP:0, SP:0 HP:0 #P:4) 1408# ----------------- 1409# | task: kworker/3:1H-312 (uid:0 nice:-20 policy:0 rt_prio:0) 1410# ----------------- 1411# 1412# _------=> CPU# 1413# / _-----=> irqs-off 1414# | / _----=> need-resched 1415# || / _---=> hardirq/softirq 1416# ||| / _--=> preempt-depth 1417# |||| / delay 1418# cmd pid ||||| time | caller 1419# \ / ||||| \ | / 1420 <idle>-0 3dNs7 0us : 0:120:R + [003] 312:100:R kworker/3:1H 1421 <idle>-0 3dNs7 1us+: ttwu_do_activate.constprop.87 <-try_to_wake_up 1422 <idle>-0 3d..3 15us : __schedule <-schedule 1423 <idle>-0 3d..3 15us : 0:120:R ==> [003] 312:100:R kworker/3:1H 1424 1425The tracer only traces the highest priority task in the system 1426to avoid tracing the normal circumstances. Here we see that 1427the kworker with a nice priority of -20 (not very nice), took 1428just 15 microseconds from the time it woke up, to the time it 1429ran. 1430 1431Non Real-Time tasks are not that interesting. A more interesting 1432trace is to concentrate only on Real-Time tasks. 1433 1434wakeup_rt 1435--------- 1436 1437In a Real-Time environment it is very important to know the 1438wakeup time it takes for the highest priority task that is woken 1439up to the time that it executes. This is also known as "schedule 1440latency". I stress the point that this is about RT tasks. It is 1441also important to know the scheduling latency of non-RT tasks, 1442but the average schedule latency is better for non-RT tasks. 1443Tools like LatencyTop are more appropriate for such 1444measurements. 1445 1446Real-Time environments are interested in the worst case latency. 1447That is the longest latency it takes for something to happen, 1448and not the average. We can have a very fast scheduler that may 1449only have a large latency once in a while, but that would not 1450work well with Real-Time tasks. The wakeup_rt tracer was designed 1451to record the worst case wakeups of RT tasks. Non-RT tasks are 1452not recorded because the tracer only records one worst case and 1453tracing non-RT tasks that are unpredictable will overwrite the 1454worst case latency of RT tasks (just run the normal wakeup 1455tracer for a while to see that effect). 1456 1457Since this tracer only deals with RT tasks, we will run this 1458slightly differently than we did with the previous tracers. 1459Instead of performing an 'ls', we will run 'sleep 1' under 1460'chrt' which changes the priority of the task. 1461 1462 # echo 0 > options/function-trace 1463 # echo wakeup_rt > current_tracer 1464 # echo 1 > tracing_on 1465 # echo 0 > tracing_max_latency 1466 # chrt -f 5 sleep 1 1467 # echo 0 > tracing_on 1468 # cat trace 1469# tracer: wakeup 1470# 1471# tracer: wakeup_rt 1472# 1473# wakeup_rt latency trace v1.1.5 on 3.8.0-test+ 1474# -------------------------------------------------------------------- 1475# latency: 5 us, #4/4, CPU#3 | (M:preempt VP:0, KP:0, SP:0 HP:0 #P:4) 1476# ----------------- 1477# | task: sleep-2389 (uid:0 nice:0 policy:1 rt_prio:5) 1478# ----------------- 1479# 1480# _------=> CPU# 1481# / _-----=> irqs-off 1482# | / _----=> need-resched 1483# || / _---=> hardirq/softirq 1484# ||| / _--=> preempt-depth 1485# |||| / delay 1486# cmd pid ||||| time | caller 1487# \ / ||||| \ | / 1488 <idle>-0 3d.h4 0us : 0:120:R + [003] 2389: 94:R sleep 1489 <idle>-0 3d.h4 1us+: ttwu_do_activate.constprop.87 <-try_to_wake_up 1490 <idle>-0 3d..3 5us : __schedule <-schedule 1491 <idle>-0 3d..3 5us : 0:120:R ==> [003] 2389: 94:R sleep 1492 1493 1494Running this on an idle system, we see that it only took 5 microseconds 1495to perform the task switch. Note, since the trace point in the schedule 1496is before the actual "switch", we stop the tracing when the recorded task 1497is about to schedule in. This may change if we add a new marker at the 1498end of the scheduler. 1499 1500Notice that the recorded task is 'sleep' with the PID of 2389 1501and it has an rt_prio of 5. This priority is user-space priority 1502and not the internal kernel priority. The policy is 1 for 1503SCHED_FIFO and 2 for SCHED_RR. 1504 1505Note, that the trace data shows the internal priority (99 - rtprio). 1506 1507 <idle>-0 3d..3 5us : 0:120:R ==> [003] 2389: 94:R sleep 1508 1509The 0:120:R means idle was running with a nice priority of 0 (120 - 20) 1510and in the running state 'R'. The sleep task was scheduled in with 15112389: 94:R. That is the priority is the kernel rtprio (99 - 5 = 94) 1512and it too is in the running state. 1513 1514Doing the same with chrt -r 5 and function-trace set. 1515 1516 echo 1 > options/function-trace 1517 1518# tracer: wakeup_rt 1519# 1520# wakeup_rt latency trace v1.1.5 on 3.8.0-test+ 1521# -------------------------------------------------------------------- 1522# latency: 29 us, #85/85, CPU#3 | (M:preempt VP:0, KP:0, SP:0 HP:0 #P:4) 1523# ----------------- 1524# | task: sleep-2448 (uid:0 nice:0 policy:1 rt_prio:5) 1525# ----------------- 1526# 1527# _------=> CPU# 1528# / _-----=> irqs-off 1529# | / _----=> need-resched 1530# || / _---=> hardirq/softirq 1531# ||| / _--=> preempt-depth 1532# |||| / delay 1533# cmd pid ||||| time | caller 1534# \ / ||||| \ | / 1535 <idle>-0 3d.h4 1us+: 0:120:R + [003] 2448: 94:R sleep 1536 <idle>-0 3d.h4 2us : ttwu_do_activate.constprop.87 <-try_to_wake_up 1537 <idle>-0 3d.h3 3us : check_preempt_curr <-ttwu_do_wakeup 1538 <idle>-0 3d.h3 3us : resched_curr <-check_preempt_curr 1539 <idle>-0 3dNh3 4us : task_woken_rt <-ttwu_do_wakeup 1540 <idle>-0 3dNh3 4us : _raw_spin_unlock <-try_to_wake_up 1541 <idle>-0 3dNh3 4us : sub_preempt_count <-_raw_spin_unlock 1542 <idle>-0 3dNh2 5us : ttwu_stat <-try_to_wake_up 1543 <idle>-0 3dNh2 5us : _raw_spin_unlock_irqrestore <-try_to_wake_up 1544 <idle>-0 3dNh2 6us : sub_preempt_count <-_raw_spin_unlock_irqrestore 1545 <idle>-0 3dNh1 6us : _raw_spin_lock <-__run_hrtimer 1546 <idle>-0 3dNh1 6us : add_preempt_count <-_raw_spin_lock 1547 <idle>-0 3dNh2 7us : _raw_spin_unlock <-hrtimer_interrupt 1548 <idle>-0 3dNh2 7us : sub_preempt_count <-_raw_spin_unlock 1549 <idle>-0 3dNh1 7us : tick_program_event <-hrtimer_interrupt 1550 <idle>-0 3dNh1 7us : clockevents_program_event <-tick_program_event 1551 <idle>-0 3dNh1 8us : ktime_get <-clockevents_program_event 1552 <idle>-0 3dNh1 8us : lapic_next_event <-clockevents_program_event 1553 <idle>-0 3dNh1 8us : irq_exit <-smp_apic_timer_interrupt 1554 <idle>-0 3dNh1 9us : sub_preempt_count <-irq_exit 1555 <idle>-0 3dN.2 9us : idle_cpu <-irq_exit 1556 <idle>-0 3dN.2 9us : rcu_irq_exit <-irq_exit 1557 <idle>-0 3dN.2 10us : rcu_eqs_enter_common.isra.45 <-rcu_irq_exit 1558 <idle>-0 3dN.2 10us : sub_preempt_count <-irq_exit 1559 <idle>-0 3.N.1 11us : rcu_idle_exit <-cpu_idle 1560 <idle>-0 3dN.1 11us : rcu_eqs_exit_common.isra.43 <-rcu_idle_exit 1561 <idle>-0 3.N.1 11us : tick_nohz_idle_exit <-cpu_idle 1562 <idle>-0 3dN.1 12us : menu_hrtimer_cancel <-tick_nohz_idle_exit 1563 <idle>-0 3dN.1 12us : ktime_get <-tick_nohz_idle_exit 1564 <idle>-0 3dN.1 12us : tick_do_update_jiffies64 <-tick_nohz_idle_exit 1565 <idle>-0 3dN.1 13us : update_cpu_load_nohz <-tick_nohz_idle_exit 1566 <idle>-0 3dN.1 13us : _raw_spin_lock <-update_cpu_load_nohz 1567 <idle>-0 3dN.1 13us : add_preempt_count <-_raw_spin_lock 1568 <idle>-0 3dN.2 13us : __update_cpu_load <-update_cpu_load_nohz 1569 <idle>-0 3dN.2 14us : sched_avg_update <-__update_cpu_load 1570 <idle>-0 3dN.2 14us : _raw_spin_unlock <-update_cpu_load_nohz 1571 <idle>-0 3dN.2 14us : sub_preempt_count <-_raw_spin_unlock 1572 <idle>-0 3dN.1 15us : calc_load_exit_idle <-tick_nohz_idle_exit 1573 <idle>-0 3dN.1 15us : touch_softlockup_watchdog <-tick_nohz_idle_exit 1574 <idle>-0 3dN.1 15us : hrtimer_cancel <-tick_nohz_idle_exit 1575 <idle>-0 3dN.1 15us : hrtimer_try_to_cancel <-hrtimer_cancel 1576 <idle>-0 3dN.1 16us : lock_hrtimer_base.isra.18 <-hrtimer_try_to_cancel 1577 <idle>-0 3dN.1 16us : _raw_spin_lock_irqsave <-lock_hrtimer_base.isra.18 1578 <idle>-0 3dN.1 16us : add_preempt_count <-_raw_spin_lock_irqsave 1579 <idle>-0 3dN.2 17us : __remove_hrtimer <-remove_hrtimer.part.16 1580 <idle>-0 3dN.2 17us : hrtimer_force_reprogram <-__remove_hrtimer 1581 <idle>-0 3dN.2 17us : tick_program_event <-hrtimer_force_reprogram 1582 <idle>-0 3dN.2 18us : clockevents_program_event <-tick_program_event 1583 <idle>-0 3dN.2 18us : ktime_get <-clockevents_program_event 1584 <idle>-0 3dN.2 18us : lapic_next_event <-clockevents_program_event 1585 <idle>-0 3dN.2 19us : _raw_spin_unlock_irqrestore <-hrtimer_try_to_cancel 1586 <idle>-0 3dN.2 19us : sub_preempt_count <-_raw_spin_unlock_irqrestore 1587 <idle>-0 3dN.1 19us : hrtimer_forward <-tick_nohz_idle_exit 1588 <idle>-0 3dN.1 20us : ktime_add_safe <-hrtimer_forward 1589 <idle>-0 3dN.1 20us : ktime_add_safe <-hrtimer_forward 1590 <idle>-0 3dN.1 20us : hrtimer_start_range_ns <-hrtimer_start_expires.constprop.11 1591 <idle>-0 3dN.1 20us : __hrtimer_start_range_ns <-hrtimer_start_range_ns 1592 <idle>-0 3dN.1 21us : lock_hrtimer_base.isra.18 <-__hrtimer_start_range_ns 1593 <idle>-0 3dN.1 21us : _raw_spin_lock_irqsave <-lock_hrtimer_base.isra.18 1594 <idle>-0 3dN.1 21us : add_preempt_count <-_raw_spin_lock_irqsave 1595 <idle>-0 3dN.2 22us : ktime_add_safe <-__hrtimer_start_range_ns 1596 <idle>-0 3dN.2 22us : enqueue_hrtimer <-__hrtimer_start_range_ns 1597 <idle>-0 3dN.2 22us : tick_program_event <-__hrtimer_start_range_ns 1598 <idle>-0 3dN.2 23us : clockevents_program_event <-tick_program_event 1599 <idle>-0 3dN.2 23us : ktime_get <-clockevents_program_event 1600 <idle>-0 3dN.2 23us : lapic_next_event <-clockevents_program_event 1601 <idle>-0 3dN.2 24us : _raw_spin_unlock_irqrestore <-__hrtimer_start_range_ns 1602 <idle>-0 3dN.2 24us : sub_preempt_count <-_raw_spin_unlock_irqrestore 1603 <idle>-0 3dN.1 24us : account_idle_ticks <-tick_nohz_idle_exit 1604 <idle>-0 3dN.1 24us : account_idle_time <-account_idle_ticks 1605 <idle>-0 3.N.1 25us : sub_preempt_count <-cpu_idle 1606 <idle>-0 3.N.. 25us : schedule <-cpu_idle 1607 <idle>-0 3.N.. 25us : __schedule <-preempt_schedule 1608 <idle>-0 3.N.. 26us : add_preempt_count <-__schedule 1609 <idle>-0 3.N.1 26us : rcu_note_context_switch <-__schedule 1610 <idle>-0 3.N.1 26us : rcu_sched_qs <-rcu_note_context_switch 1611 <idle>-0 3dN.1 27us : rcu_preempt_qs <-rcu_note_context_switch 1612 <idle>-0 3.N.1 27us : _raw_spin_lock_irq <-__schedule 1613 <idle>-0 3dN.1 27us : add_preempt_count <-_raw_spin_lock_irq 1614 <idle>-0 3dN.2 28us : put_prev_task_idle <-__schedule 1615 <idle>-0 3dN.2 28us : pick_next_task_stop <-pick_next_task 1616 <idle>-0 3dN.2 28us : pick_next_task_rt <-pick_next_task 1617 <idle>-0 3dN.2 29us : dequeue_pushable_task <-pick_next_task_rt 1618 <idle>-0 3d..3 29us : __schedule <-preempt_schedule 1619 <idle>-0 3d..3 30us : 0:120:R ==> [003] 2448: 94:R sleep 1620 1621This isn't that big of a trace, even with function tracing enabled, 1622so I included the entire trace. 1623 1624The interrupt went off while when the system was idle. Somewhere 1625before task_woken_rt() was called, the NEED_RESCHED flag was set, 1626this is indicated by the first occurrence of the 'N' flag. 1627 1628Latency tracing and events 1629-------------------------- 1630As function tracing can induce a much larger latency, but without 1631seeing what happens within the latency it is hard to know what 1632caused it. There is a middle ground, and that is with enabling 1633events. 1634 1635 # echo 0 > options/function-trace 1636 # echo wakeup_rt > current_tracer 1637 # echo 1 > events/enable 1638 # echo 1 > tracing_on 1639 # echo 0 > tracing_max_latency 1640 # chrt -f 5 sleep 1 1641 # echo 0 > tracing_on 1642 # cat trace 1643# tracer: wakeup_rt 1644# 1645# wakeup_rt latency trace v1.1.5 on 3.8.0-test+ 1646# -------------------------------------------------------------------- 1647# latency: 6 us, #12/12, CPU#2 | (M:preempt VP:0, KP:0, SP:0 HP:0 #P:4) 1648# ----------------- 1649# | task: sleep-5882 (uid:0 nice:0 policy:1 rt_prio:5) 1650# ----------------- 1651# 1652# _------=> CPU# 1653# / _-----=> irqs-off 1654# | / _----=> need-resched 1655# || / _---=> hardirq/softirq 1656# ||| / _--=> preempt-depth 1657# |||| / delay 1658# cmd pid ||||| time | caller 1659# \ / ||||| \ | / 1660 <idle>-0 2d.h4 0us : 0:120:R + [002] 5882: 94:R sleep 1661 <idle>-0 2d.h4 0us : ttwu_do_activate.constprop.87 <-try_to_wake_up 1662 <idle>-0 2d.h4 1us : sched_wakeup: comm=sleep pid=5882 prio=94 success=1 target_cpu=002 1663 <idle>-0 2dNh2 1us : hrtimer_expire_exit: hrtimer=ffff88007796feb8 1664 <idle>-0 2.N.2 2us : power_end: cpu_id=2 1665 <idle>-0 2.N.2 3us : cpu_idle: state=4294967295 cpu_id=2 1666 <idle>-0 2dN.3 4us : hrtimer_cancel: hrtimer=ffff88007d50d5e0 1667 <idle>-0 2dN.3 4us : hrtimer_start: hrtimer=ffff88007d50d5e0 function=tick_sched_timer expires=34311211000000 softexpires=34311211000000 1668 <idle>-0 2.N.2 5us : rcu_utilization: Start context switch 1669 <idle>-0 2.N.2 5us : rcu_utilization: End context switch 1670 <idle>-0 2d..3 6us : __schedule <-schedule 1671 <idle>-0 2d..3 6us : 0:120:R ==> [002] 5882: 94:R sleep 1672 1673 1674function 1675-------- 1676 1677This tracer is the function tracer. Enabling the function tracer 1678can be done from the debug file system. Make sure the 1679ftrace_enabled is set; otherwise this tracer is a nop. 1680See the "ftrace_enabled" section below. 1681 1682 # sysctl kernel.ftrace_enabled=1 1683 # echo function > current_tracer 1684 # echo 1 > tracing_on 1685 # usleep 1 1686 # echo 0 > tracing_on 1687 # cat trace 1688# tracer: function 1689# 1690# entries-in-buffer/entries-written: 24799/24799 #P:4 1691# 1692# _-----=> irqs-off 1693# / _----=> need-resched 1694# | / _---=> hardirq/softirq 1695# || / _--=> preempt-depth 1696# ||| / delay 1697# TASK-PID CPU# |||| TIMESTAMP FUNCTION 1698# | | | |||| | | 1699 bash-1994 [002] .... 3082.063030: mutex_unlock <-rb_simple_write 1700 bash-1994 [002] .... 3082.063031: __mutex_unlock_slowpath <-mutex_unlock 1701 bash-1994 [002] .... 3082.063031: __fsnotify_parent <-fsnotify_modify 1702 bash-1994 [002] .... 3082.063032: fsnotify <-fsnotify_modify 1703 bash-1994 [002] .... 3082.063032: __srcu_read_lock <-fsnotify 1704 bash-1994 [002] .... 3082.063032: add_preempt_count <-__srcu_read_lock 1705 bash-1994 [002] ...1 3082.063032: sub_preempt_count <-__srcu_read_lock 1706 bash-1994 [002] .... 3082.063033: __srcu_read_unlock <-fsnotify 1707[...] 1708 1709 1710Note: function tracer uses ring buffers to store the above 1711entries. The newest data may overwrite the oldest data. 1712Sometimes using echo to stop the trace is not sufficient because 1713the tracing could have overwritten the data that you wanted to 1714record. For this reason, it is sometimes better to disable 1715tracing directly from a program. This allows you to stop the 1716tracing at the point that you hit the part that you are 1717interested in. To disable the tracing directly from a C program, 1718something like following code snippet can be used: 1719 1720int trace_fd; 1721[...] 1722int main(int argc, char *argv[]) { 1723 [...] 1724 trace_fd = open(tracing_file("tracing_on"), O_WRONLY); 1725 [...] 1726 if (condition_hit()) { 1727 write(trace_fd, "0", 1); 1728 } 1729 [...] 1730} 1731 1732 1733Single thread tracing 1734--------------------- 1735 1736By writing into set_ftrace_pid you can trace a 1737single thread. For example: 1738 1739# cat set_ftrace_pid 1740no pid 1741# echo 3111 > set_ftrace_pid 1742# cat set_ftrace_pid 17433111 1744# echo function > current_tracer 1745# cat trace | head 1746 # tracer: function 1747 # 1748 # TASK-PID CPU# TIMESTAMP FUNCTION 1749 # | | | | | 1750 yum-updatesd-3111 [003] 1637.254676: finish_task_switch <-thread_return 1751 yum-updatesd-3111 [003] 1637.254681: hrtimer_cancel <-schedule_hrtimeout_range 1752 yum-updatesd-3111 [003] 1637.254682: hrtimer_try_to_cancel <-hrtimer_cancel 1753 yum-updatesd-3111 [003] 1637.254683: lock_hrtimer_base <-hrtimer_try_to_cancel 1754 yum-updatesd-3111 [003] 1637.254685: fget_light <-do_sys_poll 1755 yum-updatesd-3111 [003] 1637.254686: pipe_poll <-do_sys_poll 1756# echo > set_ftrace_pid 1757# cat trace |head 1758 # tracer: function 1759 # 1760 # TASK-PID CPU# TIMESTAMP FUNCTION 1761 # | | | | | 1762 ##### CPU 3 buffer started #### 1763 yum-updatesd-3111 [003] 1701.957688: free_poll_entry <-poll_freewait 1764 yum-updatesd-3111 [003] 1701.957689: remove_wait_queue <-free_poll_entry 1765 yum-updatesd-3111 [003] 1701.957691: fput <-free_poll_entry 1766 yum-updatesd-3111 [003] 1701.957692: audit_syscall_exit <-sysret_audit 1767 yum-updatesd-3111 [003] 1701.957693: path_put <-audit_syscall_exit 1768 1769If you want to trace a function when executing, you could use 1770something like this simple program: 1771 1772#include <stdio.h> 1773#include <stdlib.h> 1774#include <sys/types.h> 1775#include <sys/stat.h> 1776#include <fcntl.h> 1777#include <unistd.h> 1778#include <string.h> 1779 1780#define _STR(x) #x 1781#define STR(x) _STR(x) 1782#define MAX_PATH 256 1783 1784const char *find_debugfs(void) 1785{ 1786 static char debugfs[MAX_PATH+1]; 1787 static int debugfs_found; 1788 char type[100]; 1789 FILE *fp; 1790 1791 if (debugfs_found) 1792 return debugfs; 1793 1794 if ((fp = fopen("/proc/mounts","r")) == NULL) { 1795 perror("/proc/mounts"); 1796 return NULL; 1797 } 1798 1799 while (fscanf(fp, "%*s %" 1800 STR(MAX_PATH) 1801 "s %99s %*s %*d %*d\n", 1802 debugfs, type) == 2) { 1803 if (strcmp(type, "debugfs") == 0) 1804 break; 1805 } 1806 fclose(fp); 1807 1808 if (strcmp(type, "debugfs") != 0) { 1809 fprintf(stderr, "debugfs not mounted"); 1810 return NULL; 1811 } 1812 1813 strcat(debugfs, "/tracing/"); 1814 debugfs_found = 1; 1815 1816 return debugfs; 1817} 1818 1819const char *tracing_file(const char *file_name) 1820{ 1821 static char trace_file[MAX_PATH+1]; 1822 snprintf(trace_file, MAX_PATH, "%s/%s", find_debugfs(), file_name); 1823 return trace_file; 1824} 1825 1826int main (int argc, char **argv) 1827{ 1828 if (argc < 1) 1829 exit(-1); 1830 1831 if (fork() > 0) { 1832 int fd, ffd; 1833 char line[64]; 1834 int s; 1835 1836 ffd = open(tracing_file("current_tracer"), O_WRONLY); 1837 if (ffd < 0) 1838 exit(-1); 1839 write(ffd, "nop", 3); 1840 1841 fd = open(tracing_file("set_ftrace_pid"), O_WRONLY); 1842 s = sprintf(line, "%d\n", getpid()); 1843 write(fd, line, s); 1844 1845 write(ffd, "function", 8); 1846 1847 close(fd); 1848 close(ffd); 1849 1850 execvp(argv[1], argv+1); 1851 } 1852 1853 return 0; 1854} 1855 1856Or this simple script! 1857 1858------ 1859#!/bin/bash 1860 1861debugfs=`sed -ne 's/^debugfs \(.*\) debugfs.*/\1/p' /proc/mounts` 1862echo nop > $debugfs/tracing/current_tracer 1863echo 0 > $debugfs/tracing/tracing_on 1864echo $$ > $debugfs/tracing/set_ftrace_pid 1865echo function > $debugfs/tracing/current_tracer 1866echo 1 > $debugfs/tracing/tracing_on 1867exec "$@" 1868------ 1869 1870 1871function graph tracer 1872--------------------------- 1873 1874This tracer is similar to the function tracer except that it 1875probes a function on its entry and its exit. This is done by 1876using a dynamically allocated stack of return addresses in each 1877task_struct. On function entry the tracer overwrites the return 1878address of each function traced to set a custom probe. Thus the 1879original return address is stored on the stack of return address 1880in the task_struct. 1881 1882Probing on both ends of a function leads to special features 1883such as: 1884 1885- measure of a function's time execution 1886- having a reliable call stack to draw function calls graph 1887 1888This tracer is useful in several situations: 1889 1890- you want to find the reason of a strange kernel behavior and 1891 need to see what happens in detail on any areas (or specific 1892 ones). 1893 1894- you are experiencing weird latencies but it's difficult to 1895 find its origin. 1896 1897- you want to find quickly which path is taken by a specific 1898 function 1899 1900- you just want to peek inside a working kernel and want to see 1901 what happens there. 1902 1903# tracer: function_graph 1904# 1905# CPU DURATION FUNCTION CALLS 1906# | | | | | | | 1907 1908 0) | sys_open() { 1909 0) | do_sys_open() { 1910 0) | getname() { 1911 0) | kmem_cache_alloc() { 1912 0) 1.382 us | __might_sleep(); 1913 0) 2.478 us | } 1914 0) | strncpy_from_user() { 1915 0) | might_fault() { 1916 0) 1.389 us | __might_sleep(); 1917 0) 2.553 us | } 1918 0) 3.807 us | } 1919 0) 7.876 us | } 1920 0) | alloc_fd() { 1921 0) 0.668 us | _spin_lock(); 1922 0) 0.570 us | expand_files(); 1923 0) 0.586 us | _spin_unlock(); 1924 1925 1926There are several columns that can be dynamically 1927enabled/disabled. You can use every combination of options you 1928want, depending on your needs. 1929 1930- The cpu number on which the function executed is default 1931 enabled. It is sometimes better to only trace one cpu (see 1932 tracing_cpu_mask file) or you might sometimes see unordered 1933 function calls while cpu tracing switch. 1934 1935 hide: echo nofuncgraph-cpu > trace_options 1936 show: echo funcgraph-cpu > trace_options 1937 1938- The duration (function's time of execution) is displayed on 1939 the closing bracket line of a function or on the same line 1940 than the current function in case of a leaf one. It is default 1941 enabled. 1942 1943 hide: echo nofuncgraph-duration > trace_options 1944 show: echo funcgraph-duration > trace_options 1945 1946- The overhead field precedes the duration field in case of 1947 reached duration thresholds. 1948 1949 hide: echo nofuncgraph-overhead > trace_options 1950 show: echo funcgraph-overhead > trace_options 1951 depends on: funcgraph-duration 1952 1953 ie: 1954 1955 3) # 1837.709 us | } /* __switch_to */ 1956 3) | finish_task_switch() { 1957 3) 0.313 us | _raw_spin_unlock_irq(); 1958 3) 3.177 us | } 1959 3) # 1889.063 us | } /* __schedule */ 1960 3) ! 140.417 us | } /* __schedule */ 1961 3) # 2034.948 us | } /* schedule */ 1962 3) * 33998.59 us | } /* schedule_preempt_disabled */ 1963 1964 [...] 1965 1966 1) 0.260 us | msecs_to_jiffies(); 1967 1) 0.313 us | __rcu_read_unlock(); 1968 1) + 61.770 us | } 1969 1) + 64.479 us | } 1970 1) 0.313 us | rcu_bh_qs(); 1971 1) 0.313 us | __local_bh_enable(); 1972 1) ! 217.240 us | } 1973 1) 0.365 us | idle_cpu(); 1974 1) | rcu_irq_exit() { 1975 1) 0.417 us | rcu_eqs_enter_common.isra.47(); 1976 1) 3.125 us | } 1977 1) ! 227.812 us | } 1978 1) ! 457.395 us | } 1979 1) @ 119760.2 us | } 1980 1981 [...] 1982 1983 2) | handle_IPI() { 1984 1) 6.979 us | } 1985 2) 0.417 us | scheduler_ipi(); 1986 1) 9.791 us | } 1987 1) + 12.917 us | } 1988 2) 3.490 us | } 1989 1) + 15.729 us | } 1990 1) + 18.542 us | } 1991 2) $ 3594274 us | } 1992 1993 + means that the function exceeded 10 usecs. 1994 ! means that the function exceeded 100 usecs. 1995 # means that the function exceeded 1000 usecs. 1996 * means that the function exceeded 10 msecs. 1997 @ means that the function exceeded 100 msecs. 1998 $ means that the function exceeded 1 sec. 1999 2000 2001- The task/pid field displays the thread cmdline and pid which 2002 executed the function. It is default disabled. 2003 2004 hide: echo nofuncgraph-proc > trace_options 2005 show: echo funcgraph-proc > trace_options 2006 2007 ie: 2008 2009 # tracer: function_graph 2010 # 2011 # CPU TASK/PID DURATION FUNCTION CALLS 2012 # | | | | | | | | | 2013 0) sh-4802 | | d_free() { 2014 0) sh-4802 | | call_rcu() { 2015 0) sh-4802 | | __call_rcu() { 2016 0) sh-4802 | 0.616 us | rcu_process_gp_end(); 2017 0) sh-4802 | 0.586 us | check_for_new_grace_period(); 2018 0) sh-4802 | 2.899 us | } 2019 0) sh-4802 | 4.040 us | } 2020 0) sh-4802 | 5.151 us | } 2021 0) sh-4802 | + 49.370 us | } 2022 2023 2024- The absolute time field is an absolute timestamp given by the 2025 system clock since it started. A snapshot of this time is 2026 given on each entry/exit of functions 2027 2028 hide: echo nofuncgraph-abstime > trace_options 2029 show: echo funcgraph-abstime > trace_options 2030 2031 ie: 2032 2033 # 2034 # TIME CPU DURATION FUNCTION CALLS 2035 # | | | | | | | | 2036 360.774522 | 1) 0.541 us | } 2037 360.774522 | 1) 4.663 us | } 2038 360.774523 | 1) 0.541 us | __wake_up_bit(); 2039 360.774524 | 1) 6.796 us | } 2040 360.774524 | 1) 7.952 us | } 2041 360.774525 | 1) 9.063 us | } 2042 360.774525 | 1) 0.615 us | journal_mark_dirty(); 2043 360.774527 | 1) 0.578 us | __brelse(); 2044 360.774528 | 1) | reiserfs_prepare_for_journal() { 2045 360.774528 | 1) | unlock_buffer() { 2046 360.774529 | 1) | wake_up_bit() { 2047 360.774529 | 1) | bit_waitqueue() { 2048 360.774530 | 1) 0.594 us | __phys_addr(); 2049 2050 2051The function name is always displayed after the closing bracket 2052for a function if the start of that function is not in the 2053trace buffer. 2054 2055Display of the function name after the closing bracket may be 2056enabled for functions whose start is in the trace buffer, 2057allowing easier searching with grep for function durations. 2058It is default disabled. 2059 2060 hide: echo nofuncgraph-tail > trace_options 2061 show: echo funcgraph-tail > trace_options 2062 2063 Example with nofuncgraph-tail (default): 2064 0) | putname() { 2065 0) | kmem_cache_free() { 2066 0) 0.518 us | __phys_addr(); 2067 0) 1.757 us | } 2068 0) 2.861 us | } 2069 2070 Example with funcgraph-tail: 2071 0) | putname() { 2072 0) | kmem_cache_free() { 2073 0) 0.518 us | __phys_addr(); 2074 0) 1.757 us | } /* kmem_cache_free() */ 2075 0) 2.861 us | } /* putname() */ 2076 2077You can put some comments on specific functions by using 2078trace_printk() For example, if you want to put a comment inside 2079the __might_sleep() function, you just have to include 2080<linux/ftrace.h> and call trace_printk() inside __might_sleep() 2081 2082trace_printk("I'm a comment!\n") 2083 2084will produce: 2085 2086 1) | __might_sleep() { 2087 1) | /* I'm a comment! */ 2088 1) 1.449 us | } 2089 2090 2091You might find other useful features for this tracer in the 2092following "dynamic ftrace" section such as tracing only specific 2093functions or tasks. 2094 2095dynamic ftrace 2096-------------- 2097 2098If CONFIG_DYNAMIC_FTRACE is set, the system will run with 2099virtually no overhead when function tracing is disabled. The way 2100this works is the mcount function call (placed at the start of 2101every kernel function, produced by the -pg switch in gcc), 2102starts of pointing to a simple return. (Enabling FTRACE will 2103include the -pg switch in the compiling of the kernel.) 2104 2105At compile time every C file object is run through the 2106recordmcount program (located in the scripts directory). This 2107program will parse the ELF headers in the C object to find all 2108the locations in the .text section that call mcount. (Note, only 2109white listed .text sections are processed, since processing other 2110sections like .init.text may cause races due to those sections 2111being freed unexpectedly). 2112 2113A new section called "__mcount_loc" is created that holds 2114references to all the mcount call sites in the .text section. 2115The recordmcount program re-links this section back into the 2116original object. The final linking stage of the kernel will add all these 2117references into a single table. 2118 2119On boot up, before SMP is initialized, the dynamic ftrace code 2120scans this table and updates all the locations into nops. It 2121also records the locations, which are added to the 2122available_filter_functions list. Modules are processed as they 2123are loaded and before they are executed. When a module is 2124unloaded, it also removes its functions from the ftrace function 2125list. This is automatic in the module unload code, and the 2126module author does not need to worry about it. 2127 2128When tracing is enabled, the process of modifying the function 2129tracepoints is dependent on architecture. The old method is to use 2130kstop_machine to prevent races with the CPUs executing code being 2131modified (which can cause the CPU to do undesirable things, especially 2132if the modified code crosses cache (or page) boundaries), and the nops are 2133patched back to calls. But this time, they do not call mcount 2134(which is just a function stub). They now call into the ftrace 2135infrastructure. 2136 2137The new method of modifying the function tracepoints is to place 2138a breakpoint at the location to be modified, sync all CPUs, modify 2139the rest of the instruction not covered by the breakpoint. Sync 2140all CPUs again, and then remove the breakpoint with the finished 2141version to the ftrace call site. 2142 2143Some archs do not even need to monkey around with the synchronization, 2144and can just slap the new code on top of the old without any 2145problems with other CPUs executing it at the same time. 2146 2147One special side-effect to the recording of the functions being 2148traced is that we can now selectively choose which functions we 2149wish to trace and which ones we want the mcount calls to remain 2150as nops. 2151 2152Two files are used, one for enabling and one for disabling the 2153tracing of specified functions. They are: 2154 2155 set_ftrace_filter 2156 2157and 2158 2159 set_ftrace_notrace 2160 2161A list of available functions that you can add to these files is 2162listed in: 2163 2164 available_filter_functions 2165 2166 # cat available_filter_functions 2167put_prev_task_idle 2168kmem_cache_create 2169pick_next_task_rt 2170get_online_cpus 2171pick_next_task_fair 2172mutex_lock 2173[...] 2174 2175If I am only interested in sys_nanosleep and hrtimer_interrupt: 2176 2177 # echo sys_nanosleep hrtimer_interrupt > set_ftrace_filter 2178 # echo function > current_tracer 2179 # echo 1 > tracing_on 2180 # usleep 1 2181 # echo 0 > tracing_on 2182 # cat trace 2183# tracer: function 2184# 2185# entries-in-buffer/entries-written: 5/5 #P:4 2186# 2187# _-----=> irqs-off 2188# / _----=> need-resched 2189# | / _---=> hardirq/softirq 2190# || / _--=> preempt-depth 2191# ||| / delay 2192# TASK-PID CPU# |||| TIMESTAMP FUNCTION 2193# | | | |||| | | 2194 usleep-2665 [001] .... 4186.475355: sys_nanosleep <-system_call_fastpath 2195 <idle>-0 [001] d.h1 4186.475409: hrtimer_interrupt <-smp_apic_timer_interrupt 2196 usleep-2665 [001] d.h1 4186.475426: hrtimer_interrupt <-smp_apic_timer_interrupt 2197 <idle>-0 [003] d.h1 4186.475426: hrtimer_interrupt <-smp_apic_timer_interrupt 2198 <idle>-0 [002] d.h1 4186.475427: hrtimer_interrupt <-smp_apic_timer_interrupt 2199 2200To see which functions are being traced, you can cat the file: 2201 2202 # cat set_ftrace_filter 2203hrtimer_interrupt 2204sys_nanosleep 2205 2206 2207Perhaps this is not enough. The filters also allow simple wild 2208cards. Only the following are currently available 2209 2210 <match>* - will match functions that begin with <match> 2211 *<match> - will match functions that end with <match> 2212 *<match>* - will match functions that have <match> in it 2213 2214These are the only wild cards which are supported. 2215 2216 <match>*<match> will not work. 2217 2218Note: It is better to use quotes to enclose the wild cards, 2219 otherwise the shell may expand the parameters into names 2220 of files in the local directory. 2221 2222 # echo 'hrtimer_*' > set_ftrace_filter 2223 2224Produces: 2225 2226# tracer: function 2227# 2228# entries-in-buffer/entries-written: 897/897 #P:4 2229# 2230# _-----=> irqs-off 2231# / _----=> need-resched 2232# | / _---=> hardirq/softirq 2233# || / _--=> preempt-depth 2234# ||| / delay 2235# TASK-PID CPU# |||| TIMESTAMP FUNCTION 2236# | | | |||| | | 2237 <idle>-0 [003] dN.1 4228.547803: hrtimer_cancel <-tick_nohz_idle_exit 2238 <idle>-0 [003] dN.1 4228.547804: hrtimer_try_to_cancel <-hrtimer_cancel 2239 <idle>-0 [003] dN.2 4228.547805: hrtimer_force_reprogram <-__remove_hrtimer 2240 <idle>-0 [003] dN.1 4228.547805: hrtimer_forward <-tick_nohz_idle_exit 2241 <idle>-0 [003] dN.1 4228.547805: hrtimer_start_range_ns <-hrtimer_start_expires.constprop.11 2242 <idle>-0 [003] d..1 4228.547858: hrtimer_get_next_event <-get_next_timer_interrupt 2243 <idle>-0 [003] d..1 4228.547859: hrtimer_start <-__tick_nohz_idle_enter 2244 <idle>-0 [003] d..2 4228.547860: hrtimer_force_reprogram <-__rem 2245 2246Notice that we lost the sys_nanosleep. 2247 2248 # cat set_ftrace_filter 2249hrtimer_run_queues 2250hrtimer_run_pending 2251hrtimer_init 2252hrtimer_cancel 2253hrtimer_try_to_cancel 2254hrtimer_forward 2255hrtimer_start 2256hrtimer_reprogram 2257hrtimer_force_reprogram 2258hrtimer_get_next_event 2259hrtimer_interrupt 2260hrtimer_nanosleep 2261hrtimer_wakeup 2262hrtimer_get_remaining 2263hrtimer_get_res 2264hrtimer_init_sleeper 2265 2266 2267This is because the '>' and '>>' act just like they do in bash. 2268To rewrite the filters, use '>' 2269To append to the filters, use '>>' 2270 2271To clear out a filter so that all functions will be recorded 2272again: 2273 2274 # echo > set_ftrace_filter 2275 # cat set_ftrace_filter 2276 # 2277 2278Again, now we want to append. 2279 2280 # echo sys_nanosleep > set_ftrace_filter 2281 # cat set_ftrace_filter 2282sys_nanosleep 2283 # echo 'hrtimer_*' >> set_ftrace_filter 2284 # cat set_ftrace_filter 2285hrtimer_run_queues 2286hrtimer_run_pending 2287hrtimer_init 2288hrtimer_cancel 2289hrtimer_try_to_cancel 2290hrtimer_forward 2291hrtimer_start 2292hrtimer_reprogram 2293hrtimer_force_reprogram 2294hrtimer_get_next_event 2295hrtimer_interrupt 2296sys_nanosleep 2297hrtimer_nanosleep 2298hrtimer_wakeup 2299hrtimer_get_remaining 2300hrtimer_get_res 2301hrtimer_init_sleeper 2302 2303 2304The set_ftrace_notrace prevents those functions from being 2305traced. 2306 2307 # echo '*preempt*' '*lock*' > set_ftrace_notrace 2308 2309Produces: 2310 2311# tracer: function 2312# 2313# entries-in-buffer/entries-written: 39608/39608 #P:4 2314# 2315# _-----=> irqs-off 2316# / _----=> need-resched 2317# | / _---=> hardirq/softirq 2318# || / _--=> preempt-depth 2319# ||| / delay 2320# TASK-PID CPU# |||| TIMESTAMP FUNCTION 2321# | | | |||| | | 2322 bash-1994 [000] .... 4342.324896: file_ra_state_init <-do_dentry_open 2323 bash-1994 [000] .... 4342.324897: open_check_o_direct <-do_last 2324 bash-1994 [000] .... 4342.324897: ima_file_check <-do_last 2325 bash-1994 [000] .... 4342.324898: process_measurement <-ima_file_check 2326 bash-1994 [000] .... 4342.324898: ima_get_action <-process_measurement 2327 bash-1994 [000] .... 4342.324898: ima_match_policy <-ima_get_action 2328 bash-1994 [000] .... 4342.324899: do_truncate <-do_last 2329 bash-1994 [000] .... 4342.324899: should_remove_suid <-do_truncate 2330 bash-1994 [000] .... 4342.324899: notify_change <-do_truncate 2331 bash-1994 [000] .... 4342.324900: current_fs_time <-notify_change 2332 bash-1994 [000] .... 4342.324900: current_kernel_time <-current_fs_time 2333 bash-1994 [000] .... 4342.324900: timespec_trunc <-current_fs_time 2334 2335We can see that there's no more lock or preempt tracing. 2336 2337 2338Dynamic ftrace with the function graph tracer 2339--------------------------------------------- 2340 2341Although what has been explained above concerns both the 2342function tracer and the function-graph-tracer, there are some 2343special features only available in the function-graph tracer. 2344 2345If you want to trace only one function and all of its children, 2346you just have to echo its name into set_graph_function: 2347 2348 echo __do_fault > set_graph_function 2349 2350will produce the following "expanded" trace of the __do_fault() 2351function: 2352 2353 0) | __do_fault() { 2354 0) | filemap_fault() { 2355 0) | find_lock_page() { 2356 0) 0.804 us | find_get_page(); 2357 0) | __might_sleep() { 2358 0) 1.329 us | } 2359 0) 3.904 us | } 2360 0) 4.979 us | } 2361 0) 0.653 us | _spin_lock(); 2362 0) 0.578 us | page_add_file_rmap(); 2363 0) 0.525 us | native_set_pte_at(); 2364 0) 0.585 us | _spin_unlock(); 2365 0) | unlock_page() { 2366 0) 0.541 us | page_waitqueue(); 2367 0) 0.639 us | __wake_up_bit(); 2368 0) 2.786 us | } 2369 0) + 14.237 us | } 2370 0) | __do_fault() { 2371 0) | filemap_fault() { 2372 0) | find_lock_page() { 2373 0) 0.698 us | find_get_page(); 2374 0) | __might_sleep() { 2375 0) 1.412 us | } 2376 0) 3.950 us | } 2377 0) 5.098 us | } 2378 0) 0.631 us | _spin_lock(); 2379 0) 0.571 us | page_add_file_rmap(); 2380 0) 0.526 us | native_set_pte_at(); 2381 0) 0.586 us | _spin_unlock(); 2382 0) | unlock_page() { 2383 0) 0.533 us | page_waitqueue(); 2384 0) 0.638 us | __wake_up_bit(); 2385 0) 2.793 us | } 2386 0) + 14.012 us | } 2387 2388You can also expand several functions at once: 2389 2390 echo sys_open > set_graph_function 2391 echo sys_close >> set_graph_function 2392 2393Now if you want to go back to trace all functions you can clear 2394this special filter via: 2395 2396 echo > set_graph_function 2397 2398 2399ftrace_enabled 2400-------------- 2401 2402Note, the proc sysctl ftrace_enable is a big on/off switch for the 2403function tracer. By default it is enabled (when function tracing is 2404enabled in the kernel). If it is disabled, all function tracing is 2405disabled. This includes not only the function tracers for ftrace, but 2406also for any other uses (perf, kprobes, stack tracing, profiling, etc). 2407 2408Please disable this with care. 2409 2410This can be disable (and enabled) with: 2411 2412 sysctl kernel.ftrace_enabled=0 2413 sysctl kernel.ftrace_enabled=1 2414 2415 or 2416 2417 echo 0 > /proc/sys/kernel/ftrace_enabled 2418 echo 1 > /proc/sys/kernel/ftrace_enabled 2419 2420 2421Filter commands 2422--------------- 2423 2424A few commands are supported by the set_ftrace_filter interface. 2425Trace commands have the following format: 2426 2427<function>:<command>:<parameter> 2428 2429The following commands are supported: 2430 2431- mod 2432 This command enables function filtering per module. The 2433 parameter defines the module. For example, if only the write* 2434 functions in the ext3 module are desired, run: 2435 2436 echo 'write*:mod:ext3' > set_ftrace_filter 2437 2438 This command interacts with the filter in the same way as 2439 filtering based on function names. Thus, adding more functions 2440 in a different module is accomplished by appending (>>) to the 2441 filter file. Remove specific module functions by prepending 2442 '!': 2443 2444 echo '!writeback*:mod:ext3' >> set_ftrace_filter 2445 2446 Mod command supports module globbing. Disable tracing for all 2447 functions except a specific module: 2448 2449 echo '!*:mod:!ext3' >> set_ftrace_filter 2450 2451 Disable tracing for all modules, but still trace kernel: 2452 2453 echo '!*:mod:*' >> set_ftrace_filter 2454 2455 Enable filter only for kernel: 2456 2457 echo '*write*:mod:!*' >> set_ftrace_filter 2458 2459 Enable filter for module globbing: 2460 2461 echo '*write*:mod:*snd*' >> set_ftrace_filter 2462 2463- traceon/traceoff 2464 These commands turn tracing on and off when the specified 2465 functions are hit. The parameter determines how many times the 2466 tracing system is turned on and off. If unspecified, there is 2467 no limit. For example, to disable tracing when a schedule bug 2468 is hit the first 5 times, run: 2469 2470 echo '__schedule_bug:traceoff:5' > set_ftrace_filter 2471 2472 To always disable tracing when __schedule_bug is hit: 2473 2474 echo '__schedule_bug:traceoff' > set_ftrace_filter 2475 2476 These commands are cumulative whether or not they are appended 2477 to set_ftrace_filter. To remove a command, prepend it by '!' 2478 and drop the parameter: 2479 2480 echo '!__schedule_bug:traceoff:0' > set_ftrace_filter 2481 2482 The above removes the traceoff command for __schedule_bug 2483 that have a counter. To remove commands without counters: 2484 2485 echo '!__schedule_bug:traceoff' > set_ftrace_filter 2486 2487- snapshot 2488 Will cause a snapshot to be triggered when the function is hit. 2489 2490 echo 'native_flush_tlb_others:snapshot' > set_ftrace_filter 2491 2492 To only snapshot once: 2493 2494 echo 'native_flush_tlb_others:snapshot:1' > set_ftrace_filter 2495 2496 To remove the above commands: 2497 2498 echo '!native_flush_tlb_others:snapshot' > set_ftrace_filter 2499 echo '!native_flush_tlb_others:snapshot:0' > set_ftrace_filter 2500 2501- enable_event/disable_event 2502 These commands can enable or disable a trace event. Note, because 2503 function tracing callbacks are very sensitive, when these commands 2504 are registered, the trace point is activated, but disabled in 2505 a "soft" mode. That is, the tracepoint will be called, but 2506 just will not be traced. The event tracepoint stays in this mode 2507 as long as there's a command that triggers it. 2508 2509 echo 'try_to_wake_up:enable_event:sched:sched_switch:2' > \ 2510 set_ftrace_filter 2511 2512 The format is: 2513 2514 <function>:enable_event:<system>:<event>[:count] 2515 <function>:disable_event:<system>:<event>[:count] 2516 2517 To remove the events commands: 2518 2519 2520 echo '!try_to_wake_up:enable_event:sched:sched_switch:0' > \ 2521 set_ftrace_filter 2522 echo '!schedule:disable_event:sched:sched_switch' > \ 2523 set_ftrace_filter 2524 2525- dump 2526 When the function is hit, it will dump the contents of the ftrace 2527 ring buffer to the console. This is useful if you need to debug 2528 something, and want to dump the trace when a certain function 2529 is hit. Perhaps its a function that is called before a tripple 2530 fault happens and does not allow you to get a regular dump. 2531 2532- cpudump 2533 When the function is hit, it will dump the contents of the ftrace 2534 ring buffer for the current CPU to the console. Unlike the "dump" 2535 command, it only prints out the contents of the ring buffer for the 2536 CPU that executed the function that triggered the dump. 2537 2538trace_pipe 2539---------- 2540 2541The trace_pipe outputs the same content as the trace file, but 2542the effect on the tracing is different. Every read from 2543trace_pipe is consumed. This means that subsequent reads will be 2544different. The trace is live. 2545 2546 # echo function > current_tracer 2547 # cat trace_pipe > /tmp/trace.out & 2548[1] 4153 2549 # echo 1 > tracing_on 2550 # usleep 1 2551 # echo 0 > tracing_on 2552 # cat trace 2553# tracer: function 2554# 2555# entries-in-buffer/entries-written: 0/0 #P:4 2556# 2557# _-----=> irqs-off 2558# / _----=> need-resched 2559# | / _---=> hardirq/softirq 2560# || / _--=> preempt-depth 2561# ||| / delay 2562# TASK-PID CPU# |||| TIMESTAMP FUNCTION 2563# | | | |||| | | 2564 2565 # 2566 # cat /tmp/trace.out 2567 bash-1994 [000] .... 5281.568961: mutex_unlock <-rb_simple_write 2568 bash-1994 [000] .... 5281.568963: __mutex_unlock_slowpath <-mutex_unlock 2569 bash-1994 [000] .... 5281.568963: __fsnotify_parent <-fsnotify_modify 2570 bash-1994 [000] .... 5281.568964: fsnotify <-fsnotify_modify 2571 bash-1994 [000] .... 5281.568964: __srcu_read_lock <-fsnotify 2572 bash-1994 [000] .... 5281.568964: add_preempt_count <-__srcu_read_lock 2573 bash-1994 [000] ...1 5281.568965: sub_preempt_count <-__srcu_read_lock 2574 bash-1994 [000] .... 5281.568965: __srcu_read_unlock <-fsnotify 2575 bash-1994 [000] .... 5281.568967: sys_dup2 <-system_call_fastpath 2576 2577 2578Note, reading the trace_pipe file will block until more input is 2579added. 2580 2581trace entries 2582------------- 2583 2584Having too much or not enough data can be troublesome in 2585diagnosing an issue in the kernel. The file buffer_size_kb is 2586used to modify the size of the internal trace buffers. The 2587number listed is the number of entries that can be recorded per 2588CPU. To know the full size, multiply the number of possible CPUs 2589with the number of entries. 2590 2591 # cat buffer_size_kb 25921408 (units kilobytes) 2593 2594Or simply read buffer_total_size_kb 2595 2596 # cat buffer_total_size_kb 25975632 2598 2599To modify the buffer, simple echo in a number (in 1024 byte segments). 2600 2601 # echo 10000 > buffer_size_kb 2602 # cat buffer_size_kb 260310000 (units kilobytes) 2604 2605It will try to allocate as much as possible. If you allocate too 2606much, it can cause Out-Of-Memory to trigger. 2607 2608 # echo 1000000000000 > buffer_size_kb 2609-bash: echo: write error: Cannot allocate memory 2610 # cat buffer_size_kb 261185 2612 2613The per_cpu buffers can be changed individually as well: 2614 2615 # echo 10000 > per_cpu/cpu0/buffer_size_kb 2616 # echo 100 > per_cpu/cpu1/buffer_size_kb 2617 2618When the per_cpu buffers are not the same, the buffer_size_kb 2619at the top level will just show an X 2620 2621 # cat buffer_size_kb 2622X 2623 2624This is where the buffer_total_size_kb is useful: 2625 2626 # cat buffer_total_size_kb 262712916 2628 2629Writing to the top level buffer_size_kb will reset all the buffers 2630to be the same again. 2631 2632Snapshot 2633-------- 2634CONFIG_TRACER_SNAPSHOT makes a generic snapshot feature 2635available to all non latency tracers. (Latency tracers which 2636record max latency, such as "irqsoff" or "wakeup", can't use 2637this feature, since those are already using the snapshot 2638mechanism internally.) 2639 2640Snapshot preserves a current trace buffer at a particular point 2641in time without stopping tracing. Ftrace swaps the current 2642buffer with a spare buffer, and tracing continues in the new 2643current (=previous spare) buffer. 2644 2645The following debugfs files in "tracing" are related to this 2646feature: 2647 2648 snapshot: 2649 2650 This is used to take a snapshot and to read the output 2651 of the snapshot. Echo 1 into this file to allocate a 2652 spare buffer and to take a snapshot (swap), then read 2653 the snapshot from this file in the same format as 2654 "trace" (described above in the section "The File 2655 System"). Both reads snapshot and tracing are executable 2656 in parallel. When the spare buffer is allocated, echoing 2657 0 frees it, and echoing else (positive) values clear the 2658 snapshot contents. 2659 More details are shown in the table below. 2660 2661 status\input | 0 | 1 | else | 2662 --------------+------------+------------+------------+ 2663 not allocated |(do nothing)| alloc+swap |(do nothing)| 2664 --------------+------------+------------+------------+ 2665 allocated | free | swap | clear | 2666 --------------+------------+------------+------------+ 2667 2668Here is an example of using the snapshot feature. 2669 2670 # echo 1 > events/sched/enable 2671 # echo 1 > snapshot 2672 # cat snapshot 2673# tracer: nop 2674# 2675# entries-in-buffer/entries-written: 71/71 #P:8 2676# 2677# _-----=> irqs-off 2678# / _----=> need-resched 2679# | / _---=> hardirq/softirq 2680# || / _--=> preempt-depth 2681# ||| / delay 2682# TASK-PID CPU# |||| TIMESTAMP FUNCTION 2683# | | | |||| | | 2684 <idle>-0 [005] d... 2440.603828: sched_switch: prev_comm=swapper/5 prev_pid=0 prev_prio=120 prev_state=R ==> next_comm=snapshot-test-2 next_pid=2242 next_prio=120 2685 sleep-2242 [005] d... 2440.603846: sched_switch: prev_comm=snapshot-test-2 prev_pid=2242 prev_prio=120 prev_state=R ==> next_comm=kworker/5:1 next_pid=60 next_prio=120 2686[...] 2687 <idle>-0 [002] d... 2440.707230: sched_switch: prev_comm=swapper/2 prev_pid=0 prev_prio=120 prev_state=R ==> next_comm=snapshot-test-2 next_pid=2229 next_prio=120 2688 2689 # cat trace 2690# tracer: nop 2691# 2692# entries-in-buffer/entries-written: 77/77 #P:8 2693# 2694# _-----=> irqs-off 2695# / _----=> need-resched 2696# | / _---=> hardirq/softirq 2697# || / _--=> preempt-depth 2698# ||| / delay 2699# TASK-PID CPU# |||| TIMESTAMP FUNCTION 2700# | | | |||| | | 2701 <idle>-0 [007] d... 2440.707395: sched_switch: prev_comm=swapper/7 prev_pid=0 prev_prio=120 prev_state=R ==> next_comm=snapshot-test-2 next_pid=2243 next_prio=120 2702 snapshot-test-2-2229 [002] d... 2440.707438: sched_switch: prev_comm=snapshot-test-2 prev_pid=2229 prev_prio=120 prev_state=S ==> next_comm=swapper/2 next_pid=0 next_prio=120 2703[...] 2704 2705 2706If you try to use this snapshot feature when current tracer is 2707one of the latency tracers, you will get the following results. 2708 2709 # echo wakeup > current_tracer 2710 # echo 1 > snapshot 2711bash: echo: write error: Device or resource busy 2712 # cat snapshot 2713cat: snapshot: Device or resource busy 2714 2715 2716Instances 2717--------- 2718In the debugfs tracing directory is a directory called "instances". 2719This directory can have new directories created inside of it using 2720mkdir, and removing directories with rmdir. The directory created 2721with mkdir in this directory will already contain files and other 2722directories after it is created. 2723 2724 # mkdir instances/foo 2725 # ls instances/foo 2726buffer_size_kb buffer_total_size_kb events free_buffer per_cpu 2727set_event snapshot trace trace_clock trace_marker trace_options 2728trace_pipe tracing_on 2729 2730As you can see, the new directory looks similar to the tracing directory 2731itself. In fact, it is very similar, except that the buffer and 2732events are agnostic from the main director, or from any other 2733instances that are created. 2734 2735The files in the new directory work just like the files with the 2736same name in the tracing directory except the buffer that is used 2737is a separate and new buffer. The files affect that buffer but do not 2738affect the main buffer with the exception of trace_options. Currently, 2739the trace_options affect all instances and the top level buffer 2740the same, but this may change in future releases. That is, options 2741may become specific to the instance they reside in. 2742 2743Notice that none of the function tracer files are there, nor is 2744current_tracer and available_tracers. This is because the buffers 2745can currently only have events enabled for them. 2746 2747 # mkdir instances/foo 2748 # mkdir instances/bar 2749 # mkdir instances/zoot 2750 # echo 100000 > buffer_size_kb 2751 # echo 1000 > instances/foo/buffer_size_kb 2752 # echo 5000 > instances/bar/per_cpu/cpu1/buffer_size_kb 2753 # echo function > current_trace 2754 # echo 1 > instances/foo/events/sched/sched_wakeup/enable 2755 # echo 1 > instances/foo/events/sched/sched_wakeup_new/enable 2756 # echo 1 > instances/foo/events/sched/sched_switch/enable 2757 # echo 1 > instances/bar/events/irq/enable 2758 # echo 1 > instances/zoot/events/syscalls/enable 2759 # cat trace_pipe 2760CPU:2 [LOST 11745 EVENTS] 2761 bash-2044 [002] .... 10594.481032: _raw_spin_lock_irqsave <-get_page_from_freelist 2762 bash-2044 [002] d... 10594.481032: add_preempt_count <-_raw_spin_lock_irqsave 2763 bash-2044 [002] d..1 10594.481032: __rmqueue <-get_page_from_freelist 2764 bash-2044 [002] d..1 10594.481033: _raw_spin_unlock <-get_page_from_freelist 2765 bash-2044 [002] d..1 10594.481033: sub_preempt_count <-_raw_spin_unlock 2766 bash-2044 [002] d... 10594.481033: get_pageblock_flags_group <-get_pageblock_migratetype 2767 bash-2044 [002] d... 10594.481034: __mod_zone_page_state <-get_page_from_freelist 2768 bash-2044 [002] d... 10594.481034: zone_statistics <-get_page_from_freelist 2769 bash-2044 [002] d... 10594.481034: __inc_zone_state <-zone_statistics 2770 bash-2044 [002] d... 10594.481034: __inc_zone_state <-zone_statistics 2771 bash-2044 [002] .... 10594.481035: arch_dup_task_struct <-copy_process 2772[...] 2773 2774 # cat instances/foo/trace_pipe 2775 bash-1998 [000] d..4 136.676759: sched_wakeup: comm=kworker/0:1 pid=59 prio=120 success=1 target_cpu=000 2776 bash-1998 [000] dN.4 136.676760: sched_wakeup: comm=bash pid=1998 prio=120 success=1 target_cpu=000 2777 <idle>-0 [003] d.h3 136.676906: sched_wakeup: comm=rcu_preempt pid=9 prio=120 success=1 target_cpu=003 2778 <idle>-0 [003] d..3 136.676909: sched_switch: prev_comm=swapper/3 prev_pid=0 prev_prio=120 prev_state=R ==> next_comm=rcu_preempt next_pid=9 next_prio=120 2779 rcu_preempt-9 [003] d..3 136.676916: sched_switch: prev_comm=rcu_preempt prev_pid=9 prev_prio=120 prev_state=S ==> next_comm=swapper/3 next_pid=0 next_prio=120 2780 bash-1998 [000] d..4 136.677014: sched_wakeup: comm=kworker/0:1 pid=59 prio=120 success=1 target_cpu=000 2781 bash-1998 [000] dN.4 136.677016: sched_wakeup: comm=bash pid=1998 prio=120 success=1 target_cpu=000 2782 bash-1998 [000] d..3 136.677018: sched_switch: prev_comm=bash prev_pid=1998 prev_prio=120 prev_state=R+ ==> next_comm=kworker/0:1 next_pid=59 next_prio=120 2783 kworker/0:1-59 [000] d..4 136.677022: sched_wakeup: comm=sshd pid=1995 prio=120 success=1 target_cpu=001 2784 kworker/0:1-59 [000] d..3 136.677025: sched_switch: prev_comm=kworker/0:1 prev_pid=59 prev_prio=120 prev_state=S ==> next_comm=bash next_pid=1998 next_prio=120 2785[...] 2786 2787 # cat instances/bar/trace_pipe 2788 migration/1-14 [001] d.h3 138.732674: softirq_raise: vec=3 [action=NET_RX] 2789 <idle>-0 [001] dNh3 138.732725: softirq_raise: vec=3 [action=NET_RX] 2790 bash-1998 [000] d.h1 138.733101: softirq_raise: vec=1 [action=TIMER] 2791 bash-1998 [000] d.h1 138.733102: softirq_raise: vec=9 [action=RCU] 2792 bash-1998 [000] ..s2 138.733105: softirq_entry: vec=1 [action=TIMER] 2793 bash-1998 [000] ..s2 138.733106: softirq_exit: vec=1 [action=TIMER] 2794 bash-1998 [000] ..s2 138.733106: softirq_entry: vec=9 [action=RCU] 2795 bash-1998 [000] ..s2 138.733109: softirq_exit: vec=9 [action=RCU] 2796 sshd-1995 [001] d.h1 138.733278: irq_handler_entry: irq=21 name=uhci_hcd:usb4 2797 sshd-1995 [001] d.h1 138.733280: irq_handler_exit: irq=21 ret=unhandled 2798 sshd-1995 [001] d.h1 138.733281: irq_handler_entry: irq=21 name=eth0 2799 sshd-1995 [001] d.h1 138.733283: irq_handler_exit: irq=21 ret=handled 2800[...] 2801 2802 # cat instances/zoot/trace 2803# tracer: nop 2804# 2805# entries-in-buffer/entries-written: 18996/18996 #P:4 2806# 2807# _-----=> irqs-off 2808# / _----=> need-resched 2809# | / _---=> hardirq/softirq 2810# || / _--=> preempt-depth 2811# ||| / delay 2812# TASK-PID CPU# |||| TIMESTAMP FUNCTION 2813# | | | |||| | | 2814 bash-1998 [000] d... 140.733501: sys_write -> 0x2 2815 bash-1998 [000] d... 140.733504: sys_dup2(oldfd: a, newfd: 1) 2816 bash-1998 [000] d... 140.733506: sys_dup2 -> 0x1 2817 bash-1998 [000] d... 140.733508: sys_fcntl(fd: a, cmd: 1, arg: 0) 2818 bash-1998 [000] d... 140.733509: sys_fcntl -> 0x1 2819 bash-1998 [000] d... 140.733510: sys_close(fd: a) 2820 bash-1998 [000] d... 140.733510: sys_close -> 0x0 2821 bash-1998 [000] d... 140.733514: sys_rt_sigprocmask(how: 0, nset: 0, oset: 6e2768, sigsetsize: 8) 2822 bash-1998 [000] d... 140.733515: sys_rt_sigprocmask -> 0x0 2823 bash-1998 [000] d... 140.733516: sys_rt_sigaction(sig: 2, act: 7fff718846f0, oact: 7fff71884650, sigsetsize: 8) 2824 bash-1998 [000] d... 140.733516: sys_rt_sigaction -> 0x0 2825 2826You can see that the trace of the top most trace buffer shows only 2827the function tracing. The foo instance displays wakeups and task 2828switches. 2829 2830To remove the instances, simply delete their directories: 2831 2832 # rmdir instances/foo 2833 # rmdir instances/bar 2834 # rmdir instances/zoot 2835 2836Note, if a process has a trace file open in one of the instance 2837directories, the rmdir will fail with EBUSY. 2838 2839 2840Stack trace 2841----------- 2842Since the kernel has a fixed sized stack, it is important not to 2843waste it in functions. A kernel developer must be conscience of 2844what they allocate on the stack. If they add too much, the system 2845can be in danger of a stack overflow, and corruption will occur, 2846usually leading to a system panic. 2847 2848There are some tools that check this, usually with interrupts 2849periodically checking usage. But if you can perform a check 2850at every function call that will become very useful. As ftrace provides 2851a function tracer, it makes it convenient to check the stack size 2852at every function call. This is enabled via the stack tracer. 2853 2854CONFIG_STACK_TRACER enables the ftrace stack tracing functionality. 2855To enable it, write a '1' into /proc/sys/kernel/stack_tracer_enabled. 2856 2857 # echo 1 > /proc/sys/kernel/stack_tracer_enabled 2858 2859You can also enable it from the kernel command line to trace 2860the stack size of the kernel during boot up, by adding "stacktrace" 2861to the kernel command line parameter. 2862 2863After running it for a few minutes, the output looks like: 2864 2865 # cat stack_max_size 28662928 2867 2868 # cat stack_trace 2869 Depth Size Location (18 entries) 2870 ----- ---- -------- 2871 0) 2928 224 update_sd_lb_stats+0xbc/0x4ac 2872 1) 2704 160 find_busiest_group+0x31/0x1f1 2873 2) 2544 256 load_balance+0xd9/0x662 2874 3) 2288 80 idle_balance+0xbb/0x130 2875 4) 2208 128 __schedule+0x26e/0x5b9 2876 5) 2080 16 schedule+0x64/0x66 2877 6) 2064 128 schedule_timeout+0x34/0xe0 2878 7) 1936 112 wait_for_common+0x97/0xf1 2879 8) 1824 16 wait_for_completion+0x1d/0x1f 2880 9) 1808 128 flush_work+0xfe/0x119 2881 10) 1680 16 tty_flush_to_ldisc+0x1e/0x20 2882 11) 1664 48 input_available_p+0x1d/0x5c 2883 12) 1616 48 n_tty_poll+0x6d/0x134 2884 13) 1568 64 tty_poll+0x64/0x7f 2885 14) 1504 880 do_select+0x31e/0x511 2886 15) 624 400 core_sys_select+0x177/0x216 2887 16) 224 96 sys_select+0x91/0xb9 2888 17) 128 128 system_call_fastpath+0x16/0x1b 2889 2890Note, if -mfentry is being used by gcc, functions get traced before 2891they set up the stack frame. This means that leaf level functions 2892are not tested by the stack tracer when -mfentry is used. 2893 2894Currently, -mfentry is used by gcc 4.6.0 and above on x86 only. 2895 2896--------- 2897 2898More details can be found in the source code, in the 2899kernel/trace/*.c files. 2900