RE: db file sequential read waits on INSERT into non-indexed partitioned table
- From: "Wayne Adams" <work@xxxxxxxxxxxxxx>
- To: <oracle-l@xxxxxxxxxxxxx>
- Date: Thu, 29 Sep 2011 11:02:19 -0700
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=1178730502
tablespace #=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=33554433
obj#=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=33554433
obj#=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=33554433
obj#=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=33554433
obj#=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=1178730502
tablespace #=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 Total
Waited
---------------------------------------- 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 Total
Waited
---------------------------------------- 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 Total
Waited
---------------------------------------- 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@xxxxxxxxxxxxxx]
Sent: Thursday, September 29, 2011 1:02 AM
To: oracle-l@xxxxxxxxxxxxx
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 Total
Waited
---------------------------------------- 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 Total
Waited
---------------------------------------- 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
--
//www.freelists.org/webpage/oracle-l
Other related posts:
