11.14.2010

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)"

Mes items partagés de Google Reader