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
820 The Hardware Latency tracer is used to detect if the hardware
821 produces any latency. See "Hardware Latency Detector" section
827 the trace with the longest max latency.
830 trace with the latency-format option enabled, which
846 Traces and records the max latency that it takes for
853 Traces and records the max latency that it takes for just
859 Traces and records the max latency that it takes for
884 ----------------
916 ----------------------------
920 user-land utilities).
923 --------------
929 # entries-in-buffer/entries-written: 140080/250280 #P:4
931 # _-----=> irqs-off
932 # / _----=> need-resched
933 # | / _---=> hardirq/softirq
934 # || / _--=> preempt-depth
936 # TASK-PID CPU# |||| TIMESTAMP FUNCTION
938 bash-1977 [000] .... 17284.993652: sys_close <-system_call_fastpath
939 bash-1977 [000] .... 17284.993653: __close_fd <-sys_close
940 bash-1977 [000] .... 17284.993653: _raw_spin_lock <-__close_fd
941 sshd-1974 [003] .... 17284.993653: __srcu_read_unlock <-fsnotify
942 bash-1977 [000] .... 17284.993654: add_preempt_count <-_raw_spin_lock
943 bash-1977 [000] ...1 17284.993655: _raw_spin_unlock <-__close_fd
944 bash-1977 [000] ...1 17284.993656: sub_preempt_count <-_raw_spin_unlock
945 bash-1977 [000] .... 17284.993657: filp_close <-__close_fd
946 bash-1977 [000] .... 17284.993657: dnotify_flush <-filp_close
947 sshd-1974 [003] .... 17284.993658: sys_select <-system_call_fastpath
954 lost due to the buffer filling up (250280 - 140080 = 110200 events
958 PID "1977", the CPU that it was running on "000", the latency format
964 Latency trace format
965 --------------------
967 When the latency-format option is enabled or when one of the latency
969 why a latency happened. Here is a typical trace::
973 # irqsoff latency trace v1.1.5 on 3.8.0-test+
974 # --------------------------------------------------------------------
975 # latency: 259 us, #4/4, CPU#2 | (M:preempt VP:0, KP:0, SP:0 HP:0 #P:4)
976 # -----------------
977 # | task: ps-6143 (uid:0 nice:0 policy:0 rt_prio:0)
978 # -----------------
983 # _------=> CPU#
984 # / _-----=> irqs-off
985 # | / _----=> need-resched
986 # || / _---=> hardirq/softirq
987 # ||| / _--=> preempt-depth
991 ps-6143 2d... 0us!: trace_hardirqs_off <-__lock_task_sighand
992 ps-6143 2d..1 259us+: trace_hardirqs_on <-_raw_spin_unlock_irqrestore
993 ps-6143 2d..1 263us+: time_hardirqs_on <-_raw_spin_unlock_irqrestore
994 ps-6143 2d..1 306us : <stack trace>
1010 (3.8). Then it displays the max latency in microseconds (259 us). The number
1015 The task is the process that was running when the latency
1021 - __lock_task_sighand is where the interrupts were disabled.
1022 - _raw_spin_unlock_irqrestore is where they were enabled again.
1033 irqs-off: 'd' interrupts are disabled. '.' otherwise.
1038 need-resched:
1039 - 'N' both TIF_NEED_RESCHED and PREEMPT_NEED_RESCHED is set,
1040 - 'n' only TIF_NEED_RESCHED is set,
1041 - 'p' only PREEMPT_NEED_RESCHED is set,
1042 - '.' otherwise.
1045 - 'Z' - NMI occurred inside a hardirq
1046 - 'z' - NMI is running
1047 - 'H' - hard irq occurred inside a softirq.
1048 - 'h' - hard irq is running
1049 - 's' - soft irq is running
1050 - '.' - normal context.
1052 preempt-depth: The level of preempt_disabled
1057 When the latency-format option is enabled, the trace file
1059 trace. This differs from the output when latency-format
1068 - '$' - greater than 1 second
1069 - '@' - greater than 100 millisecond
1070 - '*' - greater than 10 millisecond
1071 - '#' - greater than 1000 microsecond
1072 - '!' - greater than 100 microsecond
1073 - '+' - greater than 10 microsecond
1074 - ' ' - less than or equal to 10 microsecond.
1078 Note, the latency tracers will usually end with a back trace
1079 to easily find where the latency occurred.
1082 -------------
1089 print-parent
1090 nosym-offset
1091 nosym-addr
1101 nosym-userobj
1102 noprintk-msg-only
1103 context-info
1104 nolatency-format
1105 record-cmd
1106 norecord-tgid
1109 irq-info
1111 noevent-fork
1112 function-trace
1113 nofunction-fork
1114 nodisplay-graph
1121 echo noprint-parent > trace_options
1125 echo sym-offset > trace_options
1129 print-parent
1134 print-parent:
1135 bash-4000 [01] 1477.606694: simple_strtoul <-kstrtoul
1137 noprint-parent:
1138 bash-4000 [01] 1477.606694: simple_strtoul
1141 sym-offset
1148 sym-offset:
1149 bash-4000 [01] 1477.606694: simple_strtoul+0x6/0xa0
1151 sym-addr
1156 sym-addr:
1157 bash-4000 [01] 1477.606694: simple_strtoul <c0339346>
1161 latency-format option is enabled.
1211 <idle>-0 [001] dNs4 21169.031481: wake_up_idle_cpu <-add_timer_on
1212 <idle>-0 [001] dNs4 21169.031482: _raw_spin_unlock_irqrestore <-add_timer_on
1213 <idle>-0 [001] .Ns4 21169.031484: sub_preempt_count <-_raw_spin_unlock_irqrestore
1215 <idle>-0 [002] .N.1 21169.031484: rcu_idle_exit <-cpu_idle
1216 <idle>-0 [001] .Ns3 21169.031484: _raw_spin_unlock <-clocksource_watchdog
1217 <idle>-0 [001] .Ns3 21169.031485: sub_preempt_count <-_raw_spin_unlock
1224 sym-userobj
1235 a.out-1623 [000] 40874.465068: /root/a.out[+0x480] <-/root/a.out[+0
1236 x494] <- /root/a.out[+0x4a8] <- /lib/libc-2.7.so[+0x1e1a6]
1239 printk-msg-only
1244 context-info
1248 latency-format
1251 latency, as described in "Latency trace format".
1253 pause-on-trace
1259 hash-ptr
1265 record-cmd
1273 record-tgid
1290 irq-info
1296 # entries-in-buffer/entries-written: 144405/9452052 #P:4
1298 # TASK-PID CPU# TIMESTAMP FUNCTION
1300 <idle>-0 [002] 23636.756054: ttwu_do_activate.constprop.89 <-try_to_wake_up
1301 <idle>-0 [002] 23636.756054: activate_task <-ttwu_do_activate.constprop.89
1302 <idle>-0 [002] 23636.756055: enqueue_task <-activate_task
1310 event-fork
1313 tasks fork. Also, when tasks with PIDs in set_event_pid exit,
1318 function-trace
1319 The latency tracers will enable function tracing
1321 it is disabled, the latency tracers do not trace
1323 when performing latency tests.
1325 function-fork
1329 set_ftrace_pid exit, their PIDs will be removed from the
1334 display-graph
1335 When set, the latency tracers (irqsoff, wakeup, etc) will
1370 funcgraph-overrun
1381 funcgraph-cpu
1385 funcgraph-overhead
1391 funcgraph-proc
1398 funcgraph-duration
1403 funcgraph-abstime
1406 funcgraph-irqs
1410 funcgraph-tail
1416 funcgraph-retval
1421 funcgraph-retval-hex
1429 sleep-time
1435 graph-time
1449 -------
1454 the kernel know of a new mouse event. The result is a latency
1458 disabled. When a new maximum latency is hit, the tracer saves
1459 the trace leading up to that latency point so that every time a
1466 # echo 0 > options/function-trace
1470 # ls -ltr
1476 # irqsoff latency trace v1.1.5 on 3.8.0-test+
1477 # --------------------------------------------------------------------
1478 # latency: 16 us, #4/4, CPU#0 | (M:preempt VP:0, KP:0, SP:0 HP:0 #P:4)
1479 # -----------------
1480 # | task: swapper/0-0 (uid:0 nice:0 policy:0 rt_prio:0)
1481 # -----------------
1486 # _------=> CPU#
1487 # / _-----=> irqs-off
1488 # | / _----=> need-resched
1489 # || / _---=> hardirq/softirq
1490 # ||| / _--=> preempt-depth
1494 <idle>-0 0d.s2 0us+: _raw_spin_lock_irq <-run_timer_softirq
1495 <idle>-0 0dNs3 17us : _raw_spin_unlock_irq <-run_timer_softirq
1496 <idle>-0 0dNs3 17us+: trace_hardirqs_on <-run_timer_softirq
1497 <idle>-0 0dNs3 25us : <stack trace>
1513 Here we see that we had a latency of 16 microseconds (which is
1516 timestamp 25us occurred because the clock was incremented
1517 between the time of recording the max latency and the time of
1518 recording the function that had that latency.
1520 Note the above example had function-trace not set. If we set
1521 function-trace, we get a much larger output::
1523 with echo 1 > options/function-trace
1527 # irqsoff latency trace v1.1.5 on 3.8.0-test+
1528 # --------------------------------------------------------------------
1529 # latency: 71 us, #168/168, CPU#3 | (M:preempt VP:0, KP:0, SP:0 HP:0 #P:4)
1530 # -----------------
1531 # | task: bash-2042 (uid:0 nice:0 policy:0 rt_prio:0)
1532 # -----------------
1537 # _------=> CPU#
1538 # / _-----=> irqs-off
1539 # | / _----=> need-resched
1540 # || / _---=> hardirq/softirq
1541 # ||| / _--=> preempt-depth
1545 bash-2042 3d... 0us : _raw_spin_lock_irqsave <-ata_scsi_queuecmd
1546 bash-2042 3d... 0us : add_preempt_count <-_raw_spin_lock_irqsave
1547 bash-2042 3d..1 1us : ata_scsi_find_dev <-ata_scsi_queuecmd
1548 bash-2042 3d..1 1us : __ata_scsi_find_dev <-ata_scsi_find_dev
1549 bash-2042 3d..1 2us : ata_find_dev.part.14 <-__ata_scsi_find_dev
1550 bash-2042 3d..1 2us : ata_qc_new_init <-__ata_scsi_queuecmd
1551 bash-2042 3d..1 3us : ata_sg_init <-__ata_scsi_queuecmd
1552 bash-2042 3d..1 4us : ata_scsi_rw_xlat <-__ata_scsi_queuecmd
1553 bash-2042 3d..1 4us : ata_build_rw_tf <-ata_scsi_rw_xlat
1555 bash-2042 3d..1 67us : delay_tsc <-__delay
1556 bash-2042 3d..1 67us : add_preempt_count <-delay_tsc
1557 bash-2042 3d..2 67us : sub_preempt_count <-delay_tsc
1558 bash-2042 3d..1 67us : add_preempt_count <-delay_tsc
1559 bash-2042 3d..2 68us : sub_preempt_count <-delay_tsc
1560 bash-2042 3d..1 68us+: ata_bmdma_start <-ata_bmdma_qc_issue
1561 bash-2042 3d..1 71us : _raw_spin_unlock_irqrestore <-ata_scsi_queuecmd
1562 bash-2042 3d..1 71us : _raw_spin_unlock_irqrestore <-ata_scsi_queuecmd
1563 bash-2042 3d..1 72us+: trace_hardirqs_on <-ata_scsi_queuecmd
1564 bash-2042 3d..1 120us : <stack trace>
1592 Here we traced a 71 microsecond latency. But we also see all the
1595 overhead may extend the latency times. But nevertheless, this
1599 display-graph option::
1601 with echo 1 > options/display-graph
1605 # irqsoff latency trace v1.1.5 on 4.20.0-rc6+
1606 # --------------------------------------------------------------------
1607 # latency: 3751 us, #274/274, CPU#0 | (M:desktop VP:0, KP:0, SP:0 HP:0 #P:4)
1608 # -----------------
1609 # | task: bash-1507 (uid:0 nice:0 policy:0 rt_prio:0)
1610 # -----------------
1615 # _-----=> irqs-off
1616 # / _----=> need-resched
1617 # | / _---=> hardirq/softirq
1618 # || / _--=> preempt-depth
1622 0 us | 0) bash-1507 | d... | 0.000 us | _raw_spin_lock_irqsave();
1623 0 us | 0) bash-1507 | d..1 | 0.378 us | do_raw_spin_trylock();
1624 1 us | 0) bash-1507 | d..2 | | set_track() {
1625 2 us | 0) bash-1507 | d..2 | | save_stack_trace() {
1626 2 us | 0) bash-1507 | d..2 | | __save_stack_trace() {
1627 3 us | 0) bash-1507 | d..2 | | __unwind_start() {
1628 3 us | 0) bash-1507 | d..2 | | get_stack_info() {
1629 3 us | 0) bash-1507 | d..2 | 0.351 us | in_task_stack();
1630 4 us | 0) bash-1507 | d..2 | 1.107 us | }
1632 3750 us | 0) bash-1507 | d..1 | 0.516 us | do_raw_spin_unlock();
1633 3750 us | 0) bash-1507 | d..1 | 0.000 us | _raw_spin_unlock_irqrestore();
1634 3764 us | 0) bash-1507 | d..1 | 0.000 us | tracer_hardirqs_on();
1635 bash-1507 0d..1 3792us : <stack trace>
1652 ----------
1660 Like the irqsoff tracer, it records the maximum latency for
1665 # echo 0 > options/function-trace
1669 # ls -ltr
1675 # preemptoff latency trace v1.1.5 on 3.8.0-test+
1676 # --------------------------------------------------------------------
1677 # latency: 46 us, #4/4, CPU#1 | (M:preempt VP:0, KP:0, SP:0 HP:0 #P:4)
1678 # -----------------
1679 # | task: sshd-1991 (uid:0 nice:0 policy:0 rt_prio:0)
1680 # -----------------
1685 # _------=> CPU#
1686 # / _-----=> irqs-off
1687 # | / _----=> need-resched
1688 # || / _---=> hardirq/softirq
1689 # ||| / _--=> preempt-depth
1693 sshd-1991 1d.h. 0us+: irq_enter <-do_IRQ
1694 sshd-1991 1d..1 46us : irq_exit <-do_IRQ
1695 sshd-1991 1d..1 47us+: trace_preempt_on <-do_IRQ
1696 sshd-1991 1d..1 52us : <stack trace>
1704 interrupt came in (notice the 'h'), and was enabled on exit.
1713 # preemptoff latency trace v1.1.5 on 3.8.0-test+
1714 # --------------------------------------------------------------------
1715 # latency: 83 us, #241/241, CPU#1 | (M:preempt VP:0, KP:0, SP:0 HP:0 #P:4)
1716 # -----------------
1717 # | task: bash-1994 (uid:0 nice:0 policy:0 rt_prio:0)
1718 # -----------------
1723 # _------=> CPU#
1724 # / _-----=> irqs-off
1725 # | / _----=> need-resched
1726 # || / _---=> hardirq/softirq
1727 # ||| / _--=> preempt-depth
1731 bash-1994 1d..1 0us : _raw_spin_lock_irqsave <-wake_up_new_task
1732 bash-1994 1d..1 0us : select_task_rq_fair <-select_task_rq
1733 bash-1994 1d..1 1us : __rcu_read_lock <-select_task_rq_fair
1734 bash-1994 1d..1 1us : source_load <-select_task_rq_fair
1735 bash-1994 1d..1 1us : source_load <-select_task_rq_fair
1737 bash-1994 1d..1 12us : irq_enter <-smp_apic_timer_interrupt
1738 bash-1994 1d..1 12us : rcu_irq_enter <-irq_enter
1739 bash-1994 1d..1 13us : add_preempt_count <-irq_enter
1740 bash-1994 1d.h1 13us : exit_idle <-smp_apic_timer_interrupt
1741 bash-1994 1d.h1 13us : hrtimer_interrupt <-smp_apic_timer_interrupt
1742 bash-1994 1d.h1 13us : _raw_spin_lock <-hrtimer_interrupt
1743 bash-1994 1d.h1 14us : add_preempt_count <-_raw_spin_lock
1744 bash-1994 1d.h2 14us : ktime_get_update_offsets <-hrtimer_interrupt
1746 bash-1994 1d.h1 35us : lapic_next_event <-clockevents_program_event
1747 bash-1994 1d.h1 35us : irq_exit <-smp_apic_timer_interrupt
1748 bash-1994 1d.h1 36us : sub_preempt_count <-irq_exit
1749 bash-1994 1d..2 36us : do_softirq <-irq_exit
1750 bash-1994 1d..2 36us : __do_softirq <-call_softirq
1751 bash-1994 1d..2 36us : __local_bh_disable <-__do_softirq
1752 bash-1994 1d.s2 37us : add_preempt_count <-_raw_spin_lock_irq
1753 bash-1994 1d.s3 38us : _raw_spin_unlock <-run_timer_softirq
1754 bash-1994 1d.s3 39us : sub_preempt_count <-_raw_spin_unlock
1755 bash-1994 1d.s2 39us : call_timer_fn <-run_timer_softirq
1757 bash-1994 1dNs2 81us : cpu_needs_another_gp <-rcu_process_callbacks
1758 bash-1994 1dNs2 82us : __local_bh_enable <-__do_softirq
1759 bash-1994 1dNs2 82us : sub_preempt_count <-__local_bh_enable
1760 bash-1994 1dN.2 82us : idle_cpu <-irq_exit
1761 bash-1994 1dN.2 83us : rcu_irq_exit <-irq_exit
1762 bash-1994 1dN.2 83us : sub_preempt_count <-irq_exit
1763 bash-1994 1.N.1 84us : _raw_spin_unlock_irqrestore <-task_rq_unlock
1764 bash-1994 1.N.1 84us+: trace_preempt_on <-task_rq_unlock
1765 bash-1994 1.N.1 104us : <stack trace>
1776 function-trace set. Here we see that interrupts were not disabled
1777 the entire time. The irq_enter code lets us know that we entered
1783 --------------
1817 # echo 0 > options/function-trace
1821 # ls -ltr
1827 # preemptirqsoff latency trace v1.1.5 on 3.8.0-test+
1828 # --------------------------------------------------------------------
1829 # latency: 100 us, #4/4, CPU#3 | (M:preempt VP:0, KP:0, SP:0 HP:0 #P:4)
1830 # -----------------
1831 # | task: ls-2230 (uid:0 nice:0 policy:0 rt_prio:0)
1832 # -----------------
1837 # _------=> CPU#
1838 # / _-----=> irqs-off
1839 # | / _----=> need-resched
1840 # || / _---=> hardirq/softirq
1841 # ||| / _--=> preempt-depth
1845 ls-2230 3d... 0us+: _raw_spin_lock_irqsave <-ata_scsi_queuecmd
1846 ls-2230 3...1 100us : _raw_spin_unlock_irqrestore <-ata_scsi_queuecmd
1847 ls-2230 3...1 101us+: trace_preempt_on <-ata_scsi_queuecmd
1848 ls-2230 3...1 111us : <stack trace>
1876 Here is a trace with function-trace set::
1880 # preemptirqsoff latency trace v1.1.5 on 3.8.0-test+
1881 # --------------------------------------------------------------------
1882 # latency: 161 us, #339/339, CPU#3 | (M:preempt VP:0, KP:0, SP:0 HP:0 #P:4)
1883 # -----------------
1884 # | task: ls-2269 (uid:0 nice:0 policy:0 rt_prio:0)
1885 # -----------------
1890 # _------=> CPU#
1891 # / _-----=> irqs-off
1892 # | / _----=> need-resched
1893 # || / _---=> hardirq/softirq
1894 # ||| / _--=> preempt-depth
1898 kworker/-59 3...1 0us : __schedule <-schedule
1899 kworker/-59 3d..1 0us : rcu_preempt_qs <-rcu_note_context_switch
1900 kworker/-59 3d..1 1us : add_preempt_count <-_raw_spin_lock_irq
1901 kworker/-59 3d..2 1us : deactivate_task <-__schedule
1902 kworker/-59 3d..2 1us : dequeue_task <-deactivate_task
1903 kworker/-59 3d..2 2us : update_rq_clock <-dequeue_task
1904 kworker/-59 3d..2 2us : dequeue_task_fair <-dequeue_task
1905 kworker/-59 3d..2 2us : update_curr <-dequeue_task_fair
1906 kworker/-59 3d..2 2us : update_min_vruntime <-update_curr
1907 kworker/-59 3d..2 3us : cpuacct_charge <-update_curr
1908 kworker/-59 3d..2 3us : __rcu_read_lock <-cpuacct_charge
1909 kworker/-59 3d..2 3us : __rcu_read_unlock <-cpuacct_charge
1910 kworker/-59 3d..2 3us : update_cfs_rq_blocked_load <-dequeue_task_fair
1911 kworker/-59 3d..2 4us : clear_buddies <-dequeue_task_fair
1912 kworker/-59 3d..2 4us : account_entity_dequeue <-dequeue_task_fair
1913 kworker/-59 3d..2 4us : update_min_vruntime <-dequeue_task_fair
1914 kworker/-59 3d..2 4us : update_cfs_shares <-dequeue_task_fair
1915 kworker/-59 3d..2 5us : hrtick_update <-dequeue_task_fair
1916 kworker/-59 3d..2 5us : wq_worker_sleeping <-__schedule
1917 kworker/-59 3d..2 5us : kthread_data <-wq_worker_sleeping
1918 kworker/-59 3d..2 5us : put_prev_task_fair <-__schedule
1919 kworker/-59 3d..2 6us : pick_next_task_fair <-pick_next_task
1920 kworker/-59 3d..2 6us : clear_buddies <-pick_next_task_fair
1921 kworker/-59 3d..2 6us : set_next_entity <-pick_next_task_fair
1922 kworker/-59 3d..2 6us : update_stats_wait_end <-set_next_entity
1923 ls-2269 3d..2 7us : finish_task_switch <-__schedule
1924 ls-2269 3d..2 7us : _raw_spin_unlock_irq <-finish_task_switch
1925 ls-2269 3d..2 8us : do_IRQ <-ret_from_intr
1926 ls-2269 3d..2 8us : irq_enter <-do_IRQ
1927 ls-2269 3d..2 8us : rcu_irq_enter <-irq_enter
1928 ls-2269 3d..2 9us : add_preempt_count <-irq_enter
1929 ls-2269 3d.h2 9us : exit_idle <-do_IRQ
1931 ls-2269 3d.h3 20us : sub_preempt_count <-_raw_spin_unlock
1932 ls-2269 3d.h2 20us : irq_exit <-do_IRQ
1933 ls-2269 3d.h2 21us : sub_preempt_count <-irq_exit
1934 ls-2269 3d..3 21us : do_softirq <-irq_exit
1935 ls-2269 3d..3 21us : __do_softirq <-call_softirq
1936 ls-2269 3d..3 21us+: __local_bh_disable <-__do_softirq
1937 ls-2269 3d.s4 29us : sub_preempt_count <-_local_bh_enable_ip
1938 ls-2269 3d.s5 29us : sub_preempt_count <-_local_bh_enable_ip
1939 ls-2269 3d.s5 31us : do_IRQ <-ret_from_intr
1940 ls-2269 3d.s5 31us : irq_enter <-do_IRQ
1941 ls-2269 3d.s5 31us : rcu_irq_enter <-irq_enter
1943 ls-2269 3d.s5 31us : rcu_irq_enter <-irq_enter
1944 ls-2269 3d.s5 32us : add_preempt_count <-irq_enter
1945 ls-2269 3d.H5 32us : exit_idle <-do_IRQ
1946 ls-2269 3d.H5 32us : handle_irq <-do_IRQ
1947 ls-2269 3d.H5 32us : irq_to_desc <-handle_irq
1948 ls-2269 3d.H5 33us : handle_fasteoi_irq <-handle_irq
1950 ls-2269 3d.s5 158us : _raw_spin_unlock_irqrestore <-rtl8139_poll
1951 ls-2269 3d.s3 158us : net_rps_action_and_irq_enable.isra.65 <-net_rx_action
1952 ls-2269 3d.s3 159us : __local_bh_enable <-__do_softirq
1953 ls-2269 3d.s3 159us : sub_preempt_count <-__local_bh_enable
1954 ls-2269 3d..3 159us : idle_cpu <-irq_exit
1955 ls-2269 3d..3 159us : rcu_irq_exit <-irq_exit
1956 ls-2269 3d..3 160us : sub_preempt_count <-irq_exit
1957 ls-2269 3d... 161us : __mutex_unlock_slowpath <-mutex_unlock
1958 ls-2269 3d... 162us+: trace_hardirqs_on <-mutex_unlock
1959 ls-2269 3d... 186us : <stack trace>
1978 ------
1982 Now for non Real-Time tasks, this can be arbitrary. But tracing
1987 # echo 0 > options/function-trace
1991 # chrt -f 5 sleep 1
1996 # wakeup latency trace v1.1.5 on 3.8.0-test+
1997 # --------------------------------------------------------------------
1998 # latency: 15 us, #4/4, CPU#3 | (M:preempt VP:0, KP:0, SP:0 HP:0 #P:4)
1999 # -----------------
2000 # | task: kworker/3:1H-312 (uid:0 nice:-20 policy:0 rt_prio:0)
2001 # -----------------
2003 # _------=> CPU#
2004 # / _-----=> irqs-off
2005 # | / _----=> need-resched
2006 # || / _---=> hardirq/softirq
2007 # ||| / _--=> preempt-depth
2011 <idle>-0 3dNs7 0us : 0:120:R + [003] 312:100:R kworker/3:1H
2012 <idle>-0 3dNs7 1us+: ttwu_do_activate.constprop.87 <-try_to_wake_up
2013 <idle>-0 3d..3 15us : __schedule <-schedule
2014 <idle>-0 3d..3 15us : 0:120:R ==> [003] 312:100:R kworker/3:1H
2018 the kworker with a nice priority of -20 (not very nice), took
2022 Non Real-Time tasks are not that interesting. A more interesting
2023 trace is to concentrate only on Real-Time tasks.
2026 ---------
2028 In a Real-Time environment it is very important to know the
2031 latency". I stress the point that this is about RT tasks. It is
2032 also important to know the scheduling latency of non-RT tasks,
2033 but the average schedule latency is better for non-RT tasks.
2037 Real-Time environments are interested in the worst case latency.
2038 That is the longest latency it takes for something to happen,
2040 only have a large latency once in a while, but that would not
2041 work well with Real-Time tasks. The wakeup_rt tracer was designed
2042 to record the worst case wakeups of RT tasks. Non-RT tasks are
2044 tracing non-RT tasks that are unpredictable will overwrite the
2045 worst case latency of RT tasks (just run the normal wakeup
2054 # echo 0 > options/function-trace
2058 # chrt -f 5 sleep 1
2065 # wakeup_rt latency trace v1.1.5 on 3.8.0-test+
2066 # --------------------------------------------------------------------
2067 # latency: 5 us, #4/4, CPU#3 | (M:preempt VP:0, KP:0, SP:0 HP:0 #P:4)
2068 # -----------------
2069 # | task: sleep-2389 (uid:0 nice:0 policy:1 rt_prio:5)
2070 # -----------------
2072 # _------=> CPU#
2073 # / _-----=> irqs-off
2074 # | / _----=> need-resched
2075 # || / _---=> hardirq/softirq
2076 # ||| / _--=> preempt-depth
2080 <idle>-0 3d.h4 0us : 0:120:R + [003] 2389: 94:R sleep
2081 <idle>-0 3d.h4 1us+: ttwu_do_activate.constprop.87 <-try_to_wake_up
2082 <idle>-0 3d..3 5us : __schedule <-schedule
2083 <idle>-0 3d..3 5us : 0:120:R ==> [003] 2389: 94:R sleep
2093 and it has an rt_prio of 5. This priority is user-space priority
2097 Note, that the trace data shows the internal priority (99 - rtprio).
2100 <idle>-0 3d..3 5us : 0:120:R ==> [003] 2389: 94:R sleep
2102 The 0:120:R means idle was running with a nice priority of 0 (120 - 120)
2104 2389: 94:R. That is the priority is the kernel rtprio (99 - 5 = 94)
2107 Doing the same with chrt -r 5 and function-trace set.
2110 echo 1 > options/function-trace
2114 # wakeup_rt latency trace v1.1.5 on 3.8.0-test+
2115 # --------------------------------------------------------------------
2116 # latency: 29 us, #85/85, CPU#3 | (M:preempt VP:0, KP:0, SP:0 HP:0 #P:4)
2117 # -----------------
2118 # | task: sleep-2448 (uid:0 nice:0 policy:1 rt_prio:5)
2119 # -----------------
2121 # _------=> CPU#
2122 # / _-----=> irqs-off
2123 # | / _----=> need-resched
2124 # || / _---=> hardirq/softirq
2125 # ||| / _--=> preempt-depth
2129 <idle>-0 3d.h4 1us+: 0:120:R + [003] 2448: 94:R sleep
2130 <idle>-0 3d.h4 2us : ttwu_do_activate.constprop.87 <-try_to_wake_up
2131 <idle>-0 3d.h3 3us : check_preempt_curr <-ttwu_do_wakeup
2132 <idle>-0 3d.h3 3us : resched_curr <-check_preempt_curr
2133 <idle>-0 3dNh3 4us : task_woken_rt <-ttwu_do_wakeup
2134 <idle>-0 3dNh3 4us : _raw_spin_unlock <-try_to_wake_up
2135 <idle>-0 3dNh3 4us : sub_preempt_count <-_raw_spin_unlock
2136 <idle>-0 3dNh2 5us : ttwu_stat <-try_to_wake_up
2137 <idle>-0 3dNh2 5us : _raw_spin_unlock_irqrestore <-try_to_wake_up
2138 <idle>-0 3dNh2 6us : sub_preempt_count <-_raw_spin_unlock_irqrestore
2139 <idle>-0 3dNh1 6us : _raw_spin_lock <-__run_hrtimer
2140 <idle>-0 3dNh1 6us : add_preempt_count <-_raw_spin_lock
2141 <idle>-0 3dNh2 7us : _raw_spin_unlock <-hrtimer_interrupt
2142 <idle>-0 3dNh2 7us : sub_preempt_count <-_raw_spin_unlock
2143 <idle>-0 3dNh1 7us : tick_program_event <-hrtimer_interrupt
2144 <idle>-0 3dNh1 7us : clockevents_program_event <-tick_program_event
2145 <idle>-0 3dNh1 8us : ktime_get <-clockevents_program_event
2146 <idle>-0 3dNh1 8us : lapic_next_event <-clockevents_program_event
2147 <idle>-0 3dNh1 8us : irq_exit <-smp_apic_timer_interrupt
2148 <idle>-0 3dNh1 9us : sub_preempt_count <-irq_exit
2149 <idle>-0 3dN.2 9us : idle_cpu <-irq_exit
2150 <idle>-0 3dN.2 9us : rcu_irq_exit <-irq_exit
2151 <idle>-0 3dN.2 10us : rcu_eqs_enter_common.isra.45 <-rcu_irq_exit
2152 <idle>-0 3dN.2 10us : sub_preempt_count <-irq_exit
2153 <idle>-0 3.N.1 11us : rcu_idle_exit <-cpu_idle
2154 <idle>-0 3dN.1 11us : rcu_eqs_exit_common.isra.43 <-rcu_idle_exit
2155 <idle>-0 3.N.1 11us : tick_nohz_idle_exit <-cpu_idle
2156 <idle>-0 3dN.1 12us : menu_hrtimer_cancel <-tick_nohz_idle_exit
2157 <idle>-0 3dN.1 12us : ktime_get <-tick_nohz_idle_exit
2158 <idle>-0 3dN.1 12us : tick_do_update_jiffies64 <-tick_nohz_idle_exit
2159 <idle>-0 3dN.1 13us : cpu_load_update_nohz <-tick_nohz_idle_exit
2160 <idle>-0 3dN.1 13us : _raw_spin_lock <-cpu_load_update_nohz
2161 <idle>-0 3dN.1 13us : add_preempt_count <-_raw_spin_lock
2162 <idle>-0 3dN.2 13us : __cpu_load_update <-cpu_load_update_nohz
2163 <idle>-0 3dN.2 14us : sched_avg_update <-__cpu_load_update
2164 <idle>-0 3dN.2 14us : _raw_spin_unlock <-cpu_load_update_nohz
2165 <idle>-0 3dN.2 14us : sub_preempt_count <-_raw_spin_unlock
2166 <idle>-0 3dN.1 15us : calc_load_nohz_stop <-tick_nohz_idle_exit
2167 <idle>-0 3dN.1 15us : touch_softlockup_watchdog <-tick_nohz_idle_exit
2168 <idle>-0 3dN.1 15us : hrtimer_cancel <-tick_nohz_idle_exit
2169 <idle>-0 3dN.1 15us : hrtimer_try_to_cancel <-hrtimer_cancel
2170 <idle>-0 3dN.1 16us : lock_hrtimer_base.isra.18 <-hrtimer_try_to_cancel
2171 <idle>-0 3dN.1 16us : _raw_spin_lock_irqsave <-lock_hrtimer_base.isra.18
2172 <idle>-0 3dN.1 16us : add_preempt_count <-_raw_spin_lock_irqsave
2173 <idle>-0 3dN.2 17us : __remove_hrtimer <-remove_hrtimer.part.16
2174 <idle>-0 3dN.2 17us : hrtimer_force_reprogram <-__remove_hrtimer
2175 <idle>-0 3dN.2 17us : tick_program_event <-hrtimer_force_reprogram
2176 <idle>-0 3dN.2 18us : clockevents_program_event <-tick_program_event
2177 <idle>-0 3dN.2 18us : ktime_get <-clockevents_program_event
2178 <idle>-0 3dN.2 18us : lapic_next_event <-clockevents_program_event
2179 <idle>-0 3dN.2 19us : _raw_spin_unlock_irqrestore <-hrtimer_try_to_cancel
2180 <idle>-0 3dN.2 19us : sub_preempt_count <-_raw_spin_unlock_irqrestore
2181 <idle>-0 3dN.1 19us : hrtimer_forward <-tick_nohz_idle_exit
2182 <idle>-0 3dN.1 20us : ktime_add_safe <-hrtimer_forward
2183 <idle>-0 3dN.1 20us : ktime_add_safe <-hrtimer_forward
2184 <idle>-0 3dN.1 20us : hrtimer_start_range_ns <-hrtimer_start_expires.constprop.11
2185 <idle>-0 3dN.1 20us : __hrtimer_start_range_ns <-hrtimer_start_range_ns
2186 <idle>-0 3dN.1 21us : lock_hrtimer_base.isra.18 <-__hrtimer_start_range_ns
2187 <idle>-0 3dN.1 21us : _raw_spin_lock_irqsave <-lock_hrtimer_base.isra.18
2188 <idle>-0 3dN.1 21us : add_preempt_count <-_raw_spin_lock_irqsave
2189 <idle>-0 3dN.2 22us : ktime_add_safe <-__hrtimer_start_range_ns
2190 <idle>-0 3dN.2 22us : enqueue_hrtimer <-__hrtimer_start_range_ns
2191 <idle>-0 3dN.2 22us : tick_program_event <-__hrtimer_start_range_ns
2192 <idle>-0 3dN.2 23us : clockevents_program_event <-tick_program_event
2193 <idle>-0 3dN.2 23us : ktime_get <-clockevents_program_event
2194 <idle>-0 3dN.2 23us : lapic_next_event <-clockevents_program_event
2195 <idle>-0 3dN.2 24us : _raw_spin_unlock_irqrestore <-__hrtimer_start_range_ns
2196 <idle>-0 3dN.2 24us : sub_preempt_count <-_raw_spin_unlock_irqrestore
2197 <idle>-0 3dN.1 24us : account_idle_ticks <-tick_nohz_idle_exit
2198 <idle>-0 3dN.1 24us : account_idle_time <-account_idle_ticks
2199 <idle>-0 3.N.1 25us : sub_preempt_count <-cpu_idle
2200 <idle>-0 3.N.. 25us : schedule <-cpu_idle
2201 <idle>-0 3.N.. 25us : __schedule <-preempt_schedule
2202 <idle>-0 3.N.. 26us : add_preempt_count <-__schedule
2203 <idle>-0 3.N.1 26us : rcu_note_context_switch <-__schedule
2204 <idle>-0 3.N.1 26us : rcu_sched_qs <-rcu_note_context_switch
2205 <idle>-0 3dN.1 27us : rcu_preempt_qs <-rcu_note_context_switch
2206 <idle>-0 3.N.1 27us : _raw_spin_lock_irq <-__schedule
2207 <idle>-0 3dN.1 27us : add_preempt_count <-_raw_spin_lock_irq
2208 <idle>-0 3dN.2 28us : put_prev_task_idle <-__schedule
2209 <idle>-0 3dN.2 28us : pick_next_task_stop <-pick_next_task
2210 <idle>-0 3dN.2 28us : pick_next_task_rt <-pick_next_task
2211 <idle>-0 3dN.2 29us : dequeue_pushable_task <-pick_next_task_rt
2212 <idle>-0 3d..3 29us : __schedule <-preempt_schedule
2213 <idle>-0 3d..3 30us : 0:120:R ==> [003] 2448: 94:R sleep
2222 Latency tracing and events
2223 --------------------------
2224 As function tracing can induce a much larger latency, but without
2225 seeing what happens within the latency it is hard to know what
2230 # echo 0 > options/function-trace
2235 # chrt -f 5 sleep 1
2240 # wakeup_rt latency trace v1.1.5 on 3.8.0-test+
2241 # --------------------------------------------------------------------
2242 # latency: 6 us, #12/12, CPU#2 | (M:preempt VP:0, KP:0, SP:0 HP:0 #P:4)
2243 # -----------------
2244 # | task: sleep-5882 (uid:0 nice:0 policy:1 rt_prio:5)
2245 # -----------------
2247 # _------=> CPU#
2248 # / _-----=> irqs-off
2249 # | / _----=> need-resched
2250 # || / _---=> hardirq/softirq
2251 # ||| / _--=> preempt-depth
2255 <idle>-0 2d.h4 0us : 0:120:R + [002] 5882: 94:R sleep
2256 <idle>-0 2d.h4 0us : ttwu_do_activate.constprop.87 <-try_to_wake_up
2257 <idle>-0 2d.h4 1us : sched_wakeup: comm=sleep pid=5882 prio=94 success=1 target_cpu=002
2258 <idle>-0 2dNh2 1us : hrtimer_expire_exit: hrtimer=ffff88007796feb8
2259 <idle>-0 2.N.2 2us : power_end: cpu_id=2
2260 <idle>-0 2.N.2 3us : cpu_idle: state=4294967295 cpu_id=2
2261 <idle>-0 2dN.3 4us : hrtimer_cancel: hrtimer=ffff88007d50d5e0
2262 …<idle>-0 2dN.3 4us : hrtimer_start: hrtimer=ffff88007d50d5e0 function=tick_sched_timer ex…
2263 <idle>-0 2.N.2 5us : rcu_utilization: Start context switch
2264 <idle>-0 2.N.2 5us : rcu_utilization: End context switch
2265 <idle>-0 2d..3 6us : __schedule <-schedule
2266 <idle>-0 2d..3 6us : 0:120:R ==> [002] 5882: 94:R sleep
2269 Hardware Latency Detector
2270 -------------------------
2272 The hardware latency detector is executed by enabling the "hwlat" tracer.
2283 # entries-in-buffer/entries-written: 13/13 #P:8
2285 # _-----=> irqs-off
2286 # / _----=> need-resched
2287 # | / _---=> hardirq/softirq
2288 # || / _--=> preempt-depth
2290 # TASK-PID CPU# |||| TIMESTAMP FUNCTION
2292 …<...>-1729 [001] d... 678.473449: #1 inner/outer(us): 11/12 ts:1581527483.343962693 co…
2293 …<...>-1729 [004] d... 689.556542: #2 inner/outer(us): 16/9 ts:1581527494.889008092 co…
2294 …<...>-1729 [005] d... 714.756290: #3 inner/outer(us): 16/16 ts:1581527519.678961629 co…
2295 …<...>-1729 [001] d... 718.788247: #4 inner/outer(us): 9/17 ts:1581527523.889012713 co…
2296 …<...>-1729 [002] d... 719.796341: #5 inner/outer(us): 13/9 ts:1581527524.912872606 co…
2297 …<...>-1729 [006] d... 844.787091: #6 inner/outer(us): 9/12 ts:1581527649.889048502 co…
2298 …<...>-1729 [003] d... 849.827033: #7 inner/outer(us): 18/9 ts:1581527654.889013793 co…
2299 …<...>-1729 [007] d... 853.859002: #8 inner/outer(us): 9/12 ts:1581527658.889065736 co…
2300 …<...>-1729 [001] d... 855.874978: #9 inner/outer(us): 9/11 ts:1581527660.861991877 co…
2301 …<...>-1729 [001] d... 863.938932: #10 inner/outer(us): 9/11 ts:1581527668.970010500 co…
2302 …<...>-1729 [007] d... 878.050780: #11 inner/outer(us): 9/12 ts:1581527683.385002600 co…
2303 …<...>-1729 [007] d... 886.114702: #12 inner/outer(us): 9/12 ts:1581527691.385001600 co…
2313 inner/outer(us): 11/11
2315 This shows two numbers as "inner latency" and "outer latency". The test
2316 runs in a loop checking a timestamp twice. The latency detected within
2317 the two timestamps is the "inner latency" and the latency detected
2319 the "outer latency".
2323 The absolute timestamp that the first latency was recorded in the window.
2327 The number of times a latency was detected during the window.
2329 nmi-total:7 nmi-count:1
2332 test, the time spent in NMI is reported in "nmi-total" (in
2335 All architectures that have NMIs will show the "nmi-count" if an
2342 microseconds. This is the threshold of latency that
2366 --------
2382 # entries-in-buffer/entries-written: 24799/24799 #P:4
2384 # _-----=> irqs-off
2385 # / _----=> need-resched
2386 # | / _---=> hardirq/softirq
2387 # || / _--=> preempt-depth
2389 # TASK-PID CPU# |||| TIMESTAMP FUNCTION
2391 bash-1994 [002] .... 3082.063030: mutex_unlock <-rb_simple_write
2392 bash-1994 [002] .... 3082.063031: __mutex_unlock_slowpath <-mutex_unlock
2393 bash-1994 [002] .... 3082.063031: __fsnotify_parent <-fsnotify_modify
2394 bash-1994 [002] .... 3082.063032: fsnotify <-fsnotify_modify
2395 bash-1994 [002] .... 3082.063032: __srcu_read_lock <-fsnotify
2396 bash-1994 [002] .... 3082.063032: add_preempt_count <-__srcu_read_lock
2397 bash-1994 [002] ...1 3082.063032: sub_preempt_count <-__srcu_read_lock
2398 bash-1994 [002] .... 3082.063033: __srcu_read_unlock <-fsnotify
2426 ---------------------
2440 # TASK-PID CPU# TIMESTAMP FUNCTION
2442 yum-updatesd-3111 [003] 1637.254676: finish_task_switch <-thread_return
2443 yum-updatesd-3111 [003] 1637.254681: hrtimer_cancel <-schedule_hrtimeout_range
2444 yum-updatesd-3111 [003] 1637.254682: hrtimer_try_to_cancel <-hrtimer_cancel
2445 yum-updatesd-3111 [003] 1637.254683: lock_hrtimer_base <-hrtimer_try_to_cancel
2446 yum-updatesd-3111 [003] 1637.254685: fget_light <-do_sys_poll
2447 yum-updatesd-3111 [003] 1637.254686: pipe_poll <-do_sys_poll
2452 # TASK-PID CPU# TIMESTAMP FUNCTION
2455 yum-updatesd-3111 [003] 1701.957688: free_poll_entry <-poll_freewait
2456 yum-updatesd-3111 [003] 1701.957689: remove_wait_queue <-free_poll_entry
2457 yum-updatesd-3111 [003] 1701.957691: fput <-free_poll_entry
2458 yum-updatesd-3111 [003] 1701.957692: audit_syscall_exit <-sysret_audit
2459 yum-updatesd-3111 [003] 1701.957693: path_put <-audit_syscall_exit
2522 exit(-1);
2531 exit(-1);
2554 tracefs=`sed -ne 's/^tracefs \(.*\) tracefs.*/\1/p' /proc/mounts`
2563 ---------------------------
2566 probes a function on its entry and its exit. This is done by
2576 - measure of a function's time execution
2577 - having a reliable call stack to draw function calls graph
2581 - you want to find the reason of a strange kernel behavior and
2585 - you are experiencing weird latencies but it's difficult to
2588 - you want to find quickly which path is taken by a specific
2591 - you just want to peek inside a working kernel and want to see
2605 0) 1.382 us | __might_sleep();
2606 0) 2.478 us | }
2609 0) 1.389 us | __might_sleep();
2610 0) 2.553 us | }
2611 0) 3.807 us | }
2612 0) 7.876 us | }
2614 0) 0.668 us | _spin_lock();
2615 0) 0.570 us | expand_files();
2616 0) 0.586 us | _spin_unlock();
2623 - The cpu number on which the function executed is default
2628 - hide: echo nofuncgraph-cpu > trace_options
2629 - show: echo funcgraph-cpu > trace_options
2631 - The duration (function's time of execution) is displayed on
2636 - hide: echo nofuncgraph-duration > trace_options
2637 - show: echo funcgraph-duration > trace_options
2639 - The overhead field precedes the duration field in case of
2642 - hide: echo nofuncgraph-overhead > trace_options
2643 - show: echo funcgraph-overhead > trace_options
2644 - depends on: funcgraph-duration
2648 3) # 1837.709 us | } /* __switch_to */
2650 3) 0.313 us | _raw_spin_unlock_irq();
2651 3) 3.177 us | }
2652 3) # 1889.063 us | } /* __schedule */
2653 3) ! 140.417 us | } /* __schedule */
2654 3) # 2034.948 us | } /* schedule */
2655 3) * 33998.59 us | } /* schedule_preempt_disabled */
2659 1) 0.260 us | msecs_to_jiffies();
2660 1) 0.313 us | __rcu_read_unlock();
2661 1) + 61.770 us | }
2662 1) + 64.479 us | }
2663 1) 0.313 us | rcu_bh_qs();
2664 1) 0.313 us | __local_bh_enable();
2665 1) ! 217.240 us | }
2666 1) 0.365 us | idle_cpu();
2668 1) 0.417 us | rcu_eqs_enter_common.isra.47();
2669 1) 3.125 us | }
2670 1) ! 227.812 us | }
2671 1) ! 457.395 us | }
2672 1) @ 119760.2 us | }
2677 1) 6.979 us | }
2678 2) 0.417 us | scheduler_ipi();
2679 1) 9.791 us | }
2680 1) + 12.917 us | }
2681 2) 3.490 us | }
2682 1) + 15.729 us | }
2683 1) + 18.542 us | }
2684 2) $ 3594274 us | }
2696 - The task/pid field displays the thread cmdline and pid which
2699 - hide: echo nofuncgraph-proc > trace_options
2700 - show: echo funcgraph-proc > trace_options
2708 0) sh-4802 | | d_free() {
2709 0) sh-4802 | | call_rcu() {
2710 0) sh-4802 | | __call_rcu() {
2711 0) sh-4802 | 0.616 us | rcu_process_gp_end();
2712 0) sh-4802 | 0.586 us | check_for_new_grace_period();
2713 0) sh-4802 | 2.899 us | }
2714 0) sh-4802 | 4.040 us | }
2715 0) sh-4802 | 5.151 us | }
2716 0) sh-4802 | + 49.370 us | }
2719 - The absolute time field is an absolute timestamp given by the
2721 given on each entry/exit of functions
2723 - hide: echo nofuncgraph-abstime > trace_options
2724 - show: echo funcgraph-abstime > trace_options
2731 360.774522 | 1) 0.541 us | }
2732 360.774522 | 1) 4.663 us | }
2733 360.774523 | 1) 0.541 us | __wake_up_bit();
2734 360.774524 | 1) 6.796 us | }
2735 360.774524 | 1) 7.952 us | }
2736 360.774525 | 1) 9.063 us | }
2737 360.774525 | 1) 0.615 us | journal_mark_dirty();
2738 360.774527 | 1) 0.578 us | __brelse();
2743 360.774530 | 1) 0.594 us | __phys_addr();
2755 - hide: echo nofuncgraph-tail > trace_options
2756 - show: echo funcgraph-tail > trace_options
2758 Example with nofuncgraph-tail (default)::
2762 0) 0.518 us | __phys_addr();
2763 0) 1.757 us | }
2764 0) 2.861 us | }
2766 Example with funcgraph-tail::
2770 0) 0.518 us | __phys_addr();
2771 0) 1.757 us | } /* kmem_cache_free() */
2772 0) 2.861 us | } /* putname() */
2779 - hide: echo nofuncgraph-retval > trace_options
2780 - show: echo funcgraph-retval > trace_options
2782 Example with funcgraph-retval::
2785 1) 0.651 us | cgroup_migrate_add_task(); /* = 0xffff93fcfd346c00 */
2789 1) 0.732 us | cgroup_taskset_next(); /* = 0xffff93fc8fb20000 */
2790 1) 1.232 us | } /* cgroup_taskset_first = 0xffff93fc8fb20000 */
2791 1) 0.380 us | sched_rt_can_attach(); /* = 0x0 */
2792 1) 2.335 us | } /* cpu_cgroup_can_attach = -22 */
2793 1) 4.369 us | } /* cgroup_migrate_execute = -22 */
2794 1) 7.143 us | } /* cgroup_migrate = -22 */
2797 returned the error code -22 firstly, then we can read the code
2800 When the option funcgraph-retval-hex is not set, the return value can
2805 - smart: echo nofuncgraph-retval-hex > trace_options
2806 - hexadecimal: echo funcgraph-retval-hex > trace_options
2808 Example with funcgraph-retval-hex::
2811 1) 0.651 us | cgroup_migrate_add_task(); /* = 0xffff93fcfd346c00 */
2815 1) 0.732 us | cgroup_taskset_next(); /* = 0xffff93fc8fb20000 */
2816 1) 1.232 us | } /* cgroup_taskset_first = 0xffff93fc8fb20000 */
2817 1) 0.380 us | sched_rt_can_attach(); /* = 0x0 */
2818 1) 2.335 us | } /* cpu_cgroup_can_attach = 0xffffffea */
2819 1) 4.369 us | } /* cgroup_migrate_execute = 0xffffffea */
2820 1) 7.143 us | } /* cgroup_migrate = 0xffffffea */
2822 At present, there are some limitations when using the funcgraph-retval
2825 - Even if the function return type is void, a return value will still
2828 - Even if return values are stored in multiple registers, only the
2831 a 64-bit return value, with the lower 32 bits saved in eax and the
2835 - In certain procedure call standards, such as arm64's AAPCS64, when a
2839 when using a u8 in a 64-bit GPR, bits [63:8] may contain arbitrary values,
2869 return -EINVAL;
2881 MOV x0, #-EINVAL
2898 1) 1.449 us | }
2906 --------------
2911 every kernel function, produced by the -pg switch in gcc),
2913 include the -pg switch in the compiling of the kernel.)
2919 with gcc version 4.6, the -mfentry has been added for x86, which
2930 The recordmcount program re-links this section back into the
2962 One special side-effect to the recording of the functions being
3002 # entries-in-buffer/entries-written: 5/5 #P:4
3004 # _-----=> irqs-off
3005 # / _----=> need-resched
3006 # | / _---=> hardirq/softirq
3007 # || / _--=> preempt-depth
3009 # TASK-PID CPU# |||| TIMESTAMP FUNCTION
3011 usleep-2665 [001] .... 4186.475355: sys_nanosleep <-system_call_fastpath
3012 <idle>-0 [001] d.h1 4186.475409: hrtimer_interrupt <-smp_apic_timer_interrupt
3013 usleep-2665 [001] d.h1 4186.475426: hrtimer_interrupt <-smp_apic_timer_interrupt
3014 <idle>-0 [003] d.h1 4186.475426: hrtimer_interrupt <-smp_apic_timer_interrupt
3015 <idle>-0 [002] d.h1 4186.475427: hrtimer_interrupt <-smp_apic_timer_interrupt
3049 # entries-in-buffer/entries-written: 897/897 #P:4
3051 # _-----=> irqs-off
3052 # / _----=> need-resched
3053 # | / _---=> hardirq/softirq
3054 # || / _--=> preempt-depth
3056 # TASK-PID CPU# |||| TIMESTAMP FUNCTION
3058 <idle>-0 [003] dN.1 4228.547803: hrtimer_cancel <-tick_nohz_idle_exit
3059 <idle>-0 [003] dN.1 4228.547804: hrtimer_try_to_cancel <-hrtimer_cancel
3060 <idle>-0 [003] dN.2 4228.547805: hrtimer_force_reprogram <-__remove_hrtimer
3061 <idle>-0 [003] dN.1 4228.547805: hrtimer_forward <-tick_nohz_idle_exit
3062 … <idle>-0 [003] dN.1 4228.547805: hrtimer_start_range_ns <-hrtimer_start_expires.constprop.11
3063 <idle>-0 [003] d..1 4228.547858: hrtimer_get_next_event <-get_next_timer_interrupt
3064 <idle>-0 [003] d..1 4228.547859: hrtimer_start <-__tick_nohz_idle_enter
3065 <idle>-0 [003] d..2 4228.547860: hrtimer_force_reprogram <-__rem
3138 # entries-in-buffer/entries-written: 39608/39608 #P:4
3140 # _-----=> irqs-off
3141 # / _----=> need-resched
3142 # | / _---=> hardirq/softirq
3143 # || / _--=> preempt-depth
3145 # TASK-PID CPU# |||| TIMESTAMP FUNCTION
3147 bash-1994 [000] .... 4342.324896: file_ra_state_init <-do_dentry_open
3148 bash-1994 [000] .... 4342.324897: open_check_o_direct <-do_last
3149 bash-1994 [000] .... 4342.324897: ima_file_check <-do_last
3150 bash-1994 [000] .... 4342.324898: process_measurement <-ima_file_check
3151 bash-1994 [000] .... 4342.324898: ima_get_action <-process_measurement
3152 bash-1994 [000] .... 4342.324898: ima_match_policy <-ima_get_action
3153 bash-1994 [000] .... 4342.324899: do_truncate <-do_last
3154 bash-1994 [000] .... 4342.324899: setattr_should_drop_suidgid <-do_truncate
3155 bash-1994 [000] .... 4342.324899: notify_change <-do_truncate
3156 bash-1994 [000] .... 4342.324900: current_fs_time <-notify_change
3157 bash-1994 [000] .... 4342.324900: current_kernel_time <-current_fs_time
3158 bash-1994 [000] .... 4342.324900: timespec_trunc <-current_fs_time
3163 ------------------------------------
3181 # head -1 available_filter_functions
3187 # head -50 available_filter_functions | tail -1
3196 ---------------------------------------------
3199 function tracer and the function-graph-tracer, there are some
3200 special features only available in the function-graph tracer.
3213 0) 0.804 us | find_get_page();
3215 0) 1.329 us | }
3216 0) 3.904 us | }
3217 0) 4.979 us | }
3218 0) 0.653 us | _spin_lock();
3219 0) 0.578 us | page_add_file_rmap();
3220 0) 0.525 us | native_set_pte_at();
3221 0) 0.585 us | _spin_unlock();
3223 0) 0.541 us | page_waitqueue();
3224 0) 0.639 us | __wake_up_bit();
3225 0) 2.786 us | }
3226 0) + 14.237 us | }
3230 0) 0.698 us | find_get_page();
3232 0) 1.412 us | }
3233 0) 3.950 us | }
3234 0) 5.098 us | }
3235 0) 0.631 us | _spin_lock();
3236 0) 0.571 us | page_add_file_rmap();
3237 0) 0.526 us | native_set_pte_at();
3238 0) 0.586 us | _spin_unlock();
3240 0) 0.533 us | page_waitqueue();
3241 0) 0.638 us | __wake_up_bit();
3242 0) 2.793 us | }
3243 0) + 14.012 us | }
3257 --------------
3281 ---------------
3290 - mod:
3322 - traceon/traceoff:
3346 - snapshot:
3362 - enable_event/disable_event:
3386 - dump:
3393 - cpudump:
3399 - stacktrace:
3403 ----------
3420 # entries-in-buffer/entries-written: 0/0 #P:4
3422 # _-----=> irqs-off
3423 # / _----=> need-resched
3424 # | / _---=> hardirq/softirq
3425 # || / _--=> preempt-depth
3427 # TASK-PID CPU# |||| TIMESTAMP FUNCTION
3432 bash-1994 [000] .... 5281.568961: mutex_unlock <-rb_simple_write
3433 bash-1994 [000] .... 5281.568963: __mutex_unlock_slowpath <-mutex_unlock
3434 bash-1994 [000] .... 5281.568963: __fsnotify_parent <-fsnotify_modify
3435 bash-1994 [000] .... 5281.568964: fsnotify <-fsnotify_modify
3436 bash-1994 [000] .... 5281.568964: __srcu_read_lock <-fsnotify
3437 bash-1994 [000] .... 5281.568964: add_preempt_count <-__srcu_read_lock
3438 bash-1994 [000] ...1 5281.568965: sub_preempt_count <-__srcu_read_lock
3439 bash-1994 [000] .... 5281.568965: __srcu_read_unlock <-fsnotify
3440 bash-1994 [000] .... 5281.568967: sys_dup2 <-system_call_fastpath
3450 -------------
3477 much, it can cause Out-Of-Memory to trigger.
3481 -bash: echo: write error: Cannot allocate memory
3508 --------
3510 available to all non latency tracers. (Latency tracers which
3511 record max latency, such as "irqsoff" or "wakeup", can't use
3536 +--------------+------------+------------+------------+
3540 +--------------+------------+------------+------------+
3542 +--------------+------------+------------+------------+
3552 # entries-in-buffer/entries-written: 71/71 #P:8
3554 # _-----=> irqs-off
3555 # / _----=> need-resched
3556 # | / _---=> hardirq/softirq
3557 # || / _--=> preempt-depth
3559 # TASK-PID CPU# |||| TIMESTAMP FUNCTION
3561 …<idle>-0 [005] d... 2440.603828: sched_switch: prev_comm=swapper/5 prev_pid=0 prev_prio=120 …
3562 …sleep-2242 [005] d... 2440.603846: sched_switch: prev_comm=snapshot-test-2 prev_pid=2242 prev_pr…
3564 …<idle>-0 [002] d... 2440.707230: sched_switch: prev_comm=swapper/2 prev_pid=0 prev_prio=120 p…
3569 # entries-in-buffer/entries-written: 77/77 #P:8
3571 # _-----=> irqs-off
3572 # / _----=> need-resched
3573 # | / _---=> hardirq/softirq
3574 # || / _--=> preempt-depth
3576 # TASK-PID CPU# |||| TIMESTAMP FUNCTION
3578 …<idle>-0 [007] d... 2440.707395: sched_switch: prev_comm=swapper/7 prev_pid=0 prev_prio=120 p…
3579 …snapshot-test-2-2229 [002] d... 2440.707438: sched_switch: prev_comm=snapshot-test-2 prev_pid=22…
3584 one of the latency tracers, you will get the following results.
3595 ---------
3641 bash-2044 [002] .... 10594.481032: _raw_spin_lock_irqsave <-get_page_from_freelist
3642 bash-2044 [002] d... 10594.481032: add_preempt_count <-_raw_spin_lock_irqsave
3643 bash-2044 [002] d..1 10594.481032: __rmqueue <-get_page_from_freelist
3644 bash-2044 [002] d..1 10594.481033: _raw_spin_unlock <-get_page_from_freelist
3645 bash-2044 [002] d..1 10594.481033: sub_preempt_count <-_raw_spin_unlock
3646 … bash-2044 [002] d... 10594.481033: get_pageblock_flags_group <-get_pageblock_migratetype
3647 bash-2044 [002] d... 10594.481034: __mod_zone_page_state <-get_page_from_freelist
3648 bash-2044 [002] d... 10594.481034: zone_statistics <-get_page_from_freelist
3649 bash-2044 [002] d... 10594.481034: __inc_zone_state <-zone_statistics
3650 bash-2044 [002] d... 10594.481034: __inc_zone_state <-zone_statistics
3651 bash-2044 [002] .... 10594.481035: arch_dup_task_struct <-copy_process
3655 …bash-1998 [000] d..4 136.676759: sched_wakeup: comm=kworker/0:1 pid=59 prio=120 success=1 targe…
3656 …bash-1998 [000] dN.4 136.676760: sched_wakeup: comm=bash pid=1998 prio=120 success=1 target_cpu…
3657 …<idle>-0 [003] d.h3 136.676906: sched_wakeup: comm=rcu_preempt pid=9 prio=120 success=1 targ…
3658 …<idle>-0 [003] d..3 136.676909: sched_switch: prev_comm=swapper/3 prev_pid=0 prev_prio=120 p…
3659 …rcu_preempt-9 [003] d..3 136.676916: sched_switch: prev_comm=rcu_preempt prev_pid=9 prev_pri…
3660 …bash-1998 [000] d..4 136.677014: sched_wakeup: comm=kworker/0:1 pid=59 prio=120 success=1 targe…
3661 …bash-1998 [000] dN.4 136.677016: sched_wakeup: comm=bash pid=1998 prio=120 success=1 target_cpu…
3662 …bash-1998 [000] d..3 136.677018: sched_switch: prev_comm=bash prev_pid=1998 prev_prio=120 prev_…
3663 …kworker/0:1-59 [000] d..4 136.677022: sched_wakeup: comm=sshd pid=1995 prio=120 success=1 tar…
3664 …kworker/0:1-59 [000] d..3 136.677025: sched_switch: prev_comm=kworker/0:1 prev_pid=59 prev_pr…
3668 migration/1-14 [001] d.h3 138.732674: softirq_raise: vec=3 [action=NET_RX]
3669 <idle>-0 [001] dNh3 138.732725: softirq_raise: vec=3 [action=NET_RX]
3670 bash-1998 [000] d.h1 138.733101: softirq_raise: vec=1 [action=TIMER]
3671 bash-1998 [000] d.h1 138.733102: softirq_raise: vec=9 [action=RCU]
3672 bash-1998 [000] ..s2 138.733105: softirq_entry: vec=1 [action=TIMER]
3673 bash-1998 [000] ..s2 138.733106: softirq_exit: vec=1 [action=TIMER]
3674 bash-1998 [000] ..s2 138.733106: softirq_entry: vec=9 [action=RCU]
3675 bash-1998 [000] ..s2 138.733109: softirq_exit: vec=9 [action=RCU]
3676 sshd-1995 [001] d.h1 138.733278: irq_handler_entry: irq=21 name=uhci_hcd:usb4
3677 sshd-1995 [001] d.h1 138.733280: irq_handler_exit: irq=21 ret=unhandled
3678 sshd-1995 [001] d.h1 138.733281: irq_handler_entry: irq=21 name=eth0
3679 sshd-1995 [001] d.h1 138.733283: irq_handler_exit: irq=21 ret=handled
3685 # entries-in-buffer/entries-written: 18996/18996 #P:4
3687 # _-----=> irqs-off
3688 # / _----=> need-resched
3689 # | / _---=> hardirq/softirq
3690 # || / _--=> preempt-depth
3692 # TASK-PID CPU# |||| TIMESTAMP FUNCTION
3694 bash-1998 [000] d... 140.733501: sys_write -> 0x2
3695 bash-1998 [000] d... 140.733504: sys_dup2(oldfd: a, newfd: 1)
3696 bash-1998 [000] d... 140.733506: sys_dup2 -> 0x1
3697 bash-1998 [000] d... 140.733508: sys_fcntl(fd: a, cmd: 1, arg: 0)
3698 bash-1998 [000] d... 140.733509: sys_fcntl -> 0x1
3699 bash-1998 [000] d... 140.733510: sys_close(fd: a)
3700 bash-1998 [000] d... 140.733510: sys_close -> 0x0
3701 …bash-1998 [000] d... 140.733514: sys_rt_sigprocmask(how: 0, nset: 0, oset: 6e2768, sigsetsize: …
3702 bash-1998 [000] d... 140.733515: sys_rt_sigprocmask -> 0x0
3703 …bash-1998 [000] d... 140.733516: sys_rt_sigaction(sig: 2, act: 7fff718846f0, oact: 7fff71884650…
3704 bash-1998 [000] d... 140.733516: sys_rt_sigaction -> 0x0
3722 -----------
3753 ----- ---- --------
3773 Note, if -mfentry is being used by gcc, functions get traced before
3775 are not tested by the stack tracer when -mfentry is used.
3777 Currently, -mfentry is used by gcc 4.6.0 and above on x86 only.
3780 ----