首页 > 代码库 > 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
声明:以上内容来自用户投稿及互联网公开渠道收集整理发布,本网站不拥有所有权,未作人工编辑处理,也不承担相关法律责任,若内容有误或涉及侵权可进行投诉: 投诉/举报 工作人员会在5个工作日内联系你,一经查实,本站将立刻删除涉嫌侵权内容。