RE: unexpected heavy buffered IO during partition bitmap index rebuild
- From: "Mark W. Farnham" <mwf@xxxxxxxx>
- To: <JTornblad@xxxxxxxxxx>
- Date: Wed, 26 Sep 2012 07:08:29 -0400
From the evidence at hand I cannot tell whether any of these is actually
relevant to your case.
Also please note I wrote "At least three" and might be something completely
different.
-----Original Message-----
From: oracle-l-bounce@xxxxxxxxxxxxx [mailto:oracle-l-bounce@xxxxxxxxxxxxx]
On Behalf Of Tornblad, John
Sent: Tuesday, September 25, 2012 2:20 PM
To: oracle-l@xxxxxxxxxxxxx
Subject: 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.
--
//www.freelists.org/webpage/oracle-l
--
//www.freelists.org/webpage/oracle-l
Other related posts:
