Consistent Gets During a Hard Parse – a Test Case to See One Possible Cause

7 10 2010

October 7, 2010

A recent OTN thread caught my attention.  The original poster noticed that when generating a TKPROF summary from a 10046 trace file that the parse call showed a significant number of consistent gets when compared to the fetch and execute calls.  The TKPROF summary looked something like this:

call     count       cpu    elapsed       disk      query    current        rows
------- ------  -------- ---------- ---------- ---------- ----------  ----------
Parse        4      0.85       1.07          0       3599          0           0
Execute      4      0.00       0.00          0          0          0           0
Fetch        4      0.01       0.05         14         36          0           4
------- ------  -------- ---------- ---------- ---------- ----------  ----------
total       12      0.86       1.13         14       3635          0           4

Misses in library cache during parse: 4
Optimizer mode: ALL_ROWS
Parsing user id: 72 

Rows     Row Source Operation
-------  ---------------------------------------------------
      1  NESTED LOOPS  (cr=9 pr=8 pw=0 time=33821 us)
      1   TABLE ACCESS BY INDEX ROWID STATUS (cr=2 pr=2 pw=0 time=21787 us)
      1    INDEX UNIQUE SCAN STATUS_CON21 (cr=1 pr=1 pw=0 time=20957 us)(object id 58618)
      1   TABLE ACCESS FULL USER_ACCOUNT (cr=7 pr=6 pw=0 time=11978 us)

The TKPROF summary showed that there were 3,599 consistent gets during the four times that this SQL statement was hard parsed, while there were only 36 consistent gets performed during the four executions and fetches.  The displayed Row Source Operation execution plan shows that 9 consistent gets were performed, and because that number is 1/4 of the value displayed by the TKPROF  summary (the SQL statement was executed four times), that likely indicates that the OP is running Oracle Database 11.1.0.6 or greater, which by default outputs the STAT lines (TKPROF Row Source Operation lines) to the trace file after every execution.

How could this SQL statement perform an average of 900 consistent gets per hard parse, and only an average of 9 consistent gets to retrieve the rows from the two tables listed in the SQL statement?  This is probably a good excuse to build a test case to try out a couple of ideas.  A couple of good suggestions were offered in the OTN thread regarding what may cause consistent gets during a hard parse, but 900 consistent gets?  The OP mentioned that this problem is happening in a development database, and that may be a key clue.  What if the OP creates a couple of tables with a couple of indexes, and then loads data into the tables just before executing his SQL statement?  If the OPTIMIZER_MODE is set to the deprecated values of RULE or CHOOSE we could very well see one result for the number of consistent gets, which differs from what happens when the OPTIMIZER_MODE is set to a non-deprecated value.  What if the OP does not collect statistics on the tables and indexes, and those tables and indexes either do not survive until 10 PM or the DBA has disabled the automatic stale statistics collection job that typically starts around 10 PM?  What if the memory allocated to the SGA is much smaller than what is needed?  What if… (fill in the blank)?

Let’s build a quick test case.  First, we will make certain that no one has adjusted the default value for dynamic sampling:

SHOW PARAMETER DYNAMIC_SAMPLING

NAME                                 TYPE        VALUE
------------------------------------ ----------- -----
optimizer_dynamic_sampling           integer     2

Still the default, so we will continue building the test case on Oracle Database 11.1.0.7:

CREATE TABLE T1 (
  C1 NUMBER NOT NULL,
  C2 VARCHAR2(20) NOT NULL,
  C3 VARCHAR2(100));

CREATE INDEX IND_T1_C1 ON T1(C1);
CREATE INDEX IND_T1_C2 ON T1(C2);

CREATE TABLE T2 (
  C1 NUMBER NOT NULL,
  C2 VARCHAR2(20) NOT NULL,
  C3 VARCHAR2(100));

CREATE INDEX IND_T2_C1 ON T2(C1);
CREATE INDEX IND_T2_C2 ON T2(C2); 

The above creates two simple tables, each with two indexes.  Note that the indexes are created before the tables contain any rows, so statistics are not automatically collected for the indexes when they are created.  Now to insert the rows:

INSERT INTO
  T1
SELECT
  ROWNUM,
  RPAD(TO_CHAR(ROWNUM),20,'A'),
  RPAD(TO_CHAR(ROWNUM),100,'B')
FROM
  DUAL
CONNECT BY
  LEVEL<=100000;

COMMIT;

INSERT INTO
  T2
SELECT
  *
FROM
  T1;

COMMIT;

Just to verify that the indexes do not have statistics:

COLUMN INDEX_NAME FORMAT A10

SELECT
  INDEX_NAME,
  BLEVEL,
  NUM_ROWS,
  LEAF_BLOCKS
FROM
  USER_INDEXES
WHERE
  INDEX_NAME IN ('IND_T1_C1','IND_T2_C1','IND_T1_C2','IND_T2_C2');

INDEX_NAME     BLEVEL   NUM_ROWS LEAF_BLOCKS
---------- ---------- ---------- -----------
IND_T1_C1
IND_T1_C2
IND_T2_C1
IND_T2_C2 

Now for the experiment:

ALTER SESSION SET TRACEFILE_IDENTIFIER = 'PARSE_TEST1';
ALTER SESSION SET EVENTS '10046 TRACE NAME CONTEXT FOREVER, LEVEL 1';

SET AUTOTRACE TRACEONLY STATISTICS

SELECT /* PARSE_TEST1 */
  T1.C1 T1_C1,
  SUBSTR(T1.C3,1,10) T1_C3,
  T2.C2 T2_C2,
  SUBSTR(T2.C3,1,10) T2_C3
FROM
  T1,
  T2
WHERE
  T1.C1=T2.C1
  AND T1.C1<=2000;

Statistics
---------------------------------------------------
         17  recursive calls
          0  db block gets
        514  consistent gets
         15  physical reads
          0  redo size
     113831  bytes sent via SQL*Net to client
       1844  bytes received via SQL*Net from client
        135  SQL*Net roundtrips to/from client
          2  sorts (memory)
          0  sorts (disk)
       2000  rows processed 

Note in the above that there were 514 consistent gets to retrieve 2,000 rows (15 rows at a time because of the default array fetch size in SQL*Plus).  Continuing with the test:

ALTER SESSION SET TRACEFILE_IDENTIFIER = 'PARSE_TEST2';

SELECT /* PARSE_TEST2 */
  T1.C1 T1_C1,
  SUBSTR(T1.C3,1,10) T1_C3,
  T2.C2 T2_C2,
  SUBSTR(T2.C3,1,10) T2_C3
FROM
  T1,
  T2
WHERE
  T1.C1=T2.C1
  AND T1.C1 BETWEEN 2001 AND 4000;

Statistics
---------------------------------------------------
         17  recursive calls
          0  db block gets
        560  consistent gets
         79  physical reads
       3276  redo size
     113930  bytes sent via SQL*Net to client
       1844  bytes received via SQL*Net from client
        135  SQL*Net roundtrips to/from client
          2  sorts (memory)
          0  sorts (disk)
       2000  rows processed 

Note in the above that there were 560 consistent gets to retrieve 2,000 rows.  Continuing with the test:

ALTER SESSION SET TRACEFILE_IDENTIFIER = 'PARSE_TEST3';

SELECT /* PARSE_TEST3 */
  T1.C1 T1_C1,
  SUBSTR(T1.C3,1,10) T1_C3,
  T2.C2 T2_C2,
  SUBSTR(T2.C3,1,10) T2_C3
FROM
  T1,
  T2
WHERE
  T1.C1=T2.C1
  AND T1.C1 BETWEEN 4001 AND 6000;

Statistics
---------------------------------------------------
         13  recursive calls
          0  db block gets
        568  consistent gets
        102  physical reads
       3564  redo size
     113930  bytes sent via SQL*Net to client
       1844  bytes received via SQL*Net from client
        135  SQL*Net roundtrips to/from client
          2  sorts (memory)
          0  sorts (disk)
       2000  rows processed 

Note in the above that there were 568 consistent gets to retrieve 2,000 rows.  Continuing with the test:

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

SELECT /* PARSE_TEST3 */
  T1.C1 T1_C1,
  SUBSTR(T1.C3,1,10) T1_C3,
  T2.C2 T2_C2,
  SUBSTR(T2.C3,1,10) T2_C3
FROM
  T1,
  T2
WHERE
  T1.C1=T2.C1
  AND T1.C1 BETWEEN 4001 AND 6000;

Statistics
---------------------------------------------------
         17  recursive calls
          0  db block gets
        520  consistent gets
          8  physical reads
          0  redo size
     113930  bytes sent via SQL*Net to client
       1844  bytes received via SQL*Net from client
        135  SQL*Net roundtrips to/from client
          2  sorts (memory)
          0  sorts (disk)
       2000  rows processed 

Note that in the above that there was another hard parse.

Now let’s take a look in the trace files (see this three part blog article series for help with decoding 10046 trace files), starting with the PARSE_TEST1 trace file (note that I manually line wrapped the dep=1 SQL statements):

...
=====================
PARSING IN CURSOR #4 len=619 dep=1 uid=60 oct=3 lid=60 tim=517854252962 hv=1052836258 ad='224c0738' sqlid='dwa1q5szc20d2'
SELECT /* OPT_DYN_SAMP */ /*+ ALL_ROWS IGNORE_WHERE_CLAUSE NO_PARALLEL(SAMPLESUB) opt_param('parallel_execution_enabled',
 'false') NO_PARALLEL_INDEX(SAMPLESUB) NO_SQL_TUNE */ NVL(SUM(C1),:"SYS_B_00"), NVL(SUM(C2),:"SYS_B_01"), COUNT(DISTINCT C3),
 NVL(SUM(CASE WHEN C3 IS NULL THEN :"SYS_B_02" ELSE :"SYS_B_03" END),:"SYS_B_04") FROM (SELECT /*+ IGNORE_WHERE_CLAUSE
 NO_PARALLEL("T1") FULL("T1") NO_PARALLEL_INDEX("T1") */ :"SYS_B_05" AS C1, CASE WHEN "T1"."C1"<=:"SYS_B_06" THEN :"SYS_B_07"
 ELSE :"SYS_B_08" END AS C2, "T1"."C1" AS C3 FROM "T1" SAMPLE BLOCK (:"SYS_B_09" , :"SYS_B_10") SEED (:"SYS_B_11") "T1") SAMPLESUB
END OF STMT
PARSE #4:c=0,e=0,p=0,cr=0,cu=0,mis=1,r=0,dep=1,og=1,plh=0,tim=517854252962
EXEC #4:c=0,e=0,p=0,cr=0,cu=0,mis=1,r=0,dep=1,og=1,plh=3906273573,tim=517854252962
FETCH #4:c=0,e=0,p=0,cr=71,cu=0,mis=0,r=1,dep=1,og=1,plh=3906273573,tim=517854252962
STAT #4 id=1 cnt=1 pid=0 pos=1 obj=0 op='SORT GROUP BY (cr=71 pr=0 pw=0 time=0 us)'
STAT #4 id=2 cnt=3410 pid=1 pos=1 obj=102003 op='TABLE ACCESS SAMPLE T1 (cr=71 pr=0 pw=0 time=0 us cost=2 size=75 card=3)'
CLOSE #4:c=0,e=0,dep=1,type=0,tim=517854252962
=====================
PARSING IN CURSOR #2 len=445 dep=1 uid=60 oct=3 lid=60 tim=517854252962 hv=840679737 ad='285dce70' sqlid='2r4a0g8t1rh9t'
SELECT /* OPT_DYN_SAMP */ /*+ ALL_ROWS opt_param('parallel_execution_enabled', 'false') NO_PARALLEL(SAMPLESUB)
 NO_PARALLEL_INDEX(SAMPLESUB) NO_SQL_TUNE */ NVL(SUM(C1),:"SYS_B_0"), NVL(SUM(C2),:"SYS_B_1"), NVL(SUM(C3),:"SYS_B_2") FROM
 (SELECT /*+ NO_PARALLEL("T1") INDEX("T1" IND_T1_C1) NO_PARALLEL_INDEX("T1") */ :"SYS_B_3" AS C1, :"SYS_B_4" AS C2, :"SYS_B_5" AS C3
  FROM "T1" "T1" WHERE "T1"."C1"<=:"SYS_B_6" AND ROWNUM <= :"SYS_B_7") SAMPLESUB
END OF STMT
PARSE #2:c=0,e=0,p=0,cr=0,cu=0,mis=1,r=0,dep=1,og=1,plh=0,tim=517854252962
EXEC #2:c=0,e=0,p=0,cr=0,cu=0,mis=1,r=0,dep=1,og=1,plh=311010773,tim=517854252962
FETCH #2:c=0,e=0,p=0,cr=5,cu=0,mis=0,r=1,dep=1,og=1,plh=311010773,tim=517854252962
STAT #2 id=1 cnt=1 pid=0 pos=1 obj=0 op='SORT AGGREGATE (cr=5 pr=0 pw=0 time=0 us)'
STAT #2 id=2 cnt=2000 pid=1 pos=1 obj=0 op='VIEW  (cr=5 pr=0 pw=0 time=0 us cost=12 size=390 card=10)'
STAT #2 id=3 cnt=2000 pid=2 pos=1 obj=0 op='COUNT STOPKEY (cr=5 pr=0 pw=0 time=0 us)'
STAT #2 id=4 cnt=2000 pid=3 pos=1 obj=102004 op='INDEX RANGE SCAN IND_T1_C1 (cr=5 pr=0 pw=0 time=0 us cost=12 size=429 card=33)'
CLOSE #2:c=0,e=0,dep=1,type=0,tim=517854252962
=====================
PARSING IN CURSOR #6 len=619 dep=1 uid=60 oct=3 lid=60 tim=517854252962 hv=3874662801 ad='224bb3a0' sqlid='0qdcdrrmg5acj'
SELECT /* OPT_DYN_SAMP */ /*+ ALL_ROWS IGNORE_WHERE_CLAUSE NO_PARALLEL(SAMPLESUB) opt_param('parallel_execution_enabled', 'false')
 NO_PARALLEL_INDEX(SAMPLESUB) NO_SQL_TUNE */ NVL(SUM(C1),:"SYS_B_00"), NVL(SUM(C2),:"SYS_B_01"), COUNT(DISTINCT C3),
 NVL(SUM(CASE WHEN C3 IS NULL THEN :"SYS_B_02" ELSE :"SYS_B_03" END),:"SYS_B_04") FROM (SELECT /*+ IGNORE_WHERE_CLAUSE NO_PARALLEL("T2")
 FULL("T2") NO_PARALLEL_INDEX("T2") */ :"SYS_B_05" AS C1, CASE WHEN "T2"."C1"<=:"SYS_B_06" THEN :"SYS_B_07" ELSE :"SYS_B_08" END AS C2,
 "T2"."C1" AS C3 FROM "T2" SAMPLE BLOCK (:"SYS_B_09" , :"SYS_B_10") SEED (:"SYS_B_11") "T2") SAMPLESUB
END OF STMT
PARSE #6:c=0,e=0,p=0,cr=0,cu=0,mis=1,r=0,dep=1,og=1,plh=0,tim=517854252962
EXEC #6:c=0,e=0,p=0,cr=0,cu=0,mis=1,r=0,dep=1,og=1,plh=724732973,tim=517854252962
FETCH #6:c=0,e=31245,p=15,cr=71,cu=0,mis=0,r=1,dep=1,og=1,plh=724732973,tim=517854284207
STAT #6 id=1 cnt=1 pid=0 pos=1 obj=0 op='SORT GROUP BY (cr=71 pr=15 pw=0 time=0 us)'
STAT #6 id=2 cnt=3420 pid=1 pos=1 obj=102006 op='TABLE ACCESS SAMPLE T2 (cr=71 pr=15 pw=0 time=0 us cost=2 size=75 card=3)'
CLOSE #6:c=0,e=0,dep=1,type=0,tim=517854284207
=====================
PARSING IN CURSOR #5 len=445 dep=1 uid=60 oct=3 lid=60 tim=517854284207 hv=2421073910 ad='1f4973fc' sqlid='b84x6ja84x9zq'
SELECT /* OPT_DYN_SAMP */ /*+ ALL_ROWS opt_param('parallel_execution_enabled', 'false') NO_PARALLEL(SAMPLESUB) NO_PARALLEL_INDEX(SAMPLESUB)
 NO_SQL_TUNE */ NVL(SUM(C1),:"SYS_B_0"), NVL(SUM(C2),:"SYS_B_1"), NVL(SUM(C3),:"SYS_B_2") FROM (SELECT /*+ NO_PARALLEL("T2")
 INDEX("T2" IND_T2_C1) NO_PARALLEL_INDEX("T2") */ :"SYS_B_3" AS C1, :"SYS_B_4" AS C2, :"SYS_B_5" AS C3  FROM "T2" "T2" WHERE
 "T2"."C1"<=:"SYS_B_6" AND ROWNUM <= :"SYS_B_7") SAMPLESUB
END OF STMT
PARSE #5:c=0,e=0,p=0,cr=0,cu=0,mis=1,r=0,dep=1,og=1,plh=0,tim=517854284207
EXEC #5:c=0,e=0,p=0,cr=0,cu=0,mis=1,r=0,dep=1,og=1,plh=1821698049,tim=517854284207
FETCH #5:c=0,e=0,p=0,cr=8,cu=0,mis=0,r=1,dep=1,og=1,plh=1821698049,tim=517854284207
STAT #5 id=1 cnt=1 pid=0 pos=1 obj=0 op='SORT AGGREGATE (cr=8 pr=0 pw=0 time=0 us)'
STAT #5 id=2 cnt=2000 pid=1 pos=1 obj=0 op='VIEW  (cr=8 pr=0 pw=0 time=0 us cost=12 size=390 card=10)'
STAT #5 id=3 cnt=2000 pid=2 pos=1 obj=0 op='COUNT STOPKEY (cr=8 pr=0 pw=0 time=0 us)'
STAT #5 id=4 cnt=2000 pid=3 pos=1 obj=102007 op='INDEX RANGE SCAN IND_T2_C1 (cr=8 pr=0 pw=0 time=0 us cost=12 size=429 card=33)'
CLOSE #5:c=0,e=0,dep=1,type=0,tim=517854284207
=====================
PARSING IN CURSOR #3 len=163 dep=0 uid=60 oct=3 lid=60 tim=517854284207 hv=701515739 ad='1f4849dc' sqlid='dr1pvrsnx0jyv'
SELECT /* PARSE_TEST1 */
  T1.C1 T1_C1,
  SUBSTR(T1.C3,1,10) T1_C3,
  T2.C2 T2_C2,
  SUBSTR(T2.C3,1,10) T2_C3
FROM
  T1,
  T2
WHERE
  T1.C1=T2.C1
  AND T1.C1<=2000
