Which PLAN_HASH_VALUE Appears in V$SQLAREA?

28 03 2012

March 28, 2012

A recent question on the OTN forums asked which PLAN_HASH_VALUE appears in V$SQLAREA when there are multiple child cursors for a single SQL_ID value, when some child cursors have a different execution plan.  Certainly, this bit of information must be in the Oracle Database documentation.  Let’s check the V$SQLAREA documentation for Oracle Database 11.2:

“Numeric representation of the SQL plan for this cursor. Comparing one PLAN_HASH_VALUE to another easily identifies whether or not two plans are the same (rather than comparing the two plans line by line).”

Well, that was not helpful, but it does remind me of something that I saw when I went out for a drive in the countryside this past weekend (all within about a 50 meter radius – click a picture to see a larger view of the picture):

 

OK, now that the initial frustration of not obtaining an answer from the documentation has subsided, let’s put together a quick test case to see if we are able to help the OP find an answer to his question.  We will borrow a slightly modified version of a test script that generates skewed data which was used in another article

CREATE TABLE T1 AS
SELECT
  ROWNUM C1,
  DECODE(ROWNUM,1,1,0) C2,
  LPAD('A',255,'A') C3
FROM
  DUAL
CONNECT BY
  LEVEL<=10000;

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

ALTER TABLE T1 MODIFY (C1 NOT NULL, C2 NOT NULL);

EXEC DBMS_STATS.GATHER_TABLE_STATS(OWNNAME=>USER,TABNAME=>'T1',CASCADE=>TRUE,ESTIMATE_PERCENT=>100,METHOD_OPT=>'FOR ALL INDEXED COLUMNS SIZE 254') 

For the initial test (in Oracle Database 11.2.0.2), I will use the BIND_AWARE hint to save Oracle from having to determine that the execution plan could (should) depend on the bind variable value, rather than having to rely on adaptive cursor sharing to eventually obtain the same effect:

SET LINESIZE 120
SET PAGESIZE 1000

VARIABLE V1 NUMBER
EXEC :V1:=1

SELECT /*+ BIND_AWARE */
  C1,
  C2,
  C3
FROM
  T1
WHERE
  C2=:V1;

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

SQL_ID  7p4yxrzwwuybt, child number 0
-------------------------------------
SELECT /*+ BIND_AWARE */   C1,   C2,   C3 FROM   T1 WHERE   C2=:V1

Plan hash value: 236868917

-----------------------------------------------------------------------------------------
| Id  | Operation                   | Name      | Rows  | Bytes | Cost (%CPU)| Time     |
-----------------------------------------------------------------------------------------
|   0 | SELECT STATEMENT            |           |       |       |     2 (100)|          |
|   1 |  TABLE ACCESS BY INDEX ROWID| T1        |     1 |   136 |     2   (0)| 00:00:01 |
|*  2 |   INDEX RANGE SCAN          | IND_T1_C2 |     1 |       |     1   (0)| 00:00:01 |
-----------------------------------------------------------------------------------------

Predicate Information (identified by operation id):
---------------------------------------------------
   2 - access("C2"=:V1)

SELECT
  PLAN_HASH_VALUE
FROM
  V$SQLAREA
WHERE
  SQL_ID='7p4yxrzwwuybt';

PLAN_HASH_VALUE
---------------
      236868917 

As shown above, the PLAN_HASH_VALUE has a value of 236868917 in V$SQLAREA, which is the same value (shown in the execution plan) of the most recently executed child number.

Let’s repeat the previous SQL statements, this time with a different bind variable value:

EXEC :V1:=0

SELECT /*+ BIND_AWARE */
  C1,
  C2,
  C3
FROM
  T1
WHERE
  C2=:V1;

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

SQL_ID  7p4yxrzwwuybt, child number 1
-------------------------------------
SELECT /*+ BIND_AWARE */   C1,   C2,   C3 FROM   T1 WHERE   C2=:V1

Plan hash value: 3617692013

--------------------------------------------------------------------------
| Id  | Operation         | Name | Rows  | Bytes | Cost (%CPU)| Time     |
--------------------------------------------------------------------------
|   0 | SELECT STATEMENT  |      |       |       |    33 (100)|          |
|*  1 |  TABLE ACCESS FULL| T1   |  9999 |  1327K|    33   (0)| 00:00:01 |
--------------------------------------------------------------------------

Predicate Information (identified by operation id):
---------------------------------------------------
   1 - filter("C2"=:V1)

SELECT
  PLAN_HASH_VALUE
FROM
  V$SQLAREA
WHERE
  SQL_ID='7p4yxrzwwuybt';

PLAN_HASH_VALUE
---------------
     3617692013 

As shown above, the execution plan changed, thus the Plan hash value in the execution plan changed to 3617692013, and that change corresponded with the PLAN_HASH_VALUE for the SQL_ID in V$SQLAREA changing to the value 3617692013 – the same value shown in the execution plan for the most recently executed child number.

Let’s trying again without changing the bind variable value to see what happens:

SELECT /*+ BIND_AWARE */
  C1,
  C2,
  C3
FROM
  T1
WHERE
  C2=:V1;

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

SQL_ID  7p4yxrzwwuybt, child number 1
-------------------------------------
SELECT /*+ BIND_AWARE */   C1,   C2,   C3 FROM   T1 WHERE   C2=:V1

Plan hash value: 3617692013

--------------------------------------------------------------------------
| Id  | Operation         | Name | Rows  | Bytes | Cost (%CPU)| Time     |
--------------------------------------------------------------------------
|   0 | SELECT STATEMENT  |      |       |       |    33 (100)|          |
|*  1 |  TABLE ACCESS FULL| T1   |  9999 |  1327K|    33   (0)| 00:00:01 |
--------------------------------------------------------------------------

Predicate Information (identified by operation id):
---------------------------------------------------
   1 - filter("C2"=:V1)

SELECT
  PLAN_HASH_VALUE
FROM
  V$SQLAREA
WHERE
  SQL_ID='7p4yxrzwwuybt';

PLAN_HASH_VALUE
---------------
     3617692013 

As shown above, the PLAN_HASH_VALUE in V$SQLAREA remained at the value 3617692013, which is the PLAN_HASH_VALUE of the most recently executed child number.

Let’s switch back to the original bind variable value to see what happens in V$SQLAREA:

EXEC :V1:=1

SELECT /*+ BIND_AWARE */
  C1,
  C2,
  C3
FROM
  T1
WHERE
  C2=:V1;

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

SQL_ID  7p4yxrzwwuybt, child number 0
-------------------------------------
SELECT /*+ BIND_AWARE */   C1,   C2,   C3 FROM   T1 WHERE   C2=:V1

Plan hash value: 236868917

-----------------------------------------------------------------------------------------
| Id  | Operation                   | Name      | Rows  | Bytes | Cost (%CPU)| Time     |
-----------------------------------------------------------------------------------------
|   0 | SELECT STATEMENT            |           |       |       |     2 (100)|          |
|   1 |  TABLE ACCESS BY INDEX ROWID| T1        |     1 |   136 |     2   (0)| 00:00:01 |
|*  2 |   INDEX RANGE SCAN          | IND_T1_C2 |     1 |       |     1   (0)| 00:00:01 |
-----------------------------------------------------------------------------------------

Predicate Information (identified by operation id):
---------------------------------------------------
   2 - access("C2"=:V1)

SELECT
  PLAN_HASH_VALUE
FROM
  V$SQLAREA
WHERE
  SQL_ID='7p4yxrzwwuybt';

PLAN_HASH_VALUE
---------------
      236868917 

As shown above, the PLAN_HASH_VALUE for the SQL_ID found in V$SQLAREA switched back to the original value – it is again showing the PLAN_HASH_VALUE of the most recently executed child cursor.

But wait, there’s more information.  Pete Finnigan recently reminded me of a problem that I had several years ago when I tried to untangle the string of synonyms and views to see the definition of various Oracle Database performance views.  He not only reminded me of the problem that I had years ago, but showed me the process of untangling the (evoke suitable picture from above) that I learned and forgot several times over the subsequent years.

Let’s get started by determining what the V$SQLAREA synonym points at:

SET LONG 9000
COLUMN TABLE_OWNER FORMAT A11

SELECT
  TABLE_OWNER,
  TABLE_NAME
FROM
  DBA_SYNONYMS
WHERE
  SYNONYM_NAME='V$SQLAREA';

TABLE_OWNER TABLE_NAME
----------- ----------
SYS         V_$SQLAREA 

A viewed named V_$SQLAREA – now what?  Let’s see the definition of that view:

SELECT
  TEXT
FROM
  DBA_VIEWS
WHERE
  VIEW_NAME='V_$SQLAREA';

select "SQL_TEXT","SQL_FULLTEXT","SQL_ID","SHARABLE_MEM","PERSISTENT_MEM","RUNTI
...
D_TOTAL","PINNED_TOTAL","IO_CELL_UNCOMPRESSED_BYTES","IO_CELL_OFFLOAD_RETURNED_B
YTES" from v$sqlarea 

So, the synonym V$SQLAREA points to the view V_$SQLAREA which selects from V$SQLAREA … that name seems oddly familiar.

SELECT
  VIEW_DEFINITION
FROM
  V$FIXED_VIEW_DEFINITION
WHERE
  VIEW_NAME='V$SQLAREA';

select    SQL_TEXT,           SQL_FULLTEXT,           SQL_ID,           SHARABLE
_MEM,           PERSISTENT_MEM,           RUNTIME_MEM,           SORTS,
...
SICAL_WRITE_BYTES,            OPTIMIZED_PHY_READ_REQUESTS,            LOCKED_TOT
AL,             PINNED_TOTAL,            IO_CELL_UNCOMPRESSED_BYTES,
IO_CELL_OFFLOAD_RETURNED_BYTES from GV$SQLAREA where inst_id = USERENV('Instance
') 

So, the view V_$SQLAREA selects from V$SQLAREA which selects from GV$SQLAREA.

SELECT
  VIEW_DEFINITION
FROM
  V$FIXED_VIEW_DEFINITION
WHERE
  VIEW_NAME='GV$SQLAREA';

select inst_id,kglnaobj,kglfnobj,kglobt03,kglobhs0+kglobhs1+kglobhs2+kglobhs3+kg
lobhs4+kglobhs5+kglobhs6,kglobt08+kglobt11,kglobt10,kglobt01,kglobccc,kglobclc,k
...
t58,kglobt23,kglobt24,kglobt59,kglobt53 - ((kglobt55+kglobt57) - kglobt52)from
x$kglcursor_child_sqlid where kglobt02 != 0

So, the view V_$SQLAREA selects from V$SQLAREA which selects from GV$SQLAREA which selects from X$KGLCURSOR_CHILD_SQLID where KGLOBT02 != 0 (COMMAND_TYPE column in V$SQLAREA). (Note, must be logged in as the SYS user for the following SQL statement.)

SELECT
  KQFDTNAM,
  KQFDTEQU
FROM
  X$KQFDT
ORDER BY
  KQFDTNAM;

KQFDTNAM                       KQFDTEQU
----------------------------- -------------
...
X$KGLBODY                      X$KGLOB
X$KGLCLUSTER                   X$KGLOB
X$KGLCURSOR                    X$KGLOB
X$KGLCURSOR_CHILD              X$KGLOB
X$KGLCURSOR_CHILD_SQLID        X$KGLOB
X$KGLCURSOR_CHILD_SQLIDPH      X$KGLOB
X$KGLINDEX                     X$KGLOB
X$KGLTABLE                     X$KGLOB
X$KGLTRIGGER                   X$KGLOB 
...

So, in summary the synonym V$SQLAREA points to the view V_$SQLAREA which selects from V$SQLAREA which selects from GV$SQLAREA which selects from X$KGLCURSOR_CHILD_SQLID where KGLOBT02 != 0, which has as a base table of X$KGLOB just like 8 other fixed tables.  If you repeat the above steps for V$SQL, you will find that it is based on X$KGLCURSOR_CHILD, which also has X$KGLOB as its base table.

Here is a piece of SQL that joins the underlying fixed table for V$SQLAREA with V$SQL to hopefully determine if the PLAN_HASH_VALUE for the most recently executed child cursor for each SQL_ID is always what appears in V$SQLAREA (I do not suggest running this SQL statement in a production environment – the test database instance in my case was bounced a couple of hours ago).  The word DIFFERENT is output if the LAST_ACTIVE_TIME from V$SQLAREA does NOT match the LAST_ACTIVE_TIME for a specific child in V$SQL (Note, must be logged in as the SYS user for the following SQL statement.):

SELECT
  X.KGLOBT03 SQL_ID,
  X.KGLOBT30 PLAN_HASH_VALUE,
  TO_CHAR(X.KGLOBCLA,'HH24:MI:SS') LAST_ACTIVE_TIME,
  S.CHILD_NUMBER,
  S.PLAN_HASH_VALUE S_PLAN_HASH_VALUE,
  TO_CHAR(S.LAST_ACTIVE_TIME,'HH24:MI:SS') S_LAST_ACTIVE_TIME,
  DECODE(X.KGLOBCLA,S.LAST_ACTIVE_TIME,NULL,'DIFFERENT') TIMESTAMP_DIFFERS
FROM
  X$KGLCURSOR_CHILD_SQLID X,
  V$SQL S
WHERE
  X.KGLOBT02 != 0
  AND X.KGLOBT03=S.SQL_ID
ORDER BY
  S.SQL_ID,
  S.CHILD_NUMBER;

SQL_ID        PLAN_HASH_VALUE LAST_ACT CHILD_NUMBER S_PLAN_HASH_VALUE S_LAST_A TIMESTAMP
------------- --------------- -------- ------------ ----------------- -------- ---------
00fx7adv5q5gm      2256887934 22:03:44            0        2256887934 22:03:44
00yp7w9j0yqma      3600061239 20:28:45            0        3600061239 20:28:45
...
07pcqtmt58zv9      1964643588 20:44:48            0        1964643588 20:28:45 DIFFERENT
07pcqtmt58zv9      1964643588 20:44:48            1        1964643588 20:44:48
...
0fr8zhn4ymu3v      1231101765 21:03:43            0        3815847153 20:28:45 DIFFERENT
0fr8zhn4ymu3v      1231101765 21:03:43            1        1231101765 21:03:43
...
0kugqg48477gf       643665366 21:03:43            0         828554155 20:28:45 DIFFERENT
0kugqg48477gf       643665366 21:03:43            1         643665366 21:03:43
...
0m78skf1mudnb      3506511888 20:28:47            0        3506511888 20:28:45 DIFFERENT
0m78skf1mudnb      3506511888 20:28:47            1        3506511888 20:28:47
...
15w1t8qpdgg5k      2628186673 21:33:45            0        2628186673 20:28:45 DIFFERENT
15w1t8qpdgg5k      2628186673 21:33:45            1        2628186673 21:33:45
...
1gu8t96d0bdmu      2035254952 21:03:43            0        2035254952 21:03:43
1gu8t96d0bdmu      2035254952 21:03:43            1        3526770254 20:28:45 DIFFERENT
1gu8t96d0bdmu      2035254952 21:03:43            2        2035254952 20:48:45 DIFFERENT
...
2jr8c42qx700h      2445831428 20:28:55            0        3034582372 20:28:45 DIFFERENT
2jr8c42qx700h      2445831428 20:28:55            1        2445831428 20:28:45 DIFFERENT
2jr8c42qx700h      2445831428 20:28:55            2        2445831428 20:28:55
...
2q93zsrvbdw48      2874733959 21:03:43            0        2874733959 21:03:43
2q93zsrvbdw48      2874733959 21:03:43            1        2874733959 20:28:45 DIFFERENT
2q93zsrvbdw48      2874733959 21:03:43            2        2874733959 20:48:45 DIFFERENT
2qqqjzkhmsbgv      1308273333 20:28:45            0        1308273333 20:28:45
2syvqzbxp4k9z      1423211129 20:28:47            0        1423211129 20:28:45 DIFFERENT
2syvqzbxp4k9z      1423211129 20:28:47            1        1423211129 20:28:47
2tkw12w5k68vd      1457651150 21:03:43            0        1457651150 20:28:45 DIFFERENT
2tkw12w5k68vd      1457651150 21:03:43            1        1457651150 21:03:43
2xgubd6ayhyb1      3418045132 21:03:43            0        3418045132 21:03:43
2xyb5d6xg9srh       785096182 20:28:47            0         785096182 20:28:45 DIFFERENT
2xyb5d6xg9srh       785096182 20:28:47            1         785096182 20:28:47
2ysccdanw72pv      3801013801 20:28:55            0        3801013801 20:28:55
32bhha21dkv0v      3765558045 21:03:43            0        3765558045 20:28:45 DIFFERENT
32bhha21dkv0v      3765558045 21:03:43            1        3765558045 21:03:43
...
38fffx897xs0v      1042772069 21:33:45            0        1042772069 20:28:45 DIFFERENT
38fffx897xs0v      1042772069 21:33:45            1        1042772069 21:33:45
...
39m4sx9k63ba2      2317816222 21:03:43            0        2317816222 20:28:45 DIFFERENT
39m4sx9k63ba2      2317816222 21:03:43            1        2317816222 21:03:43
...
3k0c6241uw582      1964643588 20:44:48            0        1964643588 20:28:45 DIFFERENT
3k0c6241uw582      1964643588 20:44:48            1        1964643588 20:44:48
3ktacv9r56b51      4184428695 21:03:43            0        4184428695 20:28:45 DIFFERENT
3ktacv9r56b51      4184428695 21:03:43            1        4184428695 20:28:45 DIFFERENT
3ktacv9r56b51      4184428695 21:03:43            2        4184428695 21:03:43
3nhfzxjzx2btx      1043815174 20:28:45            0        1043815174 20:28:45
3nkd3g3ju5ph1      2853959010 21:03:43            0        2853959010 21:03:43
3nkd3g3ju5ph1      2853959010 21:03:43            1        2853959010 20:28:45 DIFFERENT
3nkd3g3ju5ph1      2853959010 21:03:43            2        2853959010 20:48:45 DIFFERENT
3np8cptn6uzn6      1754305749 20:28:46            0        1754305749 20:28:46
3nzv2smdzzbsf      2731876963 21:33:45            0        2731876963 20:28:45 DIFFERENT
3nzv2smdzzbsf      2731876963 21:33:45            1        2731876963 21:33:45
...
3rw49yhahg984      3808094885 20:28:55            0        3808094885 20:28:45 DIFFERENT
3rw49yhahg984      3808094885 20:28:55            1        3808094885 20:28:55
...
3w4qs0tbpmxr6      1224215794 21:03:43            0        1224215794 21:03:43
3w4qs0tbpmxr6      1224215794 21:03:43            1        1224215794 20:28:45 DIFFERENT
3w4qs0tbpmxr6      1224215794 21:03:43            2        1224215794 20:48:45 DIFFERENT
...
459f3z9u4fb3u       415205717 20:44:48            0         415205717 20:28:45 DIFFERENT
459f3z9u4fb3u       415205717 20:44:48            1         415205717 20:44:48
...
4cvqvs489pd6k      2300756036 20:28:55            0        2300756036 20:28:45 DIFFERENT
4cvqvs489pd6k      2300756036 20:28:55            1        2300756036 20:28:55
...
4zzxr8rvht74z      3368685730 20:44:48            0        3368685730 20:28:45 DIFFERENT
4zzxr8rvht74z      3368685730 20:44:48            1        3368685730 20:44:48
...
53saa2zkr6wc3      3954488388 21:03:43            0        3954488388 21:03:43
53saa2zkr6wc3      3954488388 21:03:43            1        1514015273 20:28:45 DIFFERENT
53saa2zkr6wc3      3954488388 21:03:43            2        3954488388 20:33:45 DIFFERENT
...
5n1fs4m2n2y0r       299250003 21:03:43            0         299250003 20:28:45 DIFFERENT
5n1fs4m2n2y0r       299250003 21:03:43            1         299250003 21:03:43
5n1fs4m2n2y0r       299250003 21:03:43            2         299250003 20:48:45 DIFFERENT
...
5wxyshspv54v4      3009292138 20:44:48            0        3009292138 20:28:45 DIFFERENT
5wxyshspv54v4      3009292138 20:44:48            1        3009292138 20:44:48
...
6aq34nj2zb2n7      2874733959 21:03:43            0        2874733959 21:03:43
6aq34nj2zb2n7      2874733959 21:03:43            1        2874733959 20:28:45 DIFFERENT
6aq34nj2zb2n7      2874733959 21:03:43            2        2874733959 20:48:45 DIFFERENT
6b7hj70p170j1      2605232930 20:28:45            0        2605232930 20:28:45
6c9wx6z8w9qpu       785096182 20:28:47            0         785096182 20:28:45 DIFFERENT
6c9wx6z8w9qpu       785096182 20:28:47            1         785096182 20:28:47
...
6qz82dptj0qr7      2819763574 21:03:43            0        2819763574 20:28:45 DIFFERENT
6qz82dptj0qr7      2819763574 21:03:43            1        2819763574 21:03:43
...
79w2cqu2gmjm8      4145101951 20:28:55            0        2645993454 20:28:45 DIFFERENT
79w2cqu2gmjm8      4145101951 20:28:55            1        4145101951 20:28:45 DIFFERENT
79w2cqu2gmjm8      4145101951 20:28:55            2        4145101951 20:28:55
7akvnu9t168d3      1964643588 20:44:48            0        1964643588 20:28:45 DIFFERENT
7akvnu9t168d3      1964643588 20:44:48            1        1964643588 20:44:48
...
7jpt4cpfvcy1k       284504113 20:28:46            0         284504113 20:28:45 DIFFERENT
7jpt4cpfvcy1k       284504113 20:28:46            1         284504113 20:28:46
7mgr3uwydqq8j       293268181 22:13:45            0         293268181 22:13:45
7ng34ruy5awxq      3992920156 21:03:43            0        3992920156 21:03:43
7ng34ruy5awxq      3992920156 21:03:43            1         306576078 20:28:45 DIFFERENT
7ng34ruy5awxq      3992920156 21:03:43            2        3992920156 20:48:45 DIFFERENT
7nuw4xwrnuwxq      1720483994 21:03:43            0        1720483994 20:28:45 DIFFERENT
7nuw4xwrnuwxq      1720483994 21:03:43            1        1720483994 21:03:43
...
83taa7kaw59c1      3765558045 21:03:43            0        3765558045 21:03:43
83taa7kaw59c1      3765558045 21:03:43            1        3765558045 20:28:45 DIFFERENT
83taa7kaw59c1      3765558045 21:03:43            2        3765558045 20:48:45 DIFFERENT
85sxp7kypwbx6      1395584798 20:28:46            0        1395584798 20:28:46
87gaftwrm2h68      1218588913 21:03:43            0        1218588913 20:28:45 DIFFERENT
87gaftwrm2h68      1218588913 21:03:43            1        1218588913 21:03:43
87gaftwrm2h68      1218588913 21:03:43            2        1218588913 20:48:45 DIFFERENT
...
8swypbbr0m372       893970548 21:03:43            0         893970548 20:28:45 DIFFERENT
8swypbbr0m372       893970548 21:03:43            1         893970548 20:28:45 DIFFERENT
8swypbbr0m372       893970548 21:03:43            2         893970548 21:03:43
...
9g485acn2n30m      2544153582 21:03:43            0        2544153582 20:28:45 DIFFERENT
9g485acn2n30m      2544153582 21:03:43            1        2544153582 21:03:43
9gkq7rruycsjp      3362549386 20:28:46            0        3362549386 20:28:45 DIFFERENT
9gkq7rruycsjp      3362549386 20:28:46            1        3362549386 20:28:46
...
9rfqm06xmuwu0       832500465 21:03:43            0         832500465 20:28:45 DIFFERENT
9rfqm06xmuwu0       832500465 21:03:43            1         832500465 21:03:43
9rvqpun1x1xjd      2760275752 20:28:46            0        2760275752 20:28:46
9tgj4g8y4rwy8      3755742892 21:03:43            0        3755742892 20:28:45 DIFFERENT
9tgj4g8y4rwy8      3755742892 21:03:43            1        3755742892 21:03:43
...
axmdf8vq7k1rh      2203911306 20:44:48            0        2203911306 20:28:45 DIFFERENT
axmdf8vq7k1rh      2203911306 20:44:48            1        2203911306 20:44:48
...
b1wc53ddd6h3p      1637390370 21:03:43            0        1637390370 20:28:45 DIFFERENT
b1wc53ddd6h3p      1637390370 21:03:43            1        1637390370 21:03:43
...
bsa0wjtftg3uw      1512486435 22:23:19            0        2020579421 20:28:45 DIFFERENT
bsa0wjtftg3uw      1512486435 22:23:19            1        1512486435 22:23:19
bsa0wjtftg3uw      1512486435 22:23:19            2        1512486435 20:48:45 DIFFERENT
...
c4nhd1ntptxq7      3477319146 20:28:46            0        3477319146 20:28:46
c4nhd1ntptxq7      3477319146 20:28:46            1        3477319146 20:28:46
...
cb21bacyh3c7d      3452538079 21:03:43            0        3452538079 20:28:45 DIFFERENT
cb21bacyh3c7d      3452538079 21:03:43            1        3452538079 20:28:46 DIFFERENT
cb21bacyh3c7d      3452538079 21:03:43            2        3452538079 21:03:43
...
cjk1ffy5kmm5s      1964104430 20:28:46            0        1964104430 20:28:45 DIFFERENT
cjk1ffy5kmm5s      1964104430 20:28:46            1        1964104430 20:28:46
...
cvn54b7yz0s8u      3246118364 21:03:43            0        3246118364 20:28:45 DIFFERENT
cvn54b7yz0s8u      3246118364 21:03:43            1        3246118364 21:03:43
d00a21h5ybffr       959325123 20:44:48            0        2829621105 20:28:45 DIFFERENT
d00a21h5ybffr       959325123 20:44:48            1         959325123 20:44:48
...
f3g84j69n0tjh      2335623859 21:03:43            0         914792125 20:28:45 DIFFERENT
f3g84j69n0tjh      2335623859 21:03:43            1        2335623859 21:03:43
...
fzrshwabvtwc0      3637245398 22:23:45            0        3637245398 20:28:45 DIFFERENT
fzrshwabvtwc0      3637245398 22:23:45            1        3637245398 22:23:45
...
g3wrkmxkxzhf2       749386351 21:03:43            0         749386351 20:28:45 DIFFERENT
g3wrkmxkxzhf2       749386351 21:03:43            1         749386351 21:03:43
...
g7smmy8ybh3gv        43085360 20:28:55            0          43085360 20:28:46 DIFFERENT
g7smmy8ybh3gv        43085360 20:28:55            1          43085360 20:28:55
...
ga9j9xk5cy9s0      1697022209 21:03:43            0        1697022209 20:28:45 DIFFERENT
ga9j9xk5cy9s0      1697022209 21:03:43            1        1697022209 21:03:43
...
grwydz59pu6mc      3684871272 21:03:43            0        3684871272 20:28:45 DIFFERENT
grwydz59pu6mc      3684871272 21:03:43            1        3684871272 21:03:43
...
gx4mv66pvj3xz      1932954096 21:03:43            0        1932954096 21:03:43
gx4mv66pvj3xz      1932954096 21:03:43            1        2570921597 20:28:45 DIFFERENT
gx4mv66pvj3xz      1932954096 21:03:43            2        1932954096 20:48:45 DIFFERENT
... 

I feel that I need some more suitable pictures now.  :-)





