ftrace - 几种tracer的打印例子

embedded/2024/9/22 12:18:33/
  • ftrace - Function Tracer — The Linux Kernel documentation
  • 【原创】Ftrace使用及实现机制 - 沐多 - 博客园 (cnblogs.com)

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_onls -ltrecho 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=52539bash-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=120bash-39688     1..... 19049us : sched_process_wait: comm=bash pid=0 prio=120bash-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=120ls-52539     3..... 19314us!: sched_process_exec: filename=/usr/bin/ls pid=52539 old_pid=52539ls-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=003ls-52539     3d..4. 20952us!: sched_wakeup: comm=kworker/u260:1 pid=35252 prio=120 target_cpu=003

1.2 non-latency format

echo nop > /sys/kernel/tracing/current_tracer
echo 1 > /sys/kernel/tracing/events/sched/enable
echo 0 >  /sys/kernel/tracing/options/latency-format
echo 1 > /sys/kernel/tracing/tracing_onls -ltrecho 0 > /sys/kernel/tracing/tracing_on
cat /sys/kernel/tracing/trace > ftrace.log
# tracer: nop
#
# entries-in-buffer/entries-written: 205/205   #P:4
#
#                                _-----=> irqs-off/BH-disabled
#                               / _----=> need-resched
#                              | / _---=> hardirq/softirq
#                              || / _--=> preempt-depth
#                              ||| / _-=> migrate-disable
#                              |||| /     delay
#           TASK-PID     CPU#  |||||  TIMESTAMP  FUNCTION
#              | |         |   |||||     |         |kworker/1:1-82432   [001] d.h2. 20393.301354: sched_stat_runtime: comm=kworker/1:1 pid=82432 runtime=687800 [ns]kworker/2:0-120412  [002] d.h1. 20393.301356: sched_stat_runtime: comm=kworker/2:0 pid=120412 runtime=419001 [ns]bash-80299   [003] d.h1. 20393.301370: sched_stat_runtime: comm=bash pid=80299 runtime=1007701 [ns]bash-80299   [003] d..2. 20393.301747: sched_stat_runtime: comm=bash pid=80299 runtime=376800 [ns]bash-80299   [003] ..... 20393.301790: sched_process_fork: comm=bash pid=80299 child_comm=bash child_pid=123642kworker/2:0-120412  [002] d..2. 20393.301878: sched_stat_runtime: comm=kworker/2:0 pid=120412 runtime=521699 [ns]bash-80299   [003] d..2. 20393.301902: sched_wakeup_new: comm=bash pid=123642 prio=120 target_cpu=000kworker/2:0-120412  [002] d..2. 20393.301972: sched_switch: prev_comm=kworker/2:0 prev_pid=120412 prev_prio=120 prev_state=I ==> next_comm=sshd next_pid=80143 next_prio=120kworker/1:1-82432   [001] d..2. 20393.302000: sched_stat_runtime: comm=kworker/1:1 pid=82432 runtime=647100 [ns]

2.function tracer

2.1 latency format

echo function > /sys/kernel/tracing/current_tracer
echo 1 >  /sys/kernel/tracing/options/latency-format
echo 1 > /sys/kernel/tracing/tracing_onls -ltrecho 0 > /sys/kernel/tracing/tracing_on
cat /sys/kernel/tracing/trace > ftrace.log

# tracer: function
#
# function latency trace v1.1.5 on 6.8.0-44-generic
# --------------------------------------------------------------------
# latency: 0 us, #58212/58212, 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-2345      0...1. 6123us : mutex_unlock <-rb_simple_writebash-2345      0...1. 6125us : syscall_exit_to_user_mode_prepare <-syscall_exit_to_user_modebash-2345      0...1. 6126us : mem_cgroup_handle_over_high <-syscall_exit_to_user_modebash-2345      0...1. 6126us : blkcg_maybe_throttle_current <-syscall_exit_to_user_modebash-2345      0...1. 6127us : __rseq_handle_notify_resume <-syscall_exit_to_user_modebash-2345      0...1. 6127us : rseq_ip_fixup <-__rseq_handle_notify_resumebash-2345      0...1. 6127us : rseq_get_rseq_cs <-rseq_ip_fixup

