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.  :-)


Actions

Information

10 responses

30 03 2012
Log Buffer #265, A Carnival of the Vanities for DBAs | The Pythian Blog

[...] PLAN_HASH_VALUE Appears in V$SQLAREA? Charles Hooper [...]

18 05 2012
Mich Talebzadeh

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

18 05 2012
Charles Hooper

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?

18 05 2012
Mich Talebzadeh

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

20 05 2012
Charles Hooper

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.01

For 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:

C:\Oracle\diag\rdbms\or1122p\or1122p\trace>tnsping
 
TNS Ping Utility for 32-bit Windows: Version 11.2.0.1.0 - Production on 20-MAY-2012 11:00:31
 
Copyright (c) 1997, 2010, Oracle.  All rights reserved.
 
TNS-03502: Insufficient arguments.  Usage:  tnsping <address> [<count>]
20 05 2012
Charles Hooper

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.01

And 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.

20 05 2012
Charles Hooper

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.

20 05 2012
Mich Talebzadeh

Thanks Charles. I am looking at your output and doing some more of my own investigation.

FYI, My version of tkprof is

TKPROF: Release 11.2.0.1.0 
18 05 2012
Mich Talebzadeh

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

20 05 2012
Mich Talebzadeh

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

Leave a Reply

Fill in your details below or click an icon to log in:

WordPress.com Logo

You are commenting using your WordPress.com account. Log Out / Change )

Twitter picture

You are commenting using your Twitter account. Log Out / Change )

Facebook photo

You are commenting using your Facebook account. Log Out / Change )

Google+ photo

You are commenting using your Google+ account. Log Out / Change )

Connecting to %s




Follow

Get every new post delivered to your Inbox.

Join 137 other followers

%d bloggers like this: