Re: BULK bound inserts are very slow

On Mon, 06 Nov 2006 15:13:12 -0800, 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.
>

Venky, 10.2.0.2 doesn't use reason code, it uses block class instead, which means that "reason code 1" was produced by some old tool, not suitable for 10g. Formatting looks like statspack. The information about the reason code is meaningless.
Second, statspack snapshot is frequently a knee-jerk reaction of inexperienced administrators. Experienced DBA would enable 10046, level 12 and get much more detailed and accurate information. The information you have shows that
a) You have problems with concurrency and that other people are inserting

   into the database while you are doing a bulk load. Such an organization    of the application might not be the best of ideas. Bulk loads should be    done separately, when there are no other users on the systems. You also    might be waiting for a freelist. If you are on ASS managed tablespace,    the solution might be to move to space with manual segment space    management and fix FREELISTS by your own hands. You seem to have the    problems with the index, more then with the table itself. Reverse    indexes might be of some help, too.
b) Your DBWR might be having problems with catching up. You do have async

   I/O and you do have two or more DBWR processes enabled, don't you? 3) You might be waiting for the undo blocks, in which case speeding up

   access and allocation in your UNDO tablespace might actually be a good    idea.

-- 
http://www.mladen-gogala.com