In welcher Zeile verbrät mein Programm die meiste Zeit? Devel::SmallProf und Devel::FastProf geben Antworten
Veröffentlicht von Thomas Fahle am (Permalink)
Zeilenorientierte Profiler wie Devel::SmallProf bzw. Devel::FastProf von Salvador Fandiño García zeigen, welche Zeile eines Perl-Programms wie oft aufgerufen wurde und wieviel Zeit dafür benötigt wurde. Sie erlauben es dem Entwickler, solche Bereiche gezielt zu verbessern.
Beispielprogramm: Fakulät berechnen
Das Beispielprogramm berechnet die Fakulät einer Ganzzahl auf drei unterschiedliche Arten: rekursiv und zweimal iterativ. Die Variationen habe ich dem Journal of ambs: How would you write factorial? entnommen.
#!/usr/bin/perl use strict; use warnings; # Berechnung der Fakultaet n! my $n = 70; print recursive($n) , "\n"; print iterativ($n) , "\n"; print iterativ2($n) , "\n"; sub recursive { my $n = shift; if ($n == 1 or $n == 0) { return 1; } my $total = $n * recursive($n-1); return $total; } sub iterativ { my $v = shift; my $res = 1; while ($v > 1) { $res *= $v; $v--; } return $res; } sub iterativ2 { my $v = shift; my $res = 1; grep {$res*=$_} (1..$v); return $res; } # Quelle: # Journal of ambs: How would you write factorial? # http://use.perl.org/~ambs/journal/37511
Das Programm erzeugt folgende Ausgabe:
$ perl factorial.pl 1.19785716699699e+100 1.19785716699699e+100 1.19785716699699e+100
Devel::SmallProf
Das Programm lässt sich mit Devel::SmallProf wie folgt untersuchen:
perl -d:SmallProf factorial.pl
Devel::SmallProf erzeugt im aktuellen Verzeichnis eine Datei smallprof.out, welche die Ergebnisse enthält. In der ersten Spalte wird angezeigt, wie oft eine Zeile im Programm aufgerufen wurde, die zweite Spalte zeigt die tatsächlich verbrauchte Zeit, die dritte Spalte die benötigte CPU-Zeit an. Die letzte Spalte enthält den Inhalt der Zeile.
$ cat smallprof.out
================ SmallProf version 2.02 ================
Profile of factorial.pl Page 1
=================================================================
count wall tm cpu time line
0 0.00000 0.00000 1:#!/usr/bin/perl
0 0.00000 0.00000 2:use strict;
0 0.00000 0.00000 3:use warnings;
0 0.00000 0.00000 4:
0 0.00000 0.00000 5:# Berechnung der Fakultaet n!
0 0.00000 0.00000 6:
1 0.00000 0.00000 7:my $n = 70;
0 0.00000 0.00000 8:
1 0.00000 0.00000 9:print recursive($n) , "\n";
1 0.00000 0.00000 10:print iterativ($n) , "\n";
1 0.00000 0.00000 11:print iterativ2($n) , "\n";
0 0.00000 0.00000 12:
0 0.00000 0.00000 13:
0 0.00000 0.00000 14:sub recursive {
70 0.00000 0.00000 15: my $n = shift;
70 0.00000 0.00000 16: if ($n == 1 or $n == 0) {
0 0.00000 0.00000 17: return 1;
0 0.00000 0.00000 18: }
69 0.00004 0.00000 19: my $total = $n * recursive($n-1);
69 0.00014 0.00000 20: return $total;
0 0.00000 0.00000 21:}
0 0.00000 0.00000 22:sub iterativ {
1 0.00000 0.00000 23: my $v = shift;
1 0.00000 0.00000 24: my $res = 1;
1 0.00000 0.00000 25: while ($v > 1) {
69 0.00000 0.00000 26: $res *= $v;
69 0.00001 0.01000 27: $v--;
0 0.00000 0.00000 28: }
1 0.00009 0.00000 29: return $res;
0 0.00000 0.00000 30:}
0 0.00000 0.00000 31:sub iterativ2 {
1 0.00000 0.00000 32: my $v = shift;
1 0.00000 0.00000 33: my $res = 1;
1 0.00006 0.00000 34: grep {$res*=$_} (1..$v);
1 0.00010 0.00000 35: return $res;
0 0.00000 0.00000 36:}
0 0.00000 0.00000 37:# Quelle:
0 0.00000 0.00000 38:# Journal of ambs: How would you write
0 0.00000 0.00000 39:# http://use.perl.org/~ambs/journal/37511
Ausgabe nach der Anzahl der Aufrufe sortieren
Die Ausgabe lässt sich in einer Linux-Shell durch das Kommando
$ sort -k 1nr,1 smallprof.out | head
einfach nach der ersten Spalte, der Anzahl der Aufrufe, numerisch sortieren. So stehen die am häufigsten aufgerufenen Zeilen gleich am Anfang der Ausgabe.
70 0.00000 0.00000 15: my $n = shift;
70 0.00000 0.00000 16: if ($n == 1 or $n == 0) {
69 0.00000 0.00000 26: $res *= $v;
69 0.00001 0.01000 27: $v--;
69 0.00004 0.00000 19: my $total = $n * recursive($n-1);
69 0.00014 0.00000 20: return $total;
1 0.00000 0.00000 10:print iterativ($n) , "\n";
1 0.00000 0.00000 11:print iterativ2($n) , "\n";
1 0.00000 0.00000 23: my $v = shift;
1 0.00000 0.00000 24: my $res = 1;
Ausgabe nach der tatsächlich benötigten Zeit sortieren
Die Ausgabe lässt sich in einer Linux-Shell durch das Kommando
$ sort -k 2nr,2 smallprof.out | head
einfach nach dem zweiten Feld von links (der tatsächlich verbrauchten Zeit) numerisch sortieren. So stehen die Zeilen mit den größten Zeitfresser gleich am Anfang der Ausgabe.
69 0.00014 0.00000 20: return $total;
1 0.00010 0.00000 35: return $res;
1 0.00009 0.00000 29: return $res;
1 0.00006 0.00000 34: grep {$res*=$_} (1..$v);
69 0.00004 0.00000 19: my $total = $n * recursive($n-1);
69 0.00001 0.01000 27: $v--;
Devel::FastProf
Devel::FastProf ist eine Art Nachfolger von Devel::SmallProf.
Unter Windows läuft Devel::FastProf leider nicht
Das Beispielprogramm lässt sich mit Devel::FastProf wie folgt untersuchen:
perl -d:FastProf factorial.pl
Devel::FastProf erzeugt im aktuellen Verzeichnis eine Datei fastprof.out, welche die Ergebnisse in einem Binärformat enthält.
Zur Ausgabe der Ergebnisse wird das mitgelieferte Programm fprofpp benötigt.
f$ fprofpp fastprof.out
# fprofpp output format is:
# filename:line time count: source
factorial.pl:20 0.01348 69: return $total;
factorial.pl:19 0.00030 69: my $total = $n * recursive($n-1);
factorial.pl:29 0.00016 1: return $res;
factorial.pl:15 0.00015 70: my $n = shift;
factorial.pl:16 0.00015 70: if ($n == 1 or $n == 0) {
factorial.pl:26 0.00015 69: $res *= $v;
factorial.pl:27 0.00014 69: $v--;
factorial.pl:35 0.00011 1: return $res;
factorial.pl:34 0.00007 1: grep {$res*=$_} (1..$v);
factorial.pl:10 0.00001 1: print iterativ($n) , "\n";
factorial.pl:23 0.00001 1: my $v = shift;
factorial.pl:11 0.00001 1: print iterativ2($n) , "\n";
factorial.pl:25 0.00000 1: while ($v > 1) {
factorial.pl:32 0.00000 1: my $v = shift;
factorial.pl:9 0.00000 1: print recursive($n) , "\n";
factorial.pl:7 0.00000 1: my $n = 70;
factorial.pl:24 0.00000 1: my $res = 1;
factorial.pl:33 0.00000 1: my $res = 1;
fprofpp erzeugt eine übersichtliche Tabelle, in der die Zeilen, die am häufigsten aufgerufen werden und die verbrauchte Zeit angezeigt werden.
Zeilenorientierung vs. Unterprogrammorientierung
Neben den beschriebenen zeilenorientierte Profilern, gibt es noch weitere Profiler, die auf der Basis von Unterprogrammen arbeiten, z.B. Devel::DProf, auf den ich in dem Beitrag In welchem Unterprogramm verbrät mein Programm die meiste Zeit? Devel::DProf liefert Hinweise eingehe.
Zeilenorientierte Profiler haben gegenüber unterprogrammorientierten Profilern den Vorteil, daß sie auch Zeitdiebe innerhalb von Subroutinen finden, z.B. langsame Regexe innerhalb eines langen Unterprogramms.
Vorsicht AUTOLOAD
Wegen der Zeilenorientierung liefern beide Profiler falsche Ergebnisse, sobald AUTOLOAD verwendet wird.
Siehe auch
- Devel::SmallProf
- Devel::FastProf
- Perl Advent Calendar 2006-12-01: Good things come in small packages
- Michael Schilli: Laufzeit-Tacho - Profiler identifizieren Flaschenhälse in Perl-Programmen
- Mastering Perl: Profiling Perl
- Devel::NYTProf - Der beste Profiler für Perl
- In welchem Unterprogramm verbrät mein Programm die meiste Zeit? Devel::DProf liefert Hinweise
