Benchmark reveals relatively slow deletes in batch/transaction mode

h.hasenack · 2012-08-21 11:10:01

Here's a short overview of benchmarks using an oracle 10g server over a LAN. Same test is performed using combinations of batch and transactions. The Create records routine stops after 2000 ms, and the resulting records are used in the next steps, using same transactional and batch mode settings.

Process Start: C:\Users\Hans\Sources\Libsource\mORMot\UnitTest\TestOracle.exe. Base Address: $00400000. Process TestOracle.exe (6012)
Debug Output: 138 records added, avg speed 69 rps Batch=False Transaction=False Process TestOracle.exe (6012)
Debug Output: 138 records fetched, avg speed 590 rps  Process TestOracle.exe (6012)
Debug Output: 138 records modified, avg speed 354 rps Batch=False Transaction=False Process TestOracle.exe (6012)
Debug Output: 138 records deleted, avg speed 442 rps Batch=False Transaction=False Process TestOracle.exe (6012)
Debug Output: 139 records added, avg speed 70 rps Batch=False Transaction=True Process TestOracle.exe (6012)
Debug Output: 139 records fetched, avg speed 594 rps  Process TestOracle.exe (6012)
Debug Output: 139 records modified, avg speed 446 rps Batch=False Transaction=True Process TestOracle.exe (6012)
Debug Output: 139 records deleted, avg speed 468 rps Batch=False Transaction=True Process TestOracle.exe (6012)
Debug Output: 58.001 records added, avg speed 29.001 rps Batch=True Transaction=False Process TestOracle.exe (6012)
Debug Output: 58.001 records fetched, avg speed 109.436 rps  Process TestOracle.exe (6012)
Debug Output: 58.001 records modified, avg speed 12.863 rps Batch=True Transaction=False Process TestOracle.exe (6012)
Debug Output: 58.001 records deleted, avg speed 1.025 rps Batch=True Transaction=False Process TestOracle.exe (6012)
Debug Output: 55.001 records added, avg speed 27.501 rps Batch=True Transaction=True Process TestOracle.exe (6012)
Debug Output: 55.001 records fetched, avg speed 113.638 rps  Process TestOracle.exe (6012)
Debug Output: 55.001 records modified, avg speed 12.638 rps Batch=True Transaction=True Process TestOracle.exe (6012)
Debug Output: 55.001 records deleted, avg speed 1.038 rps Batch=True Transaction=True Process TestOracle.exe (6012)

What strikes me is the relatively poor performance on deleting records, I had expected it to be faster than modify. I did not examine yet wheter most time is spent in OCI or the mormot/sqlite3 framework.

What is your opinion? Do you want my unit test to try it yourself?

Hans

ab · 2012-08-21 11:58:15

Array DML binding would benefit only for Update + Insert, AFAIR.

You may try to nest your deletion within a transaction, and let only 1000 items be deleted per commit.

OR, what if you disable array DML binding by setting BatchSendingAbilities := [] for the oracle properties instead of [cCreate,cUpdate,cDelete].

But sounds like if it was a known limitation of the Oracle engine itself.
See http://asktom.oracle.com/pls/asktom/f?p … 3906925164
and http://www.dba-oracle.com/t_delete_perf … _speed.htm

As soon as it is faster than "non Batch" delete, sounds OK to me.

Thanks for the report.

h.hasenack · 2012-08-21 12:17:09

All batch operations and transactions were "mod 1000" already in this case.

Changing FBatchSendingAbilities just made things for batchmode same as for unbatched mode. (Which was logical)

I'll run some AQTime profile and see what it brings.

Regards - Hans

h.hasenack · 2012-08-21 12:27:01

Hi AB.

It looks like the TSQLDBOracleLib::ClobFromDescriptor takes all the time. (92.91%). This is ONLY for the (batched) delete action. Thgis is strange, I did not expect any BLOB/CLOB handling to be neccesary when deleting a bunch of records :s

- sorry for the format of the data , I do not have the time to make a nice table format -

Regards - Hans

Routine Name	% Time	Time	Time with Children	Shared Time	Hit Count
TSQLDBOracleLib::ClobFromDescriptor	92,9069061902652	25,7616422925527	25,7942729994605	99,8734963109509	31001
TSQLDBOracleStatement::ExecutePrepared	4,24131770456711	1,17605153410627	1,17707970966844	99,9126503028027	33
TSQLDBOracleStatement::Step	1,42987056537413	0,396480902661659	0,396480902661659	100	31002
TSQLDBOracleStatement::ColumnsToJSON	0,179882267176309	0,0498785592136639	25,8898052263941	0,192657143526185	31001
TPropInfo::SetValue	0,159425287046616	0,0442061563095382	0,10459283614875	42,2649943698522	186006
TSQLDBOracleLib::Check	0,117679532662149	0,0326307069077142	0,0326307069077142	100	124004
UTF8DecodeToUnicodeString	0,0861917809202405	0,0238996423374387	0,0383495796003135	62,320480658524	155005
GetJSONField	0,0772425465674471	0,0214181586281787	0,0214181586281787	100	279050
StrLen	0,0707899124296421	0,0196289433876839	0,0196289433876839	100	217007

ab · 2012-08-21 14:50:30

You are right, it should not call ClobFromDescriptor() at all during deletion time.

I suspect you did run some select during your AQTime benchmark.

Or there is some issue in the BATCH sequence code.
Could you put a breakpoint and find where those ClobFromDescriptor() calls come from?

h.hasenack · 2012-08-22 07:08:23

Yes you were right. In My test I had to call CreateAndFillPrepare, and this took the most time.
I separated the timing mesasurements, CreateAndFillPrepare is now displayed as 'Query took ... ms' and the tested operation is measurured independently. This produces quite a different picture:

Process Start: C:\Users\Hans\Sources\Libsource\mORMot\UnitTest\TestOracle.exe. Base Address: $00400000. Process TestOracle.exe (5620)
Debug Output: ---CREATE TEST--- Process TestOracle.exe (5620)
Debug Output: 138 records added, avg speed 69 rps Batch=False Transaction=False Process TestOracle.exe (5620)
Debug Output: ---READ TEST--- Process TestOracle.exe (5620)
Debug Output: Query took 234 ms Process TestOracle.exe (5620)
Debug Output: 138 records fetched, avg speed 138.000 rps Process TestOracle.exe (5620)
Debug Output: ---MODIFY TEST--- Process TestOracle.exe (5620)
Debug Output: Query took 0 ms Process TestOracle.exe (5620)
Debug Output: 138 records modified, avg speed 402 rps Batch=False Transaction=False Process TestOracle.exe (5620)
Debug Output: ---DELETE TEST--- Process TestOracle.exe (5620)
Debug Output: Query took 234 ms Process TestOracle.exe (5620)
Debug Output: 138 records deleted, avg speed 1.468 rps Batch=False Transaction=False Process TestOracle.exe (5620)
Debug Output: ---CREATE TEST--- Process TestOracle.exe (5620)
Debug Output: 137 records added, avg speed 69 rps Batch=False Transaction=True Process TestOracle.exe (5620)
Debug Output: ---READ TEST--- Process TestOracle.exe (5620)
Debug Output: Query took 234 ms Process TestOracle.exe (5620)
Debug Output: 137 records fetched, avg speed 137.000 rps Process TestOracle.exe (5620)
Debug Output: ---MODIFY TEST--- Process TestOracle.exe (5620)
Debug Output: Query took 0 ms Process TestOracle.exe (5620)
Debug Output: 137 records modified, avg speed 463 rps Batch=False Transaction=True Process TestOracle.exe (5620)
Debug Output: ---DELETE TEST--- Process TestOracle.exe (5620)
Debug Output: Query took 234 ms Process TestOracle.exe (5620)
Debug Output: 137 records deleted, avg speed 2.175 rps Batch=False Transaction=True Process TestOracle.exe (5620)
Debug Output: ---CREATE TEST--- Process TestOracle.exe (5620)
Debug Output: 57.001 records added, avg speed 28.501 rps Batch=True Transaction=False Process TestOracle.exe (5620)
Debug Output: ---READ TEST--- Process TestOracle.exe (5620)
Debug Output: Query took 499 ms Process TestOracle.exe (5620)
Debug Output: 57.001 records fetched, avg speed 1.838.742 rps Process TestOracle.exe (5620)
Debug Output: ---MODIFY TEST--- Process TestOracle.exe (5620)
Debug Output: Query took 0 ms Process TestOracle.exe (5620)
Debug Output: 57.001 records modified, avg speed 12.020 rps Batch=True Transaction=False Process TestOracle.exe (5620)
Debug Output: ---DELETE TEST--- Process TestOracle.exe (5620)
Debug Output: Query took 47.643 ms Process TestOracle.exe (5620)
Debug Output: 57.001 records deleted, avg speed 10.121 rps Batch=True Transaction=False Process TestOracle.exe (5620)
Debug Output: ---CREATE TEST--- Process TestOracle.exe (5620)
Debug Output: 52.001 records added, avg speed 26.001 rps Batch=True Transaction=True Process TestOracle.exe (5620)
Debug Output: ---READ TEST--- Process TestOracle.exe (5620)
Debug Output: Query took 468 ms Process TestOracle.exe (5620)
Debug Output: 52.001 records fetched, avg speed 3.250.063 rps Process TestOracle.exe (5620)
Debug Output: ---MODIFY TEST--- Process TestOracle.exe (5620)
Debug Output: Query took 0 ms Process TestOracle.exe (5620)
Debug Output: 52.001 records modified, avg speed 8.052 rps Batch=True Transaction=True Process TestOracle.exe (5620)
Debug Output: ---DELETE TEST--- Process TestOracle.exe (5620)
Debug Output: Query took 43.493 ms Process TestOracle.exe (5620)
Debug Output: 52.001 records deleted, avg speed 25.255 rps Batch=True Transaction=True Process TestOracle.exe (5620)

What is remarkable : The query run for the delete took 44 s. wheras the exactly the same query run for read and modify test took only 0..450 ms. I guess it has something to do with mormot (or maybe oracle) being busy storing the modifications of the modify test.

I did not investigate, but I'm quire sure there's a way to delete records without fetching them first. (like DELETE FROM .... WHERE ...). This would avoid the CLobFromDescriptor call as well.

Regards - Hans

mORMot Open Source

#1 2012-08-21 11:10:01

Benchmark reveals relatively slow deletes in batch/transaction mode

#2 2012-08-21 11:58:15

Re: Benchmark reveals relatively slow deletes in batch/transaction mode

#3 2012-08-21 12:17:09

Re: Benchmark reveals relatively slow deletes in batch/transaction mode

#4 2012-08-21 12:27:01

Re: Benchmark reveals relatively slow deletes in batch/transaction mode

#5 2012-08-21 14:50:30

Re: Benchmark reveals relatively slow deletes in batch/transaction mode

#6 2012-08-22 07:08:23

Re: Benchmark reveals relatively slow deletes in batch/transaction mode

Board footer