perf

Perf 是用来进行软件性能分析的工具。



通过它,应用程序可以利用 PMU,tracepoint 和内核中的特殊计数器来进行性能统计。它不但可以分析指定应用程序的性能问题 (per thread),也可以用来分析内核的性能问题,当然也可以同时分析应用代码和内核,从而全面理解应用程序中的性能瓶颈。



最初的时候,它叫做 Performance counter,在 2.6.31 中第一次亮相。此后他成为内核开发最为活跃的一个领域。在 2.6.32 中它正式改名为 Performance Event,因为 perf 已不再仅仅作为 PMU 的抽象,而是能够处理所有的性能相关的事件。



使用 perf,您可以分析程序运行期间发生的硬件事件,比如 instructions retired ,processor clock cycles 等;您也可以分析软件事件,比如 Page Fault 和进程切换。

这使得 Perf 拥有了众多的性能分析能力,举例来说,使用 Perf 可以计算每个时钟周期内的指令数,称为 IPC,IPC 偏低表明代码没有很好地利用 CPU。Perf 还可以对程序进行函数级别的采样,从而了解程序的性能瓶颈究竟在哪里等等。Perf 还可以替代 strace,可以添加动态内核 probe 点,还可以做 benchmark 衡量调度器的好坏。。。



背景知识
有些背景知识是分析性能问题时需要了解的。比如硬件 cache;再比如操作系统内核。应用程序的行为细节往往是和这些东西互相牵扯的,这些底层的东西会以意想不到的方式影响应用程序的性能,比如某些程序无法充分利用 cache,从而导致性能下降。比如不必要地调用过多的系统调用,造成频繁的内核 / 用户切换。等等。方方面面,这里只是为本文的后续内容做一些铺垫,关于调优还有很多东西,我所不知道的比知道的要多的多。



性能相关的处理器硬件特性,PMU 简介
当算法已经优化,代码不断精简,人们调到最后,便需要斤斤计较了。cache 啊,流水线啊一类平时不大注意的东西也必须精打细算了。



硬件特性之 cache
内存读写是很快的,但还是无法和处理器的指令执行速度相比。为了从内存中读取指令和数据,处理器需要等待,用处理器的时间来衡量,这种等待非常漫长。Cache 是一种 SRAM,它的读写速率非常快,能和处理器处理速度相匹配。因此将常用的数据保存在 cache 中,处理器便无须等待,从而提高性能。Cache 的尺寸一般都很小,充分利用 cache 是软件调优非常重要的部分。



硬件特性之流水线,超标量体系结构,乱序执行
提高性能最有效的方式之一就是并行。处理器在硬件设计时也尽可能地并行,比如流水线,超标量体系结构以及乱序执行。



处理器处理一条指令需要分多个步骤完成,比如先取指令,然后完成运算,最后将计算结果输出到总线上。在处理器内部,这可以看作一个三级流水线,如下图所示:



图 1. 处理器流水线
图 1. 处理器流水线
指令从左边进入处理器,上图中的流水线有三级,一个时钟周期内可以同时处理三条指令,分别被流水线的不同部分处理。



超标量(superscalar)指一个时钟周期发射多条指令的流水线机器架构,比如 Intel 的 Pentium 处理器,内部有两个执行单元,在一个时钟周期内允许执行两条指令。



此外,在处理器内部,不同指令所需要的处理步骤和时钟周期是不同的,如果严格按照程序的执行顺序执行,那么就无法充分利用处理器的流水线。因此指令有可能被乱序执行。



上述三种并行技术对所执行的指令有一个基本要求,即相邻的指令相互没有依赖关系。假如某条指令需要依赖前面一条指令的执行结果数据,那么 pipeline 便失去作用,因为第二条指令必须等待第一条指令完成。因此好的软件必须尽量避免这种代码的生成。



硬件特性之分支预测
分支指令对软件性能有比较大的影响。尤其是当处理器采用流水线设计之后,假设流水线有三级,当前进入流水的第一条指令为分支指令。假设处理器顺序读取指令,那么如果分支的结果是跳转到其他指令,那么被处理器流水线预取的后续两条指令都将被放弃,从而影响性能。为此,很多处理器都提供了分支预测功能,根据同一条指令的历史执行记录进行预测,读取最可能的下一条指令,而并非顺序读取指令。



分支预测对软件结构有一些要求,对于重复性的分支指令序列,分支预测硬件能得到较好的预测结果,而对于类似 switch case 一类的程序结构,则往往无法得到理想的预测结果。



上面介绍的几种处理器特性对软件的性能有很大的影响,然而依赖时钟进行定期采样的 profiler 模式无法揭示程序对这些处理器硬件特性的使用情况。处理器厂商针对这种情况,在硬件中加入了 PMU 单元,即 performance monitor unit。



PMU 允许软件针对某种硬件事件设置 counter,此后处理器便开始统计该事件的发生次数,当发生的次数超过 counter 内设置的值后,便产生中断。比如 cache miss 达到某个值后,PMU 便能产生相应的中断。



捕获这些中断,便可以考察程序对这些硬件特性的利用效率了。
Tracepoints
Tracepoint 是散落在内核源代码中的一些 hook,一旦使能,它们便可以在特定的代码被运行到时被触发,这一特性可以被各种 trace/debug 工具所使用。Perf 就是该特性的用户之一。



假如您想知道在应用程序运行期间,内核内存管理模块的行为,便可以利用潜伏在 slab 分配器中的 tracepoint。当内核运行到这些 tracepoint 时,便会通知 perf。



Perf 将 tracepoint 产生的事件记录下来,生成报告,通过分析这些报告,调优人员便可以了解程序运行时期内核的种种细节,对性能症状作出更准确的诊断。



perf 的基本使用
说明一个工具的最佳途径是列举一个例子。



考查下面这个例子程序。其中函数 longa() 是个很长的循环,比较浪费时间。函数 foo1 和 foo2 将分别调用该函数 10 次,以及 100 次。
//test.c
void longa()
{
int i,j;
for(i = 0; i < 1000000; i++)
j=i; //am I silly or crazy? I feel boring and desperate.
}



void foo2()
{
int i;
for(i=0 ; i < 10; i++)
longa();
}



void foo1()
{
int i;
for(i = 0; i< 100; i++)
longa();
}



int main(void)
{
foo1();
foo2();
}



找到这个程序的性能瓶颈无需任何工具,肉眼的阅读便可以完成。Longa() 是这个程序的关键,只要提高它的速度,就可以极大地提高整个程序的运行效率。



但,因为其简单,却正好可以用来演示 perf 的基本使用。假如 perf 告诉您这个程序的瓶颈在别处,您就不必再浪费宝贵时间阅读本文了。



准备使用 perf
安装 perf 非常简单,只要您有 2.6.31 以上的内核源代码,那么进入 tools/perf 目录然后敲入下面两个命令即可:



1
2
make
make install
性能调优工具如 perf,Oprofile 等的基本原理都是对被监测对象进行采样,最简单的情形是根据 tick 中断进行采样,即在 tick 中断内触发采样点,在采样点里判断程序当时的上下文。假如一个程序 90% 的时间都花费在函数 foo() 上,那么 90% 的采样点都应该落在函数 foo() 的上下文中。运气不可捉摸,但我想只要采样频率足够高,采样时间足够长,那么以上推论就比较可靠。因此,通过 tick 触发采样,我们便可以了解程序中哪些地方最耗时间,从而重点分析。



稍微扩展一下思路,就可以发现改变采样的触发条件使得我们可以获得不同的统计数据:



以时间点 ( 如 tick) 作为事件触发采样便可以获知程序运行时间的分布。



以 cache miss 事件触发采样便可以知道 cache miss 的分布,即 cache 失效经常发生在哪些程序代码中。如此等等。



因此让我们先来了解一下 perf 中能够触发采样的事件有哪些。



Perf list,perf 事件
使用 perf list 命令可以列出所有能够触发 perf 采样点的事件。比如



$ perf list
List of pre-defined events (to be used in -e):
cpu-cycles OR cycles [Hardware event]
instructions [Hardware event]

cpu-clock [Software event]
task-clock [Software event]
context-switches OR cs [Software event]

ext4:ext4allocate_inode [Tracepoint event]
kmem:kmalloc [Tracepoint event]
module:module_load [Tracepoint event]
workqueue:workqueue_execution [Tracepoint event]
sched:sched
{wakeup,switch} [Tracepoint event]
syscalls:sys_{enter,exit}_epoll_wait [Tracepoint event]



不同的系统会列出不同的结果,在 2.6.35 版本的内核中,该列表已经相当的长,但无论有多少,我们可以将它们划分为三类:



Hardware Event 是由 PMU 硬件产生的事件,比如 cache 命中,当您需要了解程序对硬件特性的使用情况时,便需要对这些事件进行采样;



Software Event 是内核软件产生的事件,比如进程切换,tick 数等 ;



Tracepoint event 是内核中的静态 tracepoint 所触发的事件,这些 tracepoint 用来判断程序运行期间内核的行为细节,比如 slab 分配器的分配次数等。



上述每一个事件都可以用于采样,并生成一项统计数据,时至今日,尚没有文档对每一个 event 的含义进行详细解释。我希望能和大家一起努力,以弄明白更多的 event 为目标。。。



Perf stat
做任何事都最好有条有理。老手往往能够做到不慌不忙,循序渐进,而新手则往往东一下,西一下,不知所措。



面对一个问题程序,最好采用自顶向下的策略。先整体看看该程序运行时各种统计事件的大概,再针对某些方向深入细节。而不要一下子扎进琐碎细节,会一叶障目的。



有些程序慢是因为计算量太大,其多数时间都应该在使用 CPU 进行计算,这叫做 CPU bound 型;有些程序慢是因为过多的 IO,这种时候其 CPU 利用率应该不高,这叫做 IO bound 型;对于 CPU bound 程序的调优和 IO bound 的调优是不同的。



如果您认同这些说法的话,Perf stat 应该是您最先使用的一个工具。它通过概括精简的方式提供被调试程序运行的整体情况和汇总数据。



还记得我们前面准备的那个例子程序么?现在将它编译为可执行文件 t1



1
gcc – o t1 – g test.c
下面演示了 perf stat 针对程序 t1 的输出:
$perf stat ./t1
Performance counter stats for ‘./t1’:



262.738415 task-clock-msecs # 0.991 CPUs
2 context-switches # 0.000 M/sec
1 CPU-migrations # 0.000 M/sec
81 page-faults # 0.000 M/sec
9478851 cycles # 36.077 M/sec (scaled from 98.24%)
6771 instructions # 0.001 IPC (scaled from 98.99%)
111114049 branches # 422.908 M/sec (scaled from 99.37%)
8495 branch-misses # 0.008 % (scaled from 95.91%)
12152161 cache-references # 46.252 M/sec (scaled from 96.16%)
7245338 cache-misses # 27.576 M/sec (scaled from 95.49%)



0.265238069 seconds time elapsed



上面告诉我们,程序 t1 是一个 CPU bound 型,因为 task-clock-msecs 接近 1。
对 t1 进行调优应该要找到热点 ( 即最耗时的代码片段 ),再看看是否能够提高热点代码的效率。



缺省情况下,除了 task-clock-msecs 之外,perf stat 还给出了其他几个最常用的统计信息:



Task-clock-msecs:CPU 利用率,该值高,说明程序的多数时间花费在 CPU 计算上而非 IO。



Context-switches:进程切换次数,记录了程序运行过程中发生了多少次进程切换,频繁的进程切换是应该避免的。



Cache-misses:程序运行过程中总体的 cache 利用情况,如果该值过高,说明程序的 cache 利用不好



CPU-migrations:表示进程 t1 运行过程中发生了多少次 CPU 迁移,即被调度器从一个 CPU 转移到另外一个 CPU 上运行。



Cycles:处理器时钟,一条机器指令可能需要多个 cycles,



Instructions: 机器指令数目。



IPC:是 Instructions/Cycles 的比值,该值越大越好,说明程序充分利用了处理器的特性。



Cache-references: cache 命中的次数



Cache-misses: cache 失效的次数。



通过指定 -e 选项,您可以改变 perf stat 的缺省事件 ( 关于事件,在上一小节已经说明,可以通过 perf list 来查看 )。假如您已经有很多的调优经验,可能会使用 -e 选项来查看您所感兴趣的特殊的事件。



perf Top
使用 perf stat 的时候,往往您已经有一个调优的目标。比如我刚才写的那个无聊程序 t1。



也有些时候,您只是发现系统性能无端下降,并不清楚究竟哪个进程成为了贪吃的 hog。



此时需要一个类似 top 的命令,列出所有值得怀疑的进程,从中找到需要进一步审查的家伙。类似法制节目中办案民警常常做的那样,通过查看监控录像从茫茫人海中找到行为古怪的那些人,而不是到大街上抓住每一个人来审问。



Perf top 用于实时显示当前系统的性能统计信息。该命令主要用来观察整个系统当前的状态,比如可以通过查看该命令的输出来查看当前系统最耗时的内核函数或某个用户进程。



让我们再设计一个例子来演示吧。



不知道您怎么想,反正我觉得做一件有益的事情很难,但做点儿坏事儿却非常容易。我很快就想到了如代码清单 2 所示的一个程序:



清单 2. 一个死循环
1
while (1) i++;
我叫他 t2。启动 t2,然后用 perf top 来观察:



下面是 perf top 的可能输出:
PerfTop: 705 irqs/sec kernel:60.4% [1000Hz cycles]
————————————————–
sampl pcnt function DSO
1503.00 49.2% t2
72.00 2.2% pthread_mutex_lock /lib/libpthread-2.12.so
68.00 2.1% delay_tsc [kernel.kallsyms]
55.00 1.7% aes_dec_blk [aes_i586]
55.00 1.7% drm_clflush_pages [drm]
52.00 1.6% system_call [kernel.kallsyms]
49.00 1.5% __memcpy_ssse3 /lib/libc-2.12.so
48.00 1.4% __strstr_ia32 /lib/libc-2.12.so
46.00 1.4% unix_poll [kernel.kallsyms]
42.00 1.3% __ieee754_pow /lib/libm-2.12.so
41.00 1.2% do_select [kernel.kallsyms]
40.00 1.2% pixman_rasterize_edges libpixman-1.so.0.18.0
37.00 1.1% _raw_spin_lock_irqsave [kernel.kallsyms]
36.00 1.1% _int_malloc /lib/libc-2.12.so
^C
很容易便发现 t2 是需要关注的可疑程序。不过其作案手法太简单:肆无忌惮地浪费着 CPU。所以我们不用再做什么其他的事情便可以找到问题所在。但现实生活中,影响性能的程序一般都不会如此愚蠢,所以我们往往还需要使用其他的 perf 工具进一步分析。



通过添加 -e 选项,您可以列出造成其他事件的 TopN 个进程 / 函数。比如 -e cache-miss,用来看看谁造成的 cache miss 最多。



3使用 perf record, 解读 report
使用 top 和 stat 之后,您可能已经大致有数了。要进一步分析,便需要一些粒度更细的信息。比如说您已经断定目标程序计算量较大,也许是因为有些代码写的不够精简。那么面对长长的代码文件,究竟哪几行代码需要进一步修改呢?这便需要使用 perf record 记录单个函数级别的统计信息,并使用 perf report 来显示统计结果。



您的调优应该将注意力集中到百分比高的热点代码片段上,假如一段代码只占用整个程序运行时间的 0.1%,即使您将其优化到仅剩一条机器指令,恐怕也只能将整体的程序性能提高 0.1%。俗话说,好钢用在刀刃上,不必我多说了。



仍以 t1 为例。



1
2
perf record – e cpu-clock ./t1
perf report
结果如下图所示:



图 2. perf report 示例
图 2. perf report 示例
不出所料,hot spot 是 longa( ) 函数。



但,代码是非常复杂难说的,t1 程序中的 foo1() 也是一个潜在的调优对象,为什么要调用 100 次那个无聊的 longa() 函数呢?但我们在上图中无法发现 foo1 和 foo2,更无法了解他们的区别了。



我曾发现自己写的一个程序居然有近一半的时间花费在 string 类的几个方法上,string 是 C++ 标准,我绝不可能写出比 STL 更好的代码了。因此我只有找到自己程序中过多使用 string 的地方。因此我很需要按照调用关系进行显示的统计信息。



使用 perf 的 -g 选项便可以得到需要的信息:



1
2
perf record – e cpu-clock – g ./t1
perf report
结果如下图所示:



图 3. perf – g report 示例
图 3. perf – g report 示例
通过对 calling graph 的分析,能很方便地看到 91% 的时间都花费在 foo1() 函数中,因为它调用了 100 次 longa() 函数,因此假如 longa() 是个无法优化的函数,那么程序员就应该考虑优化 foo1,减少对 longa() 的调用次数。



使用 PMU 的例子
例子 t1 和 t2 都较简单。所谓魔高一尺,道才能高一丈。要想演示 perf 更加强大的能力,我也必须想出一个高明的影响性能的例子,我自己想不出,只好借助于他人。下面这个例子 t3 参考了文章“Branch and Loop Reorganization to Prevent Mispredicts”[6]



该例子考察程序对奔腾处理器分支预测的利用率,如前所述,分支预测能够显著提高处理器的性能,而分支预测失败则显著降低处理器的性能。首先给出一个存在 BTB 失效的例子:



清单 3. 存在 BTB 失效的例子程序
//test.c
#include
#include



void foo()
{
int i,j;
for(i=0; i< 10; i++)
j+=2;
}
int main(void)
{
int i;
for(i = 0; i< 100000000; i++)
foo();
return 0;
}
用 gcc 编译生成测试程序 t3:



1
gcc – o t3 – O0 test.c
用 perf stat 考察分支预测的使用情况:
[lm@ovispoly perf]$ ./perf stat ./t3



Performance counter stats for ‘./t3’:



6240.758394 task-clock-msecs # 0.995 CPUs
126 context-switches # 0.000 M/sec
12 CPU-migrations # 0.000 M/sec
80 page-faults # 0.000 M/sec
17683221 cycles # 2.834 M/sec (scaled from 99.78%)
10218147 instructions # 0.578 IPC (scaled from 99.83%)
2491317951 branches # 399.201 M/sec (scaled from 99.88%)
636140932 branch-misses # 25.534 % (scaled from 99.63%)
126383570 cache-references # 20.251 M/sec (scaled from 99.68%)
942937348 cache-misses # 151.093 M/sec (scaled from 99.58%)



6.271917679 seconds time elapsed
可以看到 branche-misses 的情况比较严重,25% 左右。我测试使用的机器的处理器为 Pentium4,其 BTB 的大小为 16。而 test.c 中的循环迭代为 20 次,BTB 溢出,所以处理器的分支预测将不准确。



对于上面这句话我将简要说明一下,但关于 BTB 的细节,请阅读参考文献 [6]。



for 循环编译成为 IA 汇编后如下:



清单 4. 循环的汇编



// C code
for ( i=0; i < 20; i++ )
{ … }



//Assembly code;
mov esi, data
mov ecx, 0
ForLoop:
cmp ecx, 20
jge

EndForLoop

add ecx, 1
jmp ForLoop
EndForLoop:
可以看到,每次循环迭代中都有一个分支语句 jge,因此在运行过程中将有 20 次分支判断。每次分支判断都将写入 BTB,但 BTB 是一个 ring buffer,16 个 slot 写满后便开始覆盖。假如迭代次数正好为 16,或者小于 16,则完整的循环将全部写入 BTB,比如循环迭代次数为 4 次,则 BTB 应该如下图所示:



图 4. BTB buffer
图 4. BTB buffer
这个 buffer 完全精确地描述了整个循环迭代的分支判定情况,因此下次运行同一个循环时,处理器便可以做出完全正确的预测。但假如迭代次数为 20,则该 BTB 随着时间推移而不能完全准确地描述该循环的分支预测执行情况,处理器将做出错误的判断。



我们将测试程序进行少许的修改,将迭代次数从 20 减少到 10,为了让逻辑不变,j++ 变成了 j+=2;



清单 5. 没有 BTB 失效的代码
#include
#include



void foo()
{
int i,j;
for(i=0; i< 10; i++)
j+=2;
}
int main(void)
{
int i;
for(i = 0; i< 100000000; i++)
foo();
return 0;
}
此时再次用 perf stat 采样得到如下结果:
[lm@ovispoly perf]$ ./perf stat ./t3



Performance counter stats for ‘./t3:



2784.004851 task-clock-msecs # 0.927 CPUs
90 context-switches # 0.000 M/sec
8 CPU-migrations # 0.000 M/sec
81 page-faults # 0.000 M/sec
33632545 cycles # 12.081 M/sec (scaled from 99.63%)
42996 instructions # 0.001 IPC (scaled from 99.71%)
1474321780 branches # 529.569 M/sec (scaled from 99.78%)
49733 branch-misses # 0.003 % (scaled from 99.35%)
7073107 cache-references # 2.541 M/sec (scaled from 99.42%)
47958540 cache-misses # 17.226 M/sec (scaled from 99.33%)



3.002673524 seconds time elapsed
Branch-misses 减少了。



本例只是为了演示 perf 对 PMU 的使用,本身并无意义,关于充分利用 processor 进行调优可以参考 Intel 公司出品的调优手册,其他的处理器可能有不同的方法,还希望读者明鉴。



第二部分



之前介绍了 perf 最常见的一些用法,关注于 Linux 系统上应用程序的调优。现在让我们把目光转移到内核以及其他 perf 命令上面来。



在内核方面,人们的兴趣五花八门,有些内核开发人员热衷于寻找整个内核中的热点代码;另一些则只关注某一个主题,比如 slab 分配器,对于其余部分则不感兴趣。对这些人而言,perf 的一些奇怪用法更受欢迎。当然,诸如 perf top,perf stat, perf record 等也是内核调优的基本手段,但用法和 part1 所描述的一样,无需重述。



此外虽然内核事件对应用程序开发人员而言有些陌生,但一旦了解,对应用程序的调优也很有帮助。我曾经参与开发过一个数据库应用程序,其效率很低。通过常规的热点查询,IO 统计等方法,我们找到了一些可以优化的地方,以至于将程序的效率提高了几倍。可惜对于拥有海量数据的用户,其运行时间依然无法达到要求。进一步调优需要更加详细的统计信息,可惜本人经验有限,实在是无计可施。。。从客户反馈来看,该应用的使用频率很低。作为一个程序员,为此我时常心情沮丧。。。



假如有 perf,那么我想我可以用它来验证自己的一些猜测,比如是否太多的系统调用,或者系统中的进程切换太频繁 ? 针对这些怀疑使用 perf 都可以拿出有用的报告,或许能找到问题吧。但过去的便无可弥补,时光不会倒流,无论我如何伤感,世界绝不会以我的意志为转移。所以我们好好学习 perf,或许可以预防某些遗憾吧。



这里我还要提醒读者注意,讲述 perf 的命令和语法容易,但说明什么时候使用这些命令,或者说明怎样解决实际问题则很困难。就好象说明电子琴上 88 个琴键的唱名很容易,但想说明如何弹奏动听的曲子则很难。



在简述每个命令语法的同时,我试图通过一些示例来说明这些命令的使用场景,但这只能是一种微薄的努力。因此总体说来,本文只能充当那本随同电子琴一起发售的使用说明书。。。



使用 tracepoint
当 perf 根据 tick 时间点进行采样后,人们便能够得到内核代码中的 hot spot。那什么时候需要使用 tracepoint 来采样呢?



我想人们使用 tracepoint 的基本需求是对内核的运行时行为的关心,如前所述,有些内核开发人员需要专注于特定的子系统,比如内存管理模块。这便需要统计相关内核函数的运行情况。另外,内核行为对应用程序性能的影响也是不容忽视的:



以之前的遗憾为例,假如时光倒流,我想我要做的是统计该应用程序运行期间究竟发生了多少次系统调用。在哪里发生的?



下面我用 ls 命令来演示 sys_enter 这个 tracepoint 的使用:
[root@ovispoly /]# perf stat -e raw_syscalls:sys_enter ls
bin dbg etc lib media opt root selinux sys usr
boot dev home lost+found mnt proc sbin srv tmp var



Performance counter stats for ‘ls’:



101 raw_syscalls:sys_enter



0.003434730 seconds time elapsed



[root@ovispoly /]# perf record -e raw_syscalls:sys_enter ls



[root@ovispoly /]# perf report
Failed to open .lib/ld-2.12.so, continuing without symbols


Samples: 70


#


Overhead Command Shared Object Symbol


…….. …………… …………… ……


#
97.14% ls ld-2.12.so [.] 0x0000000001629d
2.86% ls [vdso] [.] 0x00000000421424
#


(For a higher level overview, try: perf report –sort comm,dso)


#
这个报告详细说明了在 ls 运行期间发生了多少次系统调用 ( 上例中有 101 次 ),多数系统调用都发生在哪些地方 (97% 都发生在 ld-2.12.so 中 )。



有了这个报告,或许我能够发现更多可以调优的地方。比如函数 foo() 中发生了过多的系统调用,那么我就可以思考是否有办法减少其中有些不必要的系统调用。



您可能会说 strace 也可以做同样事情啊,的确,统计系统调用这件事完全可以用 strace 完成,但 perf 还可以干些别的,您所需要的就是修改 -e 选项后的字符串。



罗列 tracepoint 实在是不太地道,本文当然不会这么做。但学习每一个 tracepoint 是有意义的,类似背单词之于学习英语一样,是一项缓慢痛苦却不得不做的事情。



perf probe
tracepoint 是静态检查点,意思是一旦它在哪里,便一直在那里了,您想让它移动一步也是不可能的。内核代码有多少行?我不知道,100 万行是至少的吧,但目前 tracepoint 有多少呢?我最大胆的想象是不超过 1000 个。所以能够动态地在想查看的地方插入动态监测点的意义是不言而喻的。



Perf 并不是第一个提供这个功能的软件,systemTap 早就实现了。但假若您不选择 RedHat 的发行版的话,安装 systemTap 并不是件轻松愉快的事情。perf 是内核代码包的一部分,所以使用和维护都非常方便。



我使用的 Linux 版本为 2.6.33。因此您自己做实验时命令参数有可能不同。
[root@ovispoly perftest]# perf probe schedule:12 cpu
Added new event:
probe:schedule (on schedule+52 with cpu)



You can now use it on all perf tools, such as:



perf record -e probe:schedule -a sleep 1



[root@ovispoly perftest]# perf record -e probe:schedule -a sleep 1
Error, output file perf.data exists, use -A to append or -f to overwrite.



[root@ovispoly perftest]# perf record -f -e probe:schedule -a sleep 1
[ perf record: Woken up 1 times to write data ]
[ perf record: Captured and wrote 0.270 MB perf.data (~11811 samples) ]
[root@ovispoly perftest]# perf report


Samples: 40


#


Overhead Command Shared Object Symbol


…….. …………… …………….. ……


#
57.50% init 0 [k] 0000000000000000
30.00% firefox [vdso] [.] 0x0000000029c424
5.00% sleep [vdso] [.] 0x00000000ca7424
5.00% perf.2.6.33.3-8 [vdso] [.] 0x00000000ca7424
2.50% ksoftirqd/0 [kernel] [k] 0000000000000000
#


(For a higher level overview, try: perf report –sort comm,dso)


#
上例利用 probe 命令在内核函数 schedule() 的第 12 行处加入了一个动态 probe 点,和 tracepoint 的功能一样,内核一旦运行到该 probe 点时,便会通知 perf。可以理解为动态增加了一个新的 tracepoint。



此后便可以用 record 命令的 -e 选项选择该 probe 点,最后用 perf report 查看报表。如何解读该报表便是见仁见智了,既然您在 shcedule() 的第 12 行加入了 probe 点,想必您知道自己为什么要统计它吧?



