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
349 the "ip modify" attribute (thus the regs->ip can be changed),
409 If the option "record-cmd" is set to "0", then comms of tasks
420 If the option "record-tgid" is set, on each scheduling context switch
422 the thread to its TGID. By default, the "record-tgid" option is
461 [local] global counter x86-tsc
488 x86-tsc:
492 ppc-tb:
515 Also on 32-bit systems, it's possible that the 64-bit boot offset
623 delta: Default timestamp mode - timestamp is a delta against
624 a per-buffer timestamp.
632 Directory for the Hardware Latency Detector.
633 See "Hardware Latency Detector" section below.
698 event (ring buffer is re-entrant), that it fills the
717 -----------
728 function tracer probes the functions on their entry
729 whereas the function graph tracer traces on both entry
741 The Hardware Latency tracer is used to detect if the hardware
742 produces any latency. See "Hardware Latency Detector" section
748 the trace with the longest max latency.
751 trace with the latency-format option enabled, which
767 Traces and records the max latency that it takes for
774 Traces and records the max latency that it takes for just
780 Traces and records the max latency that it takes for
805 ----------------
837 ----------------------------
841 user-land utilities).
844 --------------
850 # entries-in-buffer/entries-written: 140080/250280 #P:4
852 # _-----=> irqs-off
853 # / _----=> need-resched
854 # | / _---=> hardirq/softirq
855 # || / _--=> preempt-depth
857 # TASK-PID CPU# |||| TIMESTAMP FUNCTION
859 bash-1977 [000] .... 17284.993652: sys_close <-system_call_fastpath
860 bash-1977 [000] .... 17284.993653: __close_fd <-sys_close
861 bash-1977 [000] .... 17284.993653: _raw_spin_lock <-__close_fd
862 sshd-1974 [003] .... 17284.993653: __srcu_read_unlock <-fsnotify
863 bash-1977 [000] .... 17284.993654: add_preempt_count <-_raw_spin_lock
864 bash-1977 [000] ...1 17284.993655: _raw_spin_unlock <-__close_fd
865 bash-1977 [000] ...1 17284.993656: sub_preempt_count <-_raw_spin_unlock
866 bash-1977 [000] .... 17284.993657: filp_close <-__close_fd
867 bash-1977 [000] .... 17284.993657: dnotify_flush <-filp_close
868 sshd-1974 [003] .... 17284.993658: sys_select <-system_call_fastpath
875 lost due to the buffer filling up (250280 - 140080 = 110200 events
879 PID "1977", the CPU that it was running on "000", the latency format
885 Latency trace format
886 --------------------
888 When the latency-format option is enabled or when one of the latency
890 why a latency happened. Here is a typical trace::
894 # irqsoff latency trace v1.1.5 on 3.8.0-test+
895 # --------------------------------------------------------------------
896 # latency: 259 us, #4/4, CPU#2 | (M:preempt VP:0, KP:0, SP:0 HP:0 #P:4)
897 # -----------------
898 # | task: ps-6143 (uid:0 nice:0 policy:0 rt_prio:0)
899 # -----------------
904 # _------=> CPU#
905 # / _-----=> irqs-off
906 # | / _----=> need-resched
907 # || / _---=> hardirq/softirq
908 # ||| / _--=> preempt-depth
912 ps-6143 2d... 0us!: trace_hardirqs_off <-__lock_task_sighand
913 ps-6143 2d..1 259us+: trace_hardirqs_on <-_raw_spin_unlock_irqrestore
914 ps-6143 2d..1 263us+: time_hardirqs_on <-_raw_spin_unlock_irqrestore
915 ps-6143 2d..1 306us : <stack trace>
931 (3.8). Then it displays the max latency in microseconds (259 us). The number
936 The task is the process that was running when the latency
942 - __lock_task_sighand is where the interrupts were disabled.
943 - _raw_spin_unlock_irqrestore is where they were enabled again.
954 irqs-off: 'd' interrupts are disabled. '.' otherwise.
959 need-resched:
960 - 'N' both TIF_NEED_RESCHED and PREEMPT_NEED_RESCHED is set,
961 - 'n' only TIF_NEED_RESCHED is set,
962 - 'p' only PREEMPT_NEED_RESCHED is set,
963 - '.' otherwise.
966 - 'Z' - NMI occurred inside a hardirq
967 - 'z' - NMI is running
968 - 'H' - hard irq occurred inside a softirq.
969 - 'h' - hard irq is running
970 - 's' - soft irq is running
971 - '.' - normal context.
973 preempt-depth: The level of preempt_disabled
978 When the latency-format option is enabled, the trace file
980 trace. This differs from the output when latency-format
989 - '$' - greater than 1 second
990 - '@' - greater than 100 millisecond
991 - '*' - greater than 10 millisecond
992 - '#' - greater than 1000 microsecond
993 - '!' - greater than 100 microsecond
994 - '+' - greater than 10 microsecond
995 - ' ' - less than or equal to 10 microsecond.
999 Note, the latency tracers will usually end with a back trace
1000 to easily find where the latency occurred.
1003 -------------
1010 print-parent
1011 nosym-offset
1012 nosym-addr
1021 nosym-userobj
1022 noprintk-msg-only
1023 context-info
1024 nolatency-format
1025 record-cmd
1026 norecord-tgid
1029 irq-info
1031 noevent-fork
1032 function-trace
1033 nofunction-fork
1034 nodisplay-graph
1041 echo noprint-parent > trace_options
1045 echo sym-offset > trace_options
1049 print-parent
1054 print-parent:
1055 bash-4000 [01] 1477.606694: simple_strtoul <-kstrtoul
1057 noprint-parent:
1058 bash-4000 [01] 1477.606694: simple_strtoul
1061 sym-offset
1068 sym-offset:
1069 bash-4000 [01] 1477.606694: simple_strtoul+0x6/0xa0
1071 sym-addr
1076 sym-addr:
1077 bash-4000 [01] 1477.606694: simple_strtoul <c0339346>
1081 latency-format option is enabled.
1114 <idle>-0 [001] dNs4 21169.031481: wake_up_idle_cpu <-add_timer_on
1115 <idle>-0 [001] dNs4 21169.031482: _raw_spin_unlock_irqrestore <-add_timer_on
1116 <idle>-0 [001] .Ns4 21169.031484: sub_preempt_count <-_raw_spin_unlock_irqrestore
1118 <idle>-0 [002] .N.1 21169.031484: rcu_idle_exit <-cpu_idle
1119 <idle>-0 [001] .Ns3 21169.031484: _raw_spin_unlock <-clocksource_watchdog
1120 <idle>-0 [001] .Ns3 21169.031485: sub_preempt_count <-_raw_spin_unlock
1127 sym-userobj
1138 a.out-1623 [000] 40874.465068: /root/a.out[+0x480] <-/root/a.out[+0
1139 x494] <- /root/a.out[+0x4a8] <- /lib/libc-2.7.so[+0x1e1a6]
1142 printk-msg-only
1147 context-info
1151 latency-format
1154 latency, as described in "Latency trace format".
1156 pause-on-trace
1162 hash-ptr
1168 record-cmd
1176 record-tgid
1193 irq-info
1199 # entries-in-buffer/entries-written: 144405/9452052 #P:4
1201 # TASK-PID CPU# TIMESTAMP FUNCTION
1203 <idle>-0 [002] 23636.756054: ttwu_do_activate.constprop.89 <-try_to_wake_up
1204 <idle>-0 [002] 23636.756054: activate_task <-ttwu_do_activate.constprop.89
1205 <idle>-0 [002] 23636.756055: enqueue_task <-activate_task
1213 event-fork
1221 function-trace
1222 The latency tracers will enable function tracing
1224 it is disabled, the latency tracers do not trace
1226 when performing latency tests.
1228 function-fork
1237 display-graph
1238 When set, the latency tracers (irqsoff, wakeup, etc) will
1273 funcgraph-overrun
1284 funcgraph-cpu
1288 funcgraph-overhead
1294 funcgraph-proc
1301 funcgraph-duration
1306 funcgraph-abstime
1309 funcgraph-irqs
1313 funcgraph-tail
1319 sleep-time
1325 graph-time
1339 -------
1344 the kernel know of a new mouse event. The result is a latency
1348 disabled. When a new maximum latency is hit, the tracer saves
1349 the trace leading up to that latency point so that every time a
1356 # echo 0 > options/function-trace
1360 # ls -ltr
1366 # irqsoff latency trace v1.1.5 on 3.8.0-test+
1367 # --------------------------------------------------------------------
1368 # latency: 16 us, #4/4, CPU#0 | (M:preempt VP:0, KP:0, SP:0 HP:0 #P:4)
1369 # -----------------
1370 # | task: swapper/0-0 (uid:0 nice:0 policy:0 rt_prio:0)
1371 # -----------------
1376 # _------=> CPU#
1377 # / _-----=> irqs-off
1378 # | / _----=> need-resched
1379 # || / _---=> hardirq/softirq
1380 # ||| / _--=> preempt-depth
1384 <idle>-0 0d.s2 0us+: _raw_spin_lock_irq <-run_timer_softirq
1385 <idle>-0 0dNs3 17us : _raw_spin_unlock_irq <-run_timer_softirq
1386 <idle>-0 0dNs3 17us+: trace_hardirqs_on <-run_timer_softirq
1387 <idle>-0 0dNs3 25us : <stack trace>
1403 Here we see that we had a latency of 16 microseconds (which is
1406 timestamp 25us occurred because the clock was incremented
1407 between the time of recording the max latency and the time of
1408 recording the function that had that latency.
1410 Note the above example had function-trace not set. If we set
1411 function-trace, we get a much larger output::
1413 with echo 1 > options/function-trace
1417 # irqsoff latency trace v1.1.5 on 3.8.0-test+
1418 # --------------------------------------------------------------------
1419 # latency: 71 us, #168/168, CPU#3 | (M:preempt VP:0, KP:0, SP:0 HP:0 #P:4)
1420 # -----------------
1421 # | task: bash-2042 (uid:0 nice:0 policy:0 rt_prio:0)
1422 # -----------------
1427 # _------=> CPU#
1428 # / _-----=> irqs-off
1429 # | / _----=> need-resched
1430 # || / _---=> hardirq/softirq
1431 # ||| / _--=> preempt-depth
1435 bash-2042 3d... 0us : _raw_spin_lock_irqsave <-ata_scsi_queuecmd
1436 bash-2042 3d... 0us : add_preempt_count <-_raw_spin_lock_irqsave
1437 bash-2042 3d..1 1us : ata_scsi_find_dev <-ata_scsi_queuecmd
1438 bash-2042 3d..1 1us : __ata_scsi_find_dev <-ata_scsi_find_dev
1439 bash-2042 3d..1 2us : ata_find_dev.part.14 <-__ata_scsi_find_dev
1440 bash-2042 3d..1 2us : ata_qc_new_init <-__ata_scsi_queuecmd
1441 bash-2042 3d..1 3us : ata_sg_init <-__ata_scsi_queuecmd
1442 bash-2042 3d..1 4us : ata_scsi_rw_xlat <-__ata_scsi_queuecmd
1443 bash-2042 3d..1 4us : ata_build_rw_tf <-ata_scsi_rw_xlat
1445 bash-2042 3d..1 67us : delay_tsc <-__delay
1446 bash-2042 3d..1 67us : add_preempt_count <-delay_tsc
1447 bash-2042 3d..2 67us : sub_preempt_count <-delay_tsc
1448 bash-2042 3d..1 67us : add_preempt_count <-delay_tsc
1449 bash-2042 3d..2 68us : sub_preempt_count <-delay_tsc
1450 bash-2042 3d..1 68us+: ata_bmdma_start <-ata_bmdma_qc_issue
1451 bash-2042 3d..1 71us : _raw_spin_unlock_irqrestore <-ata_scsi_queuecmd
1452 bash-2042 3d..1 71us : _raw_spin_unlock_irqrestore <-ata_scsi_queuecmd
1453 bash-2042 3d..1 72us+: trace_hardirqs_on <-ata_scsi_queuecmd
1454 bash-2042 3d..1 120us : <stack trace>
1482 Here we traced a 71 microsecond latency. But we also see all the
1485 overhead may extend the latency times. But nevertheless, this
1489 display-graph option::
1491 with echo 1 > options/display-graph
1495 # irqsoff latency trace v1.1.5 on 4.20.0-rc6+
1496 # --------------------------------------------------------------------
1497 # latency: 3751 us, #274/274, CPU#0 | (M:desktop VP:0, KP:0, SP:0 HP:0 #P:4)
1498 # -----------------
1499 # | task: bash-1507 (uid:0 nice:0 policy:0 rt_prio:0)
1500 # -----------------
1505 # _-----=> irqs-off
1506 # / _----=> need-resched
1507 # | / _---=> hardirq/softirq
1508 # || / _--=> preempt-depth
1512 0 us | 0) bash-1507 | d... | 0.000 us | _raw_spin_lock_irqsave();
1513 0 us | 0) bash-1507 | d..1 | 0.378 us | do_raw_spin_trylock();
1514 1 us | 0) bash-1507 | d..2 | | set_track() {
1515 2 us | 0) bash-1507 | d..2 | | save_stack_trace() {
1516 2 us | 0) bash-1507 | d..2 | | __save_stack_trace() {
1517 3 us | 0) bash-1507 | d..2 | | __unwind_start() {
1518 3 us | 0) bash-1507 | d..2 | | get_stack_info() {
1519 3 us | 0) bash-1507 | d..2 | 0.351 us | in_task_stack();
1520 4 us | 0) bash-1507 | d..2 | 1.107 us | }
1522 3750 us | 0) bash-1507 | d..1 | 0.516 us | do_raw_spin_unlock();
1523 3750 us | 0) bash-1507 | d..1 | 0.000 us | _raw_spin_unlock_irqrestore();
1524 3764 us | 0) bash-1507 | d..1 | 0.000 us | tracer_hardirqs_on();
1525 bash-1507 0d..1 3792us : <stack trace>
1542 ----------
1550 Like the irqsoff tracer, it records the maximum latency for
1555 # echo 0 > options/function-trace
1559 # ls -ltr
1565 # preemptoff latency trace v1.1.5 on 3.8.0-test+
1566 # --------------------------------------------------------------------
1567 # latency: 46 us, #4/4, CPU#1 | (M:preempt VP:0, KP:0, SP:0 HP:0 #P:4)
1568 # -----------------
1569 # | task: sshd-1991 (uid:0 nice:0 policy:0 rt_prio:0)
1570 # -----------------
1575 # _------=> CPU#
1576 # / _-----=> irqs-off
1577 # | / _----=> need-resched
1578 # || / _---=> hardirq/softirq
1579 # ||| / _--=> preempt-depth
1583 sshd-1991 1d.h. 0us+: irq_enter <-do_IRQ
1584 sshd-1991 1d..1 46us : irq_exit <-do_IRQ
1585 sshd-1991 1d..1 47us+: trace_preempt_on <-do_IRQ
1586 sshd-1991 1d..1 52us : <stack trace>
1603 # preemptoff latency trace v1.1.5 on 3.8.0-test+
1604 # --------------------------------------------------------------------
1605 # latency: 83 us, #241/241, CPU#1 | (M:preempt VP:0, KP:0, SP:0 HP:0 #P:4)
1606 # -----------------
1607 # | task: bash-1994 (uid:0 nice:0 policy:0 rt_prio:0)
1608 # -----------------
1613 # _------=> CPU#
1614 # / _-----=> irqs-off
1615 # | / _----=> need-resched
1616 # || / _---=> hardirq/softirq
1617 # ||| / _--=> preempt-depth
1621 bash-1994 1d..1 0us : _raw_spin_lock_irqsave <-wake_up_new_task
1622 bash-1994 1d..1 0us : select_task_rq_fair <-select_task_rq
1623 bash-1994 1d..1 1us : __rcu_read_lock <-select_task_rq_fair
1624 bash-1994 1d..1 1us : source_load <-select_task_rq_fair
1625 bash-1994 1d..1 1us : source_load <-select_task_rq_fair
1627 bash-1994 1d..1 12us : irq_enter <-smp_apic_timer_interrupt
1628 bash-1994 1d..1 12us : rcu_irq_enter <-irq_enter
1629 bash-1994 1d..1 13us : add_preempt_count <-irq_enter
1630 bash-1994 1d.h1 13us : exit_idle <-smp_apic_timer_interrupt
1631 bash-1994 1d.h1 13us : hrtimer_interrupt <-smp_apic_timer_interrupt
1632 bash-1994 1d.h1 13us : _raw_spin_lock <-hrtimer_interrupt
1633 bash-1994 1d.h1 14us : add_preempt_count <-_raw_spin_lock
1634 bash-1994 1d.h2 14us : ktime_get_update_offsets <-hrtimer_interrupt
1636 bash-1994 1d.h1 35us : lapic_next_event <-clockevents_program_event
1637 bash-1994 1d.h1 35us : irq_exit <-smp_apic_timer_interrupt
1638 bash-1994 1d.h1 36us : sub_preempt_count <-irq_exit
1639 bash-1994 1d..2 36us : do_softirq <-irq_exit
1640 bash-1994 1d..2 36us : __do_softirq <-call_softirq
1641 bash-1994 1d..2 36us : __local_bh_disable <-__do_softirq
1642 bash-1994 1d.s2 37us : add_preempt_count <-_raw_spin_lock_irq
1643 bash-1994 1d.s3 38us : _raw_spin_unlock <-run_timer_softirq
1644 bash-1994 1d.s3 39us : sub_preempt_count <-_raw_spin_unlock
1645 bash-1994 1d.s2 39us : call_timer_fn <-run_timer_softirq
1647 bash-1994 1dNs2 81us : cpu_needs_another_gp <-rcu_process_callbacks
1648 bash-1994 1dNs2 82us : __local_bh_enable <-__do_softirq
1649 bash-1994 1dNs2 82us : sub_preempt_count <-__local_bh_enable
1650 bash-1994 1dN.2 82us : idle_cpu <-irq_exit
1651 bash-1994 1dN.2 83us : rcu_irq_exit <-irq_exit
1652 bash-1994 1dN.2 83us : sub_preempt_count <-irq_exit
1653 bash-1994 1.N.1 84us : _raw_spin_unlock_irqrestore <-task_rq_unlock
1654 bash-1994 1.N.1 84us+: trace_preempt_on <-task_rq_unlock
1655 bash-1994 1.N.1 104us : <stack trace>
1666 function-trace set. Here we see that interrupts were not disabled
1667 the entire time. The irq_enter code lets us know that we entered
1673 --------------
1707 # echo 0 > options/function-trace
1711 # ls -ltr
1717 # preemptirqsoff latency trace v1.1.5 on 3.8.0-test+
1718 # --------------------------------------------------------------------
1719 # latency: 100 us, #4/4, CPU#3 | (M:preempt VP:0, KP:0, SP:0 HP:0 #P:4)
1720 # -----------------
1721 # | task: ls-2230 (uid:0 nice:0 policy:0 rt_prio:0)
1722 # -----------------
1727 # _------=> CPU#
1728 # / _-----=> irqs-off
1729 # | / _----=> need-resched
1730 # || / _---=> hardirq/softirq
1731 # ||| / _--=> preempt-depth
1735 ls-2230 3d... 0us+: _raw_spin_lock_irqsave <-ata_scsi_queuecmd
1736 ls-2230 3...1 100us : _raw_spin_unlock_irqrestore <-ata_scsi_queuecmd
1737 ls-2230 3...1 101us+: trace_preempt_on <-ata_scsi_queuecmd
1738 ls-2230 3...1 111us : <stack trace>
1766 Here is a trace with function-trace set::
1770 # preemptirqsoff latency trace v1.1.5 on 3.8.0-test+
1771 # --------------------------------------------------------------------
1772 # latency: 161 us, #339/339, CPU#3 | (M:preempt VP:0, KP:0, SP:0 HP:0 #P:4)
1773 # -----------------
1774 # | task: ls-2269 (uid:0 nice:0 policy:0 rt_prio:0)
1775 # -----------------
1780 # _------=> CPU#
1781 # / _-----=> irqs-off
1782 # | / _----=> need-resched
1783 # || / _---=> hardirq/softirq
1784 # ||| / _--=> preempt-depth
1788 kworker/-59 3...1 0us : __schedule <-schedule
1789 kworker/-59 3d..1 0us : rcu_preempt_qs <-rcu_note_context_switch
1790 kworker/-59 3d..1 1us : add_preempt_count <-_raw_spin_lock_irq
1791 kworker/-59 3d..2 1us : deactivate_task <-__schedule
1792 kworker/-59 3d..2 1us : dequeue_task <-deactivate_task
1793 kworker/-59 3d..2 2us : update_rq_clock <-dequeue_task
1794 kworker/-59 3d..2 2us : dequeue_task_fair <-dequeue_task
1795 kworker/-59 3d..2 2us : update_curr <-dequeue_task_fair
1796 kworker/-59 3d..2 2us : update_min_vruntime <-update_curr
1797 kworker/-59 3d..2 3us : cpuacct_charge <-update_curr
1798 kworker/-59 3d..2 3us : __rcu_read_lock <-cpuacct_charge
1799 kworker/-59 3d..2 3us : __rcu_read_unlock <-cpuacct_charge
1800 kworker/-59 3d..2 3us : update_cfs_rq_blocked_load <-dequeue_task_fair
1801 kworker/-59 3d..2 4us : clear_buddies <-dequeue_task_fair
1802 kworker/-59 3d..2 4us : account_entity_dequeue <-dequeue_task_fair
1803 kworker/-59 3d..2 4us : update_min_vruntime <-dequeue_task_fair
1804 kworker/-59 3d..2 4us : update_cfs_shares <-dequeue_task_fair
1805 kworker/-59 3d..2 5us : hrtick_update <-dequeue_task_fair
1806 kworker/-59 3d..2 5us : wq_worker_sleeping <-__schedule
1807 kworker/-59 3d..2 5us : kthread_data <-wq_worker_sleeping
1808 kworker/-59 3d..2 5us : put_prev_task_fair <-__schedule
1809 kworker/-59 3d..2 6us : pick_next_task_fair <-pick_next_task
1810 kworker/-59 3d..2 6us : clear_buddies <-pick_next_task_fair
1811 kworker/-59 3d..2 6us : set_next_entity <-pick_next_task_fair
1812 kworker/-59 3d..2 6us : update_stats_wait_end <-set_next_entity
1813 ls-2269 3d..2 7us : finish_task_switch <-__schedule
1814 ls-2269 3d..2 7us : _raw_spin_unlock_irq <-finish_task_switch
1815 ls-2269 3d..2 8us : do_IRQ <-ret_from_intr
1816 ls-2269 3d..2 8us : irq_enter <-do_IRQ
1817 ls-2269 3d..2 8us : rcu_irq_enter <-irq_enter
1818 ls-2269 3d..2 9us : add_preempt_count <-irq_enter
1819 ls-2269 3d.h2 9us : exit_idle <-do_IRQ
1821 ls-2269 3d.h3 20us : sub_preempt_count <-_raw_spin_unlock
1822 ls-2269 3d.h2 20us : irq_exit <-do_IRQ
1823 ls-2269 3d.h2 21us : sub_preempt_count <-irq_exit
1824 ls-2269 3d..3 21us : do_softirq <-irq_exit
1825 ls-2269 3d..3 21us : __do_softirq <-call_softirq
1826 ls-2269 3d..3 21us+: __local_bh_disable <-__do_softirq
1827 ls-2269 3d.s4 29us : sub_preempt_count <-_local_bh_enable_ip
1828 ls-2269 3d.s5 29us : sub_preempt_count <-_local_bh_enable_ip
1829 ls-2269 3d.s5 31us : do_IRQ <-ret_from_intr
1830 ls-2269 3d.s5 31us : irq_enter <-do_IRQ
1831 ls-2269 3d.s5 31us : rcu_irq_enter <-irq_enter
1833 ls-2269 3d.s5 31us : rcu_irq_enter <-irq_enter
1834 ls-2269 3d.s5 32us : add_preempt_count <-irq_enter
1835 ls-2269 3d.H5 32us : exit_idle <-do_IRQ
1836 ls-2269 3d.H5 32us : handle_irq <-do_IRQ
1837 ls-2269 3d.H5 32us : irq_to_desc <-handle_irq
1838 ls-2269 3d.H5 33us : handle_fasteoi_irq <-handle_irq
1840 ls-2269 3d.s5 158us : _raw_spin_unlock_irqrestore <-rtl8139_poll
1841 ls-2269 3d.s3 158us : net_rps_action_and_irq_enable.isra.65 <-net_rx_action
1842 ls-2269 3d.s3 159us : __local_bh_enable <-__do_softirq
1843 ls-2269 3d.s3 159us : sub_preempt_count <-__local_bh_enable
1844 ls-2269 3d..3 159us : idle_cpu <-irq_exit
1845 ls-2269 3d..3 159us : rcu_irq_exit <-irq_exit
1846 ls-2269 3d..3 160us : sub_preempt_count <-irq_exit
1847 ls-2269 3d... 161us : __mutex_unlock_slowpath <-mutex_unlock
1848 ls-2269 3d... 162us+: trace_hardirqs_on <-mutex_unlock
1849 ls-2269 3d... 186us : <stack trace>
1868 ------
1872 Now for non Real-Time tasks, this can be arbitrary. But tracing
1877 # echo 0 > options/function-trace
1881 # chrt -f 5 sleep 1
1886 # wakeup latency trace v1.1.5 on 3.8.0-test+
1887 # --------------------------------------------------------------------
1888 # latency: 15 us, #4/4, CPU#3 | (M:preempt VP:0, KP:0, SP:0 HP:0 #P:4)
1889 # -----------------
1890 # | task: kworker/3:1H-312 (uid:0 nice:-20 policy:0 rt_prio:0)
1891 # -----------------
1893 # _------=> CPU#
1894 # / _-----=> irqs-off
1895 # | / _----=> need-resched
1896 # || / _---=> hardirq/softirq
1897 # ||| / _--=> preempt-depth
1901 <idle>-0 3dNs7 0us : 0:120:R + [003] 312:100:R kworker/3:1H
1902 <idle>-0 3dNs7 1us+: ttwu_do_activate.constprop.87 <-try_to_wake_up
1903 <idle>-0 3d..3 15us : __schedule <-schedule
1904 <idle>-0 3d..3 15us : 0:120:R ==> [003] 312:100:R kworker/3:1H
1908 the kworker with a nice priority of -20 (not very nice), took
1912 Non Real-Time tasks are not that interesting. A more interesting
1913 trace is to concentrate only on Real-Time tasks.
1916 ---------
1918 In a Real-Time environment it is very important to know the
1921 latency". I stress the point that this is about RT tasks. It is
1922 also important to know the scheduling latency of non-RT tasks,
1923 but the average schedule latency is better for non-RT tasks.
1927 Real-Time environments are interested in the worst case latency.
1928 That is the longest latency it takes for something to happen,
1930 only have a large latency once in a while, but that would not
1931 work well with Real-Time tasks. The wakeup_rt tracer was designed
1932 to record the worst case wakeups of RT tasks. Non-RT tasks are
1934 tracing non-RT tasks that are unpredictable will overwrite the
1935 worst case latency of RT tasks (just run the normal wakeup
1944 # echo 0 > options/function-trace
1948 # chrt -f 5 sleep 1
1955 # wakeup_rt latency trace v1.1.5 on 3.8.0-test+
1956 # --------------------------------------------------------------------
1957 # latency: 5 us, #4/4, CPU#3 | (M:preempt VP:0, KP:0, SP:0 HP:0 #P:4)
1958 # -----------------
1959 # | task: sleep-2389 (uid:0 nice:0 policy:1 rt_prio:5)
1960 # -----------------
1962 # _------=> CPU#
1963 # / _-----=> irqs-off
1964 # | / _----=> need-resched
1965 # || / _---=> hardirq/softirq
1966 # ||| / _--=> preempt-depth
1970 <idle>-0 3d.h4 0us : 0:120:R + [003] 2389: 94:R sleep
1971 <idle>-0 3d.h4 1us+: ttwu_do_activate.constprop.87 <-try_to_wake_up
1972 <idle>-0 3d..3 5us : __schedule <-schedule
1973 <idle>-0 3d..3 5us : 0:120:R ==> [003] 2389: 94:R sleep
1983 and it has an rt_prio of 5. This priority is user-space priority
1987 Note, that the trace data shows the internal priority (99 - rtprio).
1990 <idle>-0 3d..3 5us : 0:120:R ==> [003] 2389: 94:R sleep
1992 The 0:120:R means idle was running with a nice priority of 0 (120 - 120)
1994 2389: 94:R. That is the priority is the kernel rtprio (99 - 5 = 94)
1997 Doing the same with chrt -r 5 and function-trace set.
2000 echo 1 > options/function-trace
2004 # wakeup_rt latency trace v1.1.5 on 3.8.0-test+
2005 # --------------------------------------------------------------------
2006 # latency: 29 us, #85/85, CPU#3 | (M:preempt VP:0, KP:0, SP:0 HP:0 #P:4)
2007 # -----------------
2008 # | task: sleep-2448 (uid:0 nice:0 policy:1 rt_prio:5)
2009 # -----------------
2011 # _------=> CPU#
2012 # / _-----=> irqs-off
2013 # | / _----=> need-resched
2014 # || / _---=> hardirq/softirq
2015 # ||| / _--=> preempt-depth
2019 <idle>-0 3d.h4 1us+: 0:120:R + [003] 2448: 94:R sleep
2020 <idle>-0 3d.h4 2us : ttwu_do_activate.constprop.87 <-try_to_wake_up
2021 <idle>-0 3d.h3 3us : check_preempt_curr <-ttwu_do_wakeup
2022 <idle>-0 3d.h3 3us : resched_curr <-check_preempt_curr
2023 <idle>-0 3dNh3 4us : task_woken_rt <-ttwu_do_wakeup
2024 <idle>-0 3dNh3 4us : _raw_spin_unlock <-try_to_wake_up
2025 <idle>-0 3dNh3 4us : sub_preempt_count <-_raw_spin_unlock
2026 <idle>-0 3dNh2 5us : ttwu_stat <-try_to_wake_up
2027 <idle>-0 3dNh2 5us : _raw_spin_unlock_irqrestore <-try_to_wake_up
2028 <idle>-0 3dNh2 6us : sub_preempt_count <-_raw_spin_unlock_irqrestore
2029 <idle>-0 3dNh1 6us : _raw_spin_lock <-__run_hrtimer
2030 <idle>-0 3dNh1 6us : add_preempt_count <-_raw_spin_lock
2031 <idle>-0 3dNh2 7us : _raw_spin_unlock <-hrtimer_interrupt
2032 <idle>-0 3dNh2 7us : sub_preempt_count <-_raw_spin_unlock
2033 <idle>-0 3dNh1 7us : tick_program_event <-hrtimer_interrupt
2034 <idle>-0 3dNh1 7us : clockevents_program_event <-tick_program_event
2035 <idle>-0 3dNh1 8us : ktime_get <-clockevents_program_event
2036 <idle>-0 3dNh1 8us : lapic_next_event <-clockevents_program_event
2037 <idle>-0 3dNh1 8us : irq_exit <-smp_apic_timer_interrupt
2038 <idle>-0 3dNh1 9us : sub_preempt_count <-irq_exit
2039 <idle>-0 3dN.2 9us : idle_cpu <-irq_exit
2040 <idle>-0 3dN.2 9us : rcu_irq_exit <-irq_exit
2041 <idle>-0 3dN.2 10us : rcu_eqs_enter_common.isra.45 <-rcu_irq_exit
2042 <idle>-0 3dN.2 10us : sub_preempt_count <-irq_exit
2043 <idle>-0 3.N.1 11us : rcu_idle_exit <-cpu_idle
2044 <idle>-0 3dN.1 11us : rcu_eqs_exit_common.isra.43 <-rcu_idle_exit
2045 <idle>-0 3.N.1 11us : tick_nohz_idle_exit <-cpu_idle
2046 <idle>-0 3dN.1 12us : menu_hrtimer_cancel <-tick_nohz_idle_exit
2047 <idle>-0 3dN.1 12us : ktime_get <-tick_nohz_idle_exit
2048 <idle>-0 3dN.1 12us : tick_do_update_jiffies64 <-tick_nohz_idle_exit
2049 <idle>-0 3dN.1 13us : cpu_load_update_nohz <-tick_nohz_idle_exit
2050 <idle>-0 3dN.1 13us : _raw_spin_lock <-cpu_load_update_nohz
2051 <idle>-0 3dN.1 13us : add_preempt_count <-_raw_spin_lock
2052 <idle>-0 3dN.2 13us : __cpu_load_update <-cpu_load_update_nohz
2053 <idle>-0 3dN.2 14us : sched_avg_update <-__cpu_load_update
2054 <idle>-0 3dN.2 14us : _raw_spin_unlock <-cpu_load_update_nohz
2055 <idle>-0 3dN.2 14us : sub_preempt_count <-_raw_spin_unlock
2056 <idle>-0 3dN.1 15us : calc_load_nohz_stop <-tick_nohz_idle_exit
2057 <idle>-0 3dN.1 15us : touch_softlockup_watchdog <-tick_nohz_idle_exit
2058 <idle>-0 3dN.1 15us : hrtimer_cancel <-tick_nohz_idle_exit
2059 <idle>-0 3dN.1 15us : hrtimer_try_to_cancel <-hrtimer_cancel
2060 <idle>-0 3dN.1 16us : lock_hrtimer_base.isra.18 <-hrtimer_try_to_cancel
2061 <idle>-0 3dN.1 16us : _raw_spin_lock_irqsave <-lock_hrtimer_base.isra.18
2062 <idle>-0 3dN.1 16us : add_preempt_count <-_raw_spin_lock_irqsave
2063 <idle>-0 3dN.2 17us : __remove_hrtimer <-remove_hrtimer.part.16
2064 <idle>-0 3dN.2 17us : hrtimer_force_reprogram <-__remove_hrtimer
2065 <idle>-0 3dN.2 17us : tick_program_event <-hrtimer_force_reprogram
2066 <idle>-0 3dN.2 18us : clockevents_program_event <-tick_program_event
2067 <idle>-0 3dN.2 18us : ktime_get <-clockevents_program_event
2068 <idle>-0 3dN.2 18us : lapic_next_event <-clockevents_program_event
2069 <idle>-0 3dN.2 19us : _raw_spin_unlock_irqrestore <-hrtimer_try_to_cancel
2070 <idle>-0 3dN.2 19us : sub_preempt_count <-_raw_spin_unlock_irqrestore
2071 <idle>-0 3dN.1 19us : hrtimer_forward <-tick_nohz_idle_exit
2072 <idle>-0 3dN.1 20us : ktime_add_safe <-hrtimer_forward
2073 <idle>-0 3dN.1 20us : ktime_add_safe <-hrtimer_forward
2074 <idle>-0 3dN.1 20us : hrtimer_start_range_ns <-hrtimer_start_expires.constprop.11
2075 <idle>-0 3dN.1 20us : __hrtimer_start_range_ns <-hrtimer_start_range_ns
2076 <idle>-0 3dN.1 21us : lock_hrtimer_base.isra.18 <-__hrtimer_start_range_ns
2077 <idle>-0 3dN.1 21us : _raw_spin_lock_irqsave <-lock_hrtimer_base.isra.18
2078 <idle>-0 3dN.1 21us : add_preempt_count <-_raw_spin_lock_irqsave
2079 <idle>-0 3dN.2 22us : ktime_add_safe <-__hrtimer_start_range_ns
2080 <idle>-0 3dN.2 22us : enqueue_hrtimer <-__hrtimer_start_range_ns
2081 <idle>-0 3dN.2 22us : tick_program_event <-__hrtimer_start_range_ns
2082 <idle>-0 3dN.2 23us : clockevents_program_event <-tick_program_event
2083 <idle>-0 3dN.2 23us : ktime_get <-clockevents_program_event
2084 <idle>-0 3dN.2 23us : lapic_next_event <-clockevents_program_event
2085 <idle>-0 3dN.2 24us : _raw_spin_unlock_irqrestore <-__hrtimer_start_range_ns
2086 <idle>-0 3dN.2 24us : sub_preempt_count <-_raw_spin_unlock_irqrestore
2087 <idle>-0 3dN.1 24us : account_idle_ticks <-tick_nohz_idle_exit
2088 <idle>-0 3dN.1 24us : account_idle_time <-account_idle_ticks
2089 <idle>-0 3.N.1 25us : sub_preempt_count <-cpu_idle
2090 <idle>-0 3.N.. 25us : schedule <-cpu_idle
2091 <idle>-0 3.N.. 25us : __schedule <-preempt_schedule
2092 <idle>-0 3.N.. 26us : add_preempt_count <-__schedule
2093 <idle>-0 3.N.1 26us : rcu_note_context_switch <-__schedule
2094 <idle>-0 3.N.1 26us : rcu_sched_qs <-rcu_note_context_switch
2095 <idle>-0 3dN.1 27us : rcu_preempt_qs <-rcu_note_context_switch
2096 <idle>-0 3.N.1 27us : _raw_spin_lock_irq <-__schedule
2097 <idle>-0 3dN.1 27us : add_preempt_count <-_raw_spin_lock_irq
2098 <idle>-0 3dN.2 28us : put_prev_task_idle <-__schedule
2099 <idle>-0 3dN.2 28us : pick_next_task_stop <-pick_next_task
2100 <idle>-0 3dN.2 28us : pick_next_task_rt <-pick_next_task
2101 <idle>-0 3dN.2 29us : dequeue_pushable_task <-pick_next_task_rt
2102 <idle>-0 3d..3 29us : __schedule <-preempt_schedule
2103 <idle>-0 3d..3 30us : 0:120:R ==> [003] 2448: 94:R sleep
2112 Latency tracing and events
2113 --------------------------
2114 As function tracing can induce a much larger latency, but without
2115 seeing what happens within the latency it is hard to know what
2120 # echo 0 > options/function-trace
2125 # chrt -f 5 sleep 1
2130 # wakeup_rt latency trace v1.1.5 on 3.8.0-test+
2131 # --------------------------------------------------------------------
2132 # latency: 6 us, #12/12, CPU#2 | (M:preempt VP:0, KP:0, SP:0 HP:0 #P:4)
2133 # -----------------
2134 # | task: sleep-5882 (uid:0 nice:0 policy:1 rt_prio:5)
2135 # -----------------
2137 # _------=> CPU#
2138 # / _-----=> irqs-off
2139 # | / _----=> need-resched
2140 # || / _---=> hardirq/softirq
2141 # ||| / _--=> preempt-depth
2145 <idle>-0 2d.h4 0us : 0:120:R + [002] 5882: 94:R sleep
2146 <idle>-0 2d.h4 0us : ttwu_do_activate.constprop.87 <-try_to_wake_up
2147 <idle>-0 2d.h4 1us : sched_wakeup: comm=sleep pid=5882 prio=94 success=1 target_cpu=002
2148 <idle>-0 2dNh2 1us : hrtimer_expire_exit: hrtimer=ffff88007796feb8
2149 <idle>-0 2.N.2 2us : power_end: cpu_id=2
2150 <idle>-0 2.N.2 3us : cpu_idle: state=4294967295 cpu_id=2
2151 <idle>-0 2dN.3 4us : hrtimer_cancel: hrtimer=ffff88007d50d5e0
2152 …<idle>-0 2dN.3 4us : hrtimer_start: hrtimer=ffff88007d50d5e0 function=tick_sched_timer ex…
2153 <idle>-0 2.N.2 5us : rcu_utilization: Start context switch
2154 <idle>-0 2.N.2 5us : rcu_utilization: End context switch
2155 <idle>-0 2d..3 6us : __schedule <-schedule
2156 <idle>-0 2d..3 6us : 0:120:R ==> [002] 5882: 94:R sleep
2159 Hardware Latency Detector
2160 -------------------------
2162 The hardware latency detector is executed by enabling the "hwlat" tracer.
2173 # entries-in-buffer/entries-written: 13/13 #P:8
2175 # _-----=> irqs-off
2176 # / _----=> need-resched
2177 # | / _---=> hardirq/softirq
2178 # || / _--=> preempt-depth
2180 # TASK-PID CPU# |||| TIMESTAMP FUNCTION
2182 …<...>-1729 [001] d... 678.473449: #1 inner/outer(us): 11/12 ts:1581527483.343962693 co…
2183 …<...>-1729 [004] d... 689.556542: #2 inner/outer(us): 16/9 ts:1581527494.889008092 co…
2184 …<...>-1729 [005] d... 714.756290: #3 inner/outer(us): 16/16 ts:1581527519.678961629 co…
2185 …<...>-1729 [001] d... 718.788247: #4 inner/outer(us): 9/17 ts:1581527523.889012713 co…
2186 …<...>-1729 [002] d... 719.796341: #5 inner/outer(us): 13/9 ts:1581527524.912872606 co…
2187 …<...>-1729 [006] d... 844.787091: #6 inner/outer(us): 9/12 ts:1581527649.889048502 co…
2188 …<...>-1729 [003] d... 849.827033: #7 inner/outer(us): 18/9 ts:1581527654.889013793 co…
2189 …<...>-1729 [007] d... 853.859002: #8 inner/outer(us): 9/12 ts:1581527658.889065736 co…
2190 …<...>-1729 [001] d... 855.874978: #9 inner/outer(us): 9/11 ts:1581527660.861991877 co…
2191 …<...>-1729 [001] d... 863.938932: #10 inner/outer(us): 9/11 ts:1581527668.970010500 co…
2192 …<...>-1729 [007] d... 878.050780: #11 inner/outer(us): 9/12 ts:1581527683.385002600 co…
2193 …<...>-1729 [007] d... 886.114702: #12 inner/outer(us): 9/12 ts:1581527691.385001600 co…
2203 inner/outer(us): 11/11
2205 This shows two numbers as "inner latency" and "outer latency". The test
2206 runs in a loop checking a timestamp twice. The latency detected within
2207 the two timestamps is the "inner latency" and the latency detected
2209 the "outer latency".
2213 The absolute timestamp that the first latency was recorded in the window.
2217 The number of times a latency was detected during the window.
2219 nmi-total:7 nmi-count:1
2222 test, the time spent in NMI is reported in "nmi-total" (in
2225 All architectures that have NMIs will show the "nmi-count" if an
2232 microseconds. This is the threshold of latency that
2256 --------
2272 # entries-in-buffer/entries-written: 24799/24799 #P:4
2274 # _-----=> irqs-off
2275 # / _----=> need-resched
2276 # | / _---=> hardirq/softirq
2277 # || / _--=> preempt-depth
2279 # TASK-PID CPU# |||| TIMESTAMP FUNCTION
2281 bash-1994 [002] .... 3082.063030: mutex_unlock <-rb_simple_write
2282 bash-1994 [002] .... 3082.063031: __mutex_unlock_slowpath <-mutex_unlock
2283 bash-1994 [002] .... 3082.063031: __fsnotify_parent <-fsnotify_modify
2284 bash-1994 [002] .... 3082.063032: fsnotify <-fsnotify_modify
2285 bash-1994 [002] .... 3082.063032: __srcu_read_lock <-fsnotify
2286 bash-1994 [002] .... 3082.063032: add_preempt_count <-__srcu_read_lock
2287 bash-1994 [002] ...1 3082.063032: sub_preempt_count <-__srcu_read_lock
2288 bash-1994 [002] .... 3082.063033: __srcu_read_unlock <-fsnotify
2316 ---------------------
2330 # TASK-PID CPU# TIMESTAMP FUNCTION
2332 yum-updatesd-3111 [003] 1637.254676: finish_task_switch <-thread_return
2333 yum-updatesd-3111 [003] 1637.254681: hrtimer_cancel <-schedule_hrtimeout_range
2334 yum-updatesd-3111 [003] 1637.254682: hrtimer_try_to_cancel <-hrtimer_cancel
2335 yum-updatesd-3111 [003] 1637.254683: lock_hrtimer_base <-hrtimer_try_to_cancel
2336 yum-updatesd-3111 [003] 1637.254685: fget_light <-do_sys_poll
2337 yum-updatesd-3111 [003] 1637.254686: pipe_poll <-do_sys_poll
2342 # TASK-PID CPU# TIMESTAMP FUNCTION
2345 yum-updatesd-3111 [003] 1701.957688: free_poll_entry <-poll_freewait
2346 yum-updatesd-3111 [003] 1701.957689: remove_wait_queue <-free_poll_entry
2347 yum-updatesd-3111 [003] 1701.957691: fput <-free_poll_entry
2348 yum-updatesd-3111 [003] 1701.957692: audit_syscall_exit <-sysret_audit
2349 yum-updatesd-3111 [003] 1701.957693: path_put <-audit_syscall_exit
2412 exit(-1);
2421 exit(-1);
2444 tracefs=`sed -ne 's/^tracefs \(.*\) tracefs.*/\1/p' /proc/mounts`
2454 ---------------------------
2457 probes a function on its entry and its exit. This is done by
2459 task_struct. On function entry the tracer overwrites the return
2467 - measure of a function's time execution
2468 - having a reliable call stack to draw function calls graph
2472 - you want to find the reason of a strange kernel behavior and
2476 - you are experiencing weird latencies but it's difficult to
2479 - you want to find quickly which path is taken by a specific
2482 - you just want to peek inside a working kernel and want to see
2496 0) 1.382 us | __might_sleep();
2497 0) 2.478 us | }
2500 0) 1.389 us | __might_sleep();
2501 0) 2.553 us | }
2502 0) 3.807 us | }
2503 0) 7.876 us | }
2505 0) 0.668 us | _spin_lock();
2506 0) 0.570 us | expand_files();
2507 0) 0.586 us | _spin_unlock();
2514 - The cpu number on which the function executed is default
2519 - hide: echo nofuncgraph-cpu > trace_options
2520 - show: echo funcgraph-cpu > trace_options
2522 - The duration (function's time of execution) is displayed on
2527 - hide: echo nofuncgraph-duration > trace_options
2528 - show: echo funcgraph-duration > trace_options
2530 - The overhead field precedes the duration field in case of
2533 - hide: echo nofuncgraph-overhead > trace_options
2534 - show: echo funcgraph-overhead > trace_options
2535 - depends on: funcgraph-duration
2539 3) # 1837.709 us | } /* __switch_to */
2541 3) 0.313 us | _raw_spin_unlock_irq();
2542 3) 3.177 us | }
2543 3) # 1889.063 us | } /* __schedule */
2544 3) ! 140.417 us | } /* __schedule */
2545 3) # 2034.948 us | } /* schedule */
2546 3) * 33998.59 us | } /* schedule_preempt_disabled */
2550 1) 0.260 us | msecs_to_jiffies();
2551 1) 0.313 us | __rcu_read_unlock();
2552 1) + 61.770 us | }
2553 1) + 64.479 us | }
2554 1) 0.313 us | rcu_bh_qs();
2555 1) 0.313 us | __local_bh_enable();
2556 1) ! 217.240 us | }
2557 1) 0.365 us | idle_cpu();
2559 1) 0.417 us | rcu_eqs_enter_common.isra.47();
2560 1) 3.125 us | }
2561 1) ! 227.812 us | }
2562 1) ! 457.395 us | }
2563 1) @ 119760.2 us | }
2568 1) 6.979 us | }
2569 2) 0.417 us | scheduler_ipi();
2570 1) 9.791 us | }
2571 1) + 12.917 us | }
2572 2) 3.490 us | }
2573 1) + 15.729 us | }
2574 1) + 18.542 us | }
2575 2) $ 3594274 us | }
2587 - The task/pid field displays the thread cmdline and pid which
2590 - hide: echo nofuncgraph-proc > trace_options
2591 - show: echo funcgraph-proc > trace_options
2599 0) sh-4802 | | d_free() {
2600 0) sh-4802 | | call_rcu() {
2601 0) sh-4802 | | __call_rcu() {
2602 0) sh-4802 | 0.616 us | rcu_process_gp_end();
2603 0) sh-4802 | 0.586 us | check_for_new_grace_period();
2604 0) sh-4802 | 2.899 us | }
2605 0) sh-4802 | 4.040 us | }
2606 0) sh-4802 | 5.151 us | }
2607 0) sh-4802 | + 49.370 us | }
2610 - The absolute time field is an absolute timestamp given by the
2612 given on each entry/exit of functions
2614 - hide: echo nofuncgraph-abstime > trace_options
2615 - show: echo funcgraph-abstime > trace_options
2622 360.774522 | 1) 0.541 us | }
2623 360.774522 | 1) 4.663 us | }
2624 360.774523 | 1) 0.541 us | __wake_up_bit();
2625 360.774524 | 1) 6.796 us | }
2626 360.774524 | 1) 7.952 us | }
2627 360.774525 | 1) 9.063 us | }
2628 360.774525 | 1) 0.615 us | journal_mark_dirty();
2629 360.774527 | 1) 0.578 us | __brelse();
2634 360.774530 | 1) 0.594 us | __phys_addr();
2646 - hide: echo nofuncgraph-tail > trace_options
2647 - show: echo funcgraph-tail > trace_options
2649 Example with nofuncgraph-tail (default)::
2653 0) 0.518 us | __phys_addr();
2654 0) 1.757 us | }
2655 0) 2.861 us | }
2657 Example with funcgraph-tail::
2661 0) 0.518 us | __phys_addr();
2662 0) 1.757 us | } /* kmem_cache_free() */
2663 0) 2.861 us | } /* putname() */
2676 1) 1.449 us | }
2684 --------------
2689 every kernel function, produced by the -pg switch in gcc),
2691 include the -pg switch in the compiling of the kernel.)
2697 with gcc version 4.6, the -mfentry has been added for x86, which
2708 The recordmcount program re-links this section back into the
2740 One special side-effect to the recording of the functions being
2780 # entries-in-buffer/entries-written: 5/5 #P:4
2782 # _-----=> irqs-off
2783 # / _----=> need-resched
2784 # | / _---=> hardirq/softirq
2785 # || / _--=> preempt-depth
2787 # TASK-PID CPU# |||| TIMESTAMP FUNCTION
2789 usleep-2665 [001] .... 4186.475355: sys_nanosleep <-system_call_fastpath
2790 <idle>-0 [001] d.h1 4186.475409: hrtimer_interrupt <-smp_apic_timer_interrupt
2791 usleep-2665 [001] d.h1 4186.475426: hrtimer_interrupt <-smp_apic_timer_interrupt
2792 <idle>-0 [003] d.h1 4186.475426: hrtimer_interrupt <-smp_apic_timer_interrupt
2793 <idle>-0 [002] d.h1 4186.475427: hrtimer_interrupt <-smp_apic_timer_interrupt
2827 # entries-in-buffer/entries-written: 897/897 #P:4
2829 # _-----=> irqs-off
2830 # / _----=> need-resched
2831 # | / _---=> hardirq/softirq
2832 # || / _--=> preempt-depth
2834 # TASK-PID CPU# |||| TIMESTAMP FUNCTION
2836 <idle>-0 [003] dN.1 4228.547803: hrtimer_cancel <-tick_nohz_idle_exit
2837 <idle>-0 [003] dN.1 4228.547804: hrtimer_try_to_cancel <-hrtimer_cancel
2838 <idle>-0 [003] dN.2 4228.547805: hrtimer_force_reprogram <-__remove_hrtimer
2839 <idle>-0 [003] dN.1 4228.547805: hrtimer_forward <-tick_nohz_idle_exit
2840 … <idle>-0 [003] dN.1 4228.547805: hrtimer_start_range_ns <-hrtimer_start_expires.constprop.11
2841 <idle>-0 [003] d..1 4228.547858: hrtimer_get_next_event <-get_next_timer_interrupt
2842 <idle>-0 [003] d..1 4228.547859: hrtimer_start <-__tick_nohz_idle_enter
2843 <idle>-0 [003] d..2 4228.547860: hrtimer_force_reprogram <-__rem
2916 # entries-in-buffer/entries-written: 39608/39608 #P:4
2918 # _-----=> irqs-off
2919 # / _----=> need-resched
2920 # | / _---=> hardirq/softirq
2921 # || / _--=> preempt-depth
2923 # TASK-PID CPU# |||| TIMESTAMP FUNCTION
2925 bash-1994 [000] .... 4342.324896: file_ra_state_init <-do_dentry_open
2926 bash-1994 [000] .... 4342.324897: open_check_o_direct <-do_last
2927 bash-1994 [000] .... 4342.324897: ima_file_check <-do_last
2928 bash-1994 [000] .... 4342.324898: process_measurement <-ima_file_check
2929 bash-1994 [000] .... 4342.324898: ima_get_action <-process_measurement
2930 bash-1994 [000] .... 4342.324898: ima_match_policy <-ima_get_action
2931 bash-1994 [000] .... 4342.324899: do_truncate <-do_last
2932 bash-1994 [000] .... 4342.324899: should_remove_suid <-do_truncate
2933 bash-1994 [000] .... 4342.324899: notify_change <-do_truncate
2934 bash-1994 [000] .... 4342.324900: current_fs_time <-notify_change
2935 bash-1994 [000] .... 4342.324900: current_kernel_time <-current_fs_time
2936 bash-1994 [000] .... 4342.324900: timespec_trunc <-current_fs_time
2941 ------------------------------------
2959 # head -1 available_filter_functions
2965 # head -50 available_filter_functions | tail -1
2974 ---------------------------------------------
2977 function tracer and the function-graph-tracer, there are some
2978 special features only available in the function-graph tracer.
2991 0) 0.804 us | find_get_page();
2993 0) 1.329 us | }
2994 0) 3.904 us | }
2995 0) 4.979 us | }
2996 0) 0.653 us | _spin_lock();
2997 0) 0.578 us | page_add_file_rmap();
2998 0) 0.525 us | native_set_pte_at();
2999 0) 0.585 us | _spin_unlock();
3001 0) 0.541 us | page_waitqueue();
3002 0) 0.639 us | __wake_up_bit();
3003 0) 2.786 us | }
3004 0) + 14.237 us | }
3008 0) 0.698 us | find_get_page();
3010 0) 1.412 us | }
3011 0) 3.950 us | }
3012 0) 5.098 us | }
3013 0) 0.631 us | _spin_lock();
3014 0) 0.571 us | page_add_file_rmap();
3015 0) 0.526 us | native_set_pte_at();
3016 0) 0.586 us | _spin_unlock();
3018 0) 0.533 us | page_waitqueue();
3019 0) 0.638 us | __wake_up_bit();
3020 0) 2.793 us | }
3021 0) + 14.012 us | }
3035 --------------
3059 ---------------
3068 - mod:
3100 - traceon/traceoff:
3124 - snapshot:
3140 - enable_event/disable_event:
3164 - dump:
3171 - cpudump:
3177 - stacktrace:
3181 ----------
3198 # entries-in-buffer/entries-written: 0/0 #P:4
3200 # _-----=> irqs-off
3201 # / _----=> need-resched
3202 # | / _---=> hardirq/softirq
3203 # || / _--=> preempt-depth
3205 # TASK-PID CPU# |||| TIMESTAMP FUNCTION
3210 bash-1994 [000] .... 5281.568961: mutex_unlock <-rb_simple_write
3211 bash-1994 [000] .... 5281.568963: __mutex_unlock_slowpath <-mutex_unlock
3212 bash-1994 [000] .... 5281.568963: __fsnotify_parent <-fsnotify_modify
3213 bash-1994 [000] .... 5281.568964: fsnotify <-fsnotify_modify
3214 bash-1994 [000] .... 5281.568964: __srcu_read_lock <-fsnotify
3215 bash-1994 [000] .... 5281.568964: add_preempt_count <-__srcu_read_lock
3216 bash-1994 [000] ...1 5281.568965: sub_preempt_count <-__srcu_read_lock
3217 bash-1994 [000] .... 5281.568965: __srcu_read_unlock <-fsnotify
3218 bash-1994 [000] .... 5281.568967: sys_dup2 <-system_call_fastpath
3228 -------------
3255 much, it can cause Out-Of-Memory to trigger.
3259 -bash: echo: write error: Cannot allocate memory
3286 --------
3288 available to all non latency tracers. (Latency tracers which
3289 record max latency, such as "irqsoff" or "wakeup", can't use
3314 +--------------+------------+------------+------------+
3318 +--------------+------------+------------+------------+
3320 +--------------+------------+------------+------------+
3330 # entries-in-buffer/entries-written: 71/71 #P:8
3332 # _-----=> irqs-off
3333 # / _----=> need-resched
3334 # | / _---=> hardirq/softirq
3335 # || / _--=> preempt-depth
3337 # TASK-PID CPU# |||| TIMESTAMP FUNCTION
3339 …<idle>-0 [005] d... 2440.603828: sched_switch: prev_comm=swapper/5 prev_pid=0 prev_prio=120 …
3340 …sleep-2242 [005] d... 2440.603846: sched_switch: prev_comm=snapshot-test-2 prev_pid=2242 prev_pr…
3342 …<idle>-0 [002] d... 2440.707230: sched_switch: prev_comm=swapper/2 prev_pid=0 prev_prio=120 p…
3347 # entries-in-buffer/entries-written: 77/77 #P:8
3349 # _-----=> irqs-off
3350 # / _----=> need-resched
3351 # | / _---=> hardirq/softirq
3352 # || / _--=> preempt-depth
3354 # TASK-PID CPU# |||| TIMESTAMP FUNCTION
3356 …<idle>-0 [007] d... 2440.707395: sched_switch: prev_comm=swapper/7 prev_pid=0 prev_prio=120 p…
3357 …snapshot-test-2-2229 [002] d... 2440.707438: sched_switch: prev_comm=snapshot-test-2 prev_pid=22…
3362 one of the latency tracers, you will get the following results.
3373 ---------
3419 bash-2044 [002] .... 10594.481032: _raw_spin_lock_irqsave <-get_page_from_freelist
3420 bash-2044 [002] d... 10594.481032: add_preempt_count <-_raw_spin_lock_irqsave
3421 bash-2044 [002] d..1 10594.481032: __rmqueue <-get_page_from_freelist
3422 bash-2044 [002] d..1 10594.481033: _raw_spin_unlock <-get_page_from_freelist
3423 bash-2044 [002] d..1 10594.481033: sub_preempt_count <-_raw_spin_unlock
3424 … bash-2044 [002] d... 10594.481033: get_pageblock_flags_group <-get_pageblock_migratetype
3425 bash-2044 [002] d... 10594.481034: __mod_zone_page_state <-get_page_from_freelist
3426 bash-2044 [002] d... 10594.481034: zone_statistics <-get_page_from_freelist
3427 bash-2044 [002] d... 10594.481034: __inc_zone_state <-zone_statistics
3428 bash-2044 [002] d... 10594.481034: __inc_zone_state <-zone_statistics
3429 bash-2044 [002] .... 10594.481035: arch_dup_task_struct <-copy_process
3433 …bash-1998 [000] d..4 136.676759: sched_wakeup: comm=kworker/0:1 pid=59 prio=120 success=1 targe…
3434 …bash-1998 [000] dN.4 136.676760: sched_wakeup: comm=bash pid=1998 prio=120 success=1 target_cpu…
3435 …<idle>-0 [003] d.h3 136.676906: sched_wakeup: comm=rcu_preempt pid=9 prio=120 success=1 targ…
3436 …<idle>-0 [003] d..3 136.676909: sched_switch: prev_comm=swapper/3 prev_pid=0 prev_prio=120 p…
3437 …rcu_preempt-9 [003] d..3 136.676916: sched_switch: prev_comm=rcu_preempt prev_pid=9 prev_pri…
3438 …bash-1998 [000] d..4 136.677014: sched_wakeup: comm=kworker/0:1 pid=59 prio=120 success=1 targe…
3439 …bash-1998 [000] dN.4 136.677016: sched_wakeup: comm=bash pid=1998 prio=120 success=1 target_cpu…
3440 …bash-1998 [000] d..3 136.677018: sched_switch: prev_comm=bash prev_pid=1998 prev_prio=120 prev_…
3441 …kworker/0:1-59 [000] d..4 136.677022: sched_wakeup: comm=sshd pid=1995 prio=120 success=1 tar…
3442 …kworker/0:1-59 [000] d..3 136.677025: sched_switch: prev_comm=kworker/0:1 prev_pid=59 prev_pr…
3446 migration/1-14 [001] d.h3 138.732674: softirq_raise: vec=3 [action=NET_RX]
3447 <idle>-0 [001] dNh3 138.732725: softirq_raise: vec=3 [action=NET_RX]
3448 bash-1998 [000] d.h1 138.733101: softirq_raise: vec=1 [action=TIMER]
3449 bash-1998 [000] d.h1 138.733102: softirq_raise: vec=9 [action=RCU]
3450 bash-1998 [000] ..s2 138.733105: softirq_entry: vec=1 [action=TIMER]
3451 bash-1998 [000] ..s2 138.733106: softirq_exit: vec=1 [action=TIMER]
3452 bash-1998 [000] ..s2 138.733106: softirq_entry: vec=9 [action=RCU]
3453 bash-1998 [000] ..s2 138.733109: softirq_exit: vec=9 [action=RCU]
3454 sshd-1995 [001] d.h1 138.733278: irq_handler_entry: irq=21 name=uhci_hcd:usb4
3455 sshd-1995 [001] d.h1 138.733280: irq_handler_exit: irq=21 ret=unhandled
3456 sshd-1995 [001] d.h1 138.733281: irq_handler_entry: irq=21 name=eth0
3457 sshd-1995 [001] d.h1 138.733283: irq_handler_exit: irq=21 ret=handled
3463 # entries-in-buffer/entries-written: 18996/18996 #P:4
3465 # _-----=> irqs-off
3466 # / _----=> need-resched
3467 # | / _---=> hardirq/softirq
3468 # || / _--=> preempt-depth
3470 # TASK-PID CPU# |||| TIMESTAMP FUNCTION
3472 bash-1998 [000] d... 140.733501: sys_write -> 0x2
3473 bash-1998 [000] d... 140.733504: sys_dup2(oldfd: a, newfd: 1)
3474 bash-1998 [000] d... 140.733506: sys_dup2 -> 0x1
3475 bash-1998 [000] d... 140.733508: sys_fcntl(fd: a, cmd: 1, arg: 0)
3476 bash-1998 [000] d... 140.733509: sys_fcntl -> 0x1
3477 bash-1998 [000] d... 140.733510: sys_close(fd: a)
3478 bash-1998 [000] d... 140.733510: sys_close -> 0x0
3479 …bash-1998 [000] d... 140.733514: sys_rt_sigprocmask(how: 0, nset: 0, oset: 6e2768, sigsetsize: …
3480 bash-1998 [000] d... 140.733515: sys_rt_sigprocmask -> 0x0
3481 …bash-1998 [000] d... 140.733516: sys_rt_sigaction(sig: 2, act: 7fff718846f0, oact: 7fff71884650…
3482 bash-1998 [000] d... 140.733516: sys_rt_sigaction -> 0x0
3500 -----------
3531 ----- ---- --------
3551 Note, if -mfentry is being used by gcc, functions get traced before
3553 are not tested by the stack tracer when -mfentry is used.
3555 Currently, -mfentry is used by gcc 4.6.0 and above on x86 only.
3558 ----