Yuan Yao, An Oracle ACE's Blog

You may wonder which step of a SQL execution plan is the slowest. To answer this question, You have several options:

• SQL Monitor: This feature shows information either for long-running queries which consumes at least 5 seconds of CPU or I/O, or for all parallel queries. However, it does not capture short-running queries.


• Execution Time Statistics: You can get the execution time for each step by setting the statistics_level parameter to ALL at the session level, or by using the GATHER_PLAN_STATISTICS hint. However, these methods incur overhead and are not enabled by default.


• SQL Trace: Enable SQL Trace to the given SQL is another option, but this is also non-default and incur overhead.

An ingenious technique is to leverage Active Session History (ASH) raw data. ASH is always on and continuously samples active session every second. When an active session is sampled, the step it is executing is also captured. This means you use ASH data to determine where Oracle spends most of its time in an execution plan.

The following session demonstrates how to find, for a particular execution plan, in which step and on which object Oracle spends most of its time.

Consider the following problematic SQL statement and its execution plan:

SQL> SELECT * FROM DBMS_XPLAN.DISPLAY_CURSOR('gkxxkghxubh1a',format=> '+ADAPTIVE');
PLAN_TABLE_OUTPUT
SQL_ID  gkxxkghxubh1a, child number 0
-------------------------------------
SELECT ORDER_MODE, ORDERS.WAREHOUSE_ID, SUM(ORDER_TOTAL), COUNT(1) FROM
ORDERS, WAREHOUSES WHERE ORDERS.WAREHOUSE_ID = WAREHOUSES.WAREHOUSE_ID
AND WAREHOUSES.WAREHOUSE_ID = :B1 GROUP BY CUBE(ORDERS.ORDER_MODE,
ORDERS.WAREHOUSE_ID)

Plan hash value: 2692802960

---------------------------------------------------------------------------------------
| Id  | Operation             | Name          | Rows  | Bytes | Cost (%CPU)| Time     |
---------------------------------------------------------------------------------------
|   0 | SELECT STATEMENT      |               |       |       |   794K(100)|          |
|   1 |  SORT GROUP BY        |               |     2 |    38 |   794K  (1)| 00:00:32 |
|   2 |   GENERATE CUBE       |               |     2 |    38 |   794K  (1)| 00:00:32 |
|   3 |    SORT GROUP BY      |               |     2 |    38 |   794K  (1)| 00:00:32 |
|   4 |     NESTED LOOPS      |               |   164K|  3045K|   794K  (1)| 00:00:32 |
|*  5 |      INDEX UNIQUE SCAN| WAREHOUSES_PK |     1 |     4 |     1   (0)| 00:00:01 |
|*  6 |      TABLE ACCESS FULL| ORDERS        |   164K|  2404K|   794K  (1)| 00:00:32 |
---------------------------------------------------------------------------------------

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

   5 - access("WAREHOUSES"."WAREHOUSE_ID"=:B1)
   6 - filter("ORDERS"."WAREHOUSE_ID"=:B1)

27 rows selected.

Based on the execution plan, step 6 (TABLE ACCESS FULL on ORDERS) appears to be the most costly. However, this is a theoretical estimate. We can leverage ASH data to get a real picture of time distribution on each step. Since ASH indiscriminately collects samples from all active sessions every second, the time spend on each step should be proportional to the number of row that contains the step in ASH data. The query below shows the time spent on different steps of the execution plan for a specific SQL statement.

SELECT 
       sql_plan_operation AS operation,
       sql_plan_options AS options,
       sql_plan_line_id AS line_id,
       b.object_name,
       NVL(event, 'ON CPU') AS event,
       COUNT(*) AS count
FROM v$active_session_history a
left join cdb_objects b on a.con_id=b.con_id and a.current_obj#=b.object_id
WHERE sql_id = 'gkxxkghxubh1a' and SQL_PLAN_HASH_VALUE=2692802960
GROUP BY sql_plan_operation,
         sql_plan_options,
         sql_plan_line_id,
b.object_name,
         event
ORDER BY COUNT(*);

Output:

OPERATION      OPTIONS      LINE_ID OBJECT_NAME   EVENT                COUNT
                                                  ON CPU                   1
SORT           GROUP BY           3 ORDERS        ON CPU                   1
TABLE ACCESS   FULL               6 ORDERS        ON CPU                 110
TABLE ACCESS   FULL               6 ORDERS        direct path read       203

The absolute majority time is spent on step 6, with 203 samples involving direct path read, indicating substantial I/O operations. Given the filter condition on this step, creating a index on  ORDERS.WAREHOUSE_ID  can have a dramatic effect on performance by reducing the need for full table scans.

This is a simple example, and for complex SQL statements with dozens of execution steps, this technique becomes even more valuable as it helps pinpoint the precise steps that require optimization.