Re: trace file appears to be lying? (9.2.0.5)

SELECT * FROM TABLE(DBMS_XPLAN.DISPLAY_AWR('&sql_id')

It should show the explain plan it actually used.

exec

On Thu, Mar 26, 2009 at 10:07 AM, Dennis Williams < oracledba.williams_at_gmail.com> wrote:

> 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_at_nationwide.com> 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_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
>>
>>
>>
>

-- 
Andrew W. Kerber

'If at first you dont succeed, dont take up skydiving.'

--
http://www.freelists.org/webpage/oracle-l