Yesterday, during the talk “The Query Optimizer in Oracle Database 12c – What’s New?” at OakTable World UK 2013, an attendee asked me an interesting question that can be summarized as follows: does ASH show the switch of execution plan that takes place for an adaptive plan?

Since I didn’t know the answer, here are some tests I did to find out how it works.

First of all, it’s important to recognize that the plan hash value related to an adaptive plan changes depending on which subplan is activated. Let’s take as example the following query (notice that the execution plan is adaptive and that the hash value of the default plan is 1837274416):

SQL> EXPLAIN PLAN FOR SELECT * FROM t1, t2 WHERE t1.id = t2.id AND t1.n = 666;

SQL> SELECT * FROM table(dbms_xplan.display(format=>'basic +adaptive +note'));

Plan hash value: 1837274416

-----------------------------------------------
| Id  | Operation                     | Name  |
-----------------------------------------------
|   0 | SELECT STATEMENT              |       |
|-  1 |  HASH JOIN                    |       |
|   2 |   NESTED LOOPS                |       |
|   3 |    NESTED LOOPS               |       |
|-  4 |     STATISTICS COLLECTOR      |       |
|   5 |      TABLE ACCESS FULL        | T1    |
|   6 |     INDEX UNIQUE SCAN         | T2_PK |
|   7 |    TABLE ACCESS BY INDEX ROWID| T2    |
|-  8 |   TABLE ACCESS FULL           | T2    |
-----------------------------------------------

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

If the query is executed and the default plan is used (I completely deactivate adaptive plans to ensure it), the plan hash value is the same as the one we have seen before, i.e. 1837274416):

SQL> ALTER SESSION SET optimizer_adaptive_features = FALSE;

SQL> SELECT *
  2  FROM t1, t2
  3  WHERE t1.id = t2.id
  4  AND t1.n = 666;

SQL> SELECT * FROM table(dbms_xplan.display_cursor(format=>'basic +note'));

Plan hash value: 1837274416

----------------------------------------------
| Id  | Operation                    | Name  |
----------------------------------------------
|   0 | SELECT STATEMENT             |       |
|   1 |  NESTED LOOPS                |       |
|   2 |   NESTED LOOPS               |       |
|   3 |    TABLE ACCESS FULL         | T1    |
|   4 |    INDEX UNIQUE SCAN         | T2_PK |
|   5 |   TABLE ACCESS BY INDEX ROWID| T2    |
----------------------------------------------

However, if a switch of execution plan takes place, the plan hash value changes (the new value is 1838229974):

SQL> ALTER SESSION SET optimizer_adaptive_features = TRUE;

SQL> SELECT *
  2  FROM t1, t2
  3  WHERE t1.id = t2.id
  4  AND t1.n = 666;

SQL> SELECT * FROM table(dbms_xplan.display_cursor(format=>'basic +note'));

Plan hash value: 1838229974

-----------------------------------
| Id  | Operation          | Name |
-----------------------------------
|   0 | SELECT STATEMENT   |      |
|   1 |  HASH JOIN         |      |
|   2 |   TABLE ACCESS FULL| T1   |
|   3 |   TABLE ACCESS FULL| T2   |
-----------------------------------

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

Now, back to the question… Since the switch of execution plan takes place during the execution, are we able to spot the switch in the ASH samples? In other words, can we see different plan hash values for a single execution or does the database engine implements a fix-up for the plan hash value?

To test the behaviour I decided to artificially slow down my test query to make sure that ASH captures plenty of samples for a single execution. For that purpose, I usually use a function that burns a lot of CPU like the following one (notice that the parameter specifies, in seconds, how long an execution should last):

CREATE OR REPLACE FUNCTION burn_cpu(p_wait IN INTEGER) RETURN INTEGER IS
  l_begin NUMBER;
BEGIN
  l_begin := dbms_utility.get_time();
  LOOP
    EXIT WHEN l_begin+(p_wait*100) < dbms_utility.get_time();
  END LOOP;
  RETURN 1;
END burn_cpu;

To slow down the access to both tables, I added a predicate based on the burn_cpu function for each of them. In one case, 1 second of CPU is added to the processing of every row. In the other one, just few milliseconds are added (the parameter specifies 1 millisecond, but the overhead is much higher…). According to the runtime statistics the execution lasted 2.5 minutes (50 second for one table, 1 minute and 40 seconds for the other).

SQL> SELECT *
  2  FROM t1, t2
  3  WHERE t1.id = t2.id
  4  AND t1.n = 666
  5  AND burn_cpu(t1.n/t1.n) = 1
  6  AND burn_cpu(t2.n/t2.n/1000) = 1;

SQL> SELECT * FROM table(dbms_xplan.display_cursor(format=>'iostats last'));

Plan hash value: 1838229974

-------------------------------------------------------------------------------------
| Id  | Operation          | Name | Starts | E-Rows | A-Rows |   A-Time   | Buffers |
-------------------------------------------------------------------------------------
|   0 | SELECT STATEMENT   |      |      1 |        |      1 |00:02:29.53 |    1319 |
|*  1 |  HASH JOIN         |      |      1 |      1 |      1 |00:02:29.53 |    1319 |
|*  2 |   TABLE ACCESS FULL| T1   |      1 |      1 |     49 |00:00:49.52 |    1155 |
|*  3 |   TABLE ACCESS FULL| T2   |      1 |      1 |  10000 |00:01:39.98 |     164 |
-------------------------------------------------------------------------------------

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

   1 - access("T1"."ID"="T2"."ID")
   2 - filter(("T1"."N"=666 AND "BURN_CPU"("T1"."N"/"T1"."N")=1))
   3 - filter("BURN_CPU"("T2"."N"/"T2"."N"/1000)=1)

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

Note that the inflection point of the test query is 48 rows. Therefore, the decision to switch to the alternative execution plan can only take place after 48 seconds from the beginning of the execution.

For this specific execution the content of ASH is the following:

SQL> SELECT sql_exec_id, sql_plan_hash_value, sql_plan_operation, sql_plan_options, sql_plan_line_id,
  2         count(*), min(sample_id), max(sample_id)
  3  FROM v$active_session_history
  4  WHERE session_id = 16
  5  AND session_serial# = 25
  6  AND sql_id = 'ckwcszvtggvxx'
  7  AND sql_child_number = 0
  8  GROUP BY sql_exec_id, sql_plan_hash_value, sql_plan_operation, sql_plan_options, sql_plan_line_id
  9  ORDER BY min(sample_time), max(sample_time);

SQL_EXEC_ID SQL_PLAN_HASH_VALUE SQL_PLAN_OPERATION SQL_PLAN_OPTIONS SQL_PLAN_LINE_ID COUNT(*) MIN(SAMPLE_ID) MAX(SAMPLE_ID)
----------- ------------------- ------------------ ---------------- ---------------- -------- -------------- --------------
   16777216          1837274416 TABLE ACCESS       FULL                            5       49        4121942        4121990
   16777216          1837274416 TABLE ACCESS       FULL                            8        7        4121991        4121997
   16777216          1838229974 TABLE ACCESS       FULL                            8       93        4121998        4122090

The most important things to notice are the following:

  • During the execution the plan hash value changed.
  • According to ASH the plan hash value changed during the execution of the second FTS. This is not what I would expect. It should change before activating the row source operation with the id 8. It seems that there is a short delay before the plan hash value is update. As a result, you might not always be able to observe the switch.
  • The amount of time spent on each FTS matches the runtime statistics shown by DBMS_XPLAN.

In conclusion, the short answer to the question is… yes, it’s visible.