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.

How do we make trace file readable by using TKPROF?

TKPROF is Oracle utility to convert the Orace trace file into readable format. It is one of the most useful utility available to DBAs for diagnosing performance issues

TKPROF syntax is:

tkprof filename1 filename2 [waits=yesno] [sort=option] [print=n]
[aggregate=yesno] [insert=filename3] [sys=yesno] [table=schema.table]
[explain=user/password] [record=filename4] [width=n]

Here is the example to use the TKPROF utility.

tkprof dmdprod_ora_11154.trc traceoutput.txt sys=no

TKPROF command line options.

Print – This option will list number SQL statement in trace file. We can use this command when we want to list only specific number sql statement. This command is very useful when combining SORT option to list only top N statement by CPU, disk access etc.

Aggregate – When it is YES, then combine the statistics from multiple user execution for the same SQL statement.

Waits - It is used to record summary for any wait events found in the trace file

Insert – Create file to load the trace info into table for further processing. This will be useful for future analysis.

Sys – If it is NO, then it will exclude SQL statement which is executed by SYS schema. The default value is YES.

Table – It is used to load the explain plan info into table. We need to specify the schema name and table name to load the explain plan info. The table old data will be deleted when we use this option. If the table does not exist, then oracle will create the table to load the data.

Record – It is used to store all the non recursive SQL statement from the trace file. This statement can be used if we want to log the SQL statement in separate file.

Explain – It will be used if we want to generate the pre determined execution plan in trace file. When you use this option, you will see execution plan as well as Real plan in trace file. Execution plan is pre execution plan(like asking direction to home), Real Plan(like showing direction how you got home. In trace file, Real Plan will be displayed as Row source generation).

Sort – It will be useful if we want to see the top SQL which are consumed the most resources. Resource like CPU usage, disk usage etc.

The following are the data elements available for sorting:

. prscnt – The number of times the SQL was parsed.
· prscpu – The CPU time spent parsing.
· prsela – The elapsed time spent parsing the SQL.
· prsdsk – The number of physical reads required for the parse.
· prsmis – The number of consistent block reads required for the parse.
· prscu – The number of current block reads required for the parse.
· execnt – The number of times the SQL statement was executed.
· execpu – The CPU time spent executing the SQL.
· exeela – The elapsed time spent executing the SQL.
· exedsk – The number of physical reads during execution.
· exeqry – The number of consistent block reads during execution.
· execu – The number of current block reads during execution.
· exerow – The number of rows processed during execution.
· exemis – The number of library cache misses during execution.
· fchcnt – The number of fetches performed.
· fchcpu – The CPU time spent fetching rows.
· fchela – The elapsed time spent fetching rows.
· fchdsk – The number of physical disk reads during the fetch.
· fchqry – The number of consistent block reads during the fetch.
· fchcu – The number of current block reads during the fetch.
· fchrow – The number of rows fetched for the query.

TKPROF output

update COLLECTION set body=:1, control_no=:2, STATE=:3,
created_dt=:4, author=:5
where
id=:6
call count cpu elapsed disk query current rows
------- ------ -------- ---------- ---------- ---------- ---------- -------------------
Parse 0 0.00 0.00 0 0 0 0
Execute 1 55.99 145.55 1057 9495719 8238 1
Fetch 0 0.00 0.00 0 0 0 0
------- ------ -------- ---------- ---------- ---------- ---------- -------------------
total 2 55.99 145.56 1057 9495719 8238 1

Misses in library cache during parse: 1

Optimizer goal: FIRST_ROWS
Parsing user id: 67
Rows Row Source Operation
------- --------------------------------------------------------------------------------
1 UPDATE
1 TABLE ACCESS BY INDEX ROWID MWS_COLLECTION
1 INDEX UNIQUE SCAN PK_MWS_COLLECTION (object id 139890)
********************************************************************************

1. Parse – Parse does syntax checks, permissions, and all object dependencies.
2. Execute – The actual execution of the statement.
3. Fetch – The number of rows returned for a SELECT statement

count = number of times OCI procedure was executed
cpu = cpu time in seconds executing
elapsed = elapsed time in seconds executing
disk = number of physical reads of buffers from disk
query = number of buffers gotten for consistent read
current = number of buffers gotten in current mode (usually for update)
rows = number of rows processed by the fetch or execute call

V$SQLPLAN Versus EXPLAIN PLAN

EXPLAIN PLAN and v$sql_plan are providing same type of information. EXPLAIN PLAN command is used to display the execution plan of a SQL statement without actually executing it. But v$sql_plan dictionary view is used to show the execution plan of the SQL statement that has been compiled into a cursor in the cache.

What should DBA look in tkprof output file?
1. Compare the number of parses to number of executions. A Well defined system will have one parse per n executions.
2. Check any SQL do not use bind variables
3. Check if there is any Full table scan, Multiple disk reads, high CPU consumption.