Re: BULK bound inserts are very slow

Mladen Gogala wrote:
> 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

I agree, manage storage manually. This is slight overhead to ASM. Received on Tue Nov 07 2006 - 13:08:39 CST