Lines Matching +full:exit +full:- +full:latency +full:- +full:us
2 ftrace - Function Tracer
13 - Written for: 2.6.28-rc2
14 - Updated for: 3.10
15 - Updated for: 4.13 - Copyright 2017 VMware Inc. Steven Rostedt
16 - Converted to rst format - Changbin Du <changbin.du@intel.com>
19 ------------
24 performance issues that take place outside of user-space.
28 There's latency tracing to examine what occurs between interrupts
41 ----------------------
43 See :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
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
264 cause PIDs of tasks that exit to be removed from the file.
271 If the "function-fork" option is set, then when a task whose
275 cause PIDs of tasks that exit to be removed from the file.
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 -----------
730 and exit of the functions. It then provides the ability
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 record-cmd
1170 record-tgid
1187 irq-info
1193 # entries-in-buffer/entries-written: 144405/9452052 #P:4
1195 # TASK-PID CPU# TIMESTAMP FUNCTION
1197 <idle>-0 [002] 23636.756054: ttwu_do_activate.constprop.89 <-try_to_wake_up
1198 <idle>-0 [002] 23636.756054: activate_task <-ttwu_do_activate.constprop.89
1199 <idle>-0 [002] 23636.756055: enqueue_task <-activate_task
1207 event-fork
1210 tasks fork. Also, when tasks with PIDs in set_event_pid exit,
1215 function-trace
1216 The latency tracers will enable function tracing
1218 it is disabled, the latency tracers do not trace
1220 when performing latency tests.
1222 function-fork
1226 set_ftrace_pid exit, their PIDs will be removed from the
1231 display-graph
1232 When set, the latency tracers (irqsoff, wakeup, etc) will
1267 funcgraph-overrun
1278 funcgraph-cpu
1282 funcgraph-overhead
1288 funcgraph-proc
1295 funcgraph-duration
1300 funcgraph-abstime
1303 funcgraph-irqs
1307 funcgraph-tail
1313 sleep-time
1319 graph-time
1333 -------
1338 the kernel know of a new mouse event. The result is a latency
1342 disabled. When a new maximum latency is hit, the tracer saves
1343 the trace leading up to that latency point so that every time a
1350 # echo 0 > options/function-trace
1354 # ls -ltr
1360 # irqsoff latency trace v1.1.5 on 3.8.0-test+
1361 # --------------------------------------------------------------------
1362 # latency: 16 us, #4/4, CPU#0 | (M:preempt VP:0, KP:0, SP:0 HP:0 #P:4)
1363 # -----------------
1364 # | task: swapper/0-0 (uid:0 nice:0 policy:0 rt_prio:0)
1365 # -----------------
1370 # _------=> CPU#
1371 # / _-----=> irqs-off
1372 # | / _----=> need-resched
1373 # || / _---=> hardirq/softirq
1374 # ||| / _--=> preempt-depth
1378 <idle>-0 0d.s2 0us+: _raw_spin_lock_irq <-run_timer_softirq
1379 <idle>-0 0dNs3 17us : _raw_spin_unlock_irq <-run_timer_softirq
1380 <idle>-0 0dNs3 17us+: trace_hardirqs_on <-run_timer_softirq
1381 <idle>-0 0dNs3 25us : <stack trace>
1397 Here we see that we had a latency of 16 microseconds (which is
1400 timestamp 25us occurred because the clock was incremented
1401 between the time of recording the max latency and the time of
1402 recording the function that had that latency.
1404 Note the above example had function-trace not set. If we set
1405 function-trace, we get a much larger output::
1407 with echo 1 > options/function-trace
1411 # irqsoff latency trace v1.1.5 on 3.8.0-test+
1412 # --------------------------------------------------------------------
1413 # latency: 71 us, #168/168, CPU#3 | (M:preempt VP:0, KP:0, SP:0 HP:0 #P:4)
1414 # -----------------
1415 # | task: bash-2042 (uid:0 nice:0 policy:0 rt_prio:0)
1416 # -----------------
1421 # _------=> CPU#
1422 # / _-----=> irqs-off
1423 # | / _----=> need-resched
1424 # || / _---=> hardirq/softirq
1425 # ||| / _--=> preempt-depth
1429 bash-2042 3d... 0us : _raw_spin_lock_irqsave <-ata_scsi_queuecmd
1430 bash-2042 3d... 0us : add_preempt_count <-_raw_spin_lock_irqsave
1431 bash-2042 3d..1 1us : ata_scsi_find_dev <-ata_scsi_queuecmd
1432 bash-2042 3d..1 1us : __ata_scsi_find_dev <-ata_scsi_find_dev
1433 bash-2042 3d..1 2us : ata_find_dev.part.14 <-__ata_scsi_find_dev
1434 bash-2042 3d..1 2us : ata_qc_new_init <-__ata_scsi_queuecmd
1435 bash-2042 3d..1 3us : ata_sg_init <-__ata_scsi_queuecmd
1436 bash-2042 3d..1 4us : ata_scsi_rw_xlat <-__ata_scsi_queuecmd
1437 bash-2042 3d..1 4us : ata_build_rw_tf <-ata_scsi_rw_xlat
1439 bash-2042 3d..1 67us : delay_tsc <-__delay
1440 bash-2042 3d..1 67us : add_preempt_count <-delay_tsc
1441 bash-2042 3d..2 67us : sub_preempt_count <-delay_tsc
1442 bash-2042 3d..1 67us : add_preempt_count <-delay_tsc
1443 bash-2042 3d..2 68us : sub_preempt_count <-delay_tsc
1444 bash-2042 3d..1 68us+: ata_bmdma_start <-ata_bmdma_qc_issue
1445 bash-2042 3d..1 71us : _raw_spin_unlock_irqrestore <-ata_scsi_queuecmd
1446 bash-2042 3d..1 71us : _raw_spin_unlock_irqrestore <-ata_scsi_queuecmd
1447 bash-2042 3d..1 72us+: trace_hardirqs_on <-ata_scsi_queuecmd
1448 bash-2042 3d..1 120us : <stack trace>
1476 Here we traced a 71 microsecond latency. But we also see all the
1479 overhead may extend the latency times. But nevertheless, this
1483 display-graph option::
1485 with echo 1 > options/display-graph
1489 # irqsoff latency trace v1.1.5 on 4.20.0-rc6+
1490 # --------------------------------------------------------------------
1491 # latency: 3751 us, #274/274, CPU#0 | (M:desktop VP:0, KP:0, SP:0 HP:0 #P:4)
1492 # -----------------
1493 # | task: bash-1507 (uid:0 nice:0 policy:0 rt_prio:0)
1494 # -----------------
1499 # _-----=> irqs-off
1500 # / _----=> need-resched
1501 # | / _---=> hardirq/softirq
1502 # || / _--=> preempt-depth
1506 0 us | 0) bash-1507 | d... | 0.000 us | _raw_spin_lock_irqsave();
1507 0 us | 0) bash-1507 | d..1 | 0.378 us | do_raw_spin_trylock();
1508 1 us | 0) bash-1507 | d..2 | | set_track() {
1509 2 us | 0) bash-1507 | d..2 | | save_stack_trace() {
1510 2 us | 0) bash-1507 | d..2 | | __save_stack_trace() {
1511 3 us | 0) bash-1507 | d..2 | | __unwind_start() {
1512 3 us | 0) bash-1507 | d..2 | | get_stack_info() {
1513 3 us | 0) bash-1507 | d..2 | 0.351 us | in_task_stack();
1514 4 us | 0) bash-1507 | d..2 | 1.107 us | }
1516 3750 us | 0) bash-1507 | d..1 | 0.516 us | do_raw_spin_unlock();
1517 3750 us | 0) bash-1507 | d..1 | 0.000 us | _raw_spin_unlock_irqrestore();
1518 3764 us | 0) bash-1507 | d..1 | 0.000 us | tracer_hardirqs_on();
1519 bash-1507 0d..1 3792us : <stack trace>
1536 ----------
1544 Like the irqsoff tracer, it records the maximum latency for
1549 # echo 0 > options/function-trace
1553 # ls -ltr
1559 # preemptoff latency trace v1.1.5 on 3.8.0-test+
1560 # --------------------------------------------------------------------
1561 # latency: 46 us, #4/4, CPU#1 | (M:preempt VP:0, KP:0, SP:0 HP:0 #P:4)
1562 # -----------------
1563 # | task: sshd-1991 (uid:0 nice:0 policy:0 rt_prio:0)
1564 # -----------------
1569 # _------=> CPU#
1570 # / _-----=> irqs-off
1571 # | / _----=> need-resched
1572 # || / _---=> hardirq/softirq
1573 # ||| / _--=> preempt-depth
1577 sshd-1991 1d.h. 0us+: irq_enter <-do_IRQ
1578 sshd-1991 1d..1 46us : irq_exit <-do_IRQ
1579 sshd-1991 1d..1 47us+: trace_preempt_on <-do_IRQ
1580 sshd-1991 1d..1 52us : <stack trace>
1588 interrupt came in (notice the 'h'), and was enabled on exit.
1597 # preemptoff latency trace v1.1.5 on 3.8.0-test+
1598 # --------------------------------------------------------------------
1599 # latency: 83 us, #241/241, CPU#1 | (M:preempt VP:0, KP:0, SP:0 HP:0 #P:4)
1600 # -----------------
1601 # | task: bash-1994 (uid:0 nice:0 policy:0 rt_prio:0)
1602 # -----------------
1607 # _------=> CPU#
1608 # / _-----=> irqs-off
1609 # | / _----=> need-resched
1610 # || / _---=> hardirq/softirq
1611 # ||| / _--=> preempt-depth
1615 bash-1994 1d..1 0us : _raw_spin_lock_irqsave <-wake_up_new_task
1616 bash-1994 1d..1 0us : select_task_rq_fair <-select_task_rq
1617 bash-1994 1d..1 1us : __rcu_read_lock <-select_task_rq_fair
1618 bash-1994 1d..1 1us : source_load <-select_task_rq_fair
1619 bash-1994 1d..1 1us : source_load <-select_task_rq_fair
1621 bash-1994 1d..1 12us : irq_enter <-smp_apic_timer_interrupt
1622 bash-1994 1d..1 12us : rcu_irq_enter <-irq_enter
1623 bash-1994 1d..1 13us : add_preempt_count <-irq_enter
1624 bash-1994 1d.h1 13us : exit_idle <-smp_apic_timer_interrupt
1625 bash-1994 1d.h1 13us : hrtimer_interrupt <-smp_apic_timer_interrupt
1626 bash-1994 1d.h1 13us : _raw_spin_lock <-hrtimer_interrupt
1627 bash-1994 1d.h1 14us : add_preempt_count <-_raw_spin_lock
1628 bash-1994 1d.h2 14us : ktime_get_update_offsets <-hrtimer_interrupt
1630 bash-1994 1d.h1 35us : lapic_next_event <-clockevents_program_event
1631 bash-1994 1d.h1 35us : irq_exit <-smp_apic_timer_interrupt
1632 bash-1994 1d.h1 36us : sub_preempt_count <-irq_exit
1633 bash-1994 1d..2 36us : do_softirq <-irq_exit
1634 bash-1994 1d..2 36us : __do_softirq <-call_softirq
1635 bash-1994 1d..2 36us : __local_bh_disable <-__do_softirq
1636 bash-1994 1d.s2 37us : add_preempt_count <-_raw_spin_lock_irq
1637 bash-1994 1d.s3 38us : _raw_spin_unlock <-run_timer_softirq
1638 bash-1994 1d.s3 39us : sub_preempt_count <-_raw_spin_unlock
1639 bash-1994 1d.s2 39us : call_timer_fn <-run_timer_softirq
1641 bash-1994 1dNs2 81us : cpu_needs_another_gp <-rcu_process_callbacks
1642 bash-1994 1dNs2 82us : __local_bh_enable <-__do_softirq
1643 bash-1994 1dNs2 82us : sub_preempt_count <-__local_bh_enable
1644 bash-1994 1dN.2 82us : idle_cpu <-irq_exit
1645 bash-1994 1dN.2 83us : rcu_irq_exit <-irq_exit
1646 bash-1994 1dN.2 83us : sub_preempt_count <-irq_exit
1647 bash-1994 1.N.1 84us : _raw_spin_unlock_irqrestore <-task_rq_unlock
1648 bash-1994 1.N.1 84us+: trace_preempt_on <-task_rq_unlock
1649 bash-1994 1.N.1 104us : <stack trace>
1660 function-trace set. Here we see that interrupts were not disabled
1661 the entire time. The irq_enter code lets us know that we entered
1667 --------------
1701 # echo 0 > options/function-trace
1705 # ls -ltr
1711 # preemptirqsoff latency trace v1.1.5 on 3.8.0-test+
1712 # --------------------------------------------------------------------
1713 # latency: 100 us, #4/4, CPU#3 | (M:preempt VP:0, KP:0, SP:0 HP:0 #P:4)
1714 # -----------------
1715 # | task: ls-2230 (uid:0 nice:0 policy:0 rt_prio:0)
1716 # -----------------
1721 # _------=> CPU#
1722 # / _-----=> irqs-off
1723 # | / _----=> need-resched
1724 # || / _---=> hardirq/softirq
1725 # ||| / _--=> preempt-depth
1729 ls-2230 3d... 0us+: _raw_spin_lock_irqsave <-ata_scsi_queuecmd
1730 ls-2230 3...1 100us : _raw_spin_unlock_irqrestore <-ata_scsi_queuecmd
1731 ls-2230 3...1 101us+: trace_preempt_on <-ata_scsi_queuecmd
1732 ls-2230 3...1 111us : <stack trace>
1760 Here is a trace with function-trace set::
1764 # preemptirqsoff latency trace v1.1.5 on 3.8.0-test+
1765 # --------------------------------------------------------------------
1766 # latency: 161 us, #339/339, CPU#3 | (M:preempt VP:0, KP:0, SP:0 HP:0 #P:4)
1767 # -----------------
1768 # | task: ls-2269 (uid:0 nice:0 policy:0 rt_prio:0)
1769 # -----------------
1774 # _------=> CPU#
1775 # / _-----=> irqs-off
1776 # | / _----=> need-resched
1777 # || / _---=> hardirq/softirq
1778 # ||| / _--=> preempt-depth
1782 kworker/-59 3...1 0us : __schedule <-schedule
1783 kworker/-59 3d..1 0us : rcu_preempt_qs <-rcu_note_context_switch
1784 kworker/-59 3d..1 1us : add_preempt_count <-_raw_spin_lock_irq
1785 kworker/-59 3d..2 1us : deactivate_task <-__schedule
1786 kworker/-59 3d..2 1us : dequeue_task <-deactivate_task
1787 kworker/-59 3d..2 2us : update_rq_clock <-dequeue_task
1788 kworker/-59 3d..2 2us : dequeue_task_fair <-dequeue_task
1789 kworker/-59 3d..2 2us : update_curr <-dequeue_task_fair
1790 kworker/-59 3d..2 2us : update_min_vruntime <-update_curr
1791 kworker/-59 3d..2 3us : cpuacct_charge <-update_curr
1792 kworker/-59 3d..2 3us : __rcu_read_lock <-cpuacct_charge
1793 kworker/-59 3d..2 3us : __rcu_read_unlock <-cpuacct_charge
1794 kworker/-59 3d..2 3us : update_cfs_rq_blocked_load <-dequeue_task_fair
1795 kworker/-59 3d..2 4us : clear_buddies <-dequeue_task_fair
1796 kworker/-59 3d..2 4us : account_entity_dequeue <-dequeue_task_fair
1797 kworker/-59 3d..2 4us : update_min_vruntime <-dequeue_task_fair
1798 kworker/-59 3d..2 4us : update_cfs_shares <-dequeue_task_fair
1799 kworker/-59 3d..2 5us : hrtick_update <-dequeue_task_fair
1800 kworker/-59 3d..2 5us : wq_worker_sleeping <-__schedule
1801 kworker/-59 3d..2 5us : kthread_data <-wq_worker_sleeping
1802 kworker/-59 3d..2 5us : put_prev_task_fair <-__schedule
1803 kworker/-59 3d..2 6us : pick_next_task_fair <-pick_next_task
1804 kworker/-59 3d..2 6us : clear_buddies <-pick_next_task_fair
1805 kworker/-59 3d..2 6us : set_next_entity <-pick_next_task_fair
1806 kworker/-59 3d..2 6us : update_stats_wait_end <-set_next_entity
1807 ls-2269 3d..2 7us : finish_task_switch <-__schedule
1808 ls-2269 3d..2 7us : _raw_spin_unlock_irq <-finish_task_switch
1809 ls-2269 3d..2 8us : do_IRQ <-ret_from_intr
1810 ls-2269 3d..2 8us : irq_enter <-do_IRQ
1811 ls-2269 3d..2 8us : rcu_irq_enter <-irq_enter
1812 ls-2269 3d..2 9us : add_preempt_count <-irq_enter
1813 ls-2269 3d.h2 9us : exit_idle <-do_IRQ
1815 ls-2269 3d.h3 20us : sub_preempt_count <-_raw_spin_unlock
1816 ls-2269 3d.h2 20us : irq_exit <-do_IRQ
1817 ls-2269 3d.h2 21us : sub_preempt_count <-irq_exit
1818 ls-2269 3d..3 21us : do_softirq <-irq_exit
1819 ls-2269 3d..3 21us : __do_softirq <-call_softirq
1820 ls-2269 3d..3 21us+: __local_bh_disable <-__do_softirq
1821 ls-2269 3d.s4 29us : sub_preempt_count <-_local_bh_enable_ip
1822 ls-2269 3d.s5 29us : sub_preempt_count <-_local_bh_enable_ip
1823 ls-2269 3d.s5 31us : do_IRQ <-ret_from_intr
1824 ls-2269 3d.s5 31us : irq_enter <-do_IRQ
1825 ls-2269 3d.s5 31us : rcu_irq_enter <-irq_enter
1827 ls-2269 3d.s5 31us : rcu_irq_enter <-irq_enter
1828 ls-2269 3d.s5 32us : add_preempt_count <-irq_enter
1829 ls-2269 3d.H5 32us : exit_idle <-do_IRQ
1830 ls-2269 3d.H5 32us : handle_irq <-do_IRQ
1831 ls-2269 3d.H5 32us : irq_to_desc <-handle_irq
1832 ls-2269 3d.H5 33us : handle_fasteoi_irq <-handle_irq
1834 ls-2269 3d.s5 158us : _raw_spin_unlock_irqrestore <-rtl8139_poll
1835 ls-2269 3d.s3 158us : net_rps_action_and_irq_enable.isra.65 <-net_rx_action
1836 ls-2269 3d.s3 159us : __local_bh_enable <-__do_softirq
1837 ls-2269 3d.s3 159us : sub_preempt_count <-__local_bh_enable
1838 ls-2269 3d..3 159us : idle_cpu <-irq_exit
1839 ls-2269 3d..3 159us : rcu_irq_exit <-irq_exit
1840 ls-2269 3d..3 160us : sub_preempt_count <-irq_exit
1841 ls-2269 3d... 161us : __mutex_unlock_slowpath <-mutex_unlock
1842 ls-2269 3d... 162us+: trace_hardirqs_on <-mutex_unlock
1843 ls-2269 3d... 186us : <stack trace>
1862 ------
1866 Now for non Real-Time tasks, this can be arbitrary. But tracing
1871 # echo 0 > options/function-trace
1875 # chrt -f 5 sleep 1
1880 # wakeup latency trace v1.1.5 on 3.8.0-test+
1881 # --------------------------------------------------------------------
1882 # latency: 15 us, #4/4, CPU#3 | (M:preempt VP:0, KP:0, SP:0 HP:0 #P:4)
1883 # -----------------
1884 # | task: kworker/3:1H-312 (uid:0 nice:-20 policy:0 rt_prio:0)
1885 # -----------------
1887 # _------=> CPU#
1888 # / _-----=> irqs-off
1889 # | / _----=> need-resched
1890 # || / _---=> hardirq/softirq
1891 # ||| / _--=> preempt-depth
1895 <idle>-0 3dNs7 0us : 0:120:R + [003] 312:100:R kworker/3:1H
1896 <idle>-0 3dNs7 1us+: ttwu_do_activate.constprop.87 <-try_to_wake_up
1897 <idle>-0 3d..3 15us : __schedule <-schedule
1898 <idle>-0 3d..3 15us : 0:120:R ==> [003] 312:100:R kworker/3:1H
1902 the kworker with a nice priority of -20 (not very nice), took
1906 Non Real-Time tasks are not that interesting. A more interesting
1907 trace is to concentrate only on Real-Time tasks.
1910 ---------
1912 In a Real-Time environment it is very important to know the
1915 latency". I stress the point that this is about RT tasks. It is
1916 also important to know the scheduling latency of non-RT tasks,
1917 but the average schedule latency is better for non-RT tasks.
1921 Real-Time environments are interested in the worst case latency.
1922 That is the longest latency it takes for something to happen,
1924 only have a large latency once in a while, but that would not
1925 work well with Real-Time tasks. The wakeup_rt tracer was designed
1926 to record the worst case wakeups of RT tasks. Non-RT tasks are
1928 tracing non-RT tasks that are unpredictable will overwrite the
1929 worst case latency of RT tasks (just run the normal wakeup
1938 # echo 0 > options/function-trace
1942 # chrt -f 5 sleep 1
1949 # wakeup_rt latency trace v1.1.5 on 3.8.0-test+
1950 # --------------------------------------------------------------------
1951 # latency: 5 us, #4/4, CPU#3 | (M:preempt VP:0, KP:0, SP:0 HP:0 #P:4)
1952 # -----------------
1953 # | task: sleep-2389 (uid:0 nice:0 policy:1 rt_prio:5)
1954 # -----------------
1956 # _------=> CPU#
1957 # / _-----=> irqs-off
1958 # | / _----=> need-resched
1959 # || / _---=> hardirq/softirq
1960 # ||| / _--=> preempt-depth
1964 <idle>-0 3d.h4 0us : 0:120:R + [003] 2389: 94:R sleep
1965 <idle>-0 3d.h4 1us+: ttwu_do_activate.constprop.87 <-try_to_wake_up
1966 <idle>-0 3d..3 5us : __schedule <-schedule
1967 <idle>-0 3d..3 5us : 0:120:R ==> [003] 2389: 94:R sleep
1977 and it has an rt_prio of 5. This priority is user-space priority
1981 Note, that the trace data shows the internal priority (99 - rtprio).
1984 <idle>-0 3d..3 5us : 0:120:R ==> [003] 2389: 94:R sleep
1986 The 0:120:R means idle was running with a nice priority of 0 (120 - 120)
1988 2389: 94:R. That is the priority is the kernel rtprio (99 - 5 = 94)
1991 Doing the same with chrt -r 5 and function-trace set.
1994 echo 1 > options/function-trace
1998 # wakeup_rt latency trace v1.1.5 on 3.8.0-test+
1999 # --------------------------------------------------------------------
2000 # latency: 29 us, #85/85, CPU#3 | (M:preempt VP:0, KP:0, SP:0 HP:0 #P:4)
2001 # -----------------
2002 # | task: sleep-2448 (uid:0 nice:0 policy:1 rt_prio:5)
2003 # -----------------
2005 # _------=> CPU#
2006 # / _-----=> irqs-off
2007 # | / _----=> need-resched
2008 # || / _---=> hardirq/softirq
2009 # ||| / _--=> preempt-depth
2013 <idle>-0 3d.h4 1us+: 0:120:R + [003] 2448: 94:R sleep
2014 <idle>-0 3d.h4 2us : ttwu_do_activate.constprop.87 <-try_to_wake_up
2015 <idle>-0 3d.h3 3us : check_preempt_curr <-ttwu_do_wakeup
2016 <idle>-0 3d.h3 3us : resched_curr <-check_preempt_curr
2017 <idle>-0 3dNh3 4us : task_woken_rt <-ttwu_do_wakeup
2018 <idle>-0 3dNh3 4us : _raw_spin_unlock <-try_to_wake_up
2019 <idle>-0 3dNh3 4us : sub_preempt_count <-_raw_spin_unlock
2020 <idle>-0 3dNh2 5us : ttwu_stat <-try_to_wake_up
2021 <idle>-0 3dNh2 5us : _raw_spin_unlock_irqrestore <-try_to_wake_up
2022 <idle>-0 3dNh2 6us : sub_preempt_count <-_raw_spin_unlock_irqrestore
2023 <idle>-0 3dNh1 6us : _raw_spin_lock <-__run_hrtimer
2024 <idle>-0 3dNh1 6us : add_preempt_count <-_raw_spin_lock
2025 <idle>-0 3dNh2 7us : _raw_spin_unlock <-hrtimer_interrupt
2026 <idle>-0 3dNh2 7us : sub_preempt_count <-_raw_spin_unlock
2027 <idle>-0 3dNh1 7us : tick_program_event <-hrtimer_interrupt
2028 <idle>-0 3dNh1 7us : clockevents_program_event <-tick_program_event
2029 <idle>-0 3dNh1 8us : ktime_get <-clockevents_program_event
2030 <idle>-0 3dNh1 8us : lapic_next_event <-clockevents_program_event
2031 <idle>-0 3dNh1 8us : irq_exit <-smp_apic_timer_interrupt
2032 <idle>-0 3dNh1 9us : sub_preempt_count <-irq_exit
2033 <idle>-0 3dN.2 9us : idle_cpu <-irq_exit
2034 <idle>-0 3dN.2 9us : rcu_irq_exit <-irq_exit
2035 <idle>-0 3dN.2 10us : rcu_eqs_enter_common.isra.45 <-rcu_irq_exit
2036 <idle>-0 3dN.2 10us : sub_preempt_count <-irq_exit
2037 <idle>-0 3.N.1 11us : rcu_idle_exit <-cpu_idle
2038 <idle>-0 3dN.1 11us : rcu_eqs_exit_common.isra.43 <-rcu_idle_exit
2039 <idle>-0 3.N.1 11us : tick_nohz_idle_exit <-cpu_idle
2040 <idle>-0 3dN.1 12us : menu_hrtimer_cancel <-tick_nohz_idle_exit
2041 <idle>-0 3dN.1 12us : ktime_get <-tick_nohz_idle_exit
2042 <idle>-0 3dN.1 12us : tick_do_update_jiffies64 <-tick_nohz_idle_exit
2043 <idle>-0 3dN.1 13us : cpu_load_update_nohz <-tick_nohz_idle_exit
2044 <idle>-0 3dN.1 13us : _raw_spin_lock <-cpu_load_update_nohz
2045 <idle>-0 3dN.1 13us : add_preempt_count <-_raw_spin_lock
2046 <idle>-0 3dN.2 13us : __cpu_load_update <-cpu_load_update_nohz
2047 <idle>-0 3dN.2 14us : sched_avg_update <-__cpu_load_update
2048 <idle>-0 3dN.2 14us : _raw_spin_unlock <-cpu_load_update_nohz
2049 <idle>-0 3dN.2 14us : sub_preempt_count <-_raw_spin_unlock
2050 <idle>-0 3dN.1 15us : calc_load_nohz_stop <-tick_nohz_idle_exit
2051 <idle>-0 3dN.1 15us : touch_softlockup_watchdog <-tick_nohz_idle_exit
2052 <idle>-0 3dN.1 15us : hrtimer_cancel <-tick_nohz_idle_exit
2053 <idle>-0 3dN.1 15us : hrtimer_try_to_cancel <-hrtimer_cancel
2054 <idle>-0 3dN.1 16us : lock_hrtimer_base.isra.18 <-hrtimer_try_to_cancel
2055 <idle>-0 3dN.1 16us : _raw_spin_lock_irqsave <-lock_hrtimer_base.isra.18
2056 <idle>-0 3dN.1 16us : add_preempt_count <-_raw_spin_lock_irqsave
2057 <idle>-0 3dN.2 17us : __remove_hrtimer <-remove_hrtimer.part.16
2058 <idle>-0 3dN.2 17us : hrtimer_force_reprogram <-__remove_hrtimer
2059 <idle>-0 3dN.2 17us : tick_program_event <-hrtimer_force_reprogram
2060 <idle>-0 3dN.2 18us : clockevents_program_event <-tick_program_event
2061 <idle>-0 3dN.2 18us : ktime_get <-clockevents_program_event
2062 <idle>-0 3dN.2 18us : lapic_next_event <-clockevents_program_event
2063 <idle>-0 3dN.2 19us : _raw_spin_unlock_irqrestore <-hrtimer_try_to_cancel
2064 <idle>-0 3dN.2 19us : sub_preempt_count <-_raw_spin_unlock_irqrestore
2065 <idle>-0 3dN.1 19us : hrtimer_forward <-tick_nohz_idle_exit
2066 <idle>-0 3dN.1 20us : ktime_add_safe <-hrtimer_forward
2067 <idle>-0 3dN.1 20us : ktime_add_safe <-hrtimer_forward
2068 <idle>-0 3dN.1 20us : hrtimer_start_range_ns <-hrtimer_start_expires.constprop.11
2069 <idle>-0 3dN.1 20us : __hrtimer_start_range_ns <-hrtimer_start_range_ns
2070 <idle>-0 3dN.1 21us : lock_hrtimer_base.isra.18 <-__hrtimer_start_range_ns
2071 <idle>-0 3dN.1 21us : _raw_spin_lock_irqsave <-lock_hrtimer_base.isra.18
2072 <idle>-0 3dN.1 21us : add_preempt_count <-_raw_spin_lock_irqsave
2073 <idle>-0 3dN.2 22us : ktime_add_safe <-__hrtimer_start_range_ns
2074 <idle>-0 3dN.2 22us : enqueue_hrtimer <-__hrtimer_start_range_ns
2075 <idle>-0 3dN.2 22us : tick_program_event <-__hrtimer_start_range_ns
2076 <idle>-0 3dN.2 23us : clockevents_program_event <-tick_program_event
2077 <idle>-0 3dN.2 23us : ktime_get <-clockevents_program_event
2078 <idle>-0 3dN.2 23us : lapic_next_event <-clockevents_program_event
2079 <idle>-0 3dN.2 24us : _raw_spin_unlock_irqrestore <-__hrtimer_start_range_ns
2080 <idle>-0 3dN.2 24us : sub_preempt_count <-_raw_spin_unlock_irqrestore
2081 <idle>-0 3dN.1 24us : account_idle_ticks <-tick_nohz_idle_exit
2082 <idle>-0 3dN.1 24us : account_idle_time <-account_idle_ticks
2083 <idle>-0 3.N.1 25us : sub_preempt_count <-cpu_idle
2084 <idle>-0 3.N.. 25us : schedule <-cpu_idle
2085 <idle>-0 3.N.. 25us : __schedule <-preempt_schedule
2086 <idle>-0 3.N.. 26us : add_preempt_count <-__schedule
2087 <idle>-0 3.N.1 26us : rcu_note_context_switch <-__schedule
2088 <idle>-0 3.N.1 26us : rcu_sched_qs <-rcu_note_context_switch
2089 <idle>-0 3dN.1 27us : rcu_preempt_qs <-rcu_note_context_switch
2090 <idle>-0 3.N.1 27us : _raw_spin_lock_irq <-__schedule
2091 <idle>-0 3dN.1 27us : add_preempt_count <-_raw_spin_lock_irq
2092 <idle>-0 3dN.2 28us : put_prev_task_idle <-__schedule
2093 <idle>-0 3dN.2 28us : pick_next_task_stop <-pick_next_task
2094 <idle>-0 3dN.2 28us : pick_next_task_rt <-pick_next_task
2095 <idle>-0 3dN.2 29us : dequeue_pushable_task <-pick_next_task_rt
2096 <idle>-0 3d..3 29us : __schedule <-preempt_schedule
2097 <idle>-0 3d..3 30us : 0:120:R ==> [003] 2448: 94:R sleep
2106 Latency tracing and events
2107 --------------------------
2108 As function tracing can induce a much larger latency, but without
2109 seeing what happens within the latency it is hard to know what
2114 # echo 0 > options/function-trace
2119 # chrt -f 5 sleep 1
2124 # wakeup_rt latency trace v1.1.5 on 3.8.0-test+
2125 # --------------------------------------------------------------------
2126 # latency: 6 us, #12/12, CPU#2 | (M:preempt VP:0, KP:0, SP:0 HP:0 #P:4)
2127 # -----------------
2128 # | task: sleep-5882 (uid:0 nice:0 policy:1 rt_prio:5)
2129 # -----------------
2131 # _------=> CPU#
2132 # / _-----=> irqs-off
2133 # | / _----=> need-resched
2134 # || / _---=> hardirq/softirq
2135 # ||| / _--=> preempt-depth
2139 <idle>-0 2d.h4 0us : 0:120:R + [002] 5882: 94:R sleep
2140 <idle>-0 2d.h4 0us : ttwu_do_activate.constprop.87 <-try_to_wake_up
2141 <idle>-0 2d.h4 1us : sched_wakeup: comm=sleep pid=5882 prio=94 success=1 target_cpu=002
2142 <idle>-0 2dNh2 1us : hrtimer_expire_exit: hrtimer=ffff88007796feb8
2143 <idle>-0 2.N.2 2us : power_end: cpu_id=2
2144 <idle>-0 2.N.2 3us : cpu_idle: state=4294967295 cpu_id=2
2145 <idle>-0 2dN.3 4us : hrtimer_cancel: hrtimer=ffff88007d50d5e0
2146 …<idle>-0 2dN.3 4us : hrtimer_start: hrtimer=ffff88007d50d5e0 function=tick_sched_timer ex…
2147 <idle>-0 2.N.2 5us : rcu_utilization: Start context switch
2148 <idle>-0 2.N.2 5us : rcu_utilization: End context switch
2149 <idle>-0 2d..3 6us : __schedule <-schedule
2150 <idle>-0 2d..3 6us : 0:120:R ==> [002] 5882: 94:R sleep
2153 Hardware Latency Detector
2154 -------------------------
2156 The hardware latency detector is executed by enabling the "hwlat" tracer.
2167 # entries-in-buffer/entries-written: 13/13 #P:8
2169 # _-----=> irqs-off
2170 # / _----=> need-resched
2171 # | / _---=> hardirq/softirq
2172 # || / _--=> preempt-depth
2174 # TASK-PID CPU# |||| TIMESTAMP FUNCTION
2176 …<...>-1729 [001] d... 678.473449: #1 inner/outer(us): 11/12 ts:1581527483.343962693 co…
2177 …<...>-1729 [004] d... 689.556542: #2 inner/outer(us): 16/9 ts:1581527494.889008092 co…
2178 …<...>-1729 [005] d... 714.756290: #3 inner/outer(us): 16/16 ts:1581527519.678961629 co…
2179 …<...>-1729 [001] d... 718.788247: #4 inner/outer(us): 9/17 ts:1581527523.889012713 co…
2180 …<...>-1729 [002] d... 719.796341: #5 inner/outer(us): 13/9 ts:1581527524.912872606 co…
2181 …<...>-1729 [006] d... 844.787091: #6 inner/outer(us): 9/12 ts:1581527649.889048502 co…
2182 …<...>-1729 [003] d... 849.827033: #7 inner/outer(us): 18/9 ts:1581527654.889013793 co…
2183 …<...>-1729 [007] d... 853.859002: #8 inner/outer(us): 9/12 ts:1581527658.889065736 co…
2184 …<...>-1729 [001] d... 855.874978: #9 inner/outer(us): 9/11 ts:1581527660.861991877 co…
2185 …<...>-1729 [001] d... 863.938932: #10 inner/outer(us): 9/11 ts:1581527668.970010500 co…
2186 …<...>-1729 [007] d... 878.050780: #11 inner/outer(us): 9/12 ts:1581527683.385002600 co…
2187 …<...>-1729 [007] d... 886.114702: #12 inner/outer(us): 9/12 ts:1581527691.385001600 co…
2197 inner/outer(us): 11/11
2199 This shows two numbers as "inner latency" and "outer latency". The test
2200 runs in a loop checking a timestamp twice. The latency detected within
2201 the two timestamps is the "inner latency" and the latency detected
2203 the "outer latency".
2207 The absolute timestamp that the first latency was recorded in the window.
2211 The number of times a latency was detected during the window.
2213 nmi-total:7 nmi-count:1
2216 test, the time spent in NMI is reported in "nmi-total" (in
2219 All architectures that have NMIs will show the "nmi-count" if an
2226 microseconds. This is the threshold of latency that
2250 --------
2266 # entries-in-buffer/entries-written: 24799/24799 #P:4
2268 # _-----=> irqs-off
2269 # / _----=> need-resched
2270 # | / _---=> hardirq/softirq
2271 # || / _--=> preempt-depth
2273 # TASK-PID CPU# |||| TIMESTAMP FUNCTION
2275 bash-1994 [002] .... 3082.063030: mutex_unlock <-rb_simple_write
2276 bash-1994 [002] .... 3082.063031: __mutex_unlock_slowpath <-mutex_unlock
2277 bash-1994 [002] .... 3082.063031: __fsnotify_parent <-fsnotify_modify
2278 bash-1994 [002] .... 3082.063032: fsnotify <-fsnotify_modify
2279 bash-1994 [002] .... 3082.063032: __srcu_read_lock <-fsnotify
2280 bash-1994 [002] .... 3082.063032: add_preempt_count <-__srcu_read_lock
2281 bash-1994 [002] ...1 3082.063032: sub_preempt_count <-__srcu_read_lock
2282 bash-1994 [002] .... 3082.063033: __srcu_read_unlock <-fsnotify
2310 ---------------------
2324 # TASK-PID CPU# TIMESTAMP FUNCTION
2326 yum-updatesd-3111 [003] 1637.254676: finish_task_switch <-thread_return
2327 yum-updatesd-3111 [003] 1637.254681: hrtimer_cancel <-schedule_hrtimeout_range
2328 yum-updatesd-3111 [003] 1637.254682: hrtimer_try_to_cancel <-hrtimer_cancel
2329 yum-updatesd-3111 [003] 1637.254683: lock_hrtimer_base <-hrtimer_try_to_cancel
2330 yum-updatesd-3111 [003] 1637.254685: fget_light <-do_sys_poll
2331 yum-updatesd-3111 [003] 1637.254686: pipe_poll <-do_sys_poll
2336 # TASK-PID CPU# TIMESTAMP FUNCTION
2339 yum-updatesd-3111 [003] 1701.957688: free_poll_entry <-poll_freewait
2340 yum-updatesd-3111 [003] 1701.957689: remove_wait_queue <-free_poll_entry
2341 yum-updatesd-3111 [003] 1701.957691: fput <-free_poll_entry
2342 yum-updatesd-3111 [003] 1701.957692: audit_syscall_exit <-sysret_audit
2343 yum-updatesd-3111 [003] 1701.957693: path_put <-audit_syscall_exit
2406 exit(-1);
2415 exit(-1);
2438 tracefs=`sed -ne 's/^tracefs \(.*\) tracefs.*/\1/p' /proc/mounts`
2448 ---------------------------
2451 probes a function on its entry and its exit. This is done by
2461 - measure of a function's time execution
2462 - having a reliable call stack to draw function calls graph
2466 - you want to find the reason of a strange kernel behavior and
2470 - you are experiencing weird latencies but it's difficult to
2473 - you want to find quickly which path is taken by a specific
2476 - you just want to peek inside a working kernel and want to see
2490 0) 1.382 us | __might_sleep();
2491 0) 2.478 us | }
2494 0) 1.389 us | __might_sleep();
2495 0) 2.553 us | }
2496 0) 3.807 us | }
2497 0) 7.876 us | }
2499 0) 0.668 us | _spin_lock();
2500 0) 0.570 us | expand_files();
2501 0) 0.586 us | _spin_unlock();
2508 - The cpu number on which the function executed is default
2513 - hide: echo nofuncgraph-cpu > trace_options
2514 - show: echo funcgraph-cpu > trace_options
2516 - The duration (function's time of execution) is displayed on
2521 - hide: echo nofuncgraph-duration > trace_options
2522 - show: echo funcgraph-duration > trace_options
2524 - The overhead field precedes the duration field in case of
2527 - hide: echo nofuncgraph-overhead > trace_options
2528 - show: echo funcgraph-overhead > trace_options
2529 - depends on: funcgraph-duration
2533 3) # 1837.709 us | } /* __switch_to */
2535 3) 0.313 us | _raw_spin_unlock_irq();
2536 3) 3.177 us | }
2537 3) # 1889.063 us | } /* __schedule */
2538 3) ! 140.417 us | } /* __schedule */
2539 3) # 2034.948 us | } /* schedule */
2540 3) * 33998.59 us | } /* schedule_preempt_disabled */
2544 1) 0.260 us | msecs_to_jiffies();
2545 1) 0.313 us | __rcu_read_unlock();
2546 1) + 61.770 us | }
2547 1) + 64.479 us | }
2548 1) 0.313 us | rcu_bh_qs();
2549 1) 0.313 us | __local_bh_enable();
2550 1) ! 217.240 us | }
2551 1) 0.365 us | idle_cpu();
2553 1) 0.417 us | rcu_eqs_enter_common.isra.47();
2554 1) 3.125 us | }
2555 1) ! 227.812 us | }
2556 1) ! 457.395 us | }
2557 1) @ 119760.2 us | }
2562 1) 6.979 us | }
2563 2) 0.417 us | scheduler_ipi();
2564 1) 9.791 us | }
2565 1) + 12.917 us | }
2566 2) 3.490 us | }
2567 1) + 15.729 us | }
2568 1) + 18.542 us | }
2569 2) $ 3594274 us | }
2581 - The task/pid field displays the thread cmdline and pid which
2584 - hide: echo nofuncgraph-proc > trace_options
2585 - show: echo funcgraph-proc > trace_options
2593 0) sh-4802 | | d_free() {
2594 0) sh-4802 | | call_rcu() {
2595 0) sh-4802 | | __call_rcu() {
2596 0) sh-4802 | 0.616 us | rcu_process_gp_end();
2597 0) sh-4802 | 0.586 us | check_for_new_grace_period();
2598 0) sh-4802 | 2.899 us | }
2599 0) sh-4802 | 4.040 us | }
2600 0) sh-4802 | 5.151 us | }
2601 0) sh-4802 | + 49.370 us | }
2604 - The absolute time field is an absolute timestamp given by the
2606 given on each entry/exit of functions
2608 - hide: echo nofuncgraph-abstime > trace_options
2609 - show: echo funcgraph-abstime > trace_options
2616 360.774522 | 1) 0.541 us | }
2617 360.774522 | 1) 4.663 us | }
2618 360.774523 | 1) 0.541 us | __wake_up_bit();
2619 360.774524 | 1) 6.796 us | }
2620 360.774524 | 1) 7.952 us | }
2621 360.774525 | 1) 9.063 us | }
2622 360.774525 | 1) 0.615 us | journal_mark_dirty();
2623 360.774527 | 1) 0.578 us | __brelse();
2628 360.774530 | 1) 0.594 us | __phys_addr();
2640 - hide: echo nofuncgraph-tail > trace_options
2641 - show: echo funcgraph-tail > trace_options
2643 Example with nofuncgraph-tail (default)::
2647 0) 0.518 us | __phys_addr();
2648 0) 1.757 us | }
2649 0) 2.861 us | }
2651 Example with funcgraph-tail::
2655 0) 0.518 us | __phys_addr();
2656 0) 1.757 us | } /* kmem_cache_free() */
2657 0) 2.861 us | } /* putname() */
2670 1) 1.449 us | }
2678 --------------
2683 every kernel function, produced by the -pg switch in gcc),
2685 include the -pg switch in the compiling of the kernel.)
2691 with gcc version 4.6, the -mfentry has been added for x86, which
2702 The recordmcount program re-links this section back into the
2734 One special side-effect to the recording of the functions being
2774 # entries-in-buffer/entries-written: 5/5 #P:4
2776 # _-----=> irqs-off
2777 # / _----=> need-resched
2778 # | / _---=> hardirq/softirq
2779 # || / _--=> preempt-depth
2781 # TASK-PID CPU# |||| TIMESTAMP FUNCTION
2783 usleep-2665 [001] .... 4186.475355: sys_nanosleep <-system_call_fastpath
2784 <idle>-0 [001] d.h1 4186.475409: hrtimer_interrupt <-smp_apic_timer_interrupt
2785 usleep-2665 [001] d.h1 4186.475426: hrtimer_interrupt <-smp_apic_timer_interrupt
2786 <idle>-0 [003] d.h1 4186.475426: hrtimer_interrupt <-smp_apic_timer_interrupt
2787 <idle>-0 [002] d.h1 4186.475427: hrtimer_interrupt <-smp_apic_timer_interrupt
2821 # entries-in-buffer/entries-written: 897/897 #P:4
2823 # _-----=> irqs-off
2824 # / _----=> need-resched
2825 # | / _---=> hardirq/softirq
2826 # || / _--=> preempt-depth
2828 # TASK-PID CPU# |||| TIMESTAMP FUNCTION
2830 <idle>-0 [003] dN.1 4228.547803: hrtimer_cancel <-tick_nohz_idle_exit
2831 <idle>-0 [003] dN.1 4228.547804: hrtimer_try_to_cancel <-hrtimer_cancel
2832 <idle>-0 [003] dN.2 4228.547805: hrtimer_force_reprogram <-__remove_hrtimer
2833 <idle>-0 [003] dN.1 4228.547805: hrtimer_forward <-tick_nohz_idle_exit
2834 … <idle>-0 [003] dN.1 4228.547805: hrtimer_start_range_ns <-hrtimer_start_expires.constprop.11
2835 <idle>-0 [003] d..1 4228.547858: hrtimer_get_next_event <-get_next_timer_interrupt
2836 <idle>-0 [003] d..1 4228.547859: hrtimer_start <-__tick_nohz_idle_enter
2837 <idle>-0 [003] d..2 4228.547860: hrtimer_force_reprogram <-__rem
2910 # entries-in-buffer/entries-written: 39608/39608 #P:4
2912 # _-----=> irqs-off
2913 # / _----=> need-resched
2914 # | / _---=> hardirq/softirq
2915 # || / _--=> preempt-depth
2917 # TASK-PID CPU# |||| TIMESTAMP FUNCTION
2919 bash-1994 [000] .... 4342.324896: file_ra_state_init <-do_dentry_open
2920 bash-1994 [000] .... 4342.324897: open_check_o_direct <-do_last
2921 bash-1994 [000] .... 4342.324897: ima_file_check <-do_last
2922 bash-1994 [000] .... 4342.324898: process_measurement <-ima_file_check
2923 bash-1994 [000] .... 4342.324898: ima_get_action <-process_measurement
2924 bash-1994 [000] .... 4342.324898: ima_match_policy <-ima_get_action
2925 bash-1994 [000] .... 4342.324899: do_truncate <-do_last
2926 bash-1994 [000] .... 4342.324899: should_remove_suid <-do_truncate
2927 bash-1994 [000] .... 4342.324899: notify_change <-do_truncate
2928 bash-1994 [000] .... 4342.324900: current_fs_time <-notify_change
2929 bash-1994 [000] .... 4342.324900: current_kernel_time <-current_fs_time
2930 bash-1994 [000] .... 4342.324900: timespec_trunc <-current_fs_time
2935 ------------------------------------
2953 # head -1 available_filter_functions
2959 # head -50 available_filter_functions | tail -1
2968 ---------------------------------------------
2971 function tracer and the function-graph-tracer, there are some
2972 special features only available in the function-graph tracer.
2985 0) 0.804 us | find_get_page();
2987 0) 1.329 us | }
2988 0) 3.904 us | }
2989 0) 4.979 us | }
2990 0) 0.653 us | _spin_lock();
2991 0) 0.578 us | page_add_file_rmap();
2992 0) 0.525 us | native_set_pte_at();
2993 0) 0.585 us | _spin_unlock();
2995 0) 0.541 us | page_waitqueue();
2996 0) 0.639 us | __wake_up_bit();
2997 0) 2.786 us | }
2998 0) + 14.237 us | }
3002 0) 0.698 us | find_get_page();
3004 0) 1.412 us | }
3005 0) 3.950 us | }
3006 0) 5.098 us | }
3007 0) 0.631 us | _spin_lock();
3008 0) 0.571 us | page_add_file_rmap();
3009 0) 0.526 us | native_set_pte_at();
3010 0) 0.586 us | _spin_unlock();
3012 0) 0.533 us | page_waitqueue();
3013 0) 0.638 us | __wake_up_bit();
3014 0) 2.793 us | }
3015 0) + 14.012 us | }
3029 --------------
3053 ---------------
3062 - mod:
3094 - traceon/traceoff:
3118 - snapshot:
3134 - enable_event/disable_event:
3158 - dump:
3165 - cpudump:
3171 - stacktrace:
3175 ----------
3192 # entries-in-buffer/entries-written: 0/0 #P:4
3194 # _-----=> irqs-off
3195 # / _----=> need-resched
3196 # | / _---=> hardirq/softirq
3197 # || / _--=> preempt-depth
3199 # TASK-PID CPU# |||| TIMESTAMP FUNCTION
3204 bash-1994 [000] .... 5281.568961: mutex_unlock <-rb_simple_write
3205 bash-1994 [000] .... 5281.568963: __mutex_unlock_slowpath <-mutex_unlock
3206 bash-1994 [000] .... 5281.568963: __fsnotify_parent <-fsnotify_modify
3207 bash-1994 [000] .... 5281.568964: fsnotify <-fsnotify_modify
3208 bash-1994 [000] .... 5281.568964: __srcu_read_lock <-fsnotify
3209 bash-1994 [000] .... 5281.568964: add_preempt_count <-__srcu_read_lock
3210 bash-1994 [000] ...1 5281.568965: sub_preempt_count <-__srcu_read_lock
3211 bash-1994 [000] .... 5281.568965: __srcu_read_unlock <-fsnotify
3212 bash-1994 [000] .... 5281.568967: sys_dup2 <-system_call_fastpath
3222 -------------
3249 much, it can cause Out-Of-Memory to trigger.
3253 -bash: echo: write error: Cannot allocate memory
3280 --------
3282 available to all non latency tracers. (Latency tracers which
3283 record max latency, such as "irqsoff" or "wakeup", can't use
3308 +--------------+------------+------------+------------+
3312 +--------------+------------+------------+------------+
3314 +--------------+------------+------------+------------+
3324 # entries-in-buffer/entries-written: 71/71 #P:8
3326 # _-----=> irqs-off
3327 # / _----=> need-resched
3328 # | / _---=> hardirq/softirq
3329 # || / _--=> preempt-depth
3331 # TASK-PID CPU# |||| TIMESTAMP FUNCTION
3333 …<idle>-0 [005] d... 2440.603828: sched_switch: prev_comm=swapper/5 prev_pid=0 prev_prio=120 …
3334 …sleep-2242 [005] d... 2440.603846: sched_switch: prev_comm=snapshot-test-2 prev_pid=2242 prev_pr…
3336 …<idle>-0 [002] d... 2440.707230: sched_switch: prev_comm=swapper/2 prev_pid=0 prev_prio=120 p…
3341 # entries-in-buffer/entries-written: 77/77 #P:8
3343 # _-----=> irqs-off
3344 # / _----=> need-resched
3345 # | / _---=> hardirq/softirq
3346 # || / _--=> preempt-depth
3348 # TASK-PID CPU# |||| TIMESTAMP FUNCTION
3350 …<idle>-0 [007] d... 2440.707395: sched_switch: prev_comm=swapper/7 prev_pid=0 prev_prio=120 p…
3351 …snapshot-test-2-2229 [002] d... 2440.707438: sched_switch: prev_comm=snapshot-test-2 prev_pid=22…
3356 one of the latency tracers, you will get the following results.
3367 ---------
3413 bash-2044 [002] .... 10594.481032: _raw_spin_lock_irqsave <-get_page_from_freelist
3414 bash-2044 [002] d... 10594.481032: add_preempt_count <-_raw_spin_lock_irqsave
3415 bash-2044 [002] d..1 10594.481032: __rmqueue <-get_page_from_freelist
3416 bash-2044 [002] d..1 10594.481033: _raw_spin_unlock <-get_page_from_freelist
3417 bash-2044 [002] d..1 10594.481033: sub_preempt_count <-_raw_spin_unlock
3418 … bash-2044 [002] d... 10594.481033: get_pageblock_flags_group <-get_pageblock_migratetype
3419 bash-2044 [002] d... 10594.481034: __mod_zone_page_state <-get_page_from_freelist
3420 bash-2044 [002] d... 10594.481034: zone_statistics <-get_page_from_freelist
3421 bash-2044 [002] d... 10594.481034: __inc_zone_state <-zone_statistics
3422 bash-2044 [002] d... 10594.481034: __inc_zone_state <-zone_statistics
3423 bash-2044 [002] .... 10594.481035: arch_dup_task_struct <-copy_process
3427 …bash-1998 [000] d..4 136.676759: sched_wakeup: comm=kworker/0:1 pid=59 prio=120 success=1 targe…
3428 …bash-1998 [000] dN.4 136.676760: sched_wakeup: comm=bash pid=1998 prio=120 success=1 target_cpu…
3429 …<idle>-0 [003] d.h3 136.676906: sched_wakeup: comm=rcu_preempt pid=9 prio=120 success=1 targ…
3430 …<idle>-0 [003] d..3 136.676909: sched_switch: prev_comm=swapper/3 prev_pid=0 prev_prio=120 p…
3431 …rcu_preempt-9 [003] d..3 136.676916: sched_switch: prev_comm=rcu_preempt prev_pid=9 prev_pri…
3432 …bash-1998 [000] d..4 136.677014: sched_wakeup: comm=kworker/0:1 pid=59 prio=120 success=1 targe…
3433 …bash-1998 [000] dN.4 136.677016: sched_wakeup: comm=bash pid=1998 prio=120 success=1 target_cpu…
3434 …bash-1998 [000] d..3 136.677018: sched_switch: prev_comm=bash prev_pid=1998 prev_prio=120 prev_…
3435 …kworker/0:1-59 [000] d..4 136.677022: sched_wakeup: comm=sshd pid=1995 prio=120 success=1 tar…
3436 …kworker/0:1-59 [000] d..3 136.677025: sched_switch: prev_comm=kworker/0:1 prev_pid=59 prev_pr…
3440 migration/1-14 [001] d.h3 138.732674: softirq_raise: vec=3 [action=NET_RX]
3441 <idle>-0 [001] dNh3 138.732725: softirq_raise: vec=3 [action=NET_RX]
3442 bash-1998 [000] d.h1 138.733101: softirq_raise: vec=1 [action=TIMER]
3443 bash-1998 [000] d.h1 138.733102: softirq_raise: vec=9 [action=RCU]
3444 bash-1998 [000] ..s2 138.733105: softirq_entry: vec=1 [action=TIMER]
3445 bash-1998 [000] ..s2 138.733106: softirq_exit: vec=1 [action=TIMER]
3446 bash-1998 [000] ..s2 138.733106: softirq_entry: vec=9 [action=RCU]
3447 bash-1998 [000] ..s2 138.733109: softirq_exit: vec=9 [action=RCU]
3448 sshd-1995 [001] d.h1 138.733278: irq_handler_entry: irq=21 name=uhci_hcd:usb4
3449 sshd-1995 [001] d.h1 138.733280: irq_handler_exit: irq=21 ret=unhandled
3450 sshd-1995 [001] d.h1 138.733281: irq_handler_entry: irq=21 name=eth0
3451 sshd-1995 [001] d.h1 138.733283: irq_handler_exit: irq=21 ret=handled
3457 # entries-in-buffer/entries-written: 18996/18996 #P:4
3459 # _-----=> irqs-off
3460 # / _----=> need-resched
3461 # | / _---=> hardirq/softirq
3462 # || / _--=> preempt-depth
3464 # TASK-PID CPU# |||| TIMESTAMP FUNCTION
3466 bash-1998 [000] d... 140.733501: sys_write -> 0x2
3467 bash-1998 [000] d... 140.733504: sys_dup2(oldfd: a, newfd: 1)
3468 bash-1998 [000] d... 140.733506: sys_dup2 -> 0x1
3469 bash-1998 [000] d... 140.733508: sys_fcntl(fd: a, cmd: 1, arg: 0)
3470 bash-1998 [000] d... 140.733509: sys_fcntl -> 0x1
3471 bash-1998 [000] d... 140.733510: sys_close(fd: a)
3472 bash-1998 [000] d... 140.733510: sys_close -> 0x0
3473 …bash-1998 [000] d... 140.733514: sys_rt_sigprocmask(how: 0, nset: 0, oset: 6e2768, sigsetsize: …
3474 bash-1998 [000] d... 140.733515: sys_rt_sigprocmask -> 0x0
3475 …bash-1998 [000] d... 140.733516: sys_rt_sigaction(sig: 2, act: 7fff718846f0, oact: 7fff71884650…
3476 bash-1998 [000] d... 140.733516: sys_rt_sigaction -> 0x0
3494 -----------
3525 ----- ---- --------
3545 Note, if -mfentry is being used by gcc, functions get traced before
3547 are not tested by the stack tracer when -mfentry is used.
3549 Currently, -mfentry is used by gcc 4.6.0 and above on x86 only.
3552 ----