Building Oracle Database Test Case Scripts – Is there an Easy Method?

September 27, 2010

It is far too easy to invest many hours into building a test case to demonstrate or explore a simple concept, or model a particular problem that is being encountered.  I recently had the opportunity to attend a session by Jonathan Lewis that was titled “The Beginner’s Guide to Becoming an Expert”, a session which emphasized the use of test scripts to investigate various types of unexpected behavior, when that unexpected behavior is found.  Using examples from Jonathan’s session, that unexpected behavior might include noticing a reduction in the redo generated when an update statement is driven through an index access path, for instance.  Another example from Jonathan’s session included the unexpected behavior where a significant amount of redo is generated when a bitmap index is updated, compared to the amount of redo generated when a b*tree index on the same column is updated, and then finding that the amount of redo generated for the bitmap index drops significantly when the Oracle Database is upgraded from 9.2 to 11.1.  Creating a test script that models a particular situation allows that problem to be investigated in isolation, and then repeatedly analyzed as one variable is changed at a time – the change might include modifying an initialization parameter, submission of different initial bind variables, execution of the script against a different Oracle Database release version, or any number of other small scale changes.

One of the key concepts in the creation of test cases is to compare the intended end result of the test case with the starting point, and then identify logical transformation stages between the two end points.  At each transformation stage confirm that the preceding step logically leads to the next step, and then determine if there is any chance that a different result might be obtained given the same input.  Work backward from the last transformation stage to the first, and ask yourself if there is any other possible input that might have caused the outcome.  It takes practice, a fair amount of research, and sometimes trial and error to discover the multiple potential cause and effect relationships.

I recently used this technique to build a test case for an OTN thread to discover why an index was not used to retrieve three rows from an 8 million row table.  The “given” information was that the index was used if an always false comparison of two literal VARCHAR values was removed from an OR condition in the WHERE clause.  The first step in building a test case, assuming that the production environment where the problem was found is not available for use, involves building a model of the source data.  If you are familiar with the real data that causes the unexpected behavior, build a model that simulates the real data, otherwise assume that the data to be returned is scattered among the other rows in the table data.  In my test case, to simplify the calculations a bit, the number of rows to be inserted into the test table was increased to 10 million.  Before building the data model, determine what might cause a full table scan to be performed rather than using an index access path: high clustering factor for the index, poor cardinality estimates (might be caused by out of date object statistics), incorrectly gathered system statistics, poorly specified optimizer parameters, sub-optimal index definition (might require an index skip scan, or return a large number of rows that are later eliminated at the table level), optimizer bugs, maybe the full table scan really is faster than an index access path, etc.
 
Now that we have identified some of the causes for a full table scan, our test case may be used to experiment “what if” and “how would I know if that was the cause?”  To determine if the clustering factor was the problem, I might first need to know how the optimizer uses the clustering factor, and am I able to artificially adjust it to see if a change in the value makes a difference in performance.  To determine if the cardinality estimates are a problem I might use DBMS_XPLAN.DISPLAY_CURSOR to retrieve the estimated cardinality and actual number of rows returned by every operation in the execution plan.  I might remove the comparison of the two literal VARCHAR values to see how that change affects the cardinality estimates, or see if changing one of the literal values causes a change – one of those changes just might also allow an index access path to be used.  I might try to use a hint to force the use the index (hints are, after all, directives and not suggestions), and if that does not work I might analyze why the hint was invalid.  If the hint worked, after verifying that a performance improvement was achieved, I would likely consult a 10053 trace file to determine why the index access path was not automatically used – was the cost too high, or was the index access path cost not even calculated?

Once the cause of the full table scan is determined, additional what-if statements should be considered.  What if the index hint worked, am I able to permanently add that hint to the SQL statement – are there any cases were adding that hint might lead to other performance problems later?  If the cardinality estimates are incorrect, is there anything that I am able to do to fix the cardinality estimates?  If the optimizer parameters are poorly specified, am I able to adjust those parameters – and if I do what might be the impact on the other SQL statements that depend on the current initialization parameter values for optimal performance and costing calculations?  Are we able to modify the application that submitted the SQL statement to remove the unnecessary literal comparison?

Once the desired outcome is reached, work backward through the steps and determine where this approach might go wrong.  Is it reasonable to conclude that the previous step always results in the next step?  In short, test cases are not terribly difficult to construct once you learn what might cause a transformation step to simply lead to the wrong next transformation step.

Oracle Database behavior changes from one release version to another, and sometimes from one patch level to the next.  Save the test case scripts once generated, because the behavior that is demonstrated by the test script might only be true for a small number of Oracle Database releases.  My test case script for generating a deadlock on Oracle Database 11.1 and 11.2, while the same test case script simply generates an expected enqueue on Oracle Database 10.2, is just one example of the usefulness of test cases to demonstrate Oracle behavior.

Do we need a test case to determine why the OTN forums, if working at all, are so slow this morning?  I believe that it required more than two minutes just to display the forum home – that was roughly an hour after I saw the message stating that the OTN forums were down (someone must have tripped over the power cord again).

Any other ideas for easily creating useful test cases?

Test Case Showing Oracle Database 11.2.0.1 Completely Ignoring an Index Even when Hinted

September 22, 2010

In a recent OTN thread a person asked an interesting question: why isn’t my index being used?  A query of a table with 8,000,000 rows should quickly return exactly 3 rows when an available index is used, and that index is used when the WHERE clause is simply:

WHERE
  C200000020 LIKE 'BOSS' || '%' 

However, the application is submitting a WHERE clause that includes an impossible condition in an OR clause, like the following, which is not much different from stating OR 1=2:

WHERE
  C200000020 LIKE 'BOSS' || '%'
  OR 'BOSS' = ''

That constant1 = constant2 predicate, at least on Oracle Database 10.1 and above, is sufficient to keep the index from being used, thus the query performs a full table scan.  But why?

I think that we need a test case to see what is happening.  First, we will create a simple table with our column of interest and a large column that should help to discourage full table scans:

CREATE TABLE T1 (
  C200000020 VARCHAR2(20),
  PADDING VARCHAR2(250));

Next, we will insert 10,000,000 rows into the table such that an index built on the column C200000020 will have a very high clustering factor, and 3 rows will have a value that begins with BOSS (as a result of the DECODE statement):

INSERT INTO
  T1
SELECT
  DECODE(MOD(ROWNUM,3000000),0,'BOSS'||ROWNUM,
  CHR(90-MOD(ROWNUM-1,26))||
  CHR(75+MOD(ROWNUM,10))||
  CHR(80+MOD(ROWNUM,5))||
  'S'||ROWNUM) C200000020,
  RPAD('A',200,'A') PADDING
FROM
  (SELECT
    ROWNUM RN
  FROM
    DUAL
  CONNECT BY
    LEVEL<=10000) V1,
  (SELECT
    ROWNUM RN
  FROM
    DUAL
  CONNECT BY
    LEVEL<=1000) V2;

Now to create the index and collect statistics:

CREATE INDEX IND_T1 ON T1(C200000020);

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

Let’s take a look at the execution plans:

SET AUTOTRACE TRACEONLY EXPLAIN

SELECT
  *
FROM
  T1
WHERE
  C200000020 LIKE 'BOSS' || '%';

Plan hash value: 634656657

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

Predicate Information (identified by operation id):
---------------------------------------------------
   2 - access("C200000020" LIKE 'BOSS%')
       filter("C200000020" LIKE 'BOSS%')

An index access, just like we had hoped.  The optimizer is predicting a single row to be retrieved.  Let’s try the other query:

SELECT
  *
FROM
  T1
WHERE
  C200000020 LIKE 'BOSS' || '%'
  OR 'BOSS' = '';

Plan hash value: 3617692013

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

Predicate Information (identified by operation id):
---------------------------------------------------
   1 - filter('BOSS'='' OR "C200000020" LIKE 'BOSS%')

A full table scan, just like the original poster in the OTN thread experienced.  Notice that the optimizer is now predicting that 100,000 rows (1% of the rows) will be retrieved.  Repeating, 1% of the rows and a full table scan.  Let’s generate a 10053 trace for the SQL statement:

ALTER SYSTEM FLUSH SHARED_POOL;

SET AUTOTRACE OFF

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

SELECT
  *
FROM
  T1
WHERE
  C200000020 LIKE 'BOSS' || '%'
  OR 'BOSS' = '';

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

Inside the 10053 trace, my 11.2.0.1 test database produced the following:

***************************************
BASE STATISTICAL INFORMATION
***********************
Table Stats::
  Table: T1  Alias: T1
    #Rows: 10000000  #Blks:  303031  AvgRowLen:  213.00
Index Stats::
  Index: IND_T1  Col#: 1
    LVLS: 2  #LB: 32323  #DK: 9939968  LB/K: 1.00  DB/K: 1.00  CLUF: 10120176.00
Access path analysis for T1
***************************************
SINGLE TABLE ACCESS PATH
  Single Table Cardinality Estimation for T1[T1]
  Table: T1  Alias: T1
    Card: Original: 10000000.000000  Rounded: 100001  Computed: 100001.02  Non Adjusted: 100001.02
  Access Path: TableScan
    Cost:  82352.89  Resp: 82352.89  Degree: 0
      Cost_io: 82073.00  Cost_cpu: 7150017105
      Resp_io: 82073.00  Resp_cpu: 7150017105
  ****** trying bitmap/domain indexes ******
  ****** finished trying bitmap/domain indexes ******
  Best:: AccessPath: TableScan
         Cost: 82352.89  Degree: 1  Resp: 82352.89  Card: 100001.02  Bytes: 0

***************************************

OPTIMIZER STATISTICS AND COMPUTATIONS
***************************************
GENERAL PLANS
***************************************
Considering cardinality-based initial join order.
Permutations for Starting Table :0
Join order[1]:  T1[T1]#0
***********************
Best so far:  Table#: 0  cost: 82352.8851  card: 100001.0195  bytes: 21300213
***********************
(newjo-stop-1) k:0, spcnt:0, perm:1, maxperm:2000

*********************************
Number of join permutations tried: 1
*********************************

The unknown result of the constant in the WHERE clause (‘BOSS’ = ”) caused Oracle to predict that the cardinality will be (1 row) + (1% of the rows) = 100,001.  With a clustering factor of 10,120,176 the optimizer is (possibly) convinced that it will need to perform single block physical reads of a large number of table blocks to read the 100,001 rows that it expects to retrieve, so it decided that a full table scan would complete faster.  But the situation is worse than that – it did not even consider an index access path.  As a demonstration, I will manually set the index’s clustering factor to a low value and check the execution plan again:

EXEC DBMS_STATS.SET_INDEX_STATS(OWNNAME=>USER,INDNAME=>'IND_T1',CLSTFCT=>10000)

SET AUTOTRACE TRACEONLY EXPLAIN

ALTER SYSTEM FLUSH SHARED_POOL;

SELECT
  *
FROM
  T1
WHERE
  C200000020 LIKE 'BOSS' || '%'
  OR 'BOSS' = '';

Plan hash value: 3617692013

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

Predicate Information (identified by operation id):
---------------------------------------------------
   1 - filter('BOSS'='' OR "C200000020" LIKE 'BOSS%')

Still a full table scan.  If we had generated a 10053 trace, we would see that the clustering factor for the index was indeed adjusted from what we saw earlier:

***************************************
BASE STATISTICAL INFORMATION
***********************
Table Stats::
  Table: T1  Alias: T1
    #Rows: 10000000  #Blks:  303031  AvgRowLen:  213.00
Index Stats::
  Index: IND_T1  Col#: 1
    LVLS: 2  #LB: 32323  #DK: 9939968  LB/K: 1.00  DB/K: 1.00  CLUF: 10000.00
Access path analysis for T1
***************************************
SINGLE TABLE ACCESS PATH
  Single Table Cardinality Estimation for T1[T1]
  Table: T1  Alias: T1
    Card: Original: 10000000.000000  Rounded: 100001  Computed: 100001.02  Non Adjusted: 100001.02
  Access Path: TableScan
    Cost:  82352.89  Resp: 82352.89  Degree: 0
      Cost_io: 82073.00  Cost_cpu: 7150017105
      Resp_io: 82073.00  Resp_cpu: 7150017105
  ****** trying bitmap/domain indexes ******
  ****** finished trying bitmap/domain indexes ******
  Best:: AccessPath: TableScan
         Cost: 82352.89  Degree: 1  Resp: 82352.89  Card: 100001.02  Bytes: 0

Let’s force the execution plan with an index hint to see what happens:

SELECT /*+ INDEX(T1 IND_T1) */
  *
FROM
  T1
WHERE
  C200000020 LIKE 'BOSS' || '%'
  OR 'BOSS' = '';

Plan hash value: 3617692013

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

Predicate Information (identified by operation id):
---------------------------------------------------
   1 - filter('BOSS'='' OR "C200000020" LIKE 'BOSS%')

Note that the optimizer did not (or could not) obey the hint.  It decided to apply the ‘BOSS’=” predicate first, so maybe that is the problem.  Let’s try a hint to force the optimizer to apply the predicates in order, rather than based on calculated cost:

SELECT /*+ ORDERED_PREDICATES INDEX(T1 IND_T1) */
  *
FROM
  T1
WHERE
  C200000020 LIKE 'BOSS' || '%'
  OR 'BOSS' = '';

Execution Plan
----------------------------------------------------------
Plan hash value: 3617692013

--------------------------------------------------------------------------
| Id  | Operation         | Name | Rows  | Bytes | Cost (%CPU)| Time     |
--------------------------------------------------------------------------
|   0 | SELECT STATEMENT  |      |   100K|    20M| 82353   (1)| 00:16:29 |
|*  1 |  TABLE ACCESS FULL| T1   |   100K|    20M| 82353   (1)| 00:16:29 |
--------------------------------------------------------------------------
Predicate Information (identified by operation id):
---------------------------------------------------
   1 - filter("C200000020" LIKE 'BOSS%' OR 'BOSS'='')

The predicate section of the execution plan changed, but the optimizer still will not consider an index access path for the SQL statement.  There is a chance that the OP could do something to force the index access path by hacking a stored outline for the query, but my guess is that the restriction on the C200000020 column changes from time to time, so an outline likely will not work.  The OP could try to file an Oracle bug report because the optimizer completely ignored the index access paths (as shown in the 10053 trace file), but a better course of action would be to have the application submitting the SQL statement fixed.

Let’s try a small variation on the original test SQL statement.  Let’s see what happens when we add a space between the two ‘ characters:

SET AUTOTRACE TRACEONLY EXPLAIN

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

SELECT
  *
FROM
  T1
WHERE
  C200000020 LIKE 'BOSS' || '%'
  OR 'BOSS' = ' ';

Execution Plan
----------------------------------------------------------
Plan hash value: 634656657
--------------------------------------------------------------------------------------
| Id  | Operation                   | Name   | Rows  | Bytes | Cost (%CPU)| Time     |
--------------------------------------------------------------------------------------
|   0 | SELECT STATEMENT            |        |     1 |   213 |     4   (0)| 00:00:01 |
|   1 |  TABLE ACCESS BY INDEX ROWID| T1     |     1 |   213 |     4   (0)| 00:00:01 |
|*  2 |   INDEX RANGE SCAN          | IND_T1 |     1 |       |     3   (0)| 00:00:01 |
--------------------------------------------------------------------------------------
Predicate Information (identified by operation id):
---------------------------------------------------
   2 - access("C200000020" LIKE 'BOSS%')
       filter("C200000020" LIKE 'BOSS%')

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

Notice by looking at the Predicate Information section of the plan that Oracle removed the nonsensical OR clause.  The 10053 trace file showed this:

***************************************
BASE STATISTICAL INFORMATION
***********************
Table Stats::
  Table: T1  Alias: T1
    #Rows: 10000000  #Blks:  303031  AvgRowLen:  213.00
Index Stats::
  Index: IND_T1  Col#: 1
    LVLS: 2  #LB: 32323  #DK: 9939968  LB/K: 1.00  DB/K: 1.00  CLUF: 10000.00
Access path analysis for T1
***************************************
SINGLE TABLE ACCESS PATH
  Single Table Cardinality Estimation for T1[T1]
  Table: T1  Alias: T1
    Card: Original: 10000000.000000  Rounded: 1  Computed: 1.03  Non Adjusted: 1.03
  Access Path: TableScan
    Cost:  82255.34  Resp: 82255.34  Degree: 0
      Cost_io: 82073.00  Cost_cpu: 4658017105
      Resp_io: 82073.00  Resp_cpu: 4658017105
kkofmx: index filter:"T1"."C200000020" LIKE 'BOSS%'
  Access Path: index (RangeScan)
    Index: IND_T1
    resc_io: 4.00  resc_cpu: 29226
    ix_sel: 0.000000  ix_sel_with_filters: 0.000000
    Cost: 4.00  Resp: 4.00  Degree: 1
  Best:: AccessPath: IndexRange
  Index: IND_T1
         Cost: 4.00  Degree: 1  Resp: 4.00  Card: 1.03  Bytes: 0

So, it appears that if the optimizer is presented with a zero length VARCHAR being compared with another VARCHAR in the WHERE clause, there could be unexpected cases were index access paths will not be used even when hinted.

Toon Koppelaars mentioned in the OTN thread that the WHERE clause should be using bind variables, and suggested the following for the WHERE clause:

( (T131.C200000020 LIKE (:B0 || '%')) OR (:B0 IS NULL))

I agree with Toon regarding the use of bind variables.  Unfortunately, it does not look like bind variables improve the situation, at least in my test case.

I cannot use AUTOTRACE due to the risk that it will display an incorrect execution plan due to the bind variables, so I will use DBMS_XPLAN.DISPLAY_CURSOR along with a GATHER_PLAN_STATISTICS hint in the SQL statement.  First the statistics collection (to correct any manual adjustment to the index’s clustering factor that was performed earlier) and bind variable setup:

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

VARIABLE B0 VARCHAR2(50)
VARIABLE B1 VARCHAR2(50)
VARIABLE B2 VARCHAR2(50)

EXEC :B0 := 'BOSS'
EXEC :B1 := 'BOSS'
EXEC :B2 := ''

SET AUTOTRACE OFF

Since we do not know the intention of the developer, I will try a couple of combinations to see what happens:

SELECT /*+ GATHER_PLAN_STATISTICS */
  *
FROM
  T1
WHERE
  C200000020 LIKE :B0 || '%'
  OR :B1 = :B2;

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

SQL_ID  b47qzqbb6wymu, child number 0
-------------------------------------
SELECT /*+ GATHER_PLAN_STATISTICS */   * FROM   T1 WHERE   C200000020
LIKE :B0 || '%'   OR :B1 = :B2

Plan hash value: 3617692013

------------------------------------------------------------------------------------
| Id  | Operation         | Name | Starts | E-Rows | A-Rows |   A-Time   | Buffers |
------------------------------------------------------------------------------------
|   0 | SELECT STATEMENT  |      |      1 |        |      3 |00:00:00.34 |     303K|
|*  1 |  TABLE ACCESS FULL| T1   |      1 |    100K|      3 |00:00:00.34 |     303K|
------------------------------------------------------------------------------------

Predicate Information (identified by operation id):
---------------------------------------------------
   1 - filter((:B1=:B2 OR "C200000020" LIKE :B0||'%'))

The above resulted in the same full table scan that we saw earlier.

SELECT /*+ GATHER_PLAN_STATISTICS */
  *
FROM
  T1
WHERE
  C200000020 LIKE :B0 || '%'
  OR :B0 = :B2;

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

SQL_ID  1vdyc7t6wazhz, child number 0
-------------------------------------
SELECT /*+ GATHER_PLAN_STATISTICS */   * FROM   T1 WHERE   C200000020
LIKE :B0 || '%'   OR :B0 = :B2

Plan hash value: 3617692013

------------------------------------------------------------------------------------
| Id  | Operation         | Name | Starts | E-Rows | A-Rows |   A-Time   | Buffers |
------------------------------------------------------------------------------------
|   0 | SELECT STATEMENT  |      |      1 |        |      3 |00:00:00.34 |     303K|
|*  1 |  TABLE ACCESS FULL| T1   |      1 |    100K|      3 |00:00:00.34 |     303K|
------------------------------------------------------------------------------------

Predicate Information (identified by operation id):
---------------------------------------------------
   1 - filter((:B0=:B2 OR "C200000020" LIKE :B0||'%'))

Specifying the B0 bind variable twice did not help.

SELECT /*+ GATHER_PLAN_STATISTICS */
  *
FROM
  T1
WHERE
  C200000020 LIKE :B0 || '%'
  OR :B0 IS NULL;

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

SQL_ID  8n1bg0z9j0001, child number 0
-------------------------------------
SELECT /*+ GATHER_PLAN_STATISTICS */   * FROM   T1 WHERE   C200000020
LIKE :B0 || '%'   OR :B0 IS NULL

Plan hash value: 3617692013

------------------------------------------------------------------------------------
| Id  | Operation         | Name | Starts | E-Rows | A-Rows |   A-Time   | Buffers |
------------------------------------------------------------------------------------
|   0 | SELECT STATEMENT  |      |      1 |        |      3 |00:00:00.34 |     303K|
|*  1 |  TABLE ACCESS FULL| T1   |      1 |    500K|      3 |00:00:00.34 |     303K|
------------------------------------------------------------------------------------

Predicate Information (identified by operation id):
---------------------------------------------------
   1 - filter((:B0 IS NULL OR "C200000020" LIKE :B0||'%'))

Specifying that the B0 bind variable IS NULL did not help either, but notice the change in the predicted cardinality (the 100,000 rows increased to 500,000 rows).

Let’s try an index hint:

SELECT /*+ GATHER_PLAN_STATISTICS INDEX(T1 IND_T1) */
  *
FROM
  T1
WHERE
  C200000020 LIKE :B0 || '%'
  OR :B0 IS NULL;

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

SQL_ID  a241dy7mvudtk, child number 0
-------------------------------------
SELECT /*+ GATHER_PLAN_STATISTICS INDEX(T1 IND_T1) */   * FROM   T1
WHERE   C200000020 LIKE :B0 || '%'   OR :B0 IS NULL

Plan hash value: 3617692013

------------------------------------------------------------------------------------
| Id  | Operation         | Name | Starts | E-Rows | A-Rows |   A-Time   | Buffers |
------------------------------------------------------------------------------------
|   0 | SELECT STATEMENT  |      |      1 |        |      3 |00:00:00.34 |     303K|
|*  1 |  TABLE ACCESS FULL| T1   |      1 |    500K|      3 |00:00:00.34 |     303K|
------------------------------------------------------------------------------------

Predicate Information (identified by operation id):
---------------------------------------------------
   1 - filter((:B0 IS NULL OR "C200000020" LIKE :B0||'%'))

The optimizer still did not use the index.

—————–

Cases where Oracle’s optimizer ignores index hints are typically indications of bugs in the optimizer – as we saw, the optimizer did not even consider (generate a calculated cost for) an index access path when no space appeared between the two ‘ characters in the original SQL statement.  Other cases of Oracle’s optimizer ignoring hints may be found here: Demonstration of Oracle “Ignoring” an Index Hint.

SQL Challenge – Submit Update Statements, Updated Values are Reversed on Successful Commit

September 21, 2010

Is it possible to construct an Oracle Database test case such that:

1. An UPDATE statement is issued to change a DATE column value from NULL to the current date (SYSDATE) for two rows.
2. The data source is queried and the result set returned by the database shows that the DATE column is set to the current date for the two rows.
3. A COMMIT is successfully executed.
4. The data source is queried and the result set returned by the database shows that the DATE column is again NULL for the two rows.

—————–

For example, something like this:

CREATE TABLE T1 (
  C1 NUMBER,
  C2 DATE,
  C3 DATE,
  CONSTRAINT "CHECK_DATE" CHECK (
    NVL(C2,TO_DATE('01-JAN-2000','DD-MON-YYYY')) < NVL(C3,TO_DATE('01-JAN-2000','DD-MON-YYYY')))
    INITIALLY DEFERRED DEFERRABLE);

INSERT INTO T1 VALUES (1,NULL,TO_DATE('31-DEC-2000','DD-MON-YYYY'));
INSERT INTO T1 VALUES (2,NULL,TO_DATE('31-DEC-2000','DD-MON-YYYY'));
INSERT INTO T1 VALUES (3,NULL,TO_DATE('31-DEC-2000','DD-MON-YYYY'));

COMMIT;

There are now three rows in the table T1:

SELECT
  *
FROM
  T1;

 C1 C2        C3
--- --------- ---------
  1           31-DEC-00
  2           31-DEC-00
  3           31-DEC-00

We are able to update the column C2 to the current date (SYSDATE) with the following SQL statement:

UPDATE
  T1
SET
  C2=SYSDATE
WHERE
  C1 IN (1,2);

2 rows updated.

The update was successful, and we are able to confirm that the update was successful:

SELECT
  *
FROM
  T1;

C1 C2        C3
-- --------- ---------
 1 21-SEP-10 31-DEC-00
 2 21-SEP-10 31-DEC-00
 3           31-DEC-00

Now we will issue a COMMIT:

COMMIT;

Then query the table again to find the original value of column C2 was restored:

SELECT
  *
FROM
  T1;

 C1 C2        C3
--- --------- ---------
  1           31-DEC-00
  2           31-DEC-00
  3           31-DEC-00

The only catch is that “Commit complete.” must appear after the COMMIT, rather than something like the following:

COMMIT
*
ERROR at line 1:
ORA-02091: transaction rolled back
ORA-02290: check constraint (TESTUSER.CHECK_DATE) violated

Be creative.  How is it possible to update a set of rows, select the rows to prove that the rows were updated, COMMIT, receive a confirmation that the COMMIT was successful, and then find that the original values were restored?  In case you are wondering, this OTN thread was the inspiration for this blog article (but don’t look at forum thread yet).

Is the data source that makes this possible a table, or is it something else?  Is there possibly a corrupt index involved?  Is there an ON COMMIT trigger involved (as far as I am aware, there is no such trigger available on Oracle Database).  VPD (virtual private database) tricks?  View tricks?  Magic?

Technical Review of MOTS

September 18, 2010 (Updated September 18, 2010)

(Disclaimer: To satisfy the one person that might wonder if my account of this event should be “considered credible” I must admit up front that I had some involvement in the planning of the event.)

I will make a prediction that an event like this is unlikely to happen again any time in the next couple of years.  The two to one ratio of attendees to OakTable members made it quite easy for me to talk to knowledgeable people from around the region, and around the world – both OakTable and non-OakTable members were quick to share their knowledge, experiences, and knowledge acquisition techniques.  I even bumped into a couple of people who admitted to reading this blog.

Let’s first start with what I did not like about the event:

• The seat bottoms in the chairs in the conference rooms were a bit hard.  It seems that I had the constant urge to get up and fix something, yet there was nothing to fix, and I would have risked missing something that was quite useful if I did look away for a moment.
• I identified three errors in the presentation slides.  I was not able to pick out the errors until the presenter said something like, “Oh, by the way there is a typo in the second spelling of this parameter on the slide,” or “that should be REMOTE_LISTENER, not LOCAL_LISTENER,” or “that’s not supposed to happen.”  It is refreshing to see that people at this level are able to point out mistakes, and then spin that mistake into a teachable moment.
• The food and beverages.  Yes, there was an abundant supply of high quality food, and a wide variety of beverages (some only available after the sessions).  But where was the Diet Cherry Coke?  Pepsi products are OK unless you have to think clearly about performance problems (this is my excuse for being slow in spotting errors).
• While there were only three simultaneous presentations, without fail there were two sessions that I wanted/needed to see at the same time, and a third session that probably would have broadened my level of understanding into entirely new directions.
• Walking up and down the stairs rather than using the elevator – the hotel is not nearly tall enough to walk off all of the performance problems that could result from the third bullet point (I made sure to stop running the stairs to avoid compulsive tuning disorder).

As you can probably tell from the above list, it was hard to find things not to like about the event.  Carol Dacko did a fantastic job keeping everyone on the planning committee for the MOTS event on task, pushing toward an educational experience for all attendees.  All of the members of the MOTS committee contributed a substantial amount of time and effort (and travel miles) over the last seven to nine months. 

Before I describe what I liked about the event, I will first list the presentations that I managed to attend (I highly recommend these to anyone who has the opportunity to see these again in the future):

• Moans the Magnificent by Mogens Nørgaard and Cary Millsap.  An Oracle comedy routine similar to the Carnac series by Johnny Carson.  A great way to begin the event, although I think that one or two of the jokes might not have made sense to most of the audience members until a couple of hours later.
• How to Write Efficient SQL by Jonathan Lewis.  Using cutting the grass as an analogy, Jonathan explained why it was important to be familiar with the data to be queried, to ask if a better execution plan exists, and how to help the optimizer find the better execution plan.
• Battle Against Any Guess by Alex Gorbachev.  Why know when you can guess?  Not even educated guesses are good enough?  Alex founded the BAAG party and wrote a chapter in the Expert Oracle Practices book on the same topic.  Rumor is that there is a BAAD party around the corner if the NoSQL ACID-free movement gains momentum, roll-aids will be used rather than undo.  But once again this is just a rumor.
• Back to Basics – Choosing the Starting Point of Performance Tuning and Troubleshooting Wisely by Tanel Poder.  This is one of those sessions that I had hoped someone would put together.  It seems every time I see a person on the OTN forums propose the use of AWR (or Statspack) to identify a problem found in a specific session, I want to reach out and say to that person, “a system with a loose screw is rarely fixed by putting the screw into a nail gun – use the right tool for the job, and avoid what does not work.”  Tanel’s presentation covered that issue and many others.  His slides had a great deal of detail, much more than could be discussed in the 50 minute time period.  His slides made be downloaded from here. 
• CBO Fundamentals: Understanding the Different Modes of System Statistics by Randolf Geist.  Highlighting the evolution of the cost based optimizer from using the Oracle 8i OPTIMIZER_INDEX_COST_ADJ and OPTIMIZER_INDEX_CACHING parameters to reduce index costs, onto the use of system (CPU) statistics which effectively increase the cost of full table scans and consider the expected CPU utilization as a component of access path cost.
• Thinking Clearly About Performance by Cary Millsap (part I and II).  It is hard to describe this two hour presentation, other than to say that it is one of the best presentations offered at the symposium.  The whitepaper may be downloaded from here.
• SQL Baselines, Adaptive Cursor Sharing and Automatic Cardinality Feedback by Jože Senegačnik.  The presentation described interesting features that affect Oracle’s optimizer’s ability to repeatedly use the same execution plan in 10g, 11g R1, and 11g R2.
• Everything a DBA Needs to Know about TCP/IP Networks by Chen Shapira.  Chen stated up front that the presentation could not possibly contain everything that a DBA needs to know.  Instead, she described four types of network-related problems that she encountered and the tools that are available to help with analysis.  Her presentation ties into my seven part blog series on network monitoring.
• Interpreting Execution Plans by Christian Antognini.  Christian effectively covers the information that should have appeared in the Oracle documentation about how to read execution plans.  One hint from the presentation: the most indented line in the execution plan is not necessarily the starting point of the execution plan.  A very detailed (better than any other resource) description of reading execution plans is found in Christian’s Troubleshooting Oracle Performance book.
• The Beginner’s Guide to Becoming an Expert by Jonathan Lewis.  This was a presentation with a single slide, but the message was not in the slides, but instead in the scripts.  Creating models of problems, recognizing (and investigating) unexpected results, and comparing the results between Oracle releases to understand how Oracle Database behaves when certain conditions are present.  While I do not have 2,000 scripts, I would like to hope that the test cases found on this blog are constructed to serve the same purpose – to help myself (and others) understand why “A”, “B”, and “D” happen, while “C” only happens when “E” is introduced.  It was definitely a bitmap smashingly good session.  Does the method work?  My personal experience says yes.
• Understanding LGWR, Log File Sync Waits, and Commit Performance by Tanel Poder.  You might be curious about what happens when your CPUs are pushed toward 100% utilization.  You might be curious why placing your redo logs on SSD drives may not help.  You might be curious why SQL_IDs cannot be associated with the log file parallel write wait event, as was stated to be possible on page 322 of one of the books that I reviewed.  If you missed this presentation, you are probably still curious.
• Why Isn’t Oracle Using My Index by Jonathan Lewis.  Is clustering factor a factor (see the sample chapter from the “Cost-Based Oracle Fundamentals” book).  Is ASSM a factor?  Are incorrectly set parameters the problem?  Are the recorded performance statistics about the server a factor?  Are missing statistics for virtual columns the problem?  Is a function applied to the indexed column (I don’t think that this was mentioned, but the time ran out before the presentation finished)?  Interesting examples throughout.

What did I like about MOTS?

• Making a run to Kinkos (local photocopy center) at 12:45 AM to run off copies of the agenda for the next morning.
• Setting up a 13 drive RAID array using USB keys plugged into the laptop – the presentations had to be transferred onto the fancy real wood USB keys.  The MOTSCopy.doc (manually build the text file from the contents) file contains the scripts that I used for the copy process which alternated in parallel the writing to the USB keys when the CopyAll script was executed. (See below)
• Having a chance to meet for the first time a large number of OakTable members.  It is rather remarkable that the OakTable members traveled around the world on their own dime to offer this training in Michigan.  I think that says something about the commitment of the OakTable members to learn Oracle Database details thoroughly, and then openly share that knowledge – just for the sake of helping others.
• There were no sloppy, or poorly assembled, or untested presentation topics.
• The speed with which OakTable members diagnose and resolve problems, for example posting videos and pictures (and more) from the event.
• And… the list goes on, and on, and on. 

Any thoughts from other attendees? 

Hopefully, more of the pictures from the event and more of the presentations will make their way to the Internet soon.

——————————–

WordPress is currently refusing to deliver the Word documents and the double-extension attachments.  The five script files that I used to transfer the presentations to 13 USB keys simultaneously follows (only need to execute the CopyAll.bat file):

CopyAll.bat File Contents:
START copy1.bat
START copy2.bat
START copy3.bat
START copy4.bat

Copy1.bat File Contents:
xcopy C:\MOTS\*.* e:
xcopy C:\MOTS\*.* i:
xcopy C:\MOTS\*.* m:
xcopy C:\MOTS\*.* q:

Copy2.bat File Contents:
xcopy C:\MOTS\*.* f:
xcopy C:\MOTS\*.* j:
xcopy C:\MOTS\*.* n:

Copy3.bat File Contents:
xcopy C:\MOTS\*.* g:
xcopy C:\MOTS\*.* k:
xcopy C:\MOTS\*.* o:

Copy4.bat File Contents:
xcopy C:\MOTS\*.* h:
xcopy C:\MOTS\*.* l:
xcopy C:\MOTS\*.* p: 

The SQL to the Orbiting Ball

September 12, 2010

Several years ago I developed a somewhat simple program in 16 bit Borland C (last compiled in 1994, so it pre-dates graphical web pages) that was optimized for 386 and 486 computers which sported VGA graphics but was also able to work with EGA graphics cards.  The simple program, after creating 18 images on the fly that simulated a rotating basketball, generated X and Y coordinates using a specially crafted formula that was capable of producing X and Y cordinates in a circular pattern.  With slightly different inputs the same formula produced a slightly out of round circular pattern that eventually might have generated straight line patterns.  With a slight adjustment to the inputs the same formula produced W patterns within a bounded box.  Keyboard input allowed the user to specify adjusted inputs as the program executed.  The C program looked like this:

#include <graphics.h>               // for graphics functions
#include <conio.h>                  // for kbhit()
#include <math.h>
#include <dos.h>
#define LEFT      100               // boundary of rectangle
#define TOP       100
#define RADIUS    20                // radius of ball
#define pi        3.14159276
#define L_ARROW   75
#define R_ARROW   77
#define U_ARROW   72
#define D_ARROW   80
#define ESC       27

void main(void)
   {
   int driver, mode;                // for initgraph()
   float x, y, dx, dy, i, sped, temp, x1, x2, y1, y2, sta1, sta2, ena1, ena2, rad;    // ball coordinates
   int imgnum, tim, del;
   char key;
   unsigned char ballbuff[10][5000];    // buffer for ball image

   driver = DETECT;                 // auto detect
        // set graphics mode
   initgraph(&driver, &mode, "c:\\bc4\\bgi");

   x = LEFT + RADIUS;          // designate center where ball is created
   y = TOP  + RADIUS;
   for (i =0; i <180; i = i + 18) // create basketball rotation images
       {
 setcolor(RED);
 setfillstyle(SOLID_FILL, RED);
 circle(x, y, RADIUS);
 floodfill(x, y, RED);
 setcolor(BLACK);
 rad = i / (2 * pi);
 x1 = x + 30 * cos(rad);
 x2 = x - 30 * cos(rad);
 y1 = y + 30 * sin(rad);
 y2 = y - 30 * sin(rad);
 sta1 = (180 + i -62);
 ena1 = (180 + i + 42);
 sta2 = (i -62);
 ena2 = (i + 42);
 if ((i/36) != int(i/36))    // must be included to swap arcs
    {
     temp = sta1;
     sta1 = sta2;
     sta2 = temp;
     temp = ena1;
     ena1 = ena2;
     ena2 = temp;
    }
 ellipse (x1, y1, sta1, ena1, RADIUS , RADIUS);
 ellipse (x2, y2, sta2, ena2, RADIUS , RADIUS);
 line (x - cos(rad + pi/2) * RADIUS, y - sin(rad + pi/2) * RADIUS, x + cos(rad + pi/2) * RADIUS, y + sin(rad + pi/2) * RADIUS);
        // pickup image
 getimage(x-RADIUS-20, y-RADIUS-20, x+RADIUS+20, y+RADIUS+20, ballbuff[i/18]);
        // clear screen
 setcolor(WHITE);
 rectangle(-1,-1, 640, 480);
 setfillstyle(SOLID_FILL, BLACK);
 floodfill(100,100, WHITE);
       }

   imgnum = 10;                         // load first position + 1
   tim = 0;                             // set delay to zero
   dx = .1;                             // set constant in x equation
   dy = .1;
   sped = 1;
   del = 1;
   while ( key != ESC )             
      {
      if (kbhit())
      {
       key = getch();
       if (key == 61) del++;            // = key pressed
       if (key == 43) del++;            // + key pressed
       if (key == 45) del--;            // - key pressed
       if (key == 47) sped = sped +.1;  // / key pressed
       if (key == 92) sped = sped -.1;  // \ key pressed
       if (key == 0)                    // place image on screen
 switch(getch())
 {
  case L_ARROW:
     putimage(x-RADIUS, y-RADIUS, ballbuff[imgnum], XOR_PUT);
     dx = dx -.01;
     break;
  case R_ARROW:
     putimage(x-RADIUS, y-RADIUS, ballbuff[imgnum], XOR_PUT);
     dx = dx + .01;
     break;
  case U_ARROW:
     putimage(x-RADIUS, y-RADIUS, ballbuff[imgnum], XOR_PUT);
     dy = dy + .01;
     break;
  case D_ARROW:
     putimage(x-RADIUS, y-RADIUS, ballbuff[imgnum], XOR_PUT);
     dy = dy -.01;
     break;
  case ESC:
     key = 27;
     break;
        }
      }
      tim = tim + sped;
      x = (sin(dx * tim)*100) + 300;
      y = (cos(dy * tim)* 100) + 300;
      imgnum--;                   // cycle through images
      if (imgnum == -1) imgnum = 9;
      putimage(x-RADIUS, y-RADIUS, ballbuff[imgnum], COPY_PUT);

      // move ball across screen
      // to make ball move rapidly increase +
      // set height on screen
      delay(del);                 // make delay smaller for slow computers
      }
   getch();

   closegraph();
   }

If you still have a 16 bit Borland C compiler (my copy is in a huge box on the bottom self of my bookcase), feel free to compile the above program to see it in action.  The original compiled C program, last compiled in 1994, may be downloaded here: OrbitBall2.zip (save as OrbitBall.zip and extract the files – download might not work).  The original program is confirmed to work on 32 bit Windows 95 through Windows XP (in DOS full screen mode), but definitely will not work on 64 bit Windows, even in a virtual machine (it also failed to run on a 32 bit Windows 7 netbook).

You are probably thinking, “Neat, but what does that have to do with Oracle?”.  It might be interesting to produce a modernized version of the above program.  We could use a simple SQL statement like the following to generate 3,600 X and Y coordinates, much like the X and Y coordinates that were generated by the above C program (note that the COS function is typically used to derive X values (using mathematical cosine) and the SIN function is typically used to derive Y values – the functions were swapped so that the X and Y cordinates start at the bottom-center of the screen).  The SQL follows:

SELECT
  ROUND((SIN(DX * (SPEED * COUNTER)) * WIDTH/2) + WIDTH/2) X,
  ROUND((COS(DY * (SPEED * COUNTER)) * HEIGHT/2) + HEIGHT/2) Y
FROM
  (SELECT
    0.1 DX,
    0.1 DY,
    1 SPEED,
    1 DELAY,
    300 WIDTH,
    300 HEIGHT,
    LEVEL COUNTER
  FROM
    DUAL
  CONNECT BY
    LEVEL<=3600);

Now we have a slight problem, how do we present the X and Y coordinate points produced by the above SQL statement?  We need some sort of object to track the X and Y coordinate pairs.  Drawn basketballs might work, but instead I will use these pictures (created with Microsoft Power Point 2010):

To display the round oak pictures, we will put together a VBS script to build a web page on the fly, cycling through the above eight pictures (every two X,Y coordinate pairs cause the displayed picture to change).  Much like the original program, we will allow the user to control the input parameters as the program runs.  Each time the parameters are adjusted, 3,600 new X,Y coordinate points are retrieved from the database into an array – this allows the VBS script to continue at the next X,Y coordinate pair, rather than starting at the beginning every time the parameters are adjusted. 

Option Explicit

Const adCmdText = 1
Const adCmdStoredProc = 4
Const adParamInput = 1
Const adVarNumeric = 139
Const adBigInt = 20
Const adDecimal = 14
Const adDouble = 5
Const adInteger = 3
Const adLongVarBinary = 205
Const adNumeric = 131
Const adSingle = 4
Const adSmallInt = 2
Const adTinyInt = 16
Const adUnsignedBigInt = 21
Const adUnsignedInt = 19
Const adUnsignedSmallInt = 18
Const adUnsignedTinyInt = 17
Const adDate = 7
Const adDBDate = 133
Const adDBTimeStamp = 135
Const adDBTime = 134
Const adVarChar = 200
Const adUseClient = 3

Dim dbDatabase
Dim snpData
Dim comData
Dim varData
Dim objIE

Dim strUsername             'Username
Dim strPassword             'Password
Dim strDatabase             'SID name from tnsnames.ora

startup

Sub startup()
    Dim strSQL
    Dim strHTML
    Dim objOrbitBall
    Dim objOrbitBallPic
    Dim objCommand
    Dim objSettings
    Dim i
    Dim intQuit

    'Fire up Internet Explorer
    Set objIE = CreateObject("InternetExplorer.Application")
    objIE.Left = 0
    objIE.Top = 0
    objIE.Width = 930
    objIE.Height = 820
    objIE.StatusBar = True
    objIE.MenuBar = False
    objIE.Toolbar = False
    objIE.Navigate "about:blank"
    objIE.Document.Title = "The SQL to the Orbiting Ball"
    objIE.Visible = True

    'The data entry area
    strHTML = "<div style=""position: absolute;width: 180px; height: 200px;top: 10px;left: 710px;"">" & vbCrLf
    strHTML = strHTML & "<input type=text id=txtCommand value="""" size=""1""><br>" & vbCrLf
    strHTML = strHTML & "<font size=1><b>+&nbsp;&nbsp;&nbsp;Increase Delay (Not Used)<br>" & vbCrLf
    strHTML = strHTML & "-&nbsp;&nbsp;&nbsp;Decrease Delay (Not Used)<br>" & vbCrLf
    strHTML = strHTML & "/&nbsp;&nbsp;&nbsp;Increase Rotation Speed<br>" & vbCrLf
    strHTML = strHTML & "\&nbsp;&nbsp;&nbsp;Decrease Rotation Speed<br>" & vbCrLf
    strHTML = strHTML & "D&nbsp;&nbsp;&nbsp;Increase Rotation Speed X Axis<br>" & vbCrLf
    strHTML = strHTML & "A&nbsp;&nbsp;&nbsp;Decrease Rotation Speed X Axis<br>" & vbCrLf
    strHTML = strHTML & "W&nbsp;&nbsp;&nbsp;Increase Rotation Speed Y Axis<br>" & vbCrLf
    strHTML = strHTML & "S&nbsp;&nbsp;&nbsp;Decrease Rotation Speed Y Axis<br>" & vbCrLf
    strHTML = strHTML & "L&nbsp;&nbsp;&nbsp;Increase Width X Axis<br>" & vbCrLf
    strHTML = strHTML & "J&nbsp;&nbsp;&nbsp;Decrease Width X Axis<br>" & vbCrLf
    strHTML = strHTML & "I&nbsp;&nbsp;&nbsp;Increase Height Y Axis<br>" & vbCrLf
    strHTML = strHTML & "K&nbsp;&nbsp;&nbsp;Decrease Height Y Axis<br>" & vbCrLf
    strHTML = strHTML & "(space)&nbsp;&nbsp;&nbsp;Restart at 0<br>" & vbCrLf
    strHTML = strHTML & "X&nbsp;&nbsp;&nbsp;Exit</b></font>" & vbCrLf
    strHTML = strHTML & "</div>" & vbCrLf

    'The current orbit information
    strHTML = strHTML & "<div id=""Settings"" style=""position: absolute;width: 180px; height: 100px;top: 600px;left: 710px;""> </div>"
    strHTML = strHTML & "<IMG ID=""picOrbitBall"" style=""position: absolute;"" src=""https://hoopercharles.wordpress.com/wp-content/uploads/2010/09/sqlorbitingball0.png"">" & vbCrLf
    objIE.Document.Body.InnerHTML = strHTML

    'The sleep here is only necessary if the database connections happen very quickly
    'Wscript.Sleep 500

    Set dbDatabase = CreateObject("ADODB.Connection")
    Set snpData = CreateObject("ADODB.Recordset")
    Set comData = CreateObject("ADODB.Command")

    'Database configuration
    strUsername = "MyUsername"
    strPassword = "MyPassword"
    strDatabase = "MyDB"

    On Error Resume Next

    dbDatabase.ConnectionString = "Provider=OraOLEDB.Oracle;Data Source=" & strDatabase & ";User ID=" & strUsername & ";Password=" & strPassword & ";"
    dbDatabase.open

    'Should verify that the connection attempt was successful, but I will leave that for someone else to code

    strSQL = "SELECT" & vbCrLf
    strSQL = strSQL & "  ROUND((SIN(DX * (SPEED * COUNTER)) * WIDTH/2) + WIDTH/2) X," & vbCrLf
    strSQL = strSQL & "  ROUND((COS(DY * (SPEED * COUNTER)) * HEIGHT/2) + HEIGHT/2) Y" & vbCrLf
    strSQL = strSQL & "FROM" & vbCrLf
    strSQL = strSQL & "  (SELECT" & vbCrLf
    strSQL = strSQL & "    ? DX," & vbCrLf
    strSQL = strSQL & "    ? DY," & vbCrLf
    strSQL = strSQL & "    ? SPEED," & vbCrLf
    strSQL = strSQL & "    ? DELAY," & vbCrLf
    strSQL = strSQL & "    ? WIDTH," & vbCrLf
    strSQL = strSQL & "    ? HEIGHT," & vbCrLf
    strSQL = strSQL & "    LEVEL COUNTER" & vbCrLf
    strSQL = strSQL & "  FROM" & vbCrLf
    strSQL = strSQL & "    DUAL" & vbCrLf
    strSQL = strSQL & "  CONNECT BY" & vbCrLf
    strSQL = strSQL & "    LEVEL<=3600)"

    With comData
        'Set up the command properties
        .CommandText = strSQL
        .CommandType = adCmdText
        .CommandTimeout = 30

        .ActiveConnection = dbDatabase

        'Add the bind variables
        .Parameters.Append .CreateParameter("dx", adDouble, adParamInput, 30)
        .Parameters.Append .CreateParameter("dy", adDouble, adParamInput, 30)
        .Parameters.Append .CreateParameter("speed", adDouble, adParamInput, 30)
        .Parameters.Append .CreateParameter("delay", adDouble, adParamInput, 30)
        .Parameters.Append .CreateParameter("width", adDouble, adParamInput, 30)
        .Parameters.Append .CreateParameter("height", adDouble, adParamInput, 30)
    End With

    comData("dx") = 0.1
    comData("dy") = 0.1
    comData("speed") = 1
    comData("delay") = 1
    comData("width") = 600
    comData("height") = 600

    Set snpData = comData.Execute

    'Retrieve up to 10,000 data points from Oracle
    varData = snpData.GetRows(10000)
    snpData.Close
    Set snpData = Nothing

    'Allow faster access to these objects when executing in the loop
    Set objOrbitBall = objIE.Document.getElementById("picOrbitBall").Style
    Set objOrbitBallPic = objIE.Document.getElementById("picOrbitBall")
    Set objCommand = objIE.Document.All.txtCommand
    Set objSettings = objIE.Document.getElementById("Settings")

    'Write out the current settings for the orbit
    objSettings.InnerText = "DX: " & comData("dx") & Chr(10) & "DY: " & comData("dy") & Chr(10) & _
                            "Speed: " & comData("speed") &Chr(10) & _
                            "Width: " & comData("width") & Chr(10) & "Height: " & comData("height")

    intQuit = False

    Do While intQuit = False
        For i = 0 To UBound(varData, 2)
            objOrbitBall.Left = CInt(varData(0, i))
            objOrbitBall.Top = CInt(varData(1, i))
            objOrbitBallPic.Src = "https://hoopercharles.wordpress.com/wp-content/uploads/2010/09/sqlorbitingball" & cStr(i/2 Mod 8 ) & ".png"

            Wscript.Sleep 50
            Select Case Left(objCommand.Value, 1)
                Case "=", "+"
                    comData("delay") = comData("delay") + 1
                Case "-"
                    comData("delay") = comData("delay") - 1
                Case "/"
                    comData("speed") = comData("speed") + 0.1
                Case "\"
                    comData("speed") = comData("speed") - 0.1
                Case "W", "w"
                    comData("dy") = comData("dy") + 0.0005
                Case "S", "s"
                    comData("dy") = comData("dy") - 0.0005
                Case "D", "d"
                    comData("dx") = comData("dx") + 0.0005
                Case "A", "a"
                    comData("dx") = comData("dx") - 0.0005
                Case "I", "i"
                    comData("height") = comData("height") + 5
                Case "K", "k"
                    comData("height") = comData("height") - 5
                Case "L", "l"
                    comData("width") = comData("width") + 5
                Case "J", "j"
                    comData("width") = comData("width") - 5
                Case "X", "x"
                    intQuit = True
                    Exit For
                Case " "
                     'Reset the loop from the beginning
                     objCommand.Value = ""
                     Exit For
            End Select

            If objCommand.Value <> "" Then
                objCommand.Value = ""

                Set snpData = comData.Execute

                'Retrieve up to 10,000 data points from Oracle
                varData = snpData.GetRows(10000)

                snpData.Close
                Set snpData = Nothing

                'Write out the current settings for the orbit
                objSettings.InnerText = "DX: " & comData("dx") & Chr(10) & "DY: " & comData("dy") & Chr(10) & _
                                        "Speed: " & comData("speed") &Chr(10) & _
                                        "Width: " & comData("width") & Chr(10) & "Height: " & comData("height")
            End If
        Next
    Loop

    objIE.quit
    dbDatabase.Close
    Set dbDatabase = Nothing
    Set objIE = Nothing
End Sub

You may download the above script here: SQLOrbitingBall.vbs (save as SQLOrbitingBall.vbs).

A Circular Orbit:

————-

An Orbit that Changes from a Circular Orbit to a Straight Line:

————-

An Orbit where the Ball Bounces Between the Top and Bottom of the Window:

—————————

As written, the script assumes a minimum of 930 x 820 resolution (1080p resolution or greater should work without any problems).  Adjust the script as necessary for lower resolution screens.  The program written in C certainly is shorter than the moderized version of the program, and had a bit more wow factor prior to the widespread use of Windows and other graphical user interfaces.

Something is Bugging Me: V$SESSION and 10046 Trace Files Show OBJECT_ID or DATA_OBJECT_ID?

September 8, 2010

There is a section in the Oracle Database 11.2 Performance Tuning Guide, which seems to have originated all the way back to the Oracle Database 10.1 Performance Tuning Guide that has bothered me a bit:

10.3.2.5 Finding the Object Requiring I/O
To determine the possible causes, first query V$SESSION to identify the value of ROW_WAIT_OBJ# when the session waits for db file scattered read. For example:

SELECT row_wait_obj#
  FROM V$SESSION
 WHERE EVENT = 'db file scattered read';

To identify the object and object type contended for, query DBA_OBJECTS using the value for ROW_WAIT_OBJ# that is returned from V$SESSION. For example:

SELECT owner, object_name, subobject_name, object_type
  FROM DBA_OBJECTS
 WHERE data_object_id = &row_wait_obj;

Notice that the documentation shows that the value from the ROW_WAIT_OBJ# column in V$SESSION is used to drive into DBA_OBJECTS using the DATA_OBJECT_ID column to determine the OBJECT_NAME and SUBOBJECT_NAME of the object involved in the wait event.  At this point you might be thinking that it is also the DATA_OBJECT_ID that appears in the WAIT lines found in a 10046 trace file, and that would be a logical conclusion.  Let’s see if we are able to find a little clarification from the documentation about the OBJECT_ID and DATA_OBJECT_ID columns:

“OBJECT_ID: Dictionary object number of the object
DATA_OBJECT_ID: Dictionary object number of the segment that contains the object

Note: OBJECT_ID and DATA_OBJECT_ID display data dictionary metadata. Do not confuse these numbers with the unique 16-byte object identifier (object ID) that Oracle Database assigns to row objects in object tables in the system.”

Well, that almost helps a little, DATA_OBJECT_ID relates to the segments that compose the object.  More information may be found here.

A quick check of Metalink (MOS) finds the helpful Metalink Doc ID 39817.1 “Interpreting Raw SQL_TRACE and DBMS_SUPPORT.START_TRACE Output” that describes the contents of a 10046 trace file, but the document completely avoids describing the meaning of the obj# parameter in the WAIT lines of the trace file.  Another Metalink document found by searching on the keyword DATA_OBJECT_ID also seemed to be a bit unclear about V$SESSION and DATA_OBJECT_ID/OBJECT_ID (to put it nicely).

So, do the waits events in V$SESSION and in 10046 trace files show the OBJECT_ID or the DATA_OBJECT_ID?  What we need is a test case to see for ourselves.  We will create a simple table with a primary key index, add a secondary index, insert 100,000 rows into the table, and then collect table and index statistics:

CREATE TABLE T10 (
  C1 NUMBER,
  C2 NUMBER,
  C3 VARCHAR2(100),
  PRIMARY KEY (C1));

CREATE INDEX IND_T10_C2 ON T10(C2);

INSERT INTO
  T10
SELECT
  ROWNUM,
  ROWNUM,
  LPAD('A',100,'A')
FROM
  DUAL
CONNECT BY
  LEVEL<=100000;

COMMIT;

EXEC DBMS_STATS.GATHER_TABLE_STATS(OWNNAME=>USER,TABNAME=>'T10',CASCADE=>TRUE)

Next, let’s check the OBJECT_ID and the DATA_OBJECT_ID for the indexes on the table that was just created:

COLUMN OBJECT_NAME FORMAT A12

SELECT
  OBJECT_NAME,
  OBJECT_ID,
  DATA_OBJECT_ID
FROM
  DBA_OBJECTS
WHERE
  (OWNER,OBJECT_NAME) IN
  (SELECT
    OWNER,
    INDEX_NAME
  FROM
    DBA_INDEXES
  WHERE
    TABLE_NAME='T10'
    AND OWNER=USER);

OBJECT_NAME   OBJECT_ID DATA_OBJECT_ID
------------ ---------- --------------
IND_T10_C2        99707          99707
SYS_C0016827      99706          99706

At this point the OBJECT_ID and DATA_OBJECT_ID columns contain identical values.  So, let’s flush the buffer cache to force physical reads, enable a 10046 trace at level 12, and then select from the test table:

ALTER SYSTEM FLUSH BUFFER_CACHE;
ALTER SYSTEM FLUSH BUFFER_CACHE;

ALTER SESSION SET TRACEFILE_IDENTIFIER = 'TESTING_OBJECTID';
ALTER SESSION SET EVENTS '10046 TRACE NAME CONTEXT FOREVER, LEVEL 12';

SELECT
  *
FROM
  T10
WHERE
  C1 BETWEEN 1 AND 100;

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

If we look inside the TESTING_OBJECTID trace file, we will probably see something that looks like this (the obj# for the primary key index is highlighted in blue):

...
PARSING IN CURSOR #18 len=50 dep=0 uid=60 oct=3 lid=60 tim=1839119134694 hv=804032012 ad='1e3c5558' sqlid='56b2yxcryt3hc'
SELECT
  *
FROM
  T10
WHERE
  C1 BETWEEN 1 AND 100
END OF STMT
PARSE #18:c=0,e=0,p=0,cr=0,cu=0,mis=1,r=0,dep=0,og=1,plh=2473627518,tim=1839119134694
EXEC #18:c=0,e=0,p=0,cr=0,cu=0,mis=0,r=0,dep=0,og=1,plh=2473627518,tim=1839119134694
WAIT #18: nam='SQL*Net message to client' ela= 3 driver id=1413697536 #bytes=1 p3=0 obj#=376 tim=1839119156325
WAIT #18: nam='db file sequential read' ela= 16306 file#=5 block#=1322147 blocks=1 obj#=99706 tim=1839119172691
WAIT #18: nam='db file sequential read' ela= 161 file#=5 block#=1322148 blocks=1 obj#=99706 tim=1839119172929
WAIT #18: nam='db file sequential read' ela= 3604 file#=5 block#=1321964 blocks=1 obj#=99705 tim=1839119176568
FETCH #18:c=0,e=31267,p=3,cr=3,cu=0,mis=0,r=1,dep=0,og=1,plh=2473627518,tim=1839119165961
WAIT #18: nam='SQL*Net message from client' ela= 369 driver id=1413697536 #bytes=1 p3=0 obj#=99705 tim=1839119177012
WAIT #18: nam='SQL*Net message to client' ela= 1 driver id=1413697536 #bytes=1 p3=0 obj#=99705 tim=1839119177058
FETCH #18:c=0,e=0,p=0,cr=2,cu=0,mis=0,r=15,dep=0,og=1,plh=2473627518,tim=1839119165961
WAIT #18: nam='SQL*Net message from client' ela= 14786 driver id=1413697536 #bytes=1 p3=0 obj#=99705 tim=1839119191906
WAIT #18: nam='SQL*Net message to client' ela= 1 driver id=1413697536 #bytes=1 p3=0 obj#=99705 tim=1839119191942
FETCH #18:c=0,e=0,p=0,cr=2,cu=0,mis=0,r=15,dep=0,og=1,plh=2473627518,tim=1839119165961
WAIT #18: nam='SQL*Net message from client' ela= 9246 driver id=1413697536 #bytes=1 p3=0 obj#=99705 tim=1839119201244
WAIT #18: nam='SQL*Net message to client' ela= 2 driver id=1413697536 #bytes=1 p3=0 obj#=99705 tim=1839119201425
FETCH #18:c=0,e=0,p=0,cr=2,cu=0,mis=0,r=15,dep=0,og=1,plh=2473627518,tim=1839119197198
WAIT #18: nam='SQL*Net message from client' ela= 8680 driver id=1413697536 #bytes=1 p3=0 obj#=99705 tim=1839119210215
WAIT #18: nam='SQL*Net message to client' ela= 3 driver id=1413697536 #bytes=1 p3=0 obj#=99705 tim=1839119210364
FETCH #18:c=0,e=0,p=0,cr=2,cu=0,mis=0,r=15,dep=0,og=1,plh=2473627518,tim=1839119197198
WAIT #18: nam='SQL*Net message from client' ela= 15822 driver id=1413697536 #bytes=1 p3=0 obj#=99705 tim=1839119226311
WAIT #18: nam='SQL*Net message to client' ela= 1 driver id=1413697536 #bytes=1 p3=0 obj#=99705 tim=1839119226376
WAIT #18: nam='db file sequential read' ela= 174 file#=5 block#=1321965 blocks=1 obj#=99705 tim=1839119226589
FETCH #18:c=0,e=0,p=1,cr=3,cu=0,mis=0,r=15,dep=0,og=1,plh=2473627518,tim=1839119197198
WAIT #18: nam='SQL*Net message from client' ela= 10086 driver id=1413697536 #bytes=1 p3=0 obj#=99705 tim=1839119236751
WAIT #18: nam='SQL*Net message to client' ela= 1 driver id=1413697536 #bytes=1 p3=0 obj#=99705 tim=1839119236830
FETCH #18:c=0,e=0,p=0,cr=2,cu=0,mis=0,r=15,dep=0,og=1,plh=2473627518,tim=1839119228446
WAIT #18: nam='SQL*Net message from client' ela= 8652 driver id=1413697536 #bytes=1 p3=0 obj#=99705 tim=1839119245603
WAIT #18: nam='SQL*Net message to client' ela= 1 driver id=1413697536 #bytes=1 p3=0 obj#=99705 tim=1839119245641
FETCH #18:c=0,e=0,p=0,cr=2,cu=0,mis=0,r=9,dep=0,og=1,plh=2473627518,tim=1839119228446
STAT #18 id=1 cnt=100 pid=0 pos=1 obj=99705 op='TABLE ACCESS BY INDEX ROWID T10 (cr=18 pr=4 pw=0 time=0 us cost=4 size=11000 card=100)'
STAT #18 id=2 cnt=100 pid=1 pos=1 obj=99706 op='INDEX RANGE SCAN SYS_C0016827 (cr=9 pr=2 pw=0 time=0 us cost=2 size=0 card=100)'
WAIT #18: nam='SQL*Net message from client' ela= 11094 driver id=1413697536 #bytes=1 p3=0 obj#=99705 tim=1839119256866
CLOSE #18:c=0,e=0,dep=0,type=0,tim=1839119228446
...

One of Jonthan Lewis’ blog articles shows that rebuilding an index will cause its OBJECT_ID and DATA_OBJECT_ID columns to deviate from each other.  So, let’s rebuild the table’s indexes and see what happens to the OBJECT_ID and DATA_OBJECT_ID columns: 

ALTER INDEX IND_T10_C2 REBUILD;
ALTER INDEX SYS_C0016827 REBUILD;

SELECT
  OBJECT_NAME,
  OBJECT_ID,
  DATA_OBJECT_ID
FROM
  DBA_OBJECTS
WHERE
  (OWNER,OBJECT_NAME) IN
  (SELECT
    OWNER,
    INDEX_NAME
  FROM
    DBA_INDEXES
  WHERE
    TABLE_NAME='T10'
    AND OWNER=USER);

OBJECT_NAME   OBJECT_ID DATA_OBJECT_ID
------------ ---------- --------------
IND_T10_C2        99707          99708
SYS_C0016827      99706          99709

For both indexes the OBJECT_ID column stayed the same, while the DATA_OBJECT_ID changed.  Let’s repeat the earlier test:

ALTER SYSTEM FLUSH BUFFER_CACHE;
ALTER SYSTEM FLUSH BUFFER_CACHE;

ALTER SESSION SET TRACEFILE_IDENTIFIER = 'TESTING_OBJECTID2';
ALTER SESSION SET EVENTS '10046 TRACE NAME CONTEXT FOREVER, LEVEL 12';

SELECT
  *
FROM
  T10
WHERE
  C1 BETWEEN 1 AND 100;

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

If we look inside the TESTING_OBJECTID2 trace file, we will probably see something that looks like this (the obj# for the primary key index is highlighted in blue):

...
PARSING IN CURSOR #7 len=50 dep=0 uid=60 oct=3 lid=60 tim=1839468475585 hv=804032012 ad='1e3c5558' sqlid='56b2yxcryt3hc'
SELECT
  *
FROM
  T10
WHERE
  C1 BETWEEN 1 AND 100
END OF STMT
PARSE #7:c=0,e=58941,p=6,cr=7,cu=0,mis=1,r=0,dep=0,og=1,plh=2473627518,tim=1839468475585
EXEC #7:c=0,e=0,p=0,cr=0,cu=0,mis=0,r=0,dep=0,og=1,plh=2473627518,tim=1839468475585
WAIT #7: nam='SQL*Net message to client' ela= 3 driver id=1413697536 #bytes=1 p3=0 obj#=376 tim=1839468487835
WAIT #7: nam='db file sequential read' ela= 187 file#=5 block#=1322155 blocks=1 obj#=99706 tim=1839468488080
WAIT #7: nam='db file sequential read' ela= 14827 file#=5 block#=1322156 blocks=1 obj#=99706 tim=1839468502945
WAIT #7: nam='db file sequential read' ela= 2599 file#=5 block#=1321964 blocks=1 obj#=99705 tim=1839468505581
FETCH #7:c=0,e=0,p=3,cr=3,cu=0,mis=0,r=1,dep=0,og=1,plh=2473627518,tim=1839468475585
WAIT #7: nam='SQL*Net message from client' ela= 371 driver id=1413697536 #bytes=1 p3=0 obj#=99705 tim=1839468506021
WAIT #7: nam='SQL*Net message to client' ela= 1 driver id=1413697536 #bytes=1 p3=0 obj#=99705 tim=1839468506066
FETCH #7:c=0,e=0,p=0,cr=2,cu=0,mis=0,r=15,dep=0,og=1,plh=2473627518,tim=1839468475585
WAIT #7: nam='SQL*Net message from client' ela= 11270 driver id=1413697536 #bytes=1 p3=0 obj#=99705 tim=1839468517397
WAIT #7: nam='SQL*Net message to client' ela= 1 driver id=1413697536 #bytes=1 p3=0 obj#=99705 tim=1839468517471
FETCH #7:c=0,e=0,p=0,cr=2,cu=0,mis=0,r=15,dep=0,og=1,plh=2473627518,tim=1839468506832
WAIT #7: nam='SQL*Net message from client' ela= 9067 driver id=1413697536 #bytes=1 p3=0 obj#=99705 tim=1839468526595
WAIT #7: nam='SQL*Net message to client' ela= 1 driver id=1413697536 #bytes=1 p3=0 obj#=99705 tim=1839468526635
FETCH #7:c=0,e=0,p=0,cr=2,cu=0,mis=0,r=15,dep=0,og=1,plh=2473627518,tim=1839468506832
WAIT #7: nam='SQL*Net message from client' ela= 11581 driver id=1413697536 #bytes=1 p3=0 obj#=99705 tim=1839468538273
WAIT #7: nam='SQL*Net message to client' ela= 1 driver id=1413697536 #bytes=1 p3=0 obj#=99705 tim=1839468538345
FETCH #7:c=0,e=0,p=0,cr=2,cu=0,mis=0,r=15,dep=0,og=1,plh=2473627518,tim=1839468538078
WAIT #7: nam='SQL*Net message from client' ela= 14327 driver id=1413697536 #bytes=1 p3=0 obj#=99705 tim=1839468552729
WAIT #7: nam='SQL*Net message to client' ela= 1 driver id=1413697536 #bytes=1 p3=0 obj#=99705 tim=1839468552763
WAIT #7: nam='db file sequential read' ela= 160 file#=5 block#=1321965 blocks=1 obj#=99705 tim=1839468552953
FETCH #7:c=0,e=0,p=1,cr=3,cu=0,mis=0,r=15,dep=0,og=1,plh=2473627518,tim=1839468538078
WAIT #7: nam='SQL*Net message from client' ela= 13353 driver id=1413697536 #bytes=1 p3=0 obj#=99705 tim=1839468566369
WAIT #7: nam='SQL*Net message to client' ela= 1 driver id=1413697536 #bytes=1 p3=0 obj#=99705 tim=1839468566406
FETCH #7:c=0,e=0,p=0,cr=2,cu=0,mis=0,r=15,dep=0,og=1,plh=2473627518,tim=1839468538078
WAIT #7: nam='SQL*Net message from client' ela= 13395 driver id=1413697536 #bytes=1 p3=0 obj#=99705 tim=1839468579857
WAIT #7: nam='SQL*Net message to client' ela= 1 driver id=1413697536 #bytes=1 p3=0 obj#=99705 tim=1839468579922
FETCH #7:c=0,e=0,p=0,cr=2,cu=0,mis=0,r=9,dep=0,og=1,plh=2473627518,tim=1839468569331
STAT #7 id=1 cnt=100 pid=0 pos=1 obj=99705 op='TABLE ACCESS BY INDEX ROWID T10 (cr=18 pr=4 pw=0 time=0 us cost=4 size=11000 card=100)'
STAT #7 id=2 cnt=100 pid=1 pos=1 obj=99706 op='INDEX RANGE SCAN SYS_C0016827 (cr=9 pr=2 pw=0 time=0 us cost=2 size=0 card=100)'
WAIT #7: nam='SQL*Net message from client' ela= 6563 driver id=1413697536 #bytes=1 p3=0 obj#=99705 tim=1839468586612
CLOSE #7:c=0,e=0,dep=0,type=0,tim=1839468569331
...

In the above, we still see the OBJECT_ID value, not the DATA_OBJECT_ID value.  So, the quote from the Oracle Performance Tuning Guide does not agree with the trace file tests when we use the primary key index.  Let’s try again using the secondary index:

ALTER SYSTEM FLUSH BUFFER_CACHE;
ALTER SYSTEM FLUSH BUFFER_CACHE;

ALTER SESSION SET TRACEFILE_IDENTIFIER = 'TESTING_OBJECTID3';
ALTER SESSION SET EVENTS '10046 TRACE NAME CONTEXT FOREVER, LEVEL 12';

SELECT
  *
FROM
  T10
WHERE
  C2 BETWEEN 1 AND 100;

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

If we look inside the TESTING_OBJECTID3 trace file, we will probably see something that looks like this (the obj# for the secondary index is highlighted in green):

...
PARSING IN CURSOR #12 len=50 dep=0 uid=60 oct=3 lid=60 tim=1839710379843 hv=2985431092 ad='1e344a10' sqlid='7xpx31ksz441n'
SELECT
  *
FROM
  T10
WHERE
  C2 BETWEEN 1 AND 100
END OF STMT
PARSE #12:c=0,e=0,p=0,cr=0,cu=0,mis=1,r=0,dep=0,og=1,plh=1233283356,tim=1839710379843
EXEC #12:c=0,e=0,p=0,cr=0,cu=0,mis=0,r=0,dep=0,og=1,plh=1233283356,tim=1839710379843
WAIT #12: nam='SQL*Net message to client' ela= 3 driver id=1413697536 #bytes=1 p3=0 obj#=376 tim=1839710383650
WAIT #12: nam='db file sequential read' ela= 29848 file#=5 block#=3103739 blocks=1 obj#=99707 tim=1839710413557
WAIT #12: nam='db file sequential read' ela= 164 file#=5 block#=3103740 blocks=1 obj#=99707 tim=1839710413798
WAIT #12: nam='db file sequential read' ela= 14273 file#=5 block#=1321964 blocks=1 obj#=99705 tim=1839710428108
FETCH #12:c=0,e=31253,p=3,cr=3,cu=0,mis=0,r=1,dep=0,og=1,plh=1233283356,tim=1839710411096
WAIT #12: nam='SQL*Net message from client' ela= 379 driver id=1413697536 #bytes=1 p3=0 obj#=99705 tim=1839710428561
WAIT #12: nam='SQL*Net message to client' ela= 1 driver id=1413697536 #bytes=1 p3=0 obj#=99705 tim=1839710428607
FETCH #12:c=0,e=0,p=0,cr=2,cu=0,mis=0,r=15,dep=0,og=1,plh=1233283356,tim=1839710411096
WAIT #12: nam='SQL*Net message from client' ela= 11997 driver id=1413697536 #bytes=1 p3=0 obj#=99705 tim=1839710440668
WAIT #12: nam='SQL*Net message to client' ela= 0 driver id=1413697536 #bytes=1 p3=0 obj#=99705 tim=1839710440704
FETCH #12:c=0,e=0,p=0,cr=2,cu=0,mis=0,r=15,dep=0,og=1,plh=1233283356,tim=1839710411096
WAIT #12: nam='SQL*Net message from client' ela= 12518 driver id=1413697536 #bytes=1 p3=0 obj#=99705 tim=1839710453280
WAIT #12: nam='SQL*Net message to client' ela= 1 driver id=1413697536 #bytes=1 p3=0 obj#=99705 tim=1839710453359
FETCH #12:c=0,e=0,p=0,cr=2,cu=0,mis=0,r=15,dep=0,og=1,plh=1233283356,tim=1839710442343
WAIT #12: nam='SQL*Net message from client' ela= 6330 driver id=1413697536 #bytes=1 p3=0 obj#=99705 tim=1839710459749
WAIT #12: nam='SQL*Net message to client' ela= 1 driver id=1413697536 #bytes=1 p3=0 obj#=99705 tim=1839710459786
FETCH #12:c=0,e=0,p=0,cr=2,cu=0,mis=0,r=15,dep=0,og=1,plh=1233283356,tim=1839710442343
WAIT #12: nam='SQL*Net message from client' ela= 9842 driver id=1413697536 #bytes=1 p3=0 obj#=99705 tim=1839710469685
WAIT #12: nam='SQL*Net message to client' ela= 1 driver id=1413697536 #bytes=1 p3=0 obj#=99705 tim=1839710469720
WAIT #12: nam='db file sequential read' ela= 163 file#=5 block#=1321965 blocks=1 obj#=99705 tim=1839710469913
FETCH #12:c=0,e=0,p=1,cr=3,cu=0,mis=0,r=15,dep=0,og=1,plh=1233283356,tim=1839710442343
WAIT #12: nam='SQL*Net message from client' ela= 6686 driver id=1413697536 #bytes=1 p3=0 obj#=99705 tim=1839710476663
WAIT #12: nam='SQL*Net message to client' ela= 1 driver id=1413697536 #bytes=1 p3=0 obj#=99705 tim=1839710476744
FETCH #12:c=0,e=0,p=0,cr=2,cu=0,mis=0,r=15,dep=0,og=1,plh=1233283356,tim=1839710473594
WAIT #12: nam='SQL*Net message from client' ela= 7580 driver id=1413697536 #bytes=1 p3=0 obj#=99705 tim=1839710484439
WAIT #12: nam='SQL*Net message to client' ela= 1 driver id=1413697536 #bytes=1 p3=0 obj#=99705 tim=1839710484478
FETCH #12:c=0,e=0,p=0,cr=2,cu=0,mis=0,r=9,dep=0,og=1,plh=1233283356,tim=1839710473594
STAT #12 id=1 cnt=100 pid=0 pos=1 obj=99705 op='TABLE ACCESS BY INDEX ROWID T10 (cr=18 pr=4 pw=0 time=0 us cost=4 size=11000 card=100)'
STAT #12 id=2 cnt=100 pid=1 pos=1 obj=99707 op='INDEX RANGE SCAN IND_T10_C2 (cr=9 pr=2 pw=0 time=0 us cost=2 size=0 card=100)'
WAIT #12: nam='SQL*Net message from client' ela= 4803 driver id=1413697536 #bytes=1 p3=0 obj#=99705 tim=1839710489408
CLOSE #12:c=0,e=0,dep=0,type=0,tim=1839710473594
...

The above trace file section again shows the OBJECT_ID value, not the DATA_OBJECT_ID value.  Maybe the single block reads just do not follow the pattern shown in the documentation – the documentation example showed a “db file scattered read wait” event.  Let’s change the DATA_OBJECT_ID value for the table by truncating the table and re-insert the 100,000 rows so that we will be able to test a multi-block read wait event:

SELECT
  OBJECT_NAME,
  OBJECT_ID,
  DATA_OBJECT_ID
FROM
  DBA_OBJECTS
WHERE
  OBJECT_NAME='T10'
  AND OWNER=USER;

OBJECT_NAME   OBJECT_ID DATA_OBJECT_ID
------------ ---------- --------------
T10               99705          99705

TRUNCATE TABLE T10;

SELECT
  OBJECT_NAME,
  OBJECT_ID,
  DATA_OBJECT_ID
FROM
  DBA_OBJECTS
WHERE
  OBJECT_NAME='T10'
  AND OWNER=USER;

OBJECT_NAME   OBJECT_ID DATA_OBJECT_ID
------------ ---------- --------------
T10               99705          99712

INSERT INTO
  T10
SELECT
  ROWNUM,
  ROWNUM,
  LPAD('A',100,'A')
FROM
  DUAL
CONNECT BY
  LEVEL<=100000;

COMMIT;

EXEC DBMS_STATS.GATHER_TABLE_STATS(OWNNAME=>USER,TABNAME=>'T10',CASCADE=>TRUE)

ALTER SYSTEM FLUSH BUFFER_CACHE;
ALTER SYSTEM FLUSH BUFFER_CACHE;

Now, let’s repeat the test script, forcing a full table scan (ROWNUM is used to terminate the full table scan as soon as 100 rows are retrieved):

ALTER SESSION SET TRACEFILE_IDENTIFIER = 'TESTING_OBJECTID4';
ALTER SESSION SET EVENTS '10046 TRACE NAME CONTEXT FOREVER, LEVEL 12';

SELECT /*+ FULL(T10) */
  *
FROM
  T10
WHERE
  C1 BETWEEN 1 AND 100
  AND ROWNUM<=100;

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

If we look inside the TESTING_OBJECTID4 trace file, we will probably see something that looks like this (the obj# for the table is highlighted in orange):

...
PARSING IN CURSOR #7 len=85 dep=0 uid=60 oct=3 lid=60 tim=1843785745036 hv=934747497 ad='1e3459a0' sqlid='4mv0qgcvvf7b9'
SELECT /*+ FULL(T10) */
  *
FROM
  T10
WHERE
  C1 BETWEEN 1 AND 100
  AND ROWNUM<=100
END OF STMT
PARSE #7:c=0,e=0,p=0,cr=0,cu=0,mis=1,r=0,dep=0,og=1,plh=548010678,tim=1843785745036
EXEC #7:c=0,e=0,p=0,cr=0,cu=0,mis=0,r=0,dep=0,og=1,plh=548010678,tim=1843785745036
WAIT #7: nam='SQL*Net message to client' ela= 3 driver id=1413697536 #bytes=1 p3=0 obj#=376 tim=1843785748938
WAIT #7: nam='db file sequential read' ela= 12046 file#=5 block#=1321962 blocks=1 obj#=99705 tim=1843785761044
WAIT #7: nam='db file scattered read' ela= 584 file#=5 block#=1321963 blocks=5 obj#=99705 tim=1843785761743
FETCH #7:c=0,e=7583,p=6,cr=5,cu=0,mis=0,r=1,dep=0,og=1,plh=548010678,tim=1843785752619
WAIT #7: nam='SQL*Net message from client' ela= 312 driver id=1413697536 #bytes=1 p3=0 obj#=99705 tim=1843785762170
WAIT #7: nam='SQL*Net message to client' ela= 1 driver id=1413697536 #bytes=1 p3=0 obj#=99705 tim=1843785762216
FETCH #7:c=0,e=0,p=0,cr=1,cu=0,mis=0,r=15,dep=0,og=1,plh=548010678,tim=1843785752619
WAIT #7: nam='SQL*Net message from client' ela= 6205 driver id=1413697536 #bytes=1 p3=0 obj#=99705 tim=1843785768477
WAIT #7: nam='SQL*Net message to client' ela= 3 driver id=1413697536 #bytes=1 p3=0 obj#=99705 tim=1843785768573
FETCH #7:c=0,e=0,p=0,cr=1,cu=0,mis=0,r=15,dep=0,og=1,plh=548010678,tim=1843785752619
WAIT #7: nam='SQL*Net message from client' ela= 5615 driver id=1413697536 #bytes=1 p3=0 obj#=99705 tim=1843785774285
WAIT #7: nam='SQL*Net message to client' ela= 2 driver id=1413697536 #bytes=1 p3=0 obj#=99705 tim=1843785774368
FETCH #7:c=0,e=0,p=0,cr=1,cu=0,mis=0,r=15,dep=0,og=1,plh=548010678,tim=1843785752619
WAIT #7: nam='SQL*Net message from client' ela= 5314 driver id=1413697536 #bytes=1 p3=0 obj#=99705 tim=1843785779776
WAIT #7: nam='SQL*Net message to client' ela= 3 driver id=1413697536 #bytes=1 p3=0 obj#=99705 tim=1843785779888
FETCH #7:c=0,e=0,p=0,cr=1,cu=0,mis=0,r=15,dep=0,og=1,plh=548010678,tim=1843785752619
WAIT #7: nam='SQL*Net message from client' ela= 5731 driver id=1413697536 #bytes=1 p3=0 obj#=99705 tim=1843785785718
WAIT #7: nam='SQL*Net message to client' ela= 2 driver id=1413697536 #bytes=1 p3=0 obj#=99705 tim=1843785785826
FETCH #7:c=0,e=0,p=0,cr=2,cu=0,mis=0,r=15,dep=0,og=1,plh=548010678,tim=1843785783865
WAIT #7: nam='SQL*Net message from client' ela= 5572 driver id=1413697536 #bytes=1 p3=0 obj#=99705 tim=1843785791470
WAIT #7: nam='SQL*Net message to client' ela= 1 driver id=1413697536 #bytes=1 p3=0 obj#=99705 tim=1843785791505
FETCH #7:c=0,e=0,p=0,cr=1,cu=0,mis=0,r=15,dep=0,og=1,plh=548010678,tim=1843785783865
WAIT #7: nam='SQL*Net message from client' ela= 6224 driver id=1413697536 #bytes=1 p3=0 obj#=99705 tim=1843785797784
WAIT #7: nam='SQL*Net message to client' ela= 1 driver id=1413697536 #bytes=1 p3=0 obj#=99705 tim=1843785797874
FETCH #7:c=0,e=0,p=0,cr=1,cu=0,mis=0,r=9,dep=0,og=1,plh=548010678,tim=1843785783865
STAT #7 id=1 cnt=100 pid=0 pos=1 obj=0 op='COUNT STOPKEY (cr=13 pr=6 pw=0 time=0 us)'
STAT #7 id=2 cnt=100 pid=1 pos=1 obj=99705 op='TABLE ACCESS FULL T10 (cr=13 pr=6 pw=0 time=0 us cost=199 size=11000 card=100)'
WAIT #7: nam='SQL*Net message from client' ela= 4043 driver id=1413697536 #bytes=1 p3=0 obj#=99705 tim=1843785802044
CLOSE #7:c=0,e=0,dep=0,type=0,tim=1843785783865
WAIT #0: nam='SQL*Net message to client' ela= 1 driver id=1413697536 #bytes=1 p3=0 obj#=99705 tim=1843785802117
WAIT #0: nam='SQL*Net message from client' ela= 877475 driver id=1413697536 #bytes=1 p3=0 obj#=99705 tim=1843786679612
...

The above trace file section again shows the OBJECT_ID value, not the DATA_OBJECT_ID value – even for the “db file scattered read” wait event.  The documentation reference must not apply to 10046 trace files.

Now let’s test V$SESSION – the view mentioned in the Oracle Performance Tuning Guide.  We will need 2 sessions for this test.   First, let’s insert 1,000,000 rows into the test table so that it takes a little longer to select the rows from the table (allowing us to check on the session’s wait events using a second session), and then determine the SID for the first session:

Session 1:

INSERT INTO
  T10
SELECT
  ROWNUM+100000,
  ROWNUM+100000,
  LPAD('A',100,'A')
FROM
  DUAL
CONNECT BY
  LEVEL<=1000000;

COMMIT;

SELECT DISTINCT SID FROM V$MYSTAT;

SID
---
302

ALTER SYSTEM FLUSH BUFFER_CACHE;
ALTER SYSTEM FLUSH BUFFER_CACHE;

SET AUTOTRACE TRACEONLY STATISTICS
SET ARRAYSIZE 5000

The SID for session 1 is 302, so in Session 2 we will prepare to repeatedly execute the following SQL statement:

Session 2:

SELECT
  EVENT,
  ROW_WAIT_OBJ#
FROM
  V$SESSION
WHERE
  SID=302;

In Session 1, let’s start executing our SQL statement, and immediately jump into Session 2 to start querying V$SESSION:

Session 1:

SELECT
  *
FROM
  T10;

Session 2:

SELECT
  EVENT,
  ROW_WAIT_OBJ#
FROM
  V$SESSION
WHERE
  SID=302;

EVENT                          ROW_WAIT_OBJ#
------------------------------ -------------
SQL*Net message from client            99705

SQL> /

EVENT                          ROW_WAIT_OBJ#
------------------------------ -------------
SQL*Net message from client            99705

SQL> /

EVENT                          ROW_WAIT_OBJ#
------------------------------ -------------
db file sequential read                99705
 
SQL> /

EVENT                          ROW_WAIT_OBJ#
------------------------------ -------------
SQL*Net message from client            99705
...
SQL> /

EVENT                          ROW_WAIT_OBJ#
------------------------------ -------------
direct path read                       99705
 
SQL> /

EVENT                          ROW_WAIT_OBJ#
------------------------------ -------------
direct path read                       99705
 
SQL> /

EVENT                          ROW_WAIT_OBJ#
------------------------------ -------------
SQL*Net message from client            99705

Notice in the above that V$SESSION shows the OBJECT_ID for table T10, not the DATA_OBJECT_ID as described in the 11.2.0.1 Performance Tuning Guide.  Maybe it is just the “db file sequential read” and “direct path read” wait events (obviously, this test was performed in 11g or above due to the “direct path read” wait events, specifically 11.1.0.7) that show the OBJECT_ID – the example from the Performance Tuning Guide showed a lookup that involved a “db file scattered read” wait event.  Let’s see if that wait event is handled differently in V$SESSION than the  “db file sequential read” and “direct path read” wait events.  We will need to set event 10949 in the session to disable the direct path reads for the full table scan:

Session 1:

ALTER SESSION SET DB_FILE_MULTIBLOCK_READ_COUNT=16;
ALTER SESSION SET EVENTS '10949 TRACE NAME CONTEXT FOREVER, LEVEL 1';

ALTER SYSTEM FLUSH BUFFER_CACHE;
ALTER SYSTEM FLUSH BUFFER_CACHE;

SELECT
  *
FROM
  T10;

Session 2:

SQL> /

EVENT                          ROW_WAIT_OBJ#
------------------------------ -------------
SQL*Net message from client            99705

SQL> /

EVENT                          ROW_WAIT_OBJ#
------------------------------ -------------
SQL*Net message from client            99705

SQL> /

EVENT                          ROW_WAIT_OBJ#
------------------------------ -------------
db file scattered read                 99705

SQL> /

EVENT                          ROW_WAIT_OBJ#
------------------------------ -------------
db file scattered read                 99705

SQL> /

EVENT                          ROW_WAIT_OBJ#
------------------------------ -------------
db file scattered read                 99705
 
SQL> /

EVENT                          ROW_WAIT_OBJ#
------------------------------ -------------
SQL*Net more data to client            99705

We are still seeing the OBJECT_ID of table T10, and not the DATA_OBJECT_ID in the query of V$SESSION.  Just to make certain that nothing strange happened where the DATA_OBJECT_ID reverted back to the OBJECT_ID value:

SELECT
  OBJECT_NAME,
  OBJECT_ID,
  DATA_OBJECT_ID
FROM
  DBA_OBJECTS
WHERE
  OBJECT_NAME='T10'
  AND OWNER=USER;

OBJECT_NAME   OBJECT_ID DATA_OBJECT_ID
------------ ---------- --------------
T10               99705          99712

Is this the third documentation bug that was mentioned in articles of this blog (bug number 2 was identified by Chris Antognini just a couple of days ago)?  Maybe things change with partitioned objects?  What better way to determine what happens than to set up a test case?

CREATE TABLE T11
  PARTITION BY RANGE(C1)
   (PARTITION P1 VALUES LESS THAN (5),
    PARTITION P2 VALUES LESS THAN (10),
    PARTITION P3 VALUES LESS THAN (20),
    PARTITION P4 VALUES LESS THAN (40),
    PARTITION P5 VALUES LESS THAN (80),
    PARTITION P6 VALUES LESS THAN (160),
    PARTITION P7 VALUES LESS THAN (320),
    PARTITION P8 VALUES LESS THAN (640),
    PARTITION P9 VALUES LESS THAN (1280),
    PARTITION P10 VALUES LESS THAN (2560),
    PARTITION P11 VALUES LESS THAN (5120),
    PARTITION P12 VALUES LESS THAN (10240),
    PARTITION P20 VALUES LESS THAN (MAXVALUE))
AS
SELECT
  ROWNUM C1,
  ROWNUM C2,
  LPAD('A',100,'A') C3
FROM
  DUAL
CONNECT BY
  LEVEL<=1000000;

COMMIT;

EXEC DBMS_STATS.GATHER_TABLE_STATS(OWNNAME=>USER,TABNAME=>'T11',CASCADE=>TRUE)

Let’s take a look at the OBJECT_IDs and DATA_OBJECT_IDs for this table (note that I have switched from Oracle Database 11.1.0.7 to 11.2.0.1 running on a different server):

SELECT
  OBJECT_NAME,
  SUBOBJECT_NAME,
  OBJECT_ID,
  DATA_OBJECT_ID
FROM
  DBA_OBJECTS
WHERE
  OBJECT_NAME='T11'
  AND OWNER=USER
ORDER BY
  OBJECT_ID;

OBJECT_NAME  SUBOBJECT_NAME        OBJECT_ID DATA_OBJECT_ID
------------ -------------------- ---------- --------------
T11                                    77269
T11          P1                        77270          77270
T11          P2                        77271          77271
T11          P3                        77272          77272
T11          P4                        77273          77273
T11          P5                        77274          77274
T11          P6                        77275          77275
T11          P7                        77276          77276
T11          P8                        77277          77277
T11          P9                        77278          77278
T11          P10                       77279          77279
T11          P11                       77280          77280
T11          P12                       77281          77281
T11          P20                       77282          77282

We start out with the OBJECT_ID and DATA_OBJECT_IDs having the same values, and then we truncate the table and check again:

TRUNCATE TABLE T11;

INSERT INTO
  T11
SELECT
  ROWNUM C1,
  ROWNUM C2,
  LPAD('A',100,'A') C3
FROM
  DUAL
CONNECT BY
  LEVEL<=1000000;

COMMIT;

SELECT
  OBJECT_NAME,
  SUBOBJECT_NAME,
  OBJECT_ID,
  DATA_OBJECT_ID
FROM
  DBA_OBJECTS
WHERE
  OBJECT_NAME='T11'
  AND OWNER=USER
ORDER BY
  OBJECT_ID;

OBJECT_NAME  SUBOBJECT_NAME        OBJECT_ID DATA_OBJECT_ID
------------ -------------------- ---------- --------------
T11                                    77269
T11          P1                        77270          77283
T11          P2                        77271          77284
T11          P3                        77272          77285
T11          P4                        77273          77286
T11          P5                        77274          77287
T11          P6                        77275          77288
T11          P7                        77276          77289
T11          P8                        77277          77290
T11          P9                        77278          77291
T11          P10                       77279          77292
T11          P11                       77280          77293
T11          P12                       77281          77294
T11          P20                       77282          77295

The values are different now, as expected.  So, we test:

ALTER SYSTEM FLUSH BUFFER_CACHE;
ALTER SYSTEM FLUSH BUFFER_CACHE;

SET AUTOTRACE TRACEONLY STATISTICS
SET ARRAYSIZE 5000

ALTER SESSION SET TRACEFILE_IDENTIFIER = 'TESTING_OBJECTID5';
ALTER SESSION SET EVENTS '10046 TRACE NAME CONTEXT FOREVER, LEVEL 12';

SELECT /*+ FULL(T11) */
  *
FROM
  T11
WHERE
  C1 BETWEEN 1 AND 1000
  AND ROWNUM<=1000;

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

From the resulting trace file:

...
PARSING IN CURSOR #14 len=87 dep=0 uid=185 oct=3 lid=185 tim=182313780472 hv=2324608198 ad='467af4a28' sqlid='bqfj36a58xd66'
SELECT /*+ FULL(T11) */
  *
FROM
  T11
WHERE
  C1 BETWEEN 1 AND 1000
  AND ROWNUM<=1000
END OF STMT
PARSE #14:c=0,e=609,p=0,cr=0,cu=0,mis=1,r=0,dep=0,og=1,plh=3101738663,tim=182313780472
EXEC #14:c=0,e=14,p=0,cr=0,cu=0,mis=0,r=0,dep=0,og=1,plh=3101738663,tim=182313780539
WAIT #14: nam='SQL*Net message to client' ela= 1 driver id=1413697536 #bytes=1 p3=0 obj#=0 tim=182313780566
WAIT #14: nam='db file sequential read' ela= 386 file#=8 block#=13442 blocks=1 obj#=77270 tim=182313780979
WAIT #14: nam='db file scattered read' ela= 537 file#=8 block#=13443 blocks=5 obj#=77270 tim=182313781641
FETCH #14:c=0,e=1146,p=6,cr=4,cu=0,mis=0,r=1,dep=0,og=1,plh=3101738663,tim=182313781727
WAIT #14: nam='SQL*Net message from client' ela= 792 driver id=1413697536 #bytes=1 p3=0 obj#=77270 tim=182313782565
WAIT #14: nam='SQL*Net message to client' ela= 0 driver id=1413697536 #bytes=1 p3=0 obj#=77270 tim=182313782595
WAIT #14: nam='db file sequential read' ela= 395 file#=8 block#=13506 blocks=1 obj#=77271 tim=182313783021
WAIT #14: nam='db file scattered read' ela= 504 file#=8 block#=13507 blocks=5 obj#=77271 tim=182313783615
WAIT #14: nam='db file sequential read' ela= 414 file#=8 block#=13826 blocks=1 obj#=77272 tim=182313784129
WAIT #14: nam='db file scattered read' ela= 506 file#=8 block#=13827 blocks=5 obj#=77272 tim=182313784724
WAIT #14: nam='db file sequential read' ela= 396 file#=8 block#=13842 blocks=1 obj#=77273 tim=182313785226
WAIT #14: nam='db file scattered read' ela= 496 file#=8 block#=13843 blocks=5 obj#=77273 tim=182313785812
WAIT #14: nam='db file sequential read' ela= 318 file#=8 block#=13858 blocks=1 obj#=77274 tim=182313786245
WAIT #14: nam='db file scattered read' ela= 457 file#=8 block#=13859 blocks=5 obj#=77274 tim=182313786809
WAIT #14: nam='db file sequential read' ela= 369 file#=8 block#=13874 blocks=1 obj#=77275 tim=182313787319
WAIT #14: nam='db file scattered read' ela= 503 file#=8 block#=13875 blocks=5 obj#=77275 tim=182313787877
WAIT #14: nam='db file sequential read' ela= 395 file#=8 block#=13890 blocks=1 obj#=77276 tim=182313788447
WAIT #14: nam='db file scattered read' ela= 515 file#=8 block#=13891 blocks=5 obj#=77276 tim=182313789053
WAIT #14: nam='db file sequential read' ela= 329 file#=8 block#=13906 blocks=1 obj#=77277 tim=182313789587
WAIT #14: nam='db file scattered read' ela= 508 file#=8 block#=13907 blocks=5 obj#=77277 tim=182313790188
WAIT #14: nam='SQL*Net more data to client' ela= 34 driver id=1413697536 #bytes=8145 p3=0 obj#=77277 tim=182313790482
WAIT #14: nam='db file scattered read' ela= 558 file#=7 block#=2556696 blocks=8 obj#=77277 tim=182313791079
WAIT #14: nam='db file sequential read' ela= 371 file#=8 block#=13922 blocks=1 obj#=77278 tim=182313791521
WAIT #14: nam='db file scattered read' ela= 459 file#=8 block#=13923 blocks=5 obj#=77278 tim=182313792039
WAIT #14: nam='db file scattered read' ela= 457 file#=7 block#=2556720 blocks=8 obj#=77278 tim=182313792800
FETCH #14:c=0,e=10366,p=64,cr=76,cu=0,mis=0,r=999,dep=0,og=1,plh=3101738663,tim=182313792954
STAT #14 id=1 cnt=1000 pid=0 pos=1 obj=0 op='COUNT STOPKEY (cr=80 pr=70 pw=0 time=570 us)'
STAT #14 id=2 cnt=1000 pid=1 pos=1 obj=0 op='PARTITION RANGE ITERATOR PARTITION: 1 9 (cr=80 pr=70 pw=0 time=570 us cost=16 size=111000 card=1000)'
STAT #14 id=3 cnt=1000 pid=2 pos=1 obj=77269 op='TABLE ACCESS FULL T11 PARTITION: 1 9 (cr=80 pr=70 pw=0 time=353 us cost=16 size=111000 card=1000)'
WAIT #14: nam='SQL*Net message from client' ela= 4472 driver id=1413697536 #bytes=1 p3=0 obj#=77278 tim=182313797501
CLOSE #14:c=0,e=9,dep=0,type=0,tim=182313818474
...

———————–

The 10046 trace files shows the OBJECT_ID column of DBA_OBJECTS, not the DATA_OBJECT_ID column as seen in the tests that used both unpartitioned and partitioned tables.  This documentation bug has been bugging me for at least four and a half years, but probably longer than that – I just thought it was worth briefly mentioning the problem.

10046 Extended SQL Trace Interpretation 3

September 6, 2010

(Back to the Previous Post in the Series)

In previous blog articles in this series we looked at various methods for starting a 10046 trace file and also the basics of walking through a trace file.  Today’s blog article continues the investigation of 10046 trace files.  To begin, we need a test script:

CREATE TABLE T3_1 AS
SELECT
  ROWNUM C1,
  LPAD('A',100,'A') C2
FROM
  DUAL
CONNECT BY
  LEVEL<=10000;

CREATE TABLE T4_1 AS
SELECT
  ROWNUM C1,
  LPAD('A',100,'A') C2
FROM
  DUAL
CONNECT BY
  LEVEL<=10000;

CREATE INDEX IND_T4_1 ON T4_1(C1);

EXEC DBMS_STATS.GATHER_TABLE_STATS(OWNNAME=>USER,TABNAME=>'T3_1',CASCADE=>TRUE)
EXEC DBMS_STATS.GATHER_TABLE_STATS(OWNNAME=>USER,TABNAME=>'T4_1',CASCADE=>TRUE)

ALTER SYSTEM FLUSH BUFFER_CACHE;
ALTER SYSTEM FLUSH BUFFER_CACHE;
SET ARRAYSIZE 15
SET AUTOTRACE TRACEONLY STATISTICS

VARIABLE N1 NUMBER
VARIABLE N2 NUMBER

EXEC :N1 := 1
EXEC :N2 := 2

ALTER SESSION SET TRACEFILE_IDENTIFIER = '10046TraceTest';
EXEC DBMS_SESSION.SESSION_TRACE_ENABLE(WAITS=>TRUE, BINDS=>TRUE, PLAN_STAT=>'ALL_EXECUTIONS')

SELECT
  T3_1.C1, T4_1.C2
FROM
  T3_1, T4_1
WHERE
  T3_1.C1 BETWEEN :N1 AND :N2
  AND T3_1.C1=T4_1.C1;

EXEC :N2 := 10000
SET ARRAYSIZE 500

SELECT
  T3_1.C1, T4_1.C2
FROM
  T3_1, T4_1
WHERE
  T3_1.C1 BETWEEN :N1 AND :N2
  AND T3_1.C1=T4_1.C1;

SELECT SYSDATE FROM DUAL;

EXEC DBMS_SESSION.SESSION_TRACE_DISABLE;

EXEC DBMS_STATS.GATHER_TABLE_STATS(OWNNAME=>USER,TABNAME=>'T3_1',CASCADE=>TRUE)
EXEC DBMS_STATS.GATHER_TABLE_STATS(OWNNAME=>USER,TABNAME=>'T4_1',CASCADE=>TRUE)

ALTER SYSTEM FLUSH BUFFER_CACHE;
ALTER SYSTEM FLUSH BUFFER_CACHE;
SET ARRAYSIZE 15
SET AUTOTRACE TRACEONLY STATISTICS

VARIABLE N1 NUMBER
VARIABLE N2 NUMBER

EXEC :N1 := 1
EXEC :N2 := 2

ALTER SESSION SET TRACEFILE_IDENTIFIER = '10046TraceTest2';
EXEC DBMS_SESSION.SESSION_TRACE_ENABLE(WAITS=>TRUE, BINDS=>TRUE, PLAN_STAT=>'ALL_EXECUTIONS')

SELECT
  T3_1.C1, T4_1.C2
FROM
  T3_1, T4_1
WHERE
  T3_1.C1 BETWEEN :N1 AND :N2
  AND T3_1.C1=T4_1.C1;

EXEC :N2 := 10000
SET ARRAYSIZE 500

SELECT
  T3_1.C1, T4_1.C2
FROM
  T3_1, T4_1
WHERE
  T3_1.C1 BETWEEN :N1 AND :N2
  AND T3_1.C1=T4_1.C1;

SELECT SYSDATE FROM DUAL;

EXEC DBMS_SESSION.SESSION_TRACE_DISABLE;

The above test script:

• Creates two tables.
• Creates an index is created on the second table.
• Table and index statistics are collected (the index statistics would already exist on Oracle Database 10.1 and above, as the statistics are calculated automatically during index creation).
• The buffer cache is flushed twice to force physical reads when the test SQL statements are performed.
• Two bind variables are defined.
• The trace file to be created is named.
• 10046 tracing at level 12 is enabled for the session, specifying that the execution plan should be written after each execution of the SQL statement, rather when that cursor is closed (the PLAN_STAT parameter is only valid in Oracle Database 11.1 and above).
• A SQL statement using the bind variables is executed with the array fetch size set at the SQL*Plus default of 15.
• The value of the second bind variable is increased from 2 (a very small number) to 10,000 (a very large number for the tables involved).
• The array fetch size is increased from the default value of 15 to a value of 500.
• The SQL statement is executed again with the new bind variable values.
• A simple SQL statement is executed to force the closing of the previous SQL statement and the printing of the execution plan to the trace file (this is needed prior to Oracle Database 11.1, or when the PLAN_STAT parameter is not set to the default value of ALL_EXECUTIONS – note that the SQL statement being added to the session cursor cache after three executions may prevent the execution plan from being written to the trace file unless the PLAN_STAT parameter is set to ALL_EXECUTIONS).
• The test is repeated a second time with a different name specified for the trace file.

The above script was executed on Oracle Database 11.2.0.1, on a platform that only supports direct, asynchronous I/O (equivalent to setting the FILESYSTEMIO_OPTIONS initialization parameter to SETALL).  The direct, asynchronous I/O configuration prevents an operating system level file cache from speeding up the access to the physical data files (the OS would be able to completely avoid accessing the disks if an O.S. level file cache were used).  Let’s start by looking at the statistics that were output by AUTOTRACE:

N1 = 1, N2 = 2, first execution:

Statistics
--------------------------------------------
  1  recursive calls
  0  db block gets
163  consistent gets
164  physical reads
  0  redo size
840  bytes sent via SQL*Net to client
520  bytes received via SQL*Net from client
  2  SQL*Net roundtrips to/from client
  0  sorts (memory)
  0  sorts (disk)
  2  rows processed

Interesting, the number of physical blocks read from disk (164) exceeds the number of consistent gets (163) plus the current mode gets (db block gets = 0).  No redo was generated (redo generated on a SELECT might be caused by delayed block cleanout).  840 bytes were sent back to the client, and the server received 520 bytes from the client.  Two round trips were performed in order to retrieve two rows from the database (even though the array fetch size was set to 15).  There was also a single recursive call, probably during the hard parse of the SQL statement.

—

N1 = 1, N2 = 10,000, first execution:

Statistics
----------------------------------------------
    0  recursive calls
    0  db block gets
  374  consistent gets
  188  physical reads
    0  redo size
94102  bytes sent via SQL*Net to client
  729  bytes received via SQL*Net from client
   21  SQL*Net roundtrips to/from client
    0  sorts (memory)
    0  sorts (disk)
10000  rows processed

The number of recursive calls dropped from one to zero (probably because a hard parse was not required).  The number of consistent gets (blocks) is now roughly double the number of physical reads (blocks).  94,102 bytes were sent back to the client, and the server received 729 bytes from the client.  Twenty-one round trips were performed to retrieve the 10,000 rows, and there are still no sorts in memory or on disk.

—

N1 = 1, N2 = 2, second execution:

Statistics
--------------------------------------------
  1  recursive calls
  0  db block gets
163  consistent gets
171  physical reads
  0  redo size
840  bytes sent via SQL*Net to client
520  bytes received via SQL*Net from client
  2  SQL*Net roundtrips to/from client
  0  sorts (memory)
  0  sorts (disk)
  2  rows processed

On the second execution with the N2 bind variable reset to a value of 2 we see another recursive call (maybe another hard parse?).  Again, the number of physical blocks read from disk (171 – seven more than earlier) exceeds the number of consistent gets (163 – the same as earlier) plus the number of current mode gets (db block gets = 0).

—

N1 = 1, N2 = 10,000, second execution:

Statistics
----------------------------------------------
    1  recursive calls
    0  db block gets
  336  consistent gets
  150  physical reads
    0  redo size
94102  bytes sent via SQL*Net to client
  729  bytes received via SQL*Net from client
   21  SQL*Net roundtrips to/from client
    0  sorts (memory)
    0  sorts (disk)
10000  rows processed

On the second execution with the N2 bind variable reset to a value of 10,000 we see another recursive call (maybe another hard parse?).  The number of consistent gets (336 – thirty-eight less than earlier) is a bit more than twice the number of physical block reads (150 – again thirty-eight less than earlier, and now less than what was required when N2 was set to a value of 2).  What happened, is Oracle Database 11.2.0.1 toying with our performance tuning ability?  Maybe we should look at the TKPROF output (note that this is output from 11.2.0.1 TKPROF):

tkprof or112_ora_384_10046TraceTest.trc or112_ora_384_10046TraceTest.txt

tkprof or112_ora_384_10046TraceTest2.trc or112_ora_384_10046TraceTest2.txt

TKPROF N1 = 1, N2 = 2 and N2 = 10,000, first execution:

SELECT
  T3_1.C1, T4_1.C2
FROM
  T3_1, T4_1
WHERE
  T3_1.C1 BETWEEN :N1 AND :N2
  AND T3_1.C1=T4_1.C1

call     count       cpu    elapsed       disk      query    current        rows
------- ------  -------- ---------- ---------- ---------- ----------  ----------
Parse        2      0.00       0.00          0          0          0           0
Execute      2      0.00       0.00          0          0          0           0
Fetch       23      0.01       0.20        352        537          0       10002
------- ------  -------- ---------- ---------- ---------- ----------  ----------
total       27      0.01       0.20        352        537          0       10002

Misses in library cache during parse: 1
Misses in library cache during execute: 1
Optimizer mode: ALL_ROWS
Parsing user id: 90 

Rows     Row Source Operation
-------  ---------------------------------------------------
      2  FILTER  (cr=163 pr=164 pw=0 time=0 us)
      2   HASH JOIN  (cr=163 pr=164 pw=0 time=0 us cost=51 size=109 card=1)
      2    TABLE ACCESS FULL T3_1 (cr=158 pr=155 pw=0 time=0 us cost=47 size=8 card=2)
      2    TABLE ACCESS BY INDEX ROWID T4_1 (cr=5 pr=9 pw=0 time=0 us cost=3 size=210 card=2)
      2     INDEX RANGE SCAN IND_T4_1 (cr=3 pr=8 pw=0 time=4 us cost=2 size=0 card=2)(object id 83176)

Elapsed times include waiting on following events:
  Event waited on                             Times   Max. Wait  Total Waited
  ----------------------------------------   Waited  ----------  ------------
  SQL*Net message to client                      23        0.00          0.00
  db file sequential read                         2        0.00          0.00
  db file scattered read                         42        0.02          0.18
  SQL*Net message from client                    23        0.03          0.05

Assuming that TKPROF from the Oracle 11.1.0.6 client was not used, the above indicates that the same execution plan was used when C2 was set to 2 and also when it was set to 10,000.  Because the execution plan was written after each execution, the execution plan provided by TKPROF is a little confusing when trying to cross-reference the statistics to see exactly what happened.  The statistics show that 10,002 rows were retrieved in 0.20 seconds with 537 consistent gets and 352 blocks read from disk, while the execution plan shows that 2 rows were retrieved in 0.000000 seconds with 163 consistent gets and 164 blocks read from disk.  The summarized wait events in this case cannot be correlated to the lines in the execution plan because TKPROF only printed the first execution plan found in the trace file for the query.

TKPROF N1 = 1, N2 = 2 and N2 = 10,000, second execution:

SELECT
  T3_1.C1, T4_1.C2
FROM
  T3_1, T4_1
WHERE
  T3_1.C1 BETWEEN :N1 AND :N2
  AND T3_1.C1=T4_1.C1

call     count       cpu    elapsed       disk      query    current        rows
------- ------  -------- ---------- ---------- ---------- ----------  ----------
Parse        1      0.00       0.00          0          0          0           0
Execute      1      0.00       0.00          0          0          0           0
Fetch        2      0.00       0.00        171        163          0           2
------- ------  -------- ---------- ---------- ---------- ----------  ----------
total        4      0.00       0.00        171        163          0           2

Misses in library cache during parse: 0
Misses in library cache during execute: 1
Optimizer mode: ALL_ROWS
Parsing user id: 90 

Rows     Row Source Operation
-------  ---------------------------------------------------
      2  FILTER  (cr=163 pr=171 pw=0 time=0 us)
      2   HASH JOIN  (cr=163 pr=171 pw=0 time=0 us cost=51 size=109 card=1)
      2    TABLE ACCESS FULL T3_1 (cr=158 pr=155 pw=0 time=1 us cost=47 size=8 card=2)
      2    TABLE ACCESS BY INDEX ROWID T4_1 (cr=5 pr=16 pw=0 time=0 us cost=3 size=210 card=2)
      2     INDEX RANGE SCAN IND_T4_1 (cr=3 pr=8 pw=0 time=4 us cost=2 size=0 card=2)(object id 83176)

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

SELECT
  T3_1.C1, T4_1.C2
FROM
  T3_1, T4_1
WHERE
  T3_1.C1 BETWEEN :N1 AND :N2
  AND T3_1.C1=T4_1.C1

call     count       cpu    elapsed       disk      query    current        rows
------- ------  -------- ---------- ---------- ---------- ----------  ----------
Parse        1      0.00       0.00          0          0          0           0
Execute      1      0.00       0.00          0          0          0           0
Fetch       21      0.03       0.01        150        336          0       10000
------- ------  -------- ---------- ---------- ---------- ----------  ----------
total       23      0.03       0.01        150        336          0       10000

Misses in library cache during parse: 0
Misses in library cache during execute: 1
Optimizer mode: ALL_ROWS
Parsing user id: 90 

Rows     Row Source Operation
-------  ---------------------------------------------------
  10000  FILTER  (cr=336 pr=150 pw=0 time=4999 us)
  10000   HASH JOIN  (cr=336 pr=150 pw=0 time=4486 us cost=95 size=1090000 card=10000)
  10000    TABLE ACCESS FULL T3_1 (cr=158 pr=0 pw=0 time=1265 us cost=47 size=40000 card=10000)
  10000    TABLE ACCESS FULL T4_1 (cr=178 pr=150 pw=0 time=1410 us cost=47 size=1050000 card=10000)

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

Because we used the 11.2.0.1 client, TKPROF clearly shows that the execution plan changed during the second execution when the value of N2 changed from 2 to 10,000.  With the two execution plans and a single execution with each value of N2 we are able to cross-reference the various statistics. 

With N2 at a value of 2, we see that:

• 163 blocks were obtained from memory using consist gets, 3 of which belonged to the IND_T4_1 index, 2 of which belonged to the T4_1 table, and 158 of which belonged to the T3_1 table.
• 171 blocks were read from disk, 8 of which belonged to the IND_T4_1 index, 8 of which belonged to the T4_1 table, and 155 of which belonged to the T3_1 table.
• There was only 1 single block read, with 19 of the 20 physical read events performed using multi-block reads with an average of 8.95 blocks read per multi-block read [(171 – 1)/19].
• The total physical read time per the wait events is 0.00 seconds.  The elapsed time and CPU time per the statistics summary is 0.00 seconds.

With N2 at a value of 10,000, we see that:

• 336 blocks were obtained from memory using consist gets, 0 of which belonged to the IND_T4_1 index, 178 of which belonged to the T4_1 table, and 158 of which belonged to the T3_1 table.
• 150 blocks were read from disk, 0 of which belonged to the IND_T4_1 index, 150 of which belonged to the T4_1 table, and 0 of which belonged to the T3_1 table.
• There was only 1 single block read, with 16 of the 17 physical read events performed using multi-block reads with an average of 9.31 blocks read per multi-block read [(150 – 1) / 16].
• The total physical read time per the wait events is 0.00 seconds.  The elapsed time and CPU time per the statistics summary is 0.01 seconds and 0.03 seconds, respectively.

The TKPROF summaries are nice, but there is still a missing element – detail.  Before we dive into the raw 10046 trace, let’s find the OBJECT_ID and DATA_OBJECT_ID for the various objects in our test:

SELECT
  OBJECT_NAME,
  OBJECT_ID,
  DATA_OBJECT_ID
FROM
  DBA_OBJECTS
WHERE
  OBJECT_NAME IN ('T3_1','T4_1','IND_T4_1');

OBJECT_NAME  OBJECT_ID DATA_OBJECT_ID
----------- ---------- --------------
T3_1             83174          83174
T4_1             83175          83175
IND_T4_1         83176          83176

As we saw in the execution plan earlier, 83176 represents the IND_T4_1 index.  83174 represents table T3_1, and 83175 represents table T4_1.  The objects were created in an ASSM autoallocate tablespace.  Now the raw 10046 trace files.

First execution 10046 trace file, with comments:

=====================
PARSING IN CURSOR #15 len=101 dep=0 uid=90 oct=3 lid=90 tim=774686889 hv=3458052021 ad='36ce14150' sqlid='4122a6m71vbxp'
SELECT
  T3_1.C1, T4_1.C2
FROM
  T3_1, T4_1
WHERE
  T3_1.C1 BETWEEN :N1 AND :N2
  AND T3_1.C1=T4_1.C1
END OF STMT
PARSE #15:c=0,e=122,p=0,cr=0,cu=0,mis=1,r=0,dep=0,og=1,plh=0,tim=774686889
BINDS #15:
 Bind#0
  oacdty=02 mxl=22(22) mxlc=00 mal=00 scl=00 pre=00
  oacflg=03 fl2=1000000 frm=00 csi=00 siz=48 off=0
  kxsbbbfp=1e8e0aa8  bln=22  avl=02  flg=05
  value=1
 Bind#1
  oacdty=02 mxl=22(22) mxlc=00 mal=00 scl=00 pre=00
  oacflg=03 fl2=1000000 frm=00 csi=00 siz=0 off=24
  kxsbbbfp=1e8e0ac0  bln=22  avl=02  flg=01
  value=2

From the above, the parse call required 0.000122 seconds to perform a hard parse using an optimizer goal of 1 (ALL_ROWS), and two numeric bind variables were provided.  The SQL_ID and HASH_VALUE are also displayed (these may be used to retrieve a DBMS_XPLAN formatted version of the execution plan).  Continuing with the 10046 trace file:

EXEC #15:c=0,e=705,p=0,cr=0,cu=0,mis=1,r=0,dep=0,og=1,plh=39991016,tim=774687655
WAIT #15: nam='SQL*Net message to client' ela= 0 driver id=1413697536 #bytes=1 p3=0 obj#=0 tim=774687683
WAIT #15: nam='db file sequential read' ela= 93 file#=7 block#=1819466 blocks=1 obj#=83174 tim=774687866
WAIT #15: nam='db file scattered read' ela= 25845 file#=7 block#=1819467 blocks=5 obj#=83174 tim=774713774
WAIT #15: nam='db file scattered read' ela= 1443 file#=7 block#=1819472 blocks=8 obj#=83174 tim=774715430
WAIT #15: nam='db file scattered read' ela= 13640 file#=7 block#=1819481 blocks=7 obj#=83174 tim=774729168
WAIT #15: nam='db file scattered read' ela= 1788 file#=7 block#=1819488 blocks=8 obj#=83174 tim=774731067
WAIT #15: nam='db file scattered read' ela= 1372 file#=7 block#=1819497 blocks=7 obj#=83174 tim=774732504
WAIT #15: nam='db file scattered read' ela= 926 file#=7 block#=1819504 blocks=8 obj#=83174 tim=774733534
WAIT #15: nam='db file scattered read' ela= 685 file#=7 block#=1819513 blocks=7 obj#=83174 tim=774734310
WAIT #15: nam='db file scattered read' ela= 25768 file#=8 block#=214144 blocks=8 obj#=83174 tim=774760171
WAIT #15: nam='db file scattered read' ela= 1079 file#=8 block#=214153 blocks=7 obj#=83174 tim=774761358
WAIT #15: nam='db file scattered read' ela= 1044 file#=8 block#=214160 blocks=8 obj#=83174 tim=774762502
WAIT #15: nam='db file scattered read' ela= 896 file#=8 block#=214169 blocks=7 obj#=83174 tim=774763509
WAIT #15: nam='db file scattered read' ela= 1184 file#=8 block#=214176 blocks=8 obj#=83174 tim=774764754
WAIT #15: nam='db file scattered read' ela= 1816 file#=8 block#=214185 blocks=7 obj#=83174 tim=774766671
WAIT #15: nam='db file scattered read' ela= 770 file#=8 block#=214192 blocks=8 obj#=83174 tim=774767541
WAIT #15: nam='db file scattered read' ela= 872 file#=8 block#=214201 blocks=7 obj#=83174 tim=774768531
WAIT #15: nam='db file scattered read' ela= 899 file#=8 block#=214208 blocks=8 obj#=83174 tim=774769526
WAIT #15: nam='db file scattered read' ela= 2080 file#=7 block#=1819522 blocks=36 obj#=83174 tim=774771767
WAIT #15: nam='db file scattered read' ela= 24065 file#=7 block#=1819720 blocks=8 obj#=83176 tim=774796086
WAIT #15: nam='db file sequential read' ela= 303 file#=8 block#=214219 blocks=1 obj#=83175 tim=774796473
FETCH #15:c=0,e=108849,p=164,cr=161,cu=0,mis=0,r=1,dep=0,og=1,plh=39991016,tim=774796549

From the above, we see that the first fetch returned only a single row, and that fetch required 0.108849 seconds, reading 164 blocks from disk, with 161 consistent gets.  The one single block read at the start was for object 83174 (table T3_1), while the one single block read just before the fetch was for object 83175 (table T4_1).  Object 83176 (index IND_T4_1) was read using a multi-block read – not all index accesses are necessarily single block reads, although a fast full index scan will usually use multi-block reads, the execution plan shows a range scan.  What was the purpose of the two single block reads of the tables?

SELECT
  SEGMENT_NAME,
  HEADER_FILE,
  HEADER_BLOCK
FROM
  DBA_SEGMENTS
WHERE
  SEGMENT_NAME IN ('T3_1','T4_1');

SEGMENT_NAME HEADER_FILE HEADER_BLOCK
------------ ----------- ------------
T3_1                   7      1819466
T4_1                   8       214218

Comparing those numbers with the single block reads, we see that the segment header block of table T3_1 was read, and the block immediately after the segment header block of table T4_1 was read.  Notice that there is quite a bit of variation in the block read access times, ranging from 0.000093 seconds to 0.000303 seconds for a single block read and 0.000685 seconds (0.7ms) to 0.025845 seconds (25.8ms) for the multi-block reads.  While these physical read times were achieved using typical hard drives without the benefit of an operating system cache or RAID controller cache, or even a SAN cache, for the most part the times are atypically low for “spinning rust” (for example, a 15,000 RPM hard drive requires 4ms for a single rotation, the average seek time should be at least 1/2 of the single rotation time) – cache memory built into the physical drives is likely the cause of the atypically low average read times.  We see that for the most part, the multi-block reads are either 7 or 8 blocks, with a single 36 block multi-block read (the autoallocate extent size for the final extent in table T3_1 increased from the previous extent’s 64KB to 1MB, allowing for a multi-block read larger than 64KB).  The PLAN_HASH_VALUE 39991016 (visible in V$SQL) was also written to the trace file.  Continuing with the 10046 trace file:

WAIT #15: nam='SQL*Net message from client' ela= 36739 driver id=1413697536 #bytes=1 p3=0 obj#=83175 tim=774833320
WAIT #15: nam='SQL*Net message to client' ela= 0 driver id=1413697536 #bytes=1 p3=0 obj#=83175 tim=774833369
FETCH #15:c=0,e=48,p=0,cr=2,cu=0,mis=0,r=1,dep=0,og=1,plh=39991016,tim=774833406
STAT #15 id=1 cnt=2 pid=0 pos=1 obj=0 op='FILTER  (cr=163 pr=164 pw=0 time=0 us)'
STAT #15 id=2 cnt=2 pid=1 pos=1 obj=0 op='HASH JOIN  (cr=163 pr=164 pw=0 time=0 us cost=51 size=109 card=1)'
STAT #15 id=3 cnt=2 pid=2 pos=1 obj=83174 op='TABLE ACCESS FULL T3_1 (cr=158 pr=155 pw=0 time=0 us cost=47 size=8 card=2)'
STAT #15 id=4 cnt=2 pid=2 pos=2 obj=83175 op='TABLE ACCESS BY INDEX ROWID T4_1 (cr=5 pr=9 pw=0 time=0 us cost=3 size=210 card=2)'
STAT #15 id=5 cnt=2 pid=4 pos=1 obj=83176 op='INDEX RANGE SCAN IND_T4_1 (cr=3 pr=8 pw=0 time=4 us cost=2 size=0 card=2)'
WAIT #15: nam='SQL*Net message from client' ela= 455 driver id=1413697536 #bytes=1 p3=0 obj#=83175 tim=774833972
*** SESSION ID:(1232.2) 2010-09-06 10:17:12.191

CLOSE #15:c=0,e=7,dep=0,type=0,tim=774861965
=====================

From the above, we see that SQL*Plus required roughly 0.036739 seconds to process the first row that it received from the database and to request the next 15 rows.  The second fetch call, which also returned a single row, required just 0.000048 seconds and required 2 consistent gets.  If we subtract the tim= value found on the first FETCH call from the tim= value found on the second fetch call, we see that 0.036857 seconds actually elapsed, so 0.000118-0.000048 seconds = 0.000070 seconds of excution time that essentially disappeared – part of the unaccounted for time for the trace file.  Continuing with the 10046 trace file:

PARSING IN CURSOR #16 len=26 dep=0 uid=90 oct=47 lid=90 tim=774862238 hv=3000858490 ad='36ce13ac0' sqlid='56ndayftduxvu'
BEGIN :N2 := 10000; END;
END OF STMT
PARSE #16:c=0,e=223,p=0,cr=0,cu=0,mis=1,r=0,dep=0,og=1,plh=0,tim=774862237
BINDS #16:
 Bind#0
  oacdty=02 mxl=22(22) mxlc=00 mal=00 scl=00 pre=00
  oacflg=03 fl2=1000000 frm=00 csi=00 siz=24 off=0
  kxsbbbfp=1ddb9628  bln=22  avl=02  flg=05
  value=2
WAIT #16: nam='SQL*Net message to client' ela= 1 driver id=1413697536 #bytes=1 p3=0 obj#=83175 tim=774862876
EXEC #16:c=0,e=611,p=0,cr=0,cu=0,mis=1,r=1,dep=0,og=1,plh=0,tim=774862890
WAIT #16: nam='SQL*Net message from client' ela= 5694 driver id=1413697536 #bytes=1 p3=0 obj#=83175 tim=774868616
*** SESSION ID:(1232.2) 2010-09-06 10:17:12.206

CLOSE #16:c=0,e=11,dep=0,type=0,tim=774869382
=====================

In the above, SQL*Plus  changed the bind variable value from 2 to 10,000 (interesting that the old value seems to be passed in as a bind variable).  Continuing with the 10046 trace file:

PARSING IN CURSOR #17 len=101 dep=0 uid=90 oct=3 lid=90 tim=774869440 hv=3458052021 ad='36ce14150' sqlid='4122a6m71vbxp'
SELECT
  T3_1.C1, T4_1.C2
FROM
  T3_1, T4_1
WHERE
  T3_1.C1 BETWEEN :N1 AND :N2
  AND T3_1.C1=T4_1.C1
END OF STMT
PARSE #17:c=0,e=27,p=0,cr=0,cu=0,mis=0,r=0,dep=0,og=1,plh=39991016,tim=774869439
BINDS #17:
 Bind#0
  oacdty=02 mxl=22(22) mxlc=00 mal=00 scl=00 pre=00
  oacflg=03 fl2=1000000 frm=00 csi=00 siz=48 off=0
  kxsbbbfp=1e8e0aa8  bln=22  avl=02  flg=05
  value=1
 Bind#1
  oacdty=02 mxl=22(22) mxlc=00 mal=00 scl=00 pre=00
  oacflg=03 fl2=1000000 frm=00 csi=00 siz=0 off=24
  kxsbbbfp=1e8e0ac0  bln=22  avl=02  flg=01
  value=10000
EXEC #17:c=0,e=74,p=0,cr=0,cu=0,mis=0,r=0,dep=0,og=1,plh=39991016,tim=774869572
WAIT #17: nam='SQL*Net message to client' ela= 1 driver id=1413697536 #bytes=1 p3=0 obj#=83175 tim=774869596
FETCH #17:c=0,e=3430,p=0,cr=161,cu=0,mis=0,r=1,dep=0,og=1,plh=39991016,tim=774873041
WAIT #17: nam='SQL*Net message from client' ela= 133 driver id=1413697536 #bytes=1 p3=0 obj#=83175 tim=774873205
WAIT #17: nam='SQL*Net message to client' ela= 0 driver id=1413697536 #bytes=1 p3=0 obj#=83175 tim=774873238
WAIT #17: nam='db file scattered read' ela= 427 file#=8 block#=214220 blocks=4 obj#=83175 tim=774873768
WAIT #17: nam='db file scattered read' ela= 1251 file#=8 block#=214224 blocks=8 obj#=83175 tim=774875328
FETCH #17:c=0,e=2314,p=12,cr=10,cu=0,mis=0,r=500,dep=0,og=1,plh=39991016,tim=774875542

Remember here that we did not flush the buffer cache in between the execution with N2 set to 2, and when it was set to 10,000.  Notice that the first fetch of the first row this time completed in 0.003430 seconds (a decrease from 0.036739 seconds) and did not require any physical reads.  The second fetch call, which retrieved 500 rows, performed a multi-block read of 4 blocks, and then a multi-block read of 8 blocks.  Why 4 blocks and not 8 (or 128 to permit a 1MB multi-block read) for the first read request?  Block 214219 was already in the buffer cache (see the trace file section from the previous output), and since Oracle will not perform a physical read of a block for the buffer cache that is already in the buffer cache, the multi-block read of the 64KB extent could only read 3 or 4 blocks (214216 through 214218 or 214220 through 214223) before hitting an extent boundry.  The first fetch call performed 161 consistent gets with no physical reads, while the second fetch call performed 10 consistent gets with 12 physical block reads (of table T4_1) – I still wonder why the number of consistent gets is less than the number of physical reads in this one fetch call (likely a difference in the array fetch size and the number of rows returned by the multi-block read size).  Continuing with the 10046 trace file:

WAIT #17: nam='SQL*Net message from client' ela= 679 driver id=1413697536 #bytes=1 p3=0 obj#=83175 tim=774876242
WAIT #17: nam='SQL*Net message to client' ela= 1 driver id=1413697536 #bytes=1 p3=0 obj#=83175 tim=774876273
WAIT #17: nam='db file scattered read' ela= 735 file#=8 block#=214232 blocks=8 obj#=83175 tim=774877386
FETCH #17:c=0,e=1319,p=8,cr=11,cu=0,mis=0,r=500,dep=0,og=1,plh=39991016,tim=774877583
WAIT #17: nam='SQL*Net message from client' ela= 665 driver id=1413697536 #bytes=1 p3=0 obj#=83175 tim=774878269
WAIT #17: nam='SQL*Net message to client' ela= 0 driver id=1413697536 #bytes=1 p3=0 obj#=83175 tim=774878299
WAIT #17: nam='db file scattered read' ela= 847 file#=8 block#=214240 blocks=8 obj#=83175 tim=774879444
FETCH #17:c=0,e=1387,p=8,cr=11,cu=0,mis=0,r=500,dep=0,og=1,plh=39991016,tim=774879677
WAIT #17: nam='SQL*Net message from client' ela= 660 driver id=1413697536 #bytes=1 p3=0 obj#=83175 tim=774880358
WAIT #17: nam='SQL*Net message to client' ela= 0 driver id=1413697536 #bytes=1 p3=0 obj#=83175 tim=774880388
WAIT #17: nam='db file scattered read' ela= 727 file#=8 block#=214248 blocks=8 obj#=83175 tim=774881432
WAIT #17: nam='db file scattered read' ela= 1424 file#=7 block#=1819728 blocks=8 obj#=83176 tim=774883006
FETCH #17:c=0,e=2768,p=16,cr=10,cu=0,mis=0,r=500,dep=0,og=1,plh=39991016,tim=774883147
WAIT #17: nam='SQL*Net message from client' ela= 709 driver id=1413697536 #bytes=1 p3=0 obj#=83176 tim=774883879
WAIT #17: nam='SQL*Net message to client' ela= 1 driver id=1413697536 #bytes=1 p3=0 obj#=83176 tim=774883917
WAIT #17: nam='db file scattered read' ela= 15955 file#=8 block#=214256 blocks=8 obj#=83175 tim=774900156
FETCH #17:c=0,e=16555,p=8,cr=11,cu=0,mis=0,r=500,dep=0,og=1,plh=39991016,tim=774900460
WAIT #17: nam='SQL*Net message from client' ela= 942 driver id=1413697536 #bytes=1 p3=0 obj#=83175 tim=774901423
WAIT #17: nam='SQL*Net message to client' ela= 1 driver id=1413697536 #bytes=1 p3=0 obj#=83175 tim=774901479
WAIT #17: nam='db file scattered read' ela= 1119 file#=8 block#=214264 blocks=8 obj#=83175 tim=774902934
FETCH #17:c=0,e=1743,p=8,cr=11,cu=0,mis=0,r=500,dep=0,og=1,plh=39991016,tim=774903205
WAIT #17: nam='SQL*Net message from client' ela= 751 driver id=1413697536 #bytes=1 p3=0 obj#=83175 tim=774903977
WAIT #17: nam='SQL*Net message to client' ela= 1 driver id=1413697536 #bytes=1 p3=0 obj#=83175 tim=774904012
WAIT #17: nam='db file scattered read' ela= 14243 file#=7 block#=1819648 blocks=8 obj#=83175 tim=774918513
FETCH #17:c=0,e=14844,p=8,cr=10,cu=0,mis=0,r=500,dep=0,og=1,plh=39991016,tim=774918846
WAIT #17: nam='SQL*Net message from client' ela= 948 driver id=1413697536 #bytes=1 p3=0 obj#=83175 tim=774919817
WAIT #17: nam='SQL*Net message to client' ela= 1 driver id=1413697536 #bytes=1 p3=0 obj#=83175 tim=774919873
WAIT #17: nam='db file scattered read' ela= 854 file#=7 block#=1819656 blocks=8 obj#=83175 tim=774921056
FETCH #17:c=0,e=1500,p=8,cr=11,cu=0,mis=0,r=500,dep=0,og=1,plh=39991016,tim=774921356
WAIT #17: nam='SQL*Net message from client' ela= 930 driver id=1413697536 #bytes=1 p3=0 obj#=83175 tim=774922307
WAIT #17: nam='SQL*Net message to client' ela= 0 driver id=1413697536 #bytes=1 p3=0 obj#=83175 tim=774922364
WAIT #17: nam='db file scattered read' ela= 1288 file#=7 block#=1819664 blocks=8 obj#=83175 tim=774923937
FETCH #17:c=0,e=1944,p=8,cr=11,cu=0,mis=0,r=500,dep=0,og=1,plh=39991016,tim=774924291
WAIT #17: nam='SQL*Net message from client' ela= 895 driver id=1413697536 #bytes=1 p3=0 obj#=83175 tim=774925206
WAIT #17: nam='SQL*Net message to client' ela= 1 driver id=1413697536 #bytes=1 p3=0 obj#=83175 tim=774925262
WAIT #17: nam='db file scattered read' ela= 929 file#=7 block#=1819672 blocks=8 obj#=83175 tim=774926493
FETCH #17:c=0,e=1564,p=8,cr=10,cu=0,mis=0,r=500,dep=0,og=1,plh=39991016,tim=774926810
WAIT #17: nam='SQL*Net message from client' ela= 877 driver id=1413697536 #bytes=1 p3=0 obj#=83175 tim=774927707
WAIT #17: nam='SQL*Net message to client' ela= 0 driver id=1413697536 #bytes=1 p3=0 obj#=83175 tim=774927762
WAIT #17: nam='db file scattered read' ela= 946 file#=7 block#=1819680 blocks=8 obj#=83175 tim=774928969
FETCH #17:c=15600,e=1639,p=8,cr=11,cu=0,mis=0,r=500,dep=0,og=1,plh=39991016,tim=774929385
WAIT #17: nam='SQL*Net message from client' ela= 888 driver id=1413697536 #bytes=1 p3=0 obj#=83175 tim=774930316
WAIT #17: nam='SQL*Net message to client' ela= 0 driver id=1413697536 #bytes=1 p3=0 obj#=83175 tim=774930371
WAIT #17: nam='db file scattered read' ela= 3361 file#=7 block#=1819688 blocks=8 obj#=83175 tim=774934020
WAIT #17: nam='db file scattered read' ela= 1173 file#=7 block#=1819736 blocks=8 obj#=83176 tim=774935320
FETCH #17:c=0,e=5280,p=16,cr=11,cu=0,mis=0,r=500,dep=0,og=1,plh=39991016,tim=774935634
WAIT #17: nam='SQL*Net message from client' ela= 665 driver id=1413697536 #bytes=1 p3=0 obj#=83176 tim=774936320
WAIT #17: nam='SQL*Net message to client' ela= 0 driver id=1413697536 #bytes=1 p3=0 obj#=83176 tim=774936355
WAIT #17: nam='db file scattered read' ela= 979 file#=7 block#=1819696 blocks=8 obj#=83175 tim=774937529
FETCH #17:c=0,e=1538,p=8,cr=10,cu=0,mis=0,r=500,dep=0,og=1,plh=39991016,tim=774937883
WAIT #17: nam='SQL*Net message from client' ela= 665 driver id=1413697536 #bytes=1 p3=0 obj#=83175 tim=774938570
WAIT #17: nam='SQL*Net message to client' ela= 0 driver id=1413697536 #bytes=1 p3=0 obj#=83175 tim=774938605
WAIT #17: nam='db file scattered read' ela= 742 file#=7 block#=1819704 blocks=8 obj#=83175 tim=774939560
FETCH #17:c=0,e=1289,p=8,cr=11,cu=0,mis=0,r=500,dep=0,og=1,plh=39991016,tim=774939884
WAIT #17: nam='SQL*Net message from client' ela= 663 driver id=1413697536 #bytes=1 p3=0 obj#=83175 tim=774940568
WAIT #17: nam='SQL*Net message to client' ela= 0 driver id=1413697536 #bytes=1 p3=0 obj#=83175 tim=774940602
WAIT #17: nam='db file scattered read' ela= 2105 file#=7 block#=1819712 blocks=8 obj#=83175 tim=774942878
FETCH #17:c=0,e=2643,p=8,cr=11,cu=0,mis=0,r=500,dep=0,og=1,plh=39991016,tim=774943235
WAIT #17: nam='SQL*Net message from client' ela= 878 driver id=1413697536 #bytes=1 p3=0 obj#=83175 tim=774944134
WAIT #17: nam='SQL*Net message to client' ela= 1 driver id=1413697536 #bytes=1 p3=0 obj#=83175 tim=774944189
WAIT #17: nam='db file scattered read' ela= 950 file#=8 block#=214272 blocks=8 obj#=83175 tim=774945372
FETCH #17:c=0,e=1581,p=8,cr=11,cu=0,mis=0,r=500,dep=0,og=1,plh=39991016,tim=774945754
WAIT #17: nam='SQL*Net message from client' ela= 876 driver id=1413697536 #bytes=1 p3=0 obj#=83175 tim=774946651
WAIT #17: nam='SQL*Net message to client' ela= 1 driver id=1413697536 #bytes=1 p3=0 obj#=83175 tim=774946707
WAIT #17: nam='db file scattered read' ela= 4210 file#=8 block#=214280 blocks=8 obj#=83175 tim=774951052
FETCH #17:c=0,e=4854,p=8,cr=10,cu=0,mis=0,r=500,dep=0,og=1,plh=39991016,tim=774951544
WAIT #17: nam='SQL*Net message from client' ela= 662 driver id=1413697536 #bytes=1 p3=0 obj#=83175 tim=774952228
WAIT #17: nam='SQL*Net message to client' ela= 0 driver id=1413697536 #bytes=1 p3=0 obj#=83175 tim=774952262
WAIT #17: nam='db file scattered read' ela= 2160 file#=8 block#=214288 blocks=8 obj#=83175 tim=774954531
FETCH #17:c=0,e=2727,p=8,cr=11,cu=0,mis=0,r=500,dep=0,og=1,plh=39991016,tim=774954979
WAIT #17: nam='SQL*Net message from client' ela= 870 driver id=1413697536 #bytes=1 p3=0 obj#=83175 tim=774955869
WAIT #17: nam='SQL*Net message to client' ela= 1 driver id=1413697536 #bytes=1 p3=0 obj#=83175 tim=774955924
WAIT #17: nam='db file scattered read' ela= 1331 file#=8 block#=214296 blocks=8 obj#=83175 tim=774957425
WAIT #17: nam='db file scattered read' ela= 924 file#=7 block#=1819744 blocks=8 obj#=83176 tim=774958429
FETCH #17:c=0,e=2950,p=16,cr=11,cu=0,mis=0,r=500,dep=0,og=1,plh=39991016,tim=774958857
WAIT #17: nam='SQL*Net message from client' ela= 870 driver id=1413697536 #bytes=1 p3=0 obj#=83176 tim=774959748
WAIT #17: nam='SQL*Net message to client' ela= 1 driver id=1413697536 #bytes=1 p3=0 obj#=83176 tim=774959803
WAIT #17: nam='db file scattered read' ela= 17894 file#=8 block#=214304 blocks=8 obj#=83175 tim=774977886
FETCH #17:c=0,e=18537,p=8,cr=10,cu=0,mis=0,r=499,dep=0,og=1,plh=39991016,tim=774978324
STAT #17 id=1 cnt=10000 pid=0 pos=1 obj=0 op='FILTER  (cr=374 pr=188 pw=0 time=9742 us)'
STAT #17 id=2 cnt=10000 pid=1 pos=1 obj=0 op='HASH JOIN  (cr=374 pr=188 pw=0 time=8717 us cost=51 size=109 card=1)'
STAT #17 id=3 cnt=10000 pid=2 pos=1 obj=83174 op='TABLE ACCESS FULL T3_1 (cr=158 pr=0 pw=0 time=885 us cost=47 size=8 card=2)'
STAT #17 id=4 cnt=10000 pid=2 pos=2 obj=83175 op='TABLE ACCESS BY INDEX ROWID T4_1 (cr=216 pr=188 pw=0 time=5255 us cost=3 size=210 card=2)'
STAT #17 id=5 cnt=10000 pid=4 pos=1 obj=83176 op='INDEX RANGE SCAN IND_T4_1 (cr=42 pr=24 pw=0 time=2531 us cost=2 size=0 card=2)'
WAIT #17: nam='SQL*Net message from client' ela= 2221 driver id=1413697536 #bytes=1 p3=0 obj#=83175 tim=774980966
*** SESSION ID:(1232.2) 2010-09-06 10:17:12.316

CLOSE #17:c=0,e=8,dep=0,type=0,tim=774989253
=====================

From the above, we see that the execution plan, indicated by the STAT lines, was the same as when N2 was set to a value of 2.  However, unlike with TKPROF, we are able to see how long the second execution required just from looking at the STAT lines in the raw 10046 trace file.

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

Second execution 10046 trace file, without embedded comments:

=====================
PARSING IN CURSOR #7 len=101 dep=0 uid=90 oct=3 lid=90 tim=868879999 hv=3458052021 ad='36ce14150' sqlid='4122a6m71vbxp'
SELECT
  T3_1.C1, T4_1.C2
FROM
  T3_1, T4_1
WHERE
  T3_1.C1 BETWEEN :N1 AND :N2
  AND T3_1.C1=T4_1.C1
END OF STMT
PARSE #7:c=0,e=22,p=0,cr=0,cu=0,mis=0,r=0,dep=0,og=1,plh=39991016,tim=868879999
BINDS #7:
 Bind#0
  oacdty=02 mxl=22(22) mxlc=00 mal=00 scl=00 pre=00
  oacflg=03 fl2=1000000 frm=00 csi=00 siz=48 off=0
  kxsbbbfp=1d7ba010  bln=22  avl=02  flg=05
  value=1
 Bind#1
  oacdty=02 mxl=22(22) mxlc=00 mal=00 scl=00 pre=00
  oacflg=03 fl2=1000000 frm=00 csi=00 siz=0 off=24
  kxsbbbfp=1d7ba028  bln=22  avl=02  flg=01
  value=2
EXEC #7:c=0,e=989,p=0,cr=0,cu=0,mis=1,r=0,dep=0,og=1,plh=39991016,tim=868881046
WAIT #7: nam='SQL*Net message to client' ela= 0 driver id=1413697536 #bytes=1 p3=0 obj#=0 tim=868881075
WAIT #7: nam='db file sequential read' ela= 33 file#=7 block#=1819466 blocks=1 obj#=83174 tim=868881219
WAIT #7: nam='db file scattered read' ela= 28 file#=7 block#=1819467 blocks=5 obj#=83174 tim=868881311
WAIT #7: nam='db file scattered read' ela= 33 file#=7 block#=1819472 blocks=8 obj#=83174 tim=868881491
WAIT #7: nam='db file scattered read' ela= 29 file#=7 block#=1819481 blocks=7 obj#=83174 tim=868881590
WAIT #7: nam='db file scattered read' ela= 30 file#=7 block#=1819488 blocks=8 obj#=83174 tim=868881684
WAIT #7: nam='db file scattered read' ela= 28 file#=7 block#=1819497 blocks=7 obj#=83174 tim=868881783
WAIT #7: nam='db file scattered read' ela= 30 file#=7 block#=1819504 blocks=8 obj#=83174 tim=868881885
WAIT #7: nam='db file scattered read' ela= 28 file#=7 block#=1819513 blocks=7 obj#=83174 tim=868881986
WAIT #7: nam='db file scattered read' ela= 32 file#=8 block#=214144 blocks=8 obj#=83174 tim=868882088
WAIT #7: nam='db file scattered read' ela= 28 file#=8 block#=214153 blocks=7 obj#=83174 tim=868882190
WAIT #7: nam='db file scattered read' ela= 30 file#=8 block#=214160 blocks=8 obj#=83174 tim=868882288
WAIT #7: nam='db file scattered read' ela= 30 file#=8 block#=214169 blocks=7 obj#=83174 tim=868882393
WAIT #7: nam='db file scattered read' ela= 30 file#=8 block#=214176 blocks=8 obj#=83174 tim=868882493
WAIT #7: nam='db file scattered read' ela= 29 file#=8 block#=214185 blocks=7 obj#=83174 tim=868882595
WAIT #7: nam='db file scattered read' ela= 31 file#=8 block#=214192 blocks=8 obj#=83174 tim=868882696
WAIT #7: nam='db file scattered read' ela= 29 file#=8 block#=214201 blocks=7 obj#=83174 tim=868882799
WAIT #7: nam='db file scattered read' ela= 31 file#=8 block#=214208 blocks=8 obj#=83174 tim=868882930
WAIT #7: nam='db file scattered read' ela= 98 file#=7 block#=1819522 blocks=36 obj#=83174 tim=868883136
WAIT #7: nam='db file scattered read' ela= 61 file#=7 block#=1819720 blocks=8 obj#=83176 tim=868883431
WAIT #7: nam='db file scattered read' ela= 48 file#=8 block#=214216 blocks=8 obj#=83175 tim=868883532
FETCH #7:c=0,e=2481,p=171,cr=161,cu=0,mis=0,r=1,dep=0,og=1,plh=39991016,tim=868883573
WAIT #7: nam='SQL*Net message from client' ela= 175 driver id=1413697536 #bytes=1 p3=0 obj#=83175 tim=868883778
WAIT #7: nam='SQL*Net message to client' ela= 1 driver id=1413697536 #bytes=1 p3=0 obj#=83175 tim=868883813
FETCH #7:c=0,e=46,p=0,cr=2,cu=0,mis=0,r=1,dep=0,og=1,plh=39991016,tim=868883848
STAT #7 id=1 cnt=2 pid=0 pos=1 obj=0 op='FILTER  (cr=163 pr=171 pw=0 time=0 us)'
STAT #7 id=2 cnt=2 pid=1 pos=1 obj=0 op='HASH JOIN  (cr=163 pr=171 pw=0 time=0 us cost=51 size=109 card=1)'
STAT #7 id=3 cnt=2 pid=2 pos=1 obj=83174 op='TABLE ACCESS FULL T3_1 (cr=158 pr=155 pw=0 time=1 us cost=47 size=8 card=2)'
STAT #7 id=4 cnt=2 pid=2 pos=2 obj=83175 op='TABLE ACCESS BY INDEX ROWID T4_1 (cr=5 pr=16 pw=0 time=0 us cost=3 size=210 card=2)'
STAT #7 id=5 cnt=2 pid=4 pos=1 obj=83176 op='INDEX RANGE SCAN IND_T4_1 (cr=3 pr=8 pw=0 time=4 us cost=2 size=0 card=2)'
WAIT #7: nam='SQL*Net message from client' ela= 217 driver id=1413697536 #bytes=1 p3=0 obj#=83175 tim=868884157
*** SESSION ID:(1232.2) 2010-09-06 10:18:46.228

CLOSE #7:c=0,e=8,dep=0,type=0,tim=868890954
=====================
PARSING IN CURSOR #16 len=26 dep=0 uid=90 oct=47 lid=90 tim=868891061 hv=3000858490 ad='36ce13ac0' sqlid='56ndayftduxvu'
BEGIN :N2 := 10000; END;
END OF STMT
PARSE #16:c=0,e=52,p=0,cr=0,cu=0,mis=0,r=0,dep=0,og=1,plh=0,tim=868891060
BINDS #16:
 Bind#0
  oacdty=02 mxl=22(22) mxlc=00 mal=00 scl=00 pre=00
  oacflg=03 fl2=1000000 frm=00 csi=00 siz=24 off=0
  kxsbbbfp=1d7ba028  bln=22  avl=02  flg=05
  value=2
WAIT #16: nam='SQL*Net message to client' ela= 0 driver id=1413697536 #bytes=1 p3=0 obj#=83175 tim=868891170
EXEC #16:c=0,e=84,p=0,cr=0,cu=0,mis=0,r=1,dep=0,og=1,plh=0,tim=868891184
WAIT #16: nam='SQL*Net message from client' ela= 8292 driver id=1413697536 #bytes=1 p3=0 obj#=83175 tim=868899504
*** SESSION ID:(1232.2) 2010-09-06 10:18:46.228

CLOSE #16:c=0,e=11,dep=0,type=0,tim=868900212
=====================
PARSING IN CURSOR #12 len=101 dep=0 uid=90 oct=3 lid=90 tim=868900272 hv=3458052021 ad='36ce14150' sqlid='4122a6m71vbxp'
SELECT
  T3_1.C1, T4_1.C2
FROM
  T3_1, T4_1
WHERE
  T3_1.C1 BETWEEN :N1 AND :N2
  AND T3_1.C1=T4_1.C1
END OF STMT
PARSE #12:c=0,e=30,p=0,cr=0,cu=0,mis=0,r=0,dep=0,og=1,plh=39991016,tim=868900272
BINDS #12:
 Bind#0
  oacdty=02 mxl=22(22) mxlc=00 mal=00 scl=00 pre=00
  oacflg=03 fl2=1000000 frm=00 csi=00 siz=48 off=0
  kxsbbbfp=1d7c5920  bln=22  avl=02  flg=05
  value=1
 Bind#1
  oacdty=02 mxl=22(22) mxlc=00 mal=00 scl=00 pre=00
  oacflg=03 fl2=1000000 frm=00 csi=00 siz=0 off=24
  kxsbbbfp=1d7c5938  bln=22  avl=02  flg=01
  value=10000
EXEC #12:c=0,e=941,p=0,cr=0,cu=0,mis=1,r=0,dep=0,og=1,plh=1389598788,tim=868901272
WAIT #12: nam='SQL*Net message to client' ela= 0 driver id=1413697536 #bytes=1 p3=0 obj#=83175 tim=868901301
WAIT #12: nam='db file sequential read' ela= 48 file#=8 block#=214218 blocks=1 obj#=83175 tim=868904157
FETCH #12:c=15600,e=3235,p=1,cr=162,cu=0,mis=0,r=1,dep=0,og=1,plh=1389598788,tim=868904553
WAIT #12: nam='SQL*Net message from client' ela= 155 driver id=1413697536 #bytes=1 p3=0 obj#=83175 tim=868904737
WAIT #12: nam='SQL*Net message to client' ela= 1 driver id=1413697536 #bytes=1 p3=0 obj#=83175 tim=868904769
WAIT #12: nam='db file scattered read' ela= 39 file#=8 block#=214224 blocks=8 obj#=83175 tim=868905030
FETCH #12:c=0,e=409,p=8,cr=8,cu=0,mis=0,r=500,dep=0,og=1,plh=1389598788,tim=868905169
WAIT #12: nam='SQL*Net message from client' ela= 599 driver id=1413697536 #bytes=1 p3=0 obj#=83175 tim=868905788
WAIT #12: nam='SQL*Net message to client' ela= 0 driver id=1413697536 #bytes=1 p3=0 obj#=83175 tim=868905817
WAIT #12: nam='db file scattered read' ela= 32 file#=8 block#=214233 blocks=7 obj#=83175 tim=868906092
FETCH #12:c=0,e=409,p=7,cr=9,cu=0,mis=0,r=500,dep=0,og=1,plh=1389598788,tim=868906219
WAIT #12: nam='SQL*Net message from client' ela= 599 driver id=1413697536 #bytes=1 p3=0 obj#=83175 tim=868906839
WAIT #12: nam='SQL*Net message to client' ela= 1 driver id=1413697536 #bytes=1 p3=0 obj#=83175 tim=868906868
WAIT #12: nam='db file scattered read' ela= 34 file#=8 block#=214240 blocks=8 obj#=83175 tim=868907088
FETCH #12:c=0,e=382,p=8,cr=9,cu=0,mis=0,r=500,dep=0,og=1,plh=1389598788,tim=868907242
WAIT #12: nam='SQL*Net message from client' ela= 620 driver id=1413697536 #bytes=1 p3=0 obj#=83175 tim=868907883
WAIT #12: nam='SQL*Net message to client' ela= 0 driver id=1413697536 #bytes=1 p3=0 obj#=83175 tim=868907912
WAIT #12: nam='db file scattered read' ela= 34 file#=8 block#=214249 blocks=7 obj#=83175 tim=868908142
FETCH #12:c=0,e=380,p=7,cr=8,cu=0,mis=0,r=500,dep=0,og=1,plh=1389598788,tim=868908284
WAIT #12: nam='SQL*Net message from client' ela= 602 driver id=1413697536 #bytes=1 p3=0 obj#=83175 tim=868908906
WAIT #12: nam='SQL*Net message to client' ela= 1 driver id=1413697536 #bytes=1 p3=0 obj#=83175 tim=868908935
WAIT #12: nam='db file scattered read' ela= 34 file#=8 block#=214256 blocks=8 obj#=83175 tim=868909143
FETCH #12:c=0,e=382,p=8,cr=9,cu=0,mis=0,r=500,dep=0,og=1,plh=1389598788,tim=868909309
WAIT #12: nam='SQL*Net message from client' ela= 600 driver id=1413697536 #bytes=1 p3=0 obj#=83175 tim=868909929
WAIT #12: nam='SQL*Net message to client' ela= 0 driver id=1413697536 #bytes=1 p3=0 obj#=83175 tim=868909957
WAIT #12: nam='db file scattered read' ela= 32 file#=8 block#=214265 blocks=7 obj#=83175 tim=868910171
FETCH #12:c=0,e=375,p=7,cr=9,cu=0,mis=0,r=500,dep=0,og=1,plh=1389598788,tim=868910325
WAIT #12: nam='SQL*Net message from client' ela= 597 driver id=1413697536 #bytes=1 p3=0 obj#=83175 tim=868910942
WAIT #12: nam='SQL*Net message to client' ela= 0 driver id=1413697536 #bytes=1 p3=0 obj#=83175 tim=868910970
WAIT #12: nam='db file scattered read' ela= 34 file#=7 block#=1819648 blocks=8 obj#=83175 tim=868911164
FETCH #12:c=0,e=380,p=8,cr=8,cu=0,mis=0,r=500,dep=0,og=1,plh=1389598788,tim=868911343
WAIT #12: nam='SQL*Net message from client' ela= 598 driver id=1413697536 #bytes=1 p3=0 obj#=83175 tim=868911962
WAIT #12: nam='SQL*Net message to client' ela= 0 driver id=1413697536 #bytes=1 p3=0 obj#=83175 tim=868911990
WAIT #12: nam='db file scattered read' ela= 32 file#=7 block#=1819657 blocks=7 obj#=83175 tim=868912193
FETCH #12:c=0,e=387,p=7,cr=9,cu=0,mis=0,r=500,dep=0,og=1,plh=1389598788,tim=868912370
WAIT #12: nam='SQL*Net message from client' ela= 597 driver id=1413697536 #bytes=1 p3=0 obj#=83175 tim=868912987
WAIT #12: nam='SQL*Net message to client' ela= 0 driver id=1413697536 #bytes=1 p3=0 obj#=83175 tim=868913016
WAIT #12: nam='db file scattered read' ela= 35 file#=7 block#=1819664 blocks=8 obj#=83175 tim=868913198
FETCH #12:c=0,e=384,p=8,cr=9,cu=0,mis=0,r=500,dep=0,og=1,plh=1389598788,tim=868913392
WAIT #12: nam='SQL*Net message from client' ela= 599 driver id=1413697536 #bytes=1 p3=0 obj#=83175 tim=868914011
WAIT #12: nam='SQL*Net message to client' ela= 1 driver id=1413697536 #bytes=1 p3=0 obj#=83175 tim=868914040
WAIT #12: nam='db file scattered read' ela= 31 file#=7 block#=1819673 blocks=7 obj#=83175 tim=868914230
FETCH #12:c=0,e=378,p=7,cr=9,cu=0,mis=0,r=500,dep=0,og=1,plh=1389598788,tim=868914410
WAIT #12: nam='SQL*Net message from client' ela= 597 driver id=1413697536 #bytes=1 p3=0 obj#=83175 tim=868915027
WAIT #12: nam='SQL*Net message to client' ela= 0 driver id=1413697536 #bytes=1 p3=0 obj#=83175 tim=868915056
WAIT #12: nam='db file scattered read' ela= 34 file#=7 block#=1819680 blocks=8 obj#=83175 tim=868915227
FETCH #12:c=0,e=385,p=8,cr=9,cu=0,mis=0,r=500,dep=0,og=1,plh=1389598788,tim=868915434
WAIT #12: nam='SQL*Net message from client' ela= 598 driver id=1413697536 #bytes=1 p3=0 obj#=83175 tim=868916052
WAIT #12: nam='SQL*Net message to client' ela= 0 driver id=1413697536 #bytes=1 p3=0 obj#=83175 tim=868916083
WAIT #12: nam='db file scattered read' ela= 32 file#=7 block#=1819689 blocks=7 obj#=83175 tim=868916259
FETCH #12:c=0,e=382,p=7,cr=9,cu=0,mis=0,r=500,dep=0,og=1,plh=1389598788,tim=868916457
WAIT #12: nam='SQL*Net message from client' ela= 596 driver id=1413697536 #bytes=1 p3=0 obj#=83175 tim=868917073
WAIT #12: nam='SQL*Net message to client' ela= 0 driver id=1413697536 #bytes=1 p3=0 obj#=83175 tim=868917102
WAIT #12: nam='db file scattered read' ela= 33 file#=7 block#=1819696 blocks=8 obj#=83175 tim=868917258
FETCH #12:c=0,e=391,p=8,cr=8,cu=0,mis=0,r=500,dep=0,og=1,plh=1389598788,tim=868917485
WAIT #12: nam='SQL*Net message from client' ela= 598 driver id=1413697536 #bytes=1 p3=0 obj#=83175 tim=868918104
WAIT #12: nam='SQL*Net message to client' ela= 0 driver id=1413697536 #bytes=1 p3=0 obj#=83175 tim=868918159
WAIT #12: nam='db file scattered read' ela= 35 file#=7 block#=1819705 blocks=7 obj#=83175 tim=868918347
FETCH #12:c=15600,e=437,p=7,cr=9,cu=0,mis=0,r=500,dep=0,og=1,plh=1389598788,tim=868918562
WAIT #12: nam='SQL*Net message from client' ela= 604 driver id=1413697536 #bytes=1 p3=0 obj#=83175 tim=868919187
WAIT #12: nam='SQL*Net message to client' ela= 0 driver id=1413697536 #bytes=1 p3=0 obj#=83175 tim=868919216
WAIT #12: nam='db file scattered read' ela= 34 file#=7 block#=1819712 blocks=8 obj#=83175 tim=868919362
FETCH #12:c=0,e=392,p=8,cr=9,cu=0,mis=0,r=500,dep=0,og=1,plh=1389598788,tim=868919600
WAIT #12: nam='SQL*Net message from client' ela= 598 driver id=1413697536 #bytes=1 p3=0 obj#=83175 tim=868920218
WAIT #12: nam='SQL*Net message to client' ela= 0 driver id=1413697536 #bytes=1 p3=0 obj#=83175 tim=868920247
WAIT #12: nam='db file scattered read' ela= 102 file#=8 block#=214274 blocks=36 obj#=83175 tim=868920500
FETCH #12:c=0,e=585,p=36,cr=9,cu=0,mis=0,r=500,dep=0,og=1,plh=1389598788,tim=868920824
WAIT #12: nam='SQL*Net message from client' ela= 600 driver id=1413697536 #bytes=1 p3=0 obj#=83175 tim=868921445
WAIT #12: nam='SQL*Net message to client' ela= 1 driver id=1413697536 #bytes=1 p3=0 obj#=83175 tim=868921475
FETCH #12:c=0,e=290,p=0,cr=8,cu=0,mis=0,r=500,dep=0,og=1,plh=1389598788,tim=868921756
WAIT #12: nam='SQL*Net message from client' ela= 593 driver id=1413697536 #bytes=1 p3=0 obj#=83175 tim=868922368
WAIT #12: nam='SQL*Net message to client' ela= 0 driver id=1413697536 #bytes=1 p3=0 obj#=83175 tim=868922397
FETCH #12:c=0,e=286,p=0,cr=9,cu=0,mis=0,r=500,dep=0,og=1,plh=1389598788,tim=868922675
WAIT #12: nam='SQL*Net message from client' ela= 579 driver id=1413697536 #bytes=1 p3=0 obj#=83175 tim=868923272
WAIT #12: nam='SQL*Net message to client' ela= 1 driver id=1413697536 #bytes=1 p3=0 obj#=83175 tim=868923301
FETCH #12:c=0,e=287,p=0,cr=9,cu=0,mis=0,r=500,dep=0,og=1,plh=1389598788,tim=868923580
WAIT #12: nam='SQL*Net message from client' ela= 601 driver id=1413697536 #bytes=1 p3=0 obj#=83175 tim=868924201
WAIT #12: nam='SQL*Net message to client' ela= 1 driver id=1413697536 #bytes=1 p3=0 obj#=83175 tim=868924230
FETCH #12:c=0,e=314,p=0,cr=8,cu=0,mis=0,r=499,dep=0,og=1,plh=1389598788,tim=868924536
STAT #12 id=1 cnt=10000 pid=0 pos=1 obj=0 op='FILTER  (cr=336 pr=150 pw=0 time=4999 us)'
STAT #12 id=2 cnt=10000 pid=1 pos=1 obj=0 op='HASH JOIN  (cr=336 pr=150 pw=0 time=4486 us cost=95 size=1090000 card=10000)'
STAT #12 id=3 cnt=10000 pid=2 pos=1 obj=83174 op='TABLE ACCESS FULL T3_1 (cr=158 pr=0 pw=0 time=1265 us cost=47 size=40000 card=10000)'
STAT #12 id=4 cnt=10000 pid=2 pos=2 obj=83175 op='TABLE ACCESS FULL T4_1 (cr=178 pr=150 pw=0 time=1410 us cost=47 size=1050000 card=10000)'
WAIT #12: nam='SQL*Net message from client' ela= 2182 driver id=1413697536 #bytes=1 p3=0 obj#=83175 tim=868927063
*** SESSION ID:(1232.2) 2010-09-06 10:18:46.275

CLOSE #12:c=0,e=9,dep=0,type=0,tim=868935422
=====================
PARSING IN CURSOR #17 len=24 dep=0 uid=90 oct=3 lid=90 tim=868935520 hv=124468195 ad='37c5bc8a0' sqlid='c749bc43qqfz3'
SELECT SYSDATE FROM DUAL
END OF STMT
PARSE #17:c=0,e=45,p=0,cr=0,cu=0,mis=0,r=0,dep=0,og=1,plh=1388734953,tim=868935519
EXEC #17:c=0,e=12,p=0,cr=0,cu=0,mis=0,r=0,dep=0,og=1,plh=1388734953,tim=868935599
WAIT #17: nam='SQL*Net message to client' ela= 1 driver id=1413697536 #bytes=1 p3=0 obj#=83175 tim=868935633
FETCH #17:c=0,e=7,p=0,cr=0,cu=0,mis=0,r=1,dep=0,og=1,plh=1388734953,tim=868935656
STAT #17 id=1 cnt=1 pid=0 pos=1 obj=0 op='FAST DUAL  (cr=0 pr=0 pw=0 time=0 us cost=2 size=0 card=1)'
WAIT #17: nam='SQL*Net message from client' ela= 100 driver id=1413697536 #bytes=1 p3=0 obj#=83175 tim=868935790
FETCH #17:c=0,e=1,p=0,cr=0,cu=0,mis=0,r=0,dep=0,og=0,plh=1388734953,tim=868935812
WAIT #17: nam='SQL*Net message to client' ela= 0 driver id=1413697536 #bytes=1 p3=0 obj#=83175 tim=868935824
WAIT #17: nam='SQL*Net message from client' ela= 147 driver id=1413697536 #bytes=1 p3=0 obj#=83175 tim=868935981

How does the 10046 trace file for the second half of the script compare with the 10046 trace file for the first half of the script?  What has changed?  What is the same?

And just to keep you wondering (what has changed and why), here is output from another box that is also running Oracle Database 11.2.0.1 using direct, asynchronous I/O and ASSM autoallocate tablespaces:

SELECT
  OBJECT_NAME,
  OBJECT_ID,
  DATA_OBJECT_ID
FROM
  DBA_OBJECTS
WHERE
  OBJECT_NAME IN ('T3_1','T4_1','IND_T4_1');

OBJECT_NAME  OBJECT_ID DATA_OBJECT_ID
------------ --------- --------------
T3_1             77260          77260
T4_1             77261          77261
IND_T4_1         77262          77262

SELECT
  SEGMENT_NAME,
  HEADER_FILE,
  HEADER_BLOCK
FROM
  DBA_SEGMENTS
WHERE
  SEGMENT_NAME IN ('T3_1','T4_1','IND_T4_1');

SEGMENT_NAME HEADER_FILE HEADER_BLOCK
------------ ----------- ------------
IND_T4_1               8        13410
T3_1                   8        13154
T4_1                   7      2556514

The raw trace file from the first execution on the second server:

=====================
PARSING IN CURSOR #14 len=101 dep=0 uid=185 oct=3 lid=185 tim=480383990 hv=3458052021 ad='46953aca8' sqlid='4122a6m71vbxp'
SELECT
  T3_1.C1, T4_1.C2
FROM
  T3_1, T4_1
WHERE
  T3_1.C1 BETWEEN :N1 AND :N2
  AND T3_1.C1=T4_1.C1
END OF STMT
PARSE #14:c=0,e=129,p=0,cr=0,cu=0,mis=1,r=0,dep=0,og=1,plh=0,tim=480383989
BINDS #14:
 Bind#0
  oacdty=02 mxl=22(22) mxlc=00 mal=00 scl=00 pre=00
  oacflg=03 fl2=1000000 frm=00 csi=00 siz=48 off=0
  kxsbbbfp=1fc575b8  bln=22  avl=02  flg=05
  value=1
 Bind#1
  oacdty=02 mxl=22(22) mxlc=00 mal=00 scl=00 pre=00
  oacflg=03 fl2=1000000 frm=00 csi=00 siz=0 off=24
  kxsbbbfp=1fc575d0  bln=22  avl=02  flg=01
  value=2
EXEC #14:c=0,e=667,p=0,cr=0,cu=0,mis=1,r=0,dep=0,og=1,plh=39991016,tim=480384712
WAIT #14: nam='SQL*Net message to client' ela= 0 driver id=1413697536 #bytes=1 p3=0 obj#=0 tim=480384738
WAIT #14: nam='db file sequential read' ela= 455 file#=8 block#=13154 blocks=1 obj#=77260 tim=480385283
WAIT #14: nam='db file scattered read' ela= 528 file#=8 block#=13155 blocks=5 obj#=77260 tim=480385892
WAIT #14: nam='db file scattered read' ela= 70 file#=8 block#=13160 blocks=8 obj#=77260 tim=480386198
WAIT #14: nam='db file scattered read' ela= 418 file#=8 block#=13169 blocks=7 obj#=77260 tim=480386706
WAIT #14: nam='db file scattered read' ela= 58 file#=8 block#=13176 blocks=8 obj#=77260 tim=480386845
WAIT #14: nam='db file scattered read' ela= 348 file#=7 block#=2556417 blocks=7 obj#=77260 tim=480387265
WAIT #14: nam='db file scattered read' ela= 49 file#=7 block#=2556424 blocks=8 obj#=77260 tim=480387409
WAIT #14: nam='db file scattered read' ela= 360 file#=7 block#=2556433 blocks=7 obj#=77260 tim=480387840
WAIT #14: nam='db file scattered read' ela= 47 file#=7 block#=2556440 blocks=8 obj#=77260 tim=480387975
WAIT #14: nam='db file scattered read' ela= 345 file#=7 block#=2556449 blocks=7 obj#=77260 tim=480388392
WAIT #14: nam='db file scattered read' ela= 49 file#=7 block#=2556456 blocks=8 obj#=77260 tim=480388545
WAIT #14: nam='db file scattered read' ela= 358 file#=7 block#=2556465 blocks=7 obj#=77260 tim=480388980
WAIT #14: nam='db file scattered read' ela= 51 file#=7 block#=2556472 blocks=8 obj#=77260 tim=480389123
WAIT #14: nam='db file scattered read' ela= 383 file#=7 block#=2556481 blocks=7 obj#=77260 tim=480389577
WAIT #14: nam='db file scattered read' ela= 47 file#=7 block#=2556488 blocks=8 obj#=77260 tim=480389694
WAIT #14: nam='db file scattered read' ela= 402 file#=7 block#=2556497 blocks=7 obj#=77260 tim=480390166
WAIT #14: nam='db file scattered read' ela= 118 file#=7 block#=2556504 blocks=8 obj#=77260 tim=480390371
WAIT #14: nam='db file scattered read' ela= 772 file#=8 block#=13186 blocks=36 obj#=77260 tim=480391278
WAIT #14: nam='db file sequential read' ela= 343 file#=8 block#=13411 blocks=1 obj#=77262 tim=480391856
WAIT #14: nam='db file scattered read' ela= 378 file#=8 block#=13412 blocks=4 obj#=77262 tim=480392334
WAIT #14: nam='db file sequential read' ela= 42 file#=7 block#=2556515 blocks=1 obj#=77261 tim=480392421
FETCH #14:c=0,e=7721,p=161,cr=161,cu=0,mis=0,r=1,dep=0,og=1,plh=39991016,tim=480392475
WAIT #14: nam='SQL*Net message from client' ela= 820 driver id=1413697536 #bytes=1 p3=0 obj#=77261 tim=480393374
WAIT #14: nam='SQL*Net message to client' ela= 0 driver id=1413697536 #bytes=1 p3=0 obj#=77261 tim=480393452
FETCH #14:c=0,e=53,p=0,cr=2,cu=0,mis=0,r=1,dep=0,og=1,plh=39991016,tim=480393492
STAT #14 id=1 cnt=2 pid=0 pos=1 obj=0 op='FILTER  (cr=163 pr=161 pw=0 time=0 us)'
STAT #14 id=2 cnt=2 pid=1 pos=1 obj=0 op='HASH JOIN  (cr=163 pr=161 pw=0 time=0 us cost=51 size=109 card=1)'
STAT #14 id=3 cnt=2 pid=2 pos=1 obj=77260 op='TABLE ACCESS FULL T3_1 (cr=158 pr=155 pw=0 time=1 us cost=47 size=8 card=2)'
STAT #14 id=4 cnt=2 pid=2 pos=2 obj=77261 op='TABLE ACCESS BY INDEX ROWID T4_1 (cr=5 pr=6 pw=0 time=0 us cost=3 size=210 card=2)'
STAT #14 id=5 cnt=2 pid=4 pos=1 obj=77262 op='INDEX RANGE SCAN IND_T4_1 (cr=3 pr=5 pw=0 time=5 us cost=2 size=0 card=2)'
WAIT #14: nam='SQL*Net message from client' ela= 928 driver id=1413697536 #bytes=1 p3=0 obj#=77261 tim=480394549

*** 2010-09-06 15:33:24.557
*** SESSION ID:(4.7) 2010-09-06 15:33:24.557

CLOSE #14:c=0,e=12,dep=0,type=0,tim=480410306
=====================
PARSING IN CURSOR #16 len=26 dep=0 uid=185 oct=47 lid=185 tim=480410638 hv=3000858490 ad='467bc4398' sqlid='56ndayftduxvu'
BEGIN :N2 := 10000; END;
END OF STMT
PARSE #16:c=0,e=257,p=0,cr=0,cu=0,mis=1,r=0,dep=0,og=1,plh=0,tim=480410637
BINDS #16:
 Bind#0
  oacdty=02 mxl=22(22) mxlc=00 mal=00 scl=00 pre=00
  oacflg=03 fl2=1000000 frm=00 csi=00 siz=24 off=0
  kxsbbbfp=1fc575d0  bln=22  avl=02  flg=05
  value=2
WAIT #16: nam='SQL*Net message to client' ela= 1 driver id=1413697536 #bytes=1 p3=0 obj#=77261 tim=480411380
EXEC #16:c=0,e=707,p=0,cr=0,cu=0,mis=1,r=1,dep=0,og=1,plh=0,tim=480411398
WAIT #16: nam='SQL*Net message from client' ela= 13898 driver id=1413697536 #bytes=1 p3=0 obj#=77261 tim=480425340
*** SESSION ID:(4.7) 2010-09-06 15:33:24.573

CLOSE #16:c=0,e=15,dep=0,type=0,tim=480427017
=====================
PARSING IN CURSOR #2 len=101 dep=0 uid=185 oct=3 lid=185 tim=480427079 hv=3458052021 ad='46953aca8' sqlid='4122a6m71vbxp'
SELECT
  T3_1.C1, T4_1.C2
FROM
  T3_1, T4_1
WHERE
  T3_1.C1 BETWEEN :N1 AND :N2
  AND T3_1.C1=T4_1.C1
END OF STMT
PARSE #2:c=0,e=30,p=0,cr=0,cu=0,mis=0,r=0,dep=0,og=1,plh=39991016,tim=480427079
BINDS #2:
 Bind#0
  oacdty=02 mxl=22(22) mxlc=00 mal=00 scl=00 pre=00
  oacflg=03 fl2=1000000 frm=00 csi=00 siz=48 off=0
  kxsbbbfp=2157a380  bln=22  avl=02  flg=05
  value=1
 Bind#1
  oacdty=02 mxl=22(22) mxlc=00 mal=00 scl=00 pre=00
  oacflg=03 fl2=1000000 frm=00 csi=00 siz=0 off=24
  kxsbbbfp=2157a398  bln=22  avl=02  flg=01
  value=10000
EXEC #2:c=0,e=67,p=0,cr=0,cu=0,mis=0,r=0,dep=0,og=1,plh=39991016,tim=480427204
WAIT #2: nam='SQL*Net message to client' ela= 1 driver id=1413697536 #bytes=1 p3=0 obj#=77261 tim=480427226
FETCH #2:c=0,e=3440,p=0,cr=161,cu=0,mis=0,r=1,dep=0,og=1,plh=39991016,tim=480430680
WAIT #2: nam='SQL*Net message from client' ela= 639 driver id=1413697536 #bytes=1 p3=0 obj#=77261 tim=480431346
WAIT #2: nam='SQL*Net message to client' ela= 0 driver id=1413697536 #bytes=1 p3=0 obj#=77261 tim=480431379
WAIT #2: nam='db file sequential read' ela= 88 file#=7 block#=2556516 blocks=1 obj#=77261 tim=480431556
WAIT #2: nam='db file sequential read' ela= 41 file#=7 block#=2556517 blocks=1 obj#=77261 tim=480431766
WAIT #2: nam='db file sequential read' ela= 42 file#=7 block#=2556518 blocks=1 obj#=77261 tim=480431973
WAIT #2: nam='db file sequential read' ela= 41 file#=7 block#=2556519 blocks=1 obj#=77261 tim=480432178
WAIT #2: nam='db file sequential read' ela= 37 file#=7 block#=2556520 blocks=1 obj#=77261 tim=480432392
WAIT #2: nam='db file sequential read' ela= 41 file#=7 block#=2556521 blocks=1 obj#=77261 tim=480432597
WAIT #2: nam='db file sequential read' ela= 38 file#=7 block#=2556522 blocks=1 obj#=77261 tim=480432797
FETCH #2:c=0,e=1577,p=7,cr=10,cu=0,mis=0,r=500,dep=0,og=1,plh=39991016,tim=480432945
WAIT #2: nam='SQL*Net message from client' ela= 1377 driver id=1413697536 #bytes=1 p3=0 obj#=77261 tim=480434342
WAIT #2: nam='SQL*Net message to client' ela= 0 driver id=1413697536 #bytes=1 p3=0 obj#=77261 tim=480434374
WAIT #2: nam='db file sequential read' ela= 28 file#=7 block#=2556523 blocks=1 obj#=77261 tim=480434445
WAIT #2: nam='db file sequential read' ela= 41 file#=7 block#=2556524 blocks=1 obj#=77261 tim=480434653
WAIT #2: nam='db file sequential read' ela= 44 file#=7 block#=2556525 blocks=1 obj#=77261 tim=480434863
WAIT #2: nam='db file sequential read' ela= 43 file#=7 block#=2556526 blocks=1 obj#=77261 tim=480435065
WAIT #2: nam='db file sequential read' ela= 41 file#=7 block#=2556527 blocks=1 obj#=77261 tim=480435266
WAIT #2: nam='db file sequential read' ela= 374 file#=7 block#=2556529 blocks=1 obj#=77261 tim=480435806
WAIT #2: nam='db file sequential read' ela= 269 file#=7 block#=2556530 blocks=1 obj#=77261 tim=480436279
WAIT #2: nam='db file sequential read' ela= 54 file#=7 block#=2556531 blocks=1 obj#=77261 tim=480436490
FETCH #2:c=0,e=2201,p=8,cr=11,cu=0,mis=0,r=500,dep=0,og=1,plh=39991016,tim=480436565
WAIT #2: nam='SQL*Net message from client' ela= 1375 driver id=1413697536 #bytes=1 p3=0 obj#=77261 tim=480437961
WAIT #2: nam='SQL*Net message to client' ela= 0 driver id=1413697536 #bytes=1 p3=0 obj#=77261 tim=480437994
WAIT #2: nam='db file sequential read' ela= 316 file#=7 block#=2556532 blocks=1 obj#=77261 tim=480438368
WAIT #2: nam='db file sequential read' ela= 36 file#=7 block#=2556533 blocks=1 obj#=77261 tim=480438619
WAIT #2: nam='db file sequential read' ela= 41 file#=7 block#=2556534 blocks=1 obj#=77261 tim=480438817
WAIT #2: nam='db file sequential read' ela= 40 file#=7 block#=2556535 blocks=1 obj#=77261 tim=480439020
WAIT #2: nam='db file sequential read' ela= 38 file#=7 block#=2556536 blocks=1 obj#=77261 tim=480439222
WAIT #2: nam='db file sequential read' ela= 62 file#=7 block#=2556537 blocks=1 obj#=77261 tim=480439479
WAIT #2: nam='db file sequential read' ela= 42 file#=7 block#=2556538 blocks=1 obj#=77261 tim=480439693
WAIT #2: nam='db file sequential read' ela= 41 file#=7 block#=2556539 blocks=1 obj#=77261 tim=480439901
FETCH #2:c=15600,e=1968,p=8,cr=11,cu=0,mis=0,r=500,dep=0,og=1,plh=39991016,tim=480439952
WAIT #2: nam='SQL*Net message from client' ela= 1413 driver id=1413697536 #bytes=1 p3=0 obj#=77261 tim=480441410
WAIT #2: nam='SQL*Net message to client' ela= 0 driver id=1413697536 #bytes=1 p3=0 obj#=77261 tim=480441442
WAIT #2: nam='db file sequential read' ela= 39 file#=7 block#=2556540 blocks=1 obj#=77261 tim=480441558
WAIT #2: nam='db file sequential read' ela= 39 file#=7 block#=2556541 blocks=1 obj#=77261 tim=480441758
WAIT #2: nam='db file sequential read' ela= 39 file#=7 block#=2556542 blocks=1 obj#=77261 tim=480441959
WAIT #2: nam='db file sequential read' ela= 40 file#=7 block#=2556543 blocks=1 obj#=77261 tim=480442160
WAIT #2: nam='db file scattered read' ela= 494 file#=8 block#=13312 blocks=8 obj#=77261 tim=480442829
WAIT #2: nam='db file scattered read' ela= 78 file#=8 block#=13416 blocks=8 obj#=77262 tim=480443114
FETCH #2:c=0,e=1843,p=20,cr=10,cu=0,mis=0,r=500,dep=0,og=1,plh=39991016,tim=480443275
WAIT #2: nam='SQL*Net message from client' ela= 1372 driver id=1413697536 #bytes=1 p3=0 obj#=77262 tim=480444666
WAIT #2: nam='SQL*Net message to client' ela= 0 driver id=1413697536 #bytes=1 p3=0 obj#=77262 tim=480444699
WAIT #2: nam='db file scattered read' ela= 90 file#=8 block#=13320 blocks=8 obj#=77261 tim=480445061
FETCH #2:c=0,e=662,p=8,cr=11,cu=0,mis=0,r=500,dep=0,og=1,plh=39991016,tim=480445350
WAIT #2: nam='SQL*Net message from client' ela= 1364 driver id=1413697536 #bytes=1 p3=0 obj#=77261 tim=480446736
WAIT #2: nam='SQL*Net message to client' ela= 0 driver id=1413697536 #bytes=1 p3=0 obj#=77261 tim=480446768
WAIT #2: nam='db file scattered read' ela= 505 file#=8 block#=13328 blocks=8 obj#=77261 tim=480447559
FETCH #2:c=0,e=1060,p=8,cr=11,cu=0,mis=0,r=500,dep=0,og=1,plh=39991016,tim=480447818
WAIT #2: nam='SQL*Net message from client' ela= 1347 driver id=1413697536 #bytes=1 p3=0 obj#=77261 tim=480449184
WAIT #2: nam='SQL*Net message to client' ela= 1 driver id=1413697536 #bytes=1 p3=0 obj#=77261 tim=480449217
WAIT #2: nam='db file scattered read' ela= 71 file#=8 block#=13336 blocks=8 obj#=77261 tim=480449537
FETCH #2:c=0,e=650,p=8,cr=10,cu=0,mis=0,r=500,dep=0,og=1,plh=39991016,tim=480449857
WAIT #2: nam='SQL*Net message from client' ela= 1375 driver id=1413697536 #bytes=1 p3=0 obj#=77261 tim=480451251
WAIT #2: nam='SQL*Net message to client' ela= 1 driver id=1413697536 #bytes=1 p3=0 obj#=77261 tim=480451283
WAIT #2: nam='db file scattered read' ela= 487 file#=8 block#=13344 blocks=8 obj#=77261 tim=480452037
FETCH #2:c=0,e=1045,p=8,cr=11,cu=0,mis=0,r=500,dep=0,og=1,plh=39991016,tim=480452318
WAIT #2: nam='SQL*Net message from client' ela= 1502 driver id=1413697536 #bytes=1 p3=0 obj#=77261 tim=480453839
WAIT #2: nam='SQL*Net message to client' ela= 0 driver id=1413697536 #bytes=1 p3=0 obj#=77261 tim=480453872
WAIT #2: nam='db file scattered read' ela= 75 file#=8 block#=13352 blocks=8 obj#=77261 tim=480454179
FETCH #2:c=0,e=662,p=8,cr=11,cu=0,mis=0,r=500,dep=0,og=1,plh=39991016,tim=480454524
WAIT #2: nam='SQL*Net message from client' ela= 1392 driver id=1413697536 #bytes=1 p3=0 obj#=77261 tim=480455961
WAIT #2: nam='SQL*Net message to client' ela= 0 driver id=1413697536 #bytes=1 p3=0 obj#=77261 tim=480456011
WAIT #2: nam='db file scattered read' ela= 509 file#=8 block#=13360 blocks=8 obj#=77261 tim=480456764
FETCH #2:c=0,e=1095,p=8,cr=10,cu=0,mis=0,r=500,dep=0,og=1,plh=39991016,tim=480457096
WAIT #2: nam='SQL*Net message from client' ela= 1287 driver id=1413697536 #bytes=1 p3=0 obj#=77261 tim=480458402
WAIT #2: nam='SQL*Net message to client' ela= 0 driver id=1413697536 #bytes=1 p3=0 obj#=77261 tim=480458434
WAIT #2: nam='db file scattered read' ela= 74 file#=8 block#=13368 blocks=8 obj#=77261 tim=480458717
FETCH #2:c=0,e=646,p=8,cr=11,cu=0,mis=0,r=500,dep=0,og=1,plh=39991016,tim=480459070
WAIT #2: nam='SQL*Net message from client' ela= 1282 driver id=1413697536 #bytes=1 p3=0 obj#=77261 tim=480460372
WAIT #2: nam='SQL*Net message to client' ela= 1 driver id=1413697536 #bytes=1 p3=0 obj#=77261 tim=480460405
WAIT #2: nam='db file scattered read' ela= 486 file#=8 block#=13376 blocks=8 obj#=77261 tim=480461118
WAIT #2: nam='db file scattered read' ela= 506 file#=8 block#=13424 blocks=8 obj#=77262 tim=480461750
FETCH #2:c=0,e=1662,p=16,cr=11,cu=0,mis=0,r=500,dep=0,og=1,plh=39991016,tim=480462056
WAIT #2: nam='SQL*Net message from client' ela= 1298 driver id=1413697536 #bytes=1 p3=0 obj#=77262 tim=480463374
WAIT #2: nam='SQL*Net message to client' ela= 1 driver id=1413697536 #bytes=1 p3=0 obj#=77262 tim=480463408
WAIT #2: nam='db file scattered read' ela= 166 file#=8 block#=13384 blocks=8 obj#=77261 tim=480463763
FETCH #2:c=0,e=743,p=8,cr=10,cu=0,mis=0,r=500,dep=0,og=1,plh=39991016,tim=480464140
WAIT #2: nam='SQL*Net message from client' ela= 1285 driver id=1413697536 #bytes=1 p3=0 obj#=77261 tim=480465444
WAIT #2: nam='SQL*Net message to client' ela= 1 driver id=1413697536 #bytes=1 p3=0 obj#=77261 tim=480465477
WAIT #2: nam='db file scattered read' ela= 482 file#=8 block#=13392 blocks=8 obj#=77261 tim=480466169
FETCH #2:c=0,e=1043,p=8,cr=11,cu=0,mis=0,r=500,dep=0,og=1,plh=39991016,tim=480466510
WAIT #2: nam='SQL*Net message from client' ela= 1326 driver id=1413697536 #bytes=1 p3=0 obj#=77261 tim=480467855
WAIT #2: nam='SQL*Net message to client' ela= 1 driver id=1413697536 #bytes=1 p3=0 obj#=77261 tim=480467887
WAIT #2: nam='db file scattered read' ela= 72 file#=8 block#=13400 blocks=8 obj#=77261 tim=480468126
FETCH #2:c=0,e=661,p=8,cr=11,cu=0,mis=0,r=500,dep=0,og=1,plh=39991016,tim=480468538
WAIT #2: nam='SQL*Net message from client' ela= 1310 driver id=1413697536 #bytes=1 p3=0 obj#=77261 tim=480469868
WAIT #2: nam='SQL*Net message to client' ela= 0 driver id=1413697536 #bytes=1 p3=0 obj#=77261 tim=480469901
WAIT #2: nam='db file sequential read' ela= 336 file#=7 block#=2556546 blocks=1 obj#=77261 tim=480470411
WAIT #2: nam='db file sequential read' ela= 44 file#=7 block#=2556547 blocks=1 obj#=77261 tim=480470701
WAIT #2: nam='db file sequential read' ela= 396 file#=7 block#=2556548 blocks=1 obj#=77261 tim=480471336
WAIT #2: nam='db file sequential read' ela= 42 file#=7 block#=2556549 blocks=1 obj#=77261 tim=480471575
WAIT #2: nam='db file sequential read' ela= 288 file#=7 block#=2556550 blocks=1 obj#=77261 tim=480472025
WAIT #2: nam='db file sequential read' ela= 38 file#=7 block#=2556551 blocks=1 obj#=77261 tim=480472256
FETCH #2:c=15600,e=2414,p=6,cr=11,cu=0,mis=0,r=500,dep=0,og=1,plh=39991016,tim=480472305
WAIT #2: nam='SQL*Net message from client' ela= 1307 driver id=1413697536 #bytes=1 p3=0 obj#=77261 tim=480473659
WAIT #2: nam='SQL*Net message to client' ela= 1 driver id=1413697536 #bytes=1 p3=0 obj#=77261 tim=480473692
WAIT #2: nam='db file sequential read' ela= 266 file#=7 block#=2556552 blocks=1 obj#=77261 tim=480474032
WAIT #2: nam='db file sequential read' ela= 42 file#=7 block#=2556553 blocks=1 obj#=77261 tim=480474264
WAIT #2: nam='db file sequential read' ela= 278 file#=7 block#=2556554 blocks=1 obj#=77261 tim=480474708
WAIT #2: nam='db file sequential read' ela= 23 file#=7 block#=2556555 blocks=1 obj#=77261 tim=480474939
WAIT #2: nam='db file sequential read' ela= 287 file#=7 block#=2556556 blocks=1 obj#=77261 tim=480475305
WAIT #2: nam='db file sequential read' ela= 39 file#=7 block#=2556557 blocks=1 obj#=77261 tim=480475546
WAIT #2: nam='db file sequential read' ela= 281 file#=7 block#=2556558 blocks=1 obj#=77261 tim=480475989
FETCH #2:c=0,e=2484,p=7,cr=10,cu=0,mis=0,r=500,dep=0,og=1,plh=39991016,tim=480476165
WAIT #2: nam='SQL*Net message from client' ela= 1301 driver id=1413697536 #bytes=1 p3=0 obj#=77261 tim=480477486
WAIT #2: nam='SQL*Net message to client' ela= 1 driver id=1413697536 #bytes=1 p3=0 obj#=77261 tim=480477519
WAIT #2: nam='db file sequential read' ela= 110 file#=7 block#=2556559 blocks=1 obj#=77261 tim=480477664
WAIT #2: nam='db file sequential read' ela= 53 file#=7 block#=2556560 blocks=1 obj#=77261 tim=480477956
WAIT #2: nam='db file sequential read' ela= 39 file#=7 block#=2556561 blocks=1 obj#=77261 tim=480478164
WAIT #2: nam='db file sequential read' ela= 39 file#=7 block#=2556562 blocks=1 obj#=77261 tim=480478364
WAIT #2: nam='db file sequential read' ela= 41 file#=7 block#=2556563 blocks=1 obj#=77261 tim=480478562
WAIT #2: nam='db file sequential read' ela= 70 file#=7 block#=2556564 blocks=1 obj#=77261 tim=480478822
WAIT #2: nam='db file sequential read' ela= 38 file#=7 block#=2556565 blocks=1 obj#=77261 tim=480479055
WAIT #2: nam='db file sequential read' ela= 42 file#=7 block#=2556566 blocks=1 obj#=77261 tim=480479261
FETCH #2:c=0,e=1869,p=8,cr=11,cu=0,mis=0,r=500,dep=0,og=1,plh=39991016,tim=480479377
WAIT #2: nam='SQL*Net message from client' ela= 1289 driver id=1413697536 #bytes=1 p3=0 obj#=77261 tim=480480704
WAIT #2: nam='SQL*Net message to client' ela= 1 driver id=1413697536 #bytes=1 p3=0 obj#=77261 tim=480480736
WAIT #2: nam='db file sequential read' ela= 86 file#=7 block#=2556567 blocks=1 obj#=77261 tim=480480874
WAIT #2: nam='db file sequential read' ela= 39 file#=7 block#=2556568 blocks=1 obj#=77261 tim=480481096
WAIT #2: nam='db file scattered read' ela= 549 file#=8 block#=13432 blocks=8 obj#=77262 tim=480481724
WAIT #2: nam='db file sequential read' ela= 38 file#=7 block#=2556569 blocks=1 obj#=77261 tim=480481922
WAIT #2: nam='db file sequential read' ela= 38 file#=7 block#=2556570 blocks=1 obj#=77261 tim=480482122
WAIT #2: nam='db file sequential read' ela= 38 file#=7 block#=2556571 blocks=1 obj#=77261 tim=480482325
WAIT #2: nam='db file sequential read' ela= 38 file#=7 block#=2556572 blocks=1 obj#=77261 tim=480482537
WAIT #2: nam='db file sequential read' ela= 37 file#=7 block#=2556573 blocks=1 obj#=77261 tim=480482738
WAIT #2: nam='db file sequential read' ela= 36 file#=7 block#=2556574 blocks=1 obj#=77261 tim=480482939
FETCH #2:c=0,e=2276,p=16,cr=11,cu=0,mis=0,r=500,dep=0,og=1,plh=39991016,tim=480483002
WAIT #2: nam='SQL*Net message from client' ela= 1305 driver id=1413697536 #bytes=1 p3=0 obj#=77261 tim=480484352
WAIT #2: nam='SQL*Net message to client' ela= 0 driver id=1413697536 #bytes=1 p3=0 obj#=77261 tim=480484384
WAIT #2: nam='db file sequential read' ela= 49 file#=7 block#=2556575 blocks=1 obj#=77261 tim=480484502
WAIT #2: nam='db file sequential read' ela= 39 file#=7 block#=2556576 blocks=1 obj#=77261 tim=480484710
WAIT #2: nam='db file sequential read' ela= 110 file#=7 block#=2556577 blocks=1 obj#=77261 tim=480484979
WAIT #2: nam='db file sequential read' ela= 105 file#=7 block#=2556578 blocks=1 obj#=77261 tim=480485257
WAIT #2: nam='db file sequential read' ela= 108 file#=7 block#=2556579 blocks=1 obj#=77261 tim=480485531
WAIT #2: nam='db file sequential read' ela= 108 file#=7 block#=2556580 blocks=1 obj#=77261 tim=480485827
WAIT #2: nam='db file sequential read' ela= 42 file#=7 block#=2556581 blocks=1 obj#=77261 tim=480486045
FETCH #2:c=15600,e=1841,p=7,cr=10,cu=0,mis=0,r=499,dep=0,og=1,plh=39991016,tim=480486215
STAT #2 id=1 cnt=10000 pid=0 pos=1 obj=0 op='FILTER  (cr=374 pr=183 pw=0 time=53328 us)'
STAT #2 id=2 cnt=10000 pid=1 pos=1 obj=0 op='HASH JOIN  (cr=374 pr=183 pw=0 time=51020 us cost=51 size=109 card=1)'
STAT #2 id=3 cnt=10000 pid=2 pos=1 obj=77260 op='TABLE ACCESS FULL T3_1 (cr=158 pr=0 pw=0 time=1645 us cost=47 size=8 card=2)'
STAT #2 id=4 cnt=10000 pid=2 pos=2 obj=77261 op='TABLE ACCESS BY INDEX ROWID T4_1 (cr=216 pr=183 pw=0 time=46277 us cost=3 size=210 card=2)'
STAT #2 id=5 cnt=10000 pid=4 pos=1 obj=77262 op='INDEX RANGE SCAN IND_T4_1 (cr=42 pr=24 pw=0 time=2404 us cost=2 size=0 card=2)'
WAIT #2: nam='SQL*Net message from client' ela= 3978 driver id=1413697536 #bytes=1 p3=0 obj#=77261 tim=480490557
*** SESSION ID:(4.7) 2010-09-06 15:33:24.651

CLOSE #2:c=0,e=9,dep=0,type=0,tim=480512517
=====================

The raw trace file from the second execution on the second server:

=====================
PARSING IN CURSOR #14 len=101 dep=0 uid=185 oct=3 lid=185 tim=480800887 hv=3458052021 ad='46953aca8' sqlid='4122a6m71vbxp'
SELECT
  T3_1.C1, T4_1.C2
FROM
  T3_1, T4_1
WHERE
  T3_1.C1 BETWEEN :N1 AND :N2
  AND T3_1.C1=T4_1.C1
END OF STMT
PARSE #14:c=0,e=20,p=0,cr=0,cu=0,mis=0,r=0,dep=0,og=1,plh=39991016,tim=480800887
BINDS #14:
 Bind#0
  oacdty=02 mxl=22(22) mxlc=00 mal=00 scl=00 pre=00
  oacflg=03 fl2=1000000 frm=00 csi=00 siz=48 off=0
  kxsbbbfp=1fc575b8  bln=22  avl=02  flg=05
  value=1
 Bind#1
  oacdty=02 mxl=22(22) mxlc=00 mal=00 scl=00 pre=00
  oacflg=03 fl2=1000000 frm=00 csi=00 siz=0 off=24
  kxsbbbfp=1fc575d0  bln=22  avl=02  flg=01
  value=2
EXEC #14:c=0,e=898,p=0,cr=0,cu=0,mis=1,r=0,dep=0,og=1,plh=39991016,tim=480801842
WAIT #14: nam='SQL*Net message to client' ela= 1 driver id=1413697536 #bytes=1 p3=0 obj#=0 tim=480801869
WAIT #14: nam='db file sequential read' ela= 57 file#=8 block#=13154 blocks=1 obj#=77260 tim=480802004
WAIT #14: nam='db file scattered read' ela= 83 file#=8 block#=13155 blocks=5 obj#=77260 tim=480802180
WAIT #14: nam='db file scattered read' ela= 54 file#=8 block#=13160 blocks=8 obj#=77260 tim=480802462
WAIT #14: nam='db file scattered read' ela= 52 file#=8 block#=13169 blocks=7 obj#=77260 tim=480802654
WAIT #14: nam='db file scattered read' ela= 59 file#=8 block#=13176 blocks=8 obj#=77260 tim=480802843
WAIT #14: nam='db file scattered read' ela= 48 file#=7 block#=2556417 blocks=7 obj#=77260 tim=480803026
WAIT #14: nam='db file scattered read' ela= 54 file#=7 block#=2556424 blocks=8 obj#=77260 tim=480803212
WAIT #14: nam='db file scattered read' ela= 47 file#=7 block#=2556433 blocks=7 obj#=77260 tim=480803398
WAIT #14: nam='db file scattered read' ela= 56 file#=7 block#=2556440 blocks=8 obj#=77260 tim=480803591
WAIT #14: nam='db file scattered read' ela= 56 file#=7 block#=2556449 blocks=7 obj#=77260 tim=480803780
WAIT #14: nam='db file scattered read' ela= 48 file#=7 block#=2556456 blocks=8 obj#=77260 tim=480803957
WAIT #14: nam='db file scattered read' ela= 53 file#=7 block#=2556465 blocks=7 obj#=77260 tim=480804152
WAIT #14: nam='db file scattered read' ela= 64 file#=7 block#=2556472 blocks=8 obj#=77260 tim=480804342
WAIT #14: nam='db file scattered read' ela= 52 file#=7 block#=2556481 blocks=7 obj#=77260 tim=480804534
WAIT #14: nam='db file scattered read' ela= 65 file#=7 block#=2556488 blocks=8 obj#=77260 tim=480804726
WAIT #14: nam='db file scattered read' ela= 120 file#=7 block#=2556497 blocks=7 obj#=77260 tim=480804990
WAIT #14: nam='db file scattered read' ela= 100 file#=7 block#=2556504 blocks=8 obj#=77260 tim=480805216
WAIT #14: nam='db file scattered read' ela= 175 file#=8 block#=13186 blocks=36 obj#=77260 tim=480805574
WAIT #14: nam='db file scattered read' ela= 81 file#=8 block#=13408 blocks=8 obj#=77262 tim=480805968
WAIT #14: nam='db file sequential read' ela= 58 file#=7 block#=2556515 blocks=1 obj#=77261 tim=480806114
FETCH #14:c=0,e=4284,p=164,cr=161,cu=0,mis=0,r=1,dep=0,og=1,plh=39991016,tim=480806168
WAIT #14: nam='SQL*Net message from client' ela= 660 driver id=1413697536 #bytes=1 p3=0 obj#=77261 tim=480806885
WAIT #14: nam='SQL*Net message to client' ela= 0 driver id=1413697536 #bytes=1 p3=0 obj#=77261 tim=480806921
FETCH #14:c=0,e=48,p=0,cr=2,cu=0,mis=0,r=1,dep=0,og=1,plh=39991016,tim=480806957
STAT #14 id=1 cnt=2 pid=0 pos=1 obj=0 op='FILTER  (cr=163 pr=164 pw=0 time=0 us)'
STAT #14 id=2 cnt=2 pid=1 pos=1 obj=0 op='HASH JOIN  (cr=163 pr=164 pw=0 time=0 us cost=51 size=109 card=1)'
STAT #14 id=3 cnt=2 pid=2 pos=1 obj=77260 op='TABLE ACCESS FULL T3_1 (cr=158 pr=155 pw=0 time=1 us cost=47 size=8 card=2)'
STAT #14 id=4 cnt=2 pid=2 pos=2 obj=77261 op='TABLE ACCESS BY INDEX ROWID T4_1 (cr=5 pr=9 pw=0 time=0 us cost=3 size=210 card=2)'
STAT #14 id=5 cnt=2 pid=4 pos=1 obj=77262 op='INDEX RANGE SCAN IND_T4_1 (cr=3 pr=8 pw=0 time=5 us cost=2 size=0 card=2)'
WAIT #14: nam='SQL*Net message from client' ela= 916 driver id=1413697536 #bytes=1 p3=0 obj#=77261 tim=480807962
*** SESSION ID:(4.7) 2010-09-06 15:33:24.978

CLOSE #14:c=0,e=11,dep=0,type=0,tim=480829385
=====================
PARSING IN CURSOR #16 len=26 dep=0 uid=185 oct=47 lid=185 tim=480829534 hv=3000858490 ad='467bc4398' sqlid='56ndayftduxvu'
BEGIN :N2 := 10000; END;
END OF STMT
PARSE #16:c=0,e=63,p=0,cr=0,cu=0,mis=0,r=0,dep=0,og=1,plh=0,tim=480829534
BINDS #16:
 Bind#0
  oacdty=02 mxl=22(22) mxlc=00 mal=00 scl=00 pre=00
  oacflg=03 fl2=1000000 frm=00 csi=00 siz=24 off=0
  kxsbbbfp=2157ab70  bln=22  avl=02  flg=05
  value=2
WAIT #16: nam='SQL*Net message to client' ela= 0 driver id=1413697536 #bytes=1 p3=0 obj#=77261 tim=480829651
EXEC #16:c=0,e=79,p=0,cr=0,cu=0,mis=0,r=1,dep=0,og=1,plh=0,tim=480829664
WAIT #16: nam='SQL*Net message from client' ela= 16786 driver id=1413697536 #bytes=1 p3=0 obj#=77261 tim=480846479
*** SESSION ID:(4.7) 2010-09-06 15:33:24.994

CLOSE #16:c=0,e=13,dep=0,type=0,tim=480848124
=====================
PARSING IN CURSOR #9 len=101 dep=0 uid=185 oct=3 lid=185 tim=480848185 hv=3458052021 ad='46953aca8' sqlid='4122a6m71vbxp'
SELECT
  T3_1.C1, T4_1.C2
FROM
  T3_1, T4_1
WHERE
  T3_1.C1 BETWEEN :N1 AND :N2
  AND T3_1.C1=T4_1.C1
END OF STMT
PARSE #9:c=0,e=29,p=0,cr=0,cu=0,mis=0,r=0,dep=0,og=1,plh=39991016,tim=480848185
BINDS #9:
 Bind#0
  oacdty=02 mxl=22(22) mxlc=00 mal=00 scl=00 pre=00
  oacflg=03 fl2=1000000 frm=00 csi=00 siz=48 off=0
  kxsbbbfp=1fc575b8  bln=22  avl=02  flg=05
  value=1
 Bind#1
  oacdty=02 mxl=22(22) mxlc=00 mal=00 scl=00 pre=00
  oacflg=03 fl2=1000000 frm=00 csi=00 siz=0 off=24
  kxsbbbfp=1fc575d0  bln=22  avl=02  flg=01
  value=10000
EXEC #9:c=0,e=878,p=0,cr=0,cu=0,mis=1,r=0,dep=0,og=1,plh=1389598788,tim=480849120
WAIT #9: nam='SQL*Net message to client' ela= 0 driver id=1413697536 #bytes=1 p3=0 obj#=77261 tim=480849146
WAIT #9: nam='db file sequential read' ela= 64 file#=7 block#=2556514 blocks=1 obj#=77261 tim=480851978
FETCH #9:c=0,e=3233,p=1,cr=162,cu=0,mis=0,r=1,dep=0,og=1,plh=1389598788,tim=480852394
WAIT #9: nam='SQL*Net message from client' ela= 622 driver id=1413697536 #bytes=1 p3=0 obj#=77261 tim=480853041
WAIT #9: nam='SQL*Net message to client' ela= 1 driver id=1413697536 #bytes=1 p3=0 obj#=77261 tim=480853074
WAIT #9: nam='db file scattered read' ela= 56 file#=7 block#=2556516 blocks=4 obj#=77261 tim=480853200
WAIT #9: nam='db file scattered read' ela= 54 file#=7 block#=2556520 blocks=8 obj#=77261 tim=480853514
FETCH #9:c=0,e=654,p=12,cr=8,cu=0,mis=0,r=500,dep=0,og=1,plh=1389598788,tim=480853719
WAIT #9: nam='SQL*Net message from client' ela= 1298 driver id=1413697536 #bytes=1 p3=0 obj#=77261 tim=480855067
WAIT #9: nam='SQL*Net message to client' ela= 1 driver id=1413697536 #bytes=1 p3=0 obj#=77261 tim=480855099
WAIT #9: nam='db file scattered read' ela= 68 file#=7 block#=2556529 blocks=7 obj#=77261 tim=480855450
FETCH #9:c=0,e=528,p=7,cr=9,cu=0,mis=0,r=500,dep=0,og=1,plh=1389598788,tim=480855618
WAIT #9: nam='SQL*Net message from client' ela= 1296 driver id=1413697536 #bytes=1 p3=0 obj#=77261 tim=480856933
WAIT #9: nam='SQL*Net message to client' ela= 1 driver id=1413697536 #bytes=1 p3=0 obj#=77261 tim=480856964
WAIT #9: nam='db file scattered read' ela= 52 file#=7 block#=2556536 blocks=8 obj#=77261 tim=480857207
FETCH #9:c=0,e=476,p=8,cr=9,cu=0,mis=0,r=500,dep=0,og=1,plh=1389598788,tim=480857431
WAIT #9: nam='SQL*Net message from client' ela= 1299 driver id=1413697536 #bytes=1 p3=0 obj#=77261 tim=480858748
WAIT #9: nam='SQL*Net message to client' ela= 1 driver id=1413697536 #bytes=1 p3=0 obj#=77261 tim=480858779
WAIT #9: nam='db file scattered read' ela= 53 file#=8 block#=13313 blocks=7 obj#=77261 tim=480859035
FETCH #9:c=0,e=474,p=7,cr=8,cu=0,mis=0,r=500,dep=0,og=1,plh=1389598788,tim=480859245
WAIT #9: nam='SQL*Net message from client' ela= 1351 driver id=1413697536 #bytes=1 p3=0 obj#=77261 tim=480860614
WAIT #9: nam='SQL*Net message to client' ela= 1 driver id=1413697536 #bytes=1 p3=0 obj#=77261 tim=480860671
WAIT #9: nam='db file scattered read' ela= 51 file#=8 block#=13320 blocks=8 obj#=77261 tim=480860899
FETCH #9:c=0,e=465,p=8,cr=9,cu=0,mis=0,r=500,dep=0,og=1,plh=1389598788,tim=480861127
WAIT #9: nam='SQL*Net message from client' ela= 1284 driver id=1413697536 #bytes=1 p3=0 obj#=77261 tim=480862430
WAIT #9: nam='SQL*Net message to client' ela= 0 driver id=1413697536 #bytes=1 p3=0 obj#=77261 tim=480862461
WAIT #9: nam='db file scattered read' ela= 50 file#=8 block#=13329 blocks=7 obj#=77261 tim=480862698
FETCH #9:c=0,e=459,p=7,cr=9,cu=0,mis=0,r=500,dep=0,og=1,plh=1389598788,tim=480862912
WAIT #9: nam='SQL*Net message from client' ela= 1294 driver id=1413697536 #bytes=1 p3=0 obj#=77261 tim=480864224
WAIT #9: nam='SQL*Net message to client' ela= 0 driver id=1413697536 #bytes=1 p3=0 obj#=77261 tim=480864255
WAIT #9: nam='db file scattered read' ela= 50 file#=8 block#=13336 blocks=8 obj#=77261 tim=480864474
FETCH #9:c=0,e=467,p=8,cr=8,cu=0,mis=0,r=500,dep=0,og=1,plh=1389598788,tim=480864713
WAIT #9: nam='SQL*Net message from client' ela= 1300 driver id=1413697536 #bytes=1 p3=0 obj#=77261 tim=480866031
WAIT #9: nam='SQL*Net message to client' ela= 1 driver id=1413697536 #bytes=1 p3=0 obj#=77261 tim=480866062
WAIT #9: nam='db file scattered read' ela= 51 file#=8 block#=13345 blocks=7 obj#=77261 tim=480866290
FETCH #9:c=0,e=462,p=7,cr=9,cu=0,mis=0,r=500,dep=0,og=1,plh=1389598788,tim=480866516
WAIT #9: nam='SQL*Net message from client' ela= 1297 driver id=1413697536 #bytes=1 p3=0 obj#=77261 tim=480867832
WAIT #9: nam='SQL*Net message to client' ela= 0 driver id=1413697536 #bytes=1 p3=0 obj#=77261 tim=480867863
WAIT #9: nam='db file scattered read' ela= 51 file#=8 block#=13352 blocks=8 obj#=77261 tim=480868069
FETCH #9:c=0,e=467,p=8,cr=9,cu=0,mis=0,r=500,dep=0,og=1,plh=1389598788,tim=480868321
WAIT #9: nam='SQL*Net message from client' ela= 1304 driver id=1413697536 #bytes=1 p3=0 obj#=77261 tim=480869643
WAIT #9: nam='SQL*Net message to client' ela= 1 driver id=1413697536 #bytes=1 p3=0 obj#=77261 tim=480869674
WAIT #9: nam='db file scattered read' ela= 52 file#=8 block#=13361 blocks=7 obj#=77261 tim=480869892
FETCH #9:c=0,e=474,p=7,cr=9,cu=0,mis=0,r=500,dep=0,og=1,plh=1389598788,tim=480870139
WAIT #9: nam='SQL*Net message from client' ela= 1286 driver id=1413697536 #bytes=1 p3=0 obj#=77261 tim=480871444
WAIT #9: nam='SQL*Net message to client' ela= 1 driver id=1413697536 #bytes=1 p3=0 obj#=77261 tim=480871475
WAIT #9: nam='db file scattered read' ela= 55 file#=8 block#=13368 blocks=8 obj#=77261 tim=480871672
FETCH #9:c=0,e=523,p=8,cr=9,cu=0,mis=0,r=500,dep=0,og=1,plh=1389598788,tim=480871989
WAIT #9: nam='SQL*Net message from client' ela= 1343 driver id=1413697536 #bytes=1 p3=0 obj#=77261 tim=480873360
WAIT #9: nam='SQL*Net message to client' ela= 0 driver id=1413697536 #bytes=1 p3=0 obj#=77261 tim=480873392
WAIT #9: nam='db file scattered read' ela= 54 file#=8 block#=13377 blocks=7 obj#=77261 tim=480873598
FETCH #9:c=0,e=474,p=7,cr=9,cu=0,mis=0,r=500,dep=0,og=1,plh=1389598788,tim=480873857
WAIT #9: nam='SQL*Net message from client' ela= 1298 driver id=1413697536 #bytes=1 p3=0 obj#=77261 tim=480875174
WAIT #9: nam='SQL*Net message to client' ela= 1 driver id=1413697536 #bytes=1 p3=0 obj#=77261 tim=480875205
WAIT #9: nam='db file scattered read' ela= 56 file#=8 block#=13384 blocks=8 obj#=77261 tim=480875392
FETCH #9:c=0,e=472,p=8,cr=8,cu=0,mis=0,r=500,dep=0,og=1,plh=1389598788,tim=480875668
WAIT #9: nam='SQL*Net message from client' ela= 1396 driver id=1413697536 #bytes=1 p3=0 obj#=77261 tim=480877083
WAIT #9: nam='SQL*Net message to client' ela= 1 driver id=1413697536 #bytes=1 p3=0 obj#=77261 tim=480877131
WAIT #9: nam='db file scattered read' ela= 52 file#=8 block#=13393 blocks=7 obj#=77261 tim=480877320
FETCH #9:c=0,e=463,p=7,cr=9,cu=0,mis=0,r=500,dep=0,og=1,plh=1389598788,tim=480877585
WAIT #9: nam='SQL*Net message from client' ela= 1295 driver id=1413697536 #bytes=1 p3=0 obj#=77261 tim=480878899
WAIT #9: nam='SQL*Net message to client' ela= 0 driver id=1413697536 #bytes=1 p3=0 obj#=77261 tim=480878930
WAIT #9: nam='db file scattered read' ela= 52 file#=8 block#=13400 blocks=8 obj#=77261 tim=480879100
FETCH #9:c=0,e=467,p=8,cr=9,cu=0,mis=0,r=500,dep=0,og=1,plh=1389598788,tim=480879389
WAIT #9: nam='SQL*Net message from client' ela= 1296 driver id=1413697536 #bytes=1 p3=0 obj#=77261 tim=480880704
WAIT #9: nam='SQL*Net message to client' ela= 0 driver id=1413697536 #bytes=1 p3=0 obj#=77261 tim=480880735
WAIT #9: nam='db file scattered read' ela= 196 file#=7 block#=2556546 blocks=36 obj#=77261 tim=480881087
FETCH #9:c=0,e=686,p=36,cr=9,cu=0,mis=0,r=500,dep=0,og=1,plh=1389598788,tim=480881412
WAIT #9: nam='SQL*Net message from client' ela= 1349 driver id=1413697536 #bytes=1 p3=0 obj#=77261 tim=480882780
WAIT #9: nam='SQL*Net message to client' ela= 1 driver id=1413697536 #bytes=1 p3=0 obj#=77261 tim=480882811
FETCH #9:c=0,e=289,p=0,cr=8,cu=0,mis=0,r=500,dep=0,og=1,plh=1389598788,tim=480883091
WAIT #9: nam='SQL*Net message from client' ela= 1284 driver id=1413697536 #bytes=1 p3=0 obj#=77261 tim=480884393
WAIT #9: nam='SQL*Net message to client' ela= 0 driver id=1413697536 #bytes=1 p3=0 obj#=77261 tim=480884424
FETCH #9:c=0,e=289,p=0,cr=9,cu=0,mis=0,r=500,dep=0,og=1,plh=1389598788,tim=480884704
WAIT #9: nam='SQL*Net message from client' ela= 1292 driver id=1413697536 #bytes=1 p3=0 obj#=77261 tim=480886015
WAIT #9: nam='SQL*Net message to client' ela= 1 driver id=1413697536 #bytes=1 p3=0 obj#=77261 tim=480886046
FETCH #9:c=0,e=290,p=0,cr=9,cu=0,mis=0,r=500,dep=0,og=1,plh=1389598788,tim=480886327
WAIT #9: nam='SQL*Net message from client' ela= 1291 driver id=1413697536 #bytes=1 p3=0 obj#=77261 tim=480887636
WAIT #9: nam='SQL*Net message to client' ela= 0 driver id=1413697536 #bytes=1 p3=0 obj#=77261 tim=480887666
FETCH #9:c=0,e=313,p=0,cr=8,cu=0,mis=0,r=499,dep=0,og=1,plh=1389598788,tim=480887971
STAT #9 id=1 cnt=10000 pid=0 pos=1 obj=0 op='FILTER  (cr=336 pr=154 pw=0 time=4999 us)'
STAT #9 id=2 cnt=10000 pid=1 pos=1 obj=0 op='HASH JOIN  (cr=336 pr=154 pw=0 time=4102 us cost=95 size=1090000 card=10000)'
STAT #9 id=3 cnt=10000 pid=2 pos=1 obj=77260 op='TABLE ACCESS FULL T3_1 (cr=158 pr=0 pw=0 time=1771 us cost=47 size=40000 card=10000)'
STAT #9 id=4 cnt=10000 pid=2 pos=2 obj=77261 op='TABLE ACCESS FULL T4_1 (cr=178 pr=154 pw=0 time=1281 us cost=47 size=1050000 card=10000)'
WAIT #9: nam='SQL*Net message from client' ela= 4000 driver id=1413697536 #bytes=1 p3=0 obj#=77261 tim=480892264
*** SESSION ID:(4.7) 2010-09-06 15:33:25.056

CLOSE #9:c=0,e=8,dep=0,type=0,tim=480915337
=====================

How are the trace files from the two servers the same, and how are they different?  To possibly help you see the differences, the TKPROF summaries from the second server:

TKPROF N1 = 1, N2 = 2 and N2 = 10,000, first execution, second server:

SELECT
  T3_1.C1, T4_1.C2
FROM
  T3_1, T4_1
WHERE
  T3_1.C1 BETWEEN :N1 AND :N2
  AND T3_1.C1=T4_1.C1

call     count       cpu    elapsed       disk      query    current        rows
------- ------  -------- ---------- ---------- ---------- ----------  ----------
Parse        2      0.00       0.00          0          0          0           0
Execute      2      0.00       0.00          0          0          0           0
Fetch       23      0.04       0.03        344        537          0       10002
------- ------  -------- ---------- ---------- ---------- ----------  ----------
total       27      0.04       0.04        344        537          0       10002

Misses in library cache during parse: 1
Misses in library cache during execute: 1
Optimizer mode: ALL_ROWS
Parsing user id: 185 

Rows     Row Source Operation
-------  ---------------------------------------------------
  10000  FILTER  (cr=374 pr=183 pw=0 time=53328 us)
  10000   HASH JOIN  (cr=374 pr=183 pw=0 time=51020 us cost=51 size=109 card=1)
  10000    TABLE ACCESS FULL T3_1 (cr=158 pr=0 pw=0 time=1645 us cost=47 size=8 card=2)
  10000    TABLE ACCESS BY INDEX ROWID T4_1 (cr=216 pr=183 pw=0 time=46277 us cost=3 size=210 card=2)
  10000     INDEX RANGE SCAN IND_T4_1 (cr=42 pr=24 pw=0 time=2404 us cost=2 size=0 card=2)(object id 77262)

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

TKPROF N1 = 1, N2 = 2 and N2 = 10,000, second execution, second server:

SELECT
  T3_1.C1, T4_1.C2
FROM
  T3_1, T4_1
WHERE
  T3_1.C1 BETWEEN :N1 AND :N2
  AND T3_1.C1=T4_1.C1

call     count       cpu    elapsed       disk      query    current        rows
------- ------  -------- ---------- ---------- ---------- ----------  ----------
Parse        1      0.00       0.00          0          0          0           0
Execute      1      0.00       0.00          0          0          0           0
Fetch        2      0.00       0.00        164        163          0           2
------- ------  -------- ---------- ---------- ---------- ----------  ----------
total        4      0.00       0.00        164        163          0           2

Misses in library cache during parse: 0
Misses in library cache during execute: 1
Optimizer mode: ALL_ROWS
Parsing user id: 185 

Rows     Row Source Operation
-------  ---------------------------------------------------
      2  FILTER  (cr=163 pr=164 pw=0 time=0 us)
      2   HASH JOIN  (cr=163 pr=164 pw=0 time=0 us cost=51 size=109 card=1)
      2    TABLE ACCESS FULL T3_1 (cr=158 pr=155 pw=0 time=1 us cost=47 size=8 card=2)
      2    TABLE ACCESS BY INDEX ROWID T4_1 (cr=5 pr=9 pw=0 time=0 us cost=3 size=210 card=2)
      2     INDEX RANGE SCAN IND_T4_1 (cr=3 pr=8 pw=0 time=5 us cost=2 size=0 card=2)(object id 77262)

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

SELECT
  T3_1.C1, T4_1.C2
FROM
  T3_1, T4_1
WHERE
  T3_1.C1 BETWEEN :N1 AND :N2
  AND T3_1.C1=T4_1.C1

call     count       cpu    elapsed       disk      query    current        rows
------- ------  -------- ---------- ---------- ---------- ----------  ----------
Parse        1      0.00       0.00          0          0          0           0
Execute      1      0.00       0.00          0          0          0           0
Fetch       21      0.00       0.01        154        336          0       10000
------- ------  -------- ---------- ---------- ---------- ----------  ----------
total       23      0.00       0.01        154        336          0       10000

Misses in library cache during parse: 0
Misses in library cache during execute: 1
Optimizer mode: ALL_ROWS
Parsing user id: 185 

Rows     Row Source Operation
-------  ---------------------------------------------------
  10000  FILTER  (cr=336 pr=154 pw=0 time=4999 us)
  10000   HASH JOIN  (cr=336 pr=154 pw=0 time=4102 us cost=95 size=1090000 card=10000)
  10000    TABLE ACCESS FULL T3_1 (cr=158 pr=0 pw=0 time=1771 us cost=47 size=40000 card=10000)
  10000    TABLE ACCESS FULL T4_1 (cr=178 pr=154 pw=0 time=1281 us cost=47 size=1050000 card=10000)

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

The SQL*Plus statistics output from both servers were virtually identical.  What is the same, and what is the difference between the executions on both servers?

Graphical Work Center Utilization – Creating the Demo Data and Active Server Page

September 1, 2010

Today’s blog article provides a graphical view of production work areas on a factory floor, providing feedback to indicate when the production area is in use.  The blog article includes a classic ASP web page which uses VBScript to write the web page on the fly to the browser on the client computer.  The web page written to the client browser automatically refreshes itself every 30 seconds, automatically advancing the view time by 15 minutes, displaying the production work areas that were in use during the new view time (the time displayed at the top of the page).

The ASP web page is the simple part of today’s blog article (although enabling classic ASP support may be a little challenging), while creating the demo data is actually the challenging portion of the article.  First, we need a table that will define the production work areas and the locations of those areas on the factory floor:

CREATE TABLE RESOURCE_LOCATION_DEMO (
  RESOURCE_ID VARCHAR2(15),
  DESCRIPTION VARCHAR2(30),
  LOCATION_LEFT NUMBER(12,4),
  LOCATION_TOP NUMBER(12,4),
  LOCATION_WIDTH NUMBER(12,4),
  LOCATION_HEIGHT NUMBER(12,4),
  PRIMARY KEY (RESOURCE_ID));

To keep things interesting, I do not want to just place the first production work area next to the second, the second next to the third, etc.  Instead, I want to randomly locate the production work areas on the factory floor, making certain that no two work areas overlap.  We can accomplish this by creating a list of numbers and ordering the numbers in a random sequence, like this:

SELECT
  ROWNUM RN
FROM
  DUAL
CONNECT BY
  LEVEL<=200
ORDER BY
  DBMS_RANDOM.VALUE;

  RN
----
 191
 165
 122
  12
  48
  27
 104
...
 198
 168
 150

200 rows selected.

Now, to locate the production work areas, imagine that we permitted 10 work areas horizontally (along the X axis) across the factory floor.  We can use the above number sequence along with the MOD function to determine the horizontal location of the work areas, and the FLOOR function to determine the vertical location of the work areas (note that each time we run this SQL statement will we receive different results):

SELECT
  'MA'||TO_CHAR(ROWNUM) RESOURCE_ID,
  'Shop Floor Machine '||TO_CHAR(ROWNUM) DESCRIPTION,
  MOD(RN,10) BOX_LEFT,
  FLOOR(RN/10) BOX_TOP
FROM
  (SELECT
    ROWNUM RN
  FROM
    DUAL
  CONNECT BY
    LEVEL<=200
  ORDER BY
    DBMS_RANDOM.VALUE)
WHERE
  ROWNUM<=50;

RESOURCE_ID DESCRIPTION                 BOX_LEFT    BOX_TOP
----------- ------------------------- ---------- ----------
MA1         Shop Floor Machine 1               4         14
MA2         Shop Floor Machine 2               9          6
MA3         Shop Floor Machine 3               5          2
MA4         Shop Floor Machine 4               5          9
MA5         Shop Floor Machine 5               7         18
MA6         Shop Floor Machine 6               9          4
MA7         Shop Floor Machine 7               0          8
MA8         Shop Floor Machine 8               6          6
MA9         Shop Floor Machine 9               5          5
MA10        Shop Floor Machine 10              7         15
...
MA49        Shop Floor Machine 49              2         11
MA50        Shop Floor Machine 50              8          7

It would be too boring to assume that each of the production work areas is exactly the same width and height, so we will add a little more randomization.  Additionally, I want each production area to be up to 1.5 units wide and up to 1.0 units tall, both offset 0.25 units from the top-left (we are dealing with screen coordinates here, where positive Y is the same as mathematical -Y).  While there are up to 200 locations on the factory floor for work areas, we will only define 50 work areas (controlled by the ROWNUM<=50 predicate at the end of the SQL statement):

SELECT
  'MA'||TO_CHAR(ROWNUM) RESOURCE_ID,
  'Shop Floor Machine '||TO_CHAR(ROWNUM) DESCRIPTION,
  (MOD(RN,10))*1.5 + 0.25 LOCATION_LEFT,
  (FLOOR(RN/10))*1.0 + 0.25 LOCATION_TOP,
  ROUND(1.5*DBMS_RANDOM.VALUE,4) LOCATION_WIDTH,
  ROUND(1.0*DBMS_RANDOM.VALUE,4) LOCATION_HEIGHT
FROM
  (SELECT
    ROWNUM RN
  FROM
    DUAL
  CONNECT BY
    LEVEL<=200
  ORDER BY
    DBMS_RANDOM.VALUE)
WHERE
  ROWNUM<=50;

RESOURCE_ID DESCRIPTION               LOCATION_LEFT LOCATION_TOP LOCATION_WIDTH LOCATION_HEIGHT
----------- ------------------------- ------------- ------------ -------------- ---------------
MA1         Shop Floor Machine 1               3.25        18.25         1.2386           .7948
MA2         Shop Floor Machine 2               4.75        11.25          .6078           .9578
MA3         Shop Floor Machine 3               1.75        12.25          .5318            .457
MA4         Shop Floor Machine 4               3.25        13.25         1.2908           .9813
MA5         Shop Floor Machine 5                .25        16.25          .3245           .4644
MA6         Shop Floor Machine 6              12.25        15.25           .239           .3822
MA7         Shop Floor Machine 7               1.75        18.25          .0159           .8868
MA8         Shop Floor Machine 8               1.75        16.25          .3948           .8511
MA9         Shop Floor Machine 9              12.25         6.25          .4856           .3356
MA10        Shop Floor Machine 10             13.75        11.25         1.2619           .6124
...
MA49        Shop Floor Machine 49              7.75        16.25          .6664           .6938
MA50        Shop Floor Machine 50              9.25        15.25         1.3449           .6606

Now that we have tested the results, let’s insert a new set of similar random values into the RESOURCE_LOCATION_DEMO table, and display some of the inserted rows:

INSERT INTO
  RESOURCE_LOCATION_DEMO 
SELECT
  'MA'||TO_CHAR(ROWNUM) RESOURCE_ID,
  'Shop Floor Machine '||TO_CHAR(ROWNUM) DESCRIPTION,
  (MOD(RN,10))*1.5 + 0.25 LOCATION_LEFT,
  (FLOOR(RN/10))*1.0 + 0.25 LOCATION_TOP,
  ROUND(1.5*DBMS_RANDOM.VALUE,4) LOCATION_WIDTH,
  ROUND(1.0*DBMS_RANDOM.VALUE,4) LOCATION_HEIGHT
FROM
  (SELECT
    ROWNUM RN
  FROM
    DUAL
  CONNECT BY
    LEVEL<=200
  ORDER BY
    DBMS_RANDOM.VALUE)
WHERE
  ROWNUM<=50;

COMMIT;

SELECT
  *
FROM
  RESOURCE_LOCATION_DEMO;

RESOURCE_ID DESCRIPTION               LOCATION_LEFT LOCATION_TOP LOCATION_WIDTH LOCATION_HEIGHT
----------- ------------------------- ------------- ------------ -------------- ---------------
MA1         Shop Floor Machine 1              10.75        13.25           .104           .2165
MA2         Shop Floor Machine 2               7.75        18.25         1.2291            .478
MA3         Shop Floor Machine 3               9.25        16.25          .3431           .4364
MA4         Shop Floor Machine 4               1.75        15.25          .3665           .7278
MA5         Shop Floor Machine 5               4.75        15.25          .6842           .4507
MA6         Shop Floor Machine 6               4.75        18.25          .1384           .6434
MA7         Shop Floor Machine 7               4.75         7.25          .7448           .2178
MA8         Shop Floor Machine 8               7.75          .25          .3756            .499
MA9         Shop Floor Machine 9               1.75        18.25         1.0155           .0769
MA10        Shop Floor Machine 10              7.75        13.25         1.1892           .7518
...
MA49        Shop Floor Machine 49              6.25         3.25           .278           .6513
MA50        Shop Floor Machine 50               .25        15.25          .5216           .9607

To translate the above storage units (maybe in inch scale) into screen units we will multiply the storage units by 96 (96 dots per inch) and then multiply by the zoom percent (75% = 0.75).

SELECT
  RESOURCE_ID,
  ROUND(LOCATION_LEFT*96 *0.75) LOCATION_LEFT,
  ROUND(LOCATION_TOP*96 *0.75) LOCATION_TOP,
  ROUND(LOCATION_WIDTH*96 *0.75) LOCATION_WIDTH,
  ROUND(LOCATION_HEIGHT*96 *0.75) LOCATION_HEIGHT
FROM
  RESOURCE_LOCATION_DEMO;

RESOURCE_ID LOCATION_LEFT LOCATION_TOP LOCATION_WIDTH LOCATION_HEIGHT
----------- ------------- ------------ -------------- ---------------
MA1                   774          954              7              16
MA2                   558         1314             88              34
MA3                   666         1170             25              31
MA4                   126         1098             26              52
MA5                   342         1098             49              32
MA6                   342         1314             10              46
MA7                   342          522             54              16
MA8                   558           18             27              36
MA9                   126         1314             73               6
MA10                  558          954             86              54
...

Next, we need a table to maintain the time periods in which each of the production work areas was in use, and by whom the work areas were used:

CREATE TABLE LABOR_TICKET_DEMO (
  TRANSACTION_ID NUMBER,
  RESOURCE_ID VARCHAR2(15),
  EMPLOYEE_ID VARCHAR2(15),
  CLOCK_IN DATE,
  CLOCK_OUT DATE,
  PRIMARY KEY (TRANSACTION_ID));

Let’s see if we are able to generate some random data for the table:

ALTER SESSION SET NLS_DATE_FORMAT='DD-MON-YYYY HH24:MI';

SELECT
  ROWNUM TRANSACTION_ID,
  'MA'||TO_CHAR(ROUND(DBMS_RANDOM.VALUE(1,50))) RESOURCE_ID,
  'EMP'||TO_CHAR(ROUND(DBMS_RANDOM.VALUE(1,300))) EMPLOYEE_ID,
  TRUNC(SYSDATE)+DBMS_RANDOM.VALUE CLOCK_IN
FROM
  DUAL
CONNECT BY
  LEVEL<=10;

TRANSACTION_ID RESOURCE_ID EMPLOYEE_ID CLOCK_IN
-------------- ----------- ----------- -----------------
             1 MA29        EMP50       01-SEP-2010 01:56
             2 MA35        EMP181      01-SEP-2010 10:06
             3 MA13        EMP172      01-SEP-2010 17:40
             4 MA21        EMP182      01-SEP-2010 09:00
             5 MA14        EMP80       01-SEP-2010 09:53
             6 MA4         EMP80       01-SEP-2010 19:04
             7 MA7         EMP110      01-SEP-2010 14:34
             8 MA45        EMP19       01-SEP-2010 22:05
             9 MA10        EMP207      01-SEP-2010 21:51
            10 MA46        EMP127      01-SEP-2010 16:49

That worked, but note that we did not generate a CLOCK_OUT time – we want to make certain that the CLOCK_OUT time is after the CLOCK_IN time, but we simply cannot do that with the above SQL statement as written.  We slide the above into an inline view and then set the CLOCK_OUT time to be up to 12 hours after the CLOCK_IN time (DBMS_RANDOM.VALUE by default returns a value between 0 and 1, so if we divide that value by 2, we can add up to 1/2 of a day to the CLOCK_IN date and time):

INSERT INTO
  LABOR_TICKET_DEMO
SELECT
  TRANSACTION_ID,
  RESOURCE_ID,
  EMPLOYEE_ID,
  CLOCK_IN,
  CLOCK_IN + (DBMS_RANDOM.VALUE/2) CLOCK_OUT
FROM
  (SELECT
    ROWNUM TRANSACTION_ID,
    'MA'||TO_CHAR(ROUND(DBMS_RANDOM.VALUE(1,50))) RESOURCE_ID,
    'EMP'||TO_CHAR(ROUND(DBMS_RANDOM.VALUE(1,300))) EMPLOYEE_ID,
    TRUNC(SYSDATE)+DBMS_RANDOM.VALUE CLOCK_IN
  FROM
    DUAL
  CONNECT BY
    LEVEL<=1000);

COMMIT;

Let’s take a look at what made it into the table (your results will be different):

SELECT
  *
FROM
  LABOR_TICKET_DEMO
ORDER BY
  TRANSACTION_ID; 

TRANSACTION_ID RESOURCE_ID     EMPLOYEE_ID     CLOCK_IN          CLOCK_OUT
-------------- --------------- --------------- ----------------- -----------------
             1 MA34            EMP49           01-SEP-2010 20:32 02-SEP-2010 08:18
             2 MA47            EMP230          01-SEP-2010 20:08 02-SEP-2010 03:06
             3 MA20            EMP257          01-SEP-2010 02:17 01-SEP-2010 05:44
             4 MA21            EMP129          01-SEP-2010 09:37 01-SEP-2010 15:41
             5 MA18            EMP214          01-SEP-2010 18:57 01-SEP-2010 20:57
             6 MA46            EMP173          01-SEP-2010 05:51 01-SEP-2010 15:32
             7 MA34            EMP224          01-SEP-2010 20:23 02-SEP-2010 08:17
             8 MA31            EMP8            01-SEP-2010 02:56 01-SEP-2010 14:02
             9 MA37            EMP178          01-SEP-2010 09:28 01-SEP-2010 16:03
            10 MA8             EMP31           01-SEP-2010 20:17 02-SEP-2010 05:51
...
           999 MA43            EMP138          01-SEP-2010 05:07 01-SEP-2010 05:23
          1000 MA2             EMP235          01-SEP-2010 05:29 01-SEP-2010 13:28

We now have 1000 transactions scattered across the 50 work areas (RESOURCE_ID column).  What we next want to determine is which of the work areas was in use at a specific time of the day.  Because we eventually will want only one row per unique RESOURCE_ID value, we will use the ROW_NUMBER analytic function to number each of the rows within each unique RESOURCE_ID value:

SELECT
  RESOURCE_ID,
  EMPLOYEE_ID,
  TRUNC(SYSDATE) + (1.25)/24 CHECK_TIME,
  CLOCK_IN,
  CLOCK_OUT,
  ROW_NUMBER() OVER (PARTITION BY RESOURCE_ID ORDER BY CLOCK_IN) RN
FROM
  LABOR_TICKET_DEMO
WHERE
  CLOCK_IN<=TRUNC(SYSDATE) + (1.25)/24
  AND CLOCK_OUT>TRUNC(SYSDATE) + (1.25)/24
ORDER BY
  RESOURCE_ID,
  CLOCK_IN;

RESOURCE_ID  EMPLOYEE_ID  CHECK_TIME        CLOCK_IN          CLOCK_OUT         RN
------------ ------------ ----------------- ----------------- ----------------- --
MA10         EMP192       01-SEP-2010 01:15 01-SEP-2010 00:21 01-SEP-2010 05:44  1
MA10         EMP233       01-SEP-2010 01:15 01-SEP-2010 00:23 01-SEP-2010 02:42  2
MA16         EMP114       01-SEP-2010 01:15 01-SEP-2010 00:21 01-SEP-2010 04:48  1
MA18         EMP261       01-SEP-2010 01:15 01-SEP-2010 00:18 01-SEP-2010 07:02  1
MA18         EMP133       01-SEP-2010 01:15 01-SEP-2010 00:32 01-SEP-2010 04:35  2
MA2          EMP62        01-SEP-2010 01:15 01-SEP-2010 01:14 01-SEP-2010 12:03  1
MA21         EMP235       01-SEP-2010 01:15 01-SEP-2010 00:05 01-SEP-2010 10:42  1
MA22         EMP4         01-SEP-2010 01:15 01-SEP-2010 00:01 01-SEP-2010 06:27  1
MA22         EMP300       01-SEP-2010 01:15 01-SEP-2010 01:12 01-SEP-2010 11:50  2
MA23         EMP135       01-SEP-2010 01:15 01-SEP-2010 00:35 01-SEP-2010 05:19  1
MA25         EMP35        01-SEP-2010 01:15 01-SEP-2010 00:20 01-SEP-2010 06:58  1
MA28         EMP298       01-SEP-2010 01:15 01-SEP-2010 00:52 01-SEP-2010 06:27  1
MA30         EMP72        01-SEP-2010 01:15 01-SEP-2010 00:56 01-SEP-2010 07:28  1
MA32         EMP84        01-SEP-2010 01:15 01-SEP-2010 01:00 01-SEP-2010 05:25  1
MA34         EMP299       01-SEP-2010 01:15 01-SEP-2010 00:31 01-SEP-2010 12:04  1
MA38         EMP268       01-SEP-2010 01:15 01-SEP-2010 00:31 01-SEP-2010 04:15  1
MA38         EMP278       01-SEP-2010 01:15 01-SEP-2010 00:32 01-SEP-2010 04:50  2
MA38         EMP176       01-SEP-2010 01:15 01-SEP-2010 01:01 01-SEP-2010 04:01  3
MA4          EMP257       01-SEP-2010 01:15 01-SEP-2010 00:10 01-SEP-2010 10:45  1
MA40         EMP231       01-SEP-2010 01:15 01-SEP-2010 00:58 01-SEP-2010 11:01  1
MA43         EMP65        01-SEP-2010 01:15 01-SEP-2010 00:54 01-SEP-2010 09:29  1
MA44         EMP18        01-SEP-2010 01:15 01-SEP-2010 00:07 01-SEP-2010 03:30  1
MA46         EMP36        01-SEP-2010 01:15 01-SEP-2010 00:40 01-SEP-2010 04:57  1
MA48         EMP61        01-SEP-2010 01:15 01-SEP-2010 00:27 01-SEP-2010 10:20  1
MA48         EMP169       01-SEP-2010 01:15 01-SEP-2010 00:44 01-SEP-2010 01:27  2
MA5          EMP147       01-SEP-2010 01:15 01-SEP-2010 00:02 01-SEP-2010 04:48  1
MA6          EMP132       01-SEP-2010 01:15 01-SEP-2010 00:34 01-SEP-2010 09:42  1

27 rows selected.

In some cases we have up to three employees working in a work area at 1:15AM (the time of day is indicated by the 1.25 value in the SQL statement).  Now, lets eliminate the duplicate rows, leaving just the rows where the calculated RN column is equal to 1.  We will join the above SQL statement in an inline view to the RESOURCE_LOCATION_DEMO table and convert the production work area coordinates to screen coordinates, in this case 96 pixels per unit (inches) at a 75% zoom percent (we made this same screen coordinate conversion in a previous SQL statement above):

SELECT
  RL.RESOURCE_ID,
  RL.DESCRIPTION,
  ROUND(RL.LOCATION_LEFT*96 *0.75) LOCATION_LEFT,
  ROUND(RL.LOCATION_TOP*96 *0.75) LOCATION_TOP,
  ROUND(RL.LOCATION_WIDTH*96 *0.75) LOCATION_WIDTH,
  ROUND(RL.LOCATION_HEIGHT*96 *0.75) LOCATION_HEIGHT,
  LT.EMPLOYEE_ID,
  LT.CLOCK_IN,
  LT.CLOCK_OUT
FROM
  RESOURCE_LOCATION_DEMO RL,
  (SELECT
    RESOURCE_ID,
    EMPLOYEE_ID,
    CLOCK_IN,
    CLOCK_OUT,
    ROW_NUMBER() OVER (PARTITION BY RESOURCE_ID ORDER BY CLOCK_IN) RN
  FROM
    LABOR_TICKET_DEMO
  WHERE
    CLOCK_IN<=TRUNC(SYSDATE) + (1.25)/24
    AND CLOCK_OUT>TRUNC(SYSDATE) + (1.25)/24) LT
WHERE
  RL.RESOURCE_ID=LT.RESOURCE_ID(+)
  AND NVL(LT.RN,1)=1
ORDER BY
  RL.RESOURCE_ID;

RESOURCE_ID  DESCRIPTION                    LOCATION_LEFT LOCATION_TOP LOCATION_WIDTH LOCATION_HEIGHT EMPLOYEE_ID  CLOCK_IN          CLOCK_OUT
------------ ------------------------------ ------------- ------------ -------------- --------------- ------------ ----------------- -----------------
MA1          Shop Floor Machine 1                     774          954              7              16
MA10         Shop Floor Machine 10                    558          954             86              54 EMP192       01-SEP-2010 00:21 01-SEP-2010 05:44
MA11         Shop Floor Machine 11                    882         1098             29               1
MA12         Shop Floor Machine 12                    234          378             51              51
MA13         Shop Floor Machine 13                    882         1314             83              62
MA14         Shop Floor Machine 14                    558          378             38              61
MA15         Shop Floor Machine 15                    774          522             63              64
MA16         Shop Floor Machine 16                    126          666            103              55 EMP114       01-SEP-2010 00:21 01-SEP-2010 04:48
MA17         Shop Floor Machine 17                    558          234             94              30
MA18         Shop Floor Machine 18                    342          450             85              21 EMP261       01-SEP-2010 00:18 01-SEP-2010 07:02
MA19         Shop Floor Machine 19                    342          666             94              20
MA2          Shop Floor Machine 2                     558         1314             88              34 EMP62        01-SEP-2010 01:14 01-SEP-2010 12:03
MA20         Shop Floor Machine 20                    666          162             33              33
MA21         Shop Floor Machine 21                    774          306             66              22 EMP235       01-SEP-2010 00:05 01-SEP-2010 10:42
MA22         Shop Floor Machine 22                    990          378             78              71 EMP4         01-SEP-2010 00:01 01-SEP-2010 06:27
MA23         Shop Floor Machine 23                    666          666             50              37 EMP135       01-SEP-2010 00:35 01-SEP-2010 05:19
MA24         Shop Floor Machine 24                    990          810            107              45
...

From the above output, we know the screen coordinates of each production work area (RESOURCE_ID) and the first employee to use the production work area (and the employee was still using it) at 1:15AM.

For the next portion of this blog article, the portion that requires an ASP enabled web server, we need a couple of pictures (these were created using Microsoft Power Point):

Representing a production work center that is in use:

—

Representing a production work center that is idle:

—

The factory floor – the background area:

——

Now we need the classic ASP page code – note that the code syntax is very similar to that of the previous VBScript examples.  The script uses Response.Write to write information to the client computer’s web browser, and an embedded Java script to call the post event of the embedded HTML form to update the display as of time every 30 seconds (yes, I should have used bind variables in the SQL statement, but that would have required an extra 120 seconds to code and would have left you with nothing to improve):

<html>

<head>
<meta http-equiv="refresh" content="600">
<title>Graphical Work Center Utilization Animated</title>
</head>

<body>
    <%
    Dim strSQL

    Dim sglOriginLeft
    Dim sglOriginTop

    Dim sglZoom
    Dim strZoom

    Dim i
    Dim intWidth
    Dim intHeight
    Dim strOffset
    Dim sglOffset
    Dim varDateTime

    Dim snpData
    Dim dbDatabase

    Set dbDatabase = Server.CreateObject("ADODB.Connection")

    'Database configuration
    strUsername = "MyUsername"
    strPassword = "MyPassword"
    strDatabase = "MyDB"

    On Error Resume Next

    dbDatabase.ConnectionString = "Provider=OraOLEDB.Oracle;Data Source=" & strDatabase & ";User ID=" & strUsername & ";Password=" & strPassword & ";"
    dbDatabase.Open

    'Should verify that the connection attempt was successful, but I will leave that for someone else to code

    Set snpData = Server.CreateObject("ADODB.Recordset")

    'Retrieve the last value for the time offset and the selected zoom percent
    strOffset = Request.Form("txtOffset")
    strZoom = Request.Form("cboZoom")

    'Convert back to a number
    sglOffset = CSng(strOffset)
    sglZoom = CSng(strZoom) / 100

    'Advance to the next 0.25 hour
    if (sglOffset = 0) or (sglOffset = 24) then
        sglOffset = 0.25
    else
        sglOffset = sglOffset + 0.25
    end if

    'Set the zoom percent, if not already set
    If sglZoom = 0 Then
        sglZoom = 0.5 '50% zoom
    End If

    varDateTime = DateAdd("n", sglOffset*60, Date) 'Create a printable version of the view date and time

    Response.Write "<form name=" & chr(34) & "reportform" & chr(34) & " method=" & chr(34) & "POST" & chr(34) & " action=" & chr(34) & "GraphicalWorkCenterUtilization.asp" & chr(34) & ">" & vbcrlf
    Response.Write varDateTime & "  " & vbCrLf
    Response.Write "&nbsp;&nbsp;&nbsp;Zoom Percent <select size=""1"" id=""cboZoom"" name=""cboZoom"" style=""width:50"">" & vbCrLf
    For i = 10 to 200 Step 10
        If sglZoom = i / 100 Then
            Response.Write "<option selected value=""" & cStr(i) & """>" & cStr(i) & "</option>"
        Else
            Response.Write "<option value=""" & cStr(i) & """>" & cStr(i) & "</option>"
        End If
    Next
    Response.Write "</select><br>"
    Response.Write "  <input type=" & chr(34) & "submit" & chr(34) & " value=" & chr(34) & "Update View" & chr(34) & " name=" & chr(34) & "cmdViewReport" & chr(34) & ">" & vbcrlf
    Response.Write "  <input type=" & chr(34) & "hidden" & chr(34) & " name=" & chr(34) & "txtOffset" & chr(34) & " size=" & chr(34) & "5" & chr(34) & " value=" & chr(34) & cStr(sglOffset) & chr(34) & ">" & vbcrlf
    Response.Write "</form>" & vbcrlf

    'The background image
    intWidth = Round(16 * 96 * sglZoom)
    intHeight = Round(20 * 96 * sglZoom)
    Response.Write "<img src=" & chr(34) & "https://hoopercharles.wordpress.com/wp-content/uploads/2010/09/graphicalworkcenterutilizationbackground.jpg" & chr(34) & " width=" & chr(34) & cstr(intWidth) & chr(34) & " height=" & chr(34) & cstr(intheight) & chr(34) & " style=" & chr(34) & "position:absolute;top:50px;left:0px;z-index:-1" & chr(34) & "/>" & vbcrlf

    'The SQL statement developed earlier
    strSQL = "SELECT" & VBCrLf
    strSQL = strSQL & "  RL.RESOURCE_ID," & VBCrLf
    strSQL = strSQL & "  RL.DESCRIPTION," & VBCrLf
    strSQL = strSQL & "  ROUND(RL.LOCATION_LEFT*96 *" & cStr(sglZoom) & ") LOCATION_LEFT," & VBCrLf
    strSQL = strSQL & "  ROUND(RL.LOCATION_TOP*96 *" & cStr(sglZoom) & ") LOCATION_TOP," & VBCrLf
    strSQL = strSQL & "  ROUND(RL.LOCATION_WIDTH*96 *" & cStr(sglZoom) & ") LOCATION_WIDTH," & VBCrLf
    strSQL = strSQL & "  ROUND(RL.LOCATION_HEIGHT*96 *" & cStr(sglZoom) & ") LOCATION_HEIGHT," & VBCrLf
    strSQL = strSQL & "  LT.EMPLOYEE_ID," & VBCrLf
    strSQL = strSQL & "  LT.CLOCK_IN," & VBCrLf
    strSQL = strSQL & "  LT.CLOCK_OUT" & VBCrLf
    strSQL = strSQL & "FROM" & VBCrLf
    strSQL = strSQL & "  RESOURCE_LOCATION_DEMO RL," & VBCrLf
    strSQL = strSQL & "  (SELECT" & VBCrLf
    strSQL = strSQL & "    RESOURCE_ID," & VBCrLf
    strSQL = strSQL & "    EMPLOYEE_ID," & VBCrLf
    strSQL = strSQL & "    CLOCK_IN," & VBCrLf
    strSQL = strSQL & "    CLOCK_OUT," & VBCrLf
    strSQL = strSQL & "    ROW_NUMBER() OVER (PARTITION BY RESOURCE_ID ORDER BY CLOCK_IN) RN" & VBCrLf
    strSQL = strSQL & "  FROM" & VBCrLf
    strSQL = strSQL & "    LABOR_TICKET_DEMO" & VBCrLf
    strSQL = strSQL & "  WHERE" & VBCrLf
    strSQL = strSQL & "    CLOCK_IN<=TRUNC(SYSDATE) + (" & cStr(sglOffset) & ")/24" & VBCrLf
    strSQL = strSQL & "    AND CLOCK_OUT>TRUNC(SYSDATE) + (" & cStr(sglOffset) & ")/24) LT" & VBCrLf
    strSQL = strSQL & "WHERE" & VBCrLf
    strSQL = strSQL & "  RL.RESOURCE_ID=LT.RESOURCE_ID(+)" & VBCrLf
    strSQL = strSQL & "  AND NVL(LT.RN,1)=1" & VBCrLf
    strSQL = strSQL & "ORDER BY" & VBCrLf
    strSQL = strSQL & "  RL.RESOURCE_ID"

    snpData.open strSQL, dbDatabase

    If snpData.State = 1 then
        Response.Write "<B><font color=" & chr(34) & "#0000FF" & chr(34) & "><p style=" & chr(34) & "position:absolute;top:15px;left:500px" & chr(34) & ">" & FormatDateTime(cdate(snpData("START_TIME")),2) & " " & FormatDateTime(cdate(snpData("START_TIME")),4) & " - " & FormatDateTime(cdate(snpData("END_TIME")),4) & "</p></font></b>" & vbcrlf

        Do While Not snpData.EOF
            If Not(IsNull(snpData("employee_id"))) Then
                'A labor ticket was in process during this time period
                Response.Write "<img alt=" & Chr(34) & snpData("resource_id") & "  " & snpData("description") & vbCrlf & snpData("employee_id") & "(" & snpData("clock_in") & " - " & snpData("clock_out") & ")" & Chr(34) & " src=" & chr(34) & "https://hoopercharles.wordpress.com/wp-content/uploads/2010/09/graphicalworkcenterutilizationrunning.jpg" & chr(34) & " width=" & chr(34) & cStr(snpData("location_width")) & chr(34) & " height=" & chr(34) & cStr(snpData("location_height")) & chr(34) & " style=" & chr(34) & "position:absolute;top:" & cStr(cLng(snpData("location_top")) + 40) & "px;left:" & cStr(snpData("location_left")) & "px" & chr(34) & "/>" & vbcrlf
                'Write the title down 1 pixel
                Response.Write "<B><font color=" & chr(34) & "#00FFFF" & chr(34) & "><p style=" & chr(34) & "position:absolute;top:" & cStr(Round(41 + CSng(snpData("location_top")))) & "px;left:" & cStr(Round(CSng(snpData("location_left")))) & "px" & chr(34) & ">" & snpData("resource_id") & "</p></font></b>" & vbcrlf
            Else
                'No labor ticket was in process during this time period
                Response.Write "<img alt=" & Chr(34) & snpData("resource_id") & "  " & snpData("description") & Chr(34) & " src=" & chr(34) & "https://hoopercharles.wordpress.com/wp-content/uploads/2010/09/graphicalworkcenterutilizationstopped.jpg" & chr(34) & " width=" & chr(34) & cStr(snpData("location_width")) & chr(34) & " height=" & chr(34) & cStr(snpData("location_height")) & chr(34) & " style=" & chr(34) & "position:absolute;top:" & cStr(cLng(snpData("location_top")) + 40) & "px;left:" & cStr(snpData("location_left")) & "px" & chr(34) & "/>" & vbcrlf
                'Write the title down 1 pixel
                Response.Write "<B><font color=" & chr(34) & "#FF0000" & chr(34) & "><p style=" & chr(34) & "position:absolute;top:" & cStr(Round(41 + CSng(snpData("location_top")))) & "px;left:" & cStr(Round(CSng(snpData("location_left")))) & "px" & chr(34) & ">" & snpData("resource_id") & "</p></font></b>" & vbcrlf
            End If
            snpData.movenext
        Loop
    End if

    snpData.Close
    dbDatabase.Close

    Set snpData = Nothing
    Set dbDatabase = Nothing
    %>

    <script language="JavaScript1.2">
    function NextInterval(){
      reportform.submit();
    }

      setTimeout("NextInterval()",30000)
    </script>
</body>

</html>

GraphicalWorkCenterUtilization.asp (save as GraphicalWorkCenterUtilization.asp on a web server that supports classic ASP pages)

Below are samples of the output as the display as of time advanced – the zoom percent was set to 50.  Notice that the work centers go online and offline as the time progresses (click a picture to see a larger version of that picture):

—

The final example demonstrates how the display changed when the zoom percent was changed from 50% to 130%:

–

As the mouse pointer is moved over the boxes representing the work centers, a pop-up tooltip appears that describes the work center, as well as employee ID, clock in time, and clock out time for the first labor ticket at that work center in the time period.

——-

Hopefully, you have found this example to be interesting.  Your assignment is to now connect proximity switches to the devices in your office and surrounding areas, recording their location in the RESOURCE_LOCATION_DEMO table.  Then log the proximity switch status to the LABOR_TICKET_DEMO table so that you are able to determine when the water cooler, coffee machine, chairs, keyboards, and computer mice are in use.  Use the data to determine which employees are the hardest working, and which employees have determined how to think smarter rather than working harder.  🙂