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?
Charles Hooper's Oracle Notes 
Recent Comments