I have simple sorting program, which I am profiling in order to have a case to study gprof; I later plan to profile a much larger algorithm.
I have compiled with -pg and ran ./sort to produce the gmon.out file.
However, when I run gprof ./sort gmon.out the values produced in cumulative seconds and self seconds are, as I believe, not accurate.
Firstly, running time(./sort) I get:
real 0m14.352s
user 0m14.330s
sys 0m0.005s
Which is accurate with my stopwatch.
However, the gprof results for the flat profile are:
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()
So, the cumulative seconds do not accumulate to the true value (~14s), it would appear. The results do show that sort() is the most time costly, but the actual time values do not add up.
-z does not change this, but thats expected.
The call graph (not included), does not seem to show anything that suggests where the missing seconds are; i.e the extra seconds are not in children.
I seem to get similar results (where gprof gives much smaller time values than expected) when I try and profile my larger algorithm which I mention above - gprof says the runtime is ~450s, where as it actually takes over 3hrs. I though this was due to gprof not being able to handle MPI, which the larger algorithm uses extensively, but now I think I am either misinterpreting the gprof results, or I am missing some flags.
Is it possible I am not actually taking into account my gmon.out file?
The reason I think this is that, when I run gprof ./sort I get the exact same results as gprof ./sort gmon.out. Therefore, it seems like its not even using gmon.out. I thought gmon.out was needed in conjunction with the executable to map time to functions. How can gprof produce an output without gmon.out?
Any enlightening information is more than welcome, thanks in advance!
NOTE:
reading around e.g (this post) , I found info suggesting that gprof has trouble with analysis heap allocation etc (new). I should note that ./sort uses std::vector to hold elements, which will be allocated to heap. Please let me know if this is a possible issue.
gprof doesn't know about functions it doesn't have debug info access to, i.e the standard library. If you want to get accurate elapsed time and still get a callgraph you can use perf.
As an example I wrote a program that loops 10000 times. In this loop, I fill a vector with random values and then sort it. For gprof, I do the following steps:
g++ -std=c++11 -O2 -pg -g
./a.out
gprof -b ./a.out
gmon.out is created if it doesn't exist, and overwritten if it does, and is automatically used by gprof if you don't specify a file to use. -b suppresses the text blurbs.
Here's example output:
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
As you can see, it only records the time for the vector heap implementation, and doesn't know about sort (or anything else) at all. Now let's try 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
[Rest of text omitted]
As you can see, perf catches the sort function. If I ran perf stat, I would also get the accurate runtime.
If you're using GCC, you can pass -D_GLIBCXX_DEBUG to have it use the debug library implementation. This will make your code run a lot slower, but necessary in order for gprof to see those functions. An example:
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
I deliberately reduced the amount of iterations to make the execution complete in a reasonable amount of time, but you see gprof now shows the functions it wasn't counting before.