DBMS_PROFILER

The DBMS_PROFILER package was introduced in Oracle8i 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_PROFILER package:

CONNECT sys/password@service AS SYSDBA
@$ORACLE_HOME/rdbms/admin/profload.sql

CREATE USER profiler IDENTIFIED BY profiler DEFAULT TABLESPACE users QUOTA UNLIMITED ON users;
GRANT connect 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;

Next we create a dummy procedure to profile:

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 can 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        4           1          0        0        0
    1       1 ANONYMOUS BLOCK        5           1          0        0        0
    1       1 ANONYMOUS BLOCK        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  wner = '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.

For further information see:

• DBMS_PROFILER
• DBMS_TRACE

來自 “ ITPUB部落格 ” ，連結：http://blog.itpub.net/756652/viewspace-474964/，如需轉載，請註明出處，否則將追究法律責任。