END OF STMT
PARSE #3:c=0,e=31245,p=15,cr=159,cu=0,mis=1,r=0,dep=0,og=1,plh=169351222,tim=517854284207
EXEC #3:c=0,e=0,p=0,cr=0,cu=0,mis=0,r=0,dep=0,og=1,plh=169351222,tim=517854284207
FETCH #3:c=15625,e=31263,p=0,cr=45,cu=0,mis=0,r=1,dep=0,og=1,plh=169351222,tim=517854315470
FETCH #3:c=0,e=0,p=0,cr=2,cu=0,mis=0,r=15,dep=0,og=1,plh=169351222,tim=517854315470
...
FETCH #3:c=0,e=0,p=0,cr=2,cu=0,mis=0,r=4,dep=0,og=1,plh=169351222,tim=517854346714
STAT #3 id=1 cnt=2000 pid=0 pos=1 obj=0 op='HASH JOIN  (cr=355 pr=0 pw=0 time=0 us cost=48 size=284000 card=2000)'
STAT #3 id=2 cnt=2000 pid=1 pos=1 obj=102003 op='TABLE ACCESS BY INDEX ROWID T1 (cr=42 pr=0 pw=0 time=0 us cost=22 size=130000 card=2000)'
STAT #3 id=3 cnt=2000 pid=2 pos=1 obj=102004 op='INDEX RANGE SCAN IND_T1_C1 (cr=5 pr=0 pw=0 time=0 us cost=6 size=0 card=2000)'
STAT #3 id=4 cnt=2000 pid=1 pos=2 obj=102006 op='TABLE ACCESS BY INDEX ROWID T2 (cr=313 pr=0 pw=0 time=0 us cost=25 size=154000 card=2000)'
STAT #3 id=5 cnt=2000 pid=4 pos=1 obj=102007 op='INDEX RANGE SCAN IND_T2_C1 (cr=142 pr=0 pw=0 time=0 us cost=9 size=0 card=2000)' 

In the above, you will notice that the parse call for our SQL statement performed 159 consistent gets.  If you add up the number of consistent gets performed by the dep=1 SQL statements that immediately preceed our SQL statement (71 + 5 + 71 + 8), you can see where 155 consistent gets were performed during the hard parse.  The first STAT line shows that the SQL statement actually required 355 consistent gets and no physical reads (SQL*Plus showed that 514 consistent gets and 15 physical reads were performed, and if you look closely at the dep=1 SQL statement you can see where the 15 physical block reads were performed).  355 + 155 = 510, which is just less than the 514 consistent gets reported by SQL*Plus, so we could look further up in the trace file to find the remaining 4 consistent gets.

Let’s take a look at the PARSE_TEST3 trace file:

...
=====================
PARSING IN CURSOR #3 len=646 dep=1 uid=60 oct=3 lid=60 tim=518053123679 hv=1391468433 ad='2264adec' sqlid='16htvx19g07wj'
SELECT /* OPT_DYN_SAMP */ /*+ ALL_ROWS IGNORE_WHERE_CLAUSE NO_PARALLEL(SAMPLESUB) opt_param('parallel_execution_enabled', 'false')
 NO_PARALLEL_INDEX(SAMPLESUB) NO_SQL_TUNE */ NVL(SUM(C1),:"SYS_B_00"), NVL(SUM(C2),:"SYS_B_01"), COUNT(DISTINCT C3),
 NVL(SUM(CASE WHEN C3 IS NULL THEN :"SYS_B_02" ELSE :"SYS_B_03" END),:"SYS_B_04") FROM (SELECT /*+ IGNORE_WHERE_CLAUSE NO_PARALLEL("T1")
 FULL("T1") NO_PARALLEL_INDEX("T1") */ :"SYS_B_05" AS C1, CASE WHEN "T1"."C1">=:"SYS_B_06" AND "T1"."C1"<=:"SYS_B_07" THEN :"SYS_B_08"
 ELSE :"SYS_B_09" END AS C2, "T1"."C1" AS C3 FROM "T1" SAMPLE BLOCK (:"SYS_B_10" , :"SYS_B_11") SEED (:"SYS_B_12") "T1") SAMPLESUB
END OF STMT
PARSE #3:c=0,e=0,p=0,cr=0,cu=0,mis=0,r=0,dep=1,og=1,plh=3906273573,tim=518053123679
EXEC #3:c=0,e=0,p=0,cr=0,cu=0,mis=0,r=0,dep=1,og=1,plh=3906273573,tim=518053123679
FETCH #3:c=15625,e=0,p=0,cr=71,cu=0,mis=0,r=1,dep=1,og=1,plh=3906273573,tim=518053123679
STAT #3 id=1 cnt=1 pid=0 pos=1 obj=0 op='SORT GROUP BY (cr=71 pr=0 pw=0 time=0 us)'
STAT #3 id=2 cnt=3410 pid=1 pos=1 obj=102003 op='TABLE ACCESS SAMPLE T1 (cr=71 pr=0 pw=0 time=0 us cost=2 size=75 card=3)'
CLOSE #3:c=0,e=0,dep=1,type=0,tim=518053123679
=====================
PARSING IN CURSOR #4 len=471 dep=1 uid=60 oct=3 lid=60 tim=518053123679 hv=1212909034 ad='1f5d5b28' sqlid='c5sn2v544r1ga'
SELECT /* OPT_DYN_SAMP */ /*+ ALL_ROWS opt_param('parallel_execution_enabled', 'false') NO_PARALLEL(SAMPLESUB) NO_PARALLEL_INDEX(SAMPLESUB)
 NO_SQL_TUNE */ NVL(SUM(C1),:"SYS_B_0"), NVL(SUM(C2),:"SYS_B_1"), NVL(SUM(C3),:"SYS_B_2") FROM (SELECT /*+ NO_PARALLEL("T1") INDEX("T1" IND_T1_C1)
 NO_PARALLEL_INDEX("T1") */ :"SYS_B_3" AS C1, :"SYS_B_4" AS C2, :"SYS_B_5" AS C3  FROM "T1" "T1" WHERE "T1"."C1">=:"SYS_B_6"
 AND "T1"."C1"<=:"SYS_B_7" AND ROWNUM <= :"SYS_B_8") SAMPLESUB
END OF STMT
PARSE #4:c=0,e=0,p=0,cr=0,cu=0,mis=0,r=0,dep=1,og=1,plh=41534134,tim=518053123679
EXEC #4:c=0,e=0,p=0,cr=0,cu=0,mis=0,r=0,dep=1,og=1,plh=41534134,tim=518053123679
FETCH #4:c=0,e=0,p=4,cr=10,cu=0,mis=0,r=1,dep=1,og=1,plh=41534134,tim=518053123679
STAT #4 id=1 cnt=1 pid=0 pos=1 obj=0 op='SORT AGGREGATE (cr=10 pr=4 pw=0 time=0 us)'
STAT #4 id=2 cnt=2000 pid=1 pos=1 obj=0 op='VIEW  (cr=10 pr=4 pw=0 time=0 us cost=12 size=390 card=10)'
STAT #4 id=3 cnt=2000 pid=2 pos=1 obj=0 op='COUNT STOPKEY (cr=10 pr=4 pw=0 time=0 us)'
STAT #4 id=4 cnt=2000 pid=3 pos=1 obj=0 op='FILTER  (cr=10 pr=4 pw=0 time=0 us)'
STAT #4 id=5 cnt=2000 pid=4 pos=1 obj=102004 op='INDEX RANGE SCAN IND_T1_C1 (cr=10 pr=4 pw=0 time=0 us cost=12 size=429 card=33)'
CLOSE #4:c=0,e=0,dep=1,type=0,tim=518053123679
=====================
PARSING IN CURSOR #2 len=646 dep=1 uid=60 oct=3 lid=60 tim=518053123679 hv=2627297926 ad='1d2877e4' sqlid='0u23vn6f9ksn6'
SELECT /* OPT_DYN_SAMP */ /*+ ALL_ROWS IGNORE_WHERE_CLAUSE NO_PARALLEL(SAMPLESUB) opt_param('parallel_execution_enabled', 'false')
 NO_PARALLEL_INDEX(SAMPLESUB) NO_SQL_TUNE */ NVL(SUM(C1),:"SYS_B_00"), NVL(SUM(C2),:"SYS_B_01"), COUNT(DISTINCT C3),
 NVL(SUM(CASE WHEN C3 IS NULL THEN :"SYS_B_02" ELSE :"SYS_B_03" END),:"SYS_B_04") FROM (SELECT /*+ IGNORE_WHERE_CLAUSE NO_PARALLEL("T2") FULL("T2")
 NO_PARALLEL_INDEX("T2") */ :"SYS_B_05" AS C1, CASE WHEN "T2"."C1">=:"SYS_B_06" AND "T2"."C1"<=:"SYS_B_07" THEN :"SYS_B_08" ELSE :"SYS_B_09" END AS C2,
 "T2"."C1" AS C3 FROM "T2" SAMPLE BLOCK (:"SYS_B_10" , :"SYS_B_11") SEED (:"SYS_B_12") "T2") SAMPLESUB
