trace file appears to be lying? (9.2.0.5)
Date: Tue, 24 Mar 2009 09:41:58 -0400
Message-ID: <OFE57AC925.D4FB5DD7-ON85257583.004B0F92-85257583.004B4119_at_lnotes-gw.ent.nwie.net>
I have a query that explain plan (with dbms_xplan) says particular things (very different from the stats lines in the trace file, which is not surprising). I traced the execution and it seems that the stat lines show that entire subqueries never happen, and the LIO counts in the stat lines do not add up to the LIOs in the FETCH lines. I re-wrote the query to do a join in a subquery instead of having two subqueries, but the stat lines for the rewritten version (not depicted here) have the same behavior. I traced with level 12, and statistics_level=all. The trace was done by connecting, running the script that activated trace and ran the SQL code, then exited.
The object numbers in the stat lines are
3874 => v_if_status table
3876 => primary key index for v_if_status table (columns if_area,
as_of_date)
Pardon the cryptic names, I sanitized.
The stat lines indicate that lines 6 - 18 of the SQL statement never happened, but I have no idea how the "if_area = " piece on line 5 got a value without those lines (there are 14 distinct if_area values).
This is on
9.2.0.5
solaris 5.8
optimizer_mode=rule (NOT my fault!)
optimizer_features_enable=9.2.0
SQL code:
SQL> explain plan for
2 SELECT RELEASE_STATUS
3 FROM V_IF_STATUS
4 WHERE AS_OF_DATE = :B1
5 AND IF_AREA =
6 ( 7 SELECT X.SUB_TYPE 8 FROM V_IF_XREFS X 9 WHERE X.UV_DEF_SEQ_ID IN 10 ( 11 SELECT U.SEQ_ID 12 FROM V_UT_VE_DT U 13 WHERE U.F_SEQ_ID = :B2 14 AND U.SEQ_ID = X.UV_DEF_SEQ_ID 15 AND ROWNUM < 2 16 ) 17 AND ROWNUM < 2 18 );
Explained.
SQL> select * from table(dbms_xplan.display);
PLAN_TABLE_OUTPUT
| Id | Operation | Name |Rows | Bytes | Cost |
| 0 | SELECT STATEMENT | |
| | |
| 1 | TABLE ACCESS BY INDEX ROWID | V_IF_STATUS |
| | |
|* 2 | INDEX UNIQUE SCAN | INTFSTAT_PK_PRIM |
| | |
|* 3 | COUNT STOPKEY | |
| | |
|* 4 | FILTER | |
| | |
| 5 | TABLE ACCESS FULL | V_IF_XREFS |
| | |
|* 6 | FILTER | |
| | |
PLAN_TABLE_OUTPUT
|* 7 | COUNT STOPKEY | |
| | |
|* 8 | TABLE ACCESS BY INDEX ROWID| V_UT_VE_DT |
| | |
|* 9 | INDEX UNIQUE SCAN | UV_DEF_PK_PRIM |
| | |
--------------------------------------------------------------------------------------------------
Predicate Information (identified by operation id):
2 - access("V_IF_STATUS"."IF_AREA"= (SELECT "SYS_ALIAS_1"."SUB_TYPE"
FROM
"VPROD"."V_IF_XREFS" "SYS_ALIAS_1" WHERE EXISTS (SELECT 0
FROM
"VPROD"."V_UT_VE_DT" "U" WHERE ROWNUM<2 AND "U"."SEQ_ID"=:B1
AND
PLAN_TABLE_OUTPUT
"U"."F_SEQ_ID"=TO_NUMBER(:Z)) AND ROWNUM<2) AND
"V_IF_STATUS"."AS_OF_DATE"=:Z)
3 - filter(ROWNUM<2)
4 - filter( EXISTS (SELECT 0 FROM "VPROD"."V_UT_VE_DT" "U" WHERE
ROWNUM<2
AND "U"."SEQ_ID"=:B1 AND "U"."F_SEQ_ID"=TO_NUMBER(:Z)))
6 - filter("U"."SEQ_ID"=:B1)
7 - filter(ROWNUM<2)
8 - filter("U"."F_SEQ_ID"=TO_NUMBER(:Z))
9 - access("U"."SEQ_ID"=:B1)
Note: rule based optimization
32 rows selected.
Lines from the trace file:
JServer Release 9.2.0.5.0 - Production
ORACLE_HOME = /u02/home/oracle/fiord/9.2.0.5
System name: SunOS
Node name: fiord Release: 5.8 Version: Generic_117350-27 Machine: sun4u
Instance name: v
Redo thread mounted by this instance: 1
Oracle process number: 37
Unix process pid: 11190, image: oracle_at_fiord (TNS V1-V3)
- 2009-03-19 15:36:33.379
- SESSION ID:(52.48449) 2009-03-19 15:36:33.379
APPNAME mod='sqlplus_at_fiord (TNS V1-V3)' mh=0 act='' ah=0
PARSING IN CURSOR #1 len=69 dep=0 uid=0 oct=42 lid=0 tim=28604771822619 hv=2004533713 ad='98b1c410' alter session set events '10046 trace name context forever, level 12' END OF STMT EXEC #1:c=0,e=142,p=0,cr=0,cu=0,mis=0,r=0,dep=0,og=3,tim=28604771822209 WAIT #1: nam='SQL*Net message to client' ela= 2 p1=1650815232 p2=1 p3=0 WAIT #1: nam='SQL*Net message from client' ela= 1035 p1=1650815232 p2=1 p3=0
PARSING IN CURSOR #1 len=367 dep=0 uid=0 oct=3 lid=0 tim=28604771828589 hv=2410864348 ad='9699dfe0' SELECT RELEASE_STATUS FROM V_IF_STATUS WHERE AS_OF_DATE = :B1 AND IF_AREA = ( SELECT X.SUB_TYPE FROM V_IF_XREFS X WHERE X.UV_DEF_SEQ_ID IN ( SELECT U.SEQ_ID FROM V_UT_VE_DT U WHERE U.F_SEQ_ID = :B2 AND U.SEQ_ID = X.UV_DEF_SEQ_ID AND ROWNUM < 2 ) AND ROWNUM < 2 ) END OF STMT PARSE #1:c=10000,e=4309,p=0,cr=0,cu=0,mis=1,r=0,dep=0,og=0,tim=28604771828581 BINDS #1: bind 0: dty=1 mxl=32(11) mal=00 scl=00 pre=00 oacflg=03 oacfl2=0 size=56 offset=0 bfp=1037e9130 bln=32 avl=11 flg=05 Value="18-MAR-2009" bind 1: dty=2 mxl=22(22) mal=00 scl=00 pre=00 oacflg=03 oacfl2=0 size=0 offset=32 bfp=1037e9150 bln=22 avl=02 flg=01 Value=6600 WAIT #1: nam='db file scattered read' ela= 404 p1=12 p2=217345 p3=16 WAIT #1: nam='db file scattered read' ela= 185 p1=12 p2=217361 p3=8 EXEC #1:c=90000,e=88188,p=24,cr=10389,cu=0,mis=0,r=0,dep=0,og=3,tim=28604771919454 WAIT #1: nam='SQL*Net message to client' ela= 4 p1=1650815232 p2=1 p3=0 WAIT #1: nam='db file sequential read' ela= 50 p1=26 p2=7476 p3=1 WAIT #1: nam='db file sequential read' ela= 31 p1=57 p2=95050 p3=1 FETCH #1:c=0,e=601,p=2,cr=3,cu=0,mis=0,r=1,dep=0,og=3,tim=28604771920333 WAIT #1: nam='SQL*Net message from client' ela= 414 p1=1650815232 p2=1 p3=0 FETCH #1:c=0,e=1,p=0,cr=0,cu=0,mis=0,r=0,dep=0,og=0,tim=28604771921013 WAIT #1: nam='SQL*Net message to client' ela= 1 p1=1650815232 p2=1 p3=0 WAIT #1: nam='SQL*Net message from client' ela= 1228 p1=1650815232 p2=1 p3=0 XCTEND rlbk=0, rd_only=1 STAT #1 id=1 cnt=1 pid=0 pos=1 obj=3874 op='TABLE ACCESS BY INDEX ROWID OBJ#(3874) (cr=3 r=2 w=0 time=582 us)' STAT #1 id=2 cnt=1 pid=1 pos=1 obj=3876 op='INDEX UNIQUE SCAN OBJ#(3876) (cr=2 r=1 w=0 time=365 us)' -- http://www.freelists.org/webpage/oracle-l