Make the SynDB logging for the TSQLDBStatement descendants the same

mpv · 2016-12-17 13:10:38

@AB, in current implementation we have a different sllDB log output during destroying of the descendants of TSQLDBStatement:

- TSQLDBOracleStatement.Destroy put to log a total row count and time - this is VERY good, since I have a grep script to parse a slow query from logs
- TOleDBStatement.Destroy logs self (this is bad, because log becomes very verbose) and do not log a total time. Instead OleDb log a execution time in sllSQL by prepending a SQL query text by time - this is bad, because I can't parse all SQLs from logs
- ZEOS do not put anything into log
- etc

So my propose is to add a logging of the total rows and execution time to the TSQLDBStatement.Destroy (as in Oracle now) and remove logging from descendants destruction

It you don't mind I can do this modification?

Last edited by mpv (2016-12-17 14:03:47)

mpv · 2016-12-17 13:57:19

Ups..... I miss a statement caching. In case statements is cached it destroyed during connection closing.
In case of OleDb this is IMHO wrong - in OleDB - we re-prepare a statement every time it executed, so there is no reason in UseCache (even more - we keep a rowset in memory but never use it again) - may be set UseCache to false implicitly in TOleDBConnectionProperties?
For Oracle the caching is overrided and work OK
Not sure for ZEOS statements

mpv · 2020-03-21 20:14:54

Just to not forgot what UseCache problem is still exists. Corresponding today post in SynDBPostgres thread

ab · 2020-03-22 02:32:23

Please try https://synopse.info/fossil/info/e41e9c4085

When ISQLDBStatement is not used any more, its RefCount=1 and the new TSQLDBSTatement.ReleaseResource is called.
Depending on the provider, it would release the opened cursor. For instance, with SynDBPostgres it calls PQ.Clear(fRes).
It should keep the memory consumption low.

Feedback is very welcome, since it may change how statements are reused/cached.

mpv · 2020-03-22 09:37:12

This approach not work in case I have a function like such:

function InternalDBExecute(...)
var
  Query: ISQLDBStatement;
begin
  ...
  Query := safeConnection.NewStatementPrepared(...)  <--- refcount =1
  Query.ExecutePrepared;
   result := Query; // returns not nil interface on success     <--- refcount =2
  ...
end;   <--- refcount =1 ReleaseResources is called but caller expect Query to contains a result

mpv · 2020-03-22 10:17:53

@ab - I consider to remove SynDB statement level cache at all;
- I test with Postgres (override IsCachable to always return false) - the differences between SynDB level cache /no cache is too small (~0.5%)
- Oracle also do not use this feature from the beginning
This is KISS

Another approach is to move all information about statement what do not related to cursor into separate class (and descendants)

TStatementInfo = class
  fConnection: TSQLDBConnection;
  fSQL: RawUTF8;
  fExpectResults: boolean;
  fParamCount: integer;
  fColumnCount: integer;
  fColumns: TSQLDBColumnPropertyDynArray;
  fColumn: TDynArrayHashed;
end;

TStatementInfoPg = class(TStatementInfo)
  fPreparedStmtName: RawUTF8; // = SHA-256 of the SQL
  fPreparedParamsCount: integer;
  fPGParams: TPointerDynArray;
  fPGParamFormats: TIntegerDynArray;
  fPGparamLengths: TIntegerDynArray;
end;

Store a reference to TStatementInfo in the TSQLDBStatement

TSQLDBStatement = class(..)
  fStatementInfo: TStatementInfo;  // Or use interface here? a little overhead by easier when manage using fOwnsStatetementInfo
  fOwnsStatetementInfo: boolean; // if true - destroy StatementInfo in destructor; if false - it's cached and will be destroyed by cache
  // below only cursor related props

And cache only this TStatementInfo descendants. Something like

function TSQLDBConnection.NewStatementPrepared
  // Stmt := fCache.Objects[ndx];  // instead of cache whole statement 
  Stmt.statementInfo := fCache.Objects[ndx] // we cache only statement info

Last edited by mpv (2020-03-22 10:19:10)

ab · 2020-03-22 11:08:56

Please check https://synopse.info/fossil/info/a1dfe9124e

I guess that with PostgreSQL, caching is already done in libpq, thanks to the statement naming.
This is why you don't find a difference in your tests.

But when the engine has very low latency, e.g. for SQlite3, or when preparing a statement has a cost, e.g. initializing a TDataSet/TQuery is slow for a single rows SELECT, it makes a huge speed performance to reuse statements.
Of course, for SQlite3 cache is embedded at SynSQLite3.pas level.
Perhaps I would get rid of the high-level cache in mORMot2, and only use provider-level dedicated cache...

AOG · 2020-03-22 11:37:54

Perhaps I would get rid of the high-level cache in mORMot2, and only use provider-level dedicated cache...

Perhaps a very good idea. Its hard to make good use of cache in certain scenarios.

mpv · 2020-03-22 13:26:41

I test latest changes. With small modification in my code (paranoid Rows.ReleaseRows added) it works and pass all my regression test;

About get rid of the high-level cache in mORMot2 - this is nice!

The state of provider (driver) level cache for RDBMS I know (and use in production):
- Postgres: implemented if SynDBPostgres using driver feature
- Oracle: implemented is SynDBOracle using driver feature (MRU)
- ODBC: at last for MS SQL should work transparently for us on ODBC driver layer. Seams current SynDBODBC implementation can be optimized - I investigate possible optimizations (have some ideas)
- OleDB: hope the same as for ODBC
- SQLite3: embedded at SynSQLite3.pas level

So actually high-level cache needed only for TDataSet/TQuery. But!

For client-side classes like TDataSet/TQuery using driver-level prepared statement is dangerous (IMHO). Database will cache planes for each connection.
- in case of application server we have a connection pool and can control amount of connections we did
- in case of client-server (where TDataSet/TQuery is usually used) we do not know how many clients will connect to DB; Depending of DB we kill it early (for example Postgres forks for each connection) or latterly (for example Oracle can handle up to ~4000 connection without turning, > 4000 is a hard-to-solve problem); In case we adds a prepared plans for each GUI application connection we accelerate the fall of the database.

Last edited by mpv (2020-03-22 13:29:24)

ab · 2020-03-22 14:08:39

Please check https://synopse.info/fossil/info/012ea78b2f about big refactoring to have as consistent Prepare/ExecutePrepared log information in all SynDB units.
Now updatecount and rows are logged, with proper timing - if available.

Thanks for the feedback about caching statements.
Worth thinking more about it.
Two hints:
- TDataSet/TQuery is the slowest path, anyway...
- SynDBZeos: cache was buggy also depending on driver.
So cache can be added on purpose, after proper testing - it is the user responsibility.
By default, we may just disable it. Better safe than buggy.

Any ODBC optimisation is welcome! It would benefit mostly of MySQL - which uses is not adviced for serious work.
I am very happy with the SynDBPostgres unit, since this DB is just the best Open Source SQL DB available for business-level use.

mpv · 2020-03-22 14:19:19

We use ODBC to access MS SQL from Linux, so i can test it on real app.... May be I wrote a SynDBMssql using freeTDS library if ODBC optimization do not give me performance I need

mpv · 2020-03-22 19:15:43

I dig into .NET SQL server access sources (System/Data/SqlClient/SqlCommand.cs) - as expected Microsoft do not eat their own ODBC \ OLEDB shit and directly use TDS protocol with sp_prepexec call. So freeTDS is a way to go. I will study it slowly...

ab · 2020-03-22 22:19:29

And if you put a SynDBRemote instance on the Windows server, and talk to it from Linux?
If you don't require complex transactions, it should work with very high performance.

FreeTDS seems less maintained than MS ODBC driver, and with lower performance....

EgonHugeist · 2020-03-23 07:53:32

ab wrote:

Thanks for the feedback about caching statements.
Worth thinking more about it.
Two hints:
- TDataSet/TQuery is the slowest path, anyway...
- SynDBZeos: cache was buggy also depending on driver.
So cache can be added on purpose, after proper testing - it is the user responsibility.
By default, we may just disable it. Better safe than buggy.

Writing bad critics is almost quickly done and very easy. What !is! buggy? Or just !was! something buggy?
I start from the premisse you mean !IT IS SOMETHING BUGGY! otherwise you would'nt consider disabling the stmt-cache.
Any examples? You did never open a ticket, nor did you enter the zeos forum to report problems.
I usually did fix everything i could see or which was reported. So such statements are not fair. <- whithout beeing rude

ab · 2020-03-23 09:21:26

@Michael
Please keep calm and drink something sweet.
I never meant ZDBC was buggy.
The SynDBZeos cache was buggy, nothing in the ZDBC layer.
The context of this thread is about the global SynDB statement cache, which is buggy in the sense that depending on how we implemented the SynDB* units, the Reset method was sometimes not enough to re-use the statement.
The bug I wrote about is in our code, not yours.

ab · 2020-03-23 10:38:28

@mpv
About caching.
I just discovered that PostgreSQL features server-side caching.
https://www.postgresql.org/docs/current … epare.html https://www.postgresql.org/docs/current … ecute.html https://www.postgresql.org/docs/current … ocate.html
Did you test and benchmark it?

mpv · 2020-03-23 10:49:12

This is what we actually use now in SynDBPostgres. The call to PQ.Prepare is the same as SQL instruction `PREPARE name [ ( data_type [, ...] ) ] AS statement`

ab · 2020-03-23 11:44:35

Nice!

mpv · 2020-05-05 19:29:05

@ab, after a long-long investigation I decide what this is impossible to made a SynDB* loging to be in format I need.
The reason is what on the SynDB layer there is not enough information for this.

So I decide to made a pull request what mute most of SynDB log output and expose to developer additional statement properties, what allows to made a very custom SQL execution logging on the application layer.

To not pollute a blog I put a detailed description with log examples into #310 pull request description

Please, give me your feedback - this is extremely important for me. I do not have access to many of my productions and logging is an only thing a have to analyse a performance bottleneck / errors etc. And my logs is huge

Last edited by mpv (2020-05-05 19:29:49)

mpv · 2020-05-06 11:51:32

A LogView`er stat (all levels - turned on for bug hunting purpose) from one of my production, just to prove what logging is very important for me

~1 200 HTTP request/sec, ~4 300 DB query / sec. All http request is API (all static served directly by nginx). OS: Linux (THTTPServer), RDBMS: Oracle (SynDBOracle)

Started: 04.05.20 11:15:17
Closed:  04.05.20 11:46:59
Time elapsed: 0.00:31:42
Events: 2192333
Methods: 665773
Threads: 16
Size: 151 MB

Events
------

Info: 72768
Debug: 438081
Warning: 641
Error: 35
Enter: 665773
Leave: 665780
Exception: 33
SQL: 133306
DB: 139806
HTTP: 38156
Server: 1
Service call: 19073
User auth: 18615
Custom 1: 67
Custom 2: 194

Last edited by mpv (2020-05-06 11:53:26)

mORMot Open Source

#1 2016-12-17 13:10:38

Make the SynDB logging for the TSQLDBStatement descendants the same

#2 2016-12-17 13:57:19

Re: Make the SynDB logging for the TSQLDBStatement descendants the same

#3 2020-03-21 20:14:54

Re: Make the SynDB logging for the TSQLDBStatement descendants the same

#4 2020-03-22 02:32:23

Re: Make the SynDB logging for the TSQLDBStatement descendants the same

#5 2020-03-22 09:37:12

Re: Make the SynDB logging for the TSQLDBStatement descendants the same

#6 2020-03-22 10:17:53

Re: Make the SynDB logging for the TSQLDBStatement descendants the same

#7 2020-03-22 11:08:56

Re: Make the SynDB logging for the TSQLDBStatement descendants the same

#8 2020-03-22 11:37:54

Re: Make the SynDB logging for the TSQLDBStatement descendants the same

#9 2020-03-22 13:26:41

Re: Make the SynDB logging for the TSQLDBStatement descendants the same

#10 2020-03-22 14:08:39

Re: Make the SynDB logging for the TSQLDBStatement descendants the same

#11 2020-03-22 14:19:19

Re: Make the SynDB logging for the TSQLDBStatement descendants the same

#12 2020-03-22 19:15:43

Re: Make the SynDB logging for the TSQLDBStatement descendants the same

#13 2020-03-22 22:19:29

Re: Make the SynDB logging for the TSQLDBStatement descendants the same

#14 2020-03-23 07:53:32

Re: Make the SynDB logging for the TSQLDBStatement descendants the same

#15 2020-03-23 09:21:26

Re: Make the SynDB logging for the TSQLDBStatement descendants the same

#16 2020-03-23 10:38:28

Re: Make the SynDB logging for the TSQLDBStatement descendants the same

#17 2020-03-23 10:49:12

Re: Make the SynDB logging for the TSQLDBStatement descendants the same

#18 2020-03-23 11:44:35

Re: Make the SynDB logging for the TSQLDBStatement descendants the same

#19 2020-05-05 19:29:05

Re: Make the SynDB logging for the TSQLDBStatement descendants the same

#20 2020-05-06 11:51:32

Re: Make the SynDB logging for the TSQLDBStatement descendants the same

Board footer