文本模式的输出行如下所示:
它会有很多行,例如,collect profile:
$ CPUPROFILE=a.pprof LD_PRELOAD=./libprofiler.so ./a.out
程序a.out
和这里一样:Kcachegrind/callgrind is inaccurate for dispatcher functions?
然后用 pproftop
命令分析:
$ pprof ./a.out a.pprof
Using local file ./a.out.
Using local file a.pprof.
Welcome to pprof! For help, type 'help'.
(pprof) top
Total: 185 samples
76 41.1% 41.1% 76 41.1% do_4
51 27.6% 68.6% 51 27.6% do_3
37 20.0% 88.6% 37 20.0% do_2
21 11.4% 100.0% 21 11.4% do_1
0 0.0% 100.0% 185 100.0% __libc_start_main
0 0.0% 100.0% 185 100.0% dispatcher
0 0.0% 100.0% 34 18.4% first2
0 0.0% 100.0% 42 22.7% inner2
0 0.0% 100.0% 68 36.8% last2
0 0.0% 100.0% 185 100.0% main
那么,这里是什么:总样本数为 185;频率是默认值(每 10 毫秒 1 个样本;或每秒 100 个样本)。那么总运行时间约为 1.85 秒。
第一列是样本数,当 a.out 在给定函数中工作时获取。如果我们将它除以频率,我们将得到给定函数的总时间估计,例如do_4
运行约 0.8 秒
第二列是给定函数中的样本计数除以总计数,或此函数在总程序运行时间中的百分比。do_4
最慢的函数也是如此(占程序总时间的 41%),do_1
仅占程序运行时间的 11%。我想你对这个专栏很感兴趣。
第三列是当前行和前行的总和;所以我们可以知道 2 个最慢的函数,do_4
总共do_3
占总运行时间的 68% (41%+27%)
第 4 列和第 5 列与第 1 列和第 2 列一样;但是这些不仅会考虑给定函数本身的样本,还会考虑从给定直接和间接调用的所有函数的样本。您可以看到,main
从它调用的所有内容占总运行时间的 100%(因为main
是程序本身;或程序调用树的根),last2
其子项占运行时间的 36.8%(它在我的程序中的子项是:一半调用do_4
和调用的一半do_3
= 41.1 + 27.6 /2 = 69.7/2 ~= 34% + 函数本身的一些时间)
PS:还有一些其他有用的 pprof 命令,例如callgrind
或gv
显示调用树的图形表示并添加了分析信息。