END OF STMT
PARSE #2:c=0,e=0,p=0,cr=0,cu=0,mis=0,r=0,dep=1,og=1,plh=724732973,tim=518053123679
EXEC #2:c=0,e=0,p=0,cr=0,cu=0,mis=0,r=0,dep=1,og=1,plh=724732973,tim=518053123679
FETCH #2:c=0,e=31256,p=19,cr=71,cu=0,mis=0,r=1,dep=1,og=1,plh=724732973,tim=518053154935
STAT #2 id=1 cnt=1 pid=0 pos=1 obj=0 op='SORT GROUP BY (cr=71 pr=19 pw=0 time=0 us)'
STAT #2 id=2 cnt=3420 pid=1 pos=1 obj=102006 op='TABLE ACCESS SAMPLE T2 (cr=71 pr=19 pw=0 time=0 us cost=2 size=75 card=3)'
CLOSE #2:c=0,e=0,dep=1,type=0,tim=518053154935
=====================
PARSING IN CURSOR #6 len=471 dep=1 uid=60 oct=3 lid=60 tim=518053154935 hv=2390595667 ad='1f59c3c4' sqlid='5xf39uf77v62m'
SELECT /* OPT_DYN_SAMP */ /*+ ALL_ROWS opt_param('parallel_execution_enabled', 'false') NO_PARALLEL(SAMPLESUB) NO_PARALLEL_INDEX(SAMPLESUB) NO_SQL_TUNE */
 NVL(SUM(C1),:"SYS_B_0"), NVL(SUM(C2),:"SYS_B_1"), NVL(SUM(C3),:"SYS_B_2") FROM (SELECT /*+ NO_PARALLEL("T2") INDEX("T2" IND_T2_C1)
 NO_PARALLEL_INDEX("T2") */ :"SYS_B_3" AS C1, :"SYS_B_4" AS C2, :"SYS_B_5" AS C3  FROM "T2" "T2" WHERE "T2"."C1">=:"SYS_B_6" AND "T2"."C1"<=:"SYS_B_7"
 AND ROWNUM <= :"SYS_B_8") SAMPLESUB
END OF STMT
PARSE #6:c=0,e=0,p=0,cr=0,cu=0,mis=0,r=0,dep=1,og=1,plh=4155399029,tim=518053154935
EXEC #6:c=0,e=0,p=0,cr=0,cu=0,mis=0,r=0,dep=1,og=1,plh=4155399029,tim=518053154935
FETCH #6:c=0,e=31251,p=7,cr=16,cu=0,mis=0,r=1,dep=1,og=1,plh=4155399029,tim=518053186186
STAT #6 id=1 cnt=1 pid=0 pos=1 obj=0 op='SORT AGGREGATE (cr=16 pr=7 pw=0 time=0 us)'
STAT #6 id=2 cnt=2000 pid=1 pos=1 obj=0 op='VIEW  (cr=16 pr=7 pw=0 time=0 us cost=12 size=390 card=10)'
STAT #6 id=3 cnt=2000 pid=2 pos=1 obj=0 op='COUNT STOPKEY (cr=16 pr=7 pw=0 time=0 us)'
STAT #6 id=4 cnt=2000 pid=3 pos=1 obj=0 op='FILTER  (cr=16 pr=7 pw=0 time=0 us)'
STAT #6 id=5 cnt=2000 pid=4 pos=1 obj=102007 op='INDEX RANGE SCAN IND_T2_C1 (cr=16 pr=7 pw=0 time=0 us cost=12 size=429 card=33)'
CLOSE #6:c=0,e=0,dep=1,type=0,tim=518053186186
=====================
PARSING IN CURSOR #5 len=179 dep=0 uid=60 oct=3 lid=60 tim=518053186186 hv=3811374996 ad='28520570' sqlid='0m07kq3jktxwn'
SELECT /* PARSE_TEST3 */
  T1.C1 T1_C1,
  SUBSTR(T1.C3,1,10) T1_C3,
  T2.C2 T2_C2,
  SUBSTR(T2.C3,1,10) T2_C3
FROM
  T1,
  T2
WHERE
  T1.C1=T2.C1
  AND T1.C1 BETWEEN 4001 AND 6000
END OF STMT
PARSE #5:c=15625,e=62507,p=30,cr=172,cu=0,mis=1,r=0,dep=0,og=1,plh=169351222,tim=518053186186
EXEC #5:c=0,e=0,p=0,cr=0,cu=0,mis=0,r=0,dep=0,og=1,plh=169351222,tim=518053186186
...
FETCH #5:c=0,e=0,p=0,cr=2,cu=0,mis=0,r=4,dep=0,og=1,plh=169351222,tim=518053279932
STAT #5 id=1 cnt=2000 pid=0 pos=1 obj=0 op='HASH JOIN  (cr=396 pr=72 pw=0 time=0 us cost=48 size=284000 card=2000)'
STAT #5 id=2 cnt=2000 pid=1 pos=1 obj=102003 op='TABLE ACCESS BY INDEX ROWID T1 (cr=44 pr=35 pw=0 time=0 us cost=22 size=130000 card=2000)'
STAT #5 id=3 cnt=2000 pid=2 pos=1 obj=102004 op='INDEX RANGE SCAN IND_T1_C1 (cr=6 pr=0 pw=0 time=0 us cost=6 size=0 card=2000)'
STAT #5 id=4 cnt=2000 pid=1 pos=2 obj=102006 op='TABLE ACCESS BY INDEX ROWID T2 (cr=352 pr=37 pw=0 time=0 us cost=25 size=154000 card=2000)'
STAT #5 id=5 cnt=2000 pid=4 pos=1 obj=102007 op='INDEX RANGE SCAN IND_T2_C1 (cr=143 pr=0 pw=0 time=0 us cost=9 size=0 card=2000)' 

This time you can see that 172 consistent gets were performed during the hard parse.  If we add up the consistent gets just before our SQL statement appeared in the trace file (71 + 10 + 71 + 16), we can account for 168 of the 172 consistent gets during the parse of our SQL statement.  Note that the SQL_ID for the SQL statement appeared in the trace file (’0m07kq3jktxwn’ for the last trace file), so we could do something like this to quickly confirm that dynamic sampling happened during the hard parse without looking in the 10046 trace file:

SET LINESIZE 140
SET PAGESIZE 1000
SET TRIMSPOOL ON
SET AUTOTRACE OFF

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

SQL_ID  0m07kq3jktxwn, child number 0
-------------------------------------
SELECT /* PARSE_TEST3 */   T1.C1 T1_C1,   SUBSTR(T1.C3,1,10) T1_C3,
T2.C2 T2_C2,   SUBSTR(T2.C3,1,10) T2_C3 FROM   T1,   T2 WHERE
T1.C1=T2.C1   AND T1.C1 BETWEEN 4001 AND 6000

Plan hash value: 169351222

------------------------------------------------------------------------------------------
| Id  | Operation                    | Name      | Rows  | Bytes | Cost (%CPU)| Time     |
------------------------------------------------------------------------------------------
|   0 | SELECT STATEMENT             |           |       |       |    48 (100)|          |
|*  1 |  HASH JOIN                   |           |  2000 |   277K|    48   (3)| 00:00:01 |
|   2 |   TABLE ACCESS BY INDEX ROWID| T1        |  2000 |   126K|    22   (0)| 00:00:01 |
|*  3 |    INDEX RANGE SCAN          | IND_T1_C1 |  2000 |       |     6   (0)| 00:00:01 |
|   4 |   TABLE ACCESS BY INDEX ROWID| T2        |  2000 |   150K|    25   (0)| 00:00:01 |
|*  5 |    INDEX RANGE SCAN          | IND_T2_C1 |  2000 |       |     9   (0)| 00:00:01 |
------------------------------------------------------------------------------------------

Predicate Information (identified by operation id):
---------------------------------------------------
   1 - access("T1"."C1"="T2"."C1")
   3 - access("T1"."C1">=4001 AND "T1"."C1"<=6000)
   5 - access("T2"."C1">=4001 AND "T2"."C1"<=6000)

Note
-----
   - dynamic sampling used for this statement

SQL_ID  0m07kq3jktxwn, child number 1
-------------------------------------
SELECT /* PARSE_TEST3 */   T1.C1 T1_C1,   SUBSTR(T1.C3,1,10) T1_C3,
T2.C2 T2_C2,   SUBSTR(T2.C3,1,10) T2_C3 FROM   T1,   T2 WHERE
T1.C1=T2.C1   AND T1.C1 BETWEEN 4001 AND 6000

Plan hash value: 169351222

------------------------------------------------------------------------------------------
| Id  | Operation                    | Name      | Rows  | Bytes | Cost (%CPU)| Time     |
------------------------------------------------------------------------------------------
|   0 | SELECT STATEMENT             |           |       |       |    48 (100)|          |
|*  1 |  HASH JOIN                   |           |  2000 |   277K|    48   (3)| 00:00:01 |
|   2 |   TABLE ACCESS BY INDEX ROWID| T1        |  2000 |   126K|    22   (0)| 00:00:01 |
|*  3 |    INDEX RANGE SCAN          | IND_T1_C1 |  2000 |       |     6   (0)| 00:00:01 |
|   4 |   TABLE ACCESS BY INDEX ROWID| T2        |  2000 |   150K|    25   (0)| 00:00:01 |
|*  5 |    INDEX RANGE SCAN          | IND_T2_C1 |  2000 |       |     9   (0)| 00:00:01 |
------------------------------------------------------------------------------------------

Predicate Information (identified by operation id):
---------------------------------------------------
   1 - access("T1"."C1"="T2"."C1")
   3 - access("T1"."C1">=4001 AND "T1"."C1"<=6000)
   5 - access("T2"."C1">=4001 AND "T2"."C1"<=6000)

Note
-----
   - dynamic sampling used for this statement 

The note at the bottom of each execution plan shows that dynamic sampling happened during the hard parse.  Note also that there are two child cursors with the same execution plan.  One was created when the 10046 trace was active, and the other was created after the 10046 trace was disabled.

We could then extend this test case by collecting table AND index statistics, and then re-execute the test script to compare the results.  So, what are the other possible causes for consistent gets during a hard parse?  Start with my test case and see if you are able to show the source of the consistent gets that are output by SQL*Plus or a TKPROF summary.








Follow

Get every new post delivered to your Inbox.

Join 137 other followers