Hierarchical Profiler - DBMS_HPROF

Dbms_hprof package reports dynamic execution profile of the plsql program organised by subprogram calls. This seperately accounts plsql and sql calls. Also provides subprogram level execution summary. It has two components - data collection and  analyzer. Data collection has apis to turn hierarchical profiling on and off. It produces raw profiler output. Analyzer processes raw profiler output and store the data to database tables. Hierarchical profiler is aided by plshprof utility which takes the raw profiler output as input and creates html reports.

Initial setup:

By default dbms_hprof is installed in oracle 11g. One can check if it is installed by running

Desc dbms_hprof

If it is not installed, run the script dbmshptab.sql  (inside rdbms/admin folder in oracle home path) in the schema one need to profile the units.

conn user/password

@/home/oracle/app/oracle/product/11.2.0/dbhome_2/rdbms/admin/dbmshptab.sql

This script will create three tables :

- dbmshp_function_info

- dbmshp_parent_child_info

- dbmshp_runs

To do hierarchical profiling using dbms_hprof, the schema need to have execute privilege on DBMS_HPROF package and write access to a directory object referred in start_profiling procedure.

Eg: Giving access to HR schema:

GRANT EXECUTE ON dbms_hprof  TO HR;

CREATE DIRECTORY PLSQL_HPROF AS '/home/oracle/plsql_hprof';

GRANT ALL ON DIRECTORY PLSQL_HPROF TO HR;

Process of Hierarchical profiling involves starting the profiler, executing plsql program code and  stopping profiler. To start profiler, dbms_hprof offers start_profiling procedure. To stop stop_profiling procedure is used.

Example

Create or replace procedure hprof1 is

Begin

Calc_days(sysdate - 1000);

End;

begin

dbms_hprof.start_profiling( location => 'PLSQL_HPROF', filename=>'Run1.trc');

hprof1;

dbms_hprof.stop_profiling;

end;

This will generate raw profiler data in file Run1.trc in the directory referred by PLSQL_HPROF directory object. Raw profiler output is like:

P#V PLSHPROF Internal Version 1.0

P#! PL/SQL Timer Started

P#C PLSQL."HR"."CALC_DAYS"::7."CALC_DAYS"#c0e1380d4054eb50 #1

P#X 191

P#C PLSQL."SYS"."DBMS_OUTPUT"::11."PUT_LINE"#5892e4d73b579470 #109

P#X 2

P#R

P#X 6

P#C PLSQL."SYS"."DBMS_OUTPUT"::11."PUT_LINE"#5892e4d73b579470 #109

P#X 1

P#R

P#X 5

P#C PLSQL."SYS"."DBMS_OUTPUT"::11."PUT_LINE"#5892e4d73b579470 #109

P#X 1

Since the raw profiler data is hard to decipher, one needs to analyze it using analyze function. It takes trace file location and name as input and returns runid. It writes the profiled data into the database tables.

Example:

 declare

 runid number;

 begin

 runid := dbms_hprof.analyze(location=> 'PLSQL_HPROF' , filename=> 'Run1.trc');

 dbms_output.put_line(' Run ID = ' ||runid);

 end;

One can query the database tables for finding information on profiling data using below queries:

Below sql gives runid:

SELECT runid,  run_timestamp,total_elapsed_time,run_comment FROM   dbmshp_runs ORDER BY runid;

From below sql we can find symbolid of our top level procedure call.

SELECT symbolid, owner, module, type, function FROM   dbmshp_function_info WHERE  runid = 1  ORDER BY symbolid;

Using symbolid, we can get the hierarchical information using below:

SELECT RPAD(' ', level*2, ' ') || fi.owner || '.' || fi.module AS name, fi.function, pci.subtree_elapsed_time, pci.function_elapsed_time, pci.calls FROM   dbmshp_parent_child_info pci  JOIN dbmshp_function_info fi ON pci.runid = fi.runid AND pci.childsymid = fi.symbolid  WHERE  pci.runid = 1

CONNECT BY PRIOR childsymid = parentsymid

START WITH pci.parentsymid = 2;

PLSHPROF utility:

plshprof utility takes a trace file and generates various HTML reports.

