Re: BULK bound inserts are very slow

venky wrote:
> 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
> ------- ------ -------- ---------- ---------- ---------- ----------
> ----------
> total 4 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

Are there multiple sessions executing the PL/SQL or inserting into the same table at the same time? Any foreign keys on the table? How are the hard drives configured in the server?

Oracle documentation to help decode the wait events: http://download-east.oracle.com/docs/cd/B19306_01/server.102/b14237/waitevents003.htm

(buffer busy waits): "Wait Time: Normal wait time is 1 second. If the session was waiting for a buffer during the last wait, then the next wait will be 3 seconds." If this statement in the documentation is correct, the buffer busy waits would total at least 9 minutes - can't be right if the above completes in 15 seconds.

http://download-east.oracle.com/docs/cd/B19306_01/server.102/b14211/instance_tune.htm

Charles Hooper
PC Support Specialist
K&M Machine-Fabricating, Inc. Received on Mon Nov 06 2006 - 18:37:39 CST