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