用Gprof优化or测试你的程序
昨天去席老师哪里论文格式审查,回来再次修改论文。这一段时间,忙的简直要抽风了,改论文,看论文,再改论文…总算差不多了。
最近写论文的时候,第五章要写到一个测试,其中包括性能测试。本意是想测出系统中每个模块的性能,也就是每个模块运行次数以及运行时间。经过一番的百度和谷歌,最后决定使用Linux平台的Gprof。Gprof是一个GNU Profiler工具,其中GProf可以打印出每个函数的运行次数以及运行消耗时间,并且可以打印出函数的调用关系,配合KProf还可以显示函数的调用关系树。因此本测试使用Gprof,可以查看进程处理时间耗费情况。
使用Gprof之前,我们有必要了解一下他的工作原理:通过在编译和链接程序的时候(使用-pg编译和链接选项),gcc在应用程序的每个函数中都加入了一个名为mcount (or”_mcount”,or “__mcount”, 依赖于编译器或操作系统)的函数,也就是说你的应用程序里的每一个函数都会调用mcount,而mcount 会在内存中保存一张函数调用图,并通过函数调用堆栈的形式查找子函数和父函数的地址。这张调用图也保存了所有与函数相关的调用时间,调用次数等等的所有信息。
Gprof的用法:gprof [ -b ] [ -e Name ] [ -E Name ] [ -f Name ] [ -F Name ] [ -L PathName ] [ -s ] [ -z] [ a.out [ gmon.out ... ] ]
-b 不再输出统计图表中每个字段的详细描述。
-p 只输出函数的调用图(Call graph的那部分信息)。
-q 只输出函数的时间消耗列表。
-e Name 不再输出函数Name 及其子函数的调用图(除非它们有未被限制的其它父函数)。可以给定多个 -e 标志。一个 -e 标志只能指定一个函数。
-E Name 不再输出函数Name 及其子函数的调用图,此标志类似于 -e 标志,但它在总时间和百分比时间的计算中排除了由函数Name 及其子函数所用的时间。
-f Name 输出函数Name 及其子函数的调用图。可以指定多个 -f 标志。一个 -f 标志只能指定一个函数。
-F Name 输出函数Name 及其子函数的调用图,它类似于 -f 标志,但它在总时间和百分比时间计算中仅使用所打印的例程的时间。可以指定多个 -F 标志。一个 -F 标志只能指定一个函数。-F 标志覆盖 -E 标志。
-z 显示使用次数为零的函数(按照调用计数和累积时间计算)。
使用例子:
假如我写了一个程序count_data.cpp,如果要使用gprof的话,在编译程序的时候需要加上-pg,如下:
g++ -gp -o count_data count_data.cpp
编译没有错误的话,直接运行 count_data程序
./ count_data
运行过程序以后,会在程序当前文件夹下生成一个gmon.out文件,这个文件便是程序运行记录文件。下一步我们就可以使用gprof来读取分析该文件了。
gprof –q test gmon.out
如果你想多次运行程序并且记录函数运行时间,便可以用shell来实现。下面是我写的一个shell脚本。测试本程序运行。本程序被调用四次,每次传入不同参数。
#!/bin/sh
i=1
while [ $i -le 23 ]
do
echo $i
time ./count_data $i > null
cp gmon.out ${i}gmon.out
gprof -b count_data ${i}gmon.out > ${i}.txt
let i+=7
done
通过上面shell的运行,程序会产生一下几个文件:
1.txt 2.txt 3.txt 4.txt
我们可以统计该程序运行函数的时间来分析每个函数的性能。该功能可以对程序运行效率进行优化,也可以在写论文是完成测试。呵呵,下面是我的测试结果以及对测试结果的分析,直接在论文里复制出来了,懒得改了,呵呵
本次测试过程如下,首先将数据库中数据清空,然后程序循环读取七天的离线数据,模拟在线统计一小时数据,进行处理。处理过程中记录下该数据记录条数,以及更新数据条数。对Gprof产生的gmon.out文件进行分析。依次运行和分析第二批数据、第三批和第四批数据。
表1主要函数运行时间
函数名(耗时ms) 第一批 第二批 第三批 第四批 get_userid() 86733 116327 110690 120245 count_net() 54571 77240 70421 72147 update_max_area() 小于10 小于10 小于10 小于10 Insert_hourflow() 小于10 小于10 小于10 小于10 update_max_sc() 小于10 小于10 小于10 小于10 update_ip_num() 小于10 小于10 小于10 小于10 insert_top_ten() 小于10 小于10 小于10 小于10 heap_adjust() 小于10 小于10 小于10 小于10 其他代码 39395 39086 54410 48099 总耗时 180699 232653 235521 240491
表2主要函数运行次数
函数名(次数) 第一批 第二批 第三批 第四批 get_userid() 13498152 15346753 14668286 14059765 count_net() 1885952 2377368 2317642 2342265 update_max_area() 1 1 1 1 Insert_hourflow() 1 1 1 1 update_max_sc() 1 1 1 1 update_ip_num() 1 1 1 1 insert_top_ten() 1 1 1 1 heap_adjust() 247 321 276 229 数据条数 13498152 15346753 14668286 14059765 由表1和表2可以看出,第一次数据处理中共统计出13498152条记录,其中有1885952用户匹配成功,其他数据不在监控范围内,因此被get_userid()函数过滤掉,count_net()函数被调用了1885952次,耗时54571ms,数据库插入函数仅仅被调用了一次,耗时非常小,可以被忽略掉。表1第一批数据总体耗时为180699ms,用户过滤模块耗时较多,达到86733ms,接近50%。因为每条记录均要过滤,所以耗时较多,其他代码耗时39395ms。其他代码耗时主要表现在程序环境初始化、读取离线数据文件、调用存储过程等。在表2可以分析得知,四次数据处理数据文件整体记录数大致在一千五百万左右。用户匹配成功以后的数据调用count_net()函数处理的记录数大概在二百万左右。分析表1可知,程序主要耗时在get_userid()和count_net(),这两个函数分别为用户过滤模块和数据处理模块。另外由表1可得第一批数据处理耗时比第二、三、四批数据少,因为第一批数据条数较少。还可以分析到,处理响应时间在第一批到第四批的整个过程略微有些增长。此现象是正常的,因为数据库在第一批处理过程中是空的,随着记录的增多数据库表中记录会增长。
根据上面的分析我们可以看出,系统满足对记录数据处理的响应速度。处理千万级数据,耗时仅仅为三到五分钟,因此该数据处理过程满足需求。





