Re: trace file appears to be lying? (9.2.0.5)
- From: Dennis Williams <oracledba.williams@xxxxxxxxx>
- To: DEEDSD@xxxxxxxxxxxxxx
- Date: Thu, 26 Mar 2009 10:07:56 -0500
Deeds,
I don't see where anyone responded to your posting. Generally I have found
that explain plan often lies. Usually if I get results that don't make
sense, I do exactly what you've done, run a trace and forget the explain
plan for that query.
Dennis Williams
On Tue, Mar 24, 2009 at 8:41 AM, <DEEDSD@xxxxxxxxxxxxxx> wrote:
> 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@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@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)'
> --
> //www.freelists.org/webpage/oracle-l
>
>
>
Other related posts:
