Why is a Full Table Scan Selected – Will the Execution Plan Provide a Clue?

20 06 2012

June 20, 2012

I have not had much time to respond in OTN threads recently, although I do still occasionally read threads on the forum.  I was a little surprised by one of the late responses in one of the recent threads, where one of the responders suggested actually testing the problem with the assistance of execution plans.  Additionally, that responder suggested that the earlier responses missed the target.  Ouch!

The OP did not provide DDL to create the table or indexes, or DML to populate the table.  The SQL statement provided by the OP was apparently looking for rows where the VARCHAR2 column A was blank (as in containing a zero length string).  If an index exists on column A, why would the optimizer select to perform a full table scan when attempting to return all rows with a zero length string in column A?  (Raise your hand if you know the answer.)

Let’s create a test table with four indexes so that we are able to test some of the theories (or possible causes) that were proposed in the thread:

DROP TABLE T1 PURGE;

CREATE TABLE T1 AS 
SELECT
  ROWNUM C1,
  MOD(ROWNUM,10) C2,
  TRUNC(ROWNUM/10000) C3,
  RPAD(TO_CHAR(ROWNUM),6,'A') C4,
  LPAD('A',200,'A') C5
FROM
  DUAL
CONNECT BY
  LEVEL<=100000;

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

CREATE INDEX IND_T1_C1 ON T1(C1);
CREATE INDEX IND_T1_C2 ON T1(C2);
CREATE INDEX IND_T1_C3 ON T1(C3);
CREATE INDEX IND_T1_C4 ON T1(C4);

EXEC DBMS_STATS.GATHER_TABLE_STATS(OWNNAME=>USER,TABNAME=>'T1',CASCADE=>TRUE,ESTIMATE_PERCENT=>NULL)

SET LINESIZE 140
SET PAGESIZE 1000 

The above script creates a table with 100,000 rows, with the first 3 columns declared as NOT NULL.  Column C1 contains the numbers 1 through 100,000.  Column C2 contains the numbers 0 through 9 in a repeating pattern.  Column C3 contains the numbers 0 through 10 with most of the rows containing the same value likely closely bunched together (a single row contains the number 10).  Column C4 is a simple VARCHAR2 column that is the number 1 through 100,000 padded to six characters using the letter A.  The statistics for the table and indexes were collected with a 100% sampling percentage.

Using the test table created by the above script, we might simulate the OP’s SQL statement using the following.  One of the last responders in the OTN thread recommended looking at the execution plan, so we will retrieve that also:

SELECT
  *
FROM
  T1
WHERE
  C4='';

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

Unfortunately, the two single quotes () in the SQL statement are not interpretted as a test for a zero length string as happens on other DB platforms, and as the OP likely intended (see this AskTom thread).  The Oracle Database 11.2.0.2 output of the above follows:

no rows selected

SQL>

SQL_ID  5tc2j4q52493b, child number 0
-------------------------------------
SELECT   * FROM   T1 WHERE   C4=''

Plan hash value: 3332582666

---------------------------------------------------------------------------
| Id  | Operation          | Name | Rows  | Bytes | Cost (%CPU)| Time     |
---------------------------------------------------------------------------
|   0 | SELECT STATEMENT   |      |       |       |     1 (100)|          |
|*  1 |  FILTER            |      |       |       |            |          |
|   2 |   TABLE ACCESS FULL| T1   |   100K|    20M|   252   (1)| 00:00:01 |
---------------------------------------------------------------------------

Predicate Information (identified by operation id):
---------------------------------------------------
   1 - filter(NULL IS NOT NULL) 

So, the Predicate Information section shows NULL IS NOT NULL, which never has a result of TRUE.  Notice that the full table scan has a cost of 252, yet plan row 0, which is a grandparent of row 2, has a cost of 1 (costs for parent operations are supposed to include the calculated cost of child operations plus the calculated cost of the work performed at the parent operation).  (Raise your hand if you know the answer why plan row 0 has a cost of 1 when plan row 2 has a cost of 252.)  We will have to come back to this execution plan oddity later.

For a SQL statement like the following, which should return one row, you would expect the index on column C1 to be used:

SELECT
  C1,
  C2,
  C3,
  C4,
  SUBSTR(C5,1,10) C5
FROM
  T1
WHERE
  C1=9;

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

Here is the output of the above:

        C1         C2         C3 C4     C5
---------- ---------- ---------- ------ ----------
         9          9          0 9AAAAA AAAAAAAAAA

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

PLAN_TABLE_OUTPUT
-----------------------------------------------------------------------------------------
SQL_ID  90d7zdbavdpuu, child number 0
-------------------------------------
SELECT   C1,   C2,   C3,   C4,   SUBSTR(C5,1,10) C5 FROM   T1 WHERE
C1=9

Plan hash value: 683303157

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

Predicate Information (identified by operation id):
---------------------------------------------------
   2 - access("C1"=9) 

So, an index range scan was performed to retrieve the one row from table T1.  (Raise your hand if you know the answer why an index range scan operation was selected when every value in column C1 is unique and an equality predicate was used in the WHERE clause.)

For the following SQL statement, where an index on column C2 would likely have a large clustering factor value, should an index be used to retrieve 10% of the rows from the table?

SELECT
  C1,
  C2,
  C3,
  C4,
  SUBSTR(C5,1,10) C5
FROM
  T1
WHERE
  C2=9;

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

Here is a portion of the output from the above SQL statement:

...
     99969          9          9 99969A AAAAAAAAAA
     99979          9          9 99979A AAAAAAAAAA
     99989          9          9 99989A AAAAAAAAAA
     99999          9          9 99999A AAAAAAAAAA

10000 rows selected.

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

PLAN_TABLE_OUTPUT
--------------------------------------------------------------------------
SQL_ID  459zvkh9p725k, child number 0
-------------------------------------
SELECT   C1,   C2,   C3,   C4,   SUBSTR(C5,1,10) C5 FROM   T1 WHERE
C2=9

Plan hash value: 3617692013

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

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

The optimizer selected to use a full table scan in order to retrieve 10% of the rows from the table.  (Raise your hand if you know the answer why a full table scan was selected.)

A final SQL statement that also retrieves 10% of the rows from the table, this time using column C3:

SELECT
  C1,
  C2,
  C3,
  C4,
  SUBSTR(C5,1,10) C5
FROM
  T1
WHERE
  C3=9;

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

For the above SQL statement, would you expect the optimizer to select the use of an index range scan operation, or a full table scan operation?  Here is the output that I received:

...
     99996          6          9 99996A AAAAAAAAAA
     99997          7          9 99997A AAAAAAAAAA
     99998          8          9 99998A AAAAAAAAAA
     99999          9          9 99999A AAAAAAAAAA

