Insert performance is very bad

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

Quote:

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,

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

Code:

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

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?

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,

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.

Code:

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,

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).

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.

Code:

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.

Code:

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,

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.

Code:

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,

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

Quote:

Originally Posted by vnktummala

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?

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.

Code:

( :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,

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,

If i see a big number in value column of v$segment_stats, does it mean that DB is spending more time in allocating space?

Code:

select OBJECT_NAME,SUBOBJECT_NAME,object_type,statistic_name,statistic#,value from v$segment_statistics where obj# in ( select object_id from dba_objects where object_name='A_IDX') order by object_type,value desc; OBJECT_NAME SUBOBJECT_ OBJECT_TYPE STATISTIC_NAME STATISTIC# VALUE ------------------------------ ---------- ------------------ ------------------------------ ---------- -------------- A_IDX INDEX space allocated 15 3757047808 A_IDX INDEX space used 14 2555428919 A_IDX INDEX logical reads 0 352393280 A_IDX INDEX db block changes 3 119409200

If i recreate the object with bigger extent size does it help any way?

Oracle 10G R2 and all the table spaces are locally managed.

Thanks,

If you have that many inserts (using indexes), the stats would make sense/support what's being observed. You're best bet is to disable and rebuild, this isn't any different than a bulk load insert for a warehouse (or a big import having to update indexes along the way).

That may not be a feasible solution for me Stecal because most of the tables are more than 125 million and every day 4-6 million data will be loaded into these tables.

what do you think about the below stats? I am tracing a session since last 5 hours which is doing update on a huge table again which has 3 indexes in it. Please note this session is not completed yet.

Code:

Elapsed times include waiting on following events: Event waited on Times Max. Wait Total Waited ---------------------------------------- Waited ---------- ------------ db file sequential read 266920 1.39 2768.78 SQL*Net message to client 240739 0.00 0.33 SQL*Net message from client 240739 1.18 41.97 log file switch completion 4 0.23 0.36 latch: checkpoint queue latch 1 0.00 0.00 log file sync 1 0.00 0.00 latch: object queue header operation 1 0.00 0.00 ********************************************************************************

Hi Stecal,

The update statement I am referring in my previous post is just completed. Please see the tkprof output below and kindly share your taughts'.

Code:

call count cpu elapsed disk query current rows ------- ------ -------- ---------- ---------- ---------- ---------- ---------- Parse 0 0.00 0.00 0 0 0 0 Execute 296271 3900.76 17125.86 311558 912750 2129808 296271 Fetch 0 0.00 0.00 0 0 0 0 ------- ------ -------- ---------- ---------- ---------- ---------- ---------- total 296271 3900.76 17125.86 311558 912750 2129808 296271 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 ---------- ------------ db file sequential read 311558 1.39 3223.30 SQL*Net message to client 296271 0.00 0.41 SQL*Net message from client 296271 1.18 50.56 log file switch completion 4 0.23 0.36 latch: checkpoint queue latch 1 0.00 0.00 log file sync 1 0.00 0.00 latch: object queue header operation 1 0.00 0.00 ********************************************************************************

Thanks,

What OS is this?

You probably have storage problem, your sequential reads are taking around 25ms per read, that is like 8 times more than usual.

Other possibility is you are using filesystem buffer cache and suffering doube buffering effects

Also since you have 10046 trace you can look what segments are causing these waits

show us v$event_histogram output for the sequential reads

Hi Pando,

Nice to see you back after long time.

OS is HP-UX B.11.31

Actually, I have this problem with 6 out of 120 Informatica sessions. Out of these 6, five will do insert and one will do update.

The other tables residing in the same TS doesn't have any problem. Please see the out put from v$event_histogram.

Code:

EVENT# EVENT WAIT_TIME_MILLI WAIT_COUNT ---------- ---------------------------------------------------------------- --------------- ---------- 116 db file sequential read 1 609165281 116 db file sequential read 2 66522697 116 db file sequential read 4 93727756 116 db file sequential read 8 296013939 116 db file sequential read 16 170110709 116 db file sequential read 32 44205035 116 db file sequential read 64 21820058 116 db file sequential read 128 7420962 116 db file sequential read 256 2801755 116 db file sequential read 512 1270400 116 db file sequential read 1024 383451 116 db file sequential read 2048 91451 116 db file sequential read 4096 2047 116 db file sequential read 8192 128 116 db file sequential read 16384 21 116 db file sequential read 32768 5

Thanks,

Hi Pando,

missed to update in my previous post that I don't have 10046 trace file. As I don't have control for the application users, I have used dbms_monitor package to enable trace for waits.

Thanks,

Quote:

Originally Posted by vnktummala

The update statement I am referring in my previous post is just completed. Please see the tkprof output below and kindly share your taughts'.

Code:

call count cpu elapsed disk query current rows ------- ------ -------- ---------- ---------- ---------- ---------- ---------- Parse 0 0.00 0.00 0 0 0 0 Execute 296271 3900.76 17125.86 311558 912750 2129808 296271 Fetch 0 0.00 0.00 0 0 0 0 ------- ------ -------- ---------- ---------- ---------- ---------- ---------- total 296271 3900.76 17125.86 311558 912750 2129808 296271 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 ---------- ------------ db file sequential read 311558 1.39 3223.30 SQL*Net message to client 296271 0.00 0.41 SQL*Net message from client 296271 1.18 50.56 log file switch completion 4 0.23 0.36 latch: checkpoint queue latch 1 0.00 0.00 log file sync 1 0.00 0.00 latch: object queue header operation 1 0.00 0.00 ********************************************************************************

As far as I can see wait events on db_file_sequential_read account for about 20% of the total elapsed time therefore even if you manage to get rid of 100% of this particular wait event - which is not possible - you are looking at a performance gain of about 20%

What are the chances of rewritting this Informatica mapping as a PL/SQL block? - just for testing purposes :)

I would write the code without using explicit cursors a.k.a. set-based and, I'll eventually use APPEND hint during insert. On the first try I'll commit only once at the end of the job.

Quote:

Originally Posted by vnktummala

... I don't have 10046 trace file.

This is a job for oradebug -one of the many Oracle unsong super heroes.

Please try this...

0- Initiate offending process.

1- Figure out the SPID of the offending process.

2- Log into the system as sysdba

3- Start oradebug...
oradebug setospid SPID-from_step_1;

4- Enable 10046...
oradebug event 10046 trace name context forever, level 12

5- Wait... wait... keep waiting... then wait a little more :)

6- Disable 10046 tracing...
oradebug event 10046 trace name context off

7- tkprof trace file and bingo! you got your 10046 trace on remote session.

Thanks Paul.

Unfortunately, client has not given the complete DBA privileges on this DB So I can not use oradebug. Even for the trace file I am generating, I need to ask client employee to send me the file, then I am doing tkprof in my laptop.

well, we can not customize DML queries in Informatica. We can customize the queries reading from source but not the queries writing. At the most I can do is take the risk of putting table in nologging.

I am very much pity on myself.

Paul, can you help me to understand the v$segment_statistics better?

Code:

select OBJECT_NAME,SUBOBJECT_NAME,object_type,statistic_name,statistic#,value from v$segment_statistics where obj# in ( select object_id from dba_objects where object_name='A_IDX') order by object_type,value desc; OBJECT_NAME SUBOBJECT_ OBJECT_TYPE STATISTIC_NAME STATISTIC# VALUE ------------------------------ ---------- ------------------ ------------------------------ ---------- -------------- A_IDX INDEX space allocated 15 3757047808 A_IDX INDEX space used 14 2555428919 A_IDX INDEX logical reads 0 352393280 A_IDX INDEX db block changes 3 119409200

High value means DB is spending that much time to allocate space?

Also, I would like to update that the 12 hours INSERT job for which I started this thread is completed in two and half hours today after dropping all the Indexes associated. But still I am not happy because it has just inserted 600K rows. I am working with ETL guys to find the ETL side waits.

Thanks,

Quote:

Originally Posted by PAVB

As far as I can see wait events on db_file_sequential_read account for about 20% of the total elapsed time therefore even if you manage to get rid of 100% of this particular wait event - which is not possible - you are looking at a performance gain of about 20%

What are the chances of rewritting this Informatica mapping as a PL/SQL block? - just for testing purposes :)

I would write the code without using explicit cursors a.k.a. set-based and, I'll eventually use APPEND hint during insert. On the first try I'll commit only once at the end of the job.

So is Oracle waiting another approximate 20% for Informatica to push some work??

Thanks,