Lines Matching +full:exit +full:- +full:latency +full:- +full:us
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.
28 There's latency tracing to examine what occurs between interrupts
41 ----------------------
43 See Documentation/trace/ftrace-design.rst for details for arch porters and such.
47 ---------------
60 mount -t tracefs nodev /sys/kernel/tracing
65 ln -s /sys/kernel/tracing /tracing
118 set this file to "0". User space can re-enable tracing by
123 be re-enabled by user space using this file.
166 Some of the tracers record the max latency.
170 recorded if the latency is greater than the value in this file
173 By echoing in a time into this file, no latency will be recorded
178 Some latency tracers will record a trace whenever the
179 latency is greater than the number 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
300 cause PIDs of tasks that exit to be removed from the file.
307 If the "function-fork" option is set, then when a task whose
311 cause PIDs of tasks that exit to be removed from the file.
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
391 the "ip modify" attribute (thus the regs->ip can be changed),
476 If the option "record-cmd" is set to "0", then comms of tasks
487 If the option "record-tgid" is set, on each scheduling context switch
489 the thread to its TGID. By default, the "record-tgid" option is
528 [local] global counter x86-tsc
555 x86-tsc:
559 ppc-tb:
582 Also on 32-bit systems, it's possible that the 64-bit boot offset
588 This is the tai clock (CLOCK_TAI) and is derived from the wall-
702 delta: Default timestamp mode - timestamp is a delta against
703 a per-buffer timestamp.
711 Directory for the Hardware Latency Detector.
712 See "Hardware Latency Detector" section below.
777 event (ring buffer is re-entrant), that it fills the
796 -----------
809 and exit of the functions. It then provides the ability
826 The Hardware Latency tracer is used to detect if the hardware
827 produces any latency. See "Hardware Latency Detector" section
833 the trace with the longest max latency.
836 trace with the latency-format option enabled, which
852 Traces and records the max latency that it takes for
859 Traces and records the max latency that it takes for just
865 Traces and records the max latency that it takes for
890 ----------------
922 ----------------------------
926 user-land utilities).
929 --------------
935 # entries-in-buffer/entries-written: 140080/250280 #P:4
937 # _-----=> irqs-off
938 # / _----=> need-resched
939 # | / _---=> hardirq/softirq
940 # || / _--=> preempt-depth
942 # TASK-PID CPU# |||| TIMESTAMP FUNCTION
944 bash-1977 [000] .... 17284.993652: sys_close <-system_call_fastpath
945 bash-1977 [000] .... 17284.993653: __close_fd <-sys_close
946 bash-1977 [000] .... 17284.993653: _raw_spin_lock <-__close_fd
947 sshd-1974 [003] .... 17284.993653: __srcu_read_unlock <-fsnotify
948 bash-1977 [000] .... 17284.993654: add_preempt_count <-_raw_spin_lock
949 bash-1977 [000] ...1 17284.993655: _raw_spin_unlock <-__close_fd
950 bash-1977 [000] ...1 17284.993656: sub_preempt_count <-_raw_spin_unlock
951 bash-1977 [000] .... 17284.993657: filp_close <-__close_fd
952 bash-1977 [000] .... 17284.993657: dnotify_flush <-filp_close
953 sshd-1974 [003] .... 17284.993658: sys_select <-system_call_fastpath
960 lost due to the buffer filling up (250280 - 140080 = 110200 events
964 PID "1977", the CPU that it was running on "000", the latency format
970 Latency trace format
971 --------------------
973 When the latency-format option is enabled or when one of the latency
975 why a latency happened. Here is a typical trace::
979 # irqsoff latency trace v1.1.5 on 3.8.0-test+
980 # --------------------------------------------------------------------
981 # latency: 259 us, #4/4, CPU#2 | (M:preempt VP:0, KP:0, SP:0 HP:0 #P:4)
982 # -----------------
983 # | task: ps-6143 (uid:0 nice:0 policy:0 rt_prio:0)
984 # -----------------
989 # _------=> CPU#
990 # / _-----=> irqs-off
991 # | / _----=> need-resched
992 # || / _---=> hardirq/softirq
993 # ||| / _--=> preempt-depth
997 ps-6143 2d... 0us!: trace_hardirqs_off <-__lock_task_sighand
998 ps-6143 2d..1 259us+: trace_hardirqs_on <-_raw_spin_unlock_irqrestore
999 ps-6143 2d..1 263us+: time_hardirqs_on <-_raw_spin_unlock_irqrestore
1000 ps-6143 2d..1 306us : <stack trace>
1016 (3.8). Then it displays the max latency in microseconds (259 us). The number
1021 The task is the process that was running when the latency
1027 - __lock_task_sighand is where the interrupts were disabled.
1028 - _raw_spin_unlock_irqrestore is where they were enabled again.
1039 irqs-off: 'd' interrupts are disabled. '.' otherwise.
1041 need-resched:
1042 - 'B' all, TIF_NEED_RESCHED, PREEMPT_NEED_RESCHED and TIF_RESCHED_LAZY is set,
1043 - 'N' both TIF_NEED_RESCHED and PREEMPT_NEED_RESCHED is set,
1044 - 'n' only TIF_NEED_RESCHED is set,
1045 - 'p' only PREEMPT_NEED_RESCHED is set,
1046 - 'L' both PREEMPT_NEED_RESCHED and TIF_RESCHED_LAZY is set,
1047 - 'b' both TIF_NEED_RESCHED and TIF_RESCHED_LAZY is set,
1048 - 'l' only TIF_RESCHED_LAZY is set
1049 - '.' otherwise.
1052 - 'Z' - NMI occurred inside a hardirq
1053 - 'z' - NMI is running
1054 - 'H' - hard irq occurred inside a softirq.
1055 - 'h' - hard irq is running
1056 - 's' - soft irq is running
1057 - '.' - normal context.
1059 preempt-depth: The level of preempt_disabled
1064 When the latency-format option is enabled, the trace file
1066 trace. This differs from the output when latency-format
1075 - '$' - greater than 1 second
1076 - '@' - greater than 100 millisecond
1077 - '*' - greater than 10 millisecond
1078 - '#' - greater than 1000 microsecond
1079 - '!' - greater than 100 microsecond
1080 - '+' - greater than 10 microsecond
1081 - ' ' - less than or equal to 10 microsecond.
1085 Note, the latency tracers will usually end with a back trace
1086 to easily find where the latency occurred.
1089 -------------
1096 print-parent
1097 nosym-offset
1098 nosym-addr
1108 nosym-userobj
1109 noprintk-msg-only
1110 context-info
1111 nolatency-format
1112 record-cmd
1113 norecord-tgid
1116 irq-info
1118 noevent-fork
1119 function-trace
1120 nofunction-fork
1121 nodisplay-graph
1128 echo noprint-parent > trace_options
1132 echo sym-offset > trace_options
1136 print-parent
1141 print-parent:
1142 bash-4000 [01] 1477.606694: simple_strtoul <-kstrtoul
1144 noprint-parent:
1145 bash-4000 [01] 1477.606694: simple_strtoul
1148 sym-offset
1155 sym-offset:
1156 bash-4000 [01] 1477.606694: simple_strtoul+0x6/0xa0
1158 sym-addr
1163 sym-addr:
1164 bash-4000 [01] 1477.606694: simple_strtoul <c0339346>
1168 latency-format option is enabled.
1218 <idle>-0 [001] dNs4 21169.031481: wake_up_idle_cpu <-add_timer_on
1219 <idle>-0 [001] dNs4 21169.031482: _raw_spin_unlock_irqrestore <-add_timer_on
1220 <idle>-0 [001] .Ns4 21169.031484: sub_preempt_count <-_raw_spin_unlock_irqrestore
1222 <idle>-0 [002] .N.1 21169.031484: rcu_idle_exit <-cpu_idle
1223 <idle>-0 [001] .Ns3 21169.031484: _raw_spin_unlock <-clocksource_watchdog
1224 <idle>-0 [001] .Ns3 21169.031485: sub_preempt_count <-_raw_spin_unlock
1231 sym-userobj
1242 a.out-1623 [000] 40874.465068: /root/a.out[+0x480] <-/root/a.out[+0
1243 x494] <- /root/a.out[+0x4a8] <- /lib/libc-2.7.so[+0x1e1a6]
1246 printk-msg-only
1251 context-info
1255 latency-format
1258 latency, as described in "Latency trace format".
1260 pause-on-trace
1266 hash-ptr
1272 record-cmd
1280 record-tgid
1297 irq-info
1303 # entries-in-buffer/entries-written: 144405/9452052 #P:4
1305 # TASK-PID CPU# TIMESTAMP FUNCTION
1307 <idle>-0 [002] 23636.756054: ttwu_do_activate.constprop.89 <-try_to_wake_up
1308 <idle>-0 [002] 23636.756054: activate_task <-ttwu_do_activate.constprop.89
1309 <idle>-0 [002] 23636.756055: enqueue_task <-activate_task
1317 event-fork
1320 tasks fork. Also, when tasks with PIDs in set_event_pid exit,
1325 function-trace
1326 The latency tracers will enable function tracing
1328 it is disabled, the latency tracers do not trace
1330 when performing latency tests.
1332 function-fork
1336 set_ftrace_pid exit, their PIDs will be removed from the
1341 display-graph
1342 When set, the latency tracers (irqsoff, wakeup, etc) will
1377 funcgraph-overrun
1388 funcgraph-cpu
1392 funcgraph-overhead
1398 funcgraph-proc
1405 funcgraph-duration
1410 funcgraph-abstime
1413 funcgraph-irqs
1417 funcgraph-tail
1423 funcgraph-retval
1428 funcgraph-retval-hex
1436 sleep-time
1442 graph-time
1456 -------
1461 the kernel know of a new mouse event. The result is a latency
1465 disabled. When a new maximum latency is hit, the tracer saves
1466 the trace leading up to that latency point so that every time a
1473 # echo 0 > options/function-trace
1477 # ls -ltr
1483 # irqsoff latency trace v1.1.5 on 3.8.0-test+
1484 # --------------------------------------------------------------------
1485 # latency: 16 us, #4/4, CPU#0 | (M:preempt VP:0, KP:0, SP:0 HP:0 #P:4)
1486 # -----------------
1487 # | task: swapper/0-0 (uid:0 nice:0 policy:0 rt_prio:0)
1488 # -----------------
1493 # _------=> CPU#
1494 # / _-----=> irqs-off
1495 # | / _----=> need-resched
1496 # || / _---=> hardirq/softirq
1497 # ||| / _--=> preempt-depth
1501 <idle>-0 0d.s2 0us+: _raw_spin_lock_irq <-run_timer_softirq
1502 <idle>-0 0dNs3 17us : _raw_spin_unlock_irq <-run_timer_softirq
1503 <idle>-0 0dNs3 17us+: trace_hardirqs_on <-run_timer_softirq
1504 <idle>-0 0dNs3 25us : <stack trace>
1520 Here we see that we had a latency of 16 microseconds (which is
1523 timestamp 25us occurred because the clock was incremented
1524 between the time of recording the max latency and the time of
1525 recording the function that had that latency.
1527 Note the above example had function-trace not set. If we set
1528 function-trace, we get a much larger output::
1530 with echo 1 > options/function-trace
1534 # irqsoff latency trace v1.1.5 on 3.8.0-test+
1535 # --------------------------------------------------------------------
1536 # latency: 71 us, #168/168, CPU#3 | (M:preempt VP:0, KP:0, SP:0 HP:0 #P:4)
1537 # -----------------
1538 # | task: bash-2042 (uid:0 nice:0 policy:0 rt_prio:0)
1539 # -----------------
1544 # _------=> CPU#
1545 # / _-----=> irqs-off
1546 # | / _----=> need-resched
1547 # || / _---=> hardirq/softirq
1548 # ||| / _--=> preempt-depth
1552 bash-2042 3d... 0us : _raw_spin_lock_irqsave <-ata_scsi_queuecmd
1553 bash-2042 3d... 0us : add_preempt_count <-_raw_spin_lock_irqsave
1554 bash-2042 3d..1 1us : ata_scsi_find_dev <-ata_scsi_queuecmd
1555 bash-2042 3d..1 1us : __ata_scsi_find_dev <-ata_scsi_find_dev
1556 bash-2042 3d..1 2us : ata_find_dev.part.14 <-__ata_scsi_find_dev
1557 bash-2042 3d..1 2us : ata_qc_new_init <-__ata_scsi_queuecmd
1558 bash-2042 3d..1 3us : ata_sg_init <-__ata_scsi_queuecmd
1559 bash-2042 3d..1 4us : ata_scsi_rw_xlat <-__ata_scsi_queuecmd
1560 bash-2042 3d..1 4us : ata_build_rw_tf <-ata_scsi_rw_xlat
1562 bash-2042 3d..1 67us : delay_tsc <-__delay
1563 bash-2042 3d..1 67us : add_preempt_count <-delay_tsc
1564 bash-2042 3d..2 67us : sub_preempt_count <-delay_tsc
1565 bash-2042 3d..1 67us : add_preempt_count <-delay_tsc
1566 bash-2042 3d..2 68us : sub_preempt_count <-delay_tsc
1567 bash-2042 3d..1 68us+: ata_bmdma_start <-ata_bmdma_qc_issue
1568 bash-2042 3d..1 71us : _raw_spin_unlock_irqrestore <-ata_scsi_queuecmd
1569 bash-2042 3d..1 71us : _raw_spin_unlock_irqrestore <-ata_scsi_queuecmd
1570 bash-2042 3d..1 72us+: trace_hardirqs_on <-ata_scsi_queuecmd
1571 bash-2042 3d..1 120us : <stack trace>
1599 Here we traced a 71 microsecond latency. But we also see all the
1602 overhead may extend the latency times. But nevertheless, this
1606 display-graph option::
1608 with echo 1 > options/display-graph
1612 # irqsoff latency trace v1.1.5 on 4.20.0-rc6+
1613 # --------------------------------------------------------------------
1614 # latency: 3751 us, #274/274, CPU#0 | (M:desktop VP:0, KP:0, SP:0 HP:0 #P:4)
1615 # -----------------
1616 # | task: bash-1507 (uid:0 nice:0 policy:0 rt_prio:0)
1617 # -----------------
1622 # _-----=> irqs-off
1623 # / _----=> need-resched
1624 # | / _---=> hardirq/softirq
1625 # || / _--=> preempt-depth
1629 0 us | 0) bash-1507 | d... | 0.000 us | _raw_spin_lock_irqsave();
1630 0 us | 0) bash-1507 | d..1 | 0.378 us | do_raw_spin_trylock();
1631 1 us | 0) bash-1507 | d..2 | | set_track() {
1632 2 us | 0) bash-1507 | d..2 | | save_stack_trace() {
1633 2 us | 0) bash-1507 | d..2 | | __save_stack_trace() {
1634 3 us | 0) bash-1507 | d..2 | | __unwind_start() {
1635 3 us | 0) bash-1507 | d..2 | | get_stack_info() {
1636 3 us | 0) bash-1507 | d..2 | 0.351 us | in_task_stack();
1637 4 us | 0) bash-1507 | d..2 | 1.107 us | }
1639 3750 us | 0) bash-1507 | d..1 | 0.516 us | do_raw_spin_unlock();
1640 3750 us | 0) bash-1507 | d..1 | 0.000 us | _raw_spin_unlock_irqrestore();
1641 3764 us | 0) bash-1507 | d..1 | 0.000 us | tracer_hardirqs_on();
1642 bash-1507 0d..1 3792us : <stack trace>
1659 ----------
1667 Like the irqsoff tracer, it records the maximum latency for
1672 # echo 0 > options/function-trace
1676 # ls -ltr
1682 # preemptoff latency trace v1.1.5 on 3.8.0-test+
1683 # --------------------------------------------------------------------
1684 # latency: 46 us, #4/4, CPU#1 | (M:preempt VP:0, KP:0, SP:0 HP:0 #P:4)
1685 # -----------------
1686 # | task: sshd-1991 (uid:0 nice:0 policy:0 rt_prio:0)
1687 # -----------------
1692 # _------=> CPU#
1693 # / _-----=> irqs-off
1694 # | / _----=> need-resched
1695 # || / _---=> hardirq/softirq
1696 # ||| / _--=> preempt-depth
1700 sshd-1991 1d.h. 0us+: irq_enter <-do_IRQ
1701 sshd-1991 1d..1 46us : irq_exit <-do_IRQ
1702 sshd-1991 1d..1 47us+: trace_preempt_on <-do_IRQ
1703 sshd-1991 1d..1 52us : <stack trace>
1711 interrupt came in (notice the 'h'), and was enabled on exit.
1720 # preemptoff latency trace v1.1.5 on 3.8.0-test+
1721 # --------------------------------------------------------------------
1722 # latency: 83 us, #241/241, CPU#1 | (M:preempt VP:0, KP:0, SP:0 HP:0 #P:4)
1723 # -----------------
1724 # | task: bash-1994 (uid:0 nice:0 policy:0 rt_prio:0)
1725 # -----------------
1730 # _------=> CPU#
1731 # / _-----=> irqs-off
1732 # | / _----=> need-resched
1733 # || / _---=> hardirq/softirq
1734 # ||| / _--=> preempt-depth
1738 bash-1994 1d..1 0us : _raw_spin_lock_irqsave <-wake_up_new_task
1739 bash-1994 1d..1 0us : select_task_rq_fair <-select_task_rq
1740 bash-1994 1d..1 1us : __rcu_read_lock <-select_task_rq_fair
1741 bash-1994 1d..1 1us : source_load <-select_task_rq_fair
1742 bash-1994 1d..1 1us : source_load <-select_task_rq_fair
1744 bash-1994 1d..1 12us : irq_enter <-smp_apic_timer_interrupt
1745 bash-1994 1d..1 12us : rcu_irq_enter <-irq_enter
1746 bash-1994 1d..1 13us : add_preempt_count <-irq_enter
1747 bash-1994 1d.h1 13us : exit_idle <-smp_apic_timer_interrupt
1748 bash-1994 1d.h1 13us : hrtimer_interrupt <-smp_apic_timer_interrupt
1749 bash-1994 1d.h1 13us : _raw_spin_lock <-hrtimer_interrupt
1750 bash-1994 1d.h1 14us : add_preempt_count <-_raw_spin_lock
1751 bash-1994 1d.h2 14us : ktime_get_update_offsets <-hrtimer_interrupt
1753 bash-1994 1d.h1 35us : lapic_next_event <-clockevents_program_event
1754 bash-1994 1d.h1 35us : irq_exit <-smp_apic_timer_interrupt
1755 bash-1994 1d.h1 36us : sub_preempt_count <-irq_exit
1756 bash-1994 1d..2 36us : do_softirq <-irq_exit
1757 bash-1994 1d..2 36us : __do_softirq <-call_softirq
1758 bash-1994 1d..2 36us : __local_bh_disable <-__do_softirq
1759 bash-1994 1d.s2 37us : add_preempt_count <-_raw_spin_lock_irq
1760 bash-1994 1d.s3 38us : _raw_spin_unlock <-run_timer_softirq
1761 bash-1994 1d.s3 39us : sub_preempt_count <-_raw_spin_unlock
1762 bash-1994 1d.s2 39us : call_timer_fn <-run_timer_softirq
1764 bash-1994 1dNs2 81us : cpu_needs_another_gp <-rcu_process_callbacks
1765 bash-1994 1dNs2 82us : __local_bh_enable <-__do_softirq
1766 bash-1994 1dNs2 82us : sub_preempt_count <-__local_bh_enable
1767 bash-1994 1dN.2 82us : idle_cpu <-irq_exit
1768 bash-1994 1dN.2 83us : rcu_irq_exit <-irq_exit
1769 bash-1994 1dN.2 83us : sub_preempt_count <-irq_exit
1770 bash-1994 1.N.1 84us : _raw_spin_unlock_irqrestore <-task_rq_unlock
1771 bash-1994 1.N.1 84us+: trace_preempt_on <-task_rq_unlock
1772 bash-1994 1.N.1 104us : <stack trace>
1783 function-trace set. Here we see that interrupts were not disabled
1784 the entire time. The irq_enter code lets us know that we entered
1790 --------------
1824 # echo 0 > options/function-trace
1828 # ls -ltr
1834 # preemptirqsoff latency trace v1.1.5 on 3.8.0-test+
1835 # --------------------------------------------------------------------
1836 # latency: 100 us, #4/4, CPU#3 | (M:preempt VP:0, KP:0, SP:0 HP:0 #P:4)
1837 # -----------------
1838 # | task: ls-2230 (uid:0 nice:0 policy:0 rt_prio:0)
1839 # -----------------
1844 # _------=> CPU#
1845 # / _-----=> irqs-off
1846 # | / _----=> need-resched
1847 # || / _---=> hardirq/softirq
1848 # ||| / _--=> preempt-depth
1852 ls-2230 3d... 0us+: _raw_spin_lock_irqsave <-ata_scsi_queuecmd
1853 ls-2230 3...1 100us : _raw_spin_unlock_irqrestore <-ata_scsi_queuecmd
1854 ls-2230 3...1 101us+: trace_preempt_on <-ata_scsi_queuecmd
1855 ls-2230 3...1 111us : <stack trace>
1883 Here is a trace with function-trace set::
1887 # preemptirqsoff latency trace v1.1.5 on 3.8.0-test+
1888 # --------------------------------------------------------------------
1889 # latency: 161 us, #339/339, CPU#3 | (M:preempt VP:0, KP:0, SP:0 HP:0 #P:4)
1890 # -----------------
1891 # | task: ls-2269 (uid:0 nice:0 policy:0 rt_prio:0)
1892 # -----------------
1897 # _------=> CPU#
1898 # / _-----=> irqs-off
1899 # | / _----=> need-resched
1900 # || / _---=> hardirq/softirq
1901 # ||| / _--=> preempt-depth
1905 kworker/-59 3...1 0us : __schedule <-schedule
1906 kworker/-59 3d..1 0us : rcu_preempt_qs <-rcu_note_context_switch
1907 kworker/-59 3d..1 1us : add_preempt_count <-_raw_spin_lock_irq
1908 kworker/-59 3d..2 1us : deactivate_task <-__schedule
1909 kworker/-59 3d..2 1us : dequeue_task <-deactivate_task
1910 kworker/-59 3d..2 2us : update_rq_clock <-dequeue_task
1911 kworker/-59 3d..2 2us : dequeue_task_fair <-dequeue_task
1912 kworker/-59 3d..2 2us : update_curr <-dequeue_task_fair
1913 kworker/-59 3d..2 2us : update_min_vruntime <-update_curr
1914 kworker/-59 3d..2 3us : cpuacct_charge <-update_curr
1915 kworker/-59 3d..2 3us : __rcu_read_lock <-cpuacct_charge
1916 kworker/-59 3d..2 3us : __rcu_read_unlock <-cpuacct_charge
1917 kworker/-59 3d..2 3us : update_cfs_rq_blocked_load <-dequeue_task_fair
1918 kworker/-59 3d..2 4us : clear_buddies <-dequeue_task_fair
1919 kworker/-59 3d..2 4us : account_entity_dequeue <-dequeue_task_fair
1920 kworker/-59 3d..2 4us : update_min_vruntime <-dequeue_task_fair
1921 kworker/-59 3d..2 4us : update_cfs_shares <-dequeue_task_fair
1922 kworker/-59 3d..2 5us : hrtick_update <-dequeue_task_fair
1923 kworker/-59 3d..2 5us : wq_worker_sleeping <-__schedule
1924 kworker/-59 3d..2 5us : kthread_data <-wq_worker_sleeping
1925 kworker/-59 3d..2 5us : put_prev_task_fair <-__schedule
1926 kworker/-59 3d..2 6us : pick_next_task_fair <-pick_next_task
1927 kworker/-59 3d..2 6us : clear_buddies <-pick_next_task_fair
1928 kworker/-59 3d..2 6us : set_next_entity <-pick_next_task_fair
1929 kworker/-59 3d..2 6us : update_stats_wait_end <-set_next_entity
1930 ls-2269 3d..2 7us : finish_task_switch <-__schedule
1931 ls-2269 3d..2 7us : _raw_spin_unlock_irq <-finish_task_switch
1932 ls-2269 3d..2 8us : do_IRQ <-ret_from_intr
1933 ls-2269 3d..2 8us : irq_enter <-do_IRQ
1934 ls-2269 3d..2 8us : rcu_irq_enter <-irq_enter
1935 ls-2269 3d..2 9us : add_preempt_count <-irq_enter
1936 ls-2269 3d.h2 9us : exit_idle <-do_IRQ
1938 ls-2269 3d.h3 20us : sub_preempt_count <-_raw_spin_unlock
1939 ls-2269 3d.h2 20us : irq_exit <-do_IRQ
1940 ls-2269 3d.h2 21us : sub_preempt_count <-irq_exit
1941 ls-2269 3d..3 21us : do_softirq <-irq_exit
1942 ls-2269 3d..3 21us : __do_softirq <-call_softirq
1943 ls-2269 3d..3 21us+: __local_bh_disable <-__do_softirq
1944 ls-2269 3d.s4 29us : sub_preempt_count <-_local_bh_enable_ip
1945 ls-2269 3d.s5 29us : sub_preempt_count <-_local_bh_enable_ip
1946 ls-2269 3d.s5 31us : do_IRQ <-ret_from_intr
1947 ls-2269 3d.s5 31us : irq_enter <-do_IRQ
1948 ls-2269 3d.s5 31us : rcu_irq_enter <-irq_enter
1950 ls-2269 3d.s5 31us : rcu_irq_enter <-irq_enter
1951 ls-2269 3d.s5 32us : add_preempt_count <-irq_enter
1952 ls-2269 3d.H5 32us : exit_idle <-do_IRQ
1953 ls-2269 3d.H5 32us : handle_irq <-do_IRQ
1954 ls-2269 3d.H5 32us : irq_to_desc <-handle_irq
1955 ls-2269 3d.H5 33us : handle_fasteoi_irq <-handle_irq
1957 ls-2269 3d.s5 158us : _raw_spin_unlock_irqrestore <-rtl8139_poll
1958 ls-2269 3d.s3 158us : net_rps_action_and_irq_enable.isra.65 <-net_rx_action
1959 ls-2269 3d.s3 159us : __local_bh_enable <-__do_softirq
1960 ls-2269 3d.s3 159us : sub_preempt_count <-__local_bh_enable
1961 ls-2269 3d..3 159us : idle_cpu <-irq_exit
1962 ls-2269 3d..3 159us : rcu_irq_exit <-irq_exit
1963 ls-2269 3d..3 160us : sub_preempt_count <-irq_exit
1964 ls-2269 3d... 161us : __mutex_unlock_slowpath <-mutex_unlock
1965 ls-2269 3d... 162us+: trace_hardirqs_on <-mutex_unlock
1966 ls-2269 3d... 186us : <stack trace>
1985 ------
1989 Now for non Real-Time tasks, this can be arbitrary. But tracing
1994 # echo 0 > options/function-trace
1998 # chrt -f 5 sleep 1
2003 # wakeup latency trace v1.1.5 on 3.8.0-test+
2004 # --------------------------------------------------------------------
2005 # latency: 15 us, #4/4, CPU#3 | (M:preempt VP:0, KP:0, SP:0 HP:0 #P:4)
2006 # -----------------
2007 # | task: kworker/3:1H-312 (uid:0 nice:-20 policy:0 rt_prio:0)
2008 # -----------------
2010 # _------=> CPU#
2011 # / _-----=> irqs-off
2012 # | / _----=> need-resched
2013 # || / _---=> hardirq/softirq
2014 # ||| / _--=> preempt-depth
2018 <idle>-0 3dNs7 0us : 0:120:R + [003] 312:100:R kworker/3:1H
2019 <idle>-0 3dNs7 1us+: ttwu_do_activate.constprop.87 <-try_to_wake_up
2020 <idle>-0 3d..3 15us : __schedule <-schedule
2021 <idle>-0 3d..3 15us : 0:120:R ==> [003] 312:100:R kworker/3:1H
2025 the kworker with a nice priority of -20 (not very nice), took
2029 Non Real-Time tasks are not that interesting. A more interesting
2030 trace is to concentrate only on Real-Time tasks.
2033 ---------
2035 In a Real-Time environment it is very important to know the
2038 latency". I stress the point that this is about RT tasks. It is
2039 also important to know the scheduling latency of non-RT tasks,
2040 but the average schedule latency is better for non-RT tasks.
2044 Real-Time environments are interested in the worst case latency.
2045 That is the longest latency it takes for something to happen,
2047 only have a large latency once in a while, but that would not
2048 work well with Real-Time tasks. The wakeup_rt tracer was designed
2049 to record the worst case wakeups of RT tasks. Non-RT tasks are
2051 tracing non-RT tasks that are unpredictable will overwrite the
2052 worst case latency of RT tasks (just run the normal wakeup
2061 # echo 0 > options/function-trace
2065 # chrt -f 5 sleep 1
2072 # wakeup_rt latency trace v1.1.5 on 3.8.0-test+
2073 # --------------------------------------------------------------------
2074 # latency: 5 us, #4/4, CPU#3 | (M:preempt VP:0, KP:0, SP:0 HP:0 #P:4)
2075 # -----------------
2076 # | task: sleep-2389 (uid:0 nice:0 policy:1 rt_prio:5)
2077 # -----------------
2079 # _------=> CPU#
2080 # / _-----=> irqs-off
2081 # | / _----=> need-resched
2082 # || / _---=> hardirq/softirq
2083 # ||| / _--=> preempt-depth
2087 <idle>-0 3d.h4 0us : 0:120:R + [003] 2389: 94:R sleep
2088 <idle>-0 3d.h4 1us+: ttwu_do_activate.constprop.87 <-try_to_wake_up
2089 <idle>-0 3d..3 5us : __schedule <-schedule
2090 <idle>-0 3d..3 5us : 0:120:R ==> [003] 2389: 94:R sleep
2100 and it has an rt_prio of 5. This priority is user-space priority
2104 Note, that the trace data shows the internal priority (99 - rtprio).
2107 <idle>-0 3d..3 5us : 0:120:R ==> [003] 2389: 94:R sleep
2109 The 0:120:R means idle was running with a nice priority of 0 (120 - 120)
2111 2389: 94:R. That is the priority is the kernel rtprio (99 - 5 = 94)
2114 Doing the same with chrt -r 5 and function-trace set.
2117 echo 1 > options/function-trace
2121 # wakeup_rt latency trace v1.1.5 on 3.8.0-test+
2122 # --------------------------------------------------------------------
2123 # latency: 29 us, #85/85, CPU#3 | (M:preempt VP:0, KP:0, SP:0 HP:0 #P:4)
2124 # -----------------
2125 # | task: sleep-2448 (uid:0 nice:0 policy:1 rt_prio:5)
2126 # -----------------
2128 # _------=> CPU#
2129 # / _-----=> irqs-off
2130 # | / _----=> need-resched
2131 # || / _---=> hardirq/softirq
2132 # ||| / _--=> preempt-depth
2136 <idle>-0 3d.h4 1us+: 0:120:R + [003] 2448: 94:R sleep
2137 <idle>-0 3d.h4 2us : ttwu_do_activate.constprop.87 <-try_to_wake_up
2138 <idle>-0 3d.h3 3us : check_preempt_curr <-ttwu_do_wakeup
2139 <idle>-0 3d.h3 3us : resched_curr <-check_preempt_curr
2140 <idle>-0 3dNh3 4us : task_woken_rt <-ttwu_do_wakeup
2141 <idle>-0 3dNh3 4us : _raw_spin_unlock <-try_to_wake_up
2142 <idle>-0 3dNh3 4us : sub_preempt_count <-_raw_spin_unlock
2143 <idle>-0 3dNh2 5us : ttwu_stat <-try_to_wake_up
2144 <idle>-0 3dNh2 5us : _raw_spin_unlock_irqrestore <-try_to_wake_up
2145 <idle>-0 3dNh2 6us : sub_preempt_count <-_raw_spin_unlock_irqrestore
2146 <idle>-0 3dNh1 6us : _raw_spin_lock <-__run_hrtimer
2147 <idle>-0 3dNh1 6us : add_preempt_count <-_raw_spin_lock
2148 <idle>-0 3dNh2 7us : _raw_spin_unlock <-hrtimer_interrupt
2149 <idle>-0 3dNh2 7us : sub_preempt_count <-_raw_spin_unlock
2150 <idle>-0 3dNh1 7us : tick_program_event <-hrtimer_interrupt
2151 <idle>-0 3dNh1 7us : clockevents_program_event <-tick_program_event
2152 <idle>-0 3dNh1 8us : ktime_get <-clockevents_program_event
2153 <idle>-0 3dNh1 8us : lapic_next_event <-clockevents_program_event
2154 <idle>-0 3dNh1 8us : irq_exit <-smp_apic_timer_interrupt
2155 <idle>-0 3dNh1 9us : sub_preempt_count <-irq_exit
2156 <idle>-0 3dN.2 9us : idle_cpu <-irq_exit
2157 <idle>-0 3dN.2 9us : rcu_irq_exit <-irq_exit
2158 <idle>-0 3dN.2 10us : rcu_eqs_enter_common.isra.45 <-rcu_irq_exit
2159 <idle>-0 3dN.2 10us : sub_preempt_count <-irq_exit
2160 <idle>-0 3.N.1 11us : rcu_idle_exit <-cpu_idle
2161 <idle>-0 3dN.1 11us : rcu_eqs_exit_common.isra.43 <-rcu_idle_exit
2162 <idle>-0 3.N.1 11us : tick_nohz_idle_exit <-cpu_idle
2163 <idle>-0 3dN.1 12us : menu_hrtimer_cancel <-tick_nohz_idle_exit
2164 <idle>-0 3dN.1 12us : ktime_get <-tick_nohz_idle_exit
2165 <idle>-0 3dN.1 12us : tick_do_update_jiffies64 <-tick_nohz_idle_exit
2166 <idle>-0 3dN.1 13us : cpu_load_update_nohz <-tick_nohz_idle_exit
2167 <idle>-0 3dN.1 13us : _raw_spin_lock <-cpu_load_update_nohz
2168 <idle>-0 3dN.1 13us : add_preempt_count <-_raw_spin_lock
2169 <idle>-0 3dN.2 13us : __cpu_load_update <-cpu_load_update_nohz
2170 <idle>-0 3dN.2 14us : sched_avg_update <-__cpu_load_update
2171 <idle>-0 3dN.2 14us : _raw_spin_unlock <-cpu_load_update_nohz
2172 <idle>-0 3dN.2 14us : sub_preempt_count <-_raw_spin_unlock
2173 <idle>-0 3dN.1 15us : calc_load_nohz_stop <-tick_nohz_idle_exit
2174 <idle>-0 3dN.1 15us : touch_softlockup_watchdog <-tick_nohz_idle_exit
2175 <idle>-0 3dN.1 15us : hrtimer_cancel <-tick_nohz_idle_exit
2176 <idle>-0 3dN.1 15us : hrtimer_try_to_cancel <-hrtimer_cancel
2177 <idle>-0 3dN.1 16us : lock_hrtimer_base.isra.18 <-hrtimer_try_to_cancel
2178 <idle>-0 3dN.1 16us : _raw_spin_lock_irqsave <-lock_hrtimer_base.isra.18
2179 <idle>-0 3dN.1 16us : add_preempt_count <-_raw_spin_lock_irqsave
2180 <idle>-0 3dN.2 17us : __remove_hrtimer <-remove_hrtimer.part.16
2181 <idle>-0 3dN.2 17us : hrtimer_force_reprogram <-__remove_hrtimer
2182 <idle>-0 3dN.2 17us : tick_program_event <-hrtimer_force_reprogram
2183 <idle>-0 3dN.2 18us : clockevents_program_event <-tick_program_event
2184 <idle>-0 3dN.2 18us : ktime_get <-clockevents_program_event
2185 <idle>-0 3dN.2 18us : lapic_next_event <-clockevents_program_event
2186 <idle>-0 3dN.2 19us : _raw_spin_unlock_irqrestore <-hrtimer_try_to_cancel
2187 <idle>-0 3dN.2 19us : sub_preempt_count <-_raw_spin_unlock_irqrestore
2188 <idle>-0 3dN.1 19us : hrtimer_forward <-tick_nohz_idle_exit
2189 <idle>-0 3dN.1 20us : ktime_add_safe <-hrtimer_forward
2190 <idle>-0 3dN.1 20us : ktime_add_safe <-hrtimer_forward
2191 <idle>-0 3dN.1 20us : hrtimer_start_range_ns <-hrtimer_start_expires.constprop.11
2192 <idle>-0 3dN.1 20us : __hrtimer_start_range_ns <-hrtimer_start_range_ns
2193 <idle>-0 3dN.1 21us : lock_hrtimer_base.isra.18 <-__hrtimer_start_range_ns
2194 <idle>-0 3dN.1 21us : _raw_spin_lock_irqsave <-lock_hrtimer_base.isra.18
2195 <idle>-0 3dN.1 21us : add_preempt_count <-_raw_spin_lock_irqsave
2196 <idle>-0 3dN.2 22us : ktime_add_safe <-__hrtimer_start_range_ns
2197 <idle>-0 3dN.2 22us : enqueue_hrtimer <-__hrtimer_start_range_ns
2198 <idle>-0 3dN.2 22us : tick_program_event <-__hrtimer_start_range_ns
2199 <idle>-0 3dN.2 23us : clockevents_program_event <-tick_program_event
2200 <idle>-0 3dN.2 23us : ktime_get <-clockevents_program_event
2201 <idle>-0 3dN.2 23us : lapic_next_event <-clockevents_program_event
2202 <idle>-0 3dN.2 24us : _raw_spin_unlock_irqrestore <-__hrtimer_start_range_ns
2203 <idle>-0 3dN.2 24us : sub_preempt_count <-_raw_spin_unlock_irqrestore
2204 <idle>-0 3dN.1 24us : account_idle_ticks <-tick_nohz_idle_exit
2205 <idle>-0 3dN.1 24us : account_idle_time <-account_idle_ticks
2206 <idle>-0 3.N.1 25us : sub_preempt_count <-cpu_idle
2207 <idle>-0 3.N.. 25us : schedule <-cpu_idle
2208 <idle>-0 3.N.. 25us : __schedule <-preempt_schedule
2209 <idle>-0 3.N.. 26us : add_preempt_count <-__schedule
2210 <idle>-0 3.N.1 26us : rcu_note_context_switch <-__schedule
2211 <idle>-0 3.N.1 26us : rcu_sched_qs <-rcu_note_context_switch
2212 <idle>-0 3dN.1 27us : rcu_preempt_qs <-rcu_note_context_switch
2213 <idle>-0 3.N.1 27us : _raw_spin_lock_irq <-__schedule
2214 <idle>-0 3dN.1 27us : add_preempt_count <-_raw_spin_lock_irq
2215 <idle>-0 3dN.2 28us : put_prev_task_idle <-__schedule
2216 <idle>-0 3dN.2 28us : pick_next_task_stop <-pick_next_task
2217 <idle>-0 3dN.2 28us : pick_next_task_rt <-pick_next_task
2218 <idle>-0 3dN.2 29us : dequeue_pushable_task <-pick_next_task_rt
2219 <idle>-0 3d..3 29us : __schedule <-preempt_schedule
2220 <idle>-0 3d..3 30us : 0:120:R ==> [003] 2448: 94:R sleep
2229 Latency tracing and events
2230 --------------------------
2231 As function tracing can induce a much larger latency, but without
2232 seeing what happens within the latency it is hard to know what
2237 # echo 0 > options/function-trace
2242 # chrt -f 5 sleep 1
2247 # wakeup_rt latency trace v1.1.5 on 3.8.0-test+
2248 # --------------------------------------------------------------------
2249 # latency: 6 us, #12/12, CPU#2 | (M:preempt VP:0, KP:0, SP:0 HP:0 #P:4)
2250 # -----------------
2251 # | task: sleep-5882 (uid:0 nice:0 policy:1 rt_prio:5)
2252 # -----------------
2254 # _------=> CPU#
2255 # / _-----=> irqs-off
2256 # | / _----=> need-resched
2257 # || / _---=> hardirq/softirq
2258 # ||| / _--=> preempt-depth
2262 <idle>-0 2d.h4 0us : 0:120:R + [002] 5882: 94:R sleep
2263 <idle>-0 2d.h4 0us : ttwu_do_activate.constprop.87 <-try_to_wake_up
2264 <idle>-0 2d.h4 1us : sched_wakeup: comm=sleep pid=5882 prio=94 success=1 target_cpu=002
2265 <idle>-0 2dNh2 1us : hrtimer_expire_exit: hrtimer=ffff88007796feb8
2266 <idle>-0 2.N.2 2us : power_end: cpu_id=2
2267 <idle>-0 2.N.2 3us : cpu_idle: state=4294967295 cpu_id=2
2268 <idle>-0 2dN.3 4us : hrtimer_cancel: hrtimer=ffff88007d50d5e0
2269 …<idle>-0 2dN.3 4us : hrtimer_start: hrtimer=ffff88007d50d5e0 function=tick_sched_timer ex…
2270 <idle>-0 2.N.2 5us : rcu_utilization: Start context switch
2271 <idle>-0 2.N.2 5us : rcu_utilization: End context switch
2272 <idle>-0 2d..3 6us : __schedule <-schedule
2273 <idle>-0 2d..3 6us : 0:120:R ==> [002] 5882: 94:R sleep
2276 Hardware Latency Detector
2277 -------------------------
2279 The hardware latency detector is executed by enabling the "hwlat" tracer.
2290 # entries-in-buffer/entries-written: 13/13 #P:8
2292 # _-----=> irqs-off
2293 # / _----=> need-resched
2294 # | / _---=> hardirq/softirq
2295 # || / _--=> preempt-depth
2297 # TASK-PID CPU# |||| TIMESTAMP FUNCTION
2299 …<...>-1729 [001] d... 678.473449: #1 inner/outer(us): 11/12 ts:1581527483.343962693 co…
2300 …<...>-1729 [004] d... 689.556542: #2 inner/outer(us): 16/9 ts:1581527494.889008092 co…
2301 …<...>-1729 [005] d... 714.756290: #3 inner/outer(us): 16/16 ts:1581527519.678961629 co…
2302 …<...>-1729 [001] d... 718.788247: #4 inner/outer(us): 9/17 ts:1581527523.889012713 co…
2303 …<...>-1729 [002] d... 719.796341: #5 inner/outer(us): 13/9 ts:1581527524.912872606 co…
2304 …<...>-1729 [006] d... 844.787091: #6 inner/outer(us): 9/12 ts:1581527649.889048502 co…
2305 …<...>-1729 [003] d... 849.827033: #7 inner/outer(us): 18/9 ts:1581527654.889013793 co…
2306 …<...>-1729 [007] d... 853.859002: #8 inner/outer(us): 9/12 ts:1581527658.889065736 co…
2307 …<...>-1729 [001] d... 855.874978: #9 inner/outer(us): 9/11 ts:1581527660.861991877 co…
2308 …<...>-1729 [001] d... 863.938932: #10 inner/outer(us): 9/11 ts:1581527668.970010500 co…
2309 …<...>-1729 [007] d... 878.050780: #11 inner/outer(us): 9/12 ts:1581527683.385002600 co…
2310 …<...>-1729 [007] d... 886.114702: #12 inner/outer(us): 9/12 ts:1581527691.385001600 co…
2320 inner/outer(us): 11/11
2322 This shows two numbers as "inner latency" and "outer latency". The test
2323 runs in a loop checking a timestamp twice. The latency detected within
2324 the two timestamps is the "inner latency" and the latency detected
2326 the "outer latency".
2330 The absolute timestamp that the first latency was recorded in the window.
2334 The number of times a latency was detected during the window.
2336 nmi-total:7 nmi-count:1
2339 test, the time spent in NMI is reported in "nmi-total" (in
2342 All architectures that have NMIs will show the "nmi-count" if an
2349 microseconds. This is the threshold of latency that
2373 --------
2389 # entries-in-buffer/entries-written: 24799/24799 #P:4
2391 # _-----=> irqs-off
2392 # / _----=> need-resched
2393 # | / _---=> hardirq/softirq
2394 # || / _--=> preempt-depth
2396 # TASK-PID CPU# |||| TIMESTAMP FUNCTION
2398 bash-1994 [002] .... 3082.063030: mutex_unlock <-rb_simple_write
2399 bash-1994 [002] .... 3082.063031: __mutex_unlock_slowpath <-mutex_unlock
2400 bash-1994 [002] .... 3082.063031: __fsnotify_parent <-fsnotify_modify
2401 bash-1994 [002] .... 3082.063032: fsnotify <-fsnotify_modify
2402 bash-1994 [002] .... 3082.063032: __srcu_read_lock <-fsnotify
2403 bash-1994 [002] .... 3082.063032: add_preempt_count <-__srcu_read_lock
2404 bash-1994 [002] ...1 3082.063032: sub_preempt_count <-__srcu_read_lock
2405 bash-1994 [002] .... 3082.063033: __srcu_read_unlock <-fsnotify
2433 ---------------------
2447 # TASK-PID CPU# TIMESTAMP FUNCTION
2449 yum-updatesd-3111 [003] 1637.254676: finish_task_switch <-thread_return
2450 yum-updatesd-3111 [003] 1637.254681: hrtimer_cancel <-schedule_hrtimeout_range
2451 yum-updatesd-3111 [003] 1637.254682: hrtimer_try_to_cancel <-hrtimer_cancel
2452 yum-updatesd-3111 [003] 1637.254683: lock_hrtimer_base <-hrtimer_try_to_cancel
2453 yum-updatesd-3111 [003] 1637.254685: fget_light <-do_sys_poll
2454 yum-updatesd-3111 [003] 1637.254686: pipe_poll <-do_sys_poll
2459 # TASK-PID CPU# TIMESTAMP FUNCTION
2462 yum-updatesd-3111 [003] 1701.957688: free_poll_entry <-poll_freewait
2463 yum-updatesd-3111 [003] 1701.957689: remove_wait_queue <-free_poll_entry
2464 yum-updatesd-3111 [003] 1701.957691: fput <-free_poll_entry
2465 yum-updatesd-3111 [003] 1701.957692: audit_syscall_exit <-sysret_audit
2466 yum-updatesd-3111 [003] 1701.957693: path_put <-audit_syscall_exit
2529 exit(-1);
2538 exit(-1);
2561 tracefs=`sed -ne 's/^tracefs \(.*\) tracefs.*/\1/p' /proc/mounts`
2570 ---------------------------
2573 probes a function on its entry and its exit. This is done by
2583 - measure of a function's time execution
2584 - having a reliable call stack to draw function calls graph
2588 - you want to find the reason of a strange kernel behavior and
2592 - you are experiencing weird latencies but it's difficult to
2595 - you want to find quickly which path is taken by a specific
2598 - you just want to peek inside a working kernel and want to see
2612 0) 1.382 us | __might_sleep();
2613 0) 2.478 us | }
2616 0) 1.389 us | __might_sleep();
2617 0) 2.553 us | }
2618 0) 3.807 us | }
2619 0) 7.876 us | }
2621 0) 0.668 us | _spin_lock();
2622 0) 0.570 us | expand_files();
2623 0) 0.586 us | _spin_unlock();
2630 - The cpu number on which the function executed is default
2635 - hide: echo nofuncgraph-cpu > trace_options
2636 - show: echo funcgraph-cpu > trace_options
2638 - The duration (function's time of execution) is displayed on
2643 - hide: echo nofuncgraph-duration > trace_options
2644 - show: echo funcgraph-duration > trace_options
2646 - The overhead field precedes the duration field in case of
2649 - hide: echo nofuncgraph-overhead > trace_options
2650 - show: echo funcgraph-overhead > trace_options
2651 - depends on: funcgraph-duration
2655 3) # 1837.709 us | } /* __switch_to */
2657 3) 0.313 us | _raw_spin_unlock_irq();
2658 3) 3.177 us | }
2659 3) # 1889.063 us | } /* __schedule */
2660 3) ! 140.417 us | } /* __schedule */
2661 3) # 2034.948 us | } /* schedule */
2662 3) * 33998.59 us | } /* schedule_preempt_disabled */
2666 1) 0.260 us | msecs_to_jiffies();
2667 1) 0.313 us | __rcu_read_unlock();
2668 1) + 61.770 us | }
2669 1) + 64.479 us | }
2670 1) 0.313 us | rcu_bh_qs();
2671 1) 0.313 us | __local_bh_enable();
2672 1) ! 217.240 us | }
2673 1) 0.365 us | idle_cpu();
2675 1) 0.417 us | rcu_eqs_enter_common.isra.47();
2676 1) 3.125 us | }
2677 1) ! 227.812 us | }
2678 1) ! 457.395 us | }
2679 1) @ 119760.2 us | }
2684 1) 6.979 us | }
2685 2) 0.417 us | scheduler_ipi();
2686 1) 9.791 us | }
2687 1) + 12.917 us | }
2688 2) 3.490 us | }
2689 1) + 15.729 us | }
2690 1) + 18.542 us | }
2691 2) $ 3594274 us | }
2703 - The task/pid field displays the thread cmdline and pid which
2706 - hide: echo nofuncgraph-proc > trace_options
2707 - show: echo funcgraph-proc > trace_options
2715 0) sh-4802 | | d_free() {
2716 0) sh-4802 | | call_rcu() {
2717 0) sh-4802 | | __call_rcu() {
2718 0) sh-4802 | 0.616 us | rcu_process_gp_end();
2719 0) sh-4802 | 0.586 us | check_for_new_grace_period();
2720 0) sh-4802 | 2.899 us | }
2721 0) sh-4802 | 4.040 us | }
2722 0) sh-4802 | 5.151 us | }
2723 0) sh-4802 | + 49.370 us | }
2726 - The absolute time field is an absolute timestamp given by the
2728 given on each entry/exit of functions
2730 - hide: echo nofuncgraph-abstime > trace_options
2731 - show: echo funcgraph-abstime > trace_options
2738 360.774522 | 1) 0.541 us | }
2739 360.774522 | 1) 4.663 us | }
2740 360.774523 | 1) 0.541 us | __wake_up_bit();
2741 360.774524 | 1) 6.796 us | }
2742 360.774524 | 1) 7.952 us | }
2743 360.774525 | 1) 9.063 us | }
2744 360.774525 | 1) 0.615 us | journal_mark_dirty();
2745 360.774527 | 1) 0.578 us | __brelse();
2750 360.774530 | 1) 0.594 us | __phys_addr();
2762 - hide: echo nofuncgraph-tail > trace_options
2763 - show: echo funcgraph-tail > trace_options
2765 Example with nofuncgraph-tail (default)::
2769 0) 0.518 us | __phys_addr();
2770 0) 1.757 us | }
2771 0) 2.861 us | }
2773 Example with funcgraph-tail::
2777 0) 0.518 us | __phys_addr();
2778 0) 1.757 us | } /* kmem_cache_free() */
2779 0) 2.861 us | } /* putname() */
2786 - hide: echo nofuncgraph-retval > trace_options
2787 - show: echo funcgraph-retval > trace_options
2789 Example with funcgraph-retval::
2792 1) 0.651 us | cgroup_migrate_add_task(); /* = 0xffff93fcfd346c00 */
2796 1) 0.732 us | cgroup_taskset_next(); /* = 0xffff93fc8fb20000 */
2797 1) 1.232 us | } /* cgroup_taskset_first = 0xffff93fc8fb20000 */
2798 1) 0.380 us | sched_rt_can_attach(); /* = 0x0 */
2799 1) 2.335 us | } /* cpu_cgroup_can_attach = -22 */
2800 1) 4.369 us | } /* cgroup_migrate_execute = -22 */
2801 1) 7.143 us | } /* cgroup_migrate = -22 */
2804 returned the error code -22 firstly, then we can read the code
2807 When the option funcgraph-retval-hex is not set, the return value can
2812 - smart: echo nofuncgraph-retval-hex > trace_options
2813 - hexadecimal: echo funcgraph-retval-hex > trace_options
2815 Example with funcgraph-retval-hex::
2818 1) 0.651 us | cgroup_migrate_add_task(); /* = 0xffff93fcfd346c00 */
2822 1) 0.732 us | cgroup_taskset_next(); /* = 0xffff93fc8fb20000 */
2823 1) 1.232 us | } /* cgroup_taskset_first = 0xffff93fc8fb20000 */
2824 1) 0.380 us | sched_rt_can_attach(); /* = 0x0 */
2825 1) 2.335 us | } /* cpu_cgroup_can_attach = 0xffffffea */
2826 1) 4.369 us | } /* cgroup_migrate_execute = 0xffffffea */
2827 1) 7.143 us | } /* cgroup_migrate = 0xffffffea */
2829 At present, there are some limitations when using the funcgraph-retval
2832 - Even if the function return type is void, a return value will still
2835 - Even if return values are stored in multiple registers, only the
2838 a 64-bit return value, with the lower 32 bits saved in eax and the
2842 - In certain procedure call standards, such as arm64's AAPCS64, when a
2846 when using a u8 in a 64-bit GPR, bits [63:8] may contain arbitrary values,
2876 return -EINVAL;
2888 MOV x0, #-EINVAL
2905 1) 1.449 us | }
2913 --------------
2918 every kernel function, produced by the -pg switch in gcc),
2920 include the -pg switch in the compiling of the kernel.)
2926 with gcc version 4.6, the -mfentry has been added for x86, which
2937 The recordmcount program re-links this section back into the
2969 One special side-effect to the recording of the functions being
3009 # entries-in-buffer/entries-written: 5/5 #P:4
3011 # _-----=> irqs-off
3012 # / _----=> need-resched
3013 # | / _---=> hardirq/softirq
3014 # || / _--=> preempt-depth
3016 # TASK-PID CPU# |||| TIMESTAMP FUNCTION
3018 usleep-2665 [001] .... 4186.475355: sys_nanosleep <-system_call_fastpath
3019 <idle>-0 [001] d.h1 4186.475409: hrtimer_interrupt <-smp_apic_timer_interrupt
3020 usleep-2665 [001] d.h1 4186.475426: hrtimer_interrupt <-smp_apic_timer_interrupt
3021 <idle>-0 [003] d.h1 4186.475426: hrtimer_interrupt <-smp_apic_timer_interrupt
3022 <idle>-0 [002] d.h1 4186.475427: hrtimer_interrupt <-smp_apic_timer_interrupt
3056 # entries-in-buffer/entries-written: 897/897 #P:4
3058 # _-----=> irqs-off
3059 # / _----=> need-resched
3060 # | / _---=> hardirq/softirq
3061 # || / _--=> preempt-depth
3063 # TASK-PID CPU# |||| TIMESTAMP FUNCTION
3065 <idle>-0 [003] dN.1 4228.547803: hrtimer_cancel <-tick_nohz_idle_exit
3066 <idle>-0 [003] dN.1 4228.547804: hrtimer_try_to_cancel <-hrtimer_cancel
3067 <idle>-0 [003] dN.2 4228.547805: hrtimer_force_reprogram <-__remove_hrtimer
3068 <idle>-0 [003] dN.1 4228.547805: hrtimer_forward <-tick_nohz_idle_exit
3069 … <idle>-0 [003] dN.1 4228.547805: hrtimer_start_range_ns <-hrtimer_start_expires.constprop.11
3070 <idle>-0 [003] d..1 4228.547858: hrtimer_get_next_event <-get_next_timer_interrupt
3071 <idle>-0 [003] d..1 4228.547859: hrtimer_start <-__tick_nohz_idle_enter
3072 <idle>-0 [003] d..2 4228.547860: hrtimer_force_reprogram <-__rem
3145 # entries-in-buffer/entries-written: 39608/39608 #P:4
3147 # _-----=> irqs-off
3148 # / _----=> need-resched
3149 # | / _---=> hardirq/softirq
3150 # || / _--=> preempt-depth
3152 # TASK-PID CPU# |||| TIMESTAMP FUNCTION
3154 bash-1994 [000] .... 4342.324896: file_ra_state_init <-do_dentry_open
3155 bash-1994 [000] .... 4342.324897: open_check_o_direct <-do_last
3156 bash-1994 [000] .... 4342.324897: ima_file_check <-do_last
3157 bash-1994 [000] .... 4342.324898: process_measurement <-ima_file_check
3158 bash-1994 [000] .... 4342.324898: ima_get_action <-process_measurement
3159 bash-1994 [000] .... 4342.324898: ima_match_policy <-ima_get_action
3160 bash-1994 [000] .... 4342.324899: do_truncate <-do_last
3161 bash-1994 [000] .... 4342.324899: setattr_should_drop_suidgid <-do_truncate
3162 bash-1994 [000] .... 4342.324899: notify_change <-do_truncate
3163 bash-1994 [000] .... 4342.324900: current_fs_time <-notify_change
3164 bash-1994 [000] .... 4342.324900: current_kernel_time <-current_fs_time
3165 bash-1994 [000] .... 4342.324900: timespec_trunc <-current_fs_time
3170 ------------------------------------
3188 # head -1 available_filter_functions
3194 # head -50 available_filter_functions | tail -1
3203 ---------------------------------------------
3206 function tracer and the function-graph-tracer, there are some
3207 special features only available in the function-graph tracer.
3220 0) 0.804 us | find_get_page();
3222 0) 1.329 us | }
3223 0) 3.904 us | }
3224 0) 4.979 us | }
3225 0) 0.653 us | _spin_lock();
3226 0) 0.578 us | page_add_file_rmap();
3227 0) 0.525 us | native_set_pte_at();
3228 0) 0.585 us | _spin_unlock();
3230 0) 0.541 us | page_waitqueue();
3231 0) 0.639 us | __wake_up_bit();
3232 0) 2.786 us | }
3233 0) + 14.237 us | }
3237 0) 0.698 us | find_get_page();
3239 0) 1.412 us | }
3240 0) 3.950 us | }
3241 0) 5.098 us | }
3242 0) 0.631 us | _spin_lock();
3243 0) 0.571 us | page_add_file_rmap();
3244 0) 0.526 us | native_set_pte_at();
3245 0) 0.586 us | _spin_unlock();
3247 0) 0.533 us | page_waitqueue();
3248 0) 0.638 us | __wake_up_bit();
3249 0) 2.793 us | }
3250 0) + 14.012 us | }
3264 --------------
3288 ---------------
3297 - mod:
3329 - traceon/traceoff:
3353 - snapshot:
3369 - enable_event/disable_event:
3393 - dump:
3400 - cpudump:
3406 - stacktrace:
3410 ----------
3427 # entries-in-buffer/entries-written: 0/0 #P:4
3429 # _-----=> irqs-off
3430 # / _----=> need-resched
3431 # | / _---=> hardirq/softirq
3432 # || / _--=> preempt-depth
3434 # TASK-PID CPU# |||| TIMESTAMP FUNCTION
3439 bash-1994 [000] .... 5281.568961: mutex_unlock <-rb_simple_write
3440 bash-1994 [000] .... 5281.568963: __mutex_unlock_slowpath <-mutex_unlock
3441 bash-1994 [000] .... 5281.568963: __fsnotify_parent <-fsnotify_modify
3442 bash-1994 [000] .... 5281.568964: fsnotify <-fsnotify_modify
3443 bash-1994 [000] .... 5281.568964: __srcu_read_lock <-fsnotify
3444 bash-1994 [000] .... 5281.568964: add_preempt_count <-__srcu_read_lock
3445 bash-1994 [000] ...1 5281.568965: sub_preempt_count <-__srcu_read_lock
3446 bash-1994 [000] .... 5281.568965: __srcu_read_unlock <-fsnotify
3447 bash-1994 [000] .... 5281.568967: sys_dup2 <-system_call_fastpath
3457 -------------
3484 much, it can cause Out-Of-Memory to trigger.
3488 -bash: echo: write error: Cannot allocate memory
3515 --------
3517 available to all non latency tracers. (Latency tracers which
3518 record max latency, such as "irqsoff" or "wakeup", can't use
3543 +--------------+------------+------------+------------+
3547 +--------------+------------+------------+------------+
3549 +--------------+------------+------------+------------+
3559 # entries-in-buffer/entries-written: 71/71 #P:8
3561 # _-----=> irqs-off
3562 # / _----=> need-resched
3563 # | / _---=> hardirq/softirq
3564 # || / _--=> preempt-depth
3566 # TASK-PID CPU# |||| TIMESTAMP FUNCTION
3568 …<idle>-0 [005] d... 2440.603828: sched_switch: prev_comm=swapper/5 prev_pid=0 prev_prio=120 …
3569 …sleep-2242 [005] d... 2440.603846: sched_switch: prev_comm=snapshot-test-2 prev_pid=2242 prev_pr…
3571 …<idle>-0 [002] d... 2440.707230: sched_switch: prev_comm=swapper/2 prev_pid=0 prev_prio=120 p…
3576 # entries-in-buffer/entries-written: 77/77 #P:8
3578 # _-----=> irqs-off
3579 # / _----=> need-resched
3580 # | / _---=> hardirq/softirq
3581 # || / _--=> preempt-depth
3583 # TASK-PID CPU# |||| TIMESTAMP FUNCTION
3585 …<idle>-0 [007] d... 2440.707395: sched_switch: prev_comm=swapper/7 prev_pid=0 prev_prio=120 p…
3586 …snapshot-test-2-2229 [002] d... 2440.707438: sched_switch: prev_comm=snapshot-test-2 prev_pid=22…
3591 one of the latency tracers, you will get the following results.
3602 ---------
3648 bash-2044 [002] .... 10594.481032: _raw_spin_lock_irqsave <-get_page_from_freelist
3649 bash-2044 [002] d... 10594.481032: add_preempt_count <-_raw_spin_lock_irqsave
3650 bash-2044 [002] d..1 10594.481032: __rmqueue <-get_page_from_freelist
3651 bash-2044 [002] d..1 10594.481033: _raw_spin_unlock <-get_page_from_freelist
3652 bash-2044 [002] d..1 10594.481033: sub_preempt_count <-_raw_spin_unlock
3653 … bash-2044 [002] d... 10594.481033: get_pageblock_flags_group <-get_pageblock_migratetype
3654 bash-2044 [002] d... 10594.481034: __mod_zone_page_state <-get_page_from_freelist
3655 bash-2044 [002] d... 10594.481034: zone_statistics <-get_page_from_freelist
3656 bash-2044 [002] d... 10594.481034: __inc_zone_state <-zone_statistics
3657 bash-2044 [002] d... 10594.481034: __inc_zone_state <-zone_statistics
3658 bash-2044 [002] .... 10594.481035: arch_dup_task_struct <-copy_process
3662 …bash-1998 [000] d..4 136.676759: sched_wakeup: comm=kworker/0:1 pid=59 prio=120 success=1 targe…
3663 …bash-1998 [000] dN.4 136.676760: sched_wakeup: comm=bash pid=1998 prio=120 success=1 target_cpu…
3664 …<idle>-0 [003] d.h3 136.676906: sched_wakeup: comm=rcu_preempt pid=9 prio=120 success=1 targ…
3665 …<idle>-0 [003] d..3 136.676909: sched_switch: prev_comm=swapper/3 prev_pid=0 prev_prio=120 p…
3666 …rcu_preempt-9 [003] d..3 136.676916: sched_switch: prev_comm=rcu_preempt prev_pid=9 prev_pri…
3667 …bash-1998 [000] d..4 136.677014: sched_wakeup: comm=kworker/0:1 pid=59 prio=120 success=1 targe…
3668 …bash-1998 [000] dN.4 136.677016: sched_wakeup: comm=bash pid=1998 prio=120 success=1 target_cpu…
3669 …bash-1998 [000] d..3 136.677018: sched_switch: prev_comm=bash prev_pid=1998 prev_prio=120 prev_…
3670 …kworker/0:1-59 [000] d..4 136.677022: sched_wakeup: comm=sshd pid=1995 prio=120 success=1 tar…
3671 …kworker/0:1-59 [000] d..3 136.677025: sched_switch: prev_comm=kworker/0:1 prev_pid=59 prev_pr…
3675 migration/1-14 [001] d.h3 138.732674: softirq_raise: vec=3 [action=NET_RX]
3676 <idle>-0 [001] dNh3 138.732725: softirq_raise: vec=3 [action=NET_RX]
3677 bash-1998 [000] d.h1 138.733101: softirq_raise: vec=1 [action=TIMER]
3678 bash-1998 [000] d.h1 138.733102: softirq_raise: vec=9 [action=RCU]
3679 bash-1998 [000] ..s2 138.733105: softirq_entry: vec=1 [action=TIMER]
3680 bash-1998 [000] ..s2 138.733106: softirq_exit: vec=1 [action=TIMER]
3681 bash-1998 [000] ..s2 138.733106: softirq_entry: vec=9 [action=RCU]
3682 bash-1998 [000] ..s2 138.733109: softirq_exit: vec=9 [action=RCU]
3683 sshd-1995 [001] d.h1 138.733278: irq_handler_entry: irq=21 name=uhci_hcd:usb4
3684 sshd-1995 [001] d.h1 138.733280: irq_handler_exit: irq=21 ret=unhandled
3685 sshd-1995 [001] d.h1 138.733281: irq_handler_entry: irq=21 name=eth0
3686 sshd-1995 [001] d.h1 138.733283: irq_handler_exit: irq=21 ret=handled
3692 # entries-in-buffer/entries-written: 18996/18996 #P:4
3694 # _-----=> irqs-off
3695 # / _----=> need-resched
3696 # | / _---=> hardirq/softirq
3697 # || / _--=> preempt-depth
3699 # TASK-PID CPU# |||| TIMESTAMP FUNCTION
3701 bash-1998 [000] d... 140.733501: sys_write -> 0x2
3702 bash-1998 [000] d... 140.733504: sys_dup2(oldfd: a, newfd: 1)
3703 bash-1998 [000] d... 140.733506: sys_dup2 -> 0x1
3704 bash-1998 [000] d... 140.733508: sys_fcntl(fd: a, cmd: 1, arg: 0)
3705 bash-1998 [000] d... 140.733509: sys_fcntl -> 0x1
3706 bash-1998 [000] d... 140.733510: sys_close(fd: a)
3707 bash-1998 [000] d... 140.733510: sys_close -> 0x0
3708 …bash-1998 [000] d... 140.733514: sys_rt_sigprocmask(how: 0, nset: 0, oset: 6e2768, sigsetsize: …
3709 bash-1998 [000] d... 140.733515: sys_rt_sigprocmask -> 0x0
3710 …bash-1998 [000] d... 140.733516: sys_rt_sigaction(sig: 2, act: 7fff718846f0, oact: 7fff71884650…
3711 bash-1998 [000] d... 140.733516: sys_rt_sigaction -> 0x0
3729 -----------
3760 ----- ---- --------
3780 Note, if -mfentry is being used by gcc, functions get traced before
3782 are not tested by the stack tracer when -mfentry is used.
3784 Currently, -mfentry is used by gcc 4.6.0 and above on x86 only.
3787 ----