Lines Matching +full:ftrace +full:- +full:size
2 ftrace - Function Tracer
13 - Written for: 2.6.28-rc2
14 - Updated for: 3.10
15 - Updated for: 4.13 - Copyright 2017 VMware Inc. Steven Rostedt
16 - Converted to rst format - Changbin Du <changbin.du@intel.com>
19 ------------
21 Ftrace is an internal tracer designed to help out developers and
24 performance issues that take place outside of user-space.
26 Although ftrace is typically considered the function tracer, it
32 One of the most common uses of ftrace is the event tracing.
41 ----------------------
43 See Documentation/trace/ftrace-design.rst for details for arch porters and such.
47 ---------------
49 Ftrace uses the tracefs file system to hold the control files as
52 When tracefs is configured into the kernel (which selecting any ftrace
60 mount -t tracefs nodev /sys/kernel/tracing
65 ln -s /sys/kernel/tracing /tracing
69 Before 4.1, all ftrace tracing control files were within the debugfs
81 Any selected ftrace option will also create the tracefs file system.
82 The rest of the document will assume that you are in the ftrace directory
87 That's it! (assuming that you have ftrace configured into your kernel)
90 of ftrace. Here is a list of some of the key files:
118 set this file to "0". User space can re-enable tracing by
123 be re-enabled by user space using this file.
192 0 - means to wake up as soon as there is any data in the ring buffer.
193 50 - means to wake up when roughly half of the ring buffer sub-buffers
195 100 - means to block until the ring buffer is totally full and is
201 buffer holds. By default, the trace buffers are the same size
202 for each CPU. The displayed number is the size of the
203 CPU buffer and not total size of all buffers. The
205 that the kernel uses for allocation, usually 4 KB in size).
207 meta-data. If the last page allocated has room for more bytes
210 ( Note, the size may not be a multiple of the page size
211 due to buffer management meta-data. )
219 This displays the total combined size of all the trace buffers.
223 This sets or displays the sub buffer size. The ring buffer is broken up
224 into several same size "sub buffers". An event can not be bigger than
225 the size of the sub buffer. Normally, the sub buffer is the size of the
227 at the start which also limits the size of an event. That means when
228 the sub buffer is a page size, no event can be larger than the page
229 size minus the sub buffer meta data.
232 minimum size of the subbuffer. The kernel may make it bigger due to the
236 Changing the sub buffer size allows for events to be larger than the
237 page size.
239 Note: When changing the sub-buffer size, tracing is stopped and any
247 of this file, the ring buffer will be resized to its minimum size.
261 When dynamic ftrace is configured in (see the
262 section below "dynamic ftrace"), the code is dynamically
296 If the "function-fork" option is set, then when a task whose
307 If the "function-fork" option is set, then when a task whose
323 added on fork, enable the "event-fork" option. That option will also
336 added on fork, enable the "event-fork" option. That option will also
344 they call. (See the section "dynamic ftrace" for more details).
357 This lists the functions that ftrace has processed and can trace.
361 (See the section "dynamic ftrace" below for more details.)
366 for each function. The displayed address is the patch-site address
376 This file is more for debugging ftrace, but can also be useful
378 Not only does the trace infrastructure use ftrace function
391 the "ip modify" attribute (thus the regs->ip can be changed),
395 If a non ftrace trampoline is attached (BPF) a 'D' will be displayed.
396 Note, normal ftrace trampolines can also be attached, but only one
400 the ftrace ops function located above the function entry point. In
405 used to know if a function was every modified by the ftrace infrastructure,
420 to it via the ftrace infrastructure. It has the same format as
471 the event specifically saves the task comm as well. Ftrace
476 If the option "record-cmd" is set to "0", then comms of tasks
487 If the option "record-tgid" is set, on each scheduling context switch
489 the thread to its TGID. By default, the "record-tgid" option is
501 maximum stack size it has encountered.
519 clock. By default, ftrace uses the "local" clock. This
528 [local] global counter x86-tsc
551 This makes ftrace use the same clock that perf uses.
552 Eventually perf will be able to read ftrace buffers
555 x86-tsc:
559 ppc-tb:
582 Also on 32-bit systems, it's possible that the 64-bit boot offset
588 This is the tai clock (CLOCK_TAI) and is derived from the wall-
610 this file will be written into the ftrace buffer.
637 that are written into /sys/kernel/tracing/events/ftrace/print/trigger
702 delta: Default timestamp mode - timestamp is a delta against
703 a per-buffer timestamp.
720 The ftrace buffer is defined per_cpu. That is, there's a separate
723 size buffers. This file is similar to the buffer_size_kb
724 file, but it only displays or sets the buffer size for the
741 For tools that can parse the ftrace ring buffer binary format,
777 event (ring buffer is re-entrant), that it fills the
796 -----------
830 trace with the latency-format option enabled, which
884 ----------------
886 For most ftrace commands, failure modes are obvious and communicated
894 error log displaying a small number (currently, 8) of ftrace errors
916 ----------------------------
920 user-land utilities).
923 --------------
929 # entries-in-buffer/entries-written: 140080/250280 #P:4
931 # _-----=> irqs-off
932 # / _----=> need-resched
933 # | / _---=> hardirq/softirq
934 # || / _--=> preempt-depth
936 # TASK-PID CPU# |||| TIMESTAMP FUNCTION
938 bash-1977 [000] .... 17284.993652: sys_close <-system_call_fastpath
939 bash-1977 [000] .... 17284.993653: __close_fd <-sys_close
940 bash-1977 [000] .... 17284.993653: _raw_spin_lock <-__close_fd
941 sshd-1974 [003] .... 17284.993653: __srcu_read_unlock <-fsnotify
942 bash-1977 [000] .... 17284.993654: add_preempt_count <-_raw_spin_lock
943 bash-1977 [000] ...1 17284.993655: _raw_spin_unlock <-__close_fd
944 bash-1977 [000] ...1 17284.993656: sub_preempt_count <-_raw_spin_unlock
945 bash-1977 [000] .... 17284.993657: filp_close <-__close_fd
946 bash-1977 [000] .... 17284.993657: dnotify_flush <-filp_close
947 sshd-1974 [003] .... 17284.993658: sys_select <-system_call_fastpath
954 lost due to the buffer filling up (250280 - 140080 = 110200 events
965 --------------------
967 When the latency-format option is enabled or when one of the latency
973 # irqsoff latency trace v1.1.5 on 3.8.0-test+
974 # --------------------------------------------------------------------
976 # -----------------
977 # | task: ps-6143 (uid:0 nice:0 policy:0 rt_prio:0)
978 # -----------------
983 # _------=> CPU#
984 # / _-----=> irqs-off
985 # | / _----=> need-resched
986 # || / _---=> hardirq/softirq
987 # ||| / _--=> preempt-depth
991 ps-6143 2d... 0us!: trace_hardirqs_off <-__lock_task_sighand
992 ps-6143 2d..1 259us+: trace_hardirqs_on <-_raw_spin_unlock_irqrestore
993 ps-6143 2d..1 263us+: time_hardirqs_on <-_raw_spin_unlock_irqrestore
994 ps-6143 2d..1 306us : <stack trace>
1021 - __lock_task_sighand is where the interrupts were disabled.
1022 - _raw_spin_unlock_irqrestore is where they were enabled again.
1033 irqs-off: 'd' interrupts are disabled. '.' otherwise.
1035 need-resched:
1036 - 'B' all, TIF_NEED_RESCHED, PREEMPT_NEED_RESCHED and TIF_RESCHED_LAZY is set,
1037 - 'N' both TIF_NEED_RESCHED and PREEMPT_NEED_RESCHED is set,
1038 - 'n' only TIF_NEED_RESCHED is set,
1039 - 'p' only PREEMPT_NEED_RESCHED is set,
1040 - 'L' both PREEMPT_NEED_RESCHED and TIF_RESCHED_LAZY is set,
1041 - 'b' both TIF_NEED_RESCHED and TIF_RESCHED_LAZY is set,
1042 - 'l' only TIF_RESCHED_LAZY is set
1043 - '.' otherwise.
1046 - 'Z' - NMI occurred inside a hardirq
1047 - 'z' - NMI is running
1048 - 'H' - hard irq occurred inside a softirq.
1049 - 'h' - hard irq is running
1050 - 's' - soft irq is running
1051 - '.' - normal context.
1053 preempt-depth: The level of preempt_disabled
1058 When the latency-format option is enabled, the trace file
1060 trace. This differs from the output when latency-format
1069 - '$' - greater than 1 second
1070 - '@' - greater than 100 millisecond
1071 - '*' - greater than 10 millisecond
1072 - '#' - greater than 1000 microsecond
1073 - '!' - greater than 100 microsecond
1074 - '+' - greater than 10 microsecond
1075 - ' ' - less than or equal to 10 microsecond.
1083 -------------
1090 print-parent
1091 nosym-offset
1092 nosym-addr
1102 nosym-userobj
1103 noprintk-msg-only
1104 context-info
1105 nolatency-format
1106 record-cmd
1107 norecord-tgid
1110 irq-info
1112 noevent-fork
1113 function-trace
1114 nofunction-fork
1115 nodisplay-graph
1122 echo noprint-parent > trace_options
1126 echo sym-offset > trace_options
1130 print-parent
1135 print-parent:
1136 bash-4000 [01] 1477.606694: simple_strtoul <-kstrtoul
1138 noprint-parent:
1139 bash-4000 [01] 1477.606694: simple_strtoul
1142 sym-offset
1149 sym-offset:
1150 bash-4000 [01] 1477.606694: simple_strtoul+0x6/0xa0
1152 sym-addr
1157 sym-addr:
1158 bash-4000 [01] 1477.606694: simple_strtoul <c0339346>
1162 latency-format option is enabled.
1212 <idle>-0 [001] dNs4 21169.031481: wake_up_idle_cpu <-add_timer_on
1213 <idle>-0 [001] dNs4 21169.031482: _raw_spin_unlock_irqrestore <-add_timer_on
1214 <idle>-0 [001] .Ns4 21169.031484: sub_preempt_count <-_raw_spin_unlock_irqrestore
1216 <idle>-0 [002] .N.1 21169.031484: rcu_idle_exit <-cpu_idle
1217 <idle>-0 [001] .Ns3 21169.031484: _raw_spin_unlock <-clocksource_watchdog
1218 <idle>-0 [001] .Ns3 21169.031485: sub_preempt_count <-_raw_spin_unlock
1225 sym-userobj
1236 a.out-1623 [000] 40874.465068: /root/a.out[+0x480] <-/root/a.out[+0
1237 x494] <- /root/a.out[+0x4a8] <- /lib/libc-2.7.so[+0x1e1a6]
1240 printk-msg-only
1245 context-info
1249 latency-format
1254 pause-on-trace
1260 hash-ptr
1266 record-cmd
1274 record-tgid
1291 irq-info
1297 # entries-in-buffer/entries-written: 144405/9452052 #P:4
1299 # TASK-PID CPU# TIMESTAMP FUNCTION
1301 <idle>-0 [002] 23636.756054: ttwu_do_activate.constprop.89 <-try_to_wake_up
1302 <idle>-0 [002] 23636.756054: activate_task <-ttwu_do_activate.constprop.89
1303 <idle>-0 [002] 23636.756055: enqueue_task <-activate_task
1311 event-fork
1319 function-trace
1326 function-fork
1335 display-graph
1371 funcgraph-overrun
1382 funcgraph-cpu
1386 funcgraph-overhead
1392 funcgraph-proc
1399 funcgraph-duration
1404 funcgraph-abstime
1407 funcgraph-irqs
1411 funcgraph-tail
1417 funcgraph-retval
1422 funcgraph-retval-hex
1430 sleep-time
1436 graph-time
1450 -------
1467 # echo 0 > options/function-trace
1471 # ls -ltr
1477 # irqsoff latency trace v1.1.5 on 3.8.0-test+
1478 # --------------------------------------------------------------------
1480 # -----------------
1481 # | task: swapper/0-0 (uid:0 nice:0 policy:0 rt_prio:0)
1482 # -----------------
1487 # _------=> CPU#
1488 # / _-----=> irqs-off
1489 # | / _----=> need-resched
1490 # || / _---=> hardirq/softirq
1491 # ||| / _--=> preempt-depth
1495 <idle>-0 0d.s2 0us+: _raw_spin_lock_irq <-run_timer_softirq
1496 <idle>-0 0dNs3 17us : _raw_spin_unlock_irq <-run_timer_softirq
1497 <idle>-0 0dNs3 17us+: trace_hardirqs_on <-run_timer_softirq
1498 <idle>-0 0dNs3 25us : <stack trace>
1521 Note the above example had function-trace not set. If we set
1522 function-trace, we get a much larger output::
1524 with echo 1 > options/function-trace
1528 # irqsoff latency trace v1.1.5 on 3.8.0-test+
1529 # --------------------------------------------------------------------
1531 # -----------------
1532 # | task: bash-2042 (uid:0 nice:0 policy:0 rt_prio:0)
1533 # -----------------
1538 # _------=> CPU#
1539 # / _-----=> irqs-off
1540 # | / _----=> need-resched
1541 # || / _---=> hardirq/softirq
1542 # ||| / _--=> preempt-depth
1546 bash-2042 3d... 0us : _raw_spin_lock_irqsave <-ata_scsi_queuecmd
1547 bash-2042 3d... 0us : add_preempt_count <-_raw_spin_lock_irqsave
1548 bash-2042 3d..1 1us : ata_scsi_find_dev <-ata_scsi_queuecmd
1549 bash-2042 3d..1 1us : __ata_scsi_find_dev <-ata_scsi_find_dev
1550 bash-2042 3d..1 2us : ata_find_dev.part.14 <-__ata_scsi_find_dev
1551 bash-2042 3d..1 2us : ata_qc_new_init <-__ata_scsi_queuecmd
1552 bash-2042 3d..1 3us : ata_sg_init <-__ata_scsi_queuecmd
1553 bash-2042 3d..1 4us : ata_scsi_rw_xlat <-__ata_scsi_queuecmd
1554 bash-2042 3d..1 4us : ata_build_rw_tf <-ata_scsi_rw_xlat
1556 bash-2042 3d..1 67us : delay_tsc <-__delay
1557 bash-2042 3d..1 67us : add_preempt_count <-delay_tsc
1558 bash-2042 3d..2 67us : sub_preempt_count <-delay_tsc
1559 bash-2042 3d..1 67us : add_preempt_count <-delay_tsc
1560 bash-2042 3d..2 68us : sub_preempt_count <-delay_tsc
1561 bash-2042 3d..1 68us+: ata_bmdma_start <-ata_bmdma_qc_issue
1562 bash-2042 3d..1 71us : _raw_spin_unlock_irqrestore <-ata_scsi_queuecmd
1563 bash-2042 3d..1 71us : _raw_spin_unlock_irqrestore <-ata_scsi_queuecmd
1564 bash-2042 3d..1 72us+: trace_hardirqs_on <-ata_scsi_queuecmd
1565 bash-2042 3d..1 120us : <stack trace>
1600 display-graph option::
1602 with echo 1 > options/display-graph
1606 # irqsoff latency trace v1.1.5 on 4.20.0-rc6+
1607 # --------------------------------------------------------------------
1609 # -----------------
1610 # | task: bash-1507 (uid:0 nice:0 policy:0 rt_prio:0)
1611 # -----------------
1616 # _-----=> irqs-off
1617 # / _----=> need-resched
1618 # | / _---=> hardirq/softirq
1619 # || / _--=> preempt-depth
1623 0 us | 0) bash-1507 | d... | 0.000 us | _raw_spin_lock_irqsave();
1624 0 us | 0) bash-1507 | d..1 | 0.378 us | do_raw_spin_trylock();
1625 1 us | 0) bash-1507 | d..2 | | set_track() {
1626 2 us | 0) bash-1507 | d..2 | | save_stack_trace() {
1627 2 us | 0) bash-1507 | d..2 | | __save_stack_trace() {
1628 3 us | 0) bash-1507 | d..2 | | __unwind_start() {
1629 3 us | 0) bash-1507 | d..2 | | get_stack_info() {
1630 3 us | 0) bash-1507 | d..2 | 0.351 us | in_task_stack();
1631 4 us | 0) bash-1507 | d..2 | 1.107 us | }
1633 3750 us | 0) bash-1507 | d..1 | 0.516 us | do_raw_spin_unlock();
1634 3750 us | 0) bash-1507 | d..1 | 0.000 us | _raw_spin_unlock_irqrestore();
1635 3764 us | 0) bash-1507 | d..1 | 0.000 us | tracer_hardirqs_on();
1636 bash-1507 0d..1 3792us : <stack trace>
1653 ----------
1666 # echo 0 > options/function-trace
1670 # ls -ltr
1676 # preemptoff latency trace v1.1.5 on 3.8.0-test+
1677 # --------------------------------------------------------------------
1679 # -----------------
1680 # | task: sshd-1991 (uid:0 nice:0 policy:0 rt_prio:0)
1681 # -----------------
1686 # _------=> CPU#
1687 # / _-----=> irqs-off
1688 # | / _----=> need-resched
1689 # || / _---=> hardirq/softirq
1690 # ||| / _--=> preempt-depth
1694 sshd-1991 1d.h. 0us+: irq_enter <-do_IRQ
1695 sshd-1991 1d..1 46us : irq_exit <-do_IRQ
1696 sshd-1991 1d..1 47us+: trace_preempt_on <-do_IRQ
1697 sshd-1991 1d..1 52us : <stack trace>
1714 # preemptoff latency trace v1.1.5 on 3.8.0-test+
1715 # --------------------------------------------------------------------
1717 # -----------------
1718 # | task: bash-1994 (uid:0 nice:0 policy:0 rt_prio:0)
1719 # -----------------
1724 # _------=> CPU#
1725 # / _-----=> irqs-off
1726 # | / _----=> need-resched
1727 # || / _---=> hardirq/softirq
1728 # ||| / _--=> preempt-depth
1732 bash-1994 1d..1 0us : _raw_spin_lock_irqsave <-wake_up_new_task
1733 bash-1994 1d..1 0us : select_task_rq_fair <-select_task_rq
1734 bash-1994 1d..1 1us : __rcu_read_lock <-select_task_rq_fair
1735 bash-1994 1d..1 1us : source_load <-select_task_rq_fair
1736 bash-1994 1d..1 1us : source_load <-select_task_rq_fair
1738 bash-1994 1d..1 12us : irq_enter <-smp_apic_timer_interrupt
1739 bash-1994 1d..1 12us : rcu_irq_enter <-irq_enter
1740 bash-1994 1d..1 13us : add_preempt_count <-irq_enter
1741 bash-1994 1d.h1 13us : exit_idle <-smp_apic_timer_interrupt
1742 bash-1994 1d.h1 13us : hrtimer_interrupt <-smp_apic_timer_interrupt
1743 bash-1994 1d.h1 13us : _raw_spin_lock <-hrtimer_interrupt
1744 bash-1994 1d.h1 14us : add_preempt_count <-_raw_spin_lock
1745 bash-1994 1d.h2 14us : ktime_get_update_offsets <-hrtimer_interrupt
1747 bash-1994 1d.h1 35us : lapic_next_event <-clockevents_program_event
1748 bash-1994 1d.h1 35us : irq_exit <-smp_apic_timer_interrupt
1749 bash-1994 1d.h1 36us : sub_preempt_count <-irq_exit
1750 bash-1994 1d..2 36us : do_softirq <-irq_exit
1751 bash-1994 1d..2 36us : __do_softirq <-call_softirq
1752 bash-1994 1d..2 36us : __local_bh_disable <-__do_softirq
1753 bash-1994 1d.s2 37us : add_preempt_count <-_raw_spin_lock_irq
1754 bash-1994 1d.s3 38us : _raw_spin_unlock <-run_timer_softirq
1755 bash-1994 1d.s3 39us : sub_preempt_count <-_raw_spin_unlock
1756 bash-1994 1d.s2 39us : call_timer_fn <-run_timer_softirq
1758 bash-1994 1dNs2 81us : cpu_needs_another_gp <-rcu_process_callbacks
1759 bash-1994 1dNs2 82us : __local_bh_enable <-__do_softirq
1760 bash-1994 1dNs2 82us : sub_preempt_count <-__local_bh_enable
1761 bash-1994 1dN.2 82us : idle_cpu <-irq_exit
1762 bash-1994 1dN.2 83us : rcu_irq_exit <-irq_exit
1763 bash-1994 1dN.2 83us : sub_preempt_count <-irq_exit
1764 bash-1994 1.N.1 84us : _raw_spin_unlock_irqrestore <-task_rq_unlock
1765 bash-1994 1.N.1 84us+: trace_preempt_on <-task_rq_unlock
1766 bash-1994 1.N.1 104us : <stack trace>
1777 function-trace set. Here we see that interrupts were not disabled
1784 --------------
1818 # echo 0 > options/function-trace
1822 # ls -ltr
1828 # preemptirqsoff latency trace v1.1.5 on 3.8.0-test+
1829 # --------------------------------------------------------------------
1831 # -----------------
1832 # | task: ls-2230 (uid:0 nice:0 policy:0 rt_prio:0)
1833 # -----------------
1838 # _------=> CPU#
1839 # / _-----=> irqs-off
1840 # | / _----=> need-resched
1841 # || / _---=> hardirq/softirq
1842 # ||| / _--=> preempt-depth
1846 ls-2230 3d... 0us+: _raw_spin_lock_irqsave <-ata_scsi_queuecmd
1847 ls-2230 3...1 100us : _raw_spin_unlock_irqrestore <-ata_scsi_queuecmd
1848 ls-2230 3...1 101us+: trace_preempt_on <-ata_scsi_queuecmd
1849 ls-2230 3...1 111us : <stack trace>
1877 Here is a trace with function-trace set::
1881 # preemptirqsoff latency trace v1.1.5 on 3.8.0-test+
1882 # --------------------------------------------------------------------
1884 # -----------------
1885 # | task: ls-2269 (uid:0 nice:0 policy:0 rt_prio:0)
1886 # -----------------
1891 # _------=> CPU#
1892 # / _-----=> irqs-off
1893 # | / _----=> need-resched
1894 # || / _---=> hardirq/softirq
1895 # ||| / _--=> preempt-depth
1899 kworker/-59 3...1 0us : __schedule <-schedule
1900 kworker/-59 3d..1 0us : rcu_preempt_qs <-rcu_note_context_switch
1901 kworker/-59 3d..1 1us : add_preempt_count <-_raw_spin_lock_irq
1902 kworker/-59 3d..2 1us : deactivate_task <-__schedule
1903 kworker/-59 3d..2 1us : dequeue_task <-deactivate_task
1904 kworker/-59 3d..2 2us : update_rq_clock <-dequeue_task
1905 kworker/-59 3d..2 2us : dequeue_task_fair <-dequeue_task
1906 kworker/-59 3d..2 2us : update_curr <-dequeue_task_fair
1907 kworker/-59 3d..2 2us : update_min_vruntime <-update_curr
1908 kworker/-59 3d..2 3us : cpuacct_charge <-update_curr
1909 kworker/-59 3d..2 3us : __rcu_read_lock <-cpuacct_charge
1910 kworker/-59 3d..2 3us : __rcu_read_unlock <-cpuacct_charge
1911 kworker/-59 3d..2 3us : update_cfs_rq_blocked_load <-dequeue_task_fair
1912 kworker/-59 3d..2 4us : clear_buddies <-dequeue_task_fair
1913 kworker/-59 3d..2 4us : account_entity_dequeue <-dequeue_task_fair
1914 kworker/-59 3d..2 4us : update_min_vruntime <-dequeue_task_fair
1915 kworker/-59 3d..2 4us : update_cfs_shares <-dequeue_task_fair
1916 kworker/-59 3d..2 5us : hrtick_update <-dequeue_task_fair
1917 kworker/-59 3d..2 5us : wq_worker_sleeping <-__schedule
1918 kworker/-59 3d..2 5us : kthread_data <-wq_worker_sleeping
1919 kworker/-59 3d..2 5us : put_prev_task_fair <-__schedule
1920 kworker/-59 3d..2 6us : pick_next_task_fair <-pick_next_task
1921 kworker/-59 3d..2 6us : clear_buddies <-pick_next_task_fair
1922 kworker/-59 3d..2 6us : set_next_entity <-pick_next_task_fair
1923 kworker/-59 3d..2 6us : update_stats_wait_end <-set_next_entity
1924 ls-2269 3d..2 7us : finish_task_switch <-__schedule
1925 ls-2269 3d..2 7us : _raw_spin_unlock_irq <-finish_task_switch
1926 ls-2269 3d..2 8us : do_IRQ <-ret_from_intr
1927 ls-2269 3d..2 8us : irq_enter <-do_IRQ
1928 ls-2269 3d..2 8us : rcu_irq_enter <-irq_enter
1929 ls-2269 3d..2 9us : add_preempt_count <-irq_enter
1930 ls-2269 3d.h2 9us : exit_idle <-do_IRQ
1932 ls-2269 3d.h3 20us : sub_preempt_count <-_raw_spin_unlock
1933 ls-2269 3d.h2 20us : irq_exit <-do_IRQ
1934 ls-2269 3d.h2 21us : sub_preempt_count <-irq_exit
1935 ls-2269 3d..3 21us : do_softirq <-irq_exit
1936 ls-2269 3d..3 21us : __do_softirq <-call_softirq
1937 ls-2269 3d..3 21us+: __local_bh_disable <-__do_softirq
1938 ls-2269 3d.s4 29us : sub_preempt_count <-_local_bh_enable_ip
1939 ls-2269 3d.s5 29us : sub_preempt_count <-_local_bh_enable_ip
1940 ls-2269 3d.s5 31us : do_IRQ <-ret_from_intr
1941 ls-2269 3d.s5 31us : irq_enter <-do_IRQ
1942 ls-2269 3d.s5 31us : rcu_irq_enter <-irq_enter
1944 ls-2269 3d.s5 31us : rcu_irq_enter <-irq_enter
1945 ls-2269 3d.s5 32us : add_preempt_count <-irq_enter
1946 ls-2269 3d.H5 32us : exit_idle <-do_IRQ
1947 ls-2269 3d.H5 32us : handle_irq <-do_IRQ
1948 ls-2269 3d.H5 32us : irq_to_desc <-handle_irq
1949 ls-2269 3d.H5 33us : handle_fasteoi_irq <-handle_irq
1951 ls-2269 3d.s5 158us : _raw_spin_unlock_irqrestore <-rtl8139_poll
1952 ls-2269 3d.s3 158us : net_rps_action_and_irq_enable.isra.65 <-net_rx_action
1953 ls-2269 3d.s3 159us : __local_bh_enable <-__do_softirq
1954 ls-2269 3d.s3 159us : sub_preempt_count <-__local_bh_enable
1955 ls-2269 3d..3 159us : idle_cpu <-irq_exit
1956 ls-2269 3d..3 159us : rcu_irq_exit <-irq_exit
1957 ls-2269 3d..3 160us : sub_preempt_count <-irq_exit
1958 ls-2269 3d... 161us : __mutex_unlock_slowpath <-mutex_unlock
1959 ls-2269 3d... 162us+: trace_hardirqs_on <-mutex_unlock
1960 ls-2269 3d... 186us : <stack trace>
1979 ------
1983 Now for non Real-Time tasks, this can be arbitrary. But tracing
1988 # echo 0 > options/function-trace
1992 # chrt -f 5 sleep 1
1997 # wakeup latency trace v1.1.5 on 3.8.0-test+
1998 # --------------------------------------------------------------------
2000 # -----------------
2001 # | task: kworker/3:1H-312 (uid:0 nice:-20 policy:0 rt_prio:0)
2002 # -----------------
2004 # _------=> CPU#
2005 # / _-----=> irqs-off
2006 # | / _----=> need-resched
2007 # || / _---=> hardirq/softirq
2008 # ||| / _--=> preempt-depth
2012 <idle>-0 3dNs7 0us : 0:120:R + [003] 312:100:R kworker/3:1H
2013 <idle>-0 3dNs7 1us+: ttwu_do_activate.constprop.87 <-try_to_wake_up
2014 <idle>-0 3d..3 15us : __schedule <-schedule
2015 <idle>-0 3d..3 15us : 0:120:R ==> [003] 312:100:R kworker/3:1H
2019 the kworker with a nice priority of -20 (not very nice), took
2023 Non Real-Time tasks are not that interesting. A more interesting
2024 trace is to concentrate only on Real-Time tasks.
2027 ---------
2029 In a Real-Time environment it is very important to know the
2033 also important to know the scheduling latency of non-RT tasks,
2034 but the average schedule latency is better for non-RT tasks.
2038 Real-Time environments are interested in the worst case latency.
2042 work well with Real-Time tasks. The wakeup_rt tracer was designed
2043 to record the worst case wakeups of RT tasks. Non-RT tasks are
2045 tracing non-RT tasks that are unpredictable will overwrite the
2055 # echo 0 > options/function-trace
2059 # chrt -f 5 sleep 1
2066 # wakeup_rt latency trace v1.1.5 on 3.8.0-test+
2067 # --------------------------------------------------------------------
2069 # -----------------
2070 # | task: sleep-2389 (uid:0 nice:0 policy:1 rt_prio:5)
2071 # -----------------
2073 # _------=> CPU#
2074 # / _-----=> irqs-off
2075 # | / _----=> need-resched
2076 # || / _---=> hardirq/softirq
2077 # ||| / _--=> preempt-depth
2081 <idle>-0 3d.h4 0us : 0:120:R + [003] 2389: 94:R sleep
2082 <idle>-0 3d.h4 1us+: ttwu_do_activate.constprop.87 <-try_to_wake_up
2083 <idle>-0 3d..3 5us : __schedule <-schedule
2084 <idle>-0 3d..3 5us : 0:120:R ==> [003] 2389: 94:R sleep
2094 and it has an rt_prio of 5. This priority is user-space priority
2098 Note, that the trace data shows the internal priority (99 - rtprio).
2101 <idle>-0 3d..3 5us : 0:120:R ==> [003] 2389: 94:R sleep
2103 The 0:120:R means idle was running with a nice priority of 0 (120 - 120)
2105 2389: 94:R. That is the priority is the kernel rtprio (99 - 5 = 94)
2108 Doing the same with chrt -r 5 and function-trace set.
2111 echo 1 > options/function-trace
2115 # wakeup_rt latency trace v1.1.5 on 3.8.0-test+
2116 # --------------------------------------------------------------------
2118 # -----------------
2119 # | task: sleep-2448 (uid:0 nice:0 policy:1 rt_prio:5)
2120 # -----------------
2122 # _------=> CPU#
2123 # / _-----=> irqs-off
2124 # | / _----=> need-resched
2125 # || / _---=> hardirq/softirq
2126 # ||| / _--=> preempt-depth
2130 <idle>-0 3d.h4 1us+: 0:120:R + [003] 2448: 94:R sleep
2131 <idle>-0 3d.h4 2us : ttwu_do_activate.constprop.87 <-try_to_wake_up
2132 <idle>-0 3d.h3 3us : check_preempt_curr <-ttwu_do_wakeup
2133 <idle>-0 3d.h3 3us : resched_curr <-check_preempt_curr
2134 <idle>-0 3dNh3 4us : task_woken_rt <-ttwu_do_wakeup
2135 <idle>-0 3dNh3 4us : _raw_spin_unlock <-try_to_wake_up
2136 <idle>-0 3dNh3 4us : sub_preempt_count <-_raw_spin_unlock
2137 <idle>-0 3dNh2 5us : ttwu_stat <-try_to_wake_up
2138 <idle>-0 3dNh2 5us : _raw_spin_unlock_irqrestore <-try_to_wake_up
2139 <idle>-0 3dNh2 6us : sub_preempt_count <-_raw_spin_unlock_irqrestore
2140 <idle>-0 3dNh1 6us : _raw_spin_lock <-__run_hrtimer
2141 <idle>-0 3dNh1 6us : add_preempt_count <-_raw_spin_lock
2142 <idle>-0 3dNh2 7us : _raw_spin_unlock <-hrtimer_interrupt
2143 <idle>-0 3dNh2 7us : sub_preempt_count <-_raw_spin_unlock
2144 <idle>-0 3dNh1 7us : tick_program_event <-hrtimer_interrupt
2145 <idle>-0 3dNh1 7us : clockevents_program_event <-tick_program_event
2146 <idle>-0 3dNh1 8us : ktime_get <-clockevents_program_event
2147 <idle>-0 3dNh1 8us : lapic_next_event <-clockevents_program_event
2148 <idle>-0 3dNh1 8us : irq_exit <-smp_apic_timer_interrupt
2149 <idle>-0 3dNh1 9us : sub_preempt_count <-irq_exit
2150 <idle>-0 3dN.2 9us : idle_cpu <-irq_exit
2151 <idle>-0 3dN.2 9us : rcu_irq_exit <-irq_exit
2152 <idle>-0 3dN.2 10us : rcu_eqs_enter_common.isra.45 <-rcu_irq_exit
2153 <idle>-0 3dN.2 10us : sub_preempt_count <-irq_exit
2154 <idle>-0 3.N.1 11us : rcu_idle_exit <-cpu_idle
2155 <idle>-0 3dN.1 11us : rcu_eqs_exit_common.isra.43 <-rcu_idle_exit
2156 <idle>-0 3.N.1 11us : tick_nohz_idle_exit <-cpu_idle
2157 <idle>-0 3dN.1 12us : menu_hrtimer_cancel <-tick_nohz_idle_exit
2158 <idle>-0 3dN.1 12us : ktime_get <-tick_nohz_idle_exit
2159 <idle>-0 3dN.1 12us : tick_do_update_jiffies64 <-tick_nohz_idle_exit
2160 <idle>-0 3dN.1 13us : cpu_load_update_nohz <-tick_nohz_idle_exit
2161 <idle>-0 3dN.1 13us : _raw_spin_lock <-cpu_load_update_nohz
2162 <idle>-0 3dN.1 13us : add_preempt_count <-_raw_spin_lock
2163 <idle>-0 3dN.2 13us : __cpu_load_update <-cpu_load_update_nohz
2164 <idle>-0 3dN.2 14us : sched_avg_update <-__cpu_load_update
2165 <idle>-0 3dN.2 14us : _raw_spin_unlock <-cpu_load_update_nohz
2166 <idle>-0 3dN.2 14us : sub_preempt_count <-_raw_spin_unlock
2167 <idle>-0 3dN.1 15us : calc_load_nohz_stop <-tick_nohz_idle_exit
2168 <idle>-0 3dN.1 15us : touch_softlockup_watchdog <-tick_nohz_idle_exit
2169 <idle>-0 3dN.1 15us : hrtimer_cancel <-tick_nohz_idle_exit
2170 <idle>-0 3dN.1 15us : hrtimer_try_to_cancel <-hrtimer_cancel
2171 <idle>-0 3dN.1 16us : lock_hrtimer_base.isra.18 <-hrtimer_try_to_cancel
2172 <idle>-0 3dN.1 16us : _raw_spin_lock_irqsave <-lock_hrtimer_base.isra.18
2173 <idle>-0 3dN.1 16us : add_preempt_count <-_raw_spin_lock_irqsave
2174 <idle>-0 3dN.2 17us : __remove_hrtimer <-remove_hrtimer.part.16
2175 <idle>-0 3dN.2 17us : hrtimer_force_reprogram <-__remove_hrtimer
2176 <idle>-0 3dN.2 17us : tick_program_event <-hrtimer_force_reprogram
2177 <idle>-0 3dN.2 18us : clockevents_program_event <-tick_program_event
2178 <idle>-0 3dN.2 18us : ktime_get <-clockevents_program_event
2179 <idle>-0 3dN.2 18us : lapic_next_event <-clockevents_program_event
2180 <idle>-0 3dN.2 19us : _raw_spin_unlock_irqrestore <-hrtimer_try_to_cancel
2181 <idle>-0 3dN.2 19us : sub_preempt_count <-_raw_spin_unlock_irqrestore
2182 <idle>-0 3dN.1 19us : hrtimer_forward <-tick_nohz_idle_exit
2183 <idle>-0 3dN.1 20us : ktime_add_safe <-hrtimer_forward
2184 <idle>-0 3dN.1 20us : ktime_add_safe <-hrtimer_forward
2185 <idle>-0 3dN.1 20us : hrtimer_start_range_ns <-hrtimer_start_expires.constprop.11
2186 <idle>-0 3dN.1 20us : __hrtimer_start_range_ns <-hrtimer_start_range_ns
2187 <idle>-0 3dN.1 21us : lock_hrtimer_base.isra.18 <-__hrtimer_start_range_ns
2188 <idle>-0 3dN.1 21us : _raw_spin_lock_irqsave <-lock_hrtimer_base.isra.18
2189 <idle>-0 3dN.1 21us : add_preempt_count <-_raw_spin_lock_irqsave
2190 <idle>-0 3dN.2 22us : ktime_add_safe <-__hrtimer_start_range_ns
2191 <idle>-0 3dN.2 22us : enqueue_hrtimer <-__hrtimer_start_range_ns
2192 <idle>-0 3dN.2 22us : tick_program_event <-__hrtimer_start_range_ns
2193 <idle>-0 3dN.2 23us : clockevents_program_event <-tick_program_event
2194 <idle>-0 3dN.2 23us : ktime_get <-clockevents_program_event
2195 <idle>-0 3dN.2 23us : lapic_next_event <-clockevents_program_event
2196 <idle>-0 3dN.2 24us : _raw_spin_unlock_irqrestore <-__hrtimer_start_range_ns
2197 <idle>-0 3dN.2 24us : sub_preempt_count <-_raw_spin_unlock_irqrestore
2198 <idle>-0 3dN.1 24us : account_idle_ticks <-tick_nohz_idle_exit
2199 <idle>-0 3dN.1 24us : account_idle_time <-account_idle_ticks
2200 <idle>-0 3.N.1 25us : sub_preempt_count <-cpu_idle
2201 <idle>-0 3.N.. 25us : schedule <-cpu_idle
2202 <idle>-0 3.N.. 25us : __schedule <-preempt_schedule
2203 <idle>-0 3.N.. 26us : add_preempt_count <-__schedule
2204 <idle>-0 3.N.1 26us : rcu_note_context_switch <-__schedule
2205 <idle>-0 3.N.1 26us : rcu_sched_qs <-rcu_note_context_switch
2206 <idle>-0 3dN.1 27us : rcu_preempt_qs <-rcu_note_context_switch
2207 <idle>-0 3.N.1 27us : _raw_spin_lock_irq <-__schedule
2208 <idle>-0 3dN.1 27us : add_preempt_count <-_raw_spin_lock_irq
2209 <idle>-0 3dN.2 28us : put_prev_task_idle <-__schedule
2210 <idle>-0 3dN.2 28us : pick_next_task_stop <-pick_next_task
2211 <idle>-0 3dN.2 28us : pick_next_task_rt <-pick_next_task
2212 <idle>-0 3dN.2 29us : dequeue_pushable_task <-pick_next_task_rt
2213 <idle>-0 3d..3 29us : __schedule <-preempt_schedule
2214 <idle>-0 3d..3 30us : 0:120:R ==> [003] 2448: 94:R sleep
2224 --------------------------
2231 # echo 0 > options/function-trace
2236 # chrt -f 5 sleep 1
2241 # wakeup_rt latency trace v1.1.5 on 3.8.0-test+
2242 # --------------------------------------------------------------------
2244 # -----------------
2245 # | task: sleep-5882 (uid:0 nice:0 policy:1 rt_prio:5)
2246 # -----------------
2248 # _------=> CPU#
2249 # / _-----=> irqs-off
2250 # | / _----=> need-resched
2251 # || / _---=> hardirq/softirq
2252 # ||| / _--=> preempt-depth
2256 <idle>-0 2d.h4 0us : 0:120:R + [002] 5882: 94:R sleep
2257 <idle>-0 2d.h4 0us : ttwu_do_activate.constprop.87 <-try_to_wake_up
2258 <idle>-0 2d.h4 1us : sched_wakeup: comm=sleep pid=5882 prio=94 success=1 target_cpu=002
2259 <idle>-0 2dNh2 1us : hrtimer_expire_exit: hrtimer=ffff88007796feb8
2260 <idle>-0 2.N.2 2us : power_end: cpu_id=2
2261 <idle>-0 2.N.2 3us : cpu_idle: state=4294967295 cpu_id=2
2262 <idle>-0 2dN.3 4us : hrtimer_cancel: hrtimer=ffff88007d50d5e0
2263 …<idle>-0 2dN.3 4us : hrtimer_start: hrtimer=ffff88007d50d5e0 function=tick_sched_timer ex…
2264 <idle>-0 2.N.2 5us : rcu_utilization: Start context switch
2265 <idle>-0 2.N.2 5us : rcu_utilization: End context switch
2266 <idle>-0 2d..3 6us : __schedule <-schedule
2267 <idle>-0 2d..3 6us : 0:120:R ==> [002] 5882: 94:R sleep
2271 -------------------------
2284 # entries-in-buffer/entries-written: 13/13 #P:8
2286 # _-----=> irqs-off
2287 # / _----=> need-resched
2288 # | / _---=> hardirq/softirq
2289 # || / _--=> preempt-depth
2291 # TASK-PID CPU# |||| TIMESTAMP FUNCTION
2293 …<...>-1729 [001] d... 678.473449: #1 inner/outer(us): 11/12 ts:1581527483.343962693 co…
2294 …<...>-1729 [004] d... 689.556542: #2 inner/outer(us): 16/9 ts:1581527494.889008092 co…
2295 …<...>-1729 [005] d... 714.756290: #3 inner/outer(us): 16/16 ts:1581527519.678961629 co…
2296 …<...>-1729 [001] d... 718.788247: #4 inner/outer(us): 9/17 ts:1581527523.889012713 co…
2297 …<...>-1729 [002] d... 719.796341: #5 inner/outer(us): 13/9 ts:1581527524.912872606 co…
2298 …<...>-1729 [006] d... 844.787091: #6 inner/outer(us): 9/12 ts:1581527649.889048502 co…
2299 …<...>-1729 [003] d... 849.827033: #7 inner/outer(us): 18/9 ts:1581527654.889013793 co…
2300 …<...>-1729 [007] d... 853.859002: #8 inner/outer(us): 9/12 ts:1581527658.889065736 co…
2301 …<...>-1729 [001] d... 855.874978: #9 inner/outer(us): 9/11 ts:1581527660.861991877 co…
2302 …<...>-1729 [001] d... 863.938932: #10 inner/outer(us): 9/11 ts:1581527668.970010500 co…
2303 …<...>-1729 [007] d... 878.050780: #11 inner/outer(us): 9/12 ts:1581527683.385002600 co…
2304 …<...>-1729 [007] d... 886.114702: #12 inner/outer(us): 9/12 ts:1581527691.385001600 co…
2330 nmi-total:7 nmi-count:1
2333 test, the time spent in NMI is reported in "nmi-total" (in
2336 All architectures that have NMIs will show the "nmi-count" if an
2367 --------
2383 # entries-in-buffer/entries-written: 24799/24799 #P:4
2385 # _-----=> irqs-off
2386 # / _----=> need-resched
2387 # | / _---=> hardirq/softirq
2388 # || / _--=> preempt-depth
2390 # TASK-PID CPU# |||| TIMESTAMP FUNCTION
2392 bash-1994 [002] .... 3082.063030: mutex_unlock <-rb_simple_write
2393 bash-1994 [002] .... 3082.063031: __mutex_unlock_slowpath <-mutex_unlock
2394 bash-1994 [002] .... 3082.063031: __fsnotify_parent <-fsnotify_modify
2395 bash-1994 [002] .... 3082.063032: fsnotify <-fsnotify_modify
2396 bash-1994 [002] .... 3082.063032: __srcu_read_lock <-fsnotify
2397 bash-1994 [002] .... 3082.063032: add_preempt_count <-__srcu_read_lock
2398 bash-1994 [002] ...1 3082.063032: sub_preempt_count <-__srcu_read_lock
2399 bash-1994 [002] .... 3082.063033: __srcu_read_unlock <-fsnotify
2427 ---------------------
2441 # TASK-PID CPU# TIMESTAMP FUNCTION
2443 yum-updatesd-3111 [003] 1637.254676: finish_task_switch <-thread_return
2444 yum-updatesd-3111 [003] 1637.254681: hrtimer_cancel <-schedule_hrtimeout_range
2445 yum-updatesd-3111 [003] 1637.254682: hrtimer_try_to_cancel <-hrtimer_cancel
2446 yum-updatesd-3111 [003] 1637.254683: lock_hrtimer_base <-hrtimer_try_to_cancel
2447 yum-updatesd-3111 [003] 1637.254685: fget_light <-do_sys_poll
2448 yum-updatesd-3111 [003] 1637.254686: pipe_poll <-do_sys_poll
2453 # TASK-PID CPU# TIMESTAMP FUNCTION
2456 yum-updatesd-3111 [003] 1701.957688: free_poll_entry <-poll_freewait
2457 yum-updatesd-3111 [003] 1701.957689: remove_wait_queue <-free_poll_entry
2458 yum-updatesd-3111 [003] 1701.957691: fput <-free_poll_entry
2459 yum-updatesd-3111 [003] 1701.957692: audit_syscall_exit <-sysret_audit
2460 yum-updatesd-3111 [003] 1701.957693: path_put <-audit_syscall_exit
2523 exit(-1);
2532 exit(-1);
2555 tracefs=`sed -ne 's/^tracefs \(.*\) tracefs.*/\1/p' /proc/mounts`
2564 ---------------------------
2577 - measure of a function's time execution
2578 - having a reliable call stack to draw function calls graph
2582 - you want to find the reason of a strange kernel behavior and
2586 - you are experiencing weird latencies but it's difficult to
2589 - you want to find quickly which path is taken by a specific
2592 - you just want to peek inside a working kernel and want to see
2624 - The cpu number on which the function executed is default
2629 - hide: echo nofuncgraph-cpu > trace_options
2630 - show: echo funcgraph-cpu > trace_options
2632 - The duration (function's time of execution) is displayed on
2637 - hide: echo nofuncgraph-duration > trace_options
2638 - show: echo funcgraph-duration > trace_options
2640 - The overhead field precedes the duration field in case of
2643 - hide: echo nofuncgraph-overhead > trace_options
2644 - show: echo funcgraph-overhead > trace_options
2645 - depends on: funcgraph-duration
2697 - The task/pid field displays the thread cmdline and pid which
2700 - hide: echo nofuncgraph-proc > trace_options
2701 - show: echo funcgraph-proc > trace_options
2709 0) sh-4802 | | d_free() {
2710 0) sh-4802 | | call_rcu() {
2711 0) sh-4802 | | __call_rcu() {
2712 0) sh-4802 | 0.616 us | rcu_process_gp_end();
2713 0) sh-4802 | 0.586 us | check_for_new_grace_period();
2714 0) sh-4802 | 2.899 us | }
2715 0) sh-4802 | 4.040 us | }
2716 0) sh-4802 | 5.151 us | }
2717 0) sh-4802 | + 49.370 us | }
2720 - The absolute time field is an absolute timestamp given by the
2724 - hide: echo nofuncgraph-abstime > trace_options
2725 - show: echo funcgraph-abstime > trace_options
2756 - hide: echo nofuncgraph-tail > trace_options
2757 - show: echo funcgraph-tail > trace_options
2759 Example with nofuncgraph-tail (default)::
2767 Example with funcgraph-tail::
2780 - hide: echo nofuncgraph-retval > trace_options
2781 - show: echo funcgraph-retval > trace_options
2783 Example with funcgraph-retval::
2793 1) 2.335 us | } /* cpu_cgroup_can_attach = -22 */
2794 1) 4.369 us | } /* cgroup_migrate_execute = -22 */
2795 1) 7.143 us | } /* cgroup_migrate = -22 */
2798 returned the error code -22 firstly, then we can read the code
2801 When the option funcgraph-retval-hex is not set, the return value can
2806 - smart: echo nofuncgraph-retval-hex > trace_options
2807 - hexadecimal: echo funcgraph-retval-hex > trace_options
2809 Example with funcgraph-retval-hex::
2823 At present, there are some limitations when using the funcgraph-retval
2826 - Even if the function return type is void, a return value will still
2829 - Even if return values are stored in multiple registers, only the
2832 a 64-bit return value, with the lower 32 bits saved in eax and the
2836 - In certain procedure call standards, such as arm64's AAPCS64, when a
2840 when using a u8 in a 64-bit GPR, bits [63:8] may contain arbitrary values,
2857 < ... ftrace instrumentation ... >
2870 return -EINVAL;
2882 MOV x0, #-EINVAL
2891 <linux/ftrace.h> and call trace_printk() inside __might_sleep()::
2903 following "dynamic ftrace" section such as tracing only specific
2906 dynamic ftrace
2907 --------------
2912 every kernel function, produced by the -pg switch in gcc),
2913 starts of pointing to a simple return. (Enabling FTRACE will
2914 include the -pg switch in the compiling of the kernel.)
2920 with gcc version 4.6, the -mfentry has been added for x86, which
2931 The recordmcount program re-links this section back into the
2935 On boot up, before SMP is initialized, the dynamic ftrace code
2940 unloaded, it also removes its functions from the ftrace function
2950 (which is just a function stub). They now call into the ftrace
2957 version to the ftrace call site.
2963 One special side-effect to the recording of the functions being
3003 # entries-in-buffer/entries-written: 5/5 #P:4
3005 # _-----=> irqs-off
3006 # / _----=> need-resched
3007 # | / _---=> hardirq/softirq
3008 # || / _--=> preempt-depth
3010 # TASK-PID CPU# |||| TIMESTAMP FUNCTION
3012 usleep-2665 [001] .... 4186.475355: sys_nanosleep <-system_call_fastpath
3013 <idle>-0 [001] d.h1 4186.475409: hrtimer_interrupt <-smp_apic_timer_interrupt
3014 usleep-2665 [001] d.h1 4186.475426: hrtimer_interrupt <-smp_apic_timer_interrupt
3015 <idle>-0 [003] d.h1 4186.475426: hrtimer_interrupt <-smp_apic_timer_interrupt
3016 <idle>-0 [002] d.h1 4186.475427: hrtimer_interrupt <-smp_apic_timer_interrupt
3050 # entries-in-buffer/entries-written: 897/897 #P:4
3052 # _-----=> irqs-off
3053 # / _----=> need-resched
3054 # | / _---=> hardirq/softirq
3055 # || / _--=> preempt-depth
3057 # TASK-PID CPU# |||| TIMESTAMP FUNCTION
3059 <idle>-0 [003] dN.1 4228.547803: hrtimer_cancel <-tick_nohz_idle_exit
3060 <idle>-0 [003] dN.1 4228.547804: hrtimer_try_to_cancel <-hrtimer_cancel
3061 <idle>-0 [003] dN.2 4228.547805: hrtimer_force_reprogram <-__remove_hrtimer
3062 <idle>-0 [003] dN.1 4228.547805: hrtimer_forward <-tick_nohz_idle_exit
3063 … <idle>-0 [003] dN.1 4228.547805: hrtimer_start_range_ns <-hrtimer_start_expires.constprop.11
3064 <idle>-0 [003] d..1 4228.547858: hrtimer_get_next_event <-get_next_timer_interrupt
3065 <idle>-0 [003] d..1 4228.547859: hrtimer_start <-__tick_nohz_idle_enter
3066 <idle>-0 [003] d..2 4228.547860: hrtimer_force_reprogram <-__rem
3139 # entries-in-buffer/entries-written: 39608/39608 #P:4
3141 # _-----=> irqs-off
3142 # / _----=> need-resched
3143 # | / _---=> hardirq/softirq
3144 # || / _--=> preempt-depth
3146 # TASK-PID CPU# |||| TIMESTAMP FUNCTION
3148 bash-1994 [000] .... 4342.324896: file_ra_state_init <-do_dentry_open
3149 bash-1994 [000] .... 4342.324897: open_check_o_direct <-do_last
3150 bash-1994 [000] .... 4342.324897: ima_file_check <-do_last
3151 bash-1994 [000] .... 4342.324898: process_measurement <-ima_file_check
3152 bash-1994 [000] .... 4342.324898: ima_get_action <-process_measurement
3153 bash-1994 [000] .... 4342.324898: ima_match_policy <-ima_get_action
3154 bash-1994 [000] .... 4342.324899: do_truncate <-do_last
3155 bash-1994 [000] .... 4342.324899: setattr_should_drop_suidgid <-do_truncate
3156 bash-1994 [000] .... 4342.324899: notify_change <-do_truncate
3157 bash-1994 [000] .... 4342.324900: current_fs_time <-notify_change
3158 bash-1994 [000] .... 4342.324900: current_kernel_time <-current_fs_time
3159 bash-1994 [000] .... 4342.324900: timespec_trunc <-current_fs_time
3164 ------------------------------------
3182 # head -1 available_filter_functions
3188 # head -50 available_filter_functions | tail -1
3196 Dynamic ftrace with the function graph tracer
3197 ---------------------------------------------
3200 function tracer and the function-graph-tracer, there are some
3201 special features only available in the function-graph tracer.
3258 --------------
3263 disabled. This includes not only the function tracers for ftrace, but
3282 ---------------
3291 - mod:
3323 - traceon/traceoff:
3347 - snapshot:
3363 - enable_event/disable_event:
3387 - dump:
3388 When the function is hit, it will dump the contents of the ftrace
3394 - cpudump:
3395 When the function is hit, it will dump the contents of the ftrace
3400 - stacktrace:
3404 ----------
3421 # entries-in-buffer/entries-written: 0/0 #P:4
3423 # _-----=> irqs-off
3424 # / _----=> need-resched
3425 # | / _---=> hardirq/softirq
3426 # || / _--=> preempt-depth
3428 # TASK-PID CPU# |||| TIMESTAMP FUNCTION
3433 bash-1994 [000] .... 5281.568961: mutex_unlock <-rb_simple_write
3434 bash-1994 [000] .... 5281.568963: __mutex_unlock_slowpath <-mutex_unlock
3435 bash-1994 [000] .... 5281.568963: __fsnotify_parent <-fsnotify_modify
3436 bash-1994 [000] .... 5281.568964: fsnotify <-fsnotify_modify
3437 bash-1994 [000] .... 5281.568964: __srcu_read_lock <-fsnotify
3438 bash-1994 [000] .... 5281.568964: add_preempt_count <-__srcu_read_lock
3439 bash-1994 [000] ...1 5281.568965: sub_preempt_count <-__srcu_read_lock
3440 bash-1994 [000] .... 5281.568965: __srcu_read_unlock <-fsnotify
3441 bash-1994 [000] .... 5281.568967: sys_dup2 <-system_call_fastpath
3451 -------------
3455 used to modify the size of the internal trace buffers. The
3457 CPU. To know the full size, multiply the number of possible CPUs
3478 much, it can cause Out-Of-Memory to trigger.
3482 -bash: echo: write error: Cannot allocate memory
3509 --------
3517 in time without stopping tracing. Ftrace swaps the current
3537 +--------------+------------+------------+------------+
3541 +--------------+------------+------------+------------+
3543 +--------------+------------+------------+------------+
3553 # entries-in-buffer/entries-written: 71/71 #P:8
3555 # _-----=> irqs-off
3556 # / _----=> need-resched
3557 # | / _---=> hardirq/softirq
3558 # || / _--=> preempt-depth
3560 # TASK-PID CPU# |||| TIMESTAMP FUNCTION
3562 …<idle>-0 [005] d... 2440.603828: sched_switch: prev_comm=swapper/5 prev_pid=0 prev_prio=120 …
3563 …sleep-2242 [005] d... 2440.603846: sched_switch: prev_comm=snapshot-test-2 prev_pid=2242 prev_pr…
3565 …<idle>-0 [002] d... 2440.707230: sched_switch: prev_comm=swapper/2 prev_pid=0 prev_prio=120 p…
3570 # entries-in-buffer/entries-written: 77/77 #P:8
3572 # _-----=> irqs-off
3573 # / _----=> need-resched
3574 # | / _---=> hardirq/softirq
3575 # || / _--=> preempt-depth
3577 # TASK-PID CPU# |||| TIMESTAMP FUNCTION
3579 …<idle>-0 [007] d... 2440.707395: sched_switch: prev_comm=swapper/7 prev_pid=0 prev_prio=120 p…
3580 …snapshot-test-2-2229 [002] d... 2440.707438: sched_switch: prev_comm=snapshot-test-2 prev_pid=22…
3596 ---------
3642 bash-2044 [002] .... 10594.481032: _raw_spin_lock_irqsave <-get_page_from_freelist
3643 bash-2044 [002] d... 10594.481032: add_preempt_count <-_raw_spin_lock_irqsave
3644 bash-2044 [002] d..1 10594.481032: __rmqueue <-get_page_from_freelist
3645 bash-2044 [002] d..1 10594.481033: _raw_spin_unlock <-get_page_from_freelist
3646 bash-2044 [002] d..1 10594.481033: sub_preempt_count <-_raw_spin_unlock
3647 … bash-2044 [002] d... 10594.481033: get_pageblock_flags_group <-get_pageblock_migratetype
3648 bash-2044 [002] d... 10594.481034: __mod_zone_page_state <-get_page_from_freelist
3649 bash-2044 [002] d... 10594.481034: zone_statistics <-get_page_from_freelist
3650 bash-2044 [002] d... 10594.481034: __inc_zone_state <-zone_statistics
3651 bash-2044 [002] d... 10594.481034: __inc_zone_state <-zone_statistics
3652 bash-2044 [002] .... 10594.481035: arch_dup_task_struct <-copy_process
3656 …bash-1998 [000] d..4 136.676759: sched_wakeup: comm=kworker/0:1 pid=59 prio=120 success=1 targe…
3657 …bash-1998 [000] dN.4 136.676760: sched_wakeup: comm=bash pid=1998 prio=120 success=1 target_cpu…
3658 …<idle>-0 [003] d.h3 136.676906: sched_wakeup: comm=rcu_preempt pid=9 prio=120 success=1 targ…
3659 …<idle>-0 [003] d..3 136.676909: sched_switch: prev_comm=swapper/3 prev_pid=0 prev_prio=120 p…
3660 …rcu_preempt-9 [003] d..3 136.676916: sched_switch: prev_comm=rcu_preempt prev_pid=9 prev_pri…
3661 …bash-1998 [000] d..4 136.677014: sched_wakeup: comm=kworker/0:1 pid=59 prio=120 success=1 targe…
3662 …bash-1998 [000] dN.4 136.677016: sched_wakeup: comm=bash pid=1998 prio=120 success=1 target_cpu…
3663 …bash-1998 [000] d..3 136.677018: sched_switch: prev_comm=bash prev_pid=1998 prev_prio=120 prev_…
3664 …kworker/0:1-59 [000] d..4 136.677022: sched_wakeup: comm=sshd pid=1995 prio=120 success=1 tar…
3665 …kworker/0:1-59 [000] d..3 136.677025: sched_switch: prev_comm=kworker/0:1 prev_pid=59 prev_pr…
3669 migration/1-14 [001] d.h3 138.732674: softirq_raise: vec=3 [action=NET_RX]
3670 <idle>-0 [001] dNh3 138.732725: softirq_raise: vec=3 [action=NET_RX]
3671 bash-1998 [000] d.h1 138.733101: softirq_raise: vec=1 [action=TIMER]
3672 bash-1998 [000] d.h1 138.733102: softirq_raise: vec=9 [action=RCU]
3673 bash-1998 [000] ..s2 138.733105: softirq_entry: vec=1 [action=TIMER]
3674 bash-1998 [000] ..s2 138.733106: softirq_exit: vec=1 [action=TIMER]
3675 bash-1998 [000] ..s2 138.733106: softirq_entry: vec=9 [action=RCU]
3676 bash-1998 [000] ..s2 138.733109: softirq_exit: vec=9 [action=RCU]
3677 sshd-1995 [001] d.h1 138.733278: irq_handler_entry: irq=21 name=uhci_hcd:usb4
3678 sshd-1995 [001] d.h1 138.733280: irq_handler_exit: irq=21 ret=unhandled
3679 sshd-1995 [001] d.h1 138.733281: irq_handler_entry: irq=21 name=eth0
3680 sshd-1995 [001] d.h1 138.733283: irq_handler_exit: irq=21 ret=handled
3686 # entries-in-buffer/entries-written: 18996/18996 #P:4
3688 # _-----=> irqs-off
3689 # / _----=> need-resched
3690 # | / _---=> hardirq/softirq
3691 # || / _--=> preempt-depth
3693 # TASK-PID CPU# |||| TIMESTAMP FUNCTION
3695 bash-1998 [000] d... 140.733501: sys_write -> 0x2
3696 bash-1998 [000] d... 140.733504: sys_dup2(oldfd: a, newfd: 1)
3697 bash-1998 [000] d... 140.733506: sys_dup2 -> 0x1
3698 bash-1998 [000] d... 140.733508: sys_fcntl(fd: a, cmd: 1, arg: 0)
3699 bash-1998 [000] d... 140.733509: sys_fcntl -> 0x1
3700 bash-1998 [000] d... 140.733510: sys_close(fd: a)
3701 bash-1998 [000] d... 140.733510: sys_close -> 0x0
3702 …bash-1998 [000] d... 140.733514: sys_rt_sigprocmask(how: 0, nset: 0, oset: 6e2768, sigsetsize: …
3703 bash-1998 [000] d... 140.733515: sys_rt_sigprocmask -> 0x0
3704 …bash-1998 [000] d... 140.733516: sys_rt_sigaction(sig: 2, act: 7fff718846f0, oact: 7fff71884650…
3705 bash-1998 [000] d... 140.733516: sys_rt_sigaction -> 0x0
3723 -----------
3732 at every function call that will become very useful. As ftrace provides
3733 a function tracer, it makes it convenient to check the stack size
3736 CONFIG_STACK_TRACER enables the ftrace stack tracing functionality.
3743 the stack size of the kernel during boot up, by adding "stacktrace"
3753 Depth Size Location (18 entries)
3754 ----- ---- --------
3774 Note, if -mfentry is being used by gcc, functions get traced before
3776 are not tested by the stack tracer when -mfentry is used.
3778 Currently, -mfentry is used by gcc 4.6.0 and above on x86 only.
3781 ----