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()が最も時間がかかることを示していますが、実際の時間値は加算されません。 -zはこれを変更しませんが、期待通りです。 コールグラフ（含まれていない）は、秒がどこにないか示唆するものは表示されません。すなわち余分な秒は小児にはない。

私が上記の私のより大きいアルゴリズムを試してみると、gprofは実行時間が〜450sで、実際には3時間かかるので、私は似たような結果を得ているようです。私はこれはgprofがMPIを扱うことができないためです。これは大規模なアルゴリズムが広範囲に使用されていますが、現在私はgpr​​ofの結果を誤解していると思います。

私は実際に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回ループするプログラムを書いた。このループでは、ランダムな値を持つベクトルを塗りつぶして並べ替えます。 gprofのために、私は、次の手順を実行します。

g++ -std=c++11 -O2 -pg -g 
./a.out 
gprof -b ./a.out 

gmon.outは、それが存在しない場合は作成され、それがないと、あなたが使用するファイルを指定しない場合、自動的にgprofで使用されている場合、上書きされます。 -bは、テキストblurbsを抑制します。

ここでの出力例です：あなたが見ることができるように、それが唯一のベクトルヒープ実装のための時間を記録し、すべてのソート（または何か他のもの）について知らない

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が、今では以前に数えていなかった機能を示してご覧ください。