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 :doc:`ftrace-design` for details for arch porters and such.
47 ---------------
60 mount -t tracefs nodev /sys/kernel/tracing
65 ln -s /sys/kernel/tracing /tracing
121 set this file to "0". User space can re-enable tracing by
126 be re-enabled by user space using this file.
169 Some of the tracers record the max latency.
173 recorded if the latency is greater than the value in this file
176 By echoing in a time into this file, no latency will be recorded
181 Some latency tracers will record a trace whenever the
182 latency is greater than the number in this file.
195 meta-data. If the last page allocated has room for more bytes
199 due to buffer management meta-data. )
263 If the "function-fork" option is set, then when a task whose
274 If the "function-fork" option is set, then when a task whose
290 added on fork, enable the "event-fork" option. That option will also
303 added on fork, enable the "event-fork" option. That option will also
352 the "ip modify" attribute (thus the regs->ip can be changed),
412 If the option "record-cmd" is set to "0", then comms of tasks
423 If the option "record-tgid" is set, on each scheduling context switch
425 the thread to its TGID. By default, the "record-tgid" option is
464 [local] global counter x86-tsc
491 x86-tsc:
495 ppc-tb:
518 Also on 32-bit systems, it's possible that the 64-bit boot offset
626 delta: Default timestamp mode - timestamp is a delta against
627 a per-buffer timestamp.
635 Directory for the Hardware Latency Detector.
636 See "Hardware Latency Detector" section below.
701 event (ring buffer is re-entrant), that it fills the
720 -----------
731 function tracer probes the functions on their entry
732 whereas the function graph tracer traces on both entry
744 The Hardware Latency tracer is used to detect if the hardware
745 produces any latency. See "Hardware Latency Detector" section
751 the trace with the longest max latency.
754 trace with the latency-format option enabled, which
770 Traces and records the max latency that it takes for
777 Traces and records the max latency that it takes for just
783 Traces and records the max latency that it takes for
808 ----------------
840 ----------------------------
844 user-land utilities).
847 --------------
853 # entries-in-buffer/entries-written: 140080/250280 #P:4
855 # _-----=> irqs-off
856 # / _----=> need-resched
857 # | / _---=> hardirq/softirq
858 # || / _--=> preempt-depth
860 # TASK-PID CPU# |||| TIMESTAMP FUNCTION
862 bash-1977 [000] .... 17284.993652: sys_close <-system_call_fastpath
863 bash-1977 [000] .... 17284.993653: __close_fd <-sys_close
864 bash-1977 [000] .... 17284.993653: _raw_spin_lock <-__close_fd
865 sshd-1974 [003] .... 17284.993653: __srcu_read_unlock <-fsnotify
866 bash-1977 [000] .... 17284.993654: add_preempt_count <-_raw_spin_lock
867 bash-1977 [000] ...1 17284.993655: _raw_spin_unlock <-__close_fd
868 bash-1977 [000] ...1 17284.993656: sub_preempt_count <-_raw_spin_unlock
869 bash-1977 [000] .... 17284.993657: filp_close <-__close_fd
870 bash-1977 [000] .... 17284.993657: dnotify_flush <-filp_close
871 sshd-1974 [003] .... 17284.993658: sys_select <-system_call_fastpath
878 lost due to the buffer filling up (250280 - 140080 = 110200 events
882 PID "1977", the CPU that it was running on "000", the latency format
888 Latency trace format
889 --------------------
891 When the latency-format option is enabled or when one of the latency
893 why a latency happened. Here is a typical trace::
897 # irqsoff latency trace v1.1.5 on 3.8.0-test+
898 # --------------------------------------------------------------------
899 # latency: 259 us, #4/4, CPU#2 | (M:preempt VP:0, KP:0, SP:0 HP:0 #P:4)
900 # -----------------
901 # | task: ps-6143 (uid:0 nice:0 policy:0 rt_prio:0)
902 # -----------------
907 # _------=> CPU#
908 # / _-----=> irqs-off
909 # | / _----=> need-resched
910 # || / _---=> hardirq/softirq
911 # ||| / _--=> preempt-depth
915 ps-6143 2d... 0us!: trace_hardirqs_off <-__lock_task_sighand
916 ps-6143 2d..1 259us+: trace_hardirqs_on <-_raw_spin_unlock_irqrestore
917 ps-6143 2d..1 263us+: time_hardirqs_on <-_raw_spin_unlock_irqrestore
918 ps-6143 2d..1 306us : <stack trace>
934 (3.8). Then it displays the max latency in microseconds (259 us). The number
939 The task is the process that was running when the latency
945 - __lock_task_sighand is where the interrupts were disabled.
946 - _raw_spin_unlock_irqrestore is where they were enabled again.
957 irqs-off: 'd' interrupts are disabled. '.' otherwise.
962 need-resched:
963 - 'N' both TIF_NEED_RESCHED and PREEMPT_NEED_RESCHED is set,
964 - 'n' only TIF_NEED_RESCHED is set,
965 - 'p' only PREEMPT_NEED_RESCHED is set,
966 - '.' otherwise.
969 - 'Z' - NMI occurred inside a hardirq
970 - 'z' - NMI is running
971 - 'H' - hard irq occurred inside a softirq.
972 - 'h' - hard irq is running
973 - 's' - soft irq is running
974 - '.' - normal context.
976 preempt-depth: The level of preempt_disabled
981 When the latency-format option is enabled, the trace file
983 trace. This differs from the output when latency-format
992 - '$' - greater than 1 second
993 - '@' - greater than 100 millisecond
994 - '*' - greater than 10 millisecond
995 - '#' - greater than 1000 microsecond
996 - '!' - greater than 100 microsecond
997 - '+' - greater than 10 microsecond
998 - ' ' - less than or equal to 10 microsecond.
1002 Note, the latency tracers will usually end with a back trace
1003 to easily find where the latency occurred.
1006 -------------
1013 print-parent
1014 nosym-offset
1015 nosym-addr
1024 nosym-userobj
1025 noprintk-msg-only
1026 context-info
1027 nolatency-format
1028 record-cmd
1029 norecord-tgid
1032 irq-info
1034 noevent-fork
1035 function-trace
1036 nofunction-fork
1037 nodisplay-graph
1044 echo noprint-parent > trace_options
1048 echo sym-offset > trace_options
1052 print-parent
1057 print-parent:
1058 bash-4000 [01] 1477.606694: simple_strtoul <-kstrtoul
1060 noprint-parent:
1061 bash-4000 [01] 1477.606694: simple_strtoul
1064 sym-offset
1071 sym-offset:
1072 bash-4000 [01] 1477.606694: simple_strtoul+0x6/0xa0
1074 sym-addr
1079 sym-addr:
1080 bash-4000 [01] 1477.606694: simple_strtoul <c0339346>
1084 latency-format option is enabled.
1117 <idle>-0 [001] dNs4 21169.031481: wake_up_idle_cpu <-add_timer_on
1118 <idle>-0 [001] dNs4 21169.031482: _raw_spin_unlock_irqrestore <-add_timer_on
1119 <idle>-0 [001] .Ns4 21169.031484: sub_preempt_count <-_raw_spin_unlock_irqrestore
1121 <idle>-0 [002] .N.1 21169.031484: rcu_idle_exit <-cpu_idle
1122 <idle>-0 [001] .Ns3 21169.031484: _raw_spin_unlock <-clocksource_watchdog
1123 <idle>-0 [001] .Ns3 21169.031485: sub_preempt_count <-_raw_spin_unlock
1130 sym-userobj
1141 a.out-1623 [000] 40874.465068: /root/a.out[+0x480] <-/root/a.out[+0
1142 x494] <- /root/a.out[+0x4a8] <- /lib/libc-2.7.so[+0x1e1a6]
1145 printk-msg-only
1150 context-info
1154 latency-format
1157 latency, as described in "Latency trace format".
1159 pause-on-trace
1165 record-cmd
1173 record-tgid
1190 irq-info
1196 # entries-in-buffer/entries-written: 144405/9452052 #P:4
1198 # TASK-PID CPU# TIMESTAMP FUNCTION
1200 <idle>-0 [002] 23636.756054: ttwu_do_activate.constprop.89 <-try_to_wake_up
1201 <idle>-0 [002] 23636.756054: activate_task <-ttwu_do_activate.constprop.89
1202 <idle>-0 [002] 23636.756055: enqueue_task <-activate_task
1210 event-fork
1218 function-trace
1219 The latency tracers will enable function tracing
1221 it is disabled, the latency tracers do not trace
1223 when performing latency tests.
1225 function-fork
1234 display-graph
1235 When set, the latency tracers (irqsoff, wakeup, etc) will
1270 funcgraph-overrun
1281 funcgraph-cpu
1285 funcgraph-overhead
1291 funcgraph-proc
1298 funcgraph-duration
1303 funcgraph-abstime
1306 funcgraph-irqs
1310 funcgraph-tail
1316 sleep-time
1322 graph-time
1336 -------
1341 the kernel know of a new mouse event. The result is a latency
1345 disabled. When a new maximum latency is hit, the tracer saves
1346 the trace leading up to that latency point so that every time a
1353 # echo 0 > options/function-trace
1357 # ls -ltr
1363 # irqsoff latency trace v1.1.5 on 3.8.0-test+
1364 # --------------------------------------------------------------------
1365 # latency: 16 us, #4/4, CPU#0 | (M:preempt VP:0, KP:0, SP:0 HP:0 #P:4)
1366 # -----------------
1367 # | task: swapper/0-0 (uid:0 nice:0 policy:0 rt_prio:0)
1368 # -----------------
1373 # _------=> CPU#
1374 # / _-----=> irqs-off
1375 # | / _----=> need-resched
1376 # || / _---=> hardirq/softirq
1377 # ||| / _--=> preempt-depth
1381 <idle>-0 0d.s2 0us+: _raw_spin_lock_irq <-run_timer_softirq
1382 <idle>-0 0dNs3 17us : _raw_spin_unlock_irq <-run_timer_softirq
1383 <idle>-0 0dNs3 17us+: trace_hardirqs_on <-run_timer_softirq
1384 <idle>-0 0dNs3 25us : <stack trace>
1400 Here we see that we had a latency of 16 microseconds (which is
1403 timestamp 25us occurred because the clock was incremented
1404 between the time of recording the max latency and the time of
1405 recording the function that had that latency.
1407 Note the above example had function-trace not set. If we set
1408 function-trace, we get a much larger output::
1410 with echo 1 > options/function-trace
1414 # irqsoff latency trace v1.1.5 on 3.8.0-test+
1415 # --------------------------------------------------------------------
1416 # latency: 71 us, #168/168, CPU#3 | (M:preempt VP:0, KP:0, SP:0 HP:0 #P:4)
1417 # -----------------
1418 # | task: bash-2042 (uid:0 nice:0 policy:0 rt_prio:0)
1419 # -----------------
1424 # _------=> CPU#
1425 # / _-----=> irqs-off
1426 # | / _----=> need-resched
1427 # || / _---=> hardirq/softirq
1428 # ||| / _--=> preempt-depth
1432 bash-2042 3d... 0us : _raw_spin_lock_irqsave <-ata_scsi_queuecmd
1433 bash-2042 3d... 0us : add_preempt_count <-_raw_spin_lock_irqsave
1434 bash-2042 3d..1 1us : ata_scsi_find_dev <-ata_scsi_queuecmd
1435 bash-2042 3d..1 1us : __ata_scsi_find_dev <-ata_scsi_find_dev
1436 bash-2042 3d..1 2us : ata_find_dev.part.14 <-__ata_scsi_find_dev
1437 bash-2042 3d..1 2us : ata_qc_new_init <-__ata_scsi_queuecmd
1438 bash-2042 3d..1 3us : ata_sg_init <-__ata_scsi_queuecmd
1439 bash-2042 3d..1 4us : ata_scsi_rw_xlat <-__ata_scsi_queuecmd
1440 bash-2042 3d..1 4us : ata_build_rw_tf <-ata_scsi_rw_xlat
1442 bash-2042 3d..1 67us : delay_tsc <-__delay
1443 bash-2042 3d..1 67us : add_preempt_count <-delay_tsc
1444 bash-2042 3d..2 67us : sub_preempt_count <-delay_tsc
1445 bash-2042 3d..1 67us : add_preempt_count <-delay_tsc
1446 bash-2042 3d..2 68us : sub_preempt_count <-delay_tsc
1447 bash-2042 3d..1 68us+: ata_bmdma_start <-ata_bmdma_qc_issue
1448 bash-2042 3d..1 71us : _raw_spin_unlock_irqrestore <-ata_scsi_queuecmd
1449 bash-2042 3d..1 71us : _raw_spin_unlock_irqrestore <-ata_scsi_queuecmd
1450 bash-2042 3d..1 72us+: trace_hardirqs_on <-ata_scsi_queuecmd
1451 bash-2042 3d..1 120us : <stack trace>
1479 Here we traced a 71 microsecond latency. But we also see all the
1482 overhead may extend the latency times. But nevertheless, this
1486 display-graph option::
1488 with echo 1 > options/display-graph
1492 # irqsoff latency trace v1.1.5 on 4.20.0-rc6+
1493 # --------------------------------------------------------------------
1494 # latency: 3751 us, #274/274, CPU#0 | (M:desktop VP:0, KP:0, SP:0 HP:0 #P:4)
1495 # -----------------
1496 # | task: bash-1507 (uid:0 nice:0 policy:0 rt_prio:0)
1497 # -----------------
1502 # _-----=> irqs-off
1503 # / _----=> need-resched
1504 # | / _---=> hardirq/softirq
1505 # || / _--=> preempt-depth
1509 0 us | 0) bash-1507 | d... | 0.000 us | _raw_spin_lock_irqsave();
1510 0 us | 0) bash-1507 | d..1 | 0.378 us | do_raw_spin_trylock();
1511 1 us | 0) bash-1507 | d..2 | | set_track() {
1512 2 us | 0) bash-1507 | d..2 | | save_stack_trace() {
1513 2 us | 0) bash-1507 | d..2 | | __save_stack_trace() {
1514 3 us | 0) bash-1507 | d..2 | | __unwind_start() {
1515 3 us | 0) bash-1507 | d..2 | | get_stack_info() {
1516 3 us | 0) bash-1507 | d..2 | 0.351 us | in_task_stack();
1517 4 us | 0) bash-1507 | d..2 | 1.107 us | }
1519 3750 us | 0) bash-1507 | d..1 | 0.516 us | do_raw_spin_unlock();
1520 3750 us | 0) bash-1507 | d..1 | 0.000 us | _raw_spin_unlock_irqrestore();
1521 3764 us | 0) bash-1507 | d..1 | 0.000 us | tracer_hardirqs_on();
1522 bash-1507 0d..1 3792us : <stack trace>
1539 ----------
1547 Like the irqsoff tracer, it records the maximum latency for
1552 # echo 0 > options/function-trace
1556 # ls -ltr
1562 # preemptoff latency trace v1.1.5 on 3.8.0-test+
1563 # --------------------------------------------------------------------
1564 # latency: 46 us, #4/4, CPU#1 | (M:preempt VP:0, KP:0, SP:0 HP:0 #P:4)
1565 # -----------------
1566 # | task: sshd-1991 (uid:0 nice:0 policy:0 rt_prio:0)
1567 # -----------------
1572 # _------=> CPU#
1573 # / _-----=> irqs-off
1574 # | / _----=> need-resched
1575 # || / _---=> hardirq/softirq
1576 # ||| / _--=> preempt-depth
1580 sshd-1991 1d.h. 0us+: irq_enter <-do_IRQ
1581 sshd-1991 1d..1 46us : irq_exit <-do_IRQ
1582 sshd-1991 1d..1 47us+: trace_preempt_on <-do_IRQ
1583 sshd-1991 1d..1 52us : <stack trace>
1600 # preemptoff latency trace v1.1.5 on 3.8.0-test+
1601 # --------------------------------------------------------------------
1602 # latency: 83 us, #241/241, CPU#1 | (M:preempt VP:0, KP:0, SP:0 HP:0 #P:4)
1603 # -----------------
1604 # | task: bash-1994 (uid:0 nice:0 policy:0 rt_prio:0)
1605 # -----------------
1610 # _------=> CPU#
1611 # / _-----=> irqs-off
1612 # | / _----=> need-resched
1613 # || / _---=> hardirq/softirq
1614 # ||| / _--=> preempt-depth
1618 bash-1994 1d..1 0us : _raw_spin_lock_irqsave <-wake_up_new_task
1619 bash-1994 1d..1 0us : select_task_rq_fair <-select_task_rq
1620 bash-1994 1d..1 1us : __rcu_read_lock <-select_task_rq_fair
1621 bash-1994 1d..1 1us : source_load <-select_task_rq_fair
1622 bash-1994 1d..1 1us : source_load <-select_task_rq_fair
1624 bash-1994 1d..1 12us : irq_enter <-smp_apic_timer_interrupt
1625 bash-1994 1d..1 12us : rcu_irq_enter <-irq_enter
1626 bash-1994 1d..1 13us : add_preempt_count <-irq_enter
1627 bash-1994 1d.h1 13us : exit_idle <-smp_apic_timer_interrupt
1628 bash-1994 1d.h1 13us : hrtimer_interrupt <-smp_apic_timer_interrupt
1629 bash-1994 1d.h1 13us : _raw_spin_lock <-hrtimer_interrupt
1630 bash-1994 1d.h1 14us : add_preempt_count <-_raw_spin_lock
1631 bash-1994 1d.h2 14us : ktime_get_update_offsets <-hrtimer_interrupt
1633 bash-1994 1d.h1 35us : lapic_next_event <-clockevents_program_event
1634 bash-1994 1d.h1 35us : irq_exit <-smp_apic_timer_interrupt
1635 bash-1994 1d.h1 36us : sub_preempt_count <-irq_exit
1636 bash-1994 1d..2 36us : do_softirq <-irq_exit
1637 bash-1994 1d..2 36us : __do_softirq <-call_softirq
1638 bash-1994 1d..2 36us : __local_bh_disable <-__do_softirq
1639 bash-1994 1d.s2 37us : add_preempt_count <-_raw_spin_lock_irq
1640 bash-1994 1d.s3 38us : _raw_spin_unlock <-run_timer_softirq
1641 bash-1994 1d.s3 39us : sub_preempt_count <-_raw_spin_unlock
1642 bash-1994 1d.s2 39us : call_timer_fn <-run_timer_softirq
1644 bash-1994 1dNs2 81us : cpu_needs_another_gp <-rcu_process_callbacks
1645 bash-1994 1dNs2 82us : __local_bh_enable <-__do_softirq
1646 bash-1994 1dNs2 82us : sub_preempt_count <-__local_bh_enable
1647 bash-1994 1dN.2 82us : idle_cpu <-irq_exit
1648 bash-1994 1dN.2 83us : rcu_irq_exit <-irq_exit
1649 bash-1994 1dN.2 83us : sub_preempt_count <-irq_exit
1650 bash-1994 1.N.1 84us : _raw_spin_unlock_irqrestore <-task_rq_unlock
1651 bash-1994 1.N.1 84us+: trace_preempt_on <-task_rq_unlock
1652 bash-1994 1.N.1 104us : <stack trace>
1663 function-trace set. Here we see that interrupts were not disabled
1664 the entire time. The irq_enter code lets us know that we entered
1670 --------------
1704 # echo 0 > options/function-trace
1708 # ls -ltr
1714 # preemptirqsoff latency trace v1.1.5 on 3.8.0-test+
1715 # --------------------------------------------------------------------
1716 # latency: 100 us, #4/4, CPU#3 | (M:preempt VP:0, KP:0, SP:0 HP:0 #P:4)
1717 # -----------------
1718 # | task: ls-2230 (uid:0 nice:0 policy:0 rt_prio:0)
1719 # -----------------
1724 # _------=> CPU#
1725 # / _-----=> irqs-off
1726 # | / _----=> need-resched
1727 # || / _---=> hardirq/softirq
1728 # ||| / _--=> preempt-depth
1732 ls-2230 3d... 0us+: _raw_spin_lock_irqsave <-ata_scsi_queuecmd
1733 ls-2230 3...1 100us : _raw_spin_unlock_irqrestore <-ata_scsi_queuecmd
1734 ls-2230 3...1 101us+: trace_preempt_on <-ata_scsi_queuecmd
1735 ls-2230 3...1 111us : <stack trace>
1763 Here is a trace with function-trace set::
1767 # preemptirqsoff latency trace v1.1.5 on 3.8.0-test+
1768 # --------------------------------------------------------------------
1769 # latency: 161 us, #339/339, CPU#3 | (M:preempt VP:0, KP:0, SP:0 HP:0 #P:4)
1770 # -----------------
1771 # | task: ls-2269 (uid:0 nice:0 policy:0 rt_prio:0)
1772 # -----------------
1777 # _------=> CPU#
1778 # / _-----=> irqs-off
1779 # | / _----=> need-resched
1780 # || / _---=> hardirq/softirq
1781 # ||| / _--=> preempt-depth
1785 kworker/-59 3...1 0us : __schedule <-schedule
1786 kworker/-59 3d..1 0us : rcu_preempt_qs <-rcu_note_context_switch
1787 kworker/-59 3d..1 1us : add_preempt_count <-_raw_spin_lock_irq
1788 kworker/-59 3d..2 1us : deactivate_task <-__schedule
1789 kworker/-59 3d..2 1us : dequeue_task <-deactivate_task
1790 kworker/-59 3d..2 2us : update_rq_clock <-dequeue_task
1791 kworker/-59 3d..2 2us : dequeue_task_fair <-dequeue_task
1792 kworker/-59 3d..2 2us : update_curr <-dequeue_task_fair
1793 kworker/-59 3d..2 2us : update_min_vruntime <-update_curr
1794 kworker/-59 3d..2 3us : cpuacct_charge <-update_curr
1795 kworker/-59 3d..2 3us : __rcu_read_lock <-cpuacct_charge
1796 kworker/-59 3d..2 3us : __rcu_read_unlock <-cpuacct_charge
1797 kworker/-59 3d..2 3us : update_cfs_rq_blocked_load <-dequeue_task_fair
1798 kworker/-59 3d..2 4us : clear_buddies <-dequeue_task_fair
1799 kworker/-59 3d..2 4us : account_entity_dequeue <-dequeue_task_fair
1800 kworker/-59 3d..2 4us : update_min_vruntime <-dequeue_task_fair
1801 kworker/-59 3d..2 4us : update_cfs_shares <-dequeue_task_fair
1802 kworker/-59 3d..2 5us : hrtick_update <-dequeue_task_fair
1803 kworker/-59 3d..2 5us : wq_worker_sleeping <-__schedule
1804 kworker/-59 3d..2 5us : kthread_data <-wq_worker_sleeping
1805 kworker/-59 3d..2 5us : put_prev_task_fair <-__schedule
1806 kworker/-59 3d..2 6us : pick_next_task_fair <-pick_next_task
1807 kworker/-59 3d..2 6us : clear_buddies <-pick_next_task_fair
1808 kworker/-59 3d..2 6us : set_next_entity <-pick_next_task_fair
1809 kworker/-59 3d..2 6us : update_stats_wait_end <-set_next_entity
1810 ls-2269 3d..2 7us : finish_task_switch <-__schedule
1811 ls-2269 3d..2 7us : _raw_spin_unlock_irq <-finish_task_switch
1812 ls-2269 3d..2 8us : do_IRQ <-ret_from_intr
1813 ls-2269 3d..2 8us : irq_enter <-do_IRQ
1814 ls-2269 3d..2 8us : rcu_irq_enter <-irq_enter
1815 ls-2269 3d..2 9us : add_preempt_count <-irq_enter
1816 ls-2269 3d.h2 9us : exit_idle <-do_IRQ
1818 ls-2269 3d.h3 20us : sub_preempt_count <-_raw_spin_unlock
1819 ls-2269 3d.h2 20us : irq_exit <-do_IRQ
1820 ls-2269 3d.h2 21us : sub_preempt_count <-irq_exit
1821 ls-2269 3d..3 21us : do_softirq <-irq_exit
1822 ls-2269 3d..3 21us : __do_softirq <-call_softirq
1823 ls-2269 3d..3 21us+: __local_bh_disable <-__do_softirq
1824 ls-2269 3d.s4 29us : sub_preempt_count <-_local_bh_enable_ip
1825 ls-2269 3d.s5 29us : sub_preempt_count <-_local_bh_enable_ip
1826 ls-2269 3d.s5 31us : do_IRQ <-ret_from_intr
1827 ls-2269 3d.s5 31us : irq_enter <-do_IRQ
1828 ls-2269 3d.s5 31us : rcu_irq_enter <-irq_enter
1830 ls-2269 3d.s5 31us : rcu_irq_enter <-irq_enter
1831 ls-2269 3d.s5 32us : add_preempt_count <-irq_enter
1832 ls-2269 3d.H5 32us : exit_idle <-do_IRQ
1833 ls-2269 3d.H5 32us : handle_irq <-do_IRQ
1834 ls-2269 3d.H5 32us : irq_to_desc <-handle_irq
1835 ls-2269 3d.H5 33us : handle_fasteoi_irq <-handle_irq
1837 ls-2269 3d.s5 158us : _raw_spin_unlock_irqrestore <-rtl8139_poll
1838 ls-2269 3d.s3 158us : net_rps_action_and_irq_enable.isra.65 <-net_rx_action
1839 ls-2269 3d.s3 159us : __local_bh_enable <-__do_softirq
1840 ls-2269 3d.s3 159us : sub_preempt_count <-__local_bh_enable
1841 ls-2269 3d..3 159us : idle_cpu <-irq_exit
1842 ls-2269 3d..3 159us : rcu_irq_exit <-irq_exit
1843 ls-2269 3d..3 160us : sub_preempt_count <-irq_exit
1844 ls-2269 3d... 161us : __mutex_unlock_slowpath <-mutex_unlock
1845 ls-2269 3d... 162us+: trace_hardirqs_on <-mutex_unlock
1846 ls-2269 3d... 186us : <stack trace>
1865 ------
1869 Now for non Real-Time tasks, this can be arbitrary. But tracing
1874 # echo 0 > options/function-trace
1878 # chrt -f 5 sleep 1
1883 # wakeup latency trace v1.1.5 on 3.8.0-test+
1884 # --------------------------------------------------------------------
1885 # latency: 15 us, #4/4, CPU#3 | (M:preempt VP:0, KP:0, SP:0 HP:0 #P:4)
1886 # -----------------
1887 # | task: kworker/3:1H-312 (uid:0 nice:-20 policy:0 rt_prio:0)
1888 # -----------------
1890 # _------=> CPU#
1891 # / _-----=> irqs-off
1892 # | / _----=> need-resched
1893 # || / _---=> hardirq/softirq
1894 # ||| / _--=> preempt-depth
1898 <idle>-0 3dNs7 0us : 0:120:R + [003] 312:100:R kworker/3:1H
1899 <idle>-0 3dNs7 1us+: ttwu_do_activate.constprop.87 <-try_to_wake_up
1900 <idle>-0 3d..3 15us : __schedule <-schedule
1901 <idle>-0 3d..3 15us : 0:120:R ==> [003] 312:100:R kworker/3:1H
1905 the kworker with a nice priority of -20 (not very nice), took
1909 Non Real-Time tasks are not that interesting. A more interesting
1910 trace is to concentrate only on Real-Time tasks.
1913 ---------
1915 In a Real-Time environment it is very important to know the
1918 latency". I stress the point that this is about RT tasks. It is
1919 also important to know the scheduling latency of non-RT tasks,
1920 but the average schedule latency is better for non-RT tasks.
1924 Real-Time environments are interested in the worst case latency.
1925 That is the longest latency it takes for something to happen,
1927 only have a large latency once in a while, but that would not
1928 work well with Real-Time tasks. The wakeup_rt tracer was designed
1929 to record the worst case wakeups of RT tasks. Non-RT tasks are
1931 tracing non-RT tasks that are unpredictable will overwrite the
1932 worst case latency of RT tasks (just run the normal wakeup
1941 # echo 0 > options/function-trace
1945 # chrt -f 5 sleep 1
1952 # wakeup_rt latency trace v1.1.5 on 3.8.0-test+
1953 # --------------------------------------------------------------------
1954 # latency: 5 us, #4/4, CPU#3 | (M:preempt VP:0, KP:0, SP:0 HP:0 #P:4)
1955 # -----------------
1956 # | task: sleep-2389 (uid:0 nice:0 policy:1 rt_prio:5)
1957 # -----------------
1959 # _------=> CPU#
1960 # / _-----=> irqs-off
1961 # | / _----=> need-resched
1962 # || / _---=> hardirq/softirq
1963 # ||| / _--=> preempt-depth
1967 <idle>-0 3d.h4 0us : 0:120:R + [003] 2389: 94:R sleep
1968 <idle>-0 3d.h4 1us+: ttwu_do_activate.constprop.87 <-try_to_wake_up
1969 <idle>-0 3d..3 5us : __schedule <-schedule
1970 <idle>-0 3d..3 5us : 0:120:R ==> [003] 2389: 94:R sleep
1980 and it has an rt_prio of 5. This priority is user-space priority
1984 Note, that the trace data shows the internal priority (99 - rtprio).
1987 <idle>-0 3d..3 5us : 0:120:R ==> [003] 2389: 94:R sleep
1989 The 0:120:R means idle was running with a nice priority of 0 (120 - 120)
1991 2389: 94:R. That is the priority is the kernel rtprio (99 - 5 = 94)
1994 Doing the same with chrt -r 5 and function-trace set.
1997 echo 1 > options/function-trace
2001 # wakeup_rt latency trace v1.1.5 on 3.8.0-test+
2002 # --------------------------------------------------------------------
2003 # latency: 29 us, #85/85, CPU#3 | (M:preempt VP:0, KP:0, SP:0 HP:0 #P:4)
2004 # -----------------
2005 # | task: sleep-2448 (uid:0 nice:0 policy:1 rt_prio:5)
2006 # -----------------
2008 # _------=> CPU#
2009 # / _-----=> irqs-off
2010 # | / _----=> need-resched
2011 # || / _---=> hardirq/softirq
2012 # ||| / _--=> preempt-depth
2016 <idle>-0 3d.h4 1us+: 0:120:R + [003] 2448: 94:R sleep
2017 <idle>-0 3d.h4 2us : ttwu_do_activate.constprop.87 <-try_to_wake_up
2018 <idle>-0 3d.h3 3us : check_preempt_curr <-ttwu_do_wakeup
2019 <idle>-0 3d.h3 3us : resched_curr <-check_preempt_curr
2020 <idle>-0 3dNh3 4us : task_woken_rt <-ttwu_do_wakeup
2021 <idle>-0 3dNh3 4us : _raw_spin_unlock <-try_to_wake_up
2022 <idle>-0 3dNh3 4us : sub_preempt_count <-_raw_spin_unlock
2023 <idle>-0 3dNh2 5us : ttwu_stat <-try_to_wake_up
2024 <idle>-0 3dNh2 5us : _raw_spin_unlock_irqrestore <-try_to_wake_up
2025 <idle>-0 3dNh2 6us : sub_preempt_count <-_raw_spin_unlock_irqrestore
2026 <idle>-0 3dNh1 6us : _raw_spin_lock <-__run_hrtimer
2027 <idle>-0 3dNh1 6us : add_preempt_count <-_raw_spin_lock
2028 <idle>-0 3dNh2 7us : _raw_spin_unlock <-hrtimer_interrupt
2029 <idle>-0 3dNh2 7us : sub_preempt_count <-_raw_spin_unlock
2030 <idle>-0 3dNh1 7us : tick_program_event <-hrtimer_interrupt
2031 <idle>-0 3dNh1 7us : clockevents_program_event <-tick_program_event
2032 <idle>-0 3dNh1 8us : ktime_get <-clockevents_program_event
2033 <idle>-0 3dNh1 8us : lapic_next_event <-clockevents_program_event
2034 <idle>-0 3dNh1 8us : irq_exit <-smp_apic_timer_interrupt
2035 <idle>-0 3dNh1 9us : sub_preempt_count <-irq_exit
2036 <idle>-0 3dN.2 9us : idle_cpu <-irq_exit
2037 <idle>-0 3dN.2 9us : rcu_irq_exit <-irq_exit
2038 <idle>-0 3dN.2 10us : rcu_eqs_enter_common.isra.45 <-rcu_irq_exit
2039 <idle>-0 3dN.2 10us : sub_preempt_count <-irq_exit
2040 <idle>-0 3.N.1 11us : rcu_idle_exit <-cpu_idle
2041 <idle>-0 3dN.1 11us : rcu_eqs_exit_common.isra.43 <-rcu_idle_exit
2042 <idle>-0 3.N.1 11us : tick_nohz_idle_exit <-cpu_idle
2043 <idle>-0 3dN.1 12us : menu_hrtimer_cancel <-tick_nohz_idle_exit
2044 <idle>-0 3dN.1 12us : ktime_get <-tick_nohz_idle_exit
2045 <idle>-0 3dN.1 12us : tick_do_update_jiffies64 <-tick_nohz_idle_exit
2046 <idle>-0 3dN.1 13us : cpu_load_update_nohz <-tick_nohz_idle_exit
2047 <idle>-0 3dN.1 13us : _raw_spin_lock <-cpu_load_update_nohz
2048 <idle>-0 3dN.1 13us : add_preempt_count <-_raw_spin_lock
2049 <idle>-0 3dN.2 13us : __cpu_load_update <-cpu_load_update_nohz
2050 <idle>-0 3dN.2 14us : sched_avg_update <-__cpu_load_update
2051 <idle>-0 3dN.2 14us : _raw_spin_unlock <-cpu_load_update_nohz
2052 <idle>-0 3dN.2 14us : sub_preempt_count <-_raw_spin_unlock
2053 <idle>-0 3dN.1 15us : calc_load_nohz_stop <-tick_nohz_idle_exit
2054 <idle>-0 3dN.1 15us : touch_softlockup_watchdog <-tick_nohz_idle_exit
2055 <idle>-0 3dN.1 15us : hrtimer_cancel <-tick_nohz_idle_exit
2056 <idle>-0 3dN.1 15us : hrtimer_try_to_cancel <-hrtimer_cancel
2057 <idle>-0 3dN.1 16us : lock_hrtimer_base.isra.18 <-hrtimer_try_to_cancel
2058 <idle>-0 3dN.1 16us : _raw_spin_lock_irqsave <-lock_hrtimer_base.isra.18
2059 <idle>-0 3dN.1 16us : add_preempt_count <-_raw_spin_lock_irqsave
2060 <idle>-0 3dN.2 17us : __remove_hrtimer <-remove_hrtimer.part.16
2061 <idle>-0 3dN.2 17us : hrtimer_force_reprogram <-__remove_hrtimer
2062 <idle>-0 3dN.2 17us : tick_program_event <-hrtimer_force_reprogram
2063 <idle>-0 3dN.2 18us : clockevents_program_event <-tick_program_event
2064 <idle>-0 3dN.2 18us : ktime_get <-clockevents_program_event
2065 <idle>-0 3dN.2 18us : lapic_next_event <-clockevents_program_event
2066 <idle>-0 3dN.2 19us : _raw_spin_unlock_irqrestore <-hrtimer_try_to_cancel
2067 <idle>-0 3dN.2 19us : sub_preempt_count <-_raw_spin_unlock_irqrestore
2068 <idle>-0 3dN.1 19us : hrtimer_forward <-tick_nohz_idle_exit
2069 <idle>-0 3dN.1 20us : ktime_add_safe <-hrtimer_forward
2070 <idle>-0 3dN.1 20us : ktime_add_safe <-hrtimer_forward
2071 <idle>-0 3dN.1 20us : hrtimer_start_range_ns <-hrtimer_start_expires.constprop.11
2072 <idle>-0 3dN.1 20us : __hrtimer_start_range_ns <-hrtimer_start_range_ns
2073 <idle>-0 3dN.1 21us : lock_hrtimer_base.isra.18 <-__hrtimer_start_range_ns
2074 <idle>-0 3dN.1 21us : _raw_spin_lock_irqsave <-lock_hrtimer_base.isra.18
2075 <idle>-0 3dN.1 21us : add_preempt_count <-_raw_spin_lock_irqsave
2076 <idle>-0 3dN.2 22us : ktime_add_safe <-__hrtimer_start_range_ns
2077 <idle>-0 3dN.2 22us : enqueue_hrtimer <-__hrtimer_start_range_ns
2078 <idle>-0 3dN.2 22us : tick_program_event <-__hrtimer_start_range_ns
2079 <idle>-0 3dN.2 23us : clockevents_program_event <-tick_program_event
2080 <idle>-0 3dN.2 23us : ktime_get <-clockevents_program_event
2081 <idle>-0 3dN.2 23us : lapic_next_event <-clockevents_program_event
2082 <idle>-0 3dN.2 24us : _raw_spin_unlock_irqrestore <-__hrtimer_start_range_ns
2083 <idle>-0 3dN.2 24us : sub_preempt_count <-_raw_spin_unlock_irqrestore
2084 <idle>-0 3dN.1 24us : account_idle_ticks <-tick_nohz_idle_exit
2085 <idle>-0 3dN.1 24us : account_idle_time <-account_idle_ticks
2086 <idle>-0 3.N.1 25us : sub_preempt_count <-cpu_idle
2087 <idle>-0 3.N.. 25us : schedule <-cpu_idle
2088 <idle>-0 3.N.. 25us : __schedule <-preempt_schedule
2089 <idle>-0 3.N.. 26us : add_preempt_count <-__schedule
2090 <idle>-0 3.N.1 26us : rcu_note_context_switch <-__schedule
2091 <idle>-0 3.N.1 26us : rcu_sched_qs <-rcu_note_context_switch
2092 <idle>-0 3dN.1 27us : rcu_preempt_qs <-rcu_note_context_switch
2093 <idle>-0 3.N.1 27us : _raw_spin_lock_irq <-__schedule
2094 <idle>-0 3dN.1 27us : add_preempt_count <-_raw_spin_lock_irq
2095 <idle>-0 3dN.2 28us : put_prev_task_idle <-__schedule
2096 <idle>-0 3dN.2 28us : pick_next_task_stop <-pick_next_task
2097 <idle>-0 3dN.2 28us : pick_next_task_rt <-pick_next_task
2098 <idle>-0 3dN.2 29us : dequeue_pushable_task <-pick_next_task_rt
2099 <idle>-0 3d..3 29us : __schedule <-preempt_schedule
2100 <idle>-0 3d..3 30us : 0:120:R ==> [003] 2448: 94:R sleep
2109 Latency tracing and events
2110 --------------------------
2111 As function tracing can induce a much larger latency, but without
2112 seeing what happens within the latency it is hard to know what
2117 # echo 0 > options/function-trace
2122 # chrt -f 5 sleep 1
2127 # wakeup_rt latency trace v1.1.5 on 3.8.0-test+
2128 # --------------------------------------------------------------------
2129 # latency: 6 us, #12/12, CPU#2 | (M:preempt VP:0, KP:0, SP:0 HP:0 #P:4)
2130 # -----------------
2131 # | task: sleep-5882 (uid:0 nice:0 policy:1 rt_prio:5)
2132 # -----------------
2134 # _------=> CPU#
2135 # / _-----=> irqs-off
2136 # | / _----=> need-resched
2137 # || / _---=> hardirq/softirq
2138 # ||| / _--=> preempt-depth
2142 <idle>-0 2d.h4 0us : 0:120:R + [002] 5882: 94:R sleep
2143 <idle>-0 2d.h4 0us : ttwu_do_activate.constprop.87 <-try_to_wake_up
2144 <idle>-0 2d.h4 1us : sched_wakeup: comm=sleep pid=5882 prio=94 success=1 target_cpu=002
2145 <idle>-0 2dNh2 1us : hrtimer_expire_exit: hrtimer=ffff88007796feb8
2146 <idle>-0 2.N.2 2us : power_end: cpu_id=2
2147 <idle>-0 2.N.2 3us : cpu_idle: state=4294967295 cpu_id=2
2148 <idle>-0 2dN.3 4us : hrtimer_cancel: hrtimer=ffff88007d50d5e0
2149 …<idle>-0 2dN.3 4us : hrtimer_start: hrtimer=ffff88007d50d5e0 function=tick_sched_timer ex…
2150 <idle>-0 2.N.2 5us : rcu_utilization: Start context switch
2151 <idle>-0 2.N.2 5us : rcu_utilization: End context switch
2152 <idle>-0 2d..3 6us : __schedule <-schedule
2153 <idle>-0 2d..3 6us : 0:120:R ==> [002] 5882: 94:R sleep
2156 Hardware Latency Detector
2157 -------------------------
2159 The hardware latency detector is executed by enabling the "hwlat" tracer.
2170 # entries-in-buffer/entries-written: 13/13 #P:8
2172 # _-----=> irqs-off
2173 # / _----=> need-resched
2174 # | / _---=> hardirq/softirq
2175 # || / _--=> preempt-depth
2177 # TASK-PID CPU# |||| TIMESTAMP FUNCTION
2179 …<...>-1729 [001] d... 678.473449: #1 inner/outer(us): 11/12 ts:1581527483.343962693 co…
2180 …<...>-1729 [004] d... 689.556542: #2 inner/outer(us): 16/9 ts:1581527494.889008092 co…
2181 …<...>-1729 [005] d... 714.756290: #3 inner/outer(us): 16/16 ts:1581527519.678961629 co…
2182 …<...>-1729 [001] d... 718.788247: #4 inner/outer(us): 9/17 ts:1581527523.889012713 co…
2183 …<...>-1729 [002] d... 719.796341: #5 inner/outer(us): 13/9 ts:1581527524.912872606 co…
2184 …<...>-1729 [006] d... 844.787091: #6 inner/outer(us): 9/12 ts:1581527649.889048502 co…
2185 …<...>-1729 [003] d... 849.827033: #7 inner/outer(us): 18/9 ts:1581527654.889013793 co…
2186 …<...>-1729 [007] d... 853.859002: #8 inner/outer(us): 9/12 ts:1581527658.889065736 co…
2187 …<...>-1729 [001] d... 855.874978: #9 inner/outer(us): 9/11 ts:1581527660.861991877 co…
2188 …<...>-1729 [001] d... 863.938932: #10 inner/outer(us): 9/11 ts:1581527668.970010500 co…
2189 …<...>-1729 [007] d... 878.050780: #11 inner/outer(us): 9/12 ts:1581527683.385002600 co…
2190 …<...>-1729 [007] d... 886.114702: #12 inner/outer(us): 9/12 ts:1581527691.385001600 co…
2200 inner/outer(us): 11/11
2202 This shows two numbers as "inner latency" and "outer latency". The test
2203 runs in a loop checking a timestamp twice. The latency detected within
2204 the two timestamps is the "inner latency" and the latency detected
2206 the "outer latency".
2210 The absolute timestamp that the first latency was recorded in the window.
2214 The number of times a latency was detected during the window.
2216 nmi-total:7 nmi-count:1
2219 test, the time spent in NMI is reported in "nmi-total" (in
2222 All architectures that have NMIs will show the "nmi-count" if an
2229 microseconds. This is the threshold of latency that
2253 --------
2269 # entries-in-buffer/entries-written: 24799/24799 #P:4
2271 # _-----=> irqs-off
2272 # / _----=> need-resched
2273 # | / _---=> hardirq/softirq
2274 # || / _--=> preempt-depth
2276 # TASK-PID CPU# |||| TIMESTAMP FUNCTION
2278 bash-1994 [002] .... 3082.063030: mutex_unlock <-rb_simple_write
2279 bash-1994 [002] .... 3082.063031: __mutex_unlock_slowpath <-mutex_unlock
2280 bash-1994 [002] .... 3082.063031: __fsnotify_parent <-fsnotify_modify
2281 bash-1994 [002] .... 3082.063032: fsnotify <-fsnotify_modify
2282 bash-1994 [002] .... 3082.063032: __srcu_read_lock <-fsnotify
2283 bash-1994 [002] .... 3082.063032: add_preempt_count <-__srcu_read_lock
2284 bash-1994 [002] ...1 3082.063032: sub_preempt_count <-__srcu_read_lock
2285 bash-1994 [002] .... 3082.063033: __srcu_read_unlock <-fsnotify
2313 ---------------------
2327 # TASK-PID CPU# TIMESTAMP FUNCTION
2329 yum-updatesd-3111 [003] 1637.254676: finish_task_switch <-thread_return
2330 yum-updatesd-3111 [003] 1637.254681: hrtimer_cancel <-schedule_hrtimeout_range
2331 yum-updatesd-3111 [003] 1637.254682: hrtimer_try_to_cancel <-hrtimer_cancel
2332 yum-updatesd-3111 [003] 1637.254683: lock_hrtimer_base <-hrtimer_try_to_cancel
2333 yum-updatesd-3111 [003] 1637.254685: fget_light <-do_sys_poll
2334 yum-updatesd-3111 [003] 1637.254686: pipe_poll <-do_sys_poll
2339 # TASK-PID CPU# TIMESTAMP FUNCTION
2342 yum-updatesd-3111 [003] 1701.957688: free_poll_entry <-poll_freewait
2343 yum-updatesd-3111 [003] 1701.957689: remove_wait_queue <-free_poll_entry
2344 yum-updatesd-3111 [003] 1701.957691: fput <-free_poll_entry
2345 yum-updatesd-3111 [003] 1701.957692: audit_syscall_exit <-sysret_audit
2346 yum-updatesd-3111 [003] 1701.957693: path_put <-audit_syscall_exit
2409 exit(-1);
2418 exit(-1);
2441 tracefs=`sed -ne 's/^tracefs \(.*\) tracefs.*/\1/p' /proc/mounts`
2451 ---------------------------
2454 probes a function on its entry and its exit. This is done by
2456 task_struct. On function entry the tracer overwrites the return
2464 - measure of a function's time execution
2465 - having a reliable call stack to draw function calls graph
2469 - you want to find the reason of a strange kernel behavior and
2473 - you are experiencing weird latencies but it's difficult to
2476 - you want to find quickly which path is taken by a specific
2479 - you just want to peek inside a working kernel and want to see
2493 0) 1.382 us | __might_sleep();
2494 0) 2.478 us | }
2497 0) 1.389 us | __might_sleep();
2498 0) 2.553 us | }
2499 0) 3.807 us | }
2500 0) 7.876 us | }
2502 0) 0.668 us | _spin_lock();
2503 0) 0.570 us | expand_files();
2504 0) 0.586 us | _spin_unlock();
2511 - The cpu number on which the function executed is default
2516 - hide: echo nofuncgraph-cpu > trace_options
2517 - show: echo funcgraph-cpu > trace_options
2519 - The duration (function's time of execution) is displayed on
2524 - hide: echo nofuncgraph-duration > trace_options
2525 - show: echo funcgraph-duration > trace_options
2527 - The overhead field precedes the duration field in case of
2530 - hide: echo nofuncgraph-overhead > trace_options
2531 - show: echo funcgraph-overhead > trace_options
2532 - depends on: funcgraph-duration
2536 3) # 1837.709 us | } /* __switch_to */
2538 3) 0.313 us | _raw_spin_unlock_irq();
2539 3) 3.177 us | }
2540 3) # 1889.063 us | } /* __schedule */
2541 3) ! 140.417 us | } /* __schedule */
2542 3) # 2034.948 us | } /* schedule */
2543 3) * 33998.59 us | } /* schedule_preempt_disabled */
2547 1) 0.260 us | msecs_to_jiffies();
2548 1) 0.313 us | __rcu_read_unlock();
2549 1) + 61.770 us | }
2550 1) + 64.479 us | }
2551 1) 0.313 us | rcu_bh_qs();
2552 1) 0.313 us | __local_bh_enable();
2553 1) ! 217.240 us | }
2554 1) 0.365 us | idle_cpu();
2556 1) 0.417 us | rcu_eqs_enter_common.isra.47();
2557 1) 3.125 us | }
2558 1) ! 227.812 us | }
2559 1) ! 457.395 us | }
2560 1) @ 119760.2 us | }
2565 1) 6.979 us | }
2566 2) 0.417 us | scheduler_ipi();
2567 1) 9.791 us | }
2568 1) + 12.917 us | }
2569 2) 3.490 us | }
2570 1) + 15.729 us | }
2571 1) + 18.542 us | }
2572 2) $ 3594274 us | }
2584 - The task/pid field displays the thread cmdline and pid which
2587 - hide: echo nofuncgraph-proc > trace_options
2588 - show: echo funcgraph-proc > trace_options
2596 0) sh-4802 | | d_free() {
2597 0) sh-4802 | | call_rcu() {
2598 0) sh-4802 | | __call_rcu() {
2599 0) sh-4802 | 0.616 us | rcu_process_gp_end();
2600 0) sh-4802 | 0.586 us | check_for_new_grace_period();
2601 0) sh-4802 | 2.899 us | }
2602 0) sh-4802 | 4.040 us | }
2603 0) sh-4802 | 5.151 us | }
2604 0) sh-4802 | + 49.370 us | }
2607 - The absolute time field is an absolute timestamp given by the
2609 given on each entry/exit of functions
2611 - hide: echo nofuncgraph-abstime > trace_options
2612 - show: echo funcgraph-abstime > trace_options
2619 360.774522 | 1) 0.541 us | }
2620 360.774522 | 1) 4.663 us | }
2621 360.774523 | 1) 0.541 us | __wake_up_bit();
2622 360.774524 | 1) 6.796 us | }
2623 360.774524 | 1) 7.952 us | }
2624 360.774525 | 1) 9.063 us | }
2625 360.774525 | 1) 0.615 us | journal_mark_dirty();
2626 360.774527 | 1) 0.578 us | __brelse();
2631 360.774530 | 1) 0.594 us | __phys_addr();
2643 - hide: echo nofuncgraph-tail > trace_options
2644 - show: echo funcgraph-tail > trace_options
2646 Example with nofuncgraph-tail (default)::
2650 0) 0.518 us | __phys_addr();
2651 0) 1.757 us | }
2652 0) 2.861 us | }
2654 Example with funcgraph-tail::
2658 0) 0.518 us | __phys_addr();
2659 0) 1.757 us | } /* kmem_cache_free() */
2660 0) 2.861 us | } /* putname() */
2673 1) 1.449 us | }
2681 --------------
2686 every kernel function, produced by the -pg switch in gcc),
2688 include the -pg switch in the compiling of the kernel.)
2694 with gcc version 4.6, the -mfentry has been added for x86, which
2705 The recordmcount program re-links this section back into the
2737 One special side-effect to the recording of the functions being
2777 # entries-in-buffer/entries-written: 5/5 #P:4
2779 # _-----=> irqs-off
2780 # / _----=> need-resched
2781 # | / _---=> hardirq/softirq
2782 # || / _--=> preempt-depth
2784 # TASK-PID CPU# |||| TIMESTAMP FUNCTION
2786 usleep-2665 [001] .... 4186.475355: sys_nanosleep <-system_call_fastpath
2787 <idle>-0 [001] d.h1 4186.475409: hrtimer_interrupt <-smp_apic_timer_interrupt
2788 usleep-2665 [001] d.h1 4186.475426: hrtimer_interrupt <-smp_apic_timer_interrupt
2789 <idle>-0 [003] d.h1 4186.475426: hrtimer_interrupt <-smp_apic_timer_interrupt
2790 <idle>-0 [002] d.h1 4186.475427: hrtimer_interrupt <-smp_apic_timer_interrupt
2824 # entries-in-buffer/entries-written: 897/897 #P:4
2826 # _-----=> irqs-off
2827 # / _----=> need-resched
2828 # | / _---=> hardirq/softirq
2829 # || / _--=> preempt-depth
2831 # TASK-PID CPU# |||| TIMESTAMP FUNCTION
2833 <idle>-0 [003] dN.1 4228.547803: hrtimer_cancel <-tick_nohz_idle_exit
2834 <idle>-0 [003] dN.1 4228.547804: hrtimer_try_to_cancel <-hrtimer_cancel
2835 <idle>-0 [003] dN.2 4228.547805: hrtimer_force_reprogram <-__remove_hrtimer
2836 <idle>-0 [003] dN.1 4228.547805: hrtimer_forward <-tick_nohz_idle_exit
2837 … <idle>-0 [003] dN.1 4228.547805: hrtimer_start_range_ns <-hrtimer_start_expires.constprop.11
2838 <idle>-0 [003] d..1 4228.547858: hrtimer_get_next_event <-get_next_timer_interrupt
2839 <idle>-0 [003] d..1 4228.547859: hrtimer_start <-__tick_nohz_idle_enter
2840 <idle>-0 [003] d..2 4228.547860: hrtimer_force_reprogram <-__rem
2913 # entries-in-buffer/entries-written: 39608/39608 #P:4
2915 # _-----=> irqs-off
2916 # / _----=> need-resched
2917 # | / _---=> hardirq/softirq
2918 # || / _--=> preempt-depth
2920 # TASK-PID CPU# |||| TIMESTAMP FUNCTION
2922 bash-1994 [000] .... 4342.324896: file_ra_state_init <-do_dentry_open
2923 bash-1994 [000] .... 4342.324897: open_check_o_direct <-do_last
2924 bash-1994 [000] .... 4342.324897: ima_file_check <-do_last
2925 bash-1994 [000] .... 4342.324898: process_measurement <-ima_file_check
2926 bash-1994 [000] .... 4342.324898: ima_get_action <-process_measurement
2927 bash-1994 [000] .... 4342.324898: ima_match_policy <-ima_get_action
2928 bash-1994 [000] .... 4342.324899: do_truncate <-do_last
2929 bash-1994 [000] .... 4342.324899: should_remove_suid <-do_truncate
2930 bash-1994 [000] .... 4342.324899: notify_change <-do_truncate
2931 bash-1994 [000] .... 4342.324900: current_fs_time <-notify_change
2932 bash-1994 [000] .... 4342.324900: current_kernel_time <-current_fs_time
2933 bash-1994 [000] .... 4342.324900: timespec_trunc <-current_fs_time
2938 ------------------------------------
2956 # head -1 available_filter_functions
2962 # head -50 available_filter_functions | tail -1
2971 ---------------------------------------------
2974 function tracer and the function-graph-tracer, there are some
2975 special features only available in the function-graph tracer.
2988 0) 0.804 us | find_get_page();
2990 0) 1.329 us | }
2991 0) 3.904 us | }
2992 0) 4.979 us | }
2993 0) 0.653 us | _spin_lock();
2994 0) 0.578 us | page_add_file_rmap();
2995 0) 0.525 us | native_set_pte_at();
2996 0) 0.585 us | _spin_unlock();
2998 0) 0.541 us | page_waitqueue();
2999 0) 0.639 us | __wake_up_bit();
3000 0) 2.786 us | }
3001 0) + 14.237 us | }
3005 0) 0.698 us | find_get_page();
3007 0) 1.412 us | }
3008 0) 3.950 us | }
3009 0) 5.098 us | }
3010 0) 0.631 us | _spin_lock();
3011 0) 0.571 us | page_add_file_rmap();
3012 0) 0.526 us | native_set_pte_at();
3013 0) 0.586 us | _spin_unlock();
3015 0) 0.533 us | page_waitqueue();
3016 0) 0.638 us | __wake_up_bit();
3017 0) 2.793 us | }
3018 0) + 14.012 us | }
3032 --------------
3056 ---------------
3065 - mod:
3097 - traceon/traceoff:
3121 - snapshot:
3137 - enable_event/disable_event:
3161 - dump:
3168 - cpudump:
3174 - stacktrace:
3178 ----------
3195 # entries-in-buffer/entries-written: 0/0 #P:4
3197 # _-----=> irqs-off
3198 # / _----=> need-resched
3199 # | / _---=> hardirq/softirq
3200 # || / _--=> preempt-depth
3202 # TASK-PID CPU# |||| TIMESTAMP FUNCTION
3207 bash-1994 [000] .... 5281.568961: mutex_unlock <-rb_simple_write
3208 bash-1994 [000] .... 5281.568963: __mutex_unlock_slowpath <-mutex_unlock
3209 bash-1994 [000] .... 5281.568963: __fsnotify_parent <-fsnotify_modify
3210 bash-1994 [000] .... 5281.568964: fsnotify <-fsnotify_modify
3211 bash-1994 [000] .... 5281.568964: __srcu_read_lock <-fsnotify
3212 bash-1994 [000] .... 5281.568964: add_preempt_count <-__srcu_read_lock
3213 bash-1994 [000] ...1 5281.568965: sub_preempt_count <-__srcu_read_lock
3214 bash-1994 [000] .... 5281.568965: __srcu_read_unlock <-fsnotify
3215 bash-1994 [000] .... 5281.568967: sys_dup2 <-system_call_fastpath
3225 -------------
3252 much, it can cause Out-Of-Memory to trigger.
3256 -bash: echo: write error: Cannot allocate memory
3283 --------
3285 available to all non latency tracers. (Latency tracers which
3286 record max latency, such as "irqsoff" or "wakeup", can't use
3311 +--------------+------------+------------+------------+
3315 +--------------+------------+------------+------------+
3317 +--------------+------------+------------+------------+
3327 # entries-in-buffer/entries-written: 71/71 #P:8
3329 # _-----=> irqs-off
3330 # / _----=> need-resched
3331 # | / _---=> hardirq/softirq
3332 # || / _--=> preempt-depth
3334 # TASK-PID CPU# |||| TIMESTAMP FUNCTION
3336 …<idle>-0 [005] d... 2440.603828: sched_switch: prev_comm=swapper/5 prev_pid=0 prev_prio=120 …
3337 …sleep-2242 [005] d... 2440.603846: sched_switch: prev_comm=snapshot-test-2 prev_pid=2242 prev_pr…
3339 …<idle>-0 [002] d... 2440.707230: sched_switch: prev_comm=swapper/2 prev_pid=0 prev_prio=120 p…
3344 # entries-in-buffer/entries-written: 77/77 #P:8
3346 # _-----=> irqs-off
3347 # / _----=> need-resched
3348 # | / _---=> hardirq/softirq
3349 # || / _--=> preempt-depth
3351 # TASK-PID CPU# |||| TIMESTAMP FUNCTION
3353 …<idle>-0 [007] d... 2440.707395: sched_switch: prev_comm=swapper/7 prev_pid=0 prev_prio=120 p…
3354 …snapshot-test-2-2229 [002] d... 2440.707438: sched_switch: prev_comm=snapshot-test-2 prev_pid=22…
3359 one of the latency tracers, you will get the following results.
3370 ---------
3416 bash-2044 [002] .... 10594.481032: _raw_spin_lock_irqsave <-get_page_from_freelist
3417 bash-2044 [002] d... 10594.481032: add_preempt_count <-_raw_spin_lock_irqsave
3418 bash-2044 [002] d..1 10594.481032: __rmqueue <-get_page_from_freelist
3419 bash-2044 [002] d..1 10594.481033: _raw_spin_unlock <-get_page_from_freelist
3420 bash-2044 [002] d..1 10594.481033: sub_preempt_count <-_raw_spin_unlock
3421 … bash-2044 [002] d... 10594.481033: get_pageblock_flags_group <-get_pageblock_migratetype
3422 bash-2044 [002] d... 10594.481034: __mod_zone_page_state <-get_page_from_freelist
3423 bash-2044 [002] d... 10594.481034: zone_statistics <-get_page_from_freelist
3424 bash-2044 [002] d... 10594.481034: __inc_zone_state <-zone_statistics
3425 bash-2044 [002] d... 10594.481034: __inc_zone_state <-zone_statistics
3426 bash-2044 [002] .... 10594.481035: arch_dup_task_struct <-copy_process
3430 …bash-1998 [000] d..4 136.676759: sched_wakeup: comm=kworker/0:1 pid=59 prio=120 success=1 targe…
3431 …bash-1998 [000] dN.4 136.676760: sched_wakeup: comm=bash pid=1998 prio=120 success=1 target_cpu…
3432 …<idle>-0 [003] d.h3 136.676906: sched_wakeup: comm=rcu_preempt pid=9 prio=120 success=1 targ…
3433 …<idle>-0 [003] d..3 136.676909: sched_switch: prev_comm=swapper/3 prev_pid=0 prev_prio=120 p…
3434 …rcu_preempt-9 [003] d..3 136.676916: sched_switch: prev_comm=rcu_preempt prev_pid=9 prev_pri…
3435 …bash-1998 [000] d..4 136.677014: sched_wakeup: comm=kworker/0:1 pid=59 prio=120 success=1 targe…
3436 …bash-1998 [000] dN.4 136.677016: sched_wakeup: comm=bash pid=1998 prio=120 success=1 target_cpu…
3437 …bash-1998 [000] d..3 136.677018: sched_switch: prev_comm=bash prev_pid=1998 prev_prio=120 prev_…
3438 …kworker/0:1-59 [000] d..4 136.677022: sched_wakeup: comm=sshd pid=1995 prio=120 success=1 tar…
3439 …kworker/0:1-59 [000] d..3 136.677025: sched_switch: prev_comm=kworker/0:1 prev_pid=59 prev_pr…
3443 migration/1-14 [001] d.h3 138.732674: softirq_raise: vec=3 [action=NET_RX]
3444 <idle>-0 [001] dNh3 138.732725: softirq_raise: vec=3 [action=NET_RX]
3445 bash-1998 [000] d.h1 138.733101: softirq_raise: vec=1 [action=TIMER]
3446 bash-1998 [000] d.h1 138.733102: softirq_raise: vec=9 [action=RCU]
3447 bash-1998 [000] ..s2 138.733105: softirq_entry: vec=1 [action=TIMER]
3448 bash-1998 [000] ..s2 138.733106: softirq_exit: vec=1 [action=TIMER]
3449 bash-1998 [000] ..s2 138.733106: softirq_entry: vec=9 [action=RCU]
3450 bash-1998 [000] ..s2 138.733109: softirq_exit: vec=9 [action=RCU]
3451 sshd-1995 [001] d.h1 138.733278: irq_handler_entry: irq=21 name=uhci_hcd:usb4
3452 sshd-1995 [001] d.h1 138.733280: irq_handler_exit: irq=21 ret=unhandled
3453 sshd-1995 [001] d.h1 138.733281: irq_handler_entry: irq=21 name=eth0
3454 sshd-1995 [001] d.h1 138.733283: irq_handler_exit: irq=21 ret=handled
3460 # entries-in-buffer/entries-written: 18996/18996 #P:4
3462 # _-----=> irqs-off
3463 # / _----=> need-resched
3464 # | / _---=> hardirq/softirq
3465 # || / _--=> preempt-depth
3467 # TASK-PID CPU# |||| TIMESTAMP FUNCTION
3469 bash-1998 [000] d... 140.733501: sys_write -> 0x2
3470 bash-1998 [000] d... 140.733504: sys_dup2(oldfd: a, newfd: 1)
3471 bash-1998 [000] d... 140.733506: sys_dup2 -> 0x1
3472 bash-1998 [000] d... 140.733508: sys_fcntl(fd: a, cmd: 1, arg: 0)
3473 bash-1998 [000] d... 140.733509: sys_fcntl -> 0x1
3474 bash-1998 [000] d... 140.733510: sys_close(fd: a)
3475 bash-1998 [000] d... 140.733510: sys_close -> 0x0
3476 …bash-1998 [000] d... 140.733514: sys_rt_sigprocmask(how: 0, nset: 0, oset: 6e2768, sigsetsize: …
3477 bash-1998 [000] d... 140.733515: sys_rt_sigprocmask -> 0x0
3478 …bash-1998 [000] d... 140.733516: sys_rt_sigaction(sig: 2, act: 7fff718846f0, oact: 7fff71884650…
3479 bash-1998 [000] d... 140.733516: sys_rt_sigaction -> 0x0
3497 -----------
3528 ----- ---- --------
3548 Note, if -mfentry is being used by gcc, functions get traced before
3550 are not tested by the stack tracer when -mfentry is used.
3552 Currently, -mfentry is used by gcc 4.6.0 and above on x86 only.
3555 ----