In welchem Unterprogramm verbrät mein Programm die meiste Zeit? Devel::DProf liefert Hinweise

Veröffentlicht von Thomas Fahle am (Permalink)

Unterprogrammorientierte Profiler wie Devel::DProf von Ilya Zakharevich zeigen, welches Unterprogramm 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::DProf

Das Programm kann man nun mit Devel::DProf wie folgt untersuchen: 

 perl -d:DProf factorial.pl

Devel::DProf erzeugt im aktuellen Verzeichnis eine Datei tmon.out, welche die Ergebnisse enthält.

Zur Ausgabe der Ergebnisse wird das mitgelieferte Programm dprofpp benötigt. 

$ dprofpp tmon.out 
Total Elapsed Time = 0.009769 Seconds
 User+System Time =        0 Seconds
Exclusive Times
%Time ExclSec CumulS #Calls sec/call Csec/c  Name
 0.00       - -0.000      1        -      -  strict::import
 0.00       - -0.000      1        -      -  warnings::import
 0.00       - -0.000      1        -      -  strict::bits
 0.00       - -0.000      1        -      -  main::iterativ
 0.00       - -0.000      1        -      -  main::iterativ2
 0.00       - -0.000      2        -      -  main::BEGIN
 0.00       - -0.000     70        -      -  main::recursive

Der Schalter -l (kleines L) sortiert die Ausgabe nach der Anzahl der Aufrufe der Unterprogramme. 

$ dprofpp -l tmon.out 
Total Elapsed Time = 0.009769 Seconds
  User+System Time =        0 Seconds
Exclusive Times
%Time ExclSec CumulS #Calls sec/call Csec/c  Name
 0.00       - -0.000     70        -      -  main::recursive
 0.00       - -0.000      2        -      -  main::BEGIN
 0.00       - -0.000      1        -      -  strict::bits
 0.00       - -0.000      1        -      -  strict::import
 0.00       - -0.000      1        -      -  warnings::import
 0.00       - -0.000      1        -      -  main::iterativ
 0.00       - -0.000      1        -      -  main::iterativ2

Devel::DProf verwendet leider nur drei Nachkommastellen bei der Zeitmessung.

Abhilfe schafft hier z.B. eine Erhöhung der Anzahl der Aufrufe der Unterprogramme: 

my $n = 70;
for ( 1 .. 100_000 ) {
	print recursive($n)  , "\n";
	print iterativ($n)   , "\n";
	print iterativ2($n)  , "\n";
}

Die Ausgabe von dprofpp ist nun zwar nicht völlig korrekt, aber deutlich informativer, 

dprofpp -l tmon.out 
Total Elapsed Time = 19.58602 Seconds
  User+System Time =        0 Seconds
Exclusive Times
%Time ExclSec CumulS #Calls sec/call Csec/c  Name
 0.00       - -8.614 700000        -      -  main::recursive
 0.00   1.830  1.830 100000   0.0000 0.0000  main::iterativ
 0.00   2.760  2.760 100000   0.0000 0.0000  main::iterativ2
 0.00   0.010  0.010      2   0.0050 0.0050  main::BEGIN
 0.00       - -0.000      1        -      -  strict::bits
 0.00       - -0.000      1        -      -  strict::import
 0.00       - -0.000      1        -      -  warnings::import

Zeilenorientierung vs. Unterprogrammorientierung

Neben dem beschriebenem unterprogrammorientiertem Profiler Devel::DProf, gibt es noch weitere Profiler, die auf der der Basis von Zeilen arbeiten, z.B. Devel::SmallProf oder Devel::FastProf.

Devel::SmallProf und Devel::FastProf sind in dem Beitrag In welcher Zeile verbrät mein Programm die meiste Zeit? Devel::SmallProf und Devel::FastProf geben Antworten beschrieben.

Fazit

Auch wenn man Devel::DProf anmerkt, daß es bereits 1999 geschrieben wurde, ist es denoch ein einfach zu benutzendes Werkzeug, das oft hilft, Flaschenhälse aufzuspüren.

Siehe auch

Weitere Posts