This package enables the collection of data for performance improvement or for determining code coverage for PL/SQL applications. Application developers can use code coverage data to focus their incremental testing efforts. This blog provides DBAs, developers, support analysts, and consultants with PL/SQL tuning hints and tips using profiling.
With DBMS_PROFILER package, you can generate profiling information for all named library units that are executed in a session. The profiler gathers information at the PL/SQL virtual machine level. This information includes the total number of times each line has been executed, the total amount of time that has been spent executing that line, and the minimum and maximum times that have been spent on a particular execution of that line.
Installing the DBMS_PROFILER package
A DBA or developer can profile an application simply by calling the DBMS_PROFILER package calls to start and stop the profiling process.
The DBMS_PROFILER package should already be installed. A simple test is to run a describe of the package as SYSDBA. If the package is not installed then the following output will be displayed:
SQL> DESC DBMS_PROFILER
ERROR:
ORA-04043: object DBMS_PROFILER does not existThe DBMS_PROFILER package can be installed by running the profload.sql script as SYSDBA. This script can be found in the $ORACLE_HOME/rdbms/admin directory:
SQL> @?/rdbms/admin/profload.sqlThe following output indicates that the package is installed:
SQL> desc dbms_profiler
FUNCTION FLUSH_DATA RETURNS BINARY_INTEGER
PROCEDURE FLUSH_DATA
PROCEDURE GET_VERSION
Argument Name Type In/Out Default?
------------------------------ ----------------------- ------ --------
MAJOR BINARY_INTEGER OUT
MINOR BINARY_INTEGER OUT
FUNCTION INTERNAL_VERSION_CHECK RETURNS BINARY_INTEGER
FUNCTION PAUSE_PROFILER RETURNS BINARY_INTEGER
PROCEDURE PAUSE_PROFILER
FUNCTION RESUME_PROFILER RETURNS BINARY_INTEGER
PROCEDURE RESUME_PROFILER
PROCEDURE ROLLUP_RUN
Argument Name Type In/Out Default?
------------------------------ ----------------------- ------ --------
RUN_NUMBER NUMBER IN
PROCEDURE ROLLUP_UNIT
Argument Name Type In/Out Default?
------------------------------ ----------------------- ------ --------
RUN_NUMBER NUMBER IN
UNIT NUMBER IN
FUNCTION START_PROFILER RETURNS BINARY_INTEGER
Argument Name Type In/Out Default?
------------------------------ ----------------------- ------ --------
RUN_COMMENT VARCHAR2 IN DEFAULT
RUN_COMMENT1 VARCHAR2 IN DEFAULT
RUN_NUMBER BINARY_INTEGER OUT
PROCEDURE START_PROFILER
Argument Name Type In/Out Default?
------------------------------ ----------------------- ------ --------
RUN_COMMENT VARCHAR2 IN DEFAULT
RUN_COMMENT1 VARCHAR2 IN DEFAULT
RUN_NUMBER BINARY_INTEGER OUT
FUNCTION START_PROFILER RETURNS BINARY_INTEGER
Argument Name Type In/Out Default?
------------------------------ ----------------------- ------ --------
RUN_COMMENT VARCHAR2 IN DEFAULT
RUN_COMMENT1 VARCHAR2 IN DEFAULT
PROCEDURE START_PROFILER
Argument Name Type In/Out Default?
------------------------------ ----------------------- ------ --------
RUN_COMMENT VARCHAR2 IN DEFAULT
RUN_COMMENT1 VARCHAR2 IN DEFAULT
FUNCTION STOP_PROFILER RETURNS BINARY_INTEGER
PROCEDURE STOP_PROFILERThe tables and sequence can be created in the schema for each user who wants to gather profiler data or alternately these tables can be created in a central schema. For this example, we will run everything in a new created TEST schema. (Please see the code sample for the creation statements.) The SQL script that creates the required objects is also found in the $ORACLE_HOME/rdbms/admin directory within the proftab.sql file.
The test code
The following examples need select privilege granted on sys.v_$timer dynamic view. For example, execute the following to grant access to TEST user ID:
SQL> GRANT SELECT ON SYS.V_$TIMER TO TEST;
Grant succeeded.Setup the environment within the TEST schema using SQL*Plus:
SQL> CONN test/test
Connected.
SQL> @?/rdbms/admin/proftab.sql
drop table plsql_profiler_data cascade constraints
*
ERROR at line 1:
ORA-00942: table or view does not exist
drop table plsql_profiler_units cascade constraints
*
ERROR at line 1:
ORA-00942: table or view does not exist
drop table plsql_profiler_runs cascade constraints
*
ERROR at line 1:
ORA-00942: table or view does not exist
drop sequence plsql_profiler_runnumber
*
ERROR at line 1:
ORA-02289: sequence does not exist
Table created.
Comment created.
Table created.
Comment created.
Table created.
Comment created.
Sequence created.
SQL> CREATE TABLE test_table
2 (n_number int,
3 n_size varchar2(5));
Table created.
SQL> CREATE OR REPLACE PROCEDURE set_size
2 (n_number IN number, n_size OUT varchar2) AS
3 BEGIN
4 IF
5 n_number > 100
6 THEN
7 n_size := 'Large';
8 ELSE
9 n_size := 'Small';
10 END IF;
11 END set_size;
12 /
Procedure created.
SQL> CREATE OR REPLACE PACKAGE test AS
2 PROCEDURE main (n_number IN number, n_size OUT varchar2);
3 END;
4 /
Package created.
SQL> CREATE OR REPLACE PACKAGE BODY test AS
2 PROCEDURE dummy_proc (dept# IN number, count# out number) AS
3 BEGIN
4 SELECT round(DBMS_Random.Value(1,200)) INTO count# from dual;
5 END dummy_proc;
6
7 PROCEDURE main (n_number IN number, n_size OUT varchar2) IS
8 count# number;
9 start_time number;
10 end_time number;
11 BEGIN
12 select hsecs into start_time from v$timer;
13 set_size(n_number, n_size);
14 FOR i IN 1 .. 200 LOOP
15 dummy_proc( i, count#);
16 END LOOP; -- e loop
17 -- Placeholder
18 select hsecs into end_time from v$timer;
19 END main;
20 END test;
21 /
Package body created.
SQL> CREATE OR REPLACE TRIGGER trig_bi BEFORE INSERT
2 ON test_table FOR EACH ROW
3 BEGIN
4 test.main(:new.n_number, :new.n_size);
5 END;
6 /
Trigger created.Once environment has been set, start the profiling process and insert a row into the TEST_TABLE table to execute the above code and generate some trace information.
The following code turns on profiling, executes an insert then turns off profiling:
SQL> SELECT DBMS_PROFILER.START_PROFILER
2 ('TEST: '||to_char(sysdate,'dd-Mon-YYYY hh:mi:ss')) "Return Value"
3 FROM dual;
Return Value
------------
0
SQL> INSERT INTO test_table (n_number) VALUES (85) ;
1 row created.
SQL> COMMIT;
Commit complete.
SQL> SELECT DBMS_PROFILER.STOP_PROFILER "Return Value" FROM dual;
Return Value
------------
0Note: Return value may vary on your database.
Viewing the Profiling Data
There are two steps to compiling the profile information. Step 1 is to find the RunID and Step 2 is to use the RunID within subsequent queries to gather associated information.
1 – Find the RunID
To review profile results, first find the runid of the given test using the following command. The “column” command used below in SQL*Plus simply formats the data making it easier to read.
SQL> COLUMN run_comment FORMAT a40
SQL> SELECT runid, run_date, run_comment FROM plsql_profiler_runs;
RUNID RUN_DATE RUN_COMMENT
---------- --------- ----------------------------------------
1 13-FEB-13 TEST: 13-Feb-2013 05:35:09Although there may exist multiple entries, based on the timestamp it can easily be determined which was the last execution. In this case, there is just one execution and it is RUNID 1.
2 – Use the RunID to gather additional information.
To concentrate on timing details (min, max, avg), use a simple query that incorporates the RunID just obtained.
If no data is returned, there is a chance the RunID within the following SQL was not changed. The “column” command used below in SQL*Plus simply formats the data making it easier to read.
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 PAGESIZE 100
SQL> SELECT u.unit_name,
2 d.line#,
3 d.total_occur occured,
4 (d.total_time/1000000000) tot_time,
5 (d.min_time/1000000000) min_time,
6 (d.max_time/1000000000) max_time
7 FROM
8 plsql_profiler_units u,
9 plsql_profiler_data d
10 WHERE d.runid = u.runid
11 AND d.unit_number = u.unit_number
12 AND d.total_occur > 0
13 AND u.runid = &RUNID
14 ORDER BY u.unit_number, d.line# ;
Enter value for runid: 1
old 13: and u.runid = &RUNID
new 13: and u.runid = 1
UNIT_NAME LINE# OCCURED TOT_TIME MIN_TIME MAX_TIME
--------------- ------ ------- ----------- ---------- ----------
TRIG_BI 2 1 .000058 .000003879 .00005431
TRIG_BI 3 1 .000002 .000001939 .000001939
TEST 4 199 .011660 .000056249 .000133835
TEST 5 200 .000350 .000000969 .000002909
TEST 7 1 .000004 .000000969 .000002909
TEST 12 1 .001355 .001354841 .001354841
TEST 13 1 .000031 .000001939 .000029094
TEST 14 201 .000289 .000000969 .000001939
TEST 15 200 .000400 .000001939 .000002909
TEST 18 1 .000109 .00010862 .00010862
TEST 19 1 .000003 .000002909 .000002909
SET_SIZE 5 1 .000002 .000001939 .000001939
SET_SIZE 9 1 .000004 .000003879 .000003879
SET_SIZE 11 1 .000002 .000001939 .000001939
14 rows selected.To see the source code line, issue the following command using a query that incorporates the RunID just obtained.
SQL> COLUMN unit_name FORMAT a10
SQL> COLUMN line# FORMAT 99999
SQL> COLUMN text FORMAT a65
SQL> SET PAGESIZE 100
SQL> SET LINESIZE 100
SQL> SELECT p.unit_name,
2 p.line# line,
3 substr(s.text, 1,75) text
4 FROM
5 (
6 SELECT u.unit_name,
7 d.total_occur occured,
8 (d.total_time/1000000000) tot_time,
9 d.line#
10 FROM
11 plsql_profiler_units u,
12 plsql_profiler_data d
13 WHERE
14 d.runid = u.runid
15 AND d.unit_number = u.unit_number
16 AND d.total_occur > 0
17 AND u.runid = &RUNID
18 ) p, user_source s
19 WHERE
20 p.unit_name = s.name(+)
21 AND p.line# = s.line (+)
22 ORDER BY p.unit_name, p.line# ;
Enter value for runid: 1
old 17: AND u.runid = &RUNID
new 17: AND u.runid = 1
UNIT_NAME LINE TEXT
--------- ---- ---------------------------------------------------------------
SET_SIZE 5 n_number > 100
SET_SIZE 9 n_size := 'Small';
SET_SIZE 11 END set_size;
TEST 4 SELECT round(DBMS_Random.Value(1,200)) INTO count# FROM dual;
TEST 5 END dummy_proc;
TEST 7 PROCEDURE main (n_number IN number, n_size OUT varchar2) IS
TEST 12 select hsecs into start_time from v$timer;
TEST 13 set_size(n_number, n_size);
TEST 14 FOR i IN 1 .. 200 LOOP
TEST 15 dummy_proc( i, count#);
TEST 18 select hsecs into end_time from v$timer;
TEST 19 END main;
TRIG_BI 2 ON test_table FROM EACH ROW
TRIG_BI 3 BEGIN
14 rows selected.Comments on the above output
– The time is measured in 1/1000000000 seconds.
– The time of the procedure call is only the overhead of the call and return, not the execution time of the entire procedure. For example, the TRIG_BI is a call of TEST.main, and its time is less than that of the FOR loop in the main procedure.
– The FOR loop is executed 200 times. Therefore, the header line is executed 200+1 times.
Link to script that contains the examples in this post.