Précédent Index Suivant

Profiling

Cet outil permet d'obtenir un certain nombre de mesures sur l'exécution d'un programme : nombre de passages dans une fonction ou dans certaines structures de contrôle (conditionnelles, filtrages et boucles). Les informations sont enregistrées dans un fichier. De leur examen on peut déduire des erreurs algorithmiques ou les points cruciaux à optimiser dans une application.

Pour pouvoir traiter le code, il est nécessaire de compiler l'exécutable dans un mode spécial qui lui ajoute les instructions nécessaires aux divers décomptes. Il existe deux modes de profiling, un pour le compilateur de code-octet et un autre pour le compilateur natif, ainsi que deux commandes pour la présentation des résultats. Dans l'analyse du code natif on récupère aussi le temps passé dans chaque fonction.

Le profiling d'une application se déroule donc en trois temps :
  1. compilation en mode profiling;
  2. exécution du programme;
  3. présentation des mesures.

Commandes de compilation

Les commandes de compilation en mode profiling sont les suivantes : Ces compilateurs produisent le même type de fichiers que les commandes habituelles (7). Les différentes options sont décrites à la figure 10.1.
f appel de fonctions
i branches du if
l boucles while et for
m branches du match
t branches du try
a toutes les options

Figure 10.1 : Options des commandes de profiling

Elles indiquent quelles structures de contrôle doivent être prises en compte. Par défaut les options fm sont activées.

Exécution d'un programme

Compilateur de code-octet

L'exécution d'un programme compilé dans un mode de profilage produira, si il termine, un fichier nommé ocamlprof.dump qui contient les différentes informations demandées.

On reprend l'exemple sur le produit des entiers d'une liste. On écrit le fichier f1.ml suivant : 

let rec interval a b = 
  if b < a then []
  else a::(interval (a+1) b);;

exception Found_zero ;; 

let mult_list l = 
 let rec mult_rec l = match l with 
    [] -> 1
  | 0::_ -> raise Found_zero
  | n::x -> n * (mult_rec x)
 in
  try mult_rec l with Found_zero -> 0
;;


et le fichier f2.ml qui utilise les fonctions de f1.ml : 

let l1 = F1.interval 1 30;;
let l2 = F1.interval 31 60;;
let l3 = l1 @ (0::l2);;

print_int (F1.mult_list l1);;
print_newline();;

print_int (F1.mult_list l3);;
print_newline();;


La compilation de ces fichiers en mode profilage est la suivante : 
ocamlcp -i -p a -c f1.ml
val profile_f1_ : int array
val interval : int -> int -> int list
exception Found_zero
val mult_list : int list -> int
Avec l'option -p, le compilateur ajoute une nouvelle fonction (profile_f1_) pour l'initialisation des compteurs du module F1. Il en est de même pour le fichier f2.ml : 
ocamlcp -i -p a -o f2.exe f1.cmo f2.ml
val profile_f2_ : int array
val l1 : int list
val l2 : int list
val l3 : int list

Compilateur natif

La compilation en code natif donne le résultat suivant : 
$   ocamlopt -i -p  -c f1.ml
val interval : int -> int -> int list
exception Found_zero
val mult_list : int list -> int
$  ocamlopt -i -p -o f2nat.exe f1.cmx f2.ml
Seule l'option -p sans argument est utilisée. L'exécution de f2nat.exe produit un fichier de nom gmon.out. Celui-ci possède un format traitable par les outils habituels Unix (voir page ??).

Présentation des résultats

Comme les informations recueillies par les deux modes de profiling sont différentes, leur présentation s'en ressent. Dans le premier mode (code-octet), des commentaires sur le nombre de passages dans les structures de contrôle sont ajoutés au texte du programme. Dans le second (natif), on associe à chaque fonction le temps passé dans son corps et son nombre d'appels.

Compilateur code-octet

La commande ocamlprof donne l'analyse des résultats des mesures. Elle utilise les informations contenues dans le fichier camlprof.dump. Cette commande prend en entrée le source du programme, lit le fichier de mesure et produit un nouveau texte de programme contenant en commentaires les compteurs demandés.

Sur notre exemple cela donnera : 
$ ocamlprof f1.ml

let rec interval a b = 
  (* 62 *) if b < a then (* 2 *) []
  else (* 60 *) a::(interval (a+1) b);;

exception Found_zero ;; 

let mult_list l = 
 (* 2 *) let rec mult_rec l = (* 62 *) match l with 
    [] -> (* 1 *) 1
  | 0::_ -> (* 1 *) raise Found_zero
  | n::x -> (* 60 *) n * (mult_rec x)
 in
  try mult_rec l with Found_zero -> (* 1 *) 0
;;
Ces compteurs reflètent bien les calculs demandés dans F2. Il y a deux appels à list_mult et 62 à la fonction auxiliaire mult_rec. L'exploration des branches du filtrage match montre les 60 passages dans le cas courant, l'unique passage dans le filtre [] au premier calcul, et l'unique passage dans le filtre de tête égal à 0, déclenchant une exception dont le filtrage se voit dans le compteur du try.

La commande camlprof accepte deux options. La première -f fichier indique le nom du fichier contenant les mesures. La seconde -F chaîne spécifie une chaîne à ajouter dans les commentaires associés aux structures de contrôle traitées.

Compilateur natif

Pour connaître le temps passé dans les appels des fonctions de multiplication des éléments d'une liste, on écrit le fichier f3.ml suivant : 

let l1 = F1.interval 1 30;;
let l2 = F1.interval 31 60;;
let l3 = l1 @ (0::l2);;

for i=0 to 100000 do 
  F1.mult_list l1;
  F1.mult_list l3
done;;

print_int (F1.mult_list l1);;
print_newline();;

print_int (F1.mult_list l3);;
print_newline();;
C'est le même fichier que f2.ml avec une boucle de 100000 itérations.

L'exécution du programme crée le fichier gmon.out. Celui-ci est dans un format lisible par la commande gprof que l'on trouve sur les systèmes Unix. L'appel suivant de gprof affiche les informations de temps passé et le graphe des appels. Comme la sortie est assez longue, on ne montre que la première page qui contient le nom des fonctions appelées au moins une fois et le temps passé dans chacune d'elles. 
$ gprof  f3nat.exe 
Flat profile:

Each sample counts as 0.01 seconds.
  %   cumulative   self              self     total           
 time   seconds   seconds    calls  us/call  us/call  name    
 92.31      0.36     0.36   200004     1.80     1.80  F1_mult_rec_45
  7.69      0.39     0.03   200004     0.15     1.95  F1_mult_list_43
  0.00      0.39     0.00     2690     0.00     0.00  oldify
  0.00      0.39     0.00      302     0.00     0.00  darken
  0.00      0.39     0.00      188     0.00     0.00  gc_message
  0.00      0.39     0.00      174     0.00     0.00  aligned_malloc
  0.00      0.39     0.00      173     0.00     0.00  alloc_shr
  0.00      0.39     0.00      173     0.00     0.00  fl_allocate
  0.00      0.39     0.00       34     0.00     0.00  caml_alloc3
  0.00      0.39     0.00       30     0.00     0.00  caml_call_gc
  0.00      0.39     0.00       30     0.00     0.00  garbage_collection
...
Le premier enseignement est que presque tout le temps d'exécution se déroule dans la fonction F1_mult_rec_45, qui correspond à la fonction F1.mult_rec du fichier f1.ml. On s'aperçoit d'autre part que de nombreuses fonctions sont appelées. Les premières de la liste sont les fonctions de la bibliothèque d'exécution de gestion mémoire (9).





Précédent Index Suivant