函数级耗时剖析。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：还是那么的直观
通过该部分我们可以非常直观的观察调用关系，看是否有函数的调用是自己未预期的。
