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

Aktuelle Posts

Stay Tuned

Blog Roll

CC Lizenz

Powered By