Hyper-Extended Oracle Performance Monitor 6.0 Beta

15 03 2012

March 15, 2012 (Modified March 16, 2012)

Several people expressed an interest in using the Beta version of my Hyper-Extended Oracle Performance Monitor 6.0 that has been under development for about a decade.  Rather than trying to find a way to deliver the Beta version of the program to those people who left comments in the earlier thread, it seemed to be much easier to just post the Beta version to this blog.

The  Hyper-Extended Oracle Performance Monitor tool runs from a Windows client PC (XP with ADO 2.8+ installed, Vista, Windows 7 32/64 bit, Server 2003, Server 2008) and for some tasks, such as report generation, requires Microsoft Excel (2000, XP, 2003, 2007, or 2010) to be present on the PC.  Everything that is logged is written to a C:\OracleLog folder on the client computer, and unfortunately that likely means that User Access Control (UAC) in Vista and Windows 7 will either need to be turned down or turned off completely (UAC will prevent programs from writing in folders that are located directly in the root of the C:\ drive).  It is important to make certain that the Windows interfaces (all except MTS) are installed with the Oracle Client software, which should add the OraOLEDB functionality that is used by the program for connectivity to the databases.

An unfortunate side effect of using OraOLEDB functionality rather than ODBC is that the SYS user is not able to log in AS SYSDBA for certain tasks such as accessing the X$ structures (specifically X$BH, and the X$ structures (X$KSPPI, X$KSPPSV) needed for viewing the hidden initialization parameters). Setting the O7_DICTIONARY_ACCESSIBILITY initialization parameter to TRUE will allow the program to connect as the SYS user (without AS SYSDBA), but doing so may represent a security risk for the database.

The program writes nothing to the Oracle database that is monitored, although it might try to automatically adjust the MAX_DUMP_FILE_SIZE parameter if the user attempts to enable a 10046 trace using the program, and the program determines that the MAX_DUMP_FILE_SIZE parameter is set far too small.  The user that logs into the program will need proper permissions to access the various V$ views (GV$ views are not accessed) and also access the various packages that enable 10046/10053 traces (enabling a 10046 (or other trace) within the program’s interface requires that the user logging into the program have EXECUTE permission on the DBMS_SYSTEM and DBMS_MONITOR packages).

The 10046 trace file parser is still a bit stuck in the land of Oracle Database 8.1 – it still expects to find p1, p2, and p3 on WAIT event lines if the Table and Object Lookup option is selected for trace file parsing (and for certain wait event analysis).  Later versions of Oracle Database emit obj parameters on the WAIT lines, and the program should use the obj value rather than trying to look up the OBJECT_ID value using the p1, p2, and p3 parameters. The 10046 trace file parser performs a trick to handle the extremely long cursor numbers found in Oracle Database 11.2.0.2 and later.  The Hyper-Extended Oracle Performance Monitor is intended to work fully on Oracle Database 10.2, and (hopefully) gracefully degrade when an older version of Oracle Database is encountered.

The program supports several command line parameters, most of which are used to configure performance logging capabilities:

-D      The Database instance SID to which the program should connect.
-U      The user name to be used for connecting to the database instance.
-P      The password to be used for connecting to the database instance.

-LC 20  Specifies Force a Log Capture when CPU Usage Exceeds value to 20%
-LI 30  Specifies Force a Log Capture if No Log Captured in Minutes value to 30 minutes
-LB     Specifies the Force a Log Capture when a Blocking Lock is Detected value to checked
-LW     Specifies the Force a Log Capture when a Wait Reason is Detected value to checked
-LR     Specifies the Capture SQL Execution Statistics for Wait Reasons value to checked
-LD     Specifies the Capture Segment Change Statistics value to checked
-LO     Specifies the Capture Operating System and Time Model Statistics value to checked
-LH     Specifies the Capture High Load SQL Statement Statistics value to checked
-LT     Specifies the Capture High Load SQL Statement Text value to checked
-LP     Specifies the Capture High Load SQL Statement Plan value to checked
-LHC 60 Species the minimum CPU time that is considered high load to 60 seconds accum.
-LHE 90 Species the minimum elapsed time that is considered high load to 90 seconds accum.
-LS     Specifies that Smart Logging should begin as soon as the login completes
-LE 240 Specifies that Smart Logging should end after 240 minutes
-LQ     Specifies that the program should quit (end) when logging ends

-

Important: Keep in mind that there is an overhead, primarily server CPU utilization, associated with performance monitoring.  This overhead will be greatest when the program’s performance logging feature is utilized.  This overhead, while typically minor, might negatively impact the performance of other database sessions.  Under no circumstances should this program run directly on a Windows-based Oracle Database server’s console – doing so with performance logging enabled will significantly impact the performance of other database sessions.

This program does not phone home, nor does it collect any information that is not found in the C:\OracleLog folder on the client computer.  The C:\OracleLog folder could prove to provide additional information that is not presented directly in the program interface.  For example, when real-time performance is monitored, every 30 minutes the program will write one or more text files into the C:\OracleLog folder that show a crosstab style report of statistics and wait events (open the file with Microsoft Excel to aid readability).  The performance logging feature creates a Microsoft Access compatible database (named to correspond to the logging date and time) in the C:\OracleLog folder – various information, such as in-effect initialization parameters, are written in that Access database, even though that information is not displayed in the program’s user interface.

———————————————————————————————–
———————————————————————————————–
———————————————————————————————–

DOWNLOAD:

The documentation for the program is at least four years out of date.  You may download the program instructions for the Hyper-Extended Oracle Performance Monitor 3.0 Beta here: Hyper-ExtendedOraclePerformanceMonitor3Docs

The Beta version of the program is time limited, however it should continue functioning for the next 12 months.  You may download the program by right clicking the file and saving it as “Hyper-ExtendedOraclePerformanceMonitor6.zip” (the .zip extension must be specified): Hyper-ExtendedOraclePerformanceMonitor6.zip

The program is compressed using WinZip – Windows XP and later are able to directly open .zip files.  To install the program, simply extract the two files into the same folder; to uninstall, delete that folder and the C:\OracleLog folder.

If you find the program useful, feel free to leave a comment here.  If you find that this program is the biggest waste of a decade’s worth of free time, I would be happy to hear that too.  The program has a couple of known bugs – I know that they exist, but I do not know where they are in the program, nor do I yet know what the bugs affect.

———————————————————————————————–
———————————————————————————————–
———————————————————————————————–

Added March 16, 2012:

I thought that I would show a couple of screen captures from my program that are not necessarily performance tuning specific.

The Advanced Initialization Parameters Viewer (currently only works if the O7_DICTIONARY_ACCESSIBILITY initialization parameter is set to TRUE , but I am considering a couple of work around methods – note that the program’s description of the CURSOR_SHARING parameter does not yet mention that the SIMILAR value for the CURSOR_SHARING parameter is deprecated):

Keyword Search Viewer:

Lock/Wait Monitor:

Configure Data Change Log (showing one of the logging tables that was created by the program’s script generator):

DBMS_XPLAN and Trace:





Thoughts on a Hyper-Extended Oracle Performance Monitor Beta

12 03 2012

March 12, 2012

As long time readers of this blog might know, in my free time during roughly the last 10 years I have been working on a program named “Hyper-Extended Oracle Performance Monitor”.  Since 2005 or 2006 I have permitted a few people to try the beta versions of the program, thinking that I might obtain a bit of feedback about what works well, and what needs a lot of work.  I was recently informed of a couple of situations where one or two features in the program were extremely useful – I would much rather hear that kind of feedback, rather than “I forgot about that program.” :-)

What started as a simple 10046 trace file parser, easy method to execute a handful of scripts, and a V$ performance view logger has certainly grown over the years.  I have not updated the documentation for the program in almost four years, and some suggestions offered by the program seem to be Oracle Database 8.1 specific… one of these days I might have some time to address those issues.

Over the last couple of days I found a couple of unplanned features (bugs) in the program – some of those features have been in the program for a couple of years, others were added just last week.  I am currently debating whether or not to open up the beta of the program to a wider audience.  Are any readers of this blog interested?

The main screen in the program probably looks unlike any program that you have seen in the past – menus, who needs menus:

-

If you drag and drop an Oracle 10046 trace file on the picture in the main screen, you will see a daunting list of options:

-

If you have followed along with the six part series on building an Oracle Database Time Model Viewer, you might recognize this screen in my program:

-

One of the original purposes of the program was to log the various statistics found in certain V$ performance views.  Over the years I added additional information that the program is able to optionally capture, and set up the logging capabilities so that certain events will force more frequent logging of statistics: 

 

-

With logging enabled, statistics are written to an dynamically created Microsoft Access compatible database, and as the statistics are captured, a summary of the statistics is written to the main program window:

-

Once you have logged something interesting, you can go back and review the information using a variety of interfaces in the program (or just stare blankly at the Microsoft Access database that was created).  Among other things, the below screen capture shows that one session spent roughly 24 seconds of the roughly 60 second time period in the wait event enq: TX – row lock contention.

-

We can easily take a look at the system level wait events and statistics for this time period:

-

Or drill-down to the session level waits and statistics from the table at the bottom of the Review Time Model Statistics window.  There is the session and its wait event, but what caused the wait event?

-

Maybe we should investigate… there’s a button for that.  Blocker and Blocked near the bottom left of the window – I wonder if that is a clue?

-

Let’s double-click one of those rows to see what happens:

-

Nice start, but let’s ask for more information by clicking Yes.

We now have the SQL statement the blocked session was attempting to execute, and possibly the SQL statement that the blocker executed which caused the  enq: TX – row lock contention wait event (the SQL statement is actually the most recent SQL statement executed by the blocker in the time period).

-

We are also able to take a quick tour of some of the SQL statements executed in the capture period and an extended version of the execution plans for those SQL statements:

-

There are another eight year’s worth of development in the program…





Will Enabling a 10046 Trace Make My Query Slower (or Faster)?

13 02 2012

February 13, 2012 (Modified February 14, 2012)

It seems that I often wonder about the things that I read… is it really true?  Several years ago, one of the items that I wondered about is whether or not an execution plan for a SQL statement could change magically simply because the Oracle RDBMS knows that it is being watched (a bit short-sighted, but stay with me for a couple of minutes).  When you first learn to read raw 10046 extended SQL trace files, you might also start to wonder whether or not enabling a 10046 trace could make the Oracle RDBMS suddenly start to behave differently.

Let’s take a quick look at a small portion of a 11.2.0.2 trace file:

PARSING IN CURSOR #371254768 len=53 dep=0 uid=62 oct=3 lid=62 tim=184435767875 hv=1334288504 ad='7ffb8c1be40' sqlid='a75xc757sg83s'
SELECT /*+ INDEX(T3) */
  *
FROM
  T3
WHERE
  C1<=200
END OF STMT
PARSE #371254768:c=0,e=699,p=0,cr=0,cu=0,mis=1,r=0,dep=0,og=1,plh=216260220,tim=184435767874
EXEC #371254768:c=0,e=25,p=0,cr=0,cu=0,mis=0,r=0,dep=0,og=1,plh=216260220,tim=184435767947
WAIT #371254768: nam='SQL*Net message to client' ela= 0 driver id=1413697536 #bytes=1 p3=0 obj#=0 tim=184435767976
WAIT #371254768: nam='db file scattered read' ela= 320 file#=4 block#=4145624 blocks=8 obj#=73036 tim=184435768358
WAIT #371254768: nam='db file scattered read' ela= 276 file#=4 block#=4145616 blocks=8 obj#=73035 tim=184435768704
FETCH #371254768:c=0,e=764,p=16,cr=2,cu=0,mis=0,r=1,dep=0,og=1,plh=216260220,tim=184435768757 

In the above, notice the mis=1 entry on the PARSE #371254768 line – that entry indicates a hard parse, a re-optimization of the SQL statement by the query optimizer.  If this SQL statement used bind variables, a feature known as bind variable peeking (introduced in Oracle 9.0.1) would take place during re-optimization, which might provide the optimizer with more information (with the help of a histogram, for instance) and potentially result in a change to the SQL statement’s execution plan.

(A partially related note: I just recently placed an order for the book “Oracle Database 11gR2 Performance Tuning Cookbook“, and while taking a quick peek at two or three pages in the book’s preview on Amazon, I found an error related to the above mentioned feature.)

Let’s take a look at a quick example of the above situation.  We will start by creating a table, inserting 100,000 rows where 20% of the rows have the value 0 in column C2, creating an index on column C2, and gathering statistics with histograms:

CREATE TABLE T5(
  C1 NUMBER NOT NULL,
  C2 NUMBER NOT NULL,
  C3 VARCHAR2(300) NOT NULL);

INSERT INTO
  T5
SELECT
  ROWNUM C1,
  DECODE(MOD(ROWNUM,5),0,0,ROWNUM) C2,
  RPAD('A',300,'A') C3
FROM
  DUAL
CONNECT BY
  LEVEL<=100000;

COMMIT;

CREATE INDEX IND_T5_C2 ON T5(C2);

EXEC DBMS_STATS.GATHER_TABLE_STATS(OWNNAME=>NULL,TABNAME=>'T5',CASCADE=>TRUE,ESTIMATE_PERCENT=>100,METHOD_OPT=>'FOR ALL COLUMNS SIZE 254') 

Now for the first segment of the test script, where a single row will be selected from the table.  To save space, I will not show the output from the select of the table T5, but will show the DBMS_XPLAN output:

ALTER SESSION SET TRACEFILE_IDENTIFIER = '10046TraceFindMe';

SET LINESIZE 120
SET PAGESIZE 1000
VAR V2 NUMBER
EXEC :V2:=4

SELECT
  C1
FROM
  T5
WHERE
  C2=:V2;

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

SQL_ID  cmm43s6usjbk1, child number 0
-------------------------------------
SELECT   C1 FROM   T5 WHERE   C2=:V2

Plan hash value: 3443248787

-----------------------------------------------------------------------------------------
| Id  | Operation                   | Name      | Rows  | Bytes | Cost (%CPU)| Time     |
-----------------------------------------------------------------------------------------
|   0 | SELECT STATEMENT            |           |       |       |     2 (100)|          |
|   1 |  TABLE ACCESS BY INDEX ROWID| T5        |     1 |    10 |     2   (0)| 00:00:01 |
|*  2 |   INDEX RANGE SCAN          | IND_T5_C2 |     1 |       |     1   (0)| 00:00:01 |
-----------------------------------------------------------------------------------------

Predicate Information (identified by operation id):
---------------------------------------------------
   2 - access("C2"=:V2) 

An index range scan, that is reasonable.  Let’s change the value of the bind variable so that 20% of the rows from the table will be selected, and take a look at the execution plan:

EXEC :V2:=0

SELECT
  C1
FROM
  T5
WHERE
  C2=:V2;

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

SQL_ID  cmm43s6usjbk1, child number 0
-------------------------------------
SELECT   C1 FROM   T5 WHERE   C2=:V2

Plan hash value: 3443248787

-----------------------------------------------------------------------------------------
| Id  | Operation                   | Name      | Rows  | Bytes | Cost (%CPU)| Time     |
-----------------------------------------------------------------------------------------
|   0 | SELECT STATEMENT            |           |       |       |     2 (100)|          |
|   1 |  TABLE ACCESS BY INDEX ROWID| T5        |     1 |    10 |     2   (0)| 00:00:01 |
|*  2 |   INDEX RANGE SCAN          | IND_T5_C2 |     1 |       |     1   (0)| 00:00:01 |
-----------------------------------------------------------------------------------------

Predicate Information (identified by operation id):
---------------------------------------------------
   2 - access("C2"=:V2) 

Notice in the above that the child number is still 0 and that the execution plan remained the same, even though we requested the retrieval of 20% of the rows from table T5.  In Oracle Database 11.1 and above, adaptive cursor sharing might eventually step in to change the execution plan for this bind variable value to use a full table scan, but that change could not happen on the first execution.

Now, we will enable a 10046 trace, set the bind variable value to the second value listed above, and return the execution plan:

ALTER SESSION SET EVENTS '10046 TRACE NAME CONTEXT FOREVER, LEVEL 8';

EXEC :V2:=0

SELECT
  C1
FROM
  T5
WHERE
  C2=:V2;

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

SQL_ID  cmm43s6usjbk1, child number 1
-------------------------------------
SELECT   C1 FROM   T5 WHERE   C2=:V2

Plan hash value: 2002323537

--------------------------------------------------------------------------
| Id  | Operation         | Name | Rows  | Bytes | Cost (%CPU)| Time     |
--------------------------------------------------------------------------
|   0 | SELECT STATEMENT  |      |       |       |   358 (100)|          |
|*  1 |  TABLE ACCESS FULL| T5   | 19685 |   192K|   358   (1)| 00:00:01 |
--------------------------------------------------------------------------

Predicate Information (identified by operation id):
---------------------------------------------------
   1 - filter("C2"=:V2) 

Notice in the above output that while the SQL_ID has remained constant, the child number is now 1, and the execution plan changed to a full table scan.  Bind variable peeking and the histogram on column C2 provided the optimizer with enough information to result in an execution plan change.

Let’s switch back to the original bind variable value, which will result in a single row being returned:

SELECT
  C1
FROM
  T5
WHERE
  C2=:V2;

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

SQL_ID  cmm43s6usjbk1, child number 1
-------------------------------------
SELECT   C1 FROM   T5 WHERE   C2=:V2

Plan hash value: 2002323537

--------------------------------------------------------------------------
| Id  | Operation         | Name | Rows  | Bytes | Cost (%CPU)| Time     |
--------------------------------------------------------------------------
|   0 | SELECT STATEMENT  |      |       |       |   358 (100)|          |
|*  1 |  TABLE ACCESS FULL| T5   | 19685 |   192K|   358   (1)| 00:00:01 |
--------------------------------------------------------------------------

Predicate Information (identified by operation id):
---------------------------------------------------
   1 - filter("C2"=:V2) 

Note that child cursor 1 is still used – a full table scan where an index range scan was used previous to enabling a 10046 trace.  So, while we have not examined execution times, we have now seen cases where a query could potentially execute faster or slower due to a change in the execution plan after a 10046 extended SQL trace is enabled.

Let’s try one more time with the 10046 trace still enabled:

SELECT
  C1
FROM
  T5
WHERE
  C2=:V2;

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

SQL_ID  cmm43s6usjbk1, child number 2
-------------------------------------
SELECT   C1 FROM   T5 WHERE   C2=:V2

Plan hash value: 3443248787

-----------------------------------------------------------------------------------------
| Id  | Operation                   | Name      | Rows  | Bytes | Cost (%CPU)| Time     |
-----------------------------------------------------------------------------------------
|   0 | SELECT STATEMENT            |           |       |       |     2 (100)|          |
|   1 |  TABLE ACCESS BY INDEX ROWID| T5        |     1 |    10 |     2   (0)| 00:00:01 |
|*  2 |   INDEX RANGE SCAN          | IND_T5_C2 |     1 |       |     1   (0)| 00:00:01 |
-----------------------------------------------------------------------------------------

Predicate Information (identified by operation id):
---------------------------------------------------
   2 - access("C2"=:V2)

Now the child cursor number is displayed as 2, and the execution plan returned to an index range scan.  Adaptive cursor sharing kicked in and caused a re-optimization of the SQL statement.

Let’s disable the 10046 extended SQL trace:

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

A quick look at a small (marked up) portion of the raw 10046 extended SQL trace file – the first execution with the 10046 trace enabled:

PARSING IN CURSOR #429376080 len=20 dep=0 uid=62 oct=47 lid=62 tim=11461702777 hv=1269726367 ad='7ffb76adba8' sqlid='5dxda7t5uwz4z'
BEGIN :V2:=0; END;
END OF STMT
PARSE #429376080:c=0,e=56,p=0,cr=0,cu=0,mis=0,r=0,dep=0,og=1,plh=0,tim=11461702777
WAIT #429376080: nam='SQL*Net message to client' ela= 1 driver id=1413697536 #bytes=1 p3=0 obj#=532 tim=11461702853
EXEC #429376080:c=0,e=53,p=0,cr=0,cu=0,mis=0,r=1,dep=0,og=1,plh=0,tim=11461702867
WAIT #429376080: nam='SQL*Net message from client' ela= 1401 driver id=1413697536 #bytes=1 p3=0 obj#=532 tim=11461704296
CLOSE #429376080:c=0,e=12,dep=0,type=0,tim=11461704325
=====================
PARSING IN CURSOR #429376080 len=36 dep=0 uid=62 oct=3 lid=62 tim=11461704495 hv=3045633601 ad='7ffb77363b0' sqlid='cmm43s6usjbk1'
SELECT
  C1
FROM
  T5
WHERE
  C2=:V2
END OF STMT
PARSE #429376080:c=0,e=152,p=0,cr=0,cu=0,mis=1,r=0,dep=0,og=1,plh=0,tim=11461704494   <--- Hard Parse
EXEC #429376080:c=0,e=784,p=0,cr=0,cu=0,mis=1,r=0,dep=0,og=1,plh=2002323537,tim=11461705325
WAIT #429376080: nam='SQL*Net message to client' ela= 1 driver id=1413697536 #bytes=1 p3=0 obj#=532 tim=11461705357
FETCH #429376080:c=0,e=35,p=0,cr=3,cu=0,mis=0,r=1,dep=0,og=1,plh=2002323537,tim=11461705408
...
WAIT #429376080: nam='SQL*Net message to client' ela= 1 driver id=1413697536 #bytes=1 p3=0 obj#=532 tim=11463556616
FETCH #429376080:c=0,e=21,p=0,cr=1,cu=0,mis=0,r=4,dep=0,og=1,plh=2002323537,tim=11463556630
STAT #429376080 id=1 cnt=20000 pid=0 pos=1 obj=73243 op='TABLE ACCESS FULL T5 (cr=5813 pr=0 pw=0 time=15413 us cost=358 size=196850 card=19685)'
... 

In the above, notice the mis=1 entry on the PARSE #429376080 line – the optimizer hard parsed the SQL statement.  Moving down a bit in the trace file, the second execution with the changed bind variable value:

PARSING IN CURSOR #429376080 len=20 dep=0 uid=62 oct=47 lid=62 tim=11505336665 hv=1039981032 ad='7ffb873a408' sqlid='857u964yztqg8'
BEGIN :V2:=4; END;
END OF STMT
PARSE #429376080:c=0,e=93,p=0,cr=0,cu=0,mis=0,r=0,dep=0,og=1,plh=0,tim=11505336664
WAIT #429376080: nam='SQL*Net message to client' ela= 2 driver id=1413697536 #bytes=1 p3=0 obj#=532 tim=11505336754
EXEC #429376080:c=0,e=63,p=0,cr=0,cu=0,mis=0,r=1,dep=0,og=1,plh=0,tim=11505336769
WAIT #429376080: nam='SQL*Net message from client' ela= 2382 driver id=1413697536 #bytes=1 p3=0 obj#=532 tim=11505339191
CLOSE #429376080:c=0,e=13,dep=0,type=0,tim=11505339229
=====================
PARSING IN CURSOR #429376080 len=36 dep=0 uid=62 oct=3 lid=62 tim=11505339288 hv=3045633601 ad='7ffb77363b0' sqlid='cmm43s6usjbk1'
SELECT
  C1
FROM
  T5
WHERE
  C2=:V2
END OF STMT
PARSE #429376080:c=0,e=39,p=0,cr=0,cu=0,mis=0,r=0,dep=0,og=1,plh=2002323537,tim=11505339288   <--- NO Hard Parse
EXEC #429376080:c=0,e=20,p=0,cr=0,cu=0,mis=0,r=0,dep=0,og=1,plh=2002323537,tim=11505339355
WAIT #429376080: nam='SQL*Net message to client' ela= 1 driver id=1413697536 #bytes=1 p3=0 obj#=532 tim=11505339381
FETCH #429376080:c=0,e=296,p=0,cr=4,cu=0,mis=0,r=1,dep=0,og=1,plh=2002323537,tim=11505339693
... 

In the above, notice the mis=0 entry on the PARSE #429376080 line – the optimizer did NOT re-optimize this SQL statement, so the execution plan remained a full table scan.  Now the final section that was influenced by adaptive cursor sharing:

PARSING IN CURSOR #429376080 len=36 dep=0 uid=62 oct=3 lid=62 tim=12566538414 hv=3045633601 ad='7ffb77363b0' sqlid='cmm43s6usjbk1'
SELECT
  C1
FROM
  T5
WHERE
  C2=:V2
END OF STMT
PARSE #429376080:c=0,e=55,p=0,cr=0,cu=0,mis=0,r=0,dep=0,og=1,plh=2002323537,tim=12566538414   <--- NO Hard Parse
EXEC #429376080:c=0,e=1594,p=0,cr=0,cu=0,mis=1,r=0,dep=0,og=1,plh=3443248787,tim=12566540065  <--- Hard Parse
WAIT #429376080: nam='SQL*Net message to client' ela= 1 driver id=1413697536 #bytes=1 p3=0 obj#=532 tim=12566540198
FETCH #429376080:c=0,e=29,p=0,cr=3,cu=0,mis=0,r=1,dep=0,og=1,plh=3443248787,tim=12566540245 

In the above, notice the mis=0 entry on the PARSE #429376080 line – the optimizer did NOT re-optimize this SQL statement during the parse phase.  However, remember that the cursor number changed from the previous value of 1 to 2; the above EXEC #429376080 contains mis=1, so a hard parse was performed during the execution phase.

You might be thinking that maybe the execution plans can only change if we use bind variables when histograms are present.  Let’s try another experiment.  First, we will create a table, create an index on that table, insert 100,000 rows with the same characteristics as those found in table T5, and NOT collect statistics:

CREATE TABLE T6 (
  C1 NUMBER NOT NULL,
  C2 NUMBER NOT NULL,
  C3 VARCHAR2(300) NOT NULL);

CREATE INDEX IND_T6_C2 ON T6(C2);

INSERT INTO
  T6
SELECT
  ROWNUM C1,
  DECODE(MOD(ROWNUM,5),0,0,ROWNUM) C2,
  RPAD('A',300,'A') C3
FROM
  DUAL
CONNECT BY
  LEVEL<=100000;

COMMIT; 

Let’s repeat the previous test case:

SET LINESIZE 120
SET PAGESIZE 1000
VAR V2 NUMBER
EXEC :V2:=4

SELECT
  C1
FROM
  T6
WHERE
  C2=:V2;

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

SQL_ID  9krhnbpjpvpwh, child number 0
-------------------------------------
SELECT   C1 FROM   T6 WHERE   C2=:V2

Plan hash value: 4242288932

-----------------------------------------------------------------------------------------
| Id  | Operation                   | Name      | Rows  | Bytes | Cost (%CPU)| Time     |
-----------------------------------------------------------------------------------------
|   0 | SELECT STATEMENT            |           |       |       |     1 (100)|          |
|   1 |  TABLE ACCESS BY INDEX ROWID| T6        |     1 |    26 |     1   (0)| 00:00:01 |
|*  2 |   INDEX RANGE SCAN          | IND_T6_C2 |     1 |       |     1   (0)| 00:00:01 |
-----------------------------------------------------------------------------------------

Predicate Information (identified by operation id):
---------------------------------------------------
   2 - access("C2"=:V2)

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

The above shows that dynamic sampling was used during the hard parse, and as expected an index range scan was performed.  Part 2 of the previous test script:

EXEC :V2:=0

SELECT
  C1
FROM
  T6
WHERE
  C2=:V2;

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

SQL_ID  9krhnbpjpvpwh, child number 0
-------------------------------------
SELECT   C1 FROM   T6 WHERE   C2=:V2

Plan hash value: 4242288932

-----------------------------------------------------------------------------------------
| Id  | Operation                   | Name      | Rows  | Bytes | Cost (%CPU)| Time     |
-----------------------------------------------------------------------------------------
|   0 | SELECT STATEMENT            |           |       |       |     1 (100)|          |
|   1 |  TABLE ACCESS BY INDEX ROWID| T6        |     1 |    26 |     1   (0)| 00:00:01 |
|*  2 |   INDEX RANGE SCAN          | IND_T6_C2 |     1 |       |     1   (0)| 00:00:01 |
-----------------------------------------------------------------------------------------

Predicate Information (identified by operation id):
---------------------------------------------------
   2 - access("C2"=:V2)

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

Again, nothing new – no hard parse when the bind variable was changed, and so the index was still used.  Part 3 of the previous test script:

ALTER SESSION SET EVENTS '10046 TRACE NAME CONTEXT FOREVER, LEVEL 8';

EXEC :V2:=0

SELECT
  C1
FROM
  T6
WHERE
  C2=:V2;

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

SQL_ID  9krhnbpjpvpwh, child number 1
-------------------------------------
SELECT   C1 FROM   T6 WHERE   C2=:V2

Plan hash value: 4242288932

-----------------------------------------------------------------------------------------
| Id  | Operation                   | Name      | Rows  | Bytes | Cost (%CPU)| Time     |
-----------------------------------------------------------------------------------------
|   0 | SELECT STATEMENT            |           |       |       |   142 (100)|          |
|   1 |  TABLE ACCESS BY INDEX ROWID| T6        | 34140 |   866K|   142   (0)| 00:00:01 |
|*  2 |   INDEX RANGE SCAN          | IND_T6_C2 | 34140 |       |   142   (0)| 00:00:01 |
-----------------------------------------------------------------------------------------

Predicate Information (identified by operation id):
---------------------------------------------------
   2 - access("C2"=:V2)

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

There was a hard parse, as is noted by the change in the child cursor number, yet the optimizer still decided that it was most efficient to perform an index range scan.  The optimizer estimated that 34,140 rows would be returned with an estimated size of 866KB.  You might recall that earlier the same test for table T5 showed the following execution plan:

--------------------------------------------------------------------------
| Id  | Operation         | Name | Rows  | Bytes | Cost (%CPU)| Time     |
--------------------------------------------------------------------------
|   0 | SELECT STATEMENT  |      |       |       |   358 (100)|          |
|*  1 |  TABLE ACCESS FULL| T5   | 19685 |   192K|   358   (1)| 00:00:01 |
--------------------------------------------------------------------------

Predicate Information (identified by operation id):
---------------------------------------------------
   1 - filter("C2"=:V2) 

With a histogram (and without dynamic sampling), the optimizer estimated that 19,685 rows would be returned with an estimated size of 192KB – and in that case a full table scan was performed.  But why was a full table scan not performed when experimenting with dynamic sampling?  Is it possible that if the query optimizer uses dynamic sampling, that the execution plan is NOT subject to change when a 10046 extended SQL trace is enabled, or is there a simplier cause?

Let’s try executing the query with a FULL hint:

SELECT /*+ FULL(T6) */
  C1
FROM
  T6
WHERE
  C2=:V2;

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

SQL_ID  bhm179jq4vvca, child number 0
-------------------------------------
SELECT /*+ FULL(T6) */   C1 FROM   T6 WHERE   C2=:V2

Plan hash value: 1930642322

--------------------------------------------------------------------------
| Id  | Operation         | Name | Rows  | Bytes | Cost (%CPU)| Time     |
--------------------------------------------------------------------------
|   0 | SELECT STATEMENT  |      |       |       |   357 (100)|          |
|*  1 |  TABLE ACCESS FULL| T6   | 34140 |   866K|   357   (1)| 00:00:01 |
--------------------------------------------------------------------------

Predicate Information (identified by operation id):
---------------------------------------------------
   1 - filter("C2"=:V2)

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

Well, that explains part of the issue.  While the calculated cost of the full table scan access path is 357 (very close to the 358 calculated for the same SQL statement that accessed table T5), the calculated cost of the index access path was only 142 – the lowest calculated cost access path wins.

What if we force an index access path for table T5 with the same value of 0 for the bind variable.  Will the calculated cost also be roughly 142?

SELECT /*+ INDEX(T5) */
  C1
FROM
  T5
WHERE
  C2=:V2;

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

SQL_ID  5y34jm13up8xh, child number 0
-------------------------------------
SELECT /*+ INDEX(T5) */   C1 FROM   T5 WHERE   C2=:V2

Plan hash value: 3443248787

-----------------------------------------------------------------------------------------
| Id  | Operation                   | Name      | Rows  | Bytes | Cost (%CPU)| Time     |
-----------------------------------------------------------------------------------------
|   0 | SELECT STATEMENT            |           |       |       |  1826 (100)|          |
|   1 |  TABLE ACCESS BY INDEX ROWID| T5        | 19685 |   192K|  1826   (1)| 00:00:01 |
|*  2 |   INDEX RANGE SCAN          | IND_T5_C2 | 19685 |       |    43   (0)| 00:00:01 |
-----------------------------------------------------------------------------------------

Predicate Information (identified by operation id):
---------------------------------------------------
   2 - access("C2"=:V2)  

Obviously, no – otherwise the index access path would have been selected for table T5 also – as shown above, the cost is actually 1826.

—-

The challenge (drifting a bit from the topic of this article): If dynamic sampling is used, and the optimizer knows that a many (possibly 34%) of the rows will be returned when the query is executed, why is an index access path used?  In other words, what causes the index access path to be calculated so cheaply when compared to the calculated cost for the same access path with table T5?  Is the above simply a bug found in Oracle Database 11.2.0.2, or is there a better explanation?

-

Added February 14, 2012:

One person (Narendra) noticed that there appeared to be a bug in the optimizer’s calculations.  If you closely examine the execution plans above, you just might notice that the Cost displayed on the INDEX RANGE SCAN operation’s line of the execution plan (142) is identical to the Cost displayed on its the parent operation TABLE ACCESS BY INDEX ROWID (142).  As is probably well known, a parent operation’s Cost, Buffers, Reads, and various other columns display their child statistics summed with the statistics that are directly associated with the parent operation.  Take another look at a portion of one of the earlier execution plans:

-----------------------------------------------------------------------------------------
| Id  | Operation                   | Name      | Rows  | Bytes | Cost (%CPU)| Time     |
-----------------------------------------------------------------------------------------
|   0 | SELECT STATEMENT            |           |       |       |   142 (100)|          |
|   1 |  TABLE ACCESS BY INDEX ROWID| T6        | 34140 |   866K|   142   (0)| 00:00:01 |
|*  2 |   INDEX RANGE SCAN          | IND_T6_C2 | 34140 |       |   142   (0)| 00:00:01 |
----------------------------------------------------------------------------------------- 

The cost displayed for the TABLE ACCESS BY INDEX ROWID operation should be greater than the cost displayed for the index access – unless the optimizer forgot that the table must be accessed when dynamic sampling is performed.  Oracle Database 11.2.0.1 and 11.2.0.2 appear to be affected by this particular bug, while Oracle Database 10.2.0.5 and 11.1.0.7 seem to under-estimate the cost of the table access when dynamic sampling is performed.  As such, if statistics on some of the tables (for instance temp tables) are locked without any statistics set on the tables (to force dynamic sampling), there could be a minor issue that becomes a more significant issue when upgrading to 11.2.0.1 or 11.2.0.2.

Recreating the same test table as earlier:

DROP TABLE T6 PURGE;

CREATE TABLE T6 (
  C1 NUMBER NOT NULL,
  C2 NUMBER NOT NULL,
  C3 VARCHAR2(300) NOT NULL);

CREATE INDEX IND_T6_C2 ON T6(C2);

INSERT INTO
  T6
SELECT
  ROWNUM C1,
  DECODE(MOD(ROWNUM,5),0,0,ROWNUM) C2,
  RPAD('A',300,'A') C3
FROM
  DUAL
CONNECT BY
  LEVEL<=100000;

COMMIT; 

The first portion of the test:

ALTER SESSION SET TRACEFILE_IDENTIFIER = '10053NO10046TraceFindMe';
ALTER SESSION SET EVENTS '10053 TRACE NAME CONTEXT FOREVER, LEVEL 1';

SET LINESIZE 120
SET PAGESIZE 1000
VAR V2 NUMBER
EXEC :V2:=4

SELECT /*+ GATHER_PLAN_STATISTICS */
  C1
FROM
  T6
WHERE
  C2=:V2;

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

SQL_ID  bxnurhc1nmq2g, child number 0
-------------------------------------
SELECT /*+ GATHER_PLAN_STATISTICS */   C1 FROM   T6 WHERE   C2=:V2

Plan hash value: 4242288932

----------------------------------------------------------------------------------------------------------------
| Id  | Operation                   | Name      | Starts | E-Rows | Cost (%CPU)| A-Rows |   A-Time   | Buffers |
----------------------------------------------------------------------------------------------------------------
|   0 | SELECT STATEMENT            |           |      1 |        |     1 (100)|      1 |00:00:00.01 |       4 |
|   1 |  TABLE ACCESS BY INDEX ROWID| T6        |      1 |      1 |     1   (0)|      1 |00:00:00.01 |       4 |
|*  2 |   INDEX RANGE SCAN          | IND_T6_C2 |      1 |      1 |     1   (0)|      1 |00:00:00.01 |       3 |
----------------------------------------------------------------------------------------------------------------

Peeked Binds (identified by position):
--------------------------------------
   1 - (NUMBER): 4

Predicate Information (identified by operation id):
---------------------------------------------------
   2 - access("C2"=:V2)

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

The second portion of the test:

EXEC :V2:=0

SELECT /*+ GATHER_PLAN_STATISTICS */
  C1
FROM
  T6
WHERE
  C2=:V2;

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

SQL_ID  bxnurhc1nmq2g, child number 0
-------------------------------------
SELECT /*+ GATHER_PLAN_STATISTICS */   C1 FROM   T6 WHERE   C2=:V2

Plan hash value: 4242288932

----------------------------------------------------------------------------------------------------------------
| Id  | Operation                   | Name      | Starts | E-Rows | Cost (%CPU)| A-Rows |   A-Time   | Buffers |
----------------------------------------------------------------------------------------------------------------
|   0 | SELECT STATEMENT            |           |      1 |        |     1 (100)|  20000 |00:00:00.06 |    6981 |
|   1 |  TABLE ACCESS BY INDEX ROWID| T6        |      1 |      1 |     1   (0)|  20000 |00:00:00.06 |    6981 |
|*  2 |   INDEX RANGE SCAN          | IND_T6_C2 |      1 |      1 |     1   (0)|  20000 |00:00:00.03 |    1410 |
----------------------------------------------------------------------------------------------------------------

Peeked Binds (identified by position):
--------------------------------------
   1 - (NUMBER): 4

Predicate Information (identified by operation id):
---------------------------------------------------
   2 - access("C2"=:V2)

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

Notice in the above that the execution plan has not changed, and the peeked bind variable value is still 4 (this is expected).

The third portion of the test:

ALTER SESSION SET TRACEFILE_IDENTIFIER = '1005310046TraceFindMe';
ALTER SESSION SET EVENTS '10046 TRACE NAME CONTEXT FOREVER, LEVEL 8';

EXEC :V2:=0

SELECT /*+ GATHER_PLAN_STATISTICS */
  C1
FROM
  T6
WHERE
  C2=:V2;

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

SQL_ID  bxnurhc1nmq2g, child number 1
-------------------------------------
SELECT /*+ GATHER_PLAN_STATISTICS */   C1 FROM   T6 WHERE   C2=:V2

Plan hash value: 4242288932

----------------------------------------------------------------------------------------------------------------
| Id  | Operation                   | Name      | Starts | E-Rows | Cost (%CPU)| A-Rows |   A-Time   | Buffers |
----------------------------------------------------------------------------------------------------------------
|   0 | SELECT STATEMENT            |           |      1 |        |    49 (100)|  20000 |00:00:00.06 |    6944 |
|   1 |  TABLE ACCESS BY INDEX ROWID| T6        |      1 |  18399 |    49   (0)|  20000 |00:00:00.06 |    6944 |
|*  2 |   INDEX RANGE SCAN          | IND_T6_C2 |      1 |  18399 |    49   (0)|  20000 |00:00:00.03 |    1373 |
----------------------------------------------------------------------------------------------------------------

Peeked Binds (identified by position):
--------------------------------------
   1 - (NUMBER): 0

Predicate Information (identified by operation id):
---------------------------------------------------
   2 - access("C2"=:V2)

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

Notice in the above that the Cost displayed for the INDEX RANGE SCAN operation is identical to the Cost displayed for the TABLE ACCESS BY INDEX ROWID – also notice the low estimated Cost for the index access (this might be a reasonable value, as will be shown below).

The fourth portion of the test, checking the cost of the full table scan access path:

SELECT /*+ FULL(T6) GATHER_PLAN_STATISTICS */
  C1
FROM
  T6
WHERE
  C2=:V2;

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

Plan hash value: 1930642322

-------------------------------------------------------------------------------------------------
| Id  | Operation         | Name | Starts | E-Rows | Cost (%CPU)| A-Rows |   A-Time   | Buffers |
-------------------------------------------------------------------------------------------------
|   0 | SELECT STATEMENT  |      |      1 |        |  1579 (100)|  20000 |00:00:00.05 |    5815 |
|*  1 |  TABLE ACCESS FULL| T6   |      1 |  18399 |  1579   (5)|  20000 |00:00:00.05 |    5815 |
-------------------------------------------------------------------------------------------------

Peeked Binds (identified by position):
--------------------------------------
   1 - (NUMBER): 0

Predicate Information (identified by operation id):
---------------------------------------------------
   1 - filter("C2"=:V2)

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

So, the calculated cost of the full table scan access path is quite high compared to the cost of the index access path.

Let’s try an undocumented OPT_ESTIMATE hint to see what happens:

SELECT /*+ OPT_ESTIMATE(TABLE, T6, ROWS=20000) GATHER_PLAN_STATISTICS */
  C1
FROM
  T6
WHERE
  C2=:V2;

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

Plan hash value: 4242288932

----------------------------------------------------------------------------------------------------------------
| Id  | Operation                   | Name      | Starts | E-Rows | Cost (%CPU)| A-Rows |   A-Time   | Buffers |
----------------------------------------------------------------------------------------------------------------
|   0 | SELECT STATEMENT            |           |      1 |        |     1 (100)|  20000 |00:00:00.06 |    6944 |
|   1 |  TABLE ACCESS BY INDEX ROWID| T6        |      1 |  20000 |     1   (0)|  20000 |00:00:00.06 |    6944 |
|*  2 |   INDEX RANGE SCAN          | IND_T6_C2 |      1 |      1 |     1   (0)|  20000 |00:00:00.02 |    1373 |
----------------------------------------------------------------------------------------------------------------

Peeked Binds (identified by position):
--------------------------------------
   1 - (NUMBER): 0

Predicate Information (identified by operation id):
---------------------------------------------------
   2 - access("C2"=:V2)

Now the calculated Cost of the index access path is just 1 – bad idea for a solution.

Let’s collect statistics on the table with a histogram on column C2 to see what happens:

EXEC DBMS_STATS.GATHER_TABLE_STATS(OWNNAME=>NULL,TABNAME=>'T6',CASCADE=>TRUE,ESTIMATE_PERCENT=>100,METHOD_OPT=>'FOR COLUMNS C2 SIZE 254',NO_INVALIDATE=>FALSE)

SELECT /*+ GATHER_PLAN_STATISTICS */
  C1
FROM
  T6
WHERE
  C2=:V2;

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

SQL_ID  bxnurhc1nmq2g, child number 0
-------------------------------------
SELECT /*+ GATHER_PLAN_STATISTICS */   C1 FROM   T6 WHERE   C2=:V2

Plan hash value: 1930642322

-------------------------------------------------------------------------------------------------
| Id  | Operation         | Name | Starts | E-Rows | Cost (%CPU)| A-Rows |   A-Time   | Buffers |
-------------------------------------------------------------------------------------------------
|   0 | SELECT STATEMENT  |      |      1 |        |  1582 (100)|  20000 |00:00:00.05 |    5814 |
|*  1 |  TABLE ACCESS FULL| T6   |      1 |  19685 |  1582   (5)|  20000 |00:00:00.05 |    5814 |
-------------------------------------------------------------------------------------------------

Peeked Binds (identified by position):
--------------------------------------
   1 - (NUMBER): 0

Predicate Information (identified by operation id):
---------------------------------------------------
   1 - filter("C2"=:V2)

The optimizer now selected to use a full table scan, rather than an index access path.

Let’s check the cost of the index access path:

SELECT /*+ INDEX(T6) GATHER_PLAN_STATISTICS */
  C1
FROM
  T6
WHERE
  C2=:V2;

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

SQL_ID  4nqwgus0ghxmc, child number 0
-------------------------------------
SELECT /*+ INDEX(T6) GATHER_PLAN_STATISTICS */   C1 FROM   T6 WHERE
C2=:V2

Plan hash value: 4242288932

----------------------------------------------------------------------------------------------------------------
| Id  | Operation                   | Name      | Starts | E-Rows | Cost (%CPU)| A-Rows |   A-Time   | Buffers |
----------------------------------------------------------------------------------------------------------------
|   0 | SELECT STATEMENT            |           |      1 |        |  1847 (100)|  20000 |00:00:00.07 |    6944 |
|   1 |  TABLE ACCESS BY INDEX ROWID| T6        |      1 |  19685 |  1847   (2)|  20000 |00:00:00.07 |    6944 |
|*  2 |   INDEX RANGE SCAN          | IND_T6_C2 |      1 |  19685 |    44  (12)|  20000 |00:00:00.02 |    1373 |
----------------------------------------------------------------------------------------------------------------

Peeked Binds (identified by position):
--------------------------------------
   1 - (NUMBER): 0

Predicate Information (identified by operation id):
---------------------------------------------------
   2 - access("C2"=:V2)

-

The results of the test from 10.2.0.5:

The first portion of the test:

ALTER SESSION SET TRACEFILE_IDENTIFIER = '10053NO10046TraceFindMe';
ALTER SESSION SET EVENTS '10053 TRACE NAME CONTEXT FOREVER, LEVEL 1';
 
SET LINESIZE 120
SET PAGESIZE 1000
VAR V2 NUMBER
EXEC :V2:=4
 
SELECT /*+ GATHER_PLAN_STATISTICS */
  C1
FROM
  T6
WHERE
  C2=:V2;
 
SELECT * FROM TABLE(DBMS_XPLAN.DISPLAY_CURSOR(NULL,NULL,'ALLSTATS LAST +PEEKED_BINDS +COST'));
 
SQL_ID  bxnurhc1nmq2g, child number 0
-------------------------------------
SELECT /*+ GATHER_PLAN_STATISTICS */   C1 FROM   T6 WHERE   C2=:V2
 
Plan hash value: 4242288932
 
----------------------------------------------------------------------------------------------------------------
| Id  | Operation                   | Name      | Starts | E-Rows | Cost (%CPU)| A-Rows |   A-Time   | Buffers |
----------------------------------------------------------------------------------------------------------------
|   0 | SELECT STATEMENT            |           |      1 |        |     2 (100)|      1 |00:00:00.01 |       4 |
|   1 |  TABLE ACCESS BY INDEX ROWID| T6        |      1 |      1 |     2   (0)|      1 |00:00:00.01 |       4 |
|*  2 |   INDEX RANGE SCAN          | IND_T6_C2 |      1 |      1 |     1   (0)|      1 |00:00:00.01 |       3 |
----------------------------------------------------------------------------------------------------------------
 
Peeked Binds (identified by position):
--------------------------------------
   1 - (NUMBER): 4
 
Predicate Information (identified by operation id):
---------------------------------------------------
   2 - access("C2"=:V2)
 
Note
-----
   - dynamic sampling used for this statement

Notice in the above output that the Cost displayed for the TABLE ACCESS BY INDEX ROWID operation is 2, while on 11.2.0.2 it was 1.

The second portion of the test script on 10.2.0.5:

EXEC :V2:=0
  
SELECT /*+ GATHER_PLAN_STATISTICS */
  C1
FROM
  T6
WHERE
  C2=:V2;
 
SELECT * FROM TABLE(DBMS_XPLAN.DISPLAY_CURSOR(NULL,NULL,'ALLSTATS LAST +PEEKED_BINDS +COST'));
 
SQL_ID  bxnurhc1nmq2g, child number 0
-------------------------------------
SELECT /*+ GATHER_PLAN_STATISTICS */   C1 FROM   T6 WHERE   C2=:V2
 
Plan hash value: 4242288932
 
----------------------------------------------------------------------------------------------------------------
| Id  | Operation                   | Name      | Starts | E-Rows | Cost (%CPU)| A-Rows |   A-Time   | Buffers |
----------------------------------------------------------------------------------------------------------------
|   0 | SELECT STATEMENT            |           |      1 |        |     2 (100)|  20000 |00:00:00.04 |    6969 |
|   1 |  TABLE ACCESS BY INDEX ROWID| T6        |      1 |      1 |     2   (0)|  20000 |00:00:00.04 |    6969 |
|*  2 |   INDEX RANGE SCAN          | IND_T6_C2 |      1 |      1 |     1   (0)|  20000 |00:00:00.01 |    1407 |
----------------------------------------------------------------------------------------------------------------
 
Peeked Binds (identified by position):
--------------------------------------
   1 - (NUMBER): 4
 
Predicate Information (identified by operation id):
---------------------------------------------------
   2 - access("C2"=:V2)
 
Note
-----
   - dynamic sampling used for this statement

No change in the execution plan, as expected.

The third portion of the script on 10.2.0.5:

ALTER SESSION SET TRACEFILE_IDENTIFIER = '1005310046TraceFindMe';
ALTER SESSION SET EVENTS '10046 TRACE NAME CONTEXT FOREVER, LEVEL 8';
  
EXEC :V2:=0
 
SELECT /*+ GATHER_PLAN_STATISTICS */
  C1
FROM
  T6
WHERE
  C2=:V2;
 
SELECT * FROM TABLE(DBMS_XPLAN.DISPLAY_CURSOR(NULL,NULL,'ALLSTATS LAST +PEEKED_BINDS +COST'));
 
SQL_ID  bxnurhc1nmq2g, child number 1
-------------------------------------
SELECT /*+ GATHER_PLAN_STATISTICS */   C1 FROM   T6 WHERE   C2=:V2
 
Plan hash value: 4242288932
 
----------------------------------------------------------------------------------------------------------------
| Id  | Operation                   | Name      | Starts | E-Rows | Cost (%CPU)| A-Rows |   A-Time   | Buffers |
----------------------------------------------------------------------------------------------------------------
|   0 | SELECT STATEMENT            |           |      1 |        |   209 (100)|  20000 |00:00:00.02 |    6932 |
|   1 |  TABLE ACCESS BY INDEX ROWID| T6        |      1 |  20556 |   209   (0)|  20000 |00:00:00.02 |    6932 |
|*  2 |   INDEX RANGE SCAN          | IND_T6_C2 |      1 |  20556 |    49   (0)|  20000 |00:00:00.01 |    1370 |
----------------------------------------------------------------------------------------------------------------
 
Peeked Binds (identified by position):
--------------------------------------
   1 - (NUMBER): 0
 
Predicate Information (identified by operation id):
---------------------------------------------------
   2 - access("C2"=:V2)
 
Note
-----
   - dynamic sampling used for this statement

Notice in the output above the that while the cost of the TABLE ACCESS BY INDEX ROWID operation is significantly higher than the INDEX RANGE SCAN child operation, the Cost was not high enough to result in a full table scan.

Checking the calculated cost of a full table scan:

SELECT /*+ FULL(T6) GATHER_PLAN_STATISTICS */
  C1
FROM
  T6
WHERE
  C2=:V2;
 
SELECT * FROM TABLE(DBMS_XPLAN.DISPLAY_CURSOR(NULL,NULL,'ALLSTATS LAST +PEEKED_BINDS +COST'));
 
SQL_ID  bk8rwkf0ab8h5, child number 0
-------------------------------------
SELECT /*+ FULL(T6) GATHER_PLAN_STATISTICS */   C1 FROM   T6 WHERE   C2=:V2
 
Plan hash value: 1930642322
 
-------------------------------------------------------------------------------------------------
| Id  | Operation         | Name | Starts | E-Rows | Cost (%CPU)| A-Rows |   A-Time   | Buffers |
-------------------------------------------------------------------------------------------------
|   0 | SELECT STATEMENT  |      |      1 |        |   358 (100)|  20000 |00:00:00.02 |    5815 |
|*  1 |  TABLE ACCESS FULL| T6   |      1 |  20556 |   358   (1)|  20000 |00:00:00.02 |    5815 |
-------------------------------------------------------------------------------------------------
 
Peeked Binds (identified by position):
--------------------------------------
   1 - (NUMBER): 0
 
Predicate Information (identified by operation id):
---------------------------------------------------
   1 - filter("C2"=:V2)
 
Note
-----
   - dynamic sampling used for this statement 

358 is greater than 209, so no full table scan without a hint.

OPT_ESTIMATE hint test:

SELECT /*+ OPT_ESTIMATE(TABLE, T6, ROWS=20000) GATHER_PLAN_STATISTICS */
  C1
FROM
  T6
WHERE
  C2=:V2;
 
SELECT * FROM TABLE(DBMS_XPLAN.DISPLAY_CURSOR(NULL,NULL,'ALLSTATS LAST +PEEKED_BINDS +COST')); 
 
SQL_ID  bud5avdhnmssf, child number 0
-------------------------------------
SELECT /*+ OPT_ESTIMATE(TABLE, T6, ROWS=20000) GATHER_PLAN_STATISTICS */   C1 FROM   T6 WHERE   C2=:V2
 
Plan hash value: 4242288932
 
----------------------------------------------------------------------------------------------------------------
| Id  | Operation                   | Name      | Starts | E-Rows | Cost (%CPU)| A-Rows |   A-Time   | Buffers |
----------------------------------------------------------------------------------------------------------------
|   0 | SELECT STATEMENT            |           |      1 |        |     1 (100)|  20000 |00:00:00.04 |    6932 |
|   1 |  TABLE ACCESS BY INDEX ROWID| T6        |      1 |  20000 |     1   (0)|  20000 |00:00:00.04 |    6932 |
|*  2 |   INDEX RANGE SCAN          | IND_T6_C2 |      1 |      1 |     1   (0)|  20000 |00:00:00.01 |    1370 |
----------------------------------------------------------------------------------------------------------------
 
Peeked Binds (identified by position):
--------------------------------------
   1 - (NUMBER): 0
 
Predicate Information (identified by operation id):
---------------------------------------------------
   2 - access("C2"=:V2)

Gather statistics on 10.2.0.5 with a histogram on column C2, then repeat the test:

EXEC DBMS_STATS.GATHER_TABLE_STATS(OWNNAME=>NULL,TABNAME=>'T6',CASCADE=>TRUE,ESTIMATE_PERCENT=>100,METHOD_OPT=>'FOR COLUMNS C2 SIZE 254',NO_INVALIDATE=>FALSE) 
 
SELECT /*+ GATHER_PLAN_STATISTICS */
  C1
FROM
  T6
WHERE
  C2=:V2;
 
SELECT * FROM TABLE(DBMS_XPLAN.DISPLAY_CURSOR(NULL,NULL,'ALLSTATS LAST +PEEKED_BINDS +COST'));
 
SQL_ID  bxnurhc1nmq2g, child number 0
-------------------------------------
SELECT /*+ GATHER_PLAN_STATISTICS */   C1 FROM   T6 WHERE   C2=:V2
 
Plan hash value: 1930642322
 
-------------------------------------------------------------------------------------------------
| Id  | Operation         | Name | Starts | E-Rows | Cost (%CPU)| A-Rows |   A-Time   | Buffers |
-------------------------------------------------------------------------------------------------
|   0 | SELECT STATEMENT  |      |      1 |        |   358 (100)|  20000 |00:00:00.02 |    5815 |
|*  1 |  TABLE ACCESS FULL| T6   |      1 |  19685 |   358   (1)|  20000 |00:00:00.02 |    5815 |
-------------------------------------------------------------------------------------------------
 
Peeked Binds (identified by position):
--------------------------------------
   1 - (NUMBER): 0
 
Predicate Information (identified by operation id):
---------------------------------------------------
   1 - filter("C2"=:V2)

The optimizer determined that a full table scan would be most efficient.

Let’s check the cost of the index access path on 10.2.0.5:

SELECT /*+ INDEX(T6) GATHER_PLAN_STATISTICS */
  C1
FROM
  T6
WHERE
  C2=:V2;
 
SELECT * FROM TABLE(DBMS_XPLAN.DISPLAY_CURSOR(NULL,NULL,'ALLSTATS LAST +PEEKED_BINDS +COST'));
 
SQL_ID  4nqwgus0ghxmc, child number 0
-------------------------------------
SELECT /*+ INDEX(T6) GATHER_PLAN_STATISTICS */   C1 FROM   T6 WHERE   C2=:V2
 
Plan hash value: 4242288932
 
----------------------------------------------------------------------------------------------------------------
| Id  | Operation                   | Name      | Starts | E-Rows | Cost (%CPU)| A-Rows |   A-Time   | Buffers |
----------------------------------------------------------------------------------------------------------------
|   0 | SELECT STATEMENT            |           |      1 |        |  1822 (100)|  20000 |00:00:00.02 |    6932 |
|   1 |  TABLE ACCESS BY INDEX ROWID| T6        |      1 |  19685 |  1822   (1)|  20000 |00:00:00.02 |    6932 |
|*  2 |   INDEX RANGE SCAN          | IND_T6_C2 |      1 |  19685 |    39   (0)|  20000 |00:00:00.01 |    1370 |
----------------------------------------------------------------------------------------------------------------
 
Peeked Binds (identified by position):
--------------------------------------
   1 - (NUMBER): 0
 
Predicate Information (identified by operation id):
---------------------------------------------------
   2 - access("C2"=:V2)

The Cost of 1822 is greater than the Cost of 358 for the full table scan access path, so that explains why the full table scan access path was selected.





Parent-Child Relationships and the Questions Left Unanswered by TKPROF, Re-Learning Something Old

30 01 2012

January 30, 2012

As we have seen in the past, TKPROF output sometimes lies, and in a recent OTN thread I was reminded of another case or two where TKPROF output may be misleading.  In the OTN thread, the original poster (OP) started the thread by asking a simple question about an execution plan that appeared in a TKPROF output.  Below is an execution plan that is similar to the one posted by the OP:

Rows (1st) Rows (avg) Rows (max)  Row Source Operation
---------- ---------- ----------  ---------------------------------------------------
         1          1          1  TABLE ACCESS BY INDEX ROWID T4 (cr=3 pr=16 pw=0 time=1274 us cost=2 size=97 card=1)
         1          1          1   INDEX RANGE SCAN IND_T4_OBJECT_ID (cr=2 pr=8 pw=0 time=620 us cost=1 size=0 card=1)(object id 102460) 

For the above execution plan, the trace file was created on Oracle Database 11.2.0.2 and processed with a 11.2.0.1 client with the patch that fixes the ODBC problem.  The original poster (OP) in the OTN thread posed a question about the cr= (consistent gets blocks) and pr= (physical read blocks) statistics.  In the above, the INDEX RANGE SCAN operation shows cr=2 pr=8, and the TABLE ACCESS BY INDEX ROWID operation shows cr=3 pr=16.  The OP questioned whether the TABLE ACCESS BY INDEX ROWID operation statistics included the INDEX RANGE SCAN operation statistics for a total of 3 consistent gets and 16 physical blocks read from disk, or if the TABLE ACCESS BY INDEX ROWID operation statistics are in addition to the INDEX RANGE SCAN operation statistics for a total of 5 consistent gets and 24 physical blocks read from disk.  As sometimes happens with Internet forums, people responding to questions sometimes provide conflicting answers; in this case, at least one person stated that each interpretation is correct.

The OP’s actual Row Source Operation execution plan showed the following:

Rows     Row Source Operation
-------  ---------------------------------------------------
      1  TABLE ACCESS BY INDEX ROWID T (cr=5 pr=11 pw=0 time=0 us cost=4 size=8092 card=1)
      1   INDEX UNIQUE SCAN T_PK (cr=3 pr=6 pw=0 time=0 us cost=2 size=0 card=1)(object id 83084) 

In an attempt to provide the OP with answers to all of his unanswered questions to that point in the thread, I provided the following response:

In the above, the “TABLE ACCESS BY INDEX ROWID” operation is the parent operation and the “INDEX UNIQUE SCAN” is the child operation. The child’s statistics are rolled into the parent’s statistics. In Oracle Database 11.1 and above, the default behavior is to output the STAT lines (that is the Row Source Operation execution plan) after the first execution of the SQL statement. For the first execution of the SQL statement, there were 11 physical block reads, 6 from the index and 5 from the table. There were 5 consistent gets, 3 from the index and 2 from the table. The estimated cost for the index access is 2, and the estimated cost for just the table access is 2.
 
I see that you also used the EXPLAIN option of TKPROF – that can lead to misleading execution plans being written to the TKPROF output, especially when bind variables are involved. The 1 parse call should be expected – it would be bad if there were 72,181 parses, because that would mean that there would be 1 parse per execution – a sign that the cursor was not held open either by the application or by the session cursor cache. Simply enabling a 10046 trace in a session changes the environment for the session, which will typically require a hard parse of previously parsed SQL statements when those SQL statements are re-executed. Note that “recursive depth: 1” appears in the output, which suggests that this SQL statement is found in a PL/SQL block.
 
db file scattered read waits indicate that more than 1 block is read from disk at a time. You can refer to the raw 10046 trace file to determine how many blocks are read on average in the db file scattered read waits.

OK, so if you believe the above quote, the child statistics are rolled into the parent’s statistics, the EXPLAIN option of TKPROF may write incorrect execution plans to the output file especially when bind variables are used, and the original trace file included SQL statements marked with dep=0 or dep=1.  In the thread there was disagreement on the first point, so let’s throw together a very short test case to determine if that point is correct.

First, we will create a simple table with a primary key index, insert  200 rows into the table, and collect statistics on that table:

CREATE TABLE T3 (
  C1 NUMBER,
  C2 VARCHAR2(300),
  PRIMARY KEY(C1));

INSERT INTO
  T3
SELECT
  ROWNUM C1,
  RPAD('A',300,'A')
FROM
  DUAL
CONNECT BY
  LEVEL<=200;

COMMIT;

EXEC DBMS_STATS.GATHER_TABLE_STATS(OWNNAME=>USER,TABNAME=>'T3',CASCADE=>TRUE,NO_INVALIDATE=>FALSE) 

Next, I want to make certain that the two SQL statements that will be used in the test script will already exist in the library cache (so that we can test whether or not enabling a 10046 trace will cause a hard parse when the SQL statements are re-executed).  I also will set the fetch array size to 1000 to minimize the number of round trips between the server and client (the default fetch array size is 15 for SQL*Plus, and that value would make the generated trace file a bit more difficult to read due to the extra FETCH and SQL*Net wait events).  The second SQL statement, intended to make certain that the STAT lines for the first SQL statement will be written to the 10046 trace file, is only necessary prior to Oracle Database 11.1.0.6:

SELECT /*+ INDEX(T3) */
  *
FROM
  T3
WHERE
  C1<=200;

SELECT
  SYSDATE
FROM
  DUAL;

SET ARRAYSIZE 1000

Now for the final section of the test case script: flush the buffer cache, enable a 10046 trace, and execute the two SQL statements:

ALTER SYSTEM FLUSH BUFFER_CACHE;
ALTER SYSTEM FLUSH BUFFER_CACHE;

ALTER SESSION SET EVENTS '10046 TRACE NAME CONTEXT FOREVER, LEVEL 8';
ALTER SESSION SET TRACEFILE_IDENTIFIER = '10046TESTING';

SELECT /*+ INDEX(T3) */
  *
FROM
  T3
WHERE
  C1<=200;

SELECT
  SYSDATE
FROM
  DUAL;

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

Let’s start by taking a look at the raw 10046 trace file, slightly marked up:

=====================
PARSING IN CURSOR #371254768 len=53 dep=0 uid=62 oct=3 lid=62 tim=184435767875 hv=1334288504 ad='7ffb8c1be40' sqlid='a75xc757sg83s'
SELECT /*+ INDEX(T3) */
  *
FROM
  T3
WHERE
  C1<=200
END OF STMT
PARSE #371254768:c=0,e=699,p=0,cr=0,cu=0,mis=1,r=0,dep=0,og=1,plh=216260220,tim=184435767874                                <--- hard parse
EXEC #371254768:c=0,e=25,p=0,cr=0,cu=0,mis=0,r=0,dep=0,og=1,plh=216260220,tim=184435767947
WAIT #371254768: nam='SQL*Net message to client' ela= 0 driver id=1413697536 #bytes=1 p3=0 obj#=0 tim=184435767976
WAIT #371254768: nam='db file scattered read' ela= 320 file#=4 block#=4145624 blocks=8 obj#=73036 tim=184435768358          <--- 8 for index
WAIT #371254768: nam='db file scattered read' ela= 276 file#=4 block#=4145616 blocks=8 obj#=73035 tim=184435768704          <--- 8 for table
FETCH #371254768:c=0,e=764,p=16,cr=2,cu=0,mis=0,r=1,dep=0,og=1,plh=216260220,tim=184435768757
WAIT #371254768: nam='SQL*Net message from client' ela= 110 driver id=1413697536 #bytes=1 p3=0 obj#=73035 tim=184435768890
WAIT #371254768: nam='SQL*Net message to client' ela= 0 driver id=1413697536 #bytes=1 p3=0 obj#=73035 tim=184435768916
WAIT #371254768: nam='db file scattered read' ela= 283 file#=4 block#=4145632 blocks=8 obj#=73035 tim=184435769273          <--- 8 for table
FETCH #371254768:c=0,e=443,p=8,cr=10,cu=0,mis=0,r=199,dep=0,og=1,plh=216260220,tim=184435769349
STAT #371254768 id=1 cnt=200 pid=0 pos=1 obj=73035 op='TABLE ACCESS BY INDEX ROWID T3 (cr=12 pr=24 pw=0 time=762 us cost=10 size=60800 card=200)'
STAT #371254768 id=2 cnt=200 pid=1 pos=1 obj=73036 op='INDEX RANGE SCAN SYS_C008672 (cr=2 pr=8 pw=0 time=1012 us cost=1 size=0 card=200)'

*** 2012-01-25 09:17:32.639
WAIT #371254768: nam='SQL*Net message from client' ela= 1142603 driver id=1413697536 #bytes=1 p3=0 obj#=73035 tim=184436912005
CLOSE #371254768:c=0,e=19,dep=0,type=0,tim=184436912120
===================== 

The above shows a hard parse, 8 blocks read by multi-block read for the index, and 16 blocks read by multi-block read for the table.  If we process the trace file with TKPROF, a portion of the TKPROF output should look like this:

********************************************************************************
SELECT /*+ INDEX(T3) */
  *
FROM
  T3
WHERE
  C1<=200

call     count       cpu    elapsed       disk      query    current        rows
------- ------  -------- ---------- ---------- ---------- ----------  ----------
Parse        1      0.00       0.00          0          0          0           0
Execute      2      0.00       0.00          0          0          0           0
Fetch        2      0.00       0.00         24         12          0         200
------- ------  -------- ---------- ---------- ---------- ----------  ----------
total        5      0.00       0.00         24         12          0         200

Misses in library cache during parse: 1
Optimizer mode: ALL_ROWS
Parsing user id: 62 
Number of plan statistics captured: 1

Rows (1st) Rows (avg) Rows (max)  Row Source Operation
---------- ---------- ----------  ---------------------------------------------------
       200        200        200  TABLE ACCESS BY INDEX ROWID T3 (cr=12 pr=24 pw=0 time=762 us cost=10 size=60800 card=200)
       200        200        200   INDEX RANGE SCAN SYS_C008672 (cr=2 pr=8 pw=0 time=1012 us cost=1 size=0 card=200)(object id 73036)

Elapsed times include waiting on following events:
  Event waited on                             Times   Max. Wait  Total Waited
  ----------------------------------------   Waited  ----------  ------------
  SQL*Net message to client                       3        0.00          0.00
  SQL*Net message from client                     3        1.14          1.14
  db file scattered read                          3        0.00          0.00
******************************************************************************** 

By examining the raw trace file, we are able to confirm that the pr=24 statistic in the first row of the Row Source Execution plan includes the 16 blocks for the table and the 8 blocks from the index, as identified in the raw 10046 trace file.

The OP later asked a handful of questions, including whether or not he should add the statistics found in the OVERALL TOTALS FOR ALL NON-RECURSIVE STATEMENTS section of the TKPROF output to the statistics found in the OVERALL TOTALS FOR ALL RECURSIVE STATEMENTS section.  My first thought was to modify my original test case script shown above like this, so that there is a logging trigger on the T3 table that records changes made to the T3 table in the T4 table:

DROP TABLE T3 PURGE;
DROP TABLE T4 PURGE;

CREATE TABLE T3 (
  C1 NUMBER,
  C2 VARCHAR2(300),
  PRIMARY KEY(C1));

CREATE TABLE T4(
  NEW_C1 NUMBER,
  OLD_C2 VARCHAR2(300),
  NEW_C2 VARCHAR2(300),
  LOG_MODIFIED_USER_ID VARCHAR2(30) DEFAULT USER,
  LOG_MODIFIED_DATE DATE DEFAULT SYSDATE,
  LOG_TRANSACTION_TYPE VARCHAR2(1))
  PCTFREE 0
  PCTUSED 99;

CREATE OR REPLACE TRIGGER HPM_T3 AFTER
INSERT OR DELETE OR UPDATE OF C1, C2 ON T3
REFERENCING OLD AS OLDDATA NEW AS NEWDATA FOR EACH ROW
BEGIN
  IF UPDATING THEN
    IF (NVL(:OLDDATA.C1,0.0000019) <> NVL(:NEWDATA.C1,0.0000019)) OR (NVL(:OLDDATA.C2,'3!3D$FF') <> NVL(:NEWDATA.C2,'3!3D$FF'))  THEN
     INSERT INTO T4 (
      NEW_C1,
      OLD_C2,
      NEW_C2,
      LOG_TRANSACTION_TYPE)
     VALUES (
      :NEWDATA.C1,
      :OLDDATA.C2,
      :NEWDATA.C2,
      'U');
    END IF;
  END IF;

  IF DELETING THEN
    INSERT INTO T4 (
      NEW_C1,
      OLD_C2,
      LOG_TRANSACTION_TYPE)
    VALUES (
      :OLDDATA.C1,
      :OLDDATA.C2,
      'D');
  END IF;

  IF INSERTING THEN
    INSERT INTO T4 (
      NEW_C1,
      NEW_C2,
      LOG_TRANSACTION_TYPE)
    VALUES (
      :NEWDATA.C1,
      :NEWDATA.C2,
      'I');
  END IF;
END;
/

INSERT INTO
  T3
SELECT
  ROWNUM C1,
  RPAD('A',300,'A')
FROM
  DUAL
CONNECT BY
  LEVEL<=200;

COMMIT;

EXEC DBMS_STATS.GATHER_TABLE_STATS(OWNNAME=>USER,TABNAME=>'T3',CASCADE=>TRUE,NO_INVALIDATE=>FALSE)

SELECT /*+ INDEX(T3) */
  *
FROM
  T3
WHERE
  C1<=200;

SELECT
  SYSDATE
FROM
  DUAL;

SET ARRAYSIZE 1000 

Then I would add a new section to the second half of the original test script to update 50 rows of table T3:

ALTER SYSTEM FLUSH BUFFER_CACHE;
ALTER SYSTEM FLUSH BUFFER_CACHE;

ALTER SESSION SET EVENTS '10046 TRACE NAME CONTEXT FOREVER, LEVEL 8';
ALTER SESSION SET TRACEFILE_IDENTIFIER = '10046TESTING2';

SELECT /*+ INDEX(T3) */
  *
FROM
  T3
WHERE
  C1<=200;

SELECT
  SYSDATE
FROM
  DUAL;

ALTER SESSION SET TRACEFILE_IDENTIFIER = '10046TESTING3';

UPDATE
  T3
SET
  C1=C1+1000,
  C2='UPDATED BY 1000'
WHERE
  C1<=50;

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

-

I decided to abandon that approach, and instead try to reproduce the test script that the OP was attempting to use.  My best guess is that the OP’s test script looks similar to the following:

CREATE TABLE T4 AS
SELECT
  *
FROM
  ALL_OBJECTS;

ALTER TABLE T4 ADD (
  PADDING1 VARCHAR2(4000),
  PADDING2 VARCHAR2(4000));

CREATE INDEX IND_T4_OBJECT_ID ON T4(OBJECT_ID);

EXEC DBMS_STATS.GATHER_TABLE_STATS(OWNNAME=>USER,TABNAME=>'T4',CASCADE=>TRUE,NO_INVALIDATE=>FALSE)

ALTER SYSTEM FLUSH BUFFER_CACHE;
ALTER SYSTEM FLUSH BUFFER_CACHE;

ALTER SESSION SET TRACEFILE_IDENTIFIER = '10046_FIND_ME';
EXEC DBMS_MONITOR.SESSION_TRACE_ENABLE ( waits=>true );

DECLARE
        type array is table of t4%ROWTYPE index by binary_integer;
        l_data array;
        l_rec t4%rowtype;
BEGIN
        SELECT
                a.*
                ,RPAD('*',4000,'*') AS PADDING1
                ,RPAD('*',4000,'*') AS PADDING2
        BULK COLLECT INTO
        l_data
        FROM ALL_OBJECTS a;

        FOR rs IN 1 .. l_data.count
        LOOP
                BEGIN
                        SELECT * INTO l_rec FROM t4 WHERE object_id = l_data(rs).object_id;
                EXCEPTION
                  WHEN NO_DATA_FOUND THEN NULL;
                END;
        END LOOP;
END;
/

EXEC DBMS_MONITOR.SESSION_TRACE_DISABLE; 

In the script I set the NO_INVALIDATE parameter of the DBMS_STATS.GATHER_TABLE_STATS procedure to FALSE so that the session cursor cache would be flushed of all references to the T4 table, which then leads to the SQL statements appearing in the trace file on repeated executions if you need to execute the script a couple of times from that line of the test script to the end.  I also moved the DBMS_MONITOR.SESSION_TRACE_ENABLE call outside of the anonymous PL/SQL block so that PL/SQL block would be included in the trace file.

After executing the test script, I found the following lines near the start of the generated 10046 trace file:

PARSING IN CURSOR #481810328 len=63 dep=0 uid=64 oct=47 lid=64 tim=2302523409025 hv=2690357649 ad='3edbc1610' sqlid='dsvxr0ah5r6cj'
BEGIN DBMS_MONITOR.SESSION_TRACE_ENABLE ( waits=>true ); END;
END OF STMT 

In the above, note the tim=2302523409025 value.  Near the end of the 10046 trace file I found the following lines:

PARSING IN CURSOR #481810424 len=48 dep=0 uid=64 oct=47 lid=64 tim=2302533226450 hv=3127860446 ad='3eb311428' sqlid='80u1a4kx6yr6y'
BEGIN DBMS_MONITOR.SESSION_TRACE_DISABLE; END;
END OF STMT

In the above, note the tim=2302533226450 value.

We are able to determine the elapsed time between these two calls with simple mathematics: (2302533226450 – 2302523409025) / 1000000 = 9.817425 seconds elapsed time in the trace file between the start of the 10046 trace and the call to end the 10046 trace.

Now, let’s see if we are able to find another case where TKPROF lies.  We are able to find a hint of the problems in the book “Optimizing Oracle Performance” (see page xv and page 90).  Here is the TKPROF summary for my execution of the test script (generated with this command: tkprof or1122p_ora_19180_10046_FIND_ME.trc or1122p_ora_19180_10046_FIND_ME.txt):

OVERALL TOTALS FOR ALL NON-RECURSIVE STATEMENTS

call     count       cpu    elapsed       disk      query    current        rows
------- ------  -------- ---------- ---------- ---------- ----------  ----------
Parse        2      0.00       0.00          0          0          0           0
Execute      3      5.36       5.34          0          0          0           3
Fetch        0      0.00       0.00          0          0          0           0
------- ------  -------- ---------- ---------- ---------- ----------  ----------
total        5      5.36       5.35          0          0          0           3

Misses in library cache during parse: 2
Misses in library cache during execute: 1

Elapsed times include waiting on following events:
  Event waited on                             Times   Max. Wait  Total Waited
  ----------------------------------------   Waited  ----------  ------------
  SQL*Net message to client                       2        0.00          0.00
  SQL*Net message from client                     2        0.10          0.10

OVERALL TOTALS FOR ALL RECURSIVE STATEMENTS

call     count       cpu    elapsed       disk      query    current        rows
------- ------  -------- ---------- ---------- ---------- ----------  ----------
Parse        1      0.00       0.00          0          0          0           0
Execute  72720      0.99       1.08          0          0          0           0
Fetch    72720      1.01       1.02       1240     218319          0       72719
------- ------  -------- ---------- ---------- ---------- ----------  ----------
total   145441      2.01       2.10       1240     218319          0       72719

Misses in library cache during parse: 1

Elapsed times include waiting on following events:
  Event waited on                             Times   Max. Wait  Total Waited
  ----------------------------------------   Waited  ----------  ------------
  db file sequential read                      1047        0.00          0.25
  db file scattered read                        182        0.00          0.10
  asynch descriptor resize                      291        0.00          0.00

    4  user  SQL statements in session.
    0  internal SQL statements in session.
    4  SQL statements in session.
********************************************************************************
Trace file: or1122p_ora_19180_10046_FIND_ME.trc
Trace file compatibility: 11.1.0.7
Sort options: default

       1  session in tracefile.
       4  user  SQL statements in trace file.
       0  internal SQL statements in trace file.
       4  SQL statements in trace file.
       4  unique SQL statements in trace file.
  220086  lines in trace file.
       9  elapsed seconds in trace file. 

Does the above output indicate that my anonymous PL/SQL block completed in 5.35 seconds, and that the recursive call accounted for 2.1 seconds of that time?  Or, should we add the non-recursive and recursive elapsed times together to determine the total time?  Should we add the total blocks read from disk displayed in the non-recursive portion (0) to the total blocks read from disk displayed in the recursive portion (1240) to determine the total number of blocks read from disk during the execution?  The above statistics indicate that there were 1047 waits for the db file sequential read wait event and 182 waits for the db file scattered read wait event in the OVERALL TOTALS FOR ALL RECURSIVE STATEMENTS section of the TKPROF output.  We know that each db file sequential read wait event represents reading one block from disk, and that each db file scattered read wait event represents reading at least 2 blocks from disk.  Let’s try some simple mathematics: 1047 + (2 * 182) = 1411 – the wait event statistics for the OVERALL TOTALS FOR ALL RECURSIVE STATEMENTS section of the TKPROF output indicate that at least 1,411 blocks should have been read from disk, while the TKPROF output only shows 1,240 blocks.  Is TKPROF lying?

Let’s take another look at the raw 10046 trace file.  Very close to the end of the trace file I found the following line:

EXEC #481810328:c=9266459,e=9631079,p=3231,cr=267427,cu=0,mis=0,r=1,dep=0,og=1,plh=0,tim=2302533148184 

The above indicates that cursor number 481810328 consumed 9.266459 seconds of CPU time, 9.631079 seconds of elapsed time, read 3,231 blocks from disk, and performed 267,427 consistent gets when that cursor was executed – yet that is not in agreement with the above TKPROF output (the numbers are greater than even the non-recursive plus recursive statistics would suggest).  If we search upward in the trace file, we are able to find the code that is associated with cursor number 481810328:

PARSING IN CURSOR #481810328 len=610 dep=0 uid=64 oct=47 lid=64 tim=2302523516952 hv=468044383 ad='3edbc2e48' sqlid='8zytk5ndybkkz'
DECLARE
        type array is table of t4%ROWTYPE index by binary_integer;
        l_data array;
        l_rec t4%rowtype;
BEGIN
        SELECT
                a.*
                ,RPAD('*',4000,'*') AS PADDING1
                ,RPAD('*',4000,'*') AS PADDING2
        BULK COLLECT INTO
        l_data
        FROM ALL_OBJECTS a;
        FOR rs IN 1 .. l_data.count
        LOOP
                BEGIN
                        SELECT * INTO l_rec FROM t4 WHERE object_id = l_data(rs).object_id;
                EXCEPTION
                  WHEN NO_DATA_FOUND THEN NULL;
                END;
        END LOOP;
END;
END OF STMT 

That is our anonymous PL/SQL block, which would fall into the non-recursive totals that shows a total of 5.36 seconds of CPU time, 5.35 seconds of elapsed time, 0 blocks read from disk, and 0 consistent gets.

So, did TKPROF answer more questions than it generated?

I was curious, so I processed the trace file using my Hyper-Extended Oracle Performance Monitor program (AKA: Toy Project for Performance Monitoring).  This is the what was written to one of the output files:

Total for Trace File:
|PARSEs       3|CPU S    0.000000|CLOCK S    0.006473|ROWs        0|PHY RD BLKs         0|CON RD BLKs (Mem)         0|CUR RD BLKs (Mem)         0|SHARED POOL MISs      3|
|EXECs    72723|CPU S   10.264864|CLOCK S   10.715043|ROWs        3|PHY RD BLKs      3231|CON RD BLKs (Mem)    267427|CUR RD BLKs (Mem)         0|SHARED POOL MISs      1|
|FETCHs   72720|CPU S    1.014008|CLOCK S    1.021754|ROWs    72719|PHY RD BLKs      1240|CON RD BLKs (Mem)    218319|CUR RD BLKs (Mem)         0|SHARED POOL MISs      0|

Wait Event Summary:
SQL*Net message to client           0.000010  On Client/Network   Min Wait:     0.000003  Avg Wait:     0.000005  Max Wait:     0.000007  Waits:      2
SQL*Net message from client         0.107469  On Client/Network   Min Wait:     0.006123  Avg Wait:     0.053735  Max Wait:     0.101346  Waits:      2
db file sequential read             0.254673  On DB Server        Min Wait:     0.000023  Avg Wait:     0.000243  Max Wait:     0.001280  Waits:   1047
db file scattered read              0.100087  On DB Server        Min Wait:     0.000088  Avg Wait:     0.000550  Max Wait:     0.004496  Waits:    182
asynch descriptor resize            0.000359  On DB Server        Min Wait:     0.000000  Avg Wait:     0.000001  Max Wait:     0.000004  Waits:    291

Total for Similar SQL Statements in Each Group:
----------------------------------------------------------------------------------
Similar SQL Statements in Group: 1 
First Reference: Cursor 621   Ver 1   Parse at 0.000000 SQL_ID='dsvxr0ah5r6cj'
|PARSEs       0|CPU S    0.000000|CLOCK S    0.000000|ROWs        0|PHY RD BLKs         0|CON RD BLKs (Mem)         0|CUR RD BLKs (Mem)         0|SHARED POOL MISs      0|
|EXECs        1|CPU S    0.000000|CLOCK S    0.000941|ROWs        1|PHY RD BLKs         0|CON RD BLKs (Mem)         0|CUR RD BLKs (Mem)         0|SHARED POOL MISs      1|
|FETCHs       0|CPU S    0.000000|CLOCK S    0.000000|ROWs        0|PHY RD BLKs         0|CON RD BLKs (Mem)         0|CUR RD BLKs (Mem)         0|SHARED POOL MISs      0|
  CPU S 0.00%  CLOCK S 0.01%
  *    0.101349 seconds of time related to client/network events

----------------------------------------------------------------------------------
Similar SQL Statements in Group: 1 
First Reference: Cursor 621   Ver 2   Parse at 0.107927 SQL_ID='8zytk5ndybkkz'
|PARSEs       1|CPU S    0.000000|CLOCK S    0.004720|ROWs        0|PHY RD BLKs         0|CON RD BLKs (Mem)         0|CUR RD BLKs (Mem)         0|SHARED POOL MISs      1|
|EXECs        1|CPU S    9.266459|CLOCK S    9.631079|ROWs        1|PHY RD BLKs      3231|CON RD BLKs (Mem)    267427|CUR RD BLKs (Mem)         0|SHARED POOL MISs      0|
|FETCHs       0|CPU S    0.000000|CLOCK S    0.000000|ROWs        0|PHY RD BLKs         0|CON RD BLKs (Mem)         0|CUR RD BLKs (Mem)         0|SHARED POOL MISs      0|
  CPU S 82.16%  CLOCK S 82.05%
  *    0.006130 seconds of time related to client/network events
|    ++++++++++++++++||    ++++++++++++++++|

----------------------------------------------------------------------------------
Similar SQL Statements in Group: 1 
First Reference: Cursor 648   Ver 1   Parse at 2.291806 SQL_ID='5k52u3cqwkkmw'
|PARSEs       1|CPU S    0.000000|CLOCK S    0.000441|ROWs        0|PHY RD BLKs         0|CON RD BLKs (Mem)         0|CUR RD BLKs (Mem)         0|SHARED POOL MISs      1|
|EXECs    72720|CPU S    0.998405|CLOCK S    1.081928|ROWs        0|PHY RD BLKs         0|CON RD BLKs (Mem)         0|CUR RD BLKs (Mem)         0|SHARED POOL MISs      0|
|FETCHs   72720|CPU S    1.014008|CLOCK S    1.021754|ROWs    72719|PHY RD BLKs      1240|CON RD BLKs (Mem)    218319|CUR RD BLKs (Mem)         0|SHARED POOL MISs      0|
  CPU S 17.84%  CLOCK S 17.92%
  *    0.075437 seconds of time related data file I/O
|                ++++||                ++++|

----------------------------------------------------------------------------------
Similar SQL Statements in Group: 1 
First Reference: Cursor 717   Ver 1   Parse at 9.817425 SQL_ID='80u1a4kx6yr6y'
|PARSEs       1|CPU S    0.000000|CLOCK S    0.001312|ROWs        0|PHY RD BLKs         0|CON RD BLKs (Mem)         0|CUR RD BLKs (Mem)         0|SHARED POOL MISs      1|
|EXECs        1|CPU S    0.000000|CLOCK S    0.001095|ROWs        1|PHY RD BLKs         0|CON RD BLKs (Mem)         0|CUR RD BLKs (Mem)         0|SHARED POOL MISs      0|
|FETCHs       0|CPU S    0.000000|CLOCK S    0.000000|ROWs        0|PHY RD BLKs         0|CON RD BLKs (Mem)         0|CUR RD BLKs (Mem)         0|SHARED POOL MISs      0|
  CPU S 0.00%  CLOCK S 0.02%

End of Summary, Detail Follows
--------------------------------------------------------------------------------------------------
----------------------------------------------------------------------------------
Similar SQL Statements in Group: 1
|PARSEs       0|CPU S    0.000000|CLOCK S    0.000000|ROWs        0|PHY RD BLKs         0|CON RD BLKs (Mem)         0|CUR RD BLKs (Mem)         0|SHARED POOL MISs      0|
|EXECs        1|CPU S    0.000000|CLOCK S    0.000941|ROWs        1|PHY RD BLKs         0|CON RD BLKs (Mem)         0|CUR RD BLKs (Mem)         0|SHARED POOL MISs      1|
|FETCHs       0|CPU S    0.000000|CLOCK S    0.000000|ROWs        0|PHY RD BLKs         0|CON RD BLKs (Mem)         0|CUR RD BLKs (Mem)         0|SHARED POOL MISs      0|

Statement Depth 0 (Application Code)
Cursor 621   Ver 1   Parse at 0.000000 SQL_ID='dsvxr0ah5r6cj'  Similar Cnt 1
|PARSEs       0|CPU S    0.000000|CLOCK S    0.000000|ROWs        0|PHY RD BLKs         0|CON RD BLKs (Mem)         0|CUR RD BLKs (Mem)         0|SHARED POOL MISs      0|
|EXECs        1|CPU S    0.000000|CLOCK S    0.000941|ROWs        1|PHY RD BLKs         0|CON RD BLKs (Mem)         0|CUR RD BLKs (Mem)         0|SHARED POOL MISs      1|
|FETCHs       0|CPU S    0.000000|CLOCK S    0.000000|ROWs        0|PHY RD BLKs         0|CON RD BLKs (Mem)         0|CUR RD BLKs (Mem)         0|SHARED POOL MISs      0|
  CPU S 0.00%  CLOCK S 0.01%

BEGIN DBMS_MONITOR.SESSION_TRACE_ENABLE ( waits=>true ); END;
------------
----------------------------------------------------------------------------------
Similar SQL Statements in Group: 1
|PARSEs       1|CPU S    0.000000|CLOCK S    0.004720|ROWs        0|PHY RD BLKs         0|CON RD BLKs (Mem)         0|CUR RD BLKs (Mem)         0|SHARED POOL MISs      1|
|EXECs        1|CPU S    9.266459|CLOCK S    9.631079|ROWs        1|PHY RD BLKs      3231|CON RD BLKs (Mem)    267427|CUR RD BLKs (Mem)         0|SHARED POOL MISs      0|
|FETCHs       0|CPU S    0.000000|CLOCK S    0.000000|ROWs        0|PHY RD BLKs         0|CON RD BLKs (Mem)         0|CUR RD BLKs (Mem)         0|SHARED POOL MISs      0|

Statement Depth 0 (Application Code)
Cursor 621   Ver 2   Parse at 0.107927 SQL_ID='8zytk5ndybkkz'  (TD Prev 0.107927)  Similar Cnt 1
|PARSEs       1|CPU S    0.000000|CLOCK S    0.004720|ROWs        0|PHY RD BLKs         0|CON RD BLKs (Mem)         0|CUR RD BLKs (Mem)         0|SHARED POOL MISs      1|
|EXECs        1|CPU S    9.266459|CLOCK S    9.631079|ROWs        1|PHY RD BLKs      3231|CON RD BLKs (Mem)    267427|CUR RD BLKs (Mem)         0|SHARED POOL MISs      0|
|FETCHs       0|CPU S    0.000000|CLOCK S    0.000000|ROWs        0|PHY RD BLKs         0|CON RD BLKs (Mem)         0|CUR RD BLKs (Mem)         0|SHARED POOL MISs      0|
  CPU S 82.16%  CLOCK S 82.05%
|    ++++++++++++++++||    ++++++++++++++++|
DECLARE
        type array is table of t4%ROWTYPE index by binary_integer;
        l_data array;
        l_rec t4%rowtype;
BEGIN
        SELECT
                a.*
                ,RPAD('*',4000,'*') AS PADDING1
                ,RPAD('*',4000,'*') AS PADDING2
        BULK COLLECT INTO
        l_data
        FROM ALL_OBJECTS a;
        FOR rs IN 1 .. l_data.count
        LOOP
                BEGIN
                        SELECT * INTO l_rec FROM t4 WHERE object_id = l_data(rs).object_id;
                EXCEPTION
                  WHEN NO_DATA_FOUND THEN NULL;
                END;
        END LOOP;
END;
------------
----------------------------------------------------------------------------------
Similar SQL Statements in Group: 1
|PARSEs       1|CPU S    0.000000|CLOCK S    0.000441|ROWs        0|PHY RD BLKs         0|CON RD BLKs (Mem)         0|CUR RD BLKs (Mem)         0|SHARED POOL MISs      1|
|EXECs    72720|CPU S    0.998405|CLOCK S    1.081928|ROWs        0|PHY RD BLKs         0|CON RD BLKs (Mem)         0|CUR RD BLKs (Mem)         0|SHARED POOL MISs      0|
|FETCHs   72720|CPU S    1.014008|CLOCK S    1.021754|ROWs    72719|PHY RD BLKs      1240|CON RD BLKs (Mem)    218319|CUR RD BLKs (Mem)         0|SHARED POOL MISs      0|

Statement Depth 1 (Trigger Code)
Cursor 648   Ver 1   Parse at 2.291806 SQL_ID='5k52u3cqwkkmw'  (TD Prev 2.183879)  Similar Cnt 1
|PARSEs       1|CPU S    0.000000|CLOCK S    0.000441|ROWs        0|PHY RD BLKs         0|CON RD BLKs (Mem)         0|CUR RD BLKs (Mem)         0|SHARED POOL MISs      1|
|EXECs    72720|CPU S    0.998405|CLOCK S    1.081928|ROWs        0|PHY RD BLKs         0|CON RD BLKs (Mem)         0|CUR RD BLKs (Mem)         0|SHARED POOL MISs      0|
|FETCHs   72720|CPU S    1.014008|CLOCK S    1.021754|ROWs    72719|PHY RD BLKs      1240|CON RD BLKs (Mem)    218319|CUR RD BLKs (Mem)         0|SHARED POOL MISs      0|
  CPU S 17.84%  CLOCK S 17.92%
|                ++++||                ++++|
SELECT * FROM T4 WHERE OBJECT_ID = :B1

       (Rows 1)   TABLE ACCESS BY INDEX ROWID T4 (cr=3 pr=16 pw=0 time=1274 us cost=2 size=97 card=1)
       (Rows 1)    INDEX RANGE SCAN IND_T4_OBJECT_ID (cr=2 pr=8 pw=0 time=620 us cost=1 size=0 card=1)

------------
----------------------------------------------------------------------------------
Similar SQL Statements in Group: 1
|PARSEs       1|CPU S    0.000000|CLOCK S    0.001312|ROWs        0|PHY RD BLKs         0|CON RD BLKs (Mem)         0|CUR RD BLKs (Mem)         0|SHARED POOL MISs      1|
|EXECs        1|CPU S    0.000000|CLOCK S    0.001095|ROWs        1|PHY RD BLKs         0|CON RD BLKs (Mem)         0|CUR RD BLKs (Mem)         0|SHARED POOL MISs      0|
|FETCHs       0|CPU S    0.000000|CLOCK S    0.000000|ROWs        0|PHY RD BLKs         0|CON RD BLKs (Mem)         0|CUR RD BLKs (Mem)         0|SHARED POOL MISs      0|

Statement Depth 0 (Application Code)
Cursor 717   Ver 1   Parse at 9.817425 SQL_ID='80u1a4kx6yr6y'  (TD Prev 7.525619)  Similar Cnt 1
|PARSEs       1|CPU S    0.000000|CLOCK S    0.001312|ROWs        0|PHY RD BLKs         0|CON RD BLKs (Mem)         0|CUR RD BLKs (Mem)         0|SHARED POOL MISs      1|
|EXECs        1|CPU S    0.000000|CLOCK S    0.001095|ROWs        1|PHY RD BLKs         0|CON RD BLKs (Mem)         0|CUR RD BLKs (Mem)         0|SHARED POOL MISs      0|
|FETCHs       0|CPU S    0.000000|CLOCK S    0.000000|ROWs        0|PHY RD BLKs         0|CON RD BLKs (Mem)         0|CUR RD BLKs (Mem)         0|SHARED POOL MISs      0|
  CPU S 0.00%  CLOCK S 0.02%

BEGIN DBMS_MONITOR.SESSION_TRACE_DISABLE; END;

So, what does the above indicate when compared with the TKPROF output?

Let’s look at the summary again from TKPROF:

OVERALL TOTALS FOR ALL NON-RECURSIVE STATEMENTS
call     count       cpu    elapsed       disk      query    current        rows
------- ------  -------- ---------- ---------- ---------- ----------  ----------
Parse        2      0.00       0.00          0          0          0           0
Execute      3      5.36       5.34          0          0          0           3
Fetch        0      0.00       0.00          0          0          0           0
------- ------  -------- ---------- ---------- ---------- ----------  ----------
total        5      5.36       5.35          0          0          0           3

OVERALL TOTALS FOR ALL RECURSIVE STATEMENTS
call     count       cpu    elapsed       disk      query    current        rows
------- ------  -------- ---------- ---------- ---------- ----------  ----------
Parse        1      0.00       0.00          0          0          0           0
Execute  72720      0.99       1.08          0          0          0           0
Fetch    72720      1.01       1.02       1240     218319          0       72719
------- ------  -------- ---------- ---------- ---------- ----------  ----------
total   145441      2.01       2.10       1240     218319          0       72719 

And the summary from my program:

Total for Trace File:
|PARSEs       3|CPU S    0.000000|CLOCK S    0.006473|PHY RD BLKs         0|CON RD BLKs (Mem)         0|
|EXECs    72723|CPU S   10.264864|CLOCK S   10.715043|PHY RD BLKs      3231|CON RD BLKs (Mem)    267427|
|FETCHs   72720|CPU S    1.014008|CLOCK S    1.021754|PHY RD BLKs      1240|CON RD BLKs (Mem)    218319| 

My program double counted the CPU time and elapsed time (and ? … see below) from the recursive calls.  TKPROF only reported the consistent gets (218,319) and physical blocks read from disk (1,240) from the recursive FETCH lines in the trace file, but discarded those statistics from the non-recursive EXEC lines in the trace file.  That possibly explans why the number of db file single block read waits plus two times the number of db file scattered read waits exceeds the number reported in the disk column of the TKPROF output:

1047 + (2 * 182) = 1411 > 1200

The partially interesting item is that the db file scattered read waits, on average, read 12.00 blocks at a time, and the many of the db file scattered read waits are attributed to a mysterious cursor #482246872.  Another output of my program is an Excel spreadsheet that lists all wait events found in the trace file.  I added the following formula in cell F2 and copied that formula down to the last wait event line:

=IF(C2="db file sequential read",VALUE(MID(D2,FIND("blocks=",D2)+7,FIND(" ",D2,FIND("blocks",D2)+1) - (FIND("blocks=",D2)+7))),"")

I added the following formula in cell G2 and copied that formula down to the last wait event line:

=IF(C2="db file scattered read",VALUE(MID(D2,FIND("blocks=",D2)+7,FIND(" ",D2,FIND("blocks",D2)+1) - (FIND("blocks=",D2)+7))),"")

With those two formulas in place, I was able to determine the actual number of physical block reads, and whether or not the blocks were read one at a time, or more than one block at a time.  The resulting Excel spreadsheet looks like this:

 

So, the above screen captures show that there were 9.8159 seconds in the trace file between the first and last tim= values.  The last of the above screen captures shows there were in total 1,047 single block reads (db file sequential read waits) and 182 multi-block reads (db file scattered read waits), with a total of 2,184 blocks read by multi-block read for an average of 12 blocks per multi-block read.

Let’s take another look at the other output file from my program:

Total for Trace File:
|PARSEs       3|CPU S    0.000000|CLOCK S    0.006473|PHY RD BLKs         0|CON RD BLKs (Mem)         0|
|EXECs    72723|CPU S   10.264864|CLOCK S   10.715043|PHY RD BLKs      3231|CON RD BLKs (Mem)    267427|
|FETCHs   72720|CPU S    1.014008|CLOCK S    1.021754|PHY RD BLKs      1240|CON RD BLKs (Mem)    218319|  

Well, it seems that the recursive SQL has caused a bit of a problem for my program.  The 1,240 physical block reads found on the FETCHs line are actually included in the 3,231 (1,047 + 2,184) physical block reads found on the EXECs line.

As a final self-answering question, which is worse: that TKPROF reports only 1,240 physical block reads, or that my program double-counts these 1,240 physical block reads and suggest that there were 4,471 physical block reads?  Maybe we should just ignore the recursive SQL statistics by checking an option box in my program:

Total for Trace File:
|PARSEs       2|CPU S    0.000000|CLOCK S    0.006032|ROWs        0|PHY RD BLKs         0|CON RD BLKs (Mem)         0|CUR RD BLKs (Mem)         0|SHARED POOL MISs      2|
|EXECs        3|CPU S    9.266459|CLOCK S    9.633115|ROWs        3|PHY RD BLKs      3231|CON RD BLKs (Mem)    267427|CUR RD BLKs (Mem)         0|SHARED POOL MISs      1|
|FETCHs       0|CPU S    0.000000|CLOCK S    0.000000|ROWs        0|PHY RD BLKs         0|CON RD BLKs (Mem)         0|CUR RD BLKs (Mem)         0|SHARED POOL MISs      0| 

That option in my program fixed the CPU seconds, elapsed time, total physical blocks read, and total consistent gets, but now the number of EXECsFETCHs, and ROWs do not match what is found in the raw 10046 trace file.

As the above Excel output and my program’s fixed output demonstrates, sometimes there is no replacement for examining the raw 10046 trace files.





Dumping Trace Events – What You See is Not Necessarily What You Get

9 01 2012

January 9, 2012

A recent thread in the comp.databases.oracle.server Usenet group brought back memories of when Randolf Geist and I worked on the two chapters for the “Expert Oracle Practices” book.  In the chapters, among other things, we demonstrated how to enable 10046 trace files for sessions using various approaches (some of the approaches change the SQL_TRACE, SQL_TRACE_WAITS, and SQL_TRACE_BINDS columns in V$SESSION to indicate that a 10046 trace is active, and other methods do not), and how to use ORADEBUG to see which events are enabled in other sessions.

The OP in the thread mentioned that the ORADEBUG EVENTDUMP session command, when executed in SQL*Plus by a SYSDBA user, showed no events enabled for another session when the DBMS_MONITOR package was used to enable a 10046 trace at level 12 for the other session.  I have a vague memory of reading (somewhere) that the ORADEBUG EVENTDUMP session command will only show newly enabled events for another session after that other session issues another call to the database (parse, execute, fetch, etc.).  In the Usenet group thread I stated something that is slightly less complete: “I believe that the session with the trace enabled through DBMS_MONITOR must execute at least one SQL statement after tracing is enabled for the session, before ORADEBUG will report that the trace is enabled.”

In the Usenet thread I put together a quick test case script that demonstrated that after the second session (Session 1) issued a SELECT statement, the first session (Session 2) was able to issue a ORADEBUG EVENTDUMP session command and determine that a 10046 trace at level 12 was enabled for the other session.  I believe that the OP answered his own question after a bit of experimentation and searching.  I thought that I would provide an extended version of the test case script in case anyone would like to experiment a bit.  In this test case, Session 1 will be the target of the tracing – that session must be able to query V$SESSION and V$PROCESS during the script execution, while Session 2 will be connected as the SYS user.  In the test case script I have removed the SQL> prompts to make it easier for you to copy and paste the scripts into SQL*Plus, and when the returned output is important, that information also appears in the test case script (all commands executed begin with UPPERCASE keywords).

In Session 1, execute the following SQL statement to pick up the SID, SERIAL# and PID for Session 1, along with the columns in V$SESSION that indicate whether or not a 10046 trace at level 1, 4, 8, or 12 is enabled.  The SID and SERIAL# will be used in Session 2 to enable a trace in Session 1, and the PID will be used with ORADEBUG in Session 2:

SELECT
  S.SID,
  S.SERIAL#,
  P.PID,
  S.SQL_TRACE,
  S.SQL_TRACE_WAITS,
  S.SQL_TRACE_BINDS
FROM
  V$SESSION S,
  V$PROCESS P
WHERE
  S.SID=(SELECT SID FROM V$MYSTAT WHERE ROWNUM=1)
  AND S.PADDR=P.ADDR;

SID    SERIAL#        PID SQL_TRAC SQL_T SQL_T
--- ---------- ---------- -------- ----- -----
  4        143         24 DISABLED FALSE FALSE 

As can be determined by the above output, the SID is 4, PID is 24, and a 10046 trace is not enabled for the session (fair warning, the SQL_TRACE column can be misleading).

In Session 2, enable a 10046 trace using the DBMS_MONITOR package for Session 1 at level 12, and dump the events for Session 1 (note that this test case script is being executed on a Windows server with Oracle Database 11.2.0.2):

EXEC DBMS_MONITOR.SESSION_TRACE_ENABLE(SESSION_ID=>4,SERIAL_NUM=>143,WAITS=>TRUE,BINDS=>TRUE)

ORADEBUG SETORAPID 24

ORADEBUG EVENTDUMP session
Statement processed. 

The output of the ORADEBUG EVENTDUMP session command is significant – the Statement processed. note indicates that the statement executed successfully with no return output. 

In Session 1, let’s execute the same SQL statement as was executed earlier, to not only confirm that the DBMS_MONITOR.SESSION_TRACE_ENABLE call executed by Session 2 was successful, but also to issue another database call in the session (the significance will be seen later):

SELECT
  S.SID,
  S.SERIAL#,
  P.PID,
  S.SQL_TRACE,
  S.SQL_TRACE_WAITS,
  S.SQL_TRACE_BINDS
FROM
  V$SESSION S,
  V$PROCESS P
WHERE
  S.SID=(SELECT SID FROM V$MYSTAT WHERE ROWNUM=1)
  AND S.PADDR=P.ADDR;

SID    SERIAL#        PID SQL_TRAC SQL_T SQL_T
--- ---------- ---------- -------- ----- -----
  4        143         24 ENABLED  TRUE  TRUE

The above output shows that the DBMS_MONITOR.SESSION_TRACE_ENABLE call was successful, as indicated by the changed values in the SQL_TRACE, SQL_TRACE_WAITS, and SQL_TRACE_BINDS columns – a level 12 10046 trace is enabled.

In Session 2, let’s check again which events are enabled for Session 1:

ORADEBUG EVENTDUMP session
sql_trace level=12 

Notice in the above output that ORADEBUG now indicates that a 10046 trace at level 12 is enabled for Session 1, because another database call (initiated when the SQL statement was executed) was performed in Session 1 after the trace was enabled.

Let’s try a bit more experimentation.  In Session 2, let’s disable the trace in Session 1 using the DBMS_MONITOR package, and verify whether or not tracing is enabled in Session 1 by using ORADEBUG:

EXEC DBMS_MONITOR.SESSION_TRACE_DISABLE(SESSION_ID=>4,SERIAL_NUM=>143)
PL/SQL procedure successfully completed.

ORADEBUG EVENTDUMP session
sql_trace level=12 

The above output shows that ORADEBUG still indicates that a 10046 trace at level 12 is enabled for Session 1.  In Session 2, let’s check the SQL_TRACE, SQL_TRACE_WAITS, and SQL_TRACE_BINDS columns for Session 1:

SELECT
  S.SID,
  S.SERIAL#,
  P.PID,
  S.SQL_TRACE,
  S.SQL_TRACE_WAITS,
  S.SQL_TRACE_BINDS
FROM
  V$SESSION S,
  V$PROCESS P
WHERE
  S.SID=4
  AND S.PADDR=P.ADDR;

SID    SERIAL#        PID SQL_TRAC SQL_T SQL_T
--- ---------- ---------- -------- ----- -----
  4        143         24 DISABLED FALSE FALSE

ORADEBUG EVENTDUMP session
sql_trace level=12 

So, the query of V$SESSION indicates that a 10046 trace for Session 1 is disabled, yet ORADEBUG still insists that a 10046 trace at level 12 is enabled.  WYSIWYG (What You See Is What You Get) is taking a bit of a vacation.  Let’s issue another database call in Session 1 so that ORADEBUG provides correct output about whether or not a 10046 trace is enabled.  In Session 1:

SELECT
  S.SID,
  S.SERIAL#,
  P.PID,
  S.SQL_TRACE,
  S.SQL_TRACE_WAITS,
  S.SQL_TRACE_BINDS
FROM
  V$SESSION S,
  V$PROCESS P
WHERE
  S.SID=(SELECT SID FROM V$MYSTAT WHERE ROWNUM=1)
  AND S.PADDR=P.ADDR;

SID    SERIAL#        PID SQL_TRAC SQL_T SQL_T
--- ---------- ---------- -------- ----- -----
  4        143         24 DISABLED FALSE FALSE 

Let’s confirm in Session 2 that ORADEBUG now reports that a 10046 trace is not enabled in Session 1:

ORADEBUG EVENTDUMP session
Statement processed.  

OK, but what happens if we use ORADEBUG in Session 2 to enable a 10046 trace is Session 1?  In Session 2:

ORADEBUG session_event 10046 trace name context forever,level 12
Statement processed.

ORADEBUG EVENTDUMP session
sql_trace level=12 

The above shows that if ORADEBUG enables a 10046 trace in Session 1, the ORADEBUG EVENTDUMP session command will correctly indicate that a 10046 trace is enabled for Session 1.  Nice, but what about the SQL_TRACE, SQL_TRACE_WAITS, and SQL_TRACE_BINDS columns in V$SESSION for Session 1?  Let’s check using Session 2:

SELECT
  S.SID,
  S.SERIAL#,
  P.PID,
  S.SQL_TRACE,
  S.SQL_TRACE_WAITS,
  S.SQL_TRACE_BINDS
FROM
  V$SESSION S,
  V$PROCESS P
WHERE
  S.SID=4
  AND S.PADDR=P.ADDR;

SID    SERIAL#        PID SQL_TRAC SQL_T SQL_T
--- ---------- ---------- -------- ----- -----
  4        143         24 DISABLED FALSE FALSE 

The above output suggests that a 10046 trace at level 12 is not enabled for Session 1.  Let’s check again from within Session 1 and then determine today’s date (if that second SQL statement appears in the 10046 trace file, then we know that the 10046 trace was in fact enabled for Session 1):

SELECT
  S.SID,
  S.SERIAL#,
  P.PID,
  S.SQL_TRACE,
  S.SQL_TRACE_WAITS,
  S.SQL_TRACE_BINDS
FROM
  V$SESSION S,
  V$PROCESS P
WHERE
  S.SID=(SELECT SID FROM V$MYSTAT WHERE ROWNUM=1)
  AND S.PADDR=P.ADDR;

SID    SERIAL#        PID SQL_TRAC SQL_T SQL_T
--- ---------- ---------- -------- ----- -----
  4        143         24 DISABLED FALSE FALSE

SELECT SYSDATE FROM DUAL;

SYSDATE
---------
08-JAN-12  

The above still suggests that a 10046 trace is not enabled for Session 1 and that today’s date is January 8, 2012.  Let’s jump back to Session 2 and disable the 10046 trace using ORADEBUG:

ORADEBUG session_event 10046 trace name context off
Statement processed. 

Out of curiosity, let’s repeat a portion of the initial test, just to confirm that the initial test results were not a fluke:

EXEC DBMS_MONITOR.SESSION_TRACE_ENABLE(SESSION_ID=>4,SERIAL_NUM=>143,WAITS=>TRUE,BINDS=>TRUE)

ORADEBUG EVENTDUMP session
Statement processed.

SELECT
  S.SID,
  S.SERIAL#,
  P.PID,
  S.SQL_TRACE,
  S.SQL_TRACE_WAITS,
  S.SQL_TRACE_BINDS
FROM
  V$SESSION S,
  V$PROCESS P
WHERE
  S.SID=4
  AND S.PADDR=P.ADDR;

SID    SERIAL#        PID SQL_TRAC SQL_T SQL_T
--- ---------- ---------- -------- ----- -----
  4        143         24 ENABLED  TRUE  TRUE

ORADEBUG EVENTDUMP session
Statement processed. 

Once again, the above shows that ORADEBUG does not initially report that a 10046 trace is enabled in Session 1 when the officially supported method for enabling a 10046 trace in another session is used.  Let’s disable the 10046 trace using the DBMS_MONITOR package and then confirm that ORADEBUG still indicates that a 10046 trace is not enabled in Session 1:

EXEC DBMS_MONITOR.SESSION_TRACE_DISABLE(SESSION_ID=>4,SERIAL_NUM=>143)

ORADEBUG EVENTDUMP session
Statement processed. 

So, what about the unsupported method of enabling a 10046 trace in another session, using SYS.DBMS_SYSTEM.SET_EV?  In Session 2:

EXEC SYS.DBMS_SYSTEM.SET_EV(4, 143, 10046, 12, '')

SELECT
  S.SID,
  S.SERIAL#,
  P.PID,
  S.SQL_TRACE,
  S.SQL_TRACE_WAITS,
  S.SQL_TRACE_BINDS
FROM
  V$SESSION S,
  V$PROCESS P
WHERE
  S.SID=4
  AND S.PADDR=P.ADDR;

SID    SERIAL#        PID SQL_TRAC SQL_T SQL_T
--- ---------- ---------- -------- ----- -----
  4        143         24 ENABLED  TRUE  TRUE

ORADEBUG EVENTDUMP session
Statement processed. 

The SYS.DBMS_SYSTEM.SET_EV call changed the value of the columns in V$SESSION for Session 1, but still did not alter the output of ORADEBUG EVENTDUMP session.

One final test in Session 2:

ORADEBUG session_event 10046 trace name context forever,level 12
Statement processed.

ORADEBUG EVENTDUMP session
sql_trace level=12 

Once again, if we enable the 10046 trace using ORADEBUG, then ORADEBUG is able to show that the trace is enabled for Session 1.

———————————————

At this point you might be curious why I mentioned that the above test case script was performed on a Windows server running Oracle Database 11.2.0.2.  Does the Oracle Database version make a difference in the results?  Does the operating system (Windows, Linux, or Unix) make a difference in the results?  It appears that a part 2 is required for this blog article, where I will compare the above results with the results obtained with 10.2.0.5 on a Windows server and 11.1.0.6 on a Linux server.

———————————————

You are probably curious to see the contents of the trace file for Session 1.  Here is the trace file (if you need help in reading the trace file, see this three part article series):

*** 2012-01-08 09:47:51.686
*** SESSION ID:(4.143) 2012-01-08 09:47:51.686
*** CLIENT ID:() 2012-01-08 09:47:51.686
*** SERVICE NAME:(OR1122) 2012-01-08 09:47:51.686
*** MODULE NAME:(SQL*Plus) 2012-01-08 09:47:51.686
*** ACTION NAME:() 2012-01-08 09:47:51.686

Received ORADEBUG command (#1) 'EVENTDUMP session' from process 'Windows thread id: 12292, image: <none>'
Dumping Event (group=SESSION)

*** 2012-01-08 09:47:51.686
Finished processing ORADEBUG command (#1) 'EVENTDUMP session'

*** 2012-01-08 09:48:18.426
Received ORADEBUG command (#2) 'EVENTDUMP session' from process 'Windows thread id: 12292, image: <none>'
Dumping Event (group=SESSION)

*** 2012-01-08 09:48:18.426
Finished processing ORADEBUG command (#2) 'EVENTDUMP session'

*** 2012-01-08 09:49:16.415
CLOSE #3:c=0,e=20,dep=0,type=0,tim=488596106412
=====================
PARSING IN CURSOR #2 len=37 dep=1 uid=0 oct=3 lid=0 tim=488596107091 hv=1398610540 ad='7ffb8e4b250' sqlid='grwydz59pu6mc'
select text from view$ where rowid=:1
END OF STMT
PARSE #2:c=0,e=264,p=0,cr=0,cu=0,mis=1,r=0,dep=1,og=4,plh=0,tim=488596107088
BINDS #2:
 Bind#0
  oacdty=11 mxl=16(16) mxlc=00 mal=00 scl=00 pre=00
  oacflg=18 fl2=0001 frm=00 csi=00 siz=16 off=0
  kxsbbbfp=1dbe86d8  bln=16  avl=16  flg=05
  value=00000273.0010.0001
EXEC #2:c=0,e=550,p=0,cr=0,cu=0,mis=1,r=0,dep=1,og=4,plh=3684871272,tim=488596107744
FETCH #2:c=0,e=25,p=0,cr=2,cu=0,mis=0,r=1,dep=1,og=4,plh=3684871272,tim=488596107790
STAT #2 id=1 cnt=1 pid=0 pos=1 obj=69 op='TABLE ACCESS BY USER ROWID VIEW$ (cr=1 pr=0 pw=0 time=0 us cost=1 size=15 card=1)'
CLOSE #2:c=0,e=501,dep=1,type=0,tim=488596108309
=====================
PARSING IN CURSOR #5 len=37 dep=1 uid=0 oct=3 lid=0 tim=488596108602 hv=1398610540 ad='7ffb8e4b250' sqlid='grwydz59pu6mc'
select text from view$ where rowid=:1
END OF STMT
PARSE #5:c=0,e=23,p=0,cr=0,cu=0,mis=0,r=0,dep=1,og=4,plh=3684871272,tim=488596108602
BINDS #5:
 Bind#0
  oacdty=11 mxl=16(16) mxlc=00 mal=00 scl=00 pre=00
  oacflg=18 fl2=0001 frm=00 csi=00 siz=16 off=0
  kxsbbbfp=1dbe86d8  bln=16  avl=16  flg=05
  value=00000273.0012.0001
EXEC #5:c=0,e=47,p=0,cr=0,cu=0,mis=0,r=0,dep=1,og=4,plh=3684871272,tim=488596108701
FETCH #5:c=0,e=11,p=0,cr=2,cu=0,mis=0,r=1,dep=1,og=4,plh=3684871272,tim=488596108727
STAT #5 id=1 cnt=1 pid=0 pos=1 obj=69 op='TABLE ACCESS BY USER ROWID VIEW$ (cr=1 pr=0 pw=0 time=0 us cost=1 size=15 card=1)'
CLOSE #5:c=0,e=23,dep=1,type=0,tim=488596108766
=====================
PARSING IN CURSOR #3 len=37 dep=1 uid=0 oct=3 lid=0 tim=488596109217 hv=1398610540 ad='7ffb8e4b250' sqlid='grwydz59pu6mc'
select text from view$ where rowid=:1
END OF STMT
PARSE #3:c=0,e=14,p=0,cr=0,cu=0,mis=0,r=0,dep=1,og=4,plh=3684871272,tim=488596109217
BINDS #3:
 Bind#0
  oacdty=11 mxl=16(16) mxlc=00 mal=00 scl=00 pre=00
  oacflg=18 fl2=0001 frm=00 csi=00 siz=16 off=0
  kxsbbbfp=1dbe86d8  bln=16  avl=16  flg=05
  value=00000274.0010.0001
EXEC #3:c=0,e=50,p=0,cr=0,cu=0,mis=0,r=0,dep=1,og=4,plh=3684871272,tim=488596109318
FETCH #3:c=0,e=11,p=0,cr=2,cu=0,mis=0,r=1,dep=1,og=4,plh=3684871272,tim=488596109344
STAT #3 id=1 cnt=1 pid=0 pos=1 obj=69 op='TABLE ACCESS BY USER ROWID VIEW$ (cr=1 pr=0 pw=0 time=0 us cost=1 size=15 card=1)'
CLOSE #3:c=0,e=21,dep=1,type=0,tim=488596109385
=====================
PARSING IN CURSOR #4 len=204 dep=0 uid=91 oct=3 lid=91 tim=488596111910 hv=1585533233 ad='7ffb7578ec0' sqlid='dk42yjjg82n9j'
SELECT
  S.SID,
  S.SERIAL#,
  P.PID,
  S.SQL_TRACE,
  S.SQL_TRACE_WAITS,
  S.SQL_TRACE_BINDS
FROM
  V$SESSION S,
  V$PROCESS P
WHERE
  S.SID=(SELECT SID FROM V$MYSTAT WHERE ROWNUM=1)
  AND S.PADDR=P.ADDR
END OF STMT
PARSE #4:c=0,e=5410,p=0,cr=6,cu=0,mis=1,r=0,dep=0,og=1,plh=1985757361,tim=488596111909
EXEC #4:c=0,e=23,p=0,cr=0,cu=0,mis=0,r=0,dep=0,og=1,plh=1985757361,tim=488596112094
WAIT #4: nam='SQL*Net message to client' ela= 4 driver id=1413697536 #bytes=1 p3=0 obj#=-1 tim=488596112181
FETCH #4:c=0,e=1190,p=0,cr=0,cu=0,mis=0,r=1,dep=0,og=1,plh=1985757361,tim=488596113404
WAIT #4: nam='SQL*Net message from client' ela= 232 driver id=1413697536 #bytes=1 p3=0 obj#=-1 tim=488596113665
FETCH #4:c=0,e=397,p=0,cr=0,cu=0,mis=0,r=0,dep=0,og=1,plh=1985757361,tim=488596114102
STAT #4 id=1 cnt=1 pid=0 pos=1 obj=0 op='NESTED LOOPS  (cr=0 pr=0 pw=0 time=0 us cost=0 size=53 card=1)'
STAT #4 id=2 cnt=1 pid=1 pos=1 obj=0 op='NESTED LOOPS  (cr=0 pr=0 pw=0 time=0 us cost=0 size=49 card=1)'
STAT #4 id=3 cnt=810 pid=2 pos=1 obj=0 op='MERGE JOIN CARTESIAN (cr=0 pr=0 pw=0 time=346 us cost=0 size=16146 card=598)'
STAT #4 id=4 cnt=30 pid=3 pos=1 obj=0 op='FIXED TABLE FULL X$KSUPR (cr=0 pr=0 pw=0 time=0 us cost=0 size=494 card=26)'
STAT #4 id=5 cnt=810 pid=3 pos=2 obj=0 op='BUFFER SORT (cr=0 pr=0 pw=0 time=130 us cost=0 size=184 card=23)'
STAT #4 id=6 cnt=27 pid=5 pos=1 obj=0 op='FIXED TABLE FULL X$KSLWT (cr=0 pr=0 pw=0 time=26 us cost=0 size=184 card=23)'
STAT #4 id=7 cnt=1 pid=2 pos=2 obj=0 op='FIXED TABLE FIXED INDEX X$KSUSE (ind:1) (cr=0 pr=0 pw=0 time=0 us cost=0 size=22 card=1)'
STAT #4 id=8 cnt=1 pid=7 pos=1 obj=0 op='COUNT STOPKEY (cr=0 pr=0 pw=0 time=0 us)'
STAT #4 id=9 cnt=1 pid=8 pos=1 obj=0 op='FIXED TABLE FULL X$KSUMYSTA (cr=0 pr=0 pw=0 time=0 us cost=0 size=40 card=2)'
STAT #4 id=10 cnt=1 pid=9 pos=1 obj=0 op='FIXED TABLE FULL X$KSUSGIF (cr=0 pr=0 pw=0 time=0 us cost=0 size=4 card=1)'
STAT #4 id=11 cnt=1 pid=1 pos=2 obj=0 op='FIXED TABLE FIXED INDEX X$KSLED (ind:2) (cr=0 pr=0 pw=0 time=0 us cost=0 size=4 card=1)'
WAIT #4: nam='SQL*Net message to client' ela= 2 driver id=1413697536 #bytes=1 p3=0 obj#=-1 tim=488596114237

*** 2012-01-08 09:50:22.069
Received ORADEBUG command (#3) 'EVENTDUMP session' from process 'Windows thread id: 12292, image: <none>'
Dumping Event (group=SESSION)

*** 2012-01-08 09:50:22.069
Finished processing ORADEBUG command (#3) 'EVENTDUMP session'

*** 2012-01-08 09:51:24.578
Received ORADEBUG command (#4) 'EVENTDUMP session' from process 'Windows thread id: 12292, image: <none>'
Dumping Event (group=SESSION)

*** 2012-01-08 09:51:24.578
Finished processing ORADEBUG command (#4) 'EVENTDUMP session'

*** 2012-01-08 09:54:05.768
Received ORADEBUG command (#5) 'EVENTDUMP session' from process 'Windows thread id: 12292, image: <none>'
Dumping Event (group=SESSION)

*** 2012-01-08 09:54:05.768
Finished processing ORADEBUG command (#5) 'EVENTDUMP session'

*** 2012-01-08 09:55:01.068
WAIT #4: nam='SQL*Net message from client' ela= 344636055 driver id=1413697536 #bytes=1 p3=0 obj#=-1 tim=488940750307

*** 2012-01-08 09:55:48.744
Received ORADEBUG command (#6) 'EVENTDUMP session' from process 'Windows thread id: 12292, image: <none>'
Dumping Event (group=SESSION)

*** 2012-01-08 09:55:48.744
Finished processing ORADEBUG command (#6) 'EVENTDUMP session'

*** 2012-01-08 09:56:50.964
Received ORADEBUG command (#7) 'session_event 10046 trace name context forever,level 12' from process 'Windows thread id: 12292, image: <none>'

*** 2012-01-08 09:56:50.964
Finished processing ORADEBUG command (#7) 'session_event 10046 trace name context forever,level 12'

*** 2012-01-08 09:57:18.634
Received ORADEBUG command (#8) 'EVENTDUMP session' from process 'Windows thread id: 12292, image: <none>'
Dumping Event (group=SESSION)

*** 2012-01-08 09:57:18.634
Finished processing ORADEBUG command (#8) 'EVENTDUMP session'

*** 2012-01-08 10:00:01.094
WAIT #2: nam='SQL*Net message from client' ela= 300017366 driver id=1413697536 #bytes=1 p3=0 obj#=-1 tim=489240770346
CLOSE #2:c=0,e=19,dep=0,type=0,tim=489240770476
=====================
PARSING IN CURSOR #5 len=204 dep=0 uid=91 oct=3 lid=91 tim=489240770687 hv=1585533233 ad='7ffb7578ec0' sqlid='dk42yjjg82n9j'
SELECT
  S.SID,
  S.SERIAL#,
  P.PID,
  S.SQL_TRACE,
  S.SQL_TRACE_WAITS,
  S.SQL_TRACE_BINDS
FROM
  V$SESSION S,
  V$PROCESS P
WHERE
  S.SID=(SELECT SID FROM V$MYSTAT WHERE ROWNUM=1)
  AND S.PADDR=P.ADDR
END OF STMT
PARSE #5:c=0,e=130,p=0,cr=0,cu=0,mis=0,r=0,dep=0,og=1,plh=1985757361,tim=489240770686
EXEC #5:c=0,e=31,p=0,cr=0,cu=0,mis=0,r=0,dep=0,og=1,plh=1985757361,tim=489240770814
WAIT #5: nam='SQL*Net message to client' ela= 3 driver id=1413697536 #bytes=1 p3=0 obj#=-1 tim=489240770862
FETCH #5:c=0,e=7007,p=0,cr=0,cu=0,mis=0,r=1,dep=0,og=1,plh=1985757361,tim=489240777893
WAIT #5: nam='SQL*Net message from client' ela= 192 driver id=1413697536 #bytes=1 p3=0 obj#=-1 tim=489240778675
FETCH #5:c=0,e=336,p=0,cr=0,cu=0,mis=0,r=0,dep=0,og=1,plh=1985757361,tim=489240779049
STAT #5 id=1 cnt=1 pid=0 pos=1 obj=0 op='NESTED LOOPS  (cr=0 pr=0 pw=0 time=0 us cost=0 size=53 card=1)'
STAT #5 id=2 cnt=1 pid=1 pos=1 obj=0 op='NESTED LOOPS  (cr=0 pr=0 pw=0 time=0 us cost=0 size=49 card=1)'
STAT #5 id=3 cnt=700 pid=2 pos=1 obj=0 op='MERGE JOIN CARTESIAN (cr=0 pr=0 pw=0 time=349 us cost=0 size=16146 card=598)'
STAT #5 id=4 cnt=28 pid=3 pos=1 obj=0 op='FIXED TABLE FULL X$KSUPR (cr=0 pr=0 pw=0 time=0 us cost=0 size=494 card=26)'
STAT #5 id=5 cnt=700 pid=3 pos=2 obj=0 op='BUFFER SORT (cr=0 pr=0 pw=0 time=81 us cost=0 size=184 card=23)'
STAT #5 id=6 cnt=25 pid=5 pos=1 obj=0 op='FIXED TABLE FULL X$KSLWT (cr=0 pr=0 pw=0 time=0 us cost=0 size=184 card=23)'
STAT #5 id=7 cnt=1 pid=2 pos=2 obj=0 op='FIXED TABLE FIXED INDEX X$KSUSE (ind:1) (cr=0 pr=0 pw=0 time=0 us cost=0 size=22 card=1)'
STAT #5 id=8 cnt=1 pid=7 pos=1 obj=0 op='COUNT STOPKEY (cr=0 pr=0 pw=0 time=0 us)'
STAT #5 id=9 cnt=1 pid=8 pos=1 obj=0 op='FIXED TABLE FULL X$KSUMYSTA (cr=0 pr=0 pw=0 time=0 us cost=0 size=40 card=2)'
STAT #5 id=10 cnt=1 pid=9 pos=1 obj=0 op='FIXED TABLE FULL X$KSUSGIF (cr=0 pr=0 pw=0 time=0 us cost=0 size=4 card=1)'
STAT #5 id=11 cnt=1 pid=1 pos=2 obj=0 op='FIXED TABLE FIXED INDEX X$KSLED (ind:2) (cr=0 pr=0 pw=0 time=0 us cost=0 size=4 card=1)'
WAIT #5: nam='SQL*Net message to client' ela= 1 driver id=1413697536 #bytes=1 p3=0 obj#=-1 tim=489240779190

*** 2012-01-08 10:00:49.694
WAIT #5: nam='SQL*Net message from client' ela= 48590415 driver id=1413697536 #bytes=1 p3=0 obj#=-1 tim=489289369620
CLOSE #5:c=0,e=16,dep=0,type=0,tim=489289369744
=====================
PARSING IN CURSOR #3 len=24 dep=0 uid=91 oct=3 lid=91 tim=489289370485 hv=124468195 ad='7ffb78cd410' sqlid='c749bc43qqfz3'
SELECT SYSDATE FROM DUAL
END OF STMT
PARSE #3:c=0,e=704,p=0,cr=0,cu=0,mis=1,r=0,dep=0,og=1,plh=1388734953,tim=489289370484
EXEC #3:c=0,e=24,p=0,cr=0,cu=0,mis=0,r=0,dep=0,og=1,plh=1388734953,tim=489289370563
WAIT #3: nam='SQL*Net message to client' ela= 3 driver id=1413697536 #bytes=1 p3=0 obj#=-1 tim=489289370620
FETCH #3:c=0,e=13,p=0,cr=0,cu=0,mis=0,r=1,dep=0,og=1,plh=1388734953,tim=489289370661
STAT #3 id=1 cnt=1 pid=0 pos=1 obj=0 op='FAST DUAL  (cr=0 pr=0 pw=0 time=0 us cost=2 size=0 card=1)'
WAIT #3: nam='SQL*Net message from client' ela= 189 driver id=1413697536 #bytes=1 p3=0 obj#=-1 tim=489289370905
FETCH #3:c=0,e=1,p=0,cr=0,cu=0,mis=0,r=0,dep=0,og=0,plh=1388734953,tim=489289370957
WAIT #3: nam='SQL*Net message to client' ela= 2 driver id=1413697536 #bytes=1 p3=0 obj#=-1 tim=489289370997

*** 2012-01-08 10:09:13.997
Received ORADEBUG command (#9) 'session_event 10046 trace name context off' from process 'Windows thread id: 12292, image: <none>'

*** 2012-01-08 10:09:13.997
Finished processing ORADEBUG command (#9) 'session_event 10046 trace name context off'

*** 2012-01-08 10:11:16.960
Received ORADEBUG command (#10) 'EVENTDUMP session' from process 'Windows thread id: 12292, image: <none>'
Dumping Event (group=SESSION)

*** 2012-01-08 10:11:16.960
Finished processing ORADEBUG command (#10) 'EVENTDUMP session'

*** 2012-01-08 10:12:42.528
Received ORADEBUG command (#11) 'EVENTDUMP session' from process 'Windows thread id: 12292, image: <none>'
Dumping Event (group=SESSION)

*** 2012-01-08 10:12:42.528
Finished processing ORADEBUG command (#11) 'EVENTDUMP session'

*** 2012-01-08 10:15:29.621
Received ORADEBUG command (#12) 'EVENTDUMP session' from process 'Windows thread id: 12292, image: <none>'
Dumping Event (group=SESSION)

*** 2012-01-08 10:15:29.621
Finished processing ORADEBUG command (#12) 'EVENTDUMP session'

*** 2012-01-08 10:19:54.941
Received ORADEBUG command (#13) 'EVENTDUMP session' from process 'Windows thread id: 12292, image: <none>'
Dumping Event (group=SESSION)

*** 2012-01-08 10:19:54.941
Finished processing ORADEBUG command (#13) 'EVENTDUMP session'

*** 2012-01-08 10:21:25.459
Received ORADEBUG command (#14) 'session_event 10046 trace name context forever,level 12' from process 'Windows thread id: 12292, image: <none>'

*** 2012-01-08 10:21:25.459
Finished processing ORADEBUG command (#14) 'session_event 10046 trace name context forever,level 12'

*** 2012-01-08 10:21:40.549
Received ORADEBUG command (#15) 'EVENTDUMP session' from process 'Windows thread id: 12292, image: <none>'
Dumping Event (group=SESSION)

*** 2012-01-08 10:21:40.549
Finished processing ORADEBUG command (#15) 'EVENTDUMP session' 




Idle Thoughts – SSD, Redo Logs, and Sector Size

18 12 2011

December 18, 2011

It seems that I have been quite busy lately with computer related tasks that are not associated with Oracle Database, making it difficult to slow down and focus on items that have a foundation in logic.  Today I have had some spare time to dig further into the recently released “Oracle Core” book.  A Note on page 123 (obviously a logical page number) gave me a moment to pause.  Quoting a small portion of the Note:

“Recently disk manufacturers have started to produce disks with a 4KB sector size… From 11.2 Oracle lets the DBA choose which is the lesser of two evils by allowing you to specify the block size for the log file as 512 bytes, 1KB, or 4KB.” 

Do you see it yet, the reason to pause?

-

-

-

I am typing this blog article on a laptop that is a bit over a year old with two 256GB Crucial SSD drives in a RAID 0 arrangement.  Even though the laptop supports 3Gb/s transfer speeds from the internal drives rather than the more recent 6Gb/s transfer speeds, the drive arrangement is very quick (quick and potentially subject to a very bad data loss if one drive in the RAID 0 array fails), hitting a speed of 539 MB per second in a parallel full table scan.

I believe that the Crucial SSD drives have a 4 KB sector size, much like many other SSD drives.  It seems that some of Intel’s higher-end single layer drives use a 16 KB sector size (4000h = 16,384, see page 17 for the X25 series and page 22 for the 510 series).  I recall from reading the Oracle Database documentation the following statement:

“Unlike the database block size, which can be between 2K and 32K, redo log files always default to a block size that is equal to the physical sector size of the disk. Historically, this has typically been 512 bytes (512B).

Some newer high-capacity disk drives offer 4K byte (4K) sector sizes for both increased ECC capability and improved format efficiency. Most Oracle Database platforms are able to detect this larger sector size. The database then automatically creates redo log files with a 4K block size on those disks.” 

Do you see it yet, the reason to pause?

-

-

-

I recently read an interesting article titled De-Confusing SSD (for Oracle Databases) that inspired several interesting comments.  I think that the following two statements in the article contributed to the comment count:

SSD’s base memory unit is a cell, which holds 1 bit in SLC and 2 bits in MLC. Cells are organized in pages (usually 4k) and pages are organized in blocks (512K). Data can be read and written in pages, but is always deleted in blocks. This will become really important in a moment.

* Placing redo logs on SSD is not recommended. Exadata now has a “Smart Flash Logging” feature that uses redo logs on SSD. Note that it uses redo logs *also* on SSD. This feature allows Oracle to write redo in parallel to a file on SSD and a file on the magnetic disk, and finish the operation when one of the calls is successful.

Do you see it yet, the reason to pause?

-

-

-

So, the “Oracle Core” book states that as of Oracle Database 11.2 the DBA is able to select a 512 byte, 1024 byte, or 4096 byte (4 KB) block size for the redo log files.  Idle thinking… I have Oracle Database 11.2.0.2 installed on this laptop for educational purposes, let’s try executing a simple SQL statement that retrieves the block size for the redo log files:

SELECT
  GROUP#,
  BLOCKSIZE
FROM
  V$LOG
ORDER BY
  GROUP#;

GROUP#  BLOCKSIZE
------ ----------
     1        512
     2        512
     3        512 

So, if the sector size of my Crucial SSD drive is 4 KB, I have a (default) block size for the redo log files that potentially conflicts with the documentation, and if this is not an isolated issue, it might explain (in part) why the De-Confusing SSD (for Oracle Databases) article states that placing redo logs on SSD is not recommended.

Do you see it yet, the reason to pause?

-

-

-

I wonder if in testing redo log performance on SSD drives, if those drives were provided a “fair” test environment, where the BLOCKSIZE of the redo log files was sized appropriately for the write characteristics of SSD drives?  Any thoughts?








Follow

Get every new post delivered to your Inbox.

Join 142 other followers