Plan timing

I’ve copied the following question up from a recent comment on an older blog note because it’s a useful generic type of question and I think I can answer it in the few minutes I have to spare.

Hi Jonathan. I have a query plan where I cannot explain how time adds up. I did the ALTER SESSION trick but it changed nothing. I ran this, and got the following plan. I have two questions (I apologize for not being able to format this code and plan but I saw no formatting buttons on the insert box).

1) @ step #8 in the plan, the query jumps to 3 and 1/2 minutes. This step says VIEW but gives no indication of what it did that actually took 3 and 1/2 minutes. Can you explain or give me some idea how to find out what is being done on this line that takes that long. Especially with so few rows.

2) the total elapsed time of the query was 3 minutes 45 seconds. This jives with step #1 that says 3:44.54. But if A-TIME is supposed to be among other things, the sum of child steps, then how to we explain step #2. Step #2 says 3 minutes 3 minutes 44 seconds. But the sum of its child steps (#3 and #8) is 7 minutes and 25 seconds. Did this query do these steps “in parallel” so to speak? Or is there something really off in the numbers and if so how do I prove it?

This is not something that is super pressing but I sure would like to be able to explain the differences to people. It is making it somewhat harder to get people to believe I know what I am doing when I cannot explain such obvious issues as these two things.

Thanks, Kevin Meade

Fortunately Kevin included enough information to allow me to understand what was going on. In this case that means: “Here’s the statement and the execution plan pulled from memory – showing the rowsource execution statistics”. As follows:

ALTER SESSION SET STATISTICS_LEVEL=ALL
/

drop table kevtemp1
/

create table kevtemp1
nologging
as
SELECT SRCE_EFF_START_TMSP,
       AGGREGATECLAIMUID
FROM (
     SELECT  A.AGGREGATECLAIMUID,
             A.SNAPSHOT_DT,
             MAX(A.SRCE_EFF_START_TMSP) SRCE_EFF_START_TMSP
     FROM (SELECT PI.AGGREGATECLAIMUID,
                  PI.SRCE_EFF_START_TMSP,
                  (SELECT DISTINCT BW.SNAPSHOT_DT
                   FROM RRS_SHR.RRS_ETL_BATCH_WINDOW BW, RRS_SHR.RRS_LOAD_STATUS RLS
                   WHERE RLS.ASTG_LOAD_STATUS = 'STARTED'
                   AND RLS.SNAPSHOT_DT = BW.SNAPSHOT_DT
                   AND BW.RPTG_WINDOW_TYPE = 'D'
                   AND BW.OBJECT_NM = 'R_AGGREGATE_CLAIM_SEED'
                   AND PI.SRCE_EFF_START_TMSP
                       BETWEEN
                       BW.BEGIN_TMSP
                       AND
                       BW.END_TMSP
                  ) AS SNAPSHOT_DT
           FROM RRS_PSTG.P_PCD_AGGREGATECLAIM PI
           WHERE PI.BATCH_ID IN
                 (SELECT src_batch_id
                  FROM batch_processing_queue
                  WHERE dm_batch_id =
                        batch_id_pkg.get_current_batch_id('PCD','ATM')
                 )
          ) A
          GROUP BY A.AGGREGATECLAIMUID, A.SNAPSHOT_DT
     )
/

Table created.

Elapsed: 00:03:45.14

Plan hash value: 3515505567

----------------------------------------------------------------------------------------------------------------------------------------------------------------------
| Id  | Operation                       | Name                        | Starts | E-Rows | A-Rows |   A-Time   | Buffers | Reads  | Writes |  OMem |  1Mem | Used-Mem |
----------------------------------------------------------------------------------------------------------------------------------------------------------------------
|   0 | CREATE TABLE STATEMENT          |                             |      1 |        |      0 |00:03:44.54 |     246K|   8389 |    128 |       |       |          |
|   1 |  LOAD AS SELECT                 |                             |      1 |        |      0 |00:03:44.54 |     246K|   8389 |    128 |   530K|   530K|  530K (0)|
|   2 |   HASH GROUP BY                 |                             |      1 |  84487 |  48482 |00:03:44.41 |     245K|   8386 |      0 |  3128K|  1284K| 3538K (0)|
|   3 |    HASH UNIQUE                  |                             |  33524 |      1 |  33524 |00:03:40.98 |     236K|     12 |      0 |  1270K|  1270K|  523K (0)|
|   4 |     NESTED LOOPS                |                             |  33524 |      1 |  33524 |00:00:08.35 |     236K|     12 |      0 |       |       |          |
|*  5 |      TABLE ACCESS BY INDEX ROWID| RRS_ETL_BATCH_WINDOW        |  33524 |     11 |  33524 |00:00:07.84 |     203K|      9 |      0 |       |       |          |
|*  6 |       INDEX RANGE SCAN          | IDX1_RRS_ETL_BATCH_WINDOW   |  33524 |     41 |   5414K|00:00:04.09 |   86482 |      5 |      0 |       |       |          |
|*  7 |      INDEX UNIQUE SCAN          | IUK2_RRS_LOAD_STATUS        |  33524 |      1 |  33524 |00:00:00.31 |   33535 |      3 |      0 |       |       |          |
|   8 |    VIEW                         |                             |      1 |  84487 |  48484 |00:03:43.99 |     245K|   8386 |      0 |       |       |          |
|*  9 |     HASH JOIN                   |                             |      1 |  84487 |  48484 |00:00:02.63 |    9186 |   8374 |      0 |  1023K|  1023K| 1243K (0)|
|* 10 |      INDEX RANGE SCAN           | IAK1_BATCH_PROCESSING_QUEUE |      1 |      5 |    102 |00:00:00.22 |     855 |     44 |      0 |       |       |          |
|  11 |      TABLE ACCESS FULL          | P_PCD_AGGREGATECLAIM        |      1 |   1536K|   1536K|00:00:01.47 |    8331 |   8330 |      0 |       |       |          |
----------------------------------------------------------------------------------------------------------------------------------------------------------------------

Predicate Information (identified by operation id):
---------------------------------------------------

   5 - filter(("BW"."BEGIN_TMSP"=:B1)
   7 - access("RLS"."SNAPSHOT_DT"="BW"."SNAPSHOT_DT" AND "RLS"."ASTG_LOAD_STATUS"='STARTED')
   9 - access("PI"."BATCH_ID"="SRC_BATCH_ID")
  10 - access("DM_BATCH_ID"="BATCH_ID_PKG"."GET_CURRENT_BATCH_ID"('PCD','ATM'))

46 rows selected.

Elapsed: 00:00:01.75

Working through the layers of the query, from the outside towards the middle, we have a simple select from an inline view. The inline view, however, is an aggregate view that selects from another inline view. One of the “columns” of the innermost inline view is an scalar subquery that joins two tables, and the view also uses an IN subquery. So we need to identify all these pieces in the execution plan.

Lines 9 – 11 of the plan show us that the IN subquery of the innermost view has been unnested, producing a hash join. The VIEW operator tells us that this join has been optimized as a “leaf” query block. Lines 3 – 7 give us the separately optimized execution plan for the “select distinct” inline scalar subquery; I am slightly surprised that this part of the plan doesn’t appear after the VIEW operator at line 8, indented at the same level as line 9, since it is a plan that generates a value for each row returned in the view.

Note: although the plan in lines 3 – 7 could be executed once for each row returned by the plan in lines 9 – 11, the number of executions could (and in this case is) fewer than the worst case thanks to scalar subquery caching.

The location of the scalar subquery in the overall plan does make it harder to understand the various time and resource usage figures – but once you understand what the query has to do, it is easier to work out why the numbers have a dislocated look. The time in line 8 is 3:43.99 because it includes the time in line 9 (2.63 seconds) that generates 48,484 rows, plus the time in line 3 (3:40.98) that comes from running the scalar subquery 33,524 times.

Summary

Subqueries can appear in various places in execution plans – when they are scalar subqueries representing columns in the select list, they appear above the query block that calls them. This can be very confusing when you’re trying to follow the trail of where the time and resources are first used when you’ve collected rowsource execution statistics.