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.








Follow

Get every new post delivered to your Inbox.

Join 141 other followers