2009-06-16 6 views
8

J'ai essayé de débuter avec Google Perf Tools pour profiler certaines applications gourmandes en ressources CPU. C'est un calcul statistique qui saute chaque étape dans un fichier en utilisant `ofstream '. Je ne suis pas un expert en C++ donc j'ai du mal à trouver le goulot d'étranglement. Ma première passe donne des résultats:Que fait exactement le profilage C++ (google cpu perf tools)?

 
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 

Cela est surprenant, car tout le calcul réel se produit dans SliceStep :: DoStep. Le "_write $ UNIX2003" (où puis-je trouver ce que c'est?) Semble provenir de l'écriture du fichier de sortie. Maintenant, ce qui m'embrouille, c'est que si je commente toutes les instructions outfile << "text" et exécute pprof, 95% est dans SliceStep::DoStep et `_write $ UNIX2003 's'en va. Cependant, mon application n'accélère pas, mesurée par le temps total. Le tout accélère moins de 1 pour cent.

Qu'est-ce qui me manque?

Ajouté: La sortie pprof sans les déclarations outfile << 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 que je pense, sauf que je ne vois aucune augmentation visible de la performance (.1 seconde sur un calcul 10 secondes) . Le code est essentiellement:

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

Mise à jour: Je synchronisation à l'aide boost :: minuterie, démarrage où commence profileurs et se termine là où elle se termine. Je n'utilise pas de fils ou quelque chose de fantaisie.

+0

Comment mesurez-vous le temps de fonctionnement? Faites un "temps ./votre programme" pour les deux configurations. Utilisez-vous le multithreading? – ebo

+0

Effectuez une analyse avec le temps et mesurez le temps sys/usr. Les numéros du profileur indiquent que vous devriez avoir 40% moins de temps d'exécution sans sortie. L'explication la plus simple serait que la mesure du profileur est faussée. – ebo

+0

Tout est dans l'utilisateur. Ce que je fais est assez simple, je pense ... Est-ce que le fait que le fichier est ouvert tout le temps signifie quelque chose? – Tristan

Répondre

3

De mes commentaires:

Les chiffres que vous obtenez de votre profileur dire que le programme devrait être d'environ 40% plus rapide sans les instructions d'impression.

Le temps d'exécution reste toutefois pratiquement le même.

Évidemment, l'une des mesures doit être erronée. Cela signifie que vous devez faire plus et de meilleures mesures.

D'abord je suggère de commencer avec un autre outil facile: la commande de temps. Cela devrait vous donner une idée approximative où votre temps est dépensé.

Si les résultats ne sont pas encore concluants, vous avez besoin d'une meilleure testcase:

  • Utilisez un plus grand problème
  • Faire un warm-up avant de mesurer. Faire quelques boucles et commencer toute mesure après (dans le même processus).

Tiristan: Il est tout à l'utilisateur. Ce que je fais est assez simple, je pense ...Est-ce que le fait que le fichier est ouvert tout le temps signifie quelque chose?

Cela signifie que le profileur est incorrect.

Impression 100000 lignes à la console en utilisant les résultats de python dans quelque chose comme:

for i in xrange(100000): 
    print i 

à la console:

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: Votre mesure interne ents et montre que vous ne gagnez rien en désactivant la sortie. Google Perf Tools vous dit que vous devriez. Qui a tort?

+0

L'opération prend définitivement 10 secondes, toutes fondamentalement proches de la fonction Slice :: DoStep. Je ne comprends pas comment le _write peut disparaître, après avoir été 40%, et ne pas avoir d'impact ... – Tristan

+0

C'est le point. Un nombre doit avoir tort. Découvrez lequel. Les nombres générés par le profileur peuvent ne pas être statistiquement significatifs ou totalement faux. – ebo

1

_write $ UNIX2003 fait probablement référence à l'appel système POSIX write, qui est transmis au terminal. Les E/S sont très lentes comparées à presque n'importe quoi d'autre, il est donc logique que votre programme passe beaucoup de temps là-bas si vous écrivez un peu de sortie. Je ne sais pas pourquoi votre programme n'accélérerait pas lorsque vous supprimez la sortie, mais je ne peux pas vraiment deviner uniquement les informations que vous avez données. Ce serait bien de voir une partie du code, ou même la sortie de perftools lorsque l'instruction cout est supprimée.

1

Google perftools collecte des échantillons de la pile d'appels, vous devez donc avoir une certaine visibilité sur ceux-ci. Selon le document, vous pouvez afficher le graphe d'appel à l'adresse ou à la granularité de l'adresse. Cela devrait vous dire ce que vous devez savoir.