2.2 non-latency format

echo function > /sys/kernel/tracing/current_tracer
echo 0 >  /sys/kernel/tracing/options/latency-format
echo 1 > /sys/kernel/tracing/tracing_onls -ltrecho 0 > /sys/kernel/tracing/tracing_on
cat /sys/kernel/tracing/trace > ftrace.log
# tracer: function
#
# entries-in-buffer/entries-written: 62184/62184   #P:4
#
#                                _-----=> irqs-off/BH-disabled
#                               / _----=> need-resched
#                              | / _---=> hardirq/softirq
#                              || / _--=> preempt-depth
#                              ||| / _-=> migrate-disable
#                              |||| /     delay
#           TASK-PID     CPU#  |||||  TIMESTAMP  FUNCTION
#              | |         |   |||||     |         |bash-2345    [000] ...1.   461.750300: mutex_unlock <-rb_simple_writebash-2345    [000] ...1.   461.750304: syscall_exit_to_user_mode_prepare <-syscall_exit_to_user_modebash-2345    [000] ...1.   461.750305: mem_cgroup_handle_over_high <-syscall_exit_to_user_modebash-2345    [000] ...1.   461.750305: blkcg_maybe_throttle_current <-syscall_exit_to_user_modebash-2345    [000] ...1.   461.750305: __rseq_handle_notify_resume <-syscall_exit_to_user_modebash-2345    [000] ...1.   461.750306: rseq_ip_fixup <-__rseq_handle_notify_resumebash-2345    [000] ...1.   461.750306: rseq_get_rseq_cs <-rseq_ip_fixup

3.function_graph tracer

这个tracer下，default是没有显式时间戳的，需要设置 funcgraph-abstime 来展示系统启动的时间戳。如下：

echo function_graph > /sys/kernel/tracing/current_tracer
echo 1 >  /sys/kernel/tracing/options/latency-format
echo 1 > /sys/kernel/tracing/tracing_onls -ltrecho 0 > /sys/kernel/tracing/tracing_on
cat /sys/kernel/tracing/trace > ftrace1.log
# tracer: function_graph
#
# function_graph latency trace v1.1.5 on 6.8.0-44-generic
# --------------------------------------------------------------------
# latency: 0 us, #151138/51805454, 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)
#    -----------------
#
#      _-----=> irqs-off
#     / _----=> need-resched
#    | / _---=> hardirq/softirq
#    || / _--=> preempt-depth
#    ||| /
# CPU||||     DURATION                  FUNCTION CALLS
# |  ||||      |   |                     |   |   |   |1)  d..1. |   0.193 us    |              } /* idle_cpu */1)  d..2. |   0.186 us    |              cpu_util();1)  d..2. |   0.204 us    |              idle_cpu();1)  d..2. |   0.196 us    |              update_sd_pick_busiest();1)  d..2. |   0.182 us    |              cpu_util();1)  d..2. |   0.188 us    |              idle_cpu();

3.1 latency format + abstime + proc

echo function_graph > /sys/kernel/tracing/current_tracer
echo 1 >  /sys/kernel/tracing/options/latency-format
echo funcgraph-abstime > /sys/kernel/tracing/trace_options
echo funcgraph-proc > /sys/kernel/tracing/trace_optionsecho 1 > /sys/kernel/tracing/tracing_onls -ltrecho 0 > /sys/kernel/tracing/tracing_on
cat /sys/kernel/tracing/trace > ftrace.log
# tracer: function_graph
#
# function_graph latency trace v1.1.5 on 6.8.0-44-generic
# --------------------------------------------------------------------
# latency: 0 us, #127921/359709, 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)
#    -----------------
#
#                                       _-----=> irqs-off
#                                      / _----=> need-resched
#                                     | / _---=> hardirq/softirq
#                                     || / _--=> preempt-depth
#                                     ||| /
#     TIME        CPU  TASK/PID       ||||     DURATION                  FUNCTION CALLS
#      |          |     |    |        ||||      |   |                     |   |   |   |8815.427815 |     0)    ls-54057    |  ..... |   0.312 us    |          } /* taskstats_exit */8815.427815 |     0)    ls-54057    |  ...1. |               |          exit_mm() {8815.427816 |     0)    ls-54057    |  ...1. |               |            exit_mm_release() {8815.427816 |     0)    ls-54057    |  ...1. |               |              futex_exit_release() {8815.427816 |     0)    ls-54057    |  ...1. |               |                mutex_lock() {8815.427816 |     0)    ls-54057    |  ...1. |   0.189 us    |                  __cond_resched();8815.427817 |     0)    ls-54057    |  ..... |   0.540 us    |                }8815.427817 |     0)    ls-54057    |  ...1. |   0.201 us    |                _raw_spin_lock_irq();8815.427817 |     0)    ls-54057    |  d..2. |   0.196 us    |                _raw_spin_unlock_irq();8815.427817 |     0)    ls-54057    |  ...1. |   0.343 us    |                futex_cleanup();8815.427818 |     0)    ls-54057    |  ...1. |   0.191 us    |                mutex_unlock();8815.427818 |     0)    ls-54057    |  ..... |   2.477 us    |              }8815.427819 |     0)    ls-54057    |  ...1. |               |              mm_release() {8815.427819 |     0)    ls-54057    |  ...1. |   0.201 us    |                uprobe_free_utask();8815.427819 |     0)    ls-54057    |  ...1. |   0.190 us    |                shstk_free();8815.427820 |     0)    ls-54057    |  ..... |   1.065 us    |              }8815.427820 |     0)    ls-54057    |  ..... |   4.096 us    |            }

3.2 non-latency format + abstime + proc

echo function_graph > /sys/kernel/tracing/current_tracer
echo 0 >  /sys/kernel/tracing/options/latency-format
echo funcgraph-abstime > /sys/kernel/tracing/trace_options
echo funcgraph-proc > /sys/kernel/tracing/trace_optionsecho 1 > /sys/kernel/tracing/tracing_onls -ltrecho 0 > /sys/kernel/tracing/tracing_on
cat /sys/kernel/tracing/trace > ftrace.log
# tracer: function_graph
#
#     TIME        CPU  TASK/PID         DURATION                  FUNCTION CALLS
#      |          |     |    |           |   |                     |   |   |   |9016.683071 |     2)   sshd-39581   |   0.195 us    |                    } /* update_min_vruntime */9016.683071 |     2)   sshd-39581   |   4.395 us    |                  } /* dequeue_entity */9016.683071 |     2)   sshd-39581   |   0.195 us    |                  hrtick_update();9016.683071 |     2)   sshd-39581   | + 19.649 us   |                } /* dequeue_task_fair */9016.683072 |     2)   sshd-39581   |               |                pick_next_task() {9016.683072 |     2)   sshd-39581   |               |                  pick_next_task_fair() {9016.683072 |     2)   sshd-39581   |               |                    newidle_balance() {9016.683072 |     2)   sshd-39581   |   0.194 us    |                      __rcu_read_lock();9016.683073 |     2)   sshd-39581   |   0.192 us    |                      __msecs_to_jiffies();9016.683073 |     2)   sshd-39581   |   0.191 us    |                      __rcu_read_unlock();9016.683074 |     2)   sshd-39581   |   1.399 us    |                    }9016.683074 |     2)   sshd-39581   |   1.813 us    |                  }9016.683074 |     2)   sshd-39581   |               |                  put_prev_task_fair() {9016.683074 |     2)   sshd-39581   |               |                    put_prev_entity() {9016.683074 |     2)   sshd-39581   |   0.193 us    |                      check_cfs_rq_runtime();9016.683075 |     2)   sshd-39581   |   0.559 us    |                    }9016.683075 |     2)   sshd-39581   |               |                    put_prev_entity() {9016.683075 |     2)   sshd-39581   |   0.193 us    |                      check_cfs_rq_runtime();


http://www.ppmy.cn/embedded/115022.html

相关文章

ubuntu24安装vivado24（安装并解决若干错误）

ubuntu24安装vivado24（安装并解决若干错误）

目录 安装方法&#xff1a;问题1&#xff1a;解决办法&#xff1a; 问题2&#xff1a;解决方法&#xff1a; 安装完成&#xff1a; 安装方法&#xff1a; 注意&#xff1a;内存最好预留80G空闲的。 安装好大小&#xff1a; 安装依赖库&#xff1a; sudo apt-get update sud…
阅读更多...
【LLM学习之路】9月16日 第六天

【LLM学习之路】9月16日 第六天

【LLM学习之路】9月16日 第六天 损失函数 L1Loss 可以取平均也可以求和 参数解析 input &#xff08;N&#xff0c;*&#xff09; N是batchsize&#xff0c;星号代表可以是任意维度 不是输入的参数&#xff0c;只是描述数据 target 形状要同上 MSELoss平方差 CrossEntr…
阅读更多...
【笔记】第三节 组织与性能

【笔记】第三节 组织与性能

3.1 基本成分 3.2 微观组织特征 0.6-0.8C%碳素钢的组织为珠光体和少量的铁素体。 如何把组织和性能联系起来&#xff1f;德国克虏伯公司的研究——珠光体片间距与渗碳体片层厚度成比例&#xff1a; t s 0 ( ρ 15 ( C % ) − 1 ) ts_0(\frac{\rho}{15(C\%)}-1) ts0​(15(C%)…
阅读更多...
TAPD 企业版

TAPD 企业版

一、版本概述 TAPD 企业版可帮助大中型团队快速迭代&#xff0c;并有计划性地完成产品交付。TAPD 敏捷全生命周期项目管理&#xff0c;为大中型研发团队提供了 全过程、全方位 的敏捷研发管理解决方案。用户可通过制定长期的发布计划&#xff0c;有效进行产品规划&#xff1b;…
阅读更多...
Git clone远程仓库没有其他分支的问题

Git clone远程仓库没有其他分支的问题

在使用Git克隆&#xff08;Git clone&#xff09;时&#xff0c;可能遇到分支不全的问题。有以下几种可能的原因和解决方法&#xff1a; 未将所有分支克隆下来&#xff1a;默认情况下&#xff0c;Git只会克隆远程仓库的主分支。如果您想要克隆其他分支&#xff0c;可以使用以下…
阅读更多...
AI论文写作PPT思维导图PC小程序开发

AI论文写作PPT思维导图PC小程序开发

AI论文写作PPT思维导图PC小程序开发 AI智能PPT功能 一键生成PPT大纲、一键扩写大纲内容、单独扩写某个大纲内容、一键生成内容关键词、单项内容关键词生成、新增大纲项、修改大纲、删除大纲、选择PPT模板、单页模板一键切换、在线编辑模板&#xff1b;支持导出PPTX、JPEG、&am…
阅读更多...
electron nsis打包windows应用程序

electron nsis打包windows应用程序

使用electron开发应用程序之后&#xff0c;经常会单独对windows做32位或者是64位程序打包操作&#xff0c;有时候默认的程序做不了相应的需求&#xff0c;往往需要添加单独的页面或者是修改默认的操作&#xff0c;比如一下添加一个默认的选择页面&#xff1a; 自定义脚本代码如…
阅读更多...
深度学习-03 Pytorch

深度学习-03 Pytorch

损失函数是用来衡量模型预测结果与真实值之间的差异&#xff0c;并用来优化模型的指标。在机器学习和神经网络中&#xff0c;常用的损失函数包括均方误差&#xff08;Mean Squared Error&#xff0c;MSE&#xff09;、交叉熵&#xff08;Cross-Entropy&#xff09;等。 反向传播…
阅读更多...
最新文章

Copyright @ 2022~2023