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.
186 buffer holds. By default, the trace buffers are the same size
187 for each CPU. The displayed number is the size of the
188 CPU buffer and not total size of all buffers. The
190 that the kernel uses for allocation, usually 4 KB in size).
192 meta-data. If the last page allocated has room for more bytes
195 ( Note, the size may not be a multiple of the page size
196 due to buffer management meta-data. )
204 This displays the total combined size of all the trace buffers.
211 of this file, the ring buffer will be resized to its minimum size.
225 When dynamic ftrace is configured in (see the
226 section below "dynamic ftrace"), the code is dynamically
260 If the "function-fork" option is set, then when a task whose
271 If the "function-fork" option is set, then when a task whose
287 added on fork, enable the "event-fork" option. That option will also
300 added on fork, enable the "event-fork" option. That option will also
308 they call. (See the section "dynamic ftrace" for more details).
321 This lists the functions that ftrace has processed and can trace.
325 (See the section "dynamic ftrace" below for more details.)
330 for each function. The displayed address is the patch-site address
340 This file is more for debugging ftrace, but can also be useful
342 Not only does the trace infrastructure use ftrace function
355 the "ip modify" attribute (thus the regs->ip can be changed),
359 If a non ftrace trampoline is attached (BPF) a 'D' will be displayed.
360 Note, normal ftrace trampolines can also be attached, but only one
364 the ftrace ops function located above the function entry point. In
369 used to know if a function was every modified by the ftrace infrastructure,
384 to it via the ftrace infrastructure. It has the same format as
435 the event specifically saves the task comm as well. Ftrace
440 If the option "record-cmd" is set to "0", then comms of tasks
451 If the option "record-tgid" is set, on each scheduling context switch
453 the thread to its TGID. By default, the "record-tgid" option is
465 maximum stack size it has encountered.
483 clock. By default, ftrace uses the "local" clock. This
492 [local] global counter x86-tsc
515 This makes ftrace use the same clock that perf uses.
516 Eventually perf will be able to read ftrace buffers
519 x86-tsc:
523 ppc-tb:
546 Also on 32-bit systems, it's possible that the 64-bit boot offset
552 This is the tai clock (CLOCK_TAI) and is derived from the wall-
574 this file will be written into the ftrace buffer.
601 that are written into /sys/kernel/tracing/events/ftrace/print/trigger
666 delta: Default timestamp mode - timestamp is a delta against
667 a per-buffer timestamp.
684 The ftrace buffer is defined per_cpu. That is, there's a separate
687 size buffers. This file is similar to the buffer_size_kb
688 file, but it only displays or sets the buffer size for the
705 For tools that can parse the ftrace ring buffer binary format,
741 event (ring buffer is re-entrant), that it fills the
760 -----------
794 trace with the latency-format option enabled, which
848 ----------------
850 For most ftrace commands, failure modes are obvious and communicated
858 error log displaying a small number (currently, 8) of ftrace errors
880 ----------------------------
884 user-land utilities).
887 --------------
893 # entries-in-buffer/entries-written: 140080/250280 #P:4
895 # _-----=> irqs-off
896 # / _----=> need-resched
897 # | / _---=> hardirq/softirq
898 # || / _--=> preempt-depth
900 # TASK-PID CPU# |||| TIMESTAMP FUNCTION
902 bash-1977 [000] .... 17284.993652: sys_close <-system_call_fastpath
903 bash-1977 [000] .... 17284.993653: __close_fd <-sys_close
904 bash-1977 [000] .... 17284.993653: _raw_spin_lock <-__close_fd
905 sshd-1974 [003] .... 17284.993653: __srcu_read_unlock <-fsnotify
906 bash-1977 [000] .... 17284.993654: add_preempt_count <-_raw_spin_lock
907 bash-1977 [000] ...1 17284.993655: _raw_spin_unlock <-__close_fd
908 bash-1977 [000] ...1 17284.993656: sub_preempt_count <-_raw_spin_unlock
909 bash-1977 [000] .... 17284.993657: filp_close <-__close_fd
910 bash-1977 [000] .... 17284.993657: dnotify_flush <-filp_close
911 sshd-1974 [003] .... 17284.993658: sys_select <-system_call_fastpath
918 lost due to the buffer filling up (250280 - 140080 = 110200 events
929 --------------------
931 When the latency-format option is enabled or when one of the latency
937 # irqsoff latency trace v1.1.5 on 3.8.0-test+
938 # --------------------------------------------------------------------
940 # -----------------
941 # | task: ps-6143 (uid:0 nice:0 policy:0 rt_prio:0)
942 # -----------------
947 # _------=> CPU#
948 # / _-----=> irqs-off
949 # | / _----=> need-resched
950 # || / _---=> hardirq/softirq
951 # ||| / _--=> preempt-depth
955 ps-6143 2d... 0us!: trace_hardirqs_off <-__lock_task_sighand
956 ps-6143 2d..1 259us+: trace_hardirqs_on <-_raw_spin_unlock_irqrestore
957 ps-6143 2d..1 263us+: time_hardirqs_on <-_raw_spin_unlock_irqrestore
958 ps-6143 2d..1 306us : <stack trace>
985 - __lock_task_sighand is where the interrupts were disabled.
986 - _raw_spin_unlock_irqrestore is where they were enabled again.
997 irqs-off: 'd' interrupts are disabled. '.' otherwise.
1002 need-resched:
1003 - 'N' both TIF_NEED_RESCHED and PREEMPT_NEED_RESCHED is set,
1004 - 'n' only TIF_NEED_RESCHED is set,
1005 - 'p' only PREEMPT_NEED_RESCHED is set,
1006 - '.' otherwise.
1009 - 'Z' - NMI occurred inside a hardirq
1010 - 'z' - NMI is running
1011 - 'H' - hard irq occurred inside a softirq.
1012 - 'h' - hard irq is running
1013 - 's' - soft irq is running
1014 - '.' - normal context.
1016 preempt-depth: The level of preempt_disabled
1021 When the latency-format option is enabled, the trace file
1023 trace. This differs from the output when latency-format
1032 - '$' - greater than 1 second
1033 - '@' - greater than 100 millisecond
1034 - '*' - greater than 10 millisecond
1035 - '#' - greater than 1000 microsecond
1036 - '!' - greater than 100 microsecond
1037 - '+' - greater than 10 microsecond
1038 - ' ' - less than or equal to 10 microsecond.
1046 -------------
1053 print-parent
1054 nosym-offset
1055 nosym-addr
1065 nosym-userobj
1066 noprintk-msg-only
1067 context-info
1068 nolatency-format
1069 record-cmd
1070 norecord-tgid
1073 irq-info
1075 noevent-fork
1076 function-trace
1077 nofunction-fork
1078 nodisplay-graph
1085 echo noprint-parent > trace_options
1089 echo sym-offset > trace_options
1093 print-parent
1098 print-parent:
1099 bash-4000 [01] 1477.606694: simple_strtoul <-kstrtoul
1101 noprint-parent:
1102 bash-4000 [01] 1477.606694: simple_strtoul
1105 sym-offset
1112 sym-offset:
1113 bash-4000 [01] 1477.606694: simple_strtoul+0x6/0xa0
1115 sym-addr
1120 sym-addr:
1121 bash-4000 [01] 1477.606694: simple_strtoul <c0339346>
1125 latency-format option is enabled.
1163 <idle>-0 [001] dNs4 21169.031481: wake_up_idle_cpu <-add_timer_on
1164 <idle>-0 [001] dNs4 21169.031482: _raw_spin_unlock_irqrestore <-add_timer_on
1165 <idle>-0 [001] .Ns4 21169.031484: sub_preempt_count <-_raw_spin_unlock_irqrestore
1167 <idle>-0 [002] .N.1 21169.031484: rcu_idle_exit <-cpu_idle
1168 <idle>-0 [001] .Ns3 21169.031484: _raw_spin_unlock <-clocksource_watchdog
1169 <idle>-0 [001] .Ns3 21169.031485: sub_preempt_count <-_raw_spin_unlock
1176 sym-userobj
1187 a.out-1623 [000] 40874.465068: /root/a.out[+0x480] <-/root/a.out[+0
1188 x494] <- /root/a.out[+0x4a8] <- /lib/libc-2.7.so[+0x1e1a6]
1191 printk-msg-only
1196 context-info
1200 latency-format
1205 pause-on-trace
1211 hash-ptr
1217 record-cmd
1225 record-tgid
1242 irq-info
1248 # entries-in-buffer/entries-written: 144405/9452052 #P:4
1250 # TASK-PID CPU# TIMESTAMP FUNCTION
1252 <idle>-0 [002] 23636.756054: ttwu_do_activate.constprop.89 <-try_to_wake_up
1253 <idle>-0 [002] 23636.756054: activate_task <-ttwu_do_activate.constprop.89
1254 <idle>-0 [002] 23636.756055: enqueue_task <-activate_task
1262 event-fork
1270 function-trace
1277 function-fork
1286 display-graph
1322 funcgraph-overrun
1333 funcgraph-cpu
1337 funcgraph-overhead
1343 funcgraph-proc
1350 funcgraph-duration
1355 funcgraph-abstime
1358 funcgraph-irqs
1362 funcgraph-tail
1368 funcgraph-retval
1373 funcgraph-retval-hex
1381 sleep-time
1387 graph-time
1401 -------
1418 # echo 0 > options/function-trace
1422 # ls -ltr
1428 # irqsoff latency trace v1.1.5 on 3.8.0-test+
1429 # --------------------------------------------------------------------
1431 # -----------------
1432 # | task: swapper/0-0 (uid:0 nice:0 policy:0 rt_prio:0)
1433 # -----------------
1438 # _------=> CPU#
1439 # / _-----=> irqs-off
1440 # | / _----=> need-resched
1441 # || / _---=> hardirq/softirq
1442 # ||| / _--=> preempt-depth
1446 <idle>-0 0d.s2 0us+: _raw_spin_lock_irq <-run_timer_softirq
1447 <idle>-0 0dNs3 17us : _raw_spin_unlock_irq <-run_timer_softirq
1448 <idle>-0 0dNs3 17us+: trace_hardirqs_on <-run_timer_softirq
1449 <idle>-0 0dNs3 25us : <stack trace>
1472 Note the above example had function-trace not set. If we set
1473 function-trace, we get a much larger output::
1475 with echo 1 > options/function-trace
1479 # irqsoff latency trace v1.1.5 on 3.8.0-test+
1480 # --------------------------------------------------------------------
1482 # -----------------
1483 # | task: bash-2042 (uid:0 nice:0 policy:0 rt_prio:0)
1484 # -----------------
1489 # _------=> CPU#
1490 # / _-----=> irqs-off
1491 # | / _----=> need-resched
1492 # || / _---=> hardirq/softirq
1493 # ||| / _--=> preempt-depth
1497 bash-2042 3d... 0us : _raw_spin_lock_irqsave <-ata_scsi_queuecmd
1498 bash-2042 3d... 0us : add_preempt_count <-_raw_spin_lock_irqsave
1499 bash-2042 3d..1 1us : ata_scsi_find_dev <-ata_scsi_queuecmd
1500 bash-2042 3d..1 1us : __ata_scsi_find_dev <-ata_scsi_find_dev
1501 bash-2042 3d..1 2us : ata_find_dev.part.14 <-__ata_scsi_find_dev
1502 bash-2042 3d..1 2us : ata_qc_new_init <-__ata_scsi_queuecmd
1503 bash-2042 3d..1 3us : ata_sg_init <-__ata_scsi_queuecmd
1504 bash-2042 3d..1 4us : ata_scsi_rw_xlat <-__ata_scsi_queuecmd
1505 bash-2042 3d..1 4us : ata_build_rw_tf <-ata_scsi_rw_xlat
1507 bash-2042 3d..1 67us : delay_tsc <-__delay
1508 bash-2042 3d..1 67us : add_preempt_count <-delay_tsc
1509 bash-2042 3d..2 67us : sub_preempt_count <-delay_tsc
1510 bash-2042 3d..1 67us : add_preempt_count <-delay_tsc
1511 bash-2042 3d..2 68us : sub_preempt_count <-delay_tsc
1512 bash-2042 3d..1 68us+: ata_bmdma_start <-ata_bmdma_qc_issue
1513 bash-2042 3d..1 71us : _raw_spin_unlock_irqrestore <-ata_scsi_queuecmd
1514 bash-2042 3d..1 71us : _raw_spin_unlock_irqrestore <-ata_scsi_queuecmd
1515 bash-2042 3d..1 72us+: trace_hardirqs_on <-ata_scsi_queuecmd
1516 bash-2042 3d..1 120us : <stack trace>
1551 display-graph option::
1553 with echo 1 > options/display-graph
1557 # irqsoff latency trace v1.1.5 on 4.20.0-rc6+
1558 # --------------------------------------------------------------------
1560 # -----------------
1561 # | task: bash-1507 (uid:0 nice:0 policy:0 rt_prio:0)
1562 # -----------------
1567 # _-----=> irqs-off
1568 # / _----=> need-resched
1569 # | / _---=> hardirq/softirq
1570 # || / _--=> preempt-depth
1574 0 us | 0) bash-1507 | d... | 0.000 us | _raw_spin_lock_irqsave();
1575 0 us | 0) bash-1507 | d..1 | 0.378 us | do_raw_spin_trylock();
1576 1 us | 0) bash-1507 | d..2 | | set_track() {
1577 2 us | 0) bash-1507 | d..2 | | save_stack_trace() {
1578 2 us | 0) bash-1507 | d..2 | | __save_stack_trace() {
1579 3 us | 0) bash-1507 | d..2 | | __unwind_start() {
1580 3 us | 0) bash-1507 | d..2 | | get_stack_info() {
1581 3 us | 0) bash-1507 | d..2 | 0.351 us | in_task_stack();
1582 4 us | 0) bash-1507 | d..2 | 1.107 us | }
1584 3750 us | 0) bash-1507 | d..1 | 0.516 us | do_raw_spin_unlock();
1585 3750 us | 0) bash-1507 | d..1 | 0.000 us | _raw_spin_unlock_irqrestore();
1586 3764 us | 0) bash-1507 | d..1 | 0.000 us | tracer_hardirqs_on();
1587 bash-1507 0d..1 3792us : <stack trace>
1604 ----------
1617 # echo 0 > options/function-trace
1621 # ls -ltr
1627 # preemptoff latency trace v1.1.5 on 3.8.0-test+
1628 # --------------------------------------------------------------------
1630 # -----------------
1631 # | task: sshd-1991 (uid:0 nice:0 policy:0 rt_prio:0)
1632 # -----------------
1637 # _------=> CPU#
1638 # / _-----=> irqs-off
1639 # | / _----=> need-resched
1640 # || / _---=> hardirq/softirq
1641 # ||| / _--=> preempt-depth
1645 sshd-1991 1d.h. 0us+: irq_enter <-do_IRQ
1646 sshd-1991 1d..1 46us : irq_exit <-do_IRQ
1647 sshd-1991 1d..1 47us+: trace_preempt_on <-do_IRQ
1648 sshd-1991 1d..1 52us : <stack trace>
1665 # preemptoff latency trace v1.1.5 on 3.8.0-test+
1666 # --------------------------------------------------------------------
1668 # -----------------
1669 # | task: bash-1994 (uid:0 nice:0 policy:0 rt_prio:0)
1670 # -----------------
1675 # _------=> CPU#
1676 # / _-----=> irqs-off
1677 # | / _----=> need-resched
1678 # || / _---=> hardirq/softirq
1679 # ||| / _--=> preempt-depth
1683 bash-1994 1d..1 0us : _raw_spin_lock_irqsave <-wake_up_new_task
1684 bash-1994 1d..1 0us : select_task_rq_fair <-select_task_rq
1685 bash-1994 1d..1 1us : __rcu_read_lock <-select_task_rq_fair
1686 bash-1994 1d..1 1us : source_load <-select_task_rq_fair
1687 bash-1994 1d..1 1us : source_load <-select_task_rq_fair
1689 bash-1994 1d..1 12us : irq_enter <-smp_apic_timer_interrupt
1690 bash-1994 1d..1 12us : rcu_irq_enter <-irq_enter
1691 bash-1994 1d..1 13us : add_preempt_count <-irq_enter
1692 bash-1994 1d.h1 13us : exit_idle <-smp_apic_timer_interrupt
1693 bash-1994 1d.h1 13us : hrtimer_interrupt <-smp_apic_timer_interrupt
1694 bash-1994 1d.h1 13us : _raw_spin_lock <-hrtimer_interrupt
1695 bash-1994 1d.h1 14us : add_preempt_count <-_raw_spin_lock
1696 bash-1994 1d.h2 14us : ktime_get_update_offsets <-hrtimer_interrupt
1698 bash-1994 1d.h1 35us : lapic_next_event <-clockevents_program_event
1699 bash-1994 1d.h1 35us : irq_exit <-smp_apic_timer_interrupt
1700 bash-1994 1d.h1 36us : sub_preempt_count <-irq_exit
1701 bash-1994 1d..2 36us : do_softirq <-irq_exit
1702 bash-1994 1d..2 36us : __do_softirq <-call_softirq
1703 bash-1994 1d..2 36us : __local_bh_disable <-__do_softirq
1704 bash-1994 1d.s2 37us : add_preempt_count <-_raw_spin_lock_irq
1705 bash-1994 1d.s3 38us : _raw_spin_unlock <-run_timer_softirq
1706 bash-1994 1d.s3 39us : sub_preempt_count <-_raw_spin_unlock
1707 bash-1994 1d.s2 39us : call_timer_fn <-run_timer_softirq
1709 bash-1994 1dNs2 81us : cpu_needs_another_gp <-rcu_process_callbacks
1710 bash-1994 1dNs2 82us : __local_bh_enable <-__do_softirq
1711 bash-1994 1dNs2 82us : sub_preempt_count <-__local_bh_enable
1712 bash-1994 1dN.2 82us : idle_cpu <-irq_exit
1713 bash-1994 1dN.2 83us : rcu_irq_exit <-irq_exit
1714 bash-1994 1dN.2 83us : sub_preempt_count <-irq_exit
1715 bash-1994 1.N.1 84us : _raw_spin_unlock_irqrestore <-task_rq_unlock
1716 bash-1994 1.N.1 84us+: trace_preempt_on <-task_rq_unlock
1717 bash-1994 1.N.1 104us : <stack trace>
1728 function-trace set. Here we see that interrupts were not disabled
1735 --------------
1769 # echo 0 > options/function-trace
1773 # ls -ltr
1779 # preemptirqsoff latency trace v1.1.5 on 3.8.0-test+
1780 # --------------------------------------------------------------------
1782 # -----------------
1783 # | task: ls-2230 (uid:0 nice:0 policy:0 rt_prio:0)
1784 # -----------------
1789 # _------=> CPU#
1790 # / _-----=> irqs-off
1791 # | / _----=> need-resched
1792 # || / _---=> hardirq/softirq
1793 # ||| / _--=> preempt-depth
1797 ls-2230 3d... 0us+: _raw_spin_lock_irqsave <-ata_scsi_queuecmd
1798 ls-2230 3...1 100us : _raw_spin_unlock_irqrestore <-ata_scsi_queuecmd
1799 ls-2230 3...1 101us+: trace_preempt_on <-ata_scsi_queuecmd
1800 ls-2230 3...1 111us : <stack trace>
1828 Here is a trace with function-trace set::
1832 # preemptirqsoff latency trace v1.1.5 on 3.8.0-test+
1833 # --------------------------------------------------------------------
1835 # -----------------
1836 # | task: ls-2269 (uid:0 nice:0 policy:0 rt_prio:0)
1837 # -----------------
1842 # _------=> CPU#
1843 # / _-----=> irqs-off
1844 # | / _----=> need-resched
1845 # || / _---=> hardirq/softirq
1846 # ||| / _--=> preempt-depth
1850 kworker/-59 3...1 0us : __schedule <-schedule
1851 kworker/-59 3d..1 0us : rcu_preempt_qs <-rcu_note_context_switch
1852 kworker/-59 3d..1 1us : add_preempt_count <-_raw_spin_lock_irq
1853 kworker/-59 3d..2 1us : deactivate_task <-__schedule
1854 kworker/-59 3d..2 1us : dequeue_task <-deactivate_task
1855 kworker/-59 3d..2 2us : update_rq_clock <-dequeue_task
1856 kworker/-59 3d..2 2us : dequeue_task_fair <-dequeue_task
1857 kworker/-59 3d..2 2us : update_curr <-dequeue_task_fair
1858 kworker/-59 3d..2 2us : update_min_vruntime <-update_curr
1859 kworker/-59 3d..2 3us : cpuacct_charge <-update_curr
1860 kworker/-59 3d..2 3us : __rcu_read_lock <-cpuacct_charge
1861 kworker/-59 3d..2 3us : __rcu_read_unlock <-cpuacct_charge
1862 kworker/-59 3d..2 3us : update_cfs_rq_blocked_load <-dequeue_task_fair
1863 kworker/-59 3d..2 4us : clear_buddies <-dequeue_task_fair
1864 kworker/-59 3d..2 4us : account_entity_dequeue <-dequeue_task_fair
1865 kworker/-59 3d..2 4us : update_min_vruntime <-dequeue_task_fair
1866 kworker/-59 3d..2 4us : update_cfs_shares <-dequeue_task_fair
1867 kworker/-59 3d..2 5us : hrtick_update <-dequeue_task_fair
1868 kworker/-59 3d..2 5us : wq_worker_sleeping <-__schedule
1869 kworker/-59 3d..2 5us : kthread_data <-wq_worker_sleeping
1870 kworker/-59 3d..2 5us : put_prev_task_fair <-__schedule
1871 kworker/-59 3d..2 6us : pick_next_task_fair <-pick_next_task
1872 kworker/-59 3d..2 6us : clear_buddies <-pick_next_task_fair
1873 kworker/-59 3d..2 6us : set_next_entity <-pick_next_task_fair
1874 kworker/-59 3d..2 6us : update_stats_wait_end <-set_next_entity
1875 ls-2269 3d..2 7us : finish_task_switch <-__schedule
1876 ls-2269 3d..2 7us : _raw_spin_unlock_irq <-finish_task_switch
1877 ls-2269 3d..2 8us : do_IRQ <-ret_from_intr
1878 ls-2269 3d..2 8us : irq_enter <-do_IRQ
1879 ls-2269 3d..2 8us : rcu_irq_enter <-irq_enter
1880 ls-2269 3d..2 9us : add_preempt_count <-irq_enter
1881 ls-2269 3d.h2 9us : exit_idle <-do_IRQ
1883 ls-2269 3d.h3 20us : sub_preempt_count <-_raw_spin_unlock
1884 ls-2269 3d.h2 20us : irq_exit <-do_IRQ
1885 ls-2269 3d.h2 21us : sub_preempt_count <-irq_exit
1886 ls-2269 3d..3 21us : do_softirq <-irq_exit
1887 ls-2269 3d..3 21us : __do_softirq <-call_softirq
1888 ls-2269 3d..3 21us+: __local_bh_disable <-__do_softirq
1889 ls-2269 3d.s4 29us : sub_preempt_count <-_local_bh_enable_ip
1890 ls-2269 3d.s5 29us : sub_preempt_count <-_local_bh_enable_ip
1891 ls-2269 3d.s5 31us : do_IRQ <-ret_from_intr
1892 ls-2269 3d.s5 31us : irq_enter <-do_IRQ
1893 ls-2269 3d.s5 31us : rcu_irq_enter <-irq_enter
1895 ls-2269 3d.s5 31us : rcu_irq_enter <-irq_enter
1896 ls-2269 3d.s5 32us : add_preempt_count <-irq_enter
1897 ls-2269 3d.H5 32us : exit_idle <-do_IRQ
1898 ls-2269 3d.H5 32us : handle_irq <-do_IRQ
1899 ls-2269 3d.H5 32us : irq_to_desc <-handle_irq
1900 ls-2269 3d.H5 33us : handle_fasteoi_irq <-handle_irq
1902 ls-2269 3d.s5 158us : _raw_spin_unlock_irqrestore <-rtl8139_poll
1903 ls-2269 3d.s3 158us : net_rps_action_and_irq_enable.isra.65 <-net_rx_action
1904 ls-2269 3d.s3 159us : __local_bh_enable <-__do_softirq
1905 ls-2269 3d.s3 159us : sub_preempt_count <-__local_bh_enable
1906 ls-2269 3d..3 159us : idle_cpu <-irq_exit
1907 ls-2269 3d..3 159us : rcu_irq_exit <-irq_exit
1908 ls-2269 3d..3 160us : sub_preempt_count <-irq_exit
1909 ls-2269 3d... 161us : __mutex_unlock_slowpath <-mutex_unlock
1910 ls-2269 3d... 162us+: trace_hardirqs_on <-mutex_unlock
1911 ls-2269 3d... 186us : <stack trace>
1930 ------
1934 Now for non Real-Time tasks, this can be arbitrary. But tracing
1939 # echo 0 > options/function-trace
1943 # chrt -f 5 sleep 1
1948 # wakeup latency trace v1.1.5 on 3.8.0-test+
1949 # --------------------------------------------------------------------
1951 # -----------------
1952 # | task: kworker/3:1H-312 (uid:0 nice:-20 policy:0 rt_prio:0)
1953 # -----------------
1955 # _------=> CPU#
1956 # / _-----=> irqs-off
1957 # | / _----=> need-resched
1958 # || / _---=> hardirq/softirq
1959 # ||| / _--=> preempt-depth
1963 <idle>-0 3dNs7 0us : 0:120:R + [003] 312:100:R kworker/3:1H
1964 <idle>-0 3dNs7 1us+: ttwu_do_activate.constprop.87 <-try_to_wake_up
1965 <idle>-0 3d..3 15us : __schedule <-schedule
1966 <idle>-0 3d..3 15us : 0:120:R ==> [003] 312:100:R kworker/3:1H
1970 the kworker with a nice priority of -20 (not very nice), took
1974 Non Real-Time tasks are not that interesting. A more interesting
1975 trace is to concentrate only on Real-Time tasks.
1978 ---------
1980 In a Real-Time environment it is very important to know the
1984 also important to know the scheduling latency of non-RT tasks,
1985 but the average schedule latency is better for non-RT tasks.
1989 Real-Time environments are interested in the worst case latency.
1993 work well with Real-Time tasks. The wakeup_rt tracer was designed
1994 to record the worst case wakeups of RT tasks. Non-RT tasks are
1996 tracing non-RT tasks that are unpredictable will overwrite the
2006 # echo 0 > options/function-trace
2010 # chrt -f 5 sleep 1
2017 # wakeup_rt latency trace v1.1.5 on 3.8.0-test+
2018 # --------------------------------------------------------------------
2020 # -----------------
2021 # | task: sleep-2389 (uid:0 nice:0 policy:1 rt_prio:5)
2022 # -----------------
2024 # _------=> CPU#
2025 # / _-----=> irqs-off
2026 # | / _----=> need-resched
2027 # || / _---=> hardirq/softirq
2028 # ||| / _--=> preempt-depth
2032 <idle>-0 3d.h4 0us : 0:120:R + [003] 2389: 94:R sleep
2033 <idle>-0 3d.h4 1us+: ttwu_do_activate.constprop.87 <-try_to_wake_up
2034 <idle>-0 3d..3 5us : __schedule <-schedule
2035 <idle>-0 3d..3 5us : 0:120:R ==> [003] 2389: 94:R sleep
2045 and it has an rt_prio of 5. This priority is user-space priority
2049 Note, that the trace data shows the internal priority (99 - rtprio).
2052 <idle>-0 3d..3 5us : 0:120:R ==> [003] 2389: 94:R sleep
2054 The 0:120:R means idle was running with a nice priority of 0 (120 - 120)
2056 2389: 94:R. That is the priority is the kernel rtprio (99 - 5 = 94)
2059 Doing the same with chrt -r 5 and function-trace set.
2062 echo 1 > options/function-trace
2066 # wakeup_rt latency trace v1.1.5 on 3.8.0-test+
2067 # --------------------------------------------------------------------
2069 # -----------------
2070 # | task: sleep-2448 (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 1us+: 0:120:R + [003] 2448: 94:R sleep
2082 <idle>-0 3d.h4 2us : ttwu_do_activate.constprop.87 <-try_to_wake_up
2083 <idle>-0 3d.h3 3us : check_preempt_curr <-ttwu_do_wakeup
2084 <idle>-0 3d.h3 3us : resched_curr <-check_preempt_curr
2085 <idle>-0 3dNh3 4us : task_woken_rt <-ttwu_do_wakeup
2086 <idle>-0 3dNh3 4us : _raw_spin_unlock <-try_to_wake_up
2087 <idle>-0 3dNh3 4us : sub_preempt_count <-_raw_spin_unlock
2088 <idle>-0 3dNh2 5us : ttwu_stat <-try_to_wake_up
2089 <idle>-0 3dNh2 5us : _raw_spin_unlock_irqrestore <-try_to_wake_up
2090 <idle>-0 3dNh2 6us : sub_preempt_count <-_raw_spin_unlock_irqrestore
2091 <idle>-0 3dNh1 6us : _raw_spin_lock <-__run_hrtimer
2092 <idle>-0 3dNh1 6us : add_preempt_count <-_raw_spin_lock
2093 <idle>-0 3dNh2 7us : _raw_spin_unlock <-hrtimer_interrupt
2094 <idle>-0 3dNh2 7us : sub_preempt_count <-_raw_spin_unlock
2095 <idle>-0 3dNh1 7us : tick_program_event <-hrtimer_interrupt
2096 <idle>-0 3dNh1 7us : clockevents_program_event <-tick_program_event
2097 <idle>-0 3dNh1 8us : ktime_get <-clockevents_program_event
2098 <idle>-0 3dNh1 8us : lapic_next_event <-clockevents_program_event
2099 <idle>-0 3dNh1 8us : irq_exit <-smp_apic_timer_interrupt
2100 <idle>-0 3dNh1 9us : sub_preempt_count <-irq_exit
2101 <idle>-0 3dN.2 9us : idle_cpu <-irq_exit
2102 <idle>-0 3dN.2 9us : rcu_irq_exit <-irq_exit
2103 <idle>-0 3dN.2 10us : rcu_eqs_enter_common.isra.45 <-rcu_irq_exit
2104 <idle>-0 3dN.2 10us : sub_preempt_count <-irq_exit
2105 <idle>-0 3.N.1 11us : rcu_idle_exit <-cpu_idle
2106 <idle>-0 3dN.1 11us : rcu_eqs_exit_common.isra.43 <-rcu_idle_exit
2107 <idle>-0 3.N.1 11us : tick_nohz_idle_exit <-cpu_idle
2108 <idle>-0 3dN.1 12us : menu_hrtimer_cancel <-tick_nohz_idle_exit
2109 <idle>-0 3dN.1 12us : ktime_get <-tick_nohz_idle_exit
2110 <idle>-0 3dN.1 12us : tick_do_update_jiffies64 <-tick_nohz_idle_exit
2111 <idle>-0 3dN.1 13us : cpu_load_update_nohz <-tick_nohz_idle_exit
2112 <idle>-0 3dN.1 13us : _raw_spin_lock <-cpu_load_update_nohz
2113 <idle>-0 3dN.1 13us : add_preempt_count <-_raw_spin_lock
2114 <idle>-0 3dN.2 13us : __cpu_load_update <-cpu_load_update_nohz
2115 <idle>-0 3dN.2 14us : sched_avg_update <-__cpu_load_update
2116 <idle>-0 3dN.2 14us : _raw_spin_unlock <-cpu_load_update_nohz
2117 <idle>-0 3dN.2 14us : sub_preempt_count <-_raw_spin_unlock
2118 <idle>-0 3dN.1 15us : calc_load_nohz_stop <-tick_nohz_idle_exit
2119 <idle>-0 3dN.1 15us : touch_softlockup_watchdog <-tick_nohz_idle_exit
2120 <idle>-0 3dN.1 15us : hrtimer_cancel <-tick_nohz_idle_exit
2121 <idle>-0 3dN.1 15us : hrtimer_try_to_cancel <-hrtimer_cancel
2122 <idle>-0 3dN.1 16us : lock_hrtimer_base.isra.18 <-hrtimer_try_to_cancel
2123 <idle>-0 3dN.1 16us : _raw_spin_lock_irqsave <-lock_hrtimer_base.isra.18
2124 <idle>-0 3dN.1 16us : add_preempt_count <-_raw_spin_lock_irqsave
2125 <idle>-0 3dN.2 17us : __remove_hrtimer <-remove_hrtimer.part.16
2126 <idle>-0 3dN.2 17us : hrtimer_force_reprogram <-__remove_hrtimer
2127 <idle>-0 3dN.2 17us : tick_program_event <-hrtimer_force_reprogram
2128 <idle>-0 3dN.2 18us : clockevents_program_event <-tick_program_event
2129 <idle>-0 3dN.2 18us : ktime_get <-clockevents_program_event
2130 <idle>-0 3dN.2 18us : lapic_next_event <-clockevents_program_event
2131 <idle>-0 3dN.2 19us : _raw_spin_unlock_irqrestore <-hrtimer_try_to_cancel
2132 <idle>-0 3dN.2 19us : sub_preempt_count <-_raw_spin_unlock_irqrestore
2133 <idle>-0 3dN.1 19us : hrtimer_forward <-tick_nohz_idle_exit
2134 <idle>-0 3dN.1 20us : ktime_add_safe <-hrtimer_forward
2135 <idle>-0 3dN.1 20us : ktime_add_safe <-hrtimer_forward
2136 <idle>-0 3dN.1 20us : hrtimer_start_range_ns <-hrtimer_start_expires.constprop.11
2137 <idle>-0 3dN.1 20us : __hrtimer_start_range_ns <-hrtimer_start_range_ns
2138 <idle>-0 3dN.1 21us : lock_hrtimer_base.isra.18 <-__hrtimer_start_range_ns
2139 <idle>-0 3dN.1 21us : _raw_spin_lock_irqsave <-lock_hrtimer_base.isra.18
2140 <idle>-0 3dN.1 21us : add_preempt_count <-_raw_spin_lock_irqsave
2141 <idle>-0 3dN.2 22us : ktime_add_safe <-__hrtimer_start_range_ns
2142 <idle>-0 3dN.2 22us : enqueue_hrtimer <-__hrtimer_start_range_ns
2143 <idle>-0 3dN.2 22us : tick_program_event <-__hrtimer_start_range_ns
2144 <idle>-0 3dN.2 23us : clockevents_program_event <-tick_program_event
2145 <idle>-0 3dN.2 23us : ktime_get <-clockevents_program_event
2146 <idle>-0 3dN.2 23us : lapic_next_event <-clockevents_program_event
2147 <idle>-0 3dN.2 24us : _raw_spin_unlock_irqrestore <-__hrtimer_start_range_ns
2148 <idle>-0 3dN.2 24us : sub_preempt_count <-_raw_spin_unlock_irqrestore
2149 <idle>-0 3dN.1 24us : account_idle_ticks <-tick_nohz_idle_exit
2150 <idle>-0 3dN.1 24us : account_idle_time <-account_idle_ticks
2151 <idle>-0 3.N.1 25us : sub_preempt_count <-cpu_idle
2152 <idle>-0 3.N.. 25us : schedule <-cpu_idle
2153 <idle>-0 3.N.. 25us : __schedule <-preempt_schedule
2154 <idle>-0 3.N.. 26us : add_preempt_count <-__schedule
2155 <idle>-0 3.N.1 26us : rcu_note_context_switch <-__schedule
2156 <idle>-0 3.N.1 26us : rcu_sched_qs <-rcu_note_context_switch
2157 <idle>-0 3dN.1 27us : rcu_preempt_qs <-rcu_note_context_switch
2158 <idle>-0 3.N.1 27us : _raw_spin_lock_irq <-__schedule
2159 <idle>-0 3dN.1 27us : add_preempt_count <-_raw_spin_lock_irq
2160 <idle>-0 3dN.2 28us : put_prev_task_idle <-__schedule
2161 <idle>-0 3dN.2 28us : pick_next_task_stop <-pick_next_task
2162 <idle>-0 3dN.2 28us : pick_next_task_rt <-pick_next_task
2163 <idle>-0 3dN.2 29us : dequeue_pushable_task <-pick_next_task_rt
2164 <idle>-0 3d..3 29us : __schedule <-preempt_schedule
2165 <idle>-0 3d..3 30us : 0:120:R ==> [003] 2448: 94:R sleep
2175 --------------------------
2182 # echo 0 > options/function-trace
2187 # chrt -f 5 sleep 1
2192 # wakeup_rt latency trace v1.1.5 on 3.8.0-test+
2193 # --------------------------------------------------------------------
2195 # -----------------
2196 # | task: sleep-5882 (uid:0 nice:0 policy:1 rt_prio:5)
2197 # -----------------
2199 # _------=> CPU#
2200 # / _-----=> irqs-off
2201 # | / _----=> need-resched
2202 # || / _---=> hardirq/softirq
2203 # ||| / _--=> preempt-depth
2207 <idle>-0 2d.h4 0us : 0:120:R + [002] 5882: 94:R sleep
2208 <idle>-0 2d.h4 0us : ttwu_do_activate.constprop.87 <-try_to_wake_up
2209 <idle>-0 2d.h4 1us : sched_wakeup: comm=sleep pid=5882 prio=94 success=1 target_cpu=002
2210 <idle>-0 2dNh2 1us : hrtimer_expire_exit: hrtimer=ffff88007796feb8
2211 <idle>-0 2.N.2 2us : power_end: cpu_id=2
2212 <idle>-0 2.N.2 3us : cpu_idle: state=4294967295 cpu_id=2
2213 <idle>-0 2dN.3 4us : hrtimer_cancel: hrtimer=ffff88007d50d5e0
2214 …<idle>-0 2dN.3 4us : hrtimer_start: hrtimer=ffff88007d50d5e0 function=tick_sched_timer ex…
2215 <idle>-0 2.N.2 5us : rcu_utilization: Start context switch
2216 <idle>-0 2.N.2 5us : rcu_utilization: End context switch
2217 <idle>-0 2d..3 6us : __schedule <-schedule
2218 <idle>-0 2d..3 6us : 0:120:R ==> [002] 5882: 94:R sleep
2222 -------------------------
2235 # entries-in-buffer/entries-written: 13/13 #P:8
2237 # _-----=> irqs-off
2238 # / _----=> need-resched
2239 # | / _---=> hardirq/softirq
2240 # || / _--=> preempt-depth
2242 # TASK-PID CPU# |||| TIMESTAMP FUNCTION
2244 …<...>-1729 [001] d... 678.473449: #1 inner/outer(us): 11/12 ts:1581527483.343962693 co…
2245 …<...>-1729 [004] d... 689.556542: #2 inner/outer(us): 16/9 ts:1581527494.889008092 co…
2246 …<...>-1729 [005] d... 714.756290: #3 inner/outer(us): 16/16 ts:1581527519.678961629 co…
2247 …<...>-1729 [001] d... 718.788247: #4 inner/outer(us): 9/17 ts:1581527523.889012713 co…
2248 …<...>-1729 [002] d... 719.796341: #5 inner/outer(us): 13/9 ts:1581527524.912872606 co…
2249 …<...>-1729 [006] d... 844.787091: #6 inner/outer(us): 9/12 ts:1581527649.889048502 co…
2250 …<...>-1729 [003] d... 849.827033: #7 inner/outer(us): 18/9 ts:1581527654.889013793 co…
2251 …<...>-1729 [007] d... 853.859002: #8 inner/outer(us): 9/12 ts:1581527658.889065736 co…
2252 …<...>-1729 [001] d... 855.874978: #9 inner/outer(us): 9/11 ts:1581527660.861991877 co…
2253 …<...>-1729 [001] d... 863.938932: #10 inner/outer(us): 9/11 ts:1581527668.970010500 co…
2254 …<...>-1729 [007] d... 878.050780: #11 inner/outer(us): 9/12 ts:1581527683.385002600 co…
2255 …<...>-1729 [007] d... 886.114702: #12 inner/outer(us): 9/12 ts:1581527691.385001600 co…
2281 nmi-total:7 nmi-count:1
2284 test, the time spent in NMI is reported in "nmi-total" (in
2287 All architectures that have NMIs will show the "nmi-count" if an
2318 --------
2334 # entries-in-buffer/entries-written: 24799/24799 #P:4
2336 # _-----=> irqs-off
2337 # / _----=> need-resched
2338 # | / _---=> hardirq/softirq
2339 # || / _--=> preempt-depth
2341 # TASK-PID CPU# |||| TIMESTAMP FUNCTION
2343 bash-1994 [002] .... 3082.063030: mutex_unlock <-rb_simple_write
2344 bash-1994 [002] .... 3082.063031: __mutex_unlock_slowpath <-mutex_unlock
2345 bash-1994 [002] .... 3082.063031: __fsnotify_parent <-fsnotify_modify
2346 bash-1994 [002] .... 3082.063032: fsnotify <-fsnotify_modify
2347 bash-1994 [002] .... 3082.063032: __srcu_read_lock <-fsnotify
2348 bash-1994 [002] .... 3082.063032: add_preempt_count <-__srcu_read_lock
2349 bash-1994 [002] ...1 3082.063032: sub_preempt_count <-__srcu_read_lock
2350 bash-1994 [002] .... 3082.063033: __srcu_read_unlock <-fsnotify
2378 ---------------------
2392 # TASK-PID CPU# TIMESTAMP FUNCTION
2394 yum-updatesd-3111 [003] 1637.254676: finish_task_switch <-thread_return
2395 yum-updatesd-3111 [003] 1637.254681: hrtimer_cancel <-schedule_hrtimeout_range
2396 yum-updatesd-3111 [003] 1637.254682: hrtimer_try_to_cancel <-hrtimer_cancel
2397 yum-updatesd-3111 [003] 1637.254683: lock_hrtimer_base <-hrtimer_try_to_cancel
2398 yum-updatesd-3111 [003] 1637.254685: fget_light <-do_sys_poll
2399 yum-updatesd-3111 [003] 1637.254686: pipe_poll <-do_sys_poll
2404 # TASK-PID CPU# TIMESTAMP FUNCTION
2407 yum-updatesd-3111 [003] 1701.957688: free_poll_entry <-poll_freewait
2408 yum-updatesd-3111 [003] 1701.957689: remove_wait_queue <-free_poll_entry
2409 yum-updatesd-3111 [003] 1701.957691: fput <-free_poll_entry
2410 yum-updatesd-3111 [003] 1701.957692: audit_syscall_exit <-sysret_audit
2411 yum-updatesd-3111 [003] 1701.957693: path_put <-audit_syscall_exit
2474 exit(-1);
2483 exit(-1);
2506 tracefs=`sed -ne 's/^tracefs \(.*\) tracefs.*/\1/p' /proc/mounts`
2515 ---------------------------
2528 - measure of a function's time execution
2529 - having a reliable call stack to draw function calls graph
2533 - you want to find the reason of a strange kernel behavior and
2537 - you are experiencing weird latencies but it's difficult to
2540 - you want to find quickly which path is taken by a specific
2543 - you just want to peek inside a working kernel and want to see
2575 - The cpu number on which the function executed is default
2580 - hide: echo nofuncgraph-cpu > trace_options
2581 - show: echo funcgraph-cpu > trace_options
2583 - The duration (function's time of execution) is displayed on
2588 - hide: echo nofuncgraph-duration > trace_options
2589 - show: echo funcgraph-duration > trace_options
2591 - The overhead field precedes the duration field in case of
2594 - hide: echo nofuncgraph-overhead > trace_options
2595 - show: echo funcgraph-overhead > trace_options
2596 - depends on: funcgraph-duration
2648 - The task/pid field displays the thread cmdline and pid which
2651 - hide: echo nofuncgraph-proc > trace_options
2652 - show: echo funcgraph-proc > trace_options
2660 0) sh-4802 | | d_free() {
2661 0) sh-4802 | | call_rcu() {
2662 0) sh-4802 | | __call_rcu() {
2663 0) sh-4802 | 0.616 us | rcu_process_gp_end();
2664 0) sh-4802 | 0.586 us | check_for_new_grace_period();
2665 0) sh-4802 | 2.899 us | }
2666 0) sh-4802 | 4.040 us | }
2667 0) sh-4802 | 5.151 us | }
2668 0) sh-4802 | + 49.370 us | }
2671 - The absolute time field is an absolute timestamp given by the
2675 - hide: echo nofuncgraph-abstime > trace_options
2676 - show: echo funcgraph-abstime > trace_options
2707 - hide: echo nofuncgraph-tail > trace_options
2708 - show: echo funcgraph-tail > trace_options
2710 Example with nofuncgraph-tail (default)::
2718 Example with funcgraph-tail::
2731 - hide: echo nofuncgraph-retval > trace_options
2732 - show: echo funcgraph-retval > trace_options
2734 Example with funcgraph-retval::
2744 1) 2.335 us | } /* cpu_cgroup_can_attach = -22 */
2745 1) 4.369 us | } /* cgroup_migrate_execute = -22 */
2746 1) 7.143 us | } /* cgroup_migrate = -22 */
2749 returned the error code -22 firstly, then we can read the code
2752 When the option funcgraph-retval-hex is not set, the return value can
2757 - smart: echo nofuncgraph-retval-hex > trace_options
2758 - hexadecimal: echo funcgraph-retval-hex > trace_options
2760 Example with funcgraph-retval-hex::
2774 At present, there are some limitations when using the funcgraph-retval
2777 - Even if the function return type is void, a return value will still
2780 - Even if return values are stored in multiple registers, only the
2783 a 64-bit return value, with the lower 32 bits saved in eax and the
2787 - In certain procedure call standards, such as arm64's AAPCS64, when a
2791 when using a u8 in a 64-bit GPR, bits [63:8] may contain arbitrary values,
2808 < ... ftrace instrumentation ... >
2821 return -EINVAL;
2833 MOV x0, #-EINVAL
2842 <linux/ftrace.h> and call trace_printk() inside __might_sleep()::
2854 following "dynamic ftrace" section such as tracing only specific
2857 dynamic ftrace
2858 --------------
2863 every kernel function, produced by the -pg switch in gcc),
2864 starts of pointing to a simple return. (Enabling FTRACE will
2865 include the -pg switch in the compiling of the kernel.)
2871 with gcc version 4.6, the -mfentry has been added for x86, which
2882 The recordmcount program re-links this section back into the
2886 On boot up, before SMP is initialized, the dynamic ftrace code
2891 unloaded, it also removes its functions from the ftrace function
2901 (which is just a function stub). They now call into the ftrace
2908 version to the ftrace call site.
2914 One special side-effect to the recording of the functions being
2954 # entries-in-buffer/entries-written: 5/5 #P:4
2956 # _-----=> irqs-off
2957 # / _----=> need-resched
2958 # | / _---=> hardirq/softirq
2959 # || / _--=> preempt-depth
2961 # TASK-PID CPU# |||| TIMESTAMP FUNCTION
2963 usleep-2665 [001] .... 4186.475355: sys_nanosleep <-system_call_fastpath
2964 <idle>-0 [001] d.h1 4186.475409: hrtimer_interrupt <-smp_apic_timer_interrupt
2965 usleep-2665 [001] d.h1 4186.475426: hrtimer_interrupt <-smp_apic_timer_interrupt
2966 <idle>-0 [003] d.h1 4186.475426: hrtimer_interrupt <-smp_apic_timer_interrupt
2967 <idle>-0 [002] d.h1 4186.475427: hrtimer_interrupt <-smp_apic_timer_interrupt
3001 # entries-in-buffer/entries-written: 897/897 #P:4
3003 # _-----=> irqs-off
3004 # / _----=> need-resched
3005 # | / _---=> hardirq/softirq
3006 # || / _--=> preempt-depth
3008 # TASK-PID CPU# |||| TIMESTAMP FUNCTION
3010 <idle>-0 [003] dN.1 4228.547803: hrtimer_cancel <-tick_nohz_idle_exit
3011 <idle>-0 [003] dN.1 4228.547804: hrtimer_try_to_cancel <-hrtimer_cancel
3012 <idle>-0 [003] dN.2 4228.547805: hrtimer_force_reprogram <-__remove_hrtimer
3013 <idle>-0 [003] dN.1 4228.547805: hrtimer_forward <-tick_nohz_idle_exit
3014 … <idle>-0 [003] dN.1 4228.547805: hrtimer_start_range_ns <-hrtimer_start_expires.constprop.11
3015 <idle>-0 [003] d..1 4228.547858: hrtimer_get_next_event <-get_next_timer_interrupt
3016 <idle>-0 [003] d..1 4228.547859: hrtimer_start <-__tick_nohz_idle_enter
3017 <idle>-0 [003] d..2 4228.547860: hrtimer_force_reprogram <-__rem
3090 # entries-in-buffer/entries-written: 39608/39608 #P:4
3092 # _-----=> irqs-off
3093 # / _----=> need-resched
3094 # | / _---=> hardirq/softirq
3095 # || / _--=> preempt-depth
3097 # TASK-PID CPU# |||| TIMESTAMP FUNCTION
3099 bash-1994 [000] .... 4342.324896: file_ra_state_init <-do_dentry_open
3100 bash-1994 [000] .... 4342.324897: open_check_o_direct <-do_last
3101 bash-1994 [000] .... 4342.324897: ima_file_check <-do_last
3102 bash-1994 [000] .... 4342.324898: process_measurement <-ima_file_check
3103 bash-1994 [000] .... 4342.324898: ima_get_action <-process_measurement
3104 bash-1994 [000] .... 4342.324898: ima_match_policy <-ima_get_action
3105 bash-1994 [000] .... 4342.324899: do_truncate <-do_last
3106 bash-1994 [000] .... 4342.324899: setattr_should_drop_suidgid <-do_truncate
3107 bash-1994 [000] .... 4342.324899: notify_change <-do_truncate
3108 bash-1994 [000] .... 4342.324900: current_fs_time <-notify_change
3109 bash-1994 [000] .... 4342.324900: current_kernel_time <-current_fs_time
3110 bash-1994 [000] .... 4342.324900: timespec_trunc <-current_fs_time
3115 ------------------------------------
3133 # head -1 available_filter_functions
3139 # head -50 available_filter_functions | tail -1
3147 Dynamic ftrace with the function graph tracer
3148 ---------------------------------------------
3151 function tracer and the function-graph-tracer, there are some
3152 special features only available in the function-graph tracer.
3209 --------------
3214 disabled. This includes not only the function tracers for ftrace, but
3233 ---------------
3242 - mod:
3274 - traceon/traceoff:
3298 - snapshot:
3314 - enable_event/disable_event:
3338 - dump:
3339 When the function is hit, it will dump the contents of the ftrace
3345 - cpudump:
3346 When the function is hit, it will dump the contents of the ftrace
3351 - stacktrace:
3355 ----------
3372 # entries-in-buffer/entries-written: 0/0 #P:4
3374 # _-----=> irqs-off
3375 # / _----=> need-resched
3376 # | / _---=> hardirq/softirq
3377 # || / _--=> preempt-depth
3379 # TASK-PID CPU# |||| TIMESTAMP FUNCTION
3384 bash-1994 [000] .... 5281.568961: mutex_unlock <-rb_simple_write
3385 bash-1994 [000] .... 5281.568963: __mutex_unlock_slowpath <-mutex_unlock
3386 bash-1994 [000] .... 5281.568963: __fsnotify_parent <-fsnotify_modify
3387 bash-1994 [000] .... 5281.568964: fsnotify <-fsnotify_modify
3388 bash-1994 [000] .... 5281.568964: __srcu_read_lock <-fsnotify
3389 bash-1994 [000] .... 5281.568964: add_preempt_count <-__srcu_read_lock
3390 bash-1994 [000] ...1 5281.568965: sub_preempt_count <-__srcu_read_lock
3391 bash-1994 [000] .... 5281.568965: __srcu_read_unlock <-fsnotify
3392 bash-1994 [000] .... 5281.568967: sys_dup2 <-system_call_fastpath
3402 -------------
3406 used to modify the size of the internal trace buffers. The
3408 CPU. To know the full size, multiply the number of possible CPUs
3429 much, it can cause Out-Of-Memory to trigger.
3433 -bash: echo: write error: Cannot allocate memory
3460 --------
3468 in time without stopping tracing. Ftrace swaps the current
3488 +--------------+------------+------------+------------+
3492 +--------------+------------+------------+------------+
3494 +--------------+------------+------------+------------+
3504 # entries-in-buffer/entries-written: 71/71 #P:8
3506 # _-----=> irqs-off
3507 # / _----=> need-resched
3508 # | / _---=> hardirq/softirq
3509 # || / _--=> preempt-depth
3511 # TASK-PID CPU# |||| TIMESTAMP FUNCTION
3513 …<idle>-0 [005] d... 2440.603828: sched_switch: prev_comm=swapper/5 prev_pid=0 prev_prio=120 …
3514 …sleep-2242 [005] d... 2440.603846: sched_switch: prev_comm=snapshot-test-2 prev_pid=2242 prev_pr…
3516 …<idle>-0 [002] d... 2440.707230: sched_switch: prev_comm=swapper/2 prev_pid=0 prev_prio=120 p…
3521 # entries-in-buffer/entries-written: 77/77 #P:8
3523 # _-----=> irqs-off
3524 # / _----=> need-resched
3525 # | / _---=> hardirq/softirq
3526 # || / _--=> preempt-depth
3528 # TASK-PID CPU# |||| TIMESTAMP FUNCTION
3530 …<idle>-0 [007] d... 2440.707395: sched_switch: prev_comm=swapper/7 prev_pid=0 prev_prio=120 p…
3531 …snapshot-test-2-2229 [002] d... 2440.707438: sched_switch: prev_comm=snapshot-test-2 prev_pid=22…
3547 ---------
3593 bash-2044 [002] .... 10594.481032: _raw_spin_lock_irqsave <-get_page_from_freelist
3594 bash-2044 [002] d... 10594.481032: add_preempt_count <-_raw_spin_lock_irqsave
3595 bash-2044 [002] d..1 10594.481032: __rmqueue <-get_page_from_freelist
3596 bash-2044 [002] d..1 10594.481033: _raw_spin_unlock <-get_page_from_freelist
3597 bash-2044 [002] d..1 10594.481033: sub_preempt_count <-_raw_spin_unlock
3598 … bash-2044 [002] d... 10594.481033: get_pageblock_flags_group <-get_pageblock_migratetype
3599 bash-2044 [002] d... 10594.481034: __mod_zone_page_state <-get_page_from_freelist
3600 bash-2044 [002] d... 10594.481034: zone_statistics <-get_page_from_freelist
3601 bash-2044 [002] d... 10594.481034: __inc_zone_state <-zone_statistics
3602 bash-2044 [002] d... 10594.481034: __inc_zone_state <-zone_statistics
3603 bash-2044 [002] .... 10594.481035: arch_dup_task_struct <-copy_process
3607 …bash-1998 [000] d..4 136.676759: sched_wakeup: comm=kworker/0:1 pid=59 prio=120 success=1 targe…
3608 …bash-1998 [000] dN.4 136.676760: sched_wakeup: comm=bash pid=1998 prio=120 success=1 target_cpu…
3609 …<idle>-0 [003] d.h3 136.676906: sched_wakeup: comm=rcu_preempt pid=9 prio=120 success=1 targ…
3610 …<idle>-0 [003] d..3 136.676909: sched_switch: prev_comm=swapper/3 prev_pid=0 prev_prio=120 p…
3611 …rcu_preempt-9 [003] d..3 136.676916: sched_switch: prev_comm=rcu_preempt prev_pid=9 prev_pri…
3612 …bash-1998 [000] d..4 136.677014: sched_wakeup: comm=kworker/0:1 pid=59 prio=120 success=1 targe…
3613 …bash-1998 [000] dN.4 136.677016: sched_wakeup: comm=bash pid=1998 prio=120 success=1 target_cpu…
3614 …bash-1998 [000] d..3 136.677018: sched_switch: prev_comm=bash prev_pid=1998 prev_prio=120 prev_…
3615 …kworker/0:1-59 [000] d..4 136.677022: sched_wakeup: comm=sshd pid=1995 prio=120 success=1 tar…
3616 …kworker/0:1-59 [000] d..3 136.677025: sched_switch: prev_comm=kworker/0:1 prev_pid=59 prev_pr…
3620 migration/1-14 [001] d.h3 138.732674: softirq_raise: vec=3 [action=NET_RX]
3621 <idle>-0 [001] dNh3 138.732725: softirq_raise: vec=3 [action=NET_RX]
3622 bash-1998 [000] d.h1 138.733101: softirq_raise: vec=1 [action=TIMER]
3623 bash-1998 [000] d.h1 138.733102: softirq_raise: vec=9 [action=RCU]
3624 bash-1998 [000] ..s2 138.733105: softirq_entry: vec=1 [action=TIMER]
3625 bash-1998 [000] ..s2 138.733106: softirq_exit: vec=1 [action=TIMER]
3626 bash-1998 [000] ..s2 138.733106: softirq_entry: vec=9 [action=RCU]
3627 bash-1998 [000] ..s2 138.733109: softirq_exit: vec=9 [action=RCU]
3628 sshd-1995 [001] d.h1 138.733278: irq_handler_entry: irq=21 name=uhci_hcd:usb4
3629 sshd-1995 [001] d.h1 138.733280: irq_handler_exit: irq=21 ret=unhandled
3630 sshd-1995 [001] d.h1 138.733281: irq_handler_entry: irq=21 name=eth0
3631 sshd-1995 [001] d.h1 138.733283: irq_handler_exit: irq=21 ret=handled
3637 # entries-in-buffer/entries-written: 18996/18996 #P:4
3639 # _-----=> irqs-off
3640 # / _----=> need-resched
3641 # | / _---=> hardirq/softirq
3642 # || / _--=> preempt-depth
3644 # TASK-PID CPU# |||| TIMESTAMP FUNCTION
3646 bash-1998 [000] d... 140.733501: sys_write -> 0x2
3647 bash-1998 [000] d... 140.733504: sys_dup2(oldfd: a, newfd: 1)
3648 bash-1998 [000] d... 140.733506: sys_dup2 -> 0x1
3649 bash-1998 [000] d... 140.733508: sys_fcntl(fd: a, cmd: 1, arg: 0)
3650 bash-1998 [000] d... 140.733509: sys_fcntl -> 0x1
3651 bash-1998 [000] d... 140.733510: sys_close(fd: a)
3652 bash-1998 [000] d... 140.733510: sys_close -> 0x0
3653 …bash-1998 [000] d... 140.733514: sys_rt_sigprocmask(how: 0, nset: 0, oset: 6e2768, sigsetsize: …
3654 bash-1998 [000] d... 140.733515: sys_rt_sigprocmask -> 0x0
3655 …bash-1998 [000] d... 140.733516: sys_rt_sigaction(sig: 2, act: 7fff718846f0, oact: 7fff71884650…
3656 bash-1998 [000] d... 140.733516: sys_rt_sigaction -> 0x0
3674 -----------
3683 at every function call that will become very useful. As ftrace provides
3684 a function tracer, it makes it convenient to check the stack size
3687 CONFIG_STACK_TRACER enables the ftrace stack tracing functionality.
3694 the stack size of the kernel during boot up, by adding "stacktrace"
3704 Depth Size Location (18 entries)
3705 ----- ---- --------
3725 Note, if -mfentry is being used by gcc, functions get traced before
3727 are not tested by the stack tracer when -mfentry is used.
3729 Currently, -mfentry is used by gcc 4.6.0 and above on x86 only.
3732 ----