Lines Matching +full:entry +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
307 If the "function-fork" option is set, then when a task whose
323 added on fork, enable the "event-fork" option. That option will also
336 added on fork, enable the "event-fork" option. That option will also
366 for each function. The displayed address is the patch-site address
391 the "ip modify" attribute (thus the regs->ip can be changed),
400 the ftrace ops function located above the function entry point. In
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 -----------
807 function tracer probes the functions on their entry
808 whereas the function graph tracer traces on both entry
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.
1199 <idle>-0 [001] dNs4 21169.031481: wake_up_idle_cpu <-add_timer_on
1200 <idle>-0 [001] dNs4 21169.031482: _raw_spin_unlock_irqrestore <-add_timer_on
1201 <idle>-0 [001] .Ns4 21169.031484: sub_preempt_count <-_raw_spin_unlock_irqrestore
1203 <idle>-0 [002] .N.1 21169.031484: rcu_idle_exit <-cpu_idle
1204 <idle>-0 [001] .Ns3 21169.031484: _raw_spin_unlock <-clocksource_watchdog
1205 <idle>-0 [001] .Ns3 21169.031485: sub_preempt_count <-_raw_spin_unlock
1212 sym-userobj
1223 a.out-1623 [000] 40874.465068: /root/a.out[+0x480] <-/root/a.out[+0
1224 x494] <- /root/a.out[+0x4a8] <- /lib/libc-2.7.so[+0x1e1a6]
1227 printk-msg-only
1232 context-info
1236 latency-format
1239 latency, as described in "Latency trace format".
1241 pause-on-trace
1247 hash-ptr
1253 record-cmd
1261 record-tgid
1278 irq-info
1284 # entries-in-buffer/entries-written: 144405/9452052 #P:4
1286 # TASK-PID CPU# TIMESTAMP FUNCTION
1288 <idle>-0 [002] 23636.756054: ttwu_do_activate.constprop.89 <-try_to_wake_up
1289 <idle>-0 [002] 23636.756054: activate_task <-ttwu_do_activate.constprop.89
1290 <idle>-0 [002] 23636.756055: enqueue_task <-activate_task
1298 event-fork
1306 function-trace
1307 The latency tracers will enable function tracing
1309 it is disabled, the latency tracers do not trace
1311 when performing latency tests.
1313 function-fork
1322 display-graph
1323 When set, the latency tracers (irqsoff, wakeup, etc) will
1358 funcgraph-overrun
1369 funcgraph-cpu
1373 funcgraph-overhead
1379 funcgraph-proc
1386 funcgraph-duration
1391 funcgraph-abstime
1394 funcgraph-irqs
1398 funcgraph-tail
1404 funcgraph-retval
1409 funcgraph-retval-hex
1417 sleep-time
1423 graph-time
1437 -------
1442 the kernel know of a new mouse event. The result is a latency
1446 disabled. When a new maximum latency is hit, the tracer saves
1447 the trace leading up to that latency point so that every time a
1454 # echo 0 > options/function-trace
1458 # ls -ltr
1464 # irqsoff latency trace v1.1.5 on 3.8.0-test+
1465 # --------------------------------------------------------------------
1466 # latency: 16 us, #4/4, CPU#0 | (M:preempt VP:0, KP:0, SP:0 HP:0 #P:4)
1467 # -----------------
1468 # | task: swapper/0-0 (uid:0 nice:0 policy:0 rt_prio:0)
1469 # -----------------
1474 # _------=> CPU#
1475 # / _-----=> irqs-off
1476 # | / _----=> need-resched
1477 # || / _---=> hardirq/softirq
1478 # ||| / _--=> preempt-depth
1482 <idle>-0 0d.s2 0us+: _raw_spin_lock_irq <-run_timer_softirq
1483 <idle>-0 0dNs3 17us : _raw_spin_unlock_irq <-run_timer_softirq
1484 <idle>-0 0dNs3 17us+: trace_hardirqs_on <-run_timer_softirq
1485 <idle>-0 0dNs3 25us : <stack trace>
1501 Here we see that we had a latency of 16 microseconds (which is
1504 timestamp 25us occurred because the clock was incremented
1505 between the time of recording the max latency and the time of
1506 recording the function that had that latency.
1508 Note the above example had function-trace not set. If we set
1509 function-trace, we get a much larger output::
1511 with echo 1 > options/function-trace
1515 # irqsoff latency trace v1.1.5 on 3.8.0-test+
1516 # --------------------------------------------------------------------
1517 # latency: 71 us, #168/168, CPU#3 | (M:preempt VP:0, KP:0, SP:0 HP:0 #P:4)
1518 # -----------------
1519 # | task: bash-2042 (uid:0 nice:0 policy:0 rt_prio:0)
1520 # -----------------
1525 # _------=> CPU#
1526 # / _-----=> irqs-off
1527 # | / _----=> need-resched
1528 # || / _---=> hardirq/softirq
1529 # ||| / _--=> preempt-depth
1533 bash-2042 3d... 0us : _raw_spin_lock_irqsave <-ata_scsi_queuecmd
1534 bash-2042 3d... 0us : add_preempt_count <-_raw_spin_lock_irqsave
1535 bash-2042 3d..1 1us : ata_scsi_find_dev <-ata_scsi_queuecmd
1536 bash-2042 3d..1 1us : __ata_scsi_find_dev <-ata_scsi_find_dev
1537 bash-2042 3d..1 2us : ata_find_dev.part.14 <-__ata_scsi_find_dev
1538 bash-2042 3d..1 2us : ata_qc_new_init <-__ata_scsi_queuecmd
1539 bash-2042 3d..1 3us : ata_sg_init <-__ata_scsi_queuecmd
1540 bash-2042 3d..1 4us : ata_scsi_rw_xlat <-__ata_scsi_queuecmd
1541 bash-2042 3d..1 4us : ata_build_rw_tf <-ata_scsi_rw_xlat
1543 bash-2042 3d..1 67us : delay_tsc <-__delay
1544 bash-2042 3d..1 67us : add_preempt_count <-delay_tsc
1545 bash-2042 3d..2 67us : sub_preempt_count <-delay_tsc
1546 bash-2042 3d..1 67us : add_preempt_count <-delay_tsc
1547 bash-2042 3d..2 68us : sub_preempt_count <-delay_tsc
1548 bash-2042 3d..1 68us+: ata_bmdma_start <-ata_bmdma_qc_issue
1549 bash-2042 3d..1 71us : _raw_spin_unlock_irqrestore <-ata_scsi_queuecmd
1550 bash-2042 3d..1 71us : _raw_spin_unlock_irqrestore <-ata_scsi_queuecmd
1551 bash-2042 3d..1 72us+: trace_hardirqs_on <-ata_scsi_queuecmd
1552 bash-2042 3d..1 120us : <stack trace>
1580 Here we traced a 71 microsecond latency. But we also see all the
1583 overhead may extend the latency times. But nevertheless, this
1587 display-graph option::
1589 with echo 1 > options/display-graph
1593 # irqsoff latency trace v1.1.5 on 4.20.0-rc6+
1594 # --------------------------------------------------------------------
1595 # latency: 3751 us, #274/274, CPU#0 | (M:desktop VP:0, KP:0, SP:0 HP:0 #P:4)
1596 # -----------------
1597 # | task: bash-1507 (uid:0 nice:0 policy:0 rt_prio:0)
1598 # -----------------
1603 # _-----=> irqs-off
1604 # / _----=> need-resched
1605 # | / _---=> hardirq/softirq
1606 # || / _--=> preempt-depth
1610 0 us | 0) bash-1507 | d... | 0.000 us | _raw_spin_lock_irqsave();
1611 0 us | 0) bash-1507 | d..1 | 0.378 us | do_raw_spin_trylock();
1612 1 us | 0) bash-1507 | d..2 | | set_track() {
1613 2 us | 0) bash-1507 | d..2 | | save_stack_trace() {
1614 2 us | 0) bash-1507 | d..2 | | __save_stack_trace() {
1615 3 us | 0) bash-1507 | d..2 | | __unwind_start() {
1616 3 us | 0) bash-1507 | d..2 | | get_stack_info() {
1617 3 us | 0) bash-1507 | d..2 | 0.351 us | in_task_stack();
1618 4 us | 0) bash-1507 | d..2 | 1.107 us | }
1620 3750 us | 0) bash-1507 | d..1 | 0.516 us | do_raw_spin_unlock();
1621 3750 us | 0) bash-1507 | d..1 | 0.000 us | _raw_spin_unlock_irqrestore();
1622 3764 us | 0) bash-1507 | d..1 | 0.000 us | tracer_hardirqs_on();
1623 bash-1507 0d..1 3792us : <stack trace>
1640 ----------
1648 Like the irqsoff tracer, it records the maximum latency for
1653 # echo 0 > options/function-trace
1657 # ls -ltr
1663 # preemptoff latency trace v1.1.5 on 3.8.0-test+
1664 # --------------------------------------------------------------------
1665 # latency: 46 us, #4/4, CPU#1 | (M:preempt VP:0, KP:0, SP:0 HP:0 #P:4)
1666 # -----------------
1667 # | task: sshd-1991 (uid:0 nice:0 policy:0 rt_prio:0)
1668 # -----------------
1673 # _------=> CPU#
1674 # / _-----=> irqs-off
1675 # | / _----=> need-resched
1676 # || / _---=> hardirq/softirq
1677 # ||| / _--=> preempt-depth
1681 sshd-1991 1d.h. 0us+: irq_enter <-do_IRQ
1682 sshd-1991 1d..1 46us : irq_exit <-do_IRQ
1683 sshd-1991 1d..1 47us+: trace_preempt_on <-do_IRQ
1684 sshd-1991 1d..1 52us : <stack trace>
1701 # preemptoff latency trace v1.1.5 on 3.8.0-test+
1702 # --------------------------------------------------------------------
1703 # latency: 83 us, #241/241, CPU#1 | (M:preempt VP:0, KP:0, SP:0 HP:0 #P:4)
1704 # -----------------
1705 # | task: bash-1994 (uid:0 nice:0 policy:0 rt_prio:0)
1706 # -----------------
1711 # _------=> CPU#
1712 # / _-----=> irqs-off
1713 # | / _----=> need-resched
1714 # || / _---=> hardirq/softirq
1715 # ||| / _--=> preempt-depth
1719 bash-1994 1d..1 0us : _raw_spin_lock_irqsave <-wake_up_new_task
1720 bash-1994 1d..1 0us : select_task_rq_fair <-select_task_rq
1721 bash-1994 1d..1 1us : __rcu_read_lock <-select_task_rq_fair
1722 bash-1994 1d..1 1us : source_load <-select_task_rq_fair
1723 bash-1994 1d..1 1us : source_load <-select_task_rq_fair
1725 bash-1994 1d..1 12us : irq_enter <-smp_apic_timer_interrupt
1726 bash-1994 1d..1 12us : rcu_irq_enter <-irq_enter
1727 bash-1994 1d..1 13us : add_preempt_count <-irq_enter
1728 bash-1994 1d.h1 13us : exit_idle <-smp_apic_timer_interrupt
1729 bash-1994 1d.h1 13us : hrtimer_interrupt <-smp_apic_timer_interrupt
1730 bash-1994 1d.h1 13us : _raw_spin_lock <-hrtimer_interrupt
1731 bash-1994 1d.h1 14us : add_preempt_count <-_raw_spin_lock
1732 bash-1994 1d.h2 14us : ktime_get_update_offsets <-hrtimer_interrupt
1734 bash-1994 1d.h1 35us : lapic_next_event <-clockevents_program_event
1735 bash-1994 1d.h1 35us : irq_exit <-smp_apic_timer_interrupt
1736 bash-1994 1d.h1 36us : sub_preempt_count <-irq_exit
1737 bash-1994 1d..2 36us : do_softirq <-irq_exit
1738 bash-1994 1d..2 36us : __do_softirq <-call_softirq
1739 bash-1994 1d..2 36us : __local_bh_disable <-__do_softirq
1740 bash-1994 1d.s2 37us : add_preempt_count <-_raw_spin_lock_irq
1741 bash-1994 1d.s3 38us : _raw_spin_unlock <-run_timer_softirq
1742 bash-1994 1d.s3 39us : sub_preempt_count <-_raw_spin_unlock
1743 bash-1994 1d.s2 39us : call_timer_fn <-run_timer_softirq
1745 bash-1994 1dNs2 81us : cpu_needs_another_gp <-rcu_process_callbacks
1746 bash-1994 1dNs2 82us : __local_bh_enable <-__do_softirq
1747 bash-1994 1dNs2 82us : sub_preempt_count <-__local_bh_enable
1748 bash-1994 1dN.2 82us : idle_cpu <-irq_exit
1749 bash-1994 1dN.2 83us : rcu_irq_exit <-irq_exit
1750 bash-1994 1dN.2 83us : sub_preempt_count <-irq_exit
1751 bash-1994 1.N.1 84us : _raw_spin_unlock_irqrestore <-task_rq_unlock
1752 bash-1994 1.N.1 84us+: trace_preempt_on <-task_rq_unlock
1753 bash-1994 1.N.1 104us : <stack trace>
1764 function-trace set. Here we see that interrupts were not disabled
1765 the entire time. The irq_enter code lets us know that we entered
1771 --------------
1805 # echo 0 > options/function-trace
1809 # ls -ltr
1815 # preemptirqsoff latency trace v1.1.5 on 3.8.0-test+
1816 # --------------------------------------------------------------------
1817 # latency: 100 us, #4/4, CPU#3 | (M:preempt VP:0, KP:0, SP:0 HP:0 #P:4)
1818 # -----------------
1819 # | task: ls-2230 (uid:0 nice:0 policy:0 rt_prio:0)
1820 # -----------------
1825 # _------=> CPU#
1826 # / _-----=> irqs-off
1827 # | / _----=> need-resched
1828 # || / _---=> hardirq/softirq
1829 # ||| / _--=> preempt-depth
1833 ls-2230 3d... 0us+: _raw_spin_lock_irqsave <-ata_scsi_queuecmd
1834 ls-2230 3...1 100us : _raw_spin_unlock_irqrestore <-ata_scsi_queuecmd
1835 ls-2230 3...1 101us+: trace_preempt_on <-ata_scsi_queuecmd
1836 ls-2230 3...1 111us : <stack trace>
1864 Here is a trace with function-trace set::
1868 # preemptirqsoff latency trace v1.1.5 on 3.8.0-test+
1869 # --------------------------------------------------------------------
1870 # latency: 161 us, #339/339, CPU#3 | (M:preempt VP:0, KP:0, SP:0 HP:0 #P:4)
1871 # -----------------
1872 # | task: ls-2269 (uid:0 nice:0 policy:0 rt_prio:0)
1873 # -----------------
1878 # _------=> CPU#
1879 # / _-----=> irqs-off
1880 # | / _----=> need-resched
1881 # || / _---=> hardirq/softirq
1882 # ||| / _--=> preempt-depth
1886 kworker/-59 3...1 0us : __schedule <-schedule
1887 kworker/-59 3d..1 0us : rcu_preempt_qs <-rcu_note_context_switch
1888 kworker/-59 3d..1 1us : add_preempt_count <-_raw_spin_lock_irq
1889 kworker/-59 3d..2 1us : deactivate_task <-__schedule
1890 kworker/-59 3d..2 1us : dequeue_task <-deactivate_task
1891 kworker/-59 3d..2 2us : update_rq_clock <-dequeue_task
1892 kworker/-59 3d..2 2us : dequeue_task_fair <-dequeue_task
1893 kworker/-59 3d..2 2us : update_curr <-dequeue_task_fair
1894 kworker/-59 3d..2 2us : update_min_vruntime <-update_curr
1895 kworker/-59 3d..2 3us : cpuacct_charge <-update_curr
1896 kworker/-59 3d..2 3us : __rcu_read_lock <-cpuacct_charge
1897 kworker/-59 3d..2 3us : __rcu_read_unlock <-cpuacct_charge
1898 kworker/-59 3d..2 3us : update_cfs_rq_blocked_load <-dequeue_task_fair
1899 kworker/-59 3d..2 4us : clear_buddies <-dequeue_task_fair
1900 kworker/-59 3d..2 4us : account_entity_dequeue <-dequeue_task_fair
1901 kworker/-59 3d..2 4us : update_min_vruntime <-dequeue_task_fair
1902 kworker/-59 3d..2 4us : update_cfs_shares <-dequeue_task_fair
1903 kworker/-59 3d..2 5us : hrtick_update <-dequeue_task_fair
1904 kworker/-59 3d..2 5us : wq_worker_sleeping <-__schedule
1905 kworker/-59 3d..2 5us : kthread_data <-wq_worker_sleeping
1906 kworker/-59 3d..2 5us : put_prev_task_fair <-__schedule
1907 kworker/-59 3d..2 6us : pick_next_task_fair <-pick_next_task
1908 kworker/-59 3d..2 6us : clear_buddies <-pick_next_task_fair
1909 kworker/-59 3d..2 6us : set_next_entity <-pick_next_task_fair
1910 kworker/-59 3d..2 6us : update_stats_wait_end <-set_next_entity
1911 ls-2269 3d..2 7us : finish_task_switch <-__schedule
1912 ls-2269 3d..2 7us : _raw_spin_unlock_irq <-finish_task_switch
1913 ls-2269 3d..2 8us : do_IRQ <-ret_from_intr
1914 ls-2269 3d..2 8us : irq_enter <-do_IRQ
1915 ls-2269 3d..2 8us : rcu_irq_enter <-irq_enter
1916 ls-2269 3d..2 9us : add_preempt_count <-irq_enter
1917 ls-2269 3d.h2 9us : exit_idle <-do_IRQ
1919 ls-2269 3d.h3 20us : sub_preempt_count <-_raw_spin_unlock
1920 ls-2269 3d.h2 20us : irq_exit <-do_IRQ
1921 ls-2269 3d.h2 21us : sub_preempt_count <-irq_exit
1922 ls-2269 3d..3 21us : do_softirq <-irq_exit
1923 ls-2269 3d..3 21us : __do_softirq <-call_softirq
1924 ls-2269 3d..3 21us+: __local_bh_disable <-__do_softirq
1925 ls-2269 3d.s4 29us : sub_preempt_count <-_local_bh_enable_ip
1926 ls-2269 3d.s5 29us : sub_preempt_count <-_local_bh_enable_ip
1927 ls-2269 3d.s5 31us : do_IRQ <-ret_from_intr
1928 ls-2269 3d.s5 31us : irq_enter <-do_IRQ
1929 ls-2269 3d.s5 31us : rcu_irq_enter <-irq_enter
1931 ls-2269 3d.s5 31us : rcu_irq_enter <-irq_enter
1932 ls-2269 3d.s5 32us : add_preempt_count <-irq_enter
1933 ls-2269 3d.H5 32us : exit_idle <-do_IRQ
1934 ls-2269 3d.H5 32us : handle_irq <-do_IRQ
1935 ls-2269 3d.H5 32us : irq_to_desc <-handle_irq
1936 ls-2269 3d.H5 33us : handle_fasteoi_irq <-handle_irq
1938 ls-2269 3d.s5 158us : _raw_spin_unlock_irqrestore <-rtl8139_poll
1939 ls-2269 3d.s3 158us : net_rps_action_and_irq_enable.isra.65 <-net_rx_action
1940 ls-2269 3d.s3 159us : __local_bh_enable <-__do_softirq
1941 ls-2269 3d.s3 159us : sub_preempt_count <-__local_bh_enable
1942 ls-2269 3d..3 159us : idle_cpu <-irq_exit
1943 ls-2269 3d..3 159us : rcu_irq_exit <-irq_exit
1944 ls-2269 3d..3 160us : sub_preempt_count <-irq_exit
1945 ls-2269 3d... 161us : __mutex_unlock_slowpath <-mutex_unlock
1946 ls-2269 3d... 162us+: trace_hardirqs_on <-mutex_unlock
1947 ls-2269 3d... 186us : <stack trace>
1966 ------
1970 Now for non Real-Time tasks, this can be arbitrary. But tracing
1975 # echo 0 > options/function-trace
1979 # chrt -f 5 sleep 1
1984 # wakeup latency trace v1.1.5 on 3.8.0-test+
1985 # --------------------------------------------------------------------
1986 # latency: 15 us, #4/4, CPU#3 | (M:preempt VP:0, KP:0, SP:0 HP:0 #P:4)
1987 # -----------------
1988 # | task: kworker/3:1H-312 (uid:0 nice:-20 policy:0 rt_prio:0)
1989 # -----------------
1991 # _------=> CPU#
1992 # / _-----=> irqs-off
1993 # | / _----=> need-resched
1994 # || / _---=> hardirq/softirq
1995 # ||| / _--=> preempt-depth
1999 <idle>-0 3dNs7 0us : 0:120:R + [003] 312:100:R kworker/3:1H
2000 <idle>-0 3dNs7 1us+: ttwu_do_activate.constprop.87 <-try_to_wake_up
2001 <idle>-0 3d..3 15us : __schedule <-schedule
2002 <idle>-0 3d..3 15us : 0:120:R ==> [003] 312:100:R kworker/3:1H
2006 the kworker with a nice priority of -20 (not very nice), took
2010 Non Real-Time tasks are not that interesting. A more interesting
2011 trace is to concentrate only on Real-Time tasks.
2014 ---------
2016 In a Real-Time environment it is very important to know the
2019 latency". I stress the point that this is about RT tasks. It is
2020 also important to know the scheduling latency of non-RT tasks,
2021 but the average schedule latency is better for non-RT tasks.
2025 Real-Time environments are interested in the worst case latency.
2026 That is the longest latency it takes for something to happen,
2028 only have a large latency once in a while, but that would not
2029 work well with Real-Time tasks. The wakeup_rt tracer was designed
2030 to record the worst case wakeups of RT tasks. Non-RT tasks are
2032 tracing non-RT tasks that are unpredictable will overwrite the
2033 worst case latency of RT tasks (just run the normal wakeup
2042 # echo 0 > options/function-trace
2046 # chrt -f 5 sleep 1
2053 # wakeup_rt latency trace v1.1.5 on 3.8.0-test+
2054 # --------------------------------------------------------------------
2055 # latency: 5 us, #4/4, CPU#3 | (M:preempt VP:0, KP:0, SP:0 HP:0 #P:4)
2056 # -----------------
2057 # | task: sleep-2389 (uid:0 nice:0 policy:1 rt_prio:5)
2058 # -----------------
2060 # _------=> CPU#
2061 # / _-----=> irqs-off
2062 # | / _----=> need-resched
2063 # || / _---=> hardirq/softirq
2064 # ||| / _--=> preempt-depth
2068 <idle>-0 3d.h4 0us : 0:120:R + [003] 2389: 94:R sleep
2069 <idle>-0 3d.h4 1us+: ttwu_do_activate.constprop.87 <-try_to_wake_up
2070 <idle>-0 3d..3 5us : __schedule <-schedule
2071 <idle>-0 3d..3 5us : 0:120:R ==> [003] 2389: 94:R sleep
2081 and it has an rt_prio of 5. This priority is user-space priority
2085 Note, that the trace data shows the internal priority (99 - rtprio).
2088 <idle>-0 3d..3 5us : 0:120:R ==> [003] 2389: 94:R sleep
2090 The 0:120:R means idle was running with a nice priority of 0 (120 - 120)
2092 2389: 94:R. That is the priority is the kernel rtprio (99 - 5 = 94)
2095 Doing the same with chrt -r 5 and function-trace set.
2098 echo 1 > options/function-trace
2102 # wakeup_rt latency trace v1.1.5 on 3.8.0-test+
2103 # --------------------------------------------------------------------
2104 # latency: 29 us, #85/85, CPU#3 | (M:preempt VP:0, KP:0, SP:0 HP:0 #P:4)
2105 # -----------------
2106 # | task: sleep-2448 (uid:0 nice:0 policy:1 rt_prio:5)
2107 # -----------------
2109 # _------=> CPU#
2110 # / _-----=> irqs-off
2111 # | / _----=> need-resched
2112 # || / _---=> hardirq/softirq
2113 # ||| / _--=> preempt-depth
2117 <idle>-0 3d.h4 1us+: 0:120:R + [003] 2448: 94:R sleep
2118 <idle>-0 3d.h4 2us : ttwu_do_activate.constprop.87 <-try_to_wake_up
2119 <idle>-0 3d.h3 3us : check_preempt_curr <-ttwu_do_wakeup
2120 <idle>-0 3d.h3 3us : resched_curr <-check_preempt_curr
2121 <idle>-0 3dNh3 4us : task_woken_rt <-ttwu_do_wakeup
2122 <idle>-0 3dNh3 4us : _raw_spin_unlock <-try_to_wake_up
2123 <idle>-0 3dNh3 4us : sub_preempt_count <-_raw_spin_unlock
2124 <idle>-0 3dNh2 5us : ttwu_stat <-try_to_wake_up
2125 <idle>-0 3dNh2 5us : _raw_spin_unlock_irqrestore <-try_to_wake_up
2126 <idle>-0 3dNh2 6us : sub_preempt_count <-_raw_spin_unlock_irqrestore
2127 <idle>-0 3dNh1 6us : _raw_spin_lock <-__run_hrtimer
2128 <idle>-0 3dNh1 6us : add_preempt_count <-_raw_spin_lock
2129 <idle>-0 3dNh2 7us : _raw_spin_unlock <-hrtimer_interrupt
2130 <idle>-0 3dNh2 7us : sub_preempt_count <-_raw_spin_unlock
2131 <idle>-0 3dNh1 7us : tick_program_event <-hrtimer_interrupt
2132 <idle>-0 3dNh1 7us : clockevents_program_event <-tick_program_event
2133 <idle>-0 3dNh1 8us : ktime_get <-clockevents_program_event
2134 <idle>-0 3dNh1 8us : lapic_next_event <-clockevents_program_event
2135 <idle>-0 3dNh1 8us : irq_exit <-smp_apic_timer_interrupt
2136 <idle>-0 3dNh1 9us : sub_preempt_count <-irq_exit
2137 <idle>-0 3dN.2 9us : idle_cpu <-irq_exit
2138 <idle>-0 3dN.2 9us : rcu_irq_exit <-irq_exit
2139 <idle>-0 3dN.2 10us : rcu_eqs_enter_common.isra.45 <-rcu_irq_exit
2140 <idle>-0 3dN.2 10us : sub_preempt_count <-irq_exit
2141 <idle>-0 3.N.1 11us : rcu_idle_exit <-cpu_idle
2142 <idle>-0 3dN.1 11us : rcu_eqs_exit_common.isra.43 <-rcu_idle_exit
2143 <idle>-0 3.N.1 11us : tick_nohz_idle_exit <-cpu_idle
2144 <idle>-0 3dN.1 12us : menu_hrtimer_cancel <-tick_nohz_idle_exit
2145 <idle>-0 3dN.1 12us : ktime_get <-tick_nohz_idle_exit
2146 <idle>-0 3dN.1 12us : tick_do_update_jiffies64 <-tick_nohz_idle_exit
2147 <idle>-0 3dN.1 13us : cpu_load_update_nohz <-tick_nohz_idle_exit
2148 <idle>-0 3dN.1 13us : _raw_spin_lock <-cpu_load_update_nohz
2149 <idle>-0 3dN.1 13us : add_preempt_count <-_raw_spin_lock
2150 <idle>-0 3dN.2 13us : __cpu_load_update <-cpu_load_update_nohz
2151 <idle>-0 3dN.2 14us : sched_avg_update <-__cpu_load_update
2152 <idle>-0 3dN.2 14us : _raw_spin_unlock <-cpu_load_update_nohz
2153 <idle>-0 3dN.2 14us : sub_preempt_count <-_raw_spin_unlock
2154 <idle>-0 3dN.1 15us : calc_load_nohz_stop <-tick_nohz_idle_exit
2155 <idle>-0 3dN.1 15us : touch_softlockup_watchdog <-tick_nohz_idle_exit
2156 <idle>-0 3dN.1 15us : hrtimer_cancel <-tick_nohz_idle_exit
2157 <idle>-0 3dN.1 15us : hrtimer_try_to_cancel <-hrtimer_cancel
2158 <idle>-0 3dN.1 16us : lock_hrtimer_base.isra.18 <-hrtimer_try_to_cancel
2159 <idle>-0 3dN.1 16us : _raw_spin_lock_irqsave <-lock_hrtimer_base.isra.18
2160 <idle>-0 3dN.1 16us : add_preempt_count <-_raw_spin_lock_irqsave
2161 <idle>-0 3dN.2 17us : __remove_hrtimer <-remove_hrtimer.part.16
2162 <idle>-0 3dN.2 17us : hrtimer_force_reprogram <-__remove_hrtimer
2163 <idle>-0 3dN.2 17us : tick_program_event <-hrtimer_force_reprogram
2164 <idle>-0 3dN.2 18us : clockevents_program_event <-tick_program_event
2165 <idle>-0 3dN.2 18us : ktime_get <-clockevents_program_event
2166 <idle>-0 3dN.2 18us : lapic_next_event <-clockevents_program_event
2167 <idle>-0 3dN.2 19us : _raw_spin_unlock_irqrestore <-hrtimer_try_to_cancel
2168 <idle>-0 3dN.2 19us : sub_preempt_count <-_raw_spin_unlock_irqrestore
2169 <idle>-0 3dN.1 19us : hrtimer_forward <-tick_nohz_idle_exit
2170 <idle>-0 3dN.1 20us : ktime_add_safe <-hrtimer_forward
2171 <idle>-0 3dN.1 20us : ktime_add_safe <-hrtimer_forward
2172 <idle>-0 3dN.1 20us : hrtimer_start_range_ns <-hrtimer_start_expires.constprop.11
2173 <idle>-0 3dN.1 20us : __hrtimer_start_range_ns <-hrtimer_start_range_ns
2174 <idle>-0 3dN.1 21us : lock_hrtimer_base.isra.18 <-__hrtimer_start_range_ns
2175 <idle>-0 3dN.1 21us : _raw_spin_lock_irqsave <-lock_hrtimer_base.isra.18
2176 <idle>-0 3dN.1 21us : add_preempt_count <-_raw_spin_lock_irqsave
2177 <idle>-0 3dN.2 22us : ktime_add_safe <-__hrtimer_start_range_ns
2178 <idle>-0 3dN.2 22us : enqueue_hrtimer <-__hrtimer_start_range_ns
2179 <idle>-0 3dN.2 22us : tick_program_event <-__hrtimer_start_range_ns
2180 <idle>-0 3dN.2 23us : clockevents_program_event <-tick_program_event
2181 <idle>-0 3dN.2 23us : ktime_get <-clockevents_program_event
2182 <idle>-0 3dN.2 23us : lapic_next_event <-clockevents_program_event
2183 <idle>-0 3dN.2 24us : _raw_spin_unlock_irqrestore <-__hrtimer_start_range_ns
2184 <idle>-0 3dN.2 24us : sub_preempt_count <-_raw_spin_unlock_irqrestore
2185 <idle>-0 3dN.1 24us : account_idle_ticks <-tick_nohz_idle_exit
2186 <idle>-0 3dN.1 24us : account_idle_time <-account_idle_ticks
2187 <idle>-0 3.N.1 25us : sub_preempt_count <-cpu_idle
2188 <idle>-0 3.N.. 25us : schedule <-cpu_idle
2189 <idle>-0 3.N.. 25us : __schedule <-preempt_schedule
2190 <idle>-0 3.N.. 26us : add_preempt_count <-__schedule
2191 <idle>-0 3.N.1 26us : rcu_note_context_switch <-__schedule
2192 <idle>-0 3.N.1 26us : rcu_sched_qs <-rcu_note_context_switch
2193 <idle>-0 3dN.1 27us : rcu_preempt_qs <-rcu_note_context_switch
2194 <idle>-0 3.N.1 27us : _raw_spin_lock_irq <-__schedule
2195 <idle>-0 3dN.1 27us : add_preempt_count <-_raw_spin_lock_irq
2196 <idle>-0 3dN.2 28us : put_prev_task_idle <-__schedule
2197 <idle>-0 3dN.2 28us : pick_next_task_stop <-pick_next_task
2198 <idle>-0 3dN.2 28us : pick_next_task_rt <-pick_next_task
2199 <idle>-0 3dN.2 29us : dequeue_pushable_task <-pick_next_task_rt
2200 <idle>-0 3d..3 29us : __schedule <-preempt_schedule
2201 <idle>-0 3d..3 30us : 0:120:R ==> [003] 2448: 94:R sleep
2210 Latency tracing and events
2211 --------------------------
2212 As function tracing can induce a much larger latency, but without
2213 seeing what happens within the latency it is hard to know what
2218 # echo 0 > options/function-trace
2223 # chrt -f 5 sleep 1
2228 # wakeup_rt latency trace v1.1.5 on 3.8.0-test+
2229 # --------------------------------------------------------------------
2230 # latency: 6 us, #12/12, CPU#2 | (M:preempt VP:0, KP:0, SP:0 HP:0 #P:4)
2231 # -----------------
2232 # | task: sleep-5882 (uid:0 nice:0 policy:1 rt_prio:5)
2233 # -----------------
2235 # _------=> CPU#
2236 # / _-----=> irqs-off
2237 # | / _----=> need-resched
2238 # || / _---=> hardirq/softirq
2239 # ||| / _--=> preempt-depth
2243 <idle>-0 2d.h4 0us : 0:120:R + [002] 5882: 94:R sleep
2244 <idle>-0 2d.h4 0us : ttwu_do_activate.constprop.87 <-try_to_wake_up
2245 <idle>-0 2d.h4 1us : sched_wakeup: comm=sleep pid=5882 prio=94 success=1 target_cpu=002
2246 <idle>-0 2dNh2 1us : hrtimer_expire_exit: hrtimer=ffff88007796feb8
2247 <idle>-0 2.N.2 2us : power_end: cpu_id=2
2248 <idle>-0 2.N.2 3us : cpu_idle: state=4294967295 cpu_id=2
2249 <idle>-0 2dN.3 4us : hrtimer_cancel: hrtimer=ffff88007d50d5e0
2250 …<idle>-0 2dN.3 4us : hrtimer_start: hrtimer=ffff88007d50d5e0 function=tick_sched_timer ex…
2251 <idle>-0 2.N.2 5us : rcu_utilization: Start context switch
2252 <idle>-0 2.N.2 5us : rcu_utilization: End context switch
2253 <idle>-0 2d..3 6us : __schedule <-schedule
2254 <idle>-0 2d..3 6us : 0:120:R ==> [002] 5882: 94:R sleep
2257 Hardware Latency Detector
2258 -------------------------
2260 The hardware latency detector is executed by enabling the "hwlat" tracer.
2271 # entries-in-buffer/entries-written: 13/13 #P:8
2273 # _-----=> irqs-off
2274 # / _----=> need-resched
2275 # | / _---=> hardirq/softirq
2276 # || / _--=> preempt-depth
2278 # TASK-PID CPU# |||| TIMESTAMP FUNCTION
2280 …<...>-1729 [001] d... 678.473449: #1 inner/outer(us): 11/12 ts:1581527483.343962693 co…
2281 …<...>-1729 [004] d... 689.556542: #2 inner/outer(us): 16/9 ts:1581527494.889008092 co…
2282 …<...>-1729 [005] d... 714.756290: #3 inner/outer(us): 16/16 ts:1581527519.678961629 co…
2283 …<...>-1729 [001] d... 718.788247: #4 inner/outer(us): 9/17 ts:1581527523.889012713 co…
2284 …<...>-1729 [002] d... 719.796341: #5 inner/outer(us): 13/9 ts:1581527524.912872606 co…
2285 …<...>-1729 [006] d... 844.787091: #6 inner/outer(us): 9/12 ts:1581527649.889048502 co…
2286 …<...>-1729 [003] d... 849.827033: #7 inner/outer(us): 18/9 ts:1581527654.889013793 co…
2287 …<...>-1729 [007] d... 853.859002: #8 inner/outer(us): 9/12 ts:1581527658.889065736 co…
2288 …<...>-1729 [001] d... 855.874978: #9 inner/outer(us): 9/11 ts:1581527660.861991877 co…
2289 …<...>-1729 [001] d... 863.938932: #10 inner/outer(us): 9/11 ts:1581527668.970010500 co…
2290 …<...>-1729 [007] d... 878.050780: #11 inner/outer(us): 9/12 ts:1581527683.385002600 co…
2291 …<...>-1729 [007] d... 886.114702: #12 inner/outer(us): 9/12 ts:1581527691.385001600 co…
2301 inner/outer(us): 11/11
2303 This shows two numbers as "inner latency" and "outer latency". The test
2304 runs in a loop checking a timestamp twice. The latency detected within
2305 the two timestamps is the "inner latency" and the latency detected
2307 the "outer latency".
2311 The absolute timestamp that the first latency was recorded in the window.
2315 The number of times a latency was detected during the window.
2317 nmi-total:7 nmi-count:1
2320 test, the time spent in NMI is reported in "nmi-total" (in
2323 All architectures that have NMIs will show the "nmi-count" if an
2330 microseconds. This is the threshold of latency that
2354 --------
2370 # entries-in-buffer/entries-written: 24799/24799 #P:4
2372 # _-----=> irqs-off
2373 # / _----=> need-resched
2374 # | / _---=> hardirq/softirq
2375 # || / _--=> preempt-depth
2377 # TASK-PID CPU# |||| TIMESTAMP FUNCTION
2379 bash-1994 [002] .... 3082.063030: mutex_unlock <-rb_simple_write
2380 bash-1994 [002] .... 3082.063031: __mutex_unlock_slowpath <-mutex_unlock
2381 bash-1994 [002] .... 3082.063031: __fsnotify_parent <-fsnotify_modify
2382 bash-1994 [002] .... 3082.063032: fsnotify <-fsnotify_modify
2383 bash-1994 [002] .... 3082.063032: __srcu_read_lock <-fsnotify
2384 bash-1994 [002] .... 3082.063032: add_preempt_count <-__srcu_read_lock
2385 bash-1994 [002] ...1 3082.063032: sub_preempt_count <-__srcu_read_lock
2386 bash-1994 [002] .... 3082.063033: __srcu_read_unlock <-fsnotify
2414 ---------------------
2428 # TASK-PID CPU# TIMESTAMP FUNCTION
2430 yum-updatesd-3111 [003] 1637.254676: finish_task_switch <-thread_return
2431 yum-updatesd-3111 [003] 1637.254681: hrtimer_cancel <-schedule_hrtimeout_range
2432 yum-updatesd-3111 [003] 1637.254682: hrtimer_try_to_cancel <-hrtimer_cancel
2433 yum-updatesd-3111 [003] 1637.254683: lock_hrtimer_base <-hrtimer_try_to_cancel
2434 yum-updatesd-3111 [003] 1637.254685: fget_light <-do_sys_poll
2435 yum-updatesd-3111 [003] 1637.254686: pipe_poll <-do_sys_poll
2440 # TASK-PID CPU# TIMESTAMP FUNCTION
2443 yum-updatesd-3111 [003] 1701.957688: free_poll_entry <-poll_freewait
2444 yum-updatesd-3111 [003] 1701.957689: remove_wait_queue <-free_poll_entry
2445 yum-updatesd-3111 [003] 1701.957691: fput <-free_poll_entry
2446 yum-updatesd-3111 [003] 1701.957692: audit_syscall_exit <-sysret_audit
2447 yum-updatesd-3111 [003] 1701.957693: path_put <-audit_syscall_exit
2510 exit(-1);
2519 exit(-1);
2542 tracefs=`sed -ne 's/^tracefs \(.*\) tracefs.*/\1/p' /proc/mounts`
2551 ---------------------------
2554 probes a function on its entry and its exit. This is done by
2556 task_struct. On function entry the tracer overwrites the return
2564 - measure of a function's time execution
2565 - having a reliable call stack to draw function calls graph
2569 - you want to find the reason of a strange kernel behavior and
2573 - you are experiencing weird latencies but it's difficult to
2576 - you want to find quickly which path is taken by a specific
2579 - you just want to peek inside a working kernel and want to see
2593 0) 1.382 us | __might_sleep();
2594 0) 2.478 us | }
2597 0) 1.389 us | __might_sleep();
2598 0) 2.553 us | }
2599 0) 3.807 us | }
2600 0) 7.876 us | }
2602 0) 0.668 us | _spin_lock();
2603 0) 0.570 us | expand_files();
2604 0) 0.586 us | _spin_unlock();
2611 - The cpu number on which the function executed is default
2616 - hide: echo nofuncgraph-cpu > trace_options
2617 - show: echo funcgraph-cpu > trace_options
2619 - The duration (function's time of execution) is displayed on
2624 - hide: echo nofuncgraph-duration > trace_options
2625 - show: echo funcgraph-duration > trace_options
2627 - The overhead field precedes the duration field in case of
2630 - hide: echo nofuncgraph-overhead > trace_options
2631 - show: echo funcgraph-overhead > trace_options
2632 - depends on: funcgraph-duration
2636 3) # 1837.709 us | } /* __switch_to */
2638 3) 0.313 us | _raw_spin_unlock_irq();
2639 3) 3.177 us | }
2640 3) # 1889.063 us | } /* __schedule */
2641 3) ! 140.417 us | } /* __schedule */
2642 3) # 2034.948 us | } /* schedule */
2643 3) * 33998.59 us | } /* schedule_preempt_disabled */
2647 1) 0.260 us | msecs_to_jiffies();
2648 1) 0.313 us | __rcu_read_unlock();
2649 1) + 61.770 us | }
2650 1) + 64.479 us | }
2651 1) 0.313 us | rcu_bh_qs();
2652 1) 0.313 us | __local_bh_enable();
2653 1) ! 217.240 us | }
2654 1) 0.365 us | idle_cpu();
2656 1) 0.417 us | rcu_eqs_enter_common.isra.47();
2657 1) 3.125 us | }
2658 1) ! 227.812 us | }
2659 1) ! 457.395 us | }
2660 1) @ 119760.2 us | }
2665 1) 6.979 us | }
2666 2) 0.417 us | scheduler_ipi();
2667 1) 9.791 us | }
2668 1) + 12.917 us | }
2669 2) 3.490 us | }
2670 1) + 15.729 us | }
2671 1) + 18.542 us | }
2672 2) $ 3594274 us | }
2684 - The task/pid field displays the thread cmdline and pid which
2687 - hide: echo nofuncgraph-proc > trace_options
2688 - show: echo funcgraph-proc > trace_options
2696 0) sh-4802 | | d_free() {
2697 0) sh-4802 | | call_rcu() {
2698 0) sh-4802 | | __call_rcu() {
2699 0) sh-4802 | 0.616 us | rcu_process_gp_end();
2700 0) sh-4802 | 0.586 us | check_for_new_grace_period();
2701 0) sh-4802 | 2.899 us | }
2702 0) sh-4802 | 4.040 us | }
2703 0) sh-4802 | 5.151 us | }
2704 0) sh-4802 | + 49.370 us | }
2707 - The absolute time field is an absolute timestamp given by the
2709 given on each entry/exit of functions
2711 - hide: echo nofuncgraph-abstime > trace_options
2712 - show: echo funcgraph-abstime > trace_options
2719 360.774522 | 1) 0.541 us | }
2720 360.774522 | 1) 4.663 us | }
2721 360.774523 | 1) 0.541 us | __wake_up_bit();
2722 360.774524 | 1) 6.796 us | }
2723 360.774524 | 1) 7.952 us | }
2724 360.774525 | 1) 9.063 us | }
2725 360.774525 | 1) 0.615 us | journal_mark_dirty();
2726 360.774527 | 1) 0.578 us | __brelse();
2731 360.774530 | 1) 0.594 us | __phys_addr();
2743 - hide: echo nofuncgraph-tail > trace_options
2744 - show: echo funcgraph-tail > trace_options
2746 Example with nofuncgraph-tail (default)::
2750 0) 0.518 us | __phys_addr();
2751 0) 1.757 us | }
2752 0) 2.861 us | }
2754 Example with funcgraph-tail::
2758 0) 0.518 us | __phys_addr();
2759 0) 1.757 us | } /* kmem_cache_free() */
2760 0) 2.861 us | } /* putname() */
2767 - hide: echo nofuncgraph-retval > trace_options
2768 - show: echo funcgraph-retval > trace_options
2770 Example with funcgraph-retval::
2773 1) 0.651 us | cgroup_migrate_add_task(); /* = 0xffff93fcfd346c00 */
2777 1) 0.732 us | cgroup_taskset_next(); /* = 0xffff93fc8fb20000 */
2778 1) 1.232 us | } /* cgroup_taskset_first = 0xffff93fc8fb20000 */
2779 1) 0.380 us | sched_rt_can_attach(); /* = 0x0 */
2780 1) 2.335 us | } /* cpu_cgroup_can_attach = -22 */
2781 1) 4.369 us | } /* cgroup_migrate_execute = -22 */
2782 1) 7.143 us | } /* cgroup_migrate = -22 */
2785 returned the error code -22 firstly, then we can read the code
2788 When the option funcgraph-retval-hex is not set, the return value can
2793 - smart: echo nofuncgraph-retval-hex > trace_options
2794 - hexadecimal: echo funcgraph-retval-hex > trace_options
2796 Example with funcgraph-retval-hex::
2799 1) 0.651 us | cgroup_migrate_add_task(); /* = 0xffff93fcfd346c00 */
2803 1) 0.732 us | cgroup_taskset_next(); /* = 0xffff93fc8fb20000 */
2804 1) 1.232 us | } /* cgroup_taskset_first = 0xffff93fc8fb20000 */
2805 1) 0.380 us | sched_rt_can_attach(); /* = 0x0 */
2806 1) 2.335 us | } /* cpu_cgroup_can_attach = 0xffffffea */
2807 1) 4.369 us | } /* cgroup_migrate_execute = 0xffffffea */
2808 1) 7.143 us | } /* cgroup_migrate = 0xffffffea */
2810 At present, there are some limitations when using the funcgraph-retval
2813 - Even if the function return type is void, a return value will still
2816 - Even if return values are stored in multiple registers, only the
2819 a 64-bit return value, with the lower 32 bits saved in eax and the
2823 - In certain procedure call standards, such as arm64's AAPCS64, when a
2827 when using a u8 in a 64-bit GPR, bits [63:8] may contain arbitrary values,
2857 return -EINVAL;
2869 MOV x0, #-EINVAL
2886 1) 1.449 us | }
2894 --------------
2899 every kernel function, produced by the -pg switch in gcc),
2901 include the -pg switch in the compiling of the kernel.)
2907 with gcc version 4.6, the -mfentry has been added for x86, which
2918 The recordmcount program re-links this section back into the
2950 One special side-effect to the recording of the functions being
2990 # entries-in-buffer/entries-written: 5/5 #P:4
2992 # _-----=> irqs-off
2993 # / _----=> need-resched
2994 # | / _---=> hardirq/softirq
2995 # || / _--=> preempt-depth
2997 # TASK-PID CPU# |||| TIMESTAMP FUNCTION
2999 usleep-2665 [001] .... 4186.475355: sys_nanosleep <-system_call_fastpath
3000 <idle>-0 [001] d.h1 4186.475409: hrtimer_interrupt <-smp_apic_timer_interrupt
3001 usleep-2665 [001] d.h1 4186.475426: hrtimer_interrupt <-smp_apic_timer_interrupt
3002 <idle>-0 [003] d.h1 4186.475426: hrtimer_interrupt <-smp_apic_timer_interrupt
3003 <idle>-0 [002] d.h1 4186.475427: hrtimer_interrupt <-smp_apic_timer_interrupt
3037 # entries-in-buffer/entries-written: 897/897 #P:4
3039 # _-----=> irqs-off
3040 # / _----=> need-resched
3041 # | / _---=> hardirq/softirq
3042 # || / _--=> preempt-depth
3044 # TASK-PID CPU# |||| TIMESTAMP FUNCTION
3046 <idle>-0 [003] dN.1 4228.547803: hrtimer_cancel <-tick_nohz_idle_exit
3047 <idle>-0 [003] dN.1 4228.547804: hrtimer_try_to_cancel <-hrtimer_cancel
3048 <idle>-0 [003] dN.2 4228.547805: hrtimer_force_reprogram <-__remove_hrtimer
3049 <idle>-0 [003] dN.1 4228.547805: hrtimer_forward <-tick_nohz_idle_exit
3050 … <idle>-0 [003] dN.1 4228.547805: hrtimer_start_range_ns <-hrtimer_start_expires.constprop.11
3051 <idle>-0 [003] d..1 4228.547858: hrtimer_get_next_event <-get_next_timer_interrupt
3052 <idle>-0 [003] d..1 4228.547859: hrtimer_start <-__tick_nohz_idle_enter
3053 <idle>-0 [003] d..2 4228.547860: hrtimer_force_reprogram <-__rem
3126 # entries-in-buffer/entries-written: 39608/39608 #P:4
3128 # _-----=> irqs-off
3129 # / _----=> need-resched
3130 # | / _---=> hardirq/softirq
3131 # || / _--=> preempt-depth
3133 # TASK-PID CPU# |||| TIMESTAMP FUNCTION
3135 bash-1994 [000] .... 4342.324896: file_ra_state_init <-do_dentry_open
3136 bash-1994 [000] .... 4342.324897: open_check_o_direct <-do_last
3137 bash-1994 [000] .... 4342.324897: ima_file_check <-do_last
3138 bash-1994 [000] .... 4342.324898: process_measurement <-ima_file_check
3139 bash-1994 [000] .... 4342.324898: ima_get_action <-process_measurement
3140 bash-1994 [000] .... 4342.324898: ima_match_policy <-ima_get_action
3141 bash-1994 [000] .... 4342.324899: do_truncate <-do_last
3142 bash-1994 [000] .... 4342.324899: setattr_should_drop_suidgid <-do_truncate
3143 bash-1994 [000] .... 4342.324899: notify_change <-do_truncate
3144 bash-1994 [000] .... 4342.324900: current_fs_time <-notify_change
3145 bash-1994 [000] .... 4342.324900: current_kernel_time <-current_fs_time
3146 bash-1994 [000] .... 4342.324900: timespec_trunc <-current_fs_time
3151 ------------------------------------
3169 # head -1 available_filter_functions
3175 # head -50 available_filter_functions | tail -1
3184 ---------------------------------------------
3187 function tracer and the function-graph-tracer, there are some
3188 special features only available in the function-graph tracer.
3201 0) 0.804 us | find_get_page();
3203 0) 1.329 us | }
3204 0) 3.904 us | }
3205 0) 4.979 us | }
3206 0) 0.653 us | _spin_lock();
3207 0) 0.578 us | page_add_file_rmap();
3208 0) 0.525 us | native_set_pte_at();
3209 0) 0.585 us | _spin_unlock();
3211 0) 0.541 us | page_waitqueue();
3212 0) 0.639 us | __wake_up_bit();
3213 0) 2.786 us | }
3214 0) + 14.237 us | }
3218 0) 0.698 us | find_get_page();
3220 0) 1.412 us | }
3221 0) 3.950 us | }
3222 0) 5.098 us | }
3223 0) 0.631 us | _spin_lock();
3224 0) 0.571 us | page_add_file_rmap();
3225 0) 0.526 us | native_set_pte_at();
3226 0) 0.586 us | _spin_unlock();
3228 0) 0.533 us | page_waitqueue();
3229 0) 0.638 us | __wake_up_bit();
3230 0) 2.793 us | }
3231 0) + 14.012 us | }
3245 --------------
3269 ---------------
3278 - mod:
3310 - traceon/traceoff:
3334 - snapshot:
3350 - enable_event/disable_event:
3374 - dump:
3381 - cpudump:
3387 - stacktrace:
3391 ----------
3408 # entries-in-buffer/entries-written: 0/0 #P:4
3410 # _-----=> irqs-off
3411 # / _----=> need-resched
3412 # | / _---=> hardirq/softirq
3413 # || / _--=> preempt-depth
3415 # TASK-PID CPU# |||| TIMESTAMP FUNCTION
3420 bash-1994 [000] .... 5281.568961: mutex_unlock <-rb_simple_write
3421 bash-1994 [000] .... 5281.568963: __mutex_unlock_slowpath <-mutex_unlock
3422 bash-1994 [000] .... 5281.568963: __fsnotify_parent <-fsnotify_modify
3423 bash-1994 [000] .... 5281.568964: fsnotify <-fsnotify_modify
3424 bash-1994 [000] .... 5281.568964: __srcu_read_lock <-fsnotify
3425 bash-1994 [000] .... 5281.568964: add_preempt_count <-__srcu_read_lock
3426 bash-1994 [000] ...1 5281.568965: sub_preempt_count <-__srcu_read_lock
3427 bash-1994 [000] .... 5281.568965: __srcu_read_unlock <-fsnotify
3428 bash-1994 [000] .... 5281.568967: sys_dup2 <-system_call_fastpath
3438 -------------
3465 much, it can cause Out-Of-Memory to trigger.
3469 -bash: echo: write error: Cannot allocate memory
3496 --------
3498 available to all non latency tracers. (Latency tracers which
3499 record max latency, such as "irqsoff" or "wakeup", can't use
3524 +--------------+------------+------------+------------+
3528 +--------------+------------+------------+------------+
3530 +--------------+------------+------------+------------+
3540 # entries-in-buffer/entries-written: 71/71 #P:8
3542 # _-----=> irqs-off
3543 # / _----=> need-resched
3544 # | / _---=> hardirq/softirq
3545 # || / _--=> preempt-depth
3547 # TASK-PID CPU# |||| TIMESTAMP FUNCTION
3549 …<idle>-0 [005] d... 2440.603828: sched_switch: prev_comm=swapper/5 prev_pid=0 prev_prio=120 …
3550 …sleep-2242 [005] d... 2440.603846: sched_switch: prev_comm=snapshot-test-2 prev_pid=2242 prev_pr…
3552 …<idle>-0 [002] d... 2440.707230: sched_switch: prev_comm=swapper/2 prev_pid=0 prev_prio=120 p…
3557 # entries-in-buffer/entries-written: 77/77 #P:8
3559 # _-----=> irqs-off
3560 # / _----=> need-resched
3561 # | / _---=> hardirq/softirq
3562 # || / _--=> preempt-depth
3564 # TASK-PID CPU# |||| TIMESTAMP FUNCTION
3566 …<idle>-0 [007] d... 2440.707395: sched_switch: prev_comm=swapper/7 prev_pid=0 prev_prio=120 p…
3567 …snapshot-test-2-2229 [002] d... 2440.707438: sched_switch: prev_comm=snapshot-test-2 prev_pid=22…
3572 one of the latency tracers, you will get the following results.
3583 ---------
3629 bash-2044 [002] .... 10594.481032: _raw_spin_lock_irqsave <-get_page_from_freelist
3630 bash-2044 [002] d... 10594.481032: add_preempt_count <-_raw_spin_lock_irqsave
3631 bash-2044 [002] d..1 10594.481032: __rmqueue <-get_page_from_freelist
3632 bash-2044 [002] d..1 10594.481033: _raw_spin_unlock <-get_page_from_freelist
3633 bash-2044 [002] d..1 10594.481033: sub_preempt_count <-_raw_spin_unlock
3634 … bash-2044 [002] d... 10594.481033: get_pageblock_flags_group <-get_pageblock_migratetype
3635 bash-2044 [002] d... 10594.481034: __mod_zone_page_state <-get_page_from_freelist
3636 bash-2044 [002] d... 10594.481034: zone_statistics <-get_page_from_freelist
3637 bash-2044 [002] d... 10594.481034: __inc_zone_state <-zone_statistics
3638 bash-2044 [002] d... 10594.481034: __inc_zone_state <-zone_statistics
3639 bash-2044 [002] .... 10594.481035: arch_dup_task_struct <-copy_process
3643 …bash-1998 [000] d..4 136.676759: sched_wakeup: comm=kworker/0:1 pid=59 prio=120 success=1 targe…
3644 …bash-1998 [000] dN.4 136.676760: sched_wakeup: comm=bash pid=1998 prio=120 success=1 target_cpu…
3645 …<idle>-0 [003] d.h3 136.676906: sched_wakeup: comm=rcu_preempt pid=9 prio=120 success=1 targ…
3646 …<idle>-0 [003] d..3 136.676909: sched_switch: prev_comm=swapper/3 prev_pid=0 prev_prio=120 p…
3647 …rcu_preempt-9 [003] d..3 136.676916: sched_switch: prev_comm=rcu_preempt prev_pid=9 prev_pri…
3648 …bash-1998 [000] d..4 136.677014: sched_wakeup: comm=kworker/0:1 pid=59 prio=120 success=1 targe…
3649 …bash-1998 [000] dN.4 136.677016: sched_wakeup: comm=bash pid=1998 prio=120 success=1 target_cpu…
3650 …bash-1998 [000] d..3 136.677018: sched_switch: prev_comm=bash prev_pid=1998 prev_prio=120 prev_…
3651 …kworker/0:1-59 [000] d..4 136.677022: sched_wakeup: comm=sshd pid=1995 prio=120 success=1 tar…
3652 …kworker/0:1-59 [000] d..3 136.677025: sched_switch: prev_comm=kworker/0:1 prev_pid=59 prev_pr…
3656 migration/1-14 [001] d.h3 138.732674: softirq_raise: vec=3 [action=NET_RX]
3657 <idle>-0 [001] dNh3 138.732725: softirq_raise: vec=3 [action=NET_RX]
3658 bash-1998 [000] d.h1 138.733101: softirq_raise: vec=1 [action=TIMER]
3659 bash-1998 [000] d.h1 138.733102: softirq_raise: vec=9 [action=RCU]
3660 bash-1998 [000] ..s2 138.733105: softirq_entry: vec=1 [action=TIMER]
3661 bash-1998 [000] ..s2 138.733106: softirq_exit: vec=1 [action=TIMER]
3662 bash-1998 [000] ..s2 138.733106: softirq_entry: vec=9 [action=RCU]
3663 bash-1998 [000] ..s2 138.733109: softirq_exit: vec=9 [action=RCU]
3664 sshd-1995 [001] d.h1 138.733278: irq_handler_entry: irq=21 name=uhci_hcd:usb4
3665 sshd-1995 [001] d.h1 138.733280: irq_handler_exit: irq=21 ret=unhandled
3666 sshd-1995 [001] d.h1 138.733281: irq_handler_entry: irq=21 name=eth0
3667 sshd-1995 [001] d.h1 138.733283: irq_handler_exit: irq=21 ret=handled
3673 # entries-in-buffer/entries-written: 18996/18996 #P:4
3675 # _-----=> irqs-off
3676 # / _----=> need-resched
3677 # | / _---=> hardirq/softirq
3678 # || / _--=> preempt-depth
3680 # TASK-PID CPU# |||| TIMESTAMP FUNCTION
3682 bash-1998 [000] d... 140.733501: sys_write -> 0x2
3683 bash-1998 [000] d... 140.733504: sys_dup2(oldfd: a, newfd: 1)
3684 bash-1998 [000] d... 140.733506: sys_dup2 -> 0x1
3685 bash-1998 [000] d... 140.733508: sys_fcntl(fd: a, cmd: 1, arg: 0)
3686 bash-1998 [000] d... 140.733509: sys_fcntl -> 0x1
3687 bash-1998 [000] d... 140.733510: sys_close(fd: a)
3688 bash-1998 [000] d... 140.733510: sys_close -> 0x0
3689 …bash-1998 [000] d... 140.733514: sys_rt_sigprocmask(how: 0, nset: 0, oset: 6e2768, sigsetsize: …
3690 bash-1998 [000] d... 140.733515: sys_rt_sigprocmask -> 0x0
3691 …bash-1998 [000] d... 140.733516: sys_rt_sigaction(sig: 2, act: 7fff718846f0, oact: 7fff71884650…
3692 bash-1998 [000] d... 140.733516: sys_rt_sigaction -> 0x0
3710 -----------
3741 ----- ---- --------
3761 Note, if -mfentry is being used by gcc, functions get traced before
3763 are not tested by the stack tracer when -mfentry is used.
3765 Currently, -mfentry is used by gcc 4.6.0 and above on x86 only.
3768 ----