Index Range Scan and db file scattered read as session wait event

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 SYS@xx4040 > @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 SYS@xx4040 > @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 SYS@xx4040 > select object_name from dba_objects where object_id=531936;

OBJECT_NAME
----------------------------------------
S_SEQ_CD_M28_X

05:20:35 SYS@xx4040 > 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 SYS@xx4040 > 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 SYS@xx4040 > select * from X$KCBKPFS where WASTED_BLOCKS > 0;

no rows selected

Elapsed: 00:00:00.00
06:44:27 SYS@xx4040 > 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 -

SYS@xx4040 > @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('&parameter'), '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.

SYS@xx4040 > /
Enter value for parameter: _db_cache_pre_warm
Enter value for 1: _db_cache_pre_warm
old  11: AND    a.ksppinm = DECODE(LOWER('&parameter'), '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.

SYS@xx4040 > /
Enter value for parameter: _index_prefetch_factor
Enter value for 1: _index_prefetch_factor
old  11: AND    a.ksppinm = DECODE(LOWER('&parameter'), '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.

SYS@xx4040 > show parameter sga_target

NAME                                 TYPE        VALUE
------------------------------------ ----------- ------------------------------
sga_target                           big integer 6G

SYS@xx4040 > show parameter multiblock

NAME                                 TYPE        VALUE
------------------------------------ ----------- ------------------------------
db_file_multiblock_read_count        integer     8

05:47:43 SYS@xx4040 > select sum(bytes/1024/1024/1024)GB from dba_segments where segment_name='S_SEQ_CD';

        GB
----------
13.7021484

05:49:57 SYS@xx4040 > 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/

About these ads

Leave a Reply

Fill in your details below or click an icon to log in:

WordPress.com Logo

You are commenting using your WordPress.com account. Log Out / Change )

Twitter picture

You are commenting using your Twitter account. Log Out / Change )

Facebook photo

You are commenting using your Facebook account. Log Out / Change )

Google+ photo

You are commenting using your Google+ account. Log Out / Change )

Connecting to %s