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

| | Kommentare (0)

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

Jetzt kommentieren

Über diese Seite

Diese Seite enthält einen einen einzelnen Eintrag von Thomas Fahle vom 26.11.08 19:05.

In welcher Zeile verbrät mein Programm die meiste Zeit? Devel::SmallProf und Devel::FastProf geben Antworten ist der vorherige Eintrag in diesem Blog.

Devel::NYTProf - Der beste Profiler für Perl ist der nächste Eintrag in diesem Blog.

Aktuelle Einträge finden Sie auf der Startseite, alle Einträge in den Archiven.

Fachzeitschriften

Blog Roll

Powered by

Powered by Movable Type 5.2.10

Creative Commons-Lizenz

Creative Commons License
Dieses Weblog steht unter einer Creative Commons-Lizenz.