DBMS_PROFILER Usage


The DBMS_PROFILER package allows to determine the time taken by each instruction of your code.
At the same time, you could also see the internal processing time for the basic instructions.

Of course, these times depend on the power of the test machine.

On 9i database, you have to run some scripts to install the DBMS_PROFILER package

Connect to SYS

connect / as sysdba

@/rdbms/admin/proftab.sql
@/rdbms/admin/profload.sql
@/plsql/demo/profrep.sql

Then run the test with the following instructions:
SQL>
1 DECLARE
2 Pgm NUMBER;
3 BEGIN
4 DBMS_PROFILER.START_PROFILER('test','test1',Pgm);
5 FD.F_TRACE('Hello Oracle world','T');
6 DBMS_PROFILER.STOP_PROFILER;
7 DBMS_PROFILER.ROLLUP_RUN(Pgm);
8 PROF_REPORT_UTILITIES.PRINT_RUN(Pgm);
9* END;
SQL> /


On 10g database, it seems that there is nothing to install

This is a very simple procedure to test the DBMS_PROFILER package :

CREATE OR REPLACE PROCEDURE TEST_PROFILER
IS
TYPE TYP_TV1 IS TABLE OF VARCHAR2(50) INDEX BY BINARY_INTEGER ;
TYPE TYP_TV2 IS TABLE OF VARCHAR2(50) INDEX BY PLS_INTEGER ;
i1 PLS_INTEGER ;
n1 NUMBER ;
v1 VARCHAR2(2000) ;
t1 TYP_TV1 ;
t2 TYP_TV2 ;
d1 DATE ;
BEGIN

For i IN 1 .. 1000 Loop

i1 := i ;
n1 := i ;
v1 := i ;
v1 := To_char( i ) ;
v1 := Ltrim( To_Char( i ) ) ;
v1 := Replace( To_Char( i ), ' ', '' ) ;
i1 := Instr( v1, '0' ) ;
v1 := Substr( v1, 1, 1 ) ;
t1(i) := i ;
t2(i) := i ;
n1 := Round( i * 1.37 ) ;
n1 := Trunc( i * 1.37 ) ;
n1 := Round( i * 1.37999999999999 ) ;
n1 := Trunc( i * 1.37999999999999 ) ;
d1 := SYSDATE + i ;

End Loop ;

END TEST_PROFILER ;
/

Run the test:

SQL> Begin
2
3 dbms_profiler.start_profiler ('start') ;
4 test_profiler ;
5 dbms_profiler.stop_profiler ;
6
7 End ;
8 /

PL/SQL procedure successfully completed.

Then show the result:

SQL> set linesize 500
SQL>
SQL> column unit_name format a15
SQL> column occured format 999999
SQL> column line# format 99999
SQL> column tot_time format 999.999999
SQL> set linesize 500
SQL>
SQL> select p.unit_name, p.occured, p.tot_time, p.line# line,
2 substr(s.text, 1,150) text
3 from
4 (select u.unit_name, d.TOTAL_OCCUR occured,
5 (to_char(d.TOTAL_TIME/1000000000,'999.999999')) tot_time, d.line#
6 from plsql_profiler_units u, plsql_profiler_data d
7 where d.RUNID=u.runid and d.UNIT_NUMBER = u.unit_number
8 and d.TOTAL_OCCUR >0
9 and u.runid= (select max(runid) from plsql_profiler_units)) p,
10 user_source s
11 where p.unit_name = s.name(+) and p.line# = s.line (+)
12 order by p.unit_name, p.line#;

UNIT_NAME OCCURED TOT_TIME LINE TEXT
--------------- ------- ----------- ---------- ---------------------------------------------------
2 .000084 4
1 .000006 5
TEST_PROFILER 1 .000063 1 PROCEDURE TEST_PROFILER
TEST_PROFILER 1001 .000653 13 For i IN 1 .. 1000 Loop
TEST_PROFILER 1000 .001463 16 n1 := i ;
TEST_PROFILER 1000 .005228 17 v1 := i ;
TEST_PROFILER 1000 .005106 18 v1 := To_char( i ) ;
TEST_PROFILER 1000 .007010 19 v1 := Ltrim( To_Char( i ) ) ;
TEST_PROFILER 1000 .007110 20 v1 := Replace( To_Char( i ), ' ', '' ) ;
TEST_PROFILER 1000 .003209 21 i1 := Instr( v1, '0' ) ;
TEST_PROFILER 1000 .003021 22 v1 := Substr( v1, 1, 1 ) ;
TEST_PROFILER 1000 .006956 23 t1(i) := i ;
TEST_PROFILER 1000 .002220 24 t2(i) := i ;
TEST_PROFILER 1000 .006157 25 n1 := Round( i * 1.37 ) ;
TEST_PROFILER 1000 .002388 26 n1 := Trunc( i * 1.37 ) ;
TEST_PROFILER 1000 .002861 27 n1 := Round( i * 1.37999999999999 ) ;
TEST_PROFILER 1000 .001619 28 n1 := Trunc( i * 1.37999999999999 ) ;
TEST_PROFILER 1000 .011119 29 d1 := SYSDATE + i ;
TEST_PROFILER 1 .000065 33 END TEST_PROFILER ;

19 rows selected.

SQL>

As we can see, PLS_INTEGER type is 4/5 times faster than NUMBER
The NESTED TABLE INDEX BY PLS_INTEGER is 3 times faster than the INDEX BY BINARY_INTEGER
Operation on double-precision number is faster than operation on single-precision number