Sometimes statements take longer than you’d like to complete. This can happen for a number of reasons including data changes, table growth, stale statistics and the occasional optimizer bug you haven’t encountered before. When it’s a SQL query that is misbehaving it’s pretty easy to find the cause and, in many cases, fix it. When it’s PL/SQL it isn’t as easy to do. There are views available from Oracle to assist in this endeavor and, provided you’re licensed, these views can make the troubleshooting process much easier.
Finding long-running statements used to be a task for the V$SESSION_LONGOPS view but it doesn’t record every long running operation so some problem statements could be missed because their actions aren’t recorded there. With Oracle 10.2 and later releases AWR provides an extended window into performance statistics, and in this particular case the views you want are DBA_HIST_SQLSTAT and DBA_HIST_SQLTEXT. [The AWR views require being licensed for the Diagnostic and Tuning pack so you don’t run afoul of the Oracle licensing.] The following statements can be used to generate listings of long-running statements, both historically and from current sessions; put them into a single script and you can generate troubleshooting data to assist you in your efforts:
set linesize 200 trimspool on pagesize 60 verify off
column begin_interval_time format a35
column end_interval_time format a35
break on sql_id skip 1 on instance_number
column sdate new_value sdt noprint
select to_char(sysdate, 'YYYYMMDDHHMI') sdate from dual;
spool &sdt._elapsed_time_report.log
prompt
prompt Historic
prompt
prompt Elapsed by exec
prompt
select distinct x.instance_number, x.sql_id, x.time_per_exec, x.elapsed_time_total, s.begin_interval_time, s.end_interval_time
from
(select instance_number, sql_id, snap_id,
round((elapsed_time_total/1000000)/(case when executions_total = 0 then 1 else executions_total end),4) time_per_exec,
round(elapsed_time_total/1000000, 4) elapsed_time_total
from dba_hist_sqlstat) x, (select snap_id,
max(begin_interval_time) begin_interval_time,
max(end_interval_time) end_interval_time
from dba_hist_snapshot
group by snap_id) s
where s.snap_id = x.snap_id
and x.time_per_exec > &&1
and x.time_per_exec x.elapsed_time_total
order by 2 asc, 3 desc, 6 desc
/
clear breaks
prompt
prompt Elapsed time total, current statements
prompt
select inst_id,
sql_id,
executions,
round(elapsed_time/1000000, 6) elapsed_sec,
round((elapsed_time/1000000)/(case when executions = 0 then 1 else executions end), 6) elapsed_per_exec,
last_active_time
from gv$sqlstats
where elapsed_time/1000000 > &&1
order by 4 desc
/
prompt
prompt Elapsed per exec, current statements
prompt
select inst_id,
sql_id,
executions,
round(elapsed_time/1000000, 6) elapsed_sec,
round((elapsed_time/1000000)/(case when executions = 0 then 1 else executions end), 6) elapsed_per_exec,
last_active_time
from gv$sqlstats
where elapsed_time/1000000 > &&1
order by 5 desc
/
prompt
prompt SQL text for current statements
prompt
set long 1000000 linesize 200 trimspool on
column sql_text format a132
select sql_id, sql_text
from dba_hist_sqltext
where sql_id in
(
select sql_id
from gv$sqlstats
where elapsed_time/1000000 > &&1
);
set linesize 80 trimspool off
spool off
Calling such a script is straightforward, simply provide the minimum length of time, in seconds, the script should consider as a starting point for the report; notice that there is a historic section and a current statement section so don’t expect the results from the first (historic) query to match those of the remaining queries. As an example let’s look at statements running for 15 seconds or longer:
SQL> @query_elapsed_per_exec 15
Historic
Elapsed by exec
INSTANCE_NUMBER SQL_ID TIME_PER_EXEC ELAPSED_TIME_TOTAL BEGIN_INTERVAL_TIME END_INTERVAL_TIME
--------------- ------------- ------------- ------------------ ----------------------------------- -----------------------------------
1 0nazp4jx2k26t 33.9633 67.9265 30-JAN-14 02.00.05.958 AM 30-JAN-14 03.00.43.716 AM
1 6ajkhukk78nsr 20.0365 40.0729 28-JAN-14 12.00.01.801 PM 28-JAN-14 01.00.06.031 PM
1 6kk1p64v5qhvx 43.0353 258.2121 22-JAN-14 11.00.07.315 AM 22-JAN-14 12.00.14.834 PM
1 b6usrg82hwsa3 63.9262 127.8525 26-JAN-14 05.00.29.524 PM 26-JAN-14 06.00.29.893 PM
44.3428 133.0283 26-JAN-14 09.00.42.077 PM 26-JAN-14 10.00.46.559 PM
35.0675 140.2702 27-JAN-14 01.00.53.979 AM 27-JAN-14 02.01.00.542 AM
6 rows selected.
Elapsed time total, current statements
INST_ID SQL_ID EXECUTIONS ELAPSED_SEC ELAPSED_PER_EXEC LAST_ACTI
---------- ------------- ---------- ----------- ---------------- ---------
1 f6cz4n8y72xdc 1 17.983987 17.983987 30-JAN-14
1 02577v815yp77 1 17.408648 17.408648 30-JAN-14
Elapsed per exec, current statements
INST_ID SQL_ID EXECUTIONS ELAPSED_SEC ELAPSED_PER_EXEC LAST_ACTI
---------- ------------- ---------- ----------- ---------------- ---------
1 f6cz4n8y72xdc 1 17.983987 17.983987 30-JAN-14
1 02577v815yp77 1 17.408648 17.408648 30-JAN-14
SQL text for current statements
SQL_ID SQL_TEXT
------------- ------------------------------------------------------------------------------------------------------------------------------------
f6cz4n8y72xdc SELECT space_usage_kbytes FROM v$sysaux_occupants WHERE occupant_name = 'SQL_MANAGEMENT_BASE'
02577v815yp77 BEGIN :success := dbms_ha_alerts_prvt.post_instance_up; END;
SQL>
The ‘offending’ SQL text is now available so you can take that and, using UNIX/Linux utilities like grep, find source code that may need to be tuned. If you don’t have grep (you’re on Windows and haven’t installed any of the Windows-ported UNIX/Linux utilities) you can query either the DBA_SOURCE or USER_SOURCE view to find the package or procedure that contains the errant code. Presumably your enterprise is using some form of change control to manage code modifications which will make the source easy to modify. However, if for some strange reason code is simply written and deployed (a ghastly occurrence) using either DBA_SOURCE or USER_SOURCE should allow you to retrieve the problem code and get it corrected. As you can see the 15 second window doesn’t supply much data from my personal database so let’s use a shorter length of time and get more output:
SQL> query_elapsed_per_exec 4
Historic
Elapsed by exec
INSTANCE_NUMBER SQL_ID TIME_PER_EXEC ELAPSED_TIME_TOTAL BEGIN_INTERVAL_TIME END_INTERVAL_TIME
--------------- ------------- ------------- ------------------ ----------------------------------- -----------------------------------
1 0nazp4jx2k26t 33.9633 67.9265 30-JAN-14 02.00.05.958 AM 30-JAN-14 03.00.43.716 AM
1 1cd2krbdzrhvq 7.9052 79.052 30-JAN-14 02.00.05.958 AM 30-JAN-14 03.00.43.716 AM
1 1cq3qr774cu45 6.6394 66.3944 30-JAN-14 02.00.05.958 AM 30-JAN-14 03.00.43.716 AM
1 2nszajb0qbyvp 4.2614 8.5229 29-JAN-14 08.20.57.000 AM 29-JAN-14 08.32.46.414 AM
4.1071 8.2142 28-JAN-14 11.36.50.000 PM 28-JAN-14 11.48.05.036 PM
1 350myuyx0t1d6 4.6085 46.0851 30-JAN-14 02.00.05.958 AM 30-JAN-14 03.00.43.716 AM
1 35y2u24f4rxqm 6.9261 34.6305 29-JAN-14 12.00.00.587 PM 29-JAN-14 01.00.07.187 PM
5.7718 34.631 29-JAN-14 01.00.07.187 PM 29-JAN-14 02.00.11.450 PM
4.9473 34.6314 29-JAN-14 02.00.11.450 PM 29-JAN-14 03.00.16.164 PM
1 63n9pwutt8yzw 8.2877 16.5754 26-JAN-14 05.00.29.524 PM 26-JAN-14 06.00.29.893 PM
6.4604 19.3812 26-JAN-14 09.00.42.077 PM 26-JAN-14 10.00.46.559 PM
5.0272 20.1089 27-JAN-14 01.00.53.979 AM 27-JAN-14 02.01.00.542 AM
1 6ajkhukk78nsr 20.0365 40.0729 28-JAN-14 12.00.01.801 PM 28-JAN-14 01.00.06.031 PM
13.464 40.3919 28-JAN-14 01.00.06.031 PM 28-JAN-14 02.00.09.913 PM
10.1444 40.5776 28-JAN-14 02.00.09.913 PM 28-JAN-14 03.00.14.264 PM
9.9596 29.8787 23-JAN-14 11.00.11.607 AM 23-JAN-14 12.00.17.236 PM
9.1878 36.7513 23-JAN-14 12.00.17.236 PM 23-JAN-14 01.00.23.702 PM
8.3653 41.8264 28-JAN-14 03.00.14.264 PM 28-JAN-14 04.00.18.883 PM
8.2677 16.5355 23-JAN-14 10.00.06.894 AM 23-JAN-14 11.00.11.607 AM
8.0056 16.0111 24-JAN-14 09.00.15.036 AM 24-JAN-14 10.00.21.294 AM
7.4062 37.0311 23-JAN-14 01.00.23.702 PM 23-JAN-14 02.00.27.111 PM
6.8399 13.6798 22-JAN-14 09.00.56.596 AM 22-JAN-14 10.00.02.354 AM
6.3572 31.786 22-JAN-14 12.00.14.834 PM 22-JAN-14 01.00.20.445 PM
6.198 37.1877 23-JAN-14 02.00.27.111 PM 23-JAN-14 03.00.31.177 PM
5.9719 35.8313 22-JAN-14 01.00.20.445 PM 22-JAN-14 02.00.27.213 PM
5.7639 17.2917 24-JAN-14 10.00.21.294 AM 24-JAN-14 11.00.26.060 AM
5.5205 38.6435 22-JAN-14 02.00.27.213 PM 22-JAN-14 03.00.32.344 PM
4.7033 14.1099 22-JAN-14 10.00.02.354 AM 22-JAN-14 11.00.07.315 AM
4.5685 18.2742 24-JAN-14 11.00.26.060 AM 24-JAN-14 12.00.31.071 PM
4.0313 20.1563 24-JAN-14 12.00.31.071 PM 24-JAN-14 01.00.36.467 PM
1 6c9u8s2zwmthf 5.8052 17.4155 27-JAN-14 10.00.16.082 AM 27-JAN-14 11.00.23.152 AM
1 6kk1p64v5qhvx 43.0353 258.2121 22-JAN-14 11.00.07.315 AM 22-JAN-14 12.00.14.834 PM
1 6mcpb06rctk0x 7.2119 14.4237 26-JAN-14 05.00.29.524 PM 26-JAN-14 06.00.29.893 PM
4.9693 14.9079 26-JAN-14 09.00.42.077 PM 26-JAN-14 10.00.46.559 PM
1 7ydcybv1szhrj 5.1018 10.2037 29-JAN-14 08.32.46.414 AM 29-JAN-14 10.00.52.345 AM
1 9ctt1scmwbmbg 6.2727 12.5454 29-JAN-14 08.32.46.414 AM 29-JAN-14 10.00.52.345 AM
5.4683 10.9365 28-JAN-14 12.00.01.801 PM 28-JAN-14 01.00.06.031 PM
4.4863 8.9726 30-JAN-14 08.02.30.500 AM 30-JAN-14 09.00.33.806 AM
4.3223 12.9669 29-JAN-14 10.00.52.345 AM 29-JAN-14 11.00.56.416 AM
1 b3abwkm67yg8r 4.0078 8.0156 29-JAN-14 06.08.45.886 PM 29-JAN-14 07.00.30.792 PM
1 b6usrg82hwsa3 63.9262 127.8525 26-JAN-14 05.00.29.524 PM 26-JAN-14 06.00.29.893 PM
44.3428 133.0283 26-JAN-14 09.00.42.077 PM 26-JAN-14 10.00.46.559 PM
35.0675 140.2702 27-JAN-14 01.00.53.979 AM 27-JAN-14 02.01.00.542 AM
43 rows selected.
Elapsed time total, current statements
INST_ID SQL_ID EXECUTIONS ELAPSED_SEC ELAPSED_PER_EXEC LAST_ACTI
---------- ------------- ---------- ----------- ---------------- ---------
1 f6cz4n8y72xdc 1 17.983987 17.983987 30-JAN-14
1 02577v815yp77 1 17.408648 17.408648 30-JAN-14
1 12a2xbmwn5v6z 1 13.154622 13.154622 30-JAN-14
1 8mz0wa11tacp0 1 10.168939 10.168939 30-JAN-14
1 3ktacv9r56b51 163 9.548086 .058577 30-JAN-14
1 c2p32r5mzv8hb 1 9.054776 9.054776 30-JAN-14
1 9ctt1scmwbmbg 3 9.015966 3.005322 30-JAN-14
1 6ajkhukk78nsr 3 8.864179 2.954726 30-JAN-14
1 db78fxqxwxt7r 807 8.675157 .01075 30-JAN-14
1 01uy9sb7w8a9g 1 8.557564 8.557564 30-JAN-14
1 c0agatqzq2jzr 3 7.937203 2.645734 30-JAN-14
1 cvn54b7yz0s8u 99 7.722906 .078009 30-JAN-14
1 g0jvz8csyrtcf 1 6.608542 6.608542 30-JAN-14
1 ga9j9xk5cy9s0 99 5.745133 .058032 30-JAN-14
1 b3abwkm67yg8r 3 5.286708 1.762236 30-JAN-14
1 cnq31548hb8un 1 5.123489 5.123489 30-JAN-14
1 96g93hntrzjtr 3002 4.909722 .001635 30-JAN-14
1 3nkd3g3ju5ph1 910 4.892754 .005377 30-JAN-14
1 2nszajb0qbyvp 14 4.570901 .326493 30-JAN-14
1 832kkz790r75k 1 4.17935 4.17935 30-JAN-14
20 rows selected.
Elapsed per exec, current statements
INST_ID SQL_ID EXECUTIONS ELAPSED_SEC ELAPSED_PER_EXEC LAST_ACTI
---------- ------------- ---------- ----------- ---------------- ---------
1 f6cz4n8y72xdc 1 17.983987 17.983987 30-JAN-14
1 02577v815yp77 1 17.408648 17.408648 30-JAN-14
1 12a2xbmwn5v6z 1 13.154622 13.154622 30-JAN-14
1 8mz0wa11tacp0 1 10.168939 10.168939 30-JAN-14
1 c2p32r5mzv8hb 1 9.054776 9.054776 30-JAN-14
1 01uy9sb7w8a9g 1 8.557564 8.557564 30-JAN-14
1 g0jvz8csyrtcf 1 6.608542 6.608542 30-JAN-14
1 cnq31548hb8un 1 5.123489 5.123489 30-JAN-14
1 832kkz790r75k 1 4.17935 4.17935 30-JAN-14
1 9ctt1scmwbmbg 3 9.015966 3.005322 30-JAN-14
1 6ajkhukk78nsr 3 8.864179 2.954726 30-JAN-14
1 c0agatqzq2jzr 3 7.937203 2.645734 30-JAN-14
1 b3abwkm67yg8r 3 5.286708 1.762236 30-JAN-14
1 2nszajb0qbyvp 14 4.570901 .326493 30-JAN-14
1 cvn54b7yz0s8u 99 7.722906 .078009 30-JAN-14
1 3ktacv9r56b51 163 9.548086 .058577 30-JAN-14
1 ga9j9xk5cy9s0 99 5.745133 .058032 30-JAN-14
1 db78fxqxwxt7r 807 8.675157 .01075 30-JAN-14
1 3nkd3g3ju5ph1 910 4.892754 .005377 30-JAN-14
1 96g93hntrzjtr 3002 4.909722 .001635 30-JAN-14
20 rows selected.
SQL text for current statements
SQL_ID SQL_TEXT
------------- ------------------------------------------------------------------------------------------------------------------------------------
12a2xbmwn5v6z select owner, segment_name, blocks from dba_segments where tablespace_name = :tsname
cnq31548hb8un BEGIN :c := dbms_spm_internal.auto_purge_sql_plan_baseline; END;
2nszajb0qbyvp DECLARE job BINARY_INTEGER := :job; next_date DATE := :mydate; broken BOOLEAN := FALSE; BEGIN wwv_flow_mail.push_queue(wwv_flow_pla
tform.get_preference('SMTP_HOST_ADDRESS'),wwv_flow_platform.get_preference('SMTP_HOST_PORT')); :mydate := next_date; IF broken THEN
:b := 1; ELSE :b := 0; END IF; END;
f6cz4n8y72xdc SELECT space_usage_kbytes FROM v$sysaux_occupants WHERE occupant_name = 'SQL_MANAGEMENT_BASE'
db78fxqxwxt7r select /*+ rule */ bucket, endpoint, col#, epvalue from histgrm$ where obj#=:1 and intcol#=:2 and row#=:3 order by bucket
9ctt1scmwbmbg begin dbsnmp.bsln_internal.maintain_thresholds; end;
3ktacv9r56b51 select owner#,name,namespace,remoteowner,linkname,p_timestamp,p_obj#, nvl(property,0),subname,type#,d_attrs from dependency$ d, obj$
o where d_obj#=:1 and p_obj#=obj#(+) order by order#
6ajkhukk78nsr begin prvt_hdm.auto_execute( :dbid, :inst_num , :end_snap_id ); end;
96g93hntrzjtr select /*+ rule */ bucket_cnt, row_cnt, cache_cnt, null_cnt, timestamp#, sample_size, minimum, maximum, distcnt, lowval, hival, dens
ity, col#, spare1, spare2, avgcln from hist_head$ where obj#=:1 and intcol#=:2
3nkd3g3ju5ph1 select obj#,type#,ctime,mtime,stime, status, dataobj#, flags, oid$, spare1, spare2 from obj$ where owner#=:1 and name=:2 and namespa
ce=:3 and remoteowner is null and linkname is null and subname is null
cvn54b7yz0s8u select /*+ index(idl_ub1$ i_idl_ub11) +*/ piece#,length,piece from idl_ub1$ where obj#=:1 and part=:2 and version=:3 order by piece#
02577v815yp77 BEGIN :success := dbms_ha_alerts_prvt.post_instance_up; END;
ga9j9xk5cy9s0 select /*+ index(idl_sb4$ i_idl_sb41) +*/ piece#,length,piece from idl_sb4$ where obj#=:1 and part=:2 and version=:3 order by piece#
832kkz790r75k SELECT c.capture#, c.capture_name, c.flags FROM sys.streams$_capture_process c, dba_queues q, dba_queue_tables qt ,v$instance i WHE
RE c.queue_owner = q.owner and c.queue_name = q.name and qt.queue_table = q.queue_table and qt.owner = q.owner and
((qt.owner_instance = i.instance_number and (bitand(c.flags, 1572864) = 0 or bitand(c.flags, 8388608) > 0)) or (bitand(c.flags,
1572864) > 0 and bitand(c.flags, 8388608) = 0)) and bitand(c.flags, 512) != 512 and c.status = :1 ORDER BY c.capture#
b3abwkm67yg8r DECLARE job BINARY_INTEGER := :job; next_date TIMESTAMP WITH TIME ZONE := :mydate; broken BOOLEAN := FALSE; job_name VARCHAR2(30)
:= :job_name; job_subname VARCHAR2(30) := :job_subname; job_owner VARCHAR2(30) := :job_owner; job_start TIMESTAMP WITH TIME ZONE
:= :job_start; job_scheduled_start TIMESTAMP WITH TIME ZONE := :job_scheduled_start; window_start TIMESTAMP WITH TIME ZONE := :wi
ndow_start; window_end TIMESTAMP WITH TIME ZONE := :window_end; chain_id VARCHAR2(14) := :chainid; credential_owner varchar2(30)
:= :credown; credential_name varchar2(30) := :crednam; destination_owner varchar2(30) := :destown; destination_name varchar2(30
) := :destnam; job_dest_id varchar2(14) := :jdestid; log_id number := :log_id; BEGIN begin dbms_rlmgr_dr.execschdactions('RLM$SC
HDNEGACTION'); end; :mydate := next_date; IF broken THEN :b := 1; ELSE :b := 0; END IF; END;
8mz0wa11tacp0 select table_objno, primary_instance, secondary_instance, owner_instance from sys.aq$_queue_table_affinities a where a.owner_insta
nce :1 and dbms_aqadm_syscalls.get_owner_instance(a.primary_instance, a.secondary_instance, a.owner_instance) = :2 o
rder by table_objno
c2p32r5mzv8hb BEGIN prvt_advisor.delete_expired_tasks; END;
01uy9sb7w8a9g begin dbms_aqadm_sys.remove_all_nondurablesub(:1, :2); end;
c0agatqzq2jzr insert into "SYS"."ALERT_QT" (q_name, msgid, corrid, priority, state, delay, expiration, time_manager_info, local_order_no, chain
_no, enq_time, step_no, enq_uid, enq_tid, retry_count, exception_qschema, exception_queue, recipient_key, dequeue_msgid, user_da
ta, sender_name, sender_address, sender_protocol, user_prop, cscn, dscn) values (:1, :2, :3, :4, :5, :6, :7, :8, :9, :10, :11, :
12, :13, :14, 0, :15, :16, :17, :18, :19, :20, :21, :22, :23, :24, :25)
g0jvz8csyrtcf SELECT T.TASK_ID FROM SYS.DBA_ADVISOR_TASKS T, WRI$_ADV_PARAMETERS P WHERE T.TASK_ID = P.TASK_ID AND T.STATUS# :B2 AND T.READ_ONL
Y = 'FALSE' AND P.NAME = 'DAYS_TO_EXPIRE' AND PRVT_ADVISOR.CHECK_EXPIRATION_COMP(:B1 , T.LAST_MODIFIED, P.VALUE) = 1
20 rows selected.
SQL>
It’s likely that longer minimum execution times will produce a much longer report in an active production database; it’s also likely that full blocks of PL/SQL will be reported to aid you in your search for the misbehaving code. Once you get the code and the sql_id values it’s a simple task to return plan data for the sql_ids of interest:
SQL> @plan_query_hist 12a2xbmwn5v6z
I Operation Object Name # Rows BYTES COST PStart PStop
--- ---------------------------------------- ------------------------------ ---------- ---------- ---------- ------ ------
1 SELECT STATEMENT 1117
2 VIEW SYS_DBA_SEGS 474 85320 1117
3 UNION-ALL
4 NESTED LOOPS (OUTER) 1 121 1082
5 NESTED LOOPS 1 103 1081
6 HASH JOIN 33 2112 1015
7 NESTED LOO 1736 72912 20
8 NESTED L 6 96 2
9 TABLE (BY INDEX ROWID) TS$ 1 10 1
10 INDE (UNIQUE SCAN) I_TS1 1 0
11 INDEX (FULL SCAN) I_FILE2 6 36 1
12 TABLE AC (CLUSTER) SEG$ 289 7514 8
13 INDEX (RANGE SCAN) I_FILE#_BLOCK# 1 2
14 VIEW SYS_OBJECTS 5842 128524 995
15 UNION-AL
16 TABLE (FULL) TAB$ 1826 40172 296
17 TABLE (FULL) TABPART$ 110 1760 2
18 TABLE (FULL) CLU$ 10 140 296
19 TABLE (FULL) IND$ 3713 66834 296
20 TABLE (FULL) INDPART$ 127 2032 3
21 TABLE (FULL) LOB$ 22 440 296
22 TABLE (FULL) TABSUBPART$ 32 448 2
23 TABLE (FULL) INDSUBPART$ 1 52 2
24 TABLE (FULL) LOBFRAG$ 1 17 2
25 TABLE ACCESS (BY INDEX ROWID) OBJ$ 1 39 2
26 INDEX (RANGE SCAN) I_OBJ1 1 1
27 TABLE ACCESS (CLUSTER) USER$ 1 18 1
28 INDEX (UNIQUE SCAN) I_USER# 1 0
29 NESTED LOOPS (OUTER) 2 198 10
30 NESTED LOOPS 2 162 8
31 NESTED LOOPS 2 150 8
32 NESTED LOO 11 506 3
33 TABLE AC (BY INDEX ROWID) TS$ 1 10 1
34 INDEX (UNIQUE SCAN) I_TS1 1 0
35 TABLE AC (FULL) UNDO$ 11 396 2
36 TABLE ACCE (CLUSTER) SEG$ 1 29 1
37 INDEX (UNIQUE SCAN) I_FILE#_BLOCK# 1 0
38 INDEX (UNIQUE SCAN) I_FILE2 1 6 0
39 TABLE ACCESS (CLUSTER) USER$ 1 18 1
40 INDEX (UNIQUE SCAN) I_USER# 1 0
41 HASH JOIN (RIGHT OUTER) 472 33512 25
42 TABLE ACCESS (FULL) USER$ 63 1134 3
43 NESTED LOOPS 472 25016 21
44 NESTED LOOPS 6 114 3
45 TABLE ACCE (BY INDEX ROWID) TS$ 1 10 1
46 INDEX (UNIQUE SCAN) I_TS1 1 0
47 TABLE ACCE (FULL) FILE$ 6 54 2
48 TABLE ACCESS (CLUSTER) SEG$ 79 2686 8
49 INDEX (RANGE SCAN) I_FILE#_BLOCK# 1 2
49 rows selected.
Access Predicates .....
no rows selected
Filter predicates .....
no rows selected
SQL>
The statement for that plan runs for a little over 13 seconds per execution; it’s using data dictionary tables and views that can’t be modified or indexed any further so other means will need to be used to tune this statement. One option might be to gather data dictionary statistics to ensure they are current, however I have rarely found such a case to be true. Since these examples were run on a Windows system, in a fairly small database with a single disk the most likely culprit is the file configuration. This can also happen on enterprise systems, depending upon how LUNs are created and presented, so it would be a good idea to examine file placement to see if redo logs or control files are located on the same spindles as data and index files. Examining a current AWR report should shed some light on how I/O is behaving and which wait events are consuming the most resources.
Although not quite as straightforward as SQL statement tuning it is possible to find ‘offending’ PL/SQL code and work to improve its performance. The DBMS_PROFILER package, available since Oracle 10.2 was released, can be used to provide performance information for PL/SQL packages and procedures. To install the objects the dbms_profiler package requires the ?/rdbms/admin/proftab.sql script needs to be run. Once these objects are created [each user who wants to use the profiler needs to install these objects) it’s simply a matter of starting the profiler, running the problem code and then stopping the profiler run. Using the profdemo.sql script from Oracle you can see the following calls before and after the PL/SQL is executed:
SQL> Rem Start profiling.
SQL>
SQL> declare
2 status number;
3 begin
4 status := dbms_profiler.start_profiler('PROFILER DEMO');
5 end;
6 /
PL/SQL procedure successfully completed.
SQL>
SQL> execute profdemo_pack.profdemo_p1;
PL/SQL procedure successfully completed.
SQL>
SQL> Rem Stop profiling data.
SQL>
SQL> declare
2 status number;
3 begin
4 status := dbms_profiler.stop_profiler;
5 end;
6 /
PL/SQL procedure successfully completed.
SQL>
Reports were generated using the profsum.sql script, again from Oracle; the proffer.sql scripts needs to be run to create the packages and procedures called by profuse.sql:
GRAND_TOTA
----------
.00
RUNID RUN_COMMENT SECONDS
---------- ------------------------------ ----------
1 PROFILER DEMO .037
2 PROFILER DEMO .003
3 PROFILER DEMO .003
4 PROFILER DEMO .051
RUNID RUN_COMMENT UNIT_OWNER UNIT_NAME SECONDS PERCEN
---------- -------------------- -------------------------------- -------------------- --------- ------
1 PROFILER DEMO SYS PROFDEMO_PACK .00 1.4
2 PROFILER DEMO SYS PROFDEMO_PACK .00 9.6
2 PROFILER DEMO .00 1.5
2 PROFILER DEMO .00 1.2
3 PROFILER DEMO SYS PROFDEMO_PACK .00 10.7
3 PROFILER DEMO .00 2.1
3 PROFILER DEMO .00 1.4
3 PROFILER DEMO SYS DBMS_OUTPUT .00 1.1
8 rows selected.
UNIT_OWNER UNIT_NAME SECONDS PERCENTAG
-------------------------------- ------------------------- --------- ---------
SYS PROFDEMO_PACK .00 66.44
.00 23.00
SYS DBMS_OUTPUT .00 5.35
SYS DBMS_PROFILER .00 4.38
SYS PROFDEMO_TYPE .00 .83
to_char(p1.total_time/(p1.total_occur*p1.min_time),'99999.99')as "Ave/min",
*
ERROR at line 10:
ORA-01476: divisor is equal to zero
RUNID SECONDS OWNER UNIT_NAME LINE# TEXT
---------- -------- -------------------- -------------------- ---------- -------------------------------------------------------------
1 .0 SYS PROFDEMO_PACK 9 insert into profdemo_tab_1 values (d3);
4 .0 SYS PROFDEMO_PACK 9 insert into profdemo_tab_1 values (d3);
3 .0 SYS PROFDEMO_PACK 9 insert into profdemo_tab_1 values (d3);
2 .0 SYS PROFDEMO_PACK 9 insert into profdemo_tab_1 values (d3);
1 .0 SYS PROFDEMO_PACK 15 insert into profdemo_tab_1 values (d2.atr);
4 .0 SYS PROFDEMO_PACK 15 insert into profdemo_tab_1 values (d2.atr);
3 .0 SYS PROFDEMO_PACK 15 insert into profdemo_tab_1 values (d2.atr);
2 .0 SYS PROFDEMO_PACK 15 insert into profdemo_tab_1 values (d2.atr);
8 rows selected.
SECONDS UNIT_OWNER UNIT_NAME LINE# TEXT
-------- -------------------- -------------------- ---------- -------------------------------------------------------------------------
.0 SYS PROFDEMO_PACK 9 insert into profdemo_tab_1 values (d3);
.0 SYS PROFDEMO_PACK 15 insert into profdemo_tab_1 values (d2.atr);
.0 SYS PROFDEMO_PACK 8 d3 := d1.profdemo_type_regular_method()+i;
.0 SYS PROFDEMO_PACK 18 raise value_error;
.0 SYS PROFDEMO_PACK 2 procedure profdemo_p1 is
PL/SQL procedure successfully completed.
UNIT_OWNER UNIT_NAME LINES_EXECUTED
-------------------------------- -------------------------------- --------------
SYS PROFDEMO_PACK 11
SYS PROFDEMO_TYPE 4
SYS DBMS_OUTPUT 17
SYS DBMS_PROFILER 7
UNIT_OWNER UNIT_NAME LINES_PRESENT
-------------------------------- -------------------------------- -------------
SYS PROFDEMO_PACK 13
SYS PROFDEMO_TYPE 9
SYS DBMS_OUTPUT 106
SYS DBMS_PROFILER 112
LINES_EXECUTED
--------------
39
LINES_PRESENT
-------------
240
=================================trace info=================================
===========================Results for run #1 made on 30-JAN-14 11:25:14 =========================
(PROFILER DEMO) Run total time: .04 seconds
Unit #1: SYS.DBMS_PROFILER - Total time: .00 seconds
Unit #2: . - Total time: .00 seconds
Unit #3: . - Total time: .00 seconds
Unit #4: SYS.DBMS_OUTPUT - Total time: .00 seconds
Unit #5: . - Total time: .00 seconds
Unit #6: SYS.PROFDEMO_PACK - Total time: .00 seconds
1 package body profdemo_pack is
2 0 .00000795 procedure profdemo_p1 is
3 1 .00000198 .00000198 d1 profdemo_type := profdemo_type(earliest_date);
4 1 .00000497 .00000497 d2 profdemo_type := profdemo_type(earliest_date+1);
5 d3 date;
6 begin
7 6 .00000099 .00000016 for i in 1..5 loop
8 5 .00001789 .00000357 d3 := d1.profdemo_type_regular_method()+i;
9 5 .00041947 .00008389 insert into profdemo_tab_1 values (d3);
10 end loop;
11
12 1 .00000099 .00000099 if d1 > d2 then
13 0 0 insert into profdemo_tab_1 values (d1.atr);
14 else
15 1 .00004274 .00004274 insert into profdemo_tab_1 values (d2.atr);
16 end if;
17
18 1 .00001093 .00001093 raise value_error;
19
20 1 0 0 exception when value_error then
21 1 .00000099 .00000099 NULL;
22 1 .00000099 .00000099 end;
23 end profdemo_pack
Unit #7: SYS.PROFDEMO_TYPE - Total time: .00 seconds
1 type body profdemo_type is
2 0 0 static function profdemo_type_static_method return date is
3 begin
4 0 0 return (sysdate);
5 0 0 end;
6
7 0 .00000198 member function profdemo_type_regular_method return date is
8 begin
9 5 .00000099 .00000019 return (atr);
10 5 .00000099 .00000019 end;
11
12 0 0 map member function profdemo_type_map_method return date is
13 begin
14 2 .00000099 .00000049 return (atr);
15 2 0 0 end;
16 end
Unit #8: . - Total time: .00 seconds
Unit #9: . - Total time: .00 seconds
===========================Results for run #2 made on 30-JAN-14 11:27:07 =========================
(PROFILER DEMO) Run total time: .00 seconds
Unit #1: SYS.DBMS_PROFILER - Total time: .00 seconds
Unit #2: . - Total time: .00 seconds
Unit #3: . - Total time: .00 seconds
Unit #4: SYS.DBMS_OUTPUT - Total time: .00 seconds
Unit #5: . - Total time: .00 seconds
Unit #6: SYS.PROFDEMO_PACK - Total time: .00 seconds
1 package body profdemo_pack is
2 0 .00000537 procedure profdemo_p1 is
3 1 .00000179 .00000179 d1 profdemo_type := profdemo_type(earliest_date);
4 1 .00000447 .00000447 d2 profdemo_type := profdemo_type(earliest_date+1);
5 d3 date;
6 begin
7 6 0 0 for i in 1..5 loop
8 5 .00001432 .00000286 d3 := d1.profdemo_type_regular_method()+i;
9 5 .00021223 .00004244 insert into profdemo_tab_1 values (d3);
10 end loop;
11
12 1 .00000268 .00000268 if d1 > d2 then
13 0 0 insert into profdemo_tab_1 values (d1.atr);
14 else
15 1 .00003671 .00003671 insert into profdemo_tab_1 values (d2.atr);
16 end if;
17
18 1 .00000985 .00000985 raise value_error;
19
20 1 0 0 exception when value_error then
21 1 .00000089 .00000089 NULL;
22 1 .00000089 .00000089 end;
23 end profdemo_pack
Unit #7: SYS.PROFDEMO_TYPE - Total time: .00 seconds
1 type body profdemo_type is
2 0 0 static function profdemo_type_static_method return date is
3 begin
4 0 0 return (sysdate);
5 0 0 end;
6
7 0 .00000089 member function profdemo_type_regular_method return date is
8 begin
9 5 .00000179 .00000035 return (atr);
10 5 .00000179 .00000035 end;
11
12 0 0 map member function profdemo_type_map_method return date is
13 begin
14 2 .00000179 .00000089 return (atr);
15 2 0 0 end;
16 end
Unit #8: . - Total time: .00 seconds
Unit #9: . - Total time: .00 seconds
===========================Results for run #3 made on 30-JAN-14 11:29:21 =========================
(PROFILER DEMO) Run total time: .00 seconds
Unit #1: SYS.DBMS_PROFILER - Total time: .00 seconds
Unit #2: . - Total time: .00 seconds
Unit #3: . - Total time: .00 seconds
Unit #4: SYS.DBMS_OUTPUT - Total time: .00 seconds
Unit #5: . - Total time: .00 seconds
Unit #6: SYS.PROFDEMO_PACK - Total time: .00 seconds
1 package body profdemo_pack is
2 0 .00000625 procedure profdemo_p1 is
3 1 .00000267 .00000267 d1 profdemo_type := profdemo_type(earliest_date);
4 1 .00000535 .00000535 d2 profdemo_type := profdemo_type(earliest_date+1);
5 d3 date;
6 begin
7 6 .00000267 .00000044 for i in 1..5 loop
8 5 .00001339 .00000267 d3 := d1.profdemo_type_regular_method()+i;
9 5 .00023757 .00004751 insert into profdemo_tab_1 values (d3);
10 end loop;
11
12 1 .00000357 .00000357 if d1 > d2 then
13 0 0 insert into profdemo_tab_1 values (d1.atr);
14 else
15 1 .00003840 .00003840 insert into profdemo_tab_1 values (d2.atr);
16 end if;
17
18 1 .00000982 .00000982 raise value_error;
19
20 1 0 0 exception when value_error then
21 1 0 0 NULL;
22 1 .00000089 .00000089 end;
23 end profdemo_pack
Unit #7: SYS.PROFDEMO_TYPE - Total time: .00 seconds
1 type body profdemo_type is
2 0 0 static function profdemo_type_static_method return date is
3 begin
4 0 0 return (sysdate);
5 0 0 end;
6
7 0 .00000178 member function profdemo_type_regular_method return date is
8 begin
9 5 .00000089 .00000017 return (atr);
10 5 .00000178 .00000035 end;
11
12 0 0 map member function profdemo_type_map_method return date is
13 begin
14 2 .00000089 .00000044 return (atr);
15 2 0 0 end;
16 end
Unit #8: . - Total time: .00 seconds
Unit #9: . - Total time: .00 seconds
===========================Results for run #4 made on 30-JAN-14 11:30:41 =========================
(PROFILER DEMO) Run total time: .05 seconds
Unit #1: SYS.DBMS_PROFILER - Total time: .00 seconds
Unit #2: . - Total time: .00 seconds
Unit #3: . - Total time: .00 seconds
Unit #4: SYS.DBMS_OUTPUT - Total time: .00 seconds
Unit #5: . - Total time: .00 seconds
Unit #6: SYS.PROFDEMO_PACK - Total time: .00 seconds
1 package body profdemo_pack is
2 0 .00000393 procedure profdemo_p1 is
3 1 .00000295 .00000295 d1 profdemo_type := profdemo_type(earliest_date);
4 1 .00000295 .00000295 d2 profdemo_type := profdemo_type(earliest_date+1);
5 d3 date;
6 begin
7 6 .00000098 .00000016 for i in 1..5 loop
8 5 .00001968 .00000393 d3 := d1.profdemo_type_regular_method()+i;
9 5 .00027756 .00005551 insert into profdemo_tab_1 values (d3);
10 end loop;
11
12 1 .00000098 .00000098 if d1 > d2 then
13 0 0 insert into profdemo_tab_1 values (d1.atr);
14 else
15 1 .00004232 .00004232 insert into profdemo_tab_1 values (d2.atr);
16 end if;
17
18 1 .00001082 .00001082 raise value_error;
19
20 1 0 0 exception when value_error then
21 1 .00000098 .00000098 NULL;
22 1 .00000098 .00000098 end;
23 end profdemo_pack
Unit #7: SYS.PROFDEMO_TYPE - Total time: .00 seconds
1 type body profdemo_type is
2 0 0 static function profdemo_type_static_method return date is
3 begin
4 0 0 return (sysdate);
5 0 0 end;
6
7 0 0 member function profdemo_type_regular_method return date is
8 begin
9 5 .00000098 .00000019 return (atr);
10 5 0 0 end;
11
12 0 0 map member function profdemo_type_map_method return date is
13 begin
14 2 .00000098 .00000049 return (atr);
15 2 0 0 end;
16 end
Unit #8: . - Total time: .00 seconds
Unit #9: . - Total time: .00 seconds
============================================================================
PL/SQL procedure successfully completed.
================== Profiler report - all runs rolled up ===================
Unit .:
Unit SYS.DBMS_OUTPUT:
Unit SYS.DBMS_PROFILER:
Unit SYS.PROFDEMO_PACK:
1 package body profdemo_pack is
2 0 .00002351 procedure profdemo_p1 is
3 4 .00000941 .00000235 d1 profdemo_type := profdemo_type(earliest_date);
4 4 .00001775 .00000443 d2 profdemo_type := profdemo_type(earliest_date+1);
5 d3 date;
6 begin
7 24 .00000465 .00000019 for i in 1..5 loop
8 20 .00006530 .00000326 d3 := d1.profdemo_type_regular_method()+i;
9 20 .00114684 .00005734 insert into profdemo_tab_1 values (d3);
10 end loop;
11
12 4 .00000823 .00000205 if d1 > d2 then
13 0 0 insert into profdemo_tab_1 values (d1.atr);
14 else
15 4 .00016018 .00004004 insert into profdemo_tab_1 values (d2.atr);
16 end if;
17
18 4 .00004143 .00001035 raise value_error;
19
20 4 0 0 exception when value_error then
21 4 .00000287 .00000071 NULL;
22 4 .00000376 .00000094 end;
23 end profdemo_pack
Unit SYS.PROFDEMO_TYPE:
1 type body profdemo_type is
2 0 0 static function profdemo_type_static_method return date is
3 begin
4 0 0 return (sysdate);
5 0 0 end;
6
7 0 .00000466 member function profdemo_type_regular_method return date is
8 begin
9 20 .00000466 .00000023 return (atr);
10 20 .00000457 .00000022 end;
11
12 0 0 map member function profdemo_type_map_method return date is
13 begin
14 8 .00000466 .00000058 return (atr);
15 8 0 0 end;
16 end
============================================================================
PL/SQL procedure successfully completed.
A wealth of performance data is provided from the profiler; tuning the PL/SQL should then be a simple matter of working through the long-running sections and addressing any issues causing the slow performance. And all this was made available by running the set of queries provided at the start of this post so problem statements could be found.
When things start running slower, and it’s PL/SQL performance that’s impeding progress, it’s good to know how to find the problem statements so you can run the profiler (on 10.2 and later releases) to find the root causes and address them. It may take some time to correct the issues you find but it’s definitely worth the effort.
Hurry up, I haven’t got all day.