Example:

$plshprof -output run1 run1.trc

This generates a set of files with name starting with run1. Also one can generate difference between two runs of hierarchical profiling by supplying raw profiler outputs to plshprof utility.

Example:

$plshprof –output diff <Trace_file1> <Trace_File2>

Reference

1. Oracle 11g Advanced application developers guide
2. Oracle 11g PLSQL packages and types reference.
3. Www.oracle-base.com

Dbms_Trace

DBMS_TRACE helps to start and stop plsql tracing in a session.

Steps involved are:

1.      Start tracing using dbms_trace.set_plsql_trace procedure

2.      Execute application code to be traced

3.      Stop plsql tracing using dbms_trace.clear_plsql_trace procedure

Before doing this, one need to do the initial setup of creating the database tables, using which we can analyze the trace data. tracetab.sql file creates the database tables required to run dbms_trace. This file can be found in rdbms/admin folder in oracle home path:

sqlplus /nolog

conn sys/password as sysdba

@/home/oracle/app/oracle/product/11.2.0/dbhome_2/rdbms/admin/tracetab.sql

This script create 2 tables and a sequence:

1. plsql_trace_runs

2. plsql_trace_events

3. plsql_trace_runnumber

To complete the initial setup, grant access to public or the user in which one needs to trace the units:

CREATE PUBLIC SYNONYM plsql_trace_runs FOR plsql_trace_runs;

CREATE PUBLIC SYNONYM plsql_trace_events FOR plsql_trace_events;

CREATE PUBLIC SYNONYM plsql_trace_runnumber FOR plsql_trace_runnumber;

GRANT SELECT, INSERT, UPDATE, DELETE ON plsql_trace_runs TO PUBLIC;

GRANT SELECT, INSERT, UPDATE, DELETE ON plsql_trace_events TO PUBLIC;

Let’s explore how to use dbms_trace with the help of an example:

Procedure calc_days takes a date as input parameter and returns number of days between this date and current date, along with number of months and years.

Calc_days.sql:

create or replace procedure calc_days (v_date in date)

is

l_num_days number;

begin

l_num_days := trunc(sysdate- v_date  );

dbms_output.put_line('Number of days :' || l_num_days);

dbms_output.put_line('Number of months :' || l_num_days *12/365) ;

dbms_output.put_line('Number of years : ' || l_num_days /365);

end;

Now to make this procedure to be trace enabled, there are two ways:

1. set the session to trace enabled and create the procedure

alter session set set plsql_debug=TRUE;

@calc_days.sql

2. Alter and set debug for the procedure as below:

alter procedure calc_days compile debug;

Now, we can run the procedure and trace its execution. To do this the sets to follow is as mentioned above. First we need to start tracing session by calling dbms_trace.set_plsql_trace.

Set_plsql_trace procedure enables tracing in a session. It takes trace_level as input. There are various constants which can be passed for this procedure viz: trace_all_calls, trace_enabled_calls, trace_all_lines, trace_enabled_lines, trace_all_sql, trace_enabled_sql etc.

After calling set_plsql_trace, one need to run the application code to be traced after which tracing can be stopped by calling clear_plsql_trace procedure.

Example usage:

begin

dbms_trace.set_plsql_trace (dbms_trace.trace_all_lines);

dbms_output.put_line ('Trace started');

calc_days(sysdate-10000);

dbms_output.put_line('To stop trace');

dbms_trace.clear_plsql_trace;

dbms_trace.set_plsql_trace (dbms_trace.trace_enabled_lines);

dbms_output.put_line ('Trace started');

calc_days(sysdate-10000);

dbms_output.put_line('To stop trace');

dbms_trace.clear_plsql_trace;

end;

To analyze trace information, one need to take run_id of each run which can be found from below query:

select runid, run_owner , run_date from plsql_trace_runs order by runid;

Query the table plsql_trace_events table to find the difference among the two traces

SELECT e.runid,e.event_seq,TO_CHAR(e.event_time, 'DD-MON-YYYY HH24:MI:SS') AS event_time,e.event_unit_owner,e.event_unit,e.event_unit_kind,e.proc_line,e.event_comment FROM plsql_trace_events e WHERE e.runid = 1 ORDER BY e.runid, e.event_seq;

