Tuesday, September 15, 2009

DBMS_PROFILER

DBMS_PROFILER is introduced in oracle8i. It is powerful tool to find the PLSQL execution time and determine the bottleneck of the program unit. This tool provides information about how many times each line is executing and how much time it is spending to execute for each line of the code. The basic idea behind the profiling is, developers can understand where the code is taking most time and they can detect and optimize the PLSQL code. We use SQL trace to determine the bottleneck for SQL code. But for PLSQL code, we can use dbms_profiler utility to profile the run time behaviour. Steps might very for other oracle versions.

How do we set up dbms_profiler utility?

Please remember, the dbms_profiler setup is not part of Oracle installation. We need to setup manually if we want to profile the PLSQL code. There are five simple steps to configure the dbms_profiler. Let us start configure the profiler. This article is tested in oracle10g R2.

Step1. The dbms_profiler package can be loaded by running the $ORACLE_HOME/rdbms/admin/profload.sql script as the SYS user. Execute profload.sql in sys schema.

Connected to:
Oracle Database 10g Enterprise Edition Release 10.2.0.3.0 - Production
With the Partitioning, OLAP and Data Mining options

SQL> connect sys/password@orcl as sysdba
Connected.
SQL> start c:/oracle/product/10.2.0/db_1/rdbms/admin/profload.sql

Package created.

Grant succeeded.

Synonym created.

Library created.

Package body created.

Testing for correct installation
SYS.DBMS_PROFILER successfully loaded.

PL/SQL procedure successfully completed.

Step2. dbms_profiler package requires some schema objects which should be created in central schema or application schema. Create a new schema called profiler. We can either create a new schema or use existing schema. In this case, i created new schema, named Profiler.

SQL> create user profiler
2 identified by profiler;

User created.

SQL> grant create session,resource,connect to profiler;
Grant succeeded.

SQL>

Step3. Run the $ORACLE_HOME/rdbms/admin/proftab.sql file on the profiler schema to create some schema objects to store profiler information. This proftab.sql file creates below three tables with some other objects.

1.PLSQL_PROFILER_RUNS
2.PLSQL_PROFILER_UNITS
3.PLSQL_PROFILER_DATA

SQL> connect profiler/profiler@orcl
Connected.
SQL> start c:/oracle/product/10.2.0/db_1/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>

Step4. Connect into profiler schema and grant the below privileges.

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;

SQL> connect profiler/profiler@orcl
Connected.
SQL> GRANT SELECT ON plsql_profiler_runnumber TO PUBLIC;

Grant succeeded.

SQL> GRANT SELECT, INSERT, UPDATE, DELETE ON plsql_profiler_data TO PUBLIC;

Grant succeeded.

SQL> GRANT SELECT, INSERT, UPDATE, DELETE ON plsql_profiler_units TO PUBLIC;

Grant succeeded.

SQL> GRANT SELECT, INSERT, UPDATE, DELETE ON plsql_profiler_runs TO PUBLIC;

Grant succeeded.

SQL>

Step5. Connect into sys schema and grant the below privileges for dbms_profiler package.

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;

SQL> connect sys/password@orcl as sysdba
Connected.
SQL> CREATE PUBLIC SYNONYM plsql_profiler_runs FOR profiler.plsql_profiler_runs;

Synonym created.

SQL> CREATE PUBLIC SYNONYM plsql_profiler_units FOR profiler.plsql_profiler_units;

Synonym created.

SQL> CREATE PUBLIC SYNONYM plsql_profiler_data FOR profiler.plsql_profiler_data;

Synonym created.

SQL> CREATE PUBLIC SYNONYM plsql_profiler_runnumber FOR profiler.plsql_profiler_runnumber;

Synonym created.

SQL>

Once we are successful with five steps, we can start profiling the PLSQL code.

How do we profile the PLSQL Procedure?

Let us create sample procedure and profile the procedure.

1. start profiler
2. run the procedure
3. stop profiler
4. flush data from memory and save into table
5. Analyze the data and see where it is taking more time

Here i create a procedure called do_something in SCOTT schema. You can also profile the procedure which is existing in any schema in the database.

SQL> CREATE OR REPLACE PROCEDURE do_something (p_times IN NUMBER) AS
2 v_cnt NUMBER;
3 BEGIN
4 FOR i IN 1 .. p_times LOOP
5 SELECT count(*) + p_times
6 INTO v_cnt
7 FROM EMP;
8 END LOOP;
9 END;
10 /

Procedure created.

The below unnamed PLSQL code starts the profiler and call the procedure. Once the procedure is executed, it stop the profiler. It flush the data from memory and save into table.

SQL> DECLARE
2 l_result BINARY_INTEGER;
3 BEGIN
4 l_result := DBMS_PROFILER.start_profiler(run_comment => 'do_something: ' SYSDATE);
5 do_something(p_times => 100);
6 l_result := DBMS_PROFILER.stop_profiler;
7 dbms_profiler.flush_data;
8 END;
9 /

PL/SQL procedure successfully completed.

SQL>

Here is query to check the profiler result.

SQL> SET LINESIZE 200
SQL> SET TRIMOUT ON
SQL>
SQL> COLUMN runid FORMAT 99999
SQL> COLUMN run_comment FORMAT A50
SQL> SELECT runid,
2 run_date,
3 run_comment,
4 run_total_time
5 FROM plsql_profiler_runs
6 ORDER BY runid;

RUNID RUN_DATE RUN_COMMENT RUN_TOTAL_TIME
------ --------- -------------------------------------------------- --------------
4 15-SEP-09 do_something: 15-SEP-09 686370753

SQL> SELECT d.line#,
2 d.total_occur,
3 d.total_time
4 FROM plsql_profiler_units u
5 JOIN plsql_profiler_data d ON u.runid = d.runid AND u.unit_number = d.unit_number
6 WHERE u.runid = 4
7 and unit_name='DO_SOMETHING'
8 and unit_owner='SCOTT'
9 and unit_type='PROCEDURE'
10 ORDER BY u.unit_number, d.line#;

LINE# TOTAL_OCCUR TOTAL_TIME
---------- ----------- ----------
1 1 199466
4 101 2247771
5 100 513261322
9 1 85485

SQL> SELECT line ' : ' text
2 FROM all_source
3 WHERE owner = 'SCOTT'
4 AND type = 'PROCEDURE'
5 AND name = 'DO_SOMETHING';

LINE':'TEXT
----------------------------------------------------------------------------------------------------
1 : PROCEDURE do_something (p_times IN NUMBER) AS
2 : v_cnt NUMBER;
3 : BEGIN
4 : FOR i IN 1 .. p_times LOOP
5 : SELECT count(*) + p_times
6 : INTO v_cnt
7 : FROM EMP;
8 : END LOOP;
9 : END;

9 rows selected.

SQL>

Conclusion : The line number 4 runs 101 times and line number 5 runs 100 times. The procedure spends most of the time at line number 5. Now we figured out exactly where it is taking longer time. We can focus on tuning the line 5 in case if we want to....

Where do we use dbms_profiler? TKPROF and Explain plan helps to find where it is taking long time to complete the SQL. Dbms_profiler is useful, if we want to find out which line is consuming most time in entire PLSQL.

The source of this article is oracle-base.

No comments: