Lines Matching +full:d +full:- +full:cache +full:- +full:size
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
117 set this file to "0". User space can re-enable tracing by
122 be re-enabled by user space using this file.
129 are closed, tracing is re-enabled.
183 buffer holds. By default, the trace buffers are the same size
184 for each CPU. The displayed number is the size of the
185 CPU buffer and not total size of all buffers. The
187 that the kernel uses for allocation, usually 4 KB in size).
191 ( Note, the size may not be a multiple of the page size
192 due to buffer management meta-data. )
200 This displays the total combined size of all the trace buffers.
207 of this file, the ring buffer will be resized to its minimum size.
256 If the "function-fork" option is set, then when a task whose
269 added on fork, enable the "event-fork" option. That option will also
318 the "ip modify" attribute (thus the regs->ip can be changed),
374 makes a cache of pid mappings to comms to try to display
378 If the option "record-cmd" is set to "0", then comms of tasks
385 in a the number of comms to cache, into this file.
389 If the option "record-tgid" is set, on each scheduling context switch
391 the thread to its TGID. By default, the "record-tgid" option is
403 maximum stack size it has encountered.
430 [local] global counter x86-tsc
457 x86-tsc:
461 ppc-tb:
484 Also on 32-bit systems, it's possible that the 64-bit boot offset
589 delta: Default timestamp mode - timestamp is a delta against
590 a per-buffer timestamp.
609 and free from cache bouncing. These buffers may have different
610 size buffers. This file is similar to the buffer_size_kb
611 file, but it only displays or sets the buffer size for the
664 event (ring buffer is re-entrant), that it fills the
683 -----------
717 trace with the latency-format option enabled, which
771 ----------------
803 ----------------------------
807 user-land utilities).
810 --------------
816 # entries-in-buffer/entries-written: 140080/250280 #P:4
818 # _-----=> irqs-off
819 # / _----=> need-resched
820 # | / _---=> hardirq/softirq
821 # || / _--=> preempt-depth
823 # TASK-PID CPU# |||| TIMESTAMP FUNCTION
825 bash-1977 [000] .... 17284.993652: sys_close <-system_call_fastpath
826 bash-1977 [000] .... 17284.993653: __close_fd <-sys_close
827 bash-1977 [000] .... 17284.993653: _raw_spin_lock <-__close_fd
828 sshd-1974 [003] .... 17284.993653: __srcu_read_unlock <-fsnotify
829 bash-1977 [000] .... 17284.993654: add_preempt_count <-_raw_spin_lock
830 bash-1977 [000] ...1 17284.993655: _raw_spin_unlock <-__close_fd
831 bash-1977 [000] ...1 17284.993656: sub_preempt_count <-_raw_spin_unlock
832 bash-1977 [000] .... 17284.993657: filp_close <-__close_fd
833 bash-1977 [000] .... 17284.993657: dnotify_flush <-filp_close
834 sshd-1974 [003] .... 17284.993658: sys_select <-system_call_fastpath
841 lost due to the buffer filling up (250280 - 140080 = 110200 events
852 --------------------
854 When the latency-format option is enabled or when one of the latency
860 # irqsoff latency trace v1.1.5 on 3.8.0-test+
861 # --------------------------------------------------------------------
863 # -----------------
864 # | task: ps-6143 (uid:0 nice:0 policy:0 rt_prio:0)
865 # -----------------
870 # _------=> CPU#
871 # / _-----=> irqs-off
872 # | / _----=> need-resched
873 # || / _---=> hardirq/softirq
874 # ||| / _--=> preempt-depth
878 ps-6143 2d... 0us!: trace_hardirqs_off <-__lock_task_sighand
879 ps-6143 2d..1 259us+: trace_hardirqs_on <-_raw_spin_unlock_irqrestore
880 ps-6143 2d..1 263us+: time_hardirqs_on <-_raw_spin_unlock_irqrestore
881 ps-6143 2d..1 306us : <stack trace>
908 - __lock_task_sighand is where the interrupts were disabled.
909 - _raw_spin_unlock_irqrestore is where they were enabled again.
920 irqs-off: 'd' interrupts are disabled. '.' otherwise.
925 need-resched:
926 - 'N' both TIF_NEED_RESCHED and PREEMPT_NEED_RESCHED is set,
927 - 'n' only TIF_NEED_RESCHED is set,
928 - 'p' only PREEMPT_NEED_RESCHED is set,
929 - '.' otherwise.
932 - 'Z' - NMI occurred inside a hardirq
933 - 'z' - NMI is running
934 - 'H' - hard irq occurred inside a softirq.
935 - 'h' - hard irq is running
936 - 's' - soft irq is running
937 - '.' - normal context.
939 preempt-depth: The level of preempt_disabled
944 When the latency-format option is enabled, the trace file
946 trace. This differs from the output when latency-format
955 - '$' - greater than 1 second
956 - '@' - greater than 100 millisecond
957 - '*' - greater than 10 millisecond
958 - '#' - greater than 1000 microsecond
959 - '!' - greater than 100 microsecond
960 - '+' - greater than 10 microsecond
961 - ' ' - less than or equal to 10 microsecond.
969 -------------
976 print-parent
977 nosym-offset
978 nosym-addr
987 nosym-userobj
988 noprintk-msg-only
989 context-info
990 nolatency-format
991 record-cmd
992 norecord-tgid
995 irq-info
997 noevent-fork
998 function-trace
999 nofunction-fork
1000 nodisplay-graph
1007 echo noprint-parent > trace_options
1011 echo sym-offset > trace_options
1015 print-parent
1020 print-parent:
1021 bash-4000 [01] 1477.606694: simple_strtoul <-kstrtoul
1023 noprint-parent:
1024 bash-4000 [01] 1477.606694: simple_strtoul
1027 sym-offset
1034 sym-offset:
1035 bash-4000 [01] 1477.606694: simple_strtoul+0x6/0xa0
1037 sym-addr
1042 sym-addr:
1043 bash-4000 [01] 1477.606694: simple_strtoul <c0339346>
1047 latency-format option is enabled.
1080 <idle>-0 [001] dNs4 21169.031481: wake_up_idle_cpu <-add_timer_on
1081 <idle>-0 [001] dNs4 21169.031482: _raw_spin_unlock_irqrestore <-add_timer_on
1082 <idle>-0 [001] .Ns4 21169.031484: sub_preempt_count <-_raw_spin_unlock_irqrestore
1084 <idle>-0 [002] .N.1 21169.031484: rcu_idle_exit <-cpu_idle
1085 <idle>-0 [001] .Ns3 21169.031484: _raw_spin_unlock <-clocksource_watchdog
1086 <idle>-0 [001] .Ns3 21169.031485: sub_preempt_count <-_raw_spin_unlock
1093 sym-userobj
1104 a.out-1623 [000] 40874.465068: /root/a.out[+0x480] <-/root/a.out[+0
1105 x494] <- /root/a.out[+0x4a8] <- /lib/libc-2.7.so[+0x1e1a6]
1108 printk-msg-only
1113 context-info
1117 latency-format
1122 record-cmd
1124 in the sched_switch trace point to fill comm cache
1130 record-tgid
1132 in the sched_switch trace point to fill the cache of
1147 irq-info
1153 # entries-in-buffer/entries-written: 144405/9452052 #P:4
1155 # TASK-PID CPU# TIMESTAMP FUNCTION
1157 <idle>-0 [002] 23636.756054: ttwu_do_activate.constprop.89 <-try_to_wake_up
1158 <idle>-0 [002] 23636.756054: activate_task <-ttwu_do_activate.constprop.89
1159 <idle>-0 [002] 23636.756055: enqueue_task <-activate_task
1167 event-fork
1173 function-trace
1180 function-fork
1187 display-graph
1223 funcgraph-overrun
1234 funcgraph-cpu
1238 funcgraph-overhead
1244 funcgraph-proc
1251 funcgraph-duration
1256 funcgraph-abstime
1259 funcgraph-irqs
1263 funcgraph-tail
1269 sleep-time
1275 graph-time
1289 -------
1306 # echo 0 > options/function-trace
1310 # ls -ltr
1316 # irqsoff latency trace v1.1.5 on 3.8.0-test+
1317 # --------------------------------------------------------------------
1319 # -----------------
1320 # | task: swapper/0-0 (uid:0 nice:0 policy:0 rt_prio:0)
1321 # -----------------
1326 # _------=> CPU#
1327 # / _-----=> irqs-off
1328 # | / _----=> need-resched
1329 # || / _---=> hardirq/softirq
1330 # ||| / _--=> preempt-depth
1334 <idle>-0 0d.s2 0us+: _raw_spin_lock_irq <-run_timer_softirq
1335 <idle>-0 0dNs3 17us : _raw_spin_unlock_irq <-run_timer_softirq
1336 <idle>-0 0dNs3 17us+: trace_hardirqs_on <-run_timer_softirq
1337 <idle>-0 0dNs3 25us : <stack trace>
1360 Note the above example had function-trace not set. If we set
1361 function-trace, we get a much larger output::
1363 with echo 1 > options/function-trace
1367 # irqsoff latency trace v1.1.5 on 3.8.0-test+
1368 # --------------------------------------------------------------------
1370 # -----------------
1371 # | task: bash-2042 (uid:0 nice:0 policy:0 rt_prio:0)
1372 # -----------------
1377 # _------=> CPU#
1378 # / _-----=> irqs-off
1379 # | / _----=> need-resched
1380 # || / _---=> hardirq/softirq
1381 # ||| / _--=> preempt-depth
1385 bash-2042 3d... 0us : _raw_spin_lock_irqsave <-ata_scsi_queuecmd
1386 bash-2042 3d... 0us : add_preempt_count <-_raw_spin_lock_irqsave
1387 bash-2042 3d..1 1us : ata_scsi_find_dev <-ata_scsi_queuecmd
1388 bash-2042 3d..1 1us : __ata_scsi_find_dev <-ata_scsi_find_dev
1389 bash-2042 3d..1 2us : ata_find_dev.part.14 <-__ata_scsi_find_dev
1390 bash-2042 3d..1 2us : ata_qc_new_init <-__ata_scsi_queuecmd
1391 bash-2042 3d..1 3us : ata_sg_init <-__ata_scsi_queuecmd
1392 bash-2042 3d..1 4us : ata_scsi_rw_xlat <-__ata_scsi_queuecmd
1393 bash-2042 3d..1 4us : ata_build_rw_tf <-ata_scsi_rw_xlat
1395 bash-2042 3d..1 67us : delay_tsc <-__delay
1396 bash-2042 3d..1 67us : add_preempt_count <-delay_tsc
1397 bash-2042 3d..2 67us : sub_preempt_count <-delay_tsc
1398 bash-2042 3d..1 67us : add_preempt_count <-delay_tsc
1399 bash-2042 3d..2 68us : sub_preempt_count <-delay_tsc
1400 bash-2042 3d..1 68us+: ata_bmdma_start <-ata_bmdma_qc_issue
1401 bash-2042 3d..1 71us : _raw_spin_unlock_irqrestore <-ata_scsi_queuecmd
1402 bash-2042 3d..1 71us : _raw_spin_unlock_irqrestore <-ata_scsi_queuecmd
1403 bash-2042 3d..1 72us+: trace_hardirqs_on <-ata_scsi_queuecmd
1404 bash-2042 3d..1 120us : <stack trace>
1439 display-graph option::
1441 with echo 1 > options/display-graph
1445 # irqsoff latency trace v1.1.5 on 4.20.0-rc6+
1446 # --------------------------------------------------------------------
1448 # -----------------
1449 # | task: bash-1507 (uid:0 nice:0 policy:0 rt_prio:0)
1450 # -----------------
1455 # _-----=> irqs-off
1456 # / _----=> need-resched
1457 # | / _---=> hardirq/softirq
1458 # || / _--=> preempt-depth
1462 0 us | 0) bash-1507 | d... | 0.000 us | _raw_spin_lock_irqsave();
1463 0 us | 0) bash-1507 | d..1 | 0.378 us | do_raw_spin_trylock();
1464 1 us | 0) bash-1507 | d..2 | | set_track() {
1465 2 us | 0) bash-1507 | d..2 | | save_stack_trace() {
1466 2 us | 0) bash-1507 | d..2 | | __save_stack_trace() {
1467 3 us | 0) bash-1507 | d..2 | | __unwind_start() {
1468 3 us | 0) bash-1507 | d..2 | | get_stack_info() {
1469 3 us | 0) bash-1507 | d..2 | 0.351 us | in_task_stack();
1470 4 us | 0) bash-1507 | d..2 | 1.107 us | }
1472 3750 us | 0) bash-1507 | d..1 | 0.516 us | do_raw_spin_unlock();
1473 3750 us | 0) bash-1507 | d..1 | 0.000 us | _raw_spin_unlock_irqrestore();
1474 3764 us | 0) bash-1507 | d..1 | 0.000 us | tracer_hardirqs_on();
1475 bash-1507 0d..1 3792us : <stack trace>
1492 ----------
1505 # echo 0 > options/function-trace
1509 # ls -ltr
1515 # preemptoff latency trace v1.1.5 on 3.8.0-test+
1516 # --------------------------------------------------------------------
1518 # -----------------
1519 # | task: sshd-1991 (uid:0 nice:0 policy:0 rt_prio:0)
1520 # -----------------
1525 # _------=> CPU#
1526 # / _-----=> irqs-off
1527 # | / _----=> need-resched
1528 # || / _---=> hardirq/softirq
1529 # ||| / _--=> preempt-depth
1533 sshd-1991 1d.h. 0us+: irq_enter <-do_IRQ
1534 sshd-1991 1d..1 46us : irq_exit <-do_IRQ
1535 sshd-1991 1d..1 47us+: trace_preempt_on <-do_IRQ
1536 sshd-1991 1d..1 52us : <stack trace>
1546 the preempt off section and leaving it (the 'd'). We do not know if
1553 # preemptoff latency trace v1.1.5 on 3.8.0-test+
1554 # --------------------------------------------------------------------
1556 # -----------------
1557 # | task: bash-1994 (uid:0 nice:0 policy:0 rt_prio:0)
1558 # -----------------
1563 # _------=> CPU#
1564 # / _-----=> irqs-off
1565 # | / _----=> need-resched
1566 # || / _---=> hardirq/softirq
1567 # ||| / _--=> preempt-depth
1571 bash-1994 1d..1 0us : _raw_spin_lock_irqsave <-wake_up_new_task
1572 bash-1994 1d..1 0us : select_task_rq_fair <-select_task_rq
1573 bash-1994 1d..1 1us : __rcu_read_lock <-select_task_rq_fair
1574 bash-1994 1d..1 1us : source_load <-select_task_rq_fair
1575 bash-1994 1d..1 1us : source_load <-select_task_rq_fair
1577 bash-1994 1d..1 12us : irq_enter <-smp_apic_timer_interrupt
1578 bash-1994 1d..1 12us : rcu_irq_enter <-irq_enter
1579 bash-1994 1d..1 13us : add_preempt_count <-irq_enter
1580 bash-1994 1d.h1 13us : exit_idle <-smp_apic_timer_interrupt
1581 bash-1994 1d.h1 13us : hrtimer_interrupt <-smp_apic_timer_interrupt
1582 bash-1994 1d.h1 13us : _raw_spin_lock <-hrtimer_interrupt
1583 bash-1994 1d.h1 14us : add_preempt_count <-_raw_spin_lock
1584 bash-1994 1d.h2 14us : ktime_get_update_offsets <-hrtimer_interrupt
1586 bash-1994 1d.h1 35us : lapic_next_event <-clockevents_program_event
1587 bash-1994 1d.h1 35us : irq_exit <-smp_apic_timer_interrupt
1588 bash-1994 1d.h1 36us : sub_preempt_count <-irq_exit
1589 bash-1994 1d..2 36us : do_softirq <-irq_exit
1590 bash-1994 1d..2 36us : __do_softirq <-call_softirq
1591 bash-1994 1d..2 36us : __local_bh_disable <-__do_softirq
1592 bash-1994 1d.s2 37us : add_preempt_count <-_raw_spin_lock_irq
1593 bash-1994 1d.s3 38us : _raw_spin_unlock <-run_timer_softirq
1594 bash-1994 1d.s3 39us : sub_preempt_count <-_raw_spin_unlock
1595 bash-1994 1d.s2 39us : call_timer_fn <-run_timer_softirq
1597 bash-1994 1dNs2 81us : cpu_needs_another_gp <-rcu_process_callbacks
1598 bash-1994 1dNs2 82us : __local_bh_enable <-__do_softirq
1599 bash-1994 1dNs2 82us : sub_preempt_count <-__local_bh_enable
1600 bash-1994 1dN.2 82us : idle_cpu <-irq_exit
1601 bash-1994 1dN.2 83us : rcu_irq_exit <-irq_exit
1602 bash-1994 1dN.2 83us : sub_preempt_count <-irq_exit
1603 bash-1994 1.N.1 84us : _raw_spin_unlock_irqrestore <-task_rq_unlock
1604 bash-1994 1.N.1 84us+: trace_preempt_on <-task_rq_unlock
1605 bash-1994 1.N.1 104us : <stack trace>
1616 function-trace set. Here we see that interrupts were not disabled
1623 --------------
1657 # echo 0 > options/function-trace
1661 # ls -ltr
1667 # preemptirqsoff latency trace v1.1.5 on 3.8.0-test+
1668 # --------------------------------------------------------------------
1670 # -----------------
1671 # | task: ls-2230 (uid:0 nice:0 policy:0 rt_prio:0)
1672 # -----------------
1677 # _------=> CPU#
1678 # / _-----=> irqs-off
1679 # | / _----=> need-resched
1680 # || / _---=> hardirq/softirq
1681 # ||| / _--=> preempt-depth
1685 ls-2230 3d... 0us+: _raw_spin_lock_irqsave <-ata_scsi_queuecmd
1686 ls-2230 3...1 100us : _raw_spin_unlock_irqrestore <-ata_scsi_queuecmd
1687 ls-2230 3...1 101us+: trace_preempt_on <-ata_scsi_queuecmd
1688 ls-2230 3...1 111us : <stack trace>
1716 Here is a trace with function-trace set::
1720 # preemptirqsoff latency trace v1.1.5 on 3.8.0-test+
1721 # --------------------------------------------------------------------
1723 # -----------------
1724 # | task: ls-2269 (uid:0 nice:0 policy:0 rt_prio:0)
1725 # -----------------
1730 # _------=> CPU#
1731 # / _-----=> irqs-off
1732 # | / _----=> need-resched
1733 # || / _---=> hardirq/softirq
1734 # ||| / _--=> preempt-depth
1738 kworker/-59 3...1 0us : __schedule <-schedule
1739 kworker/-59 3d..1 0us : rcu_preempt_qs <-rcu_note_context_switch
1740 kworker/-59 3d..1 1us : add_preempt_count <-_raw_spin_lock_irq
1741 kworker/-59 3d..2 1us : deactivate_task <-__schedule
1742 kworker/-59 3d..2 1us : dequeue_task <-deactivate_task
1743 kworker/-59 3d..2 2us : update_rq_clock <-dequeue_task
1744 kworker/-59 3d..2 2us : dequeue_task_fair <-dequeue_task
1745 kworker/-59 3d..2 2us : update_curr <-dequeue_task_fair
1746 kworker/-59 3d..2 2us : update_min_vruntime <-update_curr
1747 kworker/-59 3d..2 3us : cpuacct_charge <-update_curr
1748 kworker/-59 3d..2 3us : __rcu_read_lock <-cpuacct_charge
1749 kworker/-59 3d..2 3us : __rcu_read_unlock <-cpuacct_charge
1750 kworker/-59 3d..2 3us : update_cfs_rq_blocked_load <-dequeue_task_fair
1751 kworker/-59 3d..2 4us : clear_buddies <-dequeue_task_fair
1752 kworker/-59 3d..2 4us : account_entity_dequeue <-dequeue_task_fair
1753 kworker/-59 3d..2 4us : update_min_vruntime <-dequeue_task_fair
1754 kworker/-59 3d..2 4us : update_cfs_shares <-dequeue_task_fair
1755 kworker/-59 3d..2 5us : hrtick_update <-dequeue_task_fair
1756 kworker/-59 3d..2 5us : wq_worker_sleeping <-__schedule
1757 kworker/-59 3d..2 5us : kthread_data <-wq_worker_sleeping
1758 kworker/-59 3d..2 5us : put_prev_task_fair <-__schedule
1759 kworker/-59 3d..2 6us : pick_next_task_fair <-pick_next_task
1760 kworker/-59 3d..2 6us : clear_buddies <-pick_next_task_fair
1761 kworker/-59 3d..2 6us : set_next_entity <-pick_next_task_fair
1762 kworker/-59 3d..2 6us : update_stats_wait_end <-set_next_entity
1763 ls-2269 3d..2 7us : finish_task_switch <-__schedule
1764 ls-2269 3d..2 7us : _raw_spin_unlock_irq <-finish_task_switch
1765 ls-2269 3d..2 8us : do_IRQ <-ret_from_intr
1766 ls-2269 3d..2 8us : irq_enter <-do_IRQ
1767 ls-2269 3d..2 8us : rcu_irq_enter <-irq_enter
1768 ls-2269 3d..2 9us : add_preempt_count <-irq_enter
1769 ls-2269 3d.h2 9us : exit_idle <-do_IRQ
1771 ls-2269 3d.h3 20us : sub_preempt_count <-_raw_spin_unlock
1772 ls-2269 3d.h2 20us : irq_exit <-do_IRQ
1773 ls-2269 3d.h2 21us : sub_preempt_count <-irq_exit
1774 ls-2269 3d..3 21us : do_softirq <-irq_exit
1775 ls-2269 3d..3 21us : __do_softirq <-call_softirq
1776 ls-2269 3d..3 21us+: __local_bh_disable <-__do_softirq
1777 ls-2269 3d.s4 29us : sub_preempt_count <-_local_bh_enable_ip
1778 ls-2269 3d.s5 29us : sub_preempt_count <-_local_bh_enable_ip
1779 ls-2269 3d.s5 31us : do_IRQ <-ret_from_intr
1780 ls-2269 3d.s5 31us : irq_enter <-do_IRQ
1781 ls-2269 3d.s5 31us : rcu_irq_enter <-irq_enter
1783 ls-2269 3d.s5 31us : rcu_irq_enter <-irq_enter
1784 ls-2269 3d.s5 32us : add_preempt_count <-irq_enter
1785 ls-2269 3d.H5 32us : exit_idle <-do_IRQ
1786 ls-2269 3d.H5 32us : handle_irq <-do_IRQ
1787 ls-2269 3d.H5 32us : irq_to_desc <-handle_irq
1788 ls-2269 3d.H5 33us : handle_fasteoi_irq <-handle_irq
1790 ls-2269 3d.s5 158us : _raw_spin_unlock_irqrestore <-rtl8139_poll
1791 ls-2269 3d.s3 158us : net_rps_action_and_irq_enable.isra.65 <-net_rx_action
1792 ls-2269 3d.s3 159us : __local_bh_enable <-__do_softirq
1793 ls-2269 3d.s3 159us : sub_preempt_count <-__local_bh_enable
1794 ls-2269 3d..3 159us : idle_cpu <-irq_exit
1795 ls-2269 3d..3 159us : rcu_irq_exit <-irq_exit
1796 ls-2269 3d..3 160us : sub_preempt_count <-irq_exit
1797 ls-2269 3d... 161us : __mutex_unlock_slowpath <-mutex_unlock
1798 ls-2269 3d... 162us+: trace_hardirqs_on <-mutex_unlock
1799 ls-2269 3d... 186us : <stack trace>
1818 ------
1822 Now for non Real-Time tasks, this can be arbitrary. But tracing
1827 # echo 0 > options/function-trace
1831 # chrt -f 5 sleep 1
1836 # wakeup latency trace v1.1.5 on 3.8.0-test+
1837 # --------------------------------------------------------------------
1839 # -----------------
1840 # | task: kworker/3:1H-312 (uid:0 nice:-20 policy:0 rt_prio:0)
1841 # -----------------
1843 # _------=> CPU#
1844 # / _-----=> irqs-off
1845 # | / _----=> need-resched
1846 # || / _---=> hardirq/softirq
1847 # ||| / _--=> preempt-depth
1851 <idle>-0 3dNs7 0us : 0:120:R + [003] 312:100:R kworker/3:1H
1852 <idle>-0 3dNs7 1us+: ttwu_do_activate.constprop.87 <-try_to_wake_up
1853 <idle>-0 3d..3 15us : __schedule <-schedule
1854 <idle>-0 3d..3 15us : 0:120:R ==> [003] 312:100:R kworker/3:1H
1858 the kworker with a nice priority of -20 (not very nice), took
1862 Non Real-Time tasks are not that interesting. A more interesting
1863 trace is to concentrate only on Real-Time tasks.
1866 ---------
1868 In a Real-Time environment it is very important to know the
1872 also important to know the scheduling latency of non-RT tasks,
1873 but the average schedule latency is better for non-RT tasks.
1877 Real-Time environments are interested in the worst case latency.
1881 work well with Real-Time tasks. The wakeup_rt tracer was designed
1882 to record the worst case wakeups of RT tasks. Non-RT tasks are
1884 tracing non-RT tasks that are unpredictable will overwrite the
1894 # echo 0 > options/function-trace
1898 # chrt -f 5 sleep 1
1905 # wakeup_rt latency trace v1.1.5 on 3.8.0-test+
1906 # --------------------------------------------------------------------
1908 # -----------------
1909 # | task: sleep-2389 (uid:0 nice:0 policy:1 rt_prio:5)
1910 # -----------------
1912 # _------=> CPU#
1913 # / _-----=> irqs-off
1914 # | / _----=> need-resched
1915 # || / _---=> hardirq/softirq
1916 # ||| / _--=> preempt-depth
1920 <idle>-0 3d.h4 0us : 0:120:R + [003] 2389: 94:R sleep
1921 <idle>-0 3d.h4 1us+: ttwu_do_activate.constprop.87 <-try_to_wake_up
1922 <idle>-0 3d..3 5us : __schedule <-schedule
1923 <idle>-0 3d..3 5us : 0:120:R ==> [003] 2389: 94:R sleep
1933 and it has an rt_prio of 5. This priority is user-space priority
1937 Note, that the trace data shows the internal priority (99 - rtprio).
1940 <idle>-0 3d..3 5us : 0:120:R ==> [003] 2389: 94:R sleep
1942 The 0:120:R means idle was running with a nice priority of 0 (120 - 120)
1944 2389: 94:R. That is the priority is the kernel rtprio (99 - 5 = 94)
1947 Doing the same with chrt -r 5 and function-trace set.
1950 echo 1 > options/function-trace
1954 # wakeup_rt latency trace v1.1.5 on 3.8.0-test+
1955 # --------------------------------------------------------------------
1957 # -----------------
1958 # | task: sleep-2448 (uid:0 nice:0 policy:1 rt_prio:5)
1959 # -----------------
1961 # _------=> CPU#
1962 # / _-----=> irqs-off
1963 # | / _----=> need-resched
1964 # || / _---=> hardirq/softirq
1965 # ||| / _--=> preempt-depth
1969 <idle>-0 3d.h4 1us+: 0:120:R + [003] 2448: 94:R sleep
1970 <idle>-0 3d.h4 2us : ttwu_do_activate.constprop.87 <-try_to_wake_up
1971 <idle>-0 3d.h3 3us : check_preempt_curr <-ttwu_do_wakeup
1972 <idle>-0 3d.h3 3us : resched_curr <-check_preempt_curr
1973 <idle>-0 3dNh3 4us : task_woken_rt <-ttwu_do_wakeup
1974 <idle>-0 3dNh3 4us : _raw_spin_unlock <-try_to_wake_up
1975 <idle>-0 3dNh3 4us : sub_preempt_count <-_raw_spin_unlock
1976 <idle>-0 3dNh2 5us : ttwu_stat <-try_to_wake_up
1977 <idle>-0 3dNh2 5us : _raw_spin_unlock_irqrestore <-try_to_wake_up
1978 <idle>-0 3dNh2 6us : sub_preempt_count <-_raw_spin_unlock_irqrestore
1979 <idle>-0 3dNh1 6us : _raw_spin_lock <-__run_hrtimer
1980 <idle>-0 3dNh1 6us : add_preempt_count <-_raw_spin_lock
1981 <idle>-0 3dNh2 7us : _raw_spin_unlock <-hrtimer_interrupt
1982 <idle>-0 3dNh2 7us : sub_preempt_count <-_raw_spin_unlock
1983 <idle>-0 3dNh1 7us : tick_program_event <-hrtimer_interrupt
1984 <idle>-0 3dNh1 7us : clockevents_program_event <-tick_program_event
1985 <idle>-0 3dNh1 8us : ktime_get <-clockevents_program_event
1986 <idle>-0 3dNh1 8us : lapic_next_event <-clockevents_program_event
1987 <idle>-0 3dNh1 8us : irq_exit <-smp_apic_timer_interrupt
1988 <idle>-0 3dNh1 9us : sub_preempt_count <-irq_exit
1989 <idle>-0 3dN.2 9us : idle_cpu <-irq_exit
1990 <idle>-0 3dN.2 9us : rcu_irq_exit <-irq_exit
1991 <idle>-0 3dN.2 10us : rcu_eqs_enter_common.isra.45 <-rcu_irq_exit
1992 <idle>-0 3dN.2 10us : sub_preempt_count <-irq_exit
1993 <idle>-0 3.N.1 11us : rcu_idle_exit <-cpu_idle
1994 <idle>-0 3dN.1 11us : rcu_eqs_exit_common.isra.43 <-rcu_idle_exit
1995 <idle>-0 3.N.1 11us : tick_nohz_idle_exit <-cpu_idle
1996 <idle>-0 3dN.1 12us : menu_hrtimer_cancel <-tick_nohz_idle_exit
1997 <idle>-0 3dN.1 12us : ktime_get <-tick_nohz_idle_exit
1998 <idle>-0 3dN.1 12us : tick_do_update_jiffies64 <-tick_nohz_idle_exit
1999 <idle>-0 3dN.1 13us : cpu_load_update_nohz <-tick_nohz_idle_exit
2000 <idle>-0 3dN.1 13us : _raw_spin_lock <-cpu_load_update_nohz
2001 <idle>-0 3dN.1 13us : add_preempt_count <-_raw_spin_lock
2002 <idle>-0 3dN.2 13us : __cpu_load_update <-cpu_load_update_nohz
2003 <idle>-0 3dN.2 14us : sched_avg_update <-__cpu_load_update
2004 <idle>-0 3dN.2 14us : _raw_spin_unlock <-cpu_load_update_nohz
2005 <idle>-0 3dN.2 14us : sub_preempt_count <-_raw_spin_unlock
2006 <idle>-0 3dN.1 15us : calc_load_nohz_stop <-tick_nohz_idle_exit
2007 <idle>-0 3dN.1 15us : touch_softlockup_watchdog <-tick_nohz_idle_exit
2008 <idle>-0 3dN.1 15us : hrtimer_cancel <-tick_nohz_idle_exit
2009 <idle>-0 3dN.1 15us : hrtimer_try_to_cancel <-hrtimer_cancel
2010 <idle>-0 3dN.1 16us : lock_hrtimer_base.isra.18 <-hrtimer_try_to_cancel
2011 <idle>-0 3dN.1 16us : _raw_spin_lock_irqsave <-lock_hrtimer_base.isra.18
2012 <idle>-0 3dN.1 16us : add_preempt_count <-_raw_spin_lock_irqsave
2013 <idle>-0 3dN.2 17us : __remove_hrtimer <-remove_hrtimer.part.16
2014 <idle>-0 3dN.2 17us : hrtimer_force_reprogram <-__remove_hrtimer
2015 <idle>-0 3dN.2 17us : tick_program_event <-hrtimer_force_reprogram
2016 <idle>-0 3dN.2 18us : clockevents_program_event <-tick_program_event
2017 <idle>-0 3dN.2 18us : ktime_get <-clockevents_program_event
2018 <idle>-0 3dN.2 18us : lapic_next_event <-clockevents_program_event
2019 <idle>-0 3dN.2 19us : _raw_spin_unlock_irqrestore <-hrtimer_try_to_cancel
2020 <idle>-0 3dN.2 19us : sub_preempt_count <-_raw_spin_unlock_irqrestore
2021 <idle>-0 3dN.1 19us : hrtimer_forward <-tick_nohz_idle_exit
2022 <idle>-0 3dN.1 20us : ktime_add_safe <-hrtimer_forward
2023 <idle>-0 3dN.1 20us : ktime_add_safe <-hrtimer_forward
2024 <idle>-0 3dN.1 20us : hrtimer_start_range_ns <-hrtimer_start_expires.constprop.11
2025 <idle>-0 3dN.1 20us : __hrtimer_start_range_ns <-hrtimer_start_range_ns
2026 <idle>-0 3dN.1 21us : lock_hrtimer_base.isra.18 <-__hrtimer_start_range_ns
2027 <idle>-0 3dN.1 21us : _raw_spin_lock_irqsave <-lock_hrtimer_base.isra.18
2028 <idle>-0 3dN.1 21us : add_preempt_count <-_raw_spin_lock_irqsave
2029 <idle>-0 3dN.2 22us : ktime_add_safe <-__hrtimer_start_range_ns
2030 <idle>-0 3dN.2 22us : enqueue_hrtimer <-__hrtimer_start_range_ns
2031 <idle>-0 3dN.2 22us : tick_program_event <-__hrtimer_start_range_ns
2032 <idle>-0 3dN.2 23us : clockevents_program_event <-tick_program_event
2033 <idle>-0 3dN.2 23us : ktime_get <-clockevents_program_event
2034 <idle>-0 3dN.2 23us : lapic_next_event <-clockevents_program_event
2035 <idle>-0 3dN.2 24us : _raw_spin_unlock_irqrestore <-__hrtimer_start_range_ns
2036 <idle>-0 3dN.2 24us : sub_preempt_count <-_raw_spin_unlock_irqrestore
2037 <idle>-0 3dN.1 24us : account_idle_ticks <-tick_nohz_idle_exit
2038 <idle>-0 3dN.1 24us : account_idle_time <-account_idle_ticks
2039 <idle>-0 3.N.1 25us : sub_preempt_count <-cpu_idle
2040 <idle>-0 3.N.. 25us : schedule <-cpu_idle
2041 <idle>-0 3.N.. 25us : __schedule <-preempt_schedule
2042 <idle>-0 3.N.. 26us : add_preempt_count <-__schedule
2043 <idle>-0 3.N.1 26us : rcu_note_context_switch <-__schedule
2044 <idle>-0 3.N.1 26us : rcu_sched_qs <-rcu_note_context_switch
2045 <idle>-0 3dN.1 27us : rcu_preempt_qs <-rcu_note_context_switch
2046 <idle>-0 3.N.1 27us : _raw_spin_lock_irq <-__schedule
2047 <idle>-0 3dN.1 27us : add_preempt_count <-_raw_spin_lock_irq
2048 <idle>-0 3dN.2 28us : put_prev_task_idle <-__schedule
2049 <idle>-0 3dN.2 28us : pick_next_task_stop <-pick_next_task
2050 <idle>-0 3dN.2 28us : pick_next_task_rt <-pick_next_task
2051 <idle>-0 3dN.2 29us : dequeue_pushable_task <-pick_next_task_rt
2052 <idle>-0 3d..3 29us : __schedule <-preempt_schedule
2053 <idle>-0 3d..3 30us : 0:120:R ==> [003] 2448: 94:R sleep
2063 --------------------------
2070 # echo 0 > options/function-trace
2075 # chrt -f 5 sleep 1
2080 # wakeup_rt latency trace v1.1.5 on 3.8.0-test+
2081 # --------------------------------------------------------------------
2083 # -----------------
2084 # | task: sleep-5882 (uid:0 nice:0 policy:1 rt_prio:5)
2085 # -----------------
2087 # _------=> CPU#
2088 # / _-----=> irqs-off
2089 # | / _----=> need-resched
2090 # || / _---=> hardirq/softirq
2091 # ||| / _--=> preempt-depth
2095 <idle>-0 2d.h4 0us : 0:120:R + [002] 5882: 94:R sleep
2096 <idle>-0 2d.h4 0us : ttwu_do_activate.constprop.87 <-try_to_wake_up
2097 <idle>-0 2d.h4 1us : sched_wakeup: comm=sleep pid=5882 prio=94 success=1 target_cpu=002
2098 <idle>-0 2dNh2 1us : hrtimer_expire_exit: hrtimer=ffff88007796feb8
2099 <idle>-0 2.N.2 2us : power_end: cpu_id=2
2100 <idle>-0 2.N.2 3us : cpu_idle: state=4294967295 cpu_id=2
2101 <idle>-0 2dN.3 4us : hrtimer_cancel: hrtimer=ffff88007d50d5e0
2102 …<idle>-0 2dN.3 4us : hrtimer_start: hrtimer=ffff88007d50d5e0 function=tick_sched_timer ex…
2103 <idle>-0 2.N.2 5us : rcu_utilization: Start context switch
2104 <idle>-0 2.N.2 5us : rcu_utilization: End context switch
2105 <idle>-0 2d..3 6us : __schedule <-schedule
2106 <idle>-0 2d..3 6us : 0:120:R ==> [002] 5882: 94:R sleep
2110 -------------------------
2123 # _-----=> irqs-off
2124 # / _----=> need-resched
2125 # | / _---=> hardirq/softirq
2126 # || / _--=> preempt-depth
2128 # TASK-PID CPU# |||| TIMESTAMP FUNCTION
2130 … <...>-3638 [001] d... 19452.055471: #1 inner/outer(us): 12/14 ts:1499801089.066141940
2131 … <...>-3638 [003] d... 19454.071354: #2 inner/outer(us): 11/9 ts:1499801091.082164365
2132 … <...>-3638 [002] dn.. 19461.126852: #3 inner/outer(us): 12/9 ts:1499801098.138150062
2133 … <...>-3638 [001] d... 19488.340960: #4 inner/outer(us): 8/12 ts:1499801125.354139633
2134 … <...>-3638 [003] d... 19494.388553: #5 inner/outer(us): 8/12 ts:1499801131.402150961
2135 …<...>-3638 [003] d... 19501.283419: #6 inner/outer(us): 0/12 ts:1499801138.297435289 nm…
2139 interrupts disabled 'd'. Under the FUNCTION title there is:
2157 nmi-total:4 nmi-count:1
2160 test, the time spent in NMI is reported in "nmi-total" (in
2163 All architectures that have NMIs will show the "nmi-count" if an
2194 --------
2210 # entries-in-buffer/entries-written: 24799/24799 #P:4
2212 # _-----=> irqs-off
2213 # / _----=> need-resched
2214 # | / _---=> hardirq/softirq
2215 # || / _--=> preempt-depth
2217 # TASK-PID CPU# |||| TIMESTAMP FUNCTION
2219 bash-1994 [002] .... 3082.063030: mutex_unlock <-rb_simple_write
2220 bash-1994 [002] .... 3082.063031: __mutex_unlock_slowpath <-mutex_unlock
2221 bash-1994 [002] .... 3082.063031: __fsnotify_parent <-fsnotify_modify
2222 bash-1994 [002] .... 3082.063032: fsnotify <-fsnotify_modify
2223 bash-1994 [002] .... 3082.063032: __srcu_read_lock <-fsnotify
2224 bash-1994 [002] .... 3082.063032: add_preempt_count <-__srcu_read_lock
2225 bash-1994 [002] ...1 3082.063032: sub_preempt_count <-__srcu_read_lock
2226 bash-1994 [002] .... 3082.063033: __srcu_read_unlock <-fsnotify
2254 ---------------------
2268 # TASK-PID CPU# TIMESTAMP FUNCTION
2270 yum-updatesd-3111 [003] 1637.254676: finish_task_switch <-thread_return
2271 yum-updatesd-3111 [003] 1637.254681: hrtimer_cancel <-schedule_hrtimeout_range
2272 yum-updatesd-3111 [003] 1637.254682: hrtimer_try_to_cancel <-hrtimer_cancel
2273 yum-updatesd-3111 [003] 1637.254683: lock_hrtimer_base <-hrtimer_try_to_cancel
2274 yum-updatesd-3111 [003] 1637.254685: fget_light <-do_sys_poll
2275 yum-updatesd-3111 [003] 1637.254686: pipe_poll <-do_sys_poll
2280 # TASK-PID CPU# TIMESTAMP FUNCTION
2283 yum-updatesd-3111 [003] 1701.957688: free_poll_entry <-poll_freewait
2284 yum-updatesd-3111 [003] 1701.957689: remove_wait_queue <-free_poll_entry
2285 yum-updatesd-3111 [003] 1701.957691: fput <-free_poll_entry
2286 yum-updatesd-3111 [003] 1701.957692: audit_syscall_exit <-sysret_audit
2287 yum-updatesd-3111 [003] 1701.957693: path_put <-audit_syscall_exit
2322 "s %99s %*s %*d %*d\n",
2350 exit(-1);
2359 exit(-1);
2363 s = sprintf(line, "%d\n", getpid());
2382 tracefs=`sed -ne 's/^tracefs \(.*\) tracefs.*/\1/p' /proc/mounts`
2392 ---------------------------
2405 - measure of a function's time execution
2406 - having a reliable call stack to draw function calls graph
2410 - you want to find the reason of a strange kernel behavior and
2414 - you are experiencing weird latencies but it's difficult to
2417 - you want to find quickly which path is taken by a specific
2420 - you just want to peek inside a working kernel and want to see
2452 - The cpu number on which the function executed is default
2457 - hide: echo nofuncgraph-cpu > trace_options
2458 - show: echo funcgraph-cpu > trace_options
2460 - The duration (function's time of execution) is displayed on
2465 - hide: echo nofuncgraph-duration > trace_options
2466 - show: echo funcgraph-duration > trace_options
2468 - The overhead field precedes the duration field in case of
2471 - hide: echo nofuncgraph-overhead > trace_options
2472 - show: echo funcgraph-overhead > trace_options
2473 - depends on: funcgraph-duration
2525 - The task/pid field displays the thread cmdline and pid which
2528 - hide: echo nofuncgraph-proc > trace_options
2529 - show: echo funcgraph-proc > trace_options
2537 0) sh-4802 | | d_free() {
2538 0) sh-4802 | | call_rcu() {
2539 0) sh-4802 | | __call_rcu() {
2540 0) sh-4802 | 0.616 us | rcu_process_gp_end();
2541 0) sh-4802 | 0.586 us | check_for_new_grace_period();
2542 0) sh-4802 | 2.899 us | }
2543 0) sh-4802 | 4.040 us | }
2544 0) sh-4802 | 5.151 us | }
2545 0) sh-4802 | + 49.370 us | }
2548 - The absolute time field is an absolute timestamp given by the
2552 - hide: echo nofuncgraph-abstime > trace_options
2553 - show: echo funcgraph-abstime > trace_options
2584 - hide: echo nofuncgraph-tail > trace_options
2585 - show: echo funcgraph-tail > trace_options
2587 Example with nofuncgraph-tail (default)::
2595 Example with funcgraph-tail::
2622 --------------
2627 every kernel function, produced by the -pg switch in gcc),
2629 include the -pg switch in the compiling of the kernel.)
2635 with gcc version 4.6, the -mfentry has been added for x86, which
2646 The recordmcount program re-links this section back into the
2663 if the modified code crosses cache (or page) boundaries), and the nops are
2678 One special side-effect to the recording of the functions being
2718 # entries-in-buffer/entries-written: 5/5 #P:4
2720 # _-----=> irqs-off
2721 # / _----=> need-resched
2722 # | / _---=> hardirq/softirq
2723 # || / _--=> preempt-depth
2725 # TASK-PID CPU# |||| TIMESTAMP FUNCTION
2727 usleep-2665 [001] .... 4186.475355: sys_nanosleep <-system_call_fastpath
2728 <idle>-0 [001] d.h1 4186.475409: hrtimer_interrupt <-smp_apic_timer_interrupt
2729 usleep-2665 [001] d.h1 4186.475426: hrtimer_interrupt <-smp_apic_timer_interrupt
2730 <idle>-0 [003] d.h1 4186.475426: hrtimer_interrupt <-smp_apic_timer_interrupt
2731 <idle>-0 [002] d.h1 4186.475427: hrtimer_interrupt <-smp_apic_timer_interrupt
2765 # entries-in-buffer/entries-written: 897/897 #P:4
2767 # _-----=> irqs-off
2768 # / _----=> need-resched
2769 # | / _---=> hardirq/softirq
2770 # || / _--=> preempt-depth
2772 # TASK-PID CPU# |||| TIMESTAMP FUNCTION
2774 <idle>-0 [003] dN.1 4228.547803: hrtimer_cancel <-tick_nohz_idle_exit
2775 <idle>-0 [003] dN.1 4228.547804: hrtimer_try_to_cancel <-hrtimer_cancel
2776 <idle>-0 [003] dN.2 4228.547805: hrtimer_force_reprogram <-__remove_hrtimer
2777 <idle>-0 [003] dN.1 4228.547805: hrtimer_forward <-tick_nohz_idle_exit
2778 … <idle>-0 [003] dN.1 4228.547805: hrtimer_start_range_ns <-hrtimer_start_expires.constprop.11
2779 <idle>-0 [003] d..1 4228.547858: hrtimer_get_next_event <-get_next_timer_interrupt
2780 <idle>-0 [003] d..1 4228.547859: hrtimer_start <-__tick_nohz_idle_enter
2781 <idle>-0 [003] d..2 4228.547860: hrtimer_force_reprogram <-__rem
2854 # entries-in-buffer/entries-written: 39608/39608 #P:4
2856 # _-----=> irqs-off
2857 # / _----=> need-resched
2858 # | / _---=> hardirq/softirq
2859 # || / _--=> preempt-depth
2861 # TASK-PID CPU# |||| TIMESTAMP FUNCTION
2863 bash-1994 [000] .... 4342.324896: file_ra_state_init <-do_dentry_open
2864 bash-1994 [000] .... 4342.324897: open_check_o_direct <-do_last
2865 bash-1994 [000] .... 4342.324897: ima_file_check <-do_last
2866 bash-1994 [000] .... 4342.324898: process_measurement <-ima_file_check
2867 bash-1994 [000] .... 4342.324898: ima_get_action <-process_measurement
2868 bash-1994 [000] .... 4342.324898: ima_match_policy <-ima_get_action
2869 bash-1994 [000] .... 4342.324899: do_truncate <-do_last
2870 bash-1994 [000] .... 4342.324899: should_remove_suid <-do_truncate
2871 bash-1994 [000] .... 4342.324899: notify_change <-do_truncate
2872 bash-1994 [000] .... 4342.324900: current_fs_time <-notify_change
2873 bash-1994 [000] .... 4342.324900: current_kernel_time <-current_fs_time
2874 bash-1994 [000] .... 4342.324900: timespec_trunc <-current_fs_time
2879 ------------------------------------
2897 # head -1 available_filter_functions
2903 # head -50 available_filter_functions | tail -1
2912 ---------------------------------------------
2915 function tracer and the function-graph-tracer, there are some
2916 special features only available in the function-graph tracer.
2973 --------------
2995 ---------------
3004 - mod:
3036 - traceon/traceoff:
3060 - snapshot:
3076 - enable_event/disable_event:
3100 - dump:
3107 - cpudump:
3113 - stacktrace:
3117 ----------
3134 # entries-in-buffer/entries-written: 0/0 #P:4
3136 # _-----=> irqs-off
3137 # / _----=> need-resched
3138 # | / _---=> hardirq/softirq
3139 # || / _--=> preempt-depth
3141 # TASK-PID CPU# |||| TIMESTAMP FUNCTION
3146 bash-1994 [000] .... 5281.568961: mutex_unlock <-rb_simple_write
3147 bash-1994 [000] .... 5281.568963: __mutex_unlock_slowpath <-mutex_unlock
3148 bash-1994 [000] .... 5281.568963: __fsnotify_parent <-fsnotify_modify
3149 bash-1994 [000] .... 5281.568964: fsnotify <-fsnotify_modify
3150 bash-1994 [000] .... 5281.568964: __srcu_read_lock <-fsnotify
3151 bash-1994 [000] .... 5281.568964: add_preempt_count <-__srcu_read_lock
3152 bash-1994 [000] ...1 5281.568965: sub_preempt_count <-__srcu_read_lock
3153 bash-1994 [000] .... 5281.568965: __srcu_read_unlock <-fsnotify
3154 bash-1994 [000] .... 5281.568967: sys_dup2 <-system_call_fastpath
3164 -------------
3168 used to modify the size of the internal trace buffers. The
3170 CPU. To know the full size, multiply the number of possible CPUs
3191 much, it can cause Out-Of-Memory to trigger.
3195 -bash: echo: write error: Cannot allocate memory
3222 --------
3250 +--------------+------------+------------+------------+
3254 +--------------+------------+------------+------------+
3256 +--------------+------------+------------+------------+
3266 # entries-in-buffer/entries-written: 71/71 #P:8
3268 # _-----=> irqs-off
3269 # / _----=> need-resched
3270 # | / _---=> hardirq/softirq
3271 # || / _--=> preempt-depth
3273 # TASK-PID CPU# |||| TIMESTAMP FUNCTION
3275 …<idle>-0 [005] d... 2440.603828: sched_switch: prev_comm=swapper/5 prev_pid=0 prev_prio=120 …
3276 …sleep-2242 [005] d... 2440.603846: sched_switch: prev_comm=snapshot-test-2 prev_pid=2242 prev_pr…
3278 …<idle>-0 [002] d... 2440.707230: sched_switch: prev_comm=swapper/2 prev_pid=0 prev_prio=120 p…
3283 # entries-in-buffer/entries-written: 77/77 #P:8
3285 # _-----=> irqs-off
3286 # / _----=> need-resched
3287 # | / _---=> hardirq/softirq
3288 # || / _--=> preempt-depth
3290 # TASK-PID CPU# |||| TIMESTAMP FUNCTION
3292 …<idle>-0 [007] d... 2440.707395: sched_switch: prev_comm=swapper/7 prev_pid=0 prev_prio=120 p…
3293 …snapshot-test-2-2229 [002] d... 2440.707438: sched_switch: prev_comm=snapshot-test-2 prev_pid=22…
3309 ---------
3355 bash-2044 [002] .... 10594.481032: _raw_spin_lock_irqsave <-get_page_from_freelist
3356 bash-2044 [002] d... 10594.481032: add_preempt_count <-_raw_spin_lock_irqsave
3357 bash-2044 [002] d..1 10594.481032: __rmqueue <-get_page_from_freelist
3358 bash-2044 [002] d..1 10594.481033: _raw_spin_unlock <-get_page_from_freelist
3359 bash-2044 [002] d..1 10594.481033: sub_preempt_count <-_raw_spin_unlock
3360 … bash-2044 [002] d... 10594.481033: get_pageblock_flags_group <-get_pageblock_migratetype
3361 bash-2044 [002] d... 10594.481034: __mod_zone_page_state <-get_page_from_freelist
3362 bash-2044 [002] d... 10594.481034: zone_statistics <-get_page_from_freelist
3363 bash-2044 [002] d... 10594.481034: __inc_zone_state <-zone_statistics
3364 bash-2044 [002] d... 10594.481034: __inc_zone_state <-zone_statistics
3365 bash-2044 [002] .... 10594.481035: arch_dup_task_struct <-copy_process
3369 …bash-1998 [000] d..4 136.676759: sched_wakeup: comm=kworker/0:1 pid=59 prio=120 success=1 targe…
3370 …bash-1998 [000] dN.4 136.676760: sched_wakeup: comm=bash pid=1998 prio=120 success=1 target_cpu…
3371 …<idle>-0 [003] d.h3 136.676906: sched_wakeup: comm=rcu_preempt pid=9 prio=120 success=1 targ…
3372 …<idle>-0 [003] d..3 136.676909: sched_switch: prev_comm=swapper/3 prev_pid=0 prev_prio=120 p…
3373 …rcu_preempt-9 [003] d..3 136.676916: sched_switch: prev_comm=rcu_preempt prev_pid=9 prev_pri…
3374 …bash-1998 [000] d..4 136.677014: sched_wakeup: comm=kworker/0:1 pid=59 prio=120 success=1 targe…
3375 …bash-1998 [000] dN.4 136.677016: sched_wakeup: comm=bash pid=1998 prio=120 success=1 target_cpu…
3376 …bash-1998 [000] d..3 136.677018: sched_switch: prev_comm=bash prev_pid=1998 prev_prio=120 prev_…
3377 …kworker/0:1-59 [000] d..4 136.677022: sched_wakeup: comm=sshd pid=1995 prio=120 success=1 tar…
3378 …kworker/0:1-59 [000] d..3 136.677025: sched_switch: prev_comm=kworker/0:1 prev_pid=59 prev_pr…
3382 migration/1-14 [001] d.h3 138.732674: softirq_raise: vec=3 [action=NET_RX]
3383 <idle>-0 [001] dNh3 138.732725: softirq_raise: vec=3 [action=NET_RX]
3384 bash-1998 [000] d.h1 138.733101: softirq_raise: vec=1 [action=TIMER]
3385 bash-1998 [000] d.h1 138.733102: softirq_raise: vec=9 [action=RCU]
3386 bash-1998 [000] ..s2 138.733105: softirq_entry: vec=1 [action=TIMER]
3387 bash-1998 [000] ..s2 138.733106: softirq_exit: vec=1 [action=TIMER]
3388 bash-1998 [000] ..s2 138.733106: softirq_entry: vec=9 [action=RCU]
3389 bash-1998 [000] ..s2 138.733109: softirq_exit: vec=9 [action=RCU]
3390 sshd-1995 [001] d.h1 138.733278: irq_handler_entry: irq=21 name=uhci_hcd:usb4
3391 sshd-1995 [001] d.h1 138.733280: irq_handler_exit: irq=21 ret=unhandled
3392 sshd-1995 [001] d.h1 138.733281: irq_handler_entry: irq=21 name=eth0
3393 sshd-1995 [001] d.h1 138.733283: irq_handler_exit: irq=21 ret=handled
3399 # entries-in-buffer/entries-written: 18996/18996 #P:4
3401 # _-----=> irqs-off
3402 # / _----=> need-resched
3403 # | / _---=> hardirq/softirq
3404 # || / _--=> preempt-depth
3406 # TASK-PID CPU# |||| TIMESTAMP FUNCTION
3408 bash-1998 [000] d... 140.733501: sys_write -> 0x2
3409 bash-1998 [000] d... 140.733504: sys_dup2(oldfd: a, newfd: 1)
3410 bash-1998 [000] d... 140.733506: sys_dup2 -> 0x1
3411 bash-1998 [000] d... 140.733508: sys_fcntl(fd: a, cmd: 1, arg: 0)
3412 bash-1998 [000] d... 140.733509: sys_fcntl -> 0x1
3413 bash-1998 [000] d... 140.733510: sys_close(fd: a)
3414 bash-1998 [000] d... 140.733510: sys_close -> 0x0
3415 …bash-1998 [000] d... 140.733514: sys_rt_sigprocmask(how: 0, nset: 0, oset: 6e2768, sigsetsize: …
3416 bash-1998 [000] d... 140.733515: sys_rt_sigprocmask -> 0x0
3417 …bash-1998 [000] d... 140.733516: sys_rt_sigaction(sig: 2, act: 7fff718846f0, oact: 7fff71884650…
3418 bash-1998 [000] d... 140.733516: sys_rt_sigaction -> 0x0
3436 -----------
3446 a function tracer, it makes it convenient to check the stack size
3456 the stack size of the kernel during boot up, by adding "stacktrace"
3466 Depth Size Location (18 entries)
3467 ----- ---- --------
3487 Note, if -mfentry is being used by gcc, functions get traced before
3489 are not tested by the stack tracer when -mfentry is used.
3491 Currently, -mfentry is used by gcc 4.6.0 and above on x86 only.
3494 ----