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