首页 > 代码库 > gprof

gprof

函数级耗时剖析。gprof不会说谎,仔细考虑下函数的实现细节。

准备工作

  • 对单文件simulator.cpp编译
    • 编译:g++ -g -pg simulator.cpp -o simulator.o
    • 链接:g++ -pg simulator.o -o simulator
  • 对于使用CMakeLists.txt的工程
    add_definitions(-g -pg)
    set_target_properties(simulator PROPERTIES LINK_FLAGS "-pg")  # 必须用""把-pg引起来
    #只对执行文件有效,对库文件使用无效
    #如果想对自己的库文件做相应的剖析,把所有源文件都放在add_executable中
    我们可以使用-O2对编译文件优化,但是一定要加-g -pg。在我的测试中,效果很好。大家务必试试。

生成剖析文件

  • 执行程序,会在当前文件目录下生成gmon.out剖析文件
    ./simulator #除非程序处理了中断,保证收到中断能正常退出时,才会生成gmon.out文件
  • 导出可读的性能文件
    gprof simulator gmon.out > perf.log

解读剖析文件

主要关注两部分:Flat profile与Call graph

Flat profile
simulator flag profile
1
2
3
4
5
6
7
Each sample counts as 0.01 seconds.
  %   cumulative   self              self     total
 time   seconds   seconds    calls   s/call   s/call  name
 25.37      3.81     3.81 71089134     0.00     0.00  shared_buffer::BufferInterface::WriteBuffer(BufferDescriptor const&)
  8.92      5.15     1.34 71089350     0.00     0.00  shared_buffer::BufferInterface::CopyBuffer(BufferDescriptor const&, SharedBuffer*)
  7.99      6.35     1.20 71089350     0.00     0.00  shared_buffer::SharedBuffer::AllocCell(int)
  5.16      7.13     0.78 71089062     0.00     0.00  GenerateTime(timeval&)

拿第5行来说

  • % time:该函数占总运行时间的8.92%
  • cumulative seconds:累积前面的函数调用,总时间为5.15秒
  • self seconds:自身使用1.34秒
  • calls:该函数被调用71089350次
  • self ms/call:(单位可能是s/ms/ns依据调用情况来决定)未知,可能是平均调用时间,求解
  • total ms/call:(单位可能是s/ms/ns依据调用情况来决定)未知,求解
  • name:那么的直观

当我们拿到这样的结果时,我们首先应该关注下排名靠前的函数(为什么这么耗时),其次关注调用次数最多的函数(为什么会调用这么多次),还有就是关注你目前想了解的函数是否符合预期(调用次数与时间)

Call graph
simulator‘s call graph
index % time    self  children    called     name
                                                 <spontaneous>
[1]     98.9    0.00   14.86                 main [1]
                0.26   14.47       1/1           RunLoader(shared_buffer::BufferInterface&) [2]
                0.00    0.11       1/1           shared_buffer::BufferInterface::BufferInterface(std::string const&) [24]
                0.00    0.02       1/1           shared_buffer::BufferInterface::~BufferInterface() [31]
-----------------------------------------------
                0.26   14.47       1/1           main [1]
[2]     98.0    0.26   14.47       1         RunLoader(BufferInterface&) [2]
                0.57   12.92 71089062/71089062     SendBuffer2(BufferInterface&, DataType, unsigned int, OMTime const&) [3]
                0.78    0.00 71089062/71089062     GenerateTime(timeval&) [10]
                0.17    0.00 71089134/71089134     omatrix::OMTime::OMTime(timeval const&) [22]
                0.03    0.00 71089134/71089145     omatrix::OMTime::~OMTime() [28]
                0.01    0.00      72/72          SendBuffer(BufferInterface&, DataType, unsigned int, OMTime const&) [36]
                0.00    0.00       4/4           rdtsc() [137]
-----------------------------------------------
                0.57   12.92 71089062/71089062     RunLoader(shared_buffer::BufferInterface&) [2]
[3]     89.8    0.57   12.92 71089062         SendBuffer2(BufferInterface&, DataType, unsigned int, OMTime const&) [3]
                3.81    9.11 71089062/71089134     shared_buffer::BufferInterface::WriteBuffer(BufferDescriptor const&) [4]
-----------------------------------------------

拿index为2的来说

  • index:目前关注的重点函数编号,我们可以每行的未端看到同样形式的编号
  • time:该函数及其子函数的总耗时百分比为98.0%
  • self:该函数自身耗时0.26秒,该值等于前面的Flat profile部分的self seconds。同时该值也等于此部分中调用该函数的self的和。
  • children:该函数调用的子函数耗时14.47,同时大家可以算算,其子函数的self+children总和等于该值。同时该值也等于此部分中调用该函数的children的和。
  • called:如果是当前函数,该值没有/分割,表明它被调用的次数;如果是父/子函数,前半部分表示涉及该调用栈的次数,后半部分表示该函数总的被调用次数
  • name:还是那么的直观

通过该部分我们可以非常直观的观察调用关系,看是否有函数的调用是自己未预期的。

gprof