While preparing the series of posts about Clustering Factor (aka CLUF in 10053 traces) I came across an interesting caveat which I decided to explore.
I will make an attempt to explain its matter, although I encourage you to reach out to the part3 of the mentioned series and navigate to “Quantifying physical reads for low CLUF” and treat it as an intro.
Nonetheless, here are the highlights.
While running my test query retrieving data from a table based on a tiny index range scan, I spotted certain – what I at first thought: anomaly – how Oracle handled this data retrieval.
In fact no anomaly and no mystery – the Oracle crew just proved they’re working with the good feeling of anticipation.
Actually, in the end, I even felt ashamed for not spotting it right away with certainty—”Wait, what are you even surprised about? Of course, they must have done that. Otherwise, you’d be jeopardizing your data quality!’
Such things are typically hidden until you dive deep down and.. to be true – you won’t be able to improve or boost any of your SQL after reading this post.
At least not directly.
It’s merely a tiny puzzle you can’t resist to explore and I won’t be surprised if an obvious fact catches your eye long before I will start drumroll announcing.. that obvious matter.
But let’s start from the beginning.
My test query was to get the data from a table based on accessing just a single index leaf block.
I dumped that leaf block so I knew which entry was the very last one (485) :
row#0[8020] flag: -------, lock: 0, len=12
col 0; len 2; (2): c1 02 --> SORTED_ID = 1 as decimal
col 1; len 6; (6): 11 71 ad d3 00 00
row#1[8008] flag: -------, lock: 0, len=12
col 0; len 2; (2): c1 03 --> SORTED_ID = 2 as decimal
col 1; len 6; (6): 11 71 ad d3 00 01
row#2[7996] flag: -------, lock: 0, len=12
col 0; len 2; (2): c1 04 --> SORTED_ID = 3 as decimal
col 1; len 6; (6): 11 71 ad d3 00 02
row#3[7984] flag: -------, lock: 0, len=12
col 0; len 2; (2): c1 05
col 1; len 6; (6): 11 71 ad d3 00 03
row#4[7972] flag: -------, lock: 0, len=12
col 0; len 2; (2): c1 06
col 1; len 6; (6): 11 71 ad d3 00 04
row#5[7960] flag: -------, lock: 0, len=12
col 0; len 2; (2): c1 07
col 1; len 6; (6): 11 71 ad d3 00 05
row#6[7948] flag: -------, lock: 0, len=12
col 0; len 2; (2): c1 08
col 1; len 6; (6): 11 71 ad d3 00 06
row#7[7936] flag: -------, lock: 0, len=12
col 0; len 2; (2): c1 09
col 1; len 6; (6): 11 71 ad d3 00 07
(…)
(…) - skipped ..
(…)
row#484[1830] flag: -------, lock: 0, len=13
col 0; len 3; (3): c2 05 56 --> Last entry in the leaf of ID_SORTED = 485 as decimal int
col 1; len 6; (6): 11 71 ad de 00 10
I then built the predicate: select * from T where col <= “that last entry”.
So, select * from TSTUS.TSCLUF where id_sorted <= 485 ;
I first flushed the buffer cache to force physical reads and executed my test query treating it with 10046 event accompanied by gathering autotrace stats.
I was obviously expecting certain amount of physical reads performed on behalf of two segments: the index and the table.
As far as the number of physical reads from the table matched my previous calculations,
surprisingly enough, I noticed one extra read performed on behalf of the index.
This is how I put it in that post :
I owe you yet another explanation considering :
“for one index block leaf read Oracle required 19 physical reads from this table” – and that’s something what puzzled me.
Wait – I dumped that very index leaf block and clearly saw it contained all 485 entries (ID_SORTED <= 485), so that 1 index block should be enough to be visited.
So why would I need 2 index leaf blocks?
Scroll up to the 10046 dump and see the 4 physical reads underneath the “Physical reads performed on behalf of index IDX_ID_SORTED (object_id = 181826)“
To be precise – in total: 4, but the first 2 can be accounted for the index root and index branch read.
So why 4 and not 3 ?
Best if I copy-paste the relevant excerpt with the hope it’ll be clear enough what I am trying to explain.
Here it is.
OBJECT SUBOBJECT_NAME OBJECT_ID DATA_OBJECT_ID OBJECT_TYPE
------------------------------------------------------------ ------------------------- ---------- -------------- ----------------
TSTUS.TSCLUF 181825 181825 TABLE
TSTUS.IDX_ID_SORTED 181826 181826 INDEX
SYS@CDBTST1->TPDB1> ALTER SESSION SET TRACEFILE_IDENTIFIER='&trfile_suffix';
Enter value for trfile_suffix: lowcluf
old 1: ALTER SESSION SET TRACEFILE_IDENTIFIER='&trfile_suffix'
new 1: ALTER SESSION SET TRACEFILE_IDENTIFIER='lowcluf'
Session altered.
SYS@CDBTST1->TPDB1>
INST_ID SID SERIAL# OSPID PID TRACEFILE
------- -------- ---------- ------------------------ -------- ----------------------------------------------------------------------------------------
1 2907 40588 187041 96 CDBTST1_ora_187041_lowcluf.trc
SYS@CDBTST1->TPDB1> exec dbms_monitor.session_trace_enable(session_id=>&sid_to_trace,serial_num=>&serial_to_trace,binds=>true,waits=>true);
Enter value for sid_to_trace: 2907
Enter value for serial_to_trace: 40588
SYS@CDBTST1->TPDB1> alter system flush buffer_cache ;
System altered.
SYS@CDBTST1->TPDB1> select /* &comm */ * from TSTUS.TSCLUF where id_sorted <= 485 ;
Enter value for comm: GOOD_CLUF
old 1: select /* &comm */ * from TSTUS.TSCLUF where id_sorted <= 485
new 1: select /* GOOD_CLUF */ * from TSTUS.TSCLUF where id_sorted <= 485
485 rows selected.
Elapsed: 00:00:00.02
Execution Plan
----------------------------------------------------------
Plan hash value: 4266397642
---------------------------------------------------------------------------------------------
| Id | Operation | Name | Rows | Bytes | Cost (%CPU)| Time |
---------------------------------------------------------------------------------------------
| 0 | SELECT STATEMENT | | 485 | 127K| 23 (0)| 00:00:01 |
| 1 | TABLE ACCESS BY INDEX ROWID| TSCLUF | 485 | 127K| 23 (0)| 00:00:01 |
|* 2 | INDEX RANGE SCAN | IDX_ID_SORTED | 485 | | 4 (0)| 00:00:01 |
---------------------------------------------------------------------------------------------
Predicate Information (identified by operation id):
---------------------------------------------------
2 - access("ID_SORTED"<=485)
Statistics
----------------------------------------------------------
1 recursive calls
0 db block gets
88 consistent gets
23 physical reads
0 redo size
143555 bytes sent via SQL*Net to client
784 bytes received via SQL*Net from client
34 SQL*Net roundtrips to/from client
0 sorts (memory)
0 sorts (disk)
485 rows processedThe dbms_monitor.session_trace_enable produced, what is widely known, the 10046 trace.
With that trace file at hand let’s get all physical reads:
So simple grepping the CDBTST1_ora_187041_lowcluf.trc reveals the following :
Physical reads performed on behalf of index IDX_ID_SORTED (object_id = 181826) :
[oracle @ CDBTST1 @ testhost01 ]$ # cat CDBTST1_ora_187041_lowcluf.trc | grep WAIT | grep physical | grep 181826
WAIT #140088361959968: nam='cell single block physical read: flash cache' ela= 867 cellhash#=3612651036 diskhash#=4260375198 bytes=8192 obj#=181826
WAIT #140088361959968: nam='cell single block physical read: flash cache' ela= 680 cellhash#=439186241 diskhash#=3459493587 bytes=8192 obj#=181826
WAIT #140088361959968: nam='cell single block physical read: flash cache' ela= 415 cellhash#=3612651036 diskhash#=4260375198 bytes=8192 obj#=181826
WAIT #140088361959968: nam='cell single block physical read: flash cache' ela= 333 cellhash#=3612651036 diskhash#=4260375198 bytes=8192 obj#=181826
Physical reads performed on behalf of table TSCLUF (object_id = 181825) :
[oracle @ CDBTST1 @ testhost01 ]$ # cat CDBTST1_ora_187041_lowcluf.trc | grep WAIT | grep physical | grep 181825
WAIT #140088361959968: nam='cell single block physical read: flash cache' ela= 779 cellhash#=1290911885 diskhash#=1644083320 bytes=8192 obj#=181825
WAIT #140088361959968: nam='cell single block physical read: flash cache' ela= 316 cellhash#=1290911885 diskhash#=1644083320 bytes=8192 obj#=181825
WAIT #140088361959968: nam='cell single block physical read: flash cache' ela= 262 cellhash#=1290911885 diskhash#=1644083320 bytes=8192 obj#=181825
WAIT #140088361959968: nam='cell single block physical read: flash cache' ela= 311 cellhash#=1290911885 diskhash#=1644083320 bytes=8192 obj#=181825
WAIT #140088361959968: nam='cell single block physical read: flash cache' ela= 233 cellhash#=1290911885 diskhash#=1644083320 bytes=8192 obj#=181825
WAIT #140088361959968: nam='cell single block physical read: flash cache' ela= 666 cellhash#=3018416126 diskhash#=3925360322 bytes=8192 obj#=181825
WAIT #140088361959968: nam='cell single block physical read: flash cache' ela= 263 cellhash#=3018416126 diskhash#=3925360322 bytes=8192 obj#=181825
WAIT #140088361959968: nam='cell single block physical read: flash cache' ela= 296 cellhash#=3018416126 diskhash#=3925360322 bytes=8192 obj#=181825
WAIT #140088361959968: nam='cell single block physical read: flash cache' ela= 178 cellhash#=3018416126 diskhash#=3925360322 bytes=8192 obj#=181825
WAIT #140088361959968: nam='cell single block physical read: flash cache' ela= 197 cellhash#=3018416126 diskhash#=3925360322 bytes=8192 obj#=181825
WAIT #140088361959968: nam='cell single block physical read: flash cache' ela= 196 cellhash#=3018416126 diskhash#=3925360322 bytes=8192 obj#=181825
WAIT #140088361959968: nam='cell single block physical read: flash cache' ela= 151 cellhash#=3018416126 diskhash#=3925360322 bytes=8192 obj#=181825
WAIT #140088361959968: nam='cell single block physical read: flash cache' ela= 171 cellhash#=3018416126 diskhash#=3925360322 bytes=8192 obj#=181825
WAIT #140088361959968: nam='cell single block physical read: flash cache' ela= 365 cellhash#=1290911885 diskhash#=1644083320 bytes=8192 obj#=181825
WAIT #140088361959968: nam='cell single block physical read: flash cache' ela= 282 cellhash#=1290911885 diskhash#=1644083320 bytes=8192 obj#=181825
WAIT #140088361959968: nam='cell single block physical read: flash cache' ela= 269 cellhash#=1290911885 diskhash#=1644083320 bytes=8192 obj#=181825
WAIT #140088361959968: nam='cell single block physical read: flash cache' ela= 311 cellhash#=1290911885 diskhash#=1644083320 bytes=8192 obj#=181825
WAIT #140088361959968: nam='cell single block physical read: flash cache' ela= 178 cellhash#=1290911885 diskhash#=1644083320 bytes=8192 obj#=181825
WAIT #140088361959968: nam='cell single block physical read: flash cache' ela= 200 cellhash#=1290911885 diskhash#=1644083320 bytes=8192 obj#=181825 I could afford to present the full content of the filtering – indeed, just 23 physical reads (see: Statistics), of which 19 were performed on behalf of the table: TSCLUF.
The reads from the table are less interesting though.
What’s interesting are the physical reads performed on behalf of the index :
[oracle @ CDBTST1 @ testhost01 ]$ # cat CDBTST1_ora_187041_lowcluf.trc | grep WAIT | grep physical | grep 181826 | wc -l
4Let us reach out to the raw 10046 trace file and dump the corresponding index blocks in order to examine their content. To dump that stuff I need file# and block# – easy to get them from the trace file.
Almost there.. But there is a problem to tackle though.
If I wasn’t running my test on the Exadata machine I would indeed get the file# and the block# directly from that 10046 dump.
The physical reads would be represented by WAIT “db file sequential read”, accompanied by the p1 (file#) and p2 (block#).
The p3 would surely be 1 as this certainly would be a single physical read.
You may btw. want to use that script to find out the meaning of p1,p2 and p3 parameters for a given wait/wait class :
col WAIT_CLASS form a30
select NAME,WAIT_CLASS,PARAMETER1,PARAMETER2,PARAMETER3
from V$EVENT_NAME
WHERE
upper(WAIT_CLASS) like upper(nvl('%&wait_class%',WAIT_CLASS))
AND
upper(NAME) like upper(nvl('%&event_name%',NAME))
order by WAIT_CLASS, NAME
/NAME WAIT_CLASS PARAMETER1 PARAMETER2 PARAMETER3
-------------------------------------------------- ------------------------------ ------------- ------------ ------------
db file sequential read User I/O file# block# blocksFor that matter, with Exadata’s 10046 traces there is a problem though.
Not only are many wait names renamed (let’s be fair: in many cases to more intuitive replacements), but with “User I/O” class their p1,p2,p3 parameters do not reflect the file and block numbers.
There are cellhash# and diskhash# available instead which obviously won’t help me much – how can I dump a block having cellhash and diskhash values?
Take a look at the four WAITs from the 10046 trace file (I have removed the tim sections) :
1.
WAIT #140657586095912: nam='cell single block physical read: flash cache' ela= 766 cellhash#=3612651036 diskhash#=4260375198 bytes=8192 obj#=181826
2.
WAIT #140657586095912: nam='cell single block physical read: flash cache' ela= 634 cellhash#=439186241 diskhash#=3459493587 bytes=8192 obj#=181826
3.
WAIT #140657586095912: nam='cell single block physical read: flash cache' ela= 348 cellhash#=3612651036 diskhash#=4260375198 bytes=8192 obj#=181826
4.
WAIT #140657586095912: nam='cell single block physical read: flash cache' ela= 356 cellhash#=3612651036 diskhash#=4260375198 bytes=8192 obj#=181826 With little digging there is a good workaround for that.
I came across the 10200 event (I mention 10200 because it’ll turn out is my hero) in Mauro’s blog.
There are many other sources explaining that problem, credit to Mauro though (actually, also to Stefan Möhler – if you scroll that blog and get to the end) – his article has the title which perfectly matches what I was looking for.
So let’s merge the outcome of 10046 and 10200 into one trace with that script :
cat tr10200.sql
-- 10200, 00000, "consistent read buffer status"
ALTER SESSION SET TRACEFILE_IDENTIFIER = '&trace_id';
ALTER SESSION SET EVENTS '10200 TRACE NAME CONTEXT FOREVER, LEVEL 1';
ALTER SESSION SET EVENTS '10046 TRACE NAME CONTEXT FOREVER, LEVEL 8';Here’s the entire prep. test :
20:13:19 SYS@CDBTST1->TPDB1> @fb
20:13:27 SYS@CDBTST1->TPDB1> alter system flush buffer_cache ;
System altered.
20:13:28 SYS@CDBTST1->TPDB1> @setts
20:13:34 SYS@CDBTST1->TPDB1> SET AUTOTRACE TRACE EXPLAIN STATISTICS
20:13:34 SYS@CDBTST1->TPDB1> @tr10200.sql
20:13:36 SYS@CDBTST1->TPDB1>
20:13:36 SYS@CDBTST1->TPDB1> -- 10200, 00000, "consistent read buffer status"
20:13:36 SYS@CDBTST1->TPDB1>
20:13:36 SYS@CDBTST1->TPDB1>
20:13:36 SYS@CDBTST1->TPDB1> ALTER SESSION SET TRACEFILE_IDENTIFIER = '&trace_id';
Enter value for trace_id: 10046_10200
old 1: ALTER SESSION SET TRACEFILE_IDENTIFIER = '&trace_id'
new 1: ALTER SESSION SET TRACEFILE_IDENTIFIER = '10046_10200'
Session altered.
Elapsed: 00:00:00.00
20:13:47 SYS@CDBTST1->TPDB1>
20:13:47 SYS@CDBTST1->TPDB1> ALTER SESSION SET EVENTS '10200 TRACE NAME CONTEXT FOREVER, LEVEL 1';
Session altered.
Elapsed: 00:00:00.00
20:13:47 SYS@CDBTST1->TPDB1> ALTER SESSION SET EVENTS '10046 TRACE NAME CONTEXT FOREVER, LEVEL 8';
Session altered.
20:13:50 SYS@CDBTST1->TPDB1> select * from TSTUS.TSCLUF where id_sorted <= 485
20:13:59 2 /
485 rows selected.
Elapsed: 00:00:00.04
Execution Plan
----------------------------------------------------------
Plan hash value: 4196823974
-----------------------------------------------------------------------------------------------------
| Id | Operation | Name | Rows | Bytes | Cost (%CPU)| Time |
-----------------------------------------------------------------------------------------------------
| 0 | SELECT STATEMENT | | 485 | 127K| 23 (0)| 00:00:01 |
| 1 | TABLE ACCESS BY INDEX ROWID BATCHED| TSCLUF | 485 | 127K| 23 (0)| 00:00:01 |
|* 2 | INDEX RANGE SCAN | IDX_ID_SORTED | 485 | | 4 (0)| 00:00:01 |
-----------------------------------------------------------------------------------------------------
Predicate Information (identified by operation id):
---------------------------------------------------
2 - access("ID_SORTED"<=485)
Statistics
----------------------------------------------------------
0 recursive calls
0 db block gets
88 consistent gets
23 physical reads
0 redo size
14486 bytes sent via SQL*Net to client
767 bytes received via SQL*Net from client
34 SQL*Net roundtrips to/from client
0 sorts (memory)
0 sorts (disk)
485 rows processedHaving at hand the CDBTST1_ora_238551_10046_10200.trc and grepping after 181826 (index object_id) here is what I came up with (re-edited).
The pairs in brackets are the (file#/block#).
WAIT #139732863711760: nam='cell single block physical read: flash cache' ela= 2612 cellhash#=3612651036 diskhash#=4260375198 bytes=8192 obj#=181826 tim=60943189337838
id1: 0x2e80bb id2: 0x44 pkey: OBJ#3,8,181826 block: (68/3047611)
WAIT #139732863711760: nam='cell single block physical read: flash cache' ela= 708 cellhash#=439186241 diskhash#=3459493587 bytes=8192 obj#=181826 tim=60943189339618
id1: 0x218836 id2: 0x31 pkey: OBJ#3,8,181826 block: (49/2197558)
WAIT #139732863711760: nam='cell single block physical read: flash cache' ela= 850 cellhash#=3612651036 diskhash#=4260375198 bytes=8192 obj#=181826 tim=60943189341362
id1: 0x2e80bc id2: 0x44 pkey: OBJ#3,8,181826 block: (68/3047612)
WAIT #139732863711760: nam='cell single block physical read: flash cache' ela= 365 cellhash#=3612651036 diskhash#=4260375198 bytes=8192 obj#=181826 tim=60943189372959
id1: 0x2e80bd id2: 0x44 pkey: OBJ#3,8,181826 block: (68/3047613)
Having utilized 10200 traces, many blogs reach out to the c-function : ktrgtc in order to find the file# and block# as shown below.
Oracle C functions annotations (orafun.info) gives the following matching :
(ktrgtc)2 – kernel transaction read consistency get a read consistent block and call back client ??
I was lucky enough to carry out my tests on Oracle 19 (I believe other articles may refer to earlier versions, i.e. Oracle 11g/12c).
Apparently, from Oracle 19c onwards there is no need to apply the following hex-to-integer conversion, whose outcome needs to be then supplied to dbms_utility.data_block_address_file and dbms_utility.data_block_address_block.
I will run that example conversion just in case – that is, if you decided to re-run that test on your own and your RDBMS version is 11g/12c (or perhaps I am simply wrong mentioning ver.19c as an easy solution).
On top, it’d have to be executed on Exadata, so we are talking about nearly impossible circumstances.
Anyway, referring to c-function seems always safe, as it’ll supposed be always present in the trace (it was in mine too).
So, here it is :
corresponding section from the 10046 and 10200 (merge) :
ktrgtc2(): started for block <0x0008 : 0x112e80bb> objd: 0x0002c642
WAIT #140657586095912: nam='cell single block physical read: flash cache' ela= 766 cellhash#=3612651036 diskhash#=4260375198 bytes=8192 obj#=181826 tim=49634500072402
14:59:37 SYS@CDBTST1->TPDB1> @hex2int
Enter value for hex_value: 112e80bb
old 2: ( select TO_NUMBER( replace('&hex_value',chr(32),'') , 'xxxxxxxxxxxxxxxxxx') n from dual )
new 2: ( select TO_NUMBER( replace('112e80bb',chr(32),'') , 'xxxxxxxxxxxxxxxxxx') n from dual )
N
--------------------------------------------------
288260283
Elapsed: 00:00:00.00
15:00:10 SYS@CDBTST1->TPDB1>
15:00:11 SYS@CDBTST1->TPDB1> @ls_file_block_dbms_utility.sql
Enter value for dba: 288260283
old 1: SELECT dbms_utility.data_block_address_file(&&dba) file_n,
new 1: SELECT dbms_utility.data_block_address_file(288260283) file_n,
old 2: dbms_utility.data_block_address_block(&&dba) block_n
new 2: dbms_utility.data_block_address_block(288260283) block_n
FILE_N BLOCK_N
-------------------------------------------------- --------------------------------------------------
68 3047611Coming back to the main topic now.
I have these four blocks to check :
block: (68/3047611)
block: (49/2197558)
block: (68/3047612)
block: (68/3047613)
So, dumping these four blocks revealed the following.
1. First, I dumped this (file#/block#) : (68/3047611)
WAIT #139732863711760: nam=’cell single block physical read: flash cache’ ela= 2612 cellhash#=3612651036 diskhash#=4260375198 bytes=8192 obj#=181826 tim=60943189337838
id1: 0x2e80bb id2: 0x44 pkey: OBJ#3,8,181826 block: (68/3047611)cat dbl.sql
alter session set tracefile_identifier = ‘&trace_file_string’ ;
alter system dump datafile &file block &block ;Then I navigated to the section right below the entry specifying the Itl (interested transaction list) which clearly describes the function of that block.
This is surely the root index block, even though named “branch”.
Fine, expected. It does not help us yet though.
Branch block dump
=================
header address 140167999897676=0x7f7b67d7c04c
kdxcolev 2
KDXCOLEV Flags = - - -
kdxcolok 0
kdxcoopc 0x80: opcode=0: iot flags=--- is converted=Y
kdxconco 2
kdxcosdc 0
kdxconro 37
kdxcofbo 102=0x66
kdxcofeo 7652=0x1de4
kdxcoavs 7550
kdxbrlmc 207718454=0xc618836
kdxbrsno 0
kdxbrbksz 8056
kdxbr2urrc 02. Then, I dumped this (file#/block#) : (49/2197558)
WAIT #139732863711760: nam=’cell single block physical read: flash cache’ ela= 708 cellhash#=439186241 diskhash#=3459493587 bytes=8192 obj#=181826 tim=60943189339618
id1: 0x218836 id2: 0x31 pkey: OBJ#3,8,181826 block: (49/2197558)Again, the (true) branch index block.
Still, it does not explain anything, apart of being the confirmation that the second read refers to the index branch block :
Branch block dump
=================
header address 140018656501836=0x7f58a248604c
kdxcolev 1
KDXCOLEV Flags = - - -
kdxcolok 0
kdxcoopc 0x80: opcode=0: iot flags=--- is converted=Y
kdxconco 2
kdxcosdc 0
kdxconro 671
kdxcofbo 1370=0x55a
kdxcofeo 1372=0x55c
kdxcoavs 2
kdxbrlmc 288260284=0x112e80bc
kdxbrsno 0
kdxbrbksz 8056
kdxbr2urrc 0
3. Subsequently, I dumped this (file#/block#) : (68/3047612)
And it’s getting interesting..
WAIT #139732863711760: nam=’cell single block physical read: flash cache’ ela= 850 cellhash#=3612651036 diskhash#=4260375198 bytes=8192 obj#=181826 tim=60943189341362
id1: 0x2e80bc id2: 0x44 pkey: OBJ#3,8,181826 block: (68/3047612)It’s the leaf block – so containing real indexed keys (values).
Leaf block dump
===============
header address 140691569573988=0x7ff54f070064
kdxcolev 0
KDXCOLEV Flags = - - -
kdxcolok 0
kdxcoopc 0x80: opcode=0: iot flags=--- is converted=Y
kdxconco 2
kdxcosdc 0
kdxconro 485
kdxcofbo 1006=0x3ee
kdxcofeo 1830=0x726
kdxcoavs 824
kdxlespl 0
kdxlende 0
kdxlenxt 288260285=0x112e80bd
kdxleprv 0=0x0
kdxledsz 0
kdxlebksz 8032
row#0[8020] flag: -------, lock: 0, len=12
col 0; len 2; (2): c1 02
col 1; len 6; (6): 11 71 ad d3 00 00
row#1[8008] flag: -------, lock: 0, len=12
col 0; len 2; (2): c1 03
col 1; len 6; (6): 11 71 ad d3 00 01
row#2[7996] flag: -------, lock: 0, len=12
col 0; len 2; (2): c1 04
col 1; len 6; (6): 11 71 ad d3 00 02
row#3[7984] flag: -------, lock: 0, len=12
(…)
(…)
row#484[1830] flag: -------, lock: 0, len=13 -> LAST ENTRY!
col 0; len 3; (3): c2 05 56
col 1; len 6; (6): 11 71 ad de 00 10So the last entry represents the indexed value (integer): 485.
Quick check :
SQL> select dump(485,16) from dual ;
DUMP(485,16)
--------------------
Typ=2 Len=3: c2,5,56If you recall the predicate in the SQL :
select * from TSTUS.TSCLUF where id_sorted <= 485
So, the last entry from the index leaf block covers the upper bound (very last value) of this range scan.
But Oracle doesn’t know whether there is indeed only one such value = 485, so it needs to check the next (logically adjacent) index leaf block.
Therefore we can observe another (possibly redundant) physical read.Let’s verify that and let’s end up with the range scan at the last before last entry value, that is: 484.
Applying this trick I’ll leave Oracle the chance to jump and read the very last entry, i.e. 485 within the same block.
With that knowledge and also “being aware” that index segment is a sorted structure, the execution does not have to check the next leaf since (I believe my theory sounds about right) it would have established there is no need to reach even further.
Let’s check it.
21:31:17 SYS@CDBTST1->TPDB1> @fb
21:31:19 SYS@CDBTST1->TPDB1> alter system flush buffer_cache ;
System altered.
Elapsed: 00:00:00.19
21:31:19 SYS@CDBTST1->TPDB1> set echo off
21:31:19 SYS@CDBTST1->TPDB1> @mysid
INST_ID SID SERIAL# OSPID PID TRACEFILE
------- ----------- ------- ---------- ---------- ------------------------------------
1 739 487 15040 294 CDBTST1_ora_15040.trc
Elapsed: 00:00:00.03
21:31:52 SYS@CDBTST1->TPDB1> @tr
21:32:26 SYS@CDBTST1->TPDB1> exec dbms_monitor.session_trace_enable(session_id=>&sid_to_trace,serial_num=>&serial_to_trace,binds=>true,waits=>true);
Enter value for sid_to_trace: 739
Enter value for serial_to_trace: 487
PL/SQL procedure successfully completed.
Elapsed: 00:00:00.01
21:32:34 SYS@CDBTST1->TPDB1> set echo off
21:32:34 SYS@CDBTST1->TPDB1> @setts
21:32:45 SYS@CDBTST1->TPDB1> SET AUTOTRACE TRACE EXPLAIN STATISTICS
21:32:46 SYS@CDBTST1->TPDB1> select * from TSTUS.TSCLUF where id_sorted <= 484 ;
484 rows selected.
Elapsed: 00:00:00.03
Execution Plan
----------------------------------------------------------
Plan hash value: 4196823974
-----------------------------------------------------------------------------------------------------
| Id | Operation | Name | Rows | Bytes | Cost (%CPU)| Time |
-----------------------------------------------------------------------------------------------------
| 0 | SELECT STATEMENT | | 484 | 127K| 23 (0)| 00:00:01 |
| 1 | TABLE ACCESS BY INDEX ROWID BATCHED| TSCLUF | 484 | 127K| 23 (0)| 00:00:01 |
|* 2 | INDEX RANGE SCAN | IDX_ID_SORTED | 484 | | 4 (0)| 00:00:01 |
-----------------------------------------------------------------------------------------------------
Predicate Information (identified by operation id):
---------------------------------------------------
2 - access("ID_SORTED"<=484)
Statistics
----------------------------------------------------------
0 recursive calls
0 db block gets
87 consistent gets
22 physical reads
0 redo size
14471 bytes sent via SQL*Net to client
765 bytes received via SQL*Net from client
34 SQL*Net roundtrips to/from client
0 sorts (memory)
0 sorts (disk)
484 rows processedAh, look at that – alone the “Statistics” section looks like a good promise: 22 physical reads (not 23 as before).
So should that 1 physical read difference be accounted to the lack of that “checking read” ?
Indeed, having examined the 10046 trace I encountered just 3 physical reads (not 4) on behalf of the index segment :
[oracle @ testhost]$ # cat CDBTST1_ora_15040.trc | grep 181826 | grep physi
1.
WAIT #139857063831128: nam='cell single block physical read: flash cache' ela= 2196 cellhash#=3612651036 diskhash#=4260375198 bytes=8192 obj#=181826 tim=60962320205834
2.
WAIT #139857063831128: nam='cell single block physical read: flash cache' ela= 2037 cellhash#=439186241 diskhash#=3459493587 bytes=8192 obj#=181826 tim=60962320208293
3.
WAIT #139857063831128: nam='cell single block physical read: flash cache' ela= 295 cellhash#=3612651036 diskhash#=4260375198 bytes=8192 obj#=181826 tim=609623202088224. Lastly, I dumped this (file#/block#) : (68/3047613)
block: (68/3047611)
block: (49/2197558)
block: (68/3047612)
–> block: (68/3047613)
You may remember: this read was the last (checking?) physical read.
So, I dumped the last block in the sequence of all physical reads which is associated with this entry in the 10046 trace:
WAIT #139732863711760: nam=’cell single block physical read: flash cache’ ela= 365 cellhash#=3612651036 diskhash#=4260375198 bytes=8192 obj#=181826 tim=60943189372959
id1: 0x2e80bd id2: 0x44 pkey: OBJ#3,8,181826 block: (68/3047613)It’s again the leaf block :
Leaf block dump
===============
header address 140114805588068=0x7f6f05370064
kdxcolev 0
KDXCOLEV Flags = - - -
kdxcolok 0
kdxcoopc 0x80: opcode=0: iot flags=--- is converted=Y
kdxconco 2
kdxcosdc 0
kdxconro 479
kdxcofbo 994=0x3e2
kdxcofeo 1810=0x712
kdxcoavs 816
kdxlespl 0
kdxlende 0
kdxlenxt 288260286=0x112e80be
kdxleprv 288260284=0x112e80bc
kdxledsz 0
kdxlebksz 8032
row#0[8019] flag: -------, lock: 0, len=13
col 0; len 3; (3): c2 05 57 --> First entry of the subsequent leaf block following the row#484[1830] from the previous block.
col 1; len 6; (6): 11 71 ad de 00 11This looks to me confirmation enough that this read is the “checking read”.
Oracle has clearly reached out to the block which does not contain any entry fulfilling the predicate. So most certainly it has read the first indexed entry (c2 05 57) and didn’t even traverse the remainder of that leaf block.
Recall: the previous logical entry was located in other physical block :
row#484[1830] flag: -------, lock: 0, len=13 --> LAST ENTRY!
col 0; len 3; (3): c2 05 56
There are two more “gotchas” on that.
First “gotcha” – the sequence of reads
First, if you look at the order of all involved physical reads you will spot (this was my case) that this “checking read” was performed at the very end of the sequence of all physical reads.
That is, after visiting the first 3 index blocks, then subsequently following retrieving the corresponding blocks from the table, that “checking read” was performed as the very last resort (see the numbering and the whole excerpt limited to physical reads. I have removed the “tim” sections for better readibility) :
[oracle @ testhost ]$ # cat -n CDBTST1_ora_148205.trc | grep physi | egrep '181826'
69 WAIT #140145365202312: nam='cell single block physical read: flash cache' ela= 2305 cellhash#=3612651036 diskhash#=4260375198 bytes=8192 obj#=181826
73 WAIT #140145365202312: nam='cell single block physical read: flash cache' ela= 713 cellhash#=439186241 diskhash#=3459493587 bytes=8192 obj#=181826
75 WAIT #140145365202312: nam='cell single block physical read: flash cache' ela= 318 cellhash#=3612651036 diskhash#=4260375198 bytes=8192 obj#=181826
217 WAIT #140145365202312: nam='cell single block physical read: flash cache' ela= 393 cellhash#=3612651036 diskhash#=4260375198 bytes=8192 obj#=181826 [oracle @ testhost ]$ # cat -n CDBTST1_ora_148205.trc | grep physi | egrep '181825|181826'
INDEX: (see: obj#=181826)
69 WAIT #140145365202312: nam='cell single block physical read: flash cache' ela= 2305 cellhash#=3612651036 diskhash#=4260375198 bytes=8192 obj#=181826
73 WAIT #140145365202312: nam='cell single block physical read: flash cache' ela= 713 cellhash#=439186241 diskhash#=3459493587 bytes=8192 obj#=181826
75 WAIT #140145365202312: nam='cell single block physical read: flash cache' ela= 318 cellhash#=3612651036 diskhash#=4260375198 bytes=8192 obj#=181826
TABLE: (see: obj#=181825)
78 WAIT #140145365202312: nam='cell single block physical read: flash cache' ela= 683 cellhash#=1290911885 diskhash#=1644083320 bytes=8192 obj#=181825
86 WAIT #140145365202312: nam='cell single block physical read: flash cache' ela= 321 cellhash#=1290911885 diskhash#=1644083320 bytes=8192 obj#=181825
95 WAIT #140145365202312: nam='cell single block physical read: flash cache' ela= 390 cellhash#=1290911885 diskhash#=1644083320 bytes=8192 obj#=181825
103 WAIT #140145365202312: nam='cell single block physical read: flash cache' ela= 276 cellhash#=1290911885 diskhash#=1644083320 bytes=8192 obj#=181825
108 WAIT #140145365202312: nam='cell single block physical read: flash cache' ela= 217 cellhash#=1290911885 diskhash#=1644083320 bytes=8192 obj#=181825
117 WAIT #140145365202312: nam='cell single block physical read: flash cache' ela= 1995 cellhash#=3018416126 diskhash#=3925360322 bytes=8192 obj#=181825
125 WAIT #140145365202312: nam='cell single block physical read: flash cache' ela= 300 cellhash#=3018416126 diskhash#=3925360322 bytes=8192 obj#=181825
133 WAIT #140145365202312: nam='cell single block physical read: flash cache' ela= 223 cellhash#=3018416126 diskhash#=3925360322 bytes=8192 obj#=181825
138 WAIT #140145365202312: nam='cell single block physical read: flash cache' ela= 178 cellhash#=3018416126 diskhash#=3925360322 bytes=8192 obj#=181825
146 WAIT #140145365202312: nam='cell single block physical read: flash cache' ela= 177 cellhash#=3018416126 diskhash#=3925360322 bytes=8192 obj#=181825
154 WAIT #140145365202312: nam='cell single block physical read: flash cache' ela= 191 cellhash#=3018416126 diskhash#=3925360322 bytes=8192 obj#=181825
161 WAIT #140145365202312: nam='cell single block physical read: flash cache' ela= 176 cellhash#=3018416126 diskhash#=3925360322 bytes=8192 obj#=181825
167 WAIT #140145365202312: nam='cell single block physical read: flash cache' ela= 174 cellhash#=3018416126 diskhash#=3925360322 bytes=8192 obj#=181825
175 WAIT #140145365202312: nam='cell single block physical read: flash cache' ela= 416 cellhash#=1290911885 diskhash#=1644083320 bytes=8192 obj#=181825
183 WAIT #140145365202312: nam='cell single block physical read: flash cache' ela= 369 cellhash#=1290911885 diskhash#=1644083320 bytes=8192 obj#=181825
188 WAIT #140145365202312: nam='cell single block physical read: flash cache' ela= 304 cellhash#=1290911885 diskhash#=1644083320 bytes=8192 obj#=181825
196 WAIT #140145365202312: nam='cell single block physical read: flash cache' ela= 340 cellhash#=1290911885 diskhash#=1644083320 bytes=8192 obj#=181825
204 WAIT #140145365202312: nam='cell single block physical read: flash cache' ela= 198 cellhash#=1290911885 diskhash#=1644083320 bytes=8192 obj#=181825
212 WAIT #140145365202312: nam='cell single block physical read: flash cache' ela= 223 cellhash#=1290911885 diskhash#=1644083320 bytes=8192 obj#=181825
INDEX (again) – checking read : (see: obj#=181826 again)
217 WAIT #140145365202312: nam='cell single block physical read: flash cache' ela= 393 cellhash#=3612651036 diskhash#=4260375198 bytes=8192 obj#=181826Second “gotcha” – unique index
I thought that creating that index as unique (because these indexed values were indeed unique, although CBO stats do not reflect that) and reaching out to the very last entry value within the index leaf block will save that checking read.
No, it didn’t, although now there is enough information not to do it.
Obviously, the gain would be negligible – all in all we’d save just one physical single block read. Apparently, Oracle team would have to change some excerpt of C-code in order to introduce this (tiny) improvement, or perhaps even sacrifice another I/O to establish the facts.
Tiny in-word.
This is not directly related, but being that far I made myself yet additional small effort and traced the CBO decisions as the SQL Plan clearly reports the cost of INDEX RANGE SCAN = 4.
I created the copy of my test table and put the unique index on it.
SQL> create table TSTUS.TSCLUF_COPY as select * from TSTUS.TSCLUF
16:00:19 2 /
Table created.
SQL> create unique index TSTUS.IDX_ID_SORTED_UQ on TSTUS.TSCLUF_COPY ( ID_SORTED ) ;
Index created.
If you dump the CBO decisions to trace (10053) and apply the formula of calculating the cost of index access:
Index_LVL + CEIL( #LB * ix_sel )
this is what you’re about to discover.
First, certain prerequisites.
The same way as above, I managed to establish the file# and block# which contains the first index leaf and continued with the test.
The value: 520 is the last indexed entry in the first index leaf block.
Here it is :
SYS@CDBTST1->TPDB1> alter system dump datafile &file block &block ;
Enter value for file: 75
Enter value for block: 311229
old 1: alter system dump datafile &file block &block
new 1: alter system dump datafile 75 block 311229
System altered.
Itl Xid Uba Flag Lck Scn/Fsc
0x01 0x0000.000.00000000 0x00000000.0000.00 ---- 0 fsc 0x0000.00000000
0x02 0xffff.000.00000000 0x00000000.0000.00 C--- 0 scn 0x00000000d8a1f3fd
Leaf block dump
===============
header address 6767681636=0x19362a064
kdxcolev 0
KDXCOLEV Flags = - - -
kdxcolok 0
kdxcoopc 0x80: opcode=0: iot flags=--- is converted=Y
kdxconco 1
kdxcosdc 0
kdxconro 520
kdxcofbo 1076=0x434
kdxcofeo 1896=0x768
kdxcoavs 820
kdxlespl 0
kdxlende 0
kdxlenxt 314884030=0x12c4bfbe
kdxleprv 0=0x0
kdxledsz 6
kdxlebksz 8032
row#0[8021] flag: -------, lock: 0, len=11, data:(6): 0a e7 c9 3b 00 00
col 0; len 2; (2): c1 02
row#1[8010] flag: -------, lock: 0, len=11, data:(6): 0a e7 c9 3b 00 01
col 0; len 2; (2): c1 03
row#2[7999] flag: -------, lock: 0, len=11, data:(6): 0a e7 c9 3b 00 02
col 0; len 2; (2): c1 04
row#3[7988] flag: -------, lock: 0, len=11, data:(6): 0a e7 c9 3b 00 03
col 0; len 2; (2): c1 05
(…)
(…)
row#517[1920] flag: -------, lock: 0, len=12, data:(6): 0a e7 c9 3a 00 17
col 0; len 3; (3): c2 06 13
row#518[1908] flag: -------, lock: 0, len=12, data:(6): 0a e7 c9 3a 00 18
col 0; len 3; (3): c2 06 14
row#519[1896] flag: -------, lock: 0, len=12, data:(6): 0a e7 c9 3a 00 19
col 0; len 3; (3): c2 06 15 --> the last entry in the first leaf block
-- indeed :
SYS@CDBTST1->TPDB1> select dump(520,16) from dual ;
DUMP(520,16)
--------------------
Typ=2 Len=3: c2,6,15
First, dump of 10053 (CBO dump) :
20:53:43 SYS@CDBTST1->PDBTST> @mysid
INST_ID SID SERIAL# OSPID PID TRACEFILE
------- ----------- ------- ---------- ---------- --------------------------------------------------------
1 2426 8252 188193 272 CDBTST1_ora_188193.trc
20:53:49 SYS@CDBTST1->PDBTST> @setts
20:53:52 SYS@CDBTST1->PDBTST> SET AUTOTRACE TRACE EXPLAIN STATISTICS
20:53:53 SYS@CDBTST1->PDBTST> @tr10053
20:53:57 SYS@CDBTST1->PDBTST> set timing on
20:53:57 SYS@CDBTST1->PDBTST> ALTER SESSION SET TRACEFILE_IDENTIFIER='&file_identifier';
Enter value for file_identifier: chkcost
old 1: ALTER SESSION SET TRACEFILE_IDENTIFIER='&file_identifier'
new 1: ALTER SESSION SET TRACEFILE_IDENTIFIER='chkcost'
Session altered.
20:54:00 SYS@CDBTST1->PDBTST> alter session set events '10053 trace name context forever, level 1';
Session altered.
20:54:02 SYS@ CDBTST1->PDBTST> select /* &comm */ * from TSTUS.TSCLUF_COPY where ID_SORTED <= 520 ;
Enter value for comm: chkcost
old 1: select /* &comm */ * from TSTUS.TSCLUF_COPY where ID_SORTED <= 520
new 1: select /* chkcost */ * from TSTUS.TSCLUF_COPY where ID_SORTED <= 520
520 rows selected.
Elapsed: 00:00:00.07
Execution Plan
----------------------------------------------------------
Plan hash value: 4243688216
--------------------------------------------------------------------------------------------------------
| Id | Operation | Name | Rows | Bytes | Cost (%CPU)| Time |
--------------------------------------------------------------------------------------------------------
| 0 | SELECT STATEMENT | | 520 | 136K| 25 (0)| 00:00:01 |
| 1 | TABLE ACCESS BY INDEX ROWID BATCHED| TSCLUF_COPY | 520 | 136K| 25 (0)| 00:00:01 |
|* 2 | INDEX RANGE SCAN | IDX_ID_SORTED_UQ | 520 | | 4 (0)| 00:00:01 |
--------------------------------------------------------------------------------------------------------
Predicate Information (identified by operation id):
---------------------------------------------------
2 - access("ID_SORTED"<=520)
Statistics
----------------------------------------------------------
1 recursive calls
0 db block gets
93 consistent gets
24 physical reads
0 redo size
153808 bytes sent via SQL*Net to client
808 bytes received via SQL*Net from client
36 SQL*Net roundtrips to/from client
0 sorts (memory)
0 sorts (disk)
520 rows processedExcerpt of the 10053 dump (relevant entries are marked red) :
Index Stats::
Index: IDX_ID_SORTED_UQ Col#: 1
LVLS: 2 #LB: 20122 #DK: 10000000 LB/K: 1.00 DB/K: 1.00 CLUF: 385177.00 NRW: 10000000.00 SSZ: 0.00 LGR: 0.00 CBK: 0.00 GQL: 0.00 CHR: 0.00 KQDFLG: 8192 BSZ: 1
****** Costing Index IDX_ID_SORTED_UQ
SPD: Return code in qosdDSDirSetup: NOCTX, estType = INDEX_SCAN
SPD: Return code in qosdDSDirSetup: NOCTX, estType = INDEX_FILTER
Estimated selectivity: 5.2000e-05 , col: #1
Access Path: index (RangeScan)
Index: IDX_ID_SORTED_UQ
resc_io: 25.000000 resc_cpu: 381226
ix_sel: 5.2000e-05 ix_sel_with_filters: 5.2000e-05
Cost: 25.010166 Resp: 25.010166 Degree: 1
Best:: AccessPath: IndexRange
Index: IDX_ID_SORTED_UQ
Cost: 25.010166 Degree: 1 Resp: 25.010166 Card: 520.000052 Bytes: 0.000000Reminder:
cost of index access: Index_LVL + CEIL( #LB * ix_sel )
Quick math :
SQL> SELECT TO_CHAR(&scientific_notation_number) FROM DUAL;
Enter value for scientific_notation_number: 5.2000e-05
old 1: SELECT TO_CHAR(&scientific_notation_number) FROM DUAL
new 1: SELECT TO_CHAR(5.2000e-05) FROM DUAL
TO_CHAR
-------
.000052
SQL> !bc
bc 1.06.95
Copyright 1991-1994, 1997, 1998, 2000, 2004, 2006 Free Software Foundation, Inc.
This is free software with ABSOLUTELY NO WARRANTY.
For details type `warranty'.
scale=10
2 + (20122*.000052)
3.046344 -> cost of accessing the index (only index, no table cost involved here)So 4 is the result of 2 (index level) + “rounding up” the 1.046344 (ceil).
This is btw. what CBO typically seems to be doing, namely, it does not truncate the floating numbers but “bumps them up”, rounding them up to the nearest integer.
Word of caution: the Cost: 25.010166 reported in the 10053 under the ****** Costing Index IDX_ID_SORTED_UQ is the accumulated cost encompassing accessing the index and and the table for the calculated index range scan (details explained here).
One more test.
I will finally merge the 10046 and 10200 into one trace dump for sake of the test with the unique index and “the last entry” test.
With that at hand I will do the same style of grepping in order to ultimately find out that even the UNIQUE index won’t give me this 1 extra read saving.
The sequence of test-steps is identical as above.
cat tr10200.sql
-- 10200, 00000, "consistent read buffer status"
ALTER SESSION SET TRACEFILE_IDENTIFIER = '&trace_id';
ALTER SESSION SET EVENTS '10200 TRACE NAME CONTEXT FOREVER, LEVEL 1';
ALTER SESSION SET EVENTS '10046 TRACE NAME CONTEXT FOREVER, LEVEL 8';SQL> @tr10200
Enter value for trace_id: unique_index
old 1: ALTER SESSION SET TRACEFILE_IDENTIFIER = '&trace_id'
new 1: ALTER SESSION SET TRACEFILE_IDENTIFIER = 'unique_index'
Session altered.
Session altered.
Session altered.
20:54:02 SYS@ CDBTST1->PDBTST> select /* &comm */ * from TSTUS.TSCLUF_COPY where ID_SORTED <= 520 ;
Enter value for comm: chkcost
old 1: select /* &comm */ * from TSTUS.TSCLUF_COPY where ID_SORTED <= 520
new 1: select /* chkcost */ * from TSTUS.TSCLUF_COPY where ID_SORTED <= 520
520 rows selected.
Elapsed: 00:00:00.07
Execution Plan
----------------------------------------------------------
Plan hash value: 4243688216
--------------------------------------------------------------------------------------------------------
| Id | Operation | Name | Rows | Bytes | Cost (%CPU)| Time |
--------------------------------------------------------------------------------------------------------
| 0 | SELECT STATEMENT | | 520 | 136K| 25 (0)| 00:00:01 |
| 1 | TABLE ACCESS BY INDEX ROWID BATCHED| TSCLUF_COPY | 520 | 136K| 25 (0)| 00:00:01 |
|* 2 | INDEX RANGE SCAN | IDX_ID_SORTED_UQ | 520 | | 4 (0)| 00:00:01 |
--------------------------------------------------------------------------------------------------------
Predicate Information (identified by operation id):
---------------------------------------------------
2 - access("ID_SORTED"<=520)
Statistics
----------------------------------------------------------
1 recursive calls
0 db block gets
93 consistent gets
24 physical reads
0 redo size
153808 bytes sent via SQL*Net to client
808 bytes received via SQL*Net from client
36 SQL*Net roundtrips to/from client
0 sorts (memory)
0 sorts (disk)
520 rows processedOBJECT OBJECT_ID DATA_OBJECT_ID OBJECT_TYPE
------------------------ ---------- -------------- --------------------
TSTUS.TSCLUF_COPY 203686 203686 TABLE
TSTUS.IDX_ID_SORTED_UQ 203687 203687 INDEX Clearly, 4 index reads with the last one as the “check read” :
[oracle @ testhost ]$ # cat CDBTST1_ora_282554_IDX_UQ.trc | grep 203687 | grep -A 2 physical
WAIT #140349485564640: nam='cell single block physical read: flash cache' ela= 917 cellhash#=4259318641 diskhash#=4277551782 bytes=8192 obj#=203687 tim=60961571989589
dbwrid: 4 obj: 203687 objn: 203687 tsn: [3/8] afn: 75 hint: f
id1: 0x4bfbc id2: 0x4b pkey: OBJ#3,8,203687 block: (75/311228)
--
WAIT #140349485564640: nam='cell single block physical read: flash cache' ela= 725 cellhash#=1290911885 diskhash#=3783142219 bytes=8192 obj#=203687 tim=60961571991610
dbwrid: 6 obj: 203687 objn: 203687 tsn: [3/8] afn: 44 hint: f
id1: 0x15d973 id2: 0x2c pkey: OBJ#3,8,203687 block: (44/1431923)
--
WAIT #140349485564640: nam='cell single block physical read: flash cache' ela= 361 cellhash#=4259318641 diskhash#=4277551782 bytes=8192 obj#=203687 tim=60961571992901
dbwrid: 0 obj: 203687 objn: 203687 tsn: [3/8] afn: 75 hint: f
id1: 0x4bfbd id2: 0x4b pkey: OBJ#3,8,203687 block: (75/311229)
--
WAIT #140349485564640: nam='cell single block physical read: flash cache' ela= 362 cellhash#=4259318641 diskhash#=4277551782 bytes=8192 obj#=203687 tim=60961572028870
dbwrid: 2 obj: 203687 objn: 203687 tsn: [3/8] afn: 75 hint: f
id1: 0x4bfbe id2: 0x4b pkey: OBJ#3,8,203687 block: (75/311230)Let’s dump the last file#/block# :
SQL> alter session set tracefile_identifier = '&trace_file_string' ;
Enter value for trace_file_string: 4th_idx_read
old 1: alter session set tracefile_identifier = '&trace_file_string'
new 1: alter session set tracefile_identifier = '4th_idx_read'
Session altered.
SQL> alter system dump datafile &file block &block ;
Enter value for file: 75
Enter value for block: 311230
old 1: alter system dump datafile &file block &block
new 1: alter system dump datafile 75 block 311230
System altered.
Itl Xid Uba Flag Lck Scn/Fsc
0x01 0x0000.000.00000000 0x00000000.0000.00 ---- 0 fsc 0x0000.00000000
0x02 0xffff.000.00000000 0x00000000.0000.00 C--- 0 scn 0x00000000d8a1f3fd
Leaf block dump
===============
header address 14683414628=0x36b332064
kdxcolev 0
KDXCOLEV Flags = - - -
kdxcolok 0
kdxcoopc 0x80: opcode=0: iot flags=--- is converted=Y
kdxconco 1
kdxcosdc 0
kdxconro 513
kdxcofbo 1062=0x426
kdxcofeo 1881=0x759
kdxcoavs 819
kdxlespl 0
kdxlende 0
kdxlenxt 314884031=0x12c4bfbf
kdxleprv 314884029=0x12c4bfbd
kdxledsz 6
kdxlebksz 8032
row#0[8020] flag: -------, lock: 0, len=12, data:(6): 12 84 e0 56 00 00
col 0; len 3; (3): c2 06 16 --> 521
row#1[8008] flag: -------, lock: 0, len=12, data:(6): 12 84 e0 56 00 01
col 0; len 3; (3): c2 06 17
row#2[7996] flag: -------, lock: 0, len=12, data:(6): 12 84 e0 56 00 02
col 0; len 3; (3): c2 06 18You may remember that the previous leaf ended up with the entry representing: 520.
So – yes, it clearly reached out to the next logically adjacent block, although this time (due to uniqueness) it didn’t have to.
Recall: the previous entry which was indeed useful was this one :
row#519[1896] flag: -------, lock: 0, len=12, data:(6): 0a e7 c9 3a 00 19
col 0; len 3; (3): c2 06 15 --> 520I hope you had some fun with fiddling around the (I still believe: seemingly) futile playing with 10046 & 10200 traces and block dumps.
Leave a Reply