c++ - gprof 和 (unix) 时间之间的差异； gprof 报告运行时间较短

Question

我有一个简单的排序程序，我正在对其进行分析，以便有一个案例来研究 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()是最耗费时间的，但实际时间值(value)并没有相加。 -z不会改变这一点，但这是预期的。 调用图(不包括在内)似乎没有显示任何表明丢失的秒数在哪里的信息；也就是说，额外的几秒钟不属于 child 。

当我尝试分析上面提到的更大的算法时，我似乎得到了类似的结果(其中 gprof 给出的时间值比预期小得多) - gprof 说运行时间约为 450 秒，而实际上它需要超过 3 小时。我认为这是由于 gprof 无法处理 MPI，而较大的算法广泛使用 MPI，但现在我认为我要么误解了 gprof 结果，要么缺少一些标志。

我是否有可能实际上没有考虑我的 gmon.out文件？ 我认为这是因为，当我运行 gprof ./sort 时我得到与 gprof ./sort gmon.out 完全相同的结果。因此，它似乎甚至没有使用 gmon.out 。我以为gmon.out需要与可执行文件结合起来将时间映射到函数。 gprof 如何在没有 gmon.out 的情况下产生输出？

非常欢迎任何有启发性的信息，提前致谢!

注意: 阅读例如( this post )，我发现信息表明 gprof 在分析堆分配等方面存在问题( new )。我应该注意./sort使用std::vector保存将分配到堆的元素。如果这可能是一个问题，请告诉我。

Answer 1

gprof 不知道它无法访问调试信息的函数，即标准库。如果您想获得准确的耗时并仍然获得调用图，您可以使用perf。

作为示例，我编写了一个循环 10000 次的程序。在此循环中，我用随机值填充 vector ，然后对其进行排序。对于 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

正如你所看到的，它只记录 vector 堆实现的时间，根本不知道排序(或其他任何东西)。现在让我们尝试一下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 现在显示了之前未计算的函数。