| Oracle FAQ | Your Portal to the Oracle Knowledge Grid | |
 |
 | |||
| Oracle FAQ | Your Portal to the Oracle Knowledge Grid | |
|
| |||
Home -> Community -> Usenet -> c.d.o.server -> BULK bound inserts are very slow
A developer is trying to do inserts into a table with forall in pl/sql
using a batch size of 10,000 rows.
Here is the table:
desc email_customer_history
Name Null? Type ----------------------------------------- --------
----------------------------
EMAIL_ID NOT NULL NUMBER(16) CUSTOMER_ID NOT NULL NUMBER(16) EMAIL_ADDRESS_ID NOT NULL NUMBER(16) SUBSCRIPTION_ID NUMBER(16) IS_PA_HEADER_INCLUDED NOT NULL NUMBER(1) OPENED_ON DATE BOUNCED_BACK_ON DATE UNSUBSCRIBED_ON DATE CREATED NOT NULL DATE LAST_UPDATE NOT NULL DATE CLICKED_ON DATE
When I did racing on this, here is what I find:
Cursor ID #33 (RECURSIVE DEPTH 1) at 11/03/2006 13:46:21 (Cursor 34):
INSERT INTO EMAIL_CUSTOMER_HISTORY ( EMAIL_ID, CUSTOMER_ID,
EMAIL_ADDRESS_ID, SU
BSCRIPTION_ID, IS_PA_HEADER_INCLUDED) VALUES (:B5, :B1, :B2, :B3, :B4 )
SQL Hash Value: 615637712
call count cpu elapsed disk query current
rows
------- ------ -------- ---------- ---------- ---------- ----------
Parse 1 0.00 0.00 0 0 0
0
Execute 3 14.13 200.02 3317 12817 278898
20362
Following are the wait events:
Significant Wait Events
Total
Wait Trace
Time File File
Block
Oracle Event Name (secs) Pct Line Numb
Number
buffer busy waits (code=1) 0.001 0% 7721 68
10353
buffer busy waits (code=1) 0.001 0% 7723 68
10365
buffer busy waits (code=1) 0.001 0% 8167 68
11482
buffer busy waits (code=1) 0.001 0% 33896 68
11602
buffer busy waits (code=1) 0.001 0% 18745 68
11625
buffer busy waits (code=1) 0.001 0% 8206 68
11793
buffer busy waits (code=1) 0.001 0% 34464 68
12071
buffer busy waits (code=1) 0.001 0% 14709 68
12552
buffer busy waits (code=1) 0.001 0% 10216 68
1271
buffer busy waits (code=1) 0.001 0% 8735 68
12947
buffer busy waits (code=1) 0.002 0% 8741 68
12968
570 more buffer busy waits (code=1) wait events...
Min Wait Time= 0.001 Avg Wait Time= 0.006 Max Wait Time= 0.277
buffer busy waits (code=8) 0.003 0% 15781 67
306697
buffer deadlock 0.001 0% 7662
buffer deadlock 0.003 0% 6232
buffer deadlock 0.003 0% 7325
buffer deadlock 0.006 0% 4215
buffer deadlock 0.022 0% 8471
buffer deadlock 0.001 0% 26948
buffer deadlock 0.001 0% 23926
buffer deadlock 0.002 0% 6759
buffer deadlock 0.001 0% 6356
buffer deadlock 0.002 0% 3117
buffer deadlock 0.008 0% 4257
5 more buffer deadlock wait events...
Min Wait Time= 0.001 Avg Wait Time= 0.005 Max Wait Time= 0.022
db file sequential read 0.003 0% 17634 31
13185
db file sequential read 0.001 0% 17637 31
20925
db file sequential read 0.001 0% 21773 31
21997
db file sequential read 0.002 0% 15780 31
22990
db file sequential read 0.001 0% 21397 31
71580
db file sequential read 0.001 0% 17008 31
72078
db file sequential read 0.002 0% 21771 31
74863
db file sequential read 0.002 0% 15775 31
75011
db file sequential read 0.012 0% 5181 67
305674
db file sequential read 0.008 0% 7076 67
305675
2360 more db file sequential read wait events...
Min Wait Time= 0.001 Avg Wait Time= 0.013 Max Wait Time= 2.015
enq: TX - contention 0.045 0% 8547
enq: TX - index contention 0.005 0% 13186
enq: TX - index contention 0.012 0% 19446
enq: TX - index contention 0.001 0% 19337
enq: TX - index contention 0.011 0% 25222
enq: TX - index contention 0.002 0% 25349
enq: TX - index contention 0.001 0% 23449
enq: TX - index contention 0.008 0% 16935
enq: TX - index contention 0.003 0% 21621
enq: TX - index contention 0.006 0% 19470
enq: TX - index contention 0.017 0% 13910
enq: TX - index contention 0.004 0% 19436
190 more enq: TX - index contention wait events...
Min Wait Time= 0.001 Avg Wait Time= 0.014 Max Wait Time= 0.217
latch: cache buffers chains 0.001 0% 25405
latch: cache buffers chains 0.002 0% 19097
latch: cache buffers chains 0.003 0% 17638
latch: cache buffers chains 0.002 0% 31984
latch: cache buffers chains 0.003 0% 32533
latch: cache buffers chains 0.003 0% 17015
latch: cache buffers chains 0.002 0% 17014
latch: cache buffers chains 0.002 0% 31982
latch: cache buffers chains 0.004 0% 29365
1 more latch: cache buffers chains wait events...
Min Wait Time= 0.001 Avg Wait Time= 0.003 Max Wait Time= 0.008
latch free (latch#=127) 0.004 0% 15776
latch: row cache objects 0.006 0% 35478
read by other session 0.002 0% 24089
read by other session 0.003 0% 18213
read by other session 0.010 0% 16397
read by other session 0.004 0% 16396
read by other session 0.002 0% 34279
read by other session 0.001 0% 31991
read by other session 0.001 0% 28825
read by other session 0.001 0% 31987
read by other session 0.002 0% 18717
read by other session 0.002 0% 15778
read by other session 0.007 0% 35501
12966 more read by other session wait events...
Min Wait Time= 0.001 Avg Wait Time= 0.011 Max Wait Time=
0.511
Total 185.696 100%
As we could see it's taken 14.13 seconds here. Not sure why it displays only so much or my understanding of the tracing is not complete. I see the time taken for each batch was close to 3 minutes (elapsed time?). Any ideas what could slow the inserts. I have 4 initrans and 10 freelists on the table and associated indexes. Ofcourse when I dropped the index on email_Address_id, it improved a lot. I checked for data distribution for that column and I find that data distribution is uneven (which is expected). I did this with, select email_Address_id,count(1) from email_customer_history group by email_Address_id;
A side note. All these even after I recreated a table from scratch. The tablespace is locally managed with segment space management auto.
Any thoughts is greatly appreciated.
Thanks!
Venky Received on Mon Nov 06 2006 - 17:13:12 CST
 |
 |