New issue
Have a question about this project? Sign up for a free GitHub account to open an issue and contact its maintainers and the community.
By clicking “Sign up for GitHub”, you agree to our terms of service and privacy statement. We’ll occasionally send you account related emails.
Already on GitHub? Sign in to your account
Add trace info about read query in packets [CORE6456] #6689
Comments
Modified by: @livius2description: Provide the way to see info about packet read in trace. Table have 10000 records. Such statement is shown in MON$STATEMENTS as „Stalled". But i need to calculate how long query was executed. => Provide a way to see info about packet read in trace. Table have 10000 records. Such statement is shown in MON$STATEMENTS as „Stalled". But i need to calculate how long query was executed. |
Commented by: @hvlad EXECUTE_STATEMENT_FINISH event contains query execution time. |
Commented by: @livius2 No. EXECUTE_STATEMENT_FINISH is send only when whole query is really finished. 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. |
Commented by: @hvlad So what do you want from trace ? |
Commented by: @livius2 >> There is no such event as "packet read" at the engine. Then how it is considered in MON$STATEMENTS as „Stalled"? in trace i see e.g. this: -------------------------------------------------------------------------------------------------------------------------------------------------------------- 2020-12-18T23:21:57.1130 (4124:00000000526B0040) EXECUTE_STATEMENT_START Statement 386: 2020-12-18T23:24:21.3410 (4124:00000000526B0040) EXECUTE_STATEMENT_FINISH Statement 386: 1222 ms, 4934 read(s), 272505 fetch(es) 2020-12-18T23:32:45.6690 (4124:00000000526B0040) CLOSE_CURSOR 2020-12-18T23:32:45.6690 (4124:00000000526B0040) FREE_STATEMENT -------------------------------------------------------------------------------------------------------------------------------------------------------------- as you can see we have: in EXECUTE_STATEMENT_FINISH it is 1222 ms but from START and FINISH we have 2 minutes and 24 seconds |
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 > 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). |
Commented by: @livius2 Ok, then what if trace generate info like: Is this possible? Now i have no other choice than report it as high resource consuming long running query. |
Commented by: @livius2 >> yes, trace reports time spend in the engine when statement was active (not stalled). 2 questiions here: When this 1222 ms info is avaiable? After this 1222 ms (point 2) or after all fetches (point 1)? EXECUTE_STATEMENT_FINISH_EXECUTE - this will be generated immidietly after this 1222 ms |
Commented by: @hvlad > Ok, then what if trace generate info like: 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. 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: 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 This is the same moment of time as EXECUTE_STATEMENT_FINISH event is reported when last record is fetched. |
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 >> 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. Maybe some treshold? |
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. 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. If you use both monitoring tables and trace in your tool, then we probably could add additional fields to the MON$STATEMENTS, > If time between statement start and this accumulated time is longer then some period of time, then generate some new event? (but only once) I prefer to avoid such timers. |
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? >> 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. |
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, > 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 |
Commented by: @livius2 Can you create separate ticket with your proposition about MON$ELAPSED_TIME and MON$ROWS_FETCHED |
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..
The text was updated successfully, but these errors were encountered: