Insert performance is very bad

[vnktummala]

Hi,

I have an issue with one of the insert queries which is performing very bad.

This query is suppose to insert 6.5 million rows but since last 6 hours it has inserted only 600K rows.

Please see the excerpt from v$sqlstats

DISK_READS DIRECT_WRITES ROWS_PROCESSED USER_IO_WAIT_TIME

505082 0 620288 14661318963

I am sure user_io_wait_time is very very high. I am working on to figure out where it is waiting such a long time. Any hints to drive me in the right direction will be much appreciated.

Table current volume - 157 million
Partitioned - Y
No. of Indexes - 2 (1 local part. & 1 global hash part.)

Thanks,

[vnktummala]

updating v$session_wait details for the session. Surprisingly (at least for me) wait time is 0 here.

       SID EVENT                          WAIT_CLASS_ID WAIT_CLASS# WAIT_CLASS       WAIT_TIME SECONDS_IN_WAIT STATE
---------- ------------------------------ ------------- ----------- --------------- ---------- --------------- -------------------
       131 db file sequential read           1740759767           8              User I/O                 0               0 WAITING

[PAVB]

May be the problem is not the insert but the select statement that feeds the insert.

Is this a set based insert or is it a cursor based a.k.a. row-by-row one?

[vnktummala]

Thanks for quicker Paul ...

Insert query is fired by Informatica session. One of the Informatica sessions reads the data from source table to informatica buffer, perform transformation, load target table.

When I verify the Informatica logs, reader busy time is less than 1%, transformation busy time is less than 1%, and writer busy time is > 90%.

Thanks,

[vnktummala]

Is there any way to find so far how many times the given Insert query is issued commit? In Informatica session commit interval is set for every 20000 rows but just want to cross check that.

Also, can any one shed some light why INSERT session is waiting on "db file sequential read" which is usually for single block reads like index reads.

I have generated the stats pack report (no license for performance pack) from 11th Nov 10pm to 12th Nov 2am and please see the top 5 wait events below.

Top 5 Timed Events                                                    Avg %Total
~~~~~~~~~~~~~~~~~~                                                   wait   Call
Event                                            Waits    Time (s)   (ms)   Time
----------------------------------------- ------------ ----------- ------ ------
CPU time                                                    70,287          60.9
db file sequential read                      2,962,799      34,443     12   29.8
enq: CI - contention                             1,276       3,590   2813    3.1
db file scattered read                         322,883       1,879      6    1.6
rdbms ipc reply                                  1,283       1,721   1341    1.5
          -------------------------------------------------------------

Please Note - only 2 very bad Insert queries are executing in the database during this time.


Thanks,

[PAVB]

Insert query is fired by Informatica session. One of the Informatica sessions reads the data from source table to informatica buffer, perform transformation, load target table.

Informatica loves row-by-row processing.
Check how often is Informatica mapping commiting the work.

Do you have a test environment available to conduct a test with no indexes?

[vnktummala]

Informatica commit interval is 200000. I have a test environment but not enough volume available there.

As the Insert is part of daily job, I have a luxury to test it in production it self. I have planned the below two things for next load.

1. Decrease the commit interval to 50000
2. Drop both the Indexes

The other insert statement which is executing along with the one I am referring, made me think about decreasing the commit interval because of the free buffer waits.

( :1, :2, :3, :4, :5, :6, :7, :8, :9, :10, :11, :12, :13, :14, :15, :16, :17,
   :18, :19, :20, :21, :22, :23, :24, :25, :26, :27, :28, :29, :30, :31, :32, 
  :33, :34, :35, :36, :37, :38, :39, :40, :41, :42, :43, :44, :45, :46, :47, 
  :48, :49, :50, :51, :52, :53, :54, :55, :56, :57, :58, :59, :60, :61, :62, 
  :63) 


call     count       cpu    elapsed       disk      query    current        rows
------- ------  -------- ---------- ---------- ---------- ----------  ----------
Parse        0      0.00       0.00          0          0          0           0
Execute   1204     73.38    2676.67      44854       9562     243505       77056
Fetch        0      0.00       0.00          0          0          0           0
------- ------  -------- ---------- ---------- ---------- ----------  ----------
total     1204     73.38    2676.67      44854       9562     243505       77056

Misses in library cache during parse: 0
Optimizer mode: CHOOSE
Parsing user id: 83  

Elapsed times include waiting on following events:
  Event waited on                             Times   Max. Wait  Total Waited
  ----------------------------------------   Waited  ----------  ------------
  SQL*Net more data from client                7224        0.00          0.10
  db file sequential read                     44852        1.23       1189.41
  SQL*Net message to client                    1204        0.00          0.00
  SQL*Net message from client                  1204        0.00          1.12
  free buffer waits                           11283        0.98        452.76
  latch: object queue header operation            6        0.00          0.00
  latch free                                      2        0.00          0.00
  log file switch completion                      1        0.17          0.17

I started looking into the respective Index TS to see if there is any contention in the underlying data files or not.

Thanks,

[vnktummala]

while investigating more on the issue I had, I have come across a nice metalink document about the Recommended Method for Obtaining 10046 trace for Tuning. This may be helpful for some one so sharing the URL.

https://support.oracle.com/CSP/main/...442.1&type=NOT

Thanks,

[stecal]

Got to read the index (or indexes) to do DML, that would account for the sequential read wait times. CPU time would be indicative of a lot of hard parsing for the insert statements (willing to bet each and every statement is different as opposed to the same via a bind variable or called procedure using a variable).

[vnktummala]

Thanks Stecal.

you could have lost the bet if you bet. Informatica construct the insert with bind variables. The values part of my bad insert query looks like below.

VALUES ( :1, :2, :3, :4, :5, :6, :7, :8, :9, :10, :11, :12, :13, :14, :15, :16, :17)

That table has only two Indexes and as I mentioned earlier both of them are partitioned. One is local and other one is global. However, I will keep this in mind and drop the Indexes during next load.

Please see my instance efficiency percentages.

Instance Efficiency Percentages
~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~
            Buffer Nowait %:  100.00       Redo NoWait %:  100.00
            Buffer  Hit   %:   95.87    In-memory Sort %:   99.99
            Library Hit   %:   88.93        Soft Parse %:   86.47
         Execute to Parse %:   58.98         Latch Hit %:   99.94
Parse CPU to Parse Elapsd %:   65.59     % Non-Parse CPU:   99.95

Thanks,