TIP #45 : Performance tuning PL/SQL with profiler.

Oracle provides dbms_profiler for tracing PL/SQL code and finding any performace bottlenecks.
This post shows how to use it.
For using dbms_profiler, first it should be installed.

Install dbms_profile and populate tables.

- @?/rdbms/admin/profload.sql (Install dbms_profiler)
- @?/rdbms/admin/proftab.sql (Populate profiler tables).

How to trace :

- exec dbms_profiler.start_profiler('Sample1');
- Run PL/SQL code (it would be better to be proc/func/package instead of anonymous code.
- exec dbms_profiler.stop_profiler;
- exec DBMS_PROFILER.FLUSH_DATA;

How to see the result :

- Which runid is for current trace
SELECT runid,
run_date,
run_comment,
run_total_time
FROM plsql_profiler_runs
ORDER BY runid;


- Total elapsed time of each PL/SQL code.


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#;


FYI : Also putting dbms_utility.get_time(); in PL/SQL code would show exact run time execution of each PL/SQL pieces.

6 comments:

Anonymous said...

hi,
You r doing great work,
iam a new oracle DBA learning from your blog, in a recent interview i was asked how u will tune a sql query running for a long time..
pls help me on this..

fabio said...

Great work.
I followed your instructions but I get incoerent results:
from sqlplus the package procedure runs for about 4 secs. When i review DBMS_PROFILER results I get durations of thousands of secs...
any suggestion?

Shervin said...

Hi,

Thanks for comment.
Please let me know on which version of Oracle you ran DBMS_PROFILER.

Shervin

fabio said...

Hi, shervin, the RDBMS is 9.2.0.7 (patched following oracle guidelines).this is the profsum script header:
Rem $Header: profsum.sql 13-apr-98.19:17:28 astocks Exp $

fabio said...

... and this is an extract from the profsum output:

===========================Results for run #1 made on 21-MAR-08 18:31:03 =========================
(ultimo) Run total time: 2803.72 seconds
[...]
19.994 1126,1389 ,05632384 fetch cur_contact_pool into tmp_id;

the strange is that when i run the script in sqlplus with timing on it takes 4.07 secs to do the job:

SQL> exec wcm.history.fy(180);

Procedura PL/SQL completata correttamente.

Passati: 00:00:04.07


Fabio

fabio said...

I have seen a lot of work on TEMP so I'VE ENLARGED SORT_AREA_SIZE to 50MB (also if the sort ratio disk/memory does'nt suggest to do it, it was done mainly in memory).
Other ratios (dbcache, etc).
And I can tell you also that using tracing timings are ok:

SELECT CONTACT_POOL_ID
FROM
CONTACT_POOL WHERE CONTACT_LIST_ID IN ( SELECT CONTACT_LIST_ID FROM
CONTACT_LIST WHERE CAMPAIGN_ID IN ( SELECT CAMPAIGN_ID FROM CAMPAIGNS C
WHERE TRUNC(SYSDATE-TO_DATE(C.DATA_FINE,'YYYYMMDD')) > :B1 AND
(C.DATA_FINE_OUT IS NULL OR TRUNC(SYSDATE-TO_DATE(C.DATA_FINE_OUT,
'YYYYMMDD')) > :B1 ) ) )


call count cpu elapsed disk query current rows
------- ------ -------- ---------- ---------- ---------- ---------- ----------
Parse 0 0.00 0.00 0 0 0 0
Execute 1 0.00 0.00 0 0 0 0
Fetch 19993 1.20 1.30 948 20378 2 19992
------- ------ -------- ---------- ---------- ---------- ---------- ----------
total 19994 1.20 1.30 948 20378 2 19992

Misses in library cache during parse: 0
Optimizer goal: CHOOSE
Parsing user id: 60 (WCM) (recursive depth: 1)

Rows Execution Plan
------- ---------------------------------------------------
0 SELECT STATEMENT GOAL: CHOOSE
0 NESTED LOOPS
0 MERGE JOIN (CARTESIAN)
0 TABLE ACCESS GOAL: ANALYZED (FULL) OF 'CAMPAIGNS'
0 BUFFER (SORT)
0 INDEX GOAL: ANALYZED (FAST FULL SCAN) OF
'SYS_IOT_TOP_31635' (UNIQUE)
0 INDEX GOAL: ANALYZED (UNIQUE SCAN) OF 'SYS_IOT_TOP_31638'
(UNIQUE)