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