TSQLRestServerDB.EngineBatchSend() exceptions

alpinistbg · 2018-11-16 18:47:07

When using TSQLClientWinHTTP.BatchSend(Batch) on TSQLRestServerDB (separate processes), there is a failures and strange entries in the log. They start to appear when the load slightly increases - 4 or 5 clients. There is no failures when server is accessed by a single client.

The log goes that way:

EXC   	EORMBatchException {"Message":"TSQLServerMIST.EngineBatchSend: TSQLServerMIST.TransactionBegin timeout"} at 00470A60 0046C7EF 00464B1B 00466B5B 0048F86D 005B1DE4 005B1808 005B146F 004264E5 004110B1 76C1343D 777D9802 777D97D5
20181116 14425804 trace 	DataModel.TSQLServerMIST(003274D8) EngineBatchSend json=4 KB add=0 update=0 delete=0 @AccessTags
20181116 14425804 warn  	DataModel.TSQLServerMIST(003274D8) {"EORMBatchException(08578680)":{"Message":"TSQLServerMIST.EngineBatchSend: TSQLServerMIST.TransactionBegin timeout"}} -> PARTIAL rollback of latest auto-committed transaction data=["automaticTransactionPerRow",2147483647,"POST@AccessTags~~{"RowID":88926204,"Cron":135469656680,...
20181116 14425804  -    02.010.165
20181116 14425804 debug DataModel.TSQLServerMIST(003274D8) TSQLRestRoutingREST.Error: {  "errorCode":500,  "error":  {"msg":"did break  BATCH process","EORMBatchException":{   "ClassName":"EORMBatchException",   "Address":"00470A60 ",   "Message": "TSQLServerMIST.EngineBatchSend: TSQLServerMIST.TransactionBegin timeout"  }}  }
20181116 14425804  +    DataModel.TSQLServerMIST(003274D8).EngineBatchSend  inlen=4100
20181116 14425804 srvr  	DataModel.TSQLServerMIST(003274D8)  192.168.0.240 PUT client/Batch Write=500 out=242 B in 5.18s
20181116 14425804  -    05.182.903

What I can understand is that there is TRANSACTION BEGIN timeout and that leads up to partial rollback of auto-committed data (none such "auto-committed" data in that case), then "did break BATCH", which is not true since the batch is not yet started to execute (starting transaction failed). All these messages are misleading.

It seems that the source of the exception is:

function TSQLRestServer.EngineBatchSend()
  ...
         if GetTickCount64>timeoutTix then
                  raise EORMBatchException.CreateUTF8(
                    '%.EngineBatchSend: %.TransactionBegin timeout',[self,RunningRest]);

Conclusion is that the increased load prevents the simultaneous processes to start a transaction for 2000 milliseconds - which is in turn another "magic" constant at mORMot.pas:44423. My previous post was about replaying the batches - but it seems no simple way of doing that, nor to increase the timeout for acquiring the transaction. I can't figure a workarounds for the issue.

Another alarming entry in the same log:

20181116 14425607 EXC   	ESQLite3Exception {"ErrorCode":1,"SQLite3ErrorCode":"secERROR","Message":"Error SQLITE_ERROR (1) [Step] using 3.25.2 - cannot rollback - no transaction is active, extended_errcode=1"} at 004A2C8F 004A261C 004A1A36 004A1AA0 0049F4D9 0049DC2C 0049B020 00470A28 0046C7EF 00464B1B 00466B5B 0048F86D 005B1DE4 005B1808 005B146F 004264E5 004110B1
20181116 14425607 SQL   	SynSQLite3.TSQLDatabase(0036CAE0) 63.64ms MISTd.db3 ROLLBACK TRANSACTION;

I'm not using explicit transactions, only batches. It must be some king of misplaced "try/except" construct in the mORMot.pas or otherwise stated - concurrency issue.

Best regards,

ab · 2018-11-16 22:49:28

Which version are you using?
I did make some fixes about batch processing some weeks ago IIRC.

alpinistbg · 2018-11-17 09:01:10

1.18.4878

Lazarus 1.9.0
FPC 3.1.1 SVN r63034
i386-win32-win32

TSQLHttpServer kind: useHttpSocket
Database.AcquireWriteMode := amBackgroundThread; {if it makes a difference}

alpinistbg · 2018-11-20 17:56:07

Hi Arnaud,

Considering the above findings and my older posts:
https://synopse.info/forum/viewtopic.ph … 505#p26505

My opinion is that it is not reliable to use mORMot batches for UOW or however we call "atomicity" of logical operations. As I can see, the batches are just an intention to speed-up mass inserts into DB.

The only workaround that comes to my mind is to serialize the objects on the client side and to use dedicated method (enclosed in begin/end transaction) on the server side, i.e. duplicating the TSQLRestServer.EngineBatchSend() functionality.

I'll appreciate your feedback on that issue. Thank you!

Kind regards,

edwinsn · 2018-11-26 12:33:36

@alpinistbg,
I have complete going through all your 3 posts related to these issues related to the client-side batch operations.

The issue
===
I have a POS program which completely relies on the client-side, UOW batch operations, and I had an issue that's almost identical to yours - it happened during a multi-db to central-db syncing process which is implemented using batch process.

When the batch update failed, I found mystery error messages in the log file: "Error SQLITE_ERROR (1) [Step] using 3.15.1 - cannot rollback - no transaction is active, extended_errcode=1", followed by a "TransactionBegin timeout" error .

From the error message I have no clue about what actually went wrong, until many months later, it turned out to be a primary key violation (you know, syncing from many branch db to a central db).

The cause of the error revealed when I have the actual data from the client and running the server-side software in the IDE.

I don't know why neither the mORMot engine log nor the caught exceptions didn't tell me the actual database error messages, otherwise I should have identified the error much much earlier.

But after that, the software which's powered by mORMot has been running for years without issues.

My thoughts
===
- It's a must for ether the server-side log or the BatchSend to tell the actually database system error message, I prefer BatchSend should return the actual database error code and message.

- As @alpinistbg has found out the 2-second timeout for starting a transaction should not be hard-coded - at least it should be customized via a property.

- To implement a retry-able client-side batch update, maybe we can do this:
a, before calling BatchSend, make a copy a the TSQLRestBatch instance.
b, if BatchSend failed, make sure the db is rolled back. @ab, how can the clients get to know this?
c, we can now retry executing BatchSend using the backup copy of TSQLRestBatch we saved earlier.

alpinistbg · 2018-11-26 14:43:05

@edwinsn,

Thanks for sharing your experience!

Currently I have hard times debugging my application, and to be honest, my code also contributed to the issue. As I wrote above there is two things alarming in the log, the first is about "TransactionBegin timeout" and second is that spurious "cannot rollback" thing.

While the former is the one I'm complaining about, the latter was actually provoked by my code. The problem lies into TSQLDataBase.TransactionBegin() method, which detects the active transaction and instead of throwing an exception like "Can't nest transactions", it surprisingly rollbacks the transaction and begins a fresh one! IMHO this is extremely insidious, because it prevents me (developer) from detecting that something is wrong with my code (yes, it is) and throws away all changes made so far without any clue.

Normally, my application works without writing a log. To get this findings I had to make special debug environment with 5 client computers and one server and to record a mouse/keyboard macros to simulate operator activity on each of the client. The macros are replayed at higher speed to stress the server. Even then, I must wait at least one hour to reveal the issue. Then I start digging in a hundred megabytes of log text (@ab: yes, the concurrency is a difficult thing, I agree).

And not surprisingly, the syncing code between the DB-s was involved one more time, the logical operation needs to update the target table and the modifications log table in one batch. That is the relational connection blamed so furiously by Mr Bouchez.

Best regards,

edwinsn · 2018-11-27 14:51:08

alpinistbg wrote:

The problem lies into TSQLDataBase.TransactionBegin() method, which detects the active transaction and instead of throwing an exception like "Can't nest transactions", it surprisingly rollbacks the transaction and begins a fresh one! IMHO this is extremely insidious, because it prevents me (developer) from detecting that something is wrong with my code (yes, it is) and throws away all changes made so far without any clue.

I haven't dig into the source of TransactionBegin, but if what you described is true, it definitely has a room to improve.

mORMot Open Source

#1 2018-11-16 18:47:07

TSQLRestServerDB.EngineBatchSend() exceptions

#2 2018-11-16 22:49:28

Re: TSQLRestServerDB.EngineBatchSend() exceptions

#3 2018-11-17 09:01:10

Re: TSQLRestServerDB.EngineBatchSend() exceptions

#4 2018-11-20 17:56:07

Re: TSQLRestServerDB.EngineBatchSend() exceptions

#5 2018-11-26 12:33:36

Re: TSQLRestServerDB.EngineBatchSend() exceptions

#6 2018-11-26 14:43:05

Re: TSQLRestServerDB.EngineBatchSend() exceptions

#7 2018-11-27 14:51:08

Re: TSQLRestServerDB.EngineBatchSend() exceptions

Board footer