Diskrepanz zwischen Gprof und (Unix) Zeit; gprof meldet niedrigere Laufzeiten

Question

Ich habe ein einfaches Sortierprogramm, das ich profile, um einen Fall zu haben, gprof zu studieren; Ich plane später, einen viel größeren Algorithmus zu profilieren.

Ich habe mit -pg kompiliert und lief ./sort die gmon.out Datei zu produzieren. Wenn ich jedoch gprof ./sort gmon.out ausführen, sind die Werte, die in kumulativen Sekunden und Selbstsekunden produziert werden, wie ich glaube, nicht genau.

Erstens läuft time(./sort) ich:

real 0m14.352s 
user 0m14.330s 
sys  0m0.005s 

, die mit meiner Stoppuhr genau ist.

jedoch die gprof Ergebnisse für das flache Profil sind:

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 werden die kumulierten Sekunden sammeln sich nicht auf den wahren Wert (~ 14s), so scheint es. Die Ergebnisse zeigen, dass sort() am teuersten ist, aber die tatsächlichen Zeitwerte addieren sich nicht. -z ändert dies nicht, aber das ist zu erwarten. Das Call Graph (nicht im Lieferumfang enthalten), scheint nichts zu zeigen, wo die fehlenden Sekunden sind; d. h. die zusätzlichen Sekunden sind nicht in Kindern.

Ich scheine ähnliche Ergebnisse zu erhalten (wo gprof viel kleinere Zeitwerte als erwartet gibt), wenn ich versuche und meinen größeren Algorithmus profiliere, den ich oben erwähne - gprof sagt die Laufzeit ist ~ 450s, wo es tatsächlich über 3 Stunden dauert. Ich dachte, dies sei darauf zurückzuführen, dass gprof nicht in der Lage ist, mit MPI umzugehen, was der größere Algorithmus ausgiebig nutzt, aber jetzt denke ich, dass ich die gprof-Ergebnisse entweder falsch interpretiere oder mir einige Flags vermisse.

Ist es möglich, dass ich meine gmon.out Datei nicht wirklich in Betracht ziehe? Der Grund, warum ich das denke ist, dass, wenn ich gprof ./sort laufen lasse ich die exakt gleichen Ergebnisse wie gprof ./sort gmon.out bekomme. Daher scheint es, als ob es nicht einmal gmon.out verwendet. Ich dachte, gmon.out wurde in Verbindung mit der ausführbaren Datei benötigt, um Zeit auf Funktionen abzubilden. Wie kann gprof eine Ausgabe ohne gmon.out erzeugen?

Jede aufschlussreiche Information ist mehr als willkommen, danke im Voraus!

HINWEIS: lesen rund um, z. B. (this post), fand ich Informationen, die darauf hindeutet, dass Gprof Probleme mit der Analyse Heap Zuordnung usw. (new) hat. Ich sollte beachten, dass ./sortstd::vector verwendet, um Elemente zu halten, die Heap zugeordnet werden. Bitte lassen Sie mich wissen, wenn dies ein mögliches Problem ist.

Answer 1

gprof weiß nicht über Funktionen, die es nicht Debug-Info-Zugriff auf hat, d. H. Die Standard-Bibliothek. Wenn Sie die genaue verstrichene Zeit erhalten möchten und trotzdem einen Callgraph erhalten möchten, können Sie perf verwenden.

Als Beispiel habe ich ein Programm geschrieben, das 10000-mal wiederholt. In dieser Schleife fülle ich einen Vektor mit zufälligen Werten und sortiere ihn dann. Für gprof, mache ich die folgenden Schritte:

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

gmon.out erstellt, wenn es nicht vorhanden ist, und überschrieben, wenn es der Fall ist, und wird verwendet, um automatisch durch gprof wenn Sie nicht über eine Datei zu verwenden, angeben. -b unterdrückt die Textflecken.

Hier Beispiel Ausgabe:

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 

Wie Sie sehen können, es zeichnet nur die Zeit für die Vektor Heap-Implementierung, und weiß nicht, über Art (oder etwas anderes) überhaupt. Jetzt versuchen sie 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 des Textes weggelassen]

Wie Sie sehen können, perf Fänge die Sortierfunktion. Wenn ich perf stat lief, würde ich auch die genaue Laufzeit bekommen.

Wenn Sie GCC verwenden, können Sie -D_GLIBCXX_DEBUG übergeben, damit es die Debug-Bibliothek-Implementierung verwendet. Dies wird Ihren Code viel langsamer laufen lassen, aber notwendig, damit gprof diese Funktionen sehen können. Ein Beispiel:

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 

mir bewusst reduzierte die Menge an Iterationen die Ausführung komplett in einer angemessenen Höhe der Zeit zu machen, aber Sie sehen gprof jetzt zeigen die Funktionen, die es vorher nicht rechnet.