Lines Matching +full:off +full:- +full:on +full:- +full:delay +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 ------------
22 designers of systems to find what is going on inside the kernel.
24 performance issues that take place outside of user-space.
35 going on in certain parts of the kernel.
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
83 (cd /sys/kernel/tracing) and will only concentrate on the files within that
118 set this file to "0". User space can re-enable tracing by
123 be re-enabled by user space using this file.
130 Note, this file is not a consumer. If tracing is off
132 the same output each time it is read. When tracing is on,
192 meta-data. If the last page allocated has room for more bytes
196 due to buffer management meta-data. )
210 killed by a signal, this file can be used for that purpose. On close
220 This is a mask that lets the user only trace on specified CPUs.
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
345 will be displayed on the same line as the function that
349 the "ip modify" attribute (thus the regs->ip can be changed),
350 an 'I' will be displayed on the same line as the function that
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
453 clock is very fast and strictly per cpu, but on some
456 with local clocks on other CPUs.
461 [local] global counter x86-tsc
477 each other on different CPUs.
488 x86-tsc:
492 ppc-tb:
508 This is the boot clock (CLOCK_BOOTTIME) and is based on the
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.
698 event (ring buffer is re-entrant), that it fills the
711 Events lost due to overwrite option being off.
717 -----------
728 function tracer probes the functions on their entry
729 whereas the function graph tracer traces on both entry
751 trace with the latency-format option enabled, which
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
856 # ||| / delay
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
886 --------------------
888 When the latency-format option is enabled or when one of the latency
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
909 # |||| / delay
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>
930 never changes) and the version of the kernel upon which this was executed on
931 (3.8). Then it displays the max latency in microseconds (259 us). The number
942 - __lock_task_sighand is where the interrupts were disabled.
943 - _raw_spin_unlock_irqrestore is where they were enabled again.
952 CPU#: The CPU which the process was running on.
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
983 delay:
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.
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
1043 To enable an option, leave off the "no"::
1045 echo sym-offset > trace_options
1049 print-parent
1050 On function traces, display the calling (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
1131 ASLR is on, otherwise you don't get a chance to
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
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
1205 on write.
1207 event-fork
1215 function-trace
1222 function-fork
1231 display-graph
1267 funcgraph-overrun
1278 funcgraph-cpu
1282 funcgraph-overhead
1284 A certain amount, then a delay marker is
1285 displayed. See "delay" above, under the
1288 funcgraph-proc
1295 funcgraph-duration
1300 funcgraph-abstime
1303 funcgraph-irqs
1307 funcgraph-tail
1309 that it represents. By default this is off, and
1313 sleep-time
1319 graph-time
1333 -------
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
1375 # |||| / delay
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>
1400 timestamp 25us occurred because the clock was incremented
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
1426 # |||| / delay
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>
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 ----------
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
1574 # |||| / delay
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.
1590 the preempt off section and leaving it (the 'd'). We do not know if
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
1612 # |||| / delay
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
1726 # |||| / delay
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>
1754 The trace_hardirqs_off_thunk is called from assembly on x86 when
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
1779 # |||| / delay
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
1892 # |||| / delay
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
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.
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
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
1961 # |||| / delay
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
1970 Running this on an idle system, we see that it only took 5 microseconds
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
2010 # |||| / delay
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
2102 The interrupt went off while when the system was idle. Somewhere
2107 --------------------------
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
2136 # |||| / delay
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
2154 -------------------------
2167 # entries-in-buffer/entries-written: 13/13 #P:8
2169 # _-----=> irqs-off
2170 # / _----=> need-resched
2171 # | / _---=> hardirq/softirq
2172 # || / _--=> preempt-depth
2173 # ||| / delay
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
2213 nmi-total:7 nmi-count:1
2215 On architectures that support it, if an NMI comes in during the
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
2247 should run on.
2250 --------
2266 # entries-in-buffer/entries-written: 24799/24799 #P:4
2268 # _-----=> irqs-off
2269 # / _----=> need-resched
2270 # | / _---=> hardirq/softirq
2271 # || / _--=> preempt-depth
2272 # ||| / delay
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
2453 task_struct. On function entry the tracer overwrites the return
2455 original return address is stored on the stack of return address
2458 Probing on both ends of a function leads to special features
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
2467 need to see what happens in detail on any areas (or specific
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();
2506 want, depending on your needs.
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
2517 the closing bracket line of a function or on the same line
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() */
2659 You can put some comments on specific functions by using
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
2706 On boot up, before SMP is initialized, the dynamic ftrace code
2716 tracepoints is dependent on architecture. The old method is to use
2731 and can just slap the new code on top of the old without any
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
2780 # ||| / delay
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
2827 # ||| / delay
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
2916 # ||| / delay
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 --------------
3031 Note, the proc sysctl ftrace_enable is a big on/off switch for the
3053 ---------------
3062 - mod:
3070 filtering based on function names. Thus, adding more functions
3094 - traceon/traceoff:
3095 These commands turn tracing on and off when the specified
3097 tracing system is turned on and off. If unspecified, there is
3118 - snapshot:
3134 - enable_event/disable_event:
3158 - dump:
3165 - cpudump:
3171 - stacktrace:
3175 ----------
3178 the effect on the tracing is different. Every read from
3192 # entries-in-buffer/entries-written: 0/0 #P:4
3194 # _-----=> irqs-off
3195 # / _----=> need-resched
3196 # | / _---=> hardirq/softirq
3197 # || / _--=> preempt-depth
3198 # ||| / delay
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 --------
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
3330 # ||| / delay
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
3347 # ||| / delay
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…
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
3463 # ||| / delay
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 -----------
3497 what they allocate on the stack. If they add too much, the system
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 ----