How hard it is to implement a new event in TZSQLMonitor?

[aehimself]

Btw. is the elapsed time available in the logs?

Hell yes, they are! Look at the end of each logged line ;)

[EgonHugeist]

I'm asking because after https://sourceforge.net/p/zeoslib/code-0/6728/ my logs are looking like:

'2020-07-23 06:07:25.491' cat: Prepare, proto: sqlite, msg: Statement 4 : PRAGMA table_info('Orders')
'2020-07-23 06:07:25.491' cat: Execute prepared, proto: sqlite, msg: Statement 4, elapsed time: '00:00:00.000'
'2020-07-23 06:07:25.492' cat: Prepare, proto: sqlite, msg: Statement 5 : select sql from sqlite_master where name = 'Orders'
'2020-07-23 06:07:25.492' cat: Execute prepared, proto: sqlite, msg: Statement 5, elapsed time: '00:00:00.000'
'2020-07-23 06:07:25.492' cat: Fetch complete, proto: sqlite, msg: Statement 4, fetched row(s): 14
'2020-07-23 06:07:25.493' cat: Execute prepared, proto: sqlite, msg: Statement 2, elapsed time: '00:00:00.003'
'2020-07-23 06:07:25.502' cat: Fetch complete, proto: sqlite, msg: Statement 2, fetched row(s): 830
'2020-07-23 06:07:25.505' cat: Prepare, proto: sqlite, msg: Statement 6 : select * from Orders

'2020-07-23 06:07:25.506' cat: Execute prepared, proto: sqlite, msg: Statement 6, elapsed time: '00:00:00.001'
'2020-07-23 06:07:25.514' cat: Fetch complete, proto: sqlite, msg: Statement 6, fetched row(s): 830

As you can see, sometimes the millisecond precision isn't enougth. That's why i was thinking about using

GetTickCount64 (since Windows Vista, Other OS's are unclear yet).. or The QueryPerformanceCounter
Volunteers for doing that?

[aehimself]

As you can see, sometimes the millisecond precision isn't enougth. That's why i was thinking about using

GetTickCount64 (since Windows Vista, Other OS's are unclear yet).. or The QueryPerformanceCounter
Volunteers for doing that?

What about https://stackoverflow.com/questions/139 ... tstopwatch? Seems to be a TStopWatch implementation for Linux and Windows, which should be FPC compatible.

On the other hand, though, does it really worth the hassle with displaying usec? I am personally completely uninterested; my time measurement ends with msec.

[Fr0sT]

GTC64 is for storing big numbers, it has the same precision as GTC32

[aehimself]

Working as expected! Question though, how come sometimes it's Fetch and then Execute, sometimes the other way around?
SQLTrace events are with bold below.

Connecting to testmysl.lan...
AutoEncodeStrings=True, controls_cp=CP_UTF16, codepage=utf8mb4
CONNECT TO "TESTDB" AS USER "testuser"
Fetch Statement 1, affected 1 row(s) in 12 ms
Execute Statement 1 : show variables like 'version' in 12 ms
Fetch Statement 2, affected 1 row(s) in 9 ms
Execute Statement 2 : show variables like 'version_comment' in 9 ms
Fetch Statement 3, affected 1 row(s) in 2 ms
Execute Statement 3 : select database() as 'DATABASE' in 2 ms
Transaction SET SESSION TRANSACTION ISOLATION LEVEL READ UNCOMMITTED
Execute Native SetAutoCommit False call, affected 0 row(s)
Collecting schema names...
Schema names successfully collected in 60 milliseconds
Collecting table names...
Fetch Statement 4, affected 1 row(s) in 11 ms
Execute Statement 4 : show variables like 'lower_case_table_names' in 11 ms
Execute Statement 5 : SHOW TABLES FROM testdb LIKE '%' in 7 ms
Fetch Statement 5, affected 11 row(s) in 7 ms
Table names successfully collected in 71 milliseconds
Successfully connected to testmysl.lan in 694 milliseconds. MySQL 8.0.18, client version: 8.0.18
Executing query... <- manual query execucion
Execute Statement 6 : UPDATE TESTTABLE SET FIELD = 1 WHERE FIELD2 = 8 , affected 1 row(s) in 4 ms
Query affected 1 row(s) in 61 milliseconds

[EgonHugeist]

Lorbs, should be fixed now. Plz test!?

[aehimself]

Seems much more consistent!

[2020.07.24 07:42:16.769] Disconnecting...
[2020.07.24 07:42:16.863] Disconnected.
[2020.07.24 07:42:16.863] Connecting to testmysql.lan...
[2020.07.24 07:42:16.863] AutoEncodeStrings=True, controls_cp=CP_UTF16, codepage=utf8mb4
[2020.07.24 07:42:17.130] CONNECT TO "TESTDB" AS USER "TESTUSER"
[2020.07.24 07:42:17.144] Execute Statement 1 : show variables like 'version' in 14 ms
[2020.07.24 07:42:17.144] Fetch Statement 1, affected 1 row(s) in 14 ms
[2020.07.24 07:42:17.144] Execute Statement 2 : show variables like 'version_comment' in 0 ms
[2020.07.24 07:42:17.144] Fetch Statement 2, affected 1 row(s) in 0 ms
[2020.07.24 07:42:17.160] Execute Statement 3 : select database() as 'DATABASE' in 0 ms
[2020.07.24 07:42:17.160] Fetch Statement 3, affected 1 row(s) in 0 ms
[2020.07.24 07:42:17.160] Transaction SET SESSION TRANSACTION ISOLATION LEVEL READ UNCOMMITTED
[2020.07.24 07:42:17.160] Execute Native SetAutoCommit False call, affected 0 row(s)
[2020.07.24 07:42:17.230] Collecting schema names...
[2020.07.24 07:42:17.285] Schema names successfully collected in 56 milliseconds
[2020.07.24 07:42:17.285] Collecting table names...
[2020.07.24 07:42:17.314] Execute Statement 4 : show variables like 'lower_case_table_names' in 13 ms
[2020.07.24 07:42:17.314] Fetch Statement 4, affected 1 row(s) in 13 ms
[2020.07.24 07:42:17.314] Execute Statement 5 : SHOW TABLES FROM testdb LIKE '%' in 0 ms
[2020.07.24 07:42:17.314] Fetch Statement 5, affected 11 row(s) in 0 ms
[2020.07.24 07:42:17.347] Table names successfully collected in 57 milliseconds
[2020.07.24 07:42:17.347] Successfully connected to testmysql.lan in 573 milliseconds. MySQL 8.0.18, client version: 8.0.18
[2020.07.24 07:44:40.418] Executing query...
[2020.07.24 07:44:40.439] Execute Statement 6 : UPDATE MYTABLE SET FIELD = 1 WHERE FIELD2 = 8 in 4 ms
[2020.07.24 07:44:40.478] Query affected 1 row(s) in 59 milliseconds

However...

While
[2020.07.24 07:42:17.160] Execute Native SetAutoCommit False call, affected 0 row(s)
returns an affected row number,
[2020.07.24 07:44:40.439] Execute Statement 6 : UPDATE MYTABLE SET FIELD = 1 WHERE FIELD2 = 8 in 4 ms
broke.

[EgonHugeist]

Yes you are, right. Fixed inbetween. I found some more related issues on other driver. Thank you for reporting. Please test, and report your findings. Bussy in backend......

[aehimself]

I know, I saw the commit in SVN and now sitting on needles to receive them in Git. And I'm really sorry that you had to work with something I wanted. I really owe you a beer, this time.

Ps.: is it on purpose that if a statement execution fails, the message does not include the statement number?

I am using a custom way to log messages in the OnTrace event, which goes something like this:

Code: Select all

Case Event.Category Of
  lcExecute: logmsg := logmsg + 'Execute ';
  lcExecPrepStmt: logmsg := logmsg + 'Execute prepared ';
  lcFetchDone: logmsg := logmsg + 'Fetch ';
End;
If String(Event.Error) <> '' Then logmsg := logmsg + 'statement failed' + LogEventError(Event)
  Else Begin
    logmsg := logmsg + eventmsg;
    If Event.ErrorCodeOrAffectedRows > -1 Then logmsg := logmsg + ', affected ' + Event.ErrorCodeOrAffectedRows.ToString + ' row(s)';
  End;

And with this, failed requests can be logged like this:

[2020.07.24 20:29:55.933] Execute statement failed Unknown column 'NOEXISTFIELD' in 'field list' (#1054)
[2020.07.24 20:29:58.173] EZSQLException was raised while executing query with the message: SQL Error: Unknown column 'NOEXISTFIELD' in 'field list' SQL: UPDATE MYTABLE SET NOEXISTFIELD = null

Behavior is the same on MySQL and on Oracle (however, on Oracle it is prepared first so it has a statement number):

[2020.07.24 20:31:00.998] Prepare Statement 10 : SELECT * FROM MYTABLE WHERE NOEXISTFIELD < 10
[2020.07.24 20:31:01.028] Execute prepared statement failed ORA-00904: "NOEXISTFIELD": invalid identifier (#904)
[2020.07.24 20:31:02.976] EZSQLException was raised while opening dataset with the message: ORA-00904: "NOEXISTFIELD": invalid identifier
SQL: OCIStmtExecute

[aehimself]

Perfect! :)

[2020.07.25 09:16:55.043] Execute Statement 6 : UPDATE MYTABLE SET FIELD = null, affected 6 row(s) in 5 ms

[aehimself]

Fyi, I rolled out the latest Zeos (and custom logger) to my headless application in my test environment. So far it is working flawlessly, and finally I can see the information which I was missing since I made the switch from

Code: Select all

dataset.SQL.Text := insert_function_from_dll(parameter1, parameter2);
Log(dataset.SQL.Text);
dataset.ExecSQL;
Log(dataset.RowsAffected + ' row(s) affected in ' + timeelapsed + ' ms');

2020.07.25. 12:15:18.570 - Successfully connected to testmysql.lan. MySQL 8.0.18, client version: 10.4.3, database component version: 7.3.0-a38ecff9
[...]
2020.07.25. 21:00:26.288 - Transaction Native SetAutoCommit False call
2020.07.25. 21:00:26.334 - Bind prepared Statement 50 : 1595703626,6
2020.07.25. 21:00:26.334 - Execute prepared Statement 50, affected 1 row(s) in 0 ms
2020.07.25. 21:00:26.334 - Bind prepared Statement 50 : 1595703626,4
2020.07.25. 21:00:26.334 - Execute prepared Statement 50, affected 1 row(s) in 0 ms
2020.07.25. 21:00:26.350 - Bind prepared Statement 50 : 1595703626,5
2020.07.25. 21:00:26.350 - Execute prepared Statement 50, affected 1 row(s) in 0 ms
2020.07.25. 21:00:26.350 - Bind prepared Statement 50 : 1595703626,3
2020.07.25. 21:00:26.350 - Execute prepared Statement 50, affected 1 row(s) in 0 ms
2020.07.25. 21:00:26.366 - Transaction COMMIT TRANSACTION
2020.07.25. 21:00:26.366 - Execute prepared Statement 4 in 0 ms
2020.07.25. 21:00:26.366 - Fetch Statement 4, affected 0 row(s) in 0 ms

It is just awesome, thank you!

P.s.: @Jan; I have a pending pull request with some comments for ZMethodInThread for a couple of weeks now; did you see it? I also sent the promised "readme" as a PM in the forum; I'm not sure you got it?

[EgonHugeist]

Behavior is the same on MySQL and on Oracle (however, on Oracle it is prepared first so it has a statement number):

That's why the Oracle and other drivers with fast protocols can't life without prepared statement. (ps. all Oracle products can't descripe parameters thus permanently mem reallocations are required). Using immediate prepares with MySQL you'll need to add

Code: Select all

TZconnection.Properties[DSProps_MinExecCntBeforePrepare]=0

(sets defaults for all statements) or use it as

Code: Select all

TZAbstractRODataSet(Descendant).Properties[DSProps_MinExecCntBeforePrepare]=0

(sets defaults per statement) to your code.
Then the DBC-Layer will Immediataly prepare the queries. Note if your'e a user which permantly changes the SQL Strings of your component: your'e gangling the server if you're using that option. A good design keeps the statement strings(Select/DML) alive. Mean's to have full power of your server use different components for it's purpose.

According the Exceptions, iv'e added some patches to get the Stmt-ID running inbetween. Yet i've not tested it, just logical code has been added.

Please test?! And report your findings