I was asked to check a session which was running for more than expected time on 11.2.0.3 single instance database.The session was running a simple select statement
05:03:09 [email protected] > @sqlid 9kpjtkdz1mzus old 9: sql_id = ('&1') new 9: sql_id = ('9kpjtkdz1mzus') SQL_ID HASH_VALUE SQL_TEXT ------------- ---------- ------------------------------------------------------------------------------------------------------------------------------------------------------ 9kpgmndz1mzus 2115632984 SELECT SC.ID FROM user.s_seq_cd SC WHERE SC.TYPE_CD <> 'CMOD' AND SC.URGENCY_CD IS NOT NULL AND SC.STAT_ID = 'Closed' 1 row selected. Elapsed: 00:00:00.00 old 26: sql_id = ('&1') new 26: sql_id = ('9kpjtkdz1mzus') CH# PARENT_HANDLE OBJECT_HANDLE PLAN_HASH OPT_COST PARSES H_PARSES EXECUTIONS FETCHES ROWS_PROCESSED CPU_MS ELA_MS AVG_ELA LIOS PIOS SORTS USERS_EXECUTING ---- ---------------- ---------------- ---------- -------- ---------- ---------- ---------- ---------- -------------- ---------- ---------- ---------- ---------- ---------- ---------- --------------- 0 00000001C76435E8 00000001C7640D80 3122863050 18774 1 1 1 56 229376 1148.076 1659299.43 1659.29943 228000 209064 0 1 1 row selected.
SQL_ID 9kpjtkdz1mzus, child number 0
-------------------------------------
SELECT SC.ID FROM USER.S_SEQ_CD SR WHERE SC.TYPE_CD <>
'CMOD' AND SC.URGENCY_CD IS NOT NULL AND SC.STAT_ID = 'Closed'
Plan hash value: 3122863050
-----------------------------------------------------------------------------------------------
| Id | Operation | Name | Rows | Bytes | Cost (%CPU)| Time |
-----------------------------------------------------------------------------------------------
| 0 | SELECT STATEMENT | | | | 18774 (100)| |
|* 1 | TABLE ACCESS BY INDEX ROWID| S_SEQ_CD | 630K| 54M| 18774 (1)| 00:03:46 |
|* 2 | INDEX RANGE SCAN | S_SEQ_CD_M28_X | 12M| | 552 (1)| 00:00:07 |
-----------------------------------------------------------------------------------------------
Predicate Information (identified by operation id):
---------------------------------------------------
1 - filter(("SC"."URGENCY_CD" IS NOT NULL AND "SC"."TYPE_CD"<>'CMOD'))
2 - access("SC"."STAT_ID"='Closed')
On checking the session wait event it showed “db file scattered read”
05:12:01 [email protected] > @asw USERNAME SID SERIAL# SPID MACHINE EVENT SQL_ID WAIT_TIME SECONDS_IN_WAIT STATE --------------- ---------- ---------- ------------------------ -------------------- ---------------------------------------- ------------- ---------- --------------- ------------------- USER 575 331 9292 xxxxxxxx db file scattered read 9kpjtkdz1mzus 0 0 WAITING
As per the plan i was expecting “db file sequential read” but seeing “db file scattered read” was little shocking to me. Traced the session at 10046 level 12, which showed
....................... WAIT #47616080937272: nam='db file parallel read' ela= 39297 files=1 blocks=7 requests=7 obj#=55745 tim=1338199998917111 WAIT #47616080937272: nam='db file scattered read' ela= 3226 file#=60 block#=71137 blocks=8 obj#=55745 tim=1338199998920723 WAIT #47616080937272: nam='db file scattered read' ela= 15988 file#=60 block#=71145 blocks=7 obj#=55745 tim=1338199998936973 *** 2012-05-28 05:13:18.945 WAIT #47616080937272: nam='db file scattered read' ela= 7994 file#=60 block#=71152 blocks=9 obj#=55745 tim=1338199998945414 WAIT #47616080937272: nam='db file scattered read' ela= 7164 file#=60 block#=71161 blocks=7 obj#=55745 tim=1338199998952955 WAIT #47616080937272: nam='db file scattered read' ela= 9505 file#=60 block#=71169 blocks=7 obj#=55745 tim=1338199998963139 WAIT #47616080937272: nam='db file sequential read' ela= 5597 file#=60 block#=71168 blocks=1 obj#=55745 tim=1338199998968993 WAIT #47616080937272: nam='db file scattered read' ela= 9685 file#=60 block#=71176 blocks=7 obj#=55745 tim=1338199998978860 WAIT #47616080937272: nam='db file scattered read' ela= 8081 file#=60 block#=71183 blocks=8 obj#=55745 tim=1338199998987329 WAIT #47616080937272: nam='db file sequential read' ela= 5535 file#=30 block#=156495 blocks=1 obj#=55745 tim=1338199998993023 WAIT #47616080937272: nam='db file scattered read' ela= 17117 file#=60 block#=71191 blocks=7 obj#=55745 tim=1338199999010375 WAIT #47616080937272: nam='db file sequential read' ela= 14412 file#=114 block#=475510 blocks=1 obj#=531936 tim=1338199999025129 ........................ ........................
05:27:25 [email protected] > select object_name from dba_objects where object_id=531936; OBJECT_NAME ---------------------------------------- S_SEQ_CD_M28_X 05:20:35 [email protected] > select object_name from dba_objects where object_id=55745; OBJECT_NAME ---------------------------------------- S_SEQ_CD
Then i came across
http://www.freelists.org/post/oracle-l/RE-Calculating-LIOs,11
If a regular index index full or range scan causes “multiblock” reads, it is due index prefetching which is up to optimizer to decide.Index prefetching means that when doing a range or full scan, then Oracle will read the index by traversing the index tree, but it reads the tree several blocks at a time (for example, it gets a number of logically
consecutive leaf block addresses from branch block and reads a batch of leafs in).
So this is a *noncontiguous* multiblock read, meaning that Oracle just issues multiple single block read requests in one batch. This should result in a “db file parallel read” wait. So, asynch IO should definitely be used when relying on index prefetch, otherwise your performance might degrade, especially when some of the prefetched blocks don’t get used at all.
CKPT process maintains statistics history in X$KCBKPFS (kernel cache buffer k? pre-fetch statistics) about wasted prefetched blocks.(Luckily this x$ table’s columns are written in english not just abbreviations). So if sessions start hitting a lot of never pinned prefetch blocks, the x$kcbkpfs statistics start to indicate inefficient prefetching, thus causing CBO not to favour it and prefer regular single block reads.
Index full scans are the main candidates which may benefit from prefetch,since a full scan needs to read all leaf blocks anyway, thus not risking with prefetch wastage. However, in order to prefetch batches of leaf blocks
you have to read in the branch blocks “above” it, causing some extra IO (for regular single block index full scan you only have to read in branch blocks from root to first or last leaf block in tree). Note that I’m only concluding my last claim, I’ve not done testing to see whether extra branch blocks actually happen – but I don’t see any other way
how to find out DBAs of next leaf block batch.
You can control prefetching with parameters:
_index_prefetch_factor – defaults to 100, but when changed smaller, the optimizer will favor index prefetching.
_db_file_noncontig_mblock_read_count – maximum number of blocks to be prefetched in one batch. If set to 1, prefetching should be disabled.
There is an event 10299 which traces prefetch operations and if you set it to CKPT process you’ll see some aggregate statistics as well, also there area lot of %prefetch% statistics in v$sesstat & v$sysstat
On checking the session stat for prefetch –
05:45:59 [email protected] > select name,value from v$sesstat s, v$statname n where s.statistic# = n.statistic# and s.sid = 575 and n.name like '%prefetch%' order by name; NAME VALUE -------------------------------------------------- ---------- index crx upgrade (prefetch) 0 physical reads cache prefetch 454875 physical reads prefetch warmup 0 prefetch clients - 16k 0 prefetch clients - 2k 0 prefetch clients - 32k 0 prefetch clients - 4k 0 prefetch clients - 8k 0 prefetch clients - default 1 prefetch clients - keep 0 prefetch clients - recycle 0 prefetch warmup blocks aged out before use 26826 prefetch warmup blocks flushed out before use 0 prefetched blocks aged out before use 468
The value for “physical reads cache prefetch” increased to 533260 and after this consistent value, the session wait started showing db file sequential read.
06:44:18 [email protected] > select * from X$KCBKPFS where WASTED_BLOCKS > 0; no rows selected Elapsed: 00:00:00.00 06:44:27 [email protected] > select * from X$KCBKPFS where PREFETCH_BLOCKS> 0; ADDR INDX INST_ID BUFFER_POOL_ID TIMESTAMP PREFETCH_OPS PREFETCH_BLOCKS WASTED_BLOCKS CLIENTS_PREFETCH PREFETCH_LIMIT ---------------- ---------- ---------- -------------- ---------- ------------ --------------- ------------- ---------------- -------------- 00002B70873F6598 100 1 3 14781146 663 4619 0 7 9376 00002B70873F6598 101 1 3 14784346 780 5428 0 7 9376 00002B70873F6598 102 1 3 14788166 1161 8074 0 7 9376 ........................ ........................ 00002B70873F6598 148 1 3 14773386 1159 8077 0 7 9376 00002B70873F6598 149 1 3 14778066 1093 7626 0 7 9376 49 rows selected.
Some important parameters set regarding it –
[email protected] > @hidden_param Enter value for parameter: _db_file_noncontig_mblock_read_count Enter value for 1: _db_file_noncontig_mblock_read_count old 11: AND a.ksppinm = DECODE(LOWER('¶meter'), 'all', a.ksppinm, LOWER('&1')) new 11: AND a.ksppinm = DECODE(LOWER('_db_file_noncontig_mblock_read_count'), 'all', a.ksppinm, LOWER('_db_file_noncontig_mblock_read_count')) PARAMETER DESCRIPTION SESSION_VA INSTANCE_V ------------------------------------- ------------------------------ ---------- ---------- _db_file_noncontig_mblock_read_count number of noncontiguous db 11 11 blocks to be prefetched 1 row selected. [email protected] > / Enter value for parameter: _db_cache_pre_warm Enter value for 1: _db_cache_pre_warm old 11: AND a.ksppinm = DECODE(LOWER('¶meter'), 'all', a.ksppinm, LOWER('&1')) new 11: AND a.ksppinm = DECODE(LOWER('_db_cache_pre_warm'), 'all', a.ksppinm, LOWER('_db_cache_pre_warm')) PARAMETER DESCRIPTION SESSION_VA INSTANCE_V ------------------------------------- ------------------------------ ---------- ---------- _db_cache_pre_warm Buffer Cache Pre-Warm Enabled TRUE TRUE : hidden parameter 1 row selected. [email protected] > / Enter value for parameter: _index_prefetch_factor Enter value for 1: _index_prefetch_factor old 11: AND a.ksppinm = DECODE(LOWER('¶meter'), 'all', a.ksppinm, LOWER('&1')) new 11: AND a.ksppinm = DECODE(LOWER('_index_prefetch_factor'), 'all', a.ksppinm, LOWER('_index_prefetch_factor')) PARAMETER DESCRIPTION SESSION_VA INSTANCE_V ------------------------------------- ------------------------------ ---------- ---------- _index_prefetch_factor index prefetching factor 100 100 1 row selected. [email protected] > show parameter sga_target NAME TYPE VALUE ------------------------------------ ----------- ------------------------------ sga_target big integer 6G [email protected] > show parameter multiblock NAME TYPE VALUE ------------------------------------ ----------- ------------------------------ db_file_multiblock_read_count integer 8 05:47:43 [email protected] > select sum(bytes/1024/1024/1024)GB from dba_segments where segment_name='S_SEQ_CD'; GB ---------- 13.7021484 05:49:57 [email protected] > select sum(bytes/1024/1024)MB from dba_segments where segment_name='S_SEQ_CD_M28_X'; MB ---------- 467.125
The database was bounced just before the start of the sql as the box got rebooted.So what is it that the prefetch is cause of empty buffer cache? I am unable to understand this behavior and so it would be great if some of you can put your thoughts as comments on it along with what all more could be checked for.
UPDATE — You can also read the below blog from Tanel Poder which mentions having mutliblock reads for index unique scan.
http://blog.tanelpoder.com/2012/05/02/advanced-oracle-troubleshooting-guide-part-10-index-unique-scan-doing-multiblock-reads/