I realized the other week while following the Diagnosing Oracle RAC Performance using AWR reports webinar that there are many persons out there asking why, despite their sql_id is present in dba_hist_active_sess_history (AWR) they are, however, unable to get its corresponding execution plan from AWR. This is the third situation, in just a couple of months, where I have seen this question being asked. It’s now time to fill this gap.
In order to answer this question one needs to know that dba_hist_active_sess_history gets its data from gv$active_session_history (ASH) while dba_hist_sqlstat and cie get their data from a bunch of other dynamic performance view like v$sql, v$version, etc..
In this context, rows flagged to be copied into AWR are dumped from gv$active_session_history into dba_hist_active_sess_history, not really on the fly, but with a relatively small time-delay which I am not able to calculate. The remaining dynamic performance views (v$sql, v$session etc…) are, however, dumped into AWR historical tables (dba_hist_sqlstat, etc…) only at AWR sample time, typically every hour.
Moreover, you know that Oracle is not flushing data from v$active_session_history the same way it does with v$sql, v$session, and with other performance dynamic views. The rate at which data are flushed from ASH depends strongly on the size defined by the value of the _ash_size parameter
SQL> @pd _ash_size Show all parameters and session values from x$ksppi/x$ksppcv... NAME VALUE DESCRIPTION ---------- --------- ------------------------------------------------------------- _ash_size 1048618 To set the size of the in-memory Active Session History buffers
It depends also on how much ASH is stressed so that emergency flush are done
SQL> select
inst_id
,total_size/power(1024,2) MB
,awr_flush_emergency_count
from gv$ash_info; 2 3 4 5
INST_ID MB AWR_FLUSH_EMERGENCY_COUNT
---------- ---------- -------------------------
1 4 0
But, typically, in real life running systems, v$active_session_history almost always retains data for more than a couple of hours (some time a whole day) allowing, as such, Oracle to dump all flagged ASH records (is_awr_sample) into dba_hist_active_sess_history without any loss.
On the other hand, you can’t possibly ignore that flushing the other dynamic performs view follows a completely different algorithm strongly related to the activity of the application. Consequently, it is very plausible that, while a sql_id is dumped into dba_hist_active_sess_history with a relatively small delay, the same sql_id could be flushed out from v$sql one hour later when the AWR snapshot is taken. This is why one cannot get the AWR execution plan of a sql_id present in dba_hist_active_sess_history.
Let’s demonstrate this with a simple model:
create table t1
as
with generator as (
select --+ materialize
rownum id
from dual
connect by
level <= 10000)
select
rownum id,
trunc(dbms_random.value(1,1000)) n1,
lpad(rownum,10,'0') small_vc,
rpad('x',100) padding
from
generator v1,
generator v2
where
rownum <= 1000000;
create index t1_n1 on t1(id, n1);
create table t2
as
with generator as (
select --+ materialize
rownum id
from dual
connect by
level <= 10000)
select
rownum id,
trunc(dbms_random.value(10001,20001)) x1,
lpad(rownum,10,'0') small_vc,
rpad('x',100) padding
from
generator v1,
generator v2
where
rownum <= 1000000;
create index t2_i1 on t2(x1);
I have created two tables with two indexes and launched the following query
select *
from t1
where id
in (select id from t2 where x1 = 17335)
order by id;
93 rows selected.
Elapsed: 00:03:05.22
But, before executing the above query, I have changed the optimizer mode from all_rows to first_rows so that a costly INDEX FULL SCAN will be used to avoid the order by operation when sorting the result by id.
While the query was running I executed the following queries against ASH and AWR to see how the dumping is going on:
SELECT
sample_time
,is_awr_sample
,COUNT(1)
FROM
gv$active_session_history
WHERE
sql_id = '069t64t6ws5mx'
AND is_awr_sample = 'Y'
GROUP BY
sample_time
,is_awr_sample
order by sample_time ;
SAMPLE_TIME I COUNT(1)
----------------------------- - ----------
26-JUN-21 03.17.29.878 PM Y 1
26-JUN-21 03.17.40.117 PM Y 1
26-JUN-21 03.17.50.357 PM Y 1
26-JUN-21 03.18.00.598 PM Y 1
26-JUN-21 03.18.10.839 PM Y 1
26-JUN-21 03.18.21.141 PM Y 1
26-JUN-21 03.18.31.510 PM Y 1
26-JUN-21 03.18.41.750 PM Y 1
26-JUN-21 03.18.51.991 PM Y 1
26-JUN-21 03.19.02.229 PM Y 1
26-JUN-21 03.19.12.470 PM Y 1
26-JUN-21 03.19.22.709 PM Y 1
26-JUN-21 03.19.32.949 PM Y 1
26-JUN-21 03.19.43.188 PM Y 1
26-JUN-21 03.19.53.493 PM Y 1
8 rows selected.
SELECT
sql_id,
sample_time
FROM
dba_hist_active_sess_history
WHERE
sql_id = '069t64t6ws5mx'
ORDER BY
2;
no rows selected
SQL> select * from table(dbms_xplan.display_awr('069t64t6ws5mx'));
no rows selected;
And so on until the end of this query
SELECT
sample_time
,is_awr_sample
,COUNT(1)
FROM
gv$active_session_history
WHERE
sql_id = '069t64t6ws5mx'
AND is_awr_sample = 'Y'
GROUP BY
sample_time
,is_awr_sample
order by sample_time ;
SAMPLE_TIME I COUNT(1)
--------------------------- - ----------
26-JUN-21 03.17.29.878 PM Y 1
26-JUN-21 03.17.40.117 PM Y 1
26-JUN-21 03.17.50.357 PM Y 1
26-JUN-21 03.18.00.598 PM Y 1
26-JUN-21 03.18.10.839 PM Y 1
26-JUN-21 03.18.21.141 PM Y 1
26-JUN-21 03.18.31.510 PM Y 1
26-JUN-21 03.18.41.750 PM Y 1
26-JUN-21 03.18.51.991 PM Y 1
26-JUN-21 03.19.02.229 PM Y 1
26-JUN-21 03.19.12.470 PM Y 1
26-JUN-21 03.19.22.709 PM Y 1
26-JUN-21 03.19.32.949 PM Y 1
26-JUN-21 03.19.43.188 PM Y 1
26-JUN-21 03.19.53.493 PM Y 1
26-JUN-21 03.20.03.733 PM Y 1
26-JUN-21 03.20.14.102 PM Y 1
26-JUN-21 03.20.24.342 PM Y 1
18 rows selected.
SELECT
sql_id,
sample_time
FROM
dba_hist_active_sess_history
WHERE
sql_id = '069t64t6ws5mx'
ORDER BY
2;
SQL_ID SAMPLE_TIME
------------- -----------------------------
069t64t6ws5mx 26-JUN-21 03.17.29.878 PM
069t64t6ws5mx 26-JUN-21 03.17.40.117 PM
069t64t6ws5mx 26-JUN-21 03.17.50.357 PM
069t64t6ws5mx 26-JUN-21 03.18.00.598 PM
069t64t6ws5mx 26-JUN-21 03.18.10.839 PM
069t64t6ws5mx 26-JUN-21 03.18.21.141 PM
069t64t6ws5mx 26-JUN-21 03.18.31.510 PM
069t64t6ws5mx 26-JUN-21 03.18.41.750 PM
069t64t6ws5mx 26-JUN-21 03.18.51.991 PM
069t64t6ws5mx 26-JUN-21 03.19.02.229 PM
069t64t6ws5mx 26-JUN-21 03.19.12.470 PM
069t64t6ws5mx 26-JUN-21 03.19.22.709 PM
069t64t6ws5mx 26-JUN-21 03.19.32.949 PM
069t64t6ws5mx 26-JUN-21 03.19.43.188 PM
069t64t6ws5mx 26-JUN-21 03.19.53.493 PM
069t64t6ws5mx 26-JUN-21 03.20.03.733 PM
069t64t6ws5mx 26-JUN-21 03.20.14.102 PM
069t64t6ws5mx 26-JUN-21 03.20.24.342 PM
18 rows selected.
SQL> select * from table(dbms_xplan.display_awr('069t64t6ws5mx'));
no rows selected
As you can see, as long as the next AWR snapshot has not been taken, the corresponding execution plan is not yet in AWR:
select
snap_id,
to_char(begin_interval_time, 'dd/mm/yyyy hh24:mi:ss') begin
,to_char(end_interval_time, 'dd/mm/yyyy hh24:mi:ss') end
from
dba_hist_snapshot
order by 1 desc
fetch first 5 rows only;
SNAP_ID BEGIN END
---------- ------------------- -------------------
392 26/06/2021 13:58:56 26/06/2021 15:00:07
391 26/06/2021 13:00:33 26/06/2021 13:58:56
390 26/06/2021 12:00:48 26/06/2021 13:00:33
389 26/06/2021 11:01:00 26/06/2021 12:00:48
388 26/06/2021 10:00:11 26/06/2021 11:01:00
Let’s then force a snapshot so that the execution plan will be dumped into AWR
SQL> EXECUTE DBMS_WORKLOAD_REPOSITORY.CREATE_SNAPSHOT();
PL/SQL procedure successfully completed.
select
snap_id,
to_char(begin_interval_time, 'dd/mm/yyyy hh24:mi:ss') begin
,to_char(end_interval_time, 'dd/mm/yyyy hh24:mi:ss') end
from
dba_hist_snapshot
order by 1 desc
fetch first 5 rows only;
SNAP_ID BEGIN END
---------- ------------------- -------------------
393 26/06/2021 15:00:07 26/06/2021 15:46:40
392 26/06/2021 13:58:56 26/06/2021 15:00:07
391 26/06/2021 13:00:33 26/06/2021 13:58:56
390 26/06/2021 12:00:48 26/06/2021 13:00:33
389 26/06/2021 11:01:00 26/06/2021 12:00:48
SQL> select * from table(dbms_xplan.display_awr('069t64t6ws5mx'));
SQL_ID 069t64t6ws5mx
--------------------
--------------------------------------------------------------------------------------
| Id | Operation | Name | Rows | Bytes | Cost (%CPU)| Time |
--------------------------------------------------------------------------------------
| 0 | SELECT STATEMENT | | | | 102M(100)| |
| 1 | NESTED LOOPS SEMI | | 100 | 13100 | 102M (1)| 01:06:26 |
| 2 | TABLE ACCESS BY INDEX ROWID| T1 | 1000K| 115M| 20332 (1)| 00:00:01 |
| 3 | INDEX FULL SCAN | T1_N1 | 1000K| | 2779 (1)| 00:00:01 |
| 4 | TABLE ACCESS BY INDEX ROWID| T2 | 1 | 10 | 102 (0)| 00:00:01 |
| 5 | INDEX RANGE SCAN | T2_I1 | 100 | | 2 (0)| 00:00:01 |
--------------------------------------------------------------------------------------
If I repeat the same experiment but, this time, I will flush the sql_id just before taking a new AWR sample you will see, then, that there will be no execution plan dumped into AWR
SELECT *
from t1
where id
in (select id from t2 where x1 = 17335)
ORDER BY id;
SELECT
sample_time
,is_awr_sample
,COUNT(1)
FROM
gv$active_session_history
WHERE
sql_id = '65gw9y7cw56k1'
AND is_awr_sample = 'Y'
GROUP BY
sample_time
,is_awr_sample
order by sample_time ;
SAMPLE_TIME I COUNT(1)
------------------------------ - ----------
27-JUN-21 09.01.47.733 AM Y 1
27-JUN-21 09.01.57.973 AM Y 1
27-JUN-21 09.02.08.277 AM Y 1
27-JUN-21 09.02.18.518 AM Y 1
27-JUN-21 09.02.28.757 AM Y 1
27-JUN-21 09.02.39.026 AM Y 1
27-JUN-21 09.02.49.301 AM Y 1
27-JUN-21 09.02.59.609 AM Y 1
8 rows selected.
SELECT
sql_id,
sample_time
FROM
dba_hist_active_sess_history
WHERE
sql_id = '65gw9y7cw56k1'
ORDER BY 2;
no rows selected ----> still no rows dumped into AWR
SELECT
sample_time
,is_awr_sample
,COUNT(1)
FROM
gv$active_session_history
WHERE
sql_id = '65gw9y7cw56k1'
AND is_awr_sample = 'Y'
GROUP BY
sample_time
,is_awr_sample
order by sample_time;
SAMPLE_TIME I COUNT(1)
--------------------------- - ----------
27-JUN-21 09.01.47.733 AM Y 1
27-JUN-21 09.01.57.973 AM Y 1
27-JUN-21 09.02.08.277 AM Y 1
27-JUN-21 09.02.18.518 AM Y 1
27-JUN-21 09.02.28.757 AM Y 1
27-JUN-21 09.02.39.026 AM Y 1
27-JUN-21 09.02.49.301 AM Y 1
27-JUN-21 09.02.59.609 AM Y 1
27-JUN-21 09.03.09.846 AM Y 1
27-JUN-21 09.03.20.085 AM Y 1
27-JUN-21 09.03.30.454 AM Y 1
27-JUN-21 09.03.40.693 AM Y 1
27-JUN-21 09.03.50.997 AM Y 1
27-JUN-21 09.04.01.365 AM Y 1
27-JUN-21 09.04.11.606 AM Y 1
15 rows selected.
SELECT
sql_id,
sample_time
FROM
dba_hist_active_sess_history
WHERE
sql_id = '65gw9y7cw56k1'
ORDER BY 2;
no rows selected ----> still no rows dumped into AWR
SELECT
sample_time
,is_awr_sample
,COUNT(1)
FROM
gv$active_session_history
WHERE
sql_id = '65gw9y7cw56k1'
AND is_awr_sample = 'Y'
GROUP BY
sample_time
,is_awr_sample
order by sample_time ;
SAMPLE_TIME I COUNT(1)
------------------------------ - ----------
27-JUN-21 09.01.47.733 AM Y 1
27-JUN-21 09.01.57.973 AM Y 1
27-JUN-21 09.02.08.277 AM Y 1
27-JUN-21 09.02.18.518 AM Y 1
27-JUN-21 09.02.28.757 AM Y 1
27-JUN-21 09.02.39.026 AM Y 1
27-JUN-21 09.02.49.301 AM Y 1
27-JUN-21 09.02.59.609 AM Y 1
27-JUN-21 09.03.09.846 AM Y 1
27-JUN-21 09.03.20.085 AM Y 1
27-JUN-21 09.03.30.454 AM Y 1
27-JUN-21 09.03.40.693 AM Y 1
27-JUN-21 09.03.50.997 AM Y 1
27-JUN-21 09.04.01.365 AM Y 1
27-JUN-21 09.04.11.606 AM Y 1
27-JUN-21 09.04.21.846 AM Y 1
27-JUN-21 09.04.32.086 AM Y 1
27-JUN-21 09.04.42.326 AM Y 1
18 rows selected.
SELECT
sql_id,
sample_time
FROM
dba_hist_active_sess_history
WHERE
sql_id = '65gw9y7cw56k1'
ORDER BY 2;
SQL_ID SAMPLE_TIME
------------- ---------------------------
65gw9y7cw56k1 27-JUN-21 09.01.47.733 AM
65gw9y7cw56k1 27-JUN-21 09.01.57.973 AM
65gw9y7cw56k1 27-JUN-21 09.02.08.277 AM
65gw9y7cw56k1 27-JUN-21 09.02.18.518 AM
65gw9y7cw56k1 27-JUN-21 09.02.28.757 AM
65gw9y7cw56k1 27-JUN-21 09.02.39.026 AM
65gw9y7cw56k1 27-JUN-21 09.02.49.301 AM
65gw9y7cw56k1 27-JUN-21 09.02.59.609 AM
65gw9y7cw56k1 27-JUN-21 09.03.09.846 AM
65gw9y7cw56k1 27-JUN-21 09.03.20.085 AM
65gw9y7cw56k1 27-JUN-21 09.03.30.454 AM
65gw9y7cw56k1 27-JUN-21 09.03.40.693 AM
65gw9y7cw56k1 27-JUN-21 09.03.50.997 AM
65gw9y7cw56k1 27-JUN-21 09.04.01.365 AM
65gw9y7cw56k1 27-JUN-21 09.04.11.606 AM
65gw9y7cw56k1 27-JUN-21 09.04.21.846 AM
65gw9y7cw56k1 27-JUN-21 09.04.32.086 AM
65gw9y7cw56k1 27-JUN-21 09.04.42.326 AM
18 rows selected. ----> all ASH rows dumped into AWR
select * from table(dbms_xplan.display_awr('65gw9y7cw56k1'));
no rows selected ----> but there is no execution plan into AWR
As you can see there is no execution plan yet into AWR. Normally, as demonstrated above, it will be dumped at AWR sample time (next hour). Unless this sql_id is flushed from memory:
SQL> select * from table(dbms_xplan.display_cursor('65gw9y7cw56k1'));
--------------------------------------------------------------
| Id | Operation | Name | Rows | Bytes |
--------------------------------------------------------------
| 0 | SELECT STATEMENT | | | |
| 1 | NESTED LOOPS SEMI | | 100 | 13100 |
| 2 | TABLE ACCESS BY INDEX ROWID| T1 | 1000K| 115M|
| 3 | INDEX FULL SCAN | T1_N1 | 1000K| |
|* 4 | TABLE ACCESS BY INDEX ROWID| T2 | 1 | 10 |
|* 5 | INDEX RANGE SCAN | T2_I1 | 100 | |
--------------------------------------------------------------
Predicate Information (identified by operation id):
---------------------------------------------------
4 - filter("ID"="ID")
5 - access("X1"=17335)
SELECT
p.sql_id
,p.plan_hash_value
,p.child_number
,p.last_load_time
,p.executions
FROM
gv$sql p
where
p.sql_id = '65gw9y7cw56k1'
and
p.is_shareable ='Y';
SQL_ID PLAN_HASH_VALUE CHILD_NUMBER LAST_LOAD_TIME EXECUTIONS
------------- --------------- ------------ ------------------- ----------
65gw9y7cw56k1 1518369540 0 2021-06-27/09:01:40 1
select address, hash_value from v$sqlarea where sql_id='65gw9y7cw56k1';
ADDRESS HASH_VALUE
---------------- ----------
000000006754FB80 3653409345
SQL> exec dbms_shared_pool.purge ('000000006754FB80, 3653409345', 'C');
PL/SQL procedure successfully completed.
SELECT
p.sql_id
,p.plan_hash_value
,p.child_number
,p.last_load_time
,p.executions
FROM
gv$sql p
where
p.sql_id = '65gw9y7cw56k1';
no rows selected ----> cursor is now purged from memory
Now that I have flushed the sql_id from memory, the next AWR snapshot will not be able to dump its execution plan (and cie) as the following proves:
select
snap_id,
to_char(begin_interval_time, 'dd/mm/yyyy hh24:mi:ss') begin
,to_char(end_interval_time, 'dd/mm/yyyy hh24:mi:ss') end
from
dba_hist_snapshot
order by 1 desc
fetch first 5 rows only;
SNAP_ID BEGIN END
---------- ------------------- -------------------
398 27/06/2021 08:02:48 27/06/2021 09:00:32
397 26/06/2021 19:00:18 27/06/2021 08:02:48
396 26/06/2021 18:00:31 26/06/2021 19:00:18
395 26/06/2021 17:00:43 26/06/2021 18:00:31
394 26/06/2021 15:46:40 26/06/2021 17:00:43
SQL> EXECUTE DBMS_WORKLOAD_REPOSITORY.CREATE_SNAPSHOT();
PL/SQL procedure successfully completed.
select
snap_id,
to_char(begin_interval_time, 'dd/mm/yyyy hh24:mi:ss') begin
,to_char(end_interval_time, 'dd/mm/yyyy hh24:mi:ss') end
from
dba_hist_snapshot
order by 1 desc
fetch first 5 rows only;
SNAP_ID BEGIN END
---------- ------------------- -------------------
399 27/06/2021 09:00:32 27/06/2021 09:17:52
398 27/06/2021 08:02:48 27/06/2021 09:00:32
397 26/06/2021 19:00:18 27/06/2021 08:02:48
396 26/06/2021 18:00:31 26/06/2021 19:00:18
395 26/06/2021 17:00:43 26/06/2021 18:00:31
SQL> select * from table(dbms_xplan.display_awr('65gw9y7cw56k1'));
no rows selected
SQL> select count(1) from dba_hist_active_sess_history where sql_id = '65gw9y7cw56k1';
COUNT(1)
----------
18
In conclusion, because information collected in the performance dynamic views is dumped into AWR at sample time, don’t be surprised when you will not find an execution plan of a cursor despite this cursor is present in dba_hist_active_sess_history. This is probably because this cursor has been flushed out from memory before the AWR sample time.
Mohamed Houri’s Oracle Notes 