10000 rows selected.

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

PLAN_TABLE_OUTPUT
--------------------------------------------------------------------------
SQL_ID  4c1s2vujtc1ff, child number 0
-------------------------------------
SELECT   C1,   C2,   C3,   C4,   SUBSTR(C5,1,10) C5 FROM   T1 WHERE
C3=9

Plan hash value: 3617692013

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

Predicate Information (identified by operation id):
---------------------------------------------------
   1 - filter("C3"=9) 

So, once again the optimizer selected to use a full table scan to facilitate the retrieval of 10% of the rows from the table.  But why, the clustering factor should be reasonably low.  (Raise your hand if you know the answer why a full table scan was selected.)

But wait… the optimizer from another 11.2.0.2 database instance decided differently:

...
     99996          6          9 99996A AAAAAAAAAA
     99997          7          9 99997A AAAAAAAAAA
     99998          8          9 99998A AAAAAAAAAA
     99999          9          9 99999A AAAAAAAAAA

10000 rows selected.

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

PLAN_TABLE_OUTPUT
-----------------------------------------------------------------------------------------
SQL_ID  4c1s2vujtc1ff, child number 0
-------------------------------------
SELECT   C1,   C2,   C3,   C4,   SUBSTR(C5,1,10) C5 FROM   T1 WHERE
C3=9

Plan hash value: 1220227203

-----------------------------------------------------------------------------------------
| Id  | Operation                   | Name      | Rows  | Bytes | Cost (%CPU)| Time     |
-----------------------------------------------------------------------------------------
|   0 | SELECT STATEMENT            |           |       |       |   304 (100)|          |
|   1 |  TABLE ACCESS BY INDEX ROWID| T1        |  9091 |  1944K|   304   (1)| 00:00:02 |
|*  2 |   INDEX RANGE SCAN          | IND_T1_C3 |  9091 |       |    18   (0)| 00:00:01 |
-----------------------------------------------------------------------------------------

Predicate Information (identified by operation id):
---------------------------------------------------
   2 - access("C3"=9) 

Why did the optimizer in one of the 11.2.0.2 database instances select to use a full table scan operation, while the optimizer in the other database instance selected to use an index range scan operation?  (Raise your hand if you know the answer why there is a difference between the two execution plan results.)

If we take another look at the execution plan for the SQL statement that simulates the problem experienced by the OP, I wonder if we are able to determine why the parent operation has a lower calculated cost than its child (or grandchild’s) calculated cost?

SELECT /*+ GATHER_PLAN_STATISTICS */
  *
FROM
  T1
WHERE
  C4='';

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

Let’s take a look at the output of the above:

no rows selected

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

PLAN_TABLE_OUTPUT
----------------------------------------------------------------------------------------
SQL_ID  63yz0tn58sz4v, child number 0
-------------------------------------
SELECT /*+ GATHER_PLAN_STATISTICS */   * FROM   T1 WHERE   C4=''

Plan hash value: 3332582666

----------------------------------------------------------------------------------------
| Id  | Operation          | Name | Starts | E-Rows | Cost (%CPU)| A-Rows |   A-Time   |
----------------------------------------------------------------------------------------
|   0 | SELECT STATEMENT   |      |      1 |        |     1 (100)|      0 |00:00:00.01 |
|*  1 |  FILTER            |      |      1 |        |            |      0 |00:00:00.01 |
|   2 |   TABLE ACCESS FULL| T1   |      0 |    100K|   252   (1)|      0 |00:00:00.01 |
----------------------------------------------------------------------------------------

Predicate Information (identified by operation id):
---------------------------------------------------
   1 - filter(NULL IS NOT NULL) 

Do you see it?  Does it matter if a full table scan of table T1 was selected by the optimizer?   (Raise your hand if you know the answer.)

What if we force an index access path:

SELECT /*+ GATHER_PLAN_STATISTICS INDEX(T1) */
  *
FROM
  T1
WHERE
  C4='';

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

Here is the output of the above:

no rows selected

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

PLAN_TABLE_OUTPUT
-------------------------------------------------------------------------------------------------------
SQL_ID  06ucccd8j8ss0, child number 0
-------------------------------------
SELECT /*+ GATHER_PLAN_STATISTICS INDEX(T1) */   * FROM   T1 WHERE
C4=''

Plan hash value: 1158503954

-------------------------------------------------------------------------------------------------------
| Id  | Operation                    | Name      | Starts | E-Rows | Cost (%CPU)| A-Rows |   A-Time   |
-------------------------------------------------------------------------------------------------------
|   0 | SELECT STATEMENT             |           |      1 |        |     1 (100)|      0 |00:00:00.01 |
|*  1 |  FILTER                      |           |      1 |        |            |      0 |00:00:00.01 |
|   2 |   TABLE ACCESS BY INDEX ROWID| T1        |      0 |    100K|  3323   (1)|      0 |00:00:00.01 |
|   3 |    INDEX FULL SCAN           | IND_T1_C3 |      0 |    100K|   196   (1)|      0 |00:00:00.01 |
-------------------------------------------------------------------------------------------------------

Predicate Information (identified by operation id):
---------------------------------------------------
   1 - filter(NULL IS NOT NULL) 

Is the above execution plan even legal because the SQL statement is essentially looking for NULL values?  (Raise your hand if you know the answer.)

—-

OK, put down your hand – the other people in the office are probably laughing at your hand-waving by now.  ;-)

I wonder if the OP now understands the problem with his SQL statement?

—–

Late Addition June 20, 2012:

Recall that the optimizer selected that a full table scan should be used for the initial SELECT statement.  Part 2 of a previous blog article on this blog pointed to an article on another blog, asking whether or not a couple of statements made on the other blog were true regarding whether or not NULL values were ever stored in a B*tree index structure.  One of my previous articles seemed to offer a counter-point, that in fact it is possible for a B*tree index to contain NULL values in certain situations.

What might happen if we swap in a bind variable in place of the literal in the initial SELECT statement?  If we set the bind variable to have a value of (the same value as the literal), will the optimizer select to use a full table scan operation or an index range scan operation?  Will the STARTS column in the execution plan contain 0 for one or more of the rows in the execution plan?  Let’s test:

VARIABLE V1 VARCHAR2
EXEC :V1:=''
 
SELECT /*+ GATHER_PLAN_STATISTICS */
  *
FROM
  T1
WHERE
  C4= :V1;
 
SELECT * FROM TABLE(DBMS_XPLAN.DISPLAY_CURSOR(NULL,NULL,'ALLSTATS LAST +COST')); 

Here is the output:

no rows selected
 
SQL>
SQL> SELECT * FROM TABLE(DBMS_XPLAN.DISPLAY_CURSOR(NULL,NULL,'ALLSTATS LAST +COST'));
 
PLAN_TABLE_OUTPUT
------------------------------------------------------------------------------------------------------
SQL_ID  c4faj4cgbdrw1, child number 0
-------------------------------------
SELECT /*+ GATHER_PLAN_STATISTICS */   * FROM   T1 WHERE   C4= :V1
 
Plan hash value: 7035821
 
------------------------------------------------------------------------------------------------------
| Id  | Operation                   | Name      | Starts | E-Rows | Cost (%CPU)| A-Rows |   A-Time   |
------------------------------------------------------------------------------------------------------
|   0 | SELECT STATEMENT            |           |      1 |        |     2 (100)|      0 |00:00:00.01 |
|   1 |  TABLE ACCESS BY INDEX ROWID| T1        |      1 |      1 |     2   (0)|      0 |00:00:00.01 |
|*  2 |   INDEX RANGE SCAN          | IND_T1_C4 |      1 |      1 |     1   (0)|      0 |00:00:00.01 |
------------------------------------------------------------------------------------------------------
 
Predicate Information (identified by operation id):
---------------------------------------------------
   2 - access("C4"=:V1)

Notice that none of the rows in the execution plan have a STARTS value of 0, and that filter(NULL IS NOT NULL) does not appear in the Predicate Information section of the execution plan as had happened when we used a literal with the same value as the bind variable.  So, if the OP would like to see an index access path in the execution plan, perhaps he should use bind variables rather than literals?  Is the above execution plan more efficient or less efficient than the execution plan with the full table scan operation that was seen when a literal was passed in the SQL statement?

Let’s insert a row into table T4 with our bind variable value being placed in column C4:

INSERT INTO T1 VALUES(
  -1,
  -1,
  -1,
  :V1,
  'A');
 
COMMIT;
 
SELECT /*+ GATHER_PLAN_STATISTICS  FIND_ME */
  *
FROM
  T1
WHERE
  C4= :V1;
  
SELECT * FROM TABLE(DBMS_XPLAN.DISPLAY_CURSOR(NULL,NULL,'ALLSTATS LAST +COST'));

Will a row be returned?  Will the execution plan change?  Here is the output for the above script:

no rows selected
 
SQL>
SQL> SELECT * FROM TABLE(DBMS_XPLAN.DISPLAY_CURSOR(NULL,NULL,'ALLSTATS LAST +COST'));
 
PLAN_TABLE_OUTPUT
------------------------------------------------------------------------------------------------------
SQL_ID  csmkq5csd6f0a, child number 0
-------------------------------------
SELECT /*+ GATHER_PLAN_STATISTICS  FIND_ME */   * FROM   T1 WHERE   C4=
:V1
 
Plan hash value: 7035821
 
------------------------------------------------------------------------------------------------------
| Id  | Operation                   | Name      | Starts | E-Rows | Cost (%CPU)| A-Rows |   A-Time   |
------------------------------------------------------------------------------------------------------
|   0 | SELECT STATEMENT            |           |      1 |        |     2 (100)|      0 |00:00:00.01 |
|   1 |  TABLE ACCESS BY INDEX ROWID| T1        |      1 |      1 |     2   (0)|      0 |00:00:00.01 |
|*  2 |   INDEX RANGE SCAN          | IND_T1_C4 |      1 |      1 |     1   (0)|      0 |00:00:00.01 |
------------------------------------------------------------------------------------------------------
 
Predicate Information (identified by operation id):
---------------------------------------------------
   2 - access("C4"=:V1)

No rows selected, even though a row was just inserted into the table with the same value  as what is in bind variable V1.  Let’s DUMP the values of a couple of columns from the row that was just inserted:

COLUMN DUMP_C1 FORMAT A25
COLUMN DUMP_C4 FORMAT A25
 
SELECT
  C1,
  DUMP(C1) DUMP_C1,
  C4,
  DUMP(C4) DUMP_C4
FROM
  T1
WHERE
  C1=-1;
 
        C1 DUMP_C1                   C4     DUMP_C4
---------- ------------------------- ------ -------------------------
        -1 Typ=2 Len=3: 62,100,102          NULL

The above output shows that column C4 of this row contains a NULL value.  I suggest that it might not matter whether or not the execution plan shows an index access path or a full table scan for this SQL statement – if the SQL statement is answering a different question than what the OP expects, then it does not matter whether or not the SQL statement executes efficiently.

However, as a bonus we were able to see the optimizer using an index access path to check for a NULL value.





SQL Challenges

14 06 2012

June 14, 2012

Dominic Delmolino put together a very interesting challenge.  The challenge is to produce something called a Pascal matrix using Oracle Database… more specifically, just SQL.  I had a vague recollection of Pascal matrixes when I read Dominic’s challenge.  Basically, the goal is to create a matrix similar to the following:

The rule for generating the matrix is simply that a cell’s value is the sum of the value in the cell that is immediately to the left plus the value in the cell that is immediately above.  Sounds easy, right?

If we were just working in Microsoft Excel (or some other spreadsheet package), we could do something like this to quickly create the matrix:

Dominic’s challenge probably would not be much of a challenge if we could just type in formulas like the above into a SQL statement.  Give his challenge a try to see if you are able to derive a unique solution to the problem.  I probably spent a couple of minutes (maybe 60 seconds with the help of copy and paste) creating the above example using Microsoft Excel, but spent a couple of hours trying to produce a solution that worked using SQL.

——

Part 2 of the challenge.

Take a look at the bullet point items in this blog article about NULL values in table’s columns, in particular the first three large bullet point items.  Do you agree or disagree with the statements, and why?





Execution Plan Changes when the OPTIMIZER_FEATURES_ENABLED Parameter is Changed, But Why?

30 05 2012

May 30, 2012

A question appeared on the OTN Database forums yesterday that has yet to receive an answer.  The question was essentially, why did the execution plan change when the OPTIMIZER_FEATURES_ENABLED parameter was adjusted from 11.2.0.2 to 11.1.0.7, and why did the execution performance improve as a result of making the change?  A DBMS_XPLAN generated execution plan where TYPICAL +OUTLINE were apparently specified for the format parameters was provided for the execution with the OPTIMIZER_FEATURES_ENABLED parameter set to 11.2.0.2, while the format parameter was apparently set to ALLSTATS LAST for the 11.1.0.7 test execution.  Why did the performance improve when the optimizer’s parameter was modified?

We do not have access to the SQL statement, but we do have a few clues.  Take a look at the Predicate Information section, you will see the following:

1 - filter(ROWNUM<=1000)

