Tracer du Pl/Sql avec DBMS_PROFILER

Même si cette facilité existe depuis Oracle 8i, c'est dernièrement que j'ai découvert qu'on pouvait tracer du code Pl/Sql ligne par ligne avec Oracle 10g. En effet, Oracle a mis à la disposition des développeurs un package DBMS_PROFILER qui permet, entre autre, de comptabiliser le nombre d'occurrences et la durée d'un appel précis dans une procédure/fonction/package.

Les prérequis:

1. Se connecter en tant que SYS
   
2. Exécuter le script $ORACLE_HOME/rdbms/admin/profload.sql
3. Pour chaque compte/schéma désirant utiliser ce service, exécuter le script $ORACLE_HOME/rdbms/admin/proftab.sql
   *Ce dernier créera des tables pour le profiler dans votre schéma.
   

Il existe 3 procédures principales pour utiliser le package DBMS_PROFILER:

• dbms_profiler.start_profiler('Début du code à tracer de la procédure TOTO');
  Marque le début de la section à tracer.
  
• dbms_profiler.stop_profiler();
• Marque la fin de la trace.
  
• dbms_profiler.flush_data();
  Enregistre les données recueillies dans les tables créées par le script proftab.sql
  

Un exemple: on veut déterminer s'il est plus avantageux d'utiliser la fonction modulo pour faire un commit à toutes les 1000 itérations, ou s'il est préférable d'incrémenter un compteur et le remettre à zéro à chaque fois.

-- Création de la procédure qui utilise le modulo
create or replace procedure commit1000_modulo as
i number := 0;
begin
dbms_profiler.start_profiler('Commit au 1000 selon modulo');
for j in 1 .. 500000 loop
i := i + 1;
if mod(i,1000) = 0 then
 commit;
end if;
end loop;
dbms_profiler.stop_profiler;
end;
/

-- Création de la procédure qui utilise un compteur en le remettant à zéro
-- à tous les 1000
create or replace procedure commit1000_compteur as
i number := 0;
begin
dbms_profiler.start_profiler('Commit au 1000 selon compteur');
for j in 1 .. 500000 loop
i := i + 1;
if i = 1000 then
 commit;
 i := 0;
end if;
end loop;
dbms_profiler.stop_profiler;
end;
/

-- Exécution des deux procédures et flush du data dans les tables du profiler
exec commit1000_modulo;
exec commit1000_compteur;
exec dbms_profiler.flush_data;

-- Obtenir la durée d'exécution pour chacune des options
set lines 132
select to_char(runid,'9999')                     "ID",
  to_char(run_date,'yyyy-mm-dd hh24:mi:ss') "EXECUTION",
  substr(run_comment,1,40)                  "DESCRIPTION",
  round(run_total_time/1000000000,2)        "DURÉE (secs)"
from plsql_profiler_runs
order by 1;

ID    EXECUTION           DESCRIPTION                              DURÉE (secs)
----- ------------------- ---------------------------------------- ------------
1 2010-11-14 19:49:53 Commit au 1000 selon modulo                       ,56
2 2010-11-14 19:49:54 Commit au 1000 selon compteur                     ,27

On remarque tout de suite que l'utilisation du compteur s'avère plus avantageuse à celle du modulo. Maintenant, regardons en détail:

-- Obtenir le détail de l'exécution pour chacune des options
break on "UNIT NAME" skip 1;
select to_char(a.runid,'9999')    "ID",
  substr(a.unit_name,1,20)   "UNIT NAME",
  b.line# "LIGNE",
  to_char(b.total_occur,'999999999')  "NB OCCUR",
  round(b.total_time/1000000000,3) "DURÉE (secs)",
  substr(c.text,1,70)        "SOURCE"
from plsql_profiler_units a,
  plsql_profiler_data  b,
  user_source c
where a.runid = b.runid
and a.unit_name = c.name
and b.line# = c.line
order by 1,2,3;

ID    UNIT NAME                 LIGNE NB OCCUR   DURÉE (secs) SOURCE
----- -------------------- ---------- ---------- ------------ ---------------------------------------------------------------
1 COMMIT1000_MODULO             1          0            0 procedure commit1000_modulo as
1                               3          0            0 i number := 0;
1                               7          0            0  dbms_profiler.start_profiler('Commit au 1000 selon modulo');
1                               9     500001         ,027  for j in 1 .. 500000 loop
1                              11     500000         ,063    i := i + 1;
1                              13     500000         ,268    if mod(i,1000) = 0 then
1                              15        500         ,013       commit;
1                              21          1            0  dbms_profiler.stop_profiler;
1                              23          0            0 end;

2 COMMIT1000_COMPTEUR           1          0            0 procedure commit1000_compteur as

ID    UNIT NAME                 LIGNE NB OCCUR   DURÉE (secs) SOURCE
----- -------------------- ---------- ---------- ------------ ---------------------------------------------------------------
2 COMMIT1000_COMPTEUR           2          0            0 i number := 0;
2                               4          0            0  dbms_profiler.start_profiler('Commit au 1000 selon compteur');
2                               5     500001         ,023  for j in 1 .. 500000 loop
2                               6     500000         ,047    i := i + 1;
2                               7     500000          ,03    if i = 1000 then
2                               8        500         ,009       commit;
2                               9        500            0       i := 0;
2                              12          1            0  dbms_profiler.stop_profiler;
2                              13          0            0 end;

On remarque que le "if mod(i,1000) = 0 then" du modulo prend 0.268 secondes, alors que l'utilisation du compteur ("if i=1000 then") prend 0.047 secondes.

Donc, l'utilisation du compteur est définitivement plus performante. Ceci n'était qu'un exemple pour vous montrer jusqu'où vous pouvez aller dans votre tuning de code Pl/Sql.

Note sur les plateformes: sur Linux/AIX, la valeur des champs temporels (run_total_time et total_time) est en nanosecondes alors que sur la plateforme Windows, elle est en picosecondes (on divise par 1000 de plus).
nanosecondes (10^-9): run_total_time/1000000000 "Durée (secs)"
picosecondes (10^12): run_total_time/1000000000000 "Durée (secs)"