Extended SQL Trace – the Case of the Missing 40,000 Seconds

4 02 2010

February 4, 2010

An interesting question recently appeared on Oracle’s OTN forums:
http://forums.oracle.com/forums/thread.jspa?threadID=1021152

The original poster stated that he noticed a slow running job and initiated a 10046 trace using ORADEBUG.  The job ran for roughly 60,000 seconds, but the 10046 trace was disabled after about 45,000 seconds.  Below is the partial output of TKPROF for his trace file that was provided in the thread:

********************************************************************************
OVERALL TOTALS FOR ALL NON-RECURSIVE STATEMENTS

call     count       cpu    elapsed       disk      query    current        rows
------- ------   -------- ---------- ---------- ---------- ----------  ----------
Parse        34      0.07       0.05          0          0          0           0
Execute  949806    924.33    1010.25          0          0          0          34
Fetch    964106    264.38    2540.21     301146   18226522          0     5094481
------- -------  -------- ---------- ---------- ---------- ----------  ----------
total   1913946   1188.78    3550.51     301146   18226522          0     5094515

Misses in library cache during parse: 5
Misses in library cache during execute: 5

Elapsed times include waiting on following events:
  Event waited on                             Times   Max. Wait  Total Waited
  ----------------------------------------   Waited  ----------  ------------
  db file sequential read                    301151        0.49       1598.40
  SQL*Net message to client                  964141        0.01          1.54
  SQL*Net message from client                964140      973.95       1720.04
  read by other session                      201948        0.98        705.53
  latch: cache buffers chains                 11496        0.01          1.40
  latch free                                     38        0.00          0.02
  cursor: pin S                                  27        0.01          0.19
  SQL*Net more data from client                  87        0.00          0.00
  wait list latch free                            1        0.01          0.01
  latch: object queue header operation            8        0.00          0.00

OVERALL TOTALS FOR ALL RECURSIVE STATEMENTS

call     count       cpu    elapsed       disk      query    current        rows
------- ------  -------- ---------- ---------- ---------- ----------  ----------
Parse        7      0.00       0.00          0          0          0           0
Execute      7      0.00       0.00          0         21          0           0
Fetch        0      0.00       0.00          0          0          0           0
------- ------  -------- ---------- ---------- ---------- ----------  ----------
total       14      0.00       0.00          0         21          0           0

Misses in library cache during parse: 0

   45  user  SQL statements in session.
    7  internal SQL statements in session.
   52  SQL statements in session.
********************************************************************************
Trace file: s1p_ora_9761.trc
Trace file compatibility: 10.01.00
Sort options: exeela  fchela  prsela
        1  session in tracefile.
       45  user  SQL statements in trace file.
        7  internal SQL statements in trace file.
       52  SQL statements in trace file.
       46  unique SQL statements in trace file.
 71815238  lines in trace file.
    45080  elapsed seconds in trace file.

Let’s see if we are able to make some sense of what was posted.  3,550.51 elapsed seconds based on the PARSE, EXEC, and FETCH lines in the trace file for SQL submitted by the user’s session; 0.00 elapsed seconds based on the PARSE, EXEC, and FETCH lines in the trace file for recursive SQL (trigger, PL/SQL functions, SQL optimization, and space management calls); 4,027.13 seconds in wait events; 1,188.78 seconds of CPU time; 45,080 elapsed seconds in the trace file (last tim= value found in the trace file minus the first tim= value found in the trace file); OP claims that the trace was enabled for about 45,000 seconds and that the entire job required 60,000 seconds.  So, what could cause the odd timing difference?

The OP was asked to post at least the last 30 lines found in the trace file, and this is what was provided:

WAIT #69: nam='db file sequential read' ela= 10255 file#=253 block#=514924 blocks=1 obj#=211550 tim=52370728986939
WAIT #69: nam='db file sequential read' ela= 23269 file#=260 block#=1202218 blocks=1 obj#=211554 tim=52370729010404
WAIT #69: nam='db file sequential read' ela= 14643 file#=260 block#=1202511 blocks=1 obj#=211554 tim=52370729025179
WAIT #69: nam='db file sequential read' ela= 4114 file#=265 block#=1033501 blocks=1 obj#=211554 tim=52370729029406
WAIT #69: nam='db file sequential read' ela= 13199 file#=253 block#=516876 blocks=1 obj#=211550 tim=52370729042681
WAIT #69: nam='db file sequential read' ela= 15608 file#=253 block#=517214 blocks=1 obj#=211550 tim=52370729058435
WAIT #69: nam='db file sequential read' ela= 11327 file#=253 block#=517552 blocks=1 obj#=211550 tim=52370729069910
WAIT #69: nam='db file sequential read' ela= 3025 file#=265 block#=1033566 blocks=1 obj#=211554 tim=52370729073032
WAIT #69: nam='db file sequential read' ela= 9539 file#=255 block#=981553 blocks=1 obj#=211550 tim=52370729082732
WAIT #69: nam='db file sequential read' ela= 13474 file#=257 block#=1259903 blocks=1 obj#=211550 tim=52370729096346
WAIT #69: nam='db file sequential read' ela= 15618 file#=265 block#=1033723 blocks=1 obj#=211554 tim=52370729112106
WAIT #69: nam='db file sequential read' ela= 7040 file#=265 block#=1033868 blocks=1 obj#=211554 tim=52370729119454
WAIT #69: nam='db file sequential read' ela= 7995 file#=257 block#=1261555 blocks=1 obj#=211550 tim=52370729127527
WAIT #69: nam='db file sequential read' ela= 9090 file#=257 block#=1261616 blocks=1 obj#=211550 tim=52370729136775
WAIT #69: nam='db file sequential read' ela= 6459 file#=257 block#=1260091 blocks=1 obj#=211550 tim=52370729143360
WAIT #69: nam='db file sequential read' ela= 14971 file#=265 block#=1033992 blocks=1 obj#=211554 tim=52370729158426
WAIT #69: nam='db file sequential read' ela= 8528 file#=257 block#=1260350 blocks=1 obj#=211550 tim=52370729167077
WAIT #69: nam='db file sequential read' ela= 17749 file#=257 block#=1262569 blocks=1 obj#=211550 tim=52370729185407
WAIT #69: nam='db file sequential read' ela= 14060 file#=257 block#=1262585 blocks=1 obj#=211550 tim=52370729199789
WAIT #69: nam='db file sequential read' ela= 5944 file#=265 block#=1034201 blocks=1 obj#=211554 tim=52370729205855
WAIT #69: nam='db file sequential read' ela= 7822 file#=265 block#=1034081 blocks=1 obj#=211554 tim=52370729213801
WAIT #69: nam='db file sequential read' ela= 9290 file#=257 block#=1260904 blocks=1 obj#=211550 tim=52370729223162
WAIT #69: nam='db file sequential read' ela= 8096 file#=257 block#=1263630 blocks=1 obj#=211550 tim=52370729231435
WAIT #69: nam='db file sequential read' ela= 17243 file#=266 block#=1164414 blocks=1 obj#=211554 tim=52370729248781
WAIT #69: nam='db file sequential read' ela= 13505 file#=257 block#=1265138 blocks=1 obj#=211550 tim=52370729262412
WAIT #69: nam='db file sequential read' ela= 8196 file#=257 block#=1263679 blocks=1 obj#=211550 tim=52370729270695
WAIT #69: nam='db file sequential read' ela= 10854 file#=266 block#=1164488 blocks=1 obj#=211554 tim=52370729281699
WAIT #69: nam='db file sequential read' ela= 6916 file#=257 block#=1266913 blocks=1 obj#=211550 tim=52370729288757
WAIT #69: nam='db file sequential read' ela= 7534 file#=266 block#=1164629 blocks=1 obj#=211554 tim=52370729296373
WAIT #69: nam='db file sequential read' ela= 11014 file#=262 block#=1215470 blocks=1 obj#=211550 tim=52370729307690
WAIT #69: nam='db file sequential read' ela= 5464 file#=266 block#=1164797 blocks=1 obj#=211554 tim=52370729313292
WAIT #69: nam='db file sequential read' ela= 7087 file#=266 block#=1164693 blocks=1 obj#=211554 tim=52370729320517
WAIT #69: nam='db file sequential read' ela= 9120 file#=266 block#=1164681 blocks=1 obj#=211554 tim=52370729329728
WAIT #69: nam='db file sequential read' ela= 9765 file#=263 block#=897664 blocks=1 obj#=211550 tim=52370729339566
WAIT #69: nam='db file sequential read' ela= 9884 file#=266 block#=1164905 blocks=1 obj#=211554 tim=52370729349619
WAIT #69: nam='db file sequential read' ela= 6704 file#=263 block#=896829 blocks=1 obj#=211550 tim=52370729356392
WAIT #69: nam='db file sequential read' ela= 11685 file#=263 block#=898947 blocks=1 obj#=211550 tim=52370729368192
WAIT #69: nam='db file sequential read' ela= 4374 file#=257 block#=1265707 blocks=1 obj#=211550 tim=52370729372745
WAIT #69: nam='db file sequential read' ela= 10176 file#=266 block#=1164943 blocks=1 obj#=211554 tim=52370729383118
WAIT #69: nam='db file sequential read' ela= 5685 file#=263 block#=898167 blocks=1 obj#=211550 tim=52370729388872
WAIT #69: nam='db file sequential read' ela= 12407 file#=263 block#=898515 blocks=1 obj#=211550 tim=52370729401365
WAIT #69: nam='db file sequential read' ela= 8000 file#=266 block#=1165054 blocks=1 obj#=211554 tim=52370729409495
WAIT #69: nam='db file sequential read' ela= 10842 file#=263 block#=898387 blocks=1 obj#=211550 tim=52370729420558
WAIT #69: nam='db file sequential read' ela= 9459 file#=266 block#=1164884 blocks=1 obj#=211554 tim=52370729430097
WAIT #69: nam='db file sequential read' ela= 9176 file#=263 block#=899680 blocks=1 obj#=211550 tim=52370729439344
WAIT #69: nam='db file sequential read' ela= 9433 file#=266 block#=1165227 blocks=1 obj#=211554 tim=52370729448885
WAIT #69: nam='db file sequential read' ela= 9860 file#=264 block#=1166755 blocks=1 obj#=211550 tim=52370729458836
WAIT #69: nam='db file sequential read' ela= 15433 file#=263 block#=899734 blocks=1 obj#=211550 tim=52370729474390
WAIT #69: nam='db file sequential read' ela= 2525 file#=264 block#=1168289 blocks=1 obj#=211550 tim=52370729477056
WAIT #69: nam='db file sequential read' ela= 14267 file#=264 block#=1166072 blocks=1 obj#=211550 tim=52370729491427
WAIT #69: nam='db file sequential read' ela= 4862 file#=266 block#=1165189 blocks=1 obj#=211554 tim=52370729496443
WAIT #69: nam='db file sequential read' ela= 6263 file#=264 block#=1165451 blocks=1 obj#=211550 tim=52370729502825
WAIT #69: nam='db file sequential read' ela= 7960 file#=266 block#=1165114 blocks=1 obj#=211554 tim=52370729510959
WAIT #69: nam='db file sequential read' ela= 11191 file#=263 block#=899590 blocks=1 obj#=211550 tim=52370729522220
WAIT #69: nam='db file sequential read' ela= 16590 file#=264 block#=1166723 blocks=1 obj#=211550 tim=52370729539121
WAIT #69: nam='db file sequential read' ela= 17177 file#=264 block#=1169520 blocks=1 obj#=211550 tim=52370729556924
WAIT #69: nam='db file sequential read' ela= 10969 file#=265 block#=1042853 blocks=1 obj#=211550 tim=52370729568068
WAIT #69: nam='db file sequential read' ela= 9767 file#=264 block#=1169529 blocks=1 obj#=211550 tim=52370729578053
WAIT #69: nam='db file sequential read' ela= 8938 file#=267 block#=874778 blocks=1 obj#=211554 tim=52370729587146
WAIT #69: nam='db file sequential read' ela= 14940 file#=7 block#=192178 blocks=1 obj#=211550 tim=52370729602405
WAIT #69: nam='db file sequential read' ela= 11551 file#=7 block#=194476 blocks=1 obj#=211550 tim=52370729614295
FETCH #69:c=50000,e=2063972,p=176,cr=1956,cu=0,mis=0,r=489,dep=0,og=1,tim=52370729615480
*** 2010-01-29 03:51:49.192
Received ORADEBUG command 'tracefile_name' from process Unix process pid: 9597, image:
*** 2010-01-29 03:53:38.062
Received ORADEBUG command 'event 10046 trace name context off' from process Unix process pid: 9597, image:
Dump file /oracle/S1P/saptrace/usertrace/s1p_ora_9761.trc
Oracle Database 10g Enterprise Edition Release 10.2.0.4.0 - 64bit Production
With the Partitioning, Data Mining and Real Application Testing options
ORACLE_HOME = /oracle/S1P/102_64
System name:    HP-UX
Node name:      nlscuxp0
Release:        B.11.23
Version:        U
Machine:        ia64
Instance name:  S1P
Redo thread mounted by this instance: 1
Oracle process number: 0
Unix process pid: 9761, image: oracle@nlscuxp0

From the above portion of the trace file, we see that the OP used ORADEBUG at 2010-01-29 03:51:49.192 to determine the trace file name for the session, and roughly 1 minute and 49 seconds later the OP used ORADEBUG to disable tracing.  The last fetch call in the trace file completed in roughly 2.06 seconds, required 0.05 seconds of CPU time and 174 physical block reads (possibly read one block at a time), and returned 489 rows to the client.  So, what happened to the missing 40,000 seconds?

  • Problem with a long CPU run queue causing a lot of missing time?
  • Problem with scheduling priority for the operating system processes?
  • Problem with a long running SQL statement that had been running for roughly 40,000 seconds and only performed logical I/O?
  • Problem where the batch process called DBMS_SLEEP?
  • Problem where the server made excessive use of the swap file, causing lost time on many “memory” accesses.
  • Problem with the network when transferring 489 rows (or some other large number) back to the client?
  • Extensive client side processing that lasted 40,000 seconds, but it would seem that Oracle would periodically write the current date and time to the trace file.

It is possibly interesting that a SQL*Net wait event of some sort did not appear after the fetch call (nothing written in the nearly 2 minute time period at the end of the trace file).  It is also possibly interesting that the TKPROF output indicated that the trace file included 45,080 seconds, which probably means that the lost 40,000 seconds did not happen in the last 50 or so lines of the trace file (this can be confirmed by checking the delta values of the tim= entries) – yet the elapsed CPU seconds plus wait events, including client side events, did not add up to the 45,000+ seconds.  Some strange/inconsistent output in the trace file should be expected if tracing is enabled or disabled in the middle of a SQL statement’s execution.

So, what happened to the missing 40,000 seconds?  Another case of a time warp?





Open Cursor Leaks – Identifying the Problem

3 02 2010

February 3, 2010

Assume that one of the users receives an error message like this one from an application (caution: some errors may be bigger than they appear).

Just what does this error message mean?  It could mean that Oracle’s OPEN_CURSORS initialization parameter, which specifies the maximum number of cursors that may be open simultaneously by a single session, is set too low.  The error could also mean that a limit of the program, the database connection method, or the application development environment was hit.  Or, the error could potentially be a false alarm – maybe there was a completely different error (maybe out of memory) and this message just happened to be selected for presentation to the user.

First, let’s try a quick experiment:

(Session 1, Just After Connecting to the Database):

SELECT SID FROM V$MYSTAT WHERE ROWNUM<=1;

  SID
-----
  168

(Session 2):

SELECT
  SQL_ID,
  SUBSTR(SQL_TEXT,1,50) SQL_TEXT,
  COUNT(*) CNT
FROM
  V$OPEN_CURSOR
WHERE
  SID=168
GROUP BY
  SQL_ID,
  SUBSTR(SQL_TEXT,1,50)
ORDER BY
  SQL_ID;

SQL_ID        SQL_TEXT                                            CNT
------------- -------------------------------------------------- ----
1uzhrfn574t12 SELECT ATTRIBUTE,SCOPE,NUMERIC_VALUE,CHAR_VALUE,DA    1
2q93zsrvbdw48 select grantee#,privilege#,nvl(col#,0),max(mod(nvl    2
425wwycyjax6t DECLARE   SHOULD_EXECUTE INTEGER; BEGIN   SELECT D    1
53saa2zkr6wc3 select intcol#,nvl(pos#,0),col#,nvl(spare1,0) from    1
6769wyy3yf66f select pos#,intcol#,col#,spare1,bo#,spare2 from ic    1
6aq34nj2zb2n7 select col#, grantee#, privilege#,max(mod(nvl(opti    2
7ng34ruy5awxq select i.obj#,i.ts#,i.file#,i.block#,i.intcols,i.t    2
83taa7kaw59c1 select name,intcol#,segcol#,type#,length,nvl(preci    2
96g93hntrzjtr select /*+ rule */ bucket_cnt, row_cnt, cache_cnt,    1
a73wbv1yu8x5c select con#,type#,condlength,intcols,robj#,rcon#,m    2
bsa0wjtftg3uw select file# from file$ where ts#=:1                  1
c4pc3jhzjcmc7 SELECT CHAR_VALUE FROM SYSTEM.PRODUCT_PRIVS WHERE     1
d6vwqbw6r2ffk SELECT USER FROM DUAL                                 1
dyk4dprp70d74 SELECT DECODE('A','A','1','2') FROM DUAL              1
f8pavn1bvsj7t select con#,obj#,rcon#,enabled,nvl(defer,0) from c    2
g4y6nw3tts7cc BEGIN DBMS_APPLICATION_INFO.SET_MODULE(:1,NULL); E    1

16 rows selected.

(Session 1):

SELECT COUNT(*) FROM ALL_OBJECTS;

(Session 2 – Re-execute the same SQL statement):

...
16 rows selected.

No change in the number of open cursors.

(Session 1):

SELECT COUNT(*) FROM ALL_OBJECTS;

SELECT COUNT(*) FROM ALL_OBJECTS;

(Session 2 – Re-execute the same SQL statement):

SQL_ID        SQL_TEXT                                            CNT
------------- -------------------------------------------------- ----
1uzhrfn574t12 SELECT ATTRIBUTE,SCOPE,NUMERIC_VALUE,CHAR_VALUE,DA    1
2q93zsrvbdw48 select grantee#,privilege#,nvl(col#,0),max(mod(nvl    2
425wwycyjax6t DECLARE   SHOULD_EXECUTE INTEGER; BEGIN   SELECT D    1
53saa2zkr6wc3 select intcol#,nvl(pos#,0),col#,nvl(spare1,0) from    1
6769wyy3yf66f select pos#,intcol#,col#,spare1,bo#,spare2 from ic    1
6aq34nj2zb2n7 select col#, grantee#, privilege#,max(mod(nvl(opti    2
7ng34ruy5awxq select i.obj#,i.ts#,i.file#,i.block#,i.intcols,i.t    2
83taa7kaw59c1 select name,intcol#,segcol#,type#,length,nvl(preci    2
96g93hntrzjtr select /*+ rule */ bucket_cnt, row_cnt, cache_cnt,    1
a73wbv1yu8x5c select con#,type#,condlength,intcols,robj#,rcon#,m    2
bsa0wjtftg3uw select file# from file$ where ts#=:1                  1
c4pc3jhzjcmc7 SELECT CHAR_VALUE FROM SYSTEM.PRODUCT_PRIVS WHERE     1
d6vwqbw6r2ffk SELECT USER FROM DUAL                                 1
dr2v8xdg4w2ag SELECT COUNT(*) FROM ALL_OBJECTS                      1
dyk4dprp70d74 SELECT DECODE('A','A','1','2') FROM DUAL              1
f8pavn1bvsj7t select con#,obj#,rcon#,enabled,nvl(defer,0) from c    2
g4y6nw3tts7cc BEGIN DBMS_APPLICATION_INFO.SET_MODULE(:1,NULL); E    1

17 rows selected.

In the above, notice that the open cursor count increased and that the “SELECT COUNT(*) FROM ALL_OBJECTS” SQL statement with SQL_ID dr2v8xdg4w2ag is now listed in the V$OPEN_CURSOR output, indicating that it is now held open in the session cursor cache.  So, the SQL statements in the session cursor cache could be affecting the actual number of cursors that may remain open, as specified by the OPEN_CURSORS initialization parameter, so this could be a problem (I have not investigated to see what happens when the OPEN_CURSORS value is reached – whether or not Oracle will throw an error, or simply close one of the cached cursors).

Back to the error message, let’s spend a couple of minutes investigating this particular problem.  We execute a SQL statement that outputs the following (note that the HASH_VALUE is output, not the SQL_ID):

SID USER_NAME  PROGRAM     HASH_VALUE  SQL_TEXT                                                         CNT
--- ---------- ----------  ----------  ------------------------------------------------------------ -------
208 USER1      CUSINQ.EXE  1511368051  SELECT BITS FROM CUST_LINE_BINARY  where TYPE = :1       and      74
235 USER2      PLNWIN.EXE   881677082  select TRANSACTION_ID,    IT.TYPE, IT.CLASS, WORKORDER_TYPE,      15
237 USER3      PURENT.EXE   233497298  select ID from VENDOR where ACTIVE_FLAG = 'N'                     11
115 USER4      APIENT.EXE   233497298  select ID from VENDOR where ACTIVE_FLAG = 'N'                    228

Does the above show a problem?  Maybe, maybe not – it depends on what the SQL statement’s output is actually showing to us.  The above output is from a query of V$SESSION and V$OPEN_CURSOR.  SID 115 (USER4) had 228 open cursors for the SQL statement “select ID from VENDOR where ACTIVE_FLAG = ‘N’“, and SID 237 (USER3) had 11 cursors open for the same SQL statement - is this a problem?  Maybe, maybe not.  At the point that this output was captured, the APIENT.EXE program was active for only a short period of time, but just a couple of minutes after the above was captured, the application crashed with the error message shown in the picture at the top of this article.  Was it a problem with too small of a value for the OPEN_CURSORS parameter?

SQL> SHOW PARAMETER OPEN_CURSORS

NAME            TYPE        VALUE
--------------- ----------- -----
open_cursors    integer     1000

From the above, probably not.  Some development environments limit the number of simulatneously open cursors in an application (or worse yet limit the sum of all cursors opened in all applications developed with that development environment that are concurrently running on a computer) to a number that is substantially lower than the 1,000 cursors permitted by the OPEN_CURSORS parameter.  This particular program was apparently developed using a version of the Centura/Gupta/Unify SQLWindows development environment that limits each application to no more than 300 open cursors.  In reality, 300 is a high limit – so hitting that limit should be uncommon, yet the application has 228 cursors open for this one SQL statement.  It appears that this application has a cursor leak, where a cursor is opened, but never closed (until the application is closed or the program crashes).  So, a quick examination of a 10046 trace for the session which was enabled in a logon trigger finds this:

PARSING IN CURSOR #4 len=69 dep=2 uid=0 oct=42 lid=0 tim=1182428884 hv=1576194328 ad='77846918'
ALTER SESSION SET EVENTS '10046 TRACE NAME CONTEXT FOREVER, LEVEL 12'
...
PARSING IN CURSOR #4 len=45 dep=0 uid=50 oct=3 lid=50 tim=3416927811 hv=233497298 ad='88d08b70'
select ID from VENDOR where ACTIVE_FLAG = 'N'
...
PARSING IN CURSOR #8 len=45 dep=0 uid=50 oct=3 lid=50 tim=3620531267 hv=233497298 ad='88d08b70'
select ID from VENDOR where ACTIVE_FLAG = 'N'
...
PARSING IN CURSOR #9 len=45 dep=0 uid=50 oct=3 lid=50 tim=3724573181 hv=233497298 ad='88d08b70'
select ID from VENDOR where ACTIVE_FLAG = 'N'
...
PARSING IN CURSOR #26 len=45 dep=0 uid=50 oct=3 lid=50 tim=3827005408 hv=233497298 ad='88d08b70'
select ID from VENDOR where ACTIVE_FLAG = 'N'
...
PARSING IN CURSOR #30 len=45 dep=0 uid=50 oct=3 lid=50 tim=3848476712 hv=233497298 ad='88d08b70'
select ID from VENDOR where ACTIVE_FLAG = 'N'
...
PARSING IN CURSOR #19 len=45 dep=0 uid=50 oct=3 lid=50 tim=3995284712 hv=233497298 ad='88d08b70'
select ID from VENDOR where ACTIVE_FLAG = 'N'
...
PARSING IN CURSOR #20 len=45 dep=0 uid=50 oct=3 lid=50 tim=4088861749 hv=233497298 ad='88d08b70'
select ID from VENDOR where ACTIVE_FLAG = 'N'
...
...

PARSING IN CURSOR #254 len=45 dep=0 uid=50 oct=3 lid=50 tim=3223320608 hv=233497298 ad='88d08b70'
select ID from VENDOR where ACTIVE_FLAG = 'N'
...
PARSING IN CURSOR #78 len=45 dep=0 uid=50 oct=3 lid=50 tim=3336508540 hv=233497298 ad='88d08b70'
select ID from VENDOR where ACTIVE_FLAG = 'N'
...
PARSING IN CURSOR #260 len=45 dep=0 uid=50 oct=3 lid=50 tim=3336615021 hv=233497298 ad='88d08b70'
select ID from VENDOR where ACTIVE_FLAG = 'N'
...
PARSING IN CURSOR #251 len=45 dep=0 uid=50 oct=3 lid=50 tim=3356820371 hv=233497298 ad='88d08b70'
select ID from VENDOR where ACTIVE_FLAG = 'N'
...
WAIT #259: nam='SQL*Net message to client' ela= 1 driver id=1413697536 #bytes=1 p3=0 obj#=12464 tim=3357352080
WAIT #259: nam='SQL*Net message from client' ela= 279 driver id=1413697536 #bytes=1 p3=0 obj#=12464 tim=3357352383
WAIT #0: nam='SQL*Net message to client' ela= 1 driver id=1413697536 #bytes=1 p3=0 obj#=12464 tim=3357352417
*** 2008-08-12 15:52:59.826
WAIT #0: nam='SQL*Net message from client' ela= 157430298 driver id=1413697536 #bytes=1 p3=0 obj#=12464 tim=3514782745
XCTEND rlbk=1, rd_only=0
WAIT #0: nam='db file sequential read' ela= 10308 file#=4 block#=221289 blocks=1 obj#=12464 tim=3514793577
WAIT #0: nam='log file sync' ela= 105 buffer#=16352 p2=0 p3=0 obj#=12464 tim=3514794105
WAIT #0: nam='SQL*Net message to client' ela= 3 driver id=1413697536 #bytes=1 p3=0 obj#=12464 tim=3514794195
WAIT #0: nam='SQL*Net message from client' ela= 3539 driver id=1413697536 #bytes=1 p3=0 obj#=12464 tim=3514797765
STAT #7 id=1 cnt=1 pid=0 pos=1 obj=11900 op='TABLE ACCESS FULL ACCOUNT_PERIOD (cr=8 pr=0 pw=0 time=83 us)'
XCTEND rlbk=1, rd_only=1
...
XCTEND rlbk=1, rd_only=1
WAIT #0: nam='SQL*Net message to client' ela= 1 driver id=1413697536 #bytes=1 p3=0 obj#=12464 tim=3514806922
WAIT #0: nam='SQL*Net message from client' ela= 263 driver id=1413697536 #bytes=1 p3=0 obj#=12464 tim=3514807200
STAT #4 id=1 cnt=0 pid=0 pos=1 obj=12943 op='TABLE ACCESS FULL VENDOR (cr=122 pr=0 pw=0 time=2238 us)'
XCTEND rlbk=1, rd_only=1
...
XCTEND rlbk=1, rd_only=1
WAIT #0: nam='SQL*Net message to client' ela= 2 driver id=1413697536 #bytes=1 p3=0 obj#=12464 tim=3514807792
WAIT #0: nam='SQL*Net message from client' ela= 265 driver id=1413697536 #bytes=1 p3=0 obj#=12464 tim=3514808072
STAT #9 id=1 cnt=0 pid=0 pos=1 obj=12943 op='TABLE ACCESS FULL VENDOR (cr=122 pr=0 pw=0 time=2235 us)'
XCTEND rlbk=1, rd_only=1
WAIT #0: nam='SQL*Net message to client' ela= 1 driver id=1413697536 #bytes=1 p3=0 obj#=12464 tim=3514808212
WAIT #0: nam='SQL*Net message from client' ela= 249 driver id=1413697536 #bytes=1 p3=0 obj#=12464 tim=3514808477

STAT #8 id=1 cnt=1 pid=0 pos=1 obj=0 op='UPDATE  SEMAPHORE (cr=1 pr=0 pw=0 time=99 us)'
STAT #8 id=2 cnt=1 pid=1 pos=1 obj=12738 op='INDEX UNIQUE SCAN X_SEMAPHORE_0 (cr=1 pr=0 pw=0 time=14 us)'
XCTEND rlbk=1, rd_only=1
...

Once a cursor is closed, Oracle will re-use the CURSOR # associated with that cursor when the next SQL statement is executed (assuming that the SQL statement is not already held open in the session cursor cache).  If the PARSING IN CURSOR # value keeps increasing, that is a sign that cursors are not being closed either due to the design of application code (it might be intentional to reduce the number of soft parses) or the session cursor cache.  From the above, it looks like the application crashed at 2008-08-12 15:52:59.826 and a rollback (XCTEND rlbk=1, rd_only=0) was performed that affected previously changed, but not committed data.  Once the program crashed, Oracle wrote the STAT lines for all cursors that were still open.  In the above, we see the STAT lines that for cursor #4 and #9 were written after the crash, and those cursors were opened fairly early in the trace activity (note that the 32 bit value used for the tim= entry wrapped around 0 while tracing was enabled).  The STAT line output for cursor #8 after the crash shows a different execution plan than that for cursor #9, indicating that at some point the “select ID from VENDOR where ACTIVE_FLAG = ‘N’” SQL statement that was opened early in the trace file for cursor #8 successfully closed at some point before the crash.  In this case, the 10046 trace file provided significant evidence that a programming fix was required.  The developers to the rescue…  :-)

Let’s try executing the following SQL statement in a time period unrelated to the above exploration (with SQL statements executed by some users explicitly omitted and some SQL statements explicitly omitted – warning, you probably should not repeatedly execute this SQL statement due to the potential for latching problems):

SELECT
  OC.SID,
  OC.USER_NAME,
  S.PROGRAM,
  COUNT(*) COUNTER,
  OC.SQL_ID,
  OC.SQL_TEXT
FROM
  V$OPEN_CURSOR OC,
  V$SESSION S
WHERE
  OC.SQL_TEXT NOT LIKE '%obj#,%'
  AND OC.SQL_TEXT NOT LIKE '%grantee#,%'
  AND OC.SQL_TEXT NOT LIKE '%privilege#%'
  AND OC.SQL_TEXT NOT LIKE 'DECLARE%'
  AND OC.SQL_TEXT NOT LIKE '%/*+ rule */%'
  AND OC.SQL_TEXT NOT LIKE '%col#%'
  AND OC.SQL_TEXT NOT LIKE '%sys.mon_mods$%'
  AND OC.SQL_TEXT NOT LIKE '%obj#=%'
  AND OC.SQL_TEXT NOT LIKE '%update$,%'
  AND OC.SID=S.SID
  AND OC.USER_NAME NOT IN ('SYS','DBSNMP','SYSTEM','SYSMAN','RMAN')
GROUP BY
  OC.SID,
  OC.USER_NAME,
  S.PROGRAM,
  OC.SQL_ID,
  OC.SQL_TEXT
HAVING
  COUNT(*)>=10
ORDER BY
  OC.USER_NAME,
  OC.SID,
  OC.SQL_TEXT;

  SID USER_NAME PROGRAM                    COUNTER SQL_ID         SQL_TEXT                                                   
----- --------- -------------------------- ------- -------------  ------------------------------------------------------------
  208 USER1     PLNWIN.EXE                      20 5ngzsfstg8tmy  select o.owner#,o.name,o.namespace,o.remoteowner,o.linkname,
  173 USER2     NCMR.exe                        10 5ngzsfstg8tmy  select o.owner#,o.name,o.namespace,o.remoteowner,o.linkname,
  173 USER2     NCMR.exe                        10 cqgv56fmuj63x  select owner#,name,namespace,remoteowner,linkname,p_timestam
  302 USER3     CapturePhoneData.exe            11 36405ka00hcv5  INSERT INTO PHONE_LOG (    ACCESS_DATE,    EXTENSION       
  230 USER4     bclabr.exe                      10 6qrbg23ub5syp  SELECT calc_end_qty, completed_qty  FROM OPERATION  WHERE WO
  235 USER5     bclabr.exe                      10 6qrbg23ub5syp  SELECT calc_end_qty, completed_qty  FROM OPERATION  WHERE WO
  246 USER6     PURENT.EXE                      14 5ngzsfstg8tmy  select o.owner#,o.name,o.namespace,o.remoteowner,o.linkname,
  171 USER7     CorrectiveActionReport.exe      15 5ngzsfstg8tmy  select o.owner#,o.name,o.namespace,o.remoteowner,o.linkname,
  167 USER8     NetworkTest.exe                 53 3ubfyvhz2zdfk  SELECT HOST_NAME , LAST_DEAD_PING , WARNING_MINUTES , IP_ADD
  167 USER8     NetworkTest.exe                 55 55gk2gdxb9mvc  SELECT IP , COMPUTER_NAME  FROM CUSTAPP.WEB_LOCAL_IP_LOOKUP
  167 USER8     NetworkTest.exe                 88 4xu4rvudbc83p  UPDATE   DOC_OBJECT_DESCRIPTION   SET   LAST_GOOD_PI       
  296 USER9     ReceivePO.exe                   10 fr464ph8jb4zm  SELECT   COUNT(*) LINES  FROM   CUSTAPP.PURC_ORDER_OPEN  WHE
  296 USER9     ReceivePO.exe                   12 5ft6wg3qhvw58  SELECT   RCE.PURC_ORDER_ID,   RCE.PURC_ORDER_LINE_NO,   P.PR
...

USER1 has about 20 cursors open for SQL_ID 5ngzsfstg8tmy, which appears to be an internal SQL statement that is executed on behalf of the session.  The same SQL_ID appears for a couple of other sessions.  Let’s take a look at that SQL statement a little more closely.

SELECT
  *
FROM
  TABLE(DBMS_XPLAN.DISPLAY_CURSOR('5ngzsfstg8tmy',NULL,'TYPICAL'));

SQL_ID  5ngzsfstg8tmy, child number 0        
-------------------------------------        
select o.owner#,o.name,o.namespace,o.remoteowner,o.linkname,o.subname,o.dataob
j#,o.flags from obj$ o where o.obj#=:1       

Plan hash value: 3317232865                  

--------------------------------------------------------------------------------------
| Id  | Operation                   | Name   | Rows  | Bytes | Cost (%CPU)| Time     |
--------------------------------------------------------------------------------------
|   0 | SELECT STATEMENT            |        |       |       |     2 (100)|          |
|   1 |  TABLE ACCESS BY INDEX ROWID| OBJ$   |     1 |    74 |     2   (0)| 00:00:01 |
|*  2 |   INDEX UNIQUE SCAN         | I_OBJ1 |     1 |       |     1   (0)| 00:00:01 |
--------------------------------------------------------------------------------------

Predicate Information (identified by operation id):
---------------------------------------------------
   2 - access("O"."OBJ#"=:1)                 

-

SQL_ID  5ngzsfstg8tmy, child number 1        
-------------------------------------        
select o.owner#,o.name,o.namespace,o.remoteowner,o.linkname,o.subname,o.dataob
j#,o.flags from obj$ o where o.obj#=:1       

Plan hash value: 3317232865                  

--------------------------------------------------------------------------------------
| Id  | Operation                   | Name   | Rows  | Bytes | Cost (%CPU)| Time     |
--------------------------------------------------------------------------------------
|   0 | SELECT STATEMENT            |        |       |       |     2 (100)|          |
|   1 |  TABLE ACCESS BY INDEX ROWID| OBJ$   |     1 |    74 |     2   (0)| 00:00:01 |
|*  2 |   INDEX UNIQUE SCAN         | I_OBJ1 |     1 |       |     1   (0)| 00:00:01 |
--------------------------------------------------------------------------------------

Predicate Information (identified by operation id):
---------------------------------------------------
   2 - access("O"."OBJ#"=:1)                 

-

SQL_ID  5ngzsfstg8tmy, child number 2        
-------------------------------------        
select o.owner#,o.name,o.namespace,o.remoteowner,o.linkname,o.subname,o.dataob
j#,o.flags from obj$ o where o.obj#=:1       

Plan hash value: 3317232865                  

--------------------------------------------------------------------------------------
| Id  | Operation                   | Name   | Rows  | Bytes | Cost (%CPU)| Time     |
--------------------------------------------------------------------------------------
|   0 | SELECT STATEMENT            |        |       |       |     2 (100)|          |
|   1 |  TABLE ACCESS BY INDEX ROWID| OBJ$   |     1 |    74 |     2   (0)| 00:00:01 |
|*  2 |   INDEX UNIQUE SCAN         | I_OBJ1 |     1 |       |     1   (0)| 00:00:01 |
--------------------------------------------------------------------------------------

Predicate Information (identified by operation id):
---------------------------------------------------
   2 - access("O"."OBJ#"=:1)                 

-

SQL_ID  5ngzsfstg8tmy, child number 3        
-------------------------------------        
select o.owner#,o.name,o.namespace,o.remoteowner,o.linkname,o.subname,o.dataob
j#,o.flags from obj$ o where o.obj#=:1       

Plan hash value: 3317232865                  

--------------------------------------------------------------------------------------
| Id  | Operation                   | Name   | Rows  | Bytes | Cost (%CPU)| Time     |
--------------------------------------------------------------------------------------
|   0 | SELECT STATEMENT            |        |       |       |     2 (100)|          |
|   1 |  TABLE ACCESS BY INDEX ROWID| OBJ$   |     1 |    74 |     2   (0)| 00:00:01 |
|*  2 |   INDEX UNIQUE SCAN         | I_OBJ1 |     1 |       |     1   (0)| 00:00:01 |
--------------------------------------------------------------------------------------

Predicate Information (identified by operation id):
---------------------------------------------------
   2 - access("O"."OBJ#"=:1)                 

-

SQL_ID  5ngzsfstg8tmy, child number 4        
-------------------------------------        
select o.owner#,o.name,o.namespace,o.remoteowner,o.linkname,o.subname,o.dataob
j#,o.flags from obj$ o where o.obj#=:1       

Plan hash value: 3317232865                  

--------------------------------------------------------------------------------------
| Id  | Operation                   | Name   | Rows  | Bytes | Cost (%CPU)| Time     |
--------------------------------------------------------------------------------------
|   0 | SELECT STATEMENT            |        |       |       |     2 (100)|          |
|   1 |  TABLE ACCESS BY INDEX ROWID| OBJ$   |     1 |    74 |     2   (0)| 00:00:01 |
|*  2 |   INDEX UNIQUE SCAN         | I_OBJ1 |     1 |       |     1   (0)| 00:00:01 |
--------------------------------------------------------------------------------------

Predicate Information (identified by operation id):
---------------------------------------------------
   2 - access("O"."OBJ#"=:1)                 

-

SQL_ID  5ngzsfstg8tmy, child number 5        
-------------------------------------        
select o.owner#,o.name,o.namespace,o.remoteowner,o.linkname,o.subname,o.dataob
j#,o.flags from obj$ o where o.obj#=:1       

Plan hash value: 3317232865                  

--------------------------------------------------------------------------------------
| Id  | Operation                   | Name   | Rows  | Bytes | Cost (%CPU)| Time     |
--------------------------------------------------------------------------------------
|   0 | SELECT STATEMENT            |        |       |       |     2 (100)|          |
|   1 |  TABLE ACCESS BY INDEX ROWID| OBJ$   |     1 |    74 |     2   (0)| 00:00:01 |
|*  2 |   INDEX UNIQUE SCAN         | I_OBJ1 |     1 |       |     1   (0)| 00:00:01 |
--------------------------------------------------------------------------------------

Predicate Information (identified by operation id):
---------------------------------------------------
   2 - access("O"."OBJ#"=:1)                 

-

SQL_ID  5ngzsfstg8tmy, child number 7        
-------------------------------------        
select o.owner#,o.name,o.namespace,o.remoteowner,o.linkname,o.subname,o.dataob
j#,o.flags from obj$ o where o.obj#=:1       

Plan hash value: 3317232865                  

--------------------------------------------------------------------------------------
| Id  | Operation                   | Name   | Rows  | Bytes | Cost (%CPU)| Time     |
--------------------------------------------------------------------------------------
|   0 | SELECT STATEMENT            |        |       |       |     2 (100)|          |
|   1 |  TABLE ACCESS BY INDEX ROWID| OBJ$   |     1 |    74 |     2   (0)| 00:00:01 |
|*  2 |   INDEX UNIQUE SCAN         | I_OBJ1 |     1 |       |     1   (0)| 00:00:01 |
--------------------------------------------------------------------------------------

Predicate Information (identified by operation id):
---------------------------------------------------
   2 - access("O"."OBJ#"=:1)                 

-

SQL_ID  5ngzsfstg8tmy, child number 9        
-------------------------------------        
select o.owner#,o.name,o.namespace,o.remoteowner,o.linkname,o.subname,o.dataob
j#,o.flags from obj$ o where o.obj#=:1       

Plan hash value: 3317232865                  

--------------------------------------------------------------------------------------
| Id  | Operation                   | Name   | Rows  | Bytes | Cost (%CPU)| Time     |
--------------------------------------------------------------------------------------
|   0 | SELECT STATEMENT            |        |       |       |     2 (100)|          |
|   1 |  TABLE ACCESS BY INDEX ROWID| OBJ$   |     1 |    74 |     2   (0)| 00:00:01 |
|*  2 |   INDEX UNIQUE SCAN         | I_OBJ1 |     1 |       |     1   (0)| 00:00:01 |
--------------------------------------------------------------------------------------

Predicate Information (identified by operation id):
---------------------------------------------------
   2 - access("O"."OBJ#"=:1)                 

-

SQL_ID  5ngzsfstg8tmy, child number 10       
--------------------------------------       
select o.owner#,o.name,o.namespace,o.remoteowner,o.linkname,o.subname,o.dataob
j#,o.flags from obj$ o where o.obj#=:1       

Plan hash value: 3317232865                  

--------------------------------------------------------------------------------------
| Id  | Operation                   | Name   | Rows  | Bytes | Cost (%CPU)| Time     |
--------------------------------------------------------------------------------------
|   0 | SELECT STATEMENT            |        |       |       |     2 (100)|          |
|   1 |  TABLE ACCESS BY INDEX ROWID| OBJ$   |     1 |    74 |     2   (0)| 00:00:01 |
|*  2 |   INDEX UNIQUE SCAN         | I_OBJ1 |     1 |       |     1   (0)| 00:00:01 |
--------------------------------------------------------------------------------------

Predicate Information (identified by operation id):
---------------------------------------------------
   2 - access("O"."OBJ#"=:1)                 

-

SQL_ID  5ngzsfstg8tmy, child number 11       
--------------------------------------       
select o.owner#,o.name,o.namespace,o.remoteowner,o.linkname,o.subname,o.dataob
j#,o.flags from obj$ o where o.obj#=:1       

Plan hash value: 3317232865                  

--------------------------------------------------------------------------------------
| Id  | Operation                   | Name   | Rows  | Bytes | Cost (%CPU)| Time     |
--------------------------------------------------------------------------------------
|   0 | SELECT STATEMENT            |        |       |       |     2 (100)|          |
|   1 |  TABLE ACCESS BY INDEX ROWID| OBJ$   |     1 |    74 |     2   (0)| 00:00:01 |
|*  2 |   INDEX UNIQUE SCAN         | I_OBJ1 |     1 |       |     1   (0)| 00:00:01 |
--------------------------------------------------------------------------------------

Predicate Information (identified by operation id):
---------------------------------------------------
   2 - access("O"."OBJ#"=:1)                 

-

SQL_ID  5ngzsfstg8tmy, child number 12       
--------------------------------------       
select o.owner#,o.name,o.namespace,o.remoteowner,o.linkname,o.subname,o.     
dataobj#,o.flags from obj$ o where o.obj#=:1 

Plan hash value: 3317232865                  

----------------------------------------------
| Id  | Operation                   | Name   |
----------------------------------------------
|   0 | SELECT STATEMENT            |        |
|   1 |  TABLE ACCESS BY INDEX ROWID| OBJ$   |
|*  2 |   INDEX UNIQUE SCAN         | I_OBJ1 |
----------------------------------------------

Predicate Information (identified by operation id):
---------------------------------------------------
   2 - access("O"."OBJ#"=:1)                 

Note                  
-----                 
   - rule based optimizer used (consider using cbo)

-

SQL_ID  5ngzsfstg8tmy, child number 14       
--------------------------------------       
select o.owner#,o.name,o.namespace,o.remoteowner,o.linkname,o.subname,o.dataob
j#,o.flags from obj$ o where o.obj#=:1       

Plan hash value: 3317232865                  

--------------------------------------------------------------------------------------
| Id  | Operation                   | Name   | Rows  | Bytes | Cost (%CPU)| Time     |
--------------------------------------------------------------------------------------
|   0 | SELECT STATEMENT            |        |       |       |     2 (100)|          |
|   1 |  TABLE ACCESS BY INDEX ROWID| OBJ$   |     1 |    74 |     2   (0)| 00:00:01 |
|*  2 |   INDEX UNIQUE SCAN         | I_OBJ1 |     1 |       |     1   (0)| 00:00:01 |
--------------------------------------------------------------------------------------

Predicate Information (identified by operation id):
---------------------------------------------------
   2 - access("O"."OBJ#"=:1)

There are 12 child cursors for this SQL statement still in the library cache, or at least the execution plans are still available.  If we check V$SQL_SHARED_CURSOR we might be able to tell why at least 15 child cursors were created for this one SQL statement:

SQL_ID        ADDRESS          CHILD_ADDRESS    CN USOOSLSEBPISTABDLTRIIRLIOSMUTNFAITDLDBPCSRPTMBMROPMFL
------------- ---------------- ---------------- -- -----------------------------------------------------
5ngzsfstg8tmy 000000018D960FF0 000000018D9600C0  0 NNYNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNYYNNNN
              000000018D960FF0 000000018D642EA8  1 NNYNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNN
              000000018D960FF0 000000018A2D1B98  2 NNYNYNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNYYNNNN
              000000018D960FF0 0000000180B86C60  3 NNYNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNYYNNNN
              000000018D960FF0 000000016AC7CD28  4 NNYNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNYYNNNN
              000000018D960FF0 0000000161B54780  5 NNYNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNYYNNNN
              000000018D960FF0 0000000175FE5788  6 NNYNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNYYNNNN
              000000018D960FF0 0000000178648270  7 NNYNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNYYNNNN
              000000018D960FF0 0000000173425140  9 NNYNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNYYNNNN
              000000018D960FF0 000000017322B9C0 10 NNYNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNYYNNNN
              000000018D960FF0 00000001834D71D8 11 NNYNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNYYNNNN
              000000018D960FF0 00000001767FE0C8 12 NNYNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNYYNNNN
              000000018D960FF0 000000017D28DFA0 14 NNYNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNYYNNNN

In the above, the first O is OPTIMIZER_MISMATCH, the second S is STATS_ROW_MISMATCH, the last R is ROLL_INVALID_MISMATCH, and the last O is OPTIMIZER_MODE_MISMATCH.  A lot of the child cursors were created due to statistics collection – I wonder if some of these older child cursors are still open by sessions.  Oracle Database 10.2.0.x does not offer the IS_SHAREABLE column in V$SQL, but the IS_OBSOLETE column shows that none of the 13 child cursors still in the library cache has been marked as obsolete:

SELECT
  CHILD_NUMBER CN,
  PARSING_SCHEMA_NAME,
  OPTIMIZER_ENV_HASH_VALUE OPTIMIZER_ENV,
  INVALIDATIONS,
  PARSE_CALLS,
  IS_OBSOLETE,
  FIRST_LOAD_TIME,
  TO_CHAR(LAST_ACTIVE_TIME,'YYYY-MM-DD/HH24:MI:SS') LAST_ACTIVE_TIME
FROM
  V$SQL
WHERE
  SQL_ID='5ngzsfstg8tmy';

CN PARSING_SC OPTIMIZER_ENV INVALIDATIONS PARSE_CALLS I FIRST_LOAD_TIME     LAST_ACTIVE_TIME  
-- ---------- ------------- ------------- ----------- - ------------------- -------------------
 0 SYS           1515106640             1        3107 N 2009-11-27/16:40:02 2010-01-25/14:53:12
 1 SYS           1515106640             0         240 N 2009-11-27/16:40:02 2010-01-25/22:03:15
 2 SYS           2540482053             0        1073 N 2009-11-27/16:40:02 2010-02-01/08:01:01
 3 SYS           1515106640             0        2810 N 2009-11-27/16:40:02 2010-02-01/03:40:02
 4 SYS           1515106640             0         583 N 2009-11-27/16:40:02 2010-01-25/18:09:13
 5 SYS           1515106640             0         239 N 2009-11-27/16:40:02 2010-02-01/10:19:44
 6 SYS           2540482053             0          69 N 2009-11-27/16:40:02 2010-02-01/10:14:58
 7 SYS           1515106640             0         763 N 2009-11-27/16:40:02 2010-01-25/10:49:16
 9 SYS           1515106640             0         510 N 2009-11-27/16:40:02 2010-02-01/08:16:10
10 SYS           2540482053             0         163 N 2009-11-27/16:40:02 2010-02-01/06:54:04
11 SYS           1515106640             0         260 N 2009-11-27/16:40:02 2010-01-31/23:07:26
12 SYS           2230081206             0           8 N 2009-11-27/16:40:02 2010-02-01/03:48:43
14 SYS           1515106640             0         654 N 2009-11-27/16:40:02 2010-02-01/06:10:55

The OPTIMIZER_ENV_HASH_VALUE is different for some of the child cursors, although all of the SQL statements were parsed by the SYS user.  Let’s take a look at what is different about the optimizer environment for some of the SQL statements:

SELECT
  CHILD_NUMBER CN,
  NAME,
  VALUE,
  ISDEFAULT DEF
FROM
  V$SQL_OPTIMIZER_ENV
WHERE
  SQL_ID='5ngzsfstg8tmy'
  AND CHILD_NUMBER in (0,2,12)
ORDER BY
  NAME,
  CHILD_NUMBER;

If we just list the differences in the output for the three child cursors, we see the following:

 CN NAME                        VALUE           DEF
--- --------------------------- --------------- ---
  2 _optim_peek_user_binds      false           NO
  0 optimizer_mode              choose          NO
  2 optimizer_mode              choose          NO
 12 optimizer_mode              rule            NO

Interesting, two of the child cursors are using an OPTIMIZER_MODE of CHOOSE, and one is using an OPTIMIZER_MODE of RULE, neither of which are valid (supported) OPTIMIZER_MODE values for this release of Oracle Database.  Of course, it is possible to supply a hint to force the use of the RULE optimizer (might be used by Oracle’s internal SQL statements), but CHOOSE?  Just to verify:

SQL> SHOW PARAMETER OPTIMIZER_MODE

NAME             TYPE        VALUE
---------------- ----------- --------
optimizer_mode   string      ALL_ROWS

The _OPTIM_PEEK_USER_BINDS is disabled for one of the three unique OPTIMIZER_ENV_HASH_VALUE values, which was implemented in a logon trigger to “fix” problems with certain applications that either fail to initialize bind variable values on the initial hard parse, or select unpopular values during the initial hard parse.  But, there is no logon trigger that sets the OPTIMIZER_MODE to CHOOSE for a session.

OK, the topic is drifting a bit.  USER1 (SID 208) has 20 cursors open with this internal SQL statement.  I wonder if the number of child cursors in the library cache could be a possible cause, combined with the value of 200 for SESSION_CACHED_CURSORS (if a SQL statement is executed at least 3 times, it will be added to the cached cursors for the session and held open, even when the client explicitly closes the cursor)?

I suppose at this point, I should probably try to determine why the NetworkTest.exe program has 88 open cursors for an update statement, 55  open cursors for one select statement, and 53 open cursors for a second select statement…  To crash, or not to crash, is not the question - it is only a matter of time.





Execution Plans – What is the Plan, and Where Do I Find It 3

2 02 2010

February 2, 2010

(Back to the Previous Post in the Series)

In the first blog article in this series, we explored several methods for generating execution plans, specifcally, we saw how to:

  • Display the actual (TYPICAL) execution plan for a SQL statement with estimated cardinality and costs.
  • Display the actual (ALLSTATS LAST) execution plan for a SQL statement using the GATHER_PLAN_STATISTICS hint to compare the estimated cardinality with the actual number of rows returned from each operation in the plan, and obtain the actual final execution time (timing of the intermediate steps might not be close to actual time).
  • Display the actual (ALLSTATS LAST) execution plan for a SQL statement with the STATISTICS_LEVEL parameter set to ALL at the session level to obtain the final execution time and close estimates for each of the intermediate steps (in some cases, a significant increase in execution time was experienced).
  • Compare the changes in the actual execution plan when changing the OPTIMIZER_MODE parameter between ALL_ROWS, FIRST_ROWS_1, and CHOOSE.  Note that setting the OPTIMIZER_MODE to FIRST_ROWS_1 may have caused the optimizer to under-estimate the number of rows that will be returned, as shown in the execution plan.
  • Display a possibly correct execution plan with SQL*Plus’ AUTOTRACE and with EXPLAIN PLAN, and explore some of the problems that might be encountered when relying on those plans.
  • See the effects of bind peeking on an execution plan.
  • Retrieve the execution plan by setting event 10132.
  • Read the execution plan directly from a 10046 trace file.
  • Process the trace file with TKPROF, and one of the potential problems caused by telling TKPROF to generate explain plans.

The first blog article in this article series used the 64 bit version of Oracle Database 10.2.0.2 (with OPTIMIZER_FEATURES_ENABLE set to 10.2.0.1).  It might be interesting to compare the output of the 64 bit version of Oracle 11.2.0.1 with that of Oracle 10.2.0.2 (note that the server running 11.2.0.1 is a bit faster than the server running 10.2.0.2).  Comparing the outputs might answer the question of whether or not there is a bug in Oracle 10.2.0.2, for instance, relating the the cardinality estimates displayed in execution plans when the OPTIMIZER_MODE was set to FIRST_ROWS_1 – if the same output is present in 11.2.0.1, that probably means that the optimizer is working as designed.  Obviously, this article will use the same table definition for T1, T2, T3, and T4 that were specified in the first article.

First, we will generate an execution plan for a SQL statement with the OPTIMIZER_MODE set to ALL_ROWS:

SET LINESIZE 150
ALTER SESSION SET OPTIMIZER_MODE='ALL_ROWS';

SELECT
  T3.C1,
  SUBSTR(T1.C2,1,10) C2
FROM
  T3,
  T1
WHERE
  T1.C1=T3.C1
  AND T1.C1 BETWEEN 1 AND 10;

 C1 C2
--- ----------
  1 1AAAAAAAAA
  2 2AAAAAAAAA
  3 3AAAAAAAAA
  4 4AAAAAAAAA
  5 5AAAAAAAAA
  6 6AAAAAAAAA
  7 7AAAAAAAAA
  8 8AAAAAAAAA
  9 9AAAAAAAAA
 10 10AAAAAAAA

The typical way to display an execution plan for a SQL statement that was just executed is as follows (note that the third parameter, the FORMAT parameter, could have also been set to NULL to produce the same result):

SELECT
  *
FROM
  TABLE(DBMS_XPLAN.DISPLAY_CURSOR(NULL,NULL,'TYPICAL'));

SQL_ID  9dq71tc7vasgu, child number 0
-------------------------------------
SELECT   T3.C1,   SUBSTR(T1.C2,1,10) C2 FROM   T3,   T1 WHERE           
T1.C1=T3.C1   AND T1.C1 BETWEEN 1 AND 10                                

Plan hash value: 985299768          

---------------------------------------------------------------------------------------------
| Id  | Operation                    | Name         | Rows  | Bytes | Cost (%CPU)| Time     |
---------------------------------------------------------------------------------------------
|   0 | SELECT STATEMENT             |              |       |       | 10219 (100)|          |
|*  1 |  HASH JOIN                   |              |     9 |  2394 | 10219   (1)| 00:02:03 |
|*  2 |   TABLE ACCESS FULL          | T3           |    10 |    50 | 10214   (1)| 00:02:03 |
|   3 |   TABLE ACCESS BY INDEX ROWID| T1           |    10 |  2610 |     4   (0)| 00:00:01 |
|*  4 |    INDEX RANGE SCAN          | SYS_C0017307 |    10 |       |     3   (0)| 00:00:01 |
---------------------------------------------------------------------------------------------

Predicate Information (identified by operation id):                     
---------------------------------------------------                     
   1 - access("T1"."C1"="T3"."C1")  
   2 - filter(("T3"."C1"<=10 AND "T3"."C1">=1))                         
   4 - access("T1"."C1">=1 AND "T1"."C1"<=10)                           

In the above, note that the calculated cost of the execution plan is 10219 (NOWORKLOAD CPU statistics).  Now, a little more experimentation, setting OPTIMIZER_MODE to FIRST_ROWS (Oracle assumes that only the first row will be retrieved, and the rest will likely be discarded):

ALTER SESSION SET OPTIMIZER_MODE='FIRST_ROWS_1';

SELECT
  T3.C1,
  SUBSTR(T1.C2,1,10) C2
FROM
  T3,
  T1
WHERE
  T1.C1=T3.C1
  AND T1.C1 BETWEEN 1 AND 10;

SELECT
  *
FROM
  TABLE(DBMS_XPLAN.DISPLAY_CURSOR(NULL,NULL,'TYPICAL'));

SQL_ID  9dq71tc7vasgu, child number 1
-------------------------------------
SELECT   T3.C1,   SUBSTR(T1.C2,1,10) C2 FROM   T3,   T1 WHERE           
T1.C1=T3.C1   AND T1.C1 BETWEEN 1 AND 10                                

Plan hash value: 2322422896         

---------------------------------------------------------------------------------------------
| Id  | Operation                    | Name         | Rows  | Bytes | Cost (%CPU)| Time     |
---------------------------------------------------------------------------------------------
|   0 | SELECT STATEMENT             |              |       |       |  3073 (100)|          |
|   1 |  NESTED LOOPS                |              |       |       |            |          |
|   2 |   NESTED LOOPS               |              |     2 |   532 |  3073   (1)| 00:00:37 |
|*  3 |    TABLE ACCESS FULL         | T3           |     7 |    35 |  3066   (1)| 00:00:37 |
|*  4 |    INDEX UNIQUE SCAN         | SYS_C0017307 |     1 |       |     1   (0)| 00:00:01 |
|   5 |   TABLE ACCESS BY INDEX ROWID| T1           |     1 |   261 |     2   (0)| 00:00:01 |
---------------------------------------------------------------------------------------------

Predicate Information (identified by operation id):                     
---------------------------------------------------                     
   3 - filter(("T3"."C1"<=10 AND "T3"."C1">=1))                         
   4 - access("T1"."C1"="T3"."C1")  
       filter(("T1"."C1"<=10 AND "T1"."C1">=1))

In the above, notice that by changing the optimizer mode from ALL_ROWS to FIRST_ROWS_1 a new execution plan was created (the child number has increased by 1 and the Plan hash value has changed) that now uses two nested loops joins (first joining the index for table T1 with the table T3), rather than a hash join, and the calculated cost has decreased to 3073.  You might be wondering why Oracle did not pick this execution plan with the nested loops joins, rather than the hash join when the OPTIMIZER_MODE was set to ALL_ROWS, since this plan has a lower calculated cost – note that Oracle 11.2.0.1 is estimating the same number of rows to be returned as Oracle 10.2.0.2.  But, we really do not know anything about performance from just looking at the above plans.  So, let’s repeat the test again, changing the SQL statement so that we are able to pass in ‘ALLSTATS LAST’ as the format parameter for the DBMS_XPLAN call:

ALTER SESSION SET OPTIMIZER_MODE='ALL_ROWS';

SELECT /*+ GATHER_PLAN_STATISTICS */
  T3.C1,
  SUBSTR(T1.C2,1,10) C2
FROM
  T3,
  T1
WHERE
  T1.C1=T3.C1
  AND T1.C1 BETWEEN 1 AND 10;

SELECT
  *
FROM
  TABLE(DBMS_XPLAN.DISPLAY_CURSOR(NULL,NULL,'ALLSTATS LAST'));

SQL_ID  ddnbt67ftu9ds, child number 0
-------------------------------------
SELECT /*+ GATHER_PLAN_STATISTICS */   T3.C1,   SUBSTR(T1.C2,1,10) C2   
FROM   T3,   T1 WHERE   T1.C1=T3.C1   AND T1.C1 BETWEEN 1 AND 10        

Plan hash value: 985299768          

----------------------------------------------------------------------------------------------------------------------------------
| Id  | Operation                    | Name         | Starts | E-Rows | A-Rows |   A-Time   | Buffers |  OMem |  1Mem | Used-Mem |
----------------------------------------------------------------------------------------------------------------------------------
|   0 | SELECT STATEMENT             |              |      1 |        |     10 |00:00:00.07 |   37170 |       |       |          |
|*  1 |  HASH JOIN                   |              |      1 |      9 |     10 |00:00:00.07 |   37170 |  1452K|  1452K| 1365K (0)|
|*  2 |   TABLE ACCESS FULL          | T3           |      1 |     10 |     10 |00:00:00.01 |   37164 |       |       |          |
|   3 |   TABLE ACCESS BY INDEX ROWID| T1           |      1 |     10 |     10 |00:00:00.01 |       6 |       |       |          |
|*  4 |    INDEX RANGE SCAN          | SYS_C0017307 |      1 |     10 |     10 |00:00:00.01 |       4 |       |       |          |
----------------------------------------------------------------------------------------------------------------------------------

Predicate Information (identified by operation id):                     
---------------------------------------------------                     
   1 - access("T1"."C1"="T3"."C1")  
   2 - filter(("T3"."C1"<=10 AND "T3"."C1">=1))                         
   4 - access("T1"."C1">=1 AND "T1"."C1"<=10)

The query completed in 0.07 seconds, retrieved 10 rows, and used 1,365 * 1,024 bytes of memory during the in-memory hash join.  No blocks were read from disk (the query was previously executed, and the table and index blocks managed to remain in the buffer cache).

ALTER SESSION SET OPTIMIZER_MODE='FIRST_ROWS_1';

SELECT /*+ GATHER_PLAN_STATISTICS */
  T3.C1,
  SUBSTR(T1.C2,1,10) C2
FROM
  T3,
  T1
WHERE
  T1.C1=T3.C1
  AND T1.C1 BETWEEN 1 AND 10;

SELECT
  *
FROM
  TABLE(DBMS_XPLAN.DISPLAY_CURSOR(NULL,NULL,'ALLSTATS LAST'));

SQL_ID  ddnbt67ftu9ds, child number 1
-------------------------------------
SELECT /*+ GATHER_PLAN_STATISTICS */   T3.C1,   SUBSTR(T1.C2,1,10) C2   
FROM   T3,   T1 WHERE   T1.C1=T3.C1   AND T1.C1 BETWEEN 1 AND 10        

Plan hash value: 2322422896         

-------------------------------------------------------------------------------------------------------                        
| Id  | Operation                    | Name         | Starts | E-Rows | A-Rows |   A-Time   | Buffers |                        
-------------------------------------------------------------------------------------------------------                        
|   0 | SELECT STATEMENT             |              |      1 |        |     10 |00:00:00.01 |   37189 |                        
|   1 |  NESTED LOOPS                |              |      1 |        |     10 |00:00:00.01 |   37189 |                        
|   2 |   NESTED LOOPS               |              |      1 |      2 |     10 |00:00:00.01 |   37179 |                        
|*  3 |    TABLE ACCESS FULL         | T3           |      1 |      7 |     10 |00:00:00.01 |   37165 |                        
|*  4 |    INDEX UNIQUE SCAN         | SYS_C0017307 |     10 |      1 |     10 |00:00:00.01 |      14 |                        
|   5 |   TABLE ACCESS BY INDEX ROWID| T1           |     10 |      1 |     10 |00:00:00.01 |      10 |                        
-------------------------------------------------------------------------------------------------------                        

Predicate Information (identified by operation id):                     
---------------------------------------------------                      

   3 - filter(("T3"."C1"<=10 AND "T3"."C1">=1))                         
   4 - access("T1"."C1"="T3"."C1")  
       filter(("T1"."C1"<=10 AND "T1"."C1">=1))

As shown above, with the FIRST_ROWS_1 optimizer mode, the query completed in 0.01 seconds.

The GATHER_PLAN_STATISTICS hint is helpful because it allows DBMS_XPLAN to output the actual execution statistics for the previous SQL statement.  If you do not want to use that hint, it is also possible to change the STATISTICS_LEVEL to ALL at the session level level, as the following demonstrates:

ALTER SESSION SET OPTIMIZER_MODE='ALL_ROWS';
ALTER SESSION SET STATISTICS_LEVEL='ALL';

SELECT
  T3.C1,
  SUBSTR(T1.C2,1,10) C2
FROM
  T3,
  T1
WHERE
  T1.C1=T3.C1
  AND T1.C1 BETWEEN 1 AND 10;

SELECT
  *
FROM
  TABLE(DBMS_XPLAN.DISPLAY_CURSOR(NULL,NULL,'ALLSTATS LAST'));

SQL_ID  9dq71tc7vasgu, child number 2
-------------------------------------
SELECT   T3.C1,   SUBSTR(T1.C2,1,10) C2 FROM   T3,   T1 WHERE           
T1.C1=T3.C1   AND T1.C1 BETWEEN 1 AND 10                                

Plan hash value: 985299768          

----------------------------------------------------------------------------------------------------------------------------------
| Id  | Operation                    | Name         | Starts | E-Rows | A-Rows |   A-Time   | Buffers |  OMem |  1Mem | Used-Mem |
----------------------------------------------------------------------------------------------------------------------------------
|   0 | SELECT STATEMENT             |              |      1 |        |     10 |00:00:00.07 |   37170 |       |       |          |
|*  1 |  HASH JOIN                   |              |      1 |      9 |     10 |00:00:00.07 |   37170 |  1452K|  1452K| 1424K (0)|
|*  2 |   TABLE ACCESS FULL          | T3           |      1 |     10 |     10 |00:00:00.07 |   37164 |       |       |          |
|   3 |   TABLE ACCESS BY INDEX ROWID| T1           |      1 |     10 |     10 |00:00:00.01 |       6 |       |       |          |
|*  4 |    INDEX RANGE SCAN          | SYS_C0017307 |      1 |     10 |     10 |00:00:00.01 |       4 |       |       |          |
----------------------------------------------------------------------------------------------------------------------------------

Predicate Information (identified by operation id):                     
---------------------------------------------------                     

   1 - access("T1"."C1"="T3"."C1")  
   2 - filter(("T3"."C1"<=10 AND "T3"."C1">=1))                         
   4 - access("T1"."C1">=1 AND "T1"."C1"<=10)

Note that the change to the STATISTICS_LEVEL caused another hard parse for the SQL statement, and the child number is now listed as 2.  For some reason, the amount of memory required for the hash join has increased slightly.  If you look closely, you will also notice that the execution time remained the same before and after the changing of the STATISTICS_LEVEL parameter.

Let’s try again with the FIRST_ROWS_1 value specified for OPTIMIZER_MODE.

ALTER SESSION SET OPTIMIZER_MODE='FIRST_ROWS_1';

SELECT
  T3.C1,
  SUBSTR(T1.C2,1,10) C2
FROM
  T3,
  T1
WHERE
  T1.C1=T3.C1
  AND T1.C1 BETWEEN 1 AND 10;

SELECT
  *
FROM
  TABLE(DBMS_XPLAN.DISPLAY_CURSOR(NULL,NULL,'ALLSTATS LAST'));

SQL_ID  9dq71tc7vasgu, child number 3
-------------------------------------
SELECT   T3.C1,   SUBSTR(T1.C2,1,10) C2 FROM   T3,   T1 WHERE           
T1.C1=T3.C1   AND T1.C1 BETWEEN 1 AND 10                                

Plan hash value: 2322422896         

-------------------------------------------------------------------------------------------------------                        
| Id  | Operation                    | Name         | Starts | E-Rows | A-Rows |   A-Time   | Buffers |                        
-------------------------------------------------------------------------------------------------------                        
|   0 | SELECT STATEMENT             |              |      1 |        |     10 |00:00:00.07 |   37189 |                        
|   1 |  NESTED LOOPS                |              |      1 |        |     10 |00:00:00.07 |   37189 |                        
|   2 |   NESTED LOOPS               |              |      1 |      2 |     10 |00:00:00.07 |   37179 |                        
|*  3 |    TABLE ACCESS FULL         | T3           |      1 |      7 |     10 |00:00:00.07 |   37165 |                        
|*  4 |    INDEX UNIQUE SCAN         | SYS_C0017307 |     10 |      1 |     10 |00:00:00.01 |      14 |                        
|   5 |   TABLE ACCESS BY INDEX ROWID| T1           |     10 |      1 |     10 |00:00:00.01 |      10 |                        
-------------------------------------------------------------------------------------------------------                        

Predicate Information (identified by operation id):                     
---------------------------------------------------                     
   3 - filter(("T3"."C1"<=10 AND "T3"."C1">=1))                         
   4 - access("T1"."C1"="T3"."C1")  
       filter(("T1"."C1"<=10 AND "T1"."C1">=1))

Note again that there was a hard parse, and the child number increased by 1.  This time, rather than completing in 0.01 seconds, the query required 0.07 seconds.

Let’s try again, this time using bind variables rather than constants (literals):

ALTER SESSION SET OPTIMIZER_MODE='ALL_ROWS';
ALTER SESSION SET STATISTICS_LEVEL='TYPICAL';

VARIABLE N1 NUMBER
VARIABLE N2 NUMBER
EXEC :N1:=1
EXEC :N2:=10

SELECT /*+ GATHER_PLAN_STATISTICS */
  T3.C1,
  SUBSTR(T1.C2,1,10) C2
FROM
  T3,
  T1
WHERE
  T1.C1=T3.C1
  AND T1.C1 BETWEEN :N1 AND :N2;

SELECT
  *
FROM
  TABLE(DBMS_XPLAN.DISPLAY_CURSOR(NULL,NULL,'ALLSTATS LAST'));

SQL_ID  cvq22z77c8fww, child number 0
-------------------------------------
SELECT /*+ GATHER_PLAN_STATISTICS */   T3.C1,   SUBSTR(T1.C2,1,10) C2   
FROM   T3,   T1 WHERE   T1.C1=T3.C1   AND T1.C1 BETWEEN :N1 AND :N2     

Plan hash value: 744086632          

-----------------------------------------------------------------------------------------------------------------------------------                                
| Id  | Operation                     | Name         | Starts | E-Rows | A-Rows |   A-Time   | Buffers |  OMem |  1Mem | Used-Mem |                                
-----------------------------------------------------------------------------------------------------------------------------------                                
|   0 | SELECT STATEMENT              |              |      1 |        |     10 |00:00:00.07 |   37170 |       |       |          |                                
|*  1 |  FILTER                       |              |      1 |        |     10 |00:00:00.07 |   37170 |       |       |          |                                
|*  2 |   HASH JOIN                   |              |      1 |      9 |     10 |00:00:00.07 |   37170 |  1452K|  1452K| 1424K (0)|                                
|*  3 |    TABLE ACCESS FULL          | T3           |      1 |     10 |     10 |00:00:00.01 |   37164 |       |       |          |                                
|   4 |    TABLE ACCESS BY INDEX ROWID| T1           |      1 |     10 |     10 |00:00:00.01 |       6 |       |       |          |                                
|*  5 |     INDEX RANGE SCAN          | SYS_C0017307 |      1 |     10 |     10 |00:00:00.01 |       4 |       |       |          |                                
-----------------------------------------------------------------------------------------------------------------------------------                                

Predicate Information (identified by operation id):                     
---------------------------------------------------                     
   1 - filter(:N1<=:N2)             
   2 - access("T1"."C1"="T3"."C1")  
   3 - filter(("T3"."C1"<=:N2 AND "T3"."C1">=:N1))                      
   5 - access("T1"."C1">=:N1 AND "T1"."C1"<=:N2)

Same execution plan as we saw earlier, with the same cardinality estimates due to bind variable peeking, except now there is a FILTER operation AT ID 1 with a predicate that states that the N1 bind variable must be less than or equal to the N2 bind variable – this is an automatically generated predicate caused by the BETWEEN syntax in the SQL statement.

Now we change the value of the second bind variable to a much larger value:

EXEC :N2:=500000

SELECT /*+ GATHER_PLAN_STATISTICS */
  T3.C1,
  SUBSTR(T1.C2,1,10) C2
FROM
  T3,
  T1
WHERE
  T1.C1=T3.C1
  AND T1.C1 BETWEEN :N1 AND :N2;

SELECT
  *
FROM
  TABLE(DBMS_XPLAN.DISPLAY_CURSOR(NULL,NULL,'ALLSTATS LAST'));

SQL_ID  cvq22z77c8fww, child number 0
-------------------------------------
SELECT /*+ GATHER_PLAN_STATISTICS */   T3.C1,   SUBSTR(T1.C2,1,10) C2   
FROM   T3,   T1 WHERE   T1.C1=T3.C1   AND T1.C1 BETWEEN :N1 AND :N2     

Plan hash value: 744086632          

--------------------------------------------------------------------------------------------------------------------------------------------                       
| Id  | Operation                     | Name         | Starts | E-Rows | A-Rows |   A-Time   | Buffers | Reads  |  OMem |  1Mem | Used-Mem |                       
--------------------------------------------------------------------------------------------------------------------------------------------                       
|   0 | SELECT STATEMENT              |              |      1 |        |    500K|00:00:08.01 |     123K|  12985 |       |       |          |                       
|*  1 |  FILTER                       |              |      1 |        |    500K|00:00:08.01 |     123K|  12985 |       |       |          |                       
|*  2 |   HASH JOIN                   |              |      1 |      9 |    500K|00:00:07.72 |     123K|  12985 |    15M|  3723K|   23M (0)|                       
|*  3 |    TABLE ACCESS FULL          | T3           |      1 |     10 |    500K|00:00:00.11 |   37164 |      0 |       |       |          |                       
|   4 |    TABLE ACCESS BY INDEX ROWID| T1           |      1 |     10 |    500K|00:00:06.72 |   86064 |  12985 |       |       |          |                       
|*  5 |     INDEX RANGE SCAN          | SYS_C0017307 |      1 |     10 |    500K|00:00:00.43 |   34211 |    634 |       |       |          |                       
--------------------------------------------------------------------------------------------------------------------------------------------                       

Predicate Information (identified by operation id):                     
---------------------------------------------------                      

   1 - filter(:N1<=:N2)             
   2 - access("T1"."C1"="T3"."C1")  
   3 - filter(("T3"."C1"<=:N2 AND "T3"."C1">=:N1))                      
   5 - access("T1"."C1">=:N1 AND "T1"."C1"<=:N2)

In the above, notice that there was no hard parse (same SQL_ID and child number as we saw earlier), and the E-Rows column is the same for the two DBMS_XPLAN outputs.  The Used-Tmp column was not displayed (11.2.0.1 had a larger value for PGA_AGGREGATE_TARGET specified).  Let’s repeat the test with the altered OPTIMIZER_MODE:

EXEC :N2:=10
ALTER SESSION SET OPTIMIZER_MODE='FIRST_ROWS_1';

SELECT /*+ GATHER_PLAN_STATISTICS */
  T3.C1,
  SUBSTR(T1.C2,1,10) C2
FROM
  T3,
  T1
WHERE
  T1.C1=T3.C1
  AND T1.C1 BETWEEN :N1 AND :N2;

SELECT
  *
FROM
  TABLE(DBMS_XPLAN.DISPLAY_CURSOR(NULL,NULL,'ALLSTATS LAST'));

SQL_ID  cvq22z77c8fww, child number 1
-------------------------------------
SELECT /*+ GATHER_PLAN_STATISTICS */   T3.C1,   SUBSTR(T1.C2,1,10) C2   
FROM   T3,   T1 WHERE   T1.C1=T3.C1   AND T1.C1 BETWEEN :N1 AND :N2     

Plan hash value: 1340904442         

--------------------------------------------------------------------------------------------------------                       
| Id  | Operation                     | Name         | Starts | E-Rows | A-Rows |   A-Time   | Buffers |                       
--------------------------------------------------------------------------------------------------------                       
|   0 | SELECT STATEMENT              |              |      1 |        |     10 |00:00:00.01 |   37189 |                       
|*  1 |  FILTER                       |              |      1 |        |     10 |00:00:00.01 |   37189 |                       
|   2 |   NESTED LOOPS                |              |      1 |        |     10 |00:00:00.01 |   37189 |                       
|   3 |    NESTED LOOPS               |              |      1 |      2 |     10 |00:00:00.01 |   37179 |                       
|*  4 |     TABLE ACCESS FULL         | T3           |      1 |      7 |     10 |00:00:00.01 |   37165 |                       
|*  5 |     INDEX UNIQUE SCAN         | SYS_C0017307 |     10 |      1 |     10 |00:00:00.01 |      14 |                       
|   6 |    TABLE ACCESS BY INDEX ROWID| T1           |     10 |      1 |     10 |00:00:00.01 |      10 |                       
--------------------------------------------------------------------------------------------------------                       

Predicate Information (identified by operation id):                     
---------------------------------------------------                     
   1 - filter(:N1<=:N2)             
   4 - filter(("T3"."C1"<=:N2 AND "T3"."C1">=:N1))                      
   5 - access("T1"."C1"="T3"."C1")  
       filter(("T1"."C1"<=:N2 AND "T1"."C1">=:N1))

EXEC :N2:=500000

SELECT /*+ GATHER_PLAN_STATISTICS */
  T3.C1,
  SUBSTR(T1.C2,1,10) C2
FROM
  T3,
  T1
WHERE
  T1.C1=T3.C1
  AND T1.C1 BETWEEN :N1 AND :N2;

SELECT
  *
FROM
  TABLE(DBMS_XPLAN.DISPLAY_CURSOR(NULL,NULL,'ALLSTATS LAST'));

SQL_ID  cvq22z77c8fww, child number 1
-------------------------------------
SELECT /*+ GATHER_PLAN_STATISTICS */   T3.C1,   SUBSTR(T1.C2,1,10) C2   
FROM   T3,   T1 WHERE   T1.C1=T3.C1   AND T1.C1 BETWEEN :N1 AND :N2     

Plan hash value: 1340904442         

-----------------------------------------------------------------------------------------------------------------              
| Id  | Operation                     | Name         | Starts | E-Rows | A-Rows |   A-Time   | Buffers | Reads  |              
-----------------------------------------------------------------------------------------------------------------              
|   0 | SELECT STATEMENT              |              |      1 |        |    500K|00:00:03.77 |     782K|      1 |              
|*  1 |  FILTER                       |              |      1 |        |    500K|00:00:03.77 |     782K|      1 |              
|   2 |   NESTED LOOPS                |              |      1 |        |    500K|00:00:03.52 |     782K|      1 |              
|   3 |    NESTED LOOPS               |              |      1 |      2 |    500K|00:00:02.00 |     282K|      1 |              
|*  4 |     TABLE ACCESS FULL         | T3           |      1 |      7 |    500K|00:00:00.39 |   70498 |      0 |              
|*  5 |     INDEX UNIQUE SCAN         | SYS_C0017307 |    500K|      1 |    500K|00:00:00.95 |     212K|      1 |              
|   6 |    TABLE ACCESS BY INDEX ROWID| T1           |    500K|      1 |    500K|00:00:00.86 |     500K|      0 |              
-----------------------------------------------------------------------------------------------------------------              

Predicate Information (identified by operation id):                     
---------------------------------------------------                     
   1 - filter(:N1<=:N2)             
   4 - filter(("T3"."C1"<=:N2 AND "T3"."C1">=:N1))                      
   5 - access("T1"."C1"="T3"."C1")  
       filter(("T1"."C1"<=:N2 AND "T1"."C1">=:N1))

3.77 seconds to execute the SQL statement with OPTIMIZER_MODE set to FIRST_ROWS_1 and 8.01 seconds with OPTIMIZER_MODE set to ALL_ROWS (and 0.01 seconds compared to 0.07 seconds for the execution retrieving 10 rows).  Obviously, this means that we should be running with OPTIMIZER_MODE set to FIRST_ROWS_1 if we want to optimize performance, right?  Well, in short No.  Maybe this will be something that will be investigated in a later blog article.

Now, turning to the unanalyzed tables.  We modify the original SQL statement using bind variables to point to the two tables without up-to-date statistics on the tables and their indexes:

EXEC :N2:=10
ALTER SESSION SET OPTIMIZER_MODE='ALL_ROWS';

SELECT /*+ GATHER_PLAN_STATISTICS */
  T4.C1,
  SUBSTR(T2.C2,1,10) C2
FROM
  T4,
  T2
WHERE
  T2.C1=T4.C1
  AND T2.C1 BETWEEN :N1 AND :N2;

SELECT
  *
FROM
  TABLE(DBMS_XPLAN.DISPLAY_CURSOR(NULL,NULL,'ALLSTATS LAST'));

SQL_ID  94bv1jwkzcc38, child number 0
-------------------------------------
SELECT /*+ GATHER_PLAN_STATISTICS */   T4.C1,   SUBSTR(T2.C2,1,10) C2   
FROM   T4,   T2 WHERE   T2.C1=T4.C1   AND T2.C1 BETWEEN :N1 AND :N2     

Plan hash value: 2134503202         

--------------------------------------------------------------------------------------------------------------------------------------------                       
| Id  | Operation                     | Name         | Starts | E-Rows | A-Rows |   A-Time   | Buffers | Reads  |  OMem |  1Mem | Used-Mem |                       
--------------------------------------------------------------------------------------------------------------------------------------------                       
|   0 | SELECT STATEMENT              |              |      1 |        |     10 |00:00:00.01 |   37169 |  37128 |       |       |          |                       
|*  1 |  FILTER                       |              |      1 |        |     10 |00:00:00.01 |   37169 |  37128 |       |       |          |                       
|*  2 |   HASH JOIN                   |              |      1 |     10 |     10 |00:00:00.01 |   37169 |  37128 |   711K|   711K| 1116K (0)|                       
|   3 |    TABLE ACCESS BY INDEX ROWID| T2           |      1 |     10 |     10 |00:00:00.01 |       4 |      1 |       |       |          |                       
|*  4 |     INDEX RANGE SCAN          | SYS_C0017308 |      1 |     10 |     10 |00:00:00.01 |       3 |      0 |       |       |          |                       
|*  5 |    TABLE ACCESS FULL          | T4           |      1 |   1855 |     10 |00:00:00.01 |   37165 |  37127 |       |       |          |                       
--------------------------------------------------------------------------------------------------------------------------------------------                       

Predicate Information (identified by operation id):                     
---------------------------------------------------                     
   1 - filter(:N1<=:N2)             
   2 - access("T2"."C1"="T4"."C1")  
   4 - access("T2"."C1">=:N1 AND "T2"."C1"<=:N2)                        
   5 - filter(("T4"."C1">=:N1 AND "T4"."C1"<=:N2))                      

Note                                
-----                               
   - dynamic sampling used for this statement (level=2)

The only change here is that Oracle is now estimating that 10 rows will be returned rather than the 9 we saw earlier, and the note below the predicate information heading that states that dynamic sampling at level 2 was used, oh – and the order of the row sources directly below the HASH JOIN line in the plan has changed just like on Oracle 10.2.0.2 (is this a problem?).  Maybe dynamic sampling will be a topic for another blog article, but the topic is discussed in various books and articles on the Internet.

ALTER SESSION SET OPTIMIZER_MODE='FIRST_ROWS_1';

SELECT /*+ GATHER_PLAN_STATISTICS */
  T4.C1,
  SUBSTR(T2.C2,1,10) C2
FROM
  T4,
  T2
WHERE
  T2.C1=T4.C1
  AND T2.C1 BETWEEN :N1 AND :N2;

SELECT
  *
FROM
  TABLE(DBMS_XPLAN.DISPLAY_CURSOR(NULL,NULL,'ALLSTATS LAST'));

SQL_ID  94bv1jwkzcc38, child number 1
-------------------------------------
SELECT /*+ GATHER_PLAN_STATISTICS */   T4.C1,   SUBSTR(T2.C2,1,10) C2   
FROM   T4,   T2 WHERE   T2.C1=T4.C1   AND T2.C1 BETWEEN :N1 AND :N2     

Plan hash value: 2134503202         

--------------------------------------------------------------------------------------------------------------------------------------------                       
| Id  | Operation                     | Name         | Starts | E-Rows | A-Rows |   A-Time   | Buffers | Reads  |  OMem |  1Mem | Used-Mem |                       
--------------------------------------------------------------------------------------------------------------------------------------------                       
|   0 | SELECT STATEMENT              |              |      1 |        |     10 |00:00:00.01 |   37169 |  37129 |       |       |          |                       
|*  1 |  FILTER                       |              |      1 |        |     10 |00:00:00.01 |   37169 |  37129 |       |       |          |                       
|*  2 |   HASH JOIN                   |              |      1 |     10 |     10 |00:00:00.01 |   37169 |  37129 |   711K|   711K| 1147K (0)|                       
|   3 |    TABLE ACCESS BY INDEX ROWID| T2           |      1 |     10 |     10 |00:00:00.01 |       4 |      1 |       |       |          |                       
|*  4 |     INDEX RANGE SCAN          | SYS_C0017308 |      1 |     10 |     10 |00:00:00.01 |       3 |      0 |       |       |          |                       
|*  5 |    TABLE ACCESS FULL          | T4           |      1 |   1855 |     10 |00:00:00.01 |   37165 |  37128 |       |       |          |                       
--------------------------------------------------------------------------------------------------------------------------------------------                       

Predicate Information (identified by operation id):                     
---------------------------------------------------                     
   1 - filter(:N1<=:N2)             
   2 - access("T2"."C1"="T4"."C1")  
   4 - access("T2"."C1">=:N1 AND "T2"."C1"<=:N2)                        
   5 - filter(("T4"."C1">=:N1 AND "T4"."C1"<=:N2))                      

Note                                
-----                               
   - dynamic sampling used for this statement (level=2)

OK, this plan changed a bit from when the SQL statement referenced tables T1 and T3.  The execution plan is no longer using a nested loops join – in fact it is using the same plan as was used when the OPTIMIZER_MODE was set to ALL_ROWS (just like on Oracle 10.2.0.2).

Oracle 9i and earlier Oracle releases had a default OPTIMIZER_MODE of CHOOSE, so let’s see what happens when we use that optimizer mode with the same two tables:

ALTER SESSION SET OPTIMIZER_MODE='CHOOSE';

SELECT /*+ GATHER_PLAN_STATISTICS */
  T4.C1,
  SUBSTR(T2.C2,1,10) C2
FROM
  T4,
  T2
WHERE
  T2.C1=T4.C1
  AND T2.C1 BETWEEN :N1 AND :N2;

SELECT
  *
FROM
  TABLE(DBMS_XPLAN.DISPLAY_CURSOR(NULL,NULL,'ALLSTATS LAST'));

SQL_ID  94bv1jwkzcc38, child number 2
-------------------------------------
SELECT /*+ GATHER_PLAN_STATISTICS */   T4.C1,   SUBSTR(T2.C2,1,10) C2   
FROM   T4,   T2 WHERE   T2.C1=T4.C1   AND T2.C1 BETWEEN :N1 AND :N2     

Plan hash value: 1136565161         

-------------------------------------------------------------------------------------------------------                        
| Id  | Operation                    | Name         | Starts | A-Rows |   A-Time   | Buffers | Reads  |                        
-------------------------------------------------------------------------------------------------------                        
|   0 | SELECT STATEMENT             |              |      1 |     10 |00:00:00.03 |     386K|  39012 |                        
|   1 |  NESTED LOOPS                |              |      1 |     10 |00:00:00.03 |     386K|  39012 |                        
|   2 |   NESTED LOOPS               |              |      1 |     10 |00:00:00.03 |     386K|  39011 |                        
|   3 |    TABLE ACCESS FULL         | T4           |      1 |   1000K|00:00:00.38 |   37165 |  37133 |                        
|*  4 |    INDEX UNIQUE SCAN         | SYS_C0017308 |   1000K|     10 |00:00:02.30 |     348K|   1878 |                        
|   5 |   TABLE ACCESS BY INDEX ROWID| T2           |     10 |     10 |00:00:00.01 |      10 |      1 |                        
-------------------------------------------------------------------------------------------------------                        

Predicate Information (identified by operation id):                     
---------------------------------------------------                     
   4 - access("T2"."C1"="T4"."C1")  
       filter(("T2"."C1"<=:N2 AND "T2"."C1">=:N1))                      

Note                                
-----                               
   - rule based optimizer used (consider using cbo)

Note that the Note section indicates that the rule based optimizer was used (just like with Oracle 10.2.0.2), even though the documentation for Oracle 10.2 states that as of Oracle 10.1 the RULE based optimizer is no longer supported.  Also note that the execution plan is now using a nested loops join, the FILTER operation no longer appears, and the full table scan is again first joined with the index for the other table, just as it was when the OPTIMIZER_MODE was set to FIRST_ROWS_1 and the query accessed tables T1 and T3.

Let’s say that we are bored, and did not read chapter 15 by Pete Finnigan in the “Expert Oracle Practices” book… assume that column C1 contains a credit card number.  Now for an experiment, we will retrieve all child cursors for SQL_ID cvq22z77c8fww with the bind variables that were submitted on the initial hard parse - be careful with who has access to this feature in a production environment, as it could expose sensitive information:

SELECT
  *
FROM
  TABLE(DBMS_XPLAN.DISPLAY_CURSOR('cvq22z77c8fww',NULL,'ALLSTATS LAST +PEEKED_BINDS'));

SQL_ID  cvq22z77c8fww, child number 0
-------------------------------------
SELECT /*+ GATHER_PLAN_STATISTICS */   T3.C1,   SUBSTR(T1.C2,1,10) C2   
FROM   T3,   T1 WHERE   T1.C1=T3.C1   AND T1.C1 BETWEEN :N1 AND :N2     

Plan hash value: 744086632          

--------------------------------------------------------------------------------------------------------------------------------------------
| Id  | Operation                     | Name         | Starts | E-Rows | A-Rows |   A-Time   | Buffers | Reads  |  OMem |  1Mem | Used-Mem |
--------------------------------------------------------------------------------------------------------------------------------------------
|   0 | SELECT STATEMENT              |              |      1 |        |    500K|00:00:08.01 |     123K|  12985 |       |       |          |
|*  1 |  FILTER                       |              |      1 |        |    500K|00:00:08.01 |     123K|  12985 |       |       |          |
|*  2 |   HASH JOIN                   |              |      1 |      9 |    500K|00:00:07.72 |     123K|  12985 |    15M|  3723K|   23M (0)|
|*  3 |    TABLE ACCESS FULL          | T3           |      1 |     10 |    500K|00:00:00.11 |   37164 |      0 |       |       |          |
|   4 |    TABLE ACCESS BY INDEX ROWID| T1           |      1 |     10 |    500K|00:00:06.72 |   86064 |  12985 |       |       |          |
|*  5 |     INDEX RANGE SCAN          | SYS_C0017307 |      1 |     10 |    500K|00:00:00.43 |   34211 |    634 |       |       |          |
--------------------------------------------------------------------------------------------------------------------------------------------

Peeked Binds (identified by position):
--------------------------------------

   1 - (NUMBER): 1                  
   2 - (NUMBER): 10                 

Predicate Information (identified by operation id):                     
---------------------------------------------------                     
   1 - filter(:N1<=:N2)             
   2 - access("T1"."C1"="T3"."C1")  
   3 - filter(("T3"."C1"<=:N2 AND "T3"."C1">=:N1))                      
   5 - access("T1"."C1">=:N1 AND "T1"."C1"<=:N2)                        

-

SQL_ID  cvq22z77c8fww, child number 1
-------------------------------------
SELECT /*+ GATHER_PLAN_STATISTICS */   T3.C1,   SUBSTR(T1.C2,1,10) C2   
FROM   T3,   T1 WHERE   T1.C1=T3.C1   AND T1.C1 BETWEEN :N1 AND :N2     

Plan hash value: 1340904442         

-----------------------------------------------------------------------------------------------------------------
| Id  | Operation                     | Name         | Starts | E-Rows | A-Rows |   A-Time   | Buffers | Reads  |
-----------------------------------------------------------------------------------------------------------------
|   0 | SELECT STATEMENT              |              |      1 |        |    500K|00:00:03.77 |     782K|      1 |
|*  1 |  FILTER                       |              |      1 |        |    500K|00:00:03.77 |     782K|      1 |
|   2 |   NESTED LOOPS                |              |      1 |        |    500K|00:00:03.52 |     782K|      1 |
|   3 |    NESTED LOOPS               |              |      1 |      2 |    500K|00:00:02.00 |     282K|      1 |
|*  4 |     TABLE ACCESS FULL         | T3           |      1 |      7 |    500K|00:00:00.39 |   70498 |      0 |
|*  5 |     INDEX UNIQUE SCAN         | SYS_C0017307 |    500K|      1 |    500K|00:00:00.95 |     212K|      1 |
|   6 |    TABLE ACCESS BY INDEX ROWID| T1           |    500K|      1 |    500K|00:00:00.86 |     500K|      0 |
-----------------------------------------------------------------------------------------------------------------

Peeked Binds (identified by position):
--------------------------------------

   1 - (NUMBER): 1                  
   2 - (NUMBER): 10                 

Predicate Information (identified by operation id):                     
---------------------------------------------------                     
   1 - filter(:N1<=:N2)             
   4 - filter(("T3"."C1"<=:N2 AND "T3"."C1">=:N1))                      
   5 - access("T1"."C1"="T3"."C1")  
       filter(("T1"."C1"<=:N2 AND "T1"."C1">=:N1))

To learn more about DBMS_XPLAN.DISPLAY_CURSOR, see the documentation.

So, what if we want to know why the child cursors were created?  We could do something like this:

DESC V$SQL_SHARED_CURSOR

SET LINESIZE 200
SET HEADING ON
BREAK ON SQL_ID SKIP 1 

SELECT
  *
FROM
  V$SQL_SHARED_CURSOR
WHERE
  SQL_ID='94bv1jwkzcc38';

SQL_ID        ADDRESS          CHILD_ADDRESS    CHILD_NUMBER USOOSLFEBPISTABDLTBIIRLIOEMUTNFAITDLDBPCSCPTMBMROPMFLPLAFLRLHPB
------------- ---------------- ---------------- ------------ ---------------------------------------------------------------
94bv1jwkzcc38 0000000257BD5498 0000000257E2E5B0            0 NNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNN
              0000000257BD5498 0000000257DC8F18            1 NNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNYNNNNNNNNNNNNNN
              0000000257BD5498 0000000257C8C3F8            2 NNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNYNNNNNNNNNNNNNN

The above shows that the child cursors were created because of an optimizer mode mismatch (yes, we changed the OPTIMIZER_MODE).  We could also check the bind variable definitions (not needed in this case because we used the undocumented PEEKED_BINDS format parameter with DBMS_XPLAN to see most of this information):

SELECT
  S.CHILD_NUMBER CN,
  SBM.*
FROM
  V$SQL_BIND_METADATA SBM,
  V$SQL S
WHERE
  S.SQL_ID='94bv1jwkzcc38'
  AND S.CHILD_ADDRESS=SBM.ADDRESS
ORDER BY
  S.CHILD_NUMBER,
  SBM.POSITION;

CN ADDRESS            POSITION   DATATYPE MAX_LENGTH  ARRAY_LEN BIND_NAME
-- ---------------- ---------- ---------- ---------- ---------- ---------
 0 0000000257E2E5B0          1          2         22          0 N1      
 0 0000000257E2E5B0          2          2         22          0 N2      
 1 0000000257DC8F18          1          2         22          0 N1      
 1 0000000257DC8F18          2          2         22          0 N2      
 2 0000000257C8C3F8          1          2         22          0 N1      
 2 0000000257C8C3F8          2          2         22          0 N2      

OK, now that we have moved off on a tangent, let’s return again to the topic of viewing execution plans.  The above examples show the actual execution plan that was used, which may be different from that produced by explain plan.  So, for fun, let’s look at the EXPLAIN PLAN FOR syntax (DBMS_XPLAN.DISPLAY is valid on Oracle 9.2.0.1 and higher):

ALTER SYSTEM FLUSH SHARED_POOL;

ALTER SESSION SET OPTIMIZER_MODE='ALL_ROWS';

EXPLAIN PLAN FOR
SELECT
  T3.C1,
  SUBSTR(T1.C2,1,10) C2
FROM
  T3,
  T1
WHERE
  T1.C1=T3.C1
  AND T1.C1 BETWEEN 1 AND 10;

Explained.

SELECT
  *
FROM
  TABLE(DBMS_XPLAN.DISPLAY());

Plan hash value: 985299768          

---------------------------------------------------------------------------------------------
| Id  | Operation                    | Name         | Rows  | Bytes | Cost (%CPU)| Time     |
---------------------------------------------------------------------------------------------
|   0 | SELECT STATEMENT             |              |     9 |  2394 | 10219   (1)| 00:02:03 |
|*  1 |  HASH JOIN                   |              |     9 |  2394 | 10219   (1)| 00:02:03 |
|*  2 |   TABLE ACCESS FULL          | T3           |    10 |    50 | 10214   (1)| 00:02:03 |
|   3 |   TABLE ACCESS BY INDEX ROWID| T1           |    10 |  2610 |     4   (0)| 00:00:01 |
|*  4 |    INDEX RANGE SCAN          | SYS_C0017307 |    10 |       |     3   (0)| 00:00:01 |
---------------------------------------------------------------------------------------------

Predicate Information (identified by operation id):                     
---------------------------------------------------                     
   1 - access("T1"."C1"="T3"."C1")  
   2 - filter("T3"."C1"<=10 AND "T3"."C1">=1)                           
   4 - access("T1"."C1">=1 AND "T1"."C1"<=10)

The above plan appears to be identical to that of the first of the actual plans.  Now a test with bind variables:

VARIABLE N1 NUMBER
VARIABLE N2 NUMBER
EXEC :N1:=1
EXEC :N2:=10

EXPLAIN PLAN FOR
SELECT
  T3.C1,
  SUBSTR(T1.C2,1,10) C2
FROM
  T3,
  T1
WHERE
  T1.C1=T3.C1
  AND T1.C1 BETWEEN :N1 AND :N2;

Explained.

SELECT
  *
FROM
  TABLE(DBMS_XPLAN.DISPLAY());

Plan hash value: 744086632          

----------------------------------------------------------------------------------------------
| Id  | Operation                     | Name         | Rows  | Bytes | Cost (%CPU)| Time     |
----------------------------------------------------------------------------------------------
|   0 | SELECT STATEMENT              |              |  2499 |   649K| 10397   (1)| 00:02:05 |
|*  1 |  FILTER                       |              |       |       |            |          |
|*  2 |   HASH JOIN                   |              |  2499 |   649K| 10397   (1)| 00:02:05 |
|*  3 |    TABLE ACCESS FULL          | T3           |  2500 | 12500 | 10219   (1)| 00:02:03 |
|   4 |    TABLE ACCESS BY INDEX ROWID| T1           |  2500 |   637K|   178   (0)| 00:00:03 |
|*  5 |     INDEX RANGE SCAN          | SYS_C0017307 |  4500 |       |    11   (0)| 00:00:01 |
----------------------------------------------------------------------------------------------

Predicate Information (identified by operation id):                     
---------------------------------------------------                     
   1 - filter(TO_NUMBER(:N1)<=TO_NUMBER(:N2))                           
   2 - access("T1"."C1"="T3"."C1")  
   3 - filter("T3"."C1">=TO_NUMBER(:N1) AND "T3"."C1"<=TO_NUMBER(:N2))  
   5 - access("T1"."C1">=TO_NUMBER(:N1) AND "T1"."C1"<=TO_NUMBER(:N2))  

Notice in the above that there are TO_NUMBER entries surrounding each of the bind variables in the Predicate Information section, even though those bind variables were declared as a NUMBER data type.  The cost has also increased a bit, and the estimated number of rows jumped from 9 to 2499 (bind peeking did not take place).

Let’s use AUTOTRACE to see the execution plan (AUTOTRACE starting in Oracle 10.1.0.1 uses DBMS_XPLAN to output the formatted execution plan).

SET AUTOTRACE TRACEONLY EXPLAIN

SELECT
  T3.C1,
  SUBSTR(T1.C2,1,10) C2
FROM
  T3,
  T1
WHERE
  T1.C1=T3.C1
  AND T1.C1 BETWEEN :N1 AND :N2;

Plan hash value: 744086632          

----------------------------------------------------------------------------------------------
| Id  | Operation                     | Name         | Rows  | Bytes | Cost (%CPU)| Time     |
----------------------------------------------------------------------------------------------
|   0 | SELECT STATEMENT              |              |  2499 |   649K| 10397   (1)| 00:02:05 |
|*  1 |  FILTER                       |              |       |       |            |          |
|*  2 |   HASH JOIN                   |              |  2499 |   649K| 10397   (1)| 00:02:05 |
|*  3 |    TABLE ACCESS FULL          | T3           |  2500 | 12500 | 10219   (1)| 00:02:03 |
|   4 |    TABLE ACCESS BY INDEX ROWID| T1           |  2500 |   637K|   178   (0)| 00:00:03 |
|*  5 |     INDEX RANGE SCAN          | SYS_C0017307 |  4500 |       |    11   (0)| 00:00:01 |
----------------------------------------------------------------------------------------------

Predicate Information (identified by operation id):                     
---------------------------------------------------                     
   1 - filter(TO_NUMBER(:N1)<=TO_NUMBER(:N2))                           
   2 - access("T1"."C1"="T3"."C1")  
   3 - filter("T3"."C1">=TO_NUMBER(:N1) AND "T3"."C1"<=TO_NUMBER(:N2))  
   5 - access("T1"."C1">=TO_NUMBER(:N1) AND "T1"."C1"<=TO_NUMBER(:N2))  

OK, the same as the previous example on Oracle 10.1.0.1 and above, complete with the incorrect Predicate Information section.  Again, displaying the runtime statistics and explain plan:

SET AUTOTRACE TRACEONLY STATISTICS EXPLAIN

SELECT
  T3.C1,
  SUBSTR(T1.C2,1,10) C2
FROM
  T3,
  T1
WHERE
  T1.C1=T3.C1
  AND T1.C1 BETWEEN :N1 AND :N2;

10 rows selected.

Execution Plan
----------------------------------------------------------              
Plan hash value: 744086632          

----------------------------------------------------------------------------------------------
| Id  | Operation                     | Name         | Rows  | Bytes | Cost (%CPU)| Time     |
----------------------------------------------------------------------------------------------
|   0 | SELECT STATEMENT              |              |  2499 |   649K| 10397   (1)| 00:02:05 |
|*  1 |  FILTER                       |              |       |       |            |          |
|*  2 |   HASH JOIN                   |              |  2499 |   649K| 10397   (1)| 00:02:05 |
|*  3 |    TABLE ACCESS FULL          | T3           |  2500 | 12500 | 10219   (1)| 00:02:03 |
|   4 |    TABLE ACCESS BY INDEX ROWID| T1           |  2500 |   637K|   178   (0)| 00:00:03 |
|*  5 |     INDEX RANGE SCAN          | SYS_C0017307 |  4500 |       |    11   (0)| 00:00:01 |
----------------------------------------------------------------------------------------------

Predicate Information (identified by operation id):                     
---------------------------------------------------                     
   1 - filter(TO_NUMBER(:N1)<=TO_NUMBER(:N2))                           
   2 - access("T1"."C1"="T3"."C1")  
   3 - filter("T3"."C1">=TO_NUMBER(:N1) AND "T3"."C1"<=TO_NUMBER(:N2))  
   5 - access("T1"."C1">=TO_NUMBER(:N1) AND "T1"."C1"<=TO_NUMBER(:N2))  

Statistics
----------------------------------------------------------              
          0  recursive calls        
          0  db block gets          
      37170  consistent gets        
       7760  physical reads         
          0  redo size              
        812  bytes sent via SQL*Net to client                           
        523  bytes received via SQL*Net from client                     
          2  SQL*Net roundtrips to/from client                          
          0  sorts (memory)         
          0  sorts (disk)           
         10  rows processed

Note that the above plan is not necessarily the actual plan, even though we are looking at the actual runtime statistics.  This could be confusing since we are seeing a rough guess for an execution plan with the actual execution statistics.

For more information about Using EXPLAIN PLAN, see the documentation.

Now, another test.  This time we will instruct Oracle to write the actual execution plan to a trace file every time Oracle must perform a hard parse.  We will force a hard parse by adding a comment to the SQL statement:

ALTER SESSION SET TRACEFILE_IDENTIFIER = '10132_HARD_PARSE';
ALTER SESSION SET EVENTS '10132 TRACE NAME CONTEXT FOREVER, LEVEL 1';

SELECT /* TEST */
  T3.C1,
  SUBSTR(T1.C2,1,10) C2
FROM
  T3,
  T1
WHERE
  T1.C1=T3.C1
  AND T1.C1 BETWEEN :N1 AND :N2;

ALTER SESSION SET EVENTS '10132 TRACE NAME CONTEXT OFF';

If we take a look at the output in the trace file, we might see something like this:

user_id=68 user_name=TESTUSER module=SQL*Plus action=
sql_id=3g3fc5qyju0j3 plan_hash_value=744086632 problem_type=3
----- Current SQL Statement for this session (sql_id=3g3fc5qyju0j3) -----
SELECT /* TEST */
  T3.C1,
  SUBSTR(T1.C2,1,10) C2
FROM
  T3,
  T1
WHERE
  T1.C1=T3.C1
  AND T1.C1 BETWEEN :N1 AND :N2
sql_text_length=119
sql=SELECT /* TEST */
  T3.C1,
  SUBSTR(T1.C2,1,10) C2
FROM
  T3,
  T1
WHERE
  T1.C1=T3.C1
  AND T1.C1 BETWEEN :N1 AND :N2
----- Explain Plan Dump -----
----- Plan Table -----

============
Plan Table
============
-----------------------------------------------------+-----------------------------------+
| Id  | Operation                      | Name        | Rows  | Bytes | Cost  | Time      |
-----------------------------------------------------+-----------------------------------+
| 0   | SELECT STATEMENT               |             |       |       |   10K |           |
| 1   |  FILTER                        |             |       |       |       |           |
| 2   |   HASH JOIN                    |             |     9 |  2394 |   10K |  00:02:03 |
| 3   |    TABLE ACCESS FULL           | T3          |    10 |    50 |   10K |  00:02:03 |
| 4   |    TABLE ACCESS BY INDEX ROWID | T1          |    10 |  2610 |     4 |  00:00:01 |
| 5   |     INDEX RANGE SCAN           | SYS_C0017307|    10 |       |     3 |  00:00:01 |
-----------------------------------------------------+-----------------------------------+
Predicate Information:
----------------------
1 - filter(:N1<=:N2)
2 - access("T1"."C1"="T3"."C1")
3 - filter(("T3"."C1"<=:N2 AND "T3"."C1">=:N1))
5 - access("T1"."C1">=:N1 AND "T1"."C1"<=:N2)

Content of other_xml column
===========================
  db_version     : 11.2.0.1
  parse_schema   : TESTUSER

  plan_hash      : 744086632
  plan_hash_2    : 3461135235
Peeked Binds
============
  Bind variable information
    position=1
    datatype(code)=2
    datatype(string)=NUMBER
    precision=0
    scale=0
    max length=22
    value=1
  Bind variable information
    position=2
    datatype(code)=2
    datatype(string)=NUMBER
    precision=0
    scale=0
    max length=22
    value=10
  Outline Data:
  /*+
    BEGIN_OUTLINE_DATA
      IGNORE_OPTIM_EMBEDDED_HINTS
      OPTIMIZER_FEATURES_ENABLE('11.2.0.1')
      DB_VERSION('11.2.0.1')
      ALL_ROWS
      OUTLINE_LEAF(@"SEL$1")
      FULL(@"SEL$1" "T3"@"SEL$1")
      INDEX_RS_ASC(@"SEL$1" "T1"@"SEL$1" ("T1"."C1"))
      LEADING(@"SEL$1" "T3"@"SEL$1" "T1"@"SEL$1")
      USE_HASH(@"SEL$1" "T1"@"SEL$1")
    END_OUTLINE_DATA
  */

Optimizer state dump:
Compilation Environment Dump
optimizer_mode_hinted               = false
optimizer_features_hinted           = 0.0.0
parallel_execution_enabled          = true
parallel_query_forced_dop           = 0
parallel_dml_forced_dop             = 0
parallel_ddl_forced_degree          = 0
parallel_ddl_forced_instances       = 0
_query_rewrite_fudge                = 90
optimizer_features_enable           = 11.2.0.1
_optimizer_search_limit             = 5
cpu_count                           = 8
active_instance_count               = 1
hash_area_size                      = 131072
bitmap_merge_area_size              = 1048576
sort_area_size                      = 65536
sort_area_retained_size             = 0
_sort_elimination_cost_ratio        = 0
_optimizer_block_size               = 8192
_sort_multiblock_read_count         = 2
_hash_multiblock_io_count           = 0
_db_file_optimizer_read_count       = 8
_optimizer_max_permutations         = 2000
pga_aggregate_target                = 1843200 KB
_pga_max_size                       = 368640 KB
_query_rewrite_maxdisjunct          = 257
_smm_auto_min_io_size               = 56 KB
_smm_auto_max_io_size               = 248 KB
_smm_min_size                       = 1024 KB
_smm_max_size                       = 184320 KB
_smm_px_max_size                    = 921600 KB
_cpu_to_io                          = 0
_optimizer_undo_cost_change         = 11.2.0.1
parallel_query_mode                 = enabled
parallel_dml_mode                   = disabled
parallel_ddl_mode                   = enabled
optimizer_mode                      = all_rows
sqlstat_enabled                     = false
_optimizer_percent_parallel         = 101
_always_anti_join                   = choose
_always_semi_join                   = choose
_optimizer_mode_force               = true
_partition_view_enabled             = true
_always_star_transformation         = false
_query_rewrite_or_error             = false
_hash_join_enabled                  = true
cursor_sharing                      = exact
_b_tree_bitmap_plans                = true
star_transformation_enabled         = false
_optimizer_cost_model               = choose
_new_sort_cost_estimate             = true
_complex_view_merging               = true
_unnest_subquery                    = true
_eliminate_common_subexpr           = true
_pred_move_around                   = true
_convert_set_to_join                = false
_push_join_predicate                = true
_push_join_union_view               = true
_fast_full_scan_enabled             = true
_optim_enhance_nnull_detection      = true
_parallel_broadcast_enabled         = true
_px_broadcast_fudge_factor          = 100
_ordered_nested_loop                = true
_no_or_expansion                    = false
optimizer_index_cost_adj            = 100
optimizer_index_caching             = 0
_system_index_caching               = 0
_disable_datalayer_sampling         = false
query_rewrite_enabled               = true
query_rewrite_integrity             = enforced
_query_cost_rewrite                 = true
_query_rewrite_2                    = true
_query_rewrite_1                    = true
_query_rewrite_expression           = true
_query_rewrite_jgmigrate            = true
_query_rewrite_fpc                  = true
_query_rewrite_drj                  = true
_full_pwise_join_enabled            = true
_partial_pwise_join_enabled         = true
_left_nested_loops_random           = true
_improved_row_length_enabled        = true
_index_join_enabled                 = true
_enable_type_dep_selectivity        = true
_improved_outerjoin_card            = true
_optimizer_adjust_for_nulls         = true
_optimizer_degree                   = 0
_use_column_stats_for_function      = true
_subquery_pruning_enabled           = true
_subquery_pruning_mv_enabled        = false
_or_expand_nvl_predicate            = true
_like_with_bind_as_equality         = false
_table_scan_cost_plus_one           = true
_cost_equality_semi_join            = true
_default_non_equality_sel_check     = true
_new_initial_join_orders            = true
_oneside_colstat_for_equijoins      = true
_optim_peek_user_binds              = true
_minimal_stats_aggregation          = true
_force_temptables_for_gsets         = false
workarea_size_policy                = auto
_smm_auto_cost_enabled              = true
_gs_anti_semi_join_allowed          = true
_optim_new_default_join_sel         = true
optimizer_dynamic_sampling          = 2
_pre_rewrite_push_pred              = true
_optimizer_new_join_card_computation = true
_union_rewrite_for_gs               = yes_gset_mvs
_generalized_pruning_enabled        = true
_optim_adjust_for_part_skews        = true
_force_datefold_trunc               = false
statistics_level                    = typical
_optimizer_system_stats_usage       = true
skip_unusable_indexes               = true
_remove_aggr_subquery               = true
_optimizer_push_down_distinct       = 0
_dml_monitoring_enabled             = true
_optimizer_undo_changes             = false
_predicate_elimination_enabled      = true
_nested_loop_fudge                  = 100
_project_view_columns               = true
_local_communication_costing_enabled = true
_local_communication_ratio          = 50
_query_rewrite_vop_cleanup          = true
_slave_mapping_enabled              = true
_optimizer_cost_based_transformation = linear
_optimizer_mjc_enabled              = true
_right_outer_hash_enable            = true
_spr_push_pred_refspr               = true
_optimizer_cache_stats              = false
_optimizer_cbqt_factor              = 50
_optimizer_squ_bottomup             = true
_fic_area_size                      = 131072
_optimizer_skip_scan_enabled        = true
_optimizer_cost_filter_pred         = false
_optimizer_sortmerge_join_enabled   = true
_optimizer_join_sel_sanity_check    = true
_mmv_query_rewrite_enabled          = true
_bt_mmv_query_rewrite_enabled       = true
_add_stale_mv_to_dependency_list    = true
_distinct_view_unnesting            = false
_optimizer_dim_subq_join_sel        = true
_optimizer_disable_strans_sanity_checks = 0
_optimizer_compute_index_stats      = true
_push_join_union_view2              = true
_optimizer_ignore_hints             = false
_optimizer_random_plan              = 0
_query_rewrite_setopgrw_enable      = true
_optimizer_correct_sq_selectivity   = true
_disable_function_based_index       = false
_optimizer_join_order_control       = 3
_optimizer_cartesian_enabled        = true
_optimizer_starplan_enabled         = true
_extended_pruning_enabled           = true
_optimizer_push_pred_cost_based     = true
_optimizer_null_aware_antijoin      = true
_optimizer_extend_jppd_view_types   = true
_sql_model_unfold_forloops          = run_time
_enable_dml_lock_escalation         = false
_bloom_filter_enabled               = true
_update_bji_ipdml_enabled           = 0
_optimizer_extended_cursor_sharing  = udo
_dm_max_shared_pool_pct             = 1
_optimizer_cost_hjsmj_multimatch    = true
_optimizer_transitivity_retain      = true
_px_pwg_enabled                     = true
optimizer_secure_view_merging       = true
_optimizer_join_elimination_enabled = true
flashback_table_rpi                 = non_fbt
_optimizer_cbqt_no_size_restriction = true
_optimizer_enhanced_filter_push     = true
_optimizer_filter_pred_pullup       = true
_rowsrc_trace_level                 = 0
_simple_view_merging                = true
_optimizer_rownum_pred_based_fkr    = true
_optimizer_better_inlist_costing    = all
_optimizer_self_induced_cache_cost  = false
_optimizer_min_cache_blocks         = 10
_optimizer_or_expansion             = depth
_optimizer_order_by_elimination_enabled = true
_optimizer_outer_to_anti_enabled    = true
_selfjoin_mv_duplicates             = true
_dimension_skip_null                = true
_force_rewrite_enable               = false
_optimizer_star_tran_in_with_clause = true
_optimizer_complex_pred_selectivity = true
_optimizer_connect_by_cost_based    = true
_gby_hash_aggregation_enabled       = true
_globalindex_pnum_filter_enabled    = true
_px_minus_intersect                 = true
_fix_control_key                    = 0
_force_slave_mapping_intra_part_loads = false
_force_tmp_segment_loads            = false
_query_mmvrewrite_maxpreds          = 10
_query_mmvrewrite_maxintervals      = 5
_query_mmvrewrite_maxinlists        = 5
_query_mmvrewrite_maxdmaps          = 10
_query_mmvrewrite_maxcmaps          = 20
_query_mmvrewrite_maxregperm        = 512
_query_mmvrewrite_maxmergedcmaps    = 50
_query_mmvrewrite_maxqryinlistvals  = 500
_disable_parallel_conventional_load = false
_trace_virtual_columns              = false
_replace_virtual_columns            = true
_virtual_column_overload_allowed    = true
_kdt_buffering                      = true
_first_k_rows_dynamic_proration     = true
_optimizer_sortmerge_join_inequality = true
_optimizer_aw_stats_enabled         = true
_bloom_pruning_enabled              = true
result_cache_mode                   = MANUAL
_px_ual_serial_input                = true
_optimizer_skip_scan_guess          = false
_enable_row_shipping                = true
_row_shipping_threshold             = 80
_row_shipping_explain               = false
transaction_isolation_level         = read_commited
_optimizer_distinct_elimination     = true
_optimizer_multi_level_push_pred    = true
_optimizer_group_by_placement       = true
_optimizer_rownum_bind_default      = 10
_enable_query_rewrite_on_remote_objs = true
_optimizer_extended_cursor_sharing_rel = simple
_optimizer_adaptive_cursor_sharing  = true
_direct_path_insert_features        = 0
_optimizer_improve_selectivity      = true
optimizer_use_pending_statistics    = false
_optimizer_enable_density_improvements = true
_optimizer_aw_join_push_enabled     = true
_optimizer_connect_by_combine_sw    = true
_enable_pmo_ctas                    = 0
_optimizer_native_full_outer_join   = force
_bloom_predicate_enabled            = true
_optimizer_enable_extended_stats    = true
_is_lock_table_for_ddl_wait_lock    = 0
_pivot_implementation_method        = choose
optimizer_capture_sql_plan_baselines = false
optimizer_use_sql_plan_baselines    = true
_optimizer_star_trans_min_cost      = 0
_optimizer_star_trans_min_ratio     = 0
_with_subquery                      = OPTIMIZER
_optimizer_fkr_index_cost_bias      = 10
_optimizer_use_subheap              = true
parallel_degree_policy              = manual
parallel_degree                     = 0
parallel_min_time_threshold         = 10
_parallel_time_unit                 = 10
_optimizer_or_expansion_subheap     = true
_optimizer_free_transformation_heap = true
_optimizer_reuse_cost_annotations   = true
_result_cache_auto_size_threshold   = 100
_result_cache_auto_time_threshold   = 1000
_optimizer_nested_rollup_for_gset   = 100
_nlj_batching_enabled               = 1
parallel_query_default_dop          = 0
is_recur_flags                      = 0
optimizer_use_invisible_indexes     = false
flashback_data_archive_internal_cursor = 0
_optimizer_extended_stats_usage_control = 224
_parallel_syspls_obey_force         = true
cell_offload_processing             = true
_rdbms_internal_fplib_enabled       = false
db_file_multiblock_read_count       = 128
_bloom_folding_enabled              = true
_mv_generalized_oj_refresh_opt      = true
cell_offload_compaction             = ADAPTIVE
parallel_degree_limit               = 65535
parallel_force_local                = false
parallel_max_degree                 = 16
total_cpu_count                     = 8
cell_offload_plan_display           = AUTO
_optimizer_coalesce_subqueries      = true
_optimizer_fast_pred_transitivity   = true
_optimizer_fast_access_pred_analysis = true
_optimizer_unnest_disjunctive_subq  = true
_optimizer_unnest_corr_set_subq     = true
_optimizer_distinct_agg_transform   = true
_aggregation_optimization_settings  = 0
_optimizer_connect_by_elim_dups     = true
_optimizer_eliminate_filtering_join = true
_connect_by_use_union_all           = true
dst_upgrade_insert_conv             = true
advanced_queuing_internal_cursor    = 0
_optimizer_unnest_all_subqueries    = true
_bloom_predicate_pushdown_to_storage = true
_bloom_vector_elements              = 0
_bloom_pushing_max                  = 524288
parallel_autodop                    = 0
parallel_ddldml                     = 0
_parallel_cluster_cache_policy      = adaptive
_parallel_scalability               = 50
iot_internal_cursor                 = 0
_optimizer_instance_count           = 0
_optimizer_connect_by_cb_whr_only   = false
_suppress_scn_chk_for_cqn           = nosuppress_1466
_optimizer_join_factorization       = true
_optimizer_use_cbqt_star_transformation = true
_optimizer_table_expansion          = true
_and_pruning_enabled                = true
_deferred_constant_folding_mode     = DEFAULT
_optimizer_distinct_placement       = true
partition_pruning_internal_cursor   = 0
parallel_hinted                     = none
_sql_compatibility                  = 0
_optimizer_use_feedback             = true
_optimizer_try_st_before_jppd       = true
Bug Fix Control Environment
    fix  3834770 = 1      
    fix  3746511 = enabled
    fix  4519016 = enabled
    fix  3118776 = enabled
    fix  4488689 = enabled
    fix  2194204 = disabled
    fix  2660592 = enabled
    fix  2320291 = enabled
    fix  2324795 = enabled
    fix  4308414 = enabled
    fix  3499674 = disabled
    fix  4569940 = enabled
    fix  4631959 = enabled
    fix  4519340 = enabled
    fix  4550003 = enabled
    fix  1403283 = enabled
    fix  4554846 = enabled
    fix  4602374 = enabled
    fix  4584065 = enabled
    fix  4545833 = enabled
    fix  4611850 = enabled
    fix  4663698 = enabled
    fix  4663804 = enabled
    fix  4666174 = enabled
    fix  4567767 = enabled
    fix  4556762 = 15     
    fix  4728348 = enabled
    fix  4708389 = enabled
    fix  4175830 = enabled
    fix  4752814 = enabled
    fix  4583239 = enabled
    fix  4386734 = enabled
    fix  4887636 = enabled
    fix  4483240 = enabled
    fix  4872602 = disabled
    fix  4711525 = enabled
    fix  4545802 = enabled
    fix  4605810 = enabled
    fix  4704779 = enabled
    fix  4900129 = enabled
    fix  4924149 = enabled
    fix  4663702 = enabled
    fix  4878299 = enabled
    fix  4658342 = enabled
    fix  4881533 = enabled
    fix  4676955 = enabled
    fix  4273361 = enabled
    fix  4967068 = enabled
    fix  4969880 = disabled
    fix  5005866 = enabled
    fix  5015557 = enabled
    fix  4705343 = enabled
    fix  4904838 = enabled
    fix  4716096 = enabled
    fix  4483286 = disabled
    fix  4722900 = enabled
    fix  4615392 = enabled
    fix  5096560 = enabled
    fix  5029464 = enabled
    fix  4134994 = enabled
    fix  4904890 = enabled
    fix  5104624 = enabled
    fix  5014836 = enabled
    fix  4768040 = enabled
    fix  4600710 = enabled
    fix  5129233 = enabled
    fix  4595987 = enabled
    fix  4908162 = enabled
    fix  5139520 = enabled
    fix  5084239 = enabled
    fix  5143477 = disabled
    fix  2663857 = enabled
    fix  4717546 = enabled
    fix  5240264 = disabled
    fix  5099909 = enabled
    fix  5240607 = enabled
    fix  5195882 = enabled
    fix  5220356 = enabled
    fix  5263572 = enabled
    fix  5385629 = enabled
    fix  5302124 = enabled
    fix  5391942 = enabled
    fix  5384335 = enabled
    fix  5482831 = enabled
    fix  4158812 = enabled
    fix  5387148 = enabled
    fix  5383891 = enabled
    fix  5466973 = enabled
    fix  5396162 = enabled
    fix  5394888 = enabled
    fix  5395291 = enabled
    fix  5236908 = enabled
    fix  5509293 = enabled
    fix  5449488 = enabled
    fix  5567933 = enabled
    fix  5570494 = enabled
    fix  5288623 = enabled
    fix  5505995 = enabled
    fix  5505157 = enabled
    fix  5112460 = enabled
    fix  5554865 = enabled
    fix  5112260 = enabled
    fix  5112352 = enabled
    fix  5547058 = enabled
    fix  5618040 = enabled
    fix  5585313 = enabled
    fix  5547895 = enabled
    fix  5634346 = enabled
    fix  5620485 = enabled
    fix  5483301 = enabled
    fix  5657044 = enabled
    fix  5694984 = enabled
    fix  5868490 = enabled
    fix  5650477 = enabled
    fix  5611962 = enabled
    fix  4279274 = enabled
    fix  5741121 = enabled
    fix  5714944 = enabled
    fix  5391505 = enabled
    fix  5762598 = enabled
    fix  5578791 = enabled
    fix  5259048 = enabled
    fix  5882954 = enabled
    fix  2492766 = enabled
    fix  5707608 = enabled
    fix  5891471 = enabled
    fix  5884780 = enabled
    fix  5680702 = enabled
    fix  5371452 = enabled
    fix  5838613 = enabled
    fix  5949981 = enabled
    fix  5624216 = enabled
    fix  5741044 = enabled
    fix  5976822 = enabled
    fix  6006457 = enabled
    fix  5872956 = enabled
    fix  5923644 = enabled
    fix  5943234 = enabled
    fix  5844495 = enabled
    fix  4168080 = enabled
    fix  6020579 = enabled
    fix  5842686 = disabled
    fix  5996801 = enabled
    fix  5593639 = enabled
    fix  6133948 = enabled
    fix  3151991 = enabled
    fix  6146906 = enabled
    fix  6239909 = enabled
    fix  6267621 = enabled
    fix  5909305 = enabled
    fix  6279918 = enabled
    fix  6141818 = enabled
    fix  6151963 = enabled
    fix  6251917 = enabled
    fix  6282093 = enabled
    fix  6119510 = enabled
    fix  6119382 = enabled
    fix  3801750 = enabled
    fix  5705630 = disabled
    fix  5944076 = enabled
    fix  5406763 = enabled
    fix  6070954 = enabled
    fix  6282944 = enabled
    fix  6138746 = enabled
    fix  6082745 = enabled
    fix  3426050 = enabled
    fix   599680 = enabled
    fix  6062266 = enabled
    fix  6087237 = enabled
    fix  6122894 = enabled
    fix  6377505 = enabled
    fix  5893768 = enabled
    fix  6163564 = enabled
    fix  6073325 = enabled
    fix  6188881 = enabled
    fix  6007259 = enabled
    fix  6239971 = enabled
    fix  5284200 = disabled
    fix  6042205 = enabled
    fix  6051211 = enabled
    fix  6434668 = enabled
    fix  6438752 = enabled
    fix  5936366 = enabled
    fix  6439032 = enabled
    fix  6438892 = enabled
    fix  6006300 = enabled
    fix  5947231 = enabled
    fix  5416118 = 1      
    fix  6365442 = 1      
    fix  6239039 = enabled
    fix  6502845 = enabled
    fix  6913094 = enabled
    fix  6029469 = enabled
    fix  5919513 = enabled
    fix  6057611 = enabled
    fix  6469667 = enabled
    fix  6608941 = disabled
    fix  6368066 = enabled
    fix  6329318 = enabled
    fix  6656356 = enabled
    fix  4507997 = enabled
    fix  6671155 = enabled
    fix  6694548 = enabled
    fix  6688200 = enabled
    fix  6612471 = enabled
    fix  6708183 = disabled
    fix  6326934 = enabled
    fix  6520717 = disabled
    fix  6714199 = enabled
    fix  6681545 = enabled
    fix  6748058 = enabled
    fix  6167716 = enabled
    fix  6674254 = enabled
    fix  6468287 = enabled
    fix  6503543 = enabled
    fix  6808773 = disabled
    fix  6766962 = enabled
    fix  6120483 = enabled
    fix  6670551 = enabled
    fix  6771838 = enabled
    fix  6626018 = disabled
    fix  6530596 = enabled
    fix  6778642 = enabled
    fix  6699059 = enabled
    fix  6376551 = enabled
    fix  6429113 = enabled
    fix  6782437 = enabled
    fix  6776808 = enabled
    fix  6765823 = enabled
    fix  6768660 = enabled
    fix  6782665 = enabled
    fix  6610822 = enabled
    fix  6514189 = enabled
    fix  6818410 = enabled
    fix  6827696 = enabled
    fix  6773613 = enabled
    fix  5902962 = enabled
    fix  6956212 = enabled
    fix  3056297 = enabled
    fix  6440977 = disabled
    fix  6972291 = disabled
    fix  6904146 = enabled
    fix  6221403 = enabled
    fix  5475051 = enabled
    fix  6845871 = enabled
    fix  5468809 = enabled
    fix  6917633 = enabled
    fix  4444536 = disabled
    fix  6955210 = enabled
    fix  6994194 = enabled
    fix  6399597 = disabled
    fix  6951776 = enabled
    fix  5648287 = 3      
    fix  6987082 = disabled
    fix  7132036 = enabled
    fix  6980350 = enabled
    fix  5199213 = enabled
    fix  7138405 = enabled
    fix  7148689 = enabled
    fix  6820988 = enabled
    fix  7032684 = enabled
    fix  6617866 = enabled
    fix  7155968 = enabled
    fix  7127980 = enabled
    fix  6982954 = enabled
    fix  7241819 = enabled
    fix  6897034 = enabled
    fix  7236148 = enabled
    fix  7298570 = enabled
    fix  7249095 = enabled
    fix  7314499 = enabled
    fix  7324224 = enabled
    fix  7289023 = enabled
    fix  7237571 = enabled
    fix  7116357 = enabled
    fix  7345484 = enabled
    fix  7375179 = enabled
    fix  6430500 = disabled
    fix  5897486 = enabled
    fix  6774209 = enabled
    fix  7306637 = enabled
    fix  6451322 = enabled
    fix  7208131 = enabled
    fix  7388652 = enabled
    fix  7127530 = enabled
    fix  6751206 = enabled
    fix  6669103 = enabled
    fix  7430474 = enabled
    fix  6990305 = enabled
    fix  7043307 = enabled
    fix  6921505 = enabled
    fix  7388457 = enabled
    fix  3120429 = enabled
    fix  7452823 = disabled
    fix  6838105 = enabled
    fix  6769711 = enabled
    fix  7170213 = enabled
    fix  6528872 = enabled
    fix  7295298 = enabled
    fix  5922070 = enabled
    fix  7259468 = enabled
    fix  6418552 = enabled
    fix  4619997 = enabled
    fix  7524366 = enabled
    fix  6942476 = enabled
    fix  6418771 = enabled
    fix  7375077 = enabled
    fix  5400639 = enabled
    fix  4570921 = enabled
    fix  7426911 = enabled
    fix  5099019 = disabled
    fix  7528216 = enabled
    fix  7521266 = enabled
    fix  7385140 = enabled
    fix  7576516 = enabled
    fix  7573526 = enabled
    fix  7576476 = enabled
    fix  7165898 = enabled
    fix  7263214 = enabled
    fix  3320140 = enabled
    fix  7555510 = enabled
    fix  7613118 = enabled
    fix  7597059 = enabled
    fix  7558911 = enabled
    fix  5520732 = enabled
    fix  7679490 = disabled
    fix  7449971 = enabled
    fix  3628118 = enabled
    fix  4370840 = enabled
    fix  7281191 = enabled
    fix  7519687 = enabled
    fix  5029592 = 3      
    fix  6012093 = 1      
    fix  6053861 = disabled
    fix  6941515 = disabled
    fix  7696414 = enabled
    fix  7272039 = enabled
    fix  7834811 = enabled
    fix  7640597 = enabled
    fix  7341616 = enabled
    fix  7168184 = enabled
    fix   399198 = enabled
    fix  7831070 = enabled
    fix  7676897 = disabled
    fix  7414637 = enabled
    fix  7585456 = enabled
    fix  8202421 = enabled
    fix  7658097 = disabled
    fix  8251486 = enabled
    fix  7132684 = enabled
    fix  7512227 = enabled
    fix  6972987 = enabled
    fix  7199035 = enabled
    fix  8243446 = enabled
    fix  7650462 = enabled
    fix  6720701 = enabled
    fix  7592673 = enabled
    fix  7718694 = enabled
    fix  7534027 = enabled
    fix  7708267 = enabled
    fix  5716785 = enabled
    fix  7356191 = enabled
    fix  7679161 = enabled
    fix  7597159 = enabled
    fix  7499258 = enabled
    fix  8328363 = enabled
    fix  7452863 = enabled
    fix  8284930 = enabled
    fix  7298626 = enabled
    fix  7657126 = enabled
    fix  8371884 = enabled
    fix  8318020 = enabled
    fix  8255423 = enabled
    fix  7135745 = enabled
    fix  8356253 = enabled
    fix  7534257 = enabled
    fix  8323407 = enabled
    fix  7539815 = enabled
    fix  8289316 = enabled
    fix  8447850 = enabled
    fix  7675944 = enabled
    fix  8355120 = enabled
    fix  7176746 = enabled
    fix  8442891 = enabled
    fix  8373261 = enabled
    fix  7679164 = enabled
    fix  7670533 = enabled
    fix  8408665 = enabled
    fix  8491399 = enabled
    fix  8348392 = enabled
    fix  8348585 = enabled
    fix  8508056 = enabled
    fix  8335178 = enabled
    fix  8515269 = enabled
    fix  8247017 = enabled
    fix  7325597 = enabled
    fix  8531490 = enabled
    fix  6163600 = enabled
    fix  8589278 = disabled
    fix  8557992 = enabled
    fix  7556098 = enabled
    fix  8580883 = enabled
    fix  5892599 = disabled
    fix  8609714 = enabled
    fix  8514561 = enabled
    fix  8619631 = disabled

Query Block Registry:
SEL$1 0x6e975eb0 (PARSER) [FINAL]

:
    call(in-use=25024, alloc=82024), compile(in-use=102048, alloc=164272), execution(in-use=12872, alloc=16200)

End of Optimizer State Dump
Dumping Hints
=============

Note in the above that we are able to see the actual execution plan, the peeked bind variables, the set of hints that will reproduce the execution plan, and a large number of normal and hidden optimizer parameters.  Comparing the output with that of Oracle Database 10.2.0.2, you will notice that server additional parameters are listed in the output.

An example with a 10046 trace at level 4 (by default, on Oracle 11.1.0.6 and higher we no longer need to execute another SQL statement after the SQL statement under investigation so that the STAT lines for our SQL statement are written to the trace file):

ALTER SESSION SET TRACEFILE_IDENTIFIER = '10046_EXECUTION_PLAN';
ALTER SESSION SET EVENTS '10046 TRACE NAME CONTEXT FOREVER, LEVEL 4';

SELECT /* TEST */
  T3.C1,
  SUBSTR(T1.C2,1,10) C2
FROM
  T3,
  T1
WHERE
  T1.C1=T3.C1
  AND T1.C1 BETWEEN :N1 AND :N2;

SELECT SYSDATE FROM DUAL;

The resulting trace file looks something like this (you did read Chapter 15 of the book, didn’t you – so be sure to delete the trace files when no longer needed):

=====================
PARSING IN CURSOR #6 len=118 dep=0 uid=68 oct=3 lid=68 tim=1264989049019258 hv=3172794915 ad='25b889600' sqlid='3g3fc5qyju0j3'
SELECT /* TEST */
  T3.C1,
  SUBSTR(T1.C2,1,10) C2
FROM
  T3,
  T1
WHERE
  T1.C1=T3.C1
  AND T1.C1 BETWEEN :N1 AND :N2
END OF STMT
PARSE #6:c=0,e=165,p=0,cr=0,cu=0,mis=1,r=0,dep=0,og=1,plh=0,tim=1264989049019257
BINDS #6:
 Bind#0
  oacdty=02 mxl=22(22) mxlc=00 mal=00 scl=00 pre=00
  oacflg=03 fl2=1000000 frm=00 csi=00 siz=48 off=0
  kxsbbbfp=2b7f6eb34ea8  bln=22  avl=02  flg=05
  value=1
 Bind#1
  oacdty=02 mxl=22(22) mxlc=00 mal=00 scl=00 pre=00
  oacflg=03 fl2=1000000 frm=00 csi=00 siz=0 off=24
  kxsbbbfp=2b7f6eb34ec0  bln=22  avl=02  flg=01
  value=10
EXEC #6:c=999,e=1078,p=0,cr=0,cu=0,mis=1,r=0,dep=0,og=1,plh=744086632,tim=1264989049020428
FETCH #6:c=74988,e=75221,p=0,cr=37168,cu=0,mis=0,r=1,dep=0,og=1,plh=744086632,tim=1264989049095700
FETCH #6:c=0,e=50,p=0,cr=2,cu=0,mis=0,r=9,dep=0,og=1,plh=744086632,tim=1264989049095954
STAT #6 id=1 cnt=10 pid=0 pos=1 obj=0 op='FILTER  (cr=37170 pr=0 pw=0 time=0 us)'
STAT #6 id=2 cnt=10 pid=1 pos=1 obj=0 op='HASH JOIN  (cr=37170 pr=0 pw=0 time=0 us cost=10219 size=2394 card=9)'
STAT #6 id=3 cnt=10 pid=2 pos=1 obj=70288 op='TABLE ACCESS FULL T3 (cr=37164 pr=0 pw=0 time=0 us cost=10214 size=50 card=10)'
STAT #6 id=4 cnt=10 pid=2 pos=2 obj=70284 op='TABLE ACCESS BY INDEX ROWID T1 (cr=6 pr=0 pw=0 time=0 us cost=4 size=2610 card=10)'
STAT #6 id=5 cnt=10 pid=4 pos=1 obj=70285 op='INDEX RANGE SCAN SYS_C0017307 (cr=4 pr=0 pw=0 time=36 us cost=3 size=0 card=10)'
CLOSE #6:c=0,e=10,dep=0,type=0,tim=1264989049096413
=====================

If you compare the above output with that of Oracle 10.2.0.2, you will notice that the SQL_ID for the SQL statement is written to the trace file, the STAT lines include cardinality estimates, and when a cursor is closed a line is written to the trace file.  We could, of course, just read the actual plan direct from the 10046 trace file, as well as the bind variable values and data types.  But, we will use TKPROF instead (we will not be able to see the bind variable values when using TKPROF).

> tkprof or112_ora_5062_10046_EXECUTION_PLAN.trc or112_ora_5062_10046_EXECUTION_PLAN.txt

The output might look like this:

call     count       cpu    elapsed       disk      query    current        rows
------- ------  -------- ---------- ---------- ---------- ----------  ----------
Parse        1      0.00       0.00          0          0          0           0
Execute      1      0.00       0.00          0          0          0           0
Fetch        2      0.07       0.07          0      37170          0          10
------- ------  -------- ---------- ---------- ---------- ----------  ----------
total        4      0.07       0.07          0      37170          0          10

Misses in library cache during parse: 1
Misses in library cache during execute: 1
Optimizer mode: ALL_ROWS
Parsing user id: 68 

Rows     Row Source Operation
-------  ---------------------------------------------------
     10  FILTER  (cr=37170 pr=0 pw=0 time=0 us)
     10   HASH JOIN  (cr=37170 pr=0 pw=0 time=0 us cost=10219 size=2394 card=9)
     10    TABLE ACCESS FULL T3 (cr=37164 pr=0 pw=0 time=0 us cost=10214 size=50 card=10)
     10    TABLE ACCESS BY INDEX ROWID T1 (cr=6 pr=0 pw=0 time=0 us cost=4 size=2610 card=10)
     10     INDEX RANGE SCAN SYS_C0017307 (cr=4 pr=0 pw=0 time=36 us cost=3 size=0 card=10)(object id 70285)

What else has changed?  Nested – Nested Loops joins… interesting.





Execution Plans – What is the Plan, and Where Do I Find It 2

1 02 2010

February 1, 2010

(Back to the Previous Post in the Series) (Forward to the Next Post in the Series)

In the earlier blog article, we saw how to:

  • Display the actual (TYPICAL) execution plan for a SQL statement with estimated cardinality and costs.
  • Display the actual (ALLSTATS LAST) execution plan for a SQL statement using the GATHER_PLAN_STATISTICS hint to compare the estimated cardinality with the actual number of rows returned from each operation in the plan, and obtain the actual final execution time (timing of the intermediate steps might not be close to actual time).
  • Display the actual (ALLSTATS LAST) execution plan for a SQL statement with the STATISTICS_LEVEL parameter set to ALL at the session level to obtain the final execution time and close estimates for each of the intermediate steps (in some cases, a significant increase in execution time was experienced).
  • Compare the changes in the actual execution plan when changing the OPTIMIZER_MODE parameter between ALL_ROWS, FIRST_ROWS_1, and CHOOSE.  Note that setting the OPTIMIZER_MODE to FIRST_ROWS_1 may have caused the optimizer to under-estimate the number of rows that will be returned, as shown in the execution plan.
  • Display a possibly correct execution plan with SQL*Plus’ AUTOTRACE and with EXPLAIN PLAN, and explore some of the problems that might be encountered when relying on those plans.
  • See the effects of bind peeking on an execution plan.
  • Retrieve the execution plan by setting event 10132.
  • Read the execution plan directly from a 10046 trace file.
  • Process the trace file with TKPROF, and one of the potential problems caused by telling TKPROF to generate explain plans.

So, what is left?  Well, the previous blog article in this series used the nearly four year old Oracle Database 10.2.0.2.  It might be interesting to look at Oracle Database 11.2.0.1, but more specifically using Statspack in that Oracle release to capture the execution plans.  If you read the documentation for Oracle Database, you might be lead to believe that Statspack disappeared with Oracle 10.1.0.1 and was replaced with AWR reports (using AWR requires an additional cost license, while using Statspack does not).  Statspack is still very much alive in Oracle Database 11.2.0.1, and has actually improved from what was offered in earlier releases.  A Statspack snapshot captured at level 6 or greater will capture excution plans – not necessarily all execution plans for all SQL statement (the criteria for what is captured can be adjusted), but quite a few with the default settings.  This blog article will use the tables that were created in the previous blog article to retrieve execution plans captured by Statspack

We will need two SQL*Plus sessions, the first connected as the PERFSTAT user (the owner of Statspack data), and the second connected as the owner of the tables created in the previous blog article.  The PERFSTAT user will execute the following script, which will collect a Statspack level 7 snapshot every 5 minutes (there is no sleep command on Windows, but it is possible to create a VBS script to perform the same task on the Windows platform, as happens when the sleep command is called on Unix/Linux – see chapter 8 of the “Expert Oracle Practices” book for the VBS script):

EXEC STATSPACK.SNAP(i_snap_level=>7)
host sleep 300
EXEC STATSPACK.SNAP(i_snap_level=>7)
host sleep 300
EXEC STATSPACK.SNAP(i_snap_level=>7)
host sleep 300
EXEC STATSPACK.SNAP(i_snap_level=>7)

While the PERSTAT user is running the above script, the other session will run the following script several times (at least 2 times per Statspack capture):

SPOOL BindTestPlans.txt

SET AUTOTRACE OFF
ALTER SESSION SET STATISTICS_LEVEL='ALL';

ALTER SESSION SET OPTIMIZER_MODE='ALL_ROWS';
ALTER SYSTEM FLUSH SHARED_POOL;

VARIABLE N1 NUMBER
VARIABLE N2 NUMBER
EXEC :N1:=1
EXEC :N2:=1

SELECT
  T3.C1,
  SUBSTR(T1.C2,1,10) T1_C2,
  SUBSTR(T2.C2,1,10) T2_C2
FROM
  T3,
  T2,
  T1
WHERE
  T1.C1=T3.C1
  AND T1.C1=T2.C1
  AND T1.C1 BETWEEN :N1 AND :N2;

SELECT
  T3.C1,
  SUBSTR(T1.C2,1,10) T1_C2,
  SUBSTR(T2.C2,1,10) T2_C2
FROM
  T3,
  T2,
  T1
WHERE
  T1.C1=T3.C1
  AND T1.C1=T2.C1
  AND T1.C1 BETWEEN :N1 AND :N2;

SELECT
  T3.C1,
  SUBSTR(T1.C2,1,10) T1_C2,
  SUBSTR(T2.C2,1,10) T2_C2
FROM
  T3,
  T2,
  T1
WHERE
  T1.C1=T3.C1
  AND T1.C1=T2.C1
  AND T1.C1 BETWEEN :N1 AND :N2;

SELECT
  *
FROM
  TABLE(DBMS_XPLAN.DISPLAY_CURSOR(NULL,NULL,'ALLSTATS LAST'));

EXEC :N2:=100

SELECT
  T3.C1,
  SUBSTR(T1.C2,1,10) T1_C2,
  SUBSTR(T2.C2,1,10) T2_C2
FROM
  T3,
  T2,
  T1
WHERE
  T1.C1=T3.C1
  AND T1.C1=T2.C1
  AND T1.C1 BETWEEN :N1 AND :N2;

SELECT
  T3.C1,
  SUBSTR(T1.C2,1,10) T1_C2,
  SUBSTR(T2.C2,1,10) T2_C2
FROM
  T3,
  T2,
  T1
WHERE
  T1.C1=T3.C1
  AND T1.C1=T2.C1
  AND T1.C1 BETWEEN :N1 AND :N2;

SELECT
  T3.C1,
  SUBSTR(T1.C2,1,10) T1_C2,
  SUBSTR(T2.C2,1,10) T2_C2
FROM
  T3,
  T2,
  T1
WHERE
  T1.C1=T3.C1
  AND T1.C1=T2.C1
  AND T1.C1 BETWEEN :N1 AND :N2;

SELECT
  *
FROM
  TABLE(DBMS_XPLAN.DISPLAY_CURSOR(NULL,NULL,'ALLSTATS LAST'));

EXEC :N2:=1000

SELECT
  T3.C1,
  SUBSTR(T1.C2,1,10) T1_C2,
  SUBSTR(T2.C2,1,10) T2_C2
FROM
  T3,
  T2,
  T1
WHERE
  T1.C1=T3.C1
  AND T1.C1=T2.C1
  AND T1.C1 BETWEEN :N1 AND :N2;

SELECT
  T3.C1,
  SUBSTR(T1.C2,1,10) T1_C2,
  SUBSTR(T2.C2,1,10) T2_C2
FROM
  T3,
  T2,
  T1
WHERE
  T1.C1=T3.C1
  AND T1.C1=T2.C1
  AND T1.C1 BETWEEN :N1 AND :N2;

SELECT
  T3.C1,
  SUBSTR(T1.C2,1,10) T1_C2,
  SUBSTR(T2.C2,1,10) T2_C2
FROM
  T3,
  T2,
  T1
WHERE
  T1.C1=T3.C1
  AND T1.C1=T2.C1
  AND T1.C1 BETWEEN :N1 AND :N2;

SELECT
  *
FROM
  TABLE(DBMS_XPLAN.DISPLAY_CURSOR(NULL,NULL,'ALLSTATS LAST'));

EXEC :N2:=10000

SELECT
  T3.C1,
  SUBSTR(T1.C2,1,10) T1_C2,
  SUBSTR(T2.C2,1,10) T2_C2
FROM
  T3,
  T2,
  T1
WHERE
  T1.C1=T3.C1
  AND T1.C1=T2.C1
  AND T1.C1 BETWEEN :N1 AND :N2;

SELECT
  T3.C1,
  SUBSTR(T1.C2,1,10) T1_C2,
  SUBSTR(T2.C2,1,10) T2_C2
FROM
  T3,
  T2,
  T1
WHERE
  T1.C1=T3.C1
  AND T1.C1=T2.C1
  AND T1.C1 BETWEEN :N1 AND :N2;

SELECT
  T3.C1,
  SUBSTR(T1.C2,1,10) T1_C2,
  SUBSTR(T2.C2,1,10) T2_C2
FROM
  T3,
  T2,
  T1
WHERE
  T1.C1=T3.C1
  AND T1.C1=T2.C1
  AND T1.C1 BETWEEN :N1 AND :N2;

SELECT
  *
FROM
  TABLE(DBMS_XPLAN.DISPLAY_CURSOR(NULL,NULL,'ALLSTATS LAST'));

EXEC :N2:=100000

SELECT
  T3.C1,
  SUBSTR(T1.C2,1,10) T1_C2,
  SUBSTR(T2.C2,1,10) T2_C2
FROM
  T3,
  T2,
  T1
WHERE
  T1.C1=T3.C1
  AND T1.C1=T2.C1
  AND T1.C1 BETWEEN :N1 AND :N2;

SELECT
  T3.C1,
  SUBSTR(T1.C2,1,10) T1_C2,
  SUBSTR(T2.C2,1,10) T2_C2
FROM
  T3,
  T2,
  T1
WHERE
  T1.C1=T3.C1
  AND T1.C1=T2.C1
  AND T1.C1 BETWEEN :N1 AND :N2;

SELECT
  T3.C1,
  SUBSTR(T1.C2,1,10) T1_C2,
  SUBSTR(T2.C2,1,10) T2_C2
FROM
  T3,
  T2,
  T1
WHERE
  T1.C1=T3.C1
  AND T1.C1=T2.C1
  AND T1.C1 BETWEEN :N1 AND :N2;

SELECT
  *
FROM
  TABLE(DBMS_XPLAN.DISPLAY_CURSOR(NULL,NULL,'ALLSTATS LAST'));

ALTER SESSION SET OPTIMIZER_MODE='FIRST_ROWS_1';
VARIABLE N1 NUMBER
VARIABLE N2 NUMBER
EXEC :N1:=1
EXEC :N2:=1

SELECT
  T3.C1,
  SUBSTR(T1.C2,1,10) T1_C2,
  SUBSTR(T2.C2,1,10) T2_C2
FROM
  T3,
  T2,
  T1
WHERE
  T1.C1=T3.C1
  AND T1.C1=T2.C1
  AND T1.C1 BETWEEN :N1 AND :N2;

SELECT
  T3.C1,
  SUBSTR(T1.C2,1,10) T1_C2,
  SUBSTR(T2.C2,1,10) T2_C2
FROM
  T3,
  T2,
  T1
WHERE
  T1.C1=T3.C1
  AND T1.C1=T2.C1
  AND T1.C1 BETWEEN :N1 AND :N2;

SELECT
  T3.C1,
  SUBSTR(T1.C2,1,10) T1_C2,
  SUBSTR(T2.C2,1,10) T2_C2
FROM
  T3,
  T2,
  T1
WHERE
  T1.C1=T3.C1
  AND T1.C1=T2.C1
  AND T1.C1 BETWEEN :N1 AND :N2;

SELECT
  *
FROM
  TABLE(DBMS_XPLAN.DISPLAY_CURSOR(NULL,NULL,'ALLSTATS LAST'));

EXEC :N2:=100

SELECT
  T3.C1,
  SUBSTR(T1.C2,1,10) T1_C2,
  SUBSTR(T2.C2,1,10) T2_C2
FROM
  T3,
  T2,
  T1
WHERE
  T1.C1=T3.C1
  AND T1.C1=T2.C1
  AND T1.C1 BETWEEN :N1 AND :N2;

SELECT
  T3.C1,
  SUBSTR(T1.C2,1,10) T1_C2,
  SUBSTR(T2.C2,1,10) T2_C2
FROM
  T3,
  T2,
  T1
WHERE
  T1.C1=T3.C1
  AND T1.C1=T2.C1
  AND T1.C1 BETWEEN :N1 AND :N2;

SELECT
  T3.C1,
  SUBSTR(T1.C2,1,10) T1_C2,
  SUBSTR(T2.C2,1,10) T2_C2
FROM
  T3,
  T2,
  T1
WHERE
  T1.C1=T3.C1
  AND T1.C1=T2.C1
  AND T1.C1 BETWEEN :N1 AND :N2;

SELECT
  *
FROM
  TABLE(DBMS_XPLAN.DISPLAY_CURSOR(NULL,NULL,'ALLSTATS LAST'));

EXEC :N2:=1000

SELECT
  T3.C1,
  SUBSTR(T1.C2,1,10) T1_C2,
  SUBSTR(T2.C2,1,10) T2_C2
FROM
  T3,
  T2,
  T1
WHERE
  T1.C1=T3.C1
  AND T1.C1=T2.C1
  AND T1.C1 BETWEEN :N1 AND :N2;

SELECT
  T3.C1,
  SUBSTR(T1.C2,1,10) T1_C2,
  SUBSTR(T2.C2,1,10) T2_C2
FROM
  T3,
  T2,
  T1
WHERE
  T1.C1=T3.C1
  AND T1.C1=T2.C1
  AND T1.C1 BETWEEN :N1 AND :N2;

SELECT
  T3.C1,
  SUBSTR(T1.C2,1,10) T1_C2,
  SUBSTR(T2.C2,1,10) T2_C2
FROM
  T3,
  T2,
  T1
WHERE
  T1.C1=T3.C1
  AND T1.C1=T2.C1
  AND T1.C1 BETWEEN :N1 AND :N2;

SELECT
  *
FROM
  TABLE(DBMS_XPLAN.DISPLAY_CURSOR(NULL,NULL,'ALLSTATS LAST'));

EXEC :N2:=10000

SELECT
  T3.C1,
  SUBSTR(T1.C2,1,10) T1_C2,
  SUBSTR(T2.C2,1,10) T2_C2
FROM
  T3,
  T2,
  T1
WHERE
  T1.C1=T3.C1
  AND T1.C1=T2.C1
  AND T1.C1 BETWEEN :N1 AND :N2;

SELECT
  T3.C1,
  SUBSTR(T1.C2,1,10) T1_C2,
  SUBSTR(T2.C2,1,10) T2_C2
FROM
  T3,
  T2,
  T1
WHERE
  T1.C1=T3.C1
  AND T1.C1=T2.C1
  AND T1.C1 BETWEEN :N1 AND :N2;

SELECT
  T3.C1,
  SUBSTR(T1.C2,1,10) T1_C2,
  SUBSTR(T2.C2,1,10) T2_C2
FROM
  T3,
  T2,
  T1
WHERE
  T1.C1=T3.C1
  AND T1.C1=T2.C1
  AND T1.C1 BETWEEN :N1 AND :N2;

SELECT
  *
FROM
  TABLE(DBMS_XPLAN.DISPLAY_CURSOR(NULL,NULL,'ALLSTATS LAST'));

EXEC :N2:=100000

SELECT
  T3.C1,
  SUBSTR(T1.C2,1,10) T1_C2,
  SUBSTR(T2.C2,1,10) T2_C2
FROM
  T3,
  T2,
  T1
WHERE
  T1.C1=T3.C1
  AND T1.C1=T2.C1
  AND T1.C1 BETWEEN :N1 AND :N2;

SELECT
  T3.C1,
  SUBSTR(T1.C2,1,10) T1_C2,
  SUBSTR(T2.C2,1,10) T2_C2
FROM
  T3,
  T2,
  T1
WHERE
  T1.C1=T3.C1
  AND T1.C1=T2.C1
  AND T1.C1 BETWEEN :N1 AND :N2;

SELECT
  T3.C1,
  SUBSTR(T1.C2,1,10) T1_C2,
  SUBSTR(T2.C2,1,10) T2_C2
FROM
  T3,
  T2,
  T1
WHERE
  T1.C1=T3.C1
  AND T1.C1=T2.C1
  AND T1.C1 BETWEEN :N1 AND :N2;

SELECT
  *
FROM
  TABLE(DBMS_XPLAN.DISPLAY_CURSOR(NULL,NULL,'ALLSTATS LAST'));

ALTER SESSION SET OPTIMIZER_MODE='FIRST_ROWS_10';
VARIABLE N1 NUMBER
VARIABLE N2 NUMBER
EXEC :N1:=1
EXEC :N2:=1

SELECT
  T3.C1,
  SUBSTR(T1.C2,1,10) T1_C2,
  SUBSTR(T2.C2,1,10) T2_C2
FROM
  T3,
  T2,
  T1
WHERE
  T1.C1=T3.C1
  AND T1.C1=T2.C1
  AND T1.C1 BETWEEN :N1 AND :N2;

SELECT
  T3.C1,
  SUBSTR(T1.C2,1,10) T1_C2,
  SUBSTR(T2.C2,1,10) T2_C2
FROM
  T3,
  T2,
  T1
WHERE
  T1.C1=T3.C1
  AND T1.C1=T2.C1
  AND T1.C1 BETWEEN :N1 AND :N2;

SELECT
  T3.C1,
  SUBSTR(T1.C2,1,10) T1_C2,
  SUBSTR(T2.C2,1,10) T2_C2
FROM
  T3,
  T2,
  T1
WHERE
  T1.C1=T3.C1
  AND T1.C1=T2.C1
  AND T1.C1 BETWEEN :N1 AND :N2;

SELECT
  *
FROM
  TABLE(DBMS_XPLAN.DISPLAY_CURSOR(NULL,NULL,'ALLSTATS LAST'));

EXEC :N2:=100

SELECT
  T3.C1,
  SUBSTR(T1.C2,1,10) T1_C2,
  SUBSTR(T2.C2,1,10) T2_C2
FROM
  T3,
  T2,
  T1
WHERE
  T1.C1=T3.C1
  AND T1.C1=T2.C1
  AND T1.C1 BETWEEN :N1 AND :N2;

SELECT
  T3.C1,
  SUBSTR(T1.C2,1,10) T1_C2,
  SUBSTR(T2.C2,1,10) T2_C2
FROM
  T3,
  T2,
  T1
WHERE
  T1.C1=T3.C1
  AND T1.C1=T2.C1
  AND T1.C1 BETWEEN :N1 AND :N2;

SELECT
  T3.C1,
  SUBSTR(T1.C2,1,10) T1_C2,
  SUBSTR(T2.C2,1,10) T2_C2
FROM
  T3,
  T2,
  T1
WHERE
  T1.C1=T3.C1
  AND T1.C1=T2.C1
  AND T1.C1 BETWEEN :N1 AND :N2;

SELECT
  *
FROM
  TABLE(DBMS_XPLAN.DISPLAY_CURSOR(NULL,NULL,'ALLSTATS LAST'));

EXEC :N2:=1000

SELECT
  T3.C1,
  SUBSTR(T1.C2,1,10) T1_C2,
  SUBSTR(T2.C2,1,10) T2_C2
FROM
  T3,
  T2,
  T1
WHERE
  T1.C1=T3.C1
  AND T1.C1=T2.C1
  AND T1.C1 BETWEEN :N1 AND :N2;

SELECT
  T3.C1,
  SUBSTR(T1.C2,1,10) T1_C2,
  SUBSTR(T2.C2,1,10) T2_C2
FROM
  T3,
  T2,
  T1
WHERE
  T1.C1=T3.C1
  AND T1.C1=T2.C1
  AND T1.C1 BETWEEN :N1 AND :N2;

SELECT
  T3.C1,
  SUBSTR(T1.C2,1,10) T1_C2,
  SUBSTR(T2.C2,1,10) T2_C2
FROM
  T3,
  T2,
  T1
WHERE
  T1.C1=T3.C1
  AND T1.C1=T2.C1
  AND T1.C1 BETWEEN :N1 AND :N2;

SELECT
  *
FROM
  TABLE(DBMS_XPLAN.DISPLAY_CURSOR(NULL,NULL,'ALLSTATS LAST'));

EXEC :N2:=10000

SELECT
  T3.C1,
  SUBSTR(T1.C2,1,10) T1_C2,
  SUBSTR(T2.C2,1,10) T2_C2
FROM
  T3,
  T2,
  T1
WHERE
  T1.C1=T3.C1
  AND T1.C1=T2.C1
  AND T1.C1 BETWEEN :N1 AND :N2;

SELECT
  T3.C1,
  SUBSTR(T1.C2,1,10) T1_C2,
  SUBSTR(T2.C2,1,10) T2_C2
FROM
  T3,
  T2,
  T1
WHERE
  T1.C1=T3.C1
  AND T1.C1=T2.C1
  AND T1.C1 BETWEEN :N1 AND :N2;

SELECT
  T3.C1,
  SUBSTR(T1.C2,1,10) T1_C2,
  SUBSTR(T2.C2,1,10) T2_C2
FROM
  T3,
  T2,
  T1
WHERE
  T1.C1=T3.C1
  AND T1.C1=T2.C1
  AND T1.C1 BETWEEN :N1 AND :N2;

SELECT
  *
FROM
  TABLE(DBMS_XPLAN.DISPLAY_CURSOR(NULL,NULL,'ALLSTATS LAST'));

EXEC :N2:=100000

SELECT
  T3.C1,
  SUBSTR(T1.C2,1,10) T1_C2,
  SUBSTR(T2.C2,1,10) T2_C2
FROM
  T3,
  T2,
  T1
WHERE
  T1.C1=T3.C1
  AND T1.C1=T2.C1
  AND T1.C1 BETWEEN :N1 AND :N2;

SELECT
  T3.C1,
  SUBSTR(T1.C2,1,10) T1_C2,
  SUBSTR(T2.C2,1,10) T2_C2
FROM
  T3,
  T2,
  T1
WHERE
  T1.C1=T3.C1
  AND T1.C1=T2.C1
  AND T1.C1 BETWEEN :N1 AND :N2;

SELECT
  T3.C1,
  SUBSTR(T1.C2,1,10) T1_C2,
  SUBSTR(T2.C2,1,10) T2_C2
FROM
  T3,
  T2,
  T1
WHERE
  T1.C1=T3.C1
  AND T1.C1=T2.C1
  AND T1.C1 BETWEEN :N1 AND :N2;

SELECT
  *
FROM
  TABLE(DBMS_XPLAN.DISPLAY_CURSOR(NULL,NULL,'ALLSTATS LAST'));

ALTER SESSION SET OPTIMIZER_MODE='FIRST_ROWS_1000';
VARIABLE N1 NUMBER
VARIABLE N2 NUMBER
EXEC :N1:=1
EXEC :N2:=1

SELECT
  T3.C1,
  SUBSTR(T1.C2,1,10) T1_C2,
  SUBSTR(T2.C2,1,10) T2_C2
FROM
  T3,
  T2,
  T1
WHERE
  T1.C1=T3.C1
  AND T1.C1=T2.C1
  AND T1.C1 BETWEEN :N1 AND :N2;

SELECT
  T3.C1,
  SUBSTR(T1.C2,1,10) T1_C2,
  SUBSTR(T2.C2,1,10) T2_C2
FROM
  T3,
  T2,
  T1
WHERE
  T1.C1=T3.C1
  AND T1.C1=T2.C1
  AND T1.C1 BETWEEN :N1 AND :N2;

SELECT
  T3.C1,
  SUBSTR(T1.C2,1,10) T1_C2,
  SUBSTR(T2.C2,1,10) T2_C2
FROM
  T3,
  T2,
  T1
WHERE
  T1.C1=T3.C1
  AND T1.C1=T2.C1
  AND T1.C1 BETWEEN :N1 AND :N2;

SELECT
  *
FROM
  TABLE(DBMS_XPLAN.DISPLAY_CURSOR(NULL,NULL,'ALLSTATS LAST'));

EXEC :N2:=100

SELECT
  T3.C1,
  SUBSTR(T1.C2,1,10) T1_C2,
  SUBSTR(T2.C2,1,10) T2_C2
FROM
  T3,
  T2,
  T1
WHERE
  T1.C1=T3.C1
  AND T1.C1=T2.C1
  AND T1.C1 BETWEEN :N1 AND :N2;

SELECT
  T3.C1,
  SUBSTR(T1.C2,1,10) T1_C2,
  SUBSTR(T2.C2,1,10) T2_C2
FROM
  T3,
  T2,
  T1
WHERE
  T1.C1=T3.C1
  AND T1.C1=T2.C1
  AND T1.C1 BETWEEN :N1 AND :N2;

SELECT
  T3.C1,
  SUBSTR(T1.C2,1,10) T1_C2,
  SUBSTR(T2.C2,1,10) T2_C2
FROM
  T3,
  T2,
  T1
WHERE
  T1.C1=T3.C1
  AND T1.C1=T2.C1
  AND T1.C1 BETWEEN :N1 AND :N2;

SELECT
  *
FROM
  TABLE(DBMS_XPLAN.DISPLAY_CURSOR(NULL,NULL,'ALLSTATS LAST'));

EXEC :N2:=1000

SELECT
  T3.C1,
  SUBSTR(T1.C2,1,10) T1_C2,
  SUBSTR(T2.C2,1,10) T2_C2
FROM
  T3,
  T2,
  T1
WHERE
  T1.C1=T3.C1
  AND T1.C1=T2.C1
  AND T1.C1 BETWEEN :N1 AND :N2;

SELECT
  T3.C1,
  SUBSTR(T1.C2,1,10) T1_C2,
  SUBSTR(T2.C2,1,10) T2_C2
FROM
  T3,
  T2,
  T1
WHERE
  T1.C1=T3.C1
  AND T1.C1=T2.C1
  AND T1.C1 BETWEEN :N1 AND :N2;

SELECT
  T3.C1,
  SUBSTR(T1.C2,1,10) T1_C2,
  SUBSTR(T2.C2,1,10) T2_C2
FROM
  T3,
  T2,
  T1
WHERE
  T1.C1=T3.C1
  AND T1.C1=T2.C1
  AND T1.C1 BETWEEN :N1 AND :N2;

SELECT
  *
FROM
  TABLE(DBMS_XPLAN.DISPLAY_CURSOR(NULL,NULL,'ALLSTATS LAST'));

EXEC :N2:=10000

SELECT
  T3.C1,
  SUBSTR(T1.C2,1,10) T1_C2,
  SUBSTR(T2.C2,1,10) T2_C2
FROM
  T3,
  T2,
  T1
WHERE
  T1.C1=T3.C1
  AND T1.C1=T2.C1
  AND T1.C1 BETWEEN :N1 AND :N2;

SELECT
  T3.C1,
  SUBSTR(T1.C2,1,10) T1_C2,
  SUBSTR(T2.C2,1,10) T2_C2
FROM
  T3,
  T2,
  T1
WHERE
  T1.C1=T3.C1
  AND T1.C1=T2.C1
  AND T1.C1 BETWEEN :N1 AND :N2;

SELECT
  T3.C1,
  SUBSTR(T1.C2,1,10) T1_C2,
  SUBSTR(T2.C2,1,10) T2_C2
FROM
  T3,
  T2,
  T1
WHERE
  T1.C1=T3.C1
  AND T1.C1=T2.C1
  AND T1.C1 BETWEEN :N1 AND :N2;

SELECT
  *
FROM
  TABLE(DBMS_XPLAN.DISPLAY_CURSOR(NULL,NULL,'ALLSTATS LAST'));

EXEC :N2:=100000

SELECT
  T3.C1,
  SUBSTR(T1.C2,1,10) T1_C2,
  SUBSTR(T2.C2,1,10) T2_C2
FROM
  T3,
  T2,
  T1
WHERE
  T1.C1=T3.C1
  AND T1.C1=T2.C1
  AND T1.C1 BETWEEN :N1 AND :N2;

SELECT
  T3.C1,
  SUBSTR(T1.C2,1,10) T1_C2,
  SUBSTR(T2.C2,1,10) T2_C2
FROM
  T3,
  T2,
  T1
WHERE
  T1.C1=T3.C1
  AND T1.C1=T2.C1
  AND T1.C1 BETWEEN :N1 AND :N2;

SELECT
  T3.C1,
  SUBSTR(T1.C2,1,10) T1_C2,
  SUBSTR(T2.C2,1,10) T2_C2
FROM
  T3,
  T2,
  T1
WHERE
  T1.C1=T3.C1
  AND T1.C1=T2.C1
  AND T1.C1 BETWEEN :N1 AND :N2;

SELECT
  *
FROM
  TABLE(DBMS_XPLAN.DISPLAY_CURSOR(NULL,NULL,'ALLSTATS LAST'));

SPOOL OFF

The above script changes the OPTIMIZER_MODE and executes the same SQL statement with different bind variable values.  Once a couple of Statspack snapshots have been collected, we can see if any of the SQL statements in the Statspack snapshots have different execution plans with a SQL statement like the following (note that it probably would be wise to specify a range of Statspack snapshots, rather than looking at all snapshots):

SPOOL MultiplePlans.txt

SELECT
  SQL_ID,
  COUNT(DISTINCT PLAN_HASH_VALUE) C
FROM
  PERFSTAT.STATS$SQL_PLAN_USAGE
GROUP BY
  SQL_ID
HAVING
  COUNT(DISTINCT PLAN_HASH_VALUE)>1;

SPOOL OFF

The above SQL statement produced the following output:

SQL_ID                 C
------------- ----------
asc81p5ttbyf4          2
94bv1jwkzcc38          2
77z8bh7b87r1s          4
ga9j9xk5cy9s0          2
ddnbt67ftu9ds          2
0fr8zhn4ymu3v          2
cvn54b7yz0s8u          2
gjm43un5cy843          2
ff9zaqp3qfnah          2
gx4mv66pvj3xz          2
cvq22z77c8fww          3
a13qjgdbjcurr          2
1gu8t96d0bdmu          2
2x7j98pyk8ggm          2
8p3pacrbngv80          2
c6awqs517jpj0          2
cds8ys5zwkrpk          2
0u02w6ryqkg66          2
39m4sx9k63ba2          2
7ng34ruy5awxq          4
9dq71tc7vasgu          2
53saa2zkr6wc3          2
bsa0wjtftg3uw          2
cn5wthk738x0x          2
f3g84j69n0tjh          2
9nv4n7b54ph9a          2
0g5sb3zpqzss8          2

Interesting – we have a couple of SQL statements with 2 execution plans, one with 3 execution plans, and two with 4 execution plans.  Our SQL statement did not constrain the time periods to specific Statspack snapshots, so some of those execution plans may be very old.  Let’s take a look at the execution plans for one of those SQL statements (note that we are excluding the Predicate Information section and the Note section from the execution plans since those sections are not captured in a Statspack snapshot):

SET LINESIZE 150
SET PAGESIZE 10000
SPOOL StatspackPlan.txt

SELECT /*+ ORDERED */
  T.*
FROM
  (SELECT DISTINCT
    PLAN_HASH_VALUE
  FROM
    PERFSTAT.STATS$SQL_PLAN_USAGE
  WHERE
    SQL_ID='7ng34ruy5awxq'
  ORDER BY
    PLAN_HASH_VALUE) SPU,
  TABLE(DBMS_XPLAN.DISPLAY(
    'PERFSTAT.STATS$SQL_PLAN',
    NULL,
    'TYPICAL -PREDICATE -NOTE',
    'PLAN_HASH_VALUE='||SPU.PLAN_HASH_VALUE)) T;

SPOOL OFF

The output for the above SQL statement looks like this:

------------------------------------------------------------
| Id  | Operation                      | Name              |
------------------------------------------------------------
|   0 | SELECT STATEMENT               |                   |
|   1 |  MERGE JOIN OUTER              |                   |
|   2 |   SORT JOIN                    |                   |
|   3 |    NESTED LOOPS OUTER          |                   |
|   4 |     TABLE ACCESS CLUSTER       | IND$              |
|   5 |      INDEX UNIQUE SCAN         | I_OBJ#            |
|   6 |     TABLE ACCESS BY INDEX ROWID| IND_STATS$        |
|   7 |      INDEX UNIQUE SCAN         | I_IND_STATS$_OBJ# |
|   8 |   SORT JOIN                    |                   |
|   9 |    VIEW                        |                   |
|  10 |     SORT GROUP BY              |                   |
|  11 |      TABLE ACCESS CLUSTER      | CDEF$             |
|  12 |       INDEX UNIQUE SCAN        | I_COBJ#           |
------------------------------------------------------------

----------------------------------------------------------------------------------------------------
| Id  | Operation                      | Name              | Rows  | Bytes | Cost (%CPU)| Time     |
----------------------------------------------------------------------------------------------------
|   0 | SELECT STATEMENT               |                   |       |       |     7 (100)|          |
|   1 |  SORT ORDER BY                 |                   |     2 |   374 |     7  (43)| 00:00:01 |
|   2 |   HASH JOIN OUTER              |                   |     2 |   374 |     6  (34)| 00:00:01 |
|   3 |    NESTED LOOPS OUTER          |                   |     2 |   288 |     2   (0)| 00:00:01 |
|   4 |     TABLE ACCESS CLUSTER       | IND$              |     2 |   184 |     2   (0)| 00:00:01 |
|   5 |      INDEX UNIQUE SCAN         | I_OBJ#            |     1 |       |     1   (0)| 00:00:01 |
|   6 |     TABLE ACCESS BY INDEX ROWID| IND_STATS$        |     1 |    52 |     0   (0)|          |
|   7 |      INDEX UNIQUE SCAN         | I_IND_STATS$_OBJ# |     1 |       |     0   (0)|          |
|   8 |    VIEW                        |                   |     1 |    43 |     3  (34)| 00:00:01 |
|   9 |     SORT GROUP BY              |                   |     1 |    15 |     3  (34)| 00:00:01 |
|  10 |      TABLE ACCESS CLUSTER      | CDEF$             |     1 |    15 |     2   (0)| 00:00:01 |
|  11 |       INDEX UNIQUE SCAN        | I_COBJ#           |     1 |       |     1   (0)| 00:00:01 |
----------------------------------------------------------------------------------------------------

----------------------------------------------------------------------------------------------------
| Id  | Operation                      | Name              | Rows  | Bytes | Cost (%CPU)| Time     |
----------------------------------------------------------------------------------------------------
|   0 | SELECT STATEMENT               |                   |       |       |     5 (100)|          |
|   1 |  SORT GROUP BY                 |                   |     2 |   342 |     5  (20)| 00:00:01 |
|   2 |   NESTED LOOPS OUTER           |                   |     2 |   342 |     4   (0)| 00:00:01 |
|   3 |    NESTED LOOPS OUTER          |                   |     2 |   312 |     2   (0)| 00:00:01 |
|   4 |     TABLE ACCESS CLUSTER       | IND$              |     2 |   184 |     2   (0)| 00:00:01 |
|   5 |      INDEX UNIQUE SCAN         | I_OBJ#            |     1 |       |     1   (0)| 00:00:01 |
|   6 |     TABLE ACCESS BY INDEX ROWID| IND_STATS$        |     1 |    64 |     0   (0)|          |
|   7 |      INDEX UNIQUE SCAN         | I_IND_STATS$_OBJ# |     1 |       |     0   (0)|          |
|   8 |    TABLE ACCESS CLUSTER        | CDEF$             |     1 |    15 |     1   (0)| 00:00:01 |
|   9 |     INDEX UNIQUE SCAN          | I_COBJ#           |     1 |       |     0   (0)|          |
----------------------------------------------------------------------------------------------------

-----------------------------------------------------------------------------------------------------
| Id  | Operation                       | Name              | Rows  | Bytes | Cost (%CPU)| Time     |
-----------------------------------------------------------------------------------------------------
|   0 | SELECT STATEMENT                |                   |       |       |     7 (100)|          |
|   1 |  SORT ORDER BY                  |                   |     2 |   374 |     7  (43)| 00:00:01 |
|   2 |   HASH JOIN OUTER               |                   |     2 |   374 |     6  (34)| 00:00:01 |
|   3 |    NESTED LOOPS OUTER           |                   |     2 |   288 |     2   (0)| 00:00:01 |
|   4 |     TABLE ACCESS CLUSTER        | IND$              |     2 |   184 |     2   (0)| 00:00:01 |
|   5 |      INDEX UNIQUE SCAN          | I_OBJ#            |     1 |       |     1   (0)| 00:00:01 |
|   6 |     TABLE ACCESS BY INDEX ROWID | IND_STATS$        |     1 |    52 |     0   (0)|          |
|   7 |      INDEX UNIQUE SCAN          | I_IND_STATS$_OBJ# |     1 |       |     0   (0)|          |
|   8 |    VIEW                         |                   |     1 |    43 |     3  (34)| 00:00:01 |
|   9 |     SORT GROUP BY               |                   |     1 |    15 |     3  (34)| 00:00:01 |
|  10 |      TABLE ACCESS BY INDEX ROWID| CDEF$             |     1 |    15 |     2   (0)| 00:00:01 |
|  11 |       INDEX RANGE SCAN          | I_CDEF2           |     4 |       |     1   (0)| 00:00:01 |
----------------------------------------------------------------------------------------------------- 

Well, that is not the execution plan for the SQL statement that we executed, but it is interesting that one of Oracle’s internal SQL statements generated 4 different execution plans (one of which appears to have been created with the RULE optimizer mode, indicated by the abscence of the Cost column).  Let’s try again (note that the SQL_ID of interest was output in the DBMS_XPLAN output, but assume that we did not have that SQL_ID and did not want to query V$SQLAREA or V$SQL):

SET LINESIZE 150
SET PAGESIZE 10000
SPOOL StatspackPlan.txt

SELECT /*+ ORDERED */
  T.*
FROM
  (SELECT DISTINCT
    PLAN_HASH_VALUE
  FROM
    PERFSTAT.STATS$SQL_PLAN_USAGE
  WHERE
    SQL_ID='77z8bh7b87r1s'
  ORDER BY
    PLAN_HASH_VALUE) SPU,
  TABLE(DBMS_XPLAN.DISPLAY(
    'PERFSTAT.STATS$SQL_PLAN',
    NULL,
    'TYPICAL -PREDICATE -NOTE',
    'PLAN_HASH_VALUE='||SPU.PLAN_HASH_VALUE)) T;

SPOOL OFF

The above output the following:

-----------------------------------------------------------------------------------------------
| Id  | Operation                      | Name         | Rows  | Bytes | Cost (%CPU)| Time     |
-----------------------------------------------------------------------------------------------
|   0 | SELECT STATEMENT               |              |       |       |  1257 (100)|          |
|   1 |  FILTER                        |              |       |       |            |          |
|   2 |   HASH JOIN                    |              |    13 |  8762 |  1257   (1)| 00:00:16 |
|   3 |    TABLE ACCESS BY INDEX ROWID | T2           |  1000 |   138K|     4   (0)| 00:00:01 |
|   4 |     INDEX RANGE SCAN           | SYS_C0017308 |  1000 |       |     3   (0)| 00:00:01 |
|   5 |    NESTED LOOPS                |              |       |       |            |          |
|   6 |     NESTED LOOPS               |              |    13 |  3458 |  1253   (1)| 00:00:16 |
|   7 |      TABLE ACCESS FULL         | T3           |  1000 |  5000 |  1227   (1)| 00:00:15 |
|   8 |      INDEX UNIQUE SCAN         | SYS_C0017307 |     1 |       |     1   (0)| 00:00:01 |
|   9 |     TABLE ACCESS BY INDEX ROWID| T1           |     1 |   261 |     2   (0)| 00:00:01 |
-----------------------------------------------------------------------------------------------

--------------------------------------------------------------------------------------------------------
| Id  | Operation                       | Name         | Rows  | Bytes |TempSpc| Cost (%CPU)| Time     |
--------------------------------------------------------------------------------------------------------
|   0 | SELECT STATEMENT                |              |       |       |       | 15215 (100)|          |
|   1 |  FILTER                         |              |       |       |       |            |          |
|   2 |   HASH JOIN                     |              | 32260 |    12M|       | 15215   (1)| 00:03:03 |
|   3 |    TABLE ACCESS FULL            | T3           |   100K|   488K|       | 10214   (1)| 00:02:03 |
|   4 |    MERGE JOIN                   |              | 32260 |    12M|       |  4999   (1)| 00:01:00 |
|   5 |     TABLE ACCESS BY INDEX ROWID | T1           |   100K|    24M|       |  3897   (1)| 00:00:47 |
|   6 |      INDEX RANGE SCAN           | SYS_C0017307 |   100K|       |       |   191   (1)| 00:00:03 |
|   7 |     SORT JOIN                   |              | 32260 |  4473K|  9752K|  1103   (1)| 00:00:14 |
|   8 |      TABLE ACCESS BY INDEX ROWID| T2           | 32260 |  4473K|       |    80   (0)| 00:00:01 |
|   9 |       INDEX RANGE SCAN          | SYS_C0017308 | 32260 |       |       |    56   (0)| 00:00:01 |
--------------------------------------------------------------------------------------------------------

------------------------------------------------------------------------------------------------
| Id  | Operation                       | Name         | Rows  | Bytes | Cost (%CPU)| Time     |
------------------------------------------------------------------------------------------------
|   0 | SELECT STATEMENT                |              |       |       | 10217 (100)|          |
|   1 |  FILTER                         |              |       |       |            |          |
|   2 |   NESTED LOOPS                  |              |       |       |            |          |
|   3 |    NESTED LOOPS                 |              |    12 |  4896 | 10217   (1)| 00:02:03 |
|   4 |     NESTED LOOPS                |              |    12 |  3192 | 10216   (1)| 00:02:03 |
|   5 |      TABLE ACCESS FULL          | T3           |   100K|   488K| 10214   (1)| 00:02:03 |
|   6 |      TABLE ACCESS BY INDEX ROWID| T1           |     1 |   261 |     2   (0)| 00:00:01 |
|   7 |       INDEX UNIQUE SCAN         | SYS_C0017307 |     1 |       |     1   (0)| 00:00:01 |
|   8 |     INDEX UNIQUE SCAN           | SYS_C0017308 |     1 |       |     0   (0)|          |
|   9 |    TABLE ACCESS BY INDEX ROWID  | T2           |     1 |   142 |     1   (0)| 00:00:01 |
------------------------------------------------------------------------------------------------

-------------------------------------------------------------------------------------------------------
| Id  | Operation                      | Name         | Rows  | Bytes |TempSpc| Cost (%CPU)| Time     |
-------------------------------------------------------------------------------------------------------
|   0 | SELECT STATEMENT               |              |       |       |       | 10897 (100)|          |
|   1 |  FILTER                        |              |       |       |       |            |          |
|   2 |   HASH JOIN                    |              |  9998 |  3983K|       | 10897   (1)| 00:02:11 |
|   3 |    TABLE ACCESS FULL           | T3           | 10000 | 50000 |       | 10214   (1)| 00:02:03 |
|   4 |    HASH JOIN                   |              |  9999 |  3935K|  2432K|   682   (1)| 00:00:09 |
|   5 |     TABLE ACCESS BY INDEX ROWID| T2           | 16130 |  2236K|       |    41   (0)| 00:00:01 |
|   6 |      INDEX RANGE SCAN          | SYS_C0017308 | 16130 |       |       |    29   (0)| 00:00:01 |
|   7 |     TABLE ACCESS BY INDEX ROWID| T1           | 10000 |  2548K|       |   392   (0)| 00:00:05 |
|   8 |      INDEX RANGE SCAN          | SYS_C0017307 | 10000 |       |       |    21   (0)| 00:00:01 |
-------------------------------------------------------------------------------------------------------

That looks like the execution plans for our query, but were there only 4 different execution plans for our query (adaptive cursor sharing should have taken effect)?  Well, there were more than 4 child cursors created, but only 4 distinct execution plans.  Interesting.  In the above (reading from the top plan), we have the following join operations:

  • Nested Loops (between a table and an index for another table), Nested Loops, Hash Join
  • Sort – Merge Join, Hash Join
  • Nested Loops, Nested Loops, Nested Loops
  • Hash Join, Hash Join

The cost-based optimizer is quite clever.  OK, it is neat that Statspack is able to capture the execution plans, but without the predicate information, the execution plan information is a bit limited.  So, let’s take a look at the DBMS_XPLAN output that was captured during the run of our script, outputting the plan only when a new execution plan (or child cursor) is created:

SQL_ID  77z8bh7b87r1s, child number 0                        
-------------------------------------                        
SELECT   T3.C1,   SUBSTR(T1.C2,1,10) T1_C2,   SUBSTR(T2.C2,1,10) T2_C2                                   
FROM   T3,   T2,   T1 WHERE   T1.C1=T3.C1   AND T1.C1=T2.C1   AND T1.C1                                  
BETWEEN :N1 AND :N2                                          

Plan hash value: 1056058413                

----------------------------------------------------------------------------------------------------------
| Id  | Operation                       | Name         | Starts | E-Rows | A-Rows |   A-Time   | Buffers |
----------------------------------------------------------------------------------------------------------
|   0 | SELECT STATEMENT                |              |      1 |        |      1 |00:00:00.08 |   37173 |
|*  1 |  FILTER                         |              |      1 |        |      1 |00:00:00.08 |   37173 |
|   2 |   NESTED LOOPS                  |              |      1 |        |      1 |00:00:00.08 |   37173 |
|   3 |    NESTED LOOPS                 |              |      1 |      1 |      1 |00:00:00.08 |   37172 |
|   4 |     NESTED LOOPS                |              |      1 |      1 |      1 |00:00:00.08 |   37169 |
|*  5 |      TABLE ACCESS FULL          | T3           |      1 |      1 |      1 |00:00:00.08 |   37165 |
|   6 |      TABLE ACCESS BY INDEX ROWID| T1           |      1 |      1 |      1 |00:00:00.01 |       4 |
|*  7 |       INDEX UNIQUE SCAN         | SYS_C0017307 |      1 |      1 |      1 |00:00:00.01 |       3 |
|*  8 |     INDEX UNIQUE SCAN           | SYS_C0017308 |      1 |      1 |      1 |00:00:00.01 |       3 |
|   9 |    TABLE ACCESS BY INDEX ROWID  | T2           |      1 |      1 |      1 |00:00:00.01 |       1 |
----------------------------------------------------------------------------------------------------------

Predicate Information (identified by operation id):          
---------------------------------------------------          
   1 - filter(:N1<=:N2)                                      
   5 - filter(("T3"."C1"<=:N2 AND "T3"."C1">=:N1))           
   7 - access("T1"."C1"="T3"."C1")                           
       filter(("T1"."C1"<=:N2 AND "T1"."C1">=:N1))           
   8 - access("T1"."C1"="T2"."C1")                           
       filter(("T2"."C1">=:N1 AND "T2"."C1"<=:N2))           

Note             
-----            
   - dynamic sampling used for this statement (level=2)

-

SQL_ID  77z8bh7b87r1s, child number 1                        
-------------------------------------                        
SELECT   T3.C1,   SUBSTR(T1.C2,1,10) T1_C2,   SUBSTR(T2.C2,1,10) T2_C2                                   
FROM   T3,   T2,   T1 WHERE   T1.C1=T3.C1   AND T1.C1=T2.C1   AND T1.C1                                  
BETWEEN :N1 AND :N2                                          

Plan hash value: 2222254696                                  

------------------------------------------------------------------------------------------------------------------------------------
| Id  | Operation                      | Name         | Starts | E-Rows | A-Rows |   A-Time   | Buffers |  OMem |  1Mem | Used-Mem |
------------------------------------------------------------------------------------------------------------------------------------
|   0 | SELECT STATEMENT               |              |      1 |        |   1000 |00:00:00.08 |   37382 |       |       |          |
|*  1 |  FILTER                        |              |      1 |        |   1000 |00:00:00.08 |   37382 |       |       |          |
|*  2 |   HASH JOIN                    |              |      1 |    998 |   1000 |00:00:00.08 |   37382 |  1452K|  1452K| 1476K (0)|
|*  3 |    TABLE ACCESS FULL           | T3           |      1 |   1000 |   1000 |00:00:00.07 |   37164 |       |       |          |
|*  4 |    HASH JOIN                   |              |      1 |    999 |   1000 |00:00:00.01 |     218 |   830K|   830K| 1277K (0)|
|   5 |     TABLE ACCESS BY INDEX ROWID| T2           |      1 |   1000 |   1000 |00:00:00.01 |      42 |       |       |          |
|*  6 |      INDEX RANGE SCAN          | SYS_C0017308 |      1 |   1000 |   1000 |00:00:00.01 |       4 |       |       |          |
|   7 |     TABLE ACCESS BY INDEX ROWID| T1           |      1 |   1000 |   1000 |00:00:00.01 |     176 |       |       |          |
|*  8 |      INDEX RANGE SCAN          | SYS_C0017307 |      1 |   1000 |   1000 |00:00:00.01 |      71 |       |       |          |
------------------------------------------------------------------------------------------------------------------------------------

Predicate Information (identified by operation id):          
---------------------------------------------------          
   1 - filter(:N1<=:N2)  
   2 - access("T1"."C1"="T3"."C1")         
   3 - filter(("T3"."C1"<=:N2 AND "T3"."C1">=:N1))           
   4 - access("T1"."C1"="T2"."C1")         
   6 - access("T2"."C1">=:N1 AND "T2"."C1"<=:N2)             
   8 - access("T1"."C1">=:N1 AND "T1"."C1"<=:N2)             

Note             
-----            
   - dynamic sampling used for this statement (level=2)

-

SQL_ID  77z8bh7b87r1s, child number 2      
-------------------------------------      
SELECT   T3.C1,   SUBSTR(T1.C2,1,10) T1_C2,   SUBSTR(T2.C2,1,10) T2_C2
FROM   T3,   T2,   T1 WHERE   T1.C1=T3.C1   AND T1.C1=T2.C1   AND T1.C1                
BETWEEN :N1 AND :N2      

Plan hash value: 2222254696                                  

------------------------------------------------------------------------------------------------------------------------------------
| Id  | Operation                      | Name         | Starts | E-Rows | A-Rows |   A-Time   | Buffers |  OMem |  1Mem | Used-Mem |
------------------------------------------------------------------------------------------------------------------------------------
|   0 | SELECT STATEMENT               |              |      1 |        |  10000 |00:00:00.14 |   39279 |       |       |          |
|*  1 |  FILTER                        |              |      1 |        |  10000 |00:00:00.14 |   39279 |       |       |          |
|*  2 |   HASH JOIN                    |              |      1 |   9998 |  10000 |00:00:00.14 |   39279 |  1452K|  1452K| 1795K (0)|
|*  3 |    TABLE ACCESS FULL           | T3           |      1 |  10000 |  10000 |00:00:00.08 |   37164 |       |       |          |
|*  4 |    HASH JOIN                   |              |      1 |   9999 |  10000 |00:00:00.04 |    2115 |  3436K|   948K| 3949K (0)|
|   5 |     TABLE ACCESS BY INDEX ROWID| T2           |      1 |  16130 |  10000 |00:00:00.01 |     391 |       |       |          |
|*  6 |      INDEX RANGE SCAN          | SYS_C0017308 |      1 |  16130 |  10000 |00:00:00.01 |      20 |       |       |          |
|   7 |     TABLE ACCESS BY INDEX ROWID| T1           |      1 |  10000 |  10000 |00:00:00.01 |    1724 |       |       |          |
|*  8 |      INDEX RANGE SCAN          | SYS_C0017307 |      1 |  10000 |  10000 |00:00:00.01 |     686 |       |       |          |
------------------------------------------------------------------------------------------------------------------------------------

Predicate Information (identified by operation id):          
---------------------------------------------------          
   1 - filter(:N1<=:N2)  
   2 - access("T1"."C1"="T3"."C1")         
   3 - filter(("T3"."C1"<=:N2 AND "T3"."C1">=:N1))           
   4 - access("T1"."C1"="T2"."C1")         
   6 - access("T2"."C1">=:N1 AND "T2"."C1"<=:N2)             
   8 - access("T1"."C1">=:N1 AND "T1"."C1"<=:N2)             

Note             
-----            
   - dynamic sampling used for this statement (level=2)

-

SQL_ID  77z8bh7b87r1s, child number 3      
-------------------------------------      
SELECT   T3.C1,   SUBSTR(T1.C2,1,10) T1_C2,   SUBSTR(T2.C2,1,10) T2_C2
FROM   T3,   T2,   T1 WHERE   T1.C1=T3.C1   AND T1.C1=T2.C1   AND T1.C1                
BETWEEN :N1 AND :N2      

Plan hash value: 736968136                 

-------------------------------------------------------------------------------------------------------------------------------------
| Id  | Operation                       | Name         | Starts | E-Rows | A-Rows |   A-Time   | Buffers |  OMem |  1Mem | Used-Mem |
-------------------------------------------------------------------------------------------------------------------------------------
|   0 | SELECT STATEMENT                |              |      1 |        |    100K|00:00:01.02 |   58272 |       |       |          |
|*  1 |  FILTER                         |              |      1 |        |    100K|00:00:01.02 |   58272 |       |       |          |
|*  2 |   HASH JOIN                     |              |      1 |  32260 |    100K|00:00:00.97 |   58272 |  3838K|  1862K| 5510K (0)|
|*  3 |    TABLE ACCESS FULL            | T3           |      1 |    100K|    100K|00:00:00.09 |   37164 |       |       |          |
|   4 |    MERGE JOIN                   |              |      1 |  32260 |    100K|00:00:00.68 |   21108 |       |       |          |
|   5 |     TABLE ACCESS BY INDEX ROWID | T1           |      1 |    100K|    100K|00:00:00.22 |   17215 |       |       |          |
|*  6 |      INDEX RANGE SCAN           | SYS_C0017307 |      1 |    100K|    100K|00:00:00.06 |    6844 |       |       |          |
|*  7 |     SORT JOIN                   |              |    100K|  32260 |    100K|00:00:00.29 |    3893 |    30M|  1975K|   26M (0)|
|   8 |      TABLE ACCESS BY INDEX ROWID| T2           |      1 |  32260 |    100K|00:00:00.06 |    3893 |       |       |          |
|*  9 |       INDEX RANGE SCAN          | SYS_C0017308 |      1 |  32260 |    100K|00:00:00.02 |     189 |       |       |          |
-------------------------------------------------------------------------------------------------------------------------------------

Predicate Information (identified by operation id):          
---------------------------------------------------          
   1 - filter(:N1<=:N2)                                      
   2 - access("T1"."C1"="T3"."C1")                           
   3 - filter(("T3"."C1"<=:N2 AND "T3"."C1">=:N1))           
   6 - access("T1"."C1">=:N1 AND "T1"."C1"<=:N2)             
   7 - access("T1"."C1"="T2"."C1")                           
       filter("T1"."C1"="T2"."C1")                           
   9 - access("T2"."C1">=:N1 AND "T2"."C1"<=:N2)             

Note             
-----            
   - dynamic sampling used for this statement (level=2)

-

SQL_ID  77z8bh7b87r1s, child number 4                        
-------------------------------------                        
SELECT   T3.C1,   SUBSTR(T1.C2,1,10) T1_C2,   SUBSTR(T2.C2,1,10) T2_C2                                   
FROM   T3,   T2,   T1 WHERE   T1.C1=T3.C1   AND T1.C1=T2.C1   AND T1.C1                                  
BETWEEN :N1 AND :N2                                          

Plan hash value: 1056058413                                  

----------------------------------------------------------------------------------------------------------
| Id  | Operation                       | Name         | Starts | E-Rows | A-Rows |   A-Time   | Buffers |
----------------------------------------------------------------------------------------------------------
|   0 | SELECT STATEMENT                |              |      1 |        |    100 |00:00:00.07 |   37411 |
|*  1 |  FILTER                         |              |      1 |        |    100 |00:00:00.07 |   37411 |
|   2 |   NESTED LOOPS                  |              |      1 |        |    100 |00:00:00.07 |   37411 |
|   3 |    NESTED LOOPS                 |              |      1 |      1 |    100 |00:00:00.07 |   37311 |
|   4 |     NESTED LOOPS                |              |      1 |      1 |    100 |00:00:00.07 |   37291 |
|*  5 |      TABLE ACCESS FULL          | T3           |      1 |      1 |    100 |00:00:00.07 |   37171 |
|   6 |      TABLE ACCESS BY INDEX ROWID| T1           |    100 |      1 |    100 |00:00:00.01 |     120 |
|*  7 |       INDEX UNIQUE SCAN         | SYS_C0017307 |    100 |      1 |    100 |00:00:00.01 |      20 |
|*  8 |     INDEX UNIQUE SCAN           | SYS_C0017308 |    100 |      1 |    100 |00:00:00.01 |      20 |
|   9 |    TABLE ACCESS BY INDEX ROWID  | T2           |    100 |      1 |    100 |00:00:00.01 |     100 |
----------------------------------------------------------------------------------------------------------

Predicate Information (identified by operation id):          
---------------------------------------------------          
   1 - filter(:N1<=:N2)                                      
   5 - filter(("T3"."C1"<=:N2 AND "T3"."C1">=:N1))           
   7 - access("T1"."C1"="T3"."C1")                           
       filter(("T1"."C1"<=:N2 AND "T1"."C1">=:N1))           
   8 - access("T1"."C1"="T2"."C1")                           
       filter(("T2"."C1">=:N1 AND "T2"."C1"<=:N2))           

Note             
-----            
   - dynamic sampling used for this statement (level=2)

-

SQL_ID  77z8bh7b87r1s, child number 5                        
-------------------------------------                        
SELECT   T3.C1,   SUBSTR(T1.C2,1,10) T1_C2,   SUBSTR(T2.C2,1,10) T2_C2                                   
FROM   T3,   T2,   T1 WHERE   T1.C1=T3.C1   AND T1.C1=T2.C1   AND T1.C1                                  
BETWEEN :N1 AND :N2                                          

Plan hash value: 1056058413                                  

----------------------------------------------------------------------------------------------------------
| Id  | Operation                       | Name         | Starts | E-Rows | A-Rows |   A-Time   | Buffers |
----------------------------------------------------------------------------------------------------------
|   0 | SELECT STATEMENT                |              |      1 |        |   1000 |00:00:00.08 |   39469 |
|*  1 |  FILTER                         |              |      1 |        |   1000 |00:00:00.08 |   39469 |
|   2 |   NESTED LOOPS                  |              |      1 |        |   1000 |00:00:00.08 |   39469 |
|   3 |    NESTED LOOPS                 |              |      1 |      4 |   1000 |00:00:00.08 |   38469 |
|   4 |     NESTED LOOPS                |              |      1 |      4 |   1000 |00:00:00.08 |   38350 |
|*  5 |      TABLE ACCESS FULL          | T3           |      1 |   1000 |   1000 |00:00:00.08 |   37231 |
|   6 |      TABLE ACCESS BY INDEX ROWID| T1           |   1000 |      1 |   1000 |00:00:00.01 |    1119 |
|*  7 |       INDEX UNIQUE SCAN         | SYS_C0017307 |   1000 |      1 |   1000 |00:00:00.01 |     119 |
|*  8 |     INDEX UNIQUE SCAN           | SYS_C0017308 |   1000 |      1 |   1000 |00:00:00.01 |     119 |
|   9 |    TABLE ACCESS BY INDEX ROWID  | T2           |   1000 |      1 |   1000 |00:00:00.01 |    1000 |
----------------------------------------------------------------------------------------------------------

Predicate Information (identified by operation id):          
---------------------------------------------------          
   1 - filter(:N1<=:N2)                                      
   5 - filter(("T3"."C1"<=:N2 AND "T3"."C1">=:N1))           
   7 - access("T1"."C1"="T3"."C1")                           
       filter(("T1"."C1"<=:N2 AND "T1"."C1">=:N1))           
   8 - access("T1"."C1"="T2"."C1")                           
       filter(("T2"."C1">=:N1 AND "T2"."C1"<=:N2))           

Note             
-----            
   - dynamic sampling used for this statement (level=2)

-

SQL_ID  77z8bh7b87r1s, child number 6                        
-------------------------------------                        
SELECT   T3.C1,   SUBSTR(T1.C2,1,10) T1_C2,   SUBSTR(T2.C2,1,10) T2_C2                                   
FROM   T3,   T2,   T1 WHERE   T1.C1=T3.C1   AND T1.C1=T2.C1   AND T1.C1                                  
BETWEEN :N1 AND :N2                                          

Plan hash value: 1056058413                                  

----------------------------------------------------------------------------------------------------------
| Id  | Operation                       | Name         | Starts | E-Rows | A-Rows |   A-Time   | Buffers |
----------------------------------------------------------------------------------------------------------
|   0 | SELECT STATEMENT                |              |      1 |        |  10000 |00:00:00.21 |   63553 |
|*  1 |  FILTER                         |              |      1 |        |  10000 |00:00:00.21 |   63553 |
|   2 |   NESTED LOOPS                  |              |      1 |        |  10000 |00:00:00.20 |   63553 |
|   3 |    NESTED LOOPS                 |              |      1 |      3 |  10000 |00:00:00.17 |   53553 |
|   4 |     NESTED LOOPS                |              |      1 |      3 |  10000 |00:00:00.14 |   50692 |
|*  5 |      TABLE ACCESS FULL          | T3           |      1 |   6668 |  10000 |00:00:00.09 |   37831 |
|   6 |      TABLE ACCESS BY INDEX ROWID| T1           |  10000 |      1 |  10000 |00:00:00.04 |   12861 |
|*  7 |       INDEX UNIQUE SCAN         | SYS_C0017307 |  10000 |      1 |  10000 |00:00:00.02 |    2861 |
|*  8 |     INDEX UNIQUE SCAN           | SYS_C0017308 |  10000 |      1 |  10000 |00:00:00.02 |    2861 |
|   9 |    TABLE ACCESS BY INDEX ROWID  | T2           |  10000 |      1 |  10000 |00:00:00.02 |   10000 |
----------------------------------------------------------------------------------------------------------

Predicate Information (identified by operation id):          
---------------------------------------------------          
   1 - filter(:N1<=:N2)                                      
   5 - filter(("T3"."C1"<=:N2 AND "T3"."C1">=:N1))           
   7 - access("T1"."C1"="T3"."C1")                           
       filter(("T1"."C1"<=:N2 AND "T1"."C1">=:N1))           
   8 - access("T1"."C1"="T2"."C1")                           
       filter(("T2"."C1">=:N1 AND "T2"."C1"<=:N2))           

Note             
-----            
   - dynamic sampling used for this statement (level=2)

-

SQL_ID  77z8bh7b87r1s, child number 7                        
-------------------------------------                        
SELECT   T3.C1,   SUBSTR(T1.C2,1,10) T1_C2,   SUBSTR(T2.C2,1,10) T2_C2                                   
FROM   T3,   T2,   T1 WHERE   T1.C1=T3.C1   AND T1.C1=T2.C1   AND T1.C1                                  
BETWEEN :N1 AND :N2                                          

Plan hash value: 1056058413                                  

----------------------------------------------------------------------------------------------------------
| Id  | Operation                       | Name         | Starts | E-Rows | A-Rows |   A-Time   | Buffers |
----------------------------------------------------------------------------------------------------------
|   0 | SELECT STATEMENT                |              |      1 |        |    100K|00:00:01.45 |     316K|
|*  1 |  FILTER                         |              |      1 |        |    100K|00:00:01.45 |     316K|
|   2 |   NESTED LOOPS                  |              |      1 |        |    100K|00:00:01.39 |     316K|
|   3 |    NESTED LOOPS                 |              |      1 |      3 |    100K|00:00:01.07 |     216K|
|   4 |     NESTED LOOPS                |              |      1 |      9 |    100K|00:00:00.76 |     180K|
|*  5 |      TABLE ACCESS FULL          | T3           |      1 |    100K|    100K|00:00:00.16 |   43822 |
|   6 |      TABLE ACCESS BY INDEX ROWID| T1           |    100K|      1 |    100K|00:00:00.46 |     136K|
|*  7 |       INDEX UNIQUE SCAN         | SYS_C0017307 |    100K|      1 |    100K|00:00:00.20 |   36565 |
|*  8 |     INDEX UNIQUE SCAN           | SYS_C0017308 |    100K|      1 |    100K|00:00:00.17 |   36565 |
|   9 |    TABLE ACCESS BY INDEX ROWID  | T2           |    100K|      1 |    100K|00:00:00.18 |     100K|
----------------------------------------------------------------------------------------------------------

Predicate Information (identified by operation id):          
---------------------------------------------------          
   1 - filter(:N1<=:N2)                                      
   5 - filter(("T3"."C1"<=:N2 AND "T3"."C1">=:N1))           
   7 - access("T1"."C1"="T3"."C1")                           
       filter(("T1"."C1"<=:N2 AND "T1"."C1">=:N1))           
   8 - access("T1"."C1"="T2"."C1")                           
       filter(("T2"."C1">=:N1 AND "T2"."C1"<=:N2))           

Note             
-----            
   - dynamic sampling used for this statement (level=2)

-

SQL_ID  77z8bh7b87r1s, child number 8                        
-------------------------------------                        
SELECT   T3.C1,   SUBSTR(T1.C2,1,10) T1_C2,   SUBSTR(T2.C2,1,10) T2_C2                                   
FROM   T3,   T2,   T1 WHERE   T1.C1=T3.C1   AND T1.C1=T2.C1   AND T1.C1                                  
BETWEEN :N1 AND :N2                                          

Plan hash value: 1056058413                                  

----------------------------------------------------------------------------------------------------------
| Id  | Operation                       | Name         | Starts | E-Rows | A-Rows |   A-Time   | Buffers |
----------------------------------------------------------------------------------------------------------
|   0 | SELECT STATEMENT                |              |      1 |        |      1 |00:00:00.07 |   37173 |
|*  1 |  FILTER                         |              |      1 |        |      1 |00:00:00.07 |   37173 |
|   2 |   NESTED LOOPS                  |              |      1 |        |      1 |00:00:00.07 |   37173 |
|   3 |    NESTED LOOPS                 |              |      1 |      1 |      1 |00:00:00.07 |   37172 |
|   4 |     NESTED LOOPS                |              |      1 |      1 |      1 |00:00:00.07 |   37169 |
|*  5 |      TABLE ACCESS FULL          | T3           |      1 |      1 |      1 |00:00:00.07 |   37165 |
|   6 |      TABLE ACCESS BY INDEX ROWID| T1           |      1 |      1 |      1 |00:00:00.01 |       4 |
|*  7 |       INDEX UNIQUE SCAN         | SYS_C0017307 |      1 |      1 |      1 |00:00:00.01 |       3 |
|*  8 |     INDEX UNIQUE SCAN           | SYS_C0017308 |      1 |      1 |      1 |00:00:00.01 |       3 |
|   9 |    TABLE ACCESS BY INDEX ROWID  | T2           |      1 |      1 |      1 |00:00:00.01 |       1 |
----------------------------------------------------------------------------------------------------------

Predicate Information (identified by operation id):          
---------------------------------------------------          
   1 - filter(:N1<=:N2)                                      
   5 - filter(("T3"."C1"<=:N2 AND "T3"."C1">=:N1))           
   7 - access("T1"."C1"="T3"."C1")                           
       filter(("T1"."C1"<=:N2 AND "T1"."C1">=:N1))           
   8 - access("T1"."C1"="T2"."C1")                           
       filter(("T2"."C1">=:N1 AND "T2"."C1"<=:N2))           

Note             
-----            
   - dynamic sampling used for this statement (level=2)

-

SQL_ID  77z8bh7b87r1s, child number 9                        
-------------------------------------                        
SELECT   T3.C1,   SUBSTR(T1.C2,1,10) T1_C2,   SUBSTR(T2.C2,1,10) T2_C2                                   
FROM   T3,   T2,   T1 WHERE   T1.C1=T3.C1   AND T1.C1=T2.C1   AND T1.C1                                  
BETWEEN :N1 AND :N2                                          

Plan hash value: 300618627                                   

------------------------------------------------------------------------------------------------------------------------------------
| Id  | Operation                      | Name         | Starts | E-Rows | A-Rows |   A-Time   | Buffers |  OMem |  1Mem | Used-Mem |
------------------------------------------------------------------------------------------------------------------------------------
|   0 | SELECT STATEMENT               |              |      1 |        |    100 |00:00:00.07 |   37298 |       |       |          |
|*  1 |  FILTER                        |              |      1 |        |    100 |00:00:00.07 |   37298 |       |       |          |
|*  2 |   HASH JOIN                    |              |      1 |     13 |    100 |00:00:00.07 |   37298 |   711K|   711K| 1272K (0)|
|   3 |    TABLE ACCESS BY INDEX ROWID | T2           |      1 |    100 |    100 |00:00:00.01 |       7 |       |       |          |
|*  4 |     INDEX RANGE SCAN           | SYS_C0017308 |      1 |    100 |    100 |00:00:00.01 |       3 |       |       |          |
|   5 |    NESTED LOOPS                |              |      1 |        |    100 |00:00:00.07 |   37291 |       |       |          |
|   6 |     NESTED LOOPS               |              |      1 |     13 |    100 |00:00:00.07 |   37191 |       |       |          |
|*  7 |      TABLE ACCESS FULL         | T3           |      1 |    100 |    100 |00:00:00.07 |   37171 |       |       |          |
|*  8 |      INDEX UNIQUE SCAN         | SYS_C0017307 |    100 |      1 |    100 |00:00:00.01 |      20 |       |       |          |
|   9 |     TABLE ACCESS BY INDEX ROWID| T1           |    100 |      1 |    100 |00:00:00.01 |     100 |       |       |          |
------------------------------------------------------------------------------------------------------------------------------------

Predicate Information (identified by operation id):          
---------------------------------------------------          
   1 - filter(:N1<=:N2)                                      
   2 - access("T1"."C1"="T2"."C1")                           
   4 - access("T2"."C1">=:N1 AND "T2"."C1"<=:N2)             
   7 - filter(("T3"."C1"<=:N2 AND "T3"."C1">=:N1))           
   8 - access("T1"."C1"="T3"."C1")                           
       filter(("T1"."C1"<=:N2 AND "T1"."C1">=:N1))           

Note             
-----            
   - dynamic sampling used for this statement (level=2)

Notice that the Note section states that dynamic sampling at level 2 was performed – it does not state that it was only performed on table T2 (because statistics were not collected on that table).

It might be fun to take a look at V$SQL_SHARED_CURSOR for this SQL_ID.  The columns in that view tell why a child cursor was created, the following was generated with the DESC V$SQL_SHARED_CURSOR command:

 Name                         
 ------------------------------
 UNBOUND_CURSOR               
 SQL_TYPE_MISMATCH            
 OPTIMIZER_MISMATCH           
 OUTLINE_MISMATCH             
 STATS_ROW_MISMATCH           
 LITERAL_MISMATCH             
 FORCE_HARD_PARSE             
 EXPLAIN_PLAN_CURSOR          
 BUFFERED_DML_MISMATCH        
 PDML_ENV_MISMATCH            
 INST_DRTLD_MISMATCH          
 SLAVE_QC_MISMATCH            
 TYPECHECK_MISMATCH           
 AUTH_CHECK_MISMATCH          
 BIND_MISMATCH                
 DESCRIBE_MISMATCH            
 LANGUAGE_MISMATCH            
 TRANSLATION_MISMATCH         
 BIND_EQUIV_FAILURE           
 INSUFF_PRIVS                 
 INSUFF_PRIVS_REM             
 REMOTE_TRANS_MISMATCH        
 LOGMINER_SESSION_MISMATCH    
 INCOMP_LTRL_MISMATCH         
 OVERLAP_TIME_MISMATCH        
 EDITION_MISMATCH             
 MV_QUERY_GEN_MISMATCH        
 USER_BIND_PEEK_MISMATCH      
 TYPCHK_DEP_MISMATCH          
 NO_TRIGGER_MISMATCH          
 FLASHBACK_CURSOR             
 ANYDATA_TRANSFORMATION       
 INCOMPLETE_CURSOR            
 TOP_LEVEL_RPI_CURSOR         
 DIFFERENT_LONG_LENGTH        
 LOGICAL_STANDBY_APPLY        
 DIFF_CALL_DURN               
 BIND_UACS_DIFF               
 PLSQL_CMP_SWITCHS_DIFF       
 CURSOR_PARTS_MISMATCH        
 STB_OBJECT_MISMATCH          
 CROSSEDITION_TRIGGER_MISMATCH
 PQ_SLAVE_MISMATCH            
 TOP_LEVEL_DDL_MISMATCH       
 MULTI_PX_MISMATCH            
 BIND_PEEKED_PQ_MISMATCH      
 MV_REWRITE_MISMATCH          
 ROLL_INVALID_MISMATCH        
 OPTIMIZER_MODE_MISMATCH      
 PX_MISMATCH                  
 MV_STALEOBJ_MISMATCH         
 FLASHBACK_TABLE_MISMATCH     
 LITREP_COMP_MISMATCH         
 PLSQL_DEBUG                  
 LOAD_OPTIMIZER_STATS         
 ACL_MISMATCH                 
 FLASHBACK_ARCHIVE_MISMATCH   
 LOCK_USER_SCHEMA_FAILED      
 REMOTE_MAPPING_MISMATCH      
 LOAD_RUNTIME_HEAP_FAILED     
 HASH_MATCH_FAILED            
 PURGED_CURSOR                
 BIND_LENGTH_UPGRADEABLE

Oracle Database 11.2.0.1 certainly has a lot of potential reasons established for creating additional child cursors.  So, what is the reason for the child cursors in our test (at least the ones that are still in the library cache after executing the script several times)?

CN USOOSLFEBPISTABDLTBIIRLIOEMUTNFAITDLDBPCSCPTMBMROPMFLPLAFLRLHPB
-- ---------------------------------------------------------------
 0 NNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNYNNNNNNNN
 1 NNNNNNNNNNNNNNNNNNYNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNN
 2 NNNNNNNNNNNNNNNNNNYNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNN
 3 NNNNNNNNNNNNNNNNNNYNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNN
 4 NNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNYNNNNNYNNNNNNNN
 5 NNNNNNNNNNNNNNNNNNYNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNN
 6 NNNNNNNNNNNNNNNNNNYNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNN
 7 NNNNNNNNNNNNNNNNNNYNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNN
 8 NNNNNNNNNNNNNNNNNNYNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNN
 9 NNNNNNNNNNNNNNNNNNYNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNN

From the above, the reasons are: L (LOAD_OPTIMIZER_STATS), B (BIND_EQUIV_FAILURE), O (OPTIMIZER_MODE_MISMATCH).








Follow

Get every new post delivered to your Inbox.

Join 137 other followers