January 26, 2010
(Back to the Previous Post in the Series) (Forward to the Next Post in the Series)
In an earlier blog article I described several methods for enabling and disabling 10046 extended SQL traces, listed several keywords that are found in 10046 traces, and demonstrated output generated by my Toy Project for Performance Tuning as it processed the raw trace file.
Another way to enable a 10046 trace for a session is through the use of a logon trigger created by the SYS user. For example, the following trigger will enable a 10046 trace at level 12 for any program that begins with the letters MS or VB, even if the path to the program is included in the PROGRAM column of V$SESSION. With the use of DECODE, it is very easy to allow the trigger to enable tracing for an additional list of programs:
CREATE OR REPLACE TRIGGER LOGON_10046_TRACE AFTER LOGON ON DATABASE DECLARE SHOULD_EXECUTE INTEGER; BEGIN SELECT DECODE(SUBSTR(UPPER(PROGRAM),1,2),'MS',1,'VB',1,0) +DECODE(INSTR(PROGRAM,'\',-1),0,0,DECODE(SUBSTR(UPPER(SUBSTR(PROGRAM,INSTR(PROGRAM,'\',-1)+1)),1,2),'MS',1,'VB',1,0)) INTO SHOULD_EXECUTE FROM V$SESSION WHERE SID=(SELECT SID FROM V$MYSTAT WHERE ROWNUM=1); IF SHOULD_EXECUTE > 0 THEN EXECUTE IMMEDIATE 'ALTER SESSION SET EVENTS ''10046 TRACE NAME CONTEXT FOREVER, LEVEL 12'''; END IF; END; /
Obviously, if you create the trigger, you should drop the trigger when it is no longer needed using the following command.
DROP TRIGGER LOGON_10046_TRACE;
Let’s try creating a test trace file with Oracle Database 10.2.0.4. First, we need to create a couple of test tables with 10,000 rows each and collect statistics for the tables and primary key indexes:
CREATE TABLE T1 ( C1 NUMBER, C2 VARCHAR2(255), PRIMARY KEY (C1)); CREATE TABLE T2 ( C1 NUMBER, C2 VARCHAR2(255), PRIMARY KEY (C1)); INSERT INTO T1 SELECT ROWNUM, RPAD(TO_CHAR(ROWNUM),255,'A') FROM DUAL CONNECT BY LEVEL<=10000; INSERT INTO T2 SELECT ROWNUM, RPAD(TO_CHAR(ROWNUM),255,'A') FROM DUAL CONNECT BY LEVEL<=10000; COMMIT; EXEC DBMS_STATS.GATHER_TABLE_STATS(OWNNAME=>USER,TABNAME=>'T1',CASCADE=>TRUE) EXEC DBMS_STATS.GATHER_TABLE_STATS(OWNNAME=>USER,TABNAME=>'T2',CASCADE=>TRUE)
We now have two tables, each with 10,000 rows. This test case in SQL*Plus will:
- Flush the buffer cache (twice) to force physical reads
- Set the fetch array size to the SQL*Plus default value of 15 rows per fetch call
- Disable output of the rows returned from the database to limit client-side delays
- Create two bind variables with the value of 1 and 2
- Enable a 10046 extended SQL trace at level 12
- Give the trace file an easy to identify name
- Execute a query that joins the two tables
- Increases the fetch array size to 50 rows per fetch call
- Increase the value of the second bind variable from 2 to 10,000
- Execute the same SQL statement executed in step 7
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 EXEC DBMS_SESSION.SESSION_TRACE_ENABLE(WAITS=>TRUE, BINDS=>TRUE) ALTER SESSION SET TRACEFILE_IDENTIFIER='10046_FIND_ME'; SELECT T1.C1, T2.C2 FROM T1, T2 WHERE T1.C1=T2.C1 AND T1.C1 BETWEEN :N1 AND :N2; SET ARRAYSIZE 50 EXEC :N1 := 1 EXEC :N2 := 10000 SELECT T1.C1, T2.C2 FROM T1, T2 WHERE T1.C1=T2.C1 AND T1.C1 BETWEEN :N1 AND :N2; SELECT SYSDATE FROM DUAL; EXEC DBMS_SESSION.SESSION_TRACE_DISABLE;
Rather than scrolling all of the rows on the screen, SQL*Plus output the following from the two executions:
Statistics --------------------------------------------------- 1 recursive calls 0 db block gets 9 consistent gets 5 physical reads 0 redo size 921 bytes sent via SQL*Net to client 334 bytes received via SQL*Net from client 2 SQL*Net roundtrips to/from client 0 sorts (memory) 0 sorts (disk) 2 rows processed Statistics --------------------------------------------------- 0 recursive calls 0 db block gets 10982 consistent gets 404 physical reads 0 redo size 2647906 bytes sent via SQL*Net to client 2523 bytes received via SQL*Net from client 201 SQL*Net roundtrips to/from client 0 sorts (memory) 0 sorts (disk) 10000 rows processed
From the above, the first execution required 9 consistent block gets, and 5 of those block gets involved reading the block from disk. The server sent 921 bytes to the client in 2 round trips, and 2 rows were retrieved. 2 round trips (we will see why later)? The second execution required 10,982 consistent block gets, and 404 of those involved physical reads. The server sent about 2.53MB to the client in 10,000 rows, using 201 round trips. Nice, but we can find out more about what happened.
We could process the trace file with tkprof using a command like this:
tkprof testdb_ora_4148_10046_find_me.trc testdb_ora_4148_10046_find_me.txt
A portion of the TKPROF output might look like this (see Metalink Doc ID 41634.1 for help with reading the tkprof output):
******************************************************************************** count = number of times OCI procedure was executed cpu = cpu time in seconds executing elapsed = elapsed time in seconds executing disk = number of physical reads of buffers from disk query = number of buffers gotten for consistent read current = number of buffers gotten in current mode (usually for update) rows = number of rows processed by the fetch or execute call ******************************************************************************** SELECT T1.C1, T2.C2 FROM T1, T2 WHERE T1.C1=T2.C1 AND T1.C1 BETWEEN :N1 AND :N2 call count cpu elapsed disk query current rows ------- ------ -------- ---------- ---------- ---------- ---------- ---------- Parse 2 0.00 0.00 0 0 0 0 Execute 3 0.00 0.00 0 0 0 0 Fetch 203 0.28 0.38 409 10991 0 10002 ------- ------ -------- ---------- ---------- ---------- ---------- ---------- total 208 0.28 0.38 409 10991 0 10002 Misses in library cache during parse: 1 Misses in library cache during execute: 1 Optimizer mode: ALL_ROWS Parsing user id: 31 Rows Row Source Operation ------- --------------------------------------------------- 2 FILTER (cr=9 pr=5 pw=0 time=19577 us) 2 NESTED LOOPS (cr=9 pr=5 pw=0 time=19569 us) 2 TABLE ACCESS BY INDEX ROWID T2 (cr=5 pr=3 pw=0 time=13843 us) 2 INDEX RANGE SCAN SYS_C0020548 (cr=3 pr=2 pw=0 time=9231 us)(object id 114211) 2 INDEX UNIQUE SCAN SYS_C0020547 (cr=4 pr=2 pw=0 time=5788 us)(object id 114210) Elapsed times include waiting on following events: Event waited on Times Max. Wait Total Waited ---------------------------------------- Waited ---------- ------------ SQL*Net message to client 204 0.00 0.00 db file sequential read 409 0.00 0.21 SQL*Net message from client 204 0.00 0.07 SQL*Net more data to client 1200 0.00 0.02
The above is a nice summary of what was found in the trace file for our specific test SQL statement, but what is it telling us? There were 2 parse calls (1 for each execution), and one of those parse calls resulted in a hard parse. There were 3 execution calls (I am only able to explain 2 of the execution calls). There were 203 fetch calls that retrieved a total of 10,002 rows – from this we could derive that on average the client fetched 49.27 rows per fetch call. All of the time for the execution happened on the fetch calls, which required 0.28 seconds of CPU time and a total of 0.38 clock seconds to execute. A total of 10,991 consistent gets were required and 409 blocks were read from disk.
The execution plan displayed is a little misleading, since it shows that only 2 rows were retrieved (note that if this example were executed on Oracle 11.1.0.6 or higher, the first and second executions of the SQL statement could have had different execution plans). An index range scan is performed on the index SYS_C0020548 (the primary key index for table T2) to locate all of the C1 values between 1 and 2 – note that the optimizer used transitive closure here since the restriction in the SQL statement was actually placed on the column C1 of table T1. The top line in the plan indicates that in total the query required 9 consistent gets, 5 physical block reads, and 0.019577 seconds to execute. The index range scan on SYS_C0020548 required 3 consistent gets, and 2 physical block reads were required to satisfy the 3 consistent gets. Table T2 required an additional 2 consistent gets and 1 physical block read. A nested loop operation was performed, driving into the primary key index for table T1 – this required an additional 4 consistent gets and 2 physical block reads. But, what about the second execution of the SQL statement?
The wait events show 409 waits on the “db file sequential read” wait event, which indicates physically reading 1 block at a time from disk – note that this exactly matches the “disk” column in the “fetch” line of the tkprof summary. Every block that had to be read from disk was read one block at a time, with an average read time of 0.000513 seconds per block read (the extremely fast average time likely indicate caching of blocks at the file system, RAID controller, SAN, or hard drive). There were 1200 waits on the “SQL*Net more data to client” wait, indicating that the SDU size was filled 1200 times when sending the data to the client computer.
We could also run the trace file though my Toy Project (below is one of 4 outputs from my program):
Total for Trace File: |PARSEs 6|CPU S 0.000000|CLOCK S 0.008073|ROWs 0|PHY RD BLKs 0|CON RD BLKs (Mem) 0|CUR RD BLKs (Mem) 0|SHARED POOL MISs 4| |EXECs 6|CPU S 0.015625|CLOCK S 0.007978|ROWs 3|PHY RD BLKs 0|CON RD BLKs (Mem) 0|CUR RD BLKs (Mem) 0|SHARED POOL MISs 2| |FETCHs 205|CPU S 0.281250|CLOCK S 0.382338|ROWs 10003|PHY RD BLKs 409|CON RD BLKs (Mem) 10991|CUR RD BLKs (Mem) 0|SHARED POOL MISs 0| Wait Event Summary: SQL*Net message to client 0.000318 On Client/Network Min Wait: 0.000001 Avg Wait: 0.000001 Max Wait: 0.000005 SQL*Net message from client 3.916585 On Client/Network Min Wait: 0.000211 Avg Wait: 0.018302 Max Wait: 3.829540 db file sequential read 0.211736 On DB Server Min Wait: 0.000182 Avg Wait: 0.000518 Max Wait: 0.005905 SQL*Net more data to client 0.020220 On Client/Network Min Wait: 0.000010 Avg Wait: 0.000017 Max Wait: 0.000258 Total for Similar SQL Statements in Each Group: ---------------------------------------------------------------------------------- Similar SQL Statements in Group: 2 |PARSEs 2|CPU S 0.000000|CLOCK S 0.001231|ROWs 0|PHY RD BLKs 0|CON RD BLKs (Mem) 0|CUR RD BLKs (Mem) 0|SHARED POOL MISs 1| |EXECs 2|CPU S 0.000000|CLOCK S 0.004237|ROWs 0|PHY RD BLKs 0|CON RD BLKs (Mem) 0|CUR RD BLKs (Mem) 0|SHARED POOL MISs 1| |FETCHs 203|CPU S 0.281250|CLOCK S 0.382314|ROWs 10002|PHY RD BLKs 409|CON RD BLKs (Mem) 10991|CUR RD BLKs (Mem) 0|SHARED POOL MISs 0| CPU S 94.74% CLOCK S 97.34% * 0.211736 seconds of time related data file I/O * 0.096212 seconds of time related to client/network events | +++++++++++++++++++|| +++++++++++++++++++| Cursor 3 Ver 1 Parse at 0.000000 Similar Cnt 1 |PARSEs 1|CPU S 0.000000|CLOCK S 0.001113|ROWs 0|PHY RD BLKs 0|CON RD BLKs (Mem) 0|CUR RD BLKs (Mem) 0|SHARED POOL MISs 1| |EXECs 1|CPU S 0.000000|CLOCK S 0.003538|ROWs 0|PHY RD BLKs 0|CON RD BLKs (Mem) 0|CUR RD BLKs (Mem) 0|SHARED POOL MISs 1| |FETCHs 2|CPU S 0.015625|CLOCK S 0.019769|ROWs 2|PHY RD BLKs 5|CON RD BLKs (Mem) 9|CUR RD BLKs (Mem) 0|SHARED POOL MISs 0| CPU S 5.26% CLOCK S 6.13% | +|| +| SELECT T1.C1, T2.C2 FROM T1, T2 WHERE T1.C1=T2.C1 AND T1.C1 BETWEEN :N1 AND :N2 (Rows 2) FILTER (cr=9 pr=5 pw=0 time=19577 us) (Rows 2) NESTED LOOPS (cr=9 pr=5 pw=0 time=19569 us) (Rows 2) TABLE ACCESS BY INDEX ROWID T2 (cr=5 pr=3 pw=0 time=13843 us) (Rows 2) INDEX RANGE SCAN SYS_C0020548 (cr=3 pr=2 pw=0 time=9231 us) (Rows 2) INDEX UNIQUE SCAN SYS_C0020547 (cr=4 pr=2 pw=0 time=5788 us) Bind Variables:BINDS #3: -0.000008 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=13ce8870 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=13ce8888 bln=22 avl=02 flg=01 value=2 ------------ Cursor 4 Ver 1 Parse at 0.041427 (TD Prev 0.007600) Similar Cnt 2 |PARSEs 1|CPU S 0.000000|CLOCK S 0.000118|ROWs 0|PHY RD BLKs 0|CON RD BLKs (Mem) 0|CUR RD BLKs (Mem) 0|SHARED POOL MISs 0| |EXECs 1|CPU S 0.000000|CLOCK S 0.000699|ROWs 0|PHY RD BLKs 0|CON RD BLKs (Mem) 0|CUR RD BLKs (Mem) 0|SHARED POOL MISs 0| |FETCHs 201|CPU S 0.265625|CLOCK S 0.362545|ROWs 10000|PHY RD BLKs 404|CON RD BLKs (Mem) 10982|CUR RD BLKs (Mem) 0|SHARED POOL MISs 0| CPU S 89.47% CLOCK S 91.21% | ++++++++++++++++++|| ++++++++++++++++++| SELECT T1.C1, T2.C2 FROM T1, T2 WHERE T1.C1=T2.C1 AND T1.C1 BETWEEN :N1 AND :N2 (Rows 10000) FILTER (cr=10982 pr=404 pw=0 time=680024 us) (Rows 10000) NESTED LOOPS (cr=10982 pr=404 pw=0 time=670018 us) (Rows 10000) TABLE ACCESS BY INDEX ROWID T2 (cr=781 pr=387 pw=0 time=590006 us) (Rows 10000) INDEX RANGE SCAN SYS_C0020548 (cr=218 pr=17 pw=0 time=10038 us) (Rows 10000) INDEX UNIQUE SCAN SYS_C0020547 (cr=10201 pr=17 pw=0 time=77882 us) Bind Variables:BINDS #4: 0.041421 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=13ce8870 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=13ce8888 bln=22 avl=02 flg=01 value=10000 ----------------------------------------------------------------------------------
The above shows basically the same output as tkprof, just with greater resolution, both sets of bind variables, and both sets of execution plans.
We could also use any number of other 10046 trace file parsers including TRCANLZR (see Metalink Doc ID 224270.1), TVD$XTAT (see the book “Troubleshooting Oracle Performance”), ESQLTRCPROF (see the book “Secrets of the Oracle Database”), the Hotsos Profiler (Method R), OraSRP (www.oracledba.ru/orasrp/), or one of several other programs.
I typically either look at the output from my program or the raw 10046 trace file. That brings us to the raw 10046 trace file. So, what does the raw output of the trace file look like? Before diving into the raw trace file, let’s find a little information to help us later:
COLUMN TABLE_NAME FORMAT A10
SELECT
TABLE_NAME,
INDEX_NAME
FROM
DBA_INDEXES
WHERE
TABLE_NAME IN ('T1','T2')
ORDER BY
TABLE_NAME;
TABLE_NAME INDEX_NAME
---------- ------------
T1 SYS_C0020547
T2 SYS_C0020548
COLUMN OBJECT_NAME FORMAT A15
SELECT
OBJECT_ID,
OBJECT_NAME,
OBJECT_TYPE
FROM
DBA_OBJECTS
WHERE
OBJECT_NAME IN ('T1','T2','SYS_C0020547','SYS_C0020548')
ORDER BY
OBJECT_NAME;
OBJECT_ID OBJECT_NAME OBJECT_TYPE
---------- --------------- -----------
114210 SYS_C0020547 INDEX
114211 SYS_C0020548 INDEX
114209 T1 TABLE
114207 T2 TABLE
From the above output, the index on table T1 is named SYS_C0020547 and it has an OBJECT_ID of 114210. The index on table T2 is named SYS_C0020548 and it has an OBJECT_ID of 114211. Table T1 has an OBJECT_ID of 114209, and table T2 has an OBJECT_ID of 114207. Now on to a portion of the raw 10046 trace file:
===================== PARSING IN CURSOR #3 len=91 dep=0 uid=31 oct=3 lid=31 tim=4963261335 hv=3021110247 ad='982ab100' SELECT T1.C1, T2.C2 FROM T1, T2 WHERE T1.C1=T2.C1 AND T1.C1 BETWEEN :N1 AND :N2 END OF STMT PARSE #3:c=0,e=1113,p=0,cr=0,cu=0,mis=1,r=0,dep=0,og=1,tim=4963261327 BINDS #3: kkscoacd 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=13ce8870 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=13ce8888 bln=22 avl=02 flg=01 value=2
From the above, we see that the first parse was a hard parse that required 0 CPU seconds and 0.001113 clock seconds. Additionally, two bind variables were passed in. A level 4 or level 12 10046 extended SQL trace file will include the submitted bind variable values, as shown above. It is possible to use the following list to decode the bind variable data type (oacdty), in the process determining that the bind variables are in fact, defined as numbers. See Metalink Doc IDs 67701.1 and 154170.1, the Oracle OCI documentation, or Julian Dyke’s site for a more complete list of datatype constants:
0 - This row is a placeholder for a procedure with no arguments. 1 - VARCHAR2 (or NVARCHAR) 2 - NUMBER 3 - NATIVE INTEGER (for PL/SQL's BINARY_INTEGER) 8 - LONG 11 - ROWID 12 - DATE 23 - RAW 24 - LONG RAW 96 - CHAR (or NCHAR) 112 - CLOB or NCLOB 113 - BLOB 114 - BFILE 106 - MLSLABEL 250 - PL/SQL RECORD 251 - PL/SQL TABLE 252 - PL/SQL BOOLEAN
The trace file continues below:
EXEC #3:c=0,e=3538,p=0,cr=0,cu=0,mis=1,r=0,dep=0,og=1,tim=4963265927 WAIT #3: nam='SQL*Net message to client' ela= 5 driver id=1413697536 #bytes=1 p3=0 obj#=-1 tim=4963266031 WAIT #3: nam='db file sequential read' ela= 4816 file#=4 block#=1138316 blocks=1 obj#=114211 tim=4963271120 WAIT #3: nam='db file sequential read' ela= 3934 file#=4 block#=1138318 blocks=1 obj#=114211 tim=4963275219 WAIT #3: nam='db file sequential read' ela= 4443 file#=4 block#=1138310 blocks=1 obj#=114207 tim=4963279805 WAIT #3: nam='db file sequential read' ela= 5221 file#=4 block#=1093148 blocks=1 obj#=114210 tim=4963285172 WAIT #3: nam='db file sequential read' ela= 236 file#=4 block#=1093150 blocks=1 obj#=114210 tim=4963285569 FETCH #3:c=15625,e=19589,p=5,cr=5,cu=0,mis=0,r=1,dep=0,og=1,tim=4963285717 WAIT #3: nam='SQL*Net message from client' ela= 364 driver id=1413697536 #bytes=1 p3=0 obj#=114210 tim=4963286240 WAIT #3: nam='SQL*Net message to client' ela= 4 driver id=1413697536 #bytes=1 p3=0 obj#=114210 tim=4963286494 FETCH #3:c=0,e=180,p=0,cr=4,cu=0,mis=0,r=1,dep=0,og=1,tim=4963286588
Above, we see the 5 physical block reads of blocks 1138316 and 1138318 of OBJECT_ID 114211 (index on table T2, SYS_C0020548), followed by a single block read of OBJECT_ID 114207 (table T2), and 2 single block reads of object 114210 (index on table T1, SYS_C0020547) – note that the final of the 5 physical block reads completed in 0.000236 seconds, which is about 20 times faster than the time it takes for 1 revolution of a 15,000 RPM hard drive platter. The first fetch call returned a single row, even though the array fetch size was explicitly set to 15 rows. That fetch required 5 consistent gets, which then required the 5 physical block reads. The 1 row was sent to the client which then fetched a second row (4963286588 – 4963286240 4963285717)/1,000,000 = 0.000348 0.000871 seconds later. The trace file continues:
WAIT #3: nam='SQL*Net message from client' ela= 319 driver id=1413697536 #bytes=1 p3=0 obj#=114210 tim=4963287035 *** SESSION ID:(211.17427) 2010-01-25 15:41:01.540 STAT #3 id=1 cnt=2 pid=0 pos=1 obj=0 op='FILTER (cr=9 pr=5 pw=0 time=19577 us)' STAT #3 id=2 cnt=2 pid=1 pos=1 obj=0 op='NESTED LOOPS (cr=9 pr=5 pw=0 time=19569 us)' STAT #3 id=3 cnt=2 pid=2 pos=1 obj=114207 op='TABLE ACCESS BY INDEX ROWID T2 (cr=5 pr=3 pw=0 time=13843 us)' STAT #3 id=4 cnt=2 pid=3 pos=1 obj=114211 op='INDEX RANGE SCAN SYS_C0020548 (cr=3 pr=2 pw=0 time=9231 us)' STAT #3 id=5 cnt=2 pid=2 pos=2 obj=114210 op='INDEX UNIQUE SCAN SYS_C0020547 (cr=4 pr=2 pw=0 time=5788 us)' WAIT #0: nam='SQL*Net message to client' ela= 2 driver id=1413697536 #bytes=1 p3=0 obj#=114210 tim=4963289021 WAIT #0: nam='SQL*Net message from client' ela= 2329 driver id=1413697536 #bytes=1 p3=0 obj#=114210 tim=4963291420 =====================
Cursor #3 was closed, so Oracle output the STAT (row source operation) lines, as we saw in the tkprof output. The trace file continues (with a couple of lines removed):
... ===================== PARSING IN CURSOR #4 len=91 dep=0 uid=31 oct=3 lid=31 tim=4963302762 hv=3021110247 ad='982ab100' SELECT T1.C1, T2.C2 FROM T1, T2 WHERE T1.C1=T2.C1 AND T1.C1 BETWEEN :N1 AND :N2 END OF STMT PARSE #4:c=0,e=118,p=0,cr=0,cu=0,mis=0,r=0,dep=0,og=1,tim=4963302756 BINDS #4: kkscoacd 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=13ce8870 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=13ce8888 bln=22 avl=02 flg=01 value=10000 EXEC #4:c=0,e=699,p=0,cr=0,cu=0,mis=0,r=0,dep=0,og=1,tim=4963304299 WAIT #4: nam='SQL*Net message to client' ela= 3 driver id=1413697536 #bytes=1 p3=0 obj#=114210 tim=4963304383 FETCH #4:c=0,e=94,p=0,cr=5,cu=0,mis=0,r=1,dep=0,og=1,tim=4963304564 WAIT #4: nam='SQL*Net message from client' ela= 718 driver id=1413697536 #bytes=1 p3=0 obj#=114210 tim=4963305403 WAIT #4: nam='SQL*Net message to client' ela= 2 driver id=1413697536 #bytes=1 p3=0 obj#=114210 tim=4963305590 WAIT #4: nam='SQL*Net more data to client' ela= 29 driver id=1413697536 #bytes=2146 p3=0 obj#=114210 tim=4963305766 WAIT #4: nam='SQL*Net more data to client' ela= 20 driver id=1413697536 #bytes=1862 p3=0 obj#=114210 tim=4963305913 WAIT #4: nam='SQL*Net more data to client' ela= 17 driver id=1413697536 #bytes=2128 p3=0 obj#=114210 tim=4963306065 WAIT #4: nam='db file sequential read' ela= 2272 file#=4 block#=1138311 blocks=1 obj#=114207 tim=4963308471 WAIT #4: nam='SQL*Net more data to client' ela= 27 driver id=1413697536 #bytes=1868 p3=0 obj#=114207 tim=4963308686 WAIT #4: nam='SQL*Net more data to client' ela= 18 driver id=1413697536 #bytes=2122 p3=0 obj#=114207 tim=4963308841 WAIT #4: nam='SQL*Net more data to client' ela= 13 driver id=1413697536 #bytes=2128 p3=0 obj#=114207 tim=4963309001 FETCH #4:c=0,e=3573,p=1,cr=54,cu=0,mis=0,r=50,dep=0,og=1,tim=4963309109
Note that there was no hard parse this time. The first two fetches are complete at this point. Again, the first fetch returned a single row, while the second fetch returned 50 rows. Note the presence of the “SQL*Net more data to client” wait before the second fetch line printed – each of these lines indicates that the SDU size was filled on the previous send to the client. Notice that there was only a single physical block read of OBJECT_ID 114207 (table T2), requiring 0.002272 seconds, when fetching the first 51 rows (the other blocks were already in the buffer cache). The trace file continues below:
WAIT #4: nam='SQL*Net message from client' ela= 256 driver id=1413697536 #bytes=1 p3=0 obj#=114207 tim=4963309476 WAIT #4: nam='SQL*Net message to client' ela= 1 driver id=1413697536 #bytes=1 p3=0 obj#=114207 tim=4963309654 WAIT #4: nam='db file sequential read' ela= 226 file#=4 block#=1138312 blocks=1 obj#=114207 tim=4963309995 WAIT #4: nam='SQL*Net more data to client' ela= 32 driver id=1413697536 #bytes=2116 p3=0 obj#=114207 tim=4963310197 WAIT #4: nam='SQL*Net more data to client' ela= 14 driver id=1413697536 #bytes=2096 p3=0 obj#=114207 tim=4963310353 WAIT #4: nam='SQL*Net more data to client' ela= 13 driver id=1413697536 #bytes=1834 p3=0 obj#=114207 tim=4963310488 WAIT #4: nam='db file sequential read' ela= 1762 file#=4 block#=1138308 blocks=1 obj#=114207 tim=4963312390 WAIT #4: nam='SQL*Net more data to client' ela= 23 driver id=1413697536 #bytes=2096 p3=0 obj#=114207 tim=4963312551 WAIT #4: nam='SQL*Net more data to client' ela= 16 driver id=1413697536 #bytes=2096 p3=0 obj#=114207 tim=4963312783 WAIT #4: nam='SQL*Net more data to client' ela= 13 driver id=1413697536 #bytes=1834 p3=0 obj#=114207 tim=4963312904 FETCH #4:c=0,e=3345,p=2,cr=55,cu=0,mis=0,r=50,dep=0,og=1,tim=4963312955
Two more physical block reads of OBJECT_ID 114207 (table T2) to return the next 50 rows to the client. Jumping forward in the trace file to the last two fetches:
... FETCH #4:c=0,e=1259,p=2,cr=55,cu=0,mis=0,r=50,dep=0,og=1,tim=4963757700 WAIT #4: nam='SQL*Net message from client' ela= 842 driver id=1413697536 #bytes=1 p3=0 obj#=114207 tim=4963758586 WAIT #4: nam='SQL*Net message to client' ela= 1 driver id=1413697536 #bytes=1 p3=0 obj#=114207 tim=4963758653 WAIT #4: nam='SQL*Net more data to client' ela= 16 driver id=1413697536 #bytes=2124 p3=0 obj#=114207 tim=4963758766 WAIT #4: nam='db file sequential read' ela= 242 file#=4 block#=1773782 blocks=1 obj#=114207 tim=4963759071 WAIT #4: nam='SQL*Net more data to client' ela= 17 driver id=1413697536 #bytes=2104 p3=0 obj#=114207 tim=4963759182 WAIT #4: nam='SQL*Net more data to client' ela= 13 driver id=1413697536 #bytes=1841 p3=0 obj#=114207 tim=4963759268 WAIT #4: nam='SQL*Net more data to client' ela= 17 driver id=1413697536 #bytes=2104 p3=0 obj#=114207 tim=4963759365 WAIT #4: nam='SQL*Net more data to client' ela= 13 driver id=1413697536 #bytes=1841 p3=0 obj#=114207 tim=4963759453 WAIT #4: nam='db file sequential read' ela= 226 file#=4 block#=1773852 blocks=1 obj#=114207 tim=4963759715 WAIT #4: nam='SQL*Net more data to client' ela= 20 driver id=1413697536 #bytes=2104 p3=0 obj#=114207 tim=4963759867 FETCH #4:c=0,e=1290,p=2,cr=54,cu=0,mis=0,r=49,dep=0,og=1,tim=4963759912
From the above, we see that Oracle is still performing an average of two single block physical reads per fetch call, and the final fetch call retrieved just 49 rows. The trace file continues:
WAIT #4: nam='SQL*Net message from client' ela= 792 driver id=1413697536 #bytes=1 p3=0 obj#=114207 tim=4963760775 *** SESSION ID:(211.17427) 2010-01-25 15:41:02.008 STAT #4 id=1 cnt=10000 pid=0 pos=1 obj=0 op='FILTER (cr=10982 pr=404 pw=0 time=680024 us)' STAT #4 id=2 cnt=10000 pid=1 pos=1 obj=0 op='NESTED LOOPS (cr=10982 pr=404 pw=0 time=670018 us)' STAT #4 id=3 cnt=10000 pid=2 pos=1 obj=114207 op='TABLE ACCESS BY INDEX ROWID T2 (cr=781 pr=387 pw=0 time=590006 us)' STAT #4 id=4 cnt=10000 pid=3 pos=1 obj=114211 op='INDEX RANGE SCAN SYS_C0020548 (cr=218 pr=17 pw=0 time=10038 us)' STAT #4 id=5 cnt=10000 pid=2 pos=2 obj=114210 op='INDEX UNIQUE SCAN SYS_C0020547 (cr=10201 pr=17 pw=0 time=77882 us)' WAIT #0: nam='SQL*Net message to client' ela= 2 driver id=1413697536 #bytes=1 p3=0 obj#=114207 tim=4963764774 WAIT #0: nam='SQL*Net message from client' ela= 2789 driver id=1413697536 #bytes=1 p3=0 obj#=114207 tim=4963767585
From the above, we see the execution plan for the second execution – this information was missing from the tkprof output. A hash join with two full table scans probably would have been more efficient than a nested loop join with index lookups, especially if the number of rows were larger. This is one of the potential problems with using bind variables, especially when bind variable peeking is enabled (by default in recent releases) – the execution plan is essentially locked after the initial hard parse. Oracle 11.1.0.6 introduced a feature known as adaptive cursor sharing that could potentially alter the plan on a future execution if Oracle senses that there will be significant changes in the number of rows returned when different bind variable values are submitted.
Incidentally, you may have noticed the keyword “oct” on the “PARSING IN CURSOR” lines in the above trace file. This keyword identifies the Oracle command type, which is related to the V$SESSION.COMMAND column and the V$SQL.COMMAND_TYPE column. Common command type values include:
1 - CREATE TABLE 2 - INSERT 3 - SELECT 6 - UPDATE 7 - DELETE 9 - CREATE INDEX
See the “Command Column of V$SESSION and Corresponding Commands” table in the Oracle Reference documentation (Table 8-2 in the Oracle Database Reference 11g Release 2 book) for a complete list of command types.
For more information about 10046 trace files, see Chapter 8, “Understanding Performance Optimization Methods”, in the book “Expert Oracle Practices: Oracle Database Administration from the Oak Table” (the chapter was co-written by Randolf Geist and myself). The book “Optimizing Oracle Performance” is also highly recommended.
Charles Hooper's Oracle Notes 
Recent Comments