Featurte/silence db log

[pavelmash]

This pull request give developer an option to made a custom SQL execution log on the application layer by expose all necessary properties on ISQLDBStatement layer and mute a build-in SynDB* layer SQL execution logging; As a side effect:

• missing StartTransaction logging added into SynDBODBC & SynDBZeos;
• TSQLDBOracleStatement will use ReplaceParamsByNumbers (:1 :2 works well for Oracle) instead of ReplaceParamsByNames (up to x10 times faster depending on parameters count);
• SQLPrepared property moved into TSQLDBStatement, so SQL can be logged as it passed to DB ( with parameters as it in query replaced to $1 or :1 depends on database, semicolon stripped etc.). The reason for this is what execution plan for statement with parameter almost always is not equal to SQLStatementWithInlineParameters;
• SQLLogTimer is moved into TSQLDBStatement. Can be used it to track query preparation/execution/fetch time on the application layer (for example to log slow queries into separate log level). Before this changes we start one more timer in our code;
• CacheIndex is moved into TSQLDBStatement. Can be used to track statements what hit a prepared statement cache and gather some statistics about it on the application layer;

We have a couple of hi-load production (~100Mb logs per minute) and need to:

• analyze a logs using script (grep, logstash). For example I want to grep all select statements across 200 files 200Mb each, group it by SQL statement and sort by occurrence with avg duration.
• minimize a log output (SynDB exception it too verbose because includes statement)
• log a rows affected, total time(us), time to first row(us), cache hit/miss together with a statement

With help of this patch I can made my logging looks like (4 lines less for every SQL, can be analyzed using RegExp/grep, exception contains only important info): (r=rows affected t=total time(us) fr=time to first row(us) c=cache q=SQL)

20200505 18590825  " info   Long fetch query (t <> tf) 
20200505 18590825  "  +     DataStore.init(uba_user)
20200505 18590825  "  +         App.fetchAllOrExec(conn=main/Oracle11)
20200505 18590826  " debug          P1: Int64   1
20200505 18590850  " SQL            r=3477 t=389472 fr=284732 c=-1 q=select ID, entity, actionType, actionUser, actionUserName, actionTime from uba_auditTrail where 1=:1
20200505 18590850  " cust2          Slow query: t=389472. See statement above
20200505 18590850  "  -         00.389.795
20200505 18590850  "  -     00.393.279
20200505 18590850  " info   Log updated count 
20200505 18590850  "  +     App.fetchAllOrExec(conn=main/Oracle11)
20200505 18590850  " debug      P1: Int64   1
20200505 18590850  "  +         StartTransaction
20200505 18590850  "  -         00.004.677
20200505 18590851  " SQL        r=6 t=5290 c=-1 q=update uba_user set disabled = 0 where 1=:1
20200505 18590851  "  -     00.010.190
20200505 18590851  " info   Preparation error 
20200505 18590851  "  +     DataStore.init(uba_user)
20200505 18590851  "  +         App.fetchAllOrExec(conn=main/Oracle11)
20200505 18590852  " EXC            ESQLDBOracle {"ESQLDBOracle":"TSQLDBOracleStatement error: ORA-00904: "UNKNOWN": invalid identifier"}{"ESQLDBOracle(7f8045473590)":[]} [] at   $000000000075DB08  $000000000076520F  $0000000000766954  $000000000073F35A  $000000000073F207  $00000000005CF7BC  $00000000005D0A7C  $00000000005D9E05  $000000000061AA89  $00007F804FA8BD78
20200505 18590852  " ERROR          q=select UNKNOWN from uba_user where name = ?
20200505 18590852  "  -         00.011.917
20200505 18590852  "  -     00.011.997

Before patch

20200505 19073235  # info   Long fetch query (t <> tf) 
20200505 19073235  #  +     DataStore.init(uba_user)
20200505 19073235  #  +         App.fetchAllOrExec
20200505 19073235  #  +             App.prepareAndRun(conn=main/Oracle11)
20200505 19073235  # debug              Statement cache miss
20200505 19073236  # debug              P1: Int64   1
20200505 19073236  # SQL                select ID, entity, actionType, actionUser, actionUserName, actionTime from uba_auditTrail where 1=?
20200505 19073257  #  -             00.361.875
20200505 19073320  # cust2          Slow query: 761.36ms. See above
20200505 19073320  # DB             3477 row(s) in 752.13ms
20200505 19073320  #  -         00.761.489
20200505 19073320  #  -     00.765.603
20200505 19073320  # info   Log updated count 
20200505 19073320  #  +     App.fetchAllOrExec
20200505 19073320  #  +         App.prepareAndRun(conn=main/Oracle11)
20200505 19073320  # debug          Statement cache miss
20200505 19073320  # debug          P1: Int64   1
20200505 19073320  #  +             StartTransaction
20200505 19073321  #  -             00.006.788
20200505 19073321  # DB             StartT
20200505 19073235  # info   Long fetch query (t <> tf) 
20200505 19073235  #  +     DataStore.init(uba_user)
20200505 19073235  #  +         App.fetchAllOrExec
20200505 19073235  #  +             App.prepareAndRun(conn=main/Oracle11)
20200505 19073235  # debug              Statement cache miss
20200505 19073236  # debug              P1: Int64   1
20200505 19073236  # SQL                select ID, entity, actionType, actionUser, actionUserName, actionTime from uba_auditTrail where 1=?
20200505 19073257  #  -             00.361.875
20200505 19073320  # cust2          Slow query: 761.36ms. See above
20200505 19073320  # DB             3477 row(s) in 752.13ms
20200505 19073320  #  -         00.761.489
20200505 19073320  #  -     00.765.603
20200505 19073320  # info   Log updated count 
20200505 19073320  #  +     App.fetchAllOrExec
20200505 19073320  #  +         App.prepareAndRun(conn=main/Oracle11)
20200505 19073320  # debug          Statement cache miss
20200505 19073320  # debug          P1: Int64   1
20200505 19073320  #  +             StartTransaction
20200505 19073321  #  -             00.006.788
20200505 19073321  # DB             StartTransaction (conn=main)
20200505 19073321  # SQL            update uba_user set disabled = 0 where 1=?
20200505 19073321  #  -         00.018.767
20200505 19073321  # DB         0 row(s) in 11.84ms
20200505 19073321  #  -     00.018.929
20200505 19073321  # info   Preparation error 
20200505 19073321  #  +     DataStore.init(uba_user)
20200505 19073321  #  +         App.fetchAllOrExec
20200505 19073321  #  +             App.prepareAndRun(conn=main/Oracle11)
20200505 19073321  # debug              Statement cache miss
20200505 19073322  # EXC                ESQLDBOracle {"Statement":{"SQL":"select UNKNOWN from uba_user where name = ?","SQLWithInlinedParams":"select UNKNOWN from uba_user where name = ?","CurrentRow":0,"TotalRowsRetrieved":0,"Connection":{"Connected":true,"ServerTimestampAtConnection":"2020-05-05T22:07:32","TotalConnectionCount":1,"TransactionCount":1,"InTransaction":true,"RollbackOnDisconnect":true,"LastErrorMessage":"","LastErrorWasAboutConnection":false,"Properties":{"ClientVersion":"libclntsh.so rev. 19.6.0.0","EnvironmentInitializationMode":135,"InternalBufferSize":131072,"RowsPrefetchSize":131072,"BlobPrefetchSize":4096,"StatementCacheSize":30,"UseWallet":false,"IgnoreORA01453OnStartTransaction":true,"Engine":"ubSQLDBOracle","ServerName":"(DESCRIPTION = (ADDRESS = (PROTOCOL = TCP)(HOST = ora12.unitybase.info)(PORT = 15211)) (CONNECT_DATA = (SERVER = DEDICATED) (SERVICE_NAME = oraub.cloud.local)))","DatabaseNameSafe":"","UserID":"UB5_AUTOTEST_LIN","DBMS":"Oracle","DBMSEngineName":"Oracle","BatchSendingAbilities":["Create","Update","Delete"],"BatchMaxSentAtOnce":10000,"LoggedSQLMaxSize":-1,"LogSQLStatementOnException":false,"ForcedSchemaName":"","UseCache":true,"RollbackOnDisconnect":true,"StoreVoidStringAsNull":false,"VariantStringAsWideString":false}},"StripSemicolon":true},"Message":"TSQLDBOracleStatement error: ORA-00904: \"UNKNOWN\": invalid identifier"} [] at 747c66 74f62f 750b85 74a215 5c481e 5c5b01 5cf68d 60d86f 7fc1a0e90d08
20200505 19073322  # ERROR              "ESQLDBOracle(7fc199380180)":{"ESQLDBOracle(7fc199380180)":{"Statement":{"TSQLDBOracleStatement(7fc19968e460)":{"SQL":"select UNKNOWN from uba_user where name = ?","SQLWithInlinedParams":"select UNKNOWN from uba_user where name = ?","CurrentRow":0,"TotalRowsRetrieved":0,"Connection":{"TubSQLDBOracleConnection(7fc1988b7180)":{"Connected":true,"ServerTimestampAtConnection":"2020-05-05T22:07:32","TotalConnectionCount":1,"TransactionCount":1,"InTransaction":true,"RollbackOnDisconnect":true,"LastErrorMessage":"","LastErrorWasAboutConnection":false,"Properties":{"TubSQLDBOracleConnectionProperties(023252a0)":{"ClientVersion":"libclntsh.so rev. 19.6.0.0","EnvironmentInitializationMode":135,"InternalBufferSize":131072,"RowsPrefetchSize":131072,"BlobPrefetchSize":4096,"StatementCacheSize":30,"UseWallet":false,"IgnoreORA01453OnStartTransaction":true,"Engine":"ubSQLDBOracle","ServerName":"(DESCRIPTION = (ADDRESS = (PROTOCOL = TCP)(HOST = ora12.unitybase.info)(PORT = 15211)) (CONNECT_DATA = (SERVER = DEDICATED) (SERVICE_NAME = oraub.cloud.local)))","DatabaseNameSafe":"","UserID":"UB5_AUTOTEST_LIN","DBMS":"Oracle","DBMSEngineName":"Oracle","BatchSendingAbilities":["Create","Update","Delete"],"BatchMaxSentAtOnce":10000,"LoggedSQLMaxSize":-1,"LogSQLStatementOnException":false,"ForcedSchemaName":"","UseCache":true,"RollbackOnDisconnect":true,"StoreVoidStringAsNull":false,"VariantStringAsWideString":false}}}},"StripSemicolon":true}},"Message":"TSQLDBOracleStatement error: ORA-00904: \"UNKNOWN\": invalid identifier"}}
20200505 19073322  # SQL                select UNKNOWN from uba_user where name = ?
20200505 19073322  # DB                 0 row(s) in 11.50ms
20200505 19073322  # EXC                EMetabaseException {"errorCode":0,"Message":"Internal server error"} [] at 5c4889 5c5b01 5cf68d 60d86f 7fc1a0e90d08
20200505 19073322  #  -             00.011.705
20200505 19073322  #  -         00.011.760
20200505 19073322  #  -     00.011.814ransaction (conn=main)
20200505 19073321  # SQL            update uba_user set disabled = 0 where 1=?
20200505 19073321  #  -         00.018.767
20200505 19073321  # DB         0 row(s) in 11.84ms
20200505 19073321  #  -     00.018.929

[synopse]

Why not include the new log layout (with r=rows affected t=total time(us) fr=time to first row(us) c=cache q=SQL information) into the trunk? I am not fixed with the previous log content. Yours seems much better. So instead of "silent" the current log, replace it with your layout.

[pavelmash]

Will be good to move this into trunk. I review UnityBase code and now I see what I can do it! The problem I can't solve before is a "total fetch time":

• in case statement does not expect result we can put new logging layout inside ExecutePrepared - this is how I did non-result logging in UnityBase because in this case "total time" === "time to first row"

• in case statement expects result then "total time" = "time to first row" + "fetch time". In UB I have a single method what do actual fetch and implement "total time" logging after call to .FetchAllAsJSON

But I can't put a final log inside FetchAllAsJSON because other app what use SynDB can use while stmt.Step do circle or similar.

But what if I add a final log for statement with result inside Step() function (in case step returns false we already in the end of cursor, so we know total fetch time)? The only BREAKING here is the case when some application did a long operation inside while stmt.Step do - in such code developer will need to add log timer pause/resume as such:

while stmt.Step do begin
  stmt.SQLLogTimer.Pause;
  // do some long operation
  stmt.SQLLogTimer.Resume;
end

@synopse - if you approve such an approach I implement it

[synopse]

Please use ISQLDBRows.Instance to access the timer/sql/cache properties.