SQL Execution Statistics -- 4 : Adaptive Plans

In the previous 3 blog posts, I have shown how you can use the GATHER_PLAN_STATISTICS Hint or the STATISTICS_LEVEL='ALL' to get sql execution statistics.

This may work with Adaptive Plans as well.

SQL> select /*+ gather_plan_statistics */ count(*)
  2  from tables_list t
  3  where (owner, table_name)
  4  not in
  5  (
  6   select owner, table_name
  7   from indexes_list i
  8  )
  9  /

  COUNT(*)
----------
       593

SQL> select * from table(dbms_xplan.display_cursor('',format=>'ALLSTATS LAST +COST +ADAPTIVE'));

PLAN_TABLE_OUTPUT
------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------
SQL_ID  g6q8m94krdvz7, child number 0
-------------------------------------
select /*+ gather_plan_statistics */ count(*) from tables_list t where
(owner, table_name) not in (  select owner, table_name  from
indexes_list i )

Plan hash value: 2460844421

---------------------------------------------------------------------------------------------------------------------------------------------------
|   Id  | Operation                | Name               | Starts | E-Rows | Cost (%CPU)| A-Rows |   A-Time   | Buffers |  OMem |  1Mem | Used-Mem |
---------------------------------------------------------------------------------------------------------------------------------------------------
|     0 | SELECT STATEMENT         |                    |      1 |        |    11 (100)|      1 |00:00:00.01 |      37 |       |       |          |
|     1 |  SORT AGGREGATE          |                    |      1 |      1 |            |      1 |00:00:00.01 |      37 |       |       |          |
|  *  2 |   HASH JOIN ANTI         |                    |      1 |     22 |    11   (0)|    593 |00:00:00.01 |      37 |  1335K|  1335K| 1376K (0)|
|-    3 |    NESTED LOOPS ANTI     |                    |      1 |     22 |    11   (0)|   2202 |00:00:00.01 |      17 |       |       |          |
|-    4 |     STATISTICS COLLECTOR |                    |      1 |        |            |   2202 |00:00:00.01 |      17 |       |       |          |
|     5 |      INDEX FAST FULL SCAN| TABLES_LIST_NDX    |      1 |   2202 |     5   (0)|   2202 |00:00:00.01 |      17 |       |       |          |
|- *  6 |     INDEX RANGE SCAN     | INDEXES_LIST_NDX_1 |      0 |   2918 |     6   (0)|      0 |00:00:00.01 |       0 |       |       |          |
|     7 |    INDEX FAST FULL SCAN  | INDEXES_LIST_NDX_1 |      1 |   2918 |     6   (0)|   2918 |00:00:00.01 |      20 |       |       |          |
---------------------------------------------------------------------------------------------------------------------------------------------------

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

   2 - access("OWNER"="OWNER" AND "TABLE_NAME"="TABLE_NAME")
   6 - access("OWNER"="OWNER" AND "TABLE_NAME"="TABLE_NAME")

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


31 rows selected.

SQL>
SQL> alter session set statistics_level='ALL';

Session altered.

SQL> select count(*)
  2  from tables_list t
  3  where (owner, table_name)
  4  not in
  5  (
  6   select owner, table_name
  7   from indexes_list i
  8  )
  9  /

  COUNT(*)
----------
       593

SQL> select * from table(dbms_xplan.display_cursor('',format=>'ALLSTATS LAST +COST +ADAPTIVE'));

PLAN_TABLE_OUTPUT
------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------
SQL_ID  c1fdcdxhvjrat, child number 0
-------------------------------------
select count(*) from tables_list t where (owner, table_name) not in (
select owner, table_name  from indexes_list i )

Plan hash value: 2460844421

---------------------------------------------------------------------------------------------------------------------------------------------------
|   Id  | Operation                | Name               | Starts | E-Rows | Cost (%CPU)| A-Rows |   A-Time   | Buffers |  OMem |  1Mem | Used-Mem |
---------------------------------------------------------------------------------------------------------------------------------------------------
|     0 | SELECT STATEMENT         |                    |      1 |        |    11 (100)|      1 |00:00:00.01 |      37 |       |       |          |
|     1 |  SORT AGGREGATE          |                    |      1 |      1 |            |      1 |00:00:00.01 |      37 |       |       |          |
|  *  2 |   HASH JOIN ANTI         |                    |      1 |     22 |    11   (0)|    593 |00:00:00.01 |      37 |  1335K|  1335K| 1381K (0)|
|-    3 |    NESTED LOOPS ANTI     |                    |      1 |     22 |    11   (0)|   2202 |00:00:00.01 |      17 |       |       |          |
|-    4 |     STATISTICS COLLECTOR |                    |      1 |        |            |   2202 |00:00:00.01 |      17 |       |       |          |
|     5 |      INDEX FAST FULL SCAN| TABLES_LIST_NDX    |      1 |   2202 |     5   (0)|   2202 |00:00:00.01 |      17 |       |       |          |
|- *  6 |     INDEX RANGE SCAN     | INDEXES_LIST_NDX_1 |      0 |   2918 |     6   (0)|      0 |00:00:00.01 |       0 |       |       |          |
|     7 |    INDEX FAST FULL SCAN  | INDEXES_LIST_NDX_1 |      1 |   2918 |     6   (0)|   2918 |00:00:00.01 |      20 |       |       |          |
---------------------------------------------------------------------------------------------------------------------------------------------------

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

   2 - access("OWNER"="OWNER" AND "TABLE_NAME"="TABLE_NAME")
   6 - access("OWNER"="OWNER" AND "TABLE_NAME"="TABLE_NAME")

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


30 rows selected.

SQL>

ote : The two SQL statements, although being the same, have different SQL_IDs because of the presence / absence of the GATHER_PLAN_STATISTICS Hint.

SQL Execution Statistics -- 3 : Using STATISTICS_LEVEL

 In my previous posts here and here, I have shown how to use the GATHER_PLAN_STATISTICS Hint to collect additional information.  But what if you can't modify the SELECT query statement ?

You could set STATISTICS_LEVEL='ALL' at the session, run the query and then reset STATISTICS_LEVEL to the default  'TYPICAL'

SQL> alter session set tracefile_identifier='H2';

Session altered.

SQL> alter session set statistics_level='ALL';

Session altered.

SQL> exec DBMS_SESSION.SET_SQL_TRACE(sql_trace=>TRUE);  -- just to get the SQL_ID in the trace file

PL/SQL procedure successfully completed.

SQL>
SQL> select
  2  d.department_id, d.department_name, e.first_name, e.last_name
  3  from hr.departments d join hr.employees e
  4  on d.department_id=e.department_id
  5  order by 1,2,4,3
  6  /
....
....
....
106 rows selected.

SQL>
SQL> exec DBMS_SESSION.SET_SQL_TRACE(sql_trace=>FALSE);

PL/SQL procedure successfully completed.

SQL>
QL> select * from table(dbms_xplan.display_cursor('4aa2k5b98ybfr',format=>'ALLSTATS LAST'));  -- SQL_ID identified from the trace file

PLAN_TABLE_OUTPUT
------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------
SQL_ID  4aa2k5b98ybfr, child number 0
-------------------------------------
select d.department_id, d.department_name, e.first_name, e.last_name
from hr.departments d join hr.employees e on
d.department_id=e.department_id order by 1,2,4,3

Plan hash value: 2209899241

-------------------------------------------------------------------------------------------------------------------------------------------------
| Id  | Operation                     | Name              | Starts | E-Rows | A-Rows |   A-Time   | Buffers | Reads  |  OMem |  1Mem | Used-Mem |
-------------------------------------------------------------------------------------------------------------------------------------------------
|   0 | SELECT STATEMENT              |                   |      1 |        |    106 |00:00:00.10 |      10 |     14 |       |       |          |
|   1 |  SORT ORDER BY                |                   |      1 |    106 |    106 |00:00:00.10 |      10 |     14 | 11264 | 11264 |10240  (0)|
|   2 |   MERGE JOIN                  |                   |      1 |    106 |    106 |00:00:00.10 |      10 |     14 |       |       |          |
|   3 |    TABLE ACCESS BY INDEX ROWID| DEPARTMENTS       |      1 |     27 |     12 |00:00:00.03 |       2 |      2 |       |       |          |
|   4 |     INDEX FULL SCAN           | DEPT_ID_PK        |      1 |     27 |     12 |00:00:00.03 |       1 |      1 |       |       |          |
|*  5 |    SORT JOIN                  |                   |     12 |    107 |    106 |00:00:00.06 |       8 |     12 |  9216 |  9216 | 8192  (0)|
|   6 |     VIEW                      | index$_join$_002  |      1 |    107 |    106 |00:00:00.06 |       8 |     12 |       |       |          |
|*  7 |      HASH JOIN                |                   |      1 |        |    106 |00:00:00.06 |       8 |     12 |  1610K|  1610K| 1658K (0)|
|   8 |       INDEX FAST FULL SCAN    | EMP_DEPARTMENT_IX |      1 |    107 |    106 |00:00:00.06 |       4 |      6 |       |       |          |
|   9 |       INDEX FAST FULL SCAN    | EMP_NAME_IX       |      1 |    107 |    107 |00:00:00.01 |       4 |      6 |       |       |          |
-------------------------------------------------------------------------------------------------------------------------------------------------

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

   5 - access("D"."DEPARTMENT_ID"="E"."DEPARTMENT_ID")
       filter("D"."DEPARTMENT_ID"="E"."DEPARTMENT_ID")
   7 - access(ROWID=ROWID)


30 rows selected.

SQL>

Thus, I was able to get similar execution statistics without the Hint if I set STATISTICS_LEVEL='ALL'.

(Note : The top level operation here is a MERGE JOIN while that in the first example of the first post of this series on 27-January-22 was a HASH JOIN. The result here is 106 rows, not the 108 rows in the first example. The first example was in an HR schema in another database -- e.g. you would see DEPARTMENT_ID=280 'New Department' and Employee 'HEMANT CHITALE' in that listing.  These are two different HR schemas where I have modified some of the data.  Thus, you'll see a difference in the Execution Plan as well between the first example and this one. although the query is similar -- because the databases, patch levels,  possibly optimizer parameters, schema and data are different.)

Even a slight difference in data or parameters or patch levels can result in different execution plans !

SQL Execution Statistics -- 2 : SQL_ID from a Tracefile

In my previous blog post, I have demonstrated sql execution statistics for the last SQL statement of the current session.

However, you can trace SQL execution in the current session or in any other session and then review the information from the tracefile.

(For different methods of SQL Tracing see this series of blog posts) 

For example, in an SQLPlus session :

SQL> alter session set tracefile_identifier='CUSTOMER_COUNT';

Session altered.

SQL>
SQL> select *
  2  from v$diag_info
  3  where name = 'Default Trace File';

   INST_ID NAME
---------- ----------------------------------------------------------------
VALUE
---------------------------------------------------------------------------------------
    CON_ID
----------
         1 Default Trace File
/opt/oracle/diag/rdbms/orclcdb/ORCLCDB/trace/ORCLCDB_ora_9416_CUSTOMER_COUNT.trc
         0


SQL>
SQL> exec DBMS_SESSION.SET_SQL_TRACE(sql_trace=>TRUE);

PL/SQL procedure successfully completed.

SQL> select /*+ gather_plan_statistics */ count(*) from tpcc.orders;

  COUNT(*)
----------
    303697

SQL> quit
Disconnected from Oracle Database 19c Enterprise Edition Release 19.0.0.0.0 - Production
Version 19.12.0.0.0
oracle19c>

From the tracefile :
PARSING IN CURSOR #139722640816616 len=62 dep=0 uid=106 oct=3 lid=106 tim=20489021058 hv=3158106211 ad='777865e0' sqlid='du49mwuy3ts33'
select /*+ gather_plan_statistics */ count(*) from tpcc.orders
END OF STMT
PARSE #139722640816616:c=10950,e=11447,p=0,cr=0,cu=0,mis=1,r=0,dep=0,og=1,plh=630573765,tim=20489021057
EXEC #139722640816616:c=52,e=51,p=0,cr=0,cu=0,mis=0,r=0,dep=0,og=1,plh=630573765,tim=20489021253
FETCH #139722640816616:c=78319,e=464572,p=1504,cr=1508,cu=0,mis=0,r=1,dep=0,og=1,plh=630573765,tim=20489485885
STAT #139722640816616 id=1 cnt=1 pid=0 pos=1 obj=0 op='SORT AGGREGATE (cr=1508 pr=1504 pw=0 str=1 time=464570 us)'
STAT #139722640816616 id=2 cnt=303697 pid=1 pos=1 obj=80213 op='TABLE ACCESS FULL ORDERS (cr=1508 pr=1504 pw=0 str=1 time=566811 us cost=411 size=0 card=303697)'
FETCH #139722640816616:c=1,e=1,p=0,cr=0,cu=0,mis=0,r=0,dep=0,og=0,plh=630573765,tim=20489486318


From a tkprof of the tracefile :
SQL ID: du49mwuy3ts33 Plan Hash: 630573765

select /*+ gather_plan_statistics */ count(*)
from
 tpcc.orders


call     count       cpu    elapsed       disk      query    current        rows
------- ------  -------- ---------- ---------- ---------- ----------  ----------
Parse        1      0.01       0.01          0          0          0           0
Execute      1      0.00       0.00          0          0          0           0
Fetch        2      0.07       0.46       1504       1508          0           1
------- ------  -------- ---------- ---------- ---------- ----------  ----------
total        4      0.08       0.47       1504       1508          0           1

Misses in library cache during parse: 1
Optimizer mode: ALL_ROWS
Parsing user id: 106
Number of plan statistics captured: 1

Rows (1st) Rows (avg) Rows (max)  Row Source Operation
---------- ---------- ----------  ---------------------------------------------------
         1          1          1  SORT AGGREGATE (cr=1508 pr=1504 pw=0 time=464570 us starts=1)
    303697     303697     303697   TABLE ACCESS FULL ORDERS (cr=1508 pr=1504 pw=0 time=566811 us starts=1 cost=411 size=0 card=303697)
    
 
 SQL> select * from table(dbms_xplan.display_cursor('du49mwuy3ts33',format=>'ALLSTATS LAST +COST'));

PLAN_TABLE_OUTPUT
------------------------------------------------------------------------------------------------------------------------------------
SQL_ID  du49mwuy3ts33, child number 0
-------------------------------------
select /*+ gather_plan_statistics */ count(*) from tpcc.orders

Plan hash value: 630573765

-------------------------------------------------------------------------------------------------------------
| Id  | Operation          | Name   | Starts | E-Rows | Cost (%CPU)| A-Rows |   A-Time   | Buffers | Reads  |
-------------------------------------------------------------------------------------------------------------
|   0 | SELECT STATEMENT   |        |      1 |        |   411 (100)|      1 |00:00:00.38 |    1506 |   1505 |
|   1 |  SORT AGGREGATE    |        |      1 |      1 |            |      1 |00:00:00.38 |    1506 |   1505 |
|   2 |   TABLE ACCESS FULL| ORDERS |      1 |    303K|   411   (1)|    303K|00:00:00.07 |    1506 |   1505 |
-------------------------------------------------------------------------------------------------------------


14 rows selected.

SQL>

From the tracefile, I could identify the SQL_ID (du49mwuy3ts33) and then run dbms_xplan.display_cursor for that SQL_ID.  

There is a slight discrepancy between the tracefile and the dbms_xplan.display_cursor output on the Actual Time and Buffers ("cr" in the tracefile) and Physical Reads ("pr" in the tracefile).  Similarly, you might notice a discrepancy in the time reported in the raw trace file STAT lines for operation Ids 2 and 1.  When the timing is in microseconds, some discrepancies may arise.

You must also note that gather_plan_statistics itself introduces an overhead on execution time for SQL statements that run in microseconds/milliseconds.

(For an explanation of reading the tracefile, see this post on the details and and this post on the summary)