ftrace - 几种tracer的打印例子

news2024/9/21 23:47:45
  • 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_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_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_on

ls -ltr

echo 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=123642
     kworker/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=000
     kworker/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=120
     kworker/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_on

ls -ltr

echo 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_write
    bash-2345      0...1. 6125us : syscall_exit_to_user_mode_prepare <-syscall_exit_to_user_mode
    bash-2345      0...1. 6126us : mem_cgroup_handle_over_high <-syscall_exit_to_user_mode
    bash-2345      0...1. 6126us : blkcg_maybe_throttle_current <-syscall_exit_to_user_mode
    bash-2345      0...1. 6127us : __rseq_handle_notify_resume <-syscall_exit_to_user_mode
    bash-2345      0...1. 6127us : rseq_ip_fixup <-__rseq_handle_notify_resume
    bash-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_on

ls -ltr

echo 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_write
            bash-2345    [000] ...1.   461.750304: syscall_exit_to_user_mode_prepare <-syscall_exit_to_user_mode
            bash-2345    [000] ...1.   461.750305: mem_cgroup_handle_over_high <-syscall_exit_to_user_mode
            bash-2345    [000] ...1.   461.750305: blkcg_maybe_throttle_current <-syscall_exit_to_user_mode
            bash-2345    [000] ...1.   461.750305: __rseq_handle_notify_resume <-syscall_exit_to_user_mode
            bash-2345    [000] ...1.   461.750306: rseq_ip_fixup <-__rseq_handle_notify_resume
            bash-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_on

ls -ltr

echo 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_options

echo 1 > /sys/kernel/tracing/tracing_on

ls -ltr

echo 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_options

echo 1 > /sys/kernel/tracing/tracing_on

ls -ltr

echo 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.coloradmin.cn/o/2153625.html

如若内容造成侵权/违法违规/事实不符,请联系多彩编程网进行投诉反馈,一经查实,立即删除!

相关文章

面向对象例题之例题的特性

答案&#xff1a;C 解析&#xff1a;对象里面的方法和属性数量是不确定的&#xff0c;可以不断扩展写多个属性和方法 清洗的边界是对象必备的&#xff0c;哪些是这个类的&#xff0c;哪些是其他类的都有体现。 良好的定义行为一般指定义良好的属性和方法 可扩展性指的是子类…

面向对象设计原则例题

答案&#xff1a;B A C D D C 知识点&#xff1a; 面向对象设计7大原则 单一职责原则 设计目的单一的类 开放—封闭原则 对外扩展开放&#xff0c;对修改封闭 里氏替换原则 子类可以替换父类 依赖倒置原则 要依赖于抽象&#xff0c;而不是具体的实现&#xff1b;针对接…

万字长文——ConvNeXt(2022CVPR),卷积网络的顶峰之作,在Transformer盛行的当下,卷积网络还能再战!

ConvNext:A ConvNet for the 2020s ConvNext:2020 年代的卷积神经网络 论文地址: https://arxiv.org/pdf/2201.03545 自从Transformer成功应用在视觉领域并且取得显著成绩后,很多人开始抛弃卷积网络架构,转而使用Transformer。然而有的大佬不认为卷积过时了,于是有了这篇…

OpenGL 原生库6 坐标系统

概述 为了将坐标从一个坐标系变换到另一个坐标系&#xff0c;我们需要用到几个变换矩阵&#xff0c;最重要的几个分别是模型(Model)、观察(View)、投影(Projection)三个矩阵。我们的顶点坐标起始于局部空间(Local Space)&#xff0c;在这里它称为局部坐标(Local Coordinate)&a…

内网渗透之中间人欺骗攻击-ARP攻击

ARP攻击 ARP协议简介 ARP全称为Address Resolution Protocol&#xff0c;即地址解析协议&#xff0c;它是一个根据IP地址获取物理地址的TCP/IP协议&#xff0c;主机发送信息时将包含目标IP地址的ARP请求广播到网络上的所有主机&#xff0c;并接收返回消息&#xff0c;以此确定…

proteus仿真学习(1)

一&#xff0c;创建工程 一般选择默认模式&#xff0c;不配置pcb文件 可以选用芯片型号也可以不选 不选则从零开始布局&#xff0c;没有初始最小系统。选用则有初始最小系统以及基础的main函数 本次学习使用从零开始&#xff0c;不配置固件 二&#xff0c;上手软件 1.在元件…

滑动窗口算法专题(1)

找往期文章包括但不限于本期文章中不懂的知识点&#xff1a; 个人主页&#xff1a;我要学编程(ಥ_ಥ)-CSDN博客 所属专栏&#xff1a; 优选算法专题 目录 滑动窗口算法的简介 209. 长度最小的子数组 3.无重复字符的最长子串 1004. 最大连续1的个数III 1658. 将减到0的最小…

Docker基本使用(持续更新中)

docker介绍 docker是一个开源的应用容器引擎&#xff0c;常见的容器引擎例如&#xff1a;docker、podman、containerd等&#xff0c;但是docker应用还是相对比较多。 1 常用命令 1.1保存镜像到本地 命令如下: docker save -o nginx.tar nginx:latest 举例 结果&#xff1a…

C++/Qt 集成 AutoHotkey

C/Qt 集成 AutoHotkey 前言AutoHotkey 介绍 方案一&#xff1a;子进程启动编写AutoHotkey脚本准备 AutoHotkey 运行环境编写 C/Qt 代码 方案二&#xff1a;显式动态链接方案探索编译动态链接库集成到C工程关于AutoHotkeyDll.dll中的函数原型 总结 前言 上一篇介绍了AutoHotkey…

求1000以内所有恰好能分解成10组两个素数之和

要求 根据哥德巴赫猜想&#xff0c;任意一个大偶数都可以分解为两个素数之和。但许多偶数分解为两个素数之和并不是唯一的。 请编写函数fun&#xff0c;其功能是:求1000(不包括1000)以内的所有恰好能分解成10组两个素数之和(5109和1095被认为是同一组)的偶并依次存入数组a中并…

SQL_yog安装和使用演示--mysql三层结构

目录 1.什么是SQL_yog 2.下载安装 3.页面介绍 3.1链接主机 3.2创建数据库 3.3建表操作 3.4向表里面填内容 3.5使用指令查看效果 4.连接mysql的指令 4.1前提条件 4.2链接指令 ​编辑 4.3创建时的说明 4.4查看是不是连接成功 5.mysql的三层结构 1.什么是SQL_yog 我…

有什么兼容macOS 15 Sequoia系统的加密软件?

前言&#xff1a;近日&#xff0c;苹果更新了 macOS 15 Sequoia正式版&#xff0c;已经有用户在电脑上安装使用了。在这个信息化时代&#xff0c;系统一直在更新&#xff0c;运用一些工具时需要考虑兼容性。 刚有个客户来问迅软&#xff1a;你们迅软DSE客户端支持新发布的macO…

python函数三:拆包和交换变量值、引用、匿名函数

文章目录 1. 拆包和交换变量值1.1 拆包1.2 交换变量值 2. 引用2.1 了解引用2.1 把引用当作参数传递 3. 匿名函数3.1 lambda语法3.2 lambda的应用3.3 使用使用函数形式来求解某天是该年的第几天&#xff1f; 1. 拆包和交换变量值 1.1 拆包 拆包&#xff1a;把组合形成的元组形…

Linux基础---13三剑客及正则表达式

一.划水阶段 首先我们先来一个三剑客与正则表达式混合使用的简单示例&#xff0c;大致了解是个啥玩意儿。下面我来演示一下如何查询登录失败的ip地址及次数。 1.首先&#xff0c;进入到 /var/log目录下 cd /var/log效果如下 2.最后&#xff0c;输入如下指令即可查看&#xf…

【读书笔记-《网络是怎样连接的》- 0】全书整体结构

网络是计算机相关课程中的重要部分&#xff0c;更是当今的学习生活中所不可或缺的。虽然相关的经典书籍很多&#xff0c;但是大多数属于深入某一部分的专著&#xff0c;比如TCP/IP协议。像我这样对于网络一知半解的同学来说&#xff0c;更需要一种覆盖网络全貌&#xff0c;每一…

《线性代数》笔记

文章目录 1 行列式1.1 克拉默法则1.2 基本性质1.3 余子式 M i j M_{ij} Mij​1.4 代数余子式 A i j ( − 1 ) i j ⋅ M i j A_{ij} (-1)^{ij} \cdot M_{ij} Aij​(−1)ij⋅Mij​1.5 具体型行列式计算&#xff08;化为基本型&#xff09;1.5.1 主对角线行列式&#xff1a;主…

Python学习——【4.2】数据容器:tuple元组

文章目录 【4.2】数据容器&#xff1a;tuple元组一、元组的定义格式二、元组的特点三、元组的操作&#xff08;一&#xff09;常见操作&#xff08;二&#xff09;循环遍历 【4.2】数据容器&#xff1a;tuple元组 一、元组的定义格式 为什么需要元组 列表是可以修改的。如果想…

seL4 Untyped(二)

链接: Untyped Untyped 这篇主要是针对seL4物理内存管理的介绍。 物理内存 在seL4系统中&#xff0c;除了内核占用的一小部分静态内存之外&#xff0c;其他的所有的物理内存都是用户一级管理的。seL4在启动时创建的对象能力&#xff0c;以及seL4管理的其余物理资源&#xf…

初始网络编程(下)

所属专栏&#xff1a;Java学习 1. TCP 的简单示例 同时&#xff0c;由于 TCP 是面向字节流的传输&#xff0c;所以说传输的基本单位是字节&#xff0c;接受发送都是使用的字节流 方法签名 方法说明 Socket accept() 开始监听指定端口&#xff08;创建时绑定的端口&…

十七、RC振荡电路

振荡电路 1、振荡电路的组成、作用、起振的相位条件以及振荡电路起振和平衡幅度条件&#xff0c; 2、RC电路阻抗与频率、相位与频率的关系曲线; 3、RC振荡电路的相位条件分析和振荡频率