使用ftrace分析函数性能

0. 背景

ftrace的功能非常强大,可以在系统的各个关键点上采集数据用以追踪系统的运行情况。既支持预设的静态插桩点(trace event),也支持每个函数的动态插桩(function tracer)。还可以利用动态插桩来测量函数的执行时间(function graph tracer)。关于ftrace的详细操作和原理分析可以参考Linux ftrace一文。

本文的主要目的主要是利用ftrace来做新增代码的性能分析和优化,应用的主要场景如下:

我们在现有的代码中增加了一批新函数A_*()

功能完成后,我们希望知道两个问题:

  • Question 1、在运行过程中,新增的函数A_*()造成了多少的性能损失?
  • Question 2、如果需要优化,怎样找出某个耗时比较大的A_xxx()函数具体开销在哪里?

1. trace-cmd工具的安装

我们可以手工操作/sys/kernel/debug/tracing路径下的大量的配置文件接口,来使用ftrace的强大功能。但是这些接口对普通用户来说太多太复杂了,我们可以使用对ftrace功能进行二次封装的一些命令来操作。

trace-cmd就是ftrace封装命令其中的一种。该软件包由两部分组成:

  • 1、trace-cmd。提供了数据抓取和数据分析的功能。
  • 2、kernelshark。可以用图形化的方式来详细分析数据,也可以做数据抓取。

首先我们需要安装trace-cmd工具,ubuntu下可以通过以下两种方式安装:

  • 1、编译源码,安装最新版本:
1、安装依赖:
sudo apt-get install build-essential git cmake libjson-c-dev -y
sudo apt-get install freeglut3-dev libxmu-dev libxi-dev -y
sudo apt-get install qtbase5-dev -y

2、下载源码:
git clone https://git.kernel.org/pub/scm/utils/trace-cmd/trace-cmd.git/

3、编译安装:
cd trace-cmd
make gui
sudo make install_gui
  • 2、从软件源安装,版本较旧:
sudo apt install trace-cmd kernelshark

2. 粗粒度分析

假设我们新增了一批函数名为vfs_*(),性能分析时我们可以先总体追踪一下这些函数的耗时,以及耗时在总体时间中的占比。即Question 1

2.1 使用trace-cmd record -l func命令抓取数据

trace-cmd从per_cpu buffer中抓取原始数据/sys/kernel/debug/tracing/per_cpu/cpu0/trace_pipe_raw,所以它的开销小并且支持长时间抓取。

sudo trace-cmd record -p function_graph -l vfs_* -F cp -r ~/perf perf.bak

命令的详细参数含义如下:

  • -p function_graph :指定当前tracer为function_graph,只有function_graph才能测量函数执行时间
  • -l vfs_* :函数过滤,指定function_graph追踪哪些函数。function_graph有两种过滤条件可以配置:
    • -l func。实际对应set_ftrace_filter,这种方式插桩的开销较小,只会追踪顶层func的执行时间且支持*等通配符的设置。
    • -g func。实际对应set_graph_function,这种方式插桩的开销较大,但能追踪func以及func所有子函数的的执行时间,不支持*等通配符的设置。
  • -F cp -r ~/perf perf.bak :进程过滤,指定对cp -r ~/perf perf.bak这个进程进行追踪。也可以使用-P pid来指定进程。还可以不指定进程默认对全局进程追踪,例如sleep 10追踪10s。

因为-l func-g func的特点,所以我们在粗粒度分析时使用-l func,在细粒度分析时使用-g func。这也是本文的一个精髓。

2.2 使用trace-cmd report --profile命令分析数据

所有的原始trace数据已经默认存储到trace.dat文件中了。

1、使用trace-cmd report命令可以把trace.dat解析成文本格式:

$ sudo trace-cmd report| more
...

# 注释 #    进程名-pid  CPU    时间戳(s)      函数入口/出口  耗时等级  函数耗时      函数名
              cp-3484  [006] 20010.128398: funcgraph_entry:      + 52.946 us  |  vfs_open();
              cp-3484  [006] 20010.128466: funcgraph_entry:      ! 212.370 us |  vfs_read();
              cp-3484  [006] 20010.128723: funcgraph_entry:        1.832 us   |  vfs_read();
              cp-3484  [006] 20010.128725: funcgraph_entry:        0.250 us   |  vfs_read();
              cp-3484  [006] 20010.128729: funcgraph_entry:        0.673 us   |  vfs_open();
              cp-3484  [006] 20010.128730: funcgraph_entry:        0.688 us   |  vfs_read();
              cp-3484  [006] 20010.128731: funcgraph_entry:        0.434 us   |  vfs_read();
              cp-3484  [006] 20010.129213: funcgraph_entry:        1.386 us   |  vfs_open();
              cp-3484  [006] 20010.129215: funcgraph_entry:                   |  vfs_statx_fd() {

文本主要格式的含义如上中文注释所示,我们读出开始的时间戳和结束的时间戳,就能计算出操作的总体时间。

2、trace-cmd report --profile命令可以对我们追踪的函数执行时间进行统计:

$ sudo trace-cmd report --profile
...

task: cp-3484   # 进程名和PID
#注释#         函数名       次数   总时长(ns)      平均时长(ns)   最大时长(ns)(时间戳s)         最小时长(ns)(时间戳s)
  Event: func: vfs_read() (6017) Total: 565900849 Avg: 94050 Max: 1827017(ts:20010.738236) Min:203(ts:20010.130418)
  Event: func: vfs_write() (3520) Total: 319047851 Avg: 90638 Max: 591045(ts:20010.398434) Min:3437(ts:20011.032217)
  Event: func: vfs_statx() (3865) Total: 49642741 Avg: 12844 Max: 1411479(ts:20010.626101) Min:924(ts:20010.718592)
  Event: func: vfs_mkdir() (690) Total: 9175927 Avg: 13298 Max: 63201(ts:20010.305020) Min:8868(ts:20010.939694)
  Event: func: vfs_getattr() (9529) Total: 5968390 Avg: 626 Max: 31850(ts:20010.459588) Min:260(ts:20010.718595)
  Event: func: vfs_statx_fd() (5666) Total: 5513205 Avg: 973 Max: 32808(ts:20010.539845) Min:434(ts:20010.508351)
  Event: func: vfs_open() (5668) Total: 4346891 Avg: 766 Max: 52724(ts:20010.128451) Min:236(ts:20011.152689)
  Event: func: vfs_getattr_nosec() (9529) Total: 2162038 Avg: 226 Max: 18470(ts:20010.182797) Min:91(ts:20010.718877)

--profile对数据进行了统计和排序。它按照进程为单位,对每个进程的监控函数的调用时间进行了统计,有调用次数总时长平均时长最大/小时长,并且默认按照总时长进行了排序。

这样就很方便的找到哪个函数耗时最多,占比有多少。比如上例中耗时最多的是vfs_read()

计算出所有函数的总体耗时,单位为ns:

// `$6`指定了第6列`总时长`
sudo trace-cmd report --profile | grep "Event: func:" | awk '{print $6}' | awk '{sum+=$1}END{print sum}'

也可以按照其他维度对数据进行排序:

// 按照`平均时长`进行排序,`k8`指定了第8列`平均时长`
sudo trace-cmd report --profile | grep "Event: func:" | sort -k8 -n -r      

3. 细粒度分析

上一节中我们使用粗粒度分析的方法找出了耗时最长的函数为vfs_read(),需要进一步分析vfs_read()的耗时究竟消耗在哪个子函数上。即Question 2

3.1 使用trace-cmd record -g func命令抓取数据

上一节已经阐述了,抓取函数内部所有子函数的执行时间,需要使用-g func选项。trace数据已经默认存储到trace.dat文件中。

 sudo trace-cmd record -p function_graph -g vfs_read -F cp -r ~/perf perf.bak

3.2 使用trace-cmd report --profile命令分析数据

1、使用trace-cmd report命令可以把trace.dat解析成文本格式:

$ sudo trace-cmd report| more
...

              cp-3663  [006] 27162.447945: funcgraph_entry:                   |  vfs_read() {
              cp-3663  [006] 27162.447948: funcgraph_entry:                   |    smp_irq_work_interrupt() {
              cp-3663  [006] 27162.447948: funcgraph_entry:                   |      irq_enter() {
              cp-3663  [006] 27162.447948: funcgraph_entry:        0.122 us   |        rcu_irq_enter();
              cp-3663  [006] 27162.447949: funcgraph_exit:         0.396 us   |      }
              cp-3663  [006] 27162.447949: funcgraph_entry:                   |      __wake_up() {
              cp-3663  [006] 27162.447950: funcgraph_entry:                   |        __wake_up_common_lock() {
              cp-3663  [006] 27162.447950: funcgraph_entry:        0.093 us   |          _raw_spin_lock_irqsave();
              cp-3663  [006] 27162.447950: funcgraph_entry:        0.100 us   |          __wake_up_common();
              cp-3663  [006] 27162.447950: funcgraph_entry:        0.098 us   |          _raw_spin_unlock_irqrestore();
              cp-3663  [006] 27162.447950: funcgraph_exit:         0.666 us   |        }
              cp-3663  [006] 27162.447950: funcgraph_exit:         0.877 us   |      }

可以看到,抓出了函数的层次调用关系,以及在函数结束时打印出了函数执行时间。

2、trace-cmd report --profile命令对所有子函数进行统计:

$ sudo trace-cmd report --profile | more
...

task: cp-3663
  Event: func: vfs_read() (6011) Total: 1573004753 Avg: 261687 Max: 49374656(ts:27164.368077) Min:3394(ts:27162.503426)
  Event: func: __vfs_read() (6011) Total: 1530911551 Avg: 254685 Max: 49372111(ts:27164.368077) Min:1928(ts:27162.451416)
  Event: func: new_sync_read() (6009) Total: 1527333966 Avg: 254174 Max: 49371813(ts:27164.368076) Min:1891(ts:27162.503426)
  Event: func: ext4_file_read_iter() (6009) Total: 1523645073 Avg: 253560 Max: 49371449(ts:27164.368076) Min:1703(ts:27162.503426)
  Event: func: generic_file_read_iter() (6009) Total: 1519828915 Avg: 252925 Max: 49371191(ts:27164.368076) Min:1547(ts:27162.503426)
  Event: func: ondemand_readahead() (3073) Total: 755070718 Avg: 245711 Max: 2425224(ts:27164.891754) Min:282(ts:27162.906376)
  Event: func: __do_page_cache_readahead() (3073) Total: 752847053 Avg: 244987 Max: 2424918(ts:27164.891753) Min:91(ts:27162.906375)
  Event: func: page_cache_sync_readahead() (2484) Total: 406033723 Avg: 163459 Max: 1685271(ts:27162.480326) Min:477(ts:27162.906376)
  Event: func: ext4_readpages() (2966) Total: 365560885 Avg: 123250 Max: 1564052(ts:27162.480212) Min:19321(ts:27162.503496)

...

--profile对数据进行了统计和排序。它按照进程为单位,对每个进程的监控函数vfs_read()及其子函数的调用时间进行了统计,有调用次数总时长平均时长最大/小时长,并且默认按照总时长进行了排序。

需要注意的是,上述的统计并没有呈现出函数的调用关系,所以它们的时长可能是相互包含的。另外因为任务切换的发生,数据中还记录了一些非追踪函数vfs_read()子函数以外的函数。但是以上的统计数据,对于排查重点函数还是非常有帮助的。

3.3 使用kernelshark图形化分析数据

trace-cmd report --profile主要是使用统计的方式来找出热点。如果要看vfs_read()一个具体的调用过程,除了使用上一节的trace-cmd report命令,还可以使用kernelshark图形化的形式来查看。

下图是使用kernelshark打开trace.dat文件,并且逐个分析vfs_read()子函数调用的示意图:

在这里插入图片描述

关于kernelshark的详细使用可以参考kernelshark guid。

参考文档:

1.Linux ftrace
2.build kernelshark
3.kernelshark guid
4.ftrace利器之trace-cmd和kernelshark
5.通过trace-cmd和kernelshark简化Ftrace的使用

热门文章

暂无图片
编程学习 ·

环型链表

环型链表 题目描述:给定一个链表,判断链表当中有没有环解体思路: 思路一:可以利用快慢指针的思路,给定两个指针,让两个指针一开始都位于链表头部的位置,然后开始走起来,一个指针每次走一步,一个指针每次走2步,如果说链表是有环的话,那么走的快的链表,就会先进入到环…
暂无图片
编程学习 ·

什么是嵌入式培养?要不要选嵌入式培养?

前言 马上要高考了,高考完后势必要面临选专业,本人作为大二的计算机专业老油条,要为想选计算机专业的小萌新们科普科普,什么是嵌入式培养。嵌入式培养的概述 这里的嵌入式,说白了,就是要把社会上的东西,嵌入到学校的教学里 这个概念本来是没有的,但是上级领导认为,计算…
暂无图片
编程学习 ·

11.登录之后的页面跳转操作

登录之后的页面跳转操作1.登录后记录用户token1.1 为什么使用token?1.2 token为什么保存在sessionStorage中?1.3 代码2. 登录成功后,页面跳转到后台主页 1.登录后记录用户token 1.1 为什么使用token? 项目中除了登录之外的其他API接口,必须要在登录之后才能访问。此时就需要…
暂无图片
编程学习 ·

【Android 内存优化】Bitmap 图像尺寸缩小 ( 考虑像素密度、针对从不同像素密度资源中解码对应的 Bitmap 对象 | inDensity | inTargetDensity )

文章目录一、像素密度对解码图片的影响二、不考虑像素密度会导致图片缩小尺寸不准确三、DisplayMetrics 源码阅读、研究手机资源获取规则四、像素密度参数设置取值 ( inDensity | inTargetDensity | setDensity )五、inDensity 与 inTargetDensity 设置六、新的图片缩小工具类代…
暂无图片
编程学习 ·

开挂的印度裔00后:7岁“出道”教编程,12岁成为IBM荣誉顾问

9年教学经验,400万播放量,还出了3本编程教学书。解锁如此成就的,正是在油管(Youtube)爆火的一位up主,印度裔加拿大籍程序员——Tanmay Bakshi。他的课程覆盖主流操作系统、编程语言,以及基础科学。其深入浅出、通俗易懂的讲解方式,大获网友们的好评。有中国网友,还将他与…
暂无图片
编程学习 ·

Go map的概念及三种使用方法

map的概念map 的基本介绍map 是 key-value 数据结构,又称为字段或者关联数组。类似其它编程语言的集合,基本语法var map 变量名 map[keytype]valuetypekey 可以是什么类型golang 中的 map,的 key 可以是很多种类型,比如 bool, 数字,string, 指针, channel , 还可以是只包…
暂无图片
编程学习 ·

微信小程序引入vant Weapp组件

微信小程序引入vant Weapp组件 步骤: 1. 打开终端: 先初始化: npm init -y 然后进行安装 npm install --productionnpm i @vant/weapp -S --production2. 需要在微信开发者工具,点击工具==>>构建npm 并点击详情,勾选 使用 npm 模块 选项,构建完成后,即可引入组件…
暂无图片
编程学习 ·

关于table中合并单元格的一些问题

关于table中合并单元格的一些问题 首先要明白列表中定义tr为一行,td为一行中的单元格,也就是列的数量。所以在合并行(rowspan)时,得到的是新的一列。代码运行结果如下。<tr><td></td><td></td><td rowspan="3"></td>…
暂无图片
编程学习 ·

springboot应用启动流程分析,嵌入式tomcat

之前我们分析了下springboot自动装载的原理,现在我们看看springboot应用启动的流程: 一般调用如下: // 应用代码SpringApplication.run(MiddlewareApplication.class, args); // SpringApplication.javapublic static ConfigurableApplicationContext run(Class<?> p…
暂无图片
编程学习 ·

【GNURadio RTL-SDR】双RTL-SDR信号源的FM调频广播接收机

文章目录1. 前言2. 实验过程2.1 制作流图2.2 RTL-SDR的设备参数1. 前言 两个RTL-SDR的dongle“电视棒”,芯片 RTL2832U + R820T ,淘宝50左右那种能收FM和我国DTMB频段,想都接到同一台电脑去用软件无线电(GNURadio)的方式收多个FM调频广播信号。 2. 实验过程 在谷歌搜了不少…
暂无图片
编程学习 ·

快速排序手撕模板(递归)

void quicksort(vector<int> arr,int left,int right) {if(right<left){return;}int low=left;int high=right;int base=arr[low]; //以最左边的第一个为基准数 //采用双指针方法while(low<left){while(high){if(high<=low) break;if(arr[high]>base){ //右…
暂无图片
编程学习 ·

Python函数图像绘制(使用海龟库)

序言 如果我们想绘制函数图像,百度上的实现方法琳琅满目,而大多都是使用matlab或其他复杂的库。对于初学者十分头疼。今天我将带着大家一起使用海龟库绘制函数图像。程序十分简单,相对的也不是很美观,大家可以再完善。 准备工作 import turtle as t t.speed(0)#绘制速度达到…
暂无图片
编程学习 ·

ZHS16GBK字符集插入中文时报错ORA-01756

插入数据时遇到一个奇怪的问题,插入中文报错ORA-01756: quoted string not properly terminated简单的复现测试如下:查看客户端及数据库字符集可以看到字符集是一样的,如果不同,设置客户端字符集与数据库端相同再测试export NLS_LANG=AMERICAN_AMERICA.ZHS16GBK找了网上好多…
暂无图片
编程学习 ·

数据库---常用数据库的驱动程序

Oracle数据库 驱动程序包名:ojdbc6.jar 驱动类的名字:oracle.jdbc.driver.OracleDriverJDBC URL:jdbc:oracle:thin: @dpip:port: databasename 说明:驱动程序包名有可能会变 JDBC URL中各个部分含义如下: dbip –为数据库服务器的IP地址,如果是本地可写:localhost或127.…
暂无图片
编程学习 ·

xp系统关于net use报错

在宿主机中使用net use命令映射xp虚拟机中c盘时,报错信息如下: 明明输入正确的用户名和密码,却提示用户名或密码不正确此时,应该在虚拟机中改变xp系统的文件夹选项 使用简单文件共享被默认打勾,去掉以后就可正常使用再次在物理机中输入命令,如图所示: 但我很迷惑为什么有…
暂无图片
编程学习 ·

CSV文件转Excel后数字自动转换成科学计数法的解决方法

CSV文件用Excel打开后,长度超过11位的数字自动转换成科学计数法显示,末尾数字变成“0000”,如何解决这一问题?以“老劳模系统数据.CSV”为例,身份证码是科学计数法了第一步:新建excel,用 office excel 打开第二步:点击“数据”---“从文本/cvs”如果乱码,则选择编码第…
暂无图片
编程学习 ·

快手2020校园招聘秋招笔试--工程B试卷

攻击者使用无效IP地址,利用TCP连接的三次握手过程,连续发送会话请求,使受害主机处于开放会话的请求之中,直至连接超时,最终因耗尽资源而停止响应。这种攻击被称为A. DNS欺骗攻击 B. DDoS攻击 C. SYN Flooding攻击 D. 重放攻击DNS欺骗攻击:DNS(Domin Name Sever)是域名服…
暂无图片
编程学习 ·

【解惑】到底是“时间片“?还是“分时轮询“?

1、任务调度任务调度对于电子类或者自动化类专业小伙伴最早接触一般都是在接触RTOS后了,然而对于计算机相关专业的小伙伴应该在学《计算机操作系统》老师对这一块讲解的非常清楚了,包括一些性能指标的定义与计算等等,不过作者这里仅仅只针对RTOS进行讲解,大家感兴趣可以找一…
暂无图片
编程学习 ·

Transformer

Transformer是谷歌大脑在2017年底发表的论文attention is all you need中所提出的seq2seq模型。现在已经取得了大范围的应用和扩展,而BERT就是从Transformer中衍生出来的预训练语言模型 这篇文章分为以下几个部分Transformer直观认识 Positional Encoding Self Attention Mech…