Tracing can be done for various levels -

ü  for all calls or only for enabled calls,

ü  for all exceptions or only for enabled exceptions

ü  for all sqls or for enabled sql

ü  for all lines or only for enabled lines.

Controlling Trace:

One can control the trace by pausing the trace when unwanted in a process execution and resume it when needed. This can be achieved by passing constants TRACE_PAUSE and TRACE_RESUME.

Reference:

1. Oracle 11g Advanced application developers guide

2. Oracle 11g PLSQL Packages and types reference 

3. www.oracle-base.com

Regards,

Vijay

Get_dependency

Dbms_utility provides a procedure to find various objects dependent on a particular object. This package has a procedure, get_dependency, which uses dbms_output procedure to print the list of objects which are dependent on the given object.

Syntax is:

 DBMS_UTILITY.GET_DEPENDENCY  
 type IN VARCHAR2,  
 schema IN VARCHAR2,  
 name IN VARCHAR2);  

Example usage:

 set serveroutput on;  
 BEGIN  
 dbms_utility.get_dependency('TABLE','HR','EMPLOYEES');  
 END;  

This would list the objects dependent on employees table in HR schema as below in my hr schema:

 DEPENDENCIES ON HR.EMPLOYEES  
 ------------------------------------------------------------------  
 *TABLE HR.EMPLOYEES()  
 *  VIEW HR.EMP_DETAILS_VIEW()  
 *  TRIGGER HR.SECURE_EMPLOYEES()  
 *  TRIGGER HR.UPDATE_JOB_HISTORY()  
 *  PROCEDURE HR.ANNUAL_SALARY()       

Regards,
Vijay

Bulk Compilation of Invalid Objects

Compile_Schema procedure in dbms_utility package can be used to compile all the objects in a schema or only the invalid objects in a schema.

Syntax is:

 DBMS_UTILITY.COMPILE_SCHEMA (  
 schema IN VARCHAR2,  
 compile_all IN BOOLEAN DEFAULT TRUE,  
 reuse_settings IN BOOLEAN DEFAULT FALSE);  

If compile_all parameter is set as false, this procedure will compile only the invalid objects in the schema. Reuse_settings parameter is a boolean parameter to instruct oracle to reuse session settings for the objects compiled.

Example usage:

This is an example usage to compile all invalid objects in HR schema:

 BEGIN  
 DBMS_UTILITY.COMPILE_SCHEMA('HR',FALSE,TRUE);  
 END;  

Regards,
Vijay

DBMS_PROFILER

 

DBMS_PROFILER package, introduced in Oracle8i, provides a means to collect profiling data of plsql program units for performance improvement.

To use dbms_profiler package, we need to create the database tables which will store the profiler data. These tables can be created by running proftab.sql script which will be present in  /rdbms/admin folder in the oracle installation folder.

This script creates:

1. A sequence plsql_profiler_runnumber
2. table plsql_profiler_data
3. plsql_profiler_units
4. plsql_profiler_runs

Lets do the initial setup:

 

   1:  CONN SYS/PASSWORD AS SYSDBA 

   2:  @/home/oracle/app/oracle/product/11.2.0/dbhome_2/rdbms/admin/proftab.sql 

   3:  CREATE PUBLIC SYNONYM plsql_profiler_runs FOR plsql_profiler_runs; 

   4:  CREATE PUBLIC SYNONYM plsql_profiler_units FOR plsql_profiler_units; 

   5:  CREATE PUBLIC SYNONYM plsql_profiler_data FOR plsql_profiler_data; 

   6:  CREATE PUBLIC SYNONYM plsql_profiler_runnumber FOR plsql_profiler_runnumber; 

   7:  GRANT SELECT ON plsql_profiler_runnumber TO PUBLIC; 

   8:  GRANT SELECT, INSERT, UPDATE, DELETE ON plsql_profiler_data TO PUBLIC; 

   9:  GRANT SELECT, INSERT, UPDATE, DELETE ON plsql_profiler_units TO PUBLIC; 

  10:  GRANT SELECT, INSERT, UPDATE, DELETE ON plsql_profiler_runs TO PUBLIC; 

The sets involved in profiling a plsql unit using dbms_profiling is:

1. Start the profiling session using dbms_profiler.start_profiling
   
2. Run the plsql unit to be profiled
   
3. Stop the profiling session
   
4. After this query the profiler tables we created earlier to check for which subprograms or line took maximum time to execute. Analyze why it took this long and modify as appropriate.

An Example:

   1:  create or replace procedure annual_salary 

   2:  as 

   3:  l_annual_salary NUMBER; 

   4:  begin 

   5:  for i in ( select employee_id, salary from employees) 

   6:  loop 

   7:  l_annual_salary := i.salary * 12; 

   8:  end loop; 

   9:  end annual_salary; 

  10:   /

  11:  DECLARE 

  12:    l_result  BINARY_INTEGER; 

  13:  BEGIN 

  14:    l_result := DBMS_PROFILER.start_profiler(run_comment => 'annual_salary' ); 

  15:    annual_salary; 

  16:    l_result := DBMS_PROFILER.stop_profiler; 

  17:  END; 

  18:  / 

Run this query 

SELECT runid,  run_date,  run_comment,  run_total_time 

FROM   plsql_profiler_runs 

where run_comment = 'annual_salary' 

ORDER BY runid;

This gave below output:

RUNID RUN_DATE  RUN_COMMENT                                        RUN_TOTAL_TIME
------ --------- -------------------------------------------------- --------------
     4 02-SEP-12 annual_salary                                           50000000

To analyze which subprogram or line in the plsql unit profiled took how much time : 

SELECT u.runid, u.unit_number, u.unit_type, u.unit_owner, u.unit_name, d.line#, d.total_occur,

d.total_time, d.min_time, d.max_time 

FROM plsql_profiler_units u JOIN plsql_profiler_data d ON u.runid = d.runid 

AND u.unit_number = d.unit_number

WHERE u.runid = 4 ORDER BY u.unit_number, d.line#; 

This produces below output:

RUNID UNIT_NUMBER UNIT_TYPE            UNIT_OWNER     UNIT_NAME            LINE# TOTAL_OCCUR TOTAL_TIME   MIN_TIME   MAX_TIME
------ ----------- -------------------- -------------- --------------- ---------- ----------- ---------- ---------- ----------
     4           1 ANONYMOUS BLOCK      <anonymous>    <anonymous>              1           0          0          0          0
     4           1 ANONYMOUS BLOCK      <anonymous>    <anonymous>              3           0          0          0          0
     4           1 ANONYMOUS BLOCK      <anonymous>    <anonymous>              4           0     233173     233173     233173
     4           1 ANONYMOUS BLOCK      <anonymous>    <anonymous>              5           2      82399      10519      71880
     4           1 ANONYMOUS BLOCK      <anonymous>    <anonymous>              6           1      14025      14025      14025
     4           1 ANONYMOUS BLOCK      <anonymous>    <anonymous>              7           0          0          0          0
     4           2 PROCEDURE            HR             ANNUAL_SALARY            1           1      29804       8765      21038
     4           2 PROCEDURE            HR             ANNUAL_SALARY            4           1          0          0          0
     4           2 PROCEDURE            HR             ANNUAL_SALARY            6         109   16819193       7012     675853
     4           2 PROCEDURE            HR             ANNUAL_SALARY            8         107    1495468       8765     120969
     4           2 PROCEDURE            HR             ANNUAL_SALARY            9           1          0          0          0

RUNID UNIT_NUMBER UNIT_TYPE            UNIT_OWNER     UNIT_NAME            LINE# TOTAL_OCCUR TOTAL_TIME   MIN_TIME   MAX_TIME
------ ----------- -------------------- -------------- --------------- ---------- ----------- ---------- ---------- ----------
     4           2 PROCEDURE            HR             ANNUAL_SALARY           10           1      15778      15778      15778
12 rows selected.

The lines 6 and 8 has taken maximun time.  

Using dbms_profiler, one can tune their plsql units iteratively.

Regards,

Vijay