Catapulse

Au commencement naquit Devel::SmallProf (1997). Son ambition, mesurer le temps consommé par chaque line de code. Testons avec ce programme en Perl :

#!/usr/bin/perl

for (1..1000) {
    my @rows = ( );
    push @rows, Tr(  map { td($_) } 'a'..'d' );
    push @rows, Tr(  map { td($_) } 'e'..'h' );
    my $var = table(@rows);
}
sub table { my @rows  = @_;    return "<table>\n@rows_-_amp_-_;lt;/table>\n";}
sub Tr    { my @cells = @_;    return "<tr>@cells_-_amp_-_;lt;/tr>\n";       }
sub td    { my $cell  = shift; return "<td>$cell_-_amp_-_;lt;/td>";          }

En utilisation normale, le programmme est relativement rapide:

time perl tablegen.pl

real    0m0.292s
user    0m0.236s
sys    0m0.000s

En utilisant le module

time perl -d:SmallProf tablegen.pl
real    0m4.144s
user    0m3.852s
sys    0m0.260s

Le fichier ' smallprof.out ' suivant est généré au bout de 4 secondes tout de même.

           ================ SmallProf version 2.02 ================
                            Profile of tablegen.pl                     Page 1
       =================================================================
    count wall tm  cpu time line
        0   0.00000   0.00000     1:#!/usr/bin/perl
        0   0.00000   0.00000     2:
        1   0.00000   0.00000     3:for (1..1000) {
     1000   0.00000   0.00000     4:    my @rows = ( );
     5000   0.02000   0.05000     5:    push @rows, Tr(  map { td($_) } 'a'..'d'
     5000   0.02000   0.04000     6:    push @rows, Tr(  map { td($_) } 'e'..'h'
     1000   0.01200   0.01000     7:    my $var = table(@rows);
        0   0.00000   0.00000     8:}
     2000   0.02400   0.02000     9:sub table { my @rows  = @_;    return
     4000   0.02000   0.03000    10:sub Tr    { my @cells = @_;    return
    16000   0.03600   0.07000    11:sub td    { my $cell  = shift; return
        0   0.00000   0.00000    12:

Simple et efficace, son seul point faible : sa lenteur.

En 2005 son grand frère Devel::FastProf vu le jour. Son but, remédier au problème de lenteur du petit frère.

time perl -d:FastProf tablegen.pl

real    0m0.456s
user    0m0.360s
sys 0m0.092s

Nettement plus véloce, le fichier ' fastprof.out ' généré est lu au moyen de l'utilitaire fprofpp .

fprofpp

# fprofpp output format is:
# filename:line time count: source
tablegen.pl:11 0.13200 160000: sub td    { my $cell  = shift; return "$cell";          }
tablegen.pl:10 0.10000 40000: sub Tr    { my @cells = @_;    return "@cells\n";       }
tablegen.pl:9 0.05600 20000: sub table { my @rows  = @_;    return "\n@rows
\n";}
tablegen.pl:6 0.02400 50000: push @rows, Tr(  map { td($_) } 'e'..'h' );
tablegen.pl:5 0.02000 50000: push @rows, Tr(  map { td($_) } 'a'..'d' );
tablegen.pl:7 0.00800 10000: my $var = table(@rows);
tablegen.pl:4 0.00400 10000: my @rows = ( );
tablegen.pl:3 0.00000 1: for (1..10000) {

Les lignes les plus consommatrices étant affichée en premier. Bien tout ça mais pour optimiser de gros programmes il aurait été intéressant d'analyser non pas par ligne mais plutôt par block, routine ou fonction.

Devinez ... en 2008 Devel::NYTProf fût :)

time perl -d:NYTProf tablegen.pl

real    0m1.272s
user    0m1.048s
sys 0m0.216s

Oups ... beaucoup plus gourmand que son précécesseur :( Mais le résultat n'est pas comparable. Pour exploiter le fichier ' nytprof.out ' le programme nytprofhtml livré avec le module est utilisé.

nytprofhtml
Generating report...
Reading nytprof.out
Writing report to nytprof directory

En ouvrant le fichier nytprof/index.html avec son navigateur, ça nous donne :

Sympa non ? Toujours plus fort ... installer le package kcachegrind et lancer :

nytprofcg
Reading nytprof.out ...
Writing nytprof.callgrind ...

et ensuite kcachegrind nous ouvre :

il est alors possible de se promener dans son programme et déceler très simplement les fonctions et code Perl consommateur de CPU.