Perf sched
调度器的好坏直接影响一个系统的整体运行效率。在这个领域,内核黑客们常会发生争执,一个重要原因是对于不同的调度器,每个人给出的评测报告都各不相同,甚至常常有相反的结论。因此一个权威的统一的评测工具将对结束这种争论有益。Perf sched 便是这种尝试。



Perf sched 有五个子命令:



1
2
3
4
5
perf sched record # low-overhead recording of arbitrary workloads
perf sched latency # output per task latency metrics
perf sched map # show summary/map of context-switching
perf sched trace # output finegrained trace
perf sched replay # replay a captured workload using simlated threads
用户一般使用’ perf sched record ’收集调度相关的数据,然后就可以用’ perf sched latency ’查看诸如调度延迟等和调度器相关的统计数据。



其他三个命令也同样读取 record 收集到的数据并从其他不同的角度来展示这些数据。下面一一进行演示。
perf sched record sleep 10 # record full system activity for 10 seconds
perf sched latency –sort max # report latencies sorted by max





Task | Runtime ms | Switches | Average delay ms | Maximum delay ms |
————————————————————————————-
:14086:14086 | 0.095 ms | 2 | avg: 3.445 ms | max: 6.891 ms |
gnome-session:13792 | 31.713 ms | 102 | avg: 0.160 ms | max: 5.992 ms |
metacity:14038 | 49.220 ms | 637 | avg: 0.066 ms | max: 5.942 ms |
gconfd-2:13971 | 48.587 ms | 777 | avg: 0.047 ms | max: 5.793 ms |
gnome-power-man:14050 | 140.601 ms | 434 | avg: 0.097 ms | max: 5.367 ms |
python:14049 | 114.694 ms | 125 | avg: 0.120 ms | max: 5.343 ms |
kblockd/1:236 | 3.458 ms | 498 | avg: 0.179 ms | max: 5.271 ms |
Xorg:3122 | 1073.107 ms | 2920 | avg: 0.030 ms | max: 5.265 ms |
dbus-daemon:2063 | 64.593 ms | 665 | avg: 0.103 ms | max: 4.730 ms |
:14040:14040 | 30.786 ms | 255 | avg: 0.095 ms | max: 4.155 ms |
events/1:8 | 0.105 ms | 13 | avg: 0.598 ms | max: 3.775 ms |
console-kit-dae:2080 | 14.867 ms | 152 | avg: 0.142 ms | max: 3.760 ms |
gnome-settings-:14023 | 572.653 ms | 979 | avg: 0.056 ms | max: 3.627 ms |

———————————————————————————–
TOTAL: | 3144.817 ms | 11654 |
—————————————————



上面的例子展示了一个 Gnome 启动时的统计信息。
各个 column 的含义如下:
Task: 进程的名字和 pid
Runtime: 实际运行时间
Switches: 进程切换的次数
Average delay: 平均的调度延迟
Maximum delay: 最大延迟
这里最值得人们关注的是 Maximum delay,一般从这里可以看到对交互性影响最大的特性:调度延迟,如果调度延迟比较大,那么用户就会感受到视频或者音频断断续续的。



其他的三个子命令提供了不同的视图,一般是由调度器的开发人员或者对调度器内部实现感兴趣的人们所使用。



首先是 map:
$ perf sched map



N1 O1 . . . S1 . . . B0 . *I0 C1 . M1 . 23002.773423 secs
N1 O1 . *Q0 . S1 . . . B0 . I0 C1 . M1 . 23002.773423 secs
N1 O1 . Q0 . S1 . . . B0 . *R1 C1 . M1 . 23002.773485 secs
N1 O1 . Q0 . S1 . *S0 . B0 . R1 C1 . M1 . 23002.773478 secs
*L0 O1 . Q0 . S1 . S0 . B0 . R1 C1 . M1 . 23002.773523 secs
L0 O1 . *. . S1 . S0 . B0 . R1 C1 . M1 . 23002.773531 secs
L0 O1 . . . S1 . S0 . B0 . R1 C1 *T1 M1 . 23002.773547 secs
T1 => irqbalance:2089
L0 O1 . . . S1 . S0 . *P0 . R1 C1 T1 M1 . 23002.773549 secs
*N1 O1 . . . S1 . S0 . P0 . R1 C1 T1 M1 . 23002.773566 secs
N1 O1 . . . *J0 . S0 . P0 . R1 C1 T1 M1 . 23002.773571 secs
N1 O1 . . . J0 . S0 *B0 P0 . R1 C1 T1 M1 . 23002.773592 secs
N1 O1 . . . J0 . *U0 B0 P0 . R1 C1 T1 M1 . 23002.773582 secs
N1 O1 . . . *S1 . U0 B0 P0 . R1 C1 T1 M1 . 23002.773604 secs
星号表示调度事件发生所在的 CPU。



点号表示该 CPU 正在 IDLE。



Map 的好处在于提供了一个的总的视图,将成百上千的调度事件进行总结,显示了系统任务在 CPU 之间的分布,假如有不好的调度迁移,比如一个任务没有被及时迁移到 idle 的 CPU 却被迁移到其他忙碌的 CPU,类似这种调度器的问题可以从 map 的报告中一眼看出来。



如果说 map 提供了高度概括的总体的报告,那么 trace 就提供了最详细,最底层的细节报告。
pipe-test-100k-13520 [001] 1254.354513808: sched_stat_wait:
task: pipe-test-100k:13521 wait: 5362 [ns]
pipe-test-100k-13520 [001] 1254.354514876: sched_switch:
task pipe-test-100k:13520 [120] (S) ==> pipe-test-100k:13521 [120]
:13521-13521 [001] 1254.354517927: sched_stat_runtime:
task: pipe-test-100k:13521 runtime: 5092 [ns], vruntime: 133967391150 [ns]
:13521-13521 [001] 1254.354518984: sched_stat_sleep:
task: pipe-test-100k:13520 sleep: 5092 [ns]
:13521-13521 [001] 1254.354520011: sched_wakeup:
task pipe-test-100k:13520 [120] success=1 [001]
要理解以上的信息,必须对调度器的源代码有一定了解,对一般用户而言,理解他们十分不易。幸好这些信息一般也只有编写调度器的人感兴趣。。。



Perf replay 这个工具更是专门为调度器开发人员所设计,它试图重放 perf.data 文件中所记录的调度场景。很多情况下,一般用户假如发现调度器的奇怪行为,他们也无法准确说明发生该情形的场景,或者一些测试场景不容易再次重现,或者仅仅是出于“偷懒”的目的,使用 perf replay,perf 将模拟 perf.data 中的场景,无需开发人员花费很多的时间去重现过去,这尤其利于调试过程,因为需要一而再,再而三地重复新的修改是否能改善原始的调度场景所发现的问题。



下面是 replay 执行的示例:
$ perf sched replay
run measurement overhead: 3771 nsecs
sleep measurement overhead: 66617 nsecs
the run test took 999708 nsecs
the sleep test took 1097207 nsecs
nr_run_events: 200221
nr_sleep_events: 200235
nr_wakeup_events: 100130
task 0 ( perf: 13519), nr_events: 148
task 1 ( perf: 13520), nr_events: 200037
task 2 ( pipe-test-100k: 13521), nr_events: 300090
task 3 ( ksoftirqd/0: 4), nr_events: 8
task 4 ( swapper: 0), nr_events: 170
task 5 ( gnome-power-man: 3192), nr_events: 3
task 6 ( gdm-simple-gree: 3234), nr_events: 3
task 7 ( Xorg: 3122), nr_events: 5
task 8 ( hald-addon-stor: 2234), nr_events: 27
task 9 ( ata/0: 321), nr_events: 29
task 10 ( scsi_eh_4: 704), nr_events: 37
task 11 ( events/1: 8), nr_events: 3
task 12 ( events/0: 7), nr_events: 6
task 13 ( flush-8:0: 6980), nr_events: 20
————————————————————
#1 : 2038.157, ravg: 2038.16, cpu: 0.09 / 0.09
#2 : 2042.153, ravg: 2038.56, cpu: 0.11 / 0.09
^C
perf bench
除了调度器之外,很多时候人们都需要衡量自己的工作对系统性能的影响。benchmark 是衡量性能的标准方法,对于同一个目标,如果能够有一个大家都承认的 benchmark,将非常有助于”提高内核性能”这项工作。



目前,就我所知,perf bench 提供了 3 个 benchmark:




  1. Sched message



[lm@ovispoly ~]$ perf bench sched messaging


Running sched/messaging benchmark…# 20 sender and receiver processes per group# 10 groups == 400 processes run Total time: 1.918 [sec]sched message 是从经典的测试程序 hackbench 移植而来,用来衡量调度器的性能,overhead 以及可扩展性。该 benchmark 启动 N 个 reader/sender 进程或线程对,通过 IPC(socket 或者 pipe) 进行并发的读写。一般人们将 N 不断加大来衡量调度器的可扩展性。Sched message 的用法及用途和 hackbench 一样。




  1. Sched Pipe



[lm@ovispoly ~]$ perf bench sched pipe


Running sched/pipe benchmark…# Extecuted 1000000 pipe operations between two tasks Total time: 20.888 [sec] 20.888017 usecs/op 47874 ops/secsched pipe 从 Ingo Molnar 的 pipe-test-1m.c 移植而来。当初 Ingo 的原始程序是为了测试不同的调度器的性能和公平性的。其工作原理很简单,两个进程互相通过 pipe 拼命地发 1000000 个整数,进程 A 发给 B,同时 B 发给 A。。。因为 A 和 B 互相依赖,因此假如调度器不公平,对 A 比 B 好,那么 A 和 B 整体所需要的时间就会更长。




  1. Mem memcpy



[lm@ovispoly ~]$ perf bench mem memcpy


Running mem/memcpy benchmark…# Copying 1MB Bytes from 0xb75bb008 to 0xb76bc008 … 364.697301 MB/Sec这个是 perf bench 的作者 Hitoshi Mitake 自己写的一个执行 memcpy 的 benchmark。该测试衡量一个拷贝 1M 数据的 memcpy() 函数所花费的时间。我尚不明白该 benchmark 的使用场景。。。或许是一个例子,告诉人们如何利用 perf bench 框架开发更多的 benchmark 吧。



这三个 benchmark 给我们展示了一个可能的未来:不同语言,不同肤色,来自不同背景的人们将来会采用同样的 benchmark,只要有一份 Linux 内核代码即可。



perf lock
锁是内核同步的方法,一旦加了锁,其他准备加锁的内核执行路径就必须等待,降低了并行。因此对于锁进行专门分析应该是调优的一项重要工作。



我运行 perf lock 后得到如下输出:
Name acquired contended total wait (ns) max wait (ns) min



&md->map_lock 396 0 0 0
&(&mm->page_tabl… 309 0 0 0
&(&tty->buf.lock… 218 0 0 0
&ctx->lock 185 0 0 0
key 178 0 0 0
&ctx->lock 132 0 0 0
&tty->output_loc… 126 0 0 0
。。。
&(&object->lock)… 1 0 0 0
&(&object->lock)… 0 0 0 0
&(&object->lock)… 0 0 0 0
&p->cred_guard_m… 0 0 0 0



=== output for debug===



bad: 28, total: 664
bad rate: 4.216867 %
histogram of events caused bad sequence
acquire: 8
acquired: 0
contended: 0
release: 20
对该报表的一些解释如下:



“Name”: 锁的名字,比如 md->map_lock,即定义在 dm.c 结构 mapped_device 中的读写锁。



“acquired”: 该锁被直接获得的次数,即没有其他内核路径拥有该锁的情况下得到该锁的次数。



“contended”冲突的次数,即在准备获得该锁的时候已经被其他人所拥有的情况的出现次数。



“total wait”:为了获得该锁,总共的等待时间。



“max wait”:为了获得该锁,最大的等待时间。



“min wait”:为了获得该锁,最小的等待时间。



目前 perf lock 还处于比较初级的阶段,我想在后续的内核版本中,还应该会有较大的变化,因此当您开始使用 perf lock 时,恐怕已经和本文这里描述的有所不同了。不过我又一次想说的是,命令语法和输出并不是最重要的,重要的是了解什么时候我们需要用这个工具,以及它能帮我们解决怎样的问题。



perf Kmem
Perf Kmem 专门收集内核 slab 分配器的相关事件。比如内存分配,释放等。可以用来研究程序在哪里分配了大量内存,或者在什么地方产生碎片之类的和内存管理相关的问题。



Perf kmem 和 perf lock 实际上都是 perf tracepoint 的特例,您也完全可以用 Perf record – e kmem:* 或者 perf record – e lock:* 来完成同样的功能。但重要的是,这些工具在内部对原始数据进行了汇总和分析,因而能够产生信息更加明确更加有用的统计报表。



perf kmem 的输出结果如下:
[root@ovispoly perf]# ./perf kmem –alloc -l 10 –caller stat
—————————————————————————
Callsite | Total_alloc/Per | Total_req/Per | Hit | Ping-pong| Frag
—————————————————————————
perf_mmap+1a8 | 1024/1024 | 572/572|1 | 0 | 44.141%
seq_open+15| 12384/96 | 8772/68 |129 | 0 | 29.167%
do_maps_open+0| 1008/16 | 756/12 |63 | 0 | 25.000%
…| … | …| … | … | …
__split_vma+50| 88/88 | 88/88 | 1 | 0 | 0.000%
—————————————————————————
Alloc Ptr | Total_alloc/Per | Total_req/Per | Hit |Ping-pong| Frag
—————————————————————————
0xd15d4600|64/64 | 33/33 1 | 0 | 48.438%
0xc461e000|1024/1024 | 572/572 |1 | 0 | 44.141%
0xd15d44c0| 64/64 | 38/38 |1 | 0 | 40.625%
… | … | … | … | … | …
—————————————————————————



SUMMARY


Total bytes requested: 10487021
Total bytes allocated: 10730448
Total bytes wasted on internal fragmentation: 243427
Internal fragmentation: 2.268563%
Cross CPU allocations: 0/246458
该报告有三个部分:根据 Callsite 显示的部分,所谓 Callsite 即内核代码中调用 kmalloc 和 kfree 的地方。比如上图中的函数 perf_mmap,Hit 栏为 1,表示该函数在 record 期间一共调用了 kmalloc 一次,假如如第三行所示数字为 653,则表示函数 sock_alloc_send_pskb 共有 653 次调用 kmalloc 分配内存。



对于第一行 Total_alloc/Per 显示为 1024/1024,第一个值 1024 表示函数 perf_mmap 总共分配的内存大小,Per 表示平均值。



比较有趣的两个参数是 Ping-pong 和 Frag。Frag 比较容易理解,即内部碎片。虽然相对于 Buddy System,Slab 正是要解决内部碎片问题,但 slab 依然存在内部碎片,比如一个 cache 的大小为 1024,但需要分配的数据结构大小为 1022,那么有 2 个字节成为碎片。Frag 即碎片的比例。



Ping-pong 是一种现象,在多 CPU 系统中,多个 CPU 共享的内存会出现”乒乓现象”。一个 CPU 分配内存,其他 CPU 可能访问该内存对象,也可能最终由另外一个 CPU 释放该内存对象。而在多 CPU 系统中,L1 cache 是 per CPU 的,CPU2 修改了内存,那么其他的 CPU 的 cache 都必须更新,这对于性能是一个损失。Perf kmem 在 kfree 事件中判断 CPU 号,如果和 kmalloc 时的不同,则视为一次 ping-pong,理想的情况下 ping-pone 越小越好。Ibm developerworks 上有一篇讲述 oprofile 的文章,其中关于 cache 的调优可以作为很好的参考资料。



后面则有根据被调用地点的显示方式的部分。



最后一个部分是汇总数据,显示总的分配的内存和碎片情况,Cross CPU allocation 即 ping-pong 的汇总。



Perf timechart
很多 perf 命令都是为调试单个程序或者单个目的而设计。有些时候,性能问题并非由单个原因所引起,需要从各个角度一一查看。为此,人们常需要综合利用各种工具,比如 top,vmstat,oprofile 或者 perf。这非常麻烦。



此外,前面介绍的所有工具都是基于命令行的,报告不够直观。更令人气馁的是,一些报告中的参数令人费解。所以人们更愿意拥有一个“傻瓜式”的工具。



以上种种就是 perf timechart 的梦想,其灵感来源于 bootchart。采用“简单”的图形“一目了然”地揭示问题所在。



加注了引号的原因是,perf timechart 虽然有了美观的图形输出,但对于新手,这个图形就好象高科技节目中播放的 DNA 图像一样,不明白那些坐在屏幕前的人是如何从密密麻麻的点和线中找到有用的信息的。但正如受过训练的科学家一样,经过一定的练习,相信您也一定能从下图中找到您想要的。



图 1. perf timechart
图 1. perf timechart
人们说,只有黑白两色是一个人内心压抑的象征,Timechart 用不同的颜色代表不同的含义。上图的最上面一行是图例,告诉人们每种颜色所代表的含义。蓝色表示忙碌,红色表示 idle,灰色表示等待,等等。



接下来是 per-cpu 信息,上图所示的系统中有两个处理器,可以看到在采样期间,两个处理器忙碌程度的概括。蓝色多的地方表示忙碌,因此上图告诉我们,CPU1 很忙,而 CPU2 很闲。



再下面是 per-process 信息,每一个进程有一个 bar。上图中进程 bash 非常忙碌,而其他进程则大多数时间都在等待着什么。Perf 自己在开始的时候很忙,接下来便开始 wait 了。



总之这张图告诉了我们一个系统的概况,但似乎不够详细?



Timechart 可以显示更详细的信息,上图实际上是一个矢量图形 SVG 格式,用 SVG viewer 的放大功能,我们可以将该图的细节部分放大,timechart 的设计理念叫做”infinitely zoomable”。放大之后便可以看到一些更详细的信息,类似网上的 google 地图,找到国家之后,可以放大,看城市的分布,再放大,可以看到某个城市的街道分布,还可以放大以便得到更加详细的信息。



完整的 timechart 图形和颜色解读超出了本文的范围,感兴趣的读者可以到作者 Arjan 的博客上查看。这里仅举一个例子,上图中有一条 bar 对应了 Xorg 进程。多数时候该进程都处于 waiting 状态,只有需要显示什么的时候它才会开始和内核通信,以便进行绘图所需的 IO 操作。



将 Xorg 条目放大的例子图形如下:



图 2. perf timechart detail
图 2. perf timechart detail
上图中需要注意的是几条绿色的短线,表示进程通信,即准备绘图。假如通信的两个进程在图中上下相邻,那么绿线可以连接他们。但如果不相邻,则只会显示如上图所示的被截断的绿色短线。



蓝色部分表示进程忙碌,黄色部分表示该进程的时间片已经用完,但仍处于就绪状态,在等待调度器给予 CPU。



通过这张图,便可以较直观地看到进程在一段时间内的详细行为。



使用 Script 增强 perf 的功能
通常,面对看似复杂,实则较有规律的计算机输出,程序员们总是会用脚本来进行处理:比如给定一个文本文件,想从中找出有多少个数字 0125,人们不会打开文件然后用肉眼去一个一个地数,而是用 grep 命令来进行处理。



perf 的输出虽然是文本格式,但还是不太容易分析和阅读。往往也需要进一步处理,perl 和 python 是目前最强大的两种脚本语言。Tom Zanussi 将 perl 和 python 解析器嵌入到 perf 程序中,从而使得 perf 能够自动执行 perl 或者 python 脚本进一步进行处理,从而为 perf 提供了强大的扩展能力。因为任何人都可以编写新的脚本,对 perf 的原始输出数据进行所需要的进一步处理。这个特性所带来的好处很类似于 plug-in 之于 eclipse。



下面的命令可以查看系统中已经安装的脚本:


perf trace -l


List of available trace scripts:
syscall-counts [comm] system-wide syscall counts
syscall-counts-by-pid [comm] system-wide syscall counts, by pid
failed-syscalls-by-pid [comm] system-wide failed syscalls, by pid 。。。 比如 failed-syscalls 脚本,执行的效果如下: # perf trace record failed-syscalls ^C[ perf record: Woken up 11 times to write data ] [ perf record: Captured and wrote 1.939 MB perf.data (~84709 samples) ]


perf trace report failed-syscalls
perf trace started with Perl script

/root/libexec/perf-core/scripts/perl/failed-syscalls.pl



failed syscalls, by comm:



comm # errors
——————– ———-
firefox 1721
claws-mail 149
konsole 99
X 77
emacs 56
[…]



failed syscalls, by syscall:



syscall # errors
—————————— ———-
sys_read 2042
sys_futex 130
sys_mmap_pgoff 71
sys_access 33
sys_stat64 5
sys_inotify_add_watch 4
[…]
该报表分别按进程和按系统调用显示失败的次数。非常简单明了,而如果通过普通的 perf record 加 perf report 命令,则需要自己手工或者编写脚本来统计这些数字。



系统级性能优化通常包括两个阶段:性能剖析(performance profiling)和代码优化。



性能剖析的目标是寻找性能瓶颈,查找引发性能问题的原因及热点代码。



代码优化的目标是针对具体性能问题而优化代码或编译选项,以改善软件性能。



在性能剖析阶段,需要借助于现有的profiling工具,如perf等。在代码优化阶段往往需要借助开发者的经验,编写简洁高效的代码,甚至在汇编级别合理使用各种指令,合理安排各种指令的执行顺序。



perf是一款Linux性能分析工具。Linux性能计数器是一个新的基于内核的子系统,它提供一个性能分析框架,比如硬件(CPU、PMU(Performance Monitoring Unit))功能和软件(软件计数器、tracepoint)功能。
通过perf,应用程序可以利用PMU、tracepoint和内核中的计数器来进行性能统计。它不但可以分析制定应用程序的性能问题(per thread),也可以用来分析内核的性能问题,当然也可以同事分析应用程序和内核,从而全面理解应用程序中的性能瓶颈。



使用perf,可以分析程序运行期间发生的硬件事件,比如instructions retired、processor clock cycles等;也可以分析软件时间,比如page fault和进程切换。



perf是一款综合性分析工具,大到系统全局性性能,再小到进程线程级别,甚至到函数及汇编级别。



perf提供了十八般武器,可以拿大刀大卸八块,也可以拿起手术刀细致分析。




  1. 背景知识
    1.1 tracepoints
    tracepoints是散落在内核源码中的一些hook,它们可以在特定的代码被执行到时触发,这一特定可以被各种trace/debug工具所使用。



perf将tracepoint产生的时间记录下来,生成报告,通过分析这些报告,条有人缘便可以了解程序运行期间内核的各种细节,对性能症状做出准确的诊断。



这些tracepint的对应的sysfs节点在/sys/kernel/debug/tracing/events目录下。



1.2 硬件特性之cache
内存读写是很快的,但是还是无法和处理器指令执行速度相比。为了从内存中读取指令和数据,处理器需要等待,用处理器时间来衡量,这种等待非常漫长。cache是一种SRAM,读写速度非常快,能和处理器相匹配。因此将常用的数据保存在cache中,处理器便无需等待,从而提高性能。cache的尺寸一般都很小,充分利用cache是软件调优非常重要部分。




  1. 主要关注点
    基于性能分析,可以进行算法优化(空间复杂度和时间复杂度权衡)、代码优化(提高执行速度、减少内存占用)。



评估程序对硬件资源的使用情况,例如各级cache的访问次数、各级cache的丢失次数、流水线停顿周期、前端总线访问次数等。



评估程序对操作系统资源的使用情况,系统调用次数、上下文切换次数、任务迁移次数。



事件可以分为三种:



Hardware Event由PMU部件产生,在特定的条件下探测性能事件是否发生以及发生的次数。比如cache命中。
Software Event是内核产生的事件,分布在各个功能模块中,统计和操作系统相关性能事件。比如进程切换,tick数等。
Tracepoint Event是内核中静态tracepoint所触发的事件,这些tracepoint用来判断程序运行期间内核的行为细节,比如slab分配器的分配次数等。




  1. perf的使用
    perf –help之后可以看到perf的二级命令。



序号 命令 作用
1 annotate 解析perf record生成的perf.data文件,显示被注释的代码。
2 archive 根据数据文件记录的build-id,将所有被采样到的elf文件打包。利用此压缩包,可以再任何机器上分析数据文件中记录的采样数据。
3 bench perf中内置的benchmark,目前包括两套针对调度器和内存管理子系统的benchmark。
4 buildid-cache 管理perf的buildid缓存,每个elf文件都有一个独一无二的buildid。buildid被perf用来关联性能数据与elf文件。
5 buildid-list 列出数据文件中记录的所有buildid。
6 diff 对比两个数据文件的差异。能够给出每个符号(函数)在热点分析上的具体差异。
7 evlist 列出数据文件perf.data中所有性能事件。
8 inject 该工具读取perf record工具记录的事件流,并将其定向到标准输出。在被分析代码中的任何一点,都可以向事件流中注入其它事件。
9 kmem 针对内核内存(slab)子系统进行追踪测量的工具
10 kvm 用来追踪测试运行在KVM虚拟机上的Guest OS。
11 list 列出当前系统支持的所有性能事件。包括硬件性能事件、软件性能事件以及检查点。
12 lock 分析内核中的锁信息,包括锁的争用情况,等待延迟等。
13 mem 内存存取情况
14 record 收集采样信息,并将其记录在数据文件中。随后可通过其它工具对数据文件进行分析。
15 report 读取perf record创建的数据文件,并给出热点分析结果。
16 sched 针对调度器子系统的分析工具。
17 script 执行perl或python写的功能扩展脚本、生成脚本框架、读取数据文件中的数据信息等。
18 stat 执行某个命令,收集特定进程的性能概况,包括CPI、Cache丢失率等。
19 test perf对当前软硬件平台进行健全性测试,可用此工具测试当前的软硬件平台是否能支持perf的所有功能。
20 timechart 针对测试期间系统行为进行可视化的工具
21 top 类似于linux的top命令,对系统性能进行实时分析。
22 trace 关于syscall的工具。
23 probe 用于定义动态检查点。
全局性概况:



perf list查看当前系统支持的性能事件;



perf bench对系统性能进行摸底;



perf test对系统进行健全性测试;



perf stat对全局性能进行统计;



全局细节:



perf top可以实时查看当前系统进程函数占用率情况;



perf probe可以自定义动态事件;



特定功能分析:



perf kmem针对slab子系统性能分析;



perf kvm针对kvm虚拟化分析;



perf lock分析锁性能;



perf mem分析内存slab性能;



perf sched分析内核调度器性能;



perf trace记录系统调用轨迹;



最常用功能perf record,可以系统全局,也可以具体到某个进程,更甚具体到某一进程某一事件;可宏观,也可以很微观。



pref record记录信息到perf.data;



perf report生成报告;



perf diff对两个记录进行diff;



perf evlist列出记录的性能事件;



perf annotate显示perf.data函数代码;



perf archive将相关符号打包,方便在其它机器进行分析;



perf script将perf.data输出可读性文本;



可视化工具perf timechart



perf timechart record记录事件;



perf timechart生成output.svg文档;



3.0 perf引入的overhead
perf测试不可避免的会引入额外负荷,有三种形式:



counting:内核提供计数总结,多是Hardware Event、Software Events、PMU计数等。相关命令perf stat。



sampling:perf将事件数据缓存到一块buffer中,然后异步写入到perf.data文件中。使用perf report等工具进行离线分析。



bpf:Kernel 4.4+新增功能,可以提供更多有效filter和输出总结。



counting引入的额外负荷最小;sampling在某些情况下会引入非常大的负荷;bpf可以有效缩减负荷。



针对sampling,可以通过挂在建立在RAM上的文件系统来有效降低读写I/O引入的负荷。



mkdir /tmpfs



mount -t tmpfs tmpfs /tmpfs



3.1 perf list
perf list不能完全显示所有支持的事件类型,需要sudo perf list。



同时还可以显示特定模块支持的perf事件:hw/cache/pmu都是硬件相关的;tracepoint基于内核的ftrace;sw实际上是内核计数器。



hw/hardware显示支持的硬件事件相关,如:



al@al-System-Product-Name:~/perf$ sudo perf list hardware



List of pre-defined events (to be used in -e):



branch-instructions OR branches [Hardware event]
branch-misses [Hardware event]
cache-misses [Hardware event]
cache-references [Hardware event]
cpu-cycles OR cycles [Hardware event]
instructions [Hardware event]
stalled-cycles-backend OR idle-cycles-backend [Hardware event]
stalled-cycles-frontend OR idle-cycles-frontend [Hardware event]
sw/software显示支持的软件事件列表:



al@al-System-Product-Name:~/perf$ sudo perf list sw



List of pre-defined events (to be used in -e):



alignment-faults [Software event]
bpf-output [Software event]
context-switches OR cs [Software event]
cpu-clock [Software event]
cpu-migrations OR migrations [Software event]
dummy [Software event]
emulation-faults [Software event]
major-faults [Software event]
minor-faults [Software event]
page-faults OR faults [Software event]
task-clock [Software event]
cache/hwcache显示硬件cache相关事件列表:



al@al-System-Product-Name:~/perf$ sudo perf list cache



List of pre-defined events (to be used in -e):



L1-dcache-load-misses [Hardware cache event]
L1-dcache-loads [Hardware cache event]
L1-dcache-prefetch-misses [Hardware cache event]
L1-dcache-prefetches [Hardware cache event]
L1-icache-load-misses [Hardware cache event]
L1-icache-loads [Hardware cache event]
L1-icache-prefetches [Hardware cache event]
LLC-load-misses [Hardware cache event]
LLC-loads [Hardware cache event]
LLC-stores [Hardware cache event]
branch-load-misses [Hardware cache event]
branch-loads [Hardware cache event]
dTLB-load-misses [Hardware cache event]
dTLB-loads [Hardware cache event]
iTLB-load-misses [Hardware cache event]
iTLB-loads [Hardware cache event]
node-load-misses [Hardware cache event]
node-loads [Hardware cache event]
pmu显示支持的PMU事件列表:



al@al-System-Product-Name:~/perf$ sudo perf list pmu



List of pre-defined events (to be used in -e):



branch-instructions OR cpu/branch-instructions/ [Kernel PMU event]
branch-misses OR cpu/branch-misses/ [Kernel PMU event]
cache-misses OR cpu/cache-misses/ [Kernel PMU event]
cache-references OR cpu/cache-references/ [Kernel PMU event]
cpu-cycles OR cpu/cpu-cycles/ [Kernel PMU event]
instructions OR cpu/instructions/ [Kernel PMU event]
msr/aperf/ [Kernel PMU event]
msr/mperf/ [Kernel PMU event]
msr/tsc/ [Kernel PMU event]
stalled-cycles-backend OR cpu/stalled-cycles-backend/ [Kernel PMU event]
stalled-cycles-frontend OR cpu/stalled-cycles-frontend/ [Kernel PMU event]
tracepoint显示支持的所有tracepoint列表,这个列表就比较庞大:



al@al-System-Product-Name:~/perf$ sudo perf list tracepoint



List of pre-defined events (to be used in -e):



alarmtimer:alarmtimer_cancel [Tracepoint event]
alarmtimer:alarmtimer_fired [Tracepoint event]
alarmtimer:alarmtimer_start [Tracepoint event]
alarmtimer:alarmtimer_suspend [Tracepoint event]
block:block_bio_backmerge [Tracepoint event]
block:block_bio_bounce [Tracepoint event]
block:block_bio_complete [Tracepoint event]
block:block_bio_frontmerge [Tracepoint event]
block:block_bio_queue [Tracepoint event]





3.2 perf top
默认情况下perf top是无法显示信息的,需要sudo perf top或者echo -1 > /proc/sys/kernel/perf_event_paranoid(在Ubuntu16.04,还需要echo 0 > /proc/sys/kernel/kptr_restrict)。



即可以正常显示perf top如下:



第一列:符号引发的性能事件的比例,指占用的cpu周期比例。



第二列:符号所在的DSO(Dynamic Shared Object),可以是应用程序、内核、动态链接库、模块。



第三列:DSO的类型。[.]表示此符号属于用户态的ELF文件,包括可执行文件与动态链接库;[k]表述此符号属于内核或模块。



第四列:符号名。有些符号不能解析为函数名,只能用地址表示。



image



关于perf top界面常用命令如下:



h:显示帮助,即可显示详细的帮助信息。



UP/DOWN/PGUP/PGDN/SPACE:上下和翻页。



a:annotate current symbol,注解当前符号。能够给出汇编语言的注解,给出各条指令的采样率。



d:过滤掉所有不属于此DSO的符号。非常方便查看同一类别的符号。



P:将当前信息保存到perf.hist.N中。



perf top常用选项有:



-e :指明要分析的性能事件。



-p :Profile events on existing Process ID (comma sperated list). 仅分析目标进程及其创建的线程。



-k :Path to vmlinux. Required for annotation functionality. 带符号表的内核映像所在的路径。



-K:不显示属于内核或模块的符号。



-U:不显示属于用户态程序的符号。



-d :界面的刷新周期,默认为2s,因为perf top默认每2s从mmap的内存区域读取一次性能数据。



-g:得到函数的调用关系图。



perf top –call-graph [fractal],路径概率为相对值,加起来为100%,调用顺序为从下往上。



perf top –call-graph graph,路径概率为绝对值,加起来为该函数的热度。



image



3.3 perf stat
perf stat用于运行指令,并分析其统计结果。虽然perf top也可以指定pid,但是必须先启动应用才能查看信息。



perf stat能完整统计应用整个生命周期的信息。



命令格式为:



perf stat [-e | --event=EVENT] [-a]
perf stat [-e | --event=EVENT] [-a] — []



下面简单看一下perf stat 的输出:



al@al-System-Product-Name:~/perf$ sudo perf stat
^C
Performance counter stats for ‘system wide’:



  40904.820871      cpu-clock (msec)          #    5.000 CPUs utilized         
18,132 context-switches # 0.443 K/sec
1,053 cpu-migrations # 0.026 K/sec
2,420 page-faults # 0.059 K/sec
3,958,376,712 cycles # 0.097 GHz (49.99%)
574,598,403 stalled-cycles-frontend # 14.52% frontend cycles idle (49.98%)
9,392,982,910 stalled-cycles-backend # 237.29% backend cycles idle (50.00%)
1,653,185,883 instructions # 0.42 insn per cycle
# 5.68 stalled cycles per insn (50.01%)
237,061,366 branches # 5.795 M/sec (50.02%)
18,333,168 branch-misses # 7.73% of all branches (50.00%)

8.181521203 seconds time elapsed 输出解释如下:


cpu-clock:任务真正占用的处理器时间,单位为ms。CPUs utilized = task-clock / time elapsed,CPU的占用率。



context-switches:程序在运行过程中上下文的切换次数。



CPU-migrations:程序在运行过程中发生的处理器迁移次数。Linux为了维持多个处理器的负载均衡,在特定条件下会将某个任务从一个CPU迁移到另一个CPU。



CPU迁移和上下文切换:发生上下文切换不一定会发生CPU迁移,而发生CPU迁移时肯定会发生上下文切换。发生上下文切换有可能只是把上下文从当前CPU中换出,下一次调度器还是将进程安排在这个CPU上执行。



page-faults:缺页异常的次数。当应用程序请求的页面尚未建立、请求的页面不在内存中,或者请求的页面虽然在内存中,但物理地址和虚拟地址的映射关系尚未建立时,都会触发一次缺页异常。另外TLB不命中,页面访问权限不匹配等情况也会触发缺页异常。



cycles:消耗的处理器周期数。如果把被ls使用的cpu cycles看成是一个处理器的,那么它的主频为2.486GHz。可以用cycles / task-clock算出。



stalled-cycles-frontend:指令读取或解码的质量步骤,未能按理想状态发挥并行左右,发生停滞的时钟周期。



stalled-cycles-backend:指令执行步骤,发生停滞的时钟周期。



instructions:执行了多少条指令。IPC为平均每个cpu cycle执行了多少条指令。



branches:遇到的分支指令数。branch-misses是预测错误的分支指令数。



其他常用参数
-a, –all-cpus 显示所有CPU上的统计信息
-C, –cpu 显示指定CPU的统计信息
-c, --scale scale/normalize counters
-D, --delay ms to wait before starting measurement after program start
-d, --detailed detailed run - start a lot of events
-e, --event event selector. use 'perf list' to list available events
-G, --cgroup monitor event in cgroup name only
-g, --group put the counters into a counter group
-I, --interval-print
print counts at regular interval in ms (>= 10)
-i, --no-inherit child tasks do not inherit counters
-n, --null null run - dont start any counters
-o, --output 输出统计信息到文件
-p, --pid stat events on existing process id
-r, --repeat repeat command and print average + stddev (max: 100, forever: 0)
-S, --sync call sync() before starting a run
-t, --tid stat events on existing thread id
...



示例
前面统计程序的示例,下面看一下统计CPU信息的示例:



执行sudo perf stat -C 0,统计CPU 0的信息。想要停止后,按下Ctrl+C终止。可以看到统计项一样,只是统计对象变了。



al@al-System-Product-Name:~/perf$ sudo perf stat -C 0
^C
Performance counter stats for ‘CPU(s) 0’:



   2517.107315      cpu-clock (msec)          #    1.000 CPUs utilized         
2,941 context-switches # 0.001 M/sec
109 cpu-migrations # 0.043 K/sec
38 page-faults # 0.015 K/sec
644,094,340 cycles # 0.256 GHz (49.94%)
70,425,076 stalled-cycles-frontend # 10.93% frontend cycles idle (49.94%)
965,270,543 stalled-cycles-backend # 149.86% backend cycles idle (49.94%)
623,284,864 instructions # 0.97 insn per cycle
# 1.55 stalled cycles per insn (50.06%)
65,658,190 branches # 26.085 M/sec (50.06%)
3,276,104 branch-misses # 4.99% of all branches (50.06%)

2.516996126 seconds time elapsed 如果需要统计更多的项,需要使用-e,如:


perf stat -e task-clock,context-switches,cpu-migrations,page-faults,cycles,stalled-cycles-frontend,stalled-cycles-backend,instructions,branches,branch-misses,L1-dcache-loads,L1-dcache-load-misses,LLC-loads,LLC-load-misses,dTLB-loads,dTLB-load-misses ls
结果如下,关注的特殊项也纳入统计。



al@al-System-Product-Name:~/perf$ sudo perf stat -e task-clock,context-switches,cpu-migrations,page-faults,cycles,stalled-cycles-frontend,stalled-cycles-backend,instructions,branches,branch-misses,L1-dcache-loads,L1-dcache-load-misses,LLC-loads,LLC-load-misses,dTLB-loads,dTLB-load-misses ls
Performance counter stats for ‘ls’:



      2.319422      task-clock (msec)         #    0.719 CPUs utilized         
0 context-switches # 0.000 K/sec
0 cpu-migrations # 0.000 K/sec
89 page-faults # 0.038 M/sec
2,142,386 cycles # 0.924 GHz
659,800 stalled-cycles-frontend # 30.80% frontend cycles idle
725,343 stalled-cycles-backend # 33.86% backend cycles idle
1,344,518 instructions # 0.63 insn per cycle
# 0.54 stalled cycles per insn
<not counted> branches
<not counted> branch-misses
<not counted> L1-dcache-loads
<not counted> L1-dcache-load-misses
<not counted> LLC-loads
<not counted> LLC-load-misses
<not counted> dTLB-loads
<not counted> dTLB-load-misses

0.003227507 seconds time elapsed


3.4 perf bench
perf bench作为benchmark工具的通用框架,包含sched/mem/numa/futex等子系统,all可以指定所有。



perf bench可用于评估系统sched/mem等特定性能。



perf bench sched:调度器和IPC机制。包含messaging和pipe两个功能。



perf bench mem:内存存取性能。包含memcpy和memset两个功能。



perf bench numa:NUMA架构的调度和内存处理性能。包含mem功能。



perf bench futex:futex压力测试。包含hash/wake/wake-parallel/requeue/lock-pi功能。



perf bench all:所有bench测试的集合



3.4.1 perf bench sched all
测试messaging和pipi两部分性能。



3.4.1.1 sched messaging评估进程调度和核间通信
sched message 是从经典的测试程序 hackbench 移植而来,用来衡量调度器的性能,overhead 以及可扩展性。



该 benchmark 启动 N 个 reader/sender 进程或线程对,通过 IPC(socket 或者 pipe) 进行并发的读写。一般人们将 N 不断加大来衡量调度器的可扩展性。



sched message 的用法及用途和 hackbench 一样,可以通过修改参数进行不同目的测试:



-g, –group Specify number of groups



-l, –nr_loops Specify the number of loops to run (default: 100)



-p, –pipe Use pipe() instead of socketpair()



-t, –thread Be multi thread instead of multi process



测试结果:



al@al-System-Product-Name:~/perf$ perf bench sched all


Running sched/messaging benchmark…


20 sender and receiver processes per group


10 groups == 400 processes run



 Total time: 0.173 [sec]


Running sched/pipe benchmark…


Executed 1000000 pipe operations between two processes



 Total time: 12.233 [sec]

12.233170 usecs/op
81744 ops/sec 使用pipe()和socketpair()对测试影响:



  1. perf bench sched messaging



Running ‘sched/messaging’ benchmark:


20 sender and receiver processes per group


10 groups == 400 processes run



 Total time: 0.176 [sec]



  1. perf bench sched messaging -p



Running ‘sched/messaging’ benchmark:


20 sender and receiver processes per group


10 groups == 400 processes run



 Total time: 0.093 [sec] 可见socketpair()性能要明显低于pipe()。


3.4.1.2 sched pipe评估pipe性能
sched pipe 从 Ingo Molnar 的 pipe-test-1m.c 移植而来。当初 Ingo 的原始程序是为了测试不同的调度器的性能和公平性的。



其工作原理很简单,两个进程互相通过 pipe 拼命地发 1000000 个整数,进程 A 发给 B,同时 B 发给 A。因为 A 和 B 互相依赖,因此假如调度器不公平,对 A 比 B 好,那么 A 和 B 整体所需要的时间就会更长。



al@al-System-Product-Name:~/perf$ perf bench sched pipe


Running ‘sched/pipe’ benchmark:


Executed 1000000 pipe operations between two processes



 Total time: 12.240 [sec]

12.240411 usecs/op
81696 ops/sec


3.4.2 perf bench mem all
该测试衡量 不同版本的memcpy/memset/ 函数处理一个 1M 数据的所花费的时间,转换成吞吐率。



al@al-System-Product-Name:~/perf$ perf bench mem all


Running mem/memcpy benchmark…


function ‘default’ (Default memcpy() provided by glibc)


Copying 1MB bytes …



   1.236155 GB/sec.


..



3.4.3 perf bench futex
Futex是一种用户态和内核态混合机制,所以需要两个部分合作完成,linux上提供了sys_futex系统调用,对进程竞争情况下的同步处理提供支持。



所有的futex同步操作都应该从用户空间开始,首先创建一个futex同步变量,也就是位于共享内存的一个整型计数器。



当进程尝试持有锁或者要进入互斥区的时候,对futex执行”down”操作,即原子性的给futex同步变量减1。如果同步变量变为0,则没有竞争发生, 进程照常执行。



如果同步变量是个负数,则意味着有竞争发生,需要调用futex系统调用的futex_wait操作休眠当前进程。



当进程释放锁或 者要离开互斥区的时候,对futex进行”up”操作,即原子性的给futex同步变量加1。如果同步变量由0变成1,则没有竞争发生,进程照常执行。



如果加之前同步变量是负数,则意味着有竞争发生,需要调用futex系统调用的futex_wake操作唤醒一个或者多个等待进程。



al@al-System-Product-Name:~/perf$ perf bench futex all


Running futex/hash benchmark…


Run summary [PID 3806]: 5 threads, each operating on 1024 [private] futexes for 10 secs.



[thread 0] futexes: 0x4003d20 … 0x4004d1c [ 4635648 ops/sec ]
[thread 1] futexes: 0x4004d30 … 0x4005d2c [ 4611072 ops/sec ]
[thread 2] futexes: 0x4005e70 … 0x4006e6c [ 4254515 ops/sec ]
[thread 3] futexes: 0x4006fb0 … 0x4007fac [ 4559360 ops/sec ]
[thread 4] futexes: 0x40080f0 … 0x40090ec [ 4636262 ops/sec ]



Averaged 4539371 operations/sec (+- 1.60%), total secs = 10



Running futex/wake benchmark…


Run summary [PID 3806]: blocking on 5 threads (at [private] futex 0x96b52c), waking up 1 at a time.





3.4 perf record
运行一个命令,并将其数据保存到perf.data中。随后,可以使用perf report进行分析。



perf record和perf report可以更精确的分析一个应用,perf record可以精确到函数级别。并且在函数里面混合显示汇编语言和代码。



创建一个fork.c文件用于测试:



复制代码
#include



void test_little(void)
{
int i,j;



for(i = 0; i < 30000000; i++)
j=i;
}



void test_mdedium(void)
{
int i,j;



for(i = 0; i < 60000000; i++)
j=i;
}



void test_high(void)
{
int i,j;



for(i = 0; i < 90000000; i++)
j=i;
}



void test_hi(void)
{
int i,j;



for(i = 0; i < 120000000; i++)
j=i;
}



int main(void)
{
int i, pid, result;



for(i = 0; i<2; i++) {
result = fork();
if(result>0)
printf(“i=%d parent parent=%d current=%d child=%d\n”, i, getppid(), getpid(), result);
else
printf(“i=%d child parent=%d current=%d\n”, i, getppid(), getpid());



if(i==0)
{
test_little();
sleep(1);
} else {
test_mdedium();
sleep(1);
} }


pid = wait(NULL);
test_high();
printf(“pid=%d wait=%d\n”, getpid(), pid);
sleep(1);
pid = wait(NULL);
test_hi();
printf(“pid=%d wait=%d\n”, getpid(), pid);
return 0;
}
复制代码



编译fork.c文件gcc fork.c -o fork-g -O0,同时可以使用此方法分析是否选择编译优化产生的结果。-g是只能callgraph功能,-O0是关闭优化。



常用选项
-e record指定PMU事件
–filter event事件过滤器
-a 录取所有CPU的事件
-p 录取指定pid进程的事件
-o 指定录取保存数据的文件名
-g 使能函数调用图功能
-C 录取指定CPU的事件



sudo perf record -a -g ./fork:会在当前目录生成perf.data文件。



sudo perf report –call-graph none结果如下,后面结合perf timechart分析.



image



上图看上去比较乱,如果想只看fork产生的信息:



sudo perf report –call-graph none -c fork



可以看出只显示了fork程序的相关符号及其占用率。



image



3.5 perf report
解析perf record产生的数据,并给出分析结果。



常用参数:
-i 导入的数据文件名称,如果没有则默认为perf.data



-g 生成函数调用关系图,此时内核要打开CONFIG_KALLSYMS;用户空间库或者执行文件需要带符号信息(not stripped),编译选项需要加上-g。



–sort 从更高层面显示分类统计信息,比如: pid, comm, dso, symbol, parent, cpu,socket, srcline, weight, local_weight.



执行sudo perf report -i perf.data,可以看出main函数所占百分比,以及funcA和funcB分别所占百分比。



在funcB执行过程中,还产生了apic timer,占用了一部分cpu资源。除此之外,占比基本上是1:10。



funcA和funcB的占比,基本符合预期。那么进入longa,分析一下热点。



在C和汇编混合显示界面,可以看出for循环占用了69.92%,j=i赋值占用了30.08%。



根据之上描述,可以看出top适合监控整个系统的性能,stat比较适合单个程序的性能分析,record/report更适合对程序进行更细粒度的分析。



注意点:



在使用perf report -g的时候,可能会提示Failed to open /lib/libpthread-0.9.33.2.so, continuing without symbols。



这时候通过file xxx查看,如果提示xxxx stripped表示此文件不包含符号信息,需要xxxx not stripped文件。



3.6 perf timechart
perf timechart是将之前的各种统计信息图形化的一个工具。



perf timechart record



perf timechart用于将perf.data转换成SVG格式的文件,SVG可以通过Inkscape或者浏览器打开。



perf timechart record可以指定特定类型的事件:



-P:记录power相关事件



-T:记录任务相关事件



-I:记录io相关事件



-g:记录函数调用关系



perf timechart用于将perf timechart record录取的perf.data转换成output.svg。



-w调整输出的svg文件长度,可以查看更多细节。



-p可以指定只查看某些进程输出,使用方式:sudo perf timechart -p test1 -p thermald



-o 指定输出文件名



-i 指定待解析的文件名



-w 输出SVG文件宽度



-P 只显示power相关事件图标



-T , –tasks-only 显示task信息,不显示处理器信息



-p 显示指定进程名称或者PID显示



–symfs= 指定系统符号表路径



-t, –topology 根据拓扑结构对CPU进行分类










–highlight=<duration_nsecs task_name> 对运行超过特定时间的task高亮


当线程太多影响svg解析速度的时候,可以通过-p指定特定线程进行分析。如果需要几个线程,每个线程采用-p xxx。



sudo perf timechart record -T ./fork && sudo perf timechart –p fork



结果如下,可以看到相关task的名称,开始时间/结束时间,每个时间点的状态(Running/Idle/Deeper Idle/Deepest Idle/Sleeping/Waiting for Cpu /Blocked on IO)。



3.6.1 结合perf timechart和perf report分析函数占比
由perf report可知test_little、test_medium、test_high、test_hi四个函数占比分别为3.84%、12.01%、22.99%、30.43%。



有代码可知如果以test_little为1单位,那么test_medium就为2单位,test_high为3单位,test_hi为4单位。



四个函数执行次数分别为2、4、4、4,所以四个函数每个单位对应CPU占比为:



test_little - 3.84%/2=1.9%



test_medium - 12.01%/4/2=1.5%



test_high - 22.99/4/3=1.9%



test_hi - 30.43%/4/4=1.9%



基本上符合预期。



记录IO事件,可以看到按应用分类的,Disk/Network/Sync/Poll/Error信息。以及每个应用数据吞吐量。



sudo perf timechart record -I && sudo perf timechart -w 1800。



记录Power状态事件,可以看到不同之处在于Idle之类的状态里面还有细分C/C2更详细的显示Power状态。



sudo perf timechart record -I && sudo perf timechart -w 1800



3.7 perf script
用于读取perf record保存的裸trace数据。



使用方法:



   perf script [<options>]
perf script [<options>] record <script> [<record-options>] <command>
perf script [<options>] report <script> [script-args]
perf script [<options>] <script> <required-script-args> [<record-options>] <command>
perf script [<options>] <top-script> [script-args] 还可以编写perl或者python脚本进行数据分析。


3.8 perf lock
3.8.1 perf lock内核配置
要使用此功能,内核需要编译选项的支持:CONFIG_LOCKDEP、CONFIG_LOCK_STAT。



CONFIG_LOCKDEP defines acquired and release events.



CONFIG_LOCK_STAT defines contended and acquired lock events.



CONFIG_LOCKDEP=y



CONFIG_LOCK_STAT=y



3.8.2 perf lock使用
分析内核锁统计信息。



锁是内核用于同步的方法,一旦加了锁,其他加锁的内核执行路径就必须等待,降低了并行。同时,如果加锁不正确还会造成死锁。



因此对于内核锁进行分析是一项重要的调优工作。



perf lock record:抓取执行命令的lock事件信息到perf.data中



perf lock report:产生统计报告



perf lock script:显示原始lock事件



perf lock info:



-k :sorting key,默认为acquired,还可以按contended、wait_total、wait_max和wait_min来排序。



Name:内核锁的名字。



aquired:该锁被直接获得的次数,因为没有其它内核路径占用该锁,此时不用等待。



contended:该锁等待后获得的次数,此时被其它内核路径占用,需要等待。



total wait:为了获得该锁,总共的等待时间。



max wait:为了获得该锁,最大的等待时间。



min wait:为了获得该锁,最小的等待时间。



3.9 perf kmem



3.9.1 perf kmem介绍
perf kmem用于跟踪测量内核slab分配器事件信息。
比如内存分配/释放等。可以用来研究程序在哪里分配了大量内存,或者在什么地方产生碎片之类的和内存管理相关的问题。



perf kmem和perf lock实际上都是perf tracepoint的子类,等同于perf record -e kmem:和perf record -e lock:



但是这些工具在内部队员是数据进行了慧聪和分析,因此统计报表更具可读性。



perf kmem record:抓取命令的内核slab分配器事件



perf kmem stat:生成内核slab分配器统计信息



选项:



–caller 显示每个调用点统计信息



--alloc   显示每次内存分配事件


-s <key[,key2…]>, –sort=<key[,key2…]>



       Sort the output (default: frag,hit,bytes for slab and bytes,hit for page). Available sort keys are ptr, callsite, bytes, hit, pingpong, frag for slab and page, callsite, bytes, hit, order, migtype, gfp for page.
This option should be preceded by one of the mode selection options - i.e. --slab, --page, --alloc and/or --caller.


-l , 只显示固定行数



--raw-ip

Print raw ip instead of symbol

--slab 分析slab分配器事件

--page 分析页分配事件

--live

Show live page stat. The perf kmem shows total allocation stat by default, but this option shows live (currently allocated) pages instead. (This option works with --page option only)


3.9.2 perf kmem使用
sudo perf kmem record ls
sudo perf kmem stat只显示概要统计信息:



SUMMARY (SLAB allocator)


Total bytes requested: 368,589
Total bytes allocated: 369,424
Total bytes wasted on internal fragmentation: 835
Internal fragmentation: 0.226028%
Cross CPU allocations: 0/2,256
sudo perf kmem –alloc –caller –slab stat显示了更加详细的分类信息:





Callsite | Total_alloc/Per | Total_req/Per | Hit | Ping-pong | Frag
———————————————————————————————————
proc_reg_open+32 | 64/64 | 40/40 | 1 | 0 | 37.500%
seq_open+34 | 384/192 | 272/136 | 2 | 0 | 29.167%
apparmor_file_alloc_security+5c | 608/32 | 456/24 | 19 | 1 | 25.000%
ext4_readdir+8bd | 64/64 | 48/48 | 1 | 0 | 25.000%
ext4_htree_store_dirent+3e | 896/68 | 770/59 | 13 | 0 | 14.062%
load_elf_phdrs+64 | 1024/512 | 896/448 | 2 | 0 | 12.500%
load_elf_binary+222 | 32/32 | 28/28 | 1 | 0 | 12.500%
anon_vma_prepare+11b | 1280/80 | 1152/72 | 16 | 0 | 10.000%
inotify_handle_event+75 | 73664/64 | 66758/58 | 1151 | 0 | 9.375%
do_execveat_common.isra.33+e5 | 2048/256 | 1920/240 | 8 | 1 | 6.250%
… | … | … | … | … | …

———————————————————————————————————





Alloc Ptr | Total_alloc/Per | Total_req/Per | Hit | Ping-pong | Frag
———————————————————————————————————
0xffff8800ca4d86c0 | 192/192 | 136/136 | 1 | 0 | 29.167%
0xffff8801ea05aa80 | 192/192 | 136/136 | 1 | 0 | 29.167%
0xffff8801f6ad6540 | 96/96 | 68/68 | 1 | 0 | 29.167%
0xffff8801f6ad6f00 | 96/96 | 68/68 | 1 | 0 | 29.167%
0xffff880214e65e80 | 96/32 | 72/24 | 3 | 0 | 25.000%
0xffff8801f45ddac0 | 64/64 | 48/48 | 1 | 0 | 25.000%
0xffff8800ac4093c0 | 32/32 | 24/24 | 1 | 1 | 25.000%
0xffff8800af5a4260 | 32/32 | 24/24 | 1 | 0 | 25.000%
0xffff880214e651e0 | 32/32 | 24/24 | 1 | 0 | 25.000%
0xffff880214e65220 | 32/32 | 24/24 | 1 | 0 | 25.000%
0xffff880214e654e0 | 32/32 | 24/24 | 1 | 0 | 25.000%
———————————————————————————————————



SUMMARY (SLAB allocator)


Total bytes requested: 409,260
Total bytes allocated: 417,008
Total bytes wasted on internal fragmentation: 7,748
Internal fragmentation: 1.857998%
Cross CPU allocations: 0/2,833



该报告有三个部分:根据 Callsite 显示的部分,所谓 Callsite 即内核代码中调用 kmalloc 和 kfree 的地方。



比如上图中的函数proc_reg_open,Hit 栏为 1,表示该函数在 record 期间一共调用了 kmalloc 一次。



对于第一行 Total_alloc/Per 显示为 1024/1024,第一个值 1024 表示函数 proc_reg_open 总共分配的内存大小,Per 表示平均值。



比较有趣的两个参数是 Ping-pong 和 Frag。Frag 比较容易理解,即内部碎片。虽然相对于 Buddy System,Slab 正是要解决内部碎片问题,但 slab 依然存在内部碎片,比如一个 cache 的大小为 1024,但需要分配的数据结构大小为 1022,那么有 2 个字节成为碎片。Frag 即碎片的比例。



Ping-pong 是一种现象,在多 CPU 系统中,多个 CPU 共享的内存会出现”乒乓现象”。一个 CPU 分配内存,其他 CPU 可能访问该内存对象,也可能最终由另外一个 CPU 释放该内存对象。而在多 CPU 系统中,L1 cache 是 per CPU 的,CPU2 修改了内存,那么其他的 CPU 的 cache 都必须更新,这对于性能是一个损失。Perf kmem 在 kfree 事件中判断 CPU 号,如果和 kmalloc 时的不同,则视为一次 ping-pong,理想的情况下 ping-pong 越小越好。Ibm developerworks 上有一篇讲述 oprofile 的文章,其中关于 cache 的调优可以作为很好的参考资料。



Callsite:内核代码中调用kmalloc和kfree的地方。



Total_alloc/Per:总共分配的内存大小,平均每次分配的内存大小。



Total_req/Per:总共请求的内存大小,平均每次请求的内存大小。



Hit:调用的次数。



Ping-pong:kmalloc和kfree不被同一个CPU执行时的次数,这会导致cache效率降低。



Frag:碎片所占的百分比,碎片 = 分配的内存 - 请求的内存,这部分是浪费的。



有使用–alloc选项,还会看到Alloc Ptr,即所分配内存的地址。



后面则有根据被调用地点的显示方式的部分。



最后一个部分是汇总数据,显示总的分配的内存和碎片情况,Cross CPU allocation 即 ping-pong 的汇总。



要分析–page事件,需要在record的时候加上–page选项。sudo perf kmem record –page ls,使用sudo perf kmem stat –page查看结果:



0xee318 [0x8]: failed to process type: 68
error during process events: -22



3.10 perf sched
perf sched专门用于跟踪/测量调度器,包括延时等。



perf sched record :录制测试过程中的调度事件



perf sched latency:报告线程调度延时和其他调度相关属性



perf sched script:查看执行过程中详细的trace信息



perf sched replay:回放perf sched record录制的执行过程



perf sched map:用字符表示打印上下文切换



执行sudo perf sched record ls后,通过不同方式查看结果。



sudo perf sched latency,可以看到ls进程的Average delay/Maximum delay时间。各个 column 的含义如下: Task: 进程的名字和 pid Runtime: 实际运行时间 Switches: 进程切换的次数 Average delay: 平均的调度延迟 Maximum delay: 最大延迟



这里最值得人们关注的是 Maximum delay,一般从这里可以看到对交互性影响最大的特性:调度延迟,如果调度延迟比较大,那么用户就会感受到视频或者音频断断续续的。





Task | Runtime ms | Switches | Average delay ms | Maximum delay ms | Maximum delay at |
—————————————————————————————————————–
/usr/bin/termin:2511 | 0.163 ms | 1 | avg: 0.019 ms | max: 0.019 ms | max at: 5398.723467 s
ls:7806 | 1.175 ms | 1 | avg: 0.017 ms | max: 0.017 ms | max at: 5398.722333 s
kworker/u12:3:7064 | 0.029 ms | 1 | avg: 0.011 ms | max: 0.011 ms | max at: 5398.723434 s
migration/4:27 | 0.000 ms | 1 | avg: 0.007 ms | max: 0.007 ms | max at: 5398.722575 s
perf:7801 | 1.256 ms | 1 | avg: 0.002 ms | max: 0.002 ms | max at: 5398.723509 s
—————————————————————————————————————–
TOTAL: | 2.623 ms | 5 |
—————————————————



sudo perf sched script能看到更详细的sched信息,包括sched_wakeup/sched_switch等等。每一列的含义依次是:进程名/pid/CPU ID/时间戳。



        perf  7801 [002]  5398.722314: sched:sched_stat_sleep: comm=perf pid=7806 delay=110095391 [ns]
perf 7801 [002] 5398.722316: sched:sched_wakeup: comm=perf pid=7806 prio=120 target_cpu=004
swapper 0 [004] 5398.722328: sched:sched_stat_wait: comm=perf pid=7806 delay=0 [ns]
swapper 0 [004] 5398.722333: sched:sched_switch: prev_comm=swapper/4 prev_pid=0 prev_prio=120 prev_state=R ==> next_comm=perf next_pid=7806 next_prio=120
perf 7801 [002] 5398.722363: sched:sched_stat_runtime: comm=perf pid=7801 runtime=1255788 [ns] vruntime=3027478102 [ns]
perf 7801 [002] 5398.722364: sched:sched_switch: prev_comm=perf prev_pid=7801 prev_prio=120 prev_state=S ==> next_comm=swapper/2 next_pid=0 next_prio=120
perf 7806 [004] 5398.722568: sched:sched_wakeup: comm=migration/4 pid=27 prio=0 target_cpu=004
perf 7806 [004] 5398.722571: sched:sched_stat_runtime: comm=perf pid=7806 runtime=254732 [ns] vruntime=1979611107 [ns]
perf 7806 [004] 5398.722575: sched:sched_switch: prev_comm=perf prev_pid=7806 prev_prio=120 prev_state=R+ ==> next_comm=migration/4 next_pid=27 next_prio=0
migration/4 27 [004] 5398.722582: sched:sched_stat_wait: comm=perf pid=7806 delay=13914 [ns]
migration/4 27 [004] 5398.722586: sched:sched_migrate_task: comm=perf pid=7806 prio=120 orig_cpu=4 dest_cpu=2
swapper 0 [002] 5398.722595: sched:sched_stat_wait: comm=perf pid=7806 delay=0 [ns]
swapper 0 [002] 5398.722596: sched:sched_switch: prev_comm=swapper/2 prev_pid=0 prev_prio=120 prev_state=R ==> next_comm=perf next_pid=7806 next_prio=120
migration/4 27 [004] 5398.722611: sched:sched_switch: prev_comm=migration/4 prev_pid=27 prev_prio=0 prev_state=S ==> next_comm=swapper/4 next_pid=0 next_prio=120
ls 7806 [002] 5398.723421: sched:sched_stat_sleep: comm=kworker/u12:3 pid=7064 delay=1226675 [ns]
ls 7806 [002] 5398.723423: sched:sched_wakeup: comm=kworker/u12:3 pid=7064 prio=120 target_cpu=003
swapper 0 [003] 5398.723432: sched:sched_stat_wait: comm=kworker/u12:3 pid=7064 delay=0 [ns]
swapper 0 [003] 5398.723434: sched:sched_switch: prev_comm=swapper/3 prev_pid=0 prev_prio=120 prev_state=R ==> next_comm=kworker/u12:3 next_pid=7064 next_prio=120 kworker/u12:3 7064 [003] 5398.723441: sched:sched_stat_sleep: comm=/usr/bin/termin pid=2511 delay=80833386 [ns] kworker/u12:3 7064 [003] 5398.723447: sched:sched_wakeup: comm=/usr/bin/termin pid=2511 prio=120 target_cpu=004 kworker/u12:3 7064 [003] 5398.723449: sched:sched_stat_runtime: comm=kworker/u12:3 pid=7064 runtime=29315 [ns] vruntime=846439549943 [ns] kworker/u12:3 7064 [003] 5398.723451: sched:sched_switch: prev_comm=kworker/u12:3 prev_pid=7064 prev_prio=120 prev_state=S ==> next_comm=swapper/3 next_pid=0 next_prio=120
swapper 0 [004] 5398.723462: sched:sched_stat_wait: comm=/usr/bin/termin pid=2511 delay=0 [ns]
swapper 0 [004] 5398.723466: sched:sched_switch: prev_comm=swapper/4 prev_pid=0 prev_prio=120 prev_state=R ==> next_comm=/usr/bin/termin next_pid=2511 next_prio=120
ls 7806 [002] 5398.723503: sched:sched_migrate_task: comm=perf pid=7801 prio=120 orig_cpu=2 dest_cpu=3
ls 7806 [002] 5398.723505: sched:sched_stat_sleep: comm=perf pid=7801 delay=1142537 [ns]
ls 7806 [002] 5398.723506: sched:sched_wakeup: comm=perf pid=7801 prio=120 target_cpu=003
ls 7806 [002] 5398.723508: sched:sched_stat_runtime: comm=ls pid=7806 runtime=920005 [ns] vruntime=3028398107 [ns]
swapper 0 [003] 5398.723508: sched:sched_stat_wait: comm=perf pid=7801 delay=0 [ns]
swapper 0 [003] 5398.723508: sched:sched_switch: prev_comm=swapper/3 prev_pid=0 prev_prio=120 prev_state=R ==> next_comm=perf next_pid=7801 next_prio=120
ls 7806 [002] 5398.723510: sched:sched_switch: prev_comm=ls prev_pid=7806 prev_prio=120 prev_state=x ==> next_comm=swapper/2 next_pid=0 next_prio=120 /usr/bin/termin 2511 [004] 5398.723605: sched:sched_stat_runtime: comm=/usr/bin/termin pid=2511 runtime=162720 [ns] vruntime=191386139371 [ns] /usr/bin/termin 2511 [004] 5398.723611: sched:sched_switch: prev_comm=/usr/bin/termin prev_pid=2511 prev_prio=120 prev_state=S ==> next_comm=swapper/4 next_pid=0 next_prio=120 sudo perf sched map的好处在于提供了一个的总的视图,将成百上千的调度事件进行总结,显示了系统任务在 CPU 之间的分布,假如有不好的调度迁移,比如一个任务没有被及时迁移到 idle 的 CPU 却被迁移到其他忙碌的 CPU,类似这种调度器的问题可以从 map 的报告中一眼看出来。


星号表示调度事件发生所在的 CPU。



点号表示该 CPU 正在 IDLE。



              *A0        5398.722333 secs A0 => perf:7806
*. A0 5398.722365 secs . => swapper:0
. *B0 5398.722575 secs B0 => migration/4:27
*A0 B0 5398.722597 secs
A0 *. 5398.722611 secs
A0 *C0 . 5398.723434 secs C0 => kworker/u12:3:7064
A0 *. . 5398.723451 secs
A0 . *D0 5398.723467 secs D0 => /usr/bin/termin:2511
A0 *E0 D0 5398.723509 secs E0 => perf:7801
*. E0 D0 5398.723510 secs
. E0 *. 5398.723612 secs perf sched replay 这个工具更是专门为调度器开发人员所设计,它试图重放 perf.data 文件中所记录的调度场景。很多情况下,一般用户假如发现调度器的奇怪行为,他们也无法准确说明发生该情形的场景,或者一些测试场景不容易再次重现,或者仅仅是出于“偷懒”的目的,使用 perf replay,perf 将模拟 perf.data 中的场景,无需开发人员花费很多的时间去重现过去,这尤其利于调试过程,因为需要一而再,再而三地重复新的修改是否能改善原始的调度场景所发现的问题。


run measurement overhead: 166 nsecs
sleep measurement overhead: 52177 nsecs
the run test took 999975 nsecs
the sleep test took 1064623 nsecs
nr_run_events: 11
nr_sleep_events: 581
nr_wakeup_events: 5
task 0 ( swapper: 0), nr_events: 11
task 1 ( swapper: 1), nr_events: 1
task 2 ( swapper: 2), nr_events: 1
task 3 ( kthreadd: 3), nr_events: 1

task 563 ( kthreadd: 7509), nr_events: 1
task 564 ( bash: 7751), nr_events: 1
task 565 ( man: 7762), nr_events: 1
task 566 ( kthreadd: 7789), nr_events: 1
task 567 ( bash: 7800), nr_events: 1
task 568 ( sudo: 7801), nr_events: 4
task 569 ( perf: 7806), nr_events: 8
————————————————————
#1 : 25.887, ravg: 25.89, cpu: 1919.68 / 1919.68
#2 : 27.994, ravg: 26.10, cpu: 2887.76 / 2016.49
#3 : 26.403, ravg: 26.13, cpu: 2976.09 / 2112.45
#4 : 29.400, ravg: 26.46, cpu: 1015.01 / 2002.70
#5 : 26.750, ravg: 26.49, cpu: 2942.80 / 2096.71
#6 : 27.647, ravg: 26.60, cpu: 3087.37 / 2195.78
#7 : 31.405, ravg: 27.08, cpu: 2762.43 / 2252.44
#8 : 23.770, ravg: 26.75, cpu: 2172.55 / 2244.45
#9 : 26.952, ravg: 26.77, cpu: 2794.93 / 2299.50
#10 : 30.904, ravg: 27.18, cpu: 973.26 / 2166.88



3.11 perf probe
Need to find vmlinux XXXXXXXXXXXXXXXXXX



可以自定义探测点。



Define new dynamic tracepoints.



使用例子



(1) Display which lines in schedule() can be probed



perf probe –line schedule



前面有行号的可以探测,没有行号的就不行了。



(2) Add a probe on schedule() function 12th line.



perf probe -a schedule:12



在schedule函数的12处增加一个探测点。



3.14 perf trace
perf trace类似于strace,但增加了其他系统事件的分析,比如pagefaults、task lifetime事件、scheduling事件等。



下面的命令可以查看系统中已经安装的脚本:



# perf trace -l
List of available trace scripts:
syscall-counts [comm] system-wide syscall counts
syscall-counts-by-pid [comm] system-wide syscall counts, by pid
failed-syscalls-by-pid [comm] system-wide failed syscalls, by pid
比如 failed-syscalls 脚本,执行的效果如下:



# perf trace record failed-syscalls
^C[ perf record: Woken up 11 times to write data ]

[ perf record: Captured and wrote 1.939 MB perf.data (~84709 samples) ]



perf trace report failed-syscalls
perf trace started with Perl script \
/root/libexec/perf-core/scripts/perl/failed-syscalls.pl



failed syscalls, by comm: 

comm # errors
-------------------- ----------
firefox 1721
claws-mail 149
konsole 99
X 77
emacs 56
[...]

failed syscalls, by syscall:

syscall # errors
------------------------------ ----------
sys_read 2042
sys_futex 130
sys_mmap_pgoff 71
sys_access 33
sys_stat64 5
sys_inotify_add_watch 4
[...] 该报表分别按进程和按系统调用显示失败的次数。非常简单明了,而如果通过普通的 perf record 加 perf report 命令,则需要自己手工或者编写脚本来统计这些数字。



  1. perf扩展应用



4.1 Flame Graph
FlameGraph是



1.抓取perf信息并转换



perf record -F 99 -a -g – sleep 60
perf script > out.perf



./stackcollapse-perf.pl out.perf > out.folded



./flamegraph.pl out.kern_folded > kernel.svg




  1. 参考资料
    系统级性能分析工具 — Perf:http://blog.csdn.net/zhangskd/article/details/37902159/



linux perf - 性能测试和优化工具:http://www.cnblogs.com/hushaojun/p/4848269.html



Linux下的内核测试工具——perf使用简介:http://www.blogjava.net/qileilove/archive/2013/09/04/403646.html



Perf – Linux下的系统性能调优工具,第 1 部分:http://www.ibm.com/developerworks/cn/linux/l-cn-perf1/



Perf – Linux下的系统性能调优工具,第 2 部分:https://www.ibm.com/developerworks/cn/linux/l-cn-perf2/



性能分析工具—Perf简介汇总整理:http://sanwen.net/a/nzsrvoo.html



性能调优工具如 perf,Oprofile 等的基本原理都是对被监测对象进行采样,最简单的情形是根据 tick 中断进行采样,即在 tick 中断内触发采样点,在采样点里判断程序当时的上下文。



事件分为以下三种:



1)Hardware Event 是由 PMU 硬件产生的事件,比如 cache 命中,当您需要了解程序对硬件特性的使用情况时,便需要对这些事件进行采样;



2)Software Event 是内核软件产生的事件,比如进程切换,tick 数等 ;



3)Tracepoint event 是内核中的静态 tracepoint 所触发的事件,这些 tracepoint 用来判断程序运行期间内核的行为细节,比如 slab 分配器的分配次数等。



Perf是内置于Linux内核源码树中的性能剖析(profiling)工具。



它基于事件采样原理,以性能事件为基础,支持针对处理器相关性能指标与操作系统相关性能指标的性能剖析。常用于性能瓶颈的查找与热点代码的定位。



CPU周期(cpu-cycles)是默认的性能事件,所谓的CPU周期是指CPU所能识别的最小时间单元,通常为亿分之几秒,是CPU执行最简单的指令时所需要的时间,例如读取寄存器中的内容,也叫做clock tick。



Perf是一个包含22种子工具的工具集,以下是最常用的5种.



perf list
Perf ist用来查看perf所支持的性能事件,有软件的也有硬件的。



List all symbolic event types.













perf list [hw sw cache tracepoint event_glob]


性能事件的分布



hw:Hardware event,9个



sw:Software event,9个



cache:Hardware cache event,26个



tracepoint:Tracepoint event,775个



sw实际上是内核的计数器,与硬件无关。



hw和cache是CPU架构相关的,依赖于具体硬件。



tracepoint是基于内核的ftrace,主线2.6.3x以上的内核版本才支持。



指定性能事件(以它的属性)



-e : u // userspace



-e : k // kernel



-e : h // hypervisor



-e : G // guest counting (in KVM guests)



-e : H // host counting (not in KVM guests)



(3) 使用例子



显示内核和模块中,消耗最多CPU周期的函数:



perf top -e cycles:k



显示分配高速缓存最多的函数:



perf top -e kmem:kmem_cache_alloc



perf top
对于一个指定的性能事件(默认是CPU周期),显示消耗最多的函数或指令。



System profiling tool.



Generates and displays a performance counter profile in real time.










perf top [-e –event=EVENT] []


perf top主要用于实时分析各个函数在某个性能事件上的热度,能够快速的定位热点函数,包括应用程序函数、



模块函数与内核函数,甚至能够定位到热点指令。默认的性能事件为cpu cycles。



perf stat
用于分析指定程序的性能概况。



Run a command and gather performance counter statistics.










perf stat [-e –event=EVENT] [-a]









perf stat [-e –event=EVENT] [-a] - []


输出格式



perf stat ls



输出包括ls的执行时间,以及10个性能事件的统计。



task-clock:任务真正占用的处理器时间,单位为ms。CPUs utilized = task-clock / time elapsed,CPU的占用率。



context-switches:上下文的切换次数。



CPU-migrations:处理器迁移次数。Linux为了维持多个处理器的负载均衡,在特定条件下会将某个任务从一个CPU



迁移到另一个CPU。



page-faults:缺页异常的次数。当应用程序请求的页面尚未建立、请求的页面不在内存中,或者请求的页面虽然在内



存中,但物理地址和虚拟地址的映射关系尚未建立时,都会触发一次缺页异常。另外TLB不命中,页面访问权限不匹配



等情况也会触发缺页异常。



cycles:消耗的处理器周期数。如果把被ls使用的cpu cycles看成是一个处理器的



可以用cycles / task-clock算出。



stalled-cycles-frontend:略过。



stalled-cycles-backend:略过。



instructions:执行了多少条指令。IPC为平均每个cpu cycle执行了多少条指令。



branches:遇到的分支指令数。branch-misses是预测错误的分支指令数。



常用参数



-p:stat events on existing process id (comma separated list). 仅分析目标进程及其创建的线程。



-a:system-wide collection from all CPUs. 从所有CPU上收集性能数据。



-r:repeat command and print average + stddev (max: 100). 重复执行命令求平均。



-C:Count only on the list of CPUs provided (comma separated list), 从指定CPU上收集性能数据。



-v:be more verbose (show counter open errors, etc), 显示更多性能数据。



-n:null run - don’t start any counters,只显示任务的执行时间 。



-x SEP:指定输出列的分隔符。



-o file:指定输出文件,–append指定追加模式。



–pre :执行目标程序前先执行的程序。



–post :执行目标程序后再执行的程序。



使用例子



执行10次程序,给出标准偏差与期望的比值:



perf stat -r 10 ls > /dev/null



显示更详细的信息:



perf stat -v ls > /dev/null



只显示任务执行时间,不显示性能计数器:



perf stat -n ls > /dev/null



单独给出每个CPU上的信息:



perf stat -a -A ls > /dev/null



ls命令执行了多少次系统调用:



perf stat -e syscalls:sys_enter ls



perf record
收集采样信息,并将其记录在数据文件中。



随后可以通过其它工具(perf-report)对数据文件进行分析,结果类似于perf-top的。



常用参数



-e:Select the PMU event.



-a:System-wide collection from all CPUs.



-p:Record events on existing process ID (comma separated list).



-A:Append to the output file to do incremental profiling.



-f:Overwrite existing data file.



-o:Output file name.



-g:Do call-graph (stack chain/backtrace) recording.



-C:Collect samples only on the list of CPUs provided.



使用例子



记录nginx进程的性能数据:



perf record -p pgrep -d ',' nginx



记录执行ls时的性能数据:



perf record ls -g



记录执行ls时的系统调用,可以知道哪些系统调用最频繁:



perf record -e syscalls:sys_enter ls



perf report
读取perf record创建的数据文件,并给出热点分析结果。



除了以上5个常用工具外,还有一些适用于较特殊场景的工具, 比如内核锁、slab分配器、调度器,



也支持自定义探测点。



perf lock



内核锁的性能分析。



Analyze lock events.












perf lock {record report script info}


需要编译选项的支持:CONFIG_LOCKDEP、CONFIG_LOCK_STAT。



CONFIG_LOCKDEP defines acquired and release events.



CONFIG_LOCK_STAT defines contended and acquired lock events.



常用选项



-i :输入文件



-k :sorting key,默认为acquired,还可以按contended、wait_total、wait_max和wait_min来排序。



使用例子



perf lock record ls // 记录



perf lock report // 报告



Name:内核锁的名字。



aquired:该锁被直接获得的次数,因为没有其它内核路径占用该锁,此时不用等待。



contended:该锁等待后获得的次数,此时被其它内核路径占用,需要等待。



total wait:为了获得该锁,总共的等待时间。



max wait:为了获得该锁,最大的等待时间。



min wait:为了获得该锁,最小的等待时间。



perf kmem



slab分配器的性能分析。



Tool to trace/measure kernel memory(slab) properties.










perf kmem {record stat} []


常用选项



–i :输入文件



–caller:show per-callsite statistics,显示内核中调用kmalloc和kfree的地方。



–alloc:show per-allocation statistics,显示分配的内存地址。



-l :print n lines only,只显示num行。



-s :sort the output (default: frag,hit,bytes)



使用例子



perf kmem record ls // 记录



perf kmem stat –caller –alloc -l 20 // 报告



Callsite:内核代码中调用kmalloc和kfree的地方。



Total_alloc/Per:总共分配的内存大小,平均每次分配的内存大小。



Total_req/Per:总共请求的内存大小,平均每次请求的内存大小。



Hit:调用的次数。



Ping-pong:kmalloc和kfree不被同一个CPU执行时的次数,这会导致cache效率降低。



Frag:碎片所占的百分比,碎片 = 分配的内存 - 请求的内存,这部分是浪费的。



有使用–alloc选项,还会看到Alloc Ptr,即所分配内存的地址。



TASK:进程名和pid。



Runtime:实际的运行时间。



Switches:进程切换的次数。



Average delay:平均的调度延迟。



Maximum delay:最大的调度延迟。



Maximum delay at:最大调度延迟发生的时刻。



probe-sched



调度模块分析。



trace/measure scheduler properties (latencies)













perf sched {record latency map replay script}


使用例子



perf sched record sleep 10 // perf sched record



perf report latency –sort max



perf-probe



自定义探测点。



Define new dynamic tracepoints.



使用例子



Display which lines in schedule() can be probed



perf probe –line schedule



前面有行号的可以探测,没有行号的就不行了。



(2) Add a probe on schedule() function 12th line.



perf probe -a schedule:12



在schedule函数的12处增加一个探测点。



程序一



void longa()



{



int i,j;



for(i = 0; i < 1000000; i++)



j=i; //am I silly or crazy? I feel boring and desperate.



}



void foo2()



{



int i;



for(i=0 ; i < 10; i++)



longa();



}



void foo1()



{



int i;



for(i = 0; i< 100; i++)



longa();



}



int main(void)



{



foo1();



foo2();



}



编译如下:gcc -o test1 -g test.c



此处一定要加-g选项,加入调试和符号表信息。



执行如下:



perf stat ./test



Performance counter stats for ‘./test’:



256.955398task-clock (msec)#0.999 CPUs utilized



4context-switches#0.016 K/sec



0cpu-migrations#0.000 K/sec



44page-faults#0.171 K/sec



cycles



stalled-cycles-frontend



stalled-cycles-backend



instructions



branches



branch-misses



0.257177573 seconds time elapsed



Task-clock-msecs:CPU 利用率,该值高,说明程序的多数时间花费在 CPU 计算上而非 IO。



Context-switches:进程切换次数,记录了程序运行过程中发生了多少次进程切换,频繁的进程切换是应该避免的。



Cache-misses:程序运行过程中总体的 cache 利用情况,如果该值过高,说明程序的 cache 利用不好



CPU-migrations:表示进程 t1 运行过程中发生了多少次 CPU 迁移,即被调度器从一个 CPU 转移到另外一个 CPU 上运行。



Cycles:处理器时钟,一条机器指令可能需要多个 cycles,



Instructions: 机器指令数目。



IPC:是 Instructions/Cycles 的比值,该值越大越好,说明程序充分利用了处理器的特性。



Cache-references: cache 命中的次数



Cache-misses: cache 失效的次数。



查找时间上的热点函数



perf record -e cpu-clock ./test1



perf report



显示如下:



Samples: 188of event ‘cpu-clock’, Event count (approx.): 47000000



OverheadCommandShared ObjectSymbol



99.47%testtest[.] longa



0.53%test[kernel.kallsyms][k] finish_task_switch


Category linux