So, ROWNUM<=1000 was specified in the SQL statement.  As mentioned in one of my other articles, there was a bug in the optimizer’s code prior to Oracle Database 11.2.0.1 related to the appearance of ROWNUM in the WHERE clause.  Would changing the  OPTIMIZER_FEATURES_ENABLED parameter to 11.1.0.7 reinstate the bug (this would not happen based on testing that I performed some time ago)?  The OP stated that the OPTIMIZER_MODE parameter is set to FIRST_ROWS_10, could specifying ROWNUM<=1000 cause the optimizer to behave as if FIRST_ROWS_1000 was set for the optimizer mode, behaving differently depending on the value of the OPTIMIZER_FEATURES_ENABLED parameter?

What other clues did the OP provide for potential readers of the OTN thread?  Let’s take a look at a portion of the outline sections supplied with the execution plans to see if there are any clues.  With OPTIMIZER_FEATURES_ENABLED set to 11.2.0.2:

OPTIMIZER_FEATURES_ENABLE('11.2.0.2')
DB_VERSION('11.2.0.2')
OPT_PARAM('_push_join_union_view' 'false')
OPT_PARAM('_optim_peek_user_binds' 'false')
OPT_PARAM('_gby_hash_aggregation_enabled' 'false')
OPT_PARAM('optimizer_index_cost_adj' 10)
OPT_PARAM('optimizer_index_caching' 80)
FIRST_ROWS(10)

With OPTIMIZER_FEATURES_ENABLED set to 11.1.0.7:

OPTIMIZER_FEATURES_ENABLE('11.1.0.7')
DB_VERSION('11.2.0.2')
OPT_PARAM('_optim_peek_user_binds' 'false')
OPT_PARAM('optimizer_index_cost_adj' 10)
OPT_PARAM('optimizer_index_caching' 80)
FIRST_ROWS(10)

Well, that is a bit interesting.  The OPTIMIZER_INDEX_COST_ADJ parameter was set to 10 in both cases, and the OPTIMIZER_INDEX_CACHING parameter was set to 80 in both cases – could the change in the execution plan be caused by a cost rounding error that is somehow slightly different when the OPTIMIZER_FEATURES_ENABLED parameter is changed?

While we are looking at the outline sections, notice that in the test with the OPTIMIZER_FEATURES_ENABLED parameter set at 11.2.0.2 that the _OPTIM_PEEK_USER_BINDS, _PUSH_JOIN_UNION_VIEW, and _GBY_HASH_AGGREGATION_ENABLED hidden parameters are all set at the non-default value of FALSE, while the test with the OPTIMIZER_FEATURES_ENABLED parameter set at 11.1.0.7 only shows that the _OPTIM_PEEK_USER_BINDS parameter is set to the non-default value of FALSE – could that difference cause of the execution plan change, and might those two hidden parameters magically change back to their default values when adjusting the OPTIMIZER_FEATURES_ENABLED parameter?

The OP did not supply a test case script, so I will create a simple test case script just to see if those two hidden parameters might magically change back to their default values when the  OPTIMIZER_FEATURES_ENABLED parameter is adjusted.

DROP TABLE T1 PURGE;

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') 

SET PAGESIZE 1000
SET LINESIZE 140

It appears that the OP had the following parameters set for the execution at 11.2.0.2:

ALTER SESSION SET "_push_join_union_view"=false;
ALTER SESSION SET "_optim_peek_user_binds"=false;
ALTER SESSION SET "_gby_hash_aggregation_enabled"=false;
ALTER SESSION SET optimizer_index_cost_adj=10;
ALTER SESSION SET optimizer_index_caching=80;
ALTER SESSION SET OPTIMIZER_MODE=FIRST_ROWS_10;

Let’s try a test script (note that you may wish to change the event 10132 to 10053, because the output of the 10132 trace event seems to be a bit scrambled in Oracle Database 11.2.0.2):

ALTER SESSION SET OPTIMIZER_FEATURES_ENABLE='11.2.0.2';
ALTER SESSION SET TRACEFILE_IDENTIFIER='11.2.0.2 HIDDEN TEST';
ALTER SESSION SET EVENTS '10132 TRACE NAME CONTEXT FOREVER, LEVEL 1';

SELECT
  *
FROM
  T1
WHERE
  ROWNUM<=1000
  AND C2=2
  AND C1>=1;

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

ALTER SESSION SET OPTIMIZER_FEATURES_ENABLE='11.1.0.7';
ALTER SESSION SET TRACEFILE_IDENTIFIER='11.1.0.7 HIDDEN TEST';

SELECT
  *
FROM
  T1
WHERE
  ROWNUM<=1000
  AND C2=2
  AND C1>=1;

SELECT * FROM TABLE(DBMS_XPLAN.DISPLAY_CURSOR(NULL,NULL,'+OUTLINE'));
ALTER SESSION SET EVENTS '10132 TRACE NAME CONTEXT OFF';

Here is the output that I received for 11.2.0.2:

SQL> SELECT
  2    *
  3  FROM
  4    T1
  5  WHERE
  6    ROWNUM<=1000
  7    AND C2=2
  8    AND C1>=1;

no rows selected

SQL> SELECT * FROM TABLE(DBMS_XPLAN.DISPLAY_CURSOR(NULL,NULL,'+OUTLINE'));

PLAN_TABLE_OUTPUT
------------------------------------------------------------------------------------------
SQL_ID  fb2ysnjkbq366, child number 0
-------------------------------------
SELECT   * FROM   T1 WHERE   ROWNUM<=1000   AND C2=2   AND C1>=1

Plan hash value: 1016793414

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

Outline Data
-------------
  /*+
      BEGIN_OUTLINE_DATA
      IGNORE_OPTIM_EMBEDDED_HINTS
      OPTIMIZER_FEATURES_ENABLE('11.2.0.2')
      DB_VERSION('11.2.0.2')
      OPT_PARAM('_push_join_union_view' 'false')
      OPT_PARAM('_optim_peek_user_binds' 'false')
      OPT_PARAM('_gby_hash_aggregation_enabled' 'false')
      OPT_PARAM('optimizer_index_cost_adj' 10)
      OPT_PARAM('optimizer_index_caching' 80)
      FIRST_ROWS(10)
      OUTLINE_LEAF(@"SEL$1")
      INDEX_RS_ASC(@"SEL$1" "T1"@"SEL$1" ("T1"."C2"))
      END_OUTLINE_DATA
  */

Predicate Information (identified by operation id):
---------------------------------------------------
   1 - filter(ROWNUM<=1000)
   2 - filter("C1">=1)
   3 - access("C2"=2) 

The output for 11.1.0.7:

SQL_ID  fb2ysnjkbq366, child number 1
-------------------------------------
SELECT   * FROM   T1 WHERE   ROWNUM<=1000   AND C2=2   AND C1>=1

Plan hash value: 1016793414

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

Outline Data
-------------
  /*+
      BEGIN_OUTLINE_DATA
      IGNORE_OPTIM_EMBEDDED_HINTS
      OPTIMIZER_FEATURES_ENABLE('11.1.0.7')
      DB_VERSION('11.2.0.2')
      OPT_PARAM('_push_join_union_view' 'false')
      OPT_PARAM('_optim_peek_user_binds' 'false')
      OPT_PARAM('_gby_hash_aggregation_enabled' 'false')
      OPT_PARAM('optimizer_index_cost_adj' 10)
      OPT_PARAM('optimizer_index_caching' 80)
      FIRST_ROWS(10)
      OUTLINE_LEAF(@"SEL$1")
      INDEX_RS_ASC(@"SEL$1" "T1"@"SEL$1" ("T1"."C2"))
      END_OUTLINE_DATA
  */

Predicate Information (identified by operation id):
---------------------------------------------------
   1 - filter(ROWNUM<=1000)
   2 - filter("C1">=1)
   3 - access("C2"=2) 

How would you answer the OP?  Could it just be the case that most of the required database blocks were in the buffer cache on the second execution when the OPTIMIZER_FEATURES_ENABLED parameter was adjusted?  If nothing else, this OTN thread provides an excuse to think about possible causes and effects when insufficient information is provided.





TKPROF Elapsed Time Challenge – the Elapsed Time is Half of the Wait Event Time

20 05 2012

May 20, 2012

An interesting quirk was recently brought to my attention by Mich Talebzadeh.  He generated a 10046 trace at level 8 for a session, executed some SQL statements, disabled the trace, and then processed the resulting trace file with TKPROF.  His TKPROF output included the following:

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 

Mich noticed that the reported elapsed time, at 1,245.41 seconds, is less than the sum of the wait event times, at 2,400.00 seconds.  Typically, the sum of the wait events plus the CPU time should be equal to or slightly less than the elapsed time (assuming that parallel query is not used, and the CPU reporting granularity did not cause odd side effects, and the session’s process did not spend much time in the CPU run queue).  In this case, the elapsed time is about 51.9% of the wait event time for this SQL statement. 

How is this possible?  Mich stated the following:

“A comment has been it is due to using different clock granularities.”

Think about that for a minute – what could explain the odd inconsistency in the output?

I recall reading in the book “Optimizing Oracle Performance” about double-counting of statistics due to recursive database calls.  Page 92 of that book includes the following quote:

“In Oracle releases through at least Oracle9i Release 2, a database call’s c, e, p, cr, and cu statistics contain an aggregation of the resources consumed by the database call itself and its entire recursive progeny.”

Page 91 of the same book makes the following statement:

“The rule for determining the recursive relationships among database calls is simple:
A database call with dep=n + 1 is the recursive child of the first subsequent dep=n database call listed in the SQL trace data stream.”

Could it be the case that this particular issue with recursive calls was addressed in later releases of TKPROF?  Might that fix explain why the elapsed time is 51.9% of the wait event time?

The OP provided a partial test case script with a description of how the tables were created.  I reduced the size of the original source table from 1,700,000 rows to 60,000 rows, and reduced the secondary source table from 1,000,000 rows to 50,000 rows.  My test script follows (note that the line that builds the IND_T2_OBJ index is commented out – we will change that later):

DROP TABLE T1 PURGE;
DROP TABLE T2 PURGE;

CREATE TABLE T1 AS
SELECT
  *
FROM
  ALL_OBJECTS
WHERE
  ROWNUM<=60000;

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

CREATE TABLE T2 AS
SELECT
  *
FROM
  T1
WHERE
  ROWNUM<=50000;

CREATE UNIQUE INDEX IND_T1_OBJ ON T1(OBJECT_ID);
--CREATE UNIQUE INDEX IND_T2_OBJ ON T2(OBJECT_ID);

ALTER SYSTEM FLUSH SHARED_POOL;

ALTER SYSTEM FLUSH BUFFER_CACHE;
ALTER SYSTEM FLUSH BUFFER_CACHE;

EXEC DBMS_MONITOR.SESSION_TRACE_ENABLE ( waits=>true, plan_stat=>'ALL_EXECUTIONS' );

DECLARE
        type ObjIdArray is table of T1.object_id%TYPE index by binary_integer;
        l_ids objIdArray;
        CURSOR c IS SELECT object_id FROM T1;
BEGIN
        OPEN c;
        LOOP
                BEGIN
                        FETCH c BULK COLLECT INTO l_ids LIMIT 100;

                        FORALL rs in 1 .. l_ids.COUNT
                                UPDATE T2
                                  SET PADDING1 =  RPAD('y',4000,'y')
                                WHERE object_id = l_ids(rs);
                        commit;
                        FORALL rs in 1 .. l_ids.COUNT
                                DELETE FROM T2
                                WHERE object_id = l_ids(rs);
                        commit;
                        FORALL rs in 1 .. l_ids.COUNT
                                INSERT INTO T2
                                SELECT * FROM T1 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;
/

EXEC DBMS_MONITOR.SESSION_TRACE_DISABLE;

That test case definitely contains calls in the trace file at a dep greater than zero.  As a matter of fact, the SQL statement of interest is at a dep of one, resulting in space management (and other calls) at a dep of two or greater:

PARSING IN CURSOR #397285536 len=66 dep=1 uid=64 oct=6 lid=64 tim=1879257875778 hv=3592437181 ad='3edea5858' sqlid='1ahnbczb20gdx'
UPDATE T2 SET PADDING1 = RPAD('y',4000,'y') WHERE OBJECT_ID = :B1 
END OF STMT
PARSE #397285536:c=0,e=169,p=0,cr=0,cu=0,mis=1,r=0,dep=1,og=1,plh=0,tim=1879257875778

I executed the test case script on 64 bit Windows with Oracle Database 11.2.0.2 with patch 5 installed.  I processed the resulting trace file with TKPROF from the 32 bit Windows Oracle 11.2.0.1 client with the ODBC update patch 10155837 installed.  My TKPROF output for the UPDATE statement showed the following:

SQL ID: 1ahnbczb20gdx
Plan Hash: 2722410703
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    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

I decided to compare the output of TKPROF with the output of my Hyper-Extended Oracle Performance Monitor program, which I know does not attempt to resolve parent and child recursive statistics:

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

Notice that the TKPROF summary shows 0.059011 fewer elapsed seconds for this SQL statement, 0.023668 fewer CPU seconds, 322 fewer blocks read from disk, 437 fewer consistent gets, and the same number of current mode reads.  Why the differences?

My program wrote the wait event details for the UPDATE statement to an Excel spreadsheet.  Examination of the wait events indicated that there were 36 db file sequential read waits (thus 36 total blocks read from disk), and 31 db file scattered read waits (416 total blocks read from disk) – the wait event details support the statistics output by TKPROF.  So, maybe the double counting of recursive calls was fixed since the release of Oracle Database 9.2.  Nice!  But we are not done yet, we still do not have the index on table T2, as was described by the OP.

Locate in the script the following line:

--CREATE UNIQUE INDEX IND_T2_OBJ ON T2(OBJECT_ID);

Change that line by removing the at the start of the line, so that the line appears like this:

CREATE UNIQUE INDEX IND_T2_OBJ ON T2(OBJECT_ID);

Disconnect from the database, then reconnect (so that you will be assigned a different default trace filename).  Now, re-execute the script, and process the resulting trace file with TKPROF.  My TKPROF output for the UPDATE SQL statement looks like this:

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
...
         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
  log file switch completion                      2        0.00          0.01

For the sake of comparison, I also processed the trace file using my Hyper-Extended Oracle Performance Monitor program.  This is my program’s output:

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=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 that there is now a significant difference in the elapsed time at 2.263344 seconds difference, CPU seconds at a difference of 2.253618 seconds, and the number of blocks read from disk at a difference of 564 blocks.

Let’s take a look at the wait events that my program wrote to Excel.   Examination of the wait events indicated that there were 42 db file sequential read waits (thus 42 total blocks read from disk), and 107 db file scattered read waits (842 total blocks read from disk), for a grand total of 884 blocks read from disk that are associated with this UPDATE SQL statement.  This time, not only are the TKPROF statistics not supported by the raw wait events, but the wait event summary included in the TKPROF summary also is not supported by the raw wait events.  Where did those number from TKPROF originate?

Well, let’s just process the 10046 trace file using TKPROF from 11.2.0.2 to confirm the output:

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    600      3.57       3.64        884     144451     426496       50000
Fetch        0      0.00       0.00          0          0          0           0
------- ------  -------- ---------- ---------- ---------- ----------  ----------
total      601      3.57       3.64        884     144451     426496       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: 600

Rows (1st) Rows (avg) Rows (max)  Row Source Operation
---------- ---------- ----------  ---------------------------------------------------
         0          0          0  UPDATE  T2 (cr=241 pr=1 pw=0 time=5550 us)
       100         83        100   INDEX UNIQUE SCAN IND_T2_OBJ (cr=106 pr=0 pw=0 time=425 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                        107        0.00          0.06
  db file sequential read                        42        0.00          0.01
  log file switch completion                      2        0.00          0.01

-

Those TKPROF numbers appear quite different; translation – it you do not like the numbers produced by TKPROF, just use a different version of TKPROF.  :-)

It appears that TKPROF in 11.2.0.1 potentially lies when reporting on a trace file generated by Oracle Database 11.2.0.2.  I wonder if this problem is caused by the large cursor number in 11.2.0.2+, or if TKPROF in 11.2.0.1 also has the same problem with trace files generated by Oracle Database 11.2.0.1?

Is anyone able to reproduce the problem reported by the OP?

If you wish to experiment with my trace file and TKPROF summaries, you may download the following file:

or1122p_ora_1808.zip

When you download the file, rename the download from or1122p_ora_1808-zip.doc to or1122p_ora_1808.zip.  The enclosed or1122p_ora_1808.trc file is the raw 10446 trace file, or1122p_ora_1808.txt is the 11.2.0.1 TKPROF generated output file, and or1122p_ora_1808-2.txt is the 11.2.0.2 generated output file.





On the Topic of Technology… 4

7 05 2012

May 7, 2012

(Back to the Previous Post in the Series) (Forward to the Next Post in the Series)

Today’s blog article has an unusual tie in with Oracle.

The last couple of weeks I have been experimenting with video technology.  Computer related video capabilities have certainly changed over the years.  In 1996 I purchased a Sony Handicam and a Video Snappy.  The Sony video camera was capable of recording video with about 480 lines of resolution (NTSC standard) with a 10x optical zoom and recording capability in just 0.6 LUX of lighting.  The Video Snappy plugs into a computer’s parallel (old style printer) port, connects to the Sony video camera by an RCA style video cable, and converts the live video feed from the video camera to still photos.  Combined with a 120MHz Pentium processor, it seemed to be a state-of-the-art setup at the time (of course ignoring the capabilities of the Commodore Amiga/Newtek Video Toaster).  A picture of the Sony/Snappy configuration is shown below.

Of course the video capabilies of current tablets, cell phones, and digital cameras far exceed what was available in the 1990s – video recording with those devices was described in the previous blog article in this series (see the link at the top of this article).

A product that I recently found is the Synology DiskStation DS212+, which has some remarkable features considering that its primary objective is to provide an external hard drive array with RAID 1.  This particular unit ships without hard drives, so I purchased two Western Digital 2TB Green hard drives.  The external hard drive enclosure includes an SD media card reader, a single USB 2 port, two USB 3 ports, and an ESATA port to allow connecting additional external hard drives, printers, and wireless cards.  While not much larger than the hard drives installed in the unit, it certainly offers much more than access to those drives.  The DS212+ offers FTP services (including secure FTP), an iSCSI interface, DHCP services, media sharing services, WordPress, MySQL, PHP, a remarkable operating system that fully renders console screens in a web browser without the use of Adobe Flash (uses HTML 5 and CSS 3), and more.

The Synology DiskStation DS212 line’s disk throughput is limited by a combination of CPU performance and gigabit network maximum transfer speed, with the DS212+ offering the fastest rated transfer speed of roughly 108 MB/s read (very close to the maximum speed of gigabit Ethernet) and 66 MB/s write.  The Synology DS212+ is pictured below, measuring roughly the same height as five books on the topic of Oracle Database.

So, what does the first picture have in common with the second?  More about that commonality later.

Below is a screen capture of the Synology DS212+ operating system GUI (graphical user interface) rendered in Internet Explorer 9, roughly 21 minutes after powering on the unit for the first time and installing the latest version of the operating system.  As seen below, the 2TB drives were 84% formatted roughly six and a half minutes after I connected for the first time (a verify process lasting several hours started immediately after the format, but the hard drives were accessible during this verify process).

The operating system renders resizable, movable, drag and drop capable, right-clickable windows within the web page.  Several of the free optional packages for the DS212+; a resource meter showing CPU, memory, and network utilization; current network connections; and recent log entries are shown in the picture below.

So, what function does the DS212+ serve other than consuming electricity?  That is still a question that I am trying to answer, but I have only had access to the system for a couple of days.  I installed several of the free optional packages (after downloading the latest version from the company’s website), and experimented a bit.  The screen capture below shows the DS212+ playing an Internet radio stream (the channel was essentially selected at random), while simultaneously playing back a 640 pixel by 480 pixel video.

Incidentally, the above video was captured in a completely dark room using infrared lights that are built into the video camera.

As I mentioned at the beginning of this article, over the last couple of weeks I have spent a bit of time working with video technology.  Pictured below are two TriVision NC-107WF video cameras and a SanDisk 32GB micro SD memory card that works with the cameras.  I have also worked with a couple of TriVision NC-107W video cameras, which lack an infrared cut filter, resulting in poor color rendering.

So, what has 16 years of technology progress provided, comparing to the Sony Handycam shown at the start of this article?  The camera shown below records video at 640 pixels by 480 pixels, much like the Sony Handycam, so that feature has not improved much.  The TriVision camera digitally records nearly a month’s worth of video to a memory card that is about the size of a thumbnail, while the Sony Hanycam digitally records between a half hour and two hours of video to a tape that is about the size of an average person’s fist.  The TriVision camera records black and white video in complete darkness due to its built in infrared lights, while the Sony Handycam records excellent completely black videos in the same lighting conditions.

Surprisingly, there are no reviews of the TriVision line of cameras on Amazon.  The cameras appear to be a clone of the (Amazon) highly rated Sharx Security brand of security cameras.  Unlike some of the other security cameras on the market, this camera ships with a well written user manual (with only a small number of typos).  Offering motion detection, support of up to 32 GB of storage, automatic upload of video and still photos to an FTP server, live streaming through desktop web browsers and mobile devices, and a handful of other capabilities, it is hard to believe just how much technology is stuffed into such a small package.  The wireless range when paired with a Cisco 1250 series access point is impressive, but not terribly impressive when paired with a consumer grade Linksys/Cisco wireless router with integrated antennas.  Poor wireless performance is not necessarily a problem, since the camera stores recorded video to the memory card until the specified FTP server is accessible.  The cameras ship with Multi-live software that permits simultaneous viewing and recording of up to 36 cameras directly from the video streams, which is helpful if an FTP server is not configured.

Reliability of the TriVision NC-107WF/NC-107W cameras is still an unknown.  I have experienced occasional glitches accessing the built-in web server, making it impossible to adjust the camera settings (power cycling the camera seems to correct this issue), however those glitches apparently do not affect video recording or uploading of the captured video to FTP servers.

I have also spent a bit of time working with TriVision’s NC-306W outdoor wireless video cameras, which are shown in the picture below.  The NC-306W camera appears to be a clone of the (Amazon) highly rated Sharx video camera.  The web-based configuration of the NC-306W is nearly identical to that of the NC-107WF.  A 32GB memory card with automatic FTP uploading is supported, as is two-way audio (the NC-107WF supports one-way audio).

Since there are no reviews of the Trivision NC-306W, it is difficult to determine the long-term reliability of this camera.  During installation, one of the mounting nuts snapped due to over-torquing, but that nut is only needed for overhead mounting as seen in the picture below (the mounting nut is attached directly between the sun shield at the top of the camera and the white colored dial at the end of the mounting rod).  As with the TriVision NC-107WF/NC-107W cameras, the built-in web server has occasionally stopped responding, but that problem has not affected video capture or FTP upload.

Below is a screen capture of a video stream from a TriVision NC-107WF camera.  The original video quality was slightly better than pictured below (conversion of the screen capture to JPG format caused some detail loss).  The same scene captured by a TriVision NC-107W camera would have a pink, purple, or red cast due to the presence of infrared light (the NC-107WF and NC-306W are able to selectively filter out the infrared light).

I had hoped to upload a couple of videos captured by the cameras, however, WordPress apparently does not support directly uploaded video formats.  I plan to update this blog article as I better understand all of the features that the Synology Diskstation DS212+ offers, and to provide reliability updates of the DS212+ and the TriVision cameras.





Brain Teaser: 10046 Extended SQL Trace Shows a FETCH Call with c=306350000, e=299174653, p=0, cr=22298 – How is that Possible?

26 04 2012

April 26, 2012

Last week I posted a popular article that questioned the effectiveness of showing a job candidate a raw 10046 trace file that was captured at level 12, asking the job candidate to evaluate whether or not the SQL statement in the 10046 trace is efficient.  Many of the commenters suggested that the approach is potentially very effective if the interviewer is knowledgeable about the subject matter, and he recognizes that the question deserves more than a simple yes or no answer.

A year ago I posted a related article, a brain teaser in fact, that showed 0.015600 seconds of CPU consumption in 0.000510 seconds of elapsed time without using parallel execution.  The comments attached to last year’s article correctly identified the source of the seemingly impossible statistics.

A recent OTN thread (don’t click the link until you have thought about the problem for a while) shows an interesting section of a 10046 trace file, a portion of which appears below:

PARSE #2:c=0,e=4764,p=0,cr=0,cu=0,mis=0,r=0,dep=0,og=1,tim=1182070262719
BINDS #2:
EXEC #2:c=0,e=255,p=0,cr=0,cu=0,mis=0,r=0,dep=0,og=1,tim=1182070263378
WAIT #2: nam='SQL*Net message to client' ela= 5 driver id=1650815232 #bytes=1 p3=0 obj#=258 tim=1182070263514
FETCH #2:c=306350000,e=299174653,p=0,cr=22298,cu=0,mis=0,r=1,dep=0,og=1,tim=1182369438322
WAIT #2: nam='SQL*Net message from client' ela= 1454 driver id=1650815232 #bytes=1 p3=0 obj#=258 tim=1182369440799
WAIT #2: nam='SQL*Net message to client' ela= 4 driver id=1650815232 #bytes=1 p3=0 obj#=258 tim=1182369441012
FETCH #2:c=0,e=293,p=0,cr=0,cu=0,mis=0,r=15,dep=0,og=1,tim=1182369441265
WAIT #2: nam='SQL*Net message from client' ela= 7437 driver id=1650815232 #bytes=1 p3=0 obj#=258 tim=1182369448858
WAIT #2: nam='SQL*Net message to client' ela= 3 driver id=1650815232 #bytes=1 p3=0 obj#=258 tim=1182369449007
FETCH #2:c=0,e=283,p=0,cr=0,cu=0,mis=0,r=15,dep=0,og=1,tim=1182369449257
WAIT #2: nam='SQL*Net message from client' ela= 6701 driver id=1650815232 #bytes=1 p3=0 obj#=258 tim=1182369456082
WAIT #2: nam='SQL*Net message to client' ela= 2 driver id=1650815232 #bytes=1 p3=0 obj#=258 tim=1182369456222 

The interesting portion of the above trace file is the first FETCH line where a single row is returned to the client.  The c=306350000 entry indicates that 306.35 seconds of server CPU time was consumed during the fetch call.  The e=299174653 entry indicates that the elapsed time (as if captured by a stop watch) of the single row fetch was 299.174653 seconds.  The p=0 entry indicates that 0 blocks were physically read from disk when preparing to retrieve the one row.  The cr=22298 entry indicates that 22,298 consistent gets were performed when preparing to retrieve the first row.  Typically, performing a large number of consistent gets will result in the consumption of a considerable number of CPU seconds, yet 22,298 consistent gets could not explain the consumption of more than 5 minutes of CPU time, even if the OP was running Oracle Database on an Intel 8088 CPU.

The brain teaser posed (directly or indirectly) by the OP:

  1. Why did the first fetch of a single row require roughly 299 seconds of elapsed time, when the second fetch of 15 rows apparently required 0.000293 seconds?
  2. Why did the first fetch of a single row require roughly 306 seconds of CPU time, when the second fetch of 15 rows apparently required no CPU time?
  3. How is it possible that the CPU consumption exceeds the elapsed time by 7.175347 seconds?
  4. How is it possible that 306.35 seconds of CPU were burned while performing only 22,298 consistent gets?
  5. The trace file indicates that 306.35 seconds of CPU were burned during the first fetch call, does the number 306.35 represent 100% of the CPU consumption during the fetch call, or is the actual CPU consumption higher or lower than that number?
  6. What release version of Oracle Database is the OP running?
  7. What operating system is the OP using for Oracle Database?
  8. What other questions might you ask of a job candidate if the 10046 trace file from the OTN thread were handed to a job candidate during an interview?

Think about the questions for a couple of minutes before visiting the OTN thread.  Several of the above questions are answered in that thread.





Temporary Tablespace Storage Parameters – What is Wrong with this Quote

22 04 2012

April 22, 2012 (Modified April 24, 2012)

I had intended to finish assembling the second half of the “Oracle Database 11gR2 Performance Tuning Cookbook” book review, however my free time that may be dedicated to book reviews has been a bit limited lately (I have a review of another book started, but left untouched for the last three months).  On a side note, I am a little shocked that none of the 21 errata reports that I filed for the first 88 pages of the book made it onto the publisher’s website, but maybe that is not too uncommon (the same has happened for at least one Apress book). 

I encountered an interesting quote on page 252 of the “Oracle Database 11gR2 Performance Tuning Cookbook” that I thought I would share with readers:

“The PCTINCREASE parameter cannot be specified when we use the AUTOALLOCATE option for the tablespace. We can have different tablespaces for each database user and we can query the dynamic performance view V$SORT_USAGE to retrieve the details about the active disk sorts occurring in the instance.

We can obtain better performance by striping the temporary tablespace using multiple disks. Please note that – due to their nature – temporary tablespaces are not affected by backup and restore operations.”

If you own the book, start on page 251 and read through the end of page 252. – there are a couple of additional interesting sentences in this section of the book 

What, if anything, is wrong with the above quote from the book? For those readers that need some assistance with this task, the Oracle Database 11.2 documentation might be helpful.

The point of blog articles like this one is not to insult authors who have spent thousands of hours carefully constructing an accurate and helpful book, but instead to suggest that readers investigate when something stated does not exactly match what one believes to be true. It could be that the author “took a long walk down a short pier”, or that the author is revealing accurate information which simply cannot be found through other resources (and may in the process be directly contradicting information sources you have used in the past). If you do not investigate in such cases, you may lose an important opportunity to learn something that could prove to be extremely valuable.

(Added April 24, 2012, my book review notes for the four quoted sentences, plus one of the preceding sentences)

 

  • The book’s discussion of defining the INITIAL and NEXT storage parameters for temporary tablespaces as a multiple of the SORT_AREA_SIZE parameter seems to be out of place in an Oracle Database 11g R2 performance tuning book – dictionary managed tablespaces were deprecated with the release of Oracle Database 9.2, and the effect of these parameters is different in locally managed tablespaces (page 252).
  • The book states, “The PCTINCREASE parameter cannot be specified when we use the AUTOALLOCATE option for the tablespace.”  This statement appears to be incorrect – the Oracle Database documentation states that a specified value for PCTINCREASE will be ignored when creating an AUTOALLOCATE tablespace (page 252).
  • The book states, “We can have different tablespaces for each user and we can query the dynamic performance view V$SORT_USAGE to retrieve the details about the active disk sorts occurring in the instance.”  This statement is a bit confusing, so it is probably best to break the sentence into two separate logical sentences for analysis.  The first half of the statement seems to suggest that a separate temp tablespace should (or could) be created for each user – I am not sure that this is the author’s intended interpretation; the default temporary tablespace may be set at the user level so that not all users are required to use the same (default) temporary tablespace.  For the second logical sentence, the V$SORT_USAGE performance view was deprecated with the release of Oracle Database 9.2, replaced with V$TEMPSEG_USAGE.  In Oracle Database 11.2 (the version mentioned on the book’s front cover), the V$SORT_USAGE view is based on the GV$SORT_USAGE view which selects from X$KTSSO (confirm by issuing SELECT VIEW_DEFINITION FROM V$FIXED_VIEW_DEFINITION WHERE VIEW_NAME=’GV$SORT_USAGE';).  The GV$SORT_USAGE  view definition, which is pointed to by both the V$SORT_USAGE and V$TEMPSEG_USAGE synonyms, indicates that the SEGTYPE column values may be one of SORT, HASH, DATA, INDEX, LOB_ DATA, LOB_INDEX , or UNDEFINED.  The potential values of the SEGTYPE column suggests that the view potentially shows a variety of activity in addition to what the book mentions (the WHERE clause should be adapted to restrict the rows returned from this view, so that the results are consistent with this chapter’s contents).  The V$SORT_USAGE view also shows entries for aborted SQL statements, for instance when Ctrl-C is pressed in SQL*Plus and another SQL statement has not been executed by the session (page 252).
  • The book states, “Please note that – due to their nature – temporary tablespaces are not affected by backup and restore operations.”  This is a vague statement at best, and the accuracy of the statement depends in part on the type of backup performed (online or offline, user-managed or RMAN hot backup, etc.).  An online RMAN backup will not back up the tempfiles of locally managed temporary tablespaces; however, when those backed up databases are restored and recovered, Oracle Database 10.2 and later will recreate the temporary tablespace tempfiles when the database is opened (page 252).







Follow

Get every new post delivered to your Inbox.

Join 139 other followers