Operations in huge transaction slow down suddenly. Why?

From: Bernhard Graeuler <fuerspam_at_gmx.de>
Date: Fri, 17 Dec 2004 17:01:12 +0100
Message-ID: <32ge68F3mhfnuU1@individual.net>

Hi,

my problem is not very easy to explain. Basically what we're doing is an import of many records to the database. Therefore, at first we load the new data by creating new local tables with "Create Table as select * from ..." over a database link.

Then we have to merge the existing data with te newly loaded data. In this step (roughly explained), new records were inserted in the existing tables. Information about newr- and changes on existing data were reported as conflicts into a separate table. These conflicts have to be resolved manually after the import finishes.
This second step is running in one single transaction. Many thousands of records were inserted into the table containing the conflicts.

Ok. Now what is the problem? After inserting about 15000 records into the conflict table and executing several thousand updates or inserts into the existing tables the process suddenly slows down. We detect this by writing a report entry containing a timestamp, every block of 500 processed steps.

The customer reported this problem because one block suddenly lasts about 24 hours.

We can not reproduce this problem here with these huge time ranges, but here you can see a snippet of a report where I reduced the size of each block to 200 steps for debugging reasons.

17.12.2004 12:42:28,0,  *** Step : 11600
17.12.2004 12:42:28,0, delay : 17.12.2004 12:42:27 - 01:03:09 (00:01:53)
17.12.2004 12:45:25,0,  *** Step : 11800
17.12.2004 12:45:25,0, delay : 17.12.2004 12:45:24 - 01:06:07 (00:02:57)
17.12.2004 12:46:32,0,  *** Step : 12000
17.12.2004 12:46:32,0, delay : 17.12.2004 12:46:32 - 01:07:14 (00:01:07)
17.12.2004 12:52:59,0,  *** Step : 12200
17.12.2004 12:52:59,0, delay : 17.12.2004 12:52:59 - 01:13:41 (00:06:26)
17.12.2004 13:28:51,0,  *** Step : 12400
17.12.2004 13:28:51,0, delay : 17.12.2004 13:28:51 - 01:49:33 (00:35:52)

Here I stopped the process after getting no results after about two hours.

What we did until now is switching on sql tracing and timed statistics and writing snapshots with the "statspack" package. We get many results and I mean the following snippets could be interesting:

*

insert into VMDPIMPORT ( FSCHANGE,CHANGEDATUM,WSGGUID,TABELLE,SPARTE,BM,

ERWEITERUNG,CODETYP,CODE,BEI,GUELTIGAB,GUELTIGBIS,NSGGUID,KONFLIKT,FELDNAME, FELDWERTALT,FELDWERTNEU,IMPORTHINT,GGUID,INSERTTIMESTAMP,INSERTUSER, UPDATETIMESTAMP,UPDATEUSER )
values
( :1,:2,:3,:4,:5,:6,:7,:8,:9,NULL,:10,:11,:12,:13,:14,:15,:16,:17,:18,:19, :20,:21,:22 )

call count cpu elapsed disk query current rows
------- ------ -------- ---------- ---------- ---------- ---------- ------

Parse 52 0.17 8.56 0 0 0 0
Execute 52 8.97 533.69 30349 1074337 4008 52
Fetch 0 0.00 0.00 0 0 0 0
------- ------ -------- ---------- ---------- ---------- ---------- ------

total 104 9.14 542.25 30349 1074337 4008 52

Misses in library cache during parse: 1
Misses in library cache during execute: 3 Optimizer goal: CHOOSE
Parsing user id: 98

VMDPIMPORT is a view on the table MDPIMPORT where the conflicts were reported into.

Another one is:

*

insert into MDPPLAUSIBILITAETEN (
INSERTTIMESTAMP,INSERTUSER,UPDATETIMESTAMP, UPDATEUSER,GGUID,SPARTE,BM,ERWEITERUNG,CODETYP,CODE,BEI,GUELTIGAB, GUELTIGBIS,SATZNOTIZ,BLOCKFLAG,DOKUKZ,NURIVM,NICHTIVM,REPLACENURIVM, REPLACENICHTIVM,KONFLIKT,FREEFIELD01,FREEFIELD02,FREEFIELD03,FREEFIELD04, FREEFIELD05,FREEFIELD06,FREEFIELD07,FREEFIELD08,FREEFIELD09,FREEFIELD10, FREEFIELD11,FREEFIELD12,NOTPUBLISHED ) values
( :1,:2,:3,:4,:5,:6,:7,:8,:9,:10,:11,:12,:13,NULL,NULL,:14,NULL,NULL,NULL, NULL,:15,NULL,NULL,NULL,NULL,NULL,NULL,NULL,NULL,NULL,NULL,NULL,NULL,NULL ) call count cpu elapsed disk query current rows
------- ------ -------- ---------- ---------- ---------- ---------- ------

Parse 48 0.13 7.57 0 0 0 0
Execute 48 15.19 374.99 210575 439706 3100 48
Fetch 0 0.00 0.00 0 0 0 0
------- ------ -------- ---------- ---------- ---------- ---------- ------

total 96 15.32 382.56 210575 439706 3100 48

Misses in library cache during parse: 1
Optimizer goal: CHOOSE
Parsing user id: 98

This an insert of a newly imported record.

Ok, that's it. If anyone has any suggestions what we could try next, or has an idea, what could be the reason for this, please answer this.

Thanks in advance and best regards

Bernhard Gräuler Received on Fri Dec 17 2004 - 10:01:12 CST