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