Que mesure exactement le profilage C ++ (outils Google cpu perf)?

Question

J'essaie de démarrer avec Google Perf Tools pour profiler certaines applications gourmandes en ressources CPU. C'est un calcul statistique qui vide chaque étape dans un fichier en utilisant `ofstream '. Je ne suis pas un expert en C ++, alors j'ai du mal à trouver le goulot d'étranglement. Mon premier passage donne des résultats:

Total: 857 samples
     357  41.7%  41.7%      357  41.7% _write$UNIX2003
     134  15.6%  57.3%      134  15.6% _exp$fenv_access_off
     109  12.7%  70.0%      276  32.2% scythe::dnorm
     103  12.0%  82.0%      103  12.0% _log$fenv_access_off
      58   6.8%  88.8%       58   6.8% scythe::const_matrix_forward_iterator::operator*
      37   4.3%  93.1%       37   4.3% scythe::matrix_forward_iterator::operator*
      15   1.8%  94.9%       47   5.5% std::transform
      13   1.5%  96.4%      486  56.7% SliceStep::DoStep
      10   1.2%  97.5%       10   1.2% 0x0002726c
       5   0.6%  98.1%        5   0.6% 0x000271c7
       5   0.6%  98.7%        5   0.6% _write$NOCANCEL$UNIX2003

Ceci est surprenant, car tout le calcul réel se produit dans SliceStep :: DoStep. Le & Quot; _write $ UNIX2003 & Quot; (Où puis-je savoir ce que c'est?) semble provenir de l'écriture du fichier de sortie. Maintenant, ce qui me dérange, c’est que si je commente toutes les instructions outfile << "text" et exécute pprof, 95% sont dans SliceStep::DoStep et que «_write $ UNIX2003» disparaît. Cependant, mon application ne s’accélère pas, mesurée par le temps total. Le tout accélère moins de 1%.

Qu'est-ce qui me manque?

Ajouté: La sortie de pprof sans les outfile << instructions est:

Total: 790 samples
     205  25.9%  25.9%      205  25.9% _exp$fenv_access_off
     170  21.5%  47.5%      170  21.5% _log$fenv_access_off
     162  20.5%  68.0%      437  55.3% scythe::dnorm
      83  10.5%  78.5%       83  10.5% scythe::const_matrix_forward_iterator::operator*
      70   8.9%  87.3%       70   8.9% scythe::matrix_forward_iterator::operator*
      28   3.5%  90.9%       78   9.9% std::transform
      26   3.3%  94.2%       26   3.3% 0x00027262
      12   1.5%  95.7%       12   1.5% _write$NOCANCEL$UNIX2003
      11   1.4%  97.1%      764  96.7% SliceStep::DoStep
       9   1.1%  98.2%        9   1.1% 0x00027253
       6   0.8%  99.0%        6   0.8% 0x000274a6

Cela ressemble à ce à quoi je m'attendais, sauf que je ne vois aucune augmentation visible de la performance (0,1 seconde sur un calcul de 10 secondes). Le code est essentiellement:

ofstream outfile("out.txt");
for loop:
  SliceStep::DoStep()
  outfile << 'result'
outfile.close()

Mise à jour: Je chronomètre à l’aide de boost :: timer, qui commence au début et à la fin du profileur. Je n'utilise pas de fils ou quoi que ce soit de fantaisie.

Answer 1

D'après mes commentaires:

Les chiffres fournis par votre profileur indiquent que le programme devrait être environ 40% plus rapide sans les instructions d'impression.

Le temps d’exécution reste toutefois pratiquement identique.

Évidemment, l’une des mesures doit être fausse. Cela signifie que vous devez faire plus et de meilleures mesures.

Tout d'abord, je suggère de commencer avec un autre outil simple: la commande time. Cela devrait vous donner une idée approximative du temps que vous passez.

Si les résultats ne sont toujours pas concluants, vous avez besoin d'un meilleur test:

• Utiliser un problème plus important
• Faites un échauffement avant de mesurer. Faites des boucles et commencez les mesures par la suite (dans le même processus).

  

Tiristan: Tout est dans l'utilisateur. Ce que je fais est assez simple, je pense ... Le fait que le fichier soit ouvert tout le temps signifie-t-il quelque chose?

Cela signifie que le profileur a tort.

Si vous imprimez 100 000 lignes sur la console à l’aide de python, vous obtiendrez quelque chose comme:

for i in xrange(100000):
    print i

Pour consoler:

time python print.py
[...]
real    0m2.370s
user    0m0.156s
sys     0m0.232s

Versus:

time python test.py > /dev/null

real    0m0.133s
user    0m0.116s
sys     0m0.008s

Mon point est le suivant: Vos mesures et internes indiquent que vous ne gagnez rien à la désactivation de la sortie. Google Perf Tools dit que vous devriez. Qui a tort?

Answer 2

_write $ UNIX2003 fait probablement référence à l'appel système write POSIX, qui envoie les données au terminal. Les E / S sont très lentes par rapport à presque tout le reste. Il est donc logique que votre programme passe beaucoup de temps là-bas si vous écrivez pas mal de résultats.

Je ne sais pas pourquoi votre programme n'accélère pas l'accélération lorsque vous supprimez la sortie, mais je ne peux pas vraiment deviner ce que vous avez donné. Ce serait bien de voir une partie du code, voire même la sortie de perftools lorsque l’instruction cout est supprimée.

Answer 3

Google perftools collecte des échantillons de la pile d'appels. Vous avez donc besoin d'obtenir une visibilité sur ceux-ci.

Selon le document, vous pouvez afficher le graphe d'appel avec une granularité d'instruction ou d'adresse. Cela devrait vous dire ce que vous devez savoir.