Lines Matching +full:ps +full:- +full:source +full:- +full:off +full:- +full:time +full:- +full:ms
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 ------------
24 performance issues that take place outside of user-space.
29 disabled and enabled, as well as for preemption and from a time
41 ----------------------
43 See Documentation/trace/ftrace-design.rst for details for arch porters and such.
47 ---------------
58 Or you can mount it at run time with::
60 mount -t tracefs nodev /sys/kernel/tracing
65 ln -s /sys/kernel/tracing /tracing
93 Note: all time values are in microseconds.
118 set this file to "0". User space can re-enable tracing by
123 be re-enabled by user space using this file.
130 Note, this file is not a consumer. If tracing is off
132 the same output each time it is read. When tracing is on,
148 information every time it is read.
167 For example, the maximum time that interrupts are disabled.
168 The maximum time is saved in this file. The max trace will also be
173 By echoing in a time into this file, no latency will be recorded
174 unless it is greater than the time in this file.
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
207 meta-data. If the last page allocated has room for more bytes
211 due to buffer management meta-data. )
239 Note: When changing the sub-buffer size, tracing is stopped and any
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
366 for each function. The displayed address is the patch-site address
399 the "ip modify" attribute (thus the regs->ip can be changed),
403 If a non-ftrace trampoline is attached (BPF) a 'D' will be displayed.
405 "direct" trampoline can be attached to a given function at a time.
443 track of the time spent in those functions. The histogram
484 If the option "record-cmd" is set to "0", then comms of tasks
495 If the option "record-tgid" is set, on each scheduling context switch
497 the thread to its TGID. By default, the "record-tgid" option is
536 [local] global counter x86-tsc
555 This uses the jiffies counter and the time stamp
556 is relative to the time since boot up.
563 x86-tsc:
567 ppc-tb:
584 fast monotonic clock, but also accounts for time spent in
587 if clock is accessed after the suspend time is accounted before
590 Also on 32-bit systems, it's possible that the 64-bit boot offset
596 This is the tai clock (CLOCK_TAI) and is derived from the wall-
597 clock time. However, this clock does not experience
602 by setting the system time or using adjtimex() with an offset.
710 delta: Default timestamp mode - timestamp is a delta against
711 a per-buffer timestamp.
785 event (ring buffer is re-entrant), that it fills the
798 Events lost due to overwrite option being off.
804 -----------
819 source.
824 the same functions, the length of the timings may be slightly off as
825 each read the timestamp separately and not at the same time.
844 trace with the latency-format option enabled, which
850 time for which preemption is disabled.
855 records the largest time for which irqs and/or preemption
898 ----------------
930 ----------------------------
934 user-land utilities).
937 --------------
943 # entries-in-buffer/entries-written: 140080/250280 #P:4
945 # _-----=> irqs-off
946 # / _----=> need-resched
947 # | / _---=> hardirq/softirq
948 # || / _--=> preempt-depth
950 # TASK-PID CPU# |||| TIMESTAMP FUNCTION
952 bash-1977 [000] .... 17284.993652: sys_close <-system_call_fastpath
953 bash-1977 [000] .... 17284.993653: __close_fd <-sys_close
954 bash-1977 [000] .... 17284.993653: _raw_spin_lock <-__close_fd
955 sshd-1974 [003] .... 17284.993653: __srcu_read_unlock <-fsnotify
956 bash-1977 [000] .... 17284.993654: add_preempt_count <-_raw_spin_lock
957 bash-1977 [000] ...1 17284.993655: _raw_spin_unlock <-__close_fd
958 bash-1977 [000] ...1 17284.993656: sub_preempt_count <-_raw_spin_unlock
959 bash-1977 [000] .... 17284.993657: filp_close <-__close_fd
960 bash-1977 [000] .... 17284.993657: dnotify_flush <-filp_close
961 sshd-1974 [003] .... 17284.993658: sys_select <-system_call_fastpath
968 lost due to the buffer filling up (250280 - 140080 = 110200 events
975 called this function "system_call_fastpath". The timestamp is the time
979 --------------------
981 When the latency-format option is enabled or when one of the latency
987 # irqsoff latency trace v1.1.5 on 3.8.0-test+
988 # --------------------------------------------------------------------
990 # -----------------
991 # | task: ps-6143 (uid:0 nice:0 policy:0 rt_prio:0)
992 # -----------------
997 # _------=> CPU#
998 # / _-----=> irqs-off
999 # | / _----=> need-resched
1000 # || / _---=> hardirq/softirq
1001 # ||| / _--=> preempt-depth
1003 # cmd pid ||||| time | caller
1005 ps-6143 2d... 0us!: trace_hardirqs_off <-__lock_task_sighand
1006 ps-6143 2d..1 259us+: trace_hardirqs_on <-_raw_spin_unlock_irqrestore
1007 ps-6143 2d..1 263us+: time_hardirqs_on <-_raw_spin_unlock_irqrestore
1008 ps-6143 2d..1 306us : <stack trace>
1021 This shows that the current tracer is "irqsoff" tracing the time
1030 occurred. (ps pid: 6143).
1035 - __lock_task_sighand is where the interrupts were disabled.
1036 - _raw_spin_unlock_irqrestore is where they were enabled again.
1047 irqs-off: 'd' interrupts are disabled. '.' otherwise.
1049 need-resched:
1050 - 'B' all, TIF_NEED_RESCHED, PREEMPT_NEED_RESCHED and TIF_RESCHED_LAZY is set,
1051 - 'N' both TIF_NEED_RESCHED and PREEMPT_NEED_RESCHED is set,
1052 - 'n' only TIF_NEED_RESCHED is set,
1053 - 'p' only PREEMPT_NEED_RESCHED is set,
1054 - 'L' both PREEMPT_NEED_RESCHED and TIF_RESCHED_LAZY is set,
1055 - 'b' both TIF_NEED_RESCHED and TIF_RESCHED_LAZY is set,
1056 - 'l' only TIF_RESCHED_LAZY is set
1057 - '.' otherwise.
1060 - 'Z' - NMI occurred inside a hardirq
1061 - 'z' - NMI is running
1062 - 'H' - hard irq occurred inside a softirq.
1063 - 'h' - hard irq is running
1064 - 's' - soft irq is running
1065 - '.' - normal context.
1067 preempt-depth: The level of preempt_disabled
1071 time:
1072 When the latency-format option is enabled, the trace file
1074 trace. This differs from the output when latency-format
1083 - '$' - greater than 1 second
1084 - '@' - greater than 100 millisecond
1085 - '*' - greater than 10 millisecond
1086 - '#' - greater than 1000 microsecond
1087 - '!' - greater than 100 microsecond
1088 - '+' - greater than 10 microsecond
1089 - ' ' - less than or equal to 10 microsecond.
1097 -------------
1104 print-parent
1105 nosym-offset
1106 nosym-addr
1116 nosym-userobj
1117 noprintk-msg-only
1118 context-info
1119 nolatency-format
1120 record-cmd
1121 norecord-tgid
1124 irq-info
1126 noevent-fork
1127 function-trace
1128 nofunction-fork
1129 nodisplay-graph
1136 echo noprint-parent > trace_options
1138 To enable an option, leave off the "no"::
1140 echo sym-offset > trace_options
1144 print-parent
1149 print-parent:
1150 bash-4000 [01] 1477.606694: simple_strtoul <-kstrtoul
1152 noprint-parent:
1153 bash-4000 [01] 1477.606694: simple_strtoul
1156 sym-offset
1163 sym-offset:
1164 bash-4000 [01] 1477.606694: simple_strtoul+0x6/0xa0
1166 sym-addr
1171 sym-addr:
1172 bash-4000 [01] 1477.606694: simple_strtoul <c0339346>
1176 latency-format option is enabled.
1179 bash 4000 1 0 00000000 00010a95 [58127d26] 1720.415ms \
1180 (+0.000ms): simple_strtoul (kstrtoul)
1232 a shorter time frame, were another CPU may have only had
1239 <idle>-0 [001] dNs4 21169.031481: wake_up_idle_cpu <-add_timer_on
1240 <idle>-0 [001] dNs4 21169.031482: _raw_spin_unlock_irqrestore <-add_timer_on
1241 <idle>-0 [001] .Ns4 21169.031484: sub_preempt_count <-_raw_spin_unlock_irqrestore
1243 <idle>-0 [002] .N.1 21169.031484: rcu_idle_exit <-cpu_idle
1244 <idle>-0 [001] .Ns3 21169.031484: _raw_spin_unlock <-clocksource_watchdog
1245 <idle>-0 [001] .Ns3 21169.031485: sub_preempt_count <-_raw_spin_unlock
1252 sym-userobj
1263 a.out-1623 [000] 40874.465068: /root/a.out[+0x480] <-/root/a.out[+0
1264 x494] <- /root/a.out[+0x4a8] <- /lib/libc-2.7.so[+0x1e1a6]
1267 printk-msg-only
1272 context-info
1276 latency-format
1281 pause-on-trace
1287 hash-ptr
1293 record-cmd
1301 record-tgid
1318 irq-info
1324 # entries-in-buffer/entries-written: 144405/9452052 #P:4
1326 # TASK-PID CPU# TIMESTAMP FUNCTION
1328 <idle>-0 [002] 23636.756054: ttwu_do_activate.constprop.89 <-try_to_wake_up
1329 <idle>-0 [002] 23636.756054: activate_task <-ttwu_do_activate.constprop.89
1330 <idle>-0 [002] 23636.756055: enqueue_task <-activate_task
1338 event-fork
1346 function-trace
1353 function-fork
1362 display-graph
1398 funcgraph-overrun
1409 funcgraph-cpu
1413 funcgraph-overhead
1419 funcgraph-proc
1426 funcgraph-duration
1428 the duration of the amount of time in the
1431 funcgraph-abstime
1434 funcgraph-irqs
1438 funcgraph-tail
1440 that it represents. By default this is off, and
1444 funcgraph-retval
1447 this is off.
1449 funcgraph-retval-hex
1455 is off.
1457 sleep-time
1459 the time a task schedules out in its function.
1460 When enabled, it will account time the task has been
1463 graph-time
1465 to include the time to call nested functions. When this is
1466 not set, the time reported for the function will only
1467 include the time the function itself executed for, not the
1468 time for functions that it called.
1477 -------
1483 with the reaction time.
1485 The irqsoff tracer tracks the time for which interrupts are
1487 the trace leading up to that latency point so that every time a
1494 # echo 0 > options/function-trace
1498 # ls -ltr
1504 # irqsoff latency trace v1.1.5 on 3.8.0-test+
1505 # --------------------------------------------------------------------
1507 # -----------------
1508 # | task: swapper/0-0 (uid:0 nice:0 policy:0 rt_prio:0)
1509 # -----------------
1514 # _------=> CPU#
1515 # / _-----=> irqs-off
1516 # | / _----=> need-resched
1517 # || / _---=> hardirq/softirq
1518 # ||| / _--=> preempt-depth
1520 # cmd pid ||||| time | caller
1522 <idle>-0 0d.s2 0us+: _raw_spin_lock_irq <-run_timer_softirq
1523 <idle>-0 0dNs3 17us : _raw_spin_unlock_irq <-run_timer_softirq
1524 <idle>-0 0dNs3 17us+: trace_hardirqs_on <-run_timer_softirq
1525 <idle>-0 0dNs3 25us : <stack trace>
1545 between the time of recording the max latency and the time of
1548 Note the above example had function-trace not set. If we set
1549 function-trace, we get a much larger output::
1551 with echo 1 > options/function-trace
1555 # irqsoff latency trace v1.1.5 on 3.8.0-test+
1556 # --------------------------------------------------------------------
1558 # -----------------
1559 # | task: bash-2042 (uid:0 nice:0 policy:0 rt_prio:0)
1560 # -----------------
1565 # _------=> CPU#
1566 # / _-----=> irqs-off
1567 # | / _----=> need-resched
1568 # || / _---=> hardirq/softirq
1569 # ||| / _--=> preempt-depth
1571 # cmd pid ||||| time | caller
1573 bash-2042 3d... 0us : _raw_spin_lock_irqsave <-ata_scsi_queuecmd
1574 bash-2042 3d... 0us : add_preempt_count <-_raw_spin_lock_irqsave
1575 bash-2042 3d..1 1us : ata_scsi_find_dev <-ata_scsi_queuecmd
1576 bash-2042 3d..1 1us : __ata_scsi_find_dev <-ata_scsi_find_dev
1577 bash-2042 3d..1 2us : ata_find_dev.part.14 <-__ata_scsi_find_dev
1578 bash-2042 3d..1 2us : ata_qc_new_init <-__ata_scsi_queuecmd
1579 bash-2042 3d..1 3us : ata_sg_init <-__ata_scsi_queuecmd
1580 bash-2042 3d..1 4us : ata_scsi_rw_xlat <-__ata_scsi_queuecmd
1581 bash-2042 3d..1 4us : ata_build_rw_tf <-ata_scsi_rw_xlat
1583 bash-2042 3d..1 67us : delay_tsc <-__delay
1584 bash-2042 3d..1 67us : add_preempt_count <-delay_tsc
1585 bash-2042 3d..2 67us : sub_preempt_count <-delay_tsc
1586 bash-2042 3d..1 67us : add_preempt_count <-delay_tsc
1587 bash-2042 3d..2 68us : sub_preempt_count <-delay_tsc
1588 bash-2042 3d..1 68us+: ata_bmdma_start <-ata_bmdma_qc_issue
1589 bash-2042 3d..1 71us : _raw_spin_unlock_irqrestore <-ata_scsi_queuecmd
1590 bash-2042 3d..1 71us : _raw_spin_unlock_irqrestore <-ata_scsi_queuecmd
1591 bash-2042 3d..1 72us+: trace_hardirqs_on <-ata_scsi_queuecmd
1592 bash-2042 3d..1 120us : <stack trace>
1621 functions that were called during that time. Note that by
1627 display-graph option::
1629 with echo 1 > options/display-graph
1633 # irqsoff latency trace v1.1.5 on 4.20.0-rc6+
1634 # --------------------------------------------------------------------
1636 # -----------------
1637 # | task: bash-1507 (uid:0 nice:0 policy:0 rt_prio:0)
1638 # -----------------
1643 # _-----=> irqs-off
1644 # / _----=> need-resched
1645 # | / _---=> hardirq/softirq
1646 # || / _--=> preempt-depth
1648 # REL TIME CPU TASK/PID |||| DURATION FUNCTION CALLS
1650 0 us | 0) bash-1507 | d... | 0.000 us | _raw_spin_lock_irqsave();
1651 0 us | 0) bash-1507 | d..1 | 0.378 us | do_raw_spin_trylock();
1652 1 us | 0) bash-1507 | d..2 | | set_track() {
1653 2 us | 0) bash-1507 | d..2 | | save_stack_trace() {
1654 2 us | 0) bash-1507 | d..2 | | __save_stack_trace() {
1655 3 us | 0) bash-1507 | d..2 | | __unwind_start() {
1656 3 us | 0) bash-1507 | d..2 | | get_stack_info() {
1657 3 us | 0) bash-1507 | d..2 | 0.351 us | in_task_stack();
1658 4 us | 0) bash-1507 | d..2 | 1.107 us | }
1660 3750 us | 0) bash-1507 | d..1 | 0.516 us | do_raw_spin_unlock();
1661 3750 us | 0) bash-1507 | d..1 | 0.000 us | _raw_spin_unlock_irqrestore();
1662 3764 us | 0) bash-1507 | d..1 | 0.000 us | tracer_hardirqs_on();
1663 bash-1507 0d..1 3792us : <stack trace>
1680 ----------
1693 # echo 0 > options/function-trace
1697 # ls -ltr
1703 # preemptoff latency trace v1.1.5 on 3.8.0-test+
1704 # --------------------------------------------------------------------
1706 # -----------------
1707 # | task: sshd-1991 (uid:0 nice:0 policy:0 rt_prio:0)
1708 # -----------------
1713 # _------=> CPU#
1714 # / _-----=> irqs-off
1715 # | / _----=> need-resched
1716 # || / _---=> hardirq/softirq
1717 # ||| / _--=> preempt-depth
1719 # cmd pid ||||| time | caller
1721 sshd-1991 1d.h. 0us+: irq_enter <-do_IRQ
1722 sshd-1991 1d..1 46us : irq_exit <-do_IRQ
1723 sshd-1991 1d..1 47us+: trace_preempt_on <-do_IRQ
1724 sshd-1991 1d..1 52us : <stack trace>
1734 the preempt off section and leaving it (the 'd'). We do not know if
1735 interrupts were enabled in the mean time or shortly after this
1741 # preemptoff latency trace v1.1.5 on 3.8.0-test+
1742 # --------------------------------------------------------------------
1744 # -----------------
1745 # | task: bash-1994 (uid:0 nice:0 policy:0 rt_prio:0)
1746 # -----------------
1751 # _------=> CPU#
1752 # / _-----=> irqs-off
1753 # | / _----=> need-resched
1754 # || / _---=> hardirq/softirq
1755 # ||| / _--=> preempt-depth
1757 # cmd pid ||||| time | caller
1759 bash-1994 1d..1 0us : _raw_spin_lock_irqsave <-wake_up_new_task
1760 bash-1994 1d..1 0us : select_task_rq_fair <-select_task_rq
1761 bash-1994 1d..1 1us : __rcu_read_lock <-select_task_rq_fair
1762 bash-1994 1d..1 1us : source_load <-select_task_rq_fair
1763 bash-1994 1d..1 1us : source_load <-select_task_rq_fair
1765 bash-1994 1d..1 12us : irq_enter <-smp_apic_timer_interrupt
1766 bash-1994 1d..1 12us : rcu_irq_enter <-irq_enter
1767 bash-1994 1d..1 13us : add_preempt_count <-irq_enter
1768 bash-1994 1d.h1 13us : exit_idle <-smp_apic_timer_interrupt
1769 bash-1994 1d.h1 13us : hrtimer_interrupt <-smp_apic_timer_interrupt
1770 bash-1994 1d.h1 13us : _raw_spin_lock <-hrtimer_interrupt
1771 bash-1994 1d.h1 14us : add_preempt_count <-_raw_spin_lock
1772 bash-1994 1d.h2 14us : ktime_get_update_offsets <-hrtimer_interrupt
1774 bash-1994 1d.h1 35us : lapic_next_event <-clockevents_program_event
1775 bash-1994 1d.h1 35us : irq_exit <-smp_apic_timer_interrupt
1776 bash-1994 1d.h1 36us : sub_preempt_count <-irq_exit
1777 bash-1994 1d..2 36us : do_softirq <-irq_exit
1778 bash-1994 1d..2 36us : __do_softirq <-call_softirq
1779 bash-1994 1d..2 36us : __local_bh_disable <-__do_softirq
1780 bash-1994 1d.s2 37us : add_preempt_count <-_raw_spin_lock_irq
1781 bash-1994 1d.s3 38us : _raw_spin_unlock <-run_timer_softirq
1782 bash-1994 1d.s3 39us : sub_preempt_count <-_raw_spin_unlock
1783 bash-1994 1d.s2 39us : call_timer_fn <-run_timer_softirq
1785 bash-1994 1dNs2 81us : cpu_needs_another_gp <-rcu_process_callbacks
1786 bash-1994 1dNs2 82us : __local_bh_enable <-__do_softirq
1787 bash-1994 1dNs2 82us : sub_preempt_count <-__local_bh_enable
1788 bash-1994 1dN.2 82us : idle_cpu <-irq_exit
1789 bash-1994 1dN.2 83us : rcu_irq_exit <-irq_exit
1790 bash-1994 1dN.2 83us : sub_preempt_count <-irq_exit
1791 bash-1994 1.N.1 84us : _raw_spin_unlock_irqrestore <-task_rq_unlock
1792 bash-1994 1.N.1 84us+: trace_preempt_on <-task_rq_unlock
1793 bash-1994 1.N.1 104us : <stack trace>
1804 function-trace set. Here we see that interrupts were not disabled
1805 the entire time. The irq_enter code lets us know that we entered
1811 --------------
1836 But neither will trace the time that interrupts and/or
1837 preemption is disabled. This total time is the time that we can
1838 not schedule. To record this time, use the preemptirqsoff
1845 # echo 0 > options/function-trace
1849 # ls -ltr
1855 # preemptirqsoff latency trace v1.1.5 on 3.8.0-test+
1856 # --------------------------------------------------------------------
1858 # -----------------
1859 # | task: ls-2230 (uid:0 nice:0 policy:0 rt_prio:0)
1860 # -----------------
1865 # _------=> CPU#
1866 # / _-----=> irqs-off
1867 # | / _----=> need-resched
1868 # || / _---=> hardirq/softirq
1869 # ||| / _--=> preempt-depth
1871 # cmd pid ||||| time | caller
1873 ls-2230 3d... 0us+: _raw_spin_lock_irqsave <-ata_scsi_queuecmd
1874 ls-2230 3...1 100us : _raw_spin_unlock_irqrestore <-ata_scsi_queuecmd
1875 ls-2230 3...1 101us+: trace_preempt_on <-ata_scsi_queuecmd
1876 ls-2230 3...1 111us : <stack trace>
1904 Here is a trace with function-trace set::
1908 # preemptirqsoff latency trace v1.1.5 on 3.8.0-test+
1909 # --------------------------------------------------------------------
1911 # -----------------
1912 # | task: ls-2269 (uid:0 nice:0 policy:0 rt_prio:0)
1913 # -----------------
1918 # _------=> CPU#
1919 # / _-----=> irqs-off
1920 # | / _----=> need-resched
1921 # || / _---=> hardirq/softirq
1922 # ||| / _--=> preempt-depth
1924 # cmd pid ||||| time | caller
1926 kworker/-59 3...1 0us : __schedule <-schedule
1927 kworker/-59 3d..1 0us : rcu_preempt_qs <-rcu_note_context_switch
1928 kworker/-59 3d..1 1us : add_preempt_count <-_raw_spin_lock_irq
1929 kworker/-59 3d..2 1us : deactivate_task <-__schedule
1930 kworker/-59 3d..2 1us : dequeue_task <-deactivate_task
1931 kworker/-59 3d..2 2us : update_rq_clock <-dequeue_task
1932 kworker/-59 3d..2 2us : dequeue_task_fair <-dequeue_task
1933 kworker/-59 3d..2 2us : update_curr <-dequeue_task_fair
1934 kworker/-59 3d..2 2us : update_min_vruntime <-update_curr
1935 kworker/-59 3d..2 3us : cpuacct_charge <-update_curr
1936 kworker/-59 3d..2 3us : __rcu_read_lock <-cpuacct_charge
1937 kworker/-59 3d..2 3us : __rcu_read_unlock <-cpuacct_charge
1938 kworker/-59 3d..2 3us : update_cfs_rq_blocked_load <-dequeue_task_fair
1939 kworker/-59 3d..2 4us : clear_buddies <-dequeue_task_fair
1940 kworker/-59 3d..2 4us : account_entity_dequeue <-dequeue_task_fair
1941 kworker/-59 3d..2 4us : update_min_vruntime <-dequeue_task_fair
1942 kworker/-59 3d..2 4us : update_cfs_shares <-dequeue_task_fair
1943 kworker/-59 3d..2 5us : hrtick_update <-dequeue_task_fair
1944 kworker/-59 3d..2 5us : wq_worker_sleeping <-__schedule
1945 kworker/-59 3d..2 5us : kthread_data <-wq_worker_sleeping
1946 kworker/-59 3d..2 5us : put_prev_task_fair <-__schedule
1947 kworker/-59 3d..2 6us : pick_next_task_fair <-pick_next_task
1948 kworker/-59 3d..2 6us : clear_buddies <-pick_next_task_fair
1949 kworker/-59 3d..2 6us : set_next_entity <-pick_next_task_fair
1950 kworker/-59 3d..2 6us : update_stats_wait_end <-set_next_entity
1951 ls-2269 3d..2 7us : finish_task_switch <-__schedule
1952 ls-2269 3d..2 7us : _raw_spin_unlock_irq <-finish_task_switch
1953 ls-2269 3d..2 8us : do_IRQ <-ret_from_intr
1954 ls-2269 3d..2 8us : irq_enter <-do_IRQ
1955 ls-2269 3d..2 8us : rcu_irq_enter <-irq_enter
1956 ls-2269 3d..2 9us : add_preempt_count <-irq_enter
1957 ls-2269 3d.h2 9us : exit_idle <-do_IRQ
1959 ls-2269 3d.h3 20us : sub_preempt_count <-_raw_spin_unlock
1960 ls-2269 3d.h2 20us : irq_exit <-do_IRQ
1961 ls-2269 3d.h2 21us : sub_preempt_count <-irq_exit
1962 ls-2269 3d..3 21us : do_softirq <-irq_exit
1963 ls-2269 3d..3 21us : __do_softirq <-call_softirq
1964 ls-2269 3d..3 21us+: __local_bh_disable <-__do_softirq
1965 ls-2269 3d.s4 29us : sub_preempt_count <-_local_bh_enable_ip
1966 ls-2269 3d.s5 29us : sub_preempt_count <-_local_bh_enable_ip
1967 ls-2269 3d.s5 31us : do_IRQ <-ret_from_intr
1968 ls-2269 3d.s5 31us : irq_enter <-do_IRQ
1969 ls-2269 3d.s5 31us : rcu_irq_enter <-irq_enter
1971 ls-2269 3d.s5 31us : rcu_irq_enter <-irq_enter
1972 ls-2269 3d.s5 32us : add_preempt_count <-irq_enter
1973 ls-2269 3d.H5 32us : exit_idle <-do_IRQ
1974 ls-2269 3d.H5 32us : handle_irq <-do_IRQ
1975 ls-2269 3d.H5 32us : irq_to_desc <-handle_irq
1976 ls-2269 3d.H5 33us : handle_fasteoi_irq <-handle_irq
1978 ls-2269 3d.s5 158us : _raw_spin_unlock_irqrestore <-rtl8139_poll
1979 ls-2269 3d.s3 158us : net_rps_action_and_irq_enable.isra.65 <-net_rx_action
1980 ls-2269 3d.s3 159us : __local_bh_enable <-__do_softirq
1981 ls-2269 3d.s3 159us : sub_preempt_count <-__local_bh_enable
1982 ls-2269 3d..3 159us : idle_cpu <-irq_exit
1983 ls-2269 3d..3 159us : rcu_irq_exit <-irq_exit
1984 ls-2269 3d..3 160us : sub_preempt_count <-irq_exit
1985 ls-2269 3d... 161us : __mutex_unlock_slowpath <-mutex_unlock
1986 ls-2269 3d... 162us+: trace_hardirqs_on <-mutex_unlock
1987 ls-2269 3d... 186us : <stack trace>
2006 ------
2009 time it takes for a task that is woken to actually wake up.
2010 Now for non Real-Time tasks, this can be arbitrary. But tracing
2015 # echo 0 > options/function-trace
2019 # chrt -f 5 sleep 1
2024 # wakeup latency trace v1.1.5 on 3.8.0-test+
2025 # --------------------------------------------------------------------
2027 # -----------------
2028 # | task: kworker/3:1H-312 (uid:0 nice:-20 policy:0 rt_prio:0)
2029 # -----------------
2031 # _------=> CPU#
2032 # / _-----=> irqs-off
2033 # | / _----=> need-resched
2034 # || / _---=> hardirq/softirq
2035 # ||| / _--=> preempt-depth
2037 # cmd pid ||||| time | caller
2039 <idle>-0 3dNs7 0us : 0:120:R + [003] 312:100:R kworker/3:1H
2040 <idle>-0 3dNs7 1us+: ttwu_do_activate.constprop.87 <-try_to_wake_up
2041 <idle>-0 3d..3 15us : __schedule <-schedule
2042 <idle>-0 3d..3 15us : 0:120:R ==> [003] 312:100:R kworker/3:1H
2046 the kworker with a nice priority of -20 (not very nice), took
2047 just 15 microseconds from the time it woke up, to the time it
2050 Non Real-Time tasks are not that interesting. A more interesting
2051 trace is to concentrate only on Real-Time tasks.
2054 ---------
2056 In a Real-Time environment it is very important to know the
2057 wakeup time it takes for the highest priority task that is woken
2058 up to the time that it executes. This is also known as "schedule
2060 also important to know the scheduling latency of non-RT tasks,
2061 but the average schedule latency is better for non-RT tasks.
2065 Real-Time environments are interested in the worst case latency.
2069 work well with Real-Time tasks. The wakeup_rt tracer was designed
2070 to record the worst case wakeups of RT tasks. Non-RT tasks are
2072 tracing non-RT tasks that are unpredictable will overwrite the
2082 # echo 0 > options/function-trace
2086 # chrt -f 5 sleep 1
2093 # wakeup_rt latency trace v1.1.5 on 3.8.0-test+
2094 # --------------------------------------------------------------------
2096 # -----------------
2097 # | task: sleep-2389 (uid:0 nice:0 policy:1 rt_prio:5)
2098 # -----------------
2100 # _------=> CPU#
2101 # / _-----=> irqs-off
2102 # | / _----=> need-resched
2103 # || / _---=> hardirq/softirq
2104 # ||| / _--=> preempt-depth
2106 # cmd pid ||||| time | caller
2108 <idle>-0 3d.h4 0us : 0:120:R + [003] 2389: 94:R sleep
2109 <idle>-0 3d.h4 1us+: ttwu_do_activate.constprop.87 <-try_to_wake_up
2110 <idle>-0 3d..3 5us : __schedule <-schedule
2111 <idle>-0 3d..3 5us : 0:120:R ==> [003] 2389: 94:R sleep
2121 and it has an rt_prio of 5. This priority is user-space priority
2125 Note, that the trace data shows the internal priority (99 - rtprio).
2128 <idle>-0 3d..3 5us : 0:120:R ==> [003] 2389: 94:R sleep
2130 The 0:120:R means idle was running with a nice priority of 0 (120 - 120)
2132 2389: 94:R. That is the priority is the kernel rtprio (99 - 5 = 94)
2135 Doing the same with chrt -r 5 and function-trace set.
2138 echo 1 > options/function-trace
2142 # wakeup_rt latency trace v1.1.5 on 3.8.0-test+
2143 # --------------------------------------------------------------------
2145 # -----------------
2146 # | task: sleep-2448 (uid:0 nice:0 policy:1 rt_prio:5)
2147 # -----------------
2149 # _------=> CPU#
2150 # / _-----=> irqs-off
2151 # | / _----=> need-resched
2152 # || / _---=> hardirq/softirq
2153 # ||| / _--=> preempt-depth
2155 # cmd pid ||||| time | caller
2157 <idle>-0 3d.h4 1us+: 0:120:R + [003] 2448: 94:R sleep
2158 <idle>-0 3d.h4 2us : ttwu_do_activate.constprop.87 <-try_to_wake_up
2159 <idle>-0 3d.h3 3us : check_preempt_curr <-ttwu_do_wakeup
2160 <idle>-0 3d.h3 3us : resched_curr <-check_preempt_curr
2161 <idle>-0 3dNh3 4us : task_woken_rt <-ttwu_do_wakeup
2162 <idle>-0 3dNh3 4us : _raw_spin_unlock <-try_to_wake_up
2163 <idle>-0 3dNh3 4us : sub_preempt_count <-_raw_spin_unlock
2164 <idle>-0 3dNh2 5us : ttwu_stat <-try_to_wake_up
2165 <idle>-0 3dNh2 5us : _raw_spin_unlock_irqrestore <-try_to_wake_up
2166 <idle>-0 3dNh2 6us : sub_preempt_count <-_raw_spin_unlock_irqrestore
2167 <idle>-0 3dNh1 6us : _raw_spin_lock <-__run_hrtimer
2168 <idle>-0 3dNh1 6us : add_preempt_count <-_raw_spin_lock
2169 <idle>-0 3dNh2 7us : _raw_spin_unlock <-hrtimer_interrupt
2170 <idle>-0 3dNh2 7us : sub_preempt_count <-_raw_spin_unlock
2171 <idle>-0 3dNh1 7us : tick_program_event <-hrtimer_interrupt
2172 <idle>-0 3dNh1 7us : clockevents_program_event <-tick_program_event
2173 <idle>-0 3dNh1 8us : ktime_get <-clockevents_program_event
2174 <idle>-0 3dNh1 8us : lapic_next_event <-clockevents_program_event
2175 <idle>-0 3dNh1 8us : irq_exit <-smp_apic_timer_interrupt
2176 <idle>-0 3dNh1 9us : sub_preempt_count <-irq_exit
2177 <idle>-0 3dN.2 9us : idle_cpu <-irq_exit
2178 <idle>-0 3dN.2 9us : rcu_irq_exit <-irq_exit
2179 <idle>-0 3dN.2 10us : rcu_eqs_enter_common.isra.45 <-rcu_irq_exit
2180 <idle>-0 3dN.2 10us : sub_preempt_count <-irq_exit
2181 <idle>-0 3.N.1 11us : rcu_idle_exit <-cpu_idle
2182 <idle>-0 3dN.1 11us : rcu_eqs_exit_common.isra.43 <-rcu_idle_exit
2183 <idle>-0 3.N.1 11us : tick_nohz_idle_exit <-cpu_idle
2184 <idle>-0 3dN.1 12us : menu_hrtimer_cancel <-tick_nohz_idle_exit
2185 <idle>-0 3dN.1 12us : ktime_get <-tick_nohz_idle_exit
2186 <idle>-0 3dN.1 12us : tick_do_update_jiffies64 <-tick_nohz_idle_exit
2187 <idle>-0 3dN.1 13us : cpu_load_update_nohz <-tick_nohz_idle_exit
2188 <idle>-0 3dN.1 13us : _raw_spin_lock <-cpu_load_update_nohz
2189 <idle>-0 3dN.1 13us : add_preempt_count <-_raw_spin_lock
2190 <idle>-0 3dN.2 13us : __cpu_load_update <-cpu_load_update_nohz
2191 <idle>-0 3dN.2 14us : sched_avg_update <-__cpu_load_update
2192 <idle>-0 3dN.2 14us : _raw_spin_unlock <-cpu_load_update_nohz
2193 <idle>-0 3dN.2 14us : sub_preempt_count <-_raw_spin_unlock
2194 <idle>-0 3dN.1 15us : calc_load_nohz_stop <-tick_nohz_idle_exit
2195 <idle>-0 3dN.1 15us : touch_softlockup_watchdog <-tick_nohz_idle_exit
2196 <idle>-0 3dN.1 15us : hrtimer_cancel <-tick_nohz_idle_exit
2197 <idle>-0 3dN.1 15us : hrtimer_try_to_cancel <-hrtimer_cancel
2198 <idle>-0 3dN.1 16us : lock_hrtimer_base.isra.18 <-hrtimer_try_to_cancel
2199 <idle>-0 3dN.1 16us : _raw_spin_lock_irqsave <-lock_hrtimer_base.isra.18
2200 <idle>-0 3dN.1 16us : add_preempt_count <-_raw_spin_lock_irqsave
2201 <idle>-0 3dN.2 17us : __remove_hrtimer <-remove_hrtimer.part.16
2202 <idle>-0 3dN.2 17us : hrtimer_force_reprogram <-__remove_hrtimer
2203 <idle>-0 3dN.2 17us : tick_program_event <-hrtimer_force_reprogram
2204 <idle>-0 3dN.2 18us : clockevents_program_event <-tick_program_event
2205 <idle>-0 3dN.2 18us : ktime_get <-clockevents_program_event
2206 <idle>-0 3dN.2 18us : lapic_next_event <-clockevents_program_event
2207 <idle>-0 3dN.2 19us : _raw_spin_unlock_irqrestore <-hrtimer_try_to_cancel
2208 <idle>-0 3dN.2 19us : sub_preempt_count <-_raw_spin_unlock_irqrestore
2209 <idle>-0 3dN.1 19us : hrtimer_forward <-tick_nohz_idle_exit
2210 <idle>-0 3dN.1 20us : ktime_add_safe <-hrtimer_forward
2211 <idle>-0 3dN.1 20us : ktime_add_safe <-hrtimer_forward
2212 <idle>-0 3dN.1 20us : hrtimer_start_range_ns <-hrtimer_start_expires.constprop.11
2213 <idle>-0 3dN.1 20us : __hrtimer_start_range_ns <-hrtimer_start_range_ns
2214 <idle>-0 3dN.1 21us : lock_hrtimer_base.isra.18 <-__hrtimer_start_range_ns
2215 <idle>-0 3dN.1 21us : _raw_spin_lock_irqsave <-lock_hrtimer_base.isra.18
2216 <idle>-0 3dN.1 21us : add_preempt_count <-_raw_spin_lock_irqsave
2217 <idle>-0 3dN.2 22us : ktime_add_safe <-__hrtimer_start_range_ns
2218 <idle>-0 3dN.2 22us : enqueue_hrtimer <-__hrtimer_start_range_ns
2219 <idle>-0 3dN.2 22us : tick_program_event <-__hrtimer_start_range_ns
2220 <idle>-0 3dN.2 23us : clockevents_program_event <-tick_program_event
2221 <idle>-0 3dN.2 23us : ktime_get <-clockevents_program_event
2222 <idle>-0 3dN.2 23us : lapic_next_event <-clockevents_program_event
2223 <idle>-0 3dN.2 24us : _raw_spin_unlock_irqrestore <-__hrtimer_start_range_ns
2224 <idle>-0 3dN.2 24us : sub_preempt_count <-_raw_spin_unlock_irqrestore
2225 <idle>-0 3dN.1 24us : account_idle_ticks <-tick_nohz_idle_exit
2226 <idle>-0 3dN.1 24us : account_idle_time <-account_idle_ticks
2227 <idle>-0 3.N.1 25us : sub_preempt_count <-cpu_idle
2228 <idle>-0 3.N.. 25us : schedule <-cpu_idle
2229 <idle>-0 3.N.. 25us : __schedule <-preempt_schedule
2230 <idle>-0 3.N.. 26us : add_preempt_count <-__schedule
2231 <idle>-0 3.N.1 26us : rcu_note_context_switch <-__schedule
2232 <idle>-0 3.N.1 26us : rcu_sched_qs <-rcu_note_context_switch
2233 <idle>-0 3dN.1 27us : rcu_preempt_qs <-rcu_note_context_switch
2234 <idle>-0 3.N.1 27us : _raw_spin_lock_irq <-__schedule
2235 <idle>-0 3dN.1 27us : add_preempt_count <-_raw_spin_lock_irq
2236 <idle>-0 3dN.2 28us : put_prev_task_idle <-__schedule
2237 <idle>-0 3dN.2 28us : pick_next_task_stop <-pick_next_task
2238 <idle>-0 3dN.2 28us : pick_next_task_rt <-pick_next_task
2239 <idle>-0 3dN.2 29us : dequeue_pushable_task <-pick_next_task_rt
2240 <idle>-0 3d..3 29us : __schedule <-preempt_schedule
2241 <idle>-0 3d..3 30us : 0:120:R ==> [003] 2448: 94:R sleep
2246 The interrupt went off while when the system was idle. Somewhere
2251 --------------------------
2258 # echo 0 > options/function-trace
2263 # chrt -f 5 sleep 1
2268 # wakeup_rt latency trace v1.1.5 on 3.8.0-test+
2269 # --------------------------------------------------------------------
2271 # -----------------
2272 # | task: sleep-5882 (uid:0 nice:0 policy:1 rt_prio:5)
2273 # -----------------
2275 # _------=> CPU#
2276 # / _-----=> irqs-off
2277 # | / _----=> need-resched
2278 # || / _---=> hardirq/softirq
2279 # ||| / _--=> preempt-depth
2281 # cmd pid ||||| time | caller
2283 <idle>-0 2d.h4 0us : 0:120:R + [002] 5882: 94:R sleep
2284 <idle>-0 2d.h4 0us : ttwu_do_activate.constprop.87 <-try_to_wake_up
2285 <idle>-0 2d.h4 1us : sched_wakeup: comm=sleep pid=5882 prio=94 success=1 target_cpu=002
2286 <idle>-0 2dNh2 1us : hrtimer_expire_exit: hrtimer=ffff88007796feb8
2287 <idle>-0 2.N.2 2us : power_end: cpu_id=2
2288 <idle>-0 2.N.2 3us : cpu_idle: state=4294967295 cpu_id=2
2289 <idle>-0 2dN.3 4us : hrtimer_cancel: hrtimer=ffff88007d50d5e0
2290 …<idle>-0 2dN.3 4us : hrtimer_start: hrtimer=ffff88007d50d5e0 function=tick_sched_timer ex…
2291 <idle>-0 2.N.2 5us : rcu_utilization: Start context switch
2292 <idle>-0 2.N.2 5us : rcu_utilization: End context switch
2293 <idle>-0 2d..3 6us : __schedule <-schedule
2294 <idle>-0 2d..3 6us : 0:120:R ==> [002] 5882: 94:R sleep
2298 -------------------------
2311 # entries-in-buffer/entries-written: 13/13 #P:8
2313 # _-----=> irqs-off
2314 # / _----=> need-resched
2315 # | / _---=> hardirq/softirq
2316 # || / _--=> preempt-depth
2318 # TASK-PID CPU# |||| TIMESTAMP FUNCTION
2320 …<...>-1729 [001] d... 678.473449: #1 inner/outer(us): 11/12 ts:1581527483.343962693 co…
2321 …<...>-1729 [004] d... 689.556542: #2 inner/outer(us): 16/9 ts:1581527494.889008092 co…
2322 …<...>-1729 [005] d... 714.756290: #3 inner/outer(us): 16/16 ts:1581527519.678961629 co…
2323 …<...>-1729 [001] d... 718.788247: #4 inner/outer(us): 9/17 ts:1581527523.889012713 co…
2324 …<...>-1729 [002] d... 719.796341: #5 inner/outer(us): 13/9 ts:1581527524.912872606 co…
2325 …<...>-1729 [006] d... 844.787091: #6 inner/outer(us): 9/12 ts:1581527649.889048502 co…
2326 …<...>-1729 [003] d... 849.827033: #7 inner/outer(us): 18/9 ts:1581527654.889013793 co…
2327 …<...>-1729 [007] d... 853.859002: #8 inner/outer(us): 9/12 ts:1581527658.889065736 co…
2328 …<...>-1729 [001] d... 855.874978: #9 inner/outer(us): 9/11 ts:1581527660.861991877 co…
2329 …<...>-1729 [001] d... 863.938932: #10 inner/outer(us): 9/11 ts:1581527668.970010500 co…
2330 …<...>-1729 [007] d... 878.050780: #11 inner/outer(us): 9/12 ts:1581527683.385002600 co…
2331 …<...>-1729 [007] d... 886.114702: #12 inner/outer(us): 9/12 ts:1581527691.385001600 co…
2357 nmi-total:7 nmi-count:1
2360 test, the time spent in NMI is reported in "nmi-total" (in
2363 All architectures that have NMIs will show the "nmi-count" if an
2378 The length of time the test runs with interrupts disabled.
2381 The length of time of the window which the test
2394 --------
2410 # entries-in-buffer/entries-written: 24799/24799 #P:4
2412 # _-----=> irqs-off
2413 # / _----=> need-resched
2414 # | / _---=> hardirq/softirq
2415 # || / _--=> preempt-depth
2417 # TASK-PID CPU# |||| TIMESTAMP FUNCTION
2419 bash-1994 [002] .... 3082.063030: mutex_unlock <-rb_simple_write
2420 bash-1994 [002] .... 3082.063031: __mutex_unlock_slowpath <-mutex_unlock
2421 bash-1994 [002] .... 3082.063031: __fsnotify_parent <-fsnotify_modify
2422 bash-1994 [002] .... 3082.063032: fsnotify <-fsnotify_modify
2423 bash-1994 [002] .... 3082.063032: __srcu_read_lock <-fsnotify
2424 bash-1994 [002] .... 3082.063032: add_preempt_count <-__srcu_read_lock
2425 bash-1994 [002] ...1 3082.063032: sub_preempt_count <-__srcu_read_lock
2426 bash-1994 [002] .... 3082.063033: __srcu_read_unlock <-fsnotify
2454 ---------------------
2468 # TASK-PID CPU# TIMESTAMP FUNCTION
2470 yum-updatesd-3111 [003] 1637.254676: finish_task_switch <-thread_return
2471 yum-updatesd-3111 [003] 1637.254681: hrtimer_cancel <-schedule_hrtimeout_range
2472 yum-updatesd-3111 [003] 1637.254682: hrtimer_try_to_cancel <-hrtimer_cancel
2473 yum-updatesd-3111 [003] 1637.254683: lock_hrtimer_base <-hrtimer_try_to_cancel
2474 yum-updatesd-3111 [003] 1637.254685: fget_light <-do_sys_poll
2475 yum-updatesd-3111 [003] 1637.254686: pipe_poll <-do_sys_poll
2480 # TASK-PID CPU# TIMESTAMP FUNCTION
2483 yum-updatesd-3111 [003] 1701.957688: free_poll_entry <-poll_freewait
2484 yum-updatesd-3111 [003] 1701.957689: remove_wait_queue <-free_poll_entry
2485 yum-updatesd-3111 [003] 1701.957691: fput <-free_poll_entry
2486 yum-updatesd-3111 [003] 1701.957692: audit_syscall_exit <-sysret_audit
2487 yum-updatesd-3111 [003] 1701.957693: path_put <-audit_syscall_exit
2550 exit(-1);
2559 exit(-1);
2582 tracefs=`sed -ne 's/^tracefs \(.*\) tracefs.*/\1/p' /proc/mounts`
2591 ---------------------------
2604 - measure of a function's time execution
2605 - having a reliable call stack to draw function calls graph
2609 - you want to find the reason of a strange kernel behavior and
2613 - you are experiencing weird latencies but it's difficult to
2616 - you want to find quickly which path is taken by a specific
2619 - you just want to peek inside a working kernel and want to see
2651 - The cpu number on which the function executed is default
2656 - hide: echo nofuncgraph-cpu > trace_options
2657 - show: echo funcgraph-cpu > trace_options
2659 - The duration (function's time of execution) is displayed on
2664 - hide: echo nofuncgraph-duration > trace_options
2665 - show: echo funcgraph-duration > trace_options
2667 - The overhead field precedes the duration field in case of
2670 - hide: echo nofuncgraph-overhead > trace_options
2671 - show: echo funcgraph-overhead > trace_options
2672 - depends on: funcgraph-duration
2724 - The task/pid field displays the thread cmdline and pid which
2727 - hide: echo nofuncgraph-proc > trace_options
2728 - show: echo funcgraph-proc > trace_options
2736 0) sh-4802 | | d_free() {
2737 0) sh-4802 | | call_rcu() {
2738 0) sh-4802 | | __call_rcu() {
2739 0) sh-4802 | 0.616 us | rcu_process_gp_end();
2740 0) sh-4802 | 0.586 us | check_for_new_grace_period();
2741 0) sh-4802 | 2.899 us | }
2742 0) sh-4802 | 4.040 us | }
2743 0) sh-4802 | 5.151 us | }
2744 0) sh-4802 | + 49.370 us | }
2747 - The absolute time field is an absolute timestamp given by the
2748 system clock since it started. A snapshot of this time is
2751 - hide: echo nofuncgraph-abstime > trace_options
2752 - show: echo funcgraph-abstime > trace_options
2757 # TIME CPU DURATION FUNCTION CALLS
2783 - hide: echo nofuncgraph-tail > trace_options
2784 - show: echo funcgraph-tail > trace_options
2786 Example with nofuncgraph-tail (default)::
2794 Example with funcgraph-tail::
2807 - hide: echo nofuncgraph-retval > trace_options
2808 - show: echo funcgraph-retval > trace_options
2810 Example with funcgraph-retval::
2820 1) 2.335 us | } /* cpu_cgroup_can_attach = -22 */
2821 1) 4.369 us | } /* cgroup_migrate_execute = -22 */
2822 1) 7.143 us | } /* cgroup_migrate = -22 */
2825 returned the error code -22 firstly, then we can read the code
2828 When the option funcgraph-retval-hex is not set, the return value can
2833 - smart: echo nofuncgraph-retval-hex > trace_options
2834 - hexadecimal: echo funcgraph-retval-hex > trace_options
2836 Example with funcgraph-retval-hex::
2850 At present, there are some limitations when using the funcgraph-retval
2853 - Even if the function return type is void, a return value will still
2856 - Even if return values are stored in multiple registers, only the
2859 a 64-bit return value, with the lower 32 bits saved in eax and the
2863 - In certain procedure call standards, such as arm64's AAPCS64, when a
2867 when using a u8 in a 64-bit GPR, bits [63:8] may contain arbitrary values,
2897 return -EINVAL;
2909 MOV x0, #-EINVAL
2934 --------------
2939 every kernel function, produced by the -pg switch in gcc),
2941 include the -pg switch in the compiling of the kernel.)
2943 At compile time every C file object is run through the
2947 with gcc version 4.6, the -mfentry has been added for x86, which
2958 The recordmcount program re-links this section back into the
2976 patched back to calls. But this time, they do not call mcount
2988 problems with other CPUs executing it at the same time.
2990 One special side-effect to the recording of the functions being
3030 # entries-in-buffer/entries-written: 5/5 #P:4
3032 # _-----=> irqs-off
3033 # / _----=> need-resched
3034 # | / _---=> hardirq/softirq
3035 # || / _--=> preempt-depth
3037 # TASK-PID CPU# |||| TIMESTAMP FUNCTION
3039 usleep-2665 [001] .... 4186.475355: sys_nanosleep <-system_call_fastpath
3040 <idle>-0 [001] d.h1 4186.475409: hrtimer_interrupt <-smp_apic_timer_interrupt
3041 usleep-2665 [001] d.h1 4186.475426: hrtimer_interrupt <-smp_apic_timer_interrupt
3042 <idle>-0 [003] d.h1 4186.475426: hrtimer_interrupt <-smp_apic_timer_interrupt
3043 <idle>-0 [002] d.h1 4186.475427: hrtimer_interrupt <-smp_apic_timer_interrupt
3077 # entries-in-buffer/entries-written: 897/897 #P:4
3079 # _-----=> irqs-off
3080 # / _----=> need-resched
3081 # | / _---=> hardirq/softirq
3082 # || / _--=> preempt-depth
3084 # TASK-PID CPU# |||| TIMESTAMP FUNCTION
3086 <idle>-0 [003] dN.1 4228.547803: hrtimer_cancel <-tick_nohz_idle_exit
3087 <idle>-0 [003] dN.1 4228.547804: hrtimer_try_to_cancel <-hrtimer_cancel
3088 <idle>-0 [003] dN.2 4228.547805: hrtimer_force_reprogram <-__remove_hrtimer
3089 <idle>-0 [003] dN.1 4228.547805: hrtimer_forward <-tick_nohz_idle_exit
3090 … <idle>-0 [003] dN.1 4228.547805: hrtimer_start_range_ns <-hrtimer_start_expires.constprop.11
3091 <idle>-0 [003] d..1 4228.547858: hrtimer_get_next_event <-get_next_timer_interrupt
3092 <idle>-0 [003] d..1 4228.547859: hrtimer_start <-__tick_nohz_idle_enter
3093 <idle>-0 [003] d..2 4228.547860: hrtimer_force_reprogram <-__rem
3166 # entries-in-buffer/entries-written: 39608/39608 #P:4
3168 # _-----=> irqs-off
3169 # / _----=> need-resched
3170 # | / _---=> hardirq/softirq
3171 # || / _--=> preempt-depth
3173 # TASK-PID CPU# |||| TIMESTAMP FUNCTION
3175 bash-1994 [000] .... 4342.324896: file_ra_state_init <-do_dentry_open
3176 bash-1994 [000] .... 4342.324897: open_check_o_direct <-do_last
3177 bash-1994 [000] .... 4342.324897: ima_file_check <-do_last
3178 bash-1994 [000] .... 4342.324898: process_measurement <-ima_file_check
3179 bash-1994 [000] .... 4342.324898: ima_get_action <-process_measurement
3180 bash-1994 [000] .... 4342.324898: ima_match_policy <-ima_get_action
3181 bash-1994 [000] .... 4342.324899: do_truncate <-do_last
3182 bash-1994 [000] .... 4342.324899: setattr_should_drop_suidgid <-do_truncate
3183 bash-1994 [000] .... 4342.324899: notify_change <-do_truncate
3184 bash-1994 [000] .... 4342.324900: current_fs_time <-notify_change
3185 bash-1994 [000] .... 4342.324900: current_kernel_time <-current_fs_time
3186 bash-1994 [000] .... 4342.324900: timespec_trunc <-current_fs_time
3191 ------------------------------------
3196 case of setting thousands of specific functions at a time. By passing
3209 # head -1 available_filter_functions
3215 # head -50 available_filter_functions | tail -1
3224 ---------------------------------------------
3227 function tracer and the function-graph-tracer, there are some
3228 special features only available in the function-graph tracer.
3285 --------------
3287 Note, the proc sysctl ftrace_enable is a big on/off switch for the
3309 ---------------
3318 - mod:
3350 - traceon/traceoff:
3351 These commands turn tracing on and off when the specified
3353 tracing system is turned on and off. If unspecified, there is
3374 - snapshot:
3390 - enable_event/disable_event:
3414 - dump:
3421 - cpudump:
3427 - stacktrace:
3431 ----------
3448 # entries-in-buffer/entries-written: 0/0 #P:4
3450 # _-----=> irqs-off
3451 # / _----=> need-resched
3452 # | / _---=> hardirq/softirq
3453 # || / _--=> preempt-depth
3455 # TASK-PID CPU# |||| TIMESTAMP FUNCTION
3460 bash-1994 [000] .... 5281.568961: mutex_unlock <-rb_simple_write
3461 bash-1994 [000] .... 5281.568963: __mutex_unlock_slowpath <-mutex_unlock
3462 bash-1994 [000] .... 5281.568963: __fsnotify_parent <-fsnotify_modify
3463 bash-1994 [000] .... 5281.568964: fsnotify <-fsnotify_modify
3464 bash-1994 [000] .... 5281.568964: __srcu_read_lock <-fsnotify
3465 bash-1994 [000] .... 5281.568964: add_preempt_count <-__srcu_read_lock
3466 bash-1994 [000] ...1 5281.568965: sub_preempt_count <-__srcu_read_lock
3467 bash-1994 [000] .... 5281.568965: __srcu_read_unlock <-fsnotify
3468 bash-1994 [000] .... 5281.568967: sys_dup2 <-system_call_fastpath
3478 -------------
3505 much, it can cause Out-Of-Memory to trigger.
3509 -bash: echo: write error: Cannot allocate memory
3536 --------
3544 in time without stopping tracing. Ftrace swaps the current
3564 +--------------+------------+------------+------------+
3568 +--------------+------------+------------+------------+
3570 +--------------+------------+------------+------------+
3580 # entries-in-buffer/entries-written: 71/71 #P:8
3582 # _-----=> irqs-off
3583 # / _----=> need-resched
3584 # | / _---=> hardirq/softirq
3585 # || / _--=> preempt-depth
3587 # TASK-PID CPU# |||| TIMESTAMP FUNCTION
3589 …<idle>-0 [005] d... 2440.603828: sched_switch: prev_comm=swapper/5 prev_pid=0 prev_prio=120 …
3590 …sleep-2242 [005] d... 2440.603846: sched_switch: prev_comm=snapshot-test-2 prev_pid=2242 prev_pr…
3592 …<idle>-0 [002] d... 2440.707230: sched_switch: prev_comm=swapper/2 prev_pid=0 prev_prio=120 p…
3597 # entries-in-buffer/entries-written: 77/77 #P:8
3599 # _-----=> irqs-off
3600 # / _----=> need-resched
3601 # | / _---=> hardirq/softirq
3602 # || / _--=> preempt-depth
3604 # TASK-PID CPU# |||| TIMESTAMP FUNCTION
3606 …<idle>-0 [007] d... 2440.707395: sched_switch: prev_comm=swapper/7 prev_pid=0 prev_prio=120 p…
3607 …snapshot-test-2-2229 [002] d... 2440.707438: sched_switch: prev_comm=snapshot-test-2 prev_pid=22…
3623 ---------
3669 bash-2044 [002] .... 10594.481032: _raw_spin_lock_irqsave <-get_page_from_freelist
3670 bash-2044 [002] d... 10594.481032: add_preempt_count <-_raw_spin_lock_irqsave
3671 bash-2044 [002] d..1 10594.481032: __rmqueue <-get_page_from_freelist
3672 bash-2044 [002] d..1 10594.481033: _raw_spin_unlock <-get_page_from_freelist
3673 bash-2044 [002] d..1 10594.481033: sub_preempt_count <-_raw_spin_unlock
3674 … bash-2044 [002] d... 10594.481033: get_pageblock_flags_group <-get_pageblock_migratetype
3675 bash-2044 [002] d... 10594.481034: __mod_zone_page_state <-get_page_from_freelist
3676 bash-2044 [002] d... 10594.481034: zone_statistics <-get_page_from_freelist
3677 bash-2044 [002] d... 10594.481034: __inc_zone_state <-zone_statistics
3678 bash-2044 [002] d... 10594.481034: __inc_zone_state <-zone_statistics
3679 bash-2044 [002] .... 10594.481035: arch_dup_task_struct <-copy_process
3683 …bash-1998 [000] d..4 136.676759: sched_wakeup: comm=kworker/0:1 pid=59 prio=120 success=1 targe…
3684 …bash-1998 [000] dN.4 136.676760: sched_wakeup: comm=bash pid=1998 prio=120 success=1 target_cpu…
3685 …<idle>-0 [003] d.h3 136.676906: sched_wakeup: comm=rcu_preempt pid=9 prio=120 success=1 targ…
3686 …<idle>-0 [003] d..3 136.676909: sched_switch: prev_comm=swapper/3 prev_pid=0 prev_prio=120 p…
3687 …rcu_preempt-9 [003] d..3 136.676916: sched_switch: prev_comm=rcu_preempt prev_pid=9 prev_pri…
3688 …bash-1998 [000] d..4 136.677014: sched_wakeup: comm=kworker/0:1 pid=59 prio=120 success=1 targe…
3689 …bash-1998 [000] dN.4 136.677016: sched_wakeup: comm=bash pid=1998 prio=120 success=1 target_cpu…
3690 …bash-1998 [000] d..3 136.677018: sched_switch: prev_comm=bash prev_pid=1998 prev_prio=120 prev_…
3691 …kworker/0:1-59 [000] d..4 136.677022: sched_wakeup: comm=sshd pid=1995 prio=120 success=1 tar…
3692 …kworker/0:1-59 [000] d..3 136.677025: sched_switch: prev_comm=kworker/0:1 prev_pid=59 prev_pr…
3696 migration/1-14 [001] d.h3 138.732674: softirq_raise: vec=3 [action=NET_RX]
3697 <idle>-0 [001] dNh3 138.732725: softirq_raise: vec=3 [action=NET_RX]
3698 bash-1998 [000] d.h1 138.733101: softirq_raise: vec=1 [action=TIMER]
3699 bash-1998 [000] d.h1 138.733102: softirq_raise: vec=9 [action=RCU]
3700 bash-1998 [000] ..s2 138.733105: softirq_entry: vec=1 [action=TIMER]
3701 bash-1998 [000] ..s2 138.733106: softirq_exit: vec=1 [action=TIMER]
3702 bash-1998 [000] ..s2 138.733106: softirq_entry: vec=9 [action=RCU]
3703 bash-1998 [000] ..s2 138.733109: softirq_exit: vec=9 [action=RCU]
3704 sshd-1995 [001] d.h1 138.733278: irq_handler_entry: irq=21 name=uhci_hcd:usb4
3705 sshd-1995 [001] d.h1 138.733280: irq_handler_exit: irq=21 ret=unhandled
3706 sshd-1995 [001] d.h1 138.733281: irq_handler_entry: irq=21 name=eth0
3707 sshd-1995 [001] d.h1 138.733283: irq_handler_exit: irq=21 ret=handled
3713 # entries-in-buffer/entries-written: 18996/18996 #P:4
3715 # _-----=> irqs-off
3716 # / _----=> need-resched
3717 # | / _---=> hardirq/softirq
3718 # || / _--=> preempt-depth
3720 # TASK-PID CPU# |||| TIMESTAMP FUNCTION
3722 bash-1998 [000] d... 140.733501: sys_write -> 0x2
3723 bash-1998 [000] d... 140.733504: sys_dup2(oldfd: a, newfd: 1)
3724 bash-1998 [000] d... 140.733506: sys_dup2 -> 0x1
3725 bash-1998 [000] d... 140.733508: sys_fcntl(fd: a, cmd: 1, arg: 0)
3726 bash-1998 [000] d... 140.733509: sys_fcntl -> 0x1
3727 bash-1998 [000] d... 140.733510: sys_close(fd: a)
3728 bash-1998 [000] d... 140.733510: sys_close -> 0x0
3729 …bash-1998 [000] d... 140.733514: sys_rt_sigprocmask(how: 0, nset: 0, oset: 6e2768, sigsetsize: …
3730 bash-1998 [000] d... 140.733515: sys_rt_sigprocmask -> 0x0
3731 …bash-1998 [000] d... 140.733516: sys_rt_sigaction(sig: 2, act: 7fff718846f0, oact: 7fff71884650…
3732 bash-1998 [000] d... 140.733516: sys_rt_sigaction -> 0x0
3750 -----------
3781 ----- ---- --------
3801 Note, if -mfentry is being used by gcc, functions get traced before
3803 are not tested by the stack tracer when -mfentry is used.
3805 Currently, -mfentry is used by gcc 4.6.0 and above on x86 only.
3808 ----
3809 More details can be found in the source code, in the `kernel/trace/*.c` files.