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