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