Divergence entre gprof et (unix) temps; gprof rapporte des temps d'exécution inférieurs

Question

J'ai un programme de tri simple, que je suis en train de profiler afin d'avoir un cas pour étudier gprof; Je prévois plus tard de profiler un algorithme beaucoup plus grand. J'ai compilé avec -pg et couru ./sort pour produire le fichier gmon.out. Cependant, quand je cours gprof ./sort gmon.out les valeurs produites en secondes cumulatives et auto-secondes sont, comme je crois, inexactes.

Tout d'abord, en cours d'exécution time(./sort) je reçois:

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

Ce qui est exact avec mon chronomètre.

Cependant, les résultats de gprof pour le profil plat sont:

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() 

Ainsi, les secondes cumulées ne s'accumulent pas à la valeur réelle (~ 14s), il semblerait. Les résultats montrent que sort() est la plus coûteuse en temps, mais les valeurs de temps réelles ne s'additionnent pas. -z ne change pas cela, mais c'est prévu. Le graphique d'appel (non inclus), ne semble pas montrer quoi que ce soit qui suggère où les secondes manquantes sont; c'est-à-dire que les secondes supplémentaires ne sont pas chez les enfants. Je semble obtenir des résultats similaires (où gprof donne des valeurs de temps beaucoup plus petites que prévu) quand j'essaie de profiler mon plus grand algorithme que je mentionne ci-dessus - gprof dit que le runtime est ~ 450s, alors qu'il prend plus de 3hrs. Je pensais que cela était dû au fait que gprof ne pouvait pas gérer MPI, ce que l'algorithme plus grand utilise intensivement, mais maintenant je pense que je suis soit en train d'interpréter les résultats de gprof, soit il me manque des drapeaux.

Est-il possible que je ne prenne pas réellement en compte mon fichier gmon.out? La raison pour laquelle je pense que c'est que, quand je cours gprof ./sort je reçois les mêmes résultats que gprof ./sort gmon.out. Par conséquent, il semble que ce n'est même pas en utilisant gmon.out. Je pensais que gmon.out était nécessaire en conjonction avec l'exécutable pour mapper le temps à des fonctions. Comment gprof peut-il produire une sortie sans gmon.out?

Toute information éclairante est plus que bienvenue, merci d'avance!

NOTE: en lisant par exemple par exemple (this post), j'ai trouvé des informations suggérant que gprof a des problèmes avec l'allocation de tas d'analyse etc (new). Je devrais noter que ./sort utilise std::vector pour contenir des éléments, qui seront alloués à tas. S'il vous plaît laissez-moi savoir si c'est un problème possible.

Answer 1

gprof ne connaît pas les fonctions pour lesquelles il n'a pas d'accès aux informations de débogage, c'est-à-dire la bibliothèque standard. Si vous voulez obtenir un temps écoulé précis et toujours obtenir un callgraph, vous pouvez utiliser perf.

À titre d'exemple, j'ai écrit un programme qui boucle 10 000 fois. Dans cette boucle, je remplis un vecteur avec des valeurs aléatoires, puis je le trier. Pour gprof, je fais les étapes suivantes:

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

gmon.out est créé si elle n'existe pas, et si elle le fait écrasé et est automatiquement utilisé par gprof si vous ne spécifiez pas de fichier à utiliser. -b supprime les textes de présentation.

est ici un exemple de sortie:

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 

Comme vous pouvez le voir, il enregistre seulement le temps pour la mise en œuvre du tas de vecteur, et ne sait pas genre (ou quoi que ce soit d'autre) du tout. Maintenant, nous allons essayer 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 

[reste du texte omis]

Comme vous pouvez le voir, perf captures, la fonction de tri. Si je courais perf stat, j'obtiendrais également l'exécution précise.

Si vous utilisez GCC, vous pouvez passer le -D_GLIBCXX_DEBUG pour qu'il utilise l'implémentation de la bibliothèque de débogage. Cela rendra votre code beaucoup plus lent, mais nécessaire afin que gprof puisse voir ces fonctions. Un exemple:

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 

Je délibérément réduit la quantité d'itérations pour rendre l'exécution complète dans un laps de temps raisonnable, mais vous voyez maintenant gprof montre les fonctions qu'il ne comptait pas avant.