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,

[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,

[vnktummala]

I have enabled the trace in the session for more than one hour, before it complete few minutes back. Please see the wait events from tkprof trace file.

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


call     count       cpu    elapsed       disk      query    current        rows
------- ------  -------- ---------- ---------- ---------- ----------  ----------
Parse        0      0.00       0.00          0          0          0           0
Execute   2779     97.96    2741.65      79587      93439    1966341      622496
Fetch        0      0.00       0.00          0          0          0           0
------- ------  -------- ---------- ---------- ---------- ----------  ----------
total     2779     97.96    2741.65      79587      93439    1966341      622496

Misses in library cache during parse: 0
Misses in library cache during execute: 1
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               22614        0.00          0.21
  db file sequential read                     79403        1.38       1861.02
  SQL*Net message to client                    2778        0.00          0.00
  SQL*Net message from client                  2778        0.00          1.96
  latch: object queue header operation            1        0.00          0.00
  log file switch completion                      2        0.51          0.51
  log file sync                                   3        0.00          0.00

based on 'db file sequential read' waits, am I correct If I conclude that there is an issue with the Indexe(s) on the table in question?


Thanks,

[stecal]

How many indexes are on the table(s) being updated/inserted into?

[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?