Icon View Thread

The following is the text of the current message along with any replies.
Messages 1 to 10 of 32 total
Thread Low performance of prepared TDBISAMQuery
Mon, Apr 8 2019 3:37 PMPermanent Link

ds

Hi
The case: i'm implementing some kind of journaling for my tables. Logic basically is pretty simple - each real data record have its own unique SyncID and in additional journal table system stores datetime of most recent action for each SyncID + action code (insert/update/delete).
Journal records inserted/updated in triggers and controlled by special objects (TTableSynchronizer in code below); these used dedicated session with 'SYNCxxx' naming.

Trigger code:
procedure TDataSynchronizer.AfterUpdate(Sender: TObject;
 TriggerSession: TDBISAMSession; TriggerDatabase: TDBISAMDatabase;
 const TableName: String; CurrentRecord: TDBISAMRecord);
 var
   sync: TTableSynchronizer;
begin
 if LeftStr(TriggerDatabase.SessionName, 4) = 'SYNC'
   then exit;
   (* insert journal record when record updated *)
   sync := TableSynchronizer(TableName); // find corresponding synchronizer object for table
   if Assigned(sync) then begin
     try
       sync.WriteSyncData(CurrentRecord.FieldByName('SYNCID').AsInteger, 1, DT);
     except
     end; (* try..except *)
   end; (* if *)
end;

TTableSynchronizer.WriteSyncData actually called prepared SQL query in way:

procedure TISAMTableSynchronizer.WriteSyncData(SyncID: integer;  Action: TSyncAction; DT: TDateTime);
begin
 try
   if Action = actUpdate then begin //actUpdate =1
     FSyncTableU.Params[1].AsInteger := SyncID;
     FSyncTableU.Params[0].AsDateTime := DT;
     try
         FSyncTableU.ExecSQL; <<== prepared sql call which is a point
  ........

FSyncTableU is prepared (on construction) sql query:
...
 FSyncTableU := TDBISAMQuery.Create(nil);
 FSyncTableU.SessionName := session.SessionName;
 FSyncTableU.DatabaseName := session.SessionName+'_J';
 FSyncTableU.SQL.Add('update '+TableName+'_J set DT = :DT where SyncID=:SyncID and Action = 1');
 FSyncTableU.ParamByName('SyncID').DataType := ftInteger;
 FSyncTableU.ParamByName('DT').DataType := ftDateTime;
 FSyncTableU.Prepare;
...

journal tables (naming like tablename_J and each data table have corresponding journal table) located in separated subfolder and have simple structure (below is journal creation code for demonstration):
   FJournal.FieldDefs.Add('SyncID', ftInteger);
   FJournal.FieldDefs.Add('Action', ftSmallint);
   FJournal.FieldDefs.Add('DT', ftDateTime);
   FJournal.CreateTable;
   FJournal.IndexDefs.Add('DTi', 'DT');
   FJournal.IndexDefs.Add('SyncIDi', 'syncid');
   FJournal.IndexDefs.Add('latestact', 'action');
   FJournal.AlterTable();

Issue is these sql queries above calls cause serious performance leak. I.e. updating for table with 130K records tooks about 20sec without construction above and >2min with it. Bottleneck is 100% this ExecSQL (i've commented it out and got 20sec back but without journaling of course)

Question why such exec is so hard - it is simple, prepared an parametrized and should be executed as a flash?
And how it can be improved in DBISAM?

In Database System Utility such query is almost instant as i expected:
================================================================================
SQL statement (Executed with 4.44 Build 3)
================================================================================

update daten_j set dt='2019-4-8 22:00' where syncid=80 and action=1

Tables Involved
---------------

daten_j (daten_j) table opened shared, has 268544 rows

WHERE Clause Execution
----------------------

The expression:

syncid = 80 and action = 1

is PARTIALLY-OPTIMIZED, covers 2 rows or index keys, costs 121 bytes, and will
be applied to the daten_j table (daten_j) before any joins

================================================================================
>>>>> 1 rows affected in 0,016 seconds
================================================================================

Hope for help and thanks in advance, Evgeny
Tue, Apr 9 2019 2:13 AMPermanent Link

Roy Lambert

NLH Associates

Team Elevate Team Elevate

ds


Have you tried running in DBSys and checking generate plan to see what it says?

Roy Lambert
Tue, Apr 9 2019 3:11 AMPermanent Link

ds

Roy Lambert wrote:

ds


Have you tried running in DBSys and checking generate plan to see what it says?

Roy Lambert

yes, output is at end of my post

regards, Evgeny
Tue, Apr 9 2019 3:53 AMPermanent Link

Roy Lambert

NLH Associates

Team Elevate Team Elevate

ds


Sorry, I must have stopped reading just before getting there Frown

Remember DBSys is just an application written in Delphi and using DBISAM behind the scenes it will be doing a simple query.open or query.execsql so there must be some difference in what you're doing or the data.

Its a long time since I used DBISAM in anger (still have a few apps using it)  but this

procedure TISAMTableSynchronizer.WriteSyncData(SyncID: integer;  Action: TSyncAction; DT: TDateTime);
begin
 try
   if Action = actUpdate then begin //actUpdate =1
     FSyncTableU.Params[1].AsInteger := SyncID;
     FSyncTableU.Params[0].AsDateTime := DT;
     try
         FSyncTableU.ExecSQL; <<== prepared sql call which is a point

confuses me a bit. Presumably you have closed the query at some point prior to applying the new parameters.

I know from conversations with Tim that preparing a query is often the longest part of it as the engine had to parse the sql and obtain handles to the tables involved so the norm is to prepare once then call multiple times with new parameters. You may be doing that but I can't tell from the code you've supplied.

If you step through your code how many times is WriteSyncData called?

Roy Lambert
Tue, Apr 9 2019 4:10 AMPermanent Link

ds

Roy Lambert wrote:

ds


Sorry, I must have stopped reading just before getting there Frown

Remember DBSys is just an application written in Delphi and using DBISAM behind the scenes it will be doing a simple query.open or query.execsql so there must be some difference in what you're doing or the data.

Its a long time since I used DBISAM in anger (still have a few apps using it)  but this

procedure TISAMTableSynchronizer.WriteSyncData(SyncID: integer;  Action: TSyncAction; DT: TDateTime);
begin
 try
   if Action = actUpdate then begin //actUpdate =1
     FSyncTableU.Params[1].AsInteger := SyncID;
     FSyncTableU.Params[0].AsDateTime := DT;
     try
         FSyncTableU.ExecSQL; <<== prepared sql call which is a point

confuses me a bit. Presumably you have closed the query at some point prior to applying the new parameters.

I know from conversations with Tim that preparing a query is often the longest part of it as the engine had to parse the sql and obtain handles to the tables involved so the norm is to prepare once then call multiple times with new parameters. You may be doing that but I can't tell from the code you've supplied.

If you step through your code how many times is WriteSyncData called?

Roy Lambert

WriteSyncData is called each time record in host table modified (by AfterUpdate trigger), so each host table Post (update)
FSyncTableU never opened or closed - its purpose just write data. It prepared once (each table have its own sync object) and have to just executed. I can close before exec, will it help?

regards, Evgeny
Tue, Apr 9 2019 4:36 AMPermanent Link

ds

Roy Lambert wrote:

....
confuses me a bit. Presumably you have closed the query at some point prior to applying the new parameters.
...

Roy Lambert

I added close before execsql - no difference, worked as before
Actually, i have an impression there is some session/database/query property causung not immediate write... But it is just impression, i don't know

regards, Evgeny
Tue, Apr 9 2019 7:02 AMPermanent Link

Roy Lambert

NLH Associates

Team Elevate Team Elevate

Evgeny


>WriteSyncData is called each time record in host table modified (by AfterUpdate trigger), so each host table Post (update)
>FSyncTableU never opened or closed - its purpose just write data. It prepared once (each table have its own sync object) and have to just executed. I can close before exec, will it help?

I know its intended to just be called once but I'm wondering if something is causing it to be called a lot of times - if you take the 0.016 seconds it takes in DBSys and multiply by the number of rows you get the sort of time you're talking about.

>Actually, i have an impression there is some session/database/query property causung not immediate write... But it is just impression, i don't know

You could try calling table.flushbuffers to see if that will help - I would expect it to slow things down, and if it does speed things up I'm totally baffled.

Really wild thought try changing

 FSyncTableU.SQL.Add('update '+TableName+'_J set DT = :DT where SyncID=:SyncID and Action = 1');

to

 FSyncTableU.SQL.Text := 'update '+TableName+'_J set DT = :DT where SyncID=:SyncID and Action = 1';

Since you're only setting the sql once, when the query is created, it shouldn't make any difference but just in case

Roy
Tue, Apr 9 2019 7:39 AMPermanent Link

ds

Roy
Thanks for cooperation. Will try your suggestions

regards, Evgeny
Tue, Apr 9 2019 10:10 AMPermanent Link

Roy Lambert

NLH Associates

Team Elevate Team Elevate

Evgeny

>Thanks for cooperation. Will try your suggestions

Its what this forum is for Smile

The more I look at and read your original post the more baffled I am. You're using an UPDATE statement but you don't show an INSERT for the first entry in the journal - either that's not happening or that piece of code is missing. The result from DBSys shows 0.016 seconds for one row. Even the 20 seconds you quote if the equivalent of >1000 rows and 2 minutes would be around 7500 rows.

My thoughts from that cover:

1.    re-entrancy problem
2.    problem in the code not shown
3.    loads of processing in the code not shown
4.    table needing repair
5.    hard drive giving problems and lots of re-reads required
6.    AV issue
7.    slow network
8.    coding problem

ie its very wide. Can you post the whole code (as an attachment) so we can look at it? Is it possible to produce a small test case showing the problem? The latter would be the best thing.

Almost every time I've had something like this, or seen a similar issue posted here (ie application results vs DBSys results) its almost always our fault, only rarely Tim's product. If it is DBISAM that's where a small test case is useful since it gives Tim something to work on. I have found that on occasions going through deleting components off a form all of a sudden things work properly so I know what's causing it.

Roy
Tue, Apr 9 2019 1:41 PMPermanent Link

ds

Roy
> The more I look at and read your original post the more baffled I am. You're using an UPDATE statement but you don't show an INSERT for the first entry in the journal - either that's not happening or that piece of code is missing. The result from DBSys shows 0.016 seconds for one row. Even the 20 seconds you quote if the equivalent of >1000 rows and 2 minutes would be around 7500 rows.

Inserts and deletes journaled in similar way, see entire code of WriteSyncData method (it called from corresponding triggers with different Action parameter:
procedure TISAMTableSynchronizer.WriteSyncData(SyncID: integer;
 Action: TSyncAction; DT: TDateTime);
 var
  ok: boolean;
begin
 try
   if Action = actUpdate then begin
     FSyncTableU.Close;
     FSyncTableU.Params[1].AsInteger := SyncID;
     FSyncTableU.Params[0].AsDateTime := DT;
     ok := false;
     repeat
       try
         FSyncTableU.ExecSQL;
         ok := true;
       except
       end;
     until ok;

     (* if no update record exists for given SyncID, it shoud be inserted *)
     if FSyncTableU.RowsAffected = 0 then begin
       FSyncTable.Params[0].AsInteger := SyncID;
       FSyncTable.Params[1].AsInteger := integer(actUpdate);
       FSyncTable.Params[2].AsDateTime := DT;
       ok := false;
       repeat
         try
           FSyncTable.ExecSQL;
           ok := true;
         except
         end;
       until ok;
     end; (* if *)
   end
   else begin
     FSyncTable.Params[0].AsInteger := SyncID;
     FSyncTable.Params[1].AsInteger := integer(Action);
     FSyncTable.Params[2].AsDateTime := DT;
     ok := false;
     repeat
       try
         FSyncTable.ExecSQL;
         ok := true;
       except
       end;
     until ok;
     (* after insert also need to insert update entry for given syncid *)
     if Action=actInsert then begin
       FSyncTable.Params[0].AsInteger := SyncID;
       FSyncTable.Params[1].AsInteger := integer(actUpdate);
       FSyncTable.Params[2].AsDateTime := DT;
       ok := false;
       repeat
         try
           FSyncTable.ExecSQL;
           ok := true;
         except
         end;
       until ok;
     end; (* end *)
   end; (* else *)
   FLastChangeSQL.Close;
   FLastChangeSQL.Params[0].AsDateTime := DT;
   ok := false;
   repeat
     try
       FLastChangeSQL.ExecSQL;
       ok := true;
     except
     end;
   until ok;
 except
 end; (* try..except *)
end; (* TISAMTableSynchronizer.WriteSyncData *)

0.016 is for 1st run in DBSys, next will show 0.000sec; guess 0.016 includes preparation time

> Can you post the whole code (as an attachment) so we can look at it? Is it possible to produce a small test case showing the problem? The latter would be the best thing.

I'm affraid it is not easy - this code deeply injected into complex business code. I will attach unit with this functionality but it can confuse because contains a lot of additional things Wink

regards, Evgeny



Attachments: DataSync.pas
Page 1 of 4Next Page
Jump to Page:  1 2 3 4
Image