Add trace info about read query in packets [CORE6456]

[firebird-automations]

Submitted by: @livius2

Provide a way to see info about packet read in trace.
I mean e.g.:

Table have 10000 records.
I do SELECT * FROM MY_TABLE
But i do not read all records at start (do not fetch all) but i read data in packets e.g. 300 records at one time.

Such statement is shown in MON$STATEMENTS as „Stalled".
Now i do not see any info in trace about this fetches.
I see only PREPARE_STATEMENT, EXECUTE_STATEMENT_START, CLOSE_CURSOR, EXECUTE_STATEMENT_FINISH, FREE_STATEMENT

But i need to calculate how long query was executed.
And between next 300 record fetches can be e.g. 5 minute break.
And i report then such query in my tool as long long running query which consume resources continously.
But really this query run only few ms. All fetches alltogether take e.g. 100ms but i report it as it had been running for an hour or more..

[firebird-automations]

Modified by: @livius2

description: Provide the way to see info about packet read in trace.
I mean e.g.:

Table have 10000 records.
I do SELECT * FROM MY_TABLE
But i do not read all records at start (do not fetch all) but i read data in packets e.g. 300 records at one time.

Such statement is shown in MON$STATEMENTS as „Stalled".
Now i do not see any info in trace about this fetches.
I see only PREPARE_STATEMENT, EXECUTE_STATEMENT_START, CLOSE_CURSOR, EXECUTE_STATEMENT_FINISH, FREE_STATEMENT

But i need to calculate how long query was executed.
And between next 300 record fetches can be e.g. 5 minute break.
And i report then such query in my tool as long long running query which consume resources continously.
But really this query run only few ms. All fetches alltogether take e.g. 100ms but i report it as they run e.g. 1 hour.

=>

Provide a way to see info about packet read in trace.
I mean e.g.:

Table have 10000 records.
I do SELECT * FROM MY_TABLE
But i do not read all records at start (do not fetch all) but i read data in packets e.g. 300 records at one time.

Such statement is shown in MON$STATEMENTS as „Stalled".
Now i do not see any info in trace about this fetches.
I see only PREPARE_STATEMENT, EXECUTE_STATEMENT_START, CLOSE_CURSOR, EXECUTE_STATEMENT_FINISH, FREE_STATEMENT

But i need to calculate how long query was executed.
And between next 300 record fetches can be e.g. 5 minute break.
And i report then such query in my tool as long long running query which consume resources continously.
But really this query run only few ms. All fetches alltogether take e.g. 100ms but i report it as it had been running for an hour or more..

[firebird-automations]

Commented by: @hvlad

EXECUTE_STATEMENT_FINISH event contains query execution time.
Is it what you are looking for ?

[firebird-automations]

Commented by: @livius2

No. EXECUTE_STATEMENT_FINISH is send only when whole query is really finished.
But when user have opened data with e.g. 300 records. Analyse it and fetch another 300 records after 20 minutes.
This process can take hours.

My tool during this query "Stalled" state report it as it run continuously 20 minutes or more. I cannot even see in trace that such query is fetched in this way.

It can be shorter, e.g. next packet fetched every 2 seconds. But i still can raport that such query run continously e.g. 30 seconds. Which can be considered as bad query in the tool.
And if user decide to add "time_threshold" e.g. 5 minutes. I never got EXECUTE_STATEMENT_FINISH info.

[firebird-automations]

Commented by: @hvlad

So what do you want from trace ?
There is no such event as "packet read" at the engine.

[firebird-automations]

Commented by: @livius2

>> There is no such event as "packet read" at the engine.

Then how it is considered in MON$STATEMENTS as „Stalled"?
And how next packet records e.g. 300 is fetched then?

in trace i see e.g. this:

--------------------------------------------------------------------------------------------------------------------------------------------------------------

2020-12-18T23:21:57.1130 (4124:00000000526B0040) EXECUTE_STATEMENT_START
T:\FIREBIRDDB\RIDO.FDB.RESTORED (ATT_66, SYSDBA:NONE, WIN1250, TCPv4:127.0.0.1/60811)
R:\KBSQLStat\KBSQLStat.exe:29868
(TRA_1431, READ_COMMITTED | REC_VERSION | NOWAIT | READ_WRITE)

Statement 386:

2020-12-18T23:24:21.3410 (4124:00000000526B0040) EXECUTE_STATEMENT_FINISH
T:\FIREBIRDDB\RIDO.FDB.RESTORED (ATT_66, SYSDBA:NONE, WIN1250, TCPv4:127.0.0.1/60811)
R:\KBSQLStat\KBSQLStat.exe:29868
(TRA_1431, READ_COMMITTED | REC_VERSION | NOWAIT | READ_WRITE)

Statement 386:

1222 ms, 4934 read(s), 272505 fetch(es)

2020-12-18T23:32:45.6690 (4124:00000000526B0040) CLOSE_CURSOR
T:\FIREBIRDDB\RIDO.FDB.RESTORED (ATT_66, SYSDBA:NONE, WIN1250, TCPv4:127.0.0.1/60811)
R:\KBSQLStat\KBSQLStat.exe:29868

2020-12-18T23:32:45.6690 (4124:00000000526B0040) FREE_STATEMENT
T:\FIREBIRDDB\RIDO.FDB.RESTORED (ATT_66, SYSDBA:NONE, WIN1250, TCPv4:127.0.0.1/60811)
R:\KBSQLStat\KBSQLStat.exe:29868

--------------------------------------------------------------------------------------------------------------------------------------------------------------

as you can see we have:
2020-12-18T23:21:57.1130 EXECUTE_STATEMENT_START
2020-12-18T23:24:21.3410 EXECUTE_STATEMENT_FINISH
2020-12-18T23:32:45.6690 CLOSE_CURSOR
2020-12-18T23:32:45.6690 FREE_STATEMENT

in EXECUTE_STATEMENT_FINISH it is 1222 ms but from START and FINISH we have 2 minutes and 24 seconds

[firebird-automations]

Commented by: @hvlad

>> There is no such event as "packet read" at the engine.

> Then how it is considered in MON$STATEMENTS as „Stalled"?

Statement is stalled when it have open cursor and there is no running fetch operation at the moment.

> And how next packet records e.g. 300 is fetched then?

Again, there is no "packet read" at the engine. There is network server feature - it prefetches bunch of records to
optimize network traffic, but engine have no idea about it. And trace implemented at the engine level. Also, note,
such prefetch could be disabled (SELECT FOR UPDATE) or not active (XNET) or not present at all (embedded).

> in EXECUTE_STATEMENT_FINISH it is 1222 ms but from START and FINISH we have 2 minutes and 24 seconds

yes, trace reports time spend in the engine when statement was active (not stalled).

[firebird-automations]

Commented by: @livius2

Ok, then what if trace generate info like:
"EXECUTE_STATEMENT_STALLED" - this is minimal requirement to solve the problem
"EXECUTE_STATEMENT_AGAIN_ACTIVE" - this will be good addition

Is this possible?
With EXECUTE_STATEMENT_STALLED i can stop monitoring such query. Not good at all but some option. Or i can simply mark it as "fetched partially" and show different kind of "problem" info.

Now i have no other choice than report it as high resource consuming long running query.
Or maybe you have some idea here?

[firebird-automations]

Commented by: @livius2

>> yes, trace reports time spend in the engine when statement was active (not stalled).

2 questiions here:
1. Is this cumulative time during next fetch + next fetch... ?
2. Or it is run once and all data are aviable but only not fetched by client?

When this 1222 ms info is avaiable? After this 1222 ms (point 2) or after all fetches (point 1)?
If this is on point 1. Then trace should have 2 trace messages instead of current one.

EXECUTE_STATEMENT_FINISH_EXECUTE - this will be generated immidietly after this 1222 ms
EXECUTE_STATEMENT_FINISH - this one which is currently generated - only after all fetches

[firebird-automations]

Commented by: @hvlad

> Ok, then what if trace generate info like:
> "EXECUTE_STATEMENT_STALLED" - this is minimal requirement to solve the problem
> "EXECUTE_STATEMENT_AGAIN_ACTIVE" - this will be good addition
>
> Is this possible?

Yes, it is technically possible, but it is very bad idea. It will generate two events on every record fetched, produce a lot of trace logs, slowdown engine and useless in 99.999% of cases.

> Now i have no other choice than report it as high resource consuming long running query.
> Or maybe you have some idea here?

I still have no idea what problem do you have and how you going to solve it.

>> yes, trace reports time spend in the engine when statement was active (not stalled).

> 2 questiions here:
> 1. Is this cumulative time during next fetch + next fetch... ?

This time is accumulated at request (statement) level

> 2. Or it is run once and all data are aviable but only not fetched by client?

Not sure I understand this

> When this 1222 ms info is avaiable? After this 1222 ms (point 2) or after all fetches (point 1)?

This info is reported with EXECUTE_STATEMENT_FINISH event

> EXECUTE_STATEMENT_FINISH_EXECUTE - this will be generated immidietly after this 1222 ms
> EXECUTE_STATEMENT_FINISH - this one which is currently generated - only after all fetches

This is the same moment of time as EXECUTE_STATEMENT_FINISH event is reported when last record is fetched.

[firebird-automations]

Commented by: @livius2

>> Yes, it is technically possible, but it is very bad idea. It will generate two events on every record fetched, produce a lot of trace logs, slowdown engine and useless in 99.999% of cases.

is that mean that state is
STALLED start_fetch ACTIVE end_fetch STALLED ....
for every statement? Or stalled is only for such queries? From your description looks like it is for every request and will generate a lot of logs and then is not acceptable.

>> I still have no idea what problem do you have and how you going to solve it.

Think about monitoring software. You have active requests monitored by trace. And you report that some query run very long.
How to identify that long running query is really short running like above 1222 ms not 2 minutes and 24 seconds?
This 2 minutes and 24 seconds gain some info but only this "1222 ms" is really important. But now we do not know that during statement execution only after.

Maybe some treshold?
If time between statement start and this accumulated time is longer then some period of time, then generate some new event? (but only once)
But i do not know if this will not be too high resource consuming task, as some timer should be per statement :(

[firebird-automations]

Commented by: @hvlad

>> Yes, it is technically possible, but it is very bad idea. It will generate two events on every record fetched, produce a lot of trace logs, slowdown engine and useless in 99.999% of cases.
>
> is that mean that state is
> STALLED start_fetch ACTIVE end_fetch STALLED ....
> for every statement?

Yes, of course.

> Or stalled is only for such queries? From your description looks like it is for every request and will generate a lot of logs and then is not acceptable.

Seems we have agreement here, good :)

>> I still have no idea what problem do you have and how you going to solve it.
>
> Think about monitoring software. You have active requests monitored by trace. And you report that some query run very long.
> How to identify that long running query is really short running like above 1222 ms not 2 minutes and 24 seconds?
> This 2 minutes and 24 seconds gain some info but only this "1222 ms" is really important. But now we do not know that during statement execution only after.

If you use both monitoring tables and trace in your tool, then we probably could add additional fields to the MON$STATEMENTS,
say MON$ELAPSED_TIME and MON$ROWS_FETCHED.

> If time between statement start and this accumulated time is longer then some period of time, then generate some new event? (but only once)
> But i do not know if this will not be too high resource consuming task, as some timer should be per statement :(

I prefer to avoid such timers.

[firebird-automations]

Commented by: @livius2

>> Yes, of course.

I have realized now that when i run select from MON$STATEMENTS i can got in any time "STALLED" for any statement?
I have never got it for "normal" retrivals. Is this prevented somehow by engine or this is only because i work most in speed LAN environment where "STALLED" state is really short?

>> If you use both monitoring tables and trace in your tool, then we probably could add additional fields to the MON$STATEMENTS, say MON$ELAPSED_TIME and MON$ROWS_FETCHED.

It will be good addition in mon tables. You can implement it without looking at this ticket :).

But i try to avoid 2 monitoring tasks in the same time. Like MON$ tables + trace.
Ideal will be to solve it in trace itself somehow.

[firebird-automations]

Commented by: @hvlad

> I have realized now that when i run select from MON$STATEMENTS i can got in any time "STALLED" for any statement?

Yes. Except of current select from MON$STATEMENTS :)

> I have never got it for "normal" retrivals. Is this prevented somehow by engine

No

> or this is only because i work most in speed LAN environment where "STALLED" state is really short?

usually, applications tries to fetch data as fast as possible and makes no delay between fetches, so, yes,
STALLED state usually too short to be noticed. In general, it depends on too many factors.

> Ideal will be to solve it in trace itself somehow.

So far, I have no good working idea how to help you using trace only, sorry

[firebird-automations]

Commented by: @livius2

Can you create separate ticket with your proposition about MON$ELAPSED_TIME and MON$ROWS_FETCHED
And is there a chance to be included in FB4? I suppose it is too late for RC1 as this require ODS change?
Ideal if possible then to port it back to FB3 too :)