10046 Extended SQL Trace Interpretation 3

6 09 2010

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?


Actions

Information

3 responses

10 09 2010
Pavel Ermakov

Hi Charles!

I have a question: why did you gather statistics for the tables twice?

10 09 2010
Charles Hooper

Pavel,

Good question regarding the two executions in the script of:

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)

The second execution of the statistics gathering was NOT performed to change the execution plan. The NO_INVALIDATE parameter (of DBMS_STATS.GATHER_TABLE_STATS) was not set to FALSE, so on Oracle Database 10.1 and above those statistics would not have immediately affected previously generated execution plans.

I selected the statistics gathering lines as the starting point where the script repeated, so that the timings in both 10046 trace files would be affected roughly the same by any data that might remain in the hard drive caches when Oracle’s buffer cache was flushed. It might be interesting to see whether or not removing those lines will affect the outcome of the test results.

13 09 2010
Pavel Ermakov

Hi Charles!

Thanks for the response.

Best regards, Pavel.

Leave a Reply

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

WordPress.com Logo

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

Twitter picture

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

Facebook photo

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

Google+ photo

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

Connecting to %s




Follow

Get every new post delivered to your Inbox.

Join 148 other followers

%d bloggers like this: