2009-06-16 8 views
8

Ich versuche mit Google Perf Tools zu beginnen, um einige CPU-intensive Anwendungen zu profilieren. Es ist eine statistische Berechnung, die jeden Schritt mit `Ofstream 'in eine Datei ablegt. Ich bin kein C++ - Experte, deshalb habe ich Probleme, den Engpass zu finden. Mein erster Durchlauf gibt Ergebnisse:Was genau misst C++ - Profiling (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 

Dies ist überraschend, da die gesamte Berechnung in SliceStep :: DoStep erfolgt. Das "_write $ UNIX2003" (wo kann ich herausfinden, was das ist?) Scheint vom Schreiben der Ausgabedatei zu stammen. Nun, was verwirrt mich ist, dass, wenn ich alle outfile << "text" Aussagen auskommentieren und pprof ausführen, 95% ist in SliceStep::DoStep und _write $ UNIX2003 geht weg. Allerdings beschleunigt sich meine Anwendung nicht, gemessen an der Gesamtzeit. Das Ganze beschleunigt weniger als 1 Prozent.

Was fehlt mir?

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 sehe keine sichtbare Zunahme der Leistung (0,1 Sekunden auf 10 Sekunden Berechnung) . Der Code ist im Wesentlichen:

Update: Ich Timing mit boost :: timer, beginnend wo der Profiler beginnt und endet wo es endet. Ich verwende keine Threads oder irgendetwas Besonderes.

+0

Wie messen Sie die Laufzeit? Führen Sie für beide Konfigurationen ein "time ./yourprogramm" durch. Verwenden Sie Multithreading? – ebo

+0

Machen Sie einen Lauf mit der Zeit und messen Sie die Systemzeit. Die Profiler-Nummern geben an, dass Sie 40% weniger Laufzeit ohne Ausgabe haben sollten. Die einfachste Erklärung wäre, dass die Profilermessung verzerrt ist. – ebo

+0

Es ist alles in Benutzer. Was ich mache, ist ziemlich einfach, denke ich ... Bedeutet die Tatsache, dass die Datei die ganze Zeit offen ist, irgendetwas? – Tristan

Antwort

3

Aus meinen Kommentaren:

Die Zahlen, die Sie von Ihrem Profiler erhalten sagen, dass das Programm ohne die Druck Aussagen rund 40% schneller sein.

Die Laufzeit bleibt jedoch nahezu gleich.

Offensichtlich muss eine der Messungen falsch sein. Das bedeutet, dass Sie mehr und bessere Messungen durchführen müssen.

Zuerst schlage ich vor, mit einem anderen einfachen Werkzeug zu beginnen: dem Zeitbefehl. Dies sollte Ihnen eine ungefähre Vorstellung davon geben, wo Ihre Zeit verbracht wird.

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. Machen Sie einige Schleifen und starten Sie danach eine Messung (im selben Prozess).

Tiristan: Es ist alles in Benutzer. Was ich mache ist ziemlich einfach, denke ich ...Ist die Tatsache, dass die Datei die ganze Zeit geöffnet ist, etwas anderes?

Das bedeutet, der Profiler ist falsch.

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 interne Messung entsagen und Zeit zeigen, dass Sie nichts von der Deaktivierung der Ausgabe profitieren. Google Perf Tools sagt, dass Sie sollten. Wer ist falsch?

+0

Die Operation dauert definitiv 10 Sekunden, alles in der Nähe der Slice :: DoStep-Funktion. Ich verstehe nicht, wie der _write weggehen kann, nachdem er 40% gewesen ist, und keine Auswirkung hat ... – Tristan

+0

Das ist der Punkt. Eine Nummer muss falsch sein. Finde heraus, welcher. Die vom Profiler erzeugten Zahlen sind möglicherweise nicht statistisch signifikant oder falsch. – ebo

1

_write $ UNIX2003 bezieht sich wahrscheinlich auf den POSIX-Systemaufruf write, der an das Terminal ausgegeben wird. I/O ist sehr langsam im Vergleich zu fast allem anderen, also macht es Sinn, dass Ihr Programm viel Zeit dort verbringt, wenn Sie ein gutes Stück Output schreiben.

Ich bin mir nicht sicher, warum Ihr Programm nicht beschleunigen würde, wenn Sie die Ausgabe entfernen, aber ich kann nicht wirklich nur die Informationen schätzen, die Sie gegeben haben. Es wäre schön, etwas Code oder sogar die Ausgabe von perfmtools zu sehen, wenn die cout-Anweisung entfernt wird.

1

Google Pertools sammelt Beispiele des Aufruf-Stacks, also benötigen Sie einen Einblick in diese.

Gemäß dem Dokument können Sie das Aufrufdiagramm bei der Granularität von Anweisungen oder Adressen anzeigen. Das sollte dir sagen, was du wissen musst.