For years, SQL Plan Management was a powerful but somewhat manual tool in the DBA’s belt — capture baselines, evolve them, accept or reject new plans… rinse and repeat. It worked, but it required attention.
With 23ai, Oracle takes a bold step toward self-driving databases: Automatic SQL Plan Management. The database now watches for regressions, evaluates alternatives, and swaps in better plans without waiting for you to notice.
I won’t hide it – I took the above from the ChatGPT after hinting her that I am going to write such article. As it sounds exactly in a way I aimed to (but I am a bit malicious here) I decided to leave it almost untouched.
I obviously browsed several other sources, but will mention three :
by Gavin Soorma – practical guide with short demonstration
and
two by Nigel Bayliss:
the first giving an overview what SQL Plan Management is (so not necessarily about its “auto” aspect) and most of all: this YT presentation.
Now let’s get to the point –
I am wondering what you may think while reading this : “the database now watches for regressions, evaluates alternatives, and swaps in better plans without waiting for you to notice.”
Doesn’t it sound scary? Yet another algorithm which takes over the thinking factor from you based on – what’s referred to as – better plans.
On top, soon (as a DBA, engineer or architect) you’ll be faced that dilemma –
“Should I recommend something over which I lose control, especially that I am not quite aware which algorithm drives it?”
The term “soon” in the vast majority of cases will likely be at least some years from now on before you’ll have to (want to? will it be your voice?) leave your cozy 19c and step onto the board labeled 23ai.
So – most of all – what’s exactly behind the term “better plan?”
Or, being more precise – what kind of factors drive such decision whether to revert to another SQL Plan?
I am afraid, whichever source you’ll read or listen, you’ll likely come across the terms or expressions like “if your SQL has acceptable performance” or “if your query gets a better plan” (hmm… so is that decision CBO cost driven?)
Even the Oracle documentation handles it more or less like that: “the database is able to recover from the suboptimal plan and application service level is restored. This occurs transparently, without manual intervention”.
So, okay — as I tend to blabber on.
In this article, I will attempt to demystify the terms “acceptable performance,” “better plan,” “suboptimal plan,” and so on — and to quantify the mechanisms Oracle uses on its path to choose one SQL plan over another.
Prepare test environment
Create a table with 20 mln rows.
Actually, just ID will be effectively used. MYDATE and PADDING are just “fillers”. Then create (invisible) index on ID.
I will toggle (in)visible according to the needs.
create table TSTUS.TESTASPM tablespace PSTS as
select rownum as ID, sysdate-mod(rownum,365) as mydate, rpad('X',32,'X') as padding
from dual connect by level <= 20e6 ;
Table created.
create index TSTUS.IDX_TESTASPM_ID on TSTUS.TESTASPM ( ID ) invisible ;
Index created.
SYS@DB23AICDB->MYPDB> @desc TESTASPM
Name Null? Type
----------------------------------------------------- -------- ------------------------------------
ID NUMBER
MYDATE DATE
PADDING VARCHAR2(32)
OWNER TABLE_NAME COL_ID COLUMN_NAME DATA_TYPE NDV DENSITY NUM_NULLS AVG_COL_LEN LOW_VAL HI_VAL HISTOGRAM NUM_BUCKETS
------------------------- ------------------------------ ------ ------------------------------ ------------ ------------ ----------- ---------- ----------- ----------------------------------- ----------------------------------- --------------- -----------
TSTUS TESTASPM 1 ID NUMBER 20,000,000 .00000005 0 6 1 20000000 NONE 1
TSTUS 2 MYDATE DATE 365 .00273973 0 8 2024-08-22/13:20:35 2025-08-21/13:20:35 NONE 1
TSTUS 3 PADDING VARCHAR2 1 1.00000000 0 33 XXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXX XXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXX NONE 1
The scripts I have used (test4b.sql will be adjusted as the tests will flow):
1. main test SQL: test4b.sql
set echo on
alter session set cell_offload_processing = false ;
alter session set db_file_multiblock_read_count = 1 ;
alter index TSTUS.IDX_TESTASPM_ID &set_index2_vis_invisb ;
@fb -- flushing buffer cache
@ssqlid -- intercept sql_id
@mysid -- retrieve current SID
--@setts -- setting AUTOTRACE with SQL plan and runtime stats (set autotrace trace explain statistics). It will be active at some later point. Now: disabled.
set echo on
select /* TESTASPM11 */ max(padding) from TSTUS.TESTASPM where ID <= 20 ;
set echo off
2. Querying current status of SPM: lssqlsts.sql
col PARSING_USER_NAME form a10
col SQL_PLAN_BASELINE form a30
col SQL_TEXT form a50 wrap
col PLAN_NAME form a30
col SIGNATURE form 999999999999999999999999
col CPU_TIME form 999,999,999
col BUFFER_GETS form 999,999
col DISK_READS form 999,999,999,999,999
col ELAPSED_TIME form 999,999,999
col EXECS form 999,999,999
col interval form 999999
select task_name, interval,status, cast(last_schedule_time as date) last_schedule_time, sysdate current_time
from dba_autotask_schedule_control
where task_name = 'Auto STS Capture Task'
/
select cast(PLAN_TIMESTAMP as date) PLAN_TIMESTAMP, SQL_ID, SQL_TEXT, PARSING_SCHEMA_NAME, ELAPSED_TIME , CPU_TIME, BUFFER_GETS, DISK_READS, EXECUTIONS as EXECS,
PARSING_USER_NAME, FIRST_LOAD_TIME, SQL_PLAN_BASELINE , OPTIMIZER_COST
from dba_sqlset_statements
where upper(SQL_TEXT) like '%TESTASPM_RANGE_2E6%' order by PLAN_TIMESTAMP
/
select
SIGNATURE, SQL_TEXT, PLAN_NAME, cast(CREATED as date) CREATED, ENABLED, ACCEPTED, REPRODUCED, OPTIMIZER_COST, ELAPSED_TIME, CPU_TIME, BUFFER_GETS,
cast(FOREGROUND_LAST_VERIFIED as date) FOREGROUND_LAST_VERIFIED
from dba_sql_plan_baselines where FOREGROUND_LAST_VERIFIED is not NULL and cast(CREATED as date) >= sysdate-1
and upper(SQL_TEXT) like '%TESTASPM%'
order by FOREGROUND_LAST_VERIFIED
/
3. Various: set runtime stats, set traces, flushing, checks, etc:
-- setts.sql
set autotr off
@mysid
set echo on
SET AUTOTRACE TRACE EXPLAIN STATISTICS
-- fb.sql
set echo on
alter system flush buffer_cache ;
set echo off
-- ssqlid.sql
set echo on
set feedback on sql_id
set echo off
-- mysid.sql
col OSPID form a10
col TRACEFILE form a100
WITH mysidq AS (select max(sid) maxsid from v$mystat)
SELECT s.inst_id, s.sid, s.serial#, p.spid OSPID , p.PID, TRACEFILE
FROM gv$session s, gv$process p , mysidq
where
s.sid = mysidq.maxsid AND
p.addr=s.paddr AND
p.inst_id = s.inst_id
/
-- trsql.sql (set 10046 on specific SQL_ID)
set echo on
alter system set events 'sql_trace [sql:&sql_id_to_10046] level 12';
set echo off
-- check the status of current tracing : lstrall.sql
set echo on
oradebug setmypid
oradebug eventdump system
set echo offBefore real test start I have executed the test SQL in order to know sql_id (it happened to be dmcmjfc9d08by), then flushed shared pool and buffer cache.
Below is the true starting point :
Verifying the current mode of SPM (Auto?) and changing it to AUTO
SQL> select parameter_name , parameter_value
from DBA_SQL_MANAGEMENT_CONFIG
where parameter_name = 'AUTO_SPM_EVOLVE_TASK'
/
PARAMETER_NAME PARAMETER_VALUE
-------------------- ------------------------------
AUTO_SPM_EVOLVE_TASK ON
SQL> exec dbms_spm.configure ('AUTO_SPM_EVOLVE_TASK', 'AUTO') ;
-- Verify :
SQL> select parameter_name , parameter_value
from DBA_SQL_MANAGEMENT_CONFIG
where parameter_name = 'AUTO_SPM_EVOLVE_TASK'
/
PARAMETER_NAME PARAMETER_VALUE
-------------------- ------------------------------
AUTO_SPM_EVOLVE_TASK AUTO
Finally, let’s change the frequency of sampling to 2 min (for the sake of the test). Default: 15 mins.
SQL> exec dbms_auto_task_admin.modify_autotask_setting('Auto STS Capture Task', 'INTERVAL', 120)
PL/SQL procedure successfully completed.
This enables Auto-SPM with FOREGROUND_LAST_VERIFIED in dba_sql_plan_baselines to be populated and sampling freq. every 2 mins.
Knowing the SQL_ID : dmcmjfc9d08by, I have set up SQL Trace (aka 10046 trace) for this SQL_ID, then checked the current status of all active traces :
SQL> @trsql
SQL> alter system set events 'sql_trace [sql:&sql_id_to_10046] level 12';
Enter value for sql_id_to_10046: dmcmjfc9d08by
old 1: alter system set events 'sql_trace [sql:&sql_id_to_10046] level 12'
new 1: alter system set events 'sql_trace [sql:dmcmjfc9d08by] level 12'
System altered.
SQL> lstrall.sql
SQL> oradebug setmypid
Statement processed.
SQL> oradebug eventdump system
sql_trace [sql:dmcmjfc9d08by] level 12
Note.
With the above settings each execution of the SQL with the given SQL_ID will be dumped to separate trace file located in “Diag Trace” directory (bdump in old school).
Btw. alter system set events ‘sql_trace [sql:&sql_id_to_10046] level 12’ could be replaced with dbms_monitor.session_trace_enable and tracing of the SID and SERIAL# of the running session.
My intention was to show that there’s a great way of setting the SQL Trace directly for the selected SQL_ID.
Moreover, this command alone can be customized further, according to the needs, so including further filters, conditions, actions, etc.
Example: alter system set events 'sql_trace [sql:dmcmjfc9d08by] {pgadep: exactdepth 1} level 12' gives you the opportunity to trigger the SQL trace for a given SQL_ID with the condition that this SQL_ID will be executed from PL/SQL block (to be more precise: it needs to be recursive SQL, with the level of dep(th) > 0).
As you can easily guess, using pgadep: exactdepth 0 will trigger the trace for the top-level SQL, meaning the one executed directly from the application layer.
Easy to guess, pgadep: exactdepth 0 will trigger the trace for the top-level SQL_ID only, so e.g. run directly from the app-level.
It’s highly recommended to become familiar with the extremely powerful (since 11g) oradebug tool to understand its interface and capabilities.
I have slightly bad conscience suggesting my own article on that topic, as it’s still unfinished.
There are other (arguably: more) useful sources: e.g. Tanel’s post, and perhaps even more practical, Sayan Malakshinov’s srticle, providing excellent usage examples.
On top (also Sayan’s), nicely formatted oradebug doc which you also can get directly from the SQL*Plus command prompt, obviously just pure text.
Test scenario
To make my intentions clear – the first test scenario is fairly obvious: I executed the same query with:
1). full table scan (lasting long)
2). index access (much faster)
The Auto-SPM should have no doubts in making its decision, as the fundamental figures (see below) left no doubts, either.
The range of IDs is really tiny (less or equal 20).
It does not help with full table scan, but it makes index range scan highly efficient.
Note, with the above settings: alter system set events 'sql_trace [sql:dmcmjfc9d08by] level 12'
each execution of the SQL with the given SQL_ID will be dumped to separate trace file located in “Diag Trace” directory (bdump in old school).
Having all set up let’s execute the test SQL for the first time within the scope of the real test (note, it’ll be executed with full table scan as I toggled the index on ID to INVISIBLE).
Worth mentioning, the tests are carried out on Exadata machine. The Auto-SPM is obviously not limited to Exadata, although I took advantage of the Exadata’s offload feature at later point in time.
For the sake of the first run though, I have made every attempt to make the full table scan as slow as possible with the following two commands : alter session set cell_offload_processing = false ;
alter session set db_file_multiblock_read_count = 1 ;
Execution with Full Table Scan (slow : ~8 seconds)
14:38:35 TSTUS @ MYPDB> @test4b
14:38:42 TSTUS @ MYPDB> alter session set cell_offload_processing = false ;
Session altered.
Elapsed: 00:00:00.01
14:38:42 TSTUS @ MYPDB> alter session set db_file_multiblock_read_count = 1 ;
Session altered.
14:38:42 TSTUS @ MYPDB> alter index TSTUS.IDX_TESTASPM_ID &set_index2_vis_invisb ;
Enter value for set_index2_vis_invisb: INVISIBLE
old 1: alter index TSTUS.IDX_TESTASPM_ID &set_index2_vis_invisb
new 1: alter index TSTUS.IDX_TESTASPM_ID INVISIBLE
Index altered.
14:38:47 TSTUS @ MYPDB> @fb
14:38:47 TSTUS @ MYPDB> set echo on
14:38:47 TSTUS @ MYPDB> alter system flush buffer_cache ;
14:38:48 TSTUS @ MYPDB> set echo off
14:38:48 TSTUS @ MYPDB> set feedback on sql_id
14:38:48 TSTUS @ MYPDB> set echo off
INST_ID SID SERIAL# OSPID PID TRACEFILE
------- ----------- ------- ---------- ---------- --------------------------
1 2428 61256 222676 131 DB23AICDB_ora_222676.trc
14:38:48 TSTUS @ MYPDB select /* TESTASPM11 */ max(padding) from TSTUS.TESTASPM where ID <= 20;
MAX(PADDING)
--------------------------------
XXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXX
1 row selected.
SQL_ID: dmcmjfc9d08by
Elapsed: 00:00:08.49
Execution with Index Range Scan (fast : below 1 second)
Then it’s the second execution of the same query.
This time with the index on ID (I have toggled the index to VISIBLE).
Taking into account the tiny range of 20 against the total cardinality of 20e6 it’s obvious the CBO will chose the index.
Note – these two alterations have no impact on performance:
alter session set cell_offload_processing = false ;
alter session set db_file_multiblock_read_count = 1 ;
14:39:51 TSTUS @ MYPDB> @test4b
14:39:53 TSTUS @ MYPDB> alter session set cell_offload_processing = false ;
Session altered.
14:39:53 TSTUS @ MYPDB> alter session set db_file_multiblock_read_count = 1 ;
Session altered.
14:39:53 TSTUS @ MYPDB>
14:39:53 TSTUS @ MYPDB> alter index TSTUS.IDX_TESTASPM_ID &set_index2_vis_invisb ;
Enter value for set_index2_vis_invisb: VISIBLE
old 1: alter index TSTUS.IDX_TESTASPM_ID &set_index2_vis_invisb
new 1: alter index TSTUS.IDX_TESTASPM_ID VISIBLE
14:40:03 TSTUS @ MYPDB> @fb
14:40:03 TSTUS @ MYPDB> set echo on
14:40:03 TSTUS @ MYPDB> alter system flush buffer_cache ;
System altered.
14:40:03 TSTUS @ MYPDB> set echo off
14:40:03 TSTUS @ MYPDB> set feedback on sql_id
14:40:03 TSTUS @ MYPDB> set echo off
INST_ID SID SERIAL# OSPID PID TRACEFILE
------- ----------- ------- ---------- ---------- ----------------------------
1 1960 660 228757 145 DB23AICDB_ora_228757.trc
1 row selected.
14:40:03 TSTUS @ MYPDB> select /* TESTASPM11 */ max(padding) from TSTUS.TESTASPM where ID <= 20;
MAX(PADDING)
--------------------------------
XXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXX
1 row selected.
SQL_ID: dmcmjfc9d08by
Elapsed: 00:00:00.13
As expected, in “Diag Trace” directory there are two 10046 trace dumps- the first representing the execution with full table scan and the second holding much more interesting content, being the product of the Index Range Scan :
[oracle @ testhost-23aidb ]$ # grep dmcmjfc9d08by *.trc
Trace file with FTS:
DB23AICDB_ora_222676.trc:PARSING IN CURSOR #139700365881920 len=71 dep=0 uid=134 oct=3 lid=134 tim=1690087159815 hv=315629950 ad='939149b0' sqlid='dmcmjfc9d08by'
Trace file with Index Access:
DB23AICDB_ora_228757.trc:PARSING IN CURSOR #139641905788104 len=71 dep=0 uid=134 oct=3 lid=134 tim=1690163165174 hv=315629950 ad='939149b0' sqlid='dmcmjfc9d08by'
DB23AICDB_ora_228757.trc: value="<notes><fg_spm><sql_id>dmcmjfc9d08by</sql_id><test_phv>522503748</test_phv><ref_phv>2920173004</ref_phv><test_ofe>23.1.0</test_ofe><ref_ofe>23.1.0</ref_ofe><ver>normal</ver><rfp>1</rfp><rep>1</rep><osfe>1</osfe><oln>0</oln><hfe>0</hfe><tosfe>4</tosfe><tol"...So, let’s take a look at some excerpts of both traces.
First, some interesting sections of the one with FTS :
10046 FTS (raw) :
364 PARSING IN CURSOR #139700365881920 len=71 dep=0 uid=134 oct=3 lid=134 tim=1690087159815 hv=315629950 ad='939149b0' sqlid='dmcmjfc9d08by'
365 select /* TESTASPM11 */ max(padding) from TSTUS.TESTASPM where ID <= 20
366 END OF STMT
367 EXEC #139700365881920:c=26,e=27,p=0,cr=0,cu=0,mis=0,r=0,dep=0,og=1,plh=2834813234,tim=1690087159815
368 WAIT #139700365881920: nam='cell single block physical read: RDMA' ela=44 cellhash#=976102048 diskhash#=0 bytes=8192 obj#=82773 tim=1690087160231
369 WAIT #139700365881920: nam='cell single block physical read: RDMA' ela=30 cellhash#=976102048 diskhash#=0 bytes=8192 obj#=82773 tim=1690087160367
370 WAIT #139700365881920: nam='cell single block physical read: RDMA' ela=31 cellhash#=976102048 diskhash#=0 bytes=8192 obj#=82773 tim=1690087160464
371 WAIT #139700365881920: nam='cell single block physical read: RDMA' ela=31 cellhash#=976102048 diskhash#=0 bytes=8192 obj#=82773 tim=1690087160552
372 WAIT #139700365881920: nam='cell single block physical read: RDMA' ela=27 cellhash#=976102048 diskhash#=0 bytes=8192 obj#=82773 tim=1690087160639
373 WAIT #139700365881920: nam='cell single block physical read: RDMA' ela=27
..
..
cellhash#=2743020163 diskhash#=0 bytes=8192 obj#=82773 tim=1690095626494
144684 WAIT #139700365881920: nam='cell single block physical read: RDMA' ela=21 cellhash#=2743020163 diskhash#=0 bytes=8192 obj#=82773 tim=1690095626545
144685 WAIT #139700365881920: nam='cell single block physical read: RDMA' ela=22 cellhash#=2743020163 diskhash#=0 bytes=8192 obj#=82773 tim=1690095626596
144686 FETCH #139700365881920:c=8376423,e=8466750,p=144284,cr=144298,cu=0,mis=0,r=1,dep=0,og=1,plh=2834813234,tim=1690095626642
Several notes –
cell single block physical read: RDMA with bytes=8192 is obviously the result of setting "alter session set db_file_multiblock_read_count = 1" – a nasty way of making full table scan (FTS) scanning the segment (table) with the tiniest possible chunks: 1 block (8192 bytes).
Typically you’d see here a wait reporting a number close to 1 048 576 (1MB) next to “bytes=”.
That’s how FTS is designed – if there’s a need to scan usually redundant amount of data, let’s do it as fast as possible. That is, “grabbing as much as OS allows at one go”.
Another one (short debate about 10046 raw trace)
I can’t emphasize enough how useful the raw 10046 (aka SQL Trace) is.
This would take several dedicated posts or a fat chapter in a book. If you’re interested in getting compact but in-depth overview, google “Oracle Trace Files Explained” by Norman Dunbar. As of time of writing of this post the PDF is available here.
Obviously, many of the entries from the raw trace file can be found in the “human readable” version of the 10046, i.e. output of tkprof.
Yet let me name two which can’t be found there and still are extremely useful – the values of bind variables with their characteristics (types, declarative and real size, etc) and.. something which at the first glance sounds not important, but sometimes is invaluable. Namely, the sequence of executions of SQLs within a session’s flow. In my case I set up a trap to intercept just a single sql_id, so I wouldn’t benefit from it (too much).
Let’s call up an example though.
Imagine that you sporadically encounter an enq-TX row lock contention wait on an UPDATE which should (and does) take just the range of milliseconds. So, to be precise its PARSE, EXEC and WAITs take ~ms.
In spite of that, it holds the lock preventing other sessions to place the commit of their (subset or superset) of data chunks for several seconds.
Usually, in such circumstances things pile up, meaning, sometimes there are chains of such sessions waiting on releasing of such TX-row locks in a cascading manner, effectively causing a really long choke.
It’s btw. the true case which I came across just some weeks ago, definitely worth of blogging about, here’s the story in the nutshell.
So, (with little luck), with tracing of a SID and SERIAL# of such offending (holding the lock) session I was able to spot the following sequence: PARSE, EXEC, WAITs (just several I/Os) – all in total took, say, ~1ms.
So where’s the lock? It’s been acquired and it was held until I have spotted : XCTEND (transaction’s end: rollback or commit) releasing the lock and letting the other session to do its job, so carrying on with its UPDATE, precisely: commit.
The thing was, that other session was waiting several seconds with “enq-TX row lock contention”.
Why was it waiting so long?
Because the session holding the lock executed a very fast SELECT in between, which was followed by a sequence of waits typically considered idle — SQL*Net message to client and, most notably, SQL*Net message from client, lasting precisely those few seconds.
It turned out that the application was designed to place that SELECT with the intention to retrieve the immediate result back for some processing.
But sometimes the application code experienced “a hiccup” which was seen on the database server and reported by a session as “SQL*Net message from client” – definitely not to be considered idle.
This case can be particularly troublesome in cloud environments.
Imagine that a network round-trip, which previously took only a few milliseconds before issuing a commit, now takes significantly longer (and yes, it wasn’t discovered during the non-functional tests).
This can effectively cause a “piling-up” effect — not necessarily due to any “hiccup” on the application side, but simply because the ordinary network latency has increased.
Let’s get even further.
Let’s assume that this “fast SELECT in between” suddenly turns out not to be that fast (for whatever reason) — most importantly, getting stuck between the EXEC of that update and the eventual commit of its transaction.
All such cases would be hard to notice without examining the raw 10046 trace of the session, focusing on the sequence of events.
Coming back to the main topic.
Below is the excerpt of human readable version of this raw trace, output of tkprof (see the inline comment):
# tkprof DB23AICDB_ora_222676.trc tkprof.fts
TKPROF: Release 23.0.0.0.0 - Development on Fri Aug 22 14:41:55 2025
Copyright (c) 1982, 2024, Oracle and/or its affiliates. All rights reserved.
SQL ID: dmcmjfc9d08by Plan Hash: 2834813234
select /* TESTASPM11 */ max(padding)
from
TSTUS.TESTASPM where ID <= 20
call count cpu elapsed disk query current rows
------- ------ -------- ---------- ---------- ---------- ---------- ----------
Parse 0 0.00 0.00 0 0 0 0
Execute 1 0.00 0.00 0 0 0 0
Fetch 2 8.37 8.46 144284 144298 0 1
------- ------ -------- ---------- ---------- ---------- ---------- ----------
total 3 8.37 8.46 144284 144298 0 1
--- note :
Worth spotting, the above comes from the raw 10046 FETCH phase after converting "us" to "sec" :
FETCH #139700365881920:c=8376423,e=8466750,p=144284,cr=144298,cu=0,mis=0,r=1,dep=0,og=1,plh=2834813234,tim=1690095626642
---- end of note
Misses in library cache during parse: 0
Optimizer mode: ALL_ROWS
Parsing user id: 134
Number of plan statistics captured: 1
Rows (1st) Rows (avg) Rows (max) Row Source Operation
---------- ---------- ---------- ---------------------------------------------------
1 1 1 SORT AGGREGATE (cr=144298 pr=144284 pw=0 time=8466751 us starts=1 direct read=0 direct write=0)
20 20 20 TABLE ACCESS FULL TESTASPM (cr=144298 pr=144284 pw=0 time=8466736 us starts=1 direct read=0 direct write=0 cost=145091 size=780 card=20)
Elapsed times include waiting on following events:
Event waited on Times Max. Wait Total Waited
---------------------------------------- Waited ---------- ------------
cell single block physical read: RDMA 144277 0.00 3.38
cell disk open 16 0.00 0.00
cell single block physical read: xrmem cache
8 0.00 0.00
SQL*Net message to client 1 0.00 0.00
SQL*Net message from client 1 0.00 0.00
********************************************************************************
See the FETCH from the raw trace brought as a “note” above – it’s source of the summary put in the table, namely the : cpu (c=) - time spent on CPU
elapsed (e=) - total elapsed time
disk (p=) - number of physical reads
query (cr=) - number of logical reads
rows (r=) - number of rows returned by the query
The values from raw trace are expressed in microseconds, whereas tkprof converts them to seconds (yet another reason to take a look at the raw version if high accuracy is required).
For the time being let’s memorize three of them: c (cpu time) ,e (total elapsed time) and cr (effectively: logical reads) which apparently are taken into account while evaluating the ultimate SQL Plan chosen by Auto-SPM.
The values representing time are then converted to milliseconds by Auto-SPM.
Note, I didn’t mention anything about the “cost” calculated by the optimizer, although that figure is saved in the intermediate structures (see later).
To refresh the memory, here’s the Execution with Index Access :
SID:
INST_ID SID SERIAL# OSPID PID TRACEFILE
------- ----------- ------- ---------- ---------- ----------------------------
1 1960 660 228757 145 DB23AICDB_ora_228757.trc
1 row selected.
14:40:03 TSTUS @ MYPDB> select /* TESTASPM11 */ max(padding) from TSTUS.TESTASPM where ID <= 20;
MAX(PADDING)
--------------------------------
XXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXX
1 row selected.
SQL_ID: dmcmjfc9d08by
Elapsed: 00:00:00.13
Let’s check the status :
SYS@DB23AICDB->MYPDB> @lssqlsts
TASK_NAME INTERVAL STATUS LAST_SCHEDULE_TIME CURRENT_TIME
---------------------------------------------------------------- -------- -------------------- ------------------- -------------------
Auto STS Capture Task 120 SUCCEEDED 22-08-2025 14:39:04 22-08-2025 14:40:13
PLAN_TIMESTAMP SQL_ID SQL_TEXT PARSING_SCHEMA_NAME ELAPSED_TIME CPU_TIME BUFFER_GETS DISK_READS EXECS PARSING_US FIRST_LOAD_TIME SQL_PLAN_BASELINE OPTIMIZER_COST
------------------- --------------- -------------------------------------------------- ------------------------------ ------------ ------------ ----------- -------------------- ------------ ---------- ------------------- ------------------------------ --------------
22-08-2025 14:38:48 dmcmjfc9d08by select /* TESTASPM11 */ max(padding) from TSTUS.TE TSTUS 8,488,802 8,395,230 144,347 144,317 1 TSTUS 2025-08-22/14:36:27 145091
STASPM where ID <= 20
SIGNATURE SQL_TEXT PLAN_NAME CREATED ENABLED ACC REP OPTIMIZER_COST ELAPSED_TIME CPU_TIME BUFFER_GETS FOREGROUND_LAST_VER
------------------------- -------------------------------------------------- ------------------------------ ------------------- -------------------- --- --- -------------- ------------ ------------ ----------- -------------------
10185720056185764403 select /* TESTASPM11 */ max(padding) from TSTUS.TE SQL_PLAN_8uqrkdm18cfjm1f24c644 22-08-2025 14:40:04 YES YES YES 4 532 532 4 22-08-2025 14:40:04
STASPM where ID <= 20
Expected behavior – better (I will try to define “better” later) SQL Plan has been selected and accepted – see the ACC = YES.
This also means – and let us emphasize it – the SQL Plan with the baseline SQL_PLAN_8uqrkdm18cfjm1f24c644 has been made active without any manual intervention.
Let’s verify it live (see: “SQL plan baseline “SQL_PLAN_8uqrkdm18cfjm1f24c644″ used for this statement”) :
15:36:40 TSTUS @ MYPDB> SET AUTOTRACE TRACE EXPLAIN STATISTICS
15:36:41 TSTUS @ MYPDB> select /* TESTASPM11 */ max(padding) from TSTUS.TESTASPM where ID <= 20;
Elapsed: 00:00:00.05
Execution Plan
----------------------------------------------------------
Plan hash value: 3639302403
--------------------------------------------------------------------------------------------------------
| Id | Operation | Name | Rows | Bytes | Cost (%CPU)| Time |
--------------------------------------------------------------------------------------------------------
| 0 | SELECT STATEMENT | | 1 | 39 | 4 (0)| 00:00:01 |
| 1 | SORT AGGREGATE | | 1 | 39 | | |
| 2 | TABLE ACCESS BY INDEX ROWID BATCHED| TESTASPM | 20 | 780 | 4 (0)| 00:00:01 |
|* 3 | INDEX RANGE SCAN | IDX_TESTASPM_ID | 20 | | 3 (0)| 00:00:01 |
--------------------------------------------------------------------------------------------------------
Predicate Information (identified by operation id):
---------------------------------------------------
3 - access("ID"<=20)
Note
-----
- SQL plan baseline "SQL_PLAN_8uqrkdm18cfjm1f24c644" used for this statement
Statistics
----------------------------------------------------------
0 recursive calls
0 db block gets
4 consistent gets
4 physical reads
348 redo size
620 bytes sent via SQL*Net to client
108 bytes received via SQL*Net from client
2 SQL*Net roundtrips to/from client
0 sorts (memory)
0 sorts (disk)
1 rows processed
Let’s get back to what we are after, so looking “under the hood”.
As you remember, also this execution left the SQL trace file in the “Diag Trace”.
Here’s the raw 10046 and its tkprof version :
2293 PARSING IN CURSOR #139641905788104 len=71 dep=0 uid=134 oct=3 lid=134 tim=1690163165174 hv=315629950 ad='939149b0' sqlid='dmcmjfc9d08by'
2294 select /* TESTASPM11 */ max(padding) from TSTUS.TESTASPM where ID <= 20
2295 END OF STMT
--- indeed: 4 physical reads, 3 for index (root, branch and leaf) + 1 for table :
2296 EXEC #139641905788104:c=70,e=70,p=0,cr=0,cu=0,mis=0,r=0,dep=0,og=1,plh=3639302403,tim=1690163165173
2297 WAIT #139641905788104: nam='cell single block physical read: RDMA' ela=62 cellhash#=2957023425 diskhash#=0 bytes=8192 obj#=82787 tim=1690163165378
2298 WAIT #139641905788104: nam='cell single block physical read: RDMA' ela=30 cellhash#=2743020163 diskhash#=0 bytes=8192 obj#=82787 tim=1690163165492
2299 WAIT #139641905788104: nam='cell single block physical read: RDMA' ela=24 cellhash#=2957023425 diskhash#=0 bytes=8192 obj#=82787 tim=1690163165555
2300 WAIT #139641905788104: nam='cell single block physical read: RDMA' ela=28 cellhash#=976102048 diskhash#=0 bytes=8192 obj#=82773 tim=1690163165620
2301 FETCH #139641905788104:c=401,e=401,p=4,cr=4,cu=0,mis=0,r=1,dep=0,og=1,plh=3639302403,tim=1690163165668
# tkprof DB23AICDB_ora_228757.trc tkprof.idx
TKPROF: Release 23.0.0.0.0 - Development on Fri Aug 22 14:44:47 2025
Copyright (c) 1982, 2024, Oracle and/or its affiliates. All rights reserved.
select /* TESTASPM11 */ max(padding)
from
TSTUS.TESTASPM where ID <= 20
call count cpu elapsed disk query current rows
------- ------ -------- ---------- ---------- ---------- ---------- ----------
Parse 0 0.00 0.00 0 0 0 0
Execute 1 0.00 0.00 0 0 0 0
Fetch 2 0.00 0.00 4 4 0 1
------- ------ -------- ---------- ---------- ---------- ---------- ----------
total 3 0.00 0.00 4 4 0 1
-- as above, the source of the above figures from the FETCH phase of 10046 :
-- cpu and elapsed are 0.00 as 401 us were converted to seconds.
FETCH #139641905788104:c=401,e=401,p=4,cr=4,cu=0,mis=0,r=1,dep=0,og=1,plh=3639302403,tim=1690163165668
--- end of note
Misses in library cache during parse: 0
Optimizer mode: ALL_ROWS
Parsing user id: 134
Number of plan statistics captured: 1
Rows (1st) Rows (avg) Rows (max) Row Source Operation
---------- ---------- ---------- ---------------------------------------------------
1 1 1 SORT AGGREGATE (cr=4 pr=4 pw=0 time=405 us starts=1 direct read=0 direct write=0)
20 20 20 TABLE ACCESS BY INDEX ROWID BATCHED TESTASPM (cr=4 pr=4 pw=0 time=406 us starts=1 direct read=0 direct write=0 cost=4 size=780 card=20)
20 20 20 INDEX RANGE SCAN IDX_TESTASPM_ID (cr=3 pr=3 pw=0 time=310 us starts=1 direct read=0 direct write=0 cost=3 size=0 card=20)(object id 82787)
Elapsed times include waiting on following events:
Event waited on Times Max. Wait Total Waited
---------------------------------------- Waited ---------- ------------
cell single block physical read: RDMA 5 0.00 0.00
DLM cross inst call completion 24 0.00 0.00
DFS lock handle 2 0.00 0.00
SQL*Net message to client 1 0.00 0.00
SQL*Net message from client 1 0.00 0.00
********************************************************************************
I have left the interesting part of 10046 raw trace for now.
After executing of the main SQL (my test SQL), there is another cursor spawned – a MERGE into sqlobj$auxdata which saves the data for the (I believe) core analysis which SQL Plan should effectively be chosen by Auto-SPM (copy-pasted unformatted, still the crucial excerpts are marked) :
2384 PARSING IN CURSOR #139641909607496 len=5018 dep=1 uid=0 oct=189 lid=0 tim=1690163167243 hv=3618241547 ad='75af4af8' sqlid='1fbu2jmbumz0b'
2385 MERGE /*+ INDEX(dest (signature category obj_type plan_id)) */ INTO sqlobj$auxdata dest USING (SELECT :1 signature, :2 category, :3 obj_type, :4 plan_id FROM dual) src ON (dest.signature = src.s ignature AND dest.category = src.category AND dest.obj_type = src.obj_type AND dest.plan_id = src.plan_id) WHEN MATCHED THEN UPDATE SET description = :5, creator = nvl(:6, creator), origin = :7, version = :8, created = :9, last_modified = :10, last_verified = :11, parse_cpu_time = NULL, optimizer_cos t = nvl(:12, optimizer_cost), module = nvl(:13, module), action = nvl(:14, action), priority = nvl(:15, priority), optimizer_env = nvl(:16, optimizer_env) , bind_data = nvl(:17, bind_data), parsing_schema_name = nvl(:18, parsing_schema_name), executions = nvl(:19, executions), elapsed_time = nvl(:20, elapsed_time), cpu_time = nvl(:21, cpu_time), buffer_gets = nvl(:22, buffer_gets), disk_reads = nvl(:23, disk_reads), direct_writes = nvl(:24, direct_writes), rows_processe d = nvl(:25, rows_processed), fetches = nvl(:26, fetches), end_of_fetch_count = nvl(:27, end_of_fetch_count), task_id = nvl(:28, task_id), task_exec_name = nvl(:29, task_exec_nam e), task_obj_id = nvl(:30, task_obj_id), task_fnd_id = nvl(:31, task_fnd_id), task_rec_id = nvl(:32, task_rec_id), flags = 0, spare1 = null, spare2 = null, task_con_dbid = nvl(:33, task_con_dbid), foreground_last_verified = :34, notes = :35 WHEN NOT MATCHED THEN INSERT (signature, category, obj_type, plan_id, description, creator, origin, version, created, last_modified, last_verified, par se_cpu_time, optimizer_cost, module, action, priority, optimizer_env, bind_data, parsing_schema_name, executions, elapsed_time, cpu_time, buffer_gets, disk_reads, direct_writes, rows_processed, fetches,end_of_fetch_count, task_id, task_exec_name, task_obj_id, task_fnd_id, task_rec_id, flags, spare1, spare2, task_con_dbid, foreground_last_verified, notes) VALUES (:36, :37, :38, :39, :40, :41, :42, : 43, :44, :45, null, null, :46, :47, :48, :49, :50, :51, :52, :53, :54, :55, :56, :57, :58, :59, :60, :61, :62, :63, :64, :65, :66, 0, null, null, :67, null, null)
2386 END OF STMT
2387 PARSE #139641909607496:c=32,e=32,p=0,cr=0,cu=0,mis=0,r=0,dep=1,og=4,plh=3568304656,tim=1690163167243
2388 BINDS #139641909607496:
2389
2390 Bind#0
2391 oacdty=01 mxl=32(20) mxlc=00 mal=00 scl=00 pre=00
2392 oacflg=21 fl2=0000 frm=01 csi=873 siz=248 off=0
2393 kxsbbbfp=7f00ea60d2c0 bln=32 avl=20 flg=05
2394 value="10185720056185764403"
..
..
2543 Bind#34
2544 oacdty=96 mxl=2000(614) mxlc=00 mal=00 scl=00 pre=00
2545 oacflg=11 fl2=0000 frm=01 csi=873 siz=2000 off=0
2546 kxsbbbfp=b9fd8d48 bln=2000 avl=614 flg=09
2547 value="<notes><fg_spm><sql_id>dmcmjfc9d08by</sql_id><test_phv>522503748</test_phv><ref_phv>2920173004</ref_phv><test_ofe>23.1.0</test_ofe><ref_ofe>23.1.0</ref_ofe><ver>normal</ver><rfp>1</rfp><rep>1</rep><osfe>1</osfe><oln>0</oln><hfe>0</hfe><tosfe>4</tosfe><tol"...The core data seems to be fetched along with the XML tree structure (see the Bind#34, so notes = :35, as the first Bind#<number> begins with 0) under the NOTES (CLOB) for a given signature (so exactly Bind#0).
After pivoting the result of the select, here’s what comes up:
SYS@DB23AICDB->MYPDB> select * from sqlobj$auxdata where SIGNATURE = 10185720056185764403
@pr
==============================
SIGNATURE : 10185720056185764403
CATEGORY : DEFAULT
OBJ_TYPE : 2
PLAN_ID : 522503748
DESCRIPTION :
CREATOR : TSTUS
ORIGIN : 15
VERSION : 23.0.0.0.0
CREATED : 22-AUG-25 02.40.04.034834 PM
LAST_MODIFIED : 22-AUG-25 02.40.04.000000 PM
LAST_VERIFIED :
PARSE_CPU_TIME :
OPTIMIZER_COST : 4
MODULE : SQL*Plus
ACTION :
PRIORITY : 0
OPTIMIZER_ENV : (removed for shorter output)
BIND_DATA :
PARSING_SCHEMA_NAME : TSTUS
EXECUTIONS : 1
ELAPSED_TIME : 532
CPU_TIME : 532
BUFFER_GETS : 4
DISK_READS : 1
DIRECT_WRITES : 140725812704376
ROWS_PROCESSED : 0
FETCHES : 0
END_OF_FETCH_COUNT :
TASK_ID :
TASK_EXEC_NAME :
TASK_OBJ_ID :
TASK_FND_ID :
TASK_REC_ID :
FLAGS : 0
SPARE1 :
SPARE2 :
TASK_CON_DBID :
FOREGROUND_LAST_VERIFIED : 22-AUG-25 02.40.04.000000 PM
NOTES :
<notes><fg_spm><sql_id>dmcmjfc9d08by</sql_id><test_phv>522503748</test_phv><ref_phv>2920173004</ref_phv><test_ofe>23.1.0</test_ofe><ref_ofe>23.1.0</ref_ofe><ver>normal</ver><rfp>1</rfp><rep>1</rep><osfe>1</osfe><oln>0</oln><hfe>0</hfe><tosfe>4</tosfe><toln>0</toln><thfe>0</thfe><comp_time>2025-08-22
/14:40:04</comp_time><ref_hp><cpu>18</cpu><bg>49</bg></ref_hp><test_hp><cpu>119</cpu><bg>289</bg></test_hp><ref_perf><bg>144298</bg><cpu>8377</cpu><elps>8488</elps></ref_perf><test_perf><bg>4</bg><cpu>0</cpu><elps>0</elps></test_perf><status>better</status><ver_time>2025-08-22/14:40:04</ver_time></f
g_spm></notes>
==============================
SIGNATURE : 10185720056185764403
CATEGORY : DEFAULT
OBJ_TYPE : 2
PLAN_ID : 2920173004
DESCRIPTION :
CREATOR : TSTUS
ORIGIN : 15
VERSION : 23.0.0.0.0
CREATED : 22-AUG-25 02.40.03.989523 PM
LAST_MODIFIED : 22-AUG-25 02.51.05.000000 PM
LAST_VERIFIED : 22-AUG-25 02.51.05.000000 PM
PARSE_CPU_TIME :
OPTIMIZER_COST : 145091
MODULE : SQL*Plus
ACTION :
PRIORITY :
OPTIMIZER_ENV :
()
BIND_DATA :
PARSING_SCHEMA_NAME : TSTUS
EXECUTIONS : 1
ELAPSED_TIME : 8488802
CPU_TIME : 8377230
BUFFER_GETS : 144298
DISK_READS : 0
DIRECT_WRITES : 0
ROWS_PROCESSED :
FETCHES :
END_OF_FETCH_COUNT :
TASK_ID :
TASK_EXEC_NAME :
TASK_OBJ_ID :
TASK_FND_ID :
TASK_REC_ID :
FLAGS : 0
SPARE1 :
SPARE2 :
TASK_CON_DBID :
FOREGROUND_LAST_VERIFIED :
NOTES :
=========================
Number of records: 39Clearly, the sqlobj$auxdata contains two entries for the given signature, so my test SQL with SQL_ID dmcmjfc9d08by :
the one which placed at the bottom part represents my test SQL executed with full table scan.
See ELAPSED_TIME, CPU_TIME and BUFFER_GETS – they very closely match the figures from the raw 10046 for the first run (the “buffer gets” even exactly matches the figure from the SQL trace, also the timestamps can obviously be matched).
The upper part is clearly the container for my execution with the Index Range Scan.
The referential point is obviously the lower part (so, FTS).
I copy-pasted the content of the NOTES (XML) to notes_mess.xml assuming that the “the crucial bits are always in the fine print” and formatted it to the human-readable shape.
For immediate matching I enclosed the two FETCHes with their values from the corresponding executions – the time related numbers which are visible in “FETCH” were converted from microseconds to milliseconds :
# xmllint --format notes_mess.xml -o notes_nice.xml
# cat notes_nice.xml
<?xml version="1.0"?>
<notes>
<fg_spm>
<sql_id>dmcmjfc9d08by</sql_id>
<test_phv>522503748</test_phv>
<ref_phv>2920173004</ref_phv>
<test_ofe>23.1.0</test_ofe>
<ref_ofe>23.1.0</ref_ofe>
<ver>normal</ver>
<rfp>1</rfp>
<rep>1</rep>
<osfe>1</osfe>
<oln>0</oln>
<hfe>0</hfe>
<tosfe>4</tosfe>
<toln>0</toln>
<thfe>0</thfe>
<comp_time>2025-08-22/14:40:04</comp_time>
<ref_hp>
<cpu>18</cpu>
<bg>49</bg>
</ref_hp>
<test_hp>
<cpu>119</cpu>
<bg>289</bg>
</test_hp>
<ref_perf>
<bg>144298</bg>
<cpu>8377</cpu>
<elps>8488</elps>
</ref_perf>
FETCH from 10046 of the run with FTS c=8376423,e=8466750,p=144284,cr=144298,cu=0,mis=0,r=1,dep=0,og=1,plh=2834813234,tim=1690095626642
<test_perf>
<bg>4</bg>
<cpu>0</cpu>
<elps>0</elps>
</test_perf>
FETCH from 10046 of the run with Index Access c=401,e=401,p=4,cr=4,cu=0,mis=0,r=1,dep=0,og=1,plh=3639302403,tim=1690163165668
<status>better</status>
<ver_time>2025-08-22/14:40:04</ver_time>
</fg_spm>
</notes>Now, below is my interpretation, it seems very likely though.
The <test_perf> seems to stand for “tested performance”, whereas <ref_perf> for “referenced performance”, so the one to be compared with, already executed and kept for that purpose.
The cpu, elps are self explanatory, whereas bg matches (exactly) the number of logical reads (no clue why it’s named “bg”).
There is also : <status>better</status> present as sort of the final statement.
There are also other test_ and ref_ present, namely test_hp and ref_hp to be spotted in this xml input tree (hp = hash plan) with cpu and bg (perhaps again LIOs), which I didn’t manage to match with anything. I would risk the statement, though, that they carry only secondary weight — if any.
Conclusion of this part.
As already mentioned, the SQL Plan utilizing Index Range Scan has been made active without any manual intervention, in-depth analysis, etc.
It’s obviously right decision and let’s be honest- we would be surprised if that one wasn’t.
So, taking into account obvious: yes, it was faster and yes, it utilized less resources, and yes, it reported lower CBO cost – although the latter does not seem to carry any meaning.
Therefore, whichever formula(s) was/were behind, the input and the final decision were consistent with the expectations.
So let’s construct less obvious scenario and make the Auto-SPM sweat a bit : )
Part 2.
Leave a Reply