Oracle Tips and Tricks — David Fitzjarrell

January 30, 2014

You Take Too Long

Filed under: General — dfitzjarrell @ 12:09

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 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 dbms_profiler package and dependent objects the ?/rdbms/admin/proftab.sql script needs to be run. Once these objects are created 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 profrep.sql script, again from Oracle:


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.

About these ads

Leave a Comment »

No comments yet.

RSS feed for comments on this post. TrackBack URI

Leave a Reply

Fill in your details below or click an icon to log in:

WordPress.com Logo

You are commenting using your WordPress.com account. Log Out / Change )

Twitter picture

You are commenting using your Twitter account. Log Out / Change )

Facebook photo

You are commenting using your Facebook account. Log Out / Change )

Google+ photo

You are commenting using your Google+ account. Log Out / Change )

Connecting to %s

The Rubric Theme. Create a free website or blog at WordPress.com.

Follow

Get every new post delivered to your Inbox.

Join 629 other followers

%d bloggers like this: