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.
Recent Comments