DBMS_PROFILER: How to analyze pl/sql performance

To analyze the PL/SQL code and identifying performance issues using DBMS_PROFILER, we need to first start the profiler using DBMS_PROFILER.START_PROFILER, then we can execute the our pl/sql procedure we want monitored and at last we need to simply call DBMS_PROFILER.STOP_PROFILER to stop the profiler. We do not need to call DBMS_PROFILER.FLUSH_DATA explicitly as DBMS_PROFILER.STOP_PROFILE flush profiler data automatically.

To analyze PL/SQL and identify bottlenecks, we can break the use of DBMS_PROFILER in following steps:

1. Collect Profiler data for PL/SQL Block

2. Identify RUNID using PLSQL_PROFILER_RUNS

3. Identify UNIT_NUMBER using PLSQL_PROFILER_UNITS

4. Identify PL/SQL Line Number which may have performace issue by PLSQL_PROFILER_DATA

5. Get the Line of Code by USER_SOURCE

We have create a procedure "SP_CREATE_CSV" hich creates CSV file, using following example:

- http://nimishgarg.blogspot.in/2011/09/create-csv-file-using-plsql.html

Step 1: Collect Profiler data

C:\>sqlplus scott/tiger
SQL*Plus: Release 11.2.0.3.0 Production on Tue Feb 26 14:21:35 2013
Copyright (c) 1982, 2011, Oracle.  All rights reserved.
Connected to:
Oracle Database 11g Release 11.2.0.3.0 - Production

SQL> exec dbms_profiler.start_profiler('Test SP_CREATE_CSV');
PL/SQL procedure successfully completed.

SQL> exec SP_CREATE_CSV;
PL/SQL procedure successfully completed.

SQL> exec dbms_profiler.stop_profiler;
PL/SQL procedure successfully completed.

PL/SQL procedure successfully completed.

Step 2. Identify RUNID using PLSQL_PROFILER_RUNS

SQL> select runid, run_owner, run_date, run_total_time
  2  from plsql_profiler_runs
  3  where run_comment='Test SP_CREATE_CSV';

     RUNID RUN_OWNER                        RUN_DATE  RUN_TOTAL_TIME
---------- -------------------------------- --------- --------------
         1 SCOTT                            26-FEB-13     2.3313E+10

Step 3. Identify UNIT_NUMBER using PLSQL_PROFILER_UNITS

SQL> select unit_number, unit_timestamp, total_time
  2  from plsql_profiler_units
  3  where runid=1 and unit_name='SP_CREATE_CSV';

UNIT_NUMBER UNIT_TIME TOTAL_TIME
----------- --------- ----------
          3 26-FEB-13          0

Step 4. Identify problematic PL/SQL Line Number by PLSQL_PROFILER_DATA

SQL> select line#, total_occur, total_time, min_time, max_time,
  2  round(total_time/total_occur,0) avg_time
  3  from plsql_profiler_data
  4  where runid=1 and unit_number=3
  5  order by avg_time desc;

     LINE# TOTAL_OCCUR TOTAL_TIME   MIN_TIME   MAX_TIME   AVG_TIME
---------- ----------- ---------- ---------- ---------- ----------
         3           1     113561        372     112488     113561
         7           3     206807         96     193721      68936
         6           1      19143      19143      19143      19143
        17           1      11097      11097      11097      11097
         1           1      10643      10643      10643      10643
         9          14      14857        640       5963       1061
        11          14      11386        673       1891        813
        12          14       8631        553        673        617
        10          14       6616        412        995        473
        13          14       6024        369        496        430
        16           1        336        336        336        336
        14          14       4273         75        396        305

Now we have all the details required to get bottlenecks of SP_CREATE_CSV. Now we know that line number 3,7 of SP_CREATE_CSV are the top two time consuming statements on an average (basis of single execution). We just need to check what code of lines are they.

Step 5. Get the Line of Code by USER_SOURCE

SQL> column text format a60;
SQL> select line, text from user_source
  2  where name='SP_CREATE_CSV'
  3  and line in (3,7);

      LINE TEXT
---------- ---------------------------------------------------------
         3 CURSOR C1 IS SELECT EMPNO, ENAME, SAL, E.DEPTNO, DNAME 
           FROM EMP E, DEPT D WHERE E.DEPTNO = D.DEPTNO ORDER BY EMPNO;
        7  FOR C1_R IN C1