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. 🙂
Charles Hooper's Oracle Notes 
[…] PLAN_HASH_VALUE Appears in V$SQLAREA? Charles Hooper […]
Hi Charles,
I have an output from tkprof that Elapsed time from wait events is higher than “elapsed” in tkprof output. However, I do not know where in your blog I can post it. So aplogies for this. A comment has been it is due to using different clock granularities. Please advise if you are interested in me posting and where.
Thanks,
Mich
MIch,
I have been struggling to find time lately to write anything on this blog (I am suffering a bit from lack of ideas), or even to look through message threads on OTN or read blogs.
That is an interesting problem that you mention. If you look in the raw trace file, do you see any waits associated with CURSOR #0? Another thought is that SQL statements at recursive dep=1 or dep=2 might be affecting the tkprof output.
I will hopefully have some time later today – it might make for an interesting blog article to explore an example of the wait time being greater than the elapsed time. How large is the trace file?
Thanks Charles.
Briefly:
This is Oracle11g R2 on 8K block
I am running the following simple OLTP type tests. Selecting 1.7 million rows into an associateive array and updating another table where object_id match (via index key)
Table tdash has 1.7 Million rows based on all_objects + padding1 varchar(4000) + padding2 varchar(4000). There is a unique index on object_id
Table testwrites was created as CREATE TABLE testwrites AS SELECT * FROM tdash WHERE ROWNUM <=1000000. A unque index was created on object_id of testwrites table.
The Pl/SQL block
EXEC DBMS_MONITOR.SESSION_TRACE_ENABLE ( waits=>true, plan_stat=>'ALL_EXECUTIONS' ); DECLARE type ObjIdArray is table of tdash.object_id%TYPE index by binary_integer; l_ids objIdArray; CURSOR c IS SELECT object_id FROM tdash; BEGIN OPEN c; LOOP BEGIN FETCH c BULK COLLECT INTO l_ids LIMIT 100; FORALL rs in 1 .. l_ids.COUNT UPDATE testwrites SET PADDING1 = RPAD('y',4000,'y') WHERE object_id = l_ids(rs); commit; FORALL rs in 1 .. l_ids.COUNT DELETE FROM testwrites WHERE object_id = l_ids(rs); commit; FORALL rs in 1 .. l_ids.COUNT INSERT INTO testwrites SELECT * FROM tdash t WHERE t.object_id = l_ids(rs); commit; EXIT WHEN C%NOTFOUND; EXCEPTION WHEN NO_DATA_FOUND THEN NULL; WHEN OTHERS THEN DBMS_OUTPUT.PUT_LINE('Transaction failed'); END; END LOOP; CLOSE c; END;TKPROF output for update only shows:
UPDATE TESTWRITES SET PADDING1 = RPAD('y',4000,'y') WHERE OBJECT_ID = :B1 call count cpu elapsed disk query current rows ------- ------ -------- ---------- ---------- ---------- ---------- ---------- Parse 4 0.00 0.00 0 0 0 0 Execute 17293 21.62 1245.41 1064667 2411398 6280588 1000000 Fetch 0 0.00 0.00 0 0 0 0 ------- ------ -------- ---------- ---------- ---------- ---------- ---------- total 17297 21.62 1245.41 1064667 2411398 6280588 1000000 Misses in library cache during parse: 1 Misses in library cache during execute: 1 Optimizer mode: ALL_ROWS Parsing user id: 93 (recursive depth: 1) Rows Row Source Operation ------- --------------------------------------------------- 0 UPDATE TESTWRITES (cr=214 pr=427 pw=0 time=0 us) 100 INDEX UNIQUE SCAN TESTWRITES_PK (cr=110 pr=3 pw=0 time=0 us cost=2 size=4007 card=1)(object id 92380) Elapsed times include waiting on following events: Event waited on Times Max. Wait Total Waited ---------------------------------------- Waited ---------- ------------ Disk file operations I/O 2 0.00 0.00 db file sequential read 2160263 1.57 2304.22 db file scattered read 27769 0.26 99.78 ******************************************************************************* SQL ID: 8ggw94h7mvxd7 Plan Hash: 0 COMMIT call count cpu elapsed disk query current rows ------- ------ -------- ---------- ---------- ---------- ---------- ---------- Parse 51879 0.16 0.35 0 0 0 0 Execute 51879 1.82 6.29 0 0 37301 0 Fetch 0 0.00 0.00 0 0 0 0 ------- ------ -------- ---------- ---------- ---------- ---------- ---------- total 103758 1.98 6.65 0 0 37301 0 Misses in library cache during parse: 0 Parsing user id: 93 (recursive depth: 1) Elapsed times include waiting on following events: Event waited on Times Max. Wait Total Waited ---------------------------------------- Waited ---------- ------------ log file switch completion 1 0.05 0.05 db file sequential read 121686 1.39 162.95 log buffer space 2 0.98 0.99 log file switch (private strand flush incomplete) 1 1.47 1.47 ********************************************************************************Now why my elapsed times for updates from wait events 2304.22+ 99.78 = 2404 sec is HIGHER than my elapsed time of 1245.21 sec? I don’t think it can be explained purely due to different clock granularities. Additionally,
Also I have “db file sequential read” = 2,160,263 physical IOs and from the rsaw trace file one physical IO in this case is 32 blocks. I also have “db file scattered read” = 27,769 physical IOs. In contrast the number of my disk reads is 1,064,667 blocks which is far less that sum of physical IOs. Something is not right somewhere.
Thanks,
Mich
Mich,
Sorry for the delay in responding.
It appears that what you are seeing is a potential bug in the version of tkprof that you are using, but the potential bug is unconfirmed at the moment. The version of tkprof is probably prior to 11.1.0.7. The potential bug appears to be related to attempting to subtract recursive child statistics from the associated from the parent UPDATE SQL statement statistics (the update statement has a dep=1, while the recursive child statistics will have a dep=2, great-grandchild will have a cursive dep=3, etc.).
I set up a test (60,000 rows in T1 from ALL_OBJECTS, 50,000 in T2) with Oracle Database 11.2.0.2, and the 32 bit Oracle Client 11.2.0.1 on Windows with patch 10155837 (fixes ODBC update problems related to bind variables), and found that that version of tkprof apparently correctly associates the parent and child statistics (I wonder about the grandchildren statitsics).
call count cpu elapsed disk query current rows ------- ------ -------- ---------- ---------- ---------- ---------- ---------- Parse 1 0.00 0.00 0 0 0 0 Execute 600 197.38 197.60 452 50299237 426582 50000 Fetch 0 0.00 0.00 0 0 0 0 ------- ------ -------- ---------- ---------- ---------- ---------- ---------- total 601 197.38 197.60 452 50299237 426582 50000 Misses in library cache during parse: 1 Misses in library cache during execute: 1 Optimizer mode: ALL_ROWS Parsing user id: 64 (recursive depth: 1) Number of plan statistics captured: 1 Rows (1st) Rows (avg) Rows (max) Row Source Operation ---------- ---------- ---------- --------------------------------------------------- 0 0 0 UPDATE T2 (cr=80409 pr=436 pw=0 time=357525 us) 100 100 100 TABLE ACCESS FULL T2 (cr=80182 pr=420 pw=0 time=337295 us cost=116 size=16120 card=8) 0 0 0 UPDATE T2 (cr=83795 pr=0 pw=0 time=344133 us) 100 100 100 TABLE ACCESS FULL T2 (cr=83598 pr=0 pw=0 time=332180 us cost=116 size=16120 card=8) 0 0 0 UPDATE T2 (cr=83790 pr=2 pw=0 time=303134 us) 100 100 100 TABLE ACCESS FULL T2 (cr=83596 pr=0 pw=0 time=288815 us cost=116 size=16120 card=8) 0 0 0 UPDATE T2 (cr=83789 pr=2 pw=0 time=283738 us) 100 100 100 TABLE ACCESS FULL T2 (cr=83595 pr=0 pw=0 time=271190 us cost=116 size=16120 card=8) ... 0 0 0 UPDATE T2 (cr=87900 pr=0 pw=0 time=375297 us) 0 0 0 TABLE ACCESS FULL T2 (cr=87900 pr=0 pw=0 time=375015 us cost=116 size=16120 card=8) Elapsed times include waiting on following events: Event waited on Times Max. Wait Total Waited ---------------------------------------- Waited ---------- ------------ db file sequential read 36 0.00 0.01 db file scattered read 31 0.00 0.01For comparison, my program (Hyper-Extended Oracle Performance Monitor), does not subtract child recursive statistics from the parent statistics, so double-counting of statistics is very likely when dep=1 (or greater) statements are found in the trace file. My program output:
Statement Depth 1 (Trigger Code) Cursor 220 Ver 1 Parse at 0.254283 SQL_ID='1ahnbczb20gdx' (TD Prev 0.000877) Similar Cnt 1 |PARSEs 1|CPU S 0.000000|CLOCK S 0.000169|ROWs 0|PHY RD BLKs 0|CON RD BLKs (Mem) 0|CUR RD BLKs (Mem) 0|SHARED POOL MISs 1| |EXECs 600|CPU S 197.403668|CLOCK S 197.659011|ROWs 50000|PHY RD BLKs 774|CON RD BLKs (Mem) 50299674|CUR RD BLKs (Mem) 426582|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 25.08% CLOCK S 25.01% | +++++|| +++++| UPDATE T2 SET PADDING1 = RPAD('y',4000,'y') WHERE OBJECT_ID = :B1 (Rows 0) UPDATE T2 (cr=80409 pr=436 pw=0 time=357525 us) (Rows 100) TABLE ACCESS FULL T2 (cr=80182 pr=420 pw=0 time=337295 us cost=116 size=16120 card=8) (Rows 0) UPDATE T2 (cr=83795 pr=0 pw=0 time=344133 us) (Rows 100) TABLE ACCESS FULL T2 (cr=83598 pr=0 pw=0 time=332180 us cost=116 size=16120 card=8) (Rows 0) UPDATE T2 (cr=83790 pr=2 pw=0 time=303134 us) (Rows 100) TABLE ACCESS FULL T2 (cr=83596 pr=0 pw=0 time=288815 us cost=116 size=16120 card=8) (Rows 0) UPDATE T2 (cr=83789 pr=2 pw=0 time=283738 us) (Rows 100) TABLE ACCESS FULL T2 (cr=83595 pr=0 pw=0 time=271190 us cost=116 size=16120 card=8)One of the outputs of my program is also an Excel spreadsheet with the wait events for each cursor. That spreadsheet confirms the tkprof output, that there were 31 db file scattered read waits (for a total of 416 blocks, all close to the start of the trace – Oracle was trying to fill the empty buffer cache) and 36 db file sequential read waits (36 total blocks). Notice also that the CPU time and elapsed times differ, in addition to the number of physical blocks read and consistent gets.
Which version of Oracle11g R2 Database are you using (11.2.0.1, 11.2.0.2, 11.2.0.3)?
Which version of the Oracle client are you using? You can determine the Oracle client by using the tnsping utility immedaitely after using tkprof:
The test case that I used to produce the above output had a unique index on the OBJECT_ID column of table T1, but not the OBJECT_ID column of table T2. Below is the output from tkprof with the index on table T2:
SQL ID: 1ahnbczb20gdx Plan Hash: 1751280057 UPDATE T2 SET PADDING1 = RPAD('y',4000,'y') WHERE OBJECT_ID = :B1 call count cpu elapsed disk query current rows ------- ------ -------- ---------- ---------- ---------- ---------- ---------- Parse 1 0.00 0.00 0 0 0 0 Execute 190 1.35 1.42 348 52552 165435 19000 Fetch 0 0.00 0.00 0 0 0 0 ------- ------ -------- ---------- ---------- ---------- ---------- ---------- total 191 1.35 1.42 348 52552 165435 19000 Misses in library cache during parse: 1 Misses in library cache during execute: 1 Optimizer mode: ALL_ROWS Parsing user id: 64 (recursive depth: 1) Number of plan statistics captured: 1 Rows (1st) Rows (avg) Rows (max) Row Source Operation ---------- ---------- ---------- --------------------------------------------------- 0 0 0 UPDATE T2 (cr=332 pr=30 pw=0 time=19223 us) 100 100 100 INDEX UNIQUE SCAN IND_T2_OBJ (cr=105 pr=8 pw=0 time=1372 us cost=1 size=2015 card=1)(object id 103855) 0 0 0 UPDATE T2 (cr=288 pr=2 pw=0 time=8629 us) 100 100 100 INDEX UNIQUE SCAN IND_T2_OBJ (cr=105 pr=0 pw=0 time=430 us cost=1 size=2015 card=1)(object id 103855) 0 0 0 UPDATE T2 (cr=294 pr=2 pw=0 time=8961 us) 100 100 100 INDEX UNIQUE SCAN IND_T2_OBJ (cr=105 pr=0 pw=0 time=438 us cost=1 size=2015 card=1)(object id 103855) ... 0 0 0 UPDATE T2 (cr=294 pr=0 pw=0 time=6507 us) 100 100 100 INDEX UNIQUE SCAN IND_T2_OBJ (cr=111 pr=0 pw=0 time=440 us cost=1 size=2015 card=1)(object id 103855) 0 0 0 UPDATE T2 (cr=291 pr=0 pw=0 time=6051 us) 100 100 100 INDEX UNIQUE SCAN IND_T2_OBJ (cr=105 pr=0 pw=0 time=430 us cost=1 size=2015 card=1)(object id 103855) Elapsed times include waiting on following events: Event waited on Times Max. Wait Total Waited ---------------------------------------- Waited ---------- ------------ db file scattered read 40 0.00 0.03 db file sequential read 32 0.00 0.01And the output from my program:
Statement Depth 1 (Trigger Code) Cursor 910 Ver 1 Parse at 0.187068 SQL_ID='1ahnbczb20gdx' (TD Prev 0.000996) Similar Cnt 1 |PARSEs 1|CPU S 0.000000|CLOCK S 0.000162|ROWs 0|PHY RD BLKs 0|CON RD BLKs (Mem) 0|CUR RD BLKs (Mem) 0|SHARED POOL MISs 1| |EXECs 600|CPU S 3.603618|CLOCK S 3.683344|ROWs 50000|PHY RD BLKs 912|CON RD BLKs (Mem) 144826|CUR RD BLKs (Mem) 426496|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 16.91% CLOCK S 15.45% | +++|| +++| UPDATE T2 SET PADDING1 = RPAD('y',4000,'y') WHERE OBJECT_ID = :B1 (Rows 0) UPDATE T2 (cr=332 pr=30 pw=0 time=19223 us) (Rows 100) INDEX UNIQUE SCAN IND_T2_OBJ (cr=105 pr=8 pw=0 time=1372 us cost=1 size=2015 card=1) (Rows 0) UPDATE T2 (cr=288 pr=2 pw=0 time=8629 us) (Rows 100) INDEX UNIQUE SCAN IND_T2_OBJ (cr=105 pr=0 pw=0 time=430 us cost=1 size=2015 card=1) (Rows 0) UPDATE T2 (cr=294 pr=2 pw=0 time=8961 us) (Rows 100) INDEX UNIQUE SCAN IND_T2_OBJ (cr=105 pr=0 pw=0 time=438 us cost=1 size=2015 card=1) ... (Rows 0) UPDATE T2 (cr=105 pr=0 pw=0 time=221 us) (Rows 0) INDEX UNIQUE SCAN IND_T2_OBJ (cr=105 pr=0 pw=0 time=174 us cost=1 size=2015 card=1) (Rows 0) UPDATE T2 (cr=105 pr=0 pw=0 time=193 us) (Rows 0) INDEX UNIQUE SCAN IND_T2_OBJ (cr=105 pr=0 pw=0 time=153 us cost=1 size=2015 card=1)Notice now that the elapsed time is just less than half of what my program outputs, while the numbers were very close when a full table scan was the only option. The same is true for the CPU time. I might have to experiment a bit more to see what is happening.
I think that I have the answer regarding why tkprof states that the elapsed time is 1.42 seconds, while my program claims that the elapsed time is 3.683344 seconds. I forsee a new blog article.
Thanks Charles. I am looking at your output and doing some more of my own investigation.
FYI, My version of tkprof is
Hi just a correction
db file sequential reads are single block IO’s. they are not 32 they are 1. db file scattered reads are the multi-block IO’s, they range from 2-7 blocks
Could this be exlained due to recursive sql
Actually this work of mine was related to comparing a typical OLTP load on Solid State Disks (SSD) vs the same load on normal hard disks (HDD) for “writes”. So using the script that I explained earier I simulated UPDATES/DELETES/INSERTS via index search. In our case we are processing 100 rows at a time.Now typically the UPDATES and DELETES affect 1000,000 existing rows in table testwrites. But remember that tdash has 1.7 million rows and above 1000,000 UPDATE AND DELETES return zero rows. However, INSERT will happen. So it total a million rows (in chuncks of 100 rows at a time) will be UPDATED, DELETED and RE-INSERTED. Above 1000,000 only INSERTS will happen and obviously index rows will be added. So there will be plenty of recursive rows.
So if I run the whole thing (UPDATES/DELETES/INSERTS) and look at the number of recursive statement for HDD I get
OVERALL TOTALS FOR ALL RECURSIVE STATEMENTS call count cpu elapsed disk query current rows ------- ------ -------- ---------- ---------- ---------- ---------- ---------- Parse 52982 0.23 0.47 3 19 0 0 Execute 105787 141.17 4308.08 3564902 12708368 43266845 3729575 Fetch 21254 0.22 3.72 4380 29023 0 1733335 ------- ------ -------- ---------- ---------- ---------- ---------- ---------- total 180023 141.63 4312.28 3569285 12737410 43266845 5462910 Elapsed times include waiting on following events: Event waited on Times Max. Wait Total Waited ---------------------------------------- Waited ---------- ------------ db file sequential read 3260950 1.57 3660.65 db file scattered read 55729 0.57 244.64 4321 elapsed seconds in trace file.That 4,321 elapsed seconds includes 4,312.28 sec from recursive statements plus 9.15 sec for non-recursive statements (not shown). These recursive statements occurred because of dynamic storage extension. Dynamic storage extension occurred in our case because table testwrites and its index had to extend beyond their allocated space (that is, new extents were allocated). The wait times included 3,660.65 sec for db file sequential reads and 244.64 sec waits for db file scattered reads.
Now this summary seems to be correct. However, it typically does not answer (at least directly) the throughput of writes. Not suprising noone waits for writes. So I wanted to devise a mechanisom for measuring writes (exclusing ORION or other scripts). I thought abou it and decided to use AWR for this purpose. Went back to my original script and used checkpoint prior and following PL/SQL block and with snapshot
ALTER SYSTEM CHECKPOINT; EXEC DBMS_WORKLOAD_REPOSITORY.CREATE_SNAPSHOT(); DECLARE type ObjIdArray is table of tdash.object_id%TYPE index by binary_integer; l_ids objIdArray; CURSOR c IS SELECT object_id FROM tdash; BEGIN OPEN c; LOOP BEGIN FETCH c BULK COLLECT INTO l_ids LIMIT 100; FORALL rs in 1 .. l_ids.COUNT UPDATE testwrites SET PADDING1 = RPAD('y',4000,'y') WHERE object_id = l_ids(rs); commit; FORALL rs in 1 .. l_ids.COUNT DELETE FROM testwrites WHERE object_id = l_ids(rs); commit; FORALL rs in 1 .. l_ids.COUNT INSERT INTO testwrites SELECT * FROM tdash t WHERE t.object_id = l_ids(rs); commit; EXIT WHEN C%NOTFOUND; EXCEPTION WHEN NO_DATA_FOUND THEN NULL; WHEN OTHERS THEN DBMS_OUTPUT.PUT_LINE('Transaction failed'); END; END LOOP; CLOSE c; END; / ALTER SYSTEM CHECKPOINT; EXEC DBMS_WORKLOAD_REPOSITORY.CREATE_SNAPSHOT();Now I can work out the volume of redos and writes generated (another topic for itself). Also for clarity with SSD tests redo files were on SSD. With HDD tests redo files were put on HDD. So after a bit of head scratching with tkprof output, I decided to look at the overall statistics for PL/SQL block. just compare the SQL execute times pretty much as they are taken at the highest level (like outside of the loop).
Cheers,
Mich