There are several methods to find out where time is spent in an execution plan of a query running in an Oracle database. Classical methods like SQL Trace and running a formatter tool like tkprof on the raw trace, or newer methods like SQL Monitor (when the Tuning Pack has been licensed) or running a query with the GATHER_PLAN_STATISTICS-hint (or with statistics_level=all set in the session) and then using DBMS_XPLAN.DISPLAY_CURSOR(format=>’ALLSTATS LAST’). However, what I often use is the information in SQL_PLAN_LINE_ID of Active Session History (ASH). I.e. more detailed by sampling every second in the recent past through V$ACTIVE_SESSION_HISTORY or in the AWR-history through DBA_HIST_ACTIVE_SESS_HISTORY. However, you have to be careful when interpreting the ASH SQL_PLAN_LINE_ID in an adaptive plan.

Here’s an example:

REMARK: I artificially slowed down the processing with the method described by Chris Antognini here: https://antognini.ch/2013/12/adaptive-plans-in-active-session-history/

SQL> @test

DEPARTMENT_NAME
------------------------------
Executive
IT
Finance
Purchasing
Shipping
Sales
Administration
Marketing
Human Resources
Public Relations
Accounting

11 rows selected.

Elapsed: 00:00:27.83
SQL> select * from table(dbms_xplan.display_cursor(format=>'ALLSTATS LAST'));

PLAN_TABLE_OUTPUT
-----------------------------------------------------------------------------------------------
SQL_ID  8nuct789bh45m, child number 0
-------------------------------------
 select distinct DEPARTMENT_NAME from DEPARTMENTS d   join EMPLOYEES e
using(DEPARTMENT_ID)   where d.LOCATION_ID like '%0' and e.SALARY>2000
burn_cpu(e.employee_id/e.employee_id/4) = 1

Plan hash value: 1057942366

------------------------------------------------------------------------------------------------------------------------
| Id  | Operation           | Name        | Starts | E-Rows | A-Rows |   A-Time   | Buffers |  OMem |  1Mem | Used-Mem |
------------------------------------------------------------------------------------------------------------------------
|   0 | SELECT STATEMENT    |             |      1 |        |     11 |00:00:27.82 |      12 |       |       |          |
|   1 |  HASH UNIQUE        |             |      1 |      1 |     11 |00:00:27.82 |      12 |  1422K|  1422K|61440  (0)|
|*  2 |   HASH JOIN         |             |      1 |      1 |    106 |00:00:27.82 |      12 |  1572K|  1572K| 1592K (0)|
|*  3 |    TABLE ACCESS FULL| DEPARTMENTS |      1 |      1 |     27 |00:00:00.01 |       6 |       |       |          |
|*  4 |    TABLE ACCESS FULL| EMPLOYEES   |      1 |      1 |    107 |00:00:27.82 |       6 |       |       |          |
------------------------------------------------------------------------------------------------------------------------

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

   2 - access("D"."DEPARTMENT_ID"="E"."DEPARTMENT_ID")
   3 - filter(TO_CHAR("D"."LOCATION_ID") LIKE '%0')
   4 - filter(("E"."SALARY">2000 AND "BURN_CPU"("E"."EMPLOYEE_ID"/"E"."EMPLOYEE_ID"/4)=1))

Note
-----
   - this is an adaptive plan


30 rows selected.

So I’d expect to see SQL_PLAN_LINE_ID = 4 in ASH for the 28 seconds of wait time here. But it’s different:

SQL> select sql_plan_line_id, count(*) from v$active_session_history 
   2 where sql_id='8nuct789bh45m'and sql_plan_hash_value=1057942366 group by sql_plan_line_id;

SQL_PLAN_LINE_ID   COUNT(*)
---------------- ----------
               9         28

1 row selected.

The 28 seconds are spent on SQL_PLAN_LINE_ID 9. Why that?

The reason is that ASH provides the SQL_PLAN_LINE_ID in adaptive plans according the whole adaptive plan:

SQL> select * from table(dbms_xplan.display_cursor('8nuct789bh45m',format=>'+ADAPTIVE'));

PLAN_TABLE_OUTPUT
--------------------------------------------------------------------------------------------
SQL_ID  8nuct789bh45m, child number 0
-------------------------------------
 select distinct DEPARTMENT_NAME from DEPARTMENTS d   join EMPLOYEES e
using(DEPARTMENT_ID)   where d.LOCATION_ID like '%0' and e.SALARY>2000
burn_cpu(e.employee_id/e.employee_id/4) = 1

Plan hash value: 1057942366

------------------------------------------------------------------------------------------------------
|   Id  | Operation                      | Name              | Rows  | Bytes | Cost (%CPU)| Time     |
------------------------------------------------------------------------------------------------------
|     0 | SELECT STATEMENT               |                   |       |       |     5 (100)|          |
|     1 |  HASH UNIQUE                   |                   |     1 |    30 |     5  (20)| 00:00:01 |
|  *  2 |   HASH JOIN                    |                   |     1 |    30 |     4   (0)| 00:00:01 |
|-    3 |    NESTED LOOPS                |                   |     1 |    30 |     4   (0)| 00:00:01 |
|-    4 |     NESTED LOOPS               |                   |    10 |    30 |     4   (0)| 00:00:01 |
|-    5 |      STATISTICS COLLECTOR      |                   |       |       |            |          |
|  *  6 |       TABLE ACCESS FULL        | DEPARTMENTS       |     1 |    19 |     3   (0)| 00:00:01 |
|- *  7 |      INDEX RANGE SCAN          | EMP_DEPARTMENT_IX |    10 |       |     0   (0)|          |
|- *  8 |     TABLE ACCESS BY INDEX ROWID| EMPLOYEES         |     1 |    11 |     1   (0)| 00:00:01 |
|  *  9 |    TABLE ACCESS FULL           | EMPLOYEES         |     1 |    11 |     1   (0)| 00:00:01 |
------------------------------------------------------------------------------------------------------

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

   2 - access("D"."DEPARTMENT_ID"="E"."DEPARTMENT_ID")
   6 - filter(TO_CHAR("D"."LOCATION_ID") LIKE '%0')
   7 - access("D"."DEPARTMENT_ID"="E"."DEPARTMENT_ID")
   8 - filter(("E"."SALARY">2000 AND "BURN_CPU"("E"."EMPLOYEE_ID"/"E"."EMPLOYEE_ID"/4)=1))
   9 - filter(("E"."SALARY">2000 AND "BURN_CPU"("E"."EMPLOYEE_ID"/"E"."EMPLOYEE_ID"/4)=1))

Note
-----
   - this is an adaptive plan (rows marked '-' are inactive)


37 rows selected.

So here we see the correct line 9. It’s actually a good idea to use 

format=>'+ADAPTIVE'

when gathering plan statistics (through GATHER_PLAN_STATISTICS-hint or STATISTICS_LEVEL=ALL):

SQL> @test

DEPARTMENT_NAME
------------------------------
Executive
IT
Finance
Purchasing
Shipping
Sales
Administration
Marketing
Human Resources
Public Relations
Accounting

11 rows selected.

Elapsed: 00:00:27.96
SQL> select * from table(dbms_xplan.display_cursor(format=>'ALLSTATS LAST +ADAPTIVE'));

PLAN_TABLE_OUTPUT
----------------------------------------------------------------------------------------
SQL_ID  8nuct789bh45m, child number 0
-------------------------------------
 select distinct DEPARTMENT_NAME from DEPARTMENTS d   join EMPLOYEES e
using(DEPARTMENT_ID)   where d.LOCATION_ID like '%0' and e.SALARY>2000
burn_cpu(e.employee_id/e.employee_id/4) = 1

Plan hash value: 1057942366

-------------------------------------------------------------------------------------------------------------------------------------------
|   Id  | Operation                      | Name              | Starts | E-Rows | A-Rows |   A-Time   | Buffers |  OMem |  1Mem | Used-Mem |
-------------------------------------------------------------------------------------------------------------------------------------------
|     0 | SELECT STATEMENT               |                   |      1 |        |     11 |00:00:27.85 |    1216 |       |       |          |
|     1 |  HASH UNIQUE                   |                   |      1 |      1 |     11 |00:00:27.85 |    1216 |  1422K|  1422K|73728  (0)|
|  *  2 |   HASH JOIN                    |                   |      1 |      1 |    106 |00:00:27.85 |    1216 |  1572K|  1572K| 1612K (0)|
|-    3 |    NESTED LOOPS                |                   |      1 |      1 |     27 |00:00:00.01 |       6 |       |       |          |
|-    4 |     NESTED LOOPS               |                   |      1 |     10 |     27 |00:00:00.01 |       6 |       |       |          |
|-    5 |      STATISTICS COLLECTOR      |                   |      1 |        |     27 |00:00:00.01 |       6 |       |       |          |
|  *  6 |       TABLE ACCESS FULL        | DEPARTMENTS       |      1 |      1 |     27 |00:00:00.01 |       6 |       |       |          |
|- *  7 |      INDEX RANGE SCAN          | EMP_DEPARTMENT_IX |      0 |     10 |      0 |00:00:00.01 |       0 |       |       |          |
|- *  8 |     TABLE ACCESS BY INDEX ROWID| EMPLOYEES         |      0 |      1 |      0 |00:00:00.01 |       0 |       |       |          |
|  *  9 |    TABLE ACCESS FULL           | EMPLOYEES         |      1 |      1 |    107 |00:00:27.85 |    1210 |       |       |          |
-------------------------------------------------------------------------------------------------------------------------------------------

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

   2 - access("D"."DEPARTMENT_ID"="E"."DEPARTMENT_ID")
   6 - filter(TO_CHAR("D"."LOCATION_ID") LIKE '%0')
   7 - access("D"."DEPARTMENT_ID"="E"."DEPARTMENT_ID")
   8 - filter(("E"."SALARY">2000 AND "BURN_CPU"("E"."EMPLOYEE_ID"/"E"."EMPLOYEE_ID"/4)=1))
   9 - filter(("E"."SALARY">2000 AND "BURN_CPU"("E"."EMPLOYEE_ID"/"E"."EMPLOYEE_ID"/4)=1))

Note
-----
   - this is an adaptive plan (rows marked '-' are inactive)


37 rows selected.

Summary: Be careful checking SQL_PLAN_LINE_IDs in adaptive plans. This seems obvious in simple plans like the one above, but you may go in wrong directions if there are plans with hundreds of lines. Your analysis may be wrong if you are looking at the wrong plan step. To do some further validation, you may query sql_plan_operation, sql_plan_options from v$active_session_history as well.

Post Views: 934
Thumbnail [60x60]
by
Clemens Bleile