gprof

时间：2023-03-08 18:01:29
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中
    gprof 我们可以使用-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：还是那么的直观

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