DBMS_PROFILER vs DBMS_HPROF

Le profiler hiérarchique d’Oracle 11g permet, comme son grand frère avant lui, d’analyser le temps passé dans les différentes procédures, fonctions, triggers et lignes de code d’un package PL/SQL. Les 2 solutions, la nouvelle comme l’ancienne, ne nécessitent aucune préparation du code et sont facilement utilisables en production. Toutefois la nouvelle améliore énormément votre capacité d’analyse :

  • DBMS_HPROF distingue finement le SQL du PL/SQL,
  • il donne une vision récursive des appels en présentant les temps cumulés ainsi que la profondeur d’exécution
  • des rapports sont générés en HTML à l’aide d’un utilitaire en ligne de commande ce qui facilite la compréhension

Vous trouverez ci-dessous un exemple de code PL/SQL simple et son profilage à l’aide de DBMS_PROFILER puis DBMS_HPROF. Cela vous permettra de comparer les 2 outils et de vous faire une première opinion.

Un exemple

Pour illustrer les différences entre les 2 packages, nous allons créer un exemple de package PL/SQL dans le schéma DEMO ci-dessous :

create user demo identified by demo
default tablespace users
temporary tablespace temp;

grant connect, resource to demo;

grant execute on dbms_random to demo;
grant select on sys.dba_objects to demo;

connect demo/demo

create or replace package mytest is
procedure caller;
function run_cpu(iter number) return number;
end;
/

create or replace package body mytest is

procedure count_objsquare is
x number;
begin
select count(*) into x
from dba_objects a,
dba_objects b;
dbms_output.put_line('rows :'||to_char(x));
end;

function run_cpu(iter number) return number is
ret number;
begin
for i in 1..iter loop
ret:=dbms_random.value();
ret:=+exp(iter);
end loop;
return ret;
end;

procedure caller is
out number;
begin
for i in 1..3 loop
count_objsquare;
out:=run_cpu(10000);
end loop;
end;

end;
/

Ce package n’a pas vraiment d’autre sens que celui d’un test. La procédure que nous allons analyser est mytest.caller ; voici une exécution sans profilage :

set timing on
set serveroutput on
set feedback off
exec mytest.caller;

rows :191961025
rows :191961025
rows :191961025
Elapsed: 00:00:31.43

DBMS_PROFILER

Pour utiliser le profiler à l’ancienne mode, il vous faut au préalable lancer le script proftab.sql dans le schéma utilisé pour exécuter votre procédure/fonction. Ce script crée notamment les tables suivantes :

  • PLSQL_PROFILER_RUNS liste l’ensemble des exécutions du profiler
  • PLSQL_PROFILER_UNITS liste l’ensemble des unités d’exécution mesurées
  • PLSQL_PROFILER_DATA stocke le détail des informations stockées par unité d’exécution
grant execute on DBMS_PROFILER to demo;

connect demo/demo
@?/rdbms/admin/proftab.sql

Utiliser DBMS_PROFILER nécessite d’utiliser la même session que l’activation ; ce n’est généralement pas un problème dans la mesure ou vous pouvez ajouter le code en entête/fin d’une procédure PL/SQL ou via un trigger de connexion / déconnexion. Dans l’exemple ci-dessous on lance simplement le profilage avant de lancer notre code et on le désactive (écrit les données dans les tables de référence) une fois la procédure exécutée :

var x number;
exec :x:= dbms_profiler.start_profiler('Run 1');
print x
X
---
0

exec mytest.caller;

exec :x:= dbms_profiler.stop_profiler;
print x

X
----
0

Il suffit ensuite de visualiser le contenu des tables d’analyse pour trouver comment améliorer le temps d’exécution :

col run_total_time format 999,999,999,999
col run_owner format a8
col run_comment format a10
select runid, run_owner,run_date, run_comment, run_total_time
from PLSQL_PROFILER_RUNS;

RUNID RUN_OWNE RUN_DATE RUN_COMMEN RUN_TOTAL_TIME
----- -------- --------- ---------- ----------------
1 DEMO 17-JUL-11 Run 1 49,160,000,000

set tab off
col unit format a15
col total_time format 999,999,999,999
set lines 120
set pages 1000
col text format a50
select d.total_occur, d.total_time, u.unit_owner||'.'||u.unit_name unit, d.line#, s.text
from PLSQL_PROFILER_DATA d, plsql_profiler_units u, user_source s
where u.runid=d.runid and u.unit_number=d.unit_number
and u.unit_owner!='<anonymous>'
and s.line=d.line#
and s.name='MYTEST'
order by d.unit_number, d.line#;

TOTAL_OCCUR TOTAL_TIME UNIT LINE# TEXT
----------- ---------------- --------------- ---------- ---------------------------------------
3 4,000 DEMO.MYTEST 3 procedure count_objsquare is
3 4,000 DEMO.MYTEST 3 function run_cpu(iter number) return number;
3 33,502,665,577 DEMO.MYTEST 6 select count(*) into x
3 141,012 DEMO.MYTEST 9 dbms_output.put_line('rows :'||to_char(x));
3 3,000 DEMO.MYTEST 10 end;
3 8,000 DEMO.MYTEST 12 function run_cpu(iter number) return number is
30003 11,985,028 DEMO.MYTEST 15 for i in 1..iter loop
30000 16,419,408 DEMO.MYTEST 16 ret:=dbms_random.value();
30000 131,358,270 DEMO.MYTEST 17 ret:=+exp(iter);
3 1,000 DEMO.MYTEST 19 return ret;
3 2,000 DEMO.MYTEST 20 end;
0 3,000 DEMO.MYTEST 22 procedure caller is
4 3,000 DEMO.MYTEST 25 for i in 1..3 loop
3 2,000 DEMO.MYTEST 26 count_objsquare;
3 2,000 DEMO.MYTEST 27 out:=run_cpu(10000);
1 2,000 DEMO.MYTEST 29 end;

Le CD de démonstration contient 2 exemples de rapports nommés profrep.sql et profsum.sql pour faciliter vos analyses.

DBMS_HPROF

DBMS_HPROF reprend pour beaucoup du fonctionnement précédent. Pour commencer, vous devrez exécuter le script dbmshptab.sql qui contient notamment la création des tables :

  • DBMSHP_RUNS contient les informations sur les exécutions
  • DBMSHP_FUNCTION_INFO contient les éléments d’exécution
  • DBMSHP_PARENT_CHILD_INFO stocke le détail des informations stockées par unité d’exécution issue de l’opération d’analyse
sqlplus demo/demo
@?/rdbms/admin/dbmshptab.sql

CREATE OR REPLACE directory PLSHPROF_DIR as '/tmp';
grant READ, WRITE on directory PLSHPROF_DIR to DEMO;
grant execute on dbms_hprof to demo;

Comme pour DBMS_PROFILER, vous devez utiliser la même session pour la procédure et l’activation ; les mêmes possibilités de triggers ou encapsulation sont à mettre en oeuvre pour une capture en production. Noter que dans ce cas, les données sont stockées sous la forme d’un fichier de trace qui peut être utilisé ultérieurement sans que les tables DBMSHP_FUNCTION_INFO et DBMSHP_PARENT_CHILD_INFO ne soient alimentées. La documentation décrit assez en détail le format de ce fichier de trace :

begin
dbms_hprof.start_profiling('PLSHPROF_DIR','greg.trc');
end;
/

exec mytest.caller

begin
dbms_hprof.stop_profiling;
end;

!more greg.trc

P#V PLSHPROF Internal Version 1.0
P#! PL/SQL Timer Started
P#C PLSQL."".""."__plsql_vm"
P#X 2
P#C PLSQL."".""."__anonymous_block"
P#X 108
P#C PLSQL."DEMO"."MYTEST"::11."CALLER"#980980e97e42f8ec #22
P#X 4
P#C PLSQL."DEMO"."MYTEST"::11."COUNT_OBJSQUARE"#980980e97e42f8ec #3
P#X 41

A cet instant, vous avez 2 options :

  • soit, générer l’ensemble des éléments de votre rapport et d’interroger les tables décrites précédemment :
var runid number;

begin
:runid:=dbms_hprof.analyze(
location=>'PLSHPROF_DIR',
filename=>'greg.trc',
run_comment=>'Analysis');
end;
/

print runid;

RUNID
----------
3
  • soit, utiliser l’utilitaire fourni pour extraire l’ensemble de ces informations sous la forme de fichiers HTML. Voici un exemple d’utilisation :
cd /tmp
plshprof -output /tmp/greg greg.trc
PLSHPROF: Oracle Database 11g Enterprise Edition Release 11.2.0.2.0 - Production
[12 symbols processed]
[Report written to '/tmp/greg.html']

Le rapport correspondant est un jeu de fichiers HTML préfixé par le paramètre -output (e.g. /tmp/gregXXX). Ils montrent, dans notre cas, que c’est le SQL de la ligne 6 du package qui représente 99.5% du temps passé dans le profiling pour 3 appels :

Il est également possible/facile d’utiliser le profilage hierarchique depuis SQL Developer comme vous le voyez ci-dessous. Les données sont alors automatiquement analysées et visualisables en partie sur un onglet spécifique de vos procédures, fonctions, packages ou triggers :

Malheureusement les analyses ne sont pas aussi riches qu’avec plshprof et il n’existe pas de rapport pré-défini. Une idée pour des DBA vertueux 😉 !

Références :
Vous trouverez ci-dessous une liste de documents de références pour faciliter l’utilisation que vous pourrez faire de DBMS_PROFILER et DBMS_HPROF :