Lines Matching +full:off +full:- +full:on +full:- +full:delay +full:- +full:us
2 ftrace - Function Tracer
13 - Written for: 2.6.28-rc2
14 - Updated for: 3.10
15 - Updated for: 4.13 - Copyright 2017 VMware Inc. Steven Rostedt
16 - Converted to rst format - Changbin Du <changbin.du@intel.com>
19 ------------
22 designers of systems to find what is going on inside the kernel.
24 performance issues that take place outside of user-space.
35 going on in certain parts of the kernel.
41 ----------------------
43 See :doc:`ftrace-design` for details for arch porters and such.
47 ---------------
60 mount -t tracefs nodev /sys/kernel/tracing
65 ln -s /sys/kernel/tracing /tracing
83 (cd /sys/kernel/tracing) and will only concentrate on the files within that
117 set this file to "0". User space can re-enable tracing by
122 be re-enabled by user space using this file.
190 due to buffer management meta-data. )
204 killed by a signal, this file can be used for that purpose. On close
214 This is a mask that lets the user only trace on specified CPUs.
248 If the "function-fork" option is set, then when a task whose
261 added on fork, enable the "event-fork" option. That option will also
306 will be displayed on the same line as the function that
310 the "ip modify" attribute (thus the regs->ip can be changed),
311 an 'I' will be displayed on the same line as the function that
370 If the option "record-cmd" is set to "0", then comms of tasks
381 If the option "record-tgid" is set, on each scheduling context switch
383 the thread to its TGID. By default, the "record-tgid" option is
414 clock is very fast and strictly per cpu, but on some
417 with local clocks on other CPUs.
422 [local] global counter x86-tsc
438 each other on different CPUs.
449 x86-tsc:
453 ppc-tb:
469 This is the boot clock (CLOCK_BOOTTIME) and is based on the
476 Also on 32-bit systems, it's possible that the 64-bit boot offset
581 delta: Default timestamp mode - timestamp is a delta against
582 a per-buffer timestamp.
656 event (ring buffer is re-entrant), that it fills the
669 Events lost due to overwrite option being off.
675 -----------
686 function tracer probes the functions on their entry
687 whereas the function graph tracer traces on both entry
709 trace with the latency-format option enabled, which
764 ----------------------------
768 user-land utilities).
771 --------------
777 # entries-in-buffer/entries-written: 140080/250280 #P:4
779 # _-----=> irqs-off
780 # / _----=> need-resched
781 # | / _---=> hardirq/softirq
782 # || / _--=> preempt-depth
783 # ||| / delay
784 # TASK-PID CPU# |||| TIMESTAMP FUNCTION
786 bash-1977 [000] .... 17284.993652: sys_close <-system_call_fastpath
787 bash-1977 [000] .... 17284.993653: __close_fd <-sys_close
788 bash-1977 [000] .... 17284.993653: _raw_spin_lock <-__close_fd
789 sshd-1974 [003] .... 17284.993653: __srcu_read_unlock <-fsnotify
790 bash-1977 [000] .... 17284.993654: add_preempt_count <-_raw_spin_lock
791 bash-1977 [000] ...1 17284.993655: _raw_spin_unlock <-__close_fd
792 bash-1977 [000] ...1 17284.993656: sub_preempt_count <-_raw_spin_unlock
793 bash-1977 [000] .... 17284.993657: filp_close <-__close_fd
794 bash-1977 [000] .... 17284.993657: dnotify_flush <-filp_close
795 sshd-1974 [003] .... 17284.993658: sys_select <-system_call_fastpath
802 lost due to the buffer filling up (250280 - 140080 = 110200 events
806 PID "1977", the CPU that it was running on "000", the latency format
813 --------------------
815 When the latency-format option is enabled or when one of the latency
821 # irqsoff latency trace v1.1.5 on 3.8.0-test+
822 # --------------------------------------------------------------------
823 # latency: 259 us, #4/4, CPU#2 | (M:preempt VP:0, KP:0, SP:0 HP:0 #P:4)
824 # -----------------
825 # | task: ps-6143 (uid:0 nice:0 policy:0 rt_prio:0)
826 # -----------------
831 # _------=> CPU#
832 # / _-----=> irqs-off
833 # | / _----=> need-resched
834 # || / _---=> hardirq/softirq
835 # ||| / _--=> preempt-depth
836 # |||| / delay
839 ps-6143 2d... 0us!: trace_hardirqs_off <-__lock_task_sighand
840 ps-6143 2d..1 259us+: trace_hardirqs_on <-_raw_spin_unlock_irqrestore
841 ps-6143 2d..1 263us+: time_hardirqs_on <-_raw_spin_unlock_irqrestore
842 ps-6143 2d..1 306us : <stack trace>
857 never changes) and the version of the kernel upon which this was executed on
858 (3.8). Then it displays the max latency in microseconds (259 us). The number
869 - __lock_task_sighand is where the interrupts were disabled.
870 - _raw_spin_unlock_irqrestore is where they were enabled again.
879 CPU#: The CPU which the process was running on.
881 irqs-off: 'd' interrupts are disabled. '.' otherwise.
886 need-resched:
887 - 'N' both TIF_NEED_RESCHED and PREEMPT_NEED_RESCHED is set,
888 - 'n' only TIF_NEED_RESCHED is set,
889 - 'p' only PREEMPT_NEED_RESCHED is set,
890 - '.' otherwise.
893 - 'Z' - NMI occurred inside a hardirq
894 - 'z' - NMI is running
895 - 'H' - hard irq occurred inside a softirq.
896 - 'h' - hard irq is running
897 - 's' - soft irq is running
898 - '.' - normal context.
900 preempt-depth: The level of preempt_disabled
905 When the latency-format option is enabled, the trace file
907 trace. This differs from the output when latency-format
910 delay:
916 - '$' - greater than 1 second
917 - '@' - greater than 100 milisecond
918 - '*' - greater than 10 milisecond
919 - '#' - greater than 1000 microsecond
920 - '!' - greater than 100 microsecond
921 - '+' - greater than 10 microsecond
922 - ' ' - less than or equal to 10 microsecond.
930 -------------
937 print-parent
938 nosym-offset
939 nosym-addr
948 nosym-userobj
949 noprintk-msg-only
950 context-info
951 nolatency-format
952 record-cmd
953 norecord-tgid
956 irq-info
958 noevent-fork
959 function-trace
960 nofunction-fork
961 nodisplay-graph
968 echo noprint-parent > trace_options
970 To enable an option, leave off the "no"::
972 echo sym-offset > trace_options
976 print-parent
977 On function traces, display the calling (parent)
981 print-parent:
982 bash-4000 [01] 1477.606694: simple_strtoul <-kstrtoul
984 noprint-parent:
985 bash-4000 [01] 1477.606694: simple_strtoul
988 sym-offset
995 sym-offset:
996 bash-4000 [01] 1477.606694: simple_strtoul+0x6/0xa0
998 sym-addr
1003 sym-addr:
1004 bash-4000 [01] 1477.606694: simple_strtoul <c0339346>
1008 latency-format option is enabled.
1041 <idle>-0 [001] dNs4 21169.031481: wake_up_idle_cpu <-add_timer_on
1042 <idle>-0 [001] dNs4 21169.031482: _raw_spin_unlock_irqrestore <-add_timer_on
1043 <idle>-0 [001] .Ns4 21169.031484: sub_preempt_count <-_raw_spin_unlock_irqrestore
1045 <idle>-0 [002] .N.1 21169.031484: rcu_idle_exit <-cpu_idle
1046 <idle>-0 [001] .Ns3 21169.031484: _raw_spin_unlock <-clocksource_watchdog
1047 <idle>-0 [001] .Ns3 21169.031485: sub_preempt_count <-_raw_spin_unlock
1054 sym-userobj
1058 ASLR is on, otherwise you don't get a chance to
1065 a.out-1623 [000] 40874.465068: /root/a.out[+0x480] <-/root/a.out[+0
1066 x494] <- /root/a.out[+0x4a8] <- /lib/libc-2.7.so[+0x1e1a6]
1069 printk-msg-only
1074 context-info
1078 latency-format
1083 record-cmd
1091 record-tgid
1108 irq-info
1114 # entries-in-buffer/entries-written: 144405/9452052 #P:4
1116 # TASK-PID CPU# TIMESTAMP FUNCTION
1118 <idle>-0 [002] 23636.756054: ttwu_do_activate.constprop.89 <-try_to_wake_up
1119 <idle>-0 [002] 23636.756054: activate_task <-ttwu_do_activate.constprop.89
1120 <idle>-0 [002] 23636.756055: enqueue_task <-activate_task
1126 on write.
1128 event-fork
1134 function-trace
1141 function-fork
1148 display-graph
1184 funcgraph-overrun
1195 funcgraph-cpu
1199 funcgraph-overhead
1201 A certain amount, then a delay marker is
1202 displayed. See "delay" above, under the
1205 funcgraph-proc
1212 funcgraph-duration
1217 funcgraph-abstime
1220 funcgraph-irqs
1224 funcgraph-tail
1226 that it represents. By default this is off, and
1230 sleep-time
1236 graph-time
1250 -------
1267 # echo 0 > options/function-trace
1271 # ls -ltr
1277 # irqsoff latency trace v1.1.5 on 3.8.0-test+
1278 # --------------------------------------------------------------------
1279 # latency: 16 us, #4/4, CPU#0 | (M:preempt VP:0, KP:0, SP:0 HP:0 #P:4)
1280 # -----------------
1281 # | task: swapper/0-0 (uid:0 nice:0 policy:0 rt_prio:0)
1282 # -----------------
1287 # _------=> CPU#
1288 # / _-----=> irqs-off
1289 # | / _----=> need-resched
1290 # || / _---=> hardirq/softirq
1291 # ||| / _--=> preempt-depth
1292 # |||| / delay
1295 <idle>-0 0d.s2 0us+: _raw_spin_lock_irq <-run_timer_softirq
1296 <idle>-0 0dNs3 17us : _raw_spin_unlock_irq <-run_timer_softirq
1297 <idle>-0 0dNs3 17us+: trace_hardirqs_on <-run_timer_softirq
1298 <idle>-0 0dNs3 25us : <stack trace>
1317 timestamp 25us occurred because the clock was incremented
1321 Note the above example had function-trace not set. If we set
1322 function-trace, we get a much larger output::
1324 with echo 1 > options/function-trace
1328 # irqsoff latency trace v1.1.5 on 3.8.0-test+
1329 # --------------------------------------------------------------------
1330 # latency: 71 us, #168/168, CPU#3 | (M:preempt VP:0, KP:0, SP:0 HP:0 #P:4)
1331 # -----------------
1332 # | task: bash-2042 (uid:0 nice:0 policy:0 rt_prio:0)
1333 # -----------------
1338 # _------=> CPU#
1339 # / _-----=> irqs-off
1340 # | / _----=> need-resched
1341 # || / _---=> hardirq/softirq
1342 # ||| / _--=> preempt-depth
1343 # |||| / delay
1346 bash-2042 3d... 0us : _raw_spin_lock_irqsave <-ata_scsi_queuecmd
1347 bash-2042 3d... 0us : add_preempt_count <-_raw_spin_lock_irqsave
1348 bash-2042 3d..1 1us : ata_scsi_find_dev <-ata_scsi_queuecmd
1349 bash-2042 3d..1 1us : __ata_scsi_find_dev <-ata_scsi_find_dev
1350 bash-2042 3d..1 2us : ata_find_dev.part.14 <-__ata_scsi_find_dev
1351 bash-2042 3d..1 2us : ata_qc_new_init <-__ata_scsi_queuecmd
1352 bash-2042 3d..1 3us : ata_sg_init <-__ata_scsi_queuecmd
1353 bash-2042 3d..1 4us : ata_scsi_rw_xlat <-__ata_scsi_queuecmd
1354 bash-2042 3d..1 4us : ata_build_rw_tf <-ata_scsi_rw_xlat
1356 bash-2042 3d..1 67us : delay_tsc <-__delay
1357 bash-2042 3d..1 67us : add_preempt_count <-delay_tsc
1358 bash-2042 3d..2 67us : sub_preempt_count <-delay_tsc
1359 bash-2042 3d..1 67us : add_preempt_count <-delay_tsc
1360 bash-2042 3d..2 68us : sub_preempt_count <-delay_tsc
1361 bash-2042 3d..1 68us+: ata_bmdma_start <-ata_bmdma_qc_issue
1362 bash-2042 3d..1 71us : _raw_spin_unlock_irqrestore <-ata_scsi_queuecmd
1363 bash-2042 3d..1 71us : _raw_spin_unlock_irqrestore <-ata_scsi_queuecmd
1364 bash-2042 3d..1 72us+: trace_hardirqs_on <-ata_scsi_queuecmd
1365 bash-2042 3d..1 120us : <stack trace>
1401 ----------
1414 # echo 0 > options/function-trace
1418 # ls -ltr
1424 # preemptoff latency trace v1.1.5 on 3.8.0-test+
1425 # --------------------------------------------------------------------
1426 # latency: 46 us, #4/4, CPU#1 | (M:preempt VP:0, KP:0, SP:0 HP:0 #P:4)
1427 # -----------------
1428 # | task: sshd-1991 (uid:0 nice:0 policy:0 rt_prio:0)
1429 # -----------------
1434 # _------=> CPU#
1435 # / _-----=> irqs-off
1436 # | / _----=> need-resched
1437 # || / _---=> hardirq/softirq
1438 # ||| / _--=> preempt-depth
1439 # |||| / delay
1442 sshd-1991 1d.h. 0us+: irq_enter <-do_IRQ
1443 sshd-1991 1d..1 46us : irq_exit <-do_IRQ
1444 sshd-1991 1d..1 47us+: trace_preempt_on <-do_IRQ
1445 sshd-1991 1d..1 52us : <stack trace>
1453 interrupt came in (notice the 'h'), and was enabled on exit.
1455 the preempt off section and leaving it (the 'd'). We do not know if
1462 # preemptoff latency trace v1.1.5 on 3.8.0-test+
1463 # --------------------------------------------------------------------
1464 # latency: 83 us, #241/241, CPU#1 | (M:preempt VP:0, KP:0, SP:0 HP:0 #P:4)
1465 # -----------------
1466 # | task: bash-1994 (uid:0 nice:0 policy:0 rt_prio:0)
1467 # -----------------
1472 # _------=> CPU#
1473 # / _-----=> irqs-off
1474 # | / _----=> need-resched
1475 # || / _---=> hardirq/softirq
1476 # ||| / _--=> preempt-depth
1477 # |||| / delay
1480 bash-1994 1d..1 0us : _raw_spin_lock_irqsave <-wake_up_new_task
1481 bash-1994 1d..1 0us : select_task_rq_fair <-select_task_rq
1482 bash-1994 1d..1 1us : __rcu_read_lock <-select_task_rq_fair
1483 bash-1994 1d..1 1us : source_load <-select_task_rq_fair
1484 bash-1994 1d..1 1us : source_load <-select_task_rq_fair
1486 bash-1994 1d..1 12us : irq_enter <-smp_apic_timer_interrupt
1487 bash-1994 1d..1 12us : rcu_irq_enter <-irq_enter
1488 bash-1994 1d..1 13us : add_preempt_count <-irq_enter
1489 bash-1994 1d.h1 13us : exit_idle <-smp_apic_timer_interrupt
1490 bash-1994 1d.h1 13us : hrtimer_interrupt <-smp_apic_timer_interrupt
1491 bash-1994 1d.h1 13us : _raw_spin_lock <-hrtimer_interrupt
1492 bash-1994 1d.h1 14us : add_preempt_count <-_raw_spin_lock
1493 bash-1994 1d.h2 14us : ktime_get_update_offsets <-hrtimer_interrupt
1495 bash-1994 1d.h1 35us : lapic_next_event <-clockevents_program_event
1496 bash-1994 1d.h1 35us : irq_exit <-smp_apic_timer_interrupt
1497 bash-1994 1d.h1 36us : sub_preempt_count <-irq_exit
1498 bash-1994 1d..2 36us : do_softirq <-irq_exit
1499 bash-1994 1d..2 36us : __do_softirq <-call_softirq
1500 bash-1994 1d..2 36us : __local_bh_disable <-__do_softirq
1501 bash-1994 1d.s2 37us : add_preempt_count <-_raw_spin_lock_irq
1502 bash-1994 1d.s3 38us : _raw_spin_unlock <-run_timer_softirq
1503 bash-1994 1d.s3 39us : sub_preempt_count <-_raw_spin_unlock
1504 bash-1994 1d.s2 39us : call_timer_fn <-run_timer_softirq
1506 bash-1994 1dNs2 81us : cpu_needs_another_gp <-rcu_process_callbacks
1507 bash-1994 1dNs2 82us : __local_bh_enable <-__do_softirq
1508 bash-1994 1dNs2 82us : sub_preempt_count <-__local_bh_enable
1509 bash-1994 1dN.2 82us : idle_cpu <-irq_exit
1510 bash-1994 1dN.2 83us : rcu_irq_exit <-irq_exit
1511 bash-1994 1dN.2 83us : sub_preempt_count <-irq_exit
1512 bash-1994 1.N.1 84us : _raw_spin_unlock_irqrestore <-task_rq_unlock
1513 bash-1994 1.N.1 84us+: trace_preempt_on <-task_rq_unlock
1514 bash-1994 1.N.1 104us : <stack trace>
1525 function-trace set. Here we see that interrupts were not disabled
1526 the entire time. The irq_enter code lets us know that we entered
1532 --------------
1566 # echo 0 > options/function-trace
1570 # ls -ltr
1576 # preemptirqsoff latency trace v1.1.5 on 3.8.0-test+
1577 # --------------------------------------------------------------------
1578 # latency: 100 us, #4/4, CPU#3 | (M:preempt VP:0, KP:0, SP:0 HP:0 #P:4)
1579 # -----------------
1580 # | task: ls-2230 (uid:0 nice:0 policy:0 rt_prio:0)
1581 # -----------------
1586 # _------=> CPU#
1587 # / _-----=> irqs-off
1588 # | / _----=> need-resched
1589 # || / _---=> hardirq/softirq
1590 # ||| / _--=> preempt-depth
1591 # |||| / delay
1594 ls-2230 3d... 0us+: _raw_spin_lock_irqsave <-ata_scsi_queuecmd
1595 ls-2230 3...1 100us : _raw_spin_unlock_irqrestore <-ata_scsi_queuecmd
1596 ls-2230 3...1 101us+: trace_preempt_on <-ata_scsi_queuecmd
1597 ls-2230 3...1 111us : <stack trace>
1619 The trace_hardirqs_off_thunk is called from assembly on x86 when
1625 Here is a trace with function-trace set::
1629 # preemptirqsoff latency trace v1.1.5 on 3.8.0-test+
1630 # --------------------------------------------------------------------
1631 # latency: 161 us, #339/339, CPU#3 | (M:preempt VP:0, KP:0, SP:0 HP:0 #P:4)
1632 # -----------------
1633 # | task: ls-2269 (uid:0 nice:0 policy:0 rt_prio:0)
1634 # -----------------
1639 # _------=> CPU#
1640 # / _-----=> irqs-off
1641 # | / _----=> need-resched
1642 # || / _---=> hardirq/softirq
1643 # ||| / _--=> preempt-depth
1644 # |||| / delay
1647 kworker/-59 3...1 0us : __schedule <-schedule
1648 kworker/-59 3d..1 0us : rcu_preempt_qs <-rcu_note_context_switch
1649 kworker/-59 3d..1 1us : add_preempt_count <-_raw_spin_lock_irq
1650 kworker/-59 3d..2 1us : deactivate_task <-__schedule
1651 kworker/-59 3d..2 1us : dequeue_task <-deactivate_task
1652 kworker/-59 3d..2 2us : update_rq_clock <-dequeue_task
1653 kworker/-59 3d..2 2us : dequeue_task_fair <-dequeue_task
1654 kworker/-59 3d..2 2us : update_curr <-dequeue_task_fair
1655 kworker/-59 3d..2 2us : update_min_vruntime <-update_curr
1656 kworker/-59 3d..2 3us : cpuacct_charge <-update_curr
1657 kworker/-59 3d..2 3us : __rcu_read_lock <-cpuacct_charge
1658 kworker/-59 3d..2 3us : __rcu_read_unlock <-cpuacct_charge
1659 kworker/-59 3d..2 3us : update_cfs_rq_blocked_load <-dequeue_task_fair
1660 kworker/-59 3d..2 4us : clear_buddies <-dequeue_task_fair
1661 kworker/-59 3d..2 4us : account_entity_dequeue <-dequeue_task_fair
1662 kworker/-59 3d..2 4us : update_min_vruntime <-dequeue_task_fair
1663 kworker/-59 3d..2 4us : update_cfs_shares <-dequeue_task_fair
1664 kworker/-59 3d..2 5us : hrtick_update <-dequeue_task_fair
1665 kworker/-59 3d..2 5us : wq_worker_sleeping <-__schedule
1666 kworker/-59 3d..2 5us : kthread_data <-wq_worker_sleeping
1667 kworker/-59 3d..2 5us : put_prev_task_fair <-__schedule
1668 kworker/-59 3d..2 6us : pick_next_task_fair <-pick_next_task
1669 kworker/-59 3d..2 6us : clear_buddies <-pick_next_task_fair
1670 kworker/-59 3d..2 6us : set_next_entity <-pick_next_task_fair
1671 kworker/-59 3d..2 6us : update_stats_wait_end <-set_next_entity
1672 ls-2269 3d..2 7us : finish_task_switch <-__schedule
1673 ls-2269 3d..2 7us : _raw_spin_unlock_irq <-finish_task_switch
1674 ls-2269 3d..2 8us : do_IRQ <-ret_from_intr
1675 ls-2269 3d..2 8us : irq_enter <-do_IRQ
1676 ls-2269 3d..2 8us : rcu_irq_enter <-irq_enter
1677 ls-2269 3d..2 9us : add_preempt_count <-irq_enter
1678 ls-2269 3d.h2 9us : exit_idle <-do_IRQ
1680 ls-2269 3d.h3 20us : sub_preempt_count <-_raw_spin_unlock
1681 ls-2269 3d.h2 20us : irq_exit <-do_IRQ
1682 ls-2269 3d.h2 21us : sub_preempt_count <-irq_exit
1683 ls-2269 3d..3 21us : do_softirq <-irq_exit
1684 ls-2269 3d..3 21us : __do_softirq <-call_softirq
1685 ls-2269 3d..3 21us+: __local_bh_disable <-__do_softirq
1686 ls-2269 3d.s4 29us : sub_preempt_count <-_local_bh_enable_ip
1687 ls-2269 3d.s5 29us : sub_preempt_count <-_local_bh_enable_ip
1688 ls-2269 3d.s5 31us : do_IRQ <-ret_from_intr
1689 ls-2269 3d.s5 31us : irq_enter <-do_IRQ
1690 ls-2269 3d.s5 31us : rcu_irq_enter <-irq_enter
1692 ls-2269 3d.s5 31us : rcu_irq_enter <-irq_enter
1693 ls-2269 3d.s5 32us : add_preempt_count <-irq_enter
1694 ls-2269 3d.H5 32us : exit_idle <-do_IRQ
1695 ls-2269 3d.H5 32us : handle_irq <-do_IRQ
1696 ls-2269 3d.H5 32us : irq_to_desc <-handle_irq
1697 ls-2269 3d.H5 33us : handle_fasteoi_irq <-handle_irq
1699 ls-2269 3d.s5 158us : _raw_spin_unlock_irqrestore <-rtl8139_poll
1700 ls-2269 3d.s3 158us : net_rps_action_and_irq_enable.isra.65 <-net_rx_action
1701 ls-2269 3d.s3 159us : __local_bh_enable <-__do_softirq
1702 ls-2269 3d.s3 159us : sub_preempt_count <-__local_bh_enable
1703 ls-2269 3d..3 159us : idle_cpu <-irq_exit
1704 ls-2269 3d..3 159us : rcu_irq_exit <-irq_exit
1705 ls-2269 3d..3 160us : sub_preempt_count <-irq_exit
1706 ls-2269 3d... 161us : __mutex_unlock_slowpath <-mutex_unlock
1707 ls-2269 3d... 162us+: trace_hardirqs_on <-mutex_unlock
1708 ls-2269 3d... 186us : <stack trace>
1727 ------
1731 Now for non Real-Time tasks, this can be arbitrary. But tracing
1736 # echo 0 > options/function-trace
1740 # chrt -f 5 sleep 1
1745 # wakeup latency trace v1.1.5 on 3.8.0-test+
1746 # --------------------------------------------------------------------
1747 # latency: 15 us, #4/4, CPU#3 | (M:preempt VP:0, KP:0, SP:0 HP:0 #P:4)
1748 # -----------------
1749 # | task: kworker/3:1H-312 (uid:0 nice:-20 policy:0 rt_prio:0)
1750 # -----------------
1752 # _------=> CPU#
1753 # / _-----=> irqs-off
1754 # | / _----=> need-resched
1755 # || / _---=> hardirq/softirq
1756 # ||| / _--=> preempt-depth
1757 # |||| / delay
1760 <idle>-0 3dNs7 0us : 0:120:R + [003] 312:100:R kworker/3:1H
1761 <idle>-0 3dNs7 1us+: ttwu_do_activate.constprop.87 <-try_to_wake_up
1762 <idle>-0 3d..3 15us : __schedule <-schedule
1763 <idle>-0 3d..3 15us : 0:120:R ==> [003] 312:100:R kworker/3:1H
1767 the kworker with a nice priority of -20 (not very nice), took
1771 Non Real-Time tasks are not that interesting. A more interesting
1772 trace is to concentrate only on Real-Time tasks.
1775 ---------
1777 In a Real-Time environment it is very important to know the
1781 also important to know the scheduling latency of non-RT tasks,
1782 but the average schedule latency is better for non-RT tasks.
1786 Real-Time environments are interested in the worst case latency.
1790 work well with Real-Time tasks. The wakeup_rt tracer was designed
1791 to record the worst case wakeups of RT tasks. Non-RT tasks are
1793 tracing non-RT tasks that are unpredictable will overwrite the
1803 # echo 0 > options/function-trace
1807 # chrt -f 5 sleep 1
1814 # wakeup_rt latency trace v1.1.5 on 3.8.0-test+
1815 # --------------------------------------------------------------------
1816 # latency: 5 us, #4/4, CPU#3 | (M:preempt VP:0, KP:0, SP:0 HP:0 #P:4)
1817 # -----------------
1818 # | task: sleep-2389 (uid:0 nice:0 policy:1 rt_prio:5)
1819 # -----------------
1821 # _------=> CPU#
1822 # / _-----=> irqs-off
1823 # | / _----=> need-resched
1824 # || / _---=> hardirq/softirq
1825 # ||| / _--=> preempt-depth
1826 # |||| / delay
1829 <idle>-0 3d.h4 0us : 0:120:R + [003] 2389: 94:R sleep
1830 <idle>-0 3d.h4 1us+: ttwu_do_activate.constprop.87 <-try_to_wake_up
1831 <idle>-0 3d..3 5us : __schedule <-schedule
1832 <idle>-0 3d..3 5us : 0:120:R ==> [003] 2389: 94:R sleep
1835 Running this on an idle system, we see that it only took 5 microseconds
1842 and it has an rt_prio of 5. This priority is user-space priority
1846 Note, that the trace data shows the internal priority (99 - rtprio).
1849 <idle>-0 3d..3 5us : 0:120:R ==> [003] 2389: 94:R sleep
1851 The 0:120:R means idle was running with a nice priority of 0 (120 - 120)
1853 2389: 94:R. That is the priority is the kernel rtprio (99 - 5 = 94)
1856 Doing the same with chrt -r 5 and function-trace set.
1859 echo 1 > options/function-trace
1863 # wakeup_rt latency trace v1.1.5 on 3.8.0-test+
1864 # --------------------------------------------------------------------
1865 # latency: 29 us, #85/85, CPU#3 | (M:preempt VP:0, KP:0, SP:0 HP:0 #P:4)
1866 # -----------------
1867 # | task: sleep-2448 (uid:0 nice:0 policy:1 rt_prio:5)
1868 # -----------------
1870 # _------=> CPU#
1871 # / _-----=> irqs-off
1872 # | / _----=> need-resched
1873 # || / _---=> hardirq/softirq
1874 # ||| / _--=> preempt-depth
1875 # |||| / delay
1878 <idle>-0 3d.h4 1us+: 0:120:R + [003] 2448: 94:R sleep
1879 <idle>-0 3d.h4 2us : ttwu_do_activate.constprop.87 <-try_to_wake_up
1880 <idle>-0 3d.h3 3us : check_preempt_curr <-ttwu_do_wakeup
1881 <idle>-0 3d.h3 3us : resched_curr <-check_preempt_curr
1882 <idle>-0 3dNh3 4us : task_woken_rt <-ttwu_do_wakeup
1883 <idle>-0 3dNh3 4us : _raw_spin_unlock <-try_to_wake_up
1884 <idle>-0 3dNh3 4us : sub_preempt_count <-_raw_spin_unlock
1885 <idle>-0 3dNh2 5us : ttwu_stat <-try_to_wake_up
1886 <idle>-0 3dNh2 5us : _raw_spin_unlock_irqrestore <-try_to_wake_up
1887 <idle>-0 3dNh2 6us : sub_preempt_count <-_raw_spin_unlock_irqrestore
1888 <idle>-0 3dNh1 6us : _raw_spin_lock <-__run_hrtimer
1889 <idle>-0 3dNh1 6us : add_preempt_count <-_raw_spin_lock
1890 <idle>-0 3dNh2 7us : _raw_spin_unlock <-hrtimer_interrupt
1891 <idle>-0 3dNh2 7us : sub_preempt_count <-_raw_spin_unlock
1892 <idle>-0 3dNh1 7us : tick_program_event <-hrtimer_interrupt
1893 <idle>-0 3dNh1 7us : clockevents_program_event <-tick_program_event
1894 <idle>-0 3dNh1 8us : ktime_get <-clockevents_program_event
1895 <idle>-0 3dNh1 8us : lapic_next_event <-clockevents_program_event
1896 <idle>-0 3dNh1 8us : irq_exit <-smp_apic_timer_interrupt
1897 <idle>-0 3dNh1 9us : sub_preempt_count <-irq_exit
1898 <idle>-0 3dN.2 9us : idle_cpu <-irq_exit
1899 <idle>-0 3dN.2 9us : rcu_irq_exit <-irq_exit
1900 <idle>-0 3dN.2 10us : rcu_eqs_enter_common.isra.45 <-rcu_irq_exit
1901 <idle>-0 3dN.2 10us : sub_preempt_count <-irq_exit
1902 <idle>-0 3.N.1 11us : rcu_idle_exit <-cpu_idle
1903 <idle>-0 3dN.1 11us : rcu_eqs_exit_common.isra.43 <-rcu_idle_exit
1904 <idle>-0 3.N.1 11us : tick_nohz_idle_exit <-cpu_idle
1905 <idle>-0 3dN.1 12us : menu_hrtimer_cancel <-tick_nohz_idle_exit
1906 <idle>-0 3dN.1 12us : ktime_get <-tick_nohz_idle_exit
1907 <idle>-0 3dN.1 12us : tick_do_update_jiffies64 <-tick_nohz_idle_exit
1908 <idle>-0 3dN.1 13us : cpu_load_update_nohz <-tick_nohz_idle_exit
1909 <idle>-0 3dN.1 13us : _raw_spin_lock <-cpu_load_update_nohz
1910 <idle>-0 3dN.1 13us : add_preempt_count <-_raw_spin_lock
1911 <idle>-0 3dN.2 13us : __cpu_load_update <-cpu_load_update_nohz
1912 <idle>-0 3dN.2 14us : sched_avg_update <-__cpu_load_update
1913 <idle>-0 3dN.2 14us : _raw_spin_unlock <-cpu_load_update_nohz
1914 <idle>-0 3dN.2 14us : sub_preempt_count <-_raw_spin_unlock
1915 <idle>-0 3dN.1 15us : calc_load_nohz_stop <-tick_nohz_idle_exit
1916 <idle>-0 3dN.1 15us : touch_softlockup_watchdog <-tick_nohz_idle_exit
1917 <idle>-0 3dN.1 15us : hrtimer_cancel <-tick_nohz_idle_exit
1918 <idle>-0 3dN.1 15us : hrtimer_try_to_cancel <-hrtimer_cancel
1919 <idle>-0 3dN.1 16us : lock_hrtimer_base.isra.18 <-hrtimer_try_to_cancel
1920 <idle>-0 3dN.1 16us : _raw_spin_lock_irqsave <-lock_hrtimer_base.isra.18
1921 <idle>-0 3dN.1 16us : add_preempt_count <-_raw_spin_lock_irqsave
1922 <idle>-0 3dN.2 17us : __remove_hrtimer <-remove_hrtimer.part.16
1923 <idle>-0 3dN.2 17us : hrtimer_force_reprogram <-__remove_hrtimer
1924 <idle>-0 3dN.2 17us : tick_program_event <-hrtimer_force_reprogram
1925 <idle>-0 3dN.2 18us : clockevents_program_event <-tick_program_event
1926 <idle>-0 3dN.2 18us : ktime_get <-clockevents_program_event
1927 <idle>-0 3dN.2 18us : lapic_next_event <-clockevents_program_event
1928 <idle>-0 3dN.2 19us : _raw_spin_unlock_irqrestore <-hrtimer_try_to_cancel
1929 <idle>-0 3dN.2 19us : sub_preempt_count <-_raw_spin_unlock_irqrestore
1930 <idle>-0 3dN.1 19us : hrtimer_forward <-tick_nohz_idle_exit
1931 <idle>-0 3dN.1 20us : ktime_add_safe <-hrtimer_forward
1932 <idle>-0 3dN.1 20us : ktime_add_safe <-hrtimer_forward
1933 <idle>-0 3dN.1 20us : hrtimer_start_range_ns <-hrtimer_start_expires.constprop.11
1934 <idle>-0 3dN.1 20us : __hrtimer_start_range_ns <-hrtimer_start_range_ns
1935 <idle>-0 3dN.1 21us : lock_hrtimer_base.isra.18 <-__hrtimer_start_range_ns
1936 <idle>-0 3dN.1 21us : _raw_spin_lock_irqsave <-lock_hrtimer_base.isra.18
1937 <idle>-0 3dN.1 21us : add_preempt_count <-_raw_spin_lock_irqsave
1938 <idle>-0 3dN.2 22us : ktime_add_safe <-__hrtimer_start_range_ns
1939 <idle>-0 3dN.2 22us : enqueue_hrtimer <-__hrtimer_start_range_ns
1940 <idle>-0 3dN.2 22us : tick_program_event <-__hrtimer_start_range_ns
1941 <idle>-0 3dN.2 23us : clockevents_program_event <-tick_program_event
1942 <idle>-0 3dN.2 23us : ktime_get <-clockevents_program_event
1943 <idle>-0 3dN.2 23us : lapic_next_event <-clockevents_program_event
1944 <idle>-0 3dN.2 24us : _raw_spin_unlock_irqrestore <-__hrtimer_start_range_ns
1945 <idle>-0 3dN.2 24us : sub_preempt_count <-_raw_spin_unlock_irqrestore
1946 <idle>-0 3dN.1 24us : account_idle_ticks <-tick_nohz_idle_exit
1947 <idle>-0 3dN.1 24us : account_idle_time <-account_idle_ticks
1948 <idle>-0 3.N.1 25us : sub_preempt_count <-cpu_idle
1949 <idle>-0 3.N.. 25us : schedule <-cpu_idle
1950 <idle>-0 3.N.. 25us : __schedule <-preempt_schedule
1951 <idle>-0 3.N.. 26us : add_preempt_count <-__schedule
1952 <idle>-0 3.N.1 26us : rcu_note_context_switch <-__schedule
1953 <idle>-0 3.N.1 26us : rcu_sched_qs <-rcu_note_context_switch
1954 <idle>-0 3dN.1 27us : rcu_preempt_qs <-rcu_note_context_switch
1955 <idle>-0 3.N.1 27us : _raw_spin_lock_irq <-__schedule
1956 <idle>-0 3dN.1 27us : add_preempt_count <-_raw_spin_lock_irq
1957 <idle>-0 3dN.2 28us : put_prev_task_idle <-__schedule
1958 <idle>-0 3dN.2 28us : pick_next_task_stop <-pick_next_task
1959 <idle>-0 3dN.2 28us : pick_next_task_rt <-pick_next_task
1960 <idle>-0 3dN.2 29us : dequeue_pushable_task <-pick_next_task_rt
1961 <idle>-0 3d..3 29us : __schedule <-preempt_schedule
1962 <idle>-0 3d..3 30us : 0:120:R ==> [003] 2448: 94:R sleep
1967 The interrupt went off while when the system was idle. Somewhere
1972 --------------------------
1979 # echo 0 > options/function-trace
1984 # chrt -f 5 sleep 1
1989 # wakeup_rt latency trace v1.1.5 on 3.8.0-test+
1990 # --------------------------------------------------------------------
1991 # latency: 6 us, #12/12, CPU#2 | (M:preempt VP:0, KP:0, SP:0 HP:0 #P:4)
1992 # -----------------
1993 # | task: sleep-5882 (uid:0 nice:0 policy:1 rt_prio:5)
1994 # -----------------
1996 # _------=> CPU#
1997 # / _-----=> irqs-off
1998 # | / _----=> need-resched
1999 # || / _---=> hardirq/softirq
2000 # ||| / _--=> preempt-depth
2001 # |||| / delay
2004 <idle>-0 2d.h4 0us : 0:120:R + [002] 5882: 94:R sleep
2005 <idle>-0 2d.h4 0us : ttwu_do_activate.constprop.87 <-try_to_wake_up
2006 <idle>-0 2d.h4 1us : sched_wakeup: comm=sleep pid=5882 prio=94 success=1 target_cpu=002
2007 <idle>-0 2dNh2 1us : hrtimer_expire_exit: hrtimer=ffff88007796feb8
2008 <idle>-0 2.N.2 2us : power_end: cpu_id=2
2009 <idle>-0 2.N.2 3us : cpu_idle: state=4294967295 cpu_id=2
2010 <idle>-0 2dN.3 4us : hrtimer_cancel: hrtimer=ffff88007d50d5e0
2011 …<idle>-0 2dN.3 4us : hrtimer_start: hrtimer=ffff88007d50d5e0 function=tick_sched_timer ex…
2012 <idle>-0 2.N.2 5us : rcu_utilization: Start context switch
2013 <idle>-0 2.N.2 5us : rcu_utilization: End context switch
2014 <idle>-0 2d..3 6us : __schedule <-schedule
2015 <idle>-0 2d..3 6us : 0:120:R ==> [002] 5882: 94:R sleep
2019 -------------------------
2032 # _-----=> irqs-off
2033 # / _----=> need-resched
2034 # | / _---=> hardirq/softirq
2035 # || / _--=> preempt-depth
2036 # ||| / delay
2037 # TASK-PID CPU# |||| TIMESTAMP FUNCTION
2039 … <...>-3638 [001] d... 19452.055471: #1 inner/outer(us): 12/14 ts:1499801089.066141940
2040 … <...>-3638 [003] d... 19454.071354: #2 inner/outer(us): 11/9 ts:1499801091.082164365
2041 … <...>-3638 [002] dn.. 19461.126852: #3 inner/outer(us): 12/9 ts:1499801098.138150062
2042 … <...>-3638 [001] d... 19488.340960: #4 inner/outer(us): 8/12 ts:1499801125.354139633
2043 … <...>-3638 [003] d... 19494.388553: #5 inner/outer(us): 8/12 ts:1499801131.402150961
2044 …<...>-3638 [003] d... 19501.283419: #6 inner/outer(us): 0/12 ts:1499801138.297435289 nm…
2054 inner/outer(us): 12/14
2066 nmi-total:4 nmi-count:1
2068 On architectures that support it, if an NMI comes in during the
2069 test, the time spent in NMI is reported in "nmi-total" (in
2072 All architectures that have NMIs will show the "nmi-count" if an
2100 should run on.
2103 --------
2119 # entries-in-buffer/entries-written: 24799/24799 #P:4
2121 # _-----=> irqs-off
2122 # / _----=> need-resched
2123 # | / _---=> hardirq/softirq
2124 # || / _--=> preempt-depth
2125 # ||| / delay
2126 # TASK-PID CPU# |||| TIMESTAMP FUNCTION
2128 bash-1994 [002] .... 3082.063030: mutex_unlock <-rb_simple_write
2129 bash-1994 [002] .... 3082.063031: __mutex_unlock_slowpath <-mutex_unlock
2130 bash-1994 [002] .... 3082.063031: __fsnotify_parent <-fsnotify_modify
2131 bash-1994 [002] .... 3082.063032: fsnotify <-fsnotify_modify
2132 bash-1994 [002] .... 3082.063032: __srcu_read_lock <-fsnotify
2133 bash-1994 [002] .... 3082.063032: add_preempt_count <-__srcu_read_lock
2134 bash-1994 [002] ...1 3082.063032: sub_preempt_count <-__srcu_read_lock
2135 bash-1994 [002] .... 3082.063033: __srcu_read_unlock <-fsnotify
2163 ---------------------
2177 # TASK-PID CPU# TIMESTAMP FUNCTION
2179 yum-updatesd-3111 [003] 1637.254676: finish_task_switch <-thread_return
2180 yum-updatesd-3111 [003] 1637.254681: hrtimer_cancel <-schedule_hrtimeout_range
2181 yum-updatesd-3111 [003] 1637.254682: hrtimer_try_to_cancel <-hrtimer_cancel
2182 yum-updatesd-3111 [003] 1637.254683: lock_hrtimer_base <-hrtimer_try_to_cancel
2183 yum-updatesd-3111 [003] 1637.254685: fget_light <-do_sys_poll
2184 yum-updatesd-3111 [003] 1637.254686: pipe_poll <-do_sys_poll
2189 # TASK-PID CPU# TIMESTAMP FUNCTION
2192 yum-updatesd-3111 [003] 1701.957688: free_poll_entry <-poll_freewait
2193 yum-updatesd-3111 [003] 1701.957689: remove_wait_queue <-free_poll_entry
2194 yum-updatesd-3111 [003] 1701.957691: fput <-free_poll_entry
2195 yum-updatesd-3111 [003] 1701.957692: audit_syscall_exit <-sysret_audit
2196 yum-updatesd-3111 [003] 1701.957693: path_put <-audit_syscall_exit
2259 exit(-1);
2268 exit(-1);
2291 tracefs=`sed -ne 's/^tracefs \(.*\) tracefs.*/\1/p' /proc/mounts`
2301 ---------------------------
2304 probes a function on its entry and its exit. This is done by
2306 task_struct. On function entry the tracer overwrites the return
2308 original return address is stored on the stack of return address
2311 Probing on both ends of a function leads to special features
2314 - measure of a function's time execution
2315 - having a reliable call stack to draw function calls graph
2319 - you want to find the reason of a strange kernel behavior and
2320 need to see what happens in detail on any areas (or specific
2323 - you are experiencing weird latencies but it's difficult to
2326 - you want to find quickly which path is taken by a specific
2329 - you just want to peek inside a working kernel and want to see
2343 0) 1.382 us | __might_sleep();
2344 0) 2.478 us | }
2347 0) 1.389 us | __might_sleep();
2348 0) 2.553 us | }
2349 0) 3.807 us | }
2350 0) 7.876 us | }
2352 0) 0.668 us | _spin_lock();
2353 0) 0.570 us | expand_files();
2354 0) 0.586 us | _spin_unlock();
2359 want, depending on your needs.
2361 - The cpu number on which the function executed is default
2366 - hide: echo nofuncgraph-cpu > trace_options
2367 - show: echo funcgraph-cpu > trace_options
2369 - The duration (function's time of execution) is displayed on
2370 the closing bracket line of a function or on the same line
2374 - hide: echo nofuncgraph-duration > trace_options
2375 - show: echo funcgraph-duration > trace_options
2377 - The overhead field precedes the duration field in case of
2380 - hide: echo nofuncgraph-overhead > trace_options
2381 - show: echo funcgraph-overhead > trace_options
2382 - depends on: funcgraph-duration
2386 3) # 1837.709 us | } /* __switch_to */
2388 3) 0.313 us | _raw_spin_unlock_irq();
2389 3) 3.177 us | }
2390 3) # 1889.063 us | } /* __schedule */
2391 3) ! 140.417 us | } /* __schedule */
2392 3) # 2034.948 us | } /* schedule */
2393 3) * 33998.59 us | } /* schedule_preempt_disabled */
2397 1) 0.260 us | msecs_to_jiffies();
2398 1) 0.313 us | __rcu_read_unlock();
2399 1) + 61.770 us | }
2400 1) + 64.479 us | }
2401 1) 0.313 us | rcu_bh_qs();
2402 1) 0.313 us | __local_bh_enable();
2403 1) ! 217.240 us | }
2404 1) 0.365 us | idle_cpu();
2406 1) 0.417 us | rcu_eqs_enter_common.isra.47();
2407 1) 3.125 us | }
2408 1) ! 227.812 us | }
2409 1) ! 457.395 us | }
2410 1) @ 119760.2 us | }
2415 1) 6.979 us | }
2416 2) 0.417 us | scheduler_ipi();
2417 1) 9.791 us | }
2418 1) + 12.917 us | }
2419 2) 3.490 us | }
2420 1) + 15.729 us | }
2421 1) + 18.542 us | }
2422 2) $ 3594274 us | }
2434 - The task/pid field displays the thread cmdline and pid which
2437 - hide: echo nofuncgraph-proc > trace_options
2438 - show: echo funcgraph-proc > trace_options
2446 0) sh-4802 | | d_free() {
2447 0) sh-4802 | | call_rcu() {
2448 0) sh-4802 | | __call_rcu() {
2449 0) sh-4802 | 0.616 us | rcu_process_gp_end();
2450 0) sh-4802 | 0.586 us | check_for_new_grace_period();
2451 0) sh-4802 | 2.899 us | }
2452 0) sh-4802 | 4.040 us | }
2453 0) sh-4802 | 5.151 us | }
2454 0) sh-4802 | + 49.370 us | }
2457 - The absolute time field is an absolute timestamp given by the
2459 given on each entry/exit of functions
2461 - hide: echo nofuncgraph-abstime > trace_options
2462 - show: echo funcgraph-abstime > trace_options
2469 360.774522 | 1) 0.541 us | }
2470 360.774522 | 1) 4.663 us | }
2471 360.774523 | 1) 0.541 us | __wake_up_bit();
2472 360.774524 | 1) 6.796 us | }
2473 360.774524 | 1) 7.952 us | }
2474 360.774525 | 1) 9.063 us | }
2475 360.774525 | 1) 0.615 us | journal_mark_dirty();
2476 360.774527 | 1) 0.578 us | __brelse();
2481 360.774530 | 1) 0.594 us | __phys_addr();
2493 - hide: echo nofuncgraph-tail > trace_options
2494 - show: echo funcgraph-tail > trace_options
2496 Example with nofuncgraph-tail (default)::
2500 0) 0.518 us | __phys_addr();
2501 0) 1.757 us | }
2502 0) 2.861 us | }
2504 Example with funcgraph-tail::
2508 0) 0.518 us | __phys_addr();
2509 0) 1.757 us | } /* kmem_cache_free() */
2510 0) 2.861 us | } /* putname() */
2512 You can put some comments on specific functions by using
2523 1) 1.449 us | }
2531 --------------
2536 every kernel function, produced by the -pg switch in gcc),
2538 include the -pg switch in the compiling of the kernel.)
2544 with gcc verson 4.6, the -mfentry has been added for x86, which
2555 The recordmcount program re-links this section back into the
2559 On boot up, before SMP is initialized, the dynamic ftrace code
2569 tracepoints is dependent on architecture. The old method is to use
2584 and can just slap the new code on top of the old without any
2587 One special side-effect to the recording of the functions being
2627 # entries-in-buffer/entries-written: 5/5 #P:4
2629 # _-----=> irqs-off
2630 # / _----=> need-resched
2631 # | / _---=> hardirq/softirq
2632 # || / _--=> preempt-depth
2633 # ||| / delay
2634 # TASK-PID CPU# |||| TIMESTAMP FUNCTION
2636 usleep-2665 [001] .... 4186.475355: sys_nanosleep <-system_call_fastpath
2637 <idle>-0 [001] d.h1 4186.475409: hrtimer_interrupt <-smp_apic_timer_interrupt
2638 usleep-2665 [001] d.h1 4186.475426: hrtimer_interrupt <-smp_apic_timer_interrupt
2639 <idle>-0 [003] d.h1 4186.475426: hrtimer_interrupt <-smp_apic_timer_interrupt
2640 <idle>-0 [002] d.h1 4186.475427: hrtimer_interrupt <-smp_apic_timer_interrupt
2674 # entries-in-buffer/entries-written: 897/897 #P:4
2676 # _-----=> irqs-off
2677 # / _----=> need-resched
2678 # | / _---=> hardirq/softirq
2679 # || / _--=> preempt-depth
2680 # ||| / delay
2681 # TASK-PID CPU# |||| TIMESTAMP FUNCTION
2683 <idle>-0 [003] dN.1 4228.547803: hrtimer_cancel <-tick_nohz_idle_exit
2684 <idle>-0 [003] dN.1 4228.547804: hrtimer_try_to_cancel <-hrtimer_cancel
2685 <idle>-0 [003] dN.2 4228.547805: hrtimer_force_reprogram <-__remove_hrtimer
2686 <idle>-0 [003] dN.1 4228.547805: hrtimer_forward <-tick_nohz_idle_exit
2687 … <idle>-0 [003] dN.1 4228.547805: hrtimer_start_range_ns <-hrtimer_start_expires.constprop.11
2688 <idle>-0 [003] d..1 4228.547858: hrtimer_get_next_event <-get_next_timer_interrupt
2689 <idle>-0 [003] d..1 4228.547859: hrtimer_start <-__tick_nohz_idle_enter
2690 <idle>-0 [003] d..2 4228.547860: hrtimer_force_reprogram <-__rem
2763 # entries-in-buffer/entries-written: 39608/39608 #P:4
2765 # _-----=> irqs-off
2766 # / _----=> need-resched
2767 # | / _---=> hardirq/softirq
2768 # || / _--=> preempt-depth
2769 # ||| / delay
2770 # TASK-PID CPU# |||| TIMESTAMP FUNCTION
2772 bash-1994 [000] .... 4342.324896: file_ra_state_init <-do_dentry_open
2773 bash-1994 [000] .... 4342.324897: open_check_o_direct <-do_last
2774 bash-1994 [000] .... 4342.324897: ima_file_check <-do_last
2775 bash-1994 [000] .... 4342.324898: process_measurement <-ima_file_check
2776 bash-1994 [000] .... 4342.324898: ima_get_action <-process_measurement
2777 bash-1994 [000] .... 4342.324898: ima_match_policy <-ima_get_action
2778 bash-1994 [000] .... 4342.324899: do_truncate <-do_last
2779 bash-1994 [000] .... 4342.324899: should_remove_suid <-do_truncate
2780 bash-1994 [000] .... 4342.324899: notify_change <-do_truncate
2781 bash-1994 [000] .... 4342.324900: current_fs_time <-notify_change
2782 bash-1994 [000] .... 4342.324900: current_kernel_time <-current_fs_time
2783 bash-1994 [000] .... 4342.324900: timespec_trunc <-current_fs_time
2789 ---------------------------------------------
2792 function tracer and the function-graph-tracer, there are some
2793 special features only available in the function-graph tracer.
2806 0) 0.804 us | find_get_page();
2808 0) 1.329 us | }
2809 0) 3.904 us | }
2810 0) 4.979 us | }
2811 0) 0.653 us | _spin_lock();
2812 0) 0.578 us | page_add_file_rmap();
2813 0) 0.525 us | native_set_pte_at();
2814 0) 0.585 us | _spin_unlock();
2816 0) 0.541 us | page_waitqueue();
2817 0) 0.639 us | __wake_up_bit();
2818 0) 2.786 us | }
2819 0) + 14.237 us | }
2823 0) 0.698 us | find_get_page();
2825 0) 1.412 us | }
2826 0) 3.950 us | }
2827 0) 5.098 us | }
2828 0) 0.631 us | _spin_lock();
2829 0) 0.571 us | page_add_file_rmap();
2830 0) 0.526 us | native_set_pte_at();
2831 0) 0.586 us | _spin_unlock();
2833 0) 0.533 us | page_waitqueue();
2834 0) 0.638 us | __wake_up_bit();
2835 0) 2.793 us | }
2836 0) + 14.012 us | }
2850 --------------
2852 Note, the proc sysctl ftrace_enable is a big on/off switch for the
2872 ---------------
2881 - mod:
2889 filtering based on function names. Thus, adding more functions
2913 - traceon/traceoff:
2914 These commands turn tracing on and off when the specified
2916 tracing system is turned on and off. If unspecified, there is
2937 - snapshot:
2953 - enable_event/disable_event:
2977 - dump:
2984 - cpudump:
2991 ----------
2994 the effect on the tracing is different. Every read from
3008 # entries-in-buffer/entries-written: 0/0 #P:4
3010 # _-----=> irqs-off
3011 # / _----=> need-resched
3012 # | / _---=> hardirq/softirq
3013 # || / _--=> preempt-depth
3014 # ||| / delay
3015 # TASK-PID CPU# |||| TIMESTAMP FUNCTION
3020 bash-1994 [000] .... 5281.568961: mutex_unlock <-rb_simple_write
3021 bash-1994 [000] .... 5281.568963: __mutex_unlock_slowpath <-mutex_unlock
3022 bash-1994 [000] .... 5281.568963: __fsnotify_parent <-fsnotify_modify
3023 bash-1994 [000] .... 5281.568964: fsnotify <-fsnotify_modify
3024 bash-1994 [000] .... 5281.568964: __srcu_read_lock <-fsnotify
3025 bash-1994 [000] .... 5281.568964: add_preempt_count <-__srcu_read_lock
3026 bash-1994 [000] ...1 5281.568965: sub_preempt_count <-__srcu_read_lock
3027 bash-1994 [000] .... 5281.568965: __srcu_read_unlock <-fsnotify
3028 bash-1994 [000] .... 5281.568967: sys_dup2 <-system_call_fastpath
3035 -------------
3062 much, it can cause Out-Of-Memory to trigger.
3066 -bash: echo: write error: Cannot allocate memory
3093 --------
3121 +--------------+------------+------------+------------+
3125 +--------------+------------+------------+------------+
3127 +--------------+------------+------------+------------+
3137 # entries-in-buffer/entries-written: 71/71 #P:8
3139 # _-----=> irqs-off
3140 # / _----=> need-resched
3141 # | / _---=> hardirq/softirq
3142 # || / _--=> preempt-depth
3143 # ||| / delay
3144 # TASK-PID CPU# |||| TIMESTAMP FUNCTION
3146 …<idle>-0 [005] d... 2440.603828: sched_switch: prev_comm=swapper/5 prev_pid=0 prev_prio=120 …
3147 …sleep-2242 [005] d... 2440.603846: sched_switch: prev_comm=snapshot-test-2 prev_pid=2242 prev_pr…
3149 …<idle>-0 [002] d... 2440.707230: sched_switch: prev_comm=swapper/2 prev_pid=0 prev_prio=120 p…
3154 # entries-in-buffer/entries-written: 77/77 #P:8
3156 # _-----=> irqs-off
3157 # / _----=> need-resched
3158 # | / _---=> hardirq/softirq
3159 # || / _--=> preempt-depth
3160 # ||| / delay
3161 # TASK-PID CPU# |||| TIMESTAMP FUNCTION
3163 …<idle>-0 [007] d... 2440.707395: sched_switch: prev_comm=swapper/7 prev_pid=0 prev_prio=120 p…
3164 …snapshot-test-2-2229 [002] d... 2440.707438: sched_switch: prev_comm=snapshot-test-2 prev_pid=22…
3180 ---------
3226 bash-2044 [002] .... 10594.481032: _raw_spin_lock_irqsave <-get_page_from_freelist
3227 bash-2044 [002] d... 10594.481032: add_preempt_count <-_raw_spin_lock_irqsave
3228 bash-2044 [002] d..1 10594.481032: __rmqueue <-get_page_from_freelist
3229 bash-2044 [002] d..1 10594.481033: _raw_spin_unlock <-get_page_from_freelist
3230 bash-2044 [002] d..1 10594.481033: sub_preempt_count <-_raw_spin_unlock
3231 … bash-2044 [002] d... 10594.481033: get_pageblock_flags_group <-get_pageblock_migratetype
3232 bash-2044 [002] d... 10594.481034: __mod_zone_page_state <-get_page_from_freelist
3233 bash-2044 [002] d... 10594.481034: zone_statistics <-get_page_from_freelist
3234 bash-2044 [002] d... 10594.481034: __inc_zone_state <-zone_statistics
3235 bash-2044 [002] d... 10594.481034: __inc_zone_state <-zone_statistics
3236 bash-2044 [002] .... 10594.481035: arch_dup_task_struct <-copy_process
3240 …bash-1998 [000] d..4 136.676759: sched_wakeup: comm=kworker/0:1 pid=59 prio=120 success=1 targe…
3241 …bash-1998 [000] dN.4 136.676760: sched_wakeup: comm=bash pid=1998 prio=120 success=1 target_cpu…
3242 …<idle>-0 [003] d.h3 136.676906: sched_wakeup: comm=rcu_preempt pid=9 prio=120 success=1 targ…
3243 …<idle>-0 [003] d..3 136.676909: sched_switch: prev_comm=swapper/3 prev_pid=0 prev_prio=120 p…
3244 …rcu_preempt-9 [003] d..3 136.676916: sched_switch: prev_comm=rcu_preempt prev_pid=9 prev_pri…
3245 …bash-1998 [000] d..4 136.677014: sched_wakeup: comm=kworker/0:1 pid=59 prio=120 success=1 targe…
3246 …bash-1998 [000] dN.4 136.677016: sched_wakeup: comm=bash pid=1998 prio=120 success=1 target_cpu…
3247 …bash-1998 [000] d..3 136.677018: sched_switch: prev_comm=bash prev_pid=1998 prev_prio=120 prev_…
3248 …kworker/0:1-59 [000] d..4 136.677022: sched_wakeup: comm=sshd pid=1995 prio=120 success=1 tar…
3249 …kworker/0:1-59 [000] d..3 136.677025: sched_switch: prev_comm=kworker/0:1 prev_pid=59 prev_pr…
3253 migration/1-14 [001] d.h3 138.732674: softirq_raise: vec=3 [action=NET_RX]
3254 <idle>-0 [001] dNh3 138.732725: softirq_raise: vec=3 [action=NET_RX]
3255 bash-1998 [000] d.h1 138.733101: softirq_raise: vec=1 [action=TIMER]
3256 bash-1998 [000] d.h1 138.733102: softirq_raise: vec=9 [action=RCU]
3257 bash-1998 [000] ..s2 138.733105: softirq_entry: vec=1 [action=TIMER]
3258 bash-1998 [000] ..s2 138.733106: softirq_exit: vec=1 [action=TIMER]
3259 bash-1998 [000] ..s2 138.733106: softirq_entry: vec=9 [action=RCU]
3260 bash-1998 [000] ..s2 138.733109: softirq_exit: vec=9 [action=RCU]
3261 sshd-1995 [001] d.h1 138.733278: irq_handler_entry: irq=21 name=uhci_hcd:usb4
3262 sshd-1995 [001] d.h1 138.733280: irq_handler_exit: irq=21 ret=unhandled
3263 sshd-1995 [001] d.h1 138.733281: irq_handler_entry: irq=21 name=eth0
3264 sshd-1995 [001] d.h1 138.733283: irq_handler_exit: irq=21 ret=handled
3270 # entries-in-buffer/entries-written: 18996/18996 #P:4
3272 # _-----=> irqs-off
3273 # / _----=> need-resched
3274 # | / _---=> hardirq/softirq
3275 # || / _--=> preempt-depth
3276 # ||| / delay
3277 # TASK-PID CPU# |||| TIMESTAMP FUNCTION
3279 bash-1998 [000] d... 140.733501: sys_write -> 0x2
3280 bash-1998 [000] d... 140.733504: sys_dup2(oldfd: a, newfd: 1)
3281 bash-1998 [000] d... 140.733506: sys_dup2 -> 0x1
3282 bash-1998 [000] d... 140.733508: sys_fcntl(fd: a, cmd: 1, arg: 0)
3283 bash-1998 [000] d... 140.733509: sys_fcntl -> 0x1
3284 bash-1998 [000] d... 140.733510: sys_close(fd: a)
3285 bash-1998 [000] d... 140.733510: sys_close -> 0x0
3286 …bash-1998 [000] d... 140.733514: sys_rt_sigprocmask(how: 0, nset: 0, oset: 6e2768, sigsetsize: …
3287 bash-1998 [000] d... 140.733515: sys_rt_sigprocmask -> 0x0
3288 …bash-1998 [000] d... 140.733516: sys_rt_sigaction(sig: 2, act: 7fff718846f0, oact: 7fff71884650…
3289 bash-1998 [000] d... 140.733516: sys_rt_sigaction -> 0x0
3307 -----------
3310 what they allocate on the stack. If they add too much, the system
3338 ----- ---- --------
3358 Note, if -mfentry is being used by gcc, functions get traced before
3360 are not tested by the stack tracer when -mfentry is used.
3362 Currently, -mfentry is used by gcc 4.6.0 and above on x86 only.
3365 ----