Introduction
When a transaction that uses PL/SQL libraries (package, procedure, functions or triggers) reports many
hours of elapsed time, but TKPROF revelas only a fraction of elapsed time for the SQL commands executed,
we all wondered which part of the code took more time. In this type situation neither TKPROF not Trace
Analyzer will help us. However, Oracle provided another utility called, PL/SQL Profiler.
In this paper, I have demonstrated how to install the profiler package and its usage.
Installation:
profload.sql can be found in $ORACLE_HOME/rdbms/admin/ dir or $ORACLE_HOME/plsql/admin
Note: profload.sql executes dbmspbp.sql and prvtpbp.plb.
Make sure that these 2 scripts are in the $ORACLE_HOME/rdbms/admin dir
Connect as sys to execute profload.sql
#sqlplus sys/
SQL> START ?/rdbms/admin/profload.sql
You should get the following message after successful run of profload.sql
Testing for correct installation
SYS.DBMS_PROFILER successfully loaded.
Creating repository tables under application user schema
#sqlplus /
SQL> show user
USER is "TAMIL"
SQL> start ?/rdbms/admin/proftab.sql
To verify all necessary tables are installed under the appln user schema, run the following statement:
SQL> select * from cat where table_name like 'PLSQL%' ;
TABLE_NAME TABLE_TYPE
------------------------------ -----------
PLSQL_PROFILER_DATA TABLE
PLSQL_PROFILER_GRAND_TOTAL VIEW
PLSQL_PROFILER_LINES_CROSS_RUN VIEW
PLSQL_PROFILER_NOTEXEC_LINES VIEW
PLSQL_PROFILER_RUNNUMBER SEQUENCE
PLSQL_PROFILER_RUNS TABLE
PLSQL_PROFILER_UNITS TABLE
PLSQL_PROFILER_UNITS_CROSS_RUN VIEW
8 rows selected.
I have created another script profreset.sql that deletes
all the rows from the repsoitory tables.
profreset.sql looks like:
Rem -- delete all rows from the profiler tables
Rem -- Author - Tamil
Rem -- Date - Apr 19, 2004
delete from PLSQL_PROFILER_DATA;
delete from PLSQL_PROFILER_UNITS;
delete from PLSQL_PROFILER_RUNS;
commit;
To demonstrate the power of the utility, I wrote a script called, prof_tamil_demo.sql
+1 Rem
+2 Rem NAME
+3 Rem prof_tamil_demo.sql - Demo program for PL/SQL profiler.
+4 Rem First Written and tested - April 19, 2004
+5 Rem DESCRIPTION
+6 Rem
+7 Rem Demo for collecting PL/SQL profiler data for constructs like packages,
+8 Rem procedures, ADTs, triggers etc.
+9 Rem
+10 Rem REQUIREMENTS
+11 Rem
+12 Rem o Package DBMS_OUTPUT is installed for the database.
+13 Rem
+14 Rem NOTES ON EXECUTING THIS DEMO PROGRAM
+15 Rem
+16 Rem o Load profiler package by running profload.sql after connecting
+17 Rem as user SYS.
+18 Rem
+19 Rem o Create profiler related data collection schema using proftab.sql
+20 Rem after connecting as the user under which this demo will be run.
+21 Rem
+22 Rem profload.sql and proftab.sql exist in ORACLE_HOME/plsql/admin directory.
+23 Rem
+24
+25 Rem Create objects for which profiler demo.
+26 set serveroutput on size 1000000
+27 set wrap on
+28 set lines 124 pages 66
+29 col text for a55
+30 column unit_owner format a10
+31
+32 drop table tamil_1 ;
+33 drop table tamil_2 ;
+34 drop table tamil_3 ;
+35
+36 create table tamil_1 ( c1 number, c2 date, c3 char(300) default 'x' );
+37 create table tamil_2 ( c1 number, c2 date , c3 char(300) default 'x');
+38 create table tamil_3 ( c1 number, c2 date , c3 char(300) default 'x');
+39
+40 Rem Create procedure 3
+41 create or replace procedure tamil_proc_3 as
+42 L_count Number ;
+43 begin
+44 for cr in (select c1,c2,c3 from tamil_2 order by c2 desc ) Loop
+45 insert into tamil_3 (c1, c2,c3) values ( cr.c1, cr.c2, cr.c3 );
+46 end loop ;
+47 commit;
+48 select count(*) into L_count from tamil_3;
+49 end;
+50 /
+51 show errors
+52
+53 Rem Create procedure 2 and calls procedure 3
+54 create or replace procedure tamil_proc_2 as
+55 L_count Number ;
+56 begin
+57 for cr in (select c1,c2,c3 from tamil_1 order by c1 desc ) Loop
+58 insert into tamil_2 (c1, c2,c3) values ( cr.c1, cr.c2, cr.c3 );
+59 end loop ;
+60 commit;
+61 select count(*) into L_count from tamil_2 ;
+62 tamil_proc_3;
+63 end;
+64 /
+65 show errors
+66
+67 Rem Create procedure 1 and calls procedure 2
+68 create or replace procedure tamil_proc_1 as
+69 begin
+70 for I in 1..10000 Loop
+71 insert into tamil_1 (c1, c2) values ( I, (sysdate-I));
+72 commit;
+73 end loop ;
+74 tamil_proc_2;
+75 end;
+76 /
+77
+78 show errors
+79
+80 Rem Start profiling.
+81
+82 declare
+83 status number;
+84 begin
+85 status := dbms_profiler.start_profiler('PROFILER TAMIL DEMO');
+86 end;
+87 /
+88
+89 execute tamil_proc_1 ;
+90
+91 Rem Stop profiling data.
+92
+93 declare
+94 status number;
+95 begin
+96 status := dbms_profiler.stop_profiler;
+97 end;
+98 /
+99
+100 Rem Generate reports using profsum script.
+101
+102 spool prof_report.lst
+103
+104 @profsum --------- Report program provided by Oracle
+105
+106 spool off
+107
+108 exit;
+109
The report produced by profsum is given below:
Please note down that all timings are reported in seconds.
GRAND_TOTA
----------
4.82
RUNID RUN_COMMENT SECONDS
---------- ------------------------------ ----------
4 PROFILER TAMIL DEMO 5.04719328
RUNID RUN_COMMENT UNIT_OWNER UNIT_NAME SECONDS PERCEN
---------- -------------------- ---------- -------------------- --------- ------
4 PROFILER TAMIL DEMO TAMIL TAMIL_PROC_1 2.35 46.6
4 PROFILER TAMIL DEMO TAMIL TAMIL_PROC_3 1.24 24.6
4 PROFILER TAMIL DEMO TAMIL TAMIL_PROC_2 1.23 24.3
UNIT_OWNER UNIT_NAME SECONDS PERCENTAG
---------- ------------------------- --------- ---------
TAMIL TAMIL_PROC_1 2.35 48.82
TAMIL TAMIL_PROC_3 1.24 25.73
TAMIL TAMIL_PROC_2 1.23 25.44
.00 .00
>
no rows selected
no rows selected
SECONDS UNIT_OWNER UNIT_NAME LINE# TEXT
-------- ---------- --------------- ---------- ---------------------------------------------------------------
1.4 TAMIL TAMIL_PROC_1 4 insert into tamil_1 (c1, c2) values ( I, (sysdate-I));
.9 TAMIL TAMIL_PROC_3 5 insert into tamil_3 (c1, c2,c3) values ( cr.c1,cr.c2, cr.c3 );
.9 TAMIL TAMIL_PROC_1 5 commit;
.9 TAMIL TAMIL_PROC_2 5 insert into tamil_2 (c1, c2,c3) values ( cr.c1,cr.c2, cr.c3 );
.3 TAMIL TAMIL_PROC_3 4 for cr in (select c1,c2,c3 from tamil_2 order by c2desc ) Loop
.3 TAMIL TAMIL_PROC_2 4 for cr in (select c1,c2,c3 from tamil_1 order by c1desc ) Loop
6 rows selected.
PL/SQL procedure successfully completed.
no rows selected
no rows selected
LINES_EXECUTED
--------------
0
LINES_PRESENT
-------------
0
=================================trace info=======================
==========Results for run #4 made on 07-APR-06 13:51:05 =========================
(PROFILER TAMIL DEMO) Run total time: 5.05 seconds
Unit #1: . - Total time: .00 seconds
Unit #2: . - Total time: .00 seconds
Unit #3: . - Total time: .00 seconds
Unit #4: TAMIL.TAMIL_PROC_1 - Total time: 2.35 seconds
1 procedure tamil_proc_1 as
2 begin
3 10,001 .01144161 .00000114 for I in 1..10000 Loop
4 10,000 1.3996578 .00013996 insert into tamil_1 (c1, c2) values ( I, (sysdate-I));
5 10,000 .94094922 .00009409 commit;
6 end loop ;
7 2 .00013863 .00006931 tamil_proc_2;
8 end
Unit #5: TAMIL.TAMIL_PROC_2 - Total time: 1.23 seconds
1 procedure tamil_proc_2 as
2 L_count Number ;
3 begin
4 10,001 .28182129 .00002817 for cr in (select c1,c2,c3 from tamil_1 order by c1 desc ) Loop
5 10,001 .93644986 .00009363 insert into tamil_2 (c1, c2,c3) values ( cr.c1, cr.c2, cr.c3 );
6 end loop ;
7 1 .00134883 .00134883 commit;
8 1 .00590142 .00590142 select count(*) into L_count from tamil_2 ;
9 2 .00007208 .00003604 tamil_proc_3;
10 end
Unit #6: TAMIL.TAMIL_PROC_3 - Total time: 1.24 seconds
1 procedure tamil_proc_3 as
2 L_count Number ;
3 begin
4 10,001 .28586930 .00002858 for cr in (select c1,c2,c3 from tamil_2 order by c2 desc ) Loop
5 10,001 .94648271 .00009463 insert into tamil_3 (c1, c2,c3) values ( cr.c1, cr.c2, cr.c3 );
6 end loop ;
7 1 .00135531 .00135531 commit;
8 1 .00591085 .00591085 select count(*) into L_count from tamil_3;
9 end
Unit #7: . - Total time: .00 seconds
Unit #8: . - Total time: .00 seconds
============================================================================
PL/SQL procedure successfully completed.
================== Profiler report - all runs rolled up ===================
Unit .:
Unit TAMIL.TAMIL_PROC_1:
1 procedure tamil_proc_1 as
2 begin
3 10,001 .01144161 .00000114 for I in 1..10000 Loop
4 10,000 1.3996578 .00013996 insert into tamil_1 (c1, c2) values ( I, (sysdate-I));
5 10,000 .94094922 .00009409 commit;
6 end loop ;
7 2 .00013863 .00006931 tamil_proc_2;
8 end
Unit TAMIL.TAMIL_PROC_2:
1 procedure tamil_proc_2 as
2 L_count Number ;
3 begin
4 10,001 .28182129 .00002817 for cr in (select c1,c2,c3 from tamil_1 order by c1 desc ) Loop
5 10,001 .93644986 .00009363 insert into tamil_2 (c1, c2,c3) values ( cr.c1, cr.c2, cr.c3 );
6 end loop ;
7 1 .00134883 .00134883 commit;
8 1 .00590142 .00590142 select count(*) into L_count from tamil_2 ;
9 2 .00007208 .00003604 tamil_proc_3;
10 end
Unit TAMIL.TAMIL_PROC_3:
1 procedure tamil_proc_3 as
2 L_count Number ;
3 begin
4 10,001 .28586930 .00002858 for cr in (select c1,c2,c3 from tamil_2 order by c2 desc ) Loop
5 10,001 .94648271 .00009463 insert into tamil_3 (c1, c2,c3) values ( cr.c1, cr.c2, cr.c3 );
6 end loop ;
7 1 .00135531 .00135531 commit;
8 1 .00591085 .00591085 select count(*) into L_count from tamil_3;
9 end
============================================================================
The run time of tamil_proc_1 is more than tamil_proc_2 or tamil_proc_3.
I deliberately put the commit statement with in the for..loop in tamil_proc_1 to simulate "commit per row".
PL/SQL profiler does not report any "WAIT" events as we get it from the extended SQL trace data, otherwise,
the report from the profiler is great for debugging 100% of application code.
Warning: If the package/procedure/trigger/function is encrypted using Oracle's wrap utility, then PL/SQL
Profiler will not report line-by-line execution of code. However, it reports total run time for each
procedure/trigger/function.
Hope this helps........
Tamilselvan G
No comments:
Post a Comment