unexpected heavy buffered IO during partition bitmap index rebuild

From: Tornblad, John <JTornblad_at_emdeon.com>
Date: Tue, 25 Sep 2012 13:19:41 -0500
Message-ID: <0EC8AF65BC8E9A4E9C4EB86F1882C96E04CF3542_at_ZBNAAEEX052.na.webmd.net>



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
Received on Tue Sep 25 2012 - 13:19:41 CDT

Original text of this message