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

Weitere Posts