ftrace - 几种tracer的打印例子

原创

已于 2024-09-21 21:51:42 修改 · 948 阅读

标签

#linux #ftrace #latency

于 2024-09-21 21:19:49 首次发布

latency format

nop tracer和function tracer下，latency format的时间戳是相对开始trace的时间，non-latency format的时间戳是相对于系统启动的时间。

1.nop tracer

1.1 latency format

echo nop > /sys/kernel/tracing/current_tracer
echo 1 > /sys/kernel/tracing/events/sched/enable
echo 1 >  /sys/kernel/tracing/options/latency-format
echo 1 > /sys/kernel/tracing/tracing_on

ls -ltr

echo 0 > /sys/kernel/tracing/tracing_on
cat /sys/kernel/tracing/trace > ftrace.log

# tracer: nop
#
# nop latency trace v1.1.5 on 6.8.0-44-generic
# --------------------------------------------------------------------
# latency: 0 us, #35/35, CPU#0 | (M:desktop VP:0, KP:0, SP:0 HP:0 #P:4)
#    -----------------
#    | task: -0 (uid:0 nice:0 policy:0 rt_prio:0)
#    -----------------
#
#                    _------=> CPU#
#                   / _-----=> irqs-off/BH-disabled
#                  | / _----=> need-resched
#                  || / _---=> hardirq/softirq
#                  ||| / _--=> preempt-depth
#                  |||| / _-=> migrate-disable
#                  ||||| /     delay
#  cmd     pid     |||||| time  |   caller
#     \   /        ||||||  \    |    /
    bash-39688     1d..2. 18934us : sched_stat_runtime: comm=bash pid=39688 runtime=339570 [ns]
    bash-39688     1..... 18938us : sched_process_fork: comm=bash pid=39688 child_comm=bash child_pid=52539
    bash-39688     1d..2. 18944us+: sched_wakeup_new: comm=bash pid=52539 prio=120 target_cpu=003
  <idle>-0         3d..2. 18974us+: sched_switch: prev_comm=swapper/3 prev_pid=0 prev_prio=120 prev_state=R ==> next_comm=bash next_pid=52539 next_prio=120
    bash-39688     1..... 19049us : sched_process_wait: comm=bash pid=0 prio=120
    bash-39688     1d..2. 19050us : sched_stat_runtime: comm=bash pid=39688 runtime=116213 [ns]
    bash-39688     1d..2. 19053us!: sched_switch: prev_comm=bash prev_pid=39688 prev_prio=120 prev_state=S ==> next_comm=swapper/1 next_pid=0 next_prio=120
      ls-52539     3..... 19314us!: sched_process_exec: filename=/usr/bin/ls pid=52539 old_pid=52539
      ls-52539     3d.h1. 19596us!: sched_stat_runtime: comm=ls pid=52539 runtime=655689 [ns]
      ls-52539     3d.h1. 20596us!: sched_stat_runtime: comm=ls pid=52539 runtime=1000109 [ns]
      ls-52539     3d..3. 20948us : sched_waking: comm=kworker/u260:1 pid=35252 prio=120 target_cpu=003
      ls-52539     3d..4. 20952us!: sched_wake

最低0.47元/天解锁文章