unexpected heavy buffered IO during partition bitmap index rebuild

I was getting ready to toss the message below in a bottle out to Oracle-L when 
Oracle support came through and I held off for a few days.  See "problem 
statement" below for setup.

Outcome...
+ They had us take a look at the output of 
DBMS_SPACE_ADMIN.ASSM_SEGMENT_SYNCHWM (which yielded 'zero' / false with 
checkonly=>1).
+ Regardless of that, they had us "sync the HWM and low HWM" with the previous 
call altered to checkonly=>0.
+ After the "sync" there were still lots of buffered reads... no change in 
behavior at all.

Finally, they had us recreate the partition segment with CTAS and exchange it 
back into the table.  Works great... low, expected amounts of direct reads now 
during a bitmap index rebuild.

But why?  Is there a bug here?  What is it?  We are waiting on answers from 
support... but in the meantime we are ruminating on the possibility of having 
to recreate all affected segments (or even *find* all the ones that may be 
affected)... not a happy prospect.

I've googled a lot of blogs in the last few days.  Ran across the discussions 
on serial direct path read, changes to the _small_table_threshold mechanism and 
Tanel's explanation & video (nice!) of the low-level mechanism for full scan 
buffered vs. direct decision-making and how it involves a look at blocks 
already in the buffer and so on.  Even if that were affecting us, the total 
amount of IO we're seeing is well beyond the size of the segment (202GB vs. 
708MB).

Any advice / links appreciated.
 
-john


Problem statement
------------------------------
A table partition with 708MB of data (32KB block size) has several local bitmap 
indexes.  Rebuilding each of these index partitions incurs 202GB of buffered, 
physical IO in scanning the table partition, observed in SQL Monitor and trace.

Other partitions that are similar in size incur the expected amount of direct 
read IO for scanning the partition, about 708MB during a bitmap index rebuild.

We are stumped on how and why all this buffered IO is getting generated.  
Version is 11.2.0.3.  It seems to be well beyond (by a factor of 285!) the 
amount necessary to read the actual extents of the segment.


Great!... 14 seconds:
 
alter index I_CLAIM_DAY_PAYER_KEY rebuild partition P201001
 
call     count       cpu    elapsed       disk      query    current        rows
------- ------  -------- ---------- ---------- ---------- ----------  ----------
Parse        1      0.00       0.00          0          1          0           0
Execute      1      8.80      14.39      22674      22810       3114           0
Fetch        0      0.00       0.00          0          0          0           0
------- ------  -------- ---------- ---------- ---------- ----------  ----------
total        2      8.80      14.39      22674      22811       3114           0
 
Misses in library cache during parse: 1
Optimizer mode: ALL_ROWS
Parsing user id: 100  
Number of plan statistics captured: 1
 
Rows (1st) Rows (avg) Rows (max)  Row Source Operation
---------- ---------- ----------  
---------------------------------------------------
         1          1          1  INDEX BUILD NON UNIQUE I_CLAIM_DAY_PAYER_KEY 
(cr=23350 pr=22674 pw=1416 time=14418406 us)(object id 0)
    189113     189113     189113   BITMAP COMPACTION  (cr=22692 pr=22674 pw=0 
time=13760301 us)
    189113     189113     189113    SORT CREATE INDEX (cr=22692 pr=22674 pw=0 
time=13611002 us)
    189113     189113     189113     PARTITION RANGE SINGLE PARTITION: 17 17 
(cr=22692 pr=22674 pw=0 time=16585630 us cost=2976 size=82946875 card=16589375)
    189113     189113     189113      BITMAP CONSTRUCTION  (cr=22692 pr=22674 
pw=0 time=16514481 us)
  16589375   16589375   16589375       MAT_VIEW ACCESS FULL A_CLAIM_DAY 
PARTITION: 17 17 (cr=22692 pr=22674 pw=0 time=7293690 us cost=2976 
size=82946875 card=16589375)
 
 
Elapsed times include waiting on following events:
  Event waited on                             Times   Max. Wait  Total Waited
  ----------------------------------------   Waited  ----------  ------------
  Disk file operations I/O                       54        0.00          0.00
  direct path read                               42        0.04          0.32
  CSS initialization                              1        0.01          0.01
  CSS operation: query                            6        0.00          0.00
  CSS operation: action                           1        0.00          0.00
  direct path write                               3        0.00          0.01
  SQL*Net message to client                       1        0.00          0.00
  SQL*Net message from client                     1        0.12          0.12
 


Not good!... 93.5 minutes:
 
alter index I_CLAIM_DAY_PAYER_KEY rebuild partition P201208
 
call     count       cpu    elapsed       disk      query    current        rows
------- ------  -------- ---------- ---------- ---------- ----------  ----------
Parse        1      0.00       0.00          0          1          0           0
Execute      1    329.99    5612.14    6620184   13310756       1996           0
Fetch        0      0.00       0.00          0          0          0           0
------- ------  -------- ---------- ---------- ---------- ----------  ----------
total        2    330.00    5612.14    6620184   13310757       1996           0
 
Misses in library cache during parse: 1
Optimizer mode: ALL_ROWS
Parsing user id: 100  
Number of plan statistics captured: 1
 
Rows (1st) Rows (avg) Rows (max)  Row Source Operation
---------- ---------- ----------  
---------------------------------------------------
         1          1          1  INDEX BUILD NON UNIQUE I_CLAIM_DAY_PAYER_KEY 
(cr=13311183 pr=6620185 pw=761 time=1317199179 us)(object id 0)
    235902     235902     235902   BITMAP COMPACTION  (cr=13310679 pr=6620183 
pw=0 time=1316822714 us)
    235902     235902     235902    SORT CREATE INDEX (cr=13310679 pr=6620183 
pw=0 time=1316664028 us)
    235902     235902     235902     PARTITION RANGE SINGLE PARTITION: 48 48 
(cr=13310679 pr=6620183 pw=0 time=3517173222 us cost=6074 size=95026830 
card=19005366)
    235902     235902     235902      BITMAP CONSTRUCTION  (cr=13310679 
pr=6620183 pw=0 time=3517083617 us)
  19005366   19005366   19005366       MAT_VIEW ACCESS FULL A_CLAIM_DAY 
PARTITION: 48 48 (cr=13310679 pr=6620183 pw=0 time=1321556021 us cost=6074 
size=95026830 card=19005366)
 
 
Elapsed times include waiting on following events:
  Event waited on                             Times   Max. Wait  Total Waited
  ----------------------------------------   Waited  ----------  ------------
  Disk file operations I/O                      106        0.00          0.00
  direct path read                              261        0.06          3.70
  db file sequential read                   6571163        0.45       5205.52
  resmgr:cpu quantum                              5        0.00          0.00
  latch free                                      4        0.00          0.00
  resmgr:internal state change                    2        0.10          0.20
  CSS operation: action                           1        0.00          0.00
  direct path write                               1        0.00          0.00
  log file sync                                   1        0.00          0.00
  SQL*Net message to client                       1        0.00          0.00
  SQL*Net message from client                     1        0.09          0.09


</pre>This message is confidential, intended only for the named 
recipient(s) and may contain information that is privileged or 
exempt from disclosure under applicable law.  If you are not 
the intended recipient(s), you are notified that the 
dissemination, distribution, or copying of this message is 
strictly prohibited.  If you receive this message in error or 
are not the named recipient(s), please notify the sender by 
return email and delete this message. Thank you.
--
http://www.freelists.org/webpage/oracle-l


Other related posts: