Help: Explain plan and tracing problems

From: Gerard M. Averill <gaverill_at_chsra.wisc.edu>
Date: 1997/11/06
Message-ID: <63tehf$7s8$1@news.doit.wisc.edu>

During the course of trying to tune a slow-running INSERT statement I discovered some strange behavior I'm interested in getting some feedback on.

The INSERT looks like (it's one of several located within a stored procedure):

        insert
        into    QC$TB_DERIVED_VALUE
        (       DERIVED_OID


        ,       SOURCE_ID

        ,       VALUE_DATE

        ,       VALUE

        )
        select  ...
        from    QC$TB_TEMP_DERIVED_VALUE S0


        ,       QC$TB_TEMP_DERIVED_VALUE S1

        ,       QC$TB_TEMP_DERIVED_VALUE S2

        ,       QC$TB_TEMP_DERIVED_VALUE S3

        ,       QC$TB_TEMP_DERIVED_VALUE S4

        ,       QC$TB_TEMP_DERIVED_VALUE S5

        ,       QC$TB_TEMP_DERIVED_VALUE S6

        where   S0.SID = Session_ID
        and     S0.SET_ID = 0
        and     S1.SID = Session_ID
        and     S1.SET_ID = 1
        and     S1.SOURCE_ID = S0.VALUE
        and     S2.SID = Session_ID
        and     S2.SET_ID = 2
        and     S2.SOURCE_ID = S0.VALUE
        and     S3.SID = Session_ID
        and     S3.SET_ID = 3
        and     S3.SOURCE_ID = S0.VALUE
        and     S4.SID = Session_ID
        and     S4.SET_ID = 4
        and     S4.SOURCE_ID = S0.VALUE
        and     S5.SID = Session_ID
        and     S5.SET_ID = 5
        and     S5.SOURCE_ID = S0.VALUE
        and     S6.SID = Session_ID
        and     S6.SET_ID = 6
        and     S6.SOURCE_ID = S0.VALUE;

There exists an index QC$IN_TEMP_DERIVED_VALUE on QC$TB_TEMP_DERIVED_VALUE which consists of the fields:

        SID
        SET_ID
        SOURCE_ID
        ...

Doing an EXPLAIN PLAN on the statement results in the following:

Execution Plan

---

INSERT STATEMENT GOAL: CHOOSE
 NESTED LOOPS
  NESTED LOOPS
   NESTED LOOPS
    NESTED LOOPS

     NESTED LOOPS
      NESTED LOOPS
       TABLE ACCESS (BY ROWID) OF 'QC$TB_TEMP_DERIVED_VALUE'
        INDEX (RANGE SCAN) OF 'QC$IN_TEMP_DERIVED_VALUE' (NON-UNIQUE)
       TABLE ACCESS (BY ROWID) OF 'QC$TB_TEMP_DERIVED_VALUE'
        INDEX (RANGE SCAN) OF 'QC$IN_TEMP_DERIVED_VALUE' (NON-UNIQUE)
      TABLE ACCESS (BY ROWID) OF 'QC$TB_TEMP_DERIVED_VALUE'
       INDEX (RANGE SCAN) OF 'QC$IN_TEMP_DERIVED_VALUE' (NON-UNIQUE)
     TABLE ACCESS (BY ROWID) OF 'QC$TB_TEMP_DERIVED_VALUE'
      INDEX (RANGE SCAN) OF 'QC$IN_TEMP_DERIVED_VALUE' (NON-UNIQUE)
    TABLE ACCESS (BY ROWID) OF 'QC$TB_TEMP_DERIVED_VALUE'
     INDEX (RANGE SCAN) OF 'QC$IN_TEMP_DERIVED_VALUE' (NON-UNIQUE)

   TABLE ACCESS (BY ROWID) OF 'QC$TB_TEMP_DERIVED_VALUE'     INDEX (RANGE SCAN) OF 'QC$IN_TEMP_DERIVED_VALUE' (NON-UNIQUE)   TABLE ACCESS (BY ROWID) OF 'QC$TB_TEMP_DERIVED_VALUE'    INDEX (RANGE SCAN) OF 'QC$IN_TEMP_DERIVED_VALUE' (NON-UNIQUE) I then executed the statement (or rather the stored procedure) such that there were 12 records within each of the 6 SID, SET_ID groups (1 SID * 6 SET_IDs). Since each record in "set 0" matches only one record in each of the other 5 "sets", this should execute quickly. However, using the trace utility reveals these statistics:

call count elapsed disk query current rows ------- ------ ---------- ---------- ---------- ---------- ----------

Parse        1        0.03          0          0          0           0
Execute      1     1510.01          0   45604118         46          12
Fetch        0        0.00          0          0          0           0
------- ------  ---------- ---------- ---------- ----------  ----------
total        2     1510.04          0   45604118         46          12

That's right! 1510 secs and 45+ million buffer reads!

Using the EXPLAIN= option with TKPROF reveals the same parse plan as above (though this doesn't imply that the same plan was actually used -- is there any way to find out the actual plan used from any system tables or views?)

When I explicitly added the following hint:

        /*+
        index(S0 QC$IN_TEMP_DERIVED_VALUE)
        index(S1 QC$IN_TEMP_DERIVED_VALUE)
        index(S2 QC$IN_TEMP_DERIVED_VALUE)
        index(S3 QC$IN_TEMP_DERIVED_VALUE)
        index(S4 QC$IN_TEMP_DERIVED_VALUE)
        index(S5 QC$IN_TEMP_DERIVED_VALUE)
        index(S6 QC$IN_TEMP_DERIVED_VALUE)
        */

and re-executed the procedure under the same circumstances, I got the following statistics:

call count elapsed disk query current rows ------- ------ ---------- ---------- ---------- ---------- ----------

Parse        1        0.04          0          0          0           0
Execute      1        2.49          0        231         48          12
Fetch        0        0.00          0          0          0           0
------- ------  ---------- ---------- ---------- ----------  ----------
total        2        2.53          0        231         48          12

Certainly more along the lines of what I expected. The explained plan for this statement (as shown by TKPROF) is also the same as above.

So the question is: what plan is _really_ being used in the first case, and if it is not the same as that described by EXPLAIN PLAN, how useful is EXPLAIN PLAN and what can be used (if anything) in its place? Does the fact that a given DML statement is inside a stored procedure change how the optimizer parses it?

Any ideas would appreciated.

Gerard

---

Gerard M. Averill, Associate Researcher
CHSRA, University of Wisconsin - Madison GAverill_at_chsra.wisc.edu Received on Thu Nov 06 1997 - 00:00:00 CST