说明
总结perf在linux下进行性能分析的常用方式。
perf介绍
Perf是一款linux性能分析工具。
通过它，应用程序可以利用 PMU(performance monitoring unit)，tracepoint和内核中的特殊计数器来进行性能统计。它不但可以分析指定应用程序的性能问题，也可以用来分析内核的性能问题，当然也可以同时分析应用代码和内核，从而全面理解应用程序中的性能瓶颈。
perf举例
perf stat
perf stat命令用于检测和汇总关键CPU计数，例如:
1
2
3
4
5
6
7
8
9
10
11
12
13
14
15
16
17
| xuchen03@pm02-bot04-30002:~$ perf stat gzip perf.data
Performance counter stats for 'gzip perf.data':
87.275950 task-clock (msec) # 0.995 CPUs utilized
0 context-switches # 0.000 K/sec
0 cpu-migrations # 0.000 K/sec
127 page-faults # 0.001 M/sec
152,861,746 cycles # 1.751 GHz
77,476,340 stalled-cycles-frontend # 50.68% frontend cycles idle
<not supported> stalled-cycles-backend
201,679,601 instructions # 1.32 insns per cycle
# 0.38 stalled cycles per insn
39,663,860 branches # 454.465 M/sec
1,397,981 branch-misses # 3.52% of all branches
0.087739461 seconds time elapsed
|
注意：在虚拟机下可能不支持某些功能
这里面有包含一个计数：每个指令周期执行的指令数(IPC)，即insns per cycle，这是一个常用的检测单位，高的IPC意味着高的CPU占用，底的IPC意味着更多的等待消耗（磁盘I/O，内存延迟）。
perf stat的使用需要对CPU体系的知识，一般如果程序在代码，算法层面都没有地方在提升的时候可以考虑深挖下这边的性能，例如brach-miss，cache-miss(我的机器上不支持)。用的比较多的还是通过perf record分析代码层面的性能问题。
perf record
perf record命令通过一定频率采样CPU当前执行的堆栈，生成一个分析文件(perf.data)进行分析。如果某个函数比较耗时，那它占用CPU的时间就会越高，从而被采样到的概率也就越高。
perf report用来统计采样文件(perf.data)，生成一个较可观的输出（但是跟火焰图的直观还是没法比）
举例
1
2
3
4
5
6
7
8
9
10
11
12
13
14
15
16
17
18
19
20
21
22
23
24
25
26
| void longa()
{
int i,j;
for(i = 0; i < 10000; i++)
j=i;
}
void foo2()
{
int i;
for(i=0 ; i < 10000; i++)
longa();
}
void foo1()
{
int i;
for(i = 0; i< 10000; i++)
longa();
}
int main(void)
{
foo1();
foo2();
}
|
执行命令
1
2
3
4
5
6
7
8
9
10
11
12
13
14
15
16
17
18
19
20
21
22
23
24
25
26
27
28
29
30
31
32
33
34
35
36
37
38
39
40
41
42
43
44
45
46
47
48
49
50
51
52
53
54
| xuchen03@pm02-bot04-30002:~$ gcc test.c
xuchen03@pm02-bot04-30002:~$ sudo perf record -g ./a.out
[ perf record: Woken up 2 times to write data ]
[ perf record: Captured and wrote 0.410 MB perf.data (~17900 samples) ]
xuchen03@pm02-bot04-30002:~$ sudo perf report --stdio
# To display the perf.data header info, please use --header/--header-only options.
#
# Samples: 2K of event 'cycles'
# Event count (approx.): 1413222776
#
# Children Self Command Shared Object Symbol
# ........ ........ ....... ................. .........................
#
99.92% 0.00% a.out libc-2.19.so [.] __libc_start_main
|
--- __libc_start_main
99.92% 0.00% a.out a.out [.] main
|
--- main
__libc_start_main
99.88% 99.88% a.out a.out [.] longa
|
--- longa
|
|--50.07%-- foo2
| main
| __libc_start_main
|
|--49.89%-- foo1
| main
| __libc_start_main
--0.04%-- [...]
50.02% 0.00% a.out a.out [.] foo2
|
--- foo2
main
__libc_start_main
49.87% 0.04% a.out a.out [.] foo1
|
--- foo1
main
__libc_start_main
0.06% 0.06% a.out ld-2.19.so [.] do_lookup_x
|
--- do_lookup_x
0.03% 0.00% a.out [unknown] [k] 0x00007f9d7dc06317
|
--- 0x7f9d7dc06317
|
可以看到self列占用时间最大的是longa，占比99.88%。堆栈也能看到，但是看起来不是很直观。
火焰图
火焰图以一种更直观的方式来看perf record的采样结果
安装
安装很简单，直接使用git clone即可
1
2
| xuchen03@pm02-bot04-30002:~$ cd ~
xuchen03@pm02-bot04-30002:~$ git clone https://github.com/brendangregg/FlameGraph.git
|
使用
继续刚刚的采样命令：
1
2
3
4
5
6
| xuchen03@pm02-bot04-30002:~$ gcc test.c
xuchen03@pm02-bot04-30002:~$ sudo perf record -ga ./a.out
[ perf record: Woken up 2 times to write data ]
[ perf record: Captured and wrote 0.410 MB perf.data (~17900 samples) ]
xuchen03@pm02-bot04-30002:~$ sudo perf report --stdio
xuchen03@pm02-bot04-30002:~$ sudo perf script |cat|c++filt|~/FlameGraph/stackcollapse-perf.pl|~/sysperf/FlameGraph/flamegraph.pl > ~/c.svg
|
在自己的home目录下生成了c.svg，可以直接用浏览器打开：
可以很清楚的看到每个函数占用CPU的比例，以及这个函数的堆栈情况。在火焰图上可以很方便的找到哪个函数是可能是性能瓶颈，从而可以进一步的对这个函数进行分析。
动态追踪
perf更强大的地方是可以自定义追踪点
perf stat
1
2
3
4
5
6
7
8
9
10
11
12
13
14
15
| xuchen03@pm02-bot04-30002:~$ sudo perf probe -x a.out --add longa
Added new event:
probe_a:longa (on longa in /home/xuchen03/a.out)
You can now use it in all perf tools, such as:
perf record -e probe_a:longa -aR sleep 1
xuchen03@pm02-bot04-30002:~$ sudo perf stat -e probe_a:longa ./a.out
Performance counter stats for './a.out':
20,000 probe_a:longa
0.754663782 seconds time elapsed
|
可以看到stat能统计出来追踪函数longa被调用2W次
perf record
同时动态追踪和perf record一起使用，可以进一步分析追踪点相关的采样情况(注意这里的perf record加了–call-graph dwarf，不加可能导致堆栈不全)
1
2
3
4
5
6
7
8
9
10
11
12
13
14
15
16
17
18
19
20
21
22
23
24
25
26
27
28
29
30
31
32
33
34
35
36
37
38
39
40
41
42
43
44
45
46
47
48
49
50
51
52
53
54
| xuchen03@pm02-bot04-30002:~$ sudo perf record --call-graph dwarf -e probe_a:longa ./a.out
[ perf record: Woken up 646 times to write data ]
[ perf record: Captured and wrote 161.319 MB perf.data (~7048126 samples) ]
xuchen03@pm02-bot04-30002:~$ sudo perf report --stdio
# To display the perf.data header info, please use --header/--header-only options.
#
# Samples: 20K of event 'probe_a:longa'
# Event count (approx.): 20000
#
# Children Self Command Shared Object Symbol
# ........ ........ ....... ............. .....................
#
100.00% 0.00% a.out a.out [.] _start
|
--- _start
100.00% 0.00% a.out libc-2.19.so [.] __libc_start_main
|
--- __libc_start_main
_start
100.00% 0.00% a.out a.out [.] main
|
--- main
__libc_start_main
_start
100.00% 100.00% a.out a.out [.] longa
|
--- longa
|
|--50.00%-- foo1
| main
| __libc_start_main
| _start
|
--50.00%-- foo2
main
__libc_start_main
_start
50.00% 0.00% a.out a.out [.] foo1
|
--- foo1
main
__libc_start_main
_start
50.00% 0.00% a.out a.out [.] foo2
|
--- foo2
main
__libc_start_main
_start
|
因为本来longa函数在使用动态追踪之前就是占用100%，所以与之前的结果差不多。对于我们一般的程序来说，就会删除大量其他函数调用，只会得到追踪点相关的调用情况。
同样对于perf record结果可以使用命令火焰图命令生成更直观的火焰图来查看
更强大的动态追踪
动态追踪更强大的地方可以追加追踪的变量，就像gdb调试程序一样方便。
例如我们这里给foo2的for循环里加追踪点，并追踪i变量：
1
2
3
4
5
6
7
8
9
10
11
12
13
14
15
16
17
18
19
20
21
22
23
24
25
26
27
28
29
30
31
32
33
34
35
36
37
38
39
40
41
42
43
44
45
46
47
48
49
50
51
52
53
54
55
56
57
58
59
60
61
62
| xuchen03@pm02-bot04-30002:~$ sudo perf probe -x a.out --add 'test.c:12 i'
Added new event:
probe_a:foo2 (on @test.c:12 in /home/xuchen03/a.out with i)
You can now use it in all perf tools, such as:
perf record -e probe_a:foo2 -aR sleep 1
xuchen03@pm02-bot04-30002:~$ sudo perf record -e probe_a:foo2 ./a.out
[ perf record: Woken up 3 times to write data ]
[ perf record: Captured and wrote 0.699 MB perf.data (~30527 samples) ]
xuchen03@pm02-bot04-30002:~$ sudo perf script
a.out 9082 [017] 21495626.717550: probe_a:foo2: (4004e9) i=0
a.out 9082 [017] 21495626.717601: probe_a:foo2: (4004e9) i=1
a.out 9082 [017] 21495626.717639: probe_a:foo2: (4004e9) i=2
a.out 9082 [017] 21495626.717676: probe_a:foo2: (4004e9) i=3
a.out 9082 [017] 21495626.717713: probe_a:foo2: (4004e9) i=4
a.out 9082 [017] 21495626.717750: probe_a:foo2: (4004e9) i=5
a.out 9082 [017] 21495626.717787: probe_a:foo2: (4004e9) i=6
a.out 9082 [017] 21495626.717824: probe_a:foo2: (4004e9) i=7
a.out 9082 [017] 21495626.717861: probe_a:foo2: (4004e9) i=8
a.out 9082 [017] 21495626.717898: probe_a:foo2: (4004e9) i=9
a.out 9082 [017] 21495626.717936: probe_a:foo2: (4004e9) i=10
a.out 9082 [017] 21495626.717973: probe_a:foo2: (4004e9) i=11
a.out 9082 [017] 21495626.718010: probe_a:foo2: (4004e9) i=12
a.out 9082 [017] 21495626.718047: probe_a:foo2: (4004e9) i=13
a.out 9082 [017] 21495626.718084: probe_a:foo2: (4004e9) i=14
a.out 9082 [017] 21495626.718121: probe_a:foo2: (4004e9) i=15
a.out 9082 [017] 21495626.718158: probe_a:foo2: (4004e9) i=16
a.out 9082 [017] 21495626.718195: probe_a:foo2: (4004e9) i=17
a.out 9082 [017] 21495626.718232: probe_a:foo2: (4004e9) i=18
a.out 9082 [017] 21495626.718269: probe_a:foo2: (4004e9) i=19
a.out 9082 [017] 21495626.718306: probe_a:foo2: (4004e9) i=20
a.out 9082 [017] 21495626.718343: probe_a:foo2: (4004e9) i=21
a.out 9082 [017] 21495626.718380: probe_a:foo2: (4004e9) i=22
a.out 9082 [017] 21495626.718417: probe_a:foo2: (4004e9) i=23
a.out 9082 [017] 21495626.718454: probe_a:foo2: (4004e9) i=24
a.out 9082 [017] 21495626.718491: probe_a:foo2: (4004e9) i=25
a.out 9082 [017] 21495626.718528: probe_a:foo2: (4004e9) i=26
a.out 9082 [017] 21495626.718565: probe_a:foo2: (4004e9) i=27
a.out 9082 [017] 21495626.718602: probe_a:foo2: (4004e9) i=28
a.out 9082 [017] 21495626.718639: probe_a:foo2: (4004e9) i=29
a.out 9082 [017] 21495626.718676: probe_a:foo2: (4004e9) i=30
a.out 9082 [017] 21495626.718713: probe_a:foo2: (4004e9) i=31
a.out 9082 [017] 21495626.718750: probe_a:foo2: (4004e9) i=32
a.out 9082 [017] 21495626.718787: probe_a:foo2: (4004e9) i=33
a.out 9082 [017] 21495626.718824: probe_a:foo2: (4004e9) i=34
a.out 9082 [017] 21495626.718861: probe_a:foo2: (4004e9) i=35
a.out 9082 [017] 21495626.718898: probe_a:foo2: (4004e9) i=36
a.out 9082 [017] 21495626.718935: probe_a:foo2: (4004e9) i=37
a.out 9082 [017] 21495626.718972: probe_a:foo2: (4004e9) i=38
a.out 9082 [017] 21495626.719009: probe_a:foo2: (4004e9) i=39
a.out 9082 [017] 21495626.719046: probe_a:foo2: (4004e9) i=40
a.out 9082 [017] 21495626.719083: probe_a:foo2: (4004e9) i=41
a.out 9082 [017] 21495626.719120: probe_a:foo2: (4004e9) i=42
a.out 9082 [017] 21495626.719157: probe_a:foo2: (4004e9) i=43
a.out 9082 [017] 21495626.719194: probe_a:foo2: (4004e9) i=44
a.out 9082 [017] 21495626.719231: probe_a:foo2: (4004e9) i=45
a.out 9082 [017] 21495626.719268: probe_a:foo2: (4004e9) i=46
a.out 9082 [017] 21495626.719305: probe_a:foo2: (4004e9) i=47
a.out 9082 [017] 21495626.719343: probe_a:foo2: (4004e9) i=48
a.out 9082 [017] 21495626.719380: probe_a:foo2: (4004e9) i=49
...
|
参考
性能分析界的牛人: http://www.brendangregg.com/perf.html
中文介绍perf较不错的技术文章，我的例子代码摘自这里: https://www.ibm.com/developerworks/cn/linux/l-cn-perf1/index.html