To profile a PL/SQL Procedure

 PLSQL profiling shows the time taken for the execution of PLSQL code at the line level. The DBMS_PROFILE package is used to profile the PLSQL application to identify performance bottlenecks. This data is stored in database profiler tables which can be queried for performance analysis.

The DBMS profiler can be used for code coverage of your PLSQL application. This is useful in development and testing. The profiler gathers information at PL/SQL virtual machine level and contains useful information like the total number of lines that are executed., the total time taken to execute these lines and the min and max time taken to execute these lines.

The main profiler tables that store this information are PLSQL_PROFILER_RUNS, PLSQL_PROFILER_UNITS and PLSQL_PROFILER_DATA.

Security - The profiler gathers data for units for which the user has CREATE privilege. i.e - u cannot profile units for which execute only privelege has been granted. This is a very important point to take note of. If you create the profiler the information gathered will not be complete.  

Oracle advises that modules that are being profiled should be compiled with DEBUG option since this provides additional information about the unit in the database. 

To create the profiler package you need to run the profload.sql package from $ORACLE_HOME/rdbms/admin.

SQL> $ORACLE_HOME/rdbms/admin/profload.sql

To collect the profile information, run proftab.sql in the schema whose objects are to be profiled.

Then you need to execute.

SQL> execute dbms_profiler.start_profiler('ROCEDURE NAME';    

SQL> exec PROCEDURE NAME;

SQL> execute dbms_profiler.stop_profiler;

The profile output can be obtained witht the below query

select s.text,
           p.total_occur,
           p.total_time/1000000000 total_time,
           p.min_time/1000000000 min_time,
           p.max_time/1000000000 max_time
    from hr.plsql_profiler_data p, dba_source s, hr.plsql_profiler_runs r
    where p.line# = s.line
    and   p.runid = r.runid
   and   s.name ='PACKAGE_NAME' -- If you are profiling a package procedure
  and s.type = 'PACKAGE BODY'
  ORDER BY s.line ;

The below query gives the number of runs that have been profiled.

select runid,
           run_owner, 
           run_date,
           run_total_time/1000000000 run_total_time,
           run_comment

from plsql_profiler_runs;    

Example You want to compare the timing of execution of a PLSQL procedure executing a dynamic sql with and without bind variables. This is to be profiled for a large number of records - say 1 lakh. Create a sample table in the HR schema as follows.

CREATE TABLE HR.EMP_MASTER
(
EMPLOYEE_ID         NUMBER,
EMPLOYEE_NAME       VARCHAR2(100),
EMPLOYEE_DOB        DATE,
EMPLOYEE_DESIG      VARCHAR2(100),  
EMPLOYEE_DOJ        DATE 
) TABLESPACE USERS;

CREATE INDEX IDX_EMP_ID ON HR.EMP_MASTER (EMPLOYEE_ID) TABLESPACE USERS;

Run a script to insert one lakh test records into this table as follows

DECLARE
v_emp_id NUMBER := 10000;
v_commit_cnt NUMBER := 0;

BEGIN

  FOR i IN 1 .. 100000
  LOOP --{
  v_emp_id := v_emp_id + 1;
  v_commit_cnt := v_commit_cnt + 1;
  
  INSERT INTO HR.EMP_MASTER
  (
  EMPLOYEE_ID,
  EMPLOYEE_NAME,
  EMPLOYEE_DOB,
  EMPLOYEE_DESIG,
  EMPLOYEE_DOJ
  )
  VALUES
  (
    v_emp_id,
    'Stephen King ' || v_emp_id,
    TO_DATE('21-JUL-1962','DD-MON-RRRR'),
    'CEO',
    TO_DATE('21-JUL-1991','DD-MON-RRRR')
  );
  IF v_commit_cnt = 5000
  THEN
    COMMIT;
    v_commit_cnt := 0;
  END IF;  
  END LOOP; --}
  
  COMMIT;
END;

Create the procedure to do a select without bind variables as below.

create or replace PROCEDURE GET_EMP_DETAILS_DYNA1 AS 
 
v_emp_id NUMBER := 10001;  

v_emp_name  VARCHAR2(500);
v_emp_dob     DATE;

v_sql VARCHAR2(1000);
  
BEGIN
  FOR i IN 1..100000
  LOOP --{
    v_emp_id := v_emp_id + 1;
   BEGIN 
      v_sql := '
      SELECT EMPLOYEE_NAME,EMPLOYEE_DOB
      FROM EMP_MASTER
      WHERE EMPLOYEE_ID = ' || v_emp_id;
      
      EXECUTE IMMEDIATE v_sql INTO v_emp_name, v_emp_dob;
    EXCEPTION
        WHEN NO_DATA_FOUND THEN NULL;
     END;
   END LOOP;  
  
END GET_EMP_DETAILS_DYNA1;

SQL> execute dbms_profiler.start_profiler('GET_EMP_DETAILS_DYNA1');

SQL> exec GET_EMP_DETAILS_DYNA1;

SQL> execute dbms_profiler.stop_profiler;

Now create a procedure to do the same select with bind variables as below

create or replace PROCEDURE GET_EMP_DETAILS_DYNA2 AS 
 
v_emp_id NUMBER := 10001;  

v_emp_name  VARCHAR2(500);
v_emp_dob     DATE;

v_sql VARCHAR2(1000);
  
BEGIN
  FOR i IN 1..100000
  LOOP --{
    v_emp_id := v_emp_id + 1;
   BEGIN 
      v_sql := '
      SELECT EMPLOYEE_NAME,EMPLOYEE_DOB
      FROM EMP_MASTER
      WHERE EMPLOYEE_ID = :v_emp_id';
      
      EXECUTE IMMEDIATE v_sql INTO v_emp_name, v_emp_dob using v_emp_id ;
    EXCEPTION
        WHEN NO_DATA_FOUND THEN NULL;
     END;
   END LOOP;  
  
END GET_EMP_DETAILS_DYNA2;

SQL> execute dbms_profiler.start_profiler('GET_EMP_DETAILS_DYNA2');

SQL> exec GET_EMP_DETAILS_DYNA2;

SQL> execute dbms_profiler.stop_profiler;

Now select the profiler output for both the runs as follows

select s.text ,
           p.total_occur ,
           p.total_time/1000000000 total_time,
           p.min_time/1000000000 min_time,
           p.max_time/1000000000 max_time
    from hr.plsql_profiler_data p, dba_source s, hr.plsql_profiler_runs r
    where p.line# = s.line
    and   p.runid = r.runid
   and   s.name ='GET_EMP_DETAILS_DYNA1' -- If you are profiling a package procedure
  and s.type = 'PROCEDURE'
  ORDER BY s.line ;

select s.text ,
           p.total_occur ,
           p.total_time/1000000000 total_time,
           p.min_time/1000000000 min_time,
           p.max_time/1000000000 max_time
    from hr.plsql_profiler_data p, dba_source s, hr.plsql_profiler_runs r
    where p.line# = s.line
    and   p.runid = r.runid
   and   s.name ='GET_EMP_DETAILS_DYNA2' -- If you are profiling a package procedure
  and s.type = 'PROCEDURE'
  ORDER BY s.line ;

You can compare the timings for the various steps. The key time to look out for is the "EXECUTE IMMEDIATE v_sql" statement. 

Thought for the day

Embrace every moment and every emotion.

Susan Gale