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 meta-data. If the last page allocated has room for more bytes
196 due to buffer management meta-data. )
260 If the "function-fork" option is set, then when a task whose
271 If the "function-fork" option is set, then when a task whose
287 added on fork, enable the "event-fork" option. That option will also
300 added on fork, enable the "event-fork" option. That option will also
330 for each function. The displayed address is the patch-site address
355 the "ip modify" attribute (thus the regs->ip can be changed),
364 the ftrace ops function located above the function entry point. In
440 If the option "record-cmd" is set to "0", then comms of tasks
451 If the option "record-tgid" is set, on each scheduling context switch
453 the thread to its TGID. By default, the "record-tgid" option is
492 [local] global counter x86-tsc
519 x86-tsc:
523 ppc-tb:
546 Also on 32-bit systems, it's possible that the 64-bit boot offset
552 This is the tai clock (CLOCK_TAI) and is derived from the wall-
666 delta: Default timestamp mode - timestamp is a delta against
667 a per-buffer timestamp.
675 Directory for the Hardware Latency Detector.
676 See "Hardware Latency Detector" section below.
741 event (ring buffer is re-entrant), that it fills the
760 -----------
771 function tracer probes the functions on their entry
772 whereas the function graph tracer traces on both entry
784 The Hardware Latency tracer is used to detect if the hardware
785 produces any latency. See "Hardware Latency Detector" section
791 the trace with the longest max latency.
794 trace with the latency-format option enabled, which
810 Traces and records the max latency that it takes for
817 Traces and records the max latency that it takes for just
823 Traces and records the max latency that it takes for
848 ----------------
880 ----------------------------
884 user-land utilities).
887 --------------
893 # entries-in-buffer/entries-written: 140080/250280 #P:4
895 # _-----=> irqs-off
896 # / _----=> need-resched
897 # | / _---=> hardirq/softirq
898 # || / _--=> preempt-depth
900 # TASK-PID CPU# |||| TIMESTAMP FUNCTION
902 bash-1977 [000] .... 17284.993652: sys_close <-system_call_fastpath
903 bash-1977 [000] .... 17284.993653: __close_fd <-sys_close
904 bash-1977 [000] .... 17284.993653: _raw_spin_lock <-__close_fd
905 sshd-1974 [003] .... 17284.993653: __srcu_read_unlock <-fsnotify
906 bash-1977 [000] .... 17284.993654: add_preempt_count <-_raw_spin_lock
907 bash-1977 [000] ...1 17284.993655: _raw_spin_unlock <-__close_fd
908 bash-1977 [000] ...1 17284.993656: sub_preempt_count <-_raw_spin_unlock
909 bash-1977 [000] .... 17284.993657: filp_close <-__close_fd
910 bash-1977 [000] .... 17284.993657: dnotify_flush <-filp_close
911 sshd-1974 [003] .... 17284.993658: sys_select <-system_call_fastpath
918 lost due to the buffer filling up (250280 - 140080 = 110200 events
922 PID "1977", the CPU that it was running on "000", the latency format
928 Latency trace format
929 --------------------
931 When the latency-format option is enabled or when one of the latency
933 why a latency happened. Here is a typical trace::
937 # irqsoff latency trace v1.1.5 on 3.8.0-test+
938 # --------------------------------------------------------------------
939 # latency: 259 us, #4/4, CPU#2 | (M:preempt VP:0, KP:0, SP:0 HP:0 #P:4)
940 # -----------------
941 # | task: ps-6143 (uid:0 nice:0 policy:0 rt_prio:0)
942 # -----------------
947 # _------=> CPU#
948 # / _-----=> irqs-off
949 # | / _----=> need-resched
950 # || / _---=> hardirq/softirq
951 # ||| / _--=> preempt-depth
955 ps-6143 2d... 0us!: trace_hardirqs_off <-__lock_task_sighand
956 ps-6143 2d..1 259us+: trace_hardirqs_on <-_raw_spin_unlock_irqrestore
957 ps-6143 2d..1 263us+: time_hardirqs_on <-_raw_spin_unlock_irqrestore
958 ps-6143 2d..1 306us : <stack trace>
974 (3.8). Then it displays the max latency in microseconds (259 us). The number
979 The task is the process that was running when the latency
985 - __lock_task_sighand is where the interrupts were disabled.
986 - _raw_spin_unlock_irqrestore is where they were enabled again.
997 irqs-off: 'd' interrupts are disabled. '.' otherwise.
1002 need-resched:
1003 - 'N' both TIF_NEED_RESCHED and PREEMPT_NEED_RESCHED is set,
1004 - 'n' only TIF_NEED_RESCHED is set,
1005 - 'p' only PREEMPT_NEED_RESCHED is set,
1006 - '.' otherwise.
1009 - 'Z' - NMI occurred inside a hardirq
1010 - 'z' - NMI is running
1011 - 'H' - hard irq occurred inside a softirq.
1012 - 'h' - hard irq is running
1013 - 's' - soft irq is running
1014 - '.' - normal context.
1016 preempt-depth: The level of preempt_disabled
1021 When the latency-format option is enabled, the trace file
1023 trace. This differs from the output when latency-format
1032 - '$' - greater than 1 second
1033 - '@' - greater than 100 millisecond
1034 - '*' - greater than 10 millisecond
1035 - '#' - greater than 1000 microsecond
1036 - '!' - greater than 100 microsecond
1037 - '+' - greater than 10 microsecond
1038 - ' ' - less than or equal to 10 microsecond.
1042 Note, the latency tracers will usually end with a back trace
1043 to easily find where the latency occurred.
1046 -------------
1053 print-parent
1054 nosym-offset
1055 nosym-addr
1065 nosym-userobj
1066 noprintk-msg-only
1067 context-info
1068 nolatency-format
1069 record-cmd
1070 norecord-tgid
1073 irq-info
1075 noevent-fork
1076 function-trace
1077 nofunction-fork
1078 nodisplay-graph
1085 echo noprint-parent > trace_options
1089 echo sym-offset > trace_options
1093 print-parent
1098 print-parent:
1099 bash-4000 [01] 1477.606694: simple_strtoul <-kstrtoul
1101 noprint-parent:
1102 bash-4000 [01] 1477.606694: simple_strtoul
1105 sym-offset
1112 sym-offset:
1113 bash-4000 [01] 1477.606694: simple_strtoul+0x6/0xa0
1115 sym-addr
1120 sym-addr:
1121 bash-4000 [01] 1477.606694: simple_strtoul <c0339346>
1125 latency-format option is enabled.
1163 <idle>-0 [001] dNs4 21169.031481: wake_up_idle_cpu <-add_timer_on
1164 <idle>-0 [001] dNs4 21169.031482: _raw_spin_unlock_irqrestore <-add_timer_on
1165 <idle>-0 [001] .Ns4 21169.031484: sub_preempt_count <-_raw_spin_unlock_irqrestore
1167 <idle>-0 [002] .N.1 21169.031484: rcu_idle_exit <-cpu_idle
1168 <idle>-0 [001] .Ns3 21169.031484: _raw_spin_unlock <-clocksource_watchdog
1169 <idle>-0 [001] .Ns3 21169.031485: sub_preempt_count <-_raw_spin_unlock
1176 sym-userobj
1187 a.out-1623 [000] 40874.465068: /root/a.out[+0x480] <-/root/a.out[+0
1188 x494] <- /root/a.out[+0x4a8] <- /lib/libc-2.7.so[+0x1e1a6]
1191 printk-msg-only
1196 context-info
1200 latency-format
1203 latency, as described in "Latency trace format".
1205 pause-on-trace
1211 hash-ptr
1217 record-cmd
1225 record-tgid
1242 irq-info
1248 # entries-in-buffer/entries-written: 144405/9452052 #P:4
1250 # TASK-PID CPU# TIMESTAMP FUNCTION
1252 <idle>-0 [002] 23636.756054: ttwu_do_activate.constprop.89 <-try_to_wake_up
1253 <idle>-0 [002] 23636.756054: activate_task <-ttwu_do_activate.constprop.89
1254 <idle>-0 [002] 23636.756055: enqueue_task <-activate_task
1262 event-fork
1270 function-trace
1271 The latency tracers will enable function tracing
1273 it is disabled, the latency tracers do not trace
1275 when performing latency tests.
1277 function-fork
1286 display-graph
1287 When set, the latency tracers (irqsoff, wakeup, etc) will
1322 funcgraph-overrun
1333 funcgraph-cpu
1337 funcgraph-overhead
1343 funcgraph-proc
1350 funcgraph-duration
1355 funcgraph-abstime
1358 funcgraph-irqs
1362 funcgraph-tail
1368 funcgraph-retval
1373 funcgraph-retval-hex
1381 sleep-time
1387 graph-time
1401 -------
1406 the kernel know of a new mouse event. The result is a latency
1410 disabled. When a new maximum latency is hit, the tracer saves
1411 the trace leading up to that latency point so that every time a
1418 # echo 0 > options/function-trace
1422 # ls -ltr
1428 # irqsoff latency trace v1.1.5 on 3.8.0-test+
1429 # --------------------------------------------------------------------
1430 # latency: 16 us, #4/4, CPU#0 | (M:preempt VP:0, KP:0, SP:0 HP:0 #P:4)
1431 # -----------------
1432 # | task: swapper/0-0 (uid:0 nice:0 policy:0 rt_prio:0)
1433 # -----------------
1438 # _------=> CPU#
1439 # / _-----=> irqs-off
1440 # | / _----=> need-resched
1441 # || / _---=> hardirq/softirq
1442 # ||| / _--=> preempt-depth
1446 <idle>-0 0d.s2 0us+: _raw_spin_lock_irq <-run_timer_softirq
1447 <idle>-0 0dNs3 17us : _raw_spin_unlock_irq <-run_timer_softirq
1448 <idle>-0 0dNs3 17us+: trace_hardirqs_on <-run_timer_softirq
1449 <idle>-0 0dNs3 25us : <stack trace>
1465 Here we see that we had a latency of 16 microseconds (which is
1468 timestamp 25us occurred because the clock was incremented
1469 between the time of recording the max latency and the time of
1470 recording the function that had that latency.
1472 Note the above example had function-trace not set. If we set
1473 function-trace, we get a much larger output::
1475 with echo 1 > options/function-trace
1479 # irqsoff latency trace v1.1.5 on 3.8.0-test+
1480 # --------------------------------------------------------------------
1481 # latency: 71 us, #168/168, CPU#3 | (M:preempt VP:0, KP:0, SP:0 HP:0 #P:4)
1482 # -----------------
1483 # | task: bash-2042 (uid:0 nice:0 policy:0 rt_prio:0)
1484 # -----------------
1489 # _------=> CPU#
1490 # / _-----=> irqs-off
1491 # | / _----=> need-resched
1492 # || / _---=> hardirq/softirq
1493 # ||| / _--=> preempt-depth
1497 bash-2042 3d... 0us : _raw_spin_lock_irqsave <-ata_scsi_queuecmd
1498 bash-2042 3d... 0us : add_preempt_count <-_raw_spin_lock_irqsave
1499 bash-2042 3d..1 1us : ata_scsi_find_dev <-ata_scsi_queuecmd
1500 bash-2042 3d..1 1us : __ata_scsi_find_dev <-ata_scsi_find_dev
1501 bash-2042 3d..1 2us : ata_find_dev.part.14 <-__ata_scsi_find_dev
1502 bash-2042 3d..1 2us : ata_qc_new_init <-__ata_scsi_queuecmd
1503 bash-2042 3d..1 3us : ata_sg_init <-__ata_scsi_queuecmd
1504 bash-2042 3d..1 4us : ata_scsi_rw_xlat <-__ata_scsi_queuecmd
1505 bash-2042 3d..1 4us : ata_build_rw_tf <-ata_scsi_rw_xlat
1507 bash-2042 3d..1 67us : delay_tsc <-__delay
1508 bash-2042 3d..1 67us : add_preempt_count <-delay_tsc
1509 bash-2042 3d..2 67us : sub_preempt_count <-delay_tsc
1510 bash-2042 3d..1 67us : add_preempt_count <-delay_tsc
1511 bash-2042 3d..2 68us : sub_preempt_count <-delay_tsc
1512 bash-2042 3d..1 68us+: ata_bmdma_start <-ata_bmdma_qc_issue
1513 bash-2042 3d..1 71us : _raw_spin_unlock_irqrestore <-ata_scsi_queuecmd
1514 bash-2042 3d..1 71us : _raw_spin_unlock_irqrestore <-ata_scsi_queuecmd
1515 bash-2042 3d..1 72us+: trace_hardirqs_on <-ata_scsi_queuecmd
1516 bash-2042 3d..1 120us : <stack trace>
1544 Here we traced a 71 microsecond latency. But we also see all the
1547 overhead may extend the latency times. But nevertheless, this
1551 display-graph option::
1553 with echo 1 > options/display-graph
1557 # irqsoff latency trace v1.1.5 on 4.20.0-rc6+
1558 # --------------------------------------------------------------------
1559 # latency: 3751 us, #274/274, CPU#0 | (M:desktop VP:0, KP:0, SP:0 HP:0 #P:4)
1560 # -----------------
1561 # | task: bash-1507 (uid:0 nice:0 policy:0 rt_prio:0)
1562 # -----------------
1567 # _-----=> irqs-off
1568 # / _----=> need-resched
1569 # | / _---=> hardirq/softirq
1570 # || / _--=> preempt-depth
1574 0 us | 0) bash-1507 | d... | 0.000 us | _raw_spin_lock_irqsave();
1575 0 us | 0) bash-1507 | d..1 | 0.378 us | do_raw_spin_trylock();
1576 1 us | 0) bash-1507 | d..2 | | set_track() {
1577 2 us | 0) bash-1507 | d..2 | | save_stack_trace() {
1578 2 us | 0) bash-1507 | d..2 | | __save_stack_trace() {
1579 3 us | 0) bash-1507 | d..2 | | __unwind_start() {
1580 3 us | 0) bash-1507 | d..2 | | get_stack_info() {
1581 3 us | 0) bash-1507 | d..2 | 0.351 us | in_task_stack();
1582 4 us | 0) bash-1507 | d..2 | 1.107 us | }
1584 3750 us | 0) bash-1507 | d..1 | 0.516 us | do_raw_spin_unlock();
1585 3750 us | 0) bash-1507 | d..1 | 0.000 us | _raw_spin_unlock_irqrestore();
1586 3764 us | 0) bash-1507 | d..1 | 0.000 us | tracer_hardirqs_on();
1587 bash-1507 0d..1 3792us : <stack trace>
1604 ----------
1612 Like the irqsoff tracer, it records the maximum latency for
1617 # echo 0 > options/function-trace
1621 # ls -ltr
1627 # preemptoff latency trace v1.1.5 on 3.8.0-test+
1628 # --------------------------------------------------------------------
1629 # latency: 46 us, #4/4, CPU#1 | (M:preempt VP:0, KP:0, SP:0 HP:0 #P:4)
1630 # -----------------
1631 # | task: sshd-1991 (uid:0 nice:0 policy:0 rt_prio:0)
1632 # -----------------
1637 # _------=> CPU#
1638 # / _-----=> irqs-off
1639 # | / _----=> need-resched
1640 # || / _---=> hardirq/softirq
1641 # ||| / _--=> preempt-depth
1645 sshd-1991 1d.h. 0us+: irq_enter <-do_IRQ
1646 sshd-1991 1d..1 46us : irq_exit <-do_IRQ
1647 sshd-1991 1d..1 47us+: trace_preempt_on <-do_IRQ
1648 sshd-1991 1d..1 52us : <stack trace>
1665 # preemptoff latency trace v1.1.5 on 3.8.0-test+
1666 # --------------------------------------------------------------------
1667 # latency: 83 us, #241/241, CPU#1 | (M:preempt VP:0, KP:0, SP:0 HP:0 #P:4)
1668 # -----------------
1669 # | task: bash-1994 (uid:0 nice:0 policy:0 rt_prio:0)
1670 # -----------------
1675 # _------=> CPU#
1676 # / _-----=> irqs-off
1677 # | / _----=> need-resched
1678 # || / _---=> hardirq/softirq
1679 # ||| / _--=> preempt-depth
1683 bash-1994 1d..1 0us : _raw_spin_lock_irqsave <-wake_up_new_task
1684 bash-1994 1d..1 0us : select_task_rq_fair <-select_task_rq
1685 bash-1994 1d..1 1us : __rcu_read_lock <-select_task_rq_fair
1686 bash-1994 1d..1 1us : source_load <-select_task_rq_fair
1687 bash-1994 1d..1 1us : source_load <-select_task_rq_fair
1689 bash-1994 1d..1 12us : irq_enter <-smp_apic_timer_interrupt
1690 bash-1994 1d..1 12us : rcu_irq_enter <-irq_enter
1691 bash-1994 1d..1 13us : add_preempt_count <-irq_enter
1692 bash-1994 1d.h1 13us : exit_idle <-smp_apic_timer_interrupt
1693 bash-1994 1d.h1 13us : hrtimer_interrupt <-smp_apic_timer_interrupt
1694 bash-1994 1d.h1 13us : _raw_spin_lock <-hrtimer_interrupt
1695 bash-1994 1d.h1 14us : add_preempt_count <-_raw_spin_lock
1696 bash-1994 1d.h2 14us : ktime_get_update_offsets <-hrtimer_interrupt
1698 bash-1994 1d.h1 35us : lapic_next_event <-clockevents_program_event
1699 bash-1994 1d.h1 35us : irq_exit <-smp_apic_timer_interrupt
1700 bash-1994 1d.h1 36us : sub_preempt_count <-irq_exit
1701 bash-1994 1d..2 36us : do_softirq <-irq_exit
1702 bash-1994 1d..2 36us : __do_softirq <-call_softirq
1703 bash-1994 1d..2 36us : __local_bh_disable <-__do_softirq
1704 bash-1994 1d.s2 37us : add_preempt_count <-_raw_spin_lock_irq
1705 bash-1994 1d.s3 38us : _raw_spin_unlock <-run_timer_softirq
1706 bash-1994 1d.s3 39us : sub_preempt_count <-_raw_spin_unlock
1707 bash-1994 1d.s2 39us : call_timer_fn <-run_timer_softirq
1709 bash-1994 1dNs2 81us : cpu_needs_another_gp <-rcu_process_callbacks
1710 bash-1994 1dNs2 82us : __local_bh_enable <-__do_softirq
1711 bash-1994 1dNs2 82us : sub_preempt_count <-__local_bh_enable
1712 bash-1994 1dN.2 82us : idle_cpu <-irq_exit
1713 bash-1994 1dN.2 83us : rcu_irq_exit <-irq_exit
1714 bash-1994 1dN.2 83us : sub_preempt_count <-irq_exit
1715 bash-1994 1.N.1 84us : _raw_spin_unlock_irqrestore <-task_rq_unlock
1716 bash-1994 1.N.1 84us+: trace_preempt_on <-task_rq_unlock
1717 bash-1994 1.N.1 104us : <stack trace>
1728 function-trace set. Here we see that interrupts were not disabled
1729 the entire time. The irq_enter code lets us know that we entered
1735 --------------
1769 # echo 0 > options/function-trace
1773 # ls -ltr
1779 # preemptirqsoff latency trace v1.1.5 on 3.8.0-test+
1780 # --------------------------------------------------------------------
1781 # latency: 100 us, #4/4, CPU#3 | (M:preempt VP:0, KP:0, SP:0 HP:0 #P:4)
1782 # -----------------
1783 # | task: ls-2230 (uid:0 nice:0 policy:0 rt_prio:0)
1784 # -----------------
1789 # _------=> CPU#
1790 # / _-----=> irqs-off
1791 # | / _----=> need-resched
1792 # || / _---=> hardirq/softirq
1793 # ||| / _--=> preempt-depth
1797 ls-2230 3d... 0us+: _raw_spin_lock_irqsave <-ata_scsi_queuecmd
1798 ls-2230 3...1 100us : _raw_spin_unlock_irqrestore <-ata_scsi_queuecmd
1799 ls-2230 3...1 101us+: trace_preempt_on <-ata_scsi_queuecmd
1800 ls-2230 3...1 111us : <stack trace>
1828 Here is a trace with function-trace set::
1832 # preemptirqsoff latency trace v1.1.5 on 3.8.0-test+
1833 # --------------------------------------------------------------------
1834 # latency: 161 us, #339/339, CPU#3 | (M:preempt VP:0, KP:0, SP:0 HP:0 #P:4)
1835 # -----------------
1836 # | task: ls-2269 (uid:0 nice:0 policy:0 rt_prio:0)
1837 # -----------------
1842 # _------=> CPU#
1843 # / _-----=> irqs-off
1844 # | / _----=> need-resched
1845 # || / _---=> hardirq/softirq
1846 # ||| / _--=> preempt-depth
1850 kworker/-59 3...1 0us : __schedule <-schedule
1851 kworker/-59 3d..1 0us : rcu_preempt_qs <-rcu_note_context_switch
1852 kworker/-59 3d..1 1us : add_preempt_count <-_raw_spin_lock_irq
1853 kworker/-59 3d..2 1us : deactivate_task <-__schedule
1854 kworker/-59 3d..2 1us : dequeue_task <-deactivate_task
1855 kworker/-59 3d..2 2us : update_rq_clock <-dequeue_task
1856 kworker/-59 3d..2 2us : dequeue_task_fair <-dequeue_task
1857 kworker/-59 3d..2 2us : update_curr <-dequeue_task_fair
1858 kworker/-59 3d..2 2us : update_min_vruntime <-update_curr
1859 kworker/-59 3d..2 3us : cpuacct_charge <-update_curr
1860 kworker/-59 3d..2 3us : __rcu_read_lock <-cpuacct_charge
1861 kworker/-59 3d..2 3us : __rcu_read_unlock <-cpuacct_charge
1862 kworker/-59 3d..2 3us : update_cfs_rq_blocked_load <-dequeue_task_fair
1863 kworker/-59 3d..2 4us : clear_buddies <-dequeue_task_fair
1864 kworker/-59 3d..2 4us : account_entity_dequeue <-dequeue_task_fair
1865 kworker/-59 3d..2 4us : update_min_vruntime <-dequeue_task_fair
1866 kworker/-59 3d..2 4us : update_cfs_shares <-dequeue_task_fair
1867 kworker/-59 3d..2 5us : hrtick_update <-dequeue_task_fair
1868 kworker/-59 3d..2 5us : wq_worker_sleeping <-__schedule
1869 kworker/-59 3d..2 5us : kthread_data <-wq_worker_sleeping
1870 kworker/-59 3d..2 5us : put_prev_task_fair <-__schedule
1871 kworker/-59 3d..2 6us : pick_next_task_fair <-pick_next_task
1872 kworker/-59 3d..2 6us : clear_buddies <-pick_next_task_fair
1873 kworker/-59 3d..2 6us : set_next_entity <-pick_next_task_fair
1874 kworker/-59 3d..2 6us : update_stats_wait_end <-set_next_entity
1875 ls-2269 3d..2 7us : finish_task_switch <-__schedule
1876 ls-2269 3d..2 7us : _raw_spin_unlock_irq <-finish_task_switch
1877 ls-2269 3d..2 8us : do_IRQ <-ret_from_intr
1878 ls-2269 3d..2 8us : irq_enter <-do_IRQ
1879 ls-2269 3d..2 8us : rcu_irq_enter <-irq_enter
1880 ls-2269 3d..2 9us : add_preempt_count <-irq_enter
1881 ls-2269 3d.h2 9us : exit_idle <-do_IRQ
1883 ls-2269 3d.h3 20us : sub_preempt_count <-_raw_spin_unlock
1884 ls-2269 3d.h2 20us : irq_exit <-do_IRQ
1885 ls-2269 3d.h2 21us : sub_preempt_count <-irq_exit
1886 ls-2269 3d..3 21us : do_softirq <-irq_exit
1887 ls-2269 3d..3 21us : __do_softirq <-call_softirq
1888 ls-2269 3d..3 21us+: __local_bh_disable <-__do_softirq
1889 ls-2269 3d.s4 29us : sub_preempt_count <-_local_bh_enable_ip
1890 ls-2269 3d.s5 29us : sub_preempt_count <-_local_bh_enable_ip
1891 ls-2269 3d.s5 31us : do_IRQ <-ret_from_intr
1892 ls-2269 3d.s5 31us : irq_enter <-do_IRQ
1893 ls-2269 3d.s5 31us : rcu_irq_enter <-irq_enter
1895 ls-2269 3d.s5 31us : rcu_irq_enter <-irq_enter
1896 ls-2269 3d.s5 32us : add_preempt_count <-irq_enter
1897 ls-2269 3d.H5 32us : exit_idle <-do_IRQ
1898 ls-2269 3d.H5 32us : handle_irq <-do_IRQ
1899 ls-2269 3d.H5 32us : irq_to_desc <-handle_irq
1900 ls-2269 3d.H5 33us : handle_fasteoi_irq <-handle_irq
1902 ls-2269 3d.s5 158us : _raw_spin_unlock_irqrestore <-rtl8139_poll
1903 ls-2269 3d.s3 158us : net_rps_action_and_irq_enable.isra.65 <-net_rx_action
1904 ls-2269 3d.s3 159us : __local_bh_enable <-__do_softirq
1905 ls-2269 3d.s3 159us : sub_preempt_count <-__local_bh_enable
1906 ls-2269 3d..3 159us : idle_cpu <-irq_exit
1907 ls-2269 3d..3 159us : rcu_irq_exit <-irq_exit
1908 ls-2269 3d..3 160us : sub_preempt_count <-irq_exit
1909 ls-2269 3d... 161us : __mutex_unlock_slowpath <-mutex_unlock
1910 ls-2269 3d... 162us+: trace_hardirqs_on <-mutex_unlock
1911 ls-2269 3d... 186us : <stack trace>
1930 ------
1934 Now for non Real-Time tasks, this can be arbitrary. But tracing
1939 # echo 0 > options/function-trace
1943 # chrt -f 5 sleep 1
1948 # wakeup latency trace v1.1.5 on 3.8.0-test+
1949 # --------------------------------------------------------------------
1950 # latency: 15 us, #4/4, CPU#3 | (M:preempt VP:0, KP:0, SP:0 HP:0 #P:4)
1951 # -----------------
1952 # | task: kworker/3:1H-312 (uid:0 nice:-20 policy:0 rt_prio:0)
1953 # -----------------
1955 # _------=> CPU#
1956 # / _-----=> irqs-off
1957 # | / _----=> need-resched
1958 # || / _---=> hardirq/softirq
1959 # ||| / _--=> preempt-depth
1963 <idle>-0 3dNs7 0us : 0:120:R + [003] 312:100:R kworker/3:1H
1964 <idle>-0 3dNs7 1us+: ttwu_do_activate.constprop.87 <-try_to_wake_up
1965 <idle>-0 3d..3 15us : __schedule <-schedule
1966 <idle>-0 3d..3 15us : 0:120:R ==> [003] 312:100:R kworker/3:1H
1970 the kworker with a nice priority of -20 (not very nice), took
1974 Non Real-Time tasks are not that interesting. A more interesting
1975 trace is to concentrate only on Real-Time tasks.
1978 ---------
1980 In a Real-Time environment it is very important to know the
1983 latency". I stress the point that this is about RT tasks. It is
1984 also important to know the scheduling latency of non-RT tasks,
1985 but the average schedule latency is better for non-RT tasks.
1989 Real-Time environments are interested in the worst case latency.
1990 That is the longest latency it takes for something to happen,
1992 only have a large latency once in a while, but that would not
1993 work well with Real-Time tasks. The wakeup_rt tracer was designed
1994 to record the worst case wakeups of RT tasks. Non-RT tasks are
1996 tracing non-RT tasks that are unpredictable will overwrite the
1997 worst case latency of RT tasks (just run the normal wakeup
2006 # echo 0 > options/function-trace
2010 # chrt -f 5 sleep 1
2017 # wakeup_rt latency trace v1.1.5 on 3.8.0-test+
2018 # --------------------------------------------------------------------
2019 # latency: 5 us, #4/4, CPU#3 | (M:preempt VP:0, KP:0, SP:0 HP:0 #P:4)
2020 # -----------------
2021 # | task: sleep-2389 (uid:0 nice:0 policy:1 rt_prio:5)
2022 # -----------------
2024 # _------=> CPU#
2025 # / _-----=> irqs-off
2026 # | / _----=> need-resched
2027 # || / _---=> hardirq/softirq
2028 # ||| / _--=> preempt-depth
2032 <idle>-0 3d.h4 0us : 0:120:R + [003] 2389: 94:R sleep
2033 <idle>-0 3d.h4 1us+: ttwu_do_activate.constprop.87 <-try_to_wake_up
2034 <idle>-0 3d..3 5us : __schedule <-schedule
2035 <idle>-0 3d..3 5us : 0:120:R ==> [003] 2389: 94:R sleep
2045 and it has an rt_prio of 5. This priority is user-space priority
2049 Note, that the trace data shows the internal priority (99 - rtprio).
2052 <idle>-0 3d..3 5us : 0:120:R ==> [003] 2389: 94:R sleep
2054 The 0:120:R means idle was running with a nice priority of 0 (120 - 120)
2056 2389: 94:R. That is the priority is the kernel rtprio (99 - 5 = 94)
2059 Doing the same with chrt -r 5 and function-trace set.
2062 echo 1 > options/function-trace
2066 # wakeup_rt latency trace v1.1.5 on 3.8.0-test+
2067 # --------------------------------------------------------------------
2068 # latency: 29 us, #85/85, CPU#3 | (M:preempt VP:0, KP:0, SP:0 HP:0 #P:4)
2069 # -----------------
2070 # | task: sleep-2448 (uid:0 nice:0 policy:1 rt_prio:5)
2071 # -----------------
2073 # _------=> CPU#
2074 # / _-----=> irqs-off
2075 # | / _----=> need-resched
2076 # || / _---=> hardirq/softirq
2077 # ||| / _--=> preempt-depth
2081 <idle>-0 3d.h4 1us+: 0:120:R + [003] 2448: 94:R sleep
2082 <idle>-0 3d.h4 2us : ttwu_do_activate.constprop.87 <-try_to_wake_up
2083 <idle>-0 3d.h3 3us : check_preempt_curr <-ttwu_do_wakeup
2084 <idle>-0 3d.h3 3us : resched_curr <-check_preempt_curr
2085 <idle>-0 3dNh3 4us : task_woken_rt <-ttwu_do_wakeup
2086 <idle>-0 3dNh3 4us : _raw_spin_unlock <-try_to_wake_up
2087 <idle>-0 3dNh3 4us : sub_preempt_count <-_raw_spin_unlock
2088 <idle>-0 3dNh2 5us : ttwu_stat <-try_to_wake_up
2089 <idle>-0 3dNh2 5us : _raw_spin_unlock_irqrestore <-try_to_wake_up
2090 <idle>-0 3dNh2 6us : sub_preempt_count <-_raw_spin_unlock_irqrestore
2091 <idle>-0 3dNh1 6us : _raw_spin_lock <-__run_hrtimer
2092 <idle>-0 3dNh1 6us : add_preempt_count <-_raw_spin_lock
2093 <idle>-0 3dNh2 7us : _raw_spin_unlock <-hrtimer_interrupt
2094 <idle>-0 3dNh2 7us : sub_preempt_count <-_raw_spin_unlock
2095 <idle>-0 3dNh1 7us : tick_program_event <-hrtimer_interrupt
2096 <idle>-0 3dNh1 7us : clockevents_program_event <-tick_program_event
2097 <idle>-0 3dNh1 8us : ktime_get <-clockevents_program_event
2098 <idle>-0 3dNh1 8us : lapic_next_event <-clockevents_program_event
2099 <idle>-0 3dNh1 8us : irq_exit <-smp_apic_timer_interrupt
2100 <idle>-0 3dNh1 9us : sub_preempt_count <-irq_exit
2101 <idle>-0 3dN.2 9us : idle_cpu <-irq_exit
2102 <idle>-0 3dN.2 9us : rcu_irq_exit <-irq_exit
2103 <idle>-0 3dN.2 10us : rcu_eqs_enter_common.isra.45 <-rcu_irq_exit
2104 <idle>-0 3dN.2 10us : sub_preempt_count <-irq_exit
2105 <idle>-0 3.N.1 11us : rcu_idle_exit <-cpu_idle
2106 <idle>-0 3dN.1 11us : rcu_eqs_exit_common.isra.43 <-rcu_idle_exit
2107 <idle>-0 3.N.1 11us : tick_nohz_idle_exit <-cpu_idle
2108 <idle>-0 3dN.1 12us : menu_hrtimer_cancel <-tick_nohz_idle_exit
2109 <idle>-0 3dN.1 12us : ktime_get <-tick_nohz_idle_exit
2110 <idle>-0 3dN.1 12us : tick_do_update_jiffies64 <-tick_nohz_idle_exit
2111 <idle>-0 3dN.1 13us : cpu_load_update_nohz <-tick_nohz_idle_exit
2112 <idle>-0 3dN.1 13us : _raw_spin_lock <-cpu_load_update_nohz
2113 <idle>-0 3dN.1 13us : add_preempt_count <-_raw_spin_lock
2114 <idle>-0 3dN.2 13us : __cpu_load_update <-cpu_load_update_nohz
2115 <idle>-0 3dN.2 14us : sched_avg_update <-__cpu_load_update
2116 <idle>-0 3dN.2 14us : _raw_spin_unlock <-cpu_load_update_nohz
2117 <idle>-0 3dN.2 14us : sub_preempt_count <-_raw_spin_unlock
2118 <idle>-0 3dN.1 15us : calc_load_nohz_stop <-tick_nohz_idle_exit
2119 <idle>-0 3dN.1 15us : touch_softlockup_watchdog <-tick_nohz_idle_exit
2120 <idle>-0 3dN.1 15us : hrtimer_cancel <-tick_nohz_idle_exit
2121 <idle>-0 3dN.1 15us : hrtimer_try_to_cancel <-hrtimer_cancel
2122 <idle>-0 3dN.1 16us : lock_hrtimer_base.isra.18 <-hrtimer_try_to_cancel
2123 <idle>-0 3dN.1 16us : _raw_spin_lock_irqsave <-lock_hrtimer_base.isra.18
2124 <idle>-0 3dN.1 16us : add_preempt_count <-_raw_spin_lock_irqsave
2125 <idle>-0 3dN.2 17us : __remove_hrtimer <-remove_hrtimer.part.16
2126 <idle>-0 3dN.2 17us : hrtimer_force_reprogram <-__remove_hrtimer
2127 <idle>-0 3dN.2 17us : tick_program_event <-hrtimer_force_reprogram
2128 <idle>-0 3dN.2 18us : clockevents_program_event <-tick_program_event
2129 <idle>-0 3dN.2 18us : ktime_get <-clockevents_program_event
2130 <idle>-0 3dN.2 18us : lapic_next_event <-clockevents_program_event
2131 <idle>-0 3dN.2 19us : _raw_spin_unlock_irqrestore <-hrtimer_try_to_cancel
2132 <idle>-0 3dN.2 19us : sub_preempt_count <-_raw_spin_unlock_irqrestore
2133 <idle>-0 3dN.1 19us : hrtimer_forward <-tick_nohz_idle_exit
2134 <idle>-0 3dN.1 20us : ktime_add_safe <-hrtimer_forward
2135 <idle>-0 3dN.1 20us : ktime_add_safe <-hrtimer_forward
2136 <idle>-0 3dN.1 20us : hrtimer_start_range_ns <-hrtimer_start_expires.constprop.11
2137 <idle>-0 3dN.1 20us : __hrtimer_start_range_ns <-hrtimer_start_range_ns
2138 <idle>-0 3dN.1 21us : lock_hrtimer_base.isra.18 <-__hrtimer_start_range_ns
2139 <idle>-0 3dN.1 21us : _raw_spin_lock_irqsave <-lock_hrtimer_base.isra.18
2140 <idle>-0 3dN.1 21us : add_preempt_count <-_raw_spin_lock_irqsave
2141 <idle>-0 3dN.2 22us : ktime_add_safe <-__hrtimer_start_range_ns
2142 <idle>-0 3dN.2 22us : enqueue_hrtimer <-__hrtimer_start_range_ns
2143 <idle>-0 3dN.2 22us : tick_program_event <-__hrtimer_start_range_ns
2144 <idle>-0 3dN.2 23us : clockevents_program_event <-tick_program_event
2145 <idle>-0 3dN.2 23us : ktime_get <-clockevents_program_event
2146 <idle>-0 3dN.2 23us : lapic_next_event <-clockevents_program_event
2147 <idle>-0 3dN.2 24us : _raw_spin_unlock_irqrestore <-__hrtimer_start_range_ns
2148 <idle>-0 3dN.2 24us : sub_preempt_count <-_raw_spin_unlock_irqrestore
2149 <idle>-0 3dN.1 24us : account_idle_ticks <-tick_nohz_idle_exit
2150 <idle>-0 3dN.1 24us : account_idle_time <-account_idle_ticks
2151 <idle>-0 3.N.1 25us : sub_preempt_count <-cpu_idle
2152 <idle>-0 3.N.. 25us : schedule <-cpu_idle
2153 <idle>-0 3.N.. 25us : __schedule <-preempt_schedule
2154 <idle>-0 3.N.. 26us : add_preempt_count <-__schedule
2155 <idle>-0 3.N.1 26us : rcu_note_context_switch <-__schedule
2156 <idle>-0 3.N.1 26us : rcu_sched_qs <-rcu_note_context_switch
2157 <idle>-0 3dN.1 27us : rcu_preempt_qs <-rcu_note_context_switch
2158 <idle>-0 3.N.1 27us : _raw_spin_lock_irq <-__schedule
2159 <idle>-0 3dN.1 27us : add_preempt_count <-_raw_spin_lock_irq
2160 <idle>-0 3dN.2 28us : put_prev_task_idle <-__schedule
2161 <idle>-0 3dN.2 28us : pick_next_task_stop <-pick_next_task
2162 <idle>-0 3dN.2 28us : pick_next_task_rt <-pick_next_task
2163 <idle>-0 3dN.2 29us : dequeue_pushable_task <-pick_next_task_rt
2164 <idle>-0 3d..3 29us : __schedule <-preempt_schedule
2165 <idle>-0 3d..3 30us : 0:120:R ==> [003] 2448: 94:R sleep
2174 Latency tracing and events
2175 --------------------------
2176 As function tracing can induce a much larger latency, but without
2177 seeing what happens within the latency it is hard to know what
2182 # echo 0 > options/function-trace
2187 # chrt -f 5 sleep 1
2192 # wakeup_rt latency trace v1.1.5 on 3.8.0-test+
2193 # --------------------------------------------------------------------
2194 # latency: 6 us, #12/12, CPU#2 | (M:preempt VP:0, KP:0, SP:0 HP:0 #P:4)
2195 # -----------------
2196 # | task: sleep-5882 (uid:0 nice:0 policy:1 rt_prio:5)
2197 # -----------------
2199 # _------=> CPU#
2200 # / _-----=> irqs-off
2201 # | / _----=> need-resched
2202 # || / _---=> hardirq/softirq
2203 # ||| / _--=> preempt-depth
2207 <idle>-0 2d.h4 0us : 0:120:R + [002] 5882: 94:R sleep
2208 <idle>-0 2d.h4 0us : ttwu_do_activate.constprop.87 <-try_to_wake_up
2209 <idle>-0 2d.h4 1us : sched_wakeup: comm=sleep pid=5882 prio=94 success=1 target_cpu=002
2210 <idle>-0 2dNh2 1us : hrtimer_expire_exit: hrtimer=ffff88007796feb8
2211 <idle>-0 2.N.2 2us : power_end: cpu_id=2
2212 <idle>-0 2.N.2 3us : cpu_idle: state=4294967295 cpu_id=2
2213 <idle>-0 2dN.3 4us : hrtimer_cancel: hrtimer=ffff88007d50d5e0
2214 …<idle>-0 2dN.3 4us : hrtimer_start: hrtimer=ffff88007d50d5e0 function=tick_sched_timer ex…
2215 <idle>-0 2.N.2 5us : rcu_utilization: Start context switch
2216 <idle>-0 2.N.2 5us : rcu_utilization: End context switch
2217 <idle>-0 2d..3 6us : __schedule <-schedule
2218 <idle>-0 2d..3 6us : 0:120:R ==> [002] 5882: 94:R sleep
2221 Hardware Latency Detector
2222 -------------------------
2224 The hardware latency detector is executed by enabling the "hwlat" tracer.
2235 # entries-in-buffer/entries-written: 13/13 #P:8
2237 # _-----=> irqs-off
2238 # / _----=> need-resched
2239 # | / _---=> hardirq/softirq
2240 # || / _--=> preempt-depth
2242 # TASK-PID CPU# |||| TIMESTAMP FUNCTION
2244 …<...>-1729 [001] d... 678.473449: #1 inner/outer(us): 11/12 ts:1581527483.343962693 co…
2245 …<...>-1729 [004] d... 689.556542: #2 inner/outer(us): 16/9 ts:1581527494.889008092 co…
2246 …<...>-1729 [005] d... 714.756290: #3 inner/outer(us): 16/16 ts:1581527519.678961629 co…
2247 …<...>-1729 [001] d... 718.788247: #4 inner/outer(us): 9/17 ts:1581527523.889012713 co…
2248 …<...>-1729 [002] d... 719.796341: #5 inner/outer(us): 13/9 ts:1581527524.912872606 co…
2249 …<...>-1729 [006] d... 844.787091: #6 inner/outer(us): 9/12 ts:1581527649.889048502 co…
2250 …<...>-1729 [003] d... 849.827033: #7 inner/outer(us): 18/9 ts:1581527654.889013793 co…
2251 …<...>-1729 [007] d... 853.859002: #8 inner/outer(us): 9/12 ts:1581527658.889065736 co…
2252 …<...>-1729 [001] d... 855.874978: #9 inner/outer(us): 9/11 ts:1581527660.861991877 co…
2253 …<...>-1729 [001] d... 863.938932: #10 inner/outer(us): 9/11 ts:1581527668.970010500 co…
2254 …<...>-1729 [007] d... 878.050780: #11 inner/outer(us): 9/12 ts:1581527683.385002600 co…
2255 …<...>-1729 [007] d... 886.114702: #12 inner/outer(us): 9/12 ts:1581527691.385001600 co…
2265 inner/outer(us): 11/11
2267 This shows two numbers as "inner latency" and "outer latency". The test
2268 runs in a loop checking a timestamp twice. The latency detected within
2269 the two timestamps is the "inner latency" and the latency detected
2271 the "outer latency".
2275 The absolute timestamp that the first latency was recorded in the window.
2279 The number of times a latency was detected during the window.
2281 nmi-total:7 nmi-count:1
2284 test, the time spent in NMI is reported in "nmi-total" (in
2287 All architectures that have NMIs will show the "nmi-count" if an
2294 microseconds. This is the threshold of latency that
2318 --------
2334 # entries-in-buffer/entries-written: 24799/24799 #P:4
2336 # _-----=> irqs-off
2337 # / _----=> need-resched
2338 # | / _---=> hardirq/softirq
2339 # || / _--=> preempt-depth
2341 # TASK-PID CPU# |||| TIMESTAMP FUNCTION
2343 bash-1994 [002] .... 3082.063030: mutex_unlock <-rb_simple_write
2344 bash-1994 [002] .... 3082.063031: __mutex_unlock_slowpath <-mutex_unlock
2345 bash-1994 [002] .... 3082.063031: __fsnotify_parent <-fsnotify_modify
2346 bash-1994 [002] .... 3082.063032: fsnotify <-fsnotify_modify
2347 bash-1994 [002] .... 3082.063032: __srcu_read_lock <-fsnotify
2348 bash-1994 [002] .... 3082.063032: add_preempt_count <-__srcu_read_lock
2349 bash-1994 [002] ...1 3082.063032: sub_preempt_count <-__srcu_read_lock
2350 bash-1994 [002] .... 3082.063033: __srcu_read_unlock <-fsnotify
2378 ---------------------
2392 # TASK-PID CPU# TIMESTAMP FUNCTION
2394 yum-updatesd-3111 [003] 1637.254676: finish_task_switch <-thread_return
2395 yum-updatesd-3111 [003] 1637.254681: hrtimer_cancel <-schedule_hrtimeout_range
2396 yum-updatesd-3111 [003] 1637.254682: hrtimer_try_to_cancel <-hrtimer_cancel
2397 yum-updatesd-3111 [003] 1637.254683: lock_hrtimer_base <-hrtimer_try_to_cancel
2398 yum-updatesd-3111 [003] 1637.254685: fget_light <-do_sys_poll
2399 yum-updatesd-3111 [003] 1637.254686: pipe_poll <-do_sys_poll
2404 # TASK-PID CPU# TIMESTAMP FUNCTION
2407 yum-updatesd-3111 [003] 1701.957688: free_poll_entry <-poll_freewait
2408 yum-updatesd-3111 [003] 1701.957689: remove_wait_queue <-free_poll_entry
2409 yum-updatesd-3111 [003] 1701.957691: fput <-free_poll_entry
2410 yum-updatesd-3111 [003] 1701.957692: audit_syscall_exit <-sysret_audit
2411 yum-updatesd-3111 [003] 1701.957693: path_put <-audit_syscall_exit
2474 exit(-1);
2483 exit(-1);
2506 tracefs=`sed -ne 's/^tracefs \(.*\) tracefs.*/\1/p' /proc/mounts`
2515 ---------------------------
2518 probes a function on its entry and its exit. This is done by
2520 task_struct. On function entry the tracer overwrites the return
2528 - measure of a function's time execution
2529 - having a reliable call stack to draw function calls graph
2533 - you want to find the reason of a strange kernel behavior and
2537 - you are experiencing weird latencies but it's difficult to
2540 - you want to find quickly which path is taken by a specific
2543 - you just want to peek inside a working kernel and want to see
2557 0) 1.382 us | __might_sleep();
2558 0) 2.478 us | }
2561 0) 1.389 us | __might_sleep();
2562 0) 2.553 us | }
2563 0) 3.807 us | }
2564 0) 7.876 us | }
2566 0) 0.668 us | _spin_lock();
2567 0) 0.570 us | expand_files();
2568 0) 0.586 us | _spin_unlock();
2575 - The cpu number on which the function executed is default
2580 - hide: echo nofuncgraph-cpu > trace_options
2581 - show: echo funcgraph-cpu > trace_options
2583 - The duration (function's time of execution) is displayed on
2588 - hide: echo nofuncgraph-duration > trace_options
2589 - show: echo funcgraph-duration > trace_options
2591 - The overhead field precedes the duration field in case of
2594 - hide: echo nofuncgraph-overhead > trace_options
2595 - show: echo funcgraph-overhead > trace_options
2596 - depends on: funcgraph-duration
2600 3) # 1837.709 us | } /* __switch_to */
2602 3) 0.313 us | _raw_spin_unlock_irq();
2603 3) 3.177 us | }
2604 3) # 1889.063 us | } /* __schedule */
2605 3) ! 140.417 us | } /* __schedule */
2606 3) # 2034.948 us | } /* schedule */
2607 3) * 33998.59 us | } /* schedule_preempt_disabled */
2611 1) 0.260 us | msecs_to_jiffies();
2612 1) 0.313 us | __rcu_read_unlock();
2613 1) + 61.770 us | }
2614 1) + 64.479 us | }
2615 1) 0.313 us | rcu_bh_qs();
2616 1) 0.313 us | __local_bh_enable();
2617 1) ! 217.240 us | }
2618 1) 0.365 us | idle_cpu();
2620 1) 0.417 us | rcu_eqs_enter_common.isra.47();
2621 1) 3.125 us | }
2622 1) ! 227.812 us | }
2623 1) ! 457.395 us | }
2624 1) @ 119760.2 us | }
2629 1) 6.979 us | }
2630 2) 0.417 us | scheduler_ipi();
2631 1) 9.791 us | }
2632 1) + 12.917 us | }
2633 2) 3.490 us | }
2634 1) + 15.729 us | }
2635 1) + 18.542 us | }
2636 2) $ 3594274 us | }
2648 - The task/pid field displays the thread cmdline and pid which
2651 - hide: echo nofuncgraph-proc > trace_options
2652 - show: echo funcgraph-proc > trace_options
2660 0) sh-4802 | | d_free() {
2661 0) sh-4802 | | call_rcu() {
2662 0) sh-4802 | | __call_rcu() {
2663 0) sh-4802 | 0.616 us | rcu_process_gp_end();
2664 0) sh-4802 | 0.586 us | check_for_new_grace_period();
2665 0) sh-4802 | 2.899 us | }
2666 0) sh-4802 | 4.040 us | }
2667 0) sh-4802 | 5.151 us | }
2668 0) sh-4802 | + 49.370 us | }
2671 - The absolute time field is an absolute timestamp given by the
2673 given on each entry/exit of functions
2675 - hide: echo nofuncgraph-abstime > trace_options
2676 - show: echo funcgraph-abstime > trace_options
2683 360.774522 | 1) 0.541 us | }
2684 360.774522 | 1) 4.663 us | }
2685 360.774523 | 1) 0.541 us | __wake_up_bit();
2686 360.774524 | 1) 6.796 us | }
2687 360.774524 | 1) 7.952 us | }
2688 360.774525 | 1) 9.063 us | }
2689 360.774525 | 1) 0.615 us | journal_mark_dirty();
2690 360.774527 | 1) 0.578 us | __brelse();
2695 360.774530 | 1) 0.594 us | __phys_addr();
2707 - hide: echo nofuncgraph-tail > trace_options
2708 - show: echo funcgraph-tail > trace_options
2710 Example with nofuncgraph-tail (default)::
2714 0) 0.518 us | __phys_addr();
2715 0) 1.757 us | }
2716 0) 2.861 us | }
2718 Example with funcgraph-tail::
2722 0) 0.518 us | __phys_addr();
2723 0) 1.757 us | } /* kmem_cache_free() */
2724 0) 2.861 us | } /* putname() */
2731 - hide: echo nofuncgraph-retval > trace_options
2732 - show: echo funcgraph-retval > trace_options
2734 Example with funcgraph-retval::
2737 1) 0.651 us | cgroup_migrate_add_task(); /* = 0xffff93fcfd346c00 */
2741 1) 0.732 us | cgroup_taskset_next(); /* = 0xffff93fc8fb20000 */
2742 1) 1.232 us | } /* cgroup_taskset_first = 0xffff93fc8fb20000 */
2743 1) 0.380 us | sched_rt_can_attach(); /* = 0x0 */
2744 1) 2.335 us | } /* cpu_cgroup_can_attach = -22 */
2745 1) 4.369 us | } /* cgroup_migrate_execute = -22 */
2746 1) 7.143 us | } /* cgroup_migrate = -22 */
2749 returned the error code -22 firstly, then we can read the code
2752 When the option funcgraph-retval-hex is not set, the return value can
2757 - smart: echo nofuncgraph-retval-hex > trace_options
2758 - hexadecimal: echo funcgraph-retval-hex > trace_options
2760 Example with funcgraph-retval-hex::
2763 1) 0.651 us | cgroup_migrate_add_task(); /* = 0xffff93fcfd346c00 */
2767 1) 0.732 us | cgroup_taskset_next(); /* = 0xffff93fc8fb20000 */
2768 1) 1.232 us | } /* cgroup_taskset_first = 0xffff93fc8fb20000 */
2769 1) 0.380 us | sched_rt_can_attach(); /* = 0x0 */
2770 1) 2.335 us | } /* cpu_cgroup_can_attach = 0xffffffea */
2771 1) 4.369 us | } /* cgroup_migrate_execute = 0xffffffea */
2772 1) 7.143 us | } /* cgroup_migrate = 0xffffffea */
2774 At present, there are some limitations when using the funcgraph-retval
2777 - Even if the function return type is void, a return value will still
2780 - Even if return values are stored in multiple registers, only the
2783 a 64-bit return value, with the lower 32 bits saved in eax and the
2787 - In certain procedure call standards, such as arm64's AAPCS64, when a
2791 when using a u8 in a 64-bit GPR, bits [63:8] may contain arbitrary values,
2821 return -EINVAL;
2833 MOV x0, #-EINVAL
2850 1) 1.449 us | }
2858 --------------
2863 every kernel function, produced by the -pg switch in gcc),
2865 include the -pg switch in the compiling of the kernel.)
2871 with gcc version 4.6, the -mfentry has been added for x86, which
2882 The recordmcount program re-links this section back into the
2914 One special side-effect to the recording of the functions being
2954 # entries-in-buffer/entries-written: 5/5 #P:4
2956 # _-----=> irqs-off
2957 # / _----=> need-resched
2958 # | / _---=> hardirq/softirq
2959 # || / _--=> preempt-depth
2961 # TASK-PID CPU# |||| TIMESTAMP FUNCTION
2963 usleep-2665 [001] .... 4186.475355: sys_nanosleep <-system_call_fastpath
2964 <idle>-0 [001] d.h1 4186.475409: hrtimer_interrupt <-smp_apic_timer_interrupt
2965 usleep-2665 [001] d.h1 4186.475426: hrtimer_interrupt <-smp_apic_timer_interrupt
2966 <idle>-0 [003] d.h1 4186.475426: hrtimer_interrupt <-smp_apic_timer_interrupt
2967 <idle>-0 [002] d.h1 4186.475427: hrtimer_interrupt <-smp_apic_timer_interrupt
3001 # entries-in-buffer/entries-written: 897/897 #P:4
3003 # _-----=> irqs-off
3004 # / _----=> need-resched
3005 # | / _---=> hardirq/softirq
3006 # || / _--=> preempt-depth
3008 # TASK-PID CPU# |||| TIMESTAMP FUNCTION
3010 <idle>-0 [003] dN.1 4228.547803: hrtimer_cancel <-tick_nohz_idle_exit
3011 <idle>-0 [003] dN.1 4228.547804: hrtimer_try_to_cancel <-hrtimer_cancel
3012 <idle>-0 [003] dN.2 4228.547805: hrtimer_force_reprogram <-__remove_hrtimer
3013 <idle>-0 [003] dN.1 4228.547805: hrtimer_forward <-tick_nohz_idle_exit
3014 … <idle>-0 [003] dN.1 4228.547805: hrtimer_start_range_ns <-hrtimer_start_expires.constprop.11
3015 <idle>-0 [003] d..1 4228.547858: hrtimer_get_next_event <-get_next_timer_interrupt
3016 <idle>-0 [003] d..1 4228.547859: hrtimer_start <-__tick_nohz_idle_enter
3017 <idle>-0 [003] d..2 4228.547860: hrtimer_force_reprogram <-__rem
3090 # entries-in-buffer/entries-written: 39608/39608 #P:4
3092 # _-----=> irqs-off
3093 # / _----=> need-resched
3094 # | / _---=> hardirq/softirq
3095 # || / _--=> preempt-depth
3097 # TASK-PID CPU# |||| TIMESTAMP FUNCTION
3099 bash-1994 [000] .... 4342.324896: file_ra_state_init <-do_dentry_open
3100 bash-1994 [000] .... 4342.324897: open_check_o_direct <-do_last
3101 bash-1994 [000] .... 4342.324897: ima_file_check <-do_last
3102 bash-1994 [000] .... 4342.324898: process_measurement <-ima_file_check
3103 bash-1994 [000] .... 4342.324898: ima_get_action <-process_measurement
3104 bash-1994 [000] .... 4342.324898: ima_match_policy <-ima_get_action
3105 bash-1994 [000] .... 4342.324899: do_truncate <-do_last
3106 bash-1994 [000] .... 4342.324899: setattr_should_drop_suidgid <-do_truncate
3107 bash-1994 [000] .... 4342.324899: notify_change <-do_truncate
3108 bash-1994 [000] .... 4342.324900: current_fs_time <-notify_change
3109 bash-1994 [000] .... 4342.324900: current_kernel_time <-current_fs_time
3110 bash-1994 [000] .... 4342.324900: timespec_trunc <-current_fs_time
3115 ------------------------------------
3133 # head -1 available_filter_functions
3139 # head -50 available_filter_functions | tail -1
3148 ---------------------------------------------
3151 function tracer and the function-graph-tracer, there are some
3152 special features only available in the function-graph tracer.
3165 0) 0.804 us | find_get_page();
3167 0) 1.329 us | }
3168 0) 3.904 us | }
3169 0) 4.979 us | }
3170 0) 0.653 us | _spin_lock();
3171 0) 0.578 us | page_add_file_rmap();
3172 0) 0.525 us | native_set_pte_at();
3173 0) 0.585 us | _spin_unlock();
3175 0) 0.541 us | page_waitqueue();
3176 0) 0.639 us | __wake_up_bit();
3177 0) 2.786 us | }
3178 0) + 14.237 us | }
3182 0) 0.698 us | find_get_page();
3184 0) 1.412 us | }
3185 0) 3.950 us | }
3186 0) 5.098 us | }
3187 0) 0.631 us | _spin_lock();
3188 0) 0.571 us | page_add_file_rmap();
3189 0) 0.526 us | native_set_pte_at();
3190 0) 0.586 us | _spin_unlock();
3192 0) 0.533 us | page_waitqueue();
3193 0) 0.638 us | __wake_up_bit();
3194 0) 2.793 us | }
3195 0) + 14.012 us | }
3209 --------------
3233 ---------------
3242 - mod:
3274 - traceon/traceoff:
3298 - snapshot:
3314 - enable_event/disable_event:
3338 - dump:
3345 - cpudump:
3351 - stacktrace:
3355 ----------
3372 # entries-in-buffer/entries-written: 0/0 #P:4
3374 # _-----=> irqs-off
3375 # / _----=> need-resched
3376 # | / _---=> hardirq/softirq
3377 # || / _--=> preempt-depth
3379 # TASK-PID CPU# |||| TIMESTAMP FUNCTION
3384 bash-1994 [000] .... 5281.568961: mutex_unlock <-rb_simple_write
3385 bash-1994 [000] .... 5281.568963: __mutex_unlock_slowpath <-mutex_unlock
3386 bash-1994 [000] .... 5281.568963: __fsnotify_parent <-fsnotify_modify
3387 bash-1994 [000] .... 5281.568964: fsnotify <-fsnotify_modify
3388 bash-1994 [000] .... 5281.568964: __srcu_read_lock <-fsnotify
3389 bash-1994 [000] .... 5281.568964: add_preempt_count <-__srcu_read_lock
3390 bash-1994 [000] ...1 5281.568965: sub_preempt_count <-__srcu_read_lock
3391 bash-1994 [000] .... 5281.568965: __srcu_read_unlock <-fsnotify
3392 bash-1994 [000] .... 5281.568967: sys_dup2 <-system_call_fastpath
3402 -------------
3429 much, it can cause Out-Of-Memory to trigger.
3433 -bash: echo: write error: Cannot allocate memory
3460 --------
3462 available to all non latency tracers. (Latency tracers which
3463 record max latency, such as "irqsoff" or "wakeup", can't use
3488 +--------------+------------+------------+------------+
3492 +--------------+------------+------------+------------+
3494 +--------------+------------+------------+------------+
3504 # entries-in-buffer/entries-written: 71/71 #P:8
3506 # _-----=> irqs-off
3507 # / _----=> need-resched
3508 # | / _---=> hardirq/softirq
3509 # || / _--=> preempt-depth
3511 # TASK-PID CPU# |||| TIMESTAMP FUNCTION
3513 …<idle>-0 [005] d... 2440.603828: sched_switch: prev_comm=swapper/5 prev_pid=0 prev_prio=120 …
3514 …sleep-2242 [005] d... 2440.603846: sched_switch: prev_comm=snapshot-test-2 prev_pid=2242 prev_pr…
3516 …<idle>-0 [002] d... 2440.707230: sched_switch: prev_comm=swapper/2 prev_pid=0 prev_prio=120 p…
3521 # entries-in-buffer/entries-written: 77/77 #P:8
3523 # _-----=> irqs-off
3524 # / _----=> need-resched
3525 # | / _---=> hardirq/softirq
3526 # || / _--=> preempt-depth
3528 # TASK-PID CPU# |||| TIMESTAMP FUNCTION
3530 …<idle>-0 [007] d... 2440.707395: sched_switch: prev_comm=swapper/7 prev_pid=0 prev_prio=120 p…
3531 …snapshot-test-2-2229 [002] d... 2440.707438: sched_switch: prev_comm=snapshot-test-2 prev_pid=22…
3536 one of the latency tracers, you will get the following results.
3547 ---------
3593 bash-2044 [002] .... 10594.481032: _raw_spin_lock_irqsave <-get_page_from_freelist
3594 bash-2044 [002] d... 10594.481032: add_preempt_count <-_raw_spin_lock_irqsave
3595 bash-2044 [002] d..1 10594.481032: __rmqueue <-get_page_from_freelist
3596 bash-2044 [002] d..1 10594.481033: _raw_spin_unlock <-get_page_from_freelist
3597 bash-2044 [002] d..1 10594.481033: sub_preempt_count <-_raw_spin_unlock
3598 … bash-2044 [002] d... 10594.481033: get_pageblock_flags_group <-get_pageblock_migratetype
3599 bash-2044 [002] d... 10594.481034: __mod_zone_page_state <-get_page_from_freelist
3600 bash-2044 [002] d... 10594.481034: zone_statistics <-get_page_from_freelist
3601 bash-2044 [002] d... 10594.481034: __inc_zone_state <-zone_statistics
3602 bash-2044 [002] d... 10594.481034: __inc_zone_state <-zone_statistics
3603 bash-2044 [002] .... 10594.481035: arch_dup_task_struct <-copy_process
3607 …bash-1998 [000] d..4 136.676759: sched_wakeup: comm=kworker/0:1 pid=59 prio=120 success=1 targe…
3608 …bash-1998 [000] dN.4 136.676760: sched_wakeup: comm=bash pid=1998 prio=120 success=1 target_cpu…
3609 …<idle>-0 [003] d.h3 136.676906: sched_wakeup: comm=rcu_preempt pid=9 prio=120 success=1 targ…
3610 …<idle>-0 [003] d..3 136.676909: sched_switch: prev_comm=swapper/3 prev_pid=0 prev_prio=120 p…
3611 …rcu_preempt-9 [003] d..3 136.676916: sched_switch: prev_comm=rcu_preempt prev_pid=9 prev_pri…
3612 …bash-1998 [000] d..4 136.677014: sched_wakeup: comm=kworker/0:1 pid=59 prio=120 success=1 targe…
3613 …bash-1998 [000] dN.4 136.677016: sched_wakeup: comm=bash pid=1998 prio=120 success=1 target_cpu…
3614 …bash-1998 [000] d..3 136.677018: sched_switch: prev_comm=bash prev_pid=1998 prev_prio=120 prev_…
3615 …kworker/0:1-59 [000] d..4 136.677022: sched_wakeup: comm=sshd pid=1995 prio=120 success=1 tar…
3616 …kworker/0:1-59 [000] d..3 136.677025: sched_switch: prev_comm=kworker/0:1 prev_pid=59 prev_pr…
3620 migration/1-14 [001] d.h3 138.732674: softirq_raise: vec=3 [action=NET_RX]
3621 <idle>-0 [001] dNh3 138.732725: softirq_raise: vec=3 [action=NET_RX]
3622 bash-1998 [000] d.h1 138.733101: softirq_raise: vec=1 [action=TIMER]
3623 bash-1998 [000] d.h1 138.733102: softirq_raise: vec=9 [action=RCU]
3624 bash-1998 [000] ..s2 138.733105: softirq_entry: vec=1 [action=TIMER]
3625 bash-1998 [000] ..s2 138.733106: softirq_exit: vec=1 [action=TIMER]
3626 bash-1998 [000] ..s2 138.733106: softirq_entry: vec=9 [action=RCU]
3627 bash-1998 [000] ..s2 138.733109: softirq_exit: vec=9 [action=RCU]
3628 sshd-1995 [001] d.h1 138.733278: irq_handler_entry: irq=21 name=uhci_hcd:usb4
3629 sshd-1995 [001] d.h1 138.733280: irq_handler_exit: irq=21 ret=unhandled
3630 sshd-1995 [001] d.h1 138.733281: irq_handler_entry: irq=21 name=eth0
3631 sshd-1995 [001] d.h1 138.733283: irq_handler_exit: irq=21 ret=handled
3637 # entries-in-buffer/entries-written: 18996/18996 #P:4
3639 # _-----=> irqs-off
3640 # / _----=> need-resched
3641 # | / _---=> hardirq/softirq
3642 # || / _--=> preempt-depth
3644 # TASK-PID CPU# |||| TIMESTAMP FUNCTION
3646 bash-1998 [000] d... 140.733501: sys_write -> 0x2
3647 bash-1998 [000] d... 140.733504: sys_dup2(oldfd: a, newfd: 1)
3648 bash-1998 [000] d... 140.733506: sys_dup2 -> 0x1
3649 bash-1998 [000] d... 140.733508: sys_fcntl(fd: a, cmd: 1, arg: 0)
3650 bash-1998 [000] d... 140.733509: sys_fcntl -> 0x1
3651 bash-1998 [000] d... 140.733510: sys_close(fd: a)
3652 bash-1998 [000] d... 140.733510: sys_close -> 0x0
3653 …bash-1998 [000] d... 140.733514: sys_rt_sigprocmask(how: 0, nset: 0, oset: 6e2768, sigsetsize: …
3654 bash-1998 [000] d... 140.733515: sys_rt_sigprocmask -> 0x0
3655 …bash-1998 [000] d... 140.733516: sys_rt_sigaction(sig: 2, act: 7fff718846f0, oact: 7fff71884650…
3656 bash-1998 [000] d... 140.733516: sys_rt_sigaction -> 0x0
3674 -----------
3705 ----- ---- --------
3725 Note, if -mfentry is being used by gcc, functions get traced before
3727 are not tested by the stack tracer when -mfentry is used.
3729 Currently, -mfentry is used by gcc 4.6.0 and above on x86 only.
3732 ----