gprof 在postgresql中的使用
gprof简介：
1.gprof是GNU profiler工具。可以显示程序运行的“flat profile”，包括每个函数的调用次数，每个函数消耗的处理器时间。也可以显示“Call graph (调用图)”，包括函数的调用关系，每个函数调用花费了多少时间。
2.gprof只能在程序正常结束退出之后才能生成程序测评报告，原因是gprof通过在atexit()里注册了一个函数来产生结果信息，任何非正常退出都不会执行atexit()的动作，所以不会产生gmon.out文件。如果你的程序是一个不会退出的服务程序，那就只有修改代码来达到目的。如果不想改变程序的运行方式，可以添加一个信号处理函数解决问题（这样对代码修改最少）。
3.通过在编译和链接程序的时候（使用 -pg 编译和链接选项），gcc 在你应用程序的每个函数中都加入了一个名为mcount ( or “_mcount” , or “__mcount” , 依赖于编译器或操作系统)的函数，也就是说你的应用程序里的每一个函数都会调用mcount, 而mcount 会在内存中保存一张函数调用图，并通过函数调用堆栈的形式查找子函数和父函数的地址。这张调用图也保存了所有与函数相关的调用时间，调用次数等等的所有信息。
gprof使用方法：
1、在编译选项中加-pg
2、执行编译的二进制程序
3、 在程序运行目录下 生成 gmon.out 文件。如果原来有gmon.out 文件，将会被重写。
4、结束进程。这时 gmon.out 会再次被刷新。
5、用 gprof 工具分析 gmon.out 文件。
PG中使用gprof：
在PG中，可以在configure中添加--enable-profiling
PS：不要直接在文件 src/Makefile.global 中的CFLAGS添加-pg
原因：修改 src/Makefile.global，在程序目录下(PGDATA)下会生成 gmon.out，但是PG不同的进程生成的 gmon.out会相互覆盖，最终只剩一个，无法得到其余进程的 gmon.out文件。
使用--enable-profiling，configure之后， src/Makefile.global 中的CFLAGS会添加-pg，且会在PG代码中定义宏PROFILE_PID_DIR，标记会在PGDATA/gprof下 为每个进程创建一个pid命名的文件夹，该进程的gmon.out文件生成在此。
使用gprof分析gmon.out
gprof 命令使用方法：
gprof 二进制程序 gmon.out >report.txt
gprof后也可以加以下参数：
l -b 不再输出统计图表中每个字段的详细描述。
l -p 只输出函数的调用图（Call graph的那部分信息）。
l -q 只输出函数的时间消耗列表。
l -e Name 不再输出函数Name 及其子函数的调用图（除非它们有未被限制的其它父函数）。可以给定多个 -e 标志。一个 -e 标志只能指定一个函数。
l -E Name 不再输出函数Name 及其子函数的调用图，此标志类似于 -e 标志，但它在总时间和百分比时间的计算中排除了由函数Name 及其子函数所用的时间。
l -f Name 输出函数Name 及其子函数的调用图。可以指定多个 -f 标志。一个 -f 标志只能指定一个函数。
l -F Name 输出函数Name 及其子函数的调用图，它类似于 -f 标志，但它在总时间和百分比时间计算中仅使用所打印的例程的时间。可以指定多个 -F 标志。一个 -F 标志只能指定一个函数。-F 标志覆盖 -E 标志。
l -z 显示使用次数为零的例程（按照调用计数和累积时间计算）。
报告说明
使用gprof命令生成的report.txt 文件说明（不加参数）：
Gprof 产生的信息解释：
| %time | Cumulative seconds | Self Seconds | Calls | Self TS/call | Total TS/call | name |
|---|---|---|---|---|---|---|
| 该函数消耗时间占程序所有时间百分比 | 程序的累积执行时间 （只是包括gprof能够监控到的函数） | 该函数本身执行时间 （所有被调用次数的合共时间，不包含子函数） | 函数被调用次数 | 函数平均执行时间 (不包含子函数) | 函数平均执行时间 （包含子函数） | 函数名 |
Call Graph 的字段含义：
| Index | %time | Self | Children | Called | Name |
|---|---|---|---|---|---|
| 索引值 | 函数消耗时间占所有时间百分比 | 函数本身执行时间 | 执行子函数所用时间 | 被调用次数 | 函数名 |
PS: gprof只能监控 添加-pg之后编译到的部分代码中函数，对于工作在内核态的函数（如内核系统调用sleep() ）、外部的函数库（libc库，so）
若想要监控普通动态链接库，可以添加-pg重新编译so.
若想要监控libc中的函数，需要启用代码剖析支持而编译的 C 库版本（libc_p.a/libc_p.so )。用 –lc_p替换-lc,这样程序会链接libc_p.so或libc_p.a。
比如
gcc example1.c –pg -lc_p -o example1
注意要用ldd ./example | grep libc来查看程序链接的是libc.so还是libc_p.so
函数分析：
Flat profile部分：
统计函数的调用情况，按照所有函数总运行时间进行排序（不包含子函数）
Flat profile: Each sample counts as 0.01 seconds. % cumulative self self total time seconds seconds calls ms/call ms/call name 8.39 6.23 6.23 182558812 0.00 0.00 SearchCatCache 7.19 11.57 5.34 980839114 0.00 0.00 AllocSetAlloc 4.89 15.20 3.63 528673804 0.00 0.00 copyObject 3.50 17.80 2.60 1942314 0.00 0.00 base_yyparse 2.19 19.43 1.63 117492872 0.00 0.00 expression_tree_walker .....
从以上数据可知，运行总时间最长的函数为SearchCatCache，被调用了182558812次，总时间为6.23（不包含其子函数）
Call graph部分：
对每个函数进行分析，并按照总运行时间排序（包含子函数）
以下 分别对三种常见的函数的分析情况进行说明
1、一般函数（没有递归的函数）
Call graph granularity: each sample hit covers 2 byte(s) for 0.01% of 74.27 seconds index % time self children called name ....... ----------------------------------------------- 0.00(A2) 0.00(B2) 2(C2)/6310643 PostgresMain [118] 表示PostgresMain的index为118 0.08(A1) 26.27(B1) 6310641(C1)/6310643 BuildCachedPlan [3] [5] 35.5 0.08(A) 26.27(B) 6310643(C) pg_plan_queries [5] 0.09(A3) 26.07(B3) 6310643/6310643 pg_plan_query [6] 0.02(A4) 0.09(B4) 6310643/85468457 lappend [58] ----------------------------------------------- ......
以上为函数pg_plan_queries的调用情况（index [5]正对的一行),该函数和他的子函数总运行时间为程序运行时间的35.5 。
pg_plan_queries 行：
self列为该函数本身的运行时间;children为该函数的子函数们运行的总时间（包含子函数的子函数。。。。）;
called列表上该函数被调用的总次数。
pg_plan_queries 被调用6310643次(记为C)，pg_plan_queries 函数本身运行总时间为0.08s(记为A),pg_plan_queries 中的子函数运行时间为26.27(记为B)。
pg_plan_queries 上面的函数为调用pg_plan_queries的函数，下面的函数为pg_plan_queries调用的函数（子函数）
调用pg_plan_queries 的函数有PostgresMain、BuildCachedPlan。
called：在pg_plan_queries被调用的6310643次中，BuildCachedPlan调用了6310641次(记为C1)，PostgresMain调用了2次(记为C2)
self&children：
pg_plan_queries在被BuildCachedPlan调用的6310641次中，共运行0.08s(记为A1),子函数运行26.27s(记为B1)
pg_plan_queries在被PostgresMain调用的2次中，共运行0.00s(记为A2),子函数运行0.00s(记为B2)
（由于PostgresMain调用pg_plan_queries次数太少，总时间在1ms之下，统计不到，
实际上，A=A1+A2,B = B1+B2,C= C1+C2）
（时间都是pg_plan_queries的运行时间。）
pg_plan_queries 下面的函数为pg_plan_queries 调用的子函数
pg_plan_queries 调用的函数有pg_plan_query和lappend
called:pg_plan_query一共被调用6310643次，全部在此处被调用；lappend共被调用85468457次，在此处被调用了6310643次。
self&children：
pg_plan_query在此处的调用中，函数本身运行时间为0.09s(记为A3),子函数运行总时间为26.07s(记为B3)
lappend在此处的调用中，函数本身运行时间为0.02s(记为A4),子函数运行总时间为0.09s(记为B4)
A3+B3+A4+B4 = B
（时间都是子函数在pg_plan_queries中的运行时间。）
2、递归函数
index % time self children called name ----------------------------------------------- 3886192 expression_tree_mutator <cycle 4> [75] 16021340(a1) simplify_function <cycle 4> [19] 16023420(a2) eval_const_expressions_mutator <cycle 4> [49] 0.00 0.00 1(a3)/6311976(s) flatten_join_alias_vars [1059] 0.00 0.00 2(a4)/6311976 create_indexscan_plan [663] 0.00 0.00 2(a5)/6311976 replace_rte_variables [1032] 0.00 0.00 98(a6)/6311976 set_plan_refs [77] 0.00 0.00 295(a7)/6311976 set_upper_references [554] [75] 1.7 0.41 0.85 32045158(a)+3886192 expression_tree_mutator <cycle 4> [75] 0.13 0.48 33499624/85468457 lappend [58] 0.01 0.08 13598206/452086227 palloc [40] 0.05 0.00 35931349/650254937 check_stack_depth [83] 0.00 0.03 2425/3012 fix_upper_expr_mutator [485] 0.03 0.00 6/8 replace_nestloop_params_mutator [468] 0.02 0.00 7769088/9711360 substitute_actual_parameters_mutator [548] 0.00 0.02 648/844 fix_join_expr_mutator [552] 0.00 0.00 203/207 replace_rte_variables_mutator [1038] 0.00 0.00 3884544/5828433 list_nth [1338] 0.00 0.00 208/209 flatten_join_alias_vars_mutator [1570] 35926889 eval_const_expressions_mutator <cycle 4> [49] 3886192 expression_tree_mutator <cycle 4> [75] -----------------------------------------------
expression_tree_mutator为递归函数
called：递归函数有两个数字，用加号“+“分隔， 第一个数字计数非递归调用，第二个计数递归调用。
递归调用有3886192次（首行和末行）
非递归调用有32045158（a）次。
非递归调用中：a = a1+a2+a3+a4+a5+a6+a7。
<cycle 4> :循环编号为4
如果两个函数互相调用，则他们是一个cycle
如果 a 和b 互相调用，b和c 相互调用,则他们是一个cycle。
eval_const_expressions_mutator、expression_tree_mutator、simplify_function函数都属于<cycle 4>。
后面有<cycle 4>的都属于这个cycle,且在此处没有统计时间。
原因：a calls b, b calls a，a统计子函数时间时包含了b和b的子函数的运行时间，而a又是b的子函数，统计会出现矛盾。
所以对每个cycle单独统计：
3、cycle（多个函数相互调用）
index % time self children called name ----------------------------------------------- [13] 23.1 1.36(t) 15.82(T) 6311976(a)+83992989(b) <cycle 4 as a whole> [13] 0.43(t1) 13.02(T1) 14079068(c) simplify_function <cycle 4> [19] 0.52(t1) 1.94(T2) 44180739(d)+3397819(e) eval_const_expressions_mutator<cycle 4>[49] 0.41(t1) 0.85(T3) 32045158(f)+3886192(g) expression_tree_mutator <cycle 4> [75] -----------------------------------------------
cycle时间：
t = t1+t2+t3：cycle中的函数们本身运行的时间。
T= T1+T2+T3：cycle中 函数的子函数（cycle外的）的总时间。
<cycle 4 as a whole>：调用次数 = 本cycle内的函数总调用次数。
a + b = c+d+f
a：非本cycle的函数调用 本cycle内部函数的次数（每个函数的entry中，caller的 x/y中的y都是a,比如【2、递归函数】中的s)
b：本cycle内部函数 互相调用的次数，递归次数不算
d,f：非递归调用的次数，包含本cycle中的函数调用和外部调用次数。
e,g：递归调用次数
关于cycle:
https://sourceware.org/binutils/docs-2.17/gprof/Cycles.html#Cycles
扫一扫
900
被折叠的 条评论
为什么被折叠?
到【灌水乐园】发言
