gprof 和 (unix) 时间之间的差异; gprof 报告较低的运行时间
Discrepancy between gprof and (unix) time; gprof reports lower runtimes
我有一个简单的排序程序,我正在对它进行分析,以便有一个案例来研究 gprof;我稍后计划分析一个更大的算法。
我已经使用 -pg
和 运行 ./sort 编译生成 gmon.out
文件。
但是,当我 运行 gprof ./sort gmon.out
时,累积秒数和自身秒数产生的值,我认为是不准确的。
首先,运行宁time(./sort)
我得到:
real 0m14.352s
user 0m14.330s
sys 0m0.005s
我的秒表是准确的。
但是,平面配置文件的 gprof 结果是:
Each sample counts as 0.01 seconds.
% cumulative self self total
time seconds seconds calls s/call s/call name
56.18 2.76 2.76 1 2.76 4.71 sort(std::vector<int, std::allocator<int> >&)
35.01 4.49 1.72 1870365596 0.00 0.00 std::vector<int, std::allocator<int> >::operator[](unsigned long)
8.96 4.93 0.44 100071 0.00 0.00 std::vector<int, std::allocator<int> >::size() const
0.00 4.93 0.00 50001 0.00 0.00 __gnu_cxx::new_allocator<int>::construct(int*, int const&)
0.00 4.93 0.00 50001 0.00 0.00 void __gnu_cxx::__alloc_traits<std::allocator<int> >::construct<int>(std::allocator<int>&, int*, int const&)
0.00 4.93 0.00 50001 0.00 0.00 std::vector<int, std::allocator<int> >::push_back(int const&)
0.00 4.93 0.00 50001 0.00 0.00 operator new(unsigned long, void*)
0.00 4.93 0.00 170 0.00 0.00 std::_Iter_base<int*, false>::_S_base(int*)
0.00 4.93 0.00 102 0.00 0.00 std::_Niter_base<int*>::iterator_type std::__niter_base<int*>(int*)
0.00 4.93 0.00 68 0.00 0.00 __gnu_cxx::__normal_iterator<int*, std::vector<int, std::allocator<int> > >::base() const
0.00 4.93 0.00 68 0.00 0.00 std::_Miter_base<int*>::iterator_type std::__miter_base<int*>(int*)
0.00 4.93 0.00 52 0.00 0.00 std::_Vector_base<int, std::allocator<int> >::_M_get_Tp_allocator()
0.00 4.93 0.00 51 0.00 0.00 __gnu_cxx::new_allocator<int>::max_size() const
0.00 4.93 0.00 34 0.00 0.00 __gnu_cxx::__alloc_traits<std::allocator<int> >::max_size(std::allocator<int> const&)
0.00 4.93 0.00 34 0.00 0.00 __gnu_cxx::__normal_iterator<int*, std::vector<int, std::allocator<int> > >::__normal_iterator(int* const&)
0.00 4.93 0.00 34 0.00 0.00 std::_Vector_base<int, std::allocator<int> >::_M_get_Tp_allocator() const
0.00 4.93 0.00 34 0.00 0.00 std::vector<int, std::allocator<int> >::max_size() const
0.00 4.93 0.00 34 0.00 0.00 int* std::__copy_move<false, true, std::random_access_iterator_tag>::__copy_m<int>(int const*, int const*, int*)
0.00 4.93 0.00 34 0.00 0.00 int* std::__uninitialized_copy<true>::__uninit_copy<int*, int*>(int*, int*, int*)
0.00 4.93 0.00 34 0.00 0.00 int* std::__copy_move_a<false, int*, int*>(int*, int*, int*)
0.00 4.93 0.00 34 0.00 0.00 int* std::__copy_move_a2<false, int*, int*>(int*, int*, int*)
0.00 4.93 0.00 34 0.00 0.00 int* std::uninitialized_copy<int*, int*>(int*, int*, int*)
0.00 4.93 0.00 34 0.00 0.00 int* std::__uninitialized_copy_a<int*, int*, int>(int*, int*, int*, std::allocator<int>&)
0.00 4.93 0.00 34 0.00 0.00 int* std::__uninitialized_move_if_noexcept_a<int*, int*, std::allocator<int> >(int*, int*, int*, std::allocator<int>&)
0.00 4.93 0.00 34 0.00 0.00 int* std::copy<int*, int*>(int*, int*, int*)
0.00 4.93 0.00 18 0.00 0.00 void std::_Destroy_aux<true>::__destroy<int*>(int*, int*)
0.00 4.93 0.00 18 0.00 0.00 std::_Vector_base<int, std::allocator<int> >::_M_deallocate(int*, unsigned long)
0.00 4.93 0.00 18 0.00 0.00 void std::_Destroy<int*>(int*, int*)
0.00 4.93 0.00 18 0.00 0.00 void std::_Destroy<int*, int>(int*, int*, std::allocator<int>&)
0.00 4.93 0.00 17 0.00 0.00 __gnu_cxx::new_allocator<int>::deallocate(int*, unsigned long)
0.00 4.93 0.00 17 0.00 0.00 __gnu_cxx::new_allocator<int>::allocate(unsigned long, void const*)
0.00 4.93 0.00 17 0.00 0.00 __gnu_cxx::__normal_iterator<int*, std::vector<int, std::allocator<int> > >::difference_type __gnu_cxx::operator-<int*, std::vector<int, std::allocator<int> > >(__gnu_cxx::__normal_iterator<int*, std::vector<int, std::allocator<int> > > const&, __gnu_cxx::__normal_iterator<int*, std::vector<int, std::allocator<int> > > const&)
0.00 4.93 0.00 17 0.00 0.00 std::vector<int, std::allocator<int> >::_M_check_len(unsigned long, char const*) const
0.00 4.93 0.00 17 0.00 0.00 std::_Vector_base<int, std::allocator<int> >::_M_allocate(unsigned long)
0.00 4.93 0.00 17 0.00 0.00 std::vector<int, std::allocator<int> >::_M_insert_aux(__gnu_cxx::__normal_iterator<int*, std::vector<int, std::allocator<int> > >, int const&)
0.00 4.93 0.00 17 0.00 0.00 std::vector<int, std::allocator<int> >::end()
0.00 4.93 0.00 17 0.00 0.00 std::vector<int, std::allocator<int> >::begin()
0.00 4.93 0.00 17 0.00 0.00 unsigned long const& std::max<unsigned long>(unsigned long const&, unsigned long const&)
0.00 4.93 0.00 2 0.00 0.00 std::operator|(std::_Ios_Openmode, std::_Ios_Openmode)
0.00 4.93 0.00 1 0.00 0.00 _GLOBAL__sub_I_main
0.00 4.93 0.00 1 0.00 0.00 generateData(std::basic_ofstream<char, std::char_traits<char> >&)
0.00 4.93 0.00 1 0.00 0.22 writeSortedFile(std::vector<int, std::allocator<int> >&)
0.00 4.93 0.00 1 0.00 0.00 __static_initialization_and_destruction_0(int, int)
0.00 4.93 0.00 1 0.00 0.00 loadBuf(std::vector<int, std::allocator<int> >&, std::basic_ifstream<char, std::char_traits<char> >&)
0.00 4.93 0.00 1 0.00 0.00 __gnu_cxx::new_allocator<int>::new_allocator()
0.00 4.93 0.00 1 0.00 0.00 __gnu_cxx::new_allocator<int>::~new_allocator()
0.00 4.93 0.00 1 0.00 0.00 std::allocator<int>::allocator()
0.00 4.93 0.00 1 0.00 0.00 std::allocator<int>::~allocator()
0.00 4.93 0.00 1 0.00 0.00 std::_Vector_base<int, std::allocator<int> >::_Vector_impl::_Vector_impl()
0.00 4.93 0.00 1 0.00 0.00 std::_Vector_base<int, std::allocator<int> >::_Vector_impl::~_Vector_impl()
0.00 4.93 0.00 1 0.00 0.00 std::_Vector_base<int, std::allocator<int> >::_Vector_base()
0.00 4.93 0.00 1 0.00 0.00 std::_Vector_base<int, std::allocator<int> >::~_Vector_base()
0.00 4.93 0.00 1 0.00 0.00 std::vector<int, std::allocator<int> >::vector()
0.00 4.93 0.00 1 0.00 0.00 std::vector<int, std::allocator<int> >::~vector()
所以,累计秒数没有累计到真实值(~14s),就会出现。结果确实显示 sort()
是最耗时的,但实际时间值并没有加起来。
-z
不会改变这一点,但这是预期的。
调用图(不包括在内)似乎没有显示任何暗示丢失的秒数在哪里的信息;即额外的秒数不在儿童身上。
当我尝试分析我上面提到的更大的算法时,我似乎得到了类似的结果(其中 gprof 给出的时间值比预期的要小得多)- gprof 说 运行 时间约为 450 秒,其中它实际上需要超过 3 小时。我虽然这是由于 gprof 无法处理 MPI,但现在我认为我要么误解了 gprof 结果,要么遗漏了一些标志。
有没有可能我实际上没有考虑我的 gmon.out
文件?
我认为这是因为,当我 运行 gprof ./sort
时,我得到与 gprof ./sort gmon.out
完全相同的结果。因此,它似乎甚至没有使用 gmon.out
。我认为需要 gmon.out
与可执行文件一起将时间映射到函数。 gprof 如何在没有 gmon.out
的情况下产生输出?
非常欢迎任何有启发性的信息,在此先感谢!
注意:
阅读例如 (this post) ,我发现信息表明 gprof 在分析堆分配等方面存在问题 (new
)。我应该注意到 ./sort
使用 std::vector
来保存元素,这些元素将被分配到堆中。如果这是一个可能的问题,请告诉我。
gprof
不知道它没有调试信息访问权限的功能,即标准库。如果你想获得准确的经过时间并仍然得到调用图,你可以使用 perf
。
举个例子,我写了一个循环10000次的程序。在这个循环中,我用 运行dom 值填充一个向量,然后对其进行排序。对于 gprof
,我执行以下步骤:
g++ -std=c++11 -O2 -pg -g
./a.out
gprof -b ./a.out
gmon.out
不存在则创建,存在则覆盖,如果不指定要使用的文件,gprof
会自动使用。 -b
抑制文本简介。
这是示例输出:
Each sample counts as 0.01 seconds.
% cumulative self self total
time seconds seconds calls Ts/call Ts/call name
100.52 4.94 4.94 frame_dummy
0.00 4.94 0.00 26 0.00 0.00 void std::__adjust_heap<__gnu_cxx::__normal_iterator<double*, std::vector<double, std::allocator<double> > >, long, double, __gnu_cxx::__ops::_Iter_less_iter>(__gnu_cxx::__normal_iterator<double*, std::vector<double, std::allocator<double> > >, long, long, double, __gnu_cxx::__ops::_Iter_less_iter)
0.00 4.94 0.00 1 0.00 0.00 _GLOBAL__sub_I_main
如你所见,它只记录向量堆实现的时间,而根本不知道排序(或其他任何东西)。现在让我们试试 perf
:
perf record -g ./a.out
perf report --call-graph --stdio
# Total Lost Samples: 0
#
# Samples: 32K of event 'cycles'
# Event count (approx.): 31899806183
#
# Children Self Command Shared Object Symbol
# ........ ........ ....... ................... ..................................................................................
#
99.98% 34.46% a.out a.out [.] main
|
|--65.52%-- main
| |
| |--65.29%-- std::__introsort_loop<__gnu_cxx::__normal_iterator<double*, std::vector<double
[省略其余文字]
如您所见,perf
捕获了排序函数。如果我运行perf stat
,我也会得到准确的运行时间。
如果您使用的是 GCC,您可以传递 -D_GLIBCXX_DEBUG
让它使用调试库实现。这将使您的代码 运行 变慢很多,但为了让 gprof
看到这些函数是必要的。一个例子:
g++ -std=c++11 -O2 test.cpp -D_GLIBCXX_DEBUG -pg -g
./a.out
gprof -b ./a.out
Each sample counts as 0.01 seconds.
% cumulative self self total
time seconds seconds calls us/call us/call name
88.26 0.15 0.15 102875 1.46 1.46 __gnu_debug::_Safe_iterator<__gnu_cxx::__normal_iterator<double*, std::__cxx1998::vector<double, std::allocator<double> > >, std::__debug::vector<double, std::allocator<double> > > std::__unguarded_partition<__gnu_debug::_Safe_iterator<__gnu_cxx::__normal_iterator<double*, std::__cxx1998::vector<double, std::allocator<double> > >, std::__debug::vector<double, std::allocator<double> > >, __gnu_cxx::__ops::_Iter_less_iter>(__gnu_debug::_Safe_iterator<__gnu_cxx::__normal_iterator<double*, std::__cxx1998::vector<double, std::allocator<double> > >, std::__debug::vector<double, std::allocator<double> > >, __gnu_debug::_Safe_iterator<__gnu_cxx::__normal_iterator<double*, std::__cxx1998::vector<double, std::allocator<double> > >, std::__debug::vector<double, std::allocator<double> > >, __gnu_debug::_Safe_iterator<__gnu_cxx::__normal_iterator<double*, std::__cxx1998::vector<double, std::allocator<double> > >, std::__debug::vector<double, std::allocator<double> > >, __gnu_cxx::__ops::_Iter_less_iter)
11.77 0.17 0.02 996280 0.02 0.02 void std::__unguarded_linear_insert<__gnu_debug::_Safe_iterator<__gnu_cxx::__normal_iterator<double*, std::__cxx1998::vector<double, std::allocator<double> > >, std::__debug::vector<double, std::allocator<double> > >, __gnu_cxx::__ops::_Val_less_iter>(__gnu_debug::_Safe_iterator<__gnu_cxx::__normal_iterator<double*, std::__cxx1998::vector<double, std::allocator<double> > >, std::__debug::vector<double, std::allocator<double> > >, __gnu_cxx::__ops::_Val_less_iter)
0.00 0.17 0.00 417220 0.00 0.00 frame_dummy
0.00 0.17 0.00 102875 0.00 0.00 void std::__move_median_to_first<__gnu_debug::_Safe_iterator<__gnu_cxx::__normal_iterator<double*, std::__cxx1998::vector<double, std::allocator<double> > >, std::__debug::vector<double, std::allocator<double> > >, __gnu_cxx::__ops::_Iter_less_iter>(__gnu_debug::_Safe_iterator<__gnu_cxx::__normal_iterator<double*, std::__cxx1998::vector<double, std::allocator<double> > >, std::__debug::vector<double, std::allocator<double> > >, __gnu_debug::_Safe_iterator<__gnu_cxx::__normal_iterator<double*, std::__cxx1998::vector<double, std::allocator<double> > >, std::__debug::vector<double, std::allocator<double> > >, __gnu_debug::_Safe_iterator<__gnu_cxx::__normal_iterator<double*, std::__cxx1998::vector<double, std::allocator<double> > >, std::__debug::vector<double, std::allocator<double> > >, __gnu_debug::_Safe_iterator<__gnu_cxx::__normal_iterator<double*, std::__cxx1998::vector<double, std::allocator<double> > >, std::__debug::vector<double, std::allocator<double> > >, __gnu_cxx::__ops::_Iter_less_iter)
0.00 0.17 0.00 1000 0.00 0.25 void std::__insertion_sort<__gnu_debug::_Safe_iterator<__gnu_cxx::__normal_iterator<double*, std::__cxx1998::vector<double, std::allocator<double> > >, std::__debug::vector<double, std::allocator<double> > >, __gnu_cxx::__ops::_Iter_less_iter>(__gnu_debug::_Safe_iterator<__gnu_cxx::__normal_iterator<double*, std::__cxx1998::vector<double, std::allocator<double> > >, std::__debug::vector<double, std::allocator<double> > >, __gnu_debug::_Safe_iterator<__gnu_cxx::__normal_iterator<double*, std::__cxx1998::vector<double, std::allocator<double> > >, std::__debug::vector<double, std::allocator<double> > >, __gnu_cxx::__ops::_Iter_less_iter)
0.00 0.17 0.00 1 0.00 0.00 _GLOBAL__sub_I_main
我特意减少了迭代次数以使执行在合理的时间内完成,但是您看到 gprof
现在显示了以前未计算在内的函数。
我有一个简单的排序程序,我正在对它进行分析,以便有一个案例来研究 gprof;我稍后计划分析一个更大的算法。
我已经使用 -pg
和 运行 ./sort 编译生成 gmon.out
文件。
但是,当我 运行 gprof ./sort gmon.out
时,累积秒数和自身秒数产生的值,我认为是不准确的。
首先,运行宁time(./sort)
我得到:
real 0m14.352s
user 0m14.330s
sys 0m0.005s
我的秒表是准确的。
但是,平面配置文件的 gprof 结果是:
Each sample counts as 0.01 seconds.
% cumulative self self total
time seconds seconds calls s/call s/call name
56.18 2.76 2.76 1 2.76 4.71 sort(std::vector<int, std::allocator<int> >&)
35.01 4.49 1.72 1870365596 0.00 0.00 std::vector<int, std::allocator<int> >::operator[](unsigned long)
8.96 4.93 0.44 100071 0.00 0.00 std::vector<int, std::allocator<int> >::size() const
0.00 4.93 0.00 50001 0.00 0.00 __gnu_cxx::new_allocator<int>::construct(int*, int const&)
0.00 4.93 0.00 50001 0.00 0.00 void __gnu_cxx::__alloc_traits<std::allocator<int> >::construct<int>(std::allocator<int>&, int*, int const&)
0.00 4.93 0.00 50001 0.00 0.00 std::vector<int, std::allocator<int> >::push_back(int const&)
0.00 4.93 0.00 50001 0.00 0.00 operator new(unsigned long, void*)
0.00 4.93 0.00 170 0.00 0.00 std::_Iter_base<int*, false>::_S_base(int*)
0.00 4.93 0.00 102 0.00 0.00 std::_Niter_base<int*>::iterator_type std::__niter_base<int*>(int*)
0.00 4.93 0.00 68 0.00 0.00 __gnu_cxx::__normal_iterator<int*, std::vector<int, std::allocator<int> > >::base() const
0.00 4.93 0.00 68 0.00 0.00 std::_Miter_base<int*>::iterator_type std::__miter_base<int*>(int*)
0.00 4.93 0.00 52 0.00 0.00 std::_Vector_base<int, std::allocator<int> >::_M_get_Tp_allocator()
0.00 4.93 0.00 51 0.00 0.00 __gnu_cxx::new_allocator<int>::max_size() const
0.00 4.93 0.00 34 0.00 0.00 __gnu_cxx::__alloc_traits<std::allocator<int> >::max_size(std::allocator<int> const&)
0.00 4.93 0.00 34 0.00 0.00 __gnu_cxx::__normal_iterator<int*, std::vector<int, std::allocator<int> > >::__normal_iterator(int* const&)
0.00 4.93 0.00 34 0.00 0.00 std::_Vector_base<int, std::allocator<int> >::_M_get_Tp_allocator() const
0.00 4.93 0.00 34 0.00 0.00 std::vector<int, std::allocator<int> >::max_size() const
0.00 4.93 0.00 34 0.00 0.00 int* std::__copy_move<false, true, std::random_access_iterator_tag>::__copy_m<int>(int const*, int const*, int*)
0.00 4.93 0.00 34 0.00 0.00 int* std::__uninitialized_copy<true>::__uninit_copy<int*, int*>(int*, int*, int*)
0.00 4.93 0.00 34 0.00 0.00 int* std::__copy_move_a<false, int*, int*>(int*, int*, int*)
0.00 4.93 0.00 34 0.00 0.00 int* std::__copy_move_a2<false, int*, int*>(int*, int*, int*)
0.00 4.93 0.00 34 0.00 0.00 int* std::uninitialized_copy<int*, int*>(int*, int*, int*)
0.00 4.93 0.00 34 0.00 0.00 int* std::__uninitialized_copy_a<int*, int*, int>(int*, int*, int*, std::allocator<int>&)
0.00 4.93 0.00 34 0.00 0.00 int* std::__uninitialized_move_if_noexcept_a<int*, int*, std::allocator<int> >(int*, int*, int*, std::allocator<int>&)
0.00 4.93 0.00 34 0.00 0.00 int* std::copy<int*, int*>(int*, int*, int*)
0.00 4.93 0.00 18 0.00 0.00 void std::_Destroy_aux<true>::__destroy<int*>(int*, int*)
0.00 4.93 0.00 18 0.00 0.00 std::_Vector_base<int, std::allocator<int> >::_M_deallocate(int*, unsigned long)
0.00 4.93 0.00 18 0.00 0.00 void std::_Destroy<int*>(int*, int*)
0.00 4.93 0.00 18 0.00 0.00 void std::_Destroy<int*, int>(int*, int*, std::allocator<int>&)
0.00 4.93 0.00 17 0.00 0.00 __gnu_cxx::new_allocator<int>::deallocate(int*, unsigned long)
0.00 4.93 0.00 17 0.00 0.00 __gnu_cxx::new_allocator<int>::allocate(unsigned long, void const*)
0.00 4.93 0.00 17 0.00 0.00 __gnu_cxx::__normal_iterator<int*, std::vector<int, std::allocator<int> > >::difference_type __gnu_cxx::operator-<int*, std::vector<int, std::allocator<int> > >(__gnu_cxx::__normal_iterator<int*, std::vector<int, std::allocator<int> > > const&, __gnu_cxx::__normal_iterator<int*, std::vector<int, std::allocator<int> > > const&)
0.00 4.93 0.00 17 0.00 0.00 std::vector<int, std::allocator<int> >::_M_check_len(unsigned long, char const*) const
0.00 4.93 0.00 17 0.00 0.00 std::_Vector_base<int, std::allocator<int> >::_M_allocate(unsigned long)
0.00 4.93 0.00 17 0.00 0.00 std::vector<int, std::allocator<int> >::_M_insert_aux(__gnu_cxx::__normal_iterator<int*, std::vector<int, std::allocator<int> > >, int const&)
0.00 4.93 0.00 17 0.00 0.00 std::vector<int, std::allocator<int> >::end()
0.00 4.93 0.00 17 0.00 0.00 std::vector<int, std::allocator<int> >::begin()
0.00 4.93 0.00 17 0.00 0.00 unsigned long const& std::max<unsigned long>(unsigned long const&, unsigned long const&)
0.00 4.93 0.00 2 0.00 0.00 std::operator|(std::_Ios_Openmode, std::_Ios_Openmode)
0.00 4.93 0.00 1 0.00 0.00 _GLOBAL__sub_I_main
0.00 4.93 0.00 1 0.00 0.00 generateData(std::basic_ofstream<char, std::char_traits<char> >&)
0.00 4.93 0.00 1 0.00 0.22 writeSortedFile(std::vector<int, std::allocator<int> >&)
0.00 4.93 0.00 1 0.00 0.00 __static_initialization_and_destruction_0(int, int)
0.00 4.93 0.00 1 0.00 0.00 loadBuf(std::vector<int, std::allocator<int> >&, std::basic_ifstream<char, std::char_traits<char> >&)
0.00 4.93 0.00 1 0.00 0.00 __gnu_cxx::new_allocator<int>::new_allocator()
0.00 4.93 0.00 1 0.00 0.00 __gnu_cxx::new_allocator<int>::~new_allocator()
0.00 4.93 0.00 1 0.00 0.00 std::allocator<int>::allocator()
0.00 4.93 0.00 1 0.00 0.00 std::allocator<int>::~allocator()
0.00 4.93 0.00 1 0.00 0.00 std::_Vector_base<int, std::allocator<int> >::_Vector_impl::_Vector_impl()
0.00 4.93 0.00 1 0.00 0.00 std::_Vector_base<int, std::allocator<int> >::_Vector_impl::~_Vector_impl()
0.00 4.93 0.00 1 0.00 0.00 std::_Vector_base<int, std::allocator<int> >::_Vector_base()
0.00 4.93 0.00 1 0.00 0.00 std::_Vector_base<int, std::allocator<int> >::~_Vector_base()
0.00 4.93 0.00 1 0.00 0.00 std::vector<int, std::allocator<int> >::vector()
0.00 4.93 0.00 1 0.00 0.00 std::vector<int, std::allocator<int> >::~vector()
所以,累计秒数没有累计到真实值(~14s),就会出现。结果确实显示 sort()
是最耗时的,但实际时间值并没有加起来。
-z
不会改变这一点,但这是预期的。
调用图(不包括在内)似乎没有显示任何暗示丢失的秒数在哪里的信息;即额外的秒数不在儿童身上。
当我尝试分析我上面提到的更大的算法时,我似乎得到了类似的结果(其中 gprof 给出的时间值比预期的要小得多)- gprof 说 运行 时间约为 450 秒,其中它实际上需要超过 3 小时。我虽然这是由于 gprof 无法处理 MPI,但现在我认为我要么误解了 gprof 结果,要么遗漏了一些标志。
有没有可能我实际上没有考虑我的 gmon.out
文件?
我认为这是因为,当我 运行 gprof ./sort
时,我得到与 gprof ./sort gmon.out
完全相同的结果。因此,它似乎甚至没有使用 gmon.out
。我认为需要 gmon.out
与可执行文件一起将时间映射到函数。 gprof 如何在没有 gmon.out
的情况下产生输出?
非常欢迎任何有启发性的信息,在此先感谢!
注意:
阅读例如 (this post) ,我发现信息表明 gprof 在分析堆分配等方面存在问题 (new
)。我应该注意到 ./sort
使用 std::vector
来保存元素,这些元素将被分配到堆中。如果这是一个可能的问题,请告诉我。
gprof
不知道它没有调试信息访问权限的功能,即标准库。如果你想获得准确的经过时间并仍然得到调用图,你可以使用 perf
。
举个例子,我写了一个循环10000次的程序。在这个循环中,我用 运行dom 值填充一个向量,然后对其进行排序。对于 gprof
,我执行以下步骤:
g++ -std=c++11 -O2 -pg -g
./a.out
gprof -b ./a.out
gmon.out
不存在则创建,存在则覆盖,如果不指定要使用的文件,gprof
会自动使用。 -b
抑制文本简介。
这是示例输出:
Each sample counts as 0.01 seconds.
% cumulative self self total
time seconds seconds calls Ts/call Ts/call name
100.52 4.94 4.94 frame_dummy
0.00 4.94 0.00 26 0.00 0.00 void std::__adjust_heap<__gnu_cxx::__normal_iterator<double*, std::vector<double, std::allocator<double> > >, long, double, __gnu_cxx::__ops::_Iter_less_iter>(__gnu_cxx::__normal_iterator<double*, std::vector<double, std::allocator<double> > >, long, long, double, __gnu_cxx::__ops::_Iter_less_iter)
0.00 4.94 0.00 1 0.00 0.00 _GLOBAL__sub_I_main
如你所见,它只记录向量堆实现的时间,而根本不知道排序(或其他任何东西)。现在让我们试试 perf
:
perf record -g ./a.out
perf report --call-graph --stdio
# Total Lost Samples: 0
#
# Samples: 32K of event 'cycles'
# Event count (approx.): 31899806183
#
# Children Self Command Shared Object Symbol
# ........ ........ ....... ................... ..................................................................................
#
99.98% 34.46% a.out a.out [.] main
|
|--65.52%-- main
| |
| |--65.29%-- std::__introsort_loop<__gnu_cxx::__normal_iterator<double*, std::vector<double
[省略其余文字]
如您所见,perf
捕获了排序函数。如果我运行perf stat
,我也会得到准确的运行时间。
如果您使用的是 GCC,您可以传递 -D_GLIBCXX_DEBUG
让它使用调试库实现。这将使您的代码 运行 变慢很多,但为了让 gprof
看到这些函数是必要的。一个例子:
g++ -std=c++11 -O2 test.cpp -D_GLIBCXX_DEBUG -pg -g
./a.out
gprof -b ./a.out
Each sample counts as 0.01 seconds.
% cumulative self self total
time seconds seconds calls us/call us/call name
88.26 0.15 0.15 102875 1.46 1.46 __gnu_debug::_Safe_iterator<__gnu_cxx::__normal_iterator<double*, std::__cxx1998::vector<double, std::allocator<double> > >, std::__debug::vector<double, std::allocator<double> > > std::__unguarded_partition<__gnu_debug::_Safe_iterator<__gnu_cxx::__normal_iterator<double*, std::__cxx1998::vector<double, std::allocator<double> > >, std::__debug::vector<double, std::allocator<double> > >, __gnu_cxx::__ops::_Iter_less_iter>(__gnu_debug::_Safe_iterator<__gnu_cxx::__normal_iterator<double*, std::__cxx1998::vector<double, std::allocator<double> > >, std::__debug::vector<double, std::allocator<double> > >, __gnu_debug::_Safe_iterator<__gnu_cxx::__normal_iterator<double*, std::__cxx1998::vector<double, std::allocator<double> > >, std::__debug::vector<double, std::allocator<double> > >, __gnu_debug::_Safe_iterator<__gnu_cxx::__normal_iterator<double*, std::__cxx1998::vector<double, std::allocator<double> > >, std::__debug::vector<double, std::allocator<double> > >, __gnu_cxx::__ops::_Iter_less_iter)
11.77 0.17 0.02 996280 0.02 0.02 void std::__unguarded_linear_insert<__gnu_debug::_Safe_iterator<__gnu_cxx::__normal_iterator<double*, std::__cxx1998::vector<double, std::allocator<double> > >, std::__debug::vector<double, std::allocator<double> > >, __gnu_cxx::__ops::_Val_less_iter>(__gnu_debug::_Safe_iterator<__gnu_cxx::__normal_iterator<double*, std::__cxx1998::vector<double, std::allocator<double> > >, std::__debug::vector<double, std::allocator<double> > >, __gnu_cxx::__ops::_Val_less_iter)
0.00 0.17 0.00 417220 0.00 0.00 frame_dummy
0.00 0.17 0.00 102875 0.00 0.00 void std::__move_median_to_first<__gnu_debug::_Safe_iterator<__gnu_cxx::__normal_iterator<double*, std::__cxx1998::vector<double, std::allocator<double> > >, std::__debug::vector<double, std::allocator<double> > >, __gnu_cxx::__ops::_Iter_less_iter>(__gnu_debug::_Safe_iterator<__gnu_cxx::__normal_iterator<double*, std::__cxx1998::vector<double, std::allocator<double> > >, std::__debug::vector<double, std::allocator<double> > >, __gnu_debug::_Safe_iterator<__gnu_cxx::__normal_iterator<double*, std::__cxx1998::vector<double, std::allocator<double> > >, std::__debug::vector<double, std::allocator<double> > >, __gnu_debug::_Safe_iterator<__gnu_cxx::__normal_iterator<double*, std::__cxx1998::vector<double, std::allocator<double> > >, std::__debug::vector<double, std::allocator<double> > >, __gnu_debug::_Safe_iterator<__gnu_cxx::__normal_iterator<double*, std::__cxx1998::vector<double, std::allocator<double> > >, std::__debug::vector<double, std::allocator<double> > >, __gnu_cxx::__ops::_Iter_less_iter)
0.00 0.17 0.00 1000 0.00 0.25 void std::__insertion_sort<__gnu_debug::_Safe_iterator<__gnu_cxx::__normal_iterator<double*, std::__cxx1998::vector<double, std::allocator<double> > >, std::__debug::vector<double, std::allocator<double> > >, __gnu_cxx::__ops::_Iter_less_iter>(__gnu_debug::_Safe_iterator<__gnu_cxx::__normal_iterator<double*, std::__cxx1998::vector<double, std::allocator<double> > >, std::__debug::vector<double, std::allocator<double> > >, __gnu_debug::_Safe_iterator<__gnu_cxx::__normal_iterator<double*, std::__cxx1998::vector<double, std::allocator<double> > >, std::__debug::vector<double, std::allocator<double> > >, __gnu_cxx::__ops::_Iter_less_iter)
0.00 0.17 0.00 1 0.00 0.00 _GLOBAL__sub_I_main
我特意减少了迭代次数以使执行在合理的时间内完成,但是您看到 gprof
现在显示了以前未计算在内的函数。