Lines Matching +full:echo +full:- +full:active +full:- +full:ms
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.
41 ----------------------
43 See Documentation/trace/ftrace-design.rst for details for arch porters and such.
47 ---------------
60 mount -t tracefs nodev /sys/kernel/tracing
65 ln -s /sys/kernel/tracing /tracing
111 ring buffer is enabled. Echo 0 into this file to disable
118 set this file to "0". User space can re-enable tracing by
123 be re-enabled by user space using this file.
180 Only active when the file contains a number greater than 0.
192 0 - means to wake up as soon as there is any data in the ring buffer.
193 50 - means to wake up when roughly half of the ring buffer sub-buffers
195 100 - means to block until the ring buffer is totally full and is
207 meta-data. If the last page allocated has room for more bytes
211 due to buffer management meta-data. )
239 Note: When changing the sub-buffer size, tracing is stopped and any
296 If the "function-fork" option is set, then when a task whose
307 If the "function-fork" option is set, then when a task whose
323 added on fork, enable the "event-fork" option. That option will also
336 added on fork, enable the "event-fork" option. That option will also
366 for each function. The displayed address is the patch-site address
391 the "ip modify" attribute (thus the regs->ip can be changed),
476 If the option "record-cmd" is set to "0", then comms of tasks
482 increase or decrease the amount of comms that are cached, echo
487 If the option "record-tgid" is set, on each scheduling context switch
489 the thread to its TGID. By default, the "record-tgid" option is
528 [local] global counter x86-tsc
555 x86-tsc:
559 ppc-tb:
582 Also on 32-bit systems, it's possible that the 64-bit boot offset
588 This is the tai clock (CLOCK_TAI) and is derived from the wall-
599 To set a clock, simply echo the clock name into this file::
601 # echo global > trace_clock
702 delta: Default timestamp mode - timestamp is a delta against
703 a per-buffer timestamp.
777 event (ring buffer is re-entrant), that it fills the
796 -----------
836 trace with the latency-format option enabled, which
886 tracers from tracing simply echo "nop" into
890 ----------------
906 # echo xxx > /sys/kernel/tracing/events/sched/sched_wakeup/trigger
907 echo: write error: Invalid argument
917 To clear the error log, echo the empty string into it::
919 # echo > /sys/kernel/tracing/error_log
922 ----------------------------
926 user-land utilities).
929 --------------
935 # entries-in-buffer/entries-written: 140080/250280 #P:4
937 # _-----=> irqs-off
938 # / _----=> need-resched
939 # | / _---=> hardirq/softirq
940 # || / _--=> preempt-depth
942 # TASK-PID CPU# |||| TIMESTAMP FUNCTION
944 bash-1977 [000] .... 17284.993652: sys_close <-system_call_fastpath
945 bash-1977 [000] .... 17284.993653: __close_fd <-sys_close
946 bash-1977 [000] .... 17284.993653: _raw_spin_lock <-__close_fd
947 sshd-1974 [003] .... 17284.993653: __srcu_read_unlock <-fsnotify
948 bash-1977 [000] .... 17284.993654: add_preempt_count <-_raw_spin_lock
949 bash-1977 [000] ...1 17284.993655: _raw_spin_unlock <-__close_fd
950 bash-1977 [000] ...1 17284.993656: sub_preempt_count <-_raw_spin_unlock
951 bash-1977 [000] .... 17284.993657: filp_close <-__close_fd
952 bash-1977 [000] .... 17284.993657: dnotify_flush <-filp_close
953 sshd-1974 [003] .... 17284.993658: sys_select <-system_call_fastpath
960 lost due to the buffer filling up (250280 - 140080 = 110200 events
971 --------------------
973 When the latency-format option is enabled or when one of the latency
979 # irqsoff latency trace v1.1.5 on 3.8.0-test+
980 # --------------------------------------------------------------------
982 # -----------------
983 # | task: ps-6143 (uid:0 nice:0 policy:0 rt_prio:0)
984 # -----------------
989 # _------=> CPU#
990 # / _-----=> irqs-off
991 # | / _----=> need-resched
992 # || / _---=> hardirq/softirq
993 # ||| / _--=> preempt-depth
997 ps-6143 2d... 0us!: trace_hardirqs_off <-__lock_task_sighand
998 ps-6143 2d..1 259us+: trace_hardirqs_on <-_raw_spin_unlock_irqrestore
999 ps-6143 2d..1 263us+: time_hardirqs_on <-_raw_spin_unlock_irqrestore
1000 ps-6143 2d..1 306us : <stack trace>
1027 - __lock_task_sighand is where the interrupts were disabled.
1028 - _raw_spin_unlock_irqrestore is where they were enabled again.
1039 irqs-off: 'd' interrupts are disabled. '.' otherwise.
1041 need-resched:
1042 - 'B' all, TIF_NEED_RESCHED, PREEMPT_NEED_RESCHED and TIF_RESCHED_LAZY is set,
1043 - 'N' both TIF_NEED_RESCHED and PREEMPT_NEED_RESCHED is set,
1044 - 'n' only TIF_NEED_RESCHED is set,
1045 - 'p' only PREEMPT_NEED_RESCHED is set,
1046 - 'L' both PREEMPT_NEED_RESCHED and TIF_RESCHED_LAZY is set,
1047 - 'b' both TIF_NEED_RESCHED and TIF_RESCHED_LAZY is set,
1048 - 'l' only TIF_RESCHED_LAZY is set
1049 - '.' otherwise.
1052 - 'Z' - NMI occurred inside a hardirq
1053 - 'z' - NMI is running
1054 - 'H' - hard irq occurred inside a softirq.
1055 - 'h' - hard irq is running
1056 - 's' - soft irq is running
1057 - '.' - normal context.
1059 preempt-depth: The level of preempt_disabled
1064 When the latency-format option is enabled, the trace file
1066 trace. This differs from the output when latency-format
1075 - '$' - greater than 1 second
1076 - '@' - greater than 100 millisecond
1077 - '*' - greater than 10 millisecond
1078 - '#' - greater than 1000 microsecond
1079 - '!' - greater than 100 microsecond
1080 - '+' - greater than 10 microsecond
1081 - ' ' - less than or equal to 10 microsecond.
1089 -------------
1096 print-parent
1097 nosym-offset
1098 nosym-addr
1108 nosym-userobj
1109 noprintk-msg-only
1110 context-info
1111 nolatency-format
1112 record-cmd
1113 norecord-tgid
1116 irq-info
1118 noevent-fork
1119 function-trace
1120 nofunction-fork
1121 nodisplay-graph
1125 To disable one of the options, echo in the option prepended with
1128 echo noprint-parent > trace_options
1132 echo sym-offset > trace_options
1136 print-parent
1141 print-parent:
1142 bash-4000 [01] 1477.606694: simple_strtoul <-kstrtoul
1144 noprint-parent:
1145 bash-4000 [01] 1477.606694: simple_strtoul
1148 sym-offset
1155 sym-offset:
1156 bash-4000 [01] 1477.606694: simple_strtoul+0x6/0xa0
1158 sym-addr
1163 sym-addr:
1164 bash-4000 [01] 1477.606694: simple_strtoul <c0339346>
1168 latency-format option is enabled.
1171 bash 4000 1 0 00000000 00010a95 [58127d26] 1720.415ms \
1172 (+0.000ms): simple_strtoul (kstrtoul)
1231 <idle>-0 [001] dNs4 21169.031481: wake_up_idle_cpu <-add_timer_on
1232 <idle>-0 [001] dNs4 21169.031482: _raw_spin_unlock_irqrestore <-add_timer_on
1233 <idle>-0 [001] .Ns4 21169.031484: sub_preempt_count <-_raw_spin_unlock_irqrestore
1235 <idle>-0 [002] .N.1 21169.031484: rcu_idle_exit <-cpu_idle
1236 <idle>-0 [001] .Ns3 21169.031484: _raw_spin_unlock <-clocksource_watchdog
1237 <idle>-0 [001] .Ns3 21169.031485: sub_preempt_count <-_raw_spin_unlock
1244 sym-userobj
1255 a.out-1623 [000] 40874.465068: /root/a.out[+0x480] <-/root/a.out[+0
1256 x494] <- /root/a.out[+0x4a8] <- /lib/libc-2.7.so[+0x1e1a6]
1259 printk-msg-only
1264 context-info
1268 latency-format
1273 pause-on-trace
1279 hash-ptr
1285 record-cmd
1293 record-tgid
1310 irq-info
1316 # entries-in-buffer/entries-written: 144405/9452052 #P:4
1318 # TASK-PID CPU# TIMESTAMP FUNCTION
1320 <idle>-0 [002] 23636.756054: ttwu_do_activate.constprop.89 <-try_to_wake_up
1321 <idle>-0 [002] 23636.756054: activate_task <-ttwu_do_activate.constprop.89
1322 <idle>-0 [002] 23636.756055: enqueue_task <-activate_task
1330 event-fork
1338 function-trace
1345 function-fork
1354 display-graph
1369 file when the tracer is active. They always appear in the
1390 funcgraph-overrun
1401 funcgraph-cpu
1405 funcgraph-overhead
1411 funcgraph-proc
1418 funcgraph-duration
1423 funcgraph-abstime
1426 funcgraph-irqs
1430 funcgraph-tail
1436 funcgraph-retval
1441 funcgraph-retval-hex
1449 sleep-time
1455 graph-time
1469 -------
1483 To reset the maximum, echo 0 into tracing_max_latency. Here is
1486 # echo 0 > options/function-trace
1487 # echo irqsoff > current_tracer
1488 # echo 1 > tracing_on
1489 # echo 0 > tracing_max_latency
1490 # ls -ltr
1492 # echo 0 > tracing_on
1496 # irqsoff latency trace v1.1.5 on 3.8.0-test+
1497 # --------------------------------------------------------------------
1499 # -----------------
1500 # | task: swapper/0-0 (uid:0 nice:0 policy:0 rt_prio:0)
1501 # -----------------
1506 # _------=> CPU#
1507 # / _-----=> irqs-off
1508 # | / _----=> need-resched
1509 # || / _---=> hardirq/softirq
1510 # ||| / _--=> preempt-depth
1514 <idle>-0 0d.s2 0us+: _raw_spin_lock_irq <-run_timer_softirq
1515 <idle>-0 0dNs3 17us : _raw_spin_unlock_irq <-run_timer_softirq
1516 <idle>-0 0dNs3 17us+: trace_hardirqs_on <-run_timer_softirq
1517 <idle>-0 0dNs3 25us : <stack trace>
1540 Note the above example had function-trace not set. If we set
1541 function-trace, we get a much larger output::
1543 with echo 1 > options/function-trace
1547 # irqsoff latency trace v1.1.5 on 3.8.0-test+
1548 # --------------------------------------------------------------------
1550 # -----------------
1551 # | task: bash-2042 (uid:0 nice:0 policy:0 rt_prio:0)
1552 # -----------------
1557 # _------=> CPU#
1558 # / _-----=> irqs-off
1559 # | / _----=> need-resched
1560 # || / _---=> hardirq/softirq
1561 # ||| / _--=> preempt-depth
1565 bash-2042 3d... 0us : _raw_spin_lock_irqsave <-ata_scsi_queuecmd
1566 bash-2042 3d... 0us : add_preempt_count <-_raw_spin_lock_irqsave
1567 bash-2042 3d..1 1us : ata_scsi_find_dev <-ata_scsi_queuecmd
1568 bash-2042 3d..1 1us : __ata_scsi_find_dev <-ata_scsi_find_dev
1569 bash-2042 3d..1 2us : ata_find_dev.part.14 <-__ata_scsi_find_dev
1570 bash-2042 3d..1 2us : ata_qc_new_init <-__ata_scsi_queuecmd
1571 bash-2042 3d..1 3us : ata_sg_init <-__ata_scsi_queuecmd
1572 bash-2042 3d..1 4us : ata_scsi_rw_xlat <-__ata_scsi_queuecmd
1573 bash-2042 3d..1 4us : ata_build_rw_tf <-ata_scsi_rw_xlat
1575 bash-2042 3d..1 67us : delay_tsc <-__delay
1576 bash-2042 3d..1 67us : add_preempt_count <-delay_tsc
1577 bash-2042 3d..2 67us : sub_preempt_count <-delay_tsc
1578 bash-2042 3d..1 67us : add_preempt_count <-delay_tsc
1579 bash-2042 3d..2 68us : sub_preempt_count <-delay_tsc
1580 bash-2042 3d..1 68us+: ata_bmdma_start <-ata_bmdma_qc_issue
1581 bash-2042 3d..1 71us : _raw_spin_unlock_irqrestore <-ata_scsi_queuecmd
1582 bash-2042 3d..1 71us : _raw_spin_unlock_irqrestore <-ata_scsi_queuecmd
1583 bash-2042 3d..1 72us+: trace_hardirqs_on <-ata_scsi_queuecmd
1584 bash-2042 3d..1 120us : <stack trace>
1619 display-graph option::
1621 with echo 1 > options/display-graph
1625 # irqsoff latency trace v1.1.5 on 4.20.0-rc6+
1626 # --------------------------------------------------------------------
1628 # -----------------
1629 # | task: bash-1507 (uid:0 nice:0 policy:0 rt_prio:0)
1630 # -----------------
1635 # _-----=> irqs-off
1636 # / _----=> need-resched
1637 # | / _---=> hardirq/softirq
1638 # || / _--=> preempt-depth
1642 0 us | 0) bash-1507 | d... | 0.000 us | _raw_spin_lock_irqsave();
1643 0 us | 0) bash-1507 | d..1 | 0.378 us | do_raw_spin_trylock();
1644 1 us | 0) bash-1507 | d..2 | | set_track() {
1645 2 us | 0) bash-1507 | d..2 | | save_stack_trace() {
1646 2 us | 0) bash-1507 | d..2 | | __save_stack_trace() {
1647 3 us | 0) bash-1507 | d..2 | | __unwind_start() {
1648 3 us | 0) bash-1507 | d..2 | | get_stack_info() {
1649 3 us | 0) bash-1507 | d..2 | 0.351 us | in_task_stack();
1650 4 us | 0) bash-1507 | d..2 | 1.107 us | }
1652 3750 us | 0) bash-1507 | d..1 | 0.516 us | do_raw_spin_unlock();
1653 3750 us | 0) bash-1507 | d..1 | 0.000 us | _raw_spin_unlock_irqrestore();
1654 3764 us | 0) bash-1507 | d..1 | 0.000 us | tracer_hardirqs_on();
1655 bash-1507 0d..1 3792us : <stack trace>
1672 ----------
1685 # echo 0 > options/function-trace
1686 # echo preemptoff > current_tracer
1687 # echo 1 > tracing_on
1688 # echo 0 > tracing_max_latency
1689 # ls -ltr
1691 # echo 0 > tracing_on
1695 # preemptoff latency trace v1.1.5 on 3.8.0-test+
1696 # --------------------------------------------------------------------
1698 # -----------------
1699 # | task: sshd-1991 (uid:0 nice:0 policy:0 rt_prio:0)
1700 # -----------------
1705 # _------=> CPU#
1706 # / _-----=> irqs-off
1707 # | / _----=> need-resched
1708 # || / _---=> hardirq/softirq
1709 # ||| / _--=> preempt-depth
1713 sshd-1991 1d.h. 0us+: irq_enter <-do_IRQ
1714 sshd-1991 1d..1 46us : irq_exit <-do_IRQ
1715 sshd-1991 1d..1 47us+: trace_preempt_on <-do_IRQ
1716 sshd-1991 1d..1 52us : <stack trace>
1733 # preemptoff latency trace v1.1.5 on 3.8.0-test+
1734 # --------------------------------------------------------------------
1736 # -----------------
1737 # | task: bash-1994 (uid:0 nice:0 policy:0 rt_prio:0)
1738 # -----------------
1743 # _------=> CPU#
1744 # / _-----=> irqs-off
1745 # | / _----=> need-resched
1746 # || / _---=> hardirq/softirq
1747 # ||| / _--=> preempt-depth
1751 bash-1994 1d..1 0us : _raw_spin_lock_irqsave <-wake_up_new_task
1752 bash-1994 1d..1 0us : select_task_rq_fair <-select_task_rq
1753 bash-1994 1d..1 1us : __rcu_read_lock <-select_task_rq_fair
1754 bash-1994 1d..1 1us : source_load <-select_task_rq_fair
1755 bash-1994 1d..1 1us : source_load <-select_task_rq_fair
1757 bash-1994 1d..1 12us : irq_enter <-smp_apic_timer_interrupt
1758 bash-1994 1d..1 12us : rcu_irq_enter <-irq_enter
1759 bash-1994 1d..1 13us : add_preempt_count <-irq_enter
1760 bash-1994 1d.h1 13us : exit_idle <-smp_apic_timer_interrupt
1761 bash-1994 1d.h1 13us : hrtimer_interrupt <-smp_apic_timer_interrupt
1762 bash-1994 1d.h1 13us : _raw_spin_lock <-hrtimer_interrupt
1763 bash-1994 1d.h1 14us : add_preempt_count <-_raw_spin_lock
1764 bash-1994 1d.h2 14us : ktime_get_update_offsets <-hrtimer_interrupt
1766 bash-1994 1d.h1 35us : lapic_next_event <-clockevents_program_event
1767 bash-1994 1d.h1 35us : irq_exit <-smp_apic_timer_interrupt
1768 bash-1994 1d.h1 36us : sub_preempt_count <-irq_exit
1769 bash-1994 1d..2 36us : do_softirq <-irq_exit
1770 bash-1994 1d..2 36us : __do_softirq <-call_softirq
1771 bash-1994 1d..2 36us : __local_bh_disable <-__do_softirq
1772 bash-1994 1d.s2 37us : add_preempt_count <-_raw_spin_lock_irq
1773 bash-1994 1d.s3 38us : _raw_spin_unlock <-run_timer_softirq
1774 bash-1994 1d.s3 39us : sub_preempt_count <-_raw_spin_unlock
1775 bash-1994 1d.s2 39us : call_timer_fn <-run_timer_softirq
1777 bash-1994 1dNs2 81us : cpu_needs_another_gp <-rcu_process_callbacks
1778 bash-1994 1dNs2 82us : __local_bh_enable <-__do_softirq
1779 bash-1994 1dNs2 82us : sub_preempt_count <-__local_bh_enable
1780 bash-1994 1dN.2 82us : idle_cpu <-irq_exit
1781 bash-1994 1dN.2 83us : rcu_irq_exit <-irq_exit
1782 bash-1994 1dN.2 83us : sub_preempt_count <-irq_exit
1783 bash-1994 1.N.1 84us : _raw_spin_unlock_irqrestore <-task_rq_unlock
1784 bash-1994 1.N.1 84us+: trace_preempt_on <-task_rq_unlock
1785 bash-1994 1.N.1 104us : <stack trace>
1796 function-trace set. Here we see that interrupts were not disabled
1803 --------------
1837 # echo 0 > options/function-trace
1838 # echo preemptirqsoff > current_tracer
1839 # echo 1 > tracing_on
1840 # echo 0 > tracing_max_latency
1841 # ls -ltr
1843 # echo 0 > tracing_on
1847 # preemptirqsoff latency trace v1.1.5 on 3.8.0-test+
1848 # --------------------------------------------------------------------
1850 # -----------------
1851 # | task: ls-2230 (uid:0 nice:0 policy:0 rt_prio:0)
1852 # -----------------
1857 # _------=> CPU#
1858 # / _-----=> irqs-off
1859 # | / _----=> need-resched
1860 # || / _---=> hardirq/softirq
1861 # ||| / _--=> preempt-depth
1865 ls-2230 3d... 0us+: _raw_spin_lock_irqsave <-ata_scsi_queuecmd
1866 ls-2230 3...1 100us : _raw_spin_unlock_irqrestore <-ata_scsi_queuecmd
1867 ls-2230 3...1 101us+: trace_preempt_on <-ata_scsi_queuecmd
1868 ls-2230 3...1 111us : <stack trace>
1896 Here is a trace with function-trace set::
1900 # preemptirqsoff latency trace v1.1.5 on 3.8.0-test+
1901 # --------------------------------------------------------------------
1903 # -----------------
1904 # | task: ls-2269 (uid:0 nice:0 policy:0 rt_prio:0)
1905 # -----------------
1910 # _------=> CPU#
1911 # / _-----=> irqs-off
1912 # | / _----=> need-resched
1913 # || / _---=> hardirq/softirq
1914 # ||| / _--=> preempt-depth
1918 kworker/-59 3...1 0us : __schedule <-schedule
1919 kworker/-59 3d..1 0us : rcu_preempt_qs <-rcu_note_context_switch
1920 kworker/-59 3d..1 1us : add_preempt_count <-_raw_spin_lock_irq
1921 kworker/-59 3d..2 1us : deactivate_task <-__schedule
1922 kworker/-59 3d..2 1us : dequeue_task <-deactivate_task
1923 kworker/-59 3d..2 2us : update_rq_clock <-dequeue_task
1924 kworker/-59 3d..2 2us : dequeue_task_fair <-dequeue_task
1925 kworker/-59 3d..2 2us : update_curr <-dequeue_task_fair
1926 kworker/-59 3d..2 2us : update_min_vruntime <-update_curr
1927 kworker/-59 3d..2 3us : cpuacct_charge <-update_curr
1928 kworker/-59 3d..2 3us : __rcu_read_lock <-cpuacct_charge
1929 kworker/-59 3d..2 3us : __rcu_read_unlock <-cpuacct_charge
1930 kworker/-59 3d..2 3us : update_cfs_rq_blocked_load <-dequeue_task_fair
1931 kworker/-59 3d..2 4us : clear_buddies <-dequeue_task_fair
1932 kworker/-59 3d..2 4us : account_entity_dequeue <-dequeue_task_fair
1933 kworker/-59 3d..2 4us : update_min_vruntime <-dequeue_task_fair
1934 kworker/-59 3d..2 4us : update_cfs_shares <-dequeue_task_fair
1935 kworker/-59 3d..2 5us : hrtick_update <-dequeue_task_fair
1936 kworker/-59 3d..2 5us : wq_worker_sleeping <-__schedule
1937 kworker/-59 3d..2 5us : kthread_data <-wq_worker_sleeping
1938 kworker/-59 3d..2 5us : put_prev_task_fair <-__schedule
1939 kworker/-59 3d..2 6us : pick_next_task_fair <-pick_next_task
1940 kworker/-59 3d..2 6us : clear_buddies <-pick_next_task_fair
1941 kworker/-59 3d..2 6us : set_next_entity <-pick_next_task_fair
1942 kworker/-59 3d..2 6us : update_stats_wait_end <-set_next_entity
1943 ls-2269 3d..2 7us : finish_task_switch <-__schedule
1944 ls-2269 3d..2 7us : _raw_spin_unlock_irq <-finish_task_switch
1945 ls-2269 3d..2 8us : do_IRQ <-ret_from_intr
1946 ls-2269 3d..2 8us : irq_enter <-do_IRQ
1947 ls-2269 3d..2 8us : rcu_irq_enter <-irq_enter
1948 ls-2269 3d..2 9us : add_preempt_count <-irq_enter
1949 ls-2269 3d.h2 9us : exit_idle <-do_IRQ
1951 ls-2269 3d.h3 20us : sub_preempt_count <-_raw_spin_unlock
1952 ls-2269 3d.h2 20us : irq_exit <-do_IRQ
1953 ls-2269 3d.h2 21us : sub_preempt_count <-irq_exit
1954 ls-2269 3d..3 21us : do_softirq <-irq_exit
1955 ls-2269 3d..3 21us : __do_softirq <-call_softirq
1956 ls-2269 3d..3 21us+: __local_bh_disable <-__do_softirq
1957 ls-2269 3d.s4 29us : sub_preempt_count <-_local_bh_enable_ip
1958 ls-2269 3d.s5 29us : sub_preempt_count <-_local_bh_enable_ip
1959 ls-2269 3d.s5 31us : do_IRQ <-ret_from_intr
1960 ls-2269 3d.s5 31us : irq_enter <-do_IRQ
1961 ls-2269 3d.s5 31us : rcu_irq_enter <-irq_enter
1963 ls-2269 3d.s5 31us : rcu_irq_enter <-irq_enter
1964 ls-2269 3d.s5 32us : add_preempt_count <-irq_enter
1965 ls-2269 3d.H5 32us : exit_idle <-do_IRQ
1966 ls-2269 3d.H5 32us : handle_irq <-do_IRQ
1967 ls-2269 3d.H5 32us : irq_to_desc <-handle_irq
1968 ls-2269 3d.H5 33us : handle_fasteoi_irq <-handle_irq
1970 ls-2269 3d.s5 158us : _raw_spin_unlock_irqrestore <-rtl8139_poll
1971 ls-2269 3d.s3 158us : net_rps_action_and_irq_enable.isra.65 <-net_rx_action
1972 ls-2269 3d.s3 159us : __local_bh_enable <-__do_softirq
1973 ls-2269 3d.s3 159us : sub_preempt_count <-__local_bh_enable
1974 ls-2269 3d..3 159us : idle_cpu <-irq_exit
1975 ls-2269 3d..3 159us : rcu_irq_exit <-irq_exit
1976 ls-2269 3d..3 160us : sub_preempt_count <-irq_exit
1977 ls-2269 3d... 161us : __mutex_unlock_slowpath <-mutex_unlock
1978 ls-2269 3d... 162us+: trace_hardirqs_on <-mutex_unlock
1979 ls-2269 3d... 186us : <stack trace>
1998 ------
2002 Now for non Real-Time tasks, this can be arbitrary. But tracing
2007 # echo 0 > options/function-trace
2008 # echo wakeup > current_tracer
2009 # echo 1 > tracing_on
2010 # echo 0 > tracing_max_latency
2011 # chrt -f 5 sleep 1
2012 # echo 0 > tracing_on
2016 # wakeup latency trace v1.1.5 on 3.8.0-test+
2017 # --------------------------------------------------------------------
2019 # -----------------
2020 # | task: kworker/3:1H-312 (uid:0 nice:-20 policy:0 rt_prio:0)
2021 # -----------------
2023 # _------=> CPU#
2024 # / _-----=> irqs-off
2025 # | / _----=> need-resched
2026 # || / _---=> hardirq/softirq
2027 # ||| / _--=> preempt-depth
2031 <idle>-0 3dNs7 0us : 0:120:R + [003] 312:100:R kworker/3:1H
2032 <idle>-0 3dNs7 1us+: ttwu_do_activate.constprop.87 <-try_to_wake_up
2033 <idle>-0 3d..3 15us : __schedule <-schedule
2034 <idle>-0 3d..3 15us : 0:120:R ==> [003] 312:100:R kworker/3:1H
2038 the kworker with a nice priority of -20 (not very nice), took
2042 Non Real-Time tasks are not that interesting. A more interesting
2043 trace is to concentrate only on Real-Time tasks.
2046 ---------
2048 In a Real-Time environment it is very important to know the
2052 also important to know the scheduling latency of non-RT tasks,
2053 but the average schedule latency is better for non-RT tasks.
2057 Real-Time environments are interested in the worst case latency.
2061 work well with Real-Time tasks. The wakeup_rt tracer was designed
2062 to record the worst case wakeups of RT tasks. Non-RT tasks are
2064 tracing non-RT tasks that are unpredictable will overwrite the
2074 # echo 0 > options/function-trace
2075 # echo wakeup_rt > current_tracer
2076 # echo 1 > tracing_on
2077 # echo 0 > tracing_max_latency
2078 # chrt -f 5 sleep 1
2079 # echo 0 > tracing_on
2085 # wakeup_rt latency trace v1.1.5 on 3.8.0-test+
2086 # --------------------------------------------------------------------
2088 # -----------------
2089 # | task: sleep-2389 (uid:0 nice:0 policy:1 rt_prio:5)
2090 # -----------------
2092 # _------=> CPU#
2093 # / _-----=> irqs-off
2094 # | / _----=> need-resched
2095 # || / _---=> hardirq/softirq
2096 # ||| / _--=> preempt-depth
2100 <idle>-0 3d.h4 0us : 0:120:R + [003] 2389: 94:R sleep
2101 <idle>-0 3d.h4 1us+: ttwu_do_activate.constprop.87 <-try_to_wake_up
2102 <idle>-0 3d..3 5us : __schedule <-schedule
2103 <idle>-0 3d..3 5us : 0:120:R ==> [003] 2389: 94:R sleep
2113 and it has an rt_prio of 5. This priority is user-space priority
2117 Note, that the trace data shows the internal priority (99 - rtprio).
2120 <idle>-0 3d..3 5us : 0:120:R ==> [003] 2389: 94:R sleep
2122 The 0:120:R means idle was running with a nice priority of 0 (120 - 120)
2124 2389: 94:R. That is the priority is the kernel rtprio (99 - 5 = 94)
2127 Doing the same with chrt -r 5 and function-trace set.
2130 echo 1 > options/function-trace
2134 # wakeup_rt latency trace v1.1.5 on 3.8.0-test+
2135 # --------------------------------------------------------------------
2137 # -----------------
2138 # | task: sleep-2448 (uid:0 nice:0 policy:1 rt_prio:5)
2139 # -----------------
2141 # _------=> CPU#
2142 # / _-----=> irqs-off
2143 # | / _----=> need-resched
2144 # || / _---=> hardirq/softirq
2145 # ||| / _--=> preempt-depth
2149 <idle>-0 3d.h4 1us+: 0:120:R + [003] 2448: 94:R sleep
2150 <idle>-0 3d.h4 2us : ttwu_do_activate.constprop.87 <-try_to_wake_up
2151 <idle>-0 3d.h3 3us : check_preempt_curr <-ttwu_do_wakeup
2152 <idle>-0 3d.h3 3us : resched_curr <-check_preempt_curr
2153 <idle>-0 3dNh3 4us : task_woken_rt <-ttwu_do_wakeup
2154 <idle>-0 3dNh3 4us : _raw_spin_unlock <-try_to_wake_up
2155 <idle>-0 3dNh3 4us : sub_preempt_count <-_raw_spin_unlock
2156 <idle>-0 3dNh2 5us : ttwu_stat <-try_to_wake_up
2157 <idle>-0 3dNh2 5us : _raw_spin_unlock_irqrestore <-try_to_wake_up
2158 <idle>-0 3dNh2 6us : sub_preempt_count <-_raw_spin_unlock_irqrestore
2159 <idle>-0 3dNh1 6us : _raw_spin_lock <-__run_hrtimer
2160 <idle>-0 3dNh1 6us : add_preempt_count <-_raw_spin_lock
2161 <idle>-0 3dNh2 7us : _raw_spin_unlock <-hrtimer_interrupt
2162 <idle>-0 3dNh2 7us : sub_preempt_count <-_raw_spin_unlock
2163 <idle>-0 3dNh1 7us : tick_program_event <-hrtimer_interrupt
2164 <idle>-0 3dNh1 7us : clockevents_program_event <-tick_program_event
2165 <idle>-0 3dNh1 8us : ktime_get <-clockevents_program_event
2166 <idle>-0 3dNh1 8us : lapic_next_event <-clockevents_program_event
2167 <idle>-0 3dNh1 8us : irq_exit <-smp_apic_timer_interrupt
2168 <idle>-0 3dNh1 9us : sub_preempt_count <-irq_exit
2169 <idle>-0 3dN.2 9us : idle_cpu <-irq_exit
2170 <idle>-0 3dN.2 9us : rcu_irq_exit <-irq_exit
2171 <idle>-0 3dN.2 10us : rcu_eqs_enter_common.isra.45 <-rcu_irq_exit
2172 <idle>-0 3dN.2 10us : sub_preempt_count <-irq_exit
2173 <idle>-0 3.N.1 11us : rcu_idle_exit <-cpu_idle
2174 <idle>-0 3dN.1 11us : rcu_eqs_exit_common.isra.43 <-rcu_idle_exit
2175 <idle>-0 3.N.1 11us : tick_nohz_idle_exit <-cpu_idle
2176 <idle>-0 3dN.1 12us : menu_hrtimer_cancel <-tick_nohz_idle_exit
2177 <idle>-0 3dN.1 12us : ktime_get <-tick_nohz_idle_exit
2178 <idle>-0 3dN.1 12us : tick_do_update_jiffies64 <-tick_nohz_idle_exit
2179 <idle>-0 3dN.1 13us : cpu_load_update_nohz <-tick_nohz_idle_exit
2180 <idle>-0 3dN.1 13us : _raw_spin_lock <-cpu_load_update_nohz
2181 <idle>-0 3dN.1 13us : add_preempt_count <-_raw_spin_lock
2182 <idle>-0 3dN.2 13us : __cpu_load_update <-cpu_load_update_nohz
2183 <idle>-0 3dN.2 14us : sched_avg_update <-__cpu_load_update
2184 <idle>-0 3dN.2 14us : _raw_spin_unlock <-cpu_load_update_nohz
2185 <idle>-0 3dN.2 14us : sub_preempt_count <-_raw_spin_unlock
2186 <idle>-0 3dN.1 15us : calc_load_nohz_stop <-tick_nohz_idle_exit
2187 <idle>-0 3dN.1 15us : touch_softlockup_watchdog <-tick_nohz_idle_exit
2188 <idle>-0 3dN.1 15us : hrtimer_cancel <-tick_nohz_idle_exit
2189 <idle>-0 3dN.1 15us : hrtimer_try_to_cancel <-hrtimer_cancel
2190 <idle>-0 3dN.1 16us : lock_hrtimer_base.isra.18 <-hrtimer_try_to_cancel
2191 <idle>-0 3dN.1 16us : _raw_spin_lock_irqsave <-lock_hrtimer_base.isra.18
2192 <idle>-0 3dN.1 16us : add_preempt_count <-_raw_spin_lock_irqsave
2193 <idle>-0 3dN.2 17us : __remove_hrtimer <-remove_hrtimer.part.16
2194 <idle>-0 3dN.2 17us : hrtimer_force_reprogram <-__remove_hrtimer
2195 <idle>-0 3dN.2 17us : tick_program_event <-hrtimer_force_reprogram
2196 <idle>-0 3dN.2 18us : clockevents_program_event <-tick_program_event
2197 <idle>-0 3dN.2 18us : ktime_get <-clockevents_program_event
2198 <idle>-0 3dN.2 18us : lapic_next_event <-clockevents_program_event
2199 <idle>-0 3dN.2 19us : _raw_spin_unlock_irqrestore <-hrtimer_try_to_cancel
2200 <idle>-0 3dN.2 19us : sub_preempt_count <-_raw_spin_unlock_irqrestore
2201 <idle>-0 3dN.1 19us : hrtimer_forward <-tick_nohz_idle_exit
2202 <idle>-0 3dN.1 20us : ktime_add_safe <-hrtimer_forward
2203 <idle>-0 3dN.1 20us : ktime_add_safe <-hrtimer_forward
2204 <idle>-0 3dN.1 20us : hrtimer_start_range_ns <-hrtimer_start_expires.constprop.11
2205 <idle>-0 3dN.1 20us : __hrtimer_start_range_ns <-hrtimer_start_range_ns
2206 <idle>-0 3dN.1 21us : lock_hrtimer_base.isra.18 <-__hrtimer_start_range_ns
2207 <idle>-0 3dN.1 21us : _raw_spin_lock_irqsave <-lock_hrtimer_base.isra.18
2208 <idle>-0 3dN.1 21us : add_preempt_count <-_raw_spin_lock_irqsave
2209 <idle>-0 3dN.2 22us : ktime_add_safe <-__hrtimer_start_range_ns
2210 <idle>-0 3dN.2 22us : enqueue_hrtimer <-__hrtimer_start_range_ns
2211 <idle>-0 3dN.2 22us : tick_program_event <-__hrtimer_start_range_ns
2212 <idle>-0 3dN.2 23us : clockevents_program_event <-tick_program_event
2213 <idle>-0 3dN.2 23us : ktime_get <-clockevents_program_event
2214 <idle>-0 3dN.2 23us : lapic_next_event <-clockevents_program_event
2215 <idle>-0 3dN.2 24us : _raw_spin_unlock_irqrestore <-__hrtimer_start_range_ns
2216 <idle>-0 3dN.2 24us : sub_preempt_count <-_raw_spin_unlock_irqrestore
2217 <idle>-0 3dN.1 24us : account_idle_ticks <-tick_nohz_idle_exit
2218 <idle>-0 3dN.1 24us : account_idle_time <-account_idle_ticks
2219 <idle>-0 3.N.1 25us : sub_preempt_count <-cpu_idle
2220 <idle>-0 3.N.. 25us : schedule <-cpu_idle
2221 <idle>-0 3.N.. 25us : __schedule <-preempt_schedule
2222 <idle>-0 3.N.. 26us : add_preempt_count <-__schedule
2223 <idle>-0 3.N.1 26us : rcu_note_context_switch <-__schedule
2224 <idle>-0 3.N.1 26us : rcu_sched_qs <-rcu_note_context_switch
2225 <idle>-0 3dN.1 27us : rcu_preempt_qs <-rcu_note_context_switch
2226 <idle>-0 3.N.1 27us : _raw_spin_lock_irq <-__schedule
2227 <idle>-0 3dN.1 27us : add_preempt_count <-_raw_spin_lock_irq
2228 <idle>-0 3dN.2 28us : put_prev_task_idle <-__schedule
2229 <idle>-0 3dN.2 28us : pick_next_task_stop <-pick_next_task
2230 <idle>-0 3dN.2 28us : pick_next_task_rt <-pick_next_task
2231 <idle>-0 3dN.2 29us : dequeue_pushable_task <-pick_next_task_rt
2232 <idle>-0 3d..3 29us : __schedule <-preempt_schedule
2233 <idle>-0 3d..3 30us : 0:120:R ==> [003] 2448: 94:R sleep
2243 --------------------------
2250 # echo 0 > options/function-trace
2251 # echo wakeup_rt > current_tracer
2252 # echo 1 > events/enable
2253 # echo 1 > tracing_on
2254 # echo 0 > tracing_max_latency
2255 # chrt -f 5 sleep 1
2256 # echo 0 > tracing_on
2260 # wakeup_rt latency trace v1.1.5 on 3.8.0-test+
2261 # --------------------------------------------------------------------
2263 # -----------------
2264 # | task: sleep-5882 (uid:0 nice:0 policy:1 rt_prio:5)
2265 # -----------------
2267 # _------=> CPU#
2268 # / _-----=> irqs-off
2269 # | / _----=> need-resched
2270 # || / _---=> hardirq/softirq
2271 # ||| / _--=> preempt-depth
2275 <idle>-0 2d.h4 0us : 0:120:R + [002] 5882: 94:R sleep
2276 <idle>-0 2d.h4 0us : ttwu_do_activate.constprop.87 <-try_to_wake_up
2277 <idle>-0 2d.h4 1us : sched_wakeup: comm=sleep pid=5882 prio=94 success=1 target_cpu=002
2278 <idle>-0 2dNh2 1us : hrtimer_expire_exit: hrtimer=ffff88007796feb8
2279 <idle>-0 2.N.2 2us : power_end: cpu_id=2
2280 <idle>-0 2.N.2 3us : cpu_idle: state=4294967295 cpu_id=2
2281 <idle>-0 2dN.3 4us : hrtimer_cancel: hrtimer=ffff88007d50d5e0
2282 …<idle>-0 2dN.3 4us : hrtimer_start: hrtimer=ffff88007d50d5e0 function=tick_sched_timer ex…
2283 <idle>-0 2.N.2 5us : rcu_utilization: Start context switch
2284 <idle>-0 2.N.2 5us : rcu_utilization: End context switch
2285 <idle>-0 2d..3 6us : __schedule <-schedule
2286 <idle>-0 2d..3 6us : 0:120:R ==> [002] 5882: 94:R sleep
2290 -------------------------
2298 # echo hwlat > current_tracer
2303 # entries-in-buffer/entries-written: 13/13 #P:8
2305 # _-----=> irqs-off
2306 # / _----=> need-resched
2307 # | / _---=> hardirq/softirq
2308 # || / _--=> preempt-depth
2310 # TASK-PID CPU# |||| TIMESTAMP FUNCTION
2312 …<...>-1729 [001] d... 678.473449: #1 inner/outer(us): 11/12 ts:1581527483.343962693 co…
2313 …<...>-1729 [004] d... 689.556542: #2 inner/outer(us): 16/9 ts:1581527494.889008092 co…
2314 …<...>-1729 [005] d... 714.756290: #3 inner/outer(us): 16/16 ts:1581527519.678961629 co…
2315 …<...>-1729 [001] d... 718.788247: #4 inner/outer(us): 9/17 ts:1581527523.889012713 co…
2316 …<...>-1729 [002] d... 719.796341: #5 inner/outer(us): 13/9 ts:1581527524.912872606 co…
2317 …<...>-1729 [006] d... 844.787091: #6 inner/outer(us): 9/12 ts:1581527649.889048502 co…
2318 …<...>-1729 [003] d... 849.827033: #7 inner/outer(us): 18/9 ts:1581527654.889013793 co…
2319 …<...>-1729 [007] d... 853.859002: #8 inner/outer(us): 9/12 ts:1581527658.889065736 co…
2320 …<...>-1729 [001] d... 855.874978: #9 inner/outer(us): 9/11 ts:1581527660.861991877 co…
2321 …<...>-1729 [001] d... 863.938932: #10 inner/outer(us): 9/11 ts:1581527668.970010500 co…
2322 …<...>-1729 [007] d... 878.050780: #11 inner/outer(us): 9/12 ts:1581527683.385002600 co…
2323 …<...>-1729 [007] d... 886.114702: #12 inner/outer(us): 9/12 ts:1581527691.385001600 co…
2349 nmi-total:7 nmi-count:1
2352 test, the time spent in NMI is reported in "nmi-total" (in
2355 All architectures that have NMIs will show the "nmi-count" if an
2386 --------
2395 # echo function > current_tracer
2396 # echo 1 > tracing_on
2398 # echo 0 > tracing_on
2402 # entries-in-buffer/entries-written: 24799/24799 #P:4
2404 # _-----=> irqs-off
2405 # / _----=> need-resched
2406 # | / _---=> hardirq/softirq
2407 # || / _--=> preempt-depth
2409 # TASK-PID CPU# |||| TIMESTAMP FUNCTION
2411 bash-1994 [002] .... 3082.063030: mutex_unlock <-rb_simple_write
2412 bash-1994 [002] .... 3082.063031: __mutex_unlock_slowpath <-mutex_unlock
2413 bash-1994 [002] .... 3082.063031: __fsnotify_parent <-fsnotify_modify
2414 bash-1994 [002] .... 3082.063032: fsnotify <-fsnotify_modify
2415 bash-1994 [002] .... 3082.063032: __srcu_read_lock <-fsnotify
2416 bash-1994 [002] .... 3082.063032: add_preempt_count <-__srcu_read_lock
2417 bash-1994 [002] ...1 3082.063032: sub_preempt_count <-__srcu_read_lock
2418 bash-1994 [002] .... 3082.063033: __srcu_read_unlock <-fsnotify
2424 Sometimes using echo to stop the trace is not sufficient because
2446 ---------------------
2453 # echo 3111 > set_ftrace_pid
2456 # echo function > current_tracer
2460 # TASK-PID CPU# TIMESTAMP FUNCTION
2462 yum-updatesd-3111 [003] 1637.254676: finish_task_switch <-thread_return
2463 yum-updatesd-3111 [003] 1637.254681: hrtimer_cancel <-schedule_hrtimeout_range
2464 yum-updatesd-3111 [003] 1637.254682: hrtimer_try_to_cancel <-hrtimer_cancel
2465 yum-updatesd-3111 [003] 1637.254683: lock_hrtimer_base <-hrtimer_try_to_cancel
2466 yum-updatesd-3111 [003] 1637.254685: fget_light <-do_sys_poll
2467 yum-updatesd-3111 [003] 1637.254686: pipe_poll <-do_sys_poll
2468 # echo > set_ftrace_pid
2472 # TASK-PID CPU# TIMESTAMP FUNCTION
2475 yum-updatesd-3111 [003] 1701.957688: free_poll_entry <-poll_freewait
2476 yum-updatesd-3111 [003] 1701.957689: remove_wait_queue <-free_poll_entry
2477 yum-updatesd-3111 [003] 1701.957691: fput <-free_poll_entry
2478 yum-updatesd-3111 [003] 1701.957692: audit_syscall_exit <-sysret_audit
2479 yum-updatesd-3111 [003] 1701.957693: path_put <-audit_syscall_exit
2542 exit(-1);
2551 exit(-1);
2574 tracefs=`sed -ne 's/^tracefs \(.*\) tracefs.*/\1/p' /proc/mounts`
2575 echo 0 > $tracefs/tracing_on
2576 echo $$ > $tracefs/set_ftrace_pid
2577 echo function > $tracefs/current_tracer
2578 echo 1 > $tracefs/tracing_on
2583 ---------------------------
2596 - measure of a function's time execution
2597 - having a reliable call stack to draw function calls graph
2601 - you want to find the reason of a strange kernel behavior and
2605 - you are experiencing weird latencies but it's difficult to
2608 - you want to find quickly which path is taken by a specific
2611 - you just want to peek inside a working kernel and want to see
2643 - The cpu number on which the function executed is default
2648 - hide: echo nofuncgraph-cpu > trace_options
2649 - show: echo funcgraph-cpu > trace_options
2651 - The duration (function's time of execution) is displayed on
2656 - hide: echo nofuncgraph-duration > trace_options
2657 - show: echo funcgraph-duration > trace_options
2659 - The overhead field precedes the duration field in case of
2662 - hide: echo nofuncgraph-overhead > trace_options
2663 - show: echo funcgraph-overhead > trace_options
2664 - depends on: funcgraph-duration
2716 - The task/pid field displays the thread cmdline and pid which
2719 - hide: echo nofuncgraph-proc > trace_options
2720 - show: echo funcgraph-proc > trace_options
2728 0) sh-4802 | | d_free() {
2729 0) sh-4802 | | call_rcu() {
2730 0) sh-4802 | | __call_rcu() {
2731 0) sh-4802 | 0.616 us | rcu_process_gp_end();
2732 0) sh-4802 | 0.586 us | check_for_new_grace_period();
2733 0) sh-4802 | 2.899 us | }
2734 0) sh-4802 | 4.040 us | }
2735 0) sh-4802 | 5.151 us | }
2736 0) sh-4802 | + 49.370 us | }
2739 - The absolute time field is an absolute timestamp given by the
2743 - hide: echo nofuncgraph-abstime > trace_options
2744 - show: echo funcgraph-abstime > trace_options
2775 - hide: echo nofuncgraph-tail > trace_options
2776 - show: echo funcgraph-tail > trace_options
2778 Example with nofuncgraph-tail (default)::
2786 Example with funcgraph-tail::
2799 - hide: echo nofuncgraph-retval > trace_options
2800 - show: echo funcgraph-retval > trace_options
2802 Example with funcgraph-retval::
2812 1) 2.335 us | } /* cpu_cgroup_can_attach = -22 */
2813 1) 4.369 us | } /* cgroup_migrate_execute = -22 */
2814 1) 7.143 us | } /* cgroup_migrate = -22 */
2817 returned the error code -22 firstly, then we can read the code
2820 When the option funcgraph-retval-hex is not set, the return value can
2825 - smart: echo nofuncgraph-retval-hex > trace_options
2826 - hexadecimal: echo funcgraph-retval-hex > trace_options
2828 Example with funcgraph-retval-hex::
2842 At present, there are some limitations when using the funcgraph-retval
2845 - Even if the function return type is void, a return value will still
2848 - Even if return values are stored in multiple registers, only the
2851 a 64-bit return value, with the lower 32 bits saved in eax and the
2855 - In certain procedure call standards, such as arm64's AAPCS64, when a
2859 when using a u8 in a 64-bit GPR, bits [63:8] may contain arbitrary values,
2889 return -EINVAL;
2901 MOV x0, #-EINVAL
2926 --------------
2931 every kernel function, produced by the -pg switch in gcc),
2933 include the -pg switch in the compiling of the kernel.)
2939 with gcc version 4.6, the -mfentry has been added for x86, which
2950 The recordmcount program re-links this section back into the
2982 One special side-effect to the recording of the functions being
3014 # echo sys_nanosleep hrtimer_interrupt > set_ftrace_filter
3015 # echo function > current_tracer
3016 # echo 1 > tracing_on
3018 # echo 0 > tracing_on
3022 # entries-in-buffer/entries-written: 5/5 #P:4
3024 # _-----=> irqs-off
3025 # / _----=> need-resched
3026 # | / _---=> hardirq/softirq
3027 # || / _--=> preempt-depth
3029 # TASK-PID CPU# |||| TIMESTAMP FUNCTION
3031 usleep-2665 [001] .... 4186.475355: sys_nanosleep <-system_call_fastpath
3032 <idle>-0 [001] d.h1 4186.475409: hrtimer_interrupt <-smp_apic_timer_interrupt
3033 usleep-2665 [001] d.h1 4186.475426: hrtimer_interrupt <-smp_apic_timer_interrupt
3034 <idle>-0 [003] d.h1 4186.475426: hrtimer_interrupt <-smp_apic_timer_interrupt
3035 <idle>-0 [002] d.h1 4186.475427: hrtimer_interrupt <-smp_apic_timer_interrupt
3063 # echo 'hrtimer_*' > set_ftrace_filter
3069 # entries-in-buffer/entries-written: 897/897 #P:4
3071 # _-----=> irqs-off
3072 # / _----=> need-resched
3073 # | / _---=> hardirq/softirq
3074 # || / _--=> preempt-depth
3076 # TASK-PID CPU# |||| TIMESTAMP FUNCTION
3078 <idle>-0 [003] dN.1 4228.547803: hrtimer_cancel <-tick_nohz_idle_exit
3079 <idle>-0 [003] dN.1 4228.547804: hrtimer_try_to_cancel <-hrtimer_cancel
3080 <idle>-0 [003] dN.2 4228.547805: hrtimer_force_reprogram <-__remove_hrtimer
3081 <idle>-0 [003] dN.1 4228.547805: hrtimer_forward <-tick_nohz_idle_exit
3082 … <idle>-0 [003] dN.1 4228.547805: hrtimer_start_range_ns <-hrtimer_start_expires.constprop.11
3083 <idle>-0 [003] d..1 4228.547858: hrtimer_get_next_event <-get_next_timer_interrupt
3084 <idle>-0 [003] d..1 4228.547859: hrtimer_start <-__tick_nohz_idle_enter
3085 <idle>-0 [003] d..2 4228.547860: hrtimer_force_reprogram <-__rem
3116 # echo > set_ftrace_filter
3124 # echo sys_nanosleep > set_ftrace_filter
3127 # echo 'hrtimer_*' >> set_ftrace_filter
3152 # echo '*preempt*' '*lock*' > set_ftrace_notrace
3158 # entries-in-buffer/entries-written: 39608/39608 #P:4
3160 # _-----=> irqs-off
3161 # / _----=> need-resched
3162 # | / _---=> hardirq/softirq
3163 # || / _--=> preempt-depth
3165 # TASK-PID CPU# |||| TIMESTAMP FUNCTION
3167 bash-1994 [000] .... 4342.324896: file_ra_state_init <-do_dentry_open
3168 bash-1994 [000] .... 4342.324897: open_check_o_direct <-do_last
3169 bash-1994 [000] .... 4342.324897: ima_file_check <-do_last
3170 bash-1994 [000] .... 4342.324898: process_measurement <-ima_file_check
3171 bash-1994 [000] .... 4342.324898: ima_get_action <-process_measurement
3172 bash-1994 [000] .... 4342.324898: ima_match_policy <-ima_get_action
3173 bash-1994 [000] .... 4342.324899: do_truncate <-do_last
3174 bash-1994 [000] .... 4342.324899: setattr_should_drop_suidgid <-do_truncate
3175 bash-1994 [000] .... 4342.324899: notify_change <-do_truncate
3176 bash-1994 [000] .... 4342.324900: current_fs_time <-notify_change
3177 bash-1994 [000] .... 4342.324900: current_kernel_time <-current_fs_time
3178 bash-1994 [000] .... 4342.324900: timespec_trunc <-current_fs_time
3183 ------------------------------------
3195 # echo 1 > set_ftrace_filter
3201 # head -1 available_filter_functions
3207 # head -50 available_filter_functions | tail -1
3210 # echo 1 50 > set_ftrace_filter
3216 ---------------------------------------------
3219 function tracer and the function-graph-tracer, there are some
3220 special features only available in the function-graph tracer.
3223 you just have to echo its name into set_graph_function::
3225 echo __do_fault > set_graph_function
3267 echo sys_open > set_graph_function
3268 echo sys_close >> set_graph_function
3273 echo > set_graph_function
3277 --------------
3296 echo 0 > /proc/sys/kernel/ftrace_enabled
3297 echo 1 > /proc/sys/kernel/ftrace_enabled
3301 ---------------
3310 - mod:
3315 echo 'write*:mod:ext3' > set_ftrace_filter
3323 echo '!writeback*:mod:ext3' >> set_ftrace_filter
3328 echo '!*:mod:!ext3' >> set_ftrace_filter
3332 echo '!*:mod:*' >> set_ftrace_filter
3336 echo '*write*:mod:!*' >> set_ftrace_filter
3340 echo '*write*:mod:*snd*' >> set_ftrace_filter
3342 - traceon/traceoff:
3349 echo '__schedule_bug:traceoff:5' > set_ftrace_filter
3353 echo '__schedule_bug:traceoff' > set_ftrace_filter
3359 echo '!__schedule_bug:traceoff:0' > set_ftrace_filter
3364 echo '!__schedule_bug:traceoff' > set_ftrace_filter
3366 - snapshot:
3370 echo 'native_flush_tlb_others:snapshot' > set_ftrace_filter
3375 echo 'native_flush_tlb_others:snapshot:1' > set_ftrace_filter
3379 echo '!native_flush_tlb_others:snapshot' > set_ftrace_filter
3380 echo '!native_flush_tlb_others:snapshot:0' > set_ftrace_filter
3382 - enable_event/disable_event:
3391 echo 'try_to_wake_up:enable_event:sched:sched_switch:2' > \
3401 echo '!try_to_wake_up:enable_event:sched:sched_switch:0' > \
3403 echo '!schedule:disable_event:sched:sched_switch' > \
3406 - dump:
3413 - cpudump:
3419 - stacktrace:
3423 ----------
3431 # echo function > current_tracer
3434 # echo 1 > tracing_on
3436 # echo 0 > tracing_on
3440 # entries-in-buffer/entries-written: 0/0 #P:4
3442 # _-----=> irqs-off
3443 # / _----=> need-resched
3444 # | / _---=> hardirq/softirq
3445 # || / _--=> preempt-depth
3447 # TASK-PID CPU# |||| TIMESTAMP FUNCTION
3452 bash-1994 [000] .... 5281.568961: mutex_unlock <-rb_simple_write
3453 bash-1994 [000] .... 5281.568963: __mutex_unlock_slowpath <-mutex_unlock
3454 bash-1994 [000] .... 5281.568963: __fsnotify_parent <-fsnotify_modify
3455 bash-1994 [000] .... 5281.568964: fsnotify <-fsnotify_modify
3456 bash-1994 [000] .... 5281.568964: __srcu_read_lock <-fsnotify
3457 bash-1994 [000] .... 5281.568964: add_preempt_count <-__srcu_read_lock
3458 bash-1994 [000] ...1 5281.568965: sub_preempt_count <-__srcu_read_lock
3459 bash-1994 [000] .... 5281.568965: __srcu_read_unlock <-fsnotify
3460 bash-1994 [000] .... 5281.568967: sys_dup2 <-system_call_fastpath
3470 -------------
3489 To modify the buffer, simple echo in a number (in 1024 byte segments).
3492 # echo 10000 > buffer_size_kb
3497 much, it can cause Out-Of-Memory to trigger.
3500 # echo 1000000000000 > buffer_size_kb
3501 -bash: echo: write error: Cannot allocate memory
3508 # echo 10000 > per_cpu/cpu0/buffer_size_kb
3509 # echo 100 > per_cpu/cpu1/buffer_size_kb
3528 --------
3546 of the snapshot. Echo 1 into this file to allocate a
3556 +--------------+------------+------------+------------+
3560 +--------------+------------+------------+------------+
3562 +--------------+------------+------------+------------+
3567 # echo 1 > events/sched/enable
3568 # echo 1 > snapshot
3572 # entries-in-buffer/entries-written: 71/71 #P:8
3574 # _-----=> irqs-off
3575 # / _----=> need-resched
3576 # | / _---=> hardirq/softirq
3577 # || / _--=> preempt-depth
3579 # TASK-PID CPU# |||| TIMESTAMP FUNCTION
3581 …<idle>-0 [005] d... 2440.603828: sched_switch: prev_comm=swapper/5 prev_pid=0 prev_prio=120 …
3582 …sleep-2242 [005] d... 2440.603846: sched_switch: prev_comm=snapshot-test-2 prev_pid=2242 prev_pr…
3584 …<idle>-0 [002] d... 2440.707230: sched_switch: prev_comm=swapper/2 prev_pid=0 prev_prio=120 p…
3589 # entries-in-buffer/entries-written: 77/77 #P:8
3591 # _-----=> irqs-off
3592 # / _----=> need-resched
3593 # | / _---=> hardirq/softirq
3594 # || / _--=> preempt-depth
3596 # TASK-PID CPU# |||| TIMESTAMP FUNCTION
3598 …<idle>-0 [007] d... 2440.707395: sched_switch: prev_comm=swapper/7 prev_pid=0 prev_prio=120 p…
3599 …snapshot-test-2-2229 [002] d... 2440.707438: sched_switch: prev_comm=snapshot-test-2 prev_pid=22…
3607 # echo wakeup > current_tracer
3608 # echo 1 > snapshot
3609 bash: echo: write error: Device or resource busy
3615 ---------
3650 # echo 100000 > buffer_size_kb
3651 # echo 1000 > instances/foo/buffer_size_kb
3652 # echo 5000 > instances/bar/per_cpu/cpu1/buffer_size_kb
3653 # echo function > current_trace
3654 # echo 1 > instances/foo/events/sched/sched_wakeup/enable
3655 # echo 1 > instances/foo/events/sched/sched_wakeup_new/enable
3656 # echo 1 > instances/foo/events/sched/sched_switch/enable
3657 # echo 1 > instances/bar/events/irq/enable
3658 # echo 1 > instances/zoot/events/syscalls/enable
3661 bash-2044 [002] .... 10594.481032: _raw_spin_lock_irqsave <-get_page_from_freelist
3662 bash-2044 [002] d... 10594.481032: add_preempt_count <-_raw_spin_lock_irqsave
3663 bash-2044 [002] d..1 10594.481032: __rmqueue <-get_page_from_freelist
3664 bash-2044 [002] d..1 10594.481033: _raw_spin_unlock <-get_page_from_freelist
3665 bash-2044 [002] d..1 10594.481033: sub_preempt_count <-_raw_spin_unlock
3666 … bash-2044 [002] d... 10594.481033: get_pageblock_flags_group <-get_pageblock_migratetype
3667 bash-2044 [002] d... 10594.481034: __mod_zone_page_state <-get_page_from_freelist
3668 bash-2044 [002] d... 10594.481034: zone_statistics <-get_page_from_freelist
3669 bash-2044 [002] d... 10594.481034: __inc_zone_state <-zone_statistics
3670 bash-2044 [002] d... 10594.481034: __inc_zone_state <-zone_statistics
3671 bash-2044 [002] .... 10594.481035: arch_dup_task_struct <-copy_process
3675 …bash-1998 [000] d..4 136.676759: sched_wakeup: comm=kworker/0:1 pid=59 prio=120 success=1 targe…
3676 …bash-1998 [000] dN.4 136.676760: sched_wakeup: comm=bash pid=1998 prio=120 success=1 target_cpu…
3677 …<idle>-0 [003] d.h3 136.676906: sched_wakeup: comm=rcu_preempt pid=9 prio=120 success=1 targ…
3678 …<idle>-0 [003] d..3 136.676909: sched_switch: prev_comm=swapper/3 prev_pid=0 prev_prio=120 p…
3679 …rcu_preempt-9 [003] d..3 136.676916: sched_switch: prev_comm=rcu_preempt prev_pid=9 prev_pri…
3680 …bash-1998 [000] d..4 136.677014: sched_wakeup: comm=kworker/0:1 pid=59 prio=120 success=1 targe…
3681 …bash-1998 [000] dN.4 136.677016: sched_wakeup: comm=bash pid=1998 prio=120 success=1 target_cpu…
3682 …bash-1998 [000] d..3 136.677018: sched_switch: prev_comm=bash prev_pid=1998 prev_prio=120 prev_…
3683 …kworker/0:1-59 [000] d..4 136.677022: sched_wakeup: comm=sshd pid=1995 prio=120 success=1 tar…
3684 …kworker/0:1-59 [000] d..3 136.677025: sched_switch: prev_comm=kworker/0:1 prev_pid=59 prev_pr…
3688 migration/1-14 [001] d.h3 138.732674: softirq_raise: vec=3 [action=NET_RX]
3689 <idle>-0 [001] dNh3 138.732725: softirq_raise: vec=3 [action=NET_RX]
3690 bash-1998 [000] d.h1 138.733101: softirq_raise: vec=1 [action=TIMER]
3691 bash-1998 [000] d.h1 138.733102: softirq_raise: vec=9 [action=RCU]
3692 bash-1998 [000] ..s2 138.733105: softirq_entry: vec=1 [action=TIMER]
3693 bash-1998 [000] ..s2 138.733106: softirq_exit: vec=1 [action=TIMER]
3694 bash-1998 [000] ..s2 138.733106: softirq_entry: vec=9 [action=RCU]
3695 bash-1998 [000] ..s2 138.733109: softirq_exit: vec=9 [action=RCU]
3696 sshd-1995 [001] d.h1 138.733278: irq_handler_entry: irq=21 name=uhci_hcd:usb4
3697 sshd-1995 [001] d.h1 138.733280: irq_handler_exit: irq=21 ret=unhandled
3698 sshd-1995 [001] d.h1 138.733281: irq_handler_entry: irq=21 name=eth0
3699 sshd-1995 [001] d.h1 138.733283: irq_handler_exit: irq=21 ret=handled
3705 # entries-in-buffer/entries-written: 18996/18996 #P:4
3707 # _-----=> irqs-off
3708 # / _----=> need-resched
3709 # | / _---=> hardirq/softirq
3710 # || / _--=> preempt-depth
3712 # TASK-PID CPU# |||| TIMESTAMP FUNCTION
3714 bash-1998 [000] d... 140.733501: sys_write -> 0x2
3715 bash-1998 [000] d... 140.733504: sys_dup2(oldfd: a, newfd: 1)
3716 bash-1998 [000] d... 140.733506: sys_dup2 -> 0x1
3717 bash-1998 [000] d... 140.733508: sys_fcntl(fd: a, cmd: 1, arg: 0)
3718 bash-1998 [000] d... 140.733509: sys_fcntl -> 0x1
3719 bash-1998 [000] d... 140.733510: sys_close(fd: a)
3720 bash-1998 [000] d... 140.733510: sys_close -> 0x0
3721 …bash-1998 [000] d... 140.733514: sys_rt_sigprocmask(how: 0, nset: 0, oset: 6e2768, sigsetsize: …
3722 bash-1998 [000] d... 140.733515: sys_rt_sigprocmask -> 0x0
3723 …bash-1998 [000] d... 140.733516: sys_rt_sigaction(sig: 2, act: 7fff718846f0, oact: 7fff71884650…
3724 bash-1998 [000] d... 140.733516: sys_rt_sigaction -> 0x0
3742 -----------
3759 # echo 1 > /proc/sys/kernel/stack_tracer_enabled
3773 ----- ---- --------
3793 Note, if -mfentry is being used by gcc, functions get traced before
3795 are not tested by the stack tracer when -mfentry is used.
3797 Currently, -mfentry is used by gcc 4.6.0 and above on x86 only.
3800 ----