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.
1038 need-resched:
1039 - 'N' both TIF_NEED_RESCHED and PREEMPT_NEED_RESCHED is set,
1040 - 'n' only TIF_NEED_RESCHED is set,
1041 - 'p' only PREEMPT_NEED_RESCHED is set,
1042 - '.' otherwise.
1045 - 'Z' - NMI occurred inside a hardirq
1046 - 'z' - NMI is running
1047 - 'H' - hard irq occurred inside a softirq.
1048 - 'h' - hard irq is running
1049 - 's' - soft irq is running
1050 - '.' - normal context.
1052 preempt-depth: The level of preempt_disabled
1057 When the latency-format option is enabled, the trace file
1059 trace. This differs from the output when latency-format
1068 - '$' - greater than 1 second
1069 - '@' - greater than 100 millisecond
1070 - '*' - greater than 10 millisecond
1071 - '#' - greater than 1000 microsecond
1072 - '!' - greater than 100 microsecond
1073 - '+' - greater than 10 microsecond
1074 - ' ' - less than or equal to 10 microsecond.
1082 -------------
1089 print-parent
1090 nosym-offset
1091 nosym-addr
1101 nosym-userobj
1102 noprintk-msg-only
1103 context-info
1104 nolatency-format
1105 record-cmd
1106 norecord-tgid
1109 irq-info
1111 noevent-fork
1112 function-trace
1113 nofunction-fork
1114 nodisplay-graph
1121 echo noprint-parent > trace_options
1125 echo sym-offset > trace_options
1129 print-parent
1134 print-parent:
1135 bash-4000 [01] 1477.606694: simple_strtoul <-kstrtoul
1137 noprint-parent:
1138 bash-4000 [01] 1477.606694: simple_strtoul
1141 sym-offset
1148 sym-offset:
1149 bash-4000 [01] 1477.606694: simple_strtoul+0x6/0xa0
1151 sym-addr
1156 sym-addr:
1157 bash-4000 [01] 1477.606694: simple_strtoul <c0339346>
1161 latency-format option is enabled.
1199 <idle>-0 [001] dNs4 21169.031481: wake_up_idle_cpu <-add_timer_on
1200 <idle>-0 [001] dNs4 21169.031482: _raw_spin_unlock_irqrestore <-add_timer_on
1201 <idle>-0 [001] .Ns4 21169.031484: sub_preempt_count <-_raw_spin_unlock_irqrestore
1203 <idle>-0 [002] .N.1 21169.031484: rcu_idle_exit <-cpu_idle
1204 <idle>-0 [001] .Ns3 21169.031484: _raw_spin_unlock <-clocksource_watchdog
1205 <idle>-0 [001] .Ns3 21169.031485: sub_preempt_count <-_raw_spin_unlock
1212 sym-userobj
1223 a.out-1623 [000] 40874.465068: /root/a.out[+0x480] <-/root/a.out[+0
1224 x494] <- /root/a.out[+0x4a8] <- /lib/libc-2.7.so[+0x1e1a6]
1227 printk-msg-only
1232 context-info
1236 latency-format
1241 pause-on-trace
1247 hash-ptr
1253 record-cmd
1261 record-tgid
1278 irq-info
1284 # entries-in-buffer/entries-written: 144405/9452052 #P:4
1286 # TASK-PID CPU# TIMESTAMP FUNCTION
1288 <idle>-0 [002] 23636.756054: ttwu_do_activate.constprop.89 <-try_to_wake_up
1289 <idle>-0 [002] 23636.756054: activate_task <-ttwu_do_activate.constprop.89
1290 <idle>-0 [002] 23636.756055: enqueue_task <-activate_task
1298 event-fork
1306 function-trace
1313 function-fork
1322 display-graph
1358 funcgraph-overrun
1369 funcgraph-cpu
1373 funcgraph-overhead
1379 funcgraph-proc
1386 funcgraph-duration
1391 funcgraph-abstime
1394 funcgraph-irqs
1398 funcgraph-tail
1404 funcgraph-retval
1409 funcgraph-retval-hex
1417 sleep-time
1423 graph-time
1437 -------
1454 # echo 0 > options/function-trace
1458 # ls -ltr
1464 # irqsoff latency trace v1.1.5 on 3.8.0-test+
1465 # --------------------------------------------------------------------
1467 # -----------------
1468 # | task: swapper/0-0 (uid:0 nice:0 policy:0 rt_prio:0)
1469 # -----------------
1474 # _------=> CPU#
1475 # / _-----=> irqs-off
1476 # | / _----=> need-resched
1477 # || / _---=> hardirq/softirq
1478 # ||| / _--=> preempt-depth
1482 <idle>-0 0d.s2 0us+: _raw_spin_lock_irq <-run_timer_softirq
1483 <idle>-0 0dNs3 17us : _raw_spin_unlock_irq <-run_timer_softirq
1484 <idle>-0 0dNs3 17us+: trace_hardirqs_on <-run_timer_softirq
1485 <idle>-0 0dNs3 25us : <stack trace>
1508 Note the above example had function-trace not set. If we set
1509 function-trace, we get a much larger output::
1511 with echo 1 > options/function-trace
1515 # irqsoff latency trace v1.1.5 on 3.8.0-test+
1516 # --------------------------------------------------------------------
1518 # -----------------
1519 # | task: bash-2042 (uid:0 nice:0 policy:0 rt_prio:0)
1520 # -----------------
1525 # _------=> CPU#
1526 # / _-----=> irqs-off
1527 # | / _----=> need-resched
1528 # || / _---=> hardirq/softirq
1529 # ||| / _--=> preempt-depth
1533 bash-2042 3d... 0us : _raw_spin_lock_irqsave <-ata_scsi_queuecmd
1534 bash-2042 3d... 0us : add_preempt_count <-_raw_spin_lock_irqsave
1535 bash-2042 3d..1 1us : ata_scsi_find_dev <-ata_scsi_queuecmd
1536 bash-2042 3d..1 1us : __ata_scsi_find_dev <-ata_scsi_find_dev
1537 bash-2042 3d..1 2us : ata_find_dev.part.14 <-__ata_scsi_find_dev
1538 bash-2042 3d..1 2us : ata_qc_new_init <-__ata_scsi_queuecmd
1539 bash-2042 3d..1 3us : ata_sg_init <-__ata_scsi_queuecmd
1540 bash-2042 3d..1 4us : ata_scsi_rw_xlat <-__ata_scsi_queuecmd
1541 bash-2042 3d..1 4us : ata_build_rw_tf <-ata_scsi_rw_xlat
1543 bash-2042 3d..1 67us : delay_tsc <-__delay
1544 bash-2042 3d..1 67us : add_preempt_count <-delay_tsc
1545 bash-2042 3d..2 67us : sub_preempt_count <-delay_tsc
1546 bash-2042 3d..1 67us : add_preempt_count <-delay_tsc
1547 bash-2042 3d..2 68us : sub_preempt_count <-delay_tsc
1548 bash-2042 3d..1 68us+: ata_bmdma_start <-ata_bmdma_qc_issue
1549 bash-2042 3d..1 71us : _raw_spin_unlock_irqrestore <-ata_scsi_queuecmd
1550 bash-2042 3d..1 71us : _raw_spin_unlock_irqrestore <-ata_scsi_queuecmd
1551 bash-2042 3d..1 72us+: trace_hardirqs_on <-ata_scsi_queuecmd
1552 bash-2042 3d..1 120us : <stack trace>
1587 display-graph option::
1589 with echo 1 > options/display-graph
1593 # irqsoff latency trace v1.1.5 on 4.20.0-rc6+
1594 # --------------------------------------------------------------------
1596 # -----------------
1597 # | task: bash-1507 (uid:0 nice:0 policy:0 rt_prio:0)
1598 # -----------------
1603 # _-----=> irqs-off
1604 # / _----=> need-resched
1605 # | / _---=> hardirq/softirq
1606 # || / _--=> preempt-depth
1610 0 us | 0) bash-1507 | d... | 0.000 us | _raw_spin_lock_irqsave();
1611 0 us | 0) bash-1507 | d..1 | 0.378 us | do_raw_spin_trylock();
1612 1 us | 0) bash-1507 | d..2 | | set_track() {
1613 2 us | 0) bash-1507 | d..2 | | save_stack_trace() {
1614 2 us | 0) bash-1507 | d..2 | | __save_stack_trace() {
1615 3 us | 0) bash-1507 | d..2 | | __unwind_start() {
1616 3 us | 0) bash-1507 | d..2 | | get_stack_info() {
1617 3 us | 0) bash-1507 | d..2 | 0.351 us | in_task_stack();
1618 4 us | 0) bash-1507 | d..2 | 1.107 us | }
1620 3750 us | 0) bash-1507 | d..1 | 0.516 us | do_raw_spin_unlock();
1621 3750 us | 0) bash-1507 | d..1 | 0.000 us | _raw_spin_unlock_irqrestore();
1622 3764 us | 0) bash-1507 | d..1 | 0.000 us | tracer_hardirqs_on();
1623 bash-1507 0d..1 3792us : <stack trace>
1640 ----------
1653 # echo 0 > options/function-trace
1657 # ls -ltr
1663 # preemptoff latency trace v1.1.5 on 3.8.0-test+
1664 # --------------------------------------------------------------------
1666 # -----------------
1667 # | task: sshd-1991 (uid:0 nice:0 policy:0 rt_prio:0)
1668 # -----------------
1673 # _------=> CPU#
1674 # / _-----=> irqs-off
1675 # | / _----=> need-resched
1676 # || / _---=> hardirq/softirq
1677 # ||| / _--=> preempt-depth
1681 sshd-1991 1d.h. 0us+: irq_enter <-do_IRQ
1682 sshd-1991 1d..1 46us : irq_exit <-do_IRQ
1683 sshd-1991 1d..1 47us+: trace_preempt_on <-do_IRQ
1684 sshd-1991 1d..1 52us : <stack trace>
1701 # preemptoff latency trace v1.1.5 on 3.8.0-test+
1702 # --------------------------------------------------------------------
1704 # -----------------
1705 # | task: bash-1994 (uid:0 nice:0 policy:0 rt_prio:0)
1706 # -----------------
1711 # _------=> CPU#
1712 # / _-----=> irqs-off
1713 # | / _----=> need-resched
1714 # || / _---=> hardirq/softirq
1715 # ||| / _--=> preempt-depth
1719 bash-1994 1d..1 0us : _raw_spin_lock_irqsave <-wake_up_new_task
1720 bash-1994 1d..1 0us : select_task_rq_fair <-select_task_rq
1721 bash-1994 1d..1 1us : __rcu_read_lock <-select_task_rq_fair
1722 bash-1994 1d..1 1us : source_load <-select_task_rq_fair
1723 bash-1994 1d..1 1us : source_load <-select_task_rq_fair
1725 bash-1994 1d..1 12us : irq_enter <-smp_apic_timer_interrupt
1726 bash-1994 1d..1 12us : rcu_irq_enter <-irq_enter
1727 bash-1994 1d..1 13us : add_preempt_count <-irq_enter
1728 bash-1994 1d.h1 13us : exit_idle <-smp_apic_timer_interrupt
1729 bash-1994 1d.h1 13us : hrtimer_interrupt <-smp_apic_timer_interrupt
1730 bash-1994 1d.h1 13us : _raw_spin_lock <-hrtimer_interrupt
1731 bash-1994 1d.h1 14us : add_preempt_count <-_raw_spin_lock
1732 bash-1994 1d.h2 14us : ktime_get_update_offsets <-hrtimer_interrupt
1734 bash-1994 1d.h1 35us : lapic_next_event <-clockevents_program_event
1735 bash-1994 1d.h1 35us : irq_exit <-smp_apic_timer_interrupt
1736 bash-1994 1d.h1 36us : sub_preempt_count <-irq_exit
1737 bash-1994 1d..2 36us : do_softirq <-irq_exit
1738 bash-1994 1d..2 36us : __do_softirq <-call_softirq
1739 bash-1994 1d..2 36us : __local_bh_disable <-__do_softirq
1740 bash-1994 1d.s2 37us : add_preempt_count <-_raw_spin_lock_irq
1741 bash-1994 1d.s3 38us : _raw_spin_unlock <-run_timer_softirq
1742 bash-1994 1d.s3 39us : sub_preempt_count <-_raw_spin_unlock
1743 bash-1994 1d.s2 39us : call_timer_fn <-run_timer_softirq
1745 bash-1994 1dNs2 81us : cpu_needs_another_gp <-rcu_process_callbacks
1746 bash-1994 1dNs2 82us : __local_bh_enable <-__do_softirq
1747 bash-1994 1dNs2 82us : sub_preempt_count <-__local_bh_enable
1748 bash-1994 1dN.2 82us : idle_cpu <-irq_exit
1749 bash-1994 1dN.2 83us : rcu_irq_exit <-irq_exit
1750 bash-1994 1dN.2 83us : sub_preempt_count <-irq_exit
1751 bash-1994 1.N.1 84us : _raw_spin_unlock_irqrestore <-task_rq_unlock
1752 bash-1994 1.N.1 84us+: trace_preempt_on <-task_rq_unlock
1753 bash-1994 1.N.1 104us : <stack trace>
1764 function-trace set. Here we see that interrupts were not disabled
1771 --------------
1805 # echo 0 > options/function-trace
1809 # ls -ltr
1815 # preemptirqsoff latency trace v1.1.5 on 3.8.0-test+
1816 # --------------------------------------------------------------------
1818 # -----------------
1819 # | task: ls-2230 (uid:0 nice:0 policy:0 rt_prio:0)
1820 # -----------------
1825 # _------=> CPU#
1826 # / _-----=> irqs-off
1827 # | / _----=> need-resched
1828 # || / _---=> hardirq/softirq
1829 # ||| / _--=> preempt-depth
1833 ls-2230 3d... 0us+: _raw_spin_lock_irqsave <-ata_scsi_queuecmd
1834 ls-2230 3...1 100us : _raw_spin_unlock_irqrestore <-ata_scsi_queuecmd
1835 ls-2230 3...1 101us+: trace_preempt_on <-ata_scsi_queuecmd
1836 ls-2230 3...1 111us : <stack trace>
1864 Here is a trace with function-trace set::
1868 # preemptirqsoff latency trace v1.1.5 on 3.8.0-test+
1869 # --------------------------------------------------------------------
1871 # -----------------
1872 # | task: ls-2269 (uid:0 nice:0 policy:0 rt_prio:0)
1873 # -----------------
1878 # _------=> CPU#
1879 # / _-----=> irqs-off
1880 # | / _----=> need-resched
1881 # || / _---=> hardirq/softirq
1882 # ||| / _--=> preempt-depth
1886 kworker/-59 3...1 0us : __schedule <-schedule
1887 kworker/-59 3d..1 0us : rcu_preempt_qs <-rcu_note_context_switch
1888 kworker/-59 3d..1 1us : add_preempt_count <-_raw_spin_lock_irq
1889 kworker/-59 3d..2 1us : deactivate_task <-__schedule
1890 kworker/-59 3d..2 1us : dequeue_task <-deactivate_task
1891 kworker/-59 3d..2 2us : update_rq_clock <-dequeue_task
1892 kworker/-59 3d..2 2us : dequeue_task_fair <-dequeue_task
1893 kworker/-59 3d..2 2us : update_curr <-dequeue_task_fair
1894 kworker/-59 3d..2 2us : update_min_vruntime <-update_curr
1895 kworker/-59 3d..2 3us : cpuacct_charge <-update_curr
1896 kworker/-59 3d..2 3us : __rcu_read_lock <-cpuacct_charge
1897 kworker/-59 3d..2 3us : __rcu_read_unlock <-cpuacct_charge
1898 kworker/-59 3d..2 3us : update_cfs_rq_blocked_load <-dequeue_task_fair
1899 kworker/-59 3d..2 4us : clear_buddies <-dequeue_task_fair
1900 kworker/-59 3d..2 4us : account_entity_dequeue <-dequeue_task_fair
1901 kworker/-59 3d..2 4us : update_min_vruntime <-dequeue_task_fair
1902 kworker/-59 3d..2 4us : update_cfs_shares <-dequeue_task_fair
1903 kworker/-59 3d..2 5us : hrtick_update <-dequeue_task_fair
1904 kworker/-59 3d..2 5us : wq_worker_sleeping <-__schedule
1905 kworker/-59 3d..2 5us : kthread_data <-wq_worker_sleeping
1906 kworker/-59 3d..2 5us : put_prev_task_fair <-__schedule
1907 kworker/-59 3d..2 6us : pick_next_task_fair <-pick_next_task
1908 kworker/-59 3d..2 6us : clear_buddies <-pick_next_task_fair
1909 kworker/-59 3d..2 6us : set_next_entity <-pick_next_task_fair
1910 kworker/-59 3d..2 6us : update_stats_wait_end <-set_next_entity
1911 ls-2269 3d..2 7us : finish_task_switch <-__schedule
1912 ls-2269 3d..2 7us : _raw_spin_unlock_irq <-finish_task_switch
1913 ls-2269 3d..2 8us : do_IRQ <-ret_from_intr
1914 ls-2269 3d..2 8us : irq_enter <-do_IRQ
1915 ls-2269 3d..2 8us : rcu_irq_enter <-irq_enter
1916 ls-2269 3d..2 9us : add_preempt_count <-irq_enter
1917 ls-2269 3d.h2 9us : exit_idle <-do_IRQ
1919 ls-2269 3d.h3 20us : sub_preempt_count <-_raw_spin_unlock
1920 ls-2269 3d.h2 20us : irq_exit <-do_IRQ
1921 ls-2269 3d.h2 21us : sub_preempt_count <-irq_exit
1922 ls-2269 3d..3 21us : do_softirq <-irq_exit
1923 ls-2269 3d..3 21us : __do_softirq <-call_softirq
1924 ls-2269 3d..3 21us+: __local_bh_disable <-__do_softirq
1925 ls-2269 3d.s4 29us : sub_preempt_count <-_local_bh_enable_ip
1926 ls-2269 3d.s5 29us : sub_preempt_count <-_local_bh_enable_ip
1927 ls-2269 3d.s5 31us : do_IRQ <-ret_from_intr
1928 ls-2269 3d.s5 31us : irq_enter <-do_IRQ
1929 ls-2269 3d.s5 31us : rcu_irq_enter <-irq_enter
1931 ls-2269 3d.s5 31us : rcu_irq_enter <-irq_enter
1932 ls-2269 3d.s5 32us : add_preempt_count <-irq_enter
1933 ls-2269 3d.H5 32us : exit_idle <-do_IRQ
1934 ls-2269 3d.H5 32us : handle_irq <-do_IRQ
1935 ls-2269 3d.H5 32us : irq_to_desc <-handle_irq
1936 ls-2269 3d.H5 33us : handle_fasteoi_irq <-handle_irq
1938 ls-2269 3d.s5 158us : _raw_spin_unlock_irqrestore <-rtl8139_poll
1939 ls-2269 3d.s3 158us : net_rps_action_and_irq_enable.isra.65 <-net_rx_action
1940 ls-2269 3d.s3 159us : __local_bh_enable <-__do_softirq
1941 ls-2269 3d.s3 159us : sub_preempt_count <-__local_bh_enable
1942 ls-2269 3d..3 159us : idle_cpu <-irq_exit
1943 ls-2269 3d..3 159us : rcu_irq_exit <-irq_exit
1944 ls-2269 3d..3 160us : sub_preempt_count <-irq_exit
1945 ls-2269 3d... 161us : __mutex_unlock_slowpath <-mutex_unlock
1946 ls-2269 3d... 162us+: trace_hardirqs_on <-mutex_unlock
1947 ls-2269 3d... 186us : <stack trace>
1966 ------
1970 Now for non Real-Time tasks, this can be arbitrary. But tracing
1975 # echo 0 > options/function-trace
1979 # chrt -f 5 sleep 1
1984 # wakeup latency trace v1.1.5 on 3.8.0-test+
1985 # --------------------------------------------------------------------
1987 # -----------------
1988 # | task: kworker/3:1H-312 (uid:0 nice:-20 policy:0 rt_prio:0)
1989 # -----------------
1991 # _------=> CPU#
1992 # / _-----=> irqs-off
1993 # | / _----=> need-resched
1994 # || / _---=> hardirq/softirq
1995 # ||| / _--=> preempt-depth
1999 <idle>-0 3dNs7 0us : 0:120:R + [003] 312:100:R kworker/3:1H
2000 <idle>-0 3dNs7 1us+: ttwu_do_activate.constprop.87 <-try_to_wake_up
2001 <idle>-0 3d..3 15us : __schedule <-schedule
2002 <idle>-0 3d..3 15us : 0:120:R ==> [003] 312:100:R kworker/3:1H
2006 the kworker with a nice priority of -20 (not very nice), took
2010 Non Real-Time tasks are not that interesting. A more interesting
2011 trace is to concentrate only on Real-Time tasks.
2014 ---------
2016 In a Real-Time environment it is very important to know the
2020 also important to know the scheduling latency of non-RT tasks,
2021 but the average schedule latency is better for non-RT tasks.
2025 Real-Time environments are interested in the worst case latency.
2029 work well with Real-Time tasks. The wakeup_rt tracer was designed
2030 to record the worst case wakeups of RT tasks. Non-RT tasks are
2032 tracing non-RT tasks that are unpredictable will overwrite the
2042 # echo 0 > options/function-trace
2046 # chrt -f 5 sleep 1
2053 # wakeup_rt latency trace v1.1.5 on 3.8.0-test+
2054 # --------------------------------------------------------------------
2056 # -----------------
2057 # | task: sleep-2389 (uid:0 nice:0 policy:1 rt_prio:5)
2058 # -----------------
2060 # _------=> CPU#
2061 # / _-----=> irqs-off
2062 # | / _----=> need-resched
2063 # || / _---=> hardirq/softirq
2064 # ||| / _--=> preempt-depth
2068 <idle>-0 3d.h4 0us : 0:120:R + [003] 2389: 94:R sleep
2069 <idle>-0 3d.h4 1us+: ttwu_do_activate.constprop.87 <-try_to_wake_up
2070 <idle>-0 3d..3 5us : __schedule <-schedule
2071 <idle>-0 3d..3 5us : 0:120:R ==> [003] 2389: 94:R sleep
2081 and it has an rt_prio of 5. This priority is user-space priority
2085 Note, that the trace data shows the internal priority (99 - rtprio).
2088 <idle>-0 3d..3 5us : 0:120:R ==> [003] 2389: 94:R sleep
2090 The 0:120:R means idle was running with a nice priority of 0 (120 - 120)
2092 2389: 94:R. That is the priority is the kernel rtprio (99 - 5 = 94)
2095 Doing the same with chrt -r 5 and function-trace set.
2098 echo 1 > options/function-trace
2102 # wakeup_rt latency trace v1.1.5 on 3.8.0-test+
2103 # --------------------------------------------------------------------
2105 # -----------------
2106 # | task: sleep-2448 (uid:0 nice:0 policy:1 rt_prio:5)
2107 # -----------------
2109 # _------=> CPU#
2110 # / _-----=> irqs-off
2111 # | / _----=> need-resched
2112 # || / _---=> hardirq/softirq
2113 # ||| / _--=> preempt-depth
2117 <idle>-0 3d.h4 1us+: 0:120:R + [003] 2448: 94:R sleep
2118 <idle>-0 3d.h4 2us : ttwu_do_activate.constprop.87 <-try_to_wake_up
2119 <idle>-0 3d.h3 3us : check_preempt_curr <-ttwu_do_wakeup
2120 <idle>-0 3d.h3 3us : resched_curr <-check_preempt_curr
2121 <idle>-0 3dNh3 4us : task_woken_rt <-ttwu_do_wakeup
2122 <idle>-0 3dNh3 4us : _raw_spin_unlock <-try_to_wake_up
2123 <idle>-0 3dNh3 4us : sub_preempt_count <-_raw_spin_unlock
2124 <idle>-0 3dNh2 5us : ttwu_stat <-try_to_wake_up
2125 <idle>-0 3dNh2 5us : _raw_spin_unlock_irqrestore <-try_to_wake_up
2126 <idle>-0 3dNh2 6us : sub_preempt_count <-_raw_spin_unlock_irqrestore
2127 <idle>-0 3dNh1 6us : _raw_spin_lock <-__run_hrtimer
2128 <idle>-0 3dNh1 6us : add_preempt_count <-_raw_spin_lock
2129 <idle>-0 3dNh2 7us : _raw_spin_unlock <-hrtimer_interrupt
2130 <idle>-0 3dNh2 7us : sub_preempt_count <-_raw_spin_unlock
2131 <idle>-0 3dNh1 7us : tick_program_event <-hrtimer_interrupt
2132 <idle>-0 3dNh1 7us : clockevents_program_event <-tick_program_event
2133 <idle>-0 3dNh1 8us : ktime_get <-clockevents_program_event
2134 <idle>-0 3dNh1 8us : lapic_next_event <-clockevents_program_event
2135 <idle>-0 3dNh1 8us : irq_exit <-smp_apic_timer_interrupt
2136 <idle>-0 3dNh1 9us : sub_preempt_count <-irq_exit
2137 <idle>-0 3dN.2 9us : idle_cpu <-irq_exit
2138 <idle>-0 3dN.2 9us : rcu_irq_exit <-irq_exit
2139 <idle>-0 3dN.2 10us : rcu_eqs_enter_common.isra.45 <-rcu_irq_exit
2140 <idle>-0 3dN.2 10us : sub_preempt_count <-irq_exit
2141 <idle>-0 3.N.1 11us : rcu_idle_exit <-cpu_idle
2142 <idle>-0 3dN.1 11us : rcu_eqs_exit_common.isra.43 <-rcu_idle_exit
2143 <idle>-0 3.N.1 11us : tick_nohz_idle_exit <-cpu_idle
2144 <idle>-0 3dN.1 12us : menu_hrtimer_cancel <-tick_nohz_idle_exit
2145 <idle>-0 3dN.1 12us : ktime_get <-tick_nohz_idle_exit
2146 <idle>-0 3dN.1 12us : tick_do_update_jiffies64 <-tick_nohz_idle_exit
2147 <idle>-0 3dN.1 13us : cpu_load_update_nohz <-tick_nohz_idle_exit
2148 <idle>-0 3dN.1 13us : _raw_spin_lock <-cpu_load_update_nohz
2149 <idle>-0 3dN.1 13us : add_preempt_count <-_raw_spin_lock
2150 <idle>-0 3dN.2 13us : __cpu_load_update <-cpu_load_update_nohz
2151 <idle>-0 3dN.2 14us : sched_avg_update <-__cpu_load_update
2152 <idle>-0 3dN.2 14us : _raw_spin_unlock <-cpu_load_update_nohz
2153 <idle>-0 3dN.2 14us : sub_preempt_count <-_raw_spin_unlock
2154 <idle>-0 3dN.1 15us : calc_load_nohz_stop <-tick_nohz_idle_exit
2155 <idle>-0 3dN.1 15us : touch_softlockup_watchdog <-tick_nohz_idle_exit
2156 <idle>-0 3dN.1 15us : hrtimer_cancel <-tick_nohz_idle_exit
2157 <idle>-0 3dN.1 15us : hrtimer_try_to_cancel <-hrtimer_cancel
2158 <idle>-0 3dN.1 16us : lock_hrtimer_base.isra.18 <-hrtimer_try_to_cancel
2159 <idle>-0 3dN.1 16us : _raw_spin_lock_irqsave <-lock_hrtimer_base.isra.18
2160 <idle>-0 3dN.1 16us : add_preempt_count <-_raw_spin_lock_irqsave
2161 <idle>-0 3dN.2 17us : __remove_hrtimer <-remove_hrtimer.part.16
2162 <idle>-0 3dN.2 17us : hrtimer_force_reprogram <-__remove_hrtimer
2163 <idle>-0 3dN.2 17us : tick_program_event <-hrtimer_force_reprogram
2164 <idle>-0 3dN.2 18us : clockevents_program_event <-tick_program_event
2165 <idle>-0 3dN.2 18us : ktime_get <-clockevents_program_event
2166 <idle>-0 3dN.2 18us : lapic_next_event <-clockevents_program_event
2167 <idle>-0 3dN.2 19us : _raw_spin_unlock_irqrestore <-hrtimer_try_to_cancel
2168 <idle>-0 3dN.2 19us : sub_preempt_count <-_raw_spin_unlock_irqrestore
2169 <idle>-0 3dN.1 19us : hrtimer_forward <-tick_nohz_idle_exit
2170 <idle>-0 3dN.1 20us : ktime_add_safe <-hrtimer_forward
2171 <idle>-0 3dN.1 20us : ktime_add_safe <-hrtimer_forward
2172 <idle>-0 3dN.1 20us : hrtimer_start_range_ns <-hrtimer_start_expires.constprop.11
2173 <idle>-0 3dN.1 20us : __hrtimer_start_range_ns <-hrtimer_start_range_ns
2174 <idle>-0 3dN.1 21us : lock_hrtimer_base.isra.18 <-__hrtimer_start_range_ns
2175 <idle>-0 3dN.1 21us : _raw_spin_lock_irqsave <-lock_hrtimer_base.isra.18
2176 <idle>-0 3dN.1 21us : add_preempt_count <-_raw_spin_lock_irqsave
2177 <idle>-0 3dN.2 22us : ktime_add_safe <-__hrtimer_start_range_ns
2178 <idle>-0 3dN.2 22us : enqueue_hrtimer <-__hrtimer_start_range_ns
2179 <idle>-0 3dN.2 22us : tick_program_event <-__hrtimer_start_range_ns
2180 <idle>-0 3dN.2 23us : clockevents_program_event <-tick_program_event
2181 <idle>-0 3dN.2 23us : ktime_get <-clockevents_program_event
2182 <idle>-0 3dN.2 23us : lapic_next_event <-clockevents_program_event
2183 <idle>-0 3dN.2 24us : _raw_spin_unlock_irqrestore <-__hrtimer_start_range_ns
2184 <idle>-0 3dN.2 24us : sub_preempt_count <-_raw_spin_unlock_irqrestore
2185 <idle>-0 3dN.1 24us : account_idle_ticks <-tick_nohz_idle_exit
2186 <idle>-0 3dN.1 24us : account_idle_time <-account_idle_ticks
2187 <idle>-0 3.N.1 25us : sub_preempt_count <-cpu_idle
2188 <idle>-0 3.N.. 25us : schedule <-cpu_idle
2189 <idle>-0 3.N.. 25us : __schedule <-preempt_schedule
2190 <idle>-0 3.N.. 26us : add_preempt_count <-__schedule
2191 <idle>-0 3.N.1 26us : rcu_note_context_switch <-__schedule
2192 <idle>-0 3.N.1 26us : rcu_sched_qs <-rcu_note_context_switch
2193 <idle>-0 3dN.1 27us : rcu_preempt_qs <-rcu_note_context_switch
2194 <idle>-0 3.N.1 27us : _raw_spin_lock_irq <-__schedule
2195 <idle>-0 3dN.1 27us : add_preempt_count <-_raw_spin_lock_irq
2196 <idle>-0 3dN.2 28us : put_prev_task_idle <-__schedule
2197 <idle>-0 3dN.2 28us : pick_next_task_stop <-pick_next_task
2198 <idle>-0 3dN.2 28us : pick_next_task_rt <-pick_next_task
2199 <idle>-0 3dN.2 29us : dequeue_pushable_task <-pick_next_task_rt
2200 <idle>-0 3d..3 29us : __schedule <-preempt_schedule
2201 <idle>-0 3d..3 30us : 0:120:R ==> [003] 2448: 94:R sleep
2211 --------------------------
2218 # echo 0 > options/function-trace
2223 # chrt -f 5 sleep 1
2228 # wakeup_rt latency trace v1.1.5 on 3.8.0-test+
2229 # --------------------------------------------------------------------
2231 # -----------------
2232 # | task: sleep-5882 (uid:0 nice:0 policy:1 rt_prio:5)
2233 # -----------------
2235 # _------=> CPU#
2236 # / _-----=> irqs-off
2237 # | / _----=> need-resched
2238 # || / _---=> hardirq/softirq
2239 # ||| / _--=> preempt-depth
2243 <idle>-0 2d.h4 0us : 0:120:R + [002] 5882: 94:R sleep
2244 <idle>-0 2d.h4 0us : ttwu_do_activate.constprop.87 <-try_to_wake_up
2245 <idle>-0 2d.h4 1us : sched_wakeup: comm=sleep pid=5882 prio=94 success=1 target_cpu=002
2246 <idle>-0 2dNh2 1us : hrtimer_expire_exit: hrtimer=ffff88007796feb8
2247 <idle>-0 2.N.2 2us : power_end: cpu_id=2
2248 <idle>-0 2.N.2 3us : cpu_idle: state=4294967295 cpu_id=2
2249 <idle>-0 2dN.3 4us : hrtimer_cancel: hrtimer=ffff88007d50d5e0
2250 …<idle>-0 2dN.3 4us : hrtimer_start: hrtimer=ffff88007d50d5e0 function=tick_sched_timer ex…
2251 <idle>-0 2.N.2 5us : rcu_utilization: Start context switch
2252 <idle>-0 2.N.2 5us : rcu_utilization: End context switch
2253 <idle>-0 2d..3 6us : __schedule <-schedule
2254 <idle>-0 2d..3 6us : 0:120:R ==> [002] 5882: 94:R sleep
2258 -------------------------
2271 # entries-in-buffer/entries-written: 13/13 #P:8
2273 # _-----=> irqs-off
2274 # / _----=> need-resched
2275 # | / _---=> hardirq/softirq
2276 # || / _--=> preempt-depth
2278 # TASK-PID CPU# |||| TIMESTAMP FUNCTION
2280 …<...>-1729 [001] d... 678.473449: #1 inner/outer(us): 11/12 ts:1581527483.343962693 co…
2281 …<...>-1729 [004] d... 689.556542: #2 inner/outer(us): 16/9 ts:1581527494.889008092 co…
2282 …<...>-1729 [005] d... 714.756290: #3 inner/outer(us): 16/16 ts:1581527519.678961629 co…
2283 …<...>-1729 [001] d... 718.788247: #4 inner/outer(us): 9/17 ts:1581527523.889012713 co…
2284 …<...>-1729 [002] d... 719.796341: #5 inner/outer(us): 13/9 ts:1581527524.912872606 co…
2285 …<...>-1729 [006] d... 844.787091: #6 inner/outer(us): 9/12 ts:1581527649.889048502 co…
2286 …<...>-1729 [003] d... 849.827033: #7 inner/outer(us): 18/9 ts:1581527654.889013793 co…
2287 …<...>-1729 [007] d... 853.859002: #8 inner/outer(us): 9/12 ts:1581527658.889065736 co…
2288 …<...>-1729 [001] d... 855.874978: #9 inner/outer(us): 9/11 ts:1581527660.861991877 co…
2289 …<...>-1729 [001] d... 863.938932: #10 inner/outer(us): 9/11 ts:1581527668.970010500 co…
2290 …<...>-1729 [007] d... 878.050780: #11 inner/outer(us): 9/12 ts:1581527683.385002600 co…
2291 …<...>-1729 [007] d... 886.114702: #12 inner/outer(us): 9/12 ts:1581527691.385001600 co…
2317 nmi-total:7 nmi-count:1
2320 test, the time spent in NMI is reported in "nmi-total" (in
2323 All architectures that have NMIs will show the "nmi-count" if an
2354 --------
2370 # entries-in-buffer/entries-written: 24799/24799 #P:4
2372 # _-----=> irqs-off
2373 # / _----=> need-resched
2374 # | / _---=> hardirq/softirq
2375 # || / _--=> preempt-depth
2377 # TASK-PID CPU# |||| TIMESTAMP FUNCTION
2379 bash-1994 [002] .... 3082.063030: mutex_unlock <-rb_simple_write
2380 bash-1994 [002] .... 3082.063031: __mutex_unlock_slowpath <-mutex_unlock
2381 bash-1994 [002] .... 3082.063031: __fsnotify_parent <-fsnotify_modify
2382 bash-1994 [002] .... 3082.063032: fsnotify <-fsnotify_modify
2383 bash-1994 [002] .... 3082.063032: __srcu_read_lock <-fsnotify
2384 bash-1994 [002] .... 3082.063032: add_preempt_count <-__srcu_read_lock
2385 bash-1994 [002] ...1 3082.063032: sub_preempt_count <-__srcu_read_lock
2386 bash-1994 [002] .... 3082.063033: __srcu_read_unlock <-fsnotify
2414 ---------------------
2428 # TASK-PID CPU# TIMESTAMP FUNCTION
2430 yum-updatesd-3111 [003] 1637.254676: finish_task_switch <-thread_return
2431 yum-updatesd-3111 [003] 1637.254681: hrtimer_cancel <-schedule_hrtimeout_range
2432 yum-updatesd-3111 [003] 1637.254682: hrtimer_try_to_cancel <-hrtimer_cancel
2433 yum-updatesd-3111 [003] 1637.254683: lock_hrtimer_base <-hrtimer_try_to_cancel
2434 yum-updatesd-3111 [003] 1637.254685: fget_light <-do_sys_poll
2435 yum-updatesd-3111 [003] 1637.254686: pipe_poll <-do_sys_poll
2440 # TASK-PID CPU# TIMESTAMP FUNCTION
2443 yum-updatesd-3111 [003] 1701.957688: free_poll_entry <-poll_freewait
2444 yum-updatesd-3111 [003] 1701.957689: remove_wait_queue <-free_poll_entry
2445 yum-updatesd-3111 [003] 1701.957691: fput <-free_poll_entry
2446 yum-updatesd-3111 [003] 1701.957692: audit_syscall_exit <-sysret_audit
2447 yum-updatesd-3111 [003] 1701.957693: path_put <-audit_syscall_exit
2510 exit(-1);
2519 exit(-1);
2542 tracefs=`sed -ne 's/^tracefs \(.*\) tracefs.*/\1/p' /proc/mounts`
2551 ---------------------------
2564 - measure of a function's time execution
2565 - having a reliable call stack to draw function calls graph
2569 - you want to find the reason of a strange kernel behavior and
2573 - you are experiencing weird latencies but it's difficult to
2576 - you want to find quickly which path is taken by a specific
2579 - you just want to peek inside a working kernel and want to see
2611 - The cpu number on which the function executed is default
2616 - hide: echo nofuncgraph-cpu > trace_options
2617 - show: echo funcgraph-cpu > trace_options
2619 - The duration (function's time of execution) is displayed on
2624 - hide: echo nofuncgraph-duration > trace_options
2625 - show: echo funcgraph-duration > trace_options
2627 - The overhead field precedes the duration field in case of
2630 - hide: echo nofuncgraph-overhead > trace_options
2631 - show: echo funcgraph-overhead > trace_options
2632 - depends on: funcgraph-duration
2684 - The task/pid field displays the thread cmdline and pid which
2687 - hide: echo nofuncgraph-proc > trace_options
2688 - show: echo funcgraph-proc > trace_options
2696 0) sh-4802 | | d_free() {
2697 0) sh-4802 | | call_rcu() {
2698 0) sh-4802 | | __call_rcu() {
2699 0) sh-4802 | 0.616 us | rcu_process_gp_end();
2700 0) sh-4802 | 0.586 us | check_for_new_grace_period();
2701 0) sh-4802 | 2.899 us | }
2702 0) sh-4802 | 4.040 us | }
2703 0) sh-4802 | 5.151 us | }
2704 0) sh-4802 | + 49.370 us | }
2707 - The absolute time field is an absolute timestamp given by the
2711 - hide: echo nofuncgraph-abstime > trace_options
2712 - show: echo funcgraph-abstime > trace_options
2743 - hide: echo nofuncgraph-tail > trace_options
2744 - show: echo funcgraph-tail > trace_options
2746 Example with nofuncgraph-tail (default)::
2754 Example with funcgraph-tail::
2767 - hide: echo nofuncgraph-retval > trace_options
2768 - show: echo funcgraph-retval > trace_options
2770 Example with funcgraph-retval::
2780 1) 2.335 us | } /* cpu_cgroup_can_attach = -22 */
2781 1) 4.369 us | } /* cgroup_migrate_execute = -22 */
2782 1) 7.143 us | } /* cgroup_migrate = -22 */
2785 returned the error code -22 firstly, then we can read the code
2788 When the option funcgraph-retval-hex is not set, the return value can
2793 - smart: echo nofuncgraph-retval-hex > trace_options
2794 - hexadecimal: echo funcgraph-retval-hex > trace_options
2796 Example with funcgraph-retval-hex::
2810 At present, there are some limitations when using the funcgraph-retval
2813 - Even if the function return type is void, a return value will still
2816 - Even if return values are stored in multiple registers, only the
2819 a 64-bit return value, with the lower 32 bits saved in eax and the
2823 - In certain procedure call standards, such as arm64's AAPCS64, when a
2827 when using a u8 in a 64-bit GPR, bits [63:8] may contain arbitrary values,
2844 < ... ftrace instrumentation ... >
2857 return -EINVAL;
2869 MOV x0, #-EINVAL
2878 <linux/ftrace.h> and call trace_printk() inside __might_sleep()::
2890 following "dynamic ftrace" section such as tracing only specific
2893 dynamic ftrace
2894 --------------
2899 every kernel function, produced by the -pg switch in gcc),
2900 starts of pointing to a simple return. (Enabling FTRACE will
2901 include the -pg switch in the compiling of the kernel.)
2907 with gcc version 4.6, the -mfentry has been added for x86, which
2918 The recordmcount program re-links this section back into the
2922 On boot up, before SMP is initialized, the dynamic ftrace code
2927 unloaded, it also removes its functions from the ftrace function
2937 (which is just a function stub). They now call into the ftrace
2944 version to the ftrace call site.
2950 One special side-effect to the recording of the functions being
2990 # entries-in-buffer/entries-written: 5/5 #P:4
2992 # _-----=> irqs-off
2993 # / _----=> need-resched
2994 # | / _---=> hardirq/softirq
2995 # || / _--=> preempt-depth
2997 # TASK-PID CPU# |||| TIMESTAMP FUNCTION
2999 usleep-2665 [001] .... 4186.475355: sys_nanosleep <-system_call_fastpath
3000 <idle>-0 [001] d.h1 4186.475409: hrtimer_interrupt <-smp_apic_timer_interrupt
3001 usleep-2665 [001] d.h1 4186.475426: hrtimer_interrupt <-smp_apic_timer_interrupt
3002 <idle>-0 [003] d.h1 4186.475426: hrtimer_interrupt <-smp_apic_timer_interrupt
3003 <idle>-0 [002] d.h1 4186.475427: hrtimer_interrupt <-smp_apic_timer_interrupt
3037 # entries-in-buffer/entries-written: 897/897 #P:4
3039 # _-----=> irqs-off
3040 # / _----=> need-resched
3041 # | / _---=> hardirq/softirq
3042 # || / _--=> preempt-depth
3044 # TASK-PID CPU# |||| TIMESTAMP FUNCTION
3046 <idle>-0 [003] dN.1 4228.547803: hrtimer_cancel <-tick_nohz_idle_exit
3047 <idle>-0 [003] dN.1 4228.547804: hrtimer_try_to_cancel <-hrtimer_cancel
3048 <idle>-0 [003] dN.2 4228.547805: hrtimer_force_reprogram <-__remove_hrtimer
3049 <idle>-0 [003] dN.1 4228.547805: hrtimer_forward <-tick_nohz_idle_exit
3050 … <idle>-0 [003] dN.1 4228.547805: hrtimer_start_range_ns <-hrtimer_start_expires.constprop.11
3051 <idle>-0 [003] d..1 4228.547858: hrtimer_get_next_event <-get_next_timer_interrupt
3052 <idle>-0 [003] d..1 4228.547859: hrtimer_start <-__tick_nohz_idle_enter
3053 <idle>-0 [003] d..2 4228.547860: hrtimer_force_reprogram <-__rem
3126 # entries-in-buffer/entries-written: 39608/39608 #P:4
3128 # _-----=> irqs-off
3129 # / _----=> need-resched
3130 # | / _---=> hardirq/softirq
3131 # || / _--=> preempt-depth
3133 # TASK-PID CPU# |||| TIMESTAMP FUNCTION
3135 bash-1994 [000] .... 4342.324896: file_ra_state_init <-do_dentry_open
3136 bash-1994 [000] .... 4342.324897: open_check_o_direct <-do_last
3137 bash-1994 [000] .... 4342.324897: ima_file_check <-do_last
3138 bash-1994 [000] .... 4342.324898: process_measurement <-ima_file_check
3139 bash-1994 [000] .... 4342.324898: ima_get_action <-process_measurement
3140 bash-1994 [000] .... 4342.324898: ima_match_policy <-ima_get_action
3141 bash-1994 [000] .... 4342.324899: do_truncate <-do_last
3142 bash-1994 [000] .... 4342.324899: setattr_should_drop_suidgid <-do_truncate
3143 bash-1994 [000] .... 4342.324899: notify_change <-do_truncate
3144 bash-1994 [000] .... 4342.324900: current_fs_time <-notify_change
3145 bash-1994 [000] .... 4342.324900: current_kernel_time <-current_fs_time
3146 bash-1994 [000] .... 4342.324900: timespec_trunc <-current_fs_time
3151 ------------------------------------
3169 # head -1 available_filter_functions
3175 # head -50 available_filter_functions | tail -1
3183 Dynamic ftrace with the function graph tracer
3184 ---------------------------------------------
3187 function tracer and the function-graph-tracer, there are some
3188 special features only available in the function-graph tracer.
3245 --------------
3250 disabled. This includes not only the function tracers for ftrace, but
3269 ---------------
3278 - mod:
3310 - traceon/traceoff:
3334 - snapshot:
3350 - enable_event/disable_event:
3374 - dump:
3375 When the function is hit, it will dump the contents of the ftrace
3381 - cpudump:
3382 When the function is hit, it will dump the contents of the ftrace
3387 - stacktrace:
3391 ----------
3408 # entries-in-buffer/entries-written: 0/0 #P:4
3410 # _-----=> irqs-off
3411 # / _----=> need-resched
3412 # | / _---=> hardirq/softirq
3413 # || / _--=> preempt-depth
3415 # TASK-PID CPU# |||| TIMESTAMP FUNCTION
3420 bash-1994 [000] .... 5281.568961: mutex_unlock <-rb_simple_write
3421 bash-1994 [000] .... 5281.568963: __mutex_unlock_slowpath <-mutex_unlock
3422 bash-1994 [000] .... 5281.568963: __fsnotify_parent <-fsnotify_modify
3423 bash-1994 [000] .... 5281.568964: fsnotify <-fsnotify_modify
3424 bash-1994 [000] .... 5281.568964: __srcu_read_lock <-fsnotify
3425 bash-1994 [000] .... 5281.568964: add_preempt_count <-__srcu_read_lock
3426 bash-1994 [000] ...1 5281.568965: sub_preempt_count <-__srcu_read_lock
3427 bash-1994 [000] .... 5281.568965: __srcu_read_unlock <-fsnotify
3428 bash-1994 [000] .... 5281.568967: sys_dup2 <-system_call_fastpath
3438 -------------
3442 used to modify the size of the internal trace buffers. The
3444 CPU. To know the full size, multiply the number of possible CPUs
3465 much, it can cause Out-Of-Memory to trigger.
3469 -bash: echo: write error: Cannot allocate memory
3496 --------
3504 in time without stopping tracing. Ftrace swaps the current
3524 +--------------+------------+------------+------------+
3528 +--------------+------------+------------+------------+
3530 +--------------+------------+------------+------------+
3540 # entries-in-buffer/entries-written: 71/71 #P:8
3542 # _-----=> irqs-off
3543 # / _----=> need-resched
3544 # | / _---=> hardirq/softirq
3545 # || / _--=> preempt-depth
3547 # TASK-PID CPU# |||| TIMESTAMP FUNCTION
3549 …<idle>-0 [005] d... 2440.603828: sched_switch: prev_comm=swapper/5 prev_pid=0 prev_prio=120 …
3550 …sleep-2242 [005] d... 2440.603846: sched_switch: prev_comm=snapshot-test-2 prev_pid=2242 prev_pr…
3552 …<idle>-0 [002] d... 2440.707230: sched_switch: prev_comm=swapper/2 prev_pid=0 prev_prio=120 p…
3557 # entries-in-buffer/entries-written: 77/77 #P:8
3559 # _-----=> irqs-off
3560 # / _----=> need-resched
3561 # | / _---=> hardirq/softirq
3562 # || / _--=> preempt-depth
3564 # TASK-PID CPU# |||| TIMESTAMP FUNCTION
3566 …<idle>-0 [007] d... 2440.707395: sched_switch: prev_comm=swapper/7 prev_pid=0 prev_prio=120 p…
3567 …snapshot-test-2-2229 [002] d... 2440.707438: sched_switch: prev_comm=snapshot-test-2 prev_pid=22…
3583 ---------
3629 bash-2044 [002] .... 10594.481032: _raw_spin_lock_irqsave <-get_page_from_freelist
3630 bash-2044 [002] d... 10594.481032: add_preempt_count <-_raw_spin_lock_irqsave
3631 bash-2044 [002] d..1 10594.481032: __rmqueue <-get_page_from_freelist
3632 bash-2044 [002] d..1 10594.481033: _raw_spin_unlock <-get_page_from_freelist
3633 bash-2044 [002] d..1 10594.481033: sub_preempt_count <-_raw_spin_unlock
3634 … bash-2044 [002] d... 10594.481033: get_pageblock_flags_group <-get_pageblock_migratetype
3635 bash-2044 [002] d... 10594.481034: __mod_zone_page_state <-get_page_from_freelist
3636 bash-2044 [002] d... 10594.481034: zone_statistics <-get_page_from_freelist
3637 bash-2044 [002] d... 10594.481034: __inc_zone_state <-zone_statistics
3638 bash-2044 [002] d... 10594.481034: __inc_zone_state <-zone_statistics
3639 bash-2044 [002] .... 10594.481035: arch_dup_task_struct <-copy_process
3643 …bash-1998 [000] d..4 136.676759: sched_wakeup: comm=kworker/0:1 pid=59 prio=120 success=1 targe…
3644 …bash-1998 [000] dN.4 136.676760: sched_wakeup: comm=bash pid=1998 prio=120 success=1 target_cpu…
3645 …<idle>-0 [003] d.h3 136.676906: sched_wakeup: comm=rcu_preempt pid=9 prio=120 success=1 targ…
3646 …<idle>-0 [003] d..3 136.676909: sched_switch: prev_comm=swapper/3 prev_pid=0 prev_prio=120 p…
3647 …rcu_preempt-9 [003] d..3 136.676916: sched_switch: prev_comm=rcu_preempt prev_pid=9 prev_pri…
3648 …bash-1998 [000] d..4 136.677014: sched_wakeup: comm=kworker/0:1 pid=59 prio=120 success=1 targe…
3649 …bash-1998 [000] dN.4 136.677016: sched_wakeup: comm=bash pid=1998 prio=120 success=1 target_cpu…
3650 …bash-1998 [000] d..3 136.677018: sched_switch: prev_comm=bash prev_pid=1998 prev_prio=120 prev_…
3651 …kworker/0:1-59 [000] d..4 136.677022: sched_wakeup: comm=sshd pid=1995 prio=120 success=1 tar…
3652 …kworker/0:1-59 [000] d..3 136.677025: sched_switch: prev_comm=kworker/0:1 prev_pid=59 prev_pr…
3656 migration/1-14 [001] d.h3 138.732674: softirq_raise: vec=3 [action=NET_RX]
3657 <idle>-0 [001] dNh3 138.732725: softirq_raise: vec=3 [action=NET_RX]
3658 bash-1998 [000] d.h1 138.733101: softirq_raise: vec=1 [action=TIMER]
3659 bash-1998 [000] d.h1 138.733102: softirq_raise: vec=9 [action=RCU]
3660 bash-1998 [000] ..s2 138.733105: softirq_entry: vec=1 [action=TIMER]
3661 bash-1998 [000] ..s2 138.733106: softirq_exit: vec=1 [action=TIMER]
3662 bash-1998 [000] ..s2 138.733106: softirq_entry: vec=9 [action=RCU]
3663 bash-1998 [000] ..s2 138.733109: softirq_exit: vec=9 [action=RCU]
3664 sshd-1995 [001] d.h1 138.733278: irq_handler_entry: irq=21 name=uhci_hcd:usb4
3665 sshd-1995 [001] d.h1 138.733280: irq_handler_exit: irq=21 ret=unhandled
3666 sshd-1995 [001] d.h1 138.733281: irq_handler_entry: irq=21 name=eth0
3667 sshd-1995 [001] d.h1 138.733283: irq_handler_exit: irq=21 ret=handled
3673 # entries-in-buffer/entries-written: 18996/18996 #P:4
3675 # _-----=> irqs-off
3676 # / _----=> need-resched
3677 # | / _---=> hardirq/softirq
3678 # || / _--=> preempt-depth
3680 # TASK-PID CPU# |||| TIMESTAMP FUNCTION
3682 bash-1998 [000] d... 140.733501: sys_write -> 0x2
3683 bash-1998 [000] d... 140.733504: sys_dup2(oldfd: a, newfd: 1)
3684 bash-1998 [000] d... 140.733506: sys_dup2 -> 0x1
3685 bash-1998 [000] d... 140.733508: sys_fcntl(fd: a, cmd: 1, arg: 0)
3686 bash-1998 [000] d... 140.733509: sys_fcntl -> 0x1
3687 bash-1998 [000] d... 140.733510: sys_close(fd: a)
3688 bash-1998 [000] d... 140.733510: sys_close -> 0x0
3689 …bash-1998 [000] d... 140.733514: sys_rt_sigprocmask(how: 0, nset: 0, oset: 6e2768, sigsetsize: …
3690 bash-1998 [000] d... 140.733515: sys_rt_sigprocmask -> 0x0
3691 …bash-1998 [000] d... 140.733516: sys_rt_sigaction(sig: 2, act: 7fff718846f0, oact: 7fff71884650…
3692 bash-1998 [000] d... 140.733516: sys_rt_sigaction -> 0x0
3710 -----------
3719 at every function call that will become very useful. As ftrace provides
3720 a function tracer, it makes it convenient to check the stack size
3723 CONFIG_STACK_TRACER enables the ftrace stack tracing functionality.
3730 the stack size of the kernel during boot up, by adding "stacktrace"
3740 Depth Size Location (18 entries)
3741 ----- ---- --------
3761 Note, if -mfentry is being used by gcc, functions get traced before
3763 are not tested by the stack tracer when -mfentry is used.
3765 Currently, -mfentry is used by gcc 4.6.0 and above on x86 only.
3768 ----