DBMS_PROFILER
The
DBMS_PROFILER package was introduced in Oracle 8i to allow developers to profile the run-time behaviour of PL/SQL code,
Making it easier to identify performance bottlenecks which can then be investigated more closely.
- The first step is to install the
DBMS_PROFILERpackage (profload.sql) - create the tables to hold the profiler results (proftab.sql).
- The profiler tables can be created in your local schema, or in a shared schema, as shown below.
-- Install the DBMS_PROFILER package.
CONNECT sys/password@service AS SYSDBA
@$ORACLE_HOME/rdbms/admin/profload.sql
-- Install tables in a shared schema.
CREATE USER profiler IDENTIFIED BY profiler DEFAULT TABLESPACE users QUOTA UNLIMITED ON users;
GRANT CREATE SESSION TO profiler;
GRANT CREATE TABLE, CREATE SEQUENCE TO profiler;
CREATE PUBLIC SYNONYM plsql_profiler_runs FOR profiler.plsql_profiler_runs;
CREATE PUBLIC SYNONYM plsql_profiler_units FOR profiler.plsql_profiler_units;
CREATE PUBLIC SYNONYM plsql_profiler_data FOR profiler.plsql_profiler_data;
CREATE PUBLIC SYNONYM plsql_profiler_runnumber FOR profiler.plsql_profiler_runnumber;
CONNECT profiler/profiler@service
@$ORACLE_HOME/rdbms/admin/proftab.sql
GRANT SELECT ON plsql_profiler_runnumber TO PUBLIC;
GRANT SELECT, INSERT, UPDATE, DELETE ON plsql_profiler_data TO PUBLIC;
GRANT SELECT, INSERT, UPDATE, DELETE ON plsql_profiler_units TO PUBLIC;
GRANT SELECT, INSERT, UPDATE, DELETE ON plsql_profiler_runs TO PUBLIC;
Make sure the user that needs to run the profiler has the correct privileges on the
DBMS_PROFILER package.
GRANT EXECUTE ON dbms_profiler TO test;
Next we connect to the test user and create a dummy procedure to profile.
CONN test/test@service
CREATE OR REPLACE PROCEDURE do_something (p_times IN NUMBER) AS
l_dummy NUMBER;
BEGIN
FOR i IN 1 .. p_times LOOP
SELECT l_dummy + 1
INTO l_dummy
FROM dual;
END LOOP;
END;
/
Next we start the profiler, run our procedure and stop the profiler.
DECLARE
l_result BINARY_INTEGER;
BEGIN
l_result := DBMS_PROFILER.start_profiler(run_comment => 'do_something: ' || SYSDATE);
do_something(p_times => 100);
l_result := DBMS_PROFILER.stop_profiler;
END;
/
With the profile complete we can analyze the data to see which bits of the process took the most time, with all times presented in nanoseconds. First we check out which runs we have.
SET LINESIZE 200
SET TRIMOUT ON
COLUMN runid FORMAT 99999
COLUMN run_comment FORMAT A50
SELECT runid,
run_date,
run_comment,
run_total_time
FROM plsql_profiler_runs
ORDER BY runid;
RUNID RUN_DATE RUN_COMMENT RUN_TOTAL_TIME
----- --------- ---------------------------------- --------------
1 21-AUG-03 do_something: 21-AUG-2003 14:51:54 131072000
We then use the appropriate
RUNID value in the following query.
COLUMN runid FORMAT 99999
COLUMN unit_number FORMAT 99999
COLUMN unit_type FORMAT A20
COLUMN unit_owner FORMAT A20
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 = 1
ORDER BY u.unit_number, d.line#;
RUNID UNIT_NU UNIT_TYPE UNIT_OWNER UNIT_NAME LINE# TOTAL_OCCUR TOTAL_TIME MIN_TIME MAX_TIME
----- ------- --------------- ----------- ------------ ----- ----------- ---------- -------- --------
1 1 ANONYMOUS BLOCK <anonymous> <anonymous> 4 1 0 0 0
1 1 ANONYMOUS BLOCK <anonymous> <anonymous> 5 1 0 0 0
1 1 ANONYMOUS BLOCK <anonymous> <anonymous> 6 1 0 0 0
1 2 PROCEDURE MY_SCHEMA DO_SOMETHING 4 101 0 0 0
1 2 PROCEDURE MY_SCHEMA DO_SOMETHING 5 100 17408000 0 2048000
5 rows selected.
The results of this query show that line 4 of the
DO_SOMETHING procedure ran 101 times but took very little time, while line 5 ran 100 times and took proportionately more time.
We can check the line numbers of the source using the following query.
SELECT line || ' : ' || text
FROM all_source
WHERE owner = 'MY_SCHEMA'
AND type = 'PROCEDURE'
AND name = 'DO_SOMETHING';
LINE||':'||TEXT
---------------------------------------------------
1 : PROCEDURE do_something (p_times IN NUMBER) AS
2 : l_dummy NUMBER;
3 : BEGIN
4 : FOR i IN 1 .. p_times LOOP
5 : SELECT l_dummy + 1
6 : INTO l_dummy
7 : FROM dual;
8 : END LOOP;
9 : END;
As expected, the query took proportionately more time than the procedural loop. Assuming this were a real procedure we could use the DBMS_TRACE or the SQL trace facilities to investigate the problem area further.
