RE: db file sequential read waits on INSERT into non-indexed partitioned table
Date: Thu, 29 Sep 2011 11:02:19 -0700
Message-ID: <021a01cc7ed1$ee57d520$cb077f60$_at_wayneadams.com>
Thanks Jonathan for the response and the explanations!
The tablespaces have an 8k blocksize. These tests have been in our QA system which has FLASHBACK DATABASE turned off. So I don't think we can attribute the "db file sequential reads" to that (flashback is turned on in our production system however, so we'll have to look at how much that factors into the INSERT performance there).
Avg Row Len is 719, but I ran your rows/block script for a more accurate result:
TWENTIETH MIN_ROWS MAX_ROWS TOT_BLOCKS TOT_ROWS AVG_ROWS
---------- ---------- ---------- ---------- ---------- --------
1 1 1 212 212 1.00
2 2 2 16 32 2.00
3 3 3 21 63 3.00
4 4 4 19 76 4.00
5 5 5 14 70 5.00
6 6 6 16 96 6.00
7 7 7 259 1813 7.00
8 8 8 6577 52616 8.00
9 9 9 43927 395343 9.00
10 10 10 9651 96510 10.00
11 11 11 158 1738 11.00
----------
sum 60870 548569
I have included a sampling of the WAITS for the INSERT. Obj# are all various SUBP of the table.
WAIT #11: nam='db file sequential read' ela= 259 file#=12 block#=7573302 blocks=1 obj#=38684000 tim=1286408819092647 WAIT #11: nam='enq: FB - contention' ela= 665 name|mode=1178730502tablespace #=6 dba=5749315 obj#=38684000 tim=1286408819095790
WAIT #11: nam='db file sequential read' ela= 994 file#=12 block#=7573318 blocks=1 obj#=38684000 tim=1286408819098305 WAIT #11: nam='db file sequential read' ela= 171 file#=12 block#=7452688 blocks=1 obj#=38684073 tim=1286408819098944 WAIT #11: nam='db file sequential read' ela= 1347 file#=12 block#=7573334 blocks=1 obj#=38684000 tim=1286408819103219 WAIT #11: nam='db file sequential read' ela= 817 file#=12 block#=7573350 blocks=1 obj#=38684000 tim=1286408819108149 WAIT #11: nam='db file sequential read' ela= 433 file#=12 block#=7573366 blocks=1 obj#=38684000 tim=1286408819112474 WAIT #11: nam='gc current grant 2-way' ela= 262 p1=12 p2=7573382 p3=33554433obj#=38684000 tim=1286408819118822
WAIT #11: nam='db file sequential read' ela= 1829 file#=12 block#=7573382 blocks=1 obj#=38684000 tim=1286408819120736 WAIT #11: nam='gc current grant 2-way' ela= 265 p1=12 p2=7573398 p3=33554433obj#=38684000 tim=1286408819124516
WAIT #11: nam='db file sequential read' ela= 2041 file#=12 block#=7573398 blocks=1 obj#=38684000 tim=1286408819126633 WAIT #11: nam='gc current grant 2-way' ela= 231 p1=12 p2=5716113 p3=33554433obj#=38683993 tim=1286408819127771
WAIT #11: nam='db file sequential read' ela= 814 file#=12 block#=5716113 blocks=1 obj#=38683993 tim=1286408819128632 WAIT #11: nam='gc current grant 2-way' ela= 250 p1=12 p2=7573414 p3=33554433obj#=38684000 tim=1286408819130314
WAIT #11: nam='db file sequential read' ela= 1218 file#=12 block#=7573414 blocks=1 obj#=38684000 tim=1286408819131582 WAIT #11: nam='db file sequential read' ela= 1172 file#=12 block#=5617757 blocks=1 obj#=38683987 tim=1286408819137810 WAIT #11: nam='enq: FB - contention' ela= 522 name|mode=1178730502tablespace #=6 dba=7452675 obj#=38683987 tim=1286408819143040
Also, regarding your damage limitation. Since the performance seems to be affected by the hash subpartitions and not the range (there is only 1 range partition in my test table), how would you sort the data before inserting it?
In order to test the ASSM impact, I created a non ASSM tablespace and reran my tests. The fact that ASSM has a negative affect didn't surprise me, but the degree did.
INSERT into range part (no SUBP), no indexes, ASSM
call count cpu elapsed disk query current
rows
------- ------ -------- ---------- ---------- ---------- ----------
Parse 1 0.00 0.00 0 0 0 0
Execute 6 3.26 3.62 310 10393 48259 50877
Fetch 0 0.00 0.00 0 0 0 0
------- ------ -------- ---------- ---------- ---------- ----------
total 7 3.26 3.62 310 10393 48259 50877
Elapsed times include waiting on following events:
Event waited on Times Max. Wait TotalWaited
- Waited ----------
db file sequential read 307 0.01 0.20 enq: FB - contention 183 0.00 0.08 enq: HW - contention 3 0.00 0.00 row cache lock 2 0.00 0.00
INSERT into range-hash part (128 SUBP), no indexes, no ASSM
call count cpu elapsed disk query current
rows
------- ------ -------- ---------- ---------- ---------- ----------
Parse 1 0.00 0.00 0 0 0 0
Execute 6 6.16 7.25 507 53036 68817 50877
Fetch 0 0.00 0.00 0 0 0 0
------- ------ -------- ---------- ---------- ---------- ----------
total 7 6.16 7.25 507 53036 68817 50877
Elapsed times include waiting on following events:
Event waited on Times Max. Wait TotalWaited
- Waited ----------
gc cr grant 2-way 63 0.00 0.01 db file sequential read 507 0.02 0.28 gc current grant 2-way 222 0.00 0.05 enq: HW - contention 1630 0.00 0.43 gc current multi block request 733 0.00 0.34 enq: TT - contention 7 0.00 0.00 KJC: Wait for msg sends to complete 8 0.00 0.00 latch free 2 0.00 0.00 latch: ges resource hash list 1 0.00 0.00
INSERT into range-hash part (128 SUBP), no indexes, ASSM
call count cpu elapsed disk query current
rows
------- ------ -------- ---------- ---------- ---------- ----------
Parse 1 0.00 0.00 0 0 0 0
Execute 6 8.57 12.47 3494 53406 179867 50877
Fetch 0 0.00 0.00 0 0 0 0
------- ------ -------- ---------- ---------- ---------- ----------
total 7 8.57 12.47 3494 53406 179867 50877
Elapsed times include waiting on following events:
Event waited on Times Max. Wait TotalWaited
- Waited ----------
db file sequential read 3492 0.04 3.80 gc current grant 2-way 1857 0.00 0.52 gc cr grant 2-way 17 0.00 0.00 enq: FB - contention 215 0.00 0.10 gc current multi block request 307 0.00 0.15 enq: TT - contention 3 0.00 0.00
Wayne
-----Original Message-----
I should have asked - how many rows do you get per block, and what's the
block
size (which, in your version, with ASSM) might make a difference to what's
going on.
Regards
Jonathan Lewis
-----Original Message-----
Wayne,
I can't explain why you are waiting for the enqueues, but I think the extra
current block gets appear because every time a row in the array goes into a
different partition from the previous row your session does a bitmap search
for
the first free block in that partition. The more partitions you have the
more
likely it is that the next row belongs in a different partition from the
previous row. The difference (worst case) is probably three current gets
per
row, although I haven't tested your scenario, which may make it four.
Damage limitation:
a) sort the data by target partition before inserting it.
b) use freelist management, not ASSM.
The db file sequentil reads are probably the effect of enabling flashback
datase, every block you "new" may have to be read and copied into the
flashback
log.
The FB enqueues are Format Block - and I think you're formatting 16 blocks
at a
time; the TT enqueues are tablespace bitmap update locks taken as you modify
space from the tablespace freespace bitmap (there are related reasons for
TT's), and the HW lock is the highwatermark bump lock, taken as you update
the
segment header highwater mark. I can understand the TT resulting in a wait,
but if you are the only person inserting into this table I don't understand
why
the FB and HW see waits.
I have a few clues that things are done a little differently in 11.2, and
the
changes may make a difference to the results you are seeing.
Regards
Jonathan Lewis
-----Original Message-----
From: Wayne Adams [mailto:work_at_wayneadams.com]
Sent: Thursday, September 29, 2011 1:02 AM
To: oracle-l_at_freelists.org
Subject: RE: db file sequential read waits on INSERT into non-indexed
partitioned table
Just for completeness, I created another test table (range-hash, 128 SUBP) specifying a large INITIAL/NEXT so that I would get 8MB extents. I then ran the tests again. The results were practically identical to my other tests.
INSERT into range-hash (128 SUBP)
call count cpu elapsed disk query current
rows
------- ------ -------- ---------- ---------- ---------- ----------
Parse 1 0.00 0.00 0 0 0 0
Execute 6 8.89 13.97 2572 53355 180107 50877
Fetch 0 0.00 0.00 0 0 0 0
------- ------ -------- ---------- ---------- ---------- ----------
total 7 8.89 13.97 2572 53355 180107 50877
Elapsed times include waiting on following events:
Event waited on Times Max. Wait TotalWaited
- Waited ----------
db file sequential read 2570 0.04 4.61 gc current grant 2-way 1495 0.03 0.45 gc cr grant 2-way 17 0.00 0.00 enq: FB - contention 216 0.00 0.12 gc current multi block request 439 0.00 0.16 enq: TT - contention 5 0.00 0.00 gc current grant busy 2 0.00 0.00
INSERT into range (no SUBP)
call count cpu elapsed disk query current
rows
------- ------ -------- ---------- ---------- ---------- ----------
Parse 1 0.00 0.00 0 0 0 0
Execute 6 3.03 3.17 99 10218 48616 50877
Fetch 0 0.00 0.00 0 0 0 0
------- ------ -------- ---------- ---------- ---------- ----------
total 7 3.03 3.17 99 10218 48616 50877
Elapsed times include waiting on following events:
Event waited on Times Max. Wait TotalWaited
- Waited ----------
db file sequential read 99 0.00 0.07 enq: FB - contention 194 0.00 0.08 buffer busy waits 1 0.00 0.00 KJC: Wait for msg sends to complete 1 0.00 0.00
Wayne
-- http://www.freelists.org/webpage/oracle-lReceived on Thu Sep 29 2011 - 13:02:19 CDT