This post is the continuation of the previous part.
Clustering Factor – tests with 10046
Let’s go through the cases represented by SELECT statements and examine the true effort measured with the number of physical reads which are hidden behind a query retrieving its data from the table, yet by the means of either one: ID_SORTED or ID_MESS in the predicate section.
Both queries will stick to the same scenario – I will incur physical reads directed to table’s blocks for ID_SORTED and ID_MESS, respectively.
They which will triggered by the single (corresponding) index block leaf read.
So, speaking “performance freaks’ language”, the below depicted scenarios will answer the following question:
how many physical reads from a table are incurred on behalf of a (I am simplifying now) single index block read, if low or high CLUF is in play.
As you’ll see, the intercepted numbers will perfectly match the calculations from the previous part based on block dumps. This time I will use the output of two 10046 traces (each time I flushed the buffer cache to force physical reads).
Quantifying physical reads for low CLUF
I will need the OBJECT_IDs of all involved segments as they are reported in the raw 10046 trace files.
OBJECT SUBOBJECT_NAME OBJECT_ID DATA_OBJECT_ID OBJECT_TYPE
------------------------------------------------------------ ------------------------- ---------- -------------- ----------------
TSTUS.TSCLUF 181825 181825 TABLE
TSTUS.IDX_ID_SORTED 181826 181826 INDEX
TSTUS.IDX_ID_MESS 181827 181827 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, a 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, of which 19 were performed on behalf of the table: TSCLUF.
Note, on non-Exadata platform you’ll see the following enrtry:
WAIT #<cursor_number>: nam=’db file sequential read”
So if you happen run your own test on non-Exadata change your grepping pattern.
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
4Physical reads performed on behalf of the table :
[oracle @ CDBTST1 @ testhost01 ]$ # cat CDBTST1_ora_187041_lowcluf.trc | grep WAIT | grep physical | grep 181825 | wc -l
1923 (4 + 19) exactly matches the output of the “set autotrace trace explain statistics”. But this is not something which we would get excited with.
Namely, the 19 is the magic number.
If you change to the previous part of the post, you’ll find out that this is the number I calculated from various block dumps.
The 19 was to be the expected number of physical table block reads which were to be carried out on behalf of single index leaf block read (so very limited index range scan).
So, clearly, with the perfect CLUF, for one index leaf block read Oracle required 19 physical reads from this table.
This is the best possible scenario (I mean: the 19 physical reads), given the length of each row (note, the PAD takes 256 bytes) and the perfect CLUF.
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 ?
I have explained that caveat here (unless you have an idea ..? 😉 )
For the time being, let’s carry on with the test – this time I will take the HIGH CLUF scenario on my plate.
Quantifying physical reads for high CLUF
SYS@CDBTST1->TPDB1> ALTER SESSION SET TRACEFILE_IDENTIFIER='&trfile_suffix';
Enter value for trfile_suffix: hi_cluf
old 1: ALTER SESSION SET TRACEFILE_IDENTIFIER='&trfile_suffix'
new 1: ALTER SESSION SET TRACEFILE_IDENTIFIER='hi_cluf'
Session altered.
INST_ID SID SERIAL# OSPID PID TRACEFILE
------- -------- ---------- ------------------------ -------- --------------------------------------------------------------------------------------
1 2907 31646 239127 96 CDBTST1_ora_239127_hi_cluf.trc
SYS@CDBTST1->TPDB1> alter system flush buffer_cache ;
System altered.
19:30:55 SYS@CDBTST1->TPDB1>
19:30:55 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: 31646
PL/SQL procedure successfully completed.
SYS@CDBTST1->TPDB1> @setts
SYS@CDBTST1->TPDB1> SET AUTOTRACE TRACE EXPLAIN STATISTICS
SYS@CDBTST1->TPDB1> select /* &comm */ * from TSTUS.TSCLUF where id_mess <= 485 ;
Enter value for comm: hi_cluf
old 1: select /* &comm */ * from TSTUS.TSCLUF where id_mess <= 485
new 1: select /* hi_cluf */ * from TSTUS.TSCLUF where id_mess <= 485
470 rows selected.
Elapsed: 00:00:00.08
Execution Plan
----------------------------------------------------------
Plan hash value: 3542504988
---------------------------------------------------------------------------------------------------
| Id | Operation | Name | Rows | Bytes | Cost (%CPU)| Time |
---------------------------------------------------------------------------------------------------
| 0 | SELECT STATEMENT | | 486 | 127K| 490 (0)| 00:00:01 |
| 1 | TABLE ACCESS BY INDEX ROWID BATCHED| TSCLUF | 486 | 127K| 490 (0)| 00:00:01 |
|* 2 | INDEX RANGE SCAN | IDX_ID_MESS | 486 | | 4 (0)| 00:00:01 |
---------------------------------------------------------------------------------------------------
Predicate Information (identified by operation id):
---------------------------------------------------
2 - access("ID_MESS"<=485)
Statistics
----------------------------------------------------------
1 recursive calls
0 db block gets
505 consistent gets
472 physical reads
0 redo size
13563 bytes sent via SQL*Net to client
765 bytes received via SQL*Net from client
33 SQL*Net roundtrips to/from client
0 sorts (memory)
0 sorts (disk)
470 rows processedPhysical reads from the 10046 trace CDBTST1_ora_239127_hi_cluf.trc :
Physical reads performed on behalf of index IDX_ID_MESS (object_id = 181827) :
[oracle @ CDBTST1 @ testhost01 ]$ # cat CDBTST1_ora_239127_hi_cluf.trc | grep WAIT | grep physical | grep 181827
WAIT #139803498625344: nam='cell single block physical read: flash cache' ela= 2449 cellhash#=4259318641 diskhash#=1265020198 bytes=8192 obj#=181827
WAIT #139803498625344: nam='cell single block physical read: flash cache' ela= 703 cellhash#=1290911885 diskhash#=2137534647 bytes=8192 obj#=181827
WAIT #139803498625344: nam='cell single block physical read: flash cache' ela= 311 cellhash#=4259318641 diskhash#=1265020198 bytes=8192 obj#=181827
Physical reads performed on behalf of table (object_id = 181825) :
[oracle @ CDBTST1 @ testhost01 ]$ # cat CDBTST1_ora_239127_hi_cluf.trc | grep WAIT | grep physical | grep 181825
WAIT #139803498625344: nam='cell single block physical read: flash cache' ela= 2135 cellhash#=439186241 diskhash#=3981647790 bytes=8192 obj#=181825
WAIT #139803498625344: nam='cell single block physical read: flash cache' ela= 742 cellhash#=1810516308 diskhash#=1028073414 bytes=8192 obj#=181825
WAIT #139803498625344: nam='cell single block physical read: flash cache' ela= 1997 cellhash#=3018416126 diskhash#=3263235976 bytes=8192 obj#=181825
WAIT #139803498625344: nam='cell list of blocks physical read' ela= 375 cellhash#=0 diskhash#=0 blocks=13 obj#=181825 tim=48088787822650
WAIT #139803498625344: nam='cell list of blocks physical read' ela= 302 cellhash#=0 diskhash#=0 blocks=15 obj#=181825 tim=48088787827672
WAIT #139803498625344: nam='cell list of blocks physical read' ela= 323 cellhash#=0 diskhash#=0 blocks=15 obj#=181825 tim=48088787830565
WAIT #139803498625344: nam='cell list of blocks physical read' ela= 332 cellhash#=0 diskhash#=0 blocks=15 obj#=181825 tim=48088787833128
WAIT #139803498625344: nam='cell list of blocks physical read' ela= 303 cellhash#=0 diskhash#=0 blocks=15 obj#=181825 tim=48088787835531
WAIT #139803498625344: nam='cell list of blocks physical read' ela= 384 cellhash#=0 diskhash#=0 blocks=15 obj#=181825 tim=48088787838367
WAIT #139803498625344: nam='cell list of blocks physical read' ela= 400 cellhash#=0 diskhash#=0 blocks=15 obj#=181825 tim=48088787840232
WAIT #139803498625344: nam='cell list of blocks physical read' ela= 284 cellhash#=0 diskhash#=0 blocks=15 obj#=181825 tim=48088787841973
WAIT #139803498625344: nam='cell list of blocks physical read' ela= 238 cellhash#=0 diskhash#=0 blocks=15 obj#=181825 tim=48088787843783
WAIT #139803498625344: nam='cell list of blocks physical read' ela= 278 cellhash#=0 diskhash#=0 blocks=15 obj#=181825 tim=48088787845159
WAIT #139803498625344: nam='cell list of blocks physical read' ela= 308 cellhash#=0 diskhash#=0 blocks=15 obj#=181825 tim=48088787846260
WAIT #139803498625344: nam='cell list of blocks physical read' ela= 286 cellhash#=0 diskhash#=0 blocks=15 obj#=181825 tim=48088787848015
WAIT #139803498625344: nam='cell list of blocks physical read' ela= 265 cellhash#=0 diskhash#=0 blocks=15 obj#=181825 tim=48088787849530
WAIT #139803498625344: nam='cell list of blocks physical read' ela= 272 cellhash#=0 diskhash#=0 blocks=15 obj#=181825 tim=48088787851241
WAIT #139803498625344: nam='cell list of blocks physical read' ela= 294 cellhash#=0 diskhash#=0 blocks=15 obj#=181825 tim=48088787852730
WAIT #139803498625344: nam='cell list of blocks physical read' ela= 279 cellhash#=0 diskhash#=0 blocks=15 obj#=181825 tim=48088787854184
WAIT #139803498625344: nam='cell list of blocks physical read' ela= 315 cellhash#=0 diskhash#=0 blocks=15 obj#=181825 tim=48088787855098
WAIT #139803498625344: nam='cell list of blocks physical read' ela= 311 cellhash#=0 diskhash#=0 blocks=15 obj#=181825 tim=48088787855887
WAIT #139803498625344: nam='cell list of blocks physical read' ela= 302 cellhash#=0 diskhash#=0 blocks=15 obj#=181825 tim=48088787856696
WAIT #139803498625344: nam='cell list of blocks physical read' ela= 300 cellhash#=0 diskhash#=0 blocks=15 obj#=181825 tim=48088787857460
WAIT #139803498625344: nam='cell list of blocks physical read' ela= 369 cellhash#=0 diskhash#=0 blocks=15 obj#=181825 tim=48088787858267
WAIT #139803498625344: nam='cell list of blocks physical read' ela= 300 cellhash#=0 diskhash#=0 blocks=15 obj#=181825 tim=48088787859060
WAIT #139803498625344: nam='cell list of blocks physical read' ela= 256 cellhash#=0 diskhash#=0 blocks=15 obj#=181825 tim=48088787859853
WAIT #139803498625344: nam='cell list of blocks physical read' ela= 270 cellhash#=0 diskhash#=0 blocks=15 obj#=181825 tim=48088787860593
WAIT #139803498625344: nam='cell list of blocks physical read' ela= 317 cellhash#=0 diskhash#=0 blocks=15 obj#=181825 tim=48088787861333
WAIT #139803498625344: nam='cell list of blocks physical read' ela= 317 cellhash#=0 diskhash#=0 blocks=14 obj#=181825 tim=48088787862223
WAIT #139803498625344: nam='cell list of blocks physical read' ela= 334 cellhash#=0 diskhash#=0 blocks=15 obj#=181825 tim=48088787863024
WAIT #139803498625344: nam='cell list of blocks physical read' ela= 409 cellhash#=0 diskhash#=0 blocks=15 obj#=181825 tim=48088787863918
WAIT #139803498625344: nam='cell list of blocks physical read' ela= 289 cellhash#=0 diskhash#=0 blocks=15 obj#=181825 tim=48088787864682
WAIT #139803498625344: nam='cell list of blocks physical read' ela= 311 cellhash#=0 diskhash#=0 blocks=15 obj#=181825 tim=48088787865484
WAIT #139803498625344: nam='cell list of blocks physical read' ela= 308 cellhash#=0 diskhash#=0 blocks=15 obj#=181825 tim=48088787866654
WAIT #139803498625344: nam='cell list of blocks physical read' ela= 385 cellhash#=0 diskhash#=0 blocks=4 obj#=181825 tim=48088787867339As you probably noticed, this time Oracle applied batched reads: “cell list of blocks physical read”.
Fortunately, it also reported the number of true physical reads which were performed on behalf of each such batched I/O (see: blocks=n).
Let’s filter them out and group them by the size of the batched reads.
Finally, I will add them up.
[oracle @ CDBTST1 @ testhost01 ]$ # cat CDBTST1_ora_239127_hi_cluf.trc | grep WAIT | grep physical | grep 181825 | grep "blocks=15" | wc -l
29
[oracle @ CDBTST1 @ testhost01 ]$ # cat CDBTST1_ora_239127_hi_cluf.trc | grep WAIT | grep physical | grep 181825 | grep "blocks=13" | wc -l
1
[oracle @ CDBTST1 @ testhost01 ]$ # cat CDBTST1_ora_239127_hi_cluf.trc | grep WAIT | grep physical | grep 181825 | grep "blocks=4" | wc -l
1
[oracle @ CDBTST1 @ testhost01 ]$ # cat CDBTST1_ora_239127_hi_cluf.trc | grep WAIT | grep physical | grep 181825 | grep "blocks=14" | wc -l
1Quick math :
Total physical reads performed on behalf of the table:
29*15 + 1*13 + 1*14 + 1*4 + 3(single reads) = 469Ah – look at that!
469 is the number which was calculated in the previous part while dumping the contents of the blocks.
The Statistics section from the AUTOTRACE reports the matching number: 472 physical reads (469 reads from the table + 3 reads from the index).
For the time being, it’s worth to note one crucial thing.
The high Clustering Factor incurs much bigger effort in terms of the number of physical I/O, higher CPU utilization and last but not least: higher utilization of the buffer cache, to treat the things somewhat superficial.
I have carried out some analysis considering the above statements here – search for the text: “TEST #1” in this linked post and start from there.
Here I will just copy-paste the conclusion :
The first batch reads brought back the portion of rows which may not be used on the immediate basis, but will surely be needed later. In the meantime they got cached in the SGA.
As the scan continued, the batch size gets gradually reduced because some rows were already in the cache, having been read during earlier operations.
It’s not immediately visible based on that tiny samples from above. After all, we carried out a “single index leaf block surgery” and cascaded it to just several hundreds corresponding reads from the table, but it becomes obvious with larger portion, that is, with broader range scan.
Side note: this time Oracle was happy with just 3 physical index reads: root + branch + just one leaf block read – it’s clear from the 10046 trace just at the top.
I mean, it’s clear that it required 3 index reads, but it’s not clear yet that it needed just one index block leaf (as I expected).
Clustering Factor – part4
Leave a Reply