Was genau macht C ++ Profilierung (google cpu perf-Tools) messen?

Question

ich versuche, mit Google Perf-Tool, um zu beginnen, einige CPU-intensive Anwendungen zu profilieren. Es ist eine statistische Berechnung, die jeden Schritt in eine Datei `ofstream‘ mit Dumps. Ich bin keine C ++ Experten so dass ich mit dem Engpass beunruhigend finden. Mein erster Pass gibt Ergebnisse:

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

Dies ist überraschend, da alle die wirkliche Berechnung erfolgt in SliceStep :: DoStep. Die „_write $ UNIX2003“ (wo kann ich herausfinden, was das ist?) Erscheint aus Schreiben der Ausgabedatei zu kommen. Nun, was mich verwirrt, ist, dass, wenn ich alle outfile << "text" Aussagen kommentieren und pprof laufen, 95% in SliceStep::DoStep ist und `_write $ UNIX2003' geht weg. Wie jedoch meine Anwendung beschleunigt nicht, durch die Gesamtzeit gemessen. Das Ganze beschleunigt weniger als 1 Prozent.

Was bin ich fehlt?

Hinzugefügt: Der pprof Ausgang ohne outfile << Aussagen ist:

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

Das sieht aus wie, was ich erwarten würde, es sei denn ich keine sichtbare Steigerung der Leistung (0,1 Sekunden auf 10 Sekunden Berechnung) zu sehen. Der Code ist im Wesentlichen:

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

Update: Ich Timing mit boost :: Timer ab, wo der Profiler beginnt und endet, wo es endet. Ich benutze keine Fäden oder etwas Phantasie.

Answer 1

Aus meinen Kommentaren:

Die Zahlen, die Sie von Ihrem Profiler erhalten sagen, dass das Programm sollte etwa 40% schneller, ohne dass die Druckanweisungen sein.

Die Laufzeit bleibt jedoch nahezu gleich.

Offensichtlich eine der Messungen muss falsch sein. Das heißt, Sie müssen mehr und bessere Messungen tun.

Zuerst schlage ich mit einem anderen einfachen Werkzeug Start: der Zeitbefehl. Dies sollte Ihnen eine grobe Vorstellung, wo Ihre Zeit verbringen.

Wenn die Ergebnisse noch nicht schlüssig sind, brauchen Sie einen besseren Testfall:

• Verwenden Sie ein größeres Problem
• ein Warm-up Sie vor der Messung. Hat einige Schleifen und startet jede Messung danach (im gleichen Prozess).

---

  

Tiristan: Es ist alles in Benutzer. Was ich tue, ist ziemlich einfach, ich denke ... Hat die Tatsache, dass die Datei geöffnet ist die ganze Zeit alles bedeuten?

Das bedeutet, dass der Profiler falsch ist.

Drucken 100000 Linien auf der Konsole mit Python Ergebnisse in so etwas wie:

for i in xrange(100000):
    print i

Zum Trost:

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

Mein Punkt ist: Ihre internen Messungen und Zeit zeigen Sie gewinnen nichts von dem Ausgang zu deaktivieren. Google Perf Werkzeuge sagt, Sie sollten. Wer ist denn los?

Answer 2

_write $ UNIX2003 bezieht sich wahrscheinlich auf die write POSIX-Systemaufruf, der an das Endgerät ausgibt. I / O ist sehr langsam im Vergleich zu fast alles andere, so macht es Sinn, dass Ihr Programm dort viel Zeit verbringen, wenn Sie ein gutes Stück von Ausgabe schreiben.

Ich bin mir nicht sicher, warum Ihr Programm würde nach oben nicht beschleunigen, wenn Sie die Ausgabe entfernen, aber ich kann nur nicht wirklich eine Vermutung über die Informationen, die Sie gegeben haben. Es wäre schön, einen Teil des Codes, oder sogar die perftools Ausgabe zu sehen, wenn die cout-Anweisung entfernt wird.

Answer 3

Google perftools sammelt Proben des Call-Stack, also was Sie brauchen, ist etwas Einblick in denen zu erhalten.

Nach dem doc, können Sie den Anruf Graph auf Anweisung oder Adresse Granularität anzuzeigen. Das sollte Ihnen sagen, was Sie wissen müssen.