Re: [PATCHES] [HACKERS] statement logging / extended query protocol issues
I have adjusted your patch to log FETCH for protocol-level executes that are really fetches. What I did not do was to handle unnamed portals differently, and I did not include a fetch count in the log message. Let's see if we need that later. This leaves output of bind parameter values as the only open TODO in this area. Patch attached and applied. --- Simon Riggs wrote: On Thu, 2005-09-08 at 13:14 +1200, Oliver Jowett wrote: Simon Riggs wrote: Oliver, would it be possible to show a simplified call sequence and what you would like to see logged for each call? These are good: Maybe it should even be in the docs for the driver? It would be good if it could be written as a test within the driver, so we can expand it and test the logging. The JDBC driver generates one of these sequences: (1) Parse (unnamed statement) SELECT 1 Bind (unnamed statement - unnamed portal) Execute (unnamed portal, no row limit) (2) Parse (named statement S_1) SELECT 1 repeatedly: Bind (named statement S_1 - unnamed portal) Execute (unnamed portal, no row limit) (3) Parse (named statement S_2) SELECT 1 repeatedly: Bind (named statement S_2 - named portal C_2) repeatedly: Execute (named portal C_2, row limit 42) Are we sure there is just 3 cases? Ideal output is: (1) LOG: statement: SELECT 1 (2) LOG: statement: SELECT 1 LOG: statement: SELECT 1 LOG: statement: SELECT 1 (3) LOG: statement: SELECT 1 LOG: statement: SELECT 1 LOG: statement: SELECT 1 In case (3), that's one log line per repeat of the outer loop, regardless of how many Executes are sent in the inner loop. Note that case (1) is the most common case for application queries via the JDBC driver, and case (2) is the most common for internally generated statements like BEGIN. Even if case (3) is not that common, I still want to know it is occurring, to see what effect or overhead it has. As you can see from the output I'd like, I don't think that synthesizing FETCH / EXECUTE queries that don't actually exist [is a] useful thing to do, at least at the Joe Average User level. Your original point at the top of this thread was valid: a get-next-rows shouldn't look like a re-execute. We can call it something else if you like, as long as we can tell the difference. We'll only see the output for case (3) when someone has programmed things that way by using setFetchSize. Also note that the JDBC driver doesn't exercise all of the extended protocol -- for example it's possible to re-Bind the same unnamed statement repeatedly, or have multiple Executes on an unnamed portal with a row limit, but the JDBC driver never does that. I agree there's not much gained from displaying the BIND statement as it is. I argued previously against including the BIND parameters. Now I would say we should either include them or leave out BIND altogether. Here's a new suggestion and patch that brings together - Oliver and Simon's wish to remove BIND from normal logging - Oliver's suggestion to remove the PREPARE logging for unnamed statements, which would otherwise double-up logging for case(1) - Bruce and Simon's view to keep some form of FETCH logging - Tom's view to rationalise the way ROWS is mentioned (lines beginning jdbc don't show in the log, but are just there to show clearly the time sequence of activities and what gets subsequently logged) (1) Parse (unnamed statement) SELECT * from pg_proc Bind (unnamed statement - unnamed portal) Execute (unnamed portal, no row limit) (1) jdbc parse jdbc bind jdbc execute LOG: statement: SELECT * from pg_proc jdbc parse jdbc bind jdbc execute LOG: statement: SELECT * from pg_proc jdbc parse jdbc bind jdbc execute LOG: statement: SELECT * from pg_proc Notice that the parse of the unnamed statement does *not* now generate a log record. (2) Parse (named statement S_1) SELECT * from pg_proc repeatedly: Bind (named statement S_1 - unnamed portal) Execute (unnamed portal, no row limit) (2) jdbc parse S_1 LOG: statement: PREPARE S_1 AS SELECT * from pg_proc (perhaps this should be logged at BIND time, just like the optimization?) jdbc bind S_1 jdbc execute LOG: statement: EXECUTE unnamed [PREPARE: SELECT * from pg_proc] jdbc bind S_1 jdbc execute LOG: statement: EXECUTE unnamed [PREPARE: SELECT * from pg_proc] jdbc bind S_1 jdbc execute LOG: statement: EXECUTE unnamed [PREPARE: SELECT * from pg_proc] ...I wonder if unnamed just confuses what is going on here? I've left it in for now, but suggest that we take that out again? (3) Parse (named statement S_2) SELECT * from pg_proc repeatedly: Bind (named statement S_2 - named portal C_2) repeatedly: Execute
Re: [PATCHES] [HACKERS] statement logging / extended query protocol issues
On Thu, 2005-09-22 at 21:54 -0400, Bruce Momjian wrote:
Here are comments on this posting and the patch (it is long):
Thanks for reading through this. I understand now why nobody had gone
into this detail before...
(1)
Parse (unnamed statement) SELECT * from pg_proc
Bind (unnamed statement - unnamed portal)
Execute (unnamed portal, no row limit)
(1)
jdbc parse
jdbc bind
jdbc execute
LOG: statement: SELECT * from pg_proc
jdbc parse
jdbc bind
jdbc execute
LOG: statement: SELECT * from pg_proc
jdbc parse
jdbc bind
jdbc execute
LOG: statement: SELECT * from pg_proc
Notice that the parse of the unnamed statement does *not* now generate a
log record.
What is the reason for this? I am not so worried about what JDBC uses
but what the protocol supports. From my reading of the documentatation
is seems to support a single prepare and multiple executes of an unnamed
statement.
OK, in terms of the documented protocol, this represents a SimpleQuery
message. i.e. parse then immediate execute - produces only ONE log of
the statement.
I agree we should be doing this in terms of the protocol, not the
driver.
(2) and (3) represent the Extended Query protocol.
(2)
Parse (named statement S_1) SELECT * from pg_proc
repeatedly:
Bind (named statement S_1 - unnamed portal)
Execute (unnamed portal, no row limit)
...
jdbc bind S_1
jdbc execute
LOG: statement: EXECUTE unnamed [PREPARE: SELECT * from pg_proc]
...I wonder if unnamed just confuses what is going on here? I've left
it in for now, but suggest that we take that out again?
What do you want to replace it with? A missing name seems confusing.
OK, no change then
Here are my comments on the patch:
+
+ /* Log parse only when using named statements, unless in debug1 mode
*/
+ if (log_statement == LOGSTMT_ALL)
+ ereport((is_named ? DEBUG1 : LOG),
+ (errmsg(statement: PREPARE %s AS %s, stmt_name,
query_string)));
+
This seems backwards. The comments says log only named statements, but
the '?' test makes named statements DEBUG. Is this intended?
Why have you dropped the unnamed? Whether it is DEBUG or not we
should display meaningful output.
As above, I'll remove that part of the code.
/*
* Do basic parsing of the query or queries (this should be safe even
* if we are in aborted transaction state!)
***
*** 1467,1473
portal = CreatePortal(portal_name, false, false);
if (log_statement == LOGSTMT_ALL)
! ereport(LOG,
(errmsg(statement: BIND %s, portal_name)));
/*
--- 1467,1473
portal = CreatePortal(portal_name, false, false);
if (log_statement == LOGSTMT_ALL)
! ereport(DEBUG1,
(errmsg(statement: BIND %s, portal_name)));
Can we get the BIND parameters here? They seem significant for
debugging.
Maybe, but I'll punt on this for now in an attempt to not overextend
myself.
I think this would be best handled with a log_bind_parms = (none | first
| all) so that all would be happy.
/*
***
*** 1683,1688
--- 1683,1689
boolsave_log_duration = log_duration;
int save_log_min_duration_statement =
log_min_duration_statement;
boolsave_log_statement_stats = log_statement_stats;
+ boolsubsequent_fetch = false;
Can we call this execute_is_fetch. That seems clearer.
Will do.
***
*** 1706,1712
return;
}
! if (portal-sourceText)
{
debug_query_string = portal-sourceText;
pgstat_report_activity(portal-sourceText);
--- 1716,1727
return;
}
! if (subsequent_fetch)
! {
! debug_query_string = fetch message;
! pgstat_report_activity(FETCH);
! }
! else if (portal-sourceText)
Shouldn't we supply the name of the prepare here, or don't we have one?
If not, we should call it unnamed.
Yes we can, and yes will do.
***
*** 1865,1877
if (save_log_min_duration_statement == 0 ||
(save_log_min_duration_statement 0
usecs = save_log_min_duration_statement * 1000))
! ereport(LOG,
! (errmsg(duration: %ld.%03ld ms statement: EXECUTE %s
[PREPARE: %s],
(long) ((stop_t.tv_sec - start_t.tv_sec) * 1000 +
(stop_t.tv_usec - start_t.tv_usec) / 1000),
(long) (stop_t.tv_usec - start_t.tv_usec) % 1000,
! (*portal_name != '\0') ? portal_name :
unnamed,
! portal-sourceText ? portal-sourceText : )));
}
if (save_log_statement_stats)
--- 1897,1929
if
Re: [PATCHES] [HACKERS] statement logging / extended query protocol issues
Here are comments on this posting and the patch (it is long): Simon Riggs wrote: On Thu, 2005-09-08 at 13:14 +1200, Oliver Jowett wrote: Simon Riggs wrote: Oliver, would it be possible to show a simplified call sequence and what you would like to see logged for each call? These are good: Maybe it should even be in the docs for the driver? It would be good if it could be written as a test within the driver, so we can expand it and test the logging. The JDBC driver generates one of these sequences: (1) Parse (unnamed statement) SELECT 1 Bind (unnamed statement - unnamed portal) Execute (unnamed portal, no row limit) (2) Parse (named statement S_1) SELECT 1 repeatedly: Bind (named statement S_1 - unnamed portal) Execute (unnamed portal, no row limit) (3) Parse (named statement S_2) SELECT 1 repeatedly: Bind (named statement S_2 - named portal C_2) repeatedly: Execute (named portal C_2, row limit 42) Are we sure there is just 3 cases? Ideal output is: (1) LOG: statement: SELECT 1 (2) LOG: statement: SELECT 1 LOG: statement: SELECT 1 LOG: statement: SELECT 1 (3) LOG: statement: SELECT 1 LOG: statement: SELECT 1 LOG: statement: SELECT 1 In case (3), that's one log line per repeat of the outer loop, regardless of how many Executes are sent in the inner loop. Note that case (1) is the most common case for application queries via the JDBC driver, and case (2) is the most common for internally generated statements like BEGIN. Even if case (3) is not that common, I still want to know it is occurring, to see what effect or overhead it has. Agreed. As you can see from the output I'd like, I don't think that synthesizing FETCH / EXECUTE queries that don't actually exist [is a] useful thing to do, at least at the Joe Average User level. Your original point at the top of this thread was valid: a get-next-rows shouldn't look like a re-execute. We can call it something else if you like, as long as we can tell the difference. We'll only see the output for case (3) when someone has programmed things that way by using setFetchSize. Also note that the JDBC driver doesn't exercise all of the extended protocol -- for example it's possible to re-Bind the same unnamed statement repeatedly, or have multiple Executes on an unnamed portal with a row limit, but the JDBC driver never does that. I agree there's not much gained from displaying the BIND statement as it is. I argued previously against including the BIND parameters. Now I would say we should either include them or leave out BIND altogether. Agreed. We should output BIND parameters at some point. We do log client-side PREPARE parameters now. Here's a new suggestion and patch that brings together - Oliver and Simon's wish to remove BIND from normal logging - Oliver's suggestion to remove the PREPARE logging for unnamed statements, which would otherwise double-up logging for case(1) - Bruce and Simon's view to keep some form of FETCH logging - Tom's view to rationalise the way ROWS is mentioned (lines beginning jdbc don't show in the log, but are just there to show clearly the time sequence of activities and what gets subsequently logged) (1) Parse (unnamed statement) SELECT * from pg_proc Bind (unnamed statement - unnamed portal) Execute (unnamed portal, no row limit) (1) jdbc parse jdbc bind jdbc execute LOG: statement: SELECT * from pg_proc jdbc parse jdbc bind jdbc execute LOG: statement: SELECT * from pg_proc jdbc parse jdbc bind jdbc execute LOG: statement: SELECT * from pg_proc Notice that the parse of the unnamed statement does *not* now generate a log record. What is the reason for this? I am not so worried about what JDBC uses but what the protocol supports. From my reading of the documentatation is seems to support a single prepare and multiple executes of an unnamed statement. (2) Parse (named statement S_1) SELECT * from pg_proc repeatedly: Bind (named statement S_1 - unnamed portal) Execute (unnamed portal, no row limit) (2) jdbc parse S_1 LOG: statement: PREPARE S_1 AS SELECT * from pg_proc (perhaps this should be logged at BIND time, just like the optimization?) jdbc bind S_1 jdbc execute LOG: statement: EXECUTE unnamed [PREPARE: SELECT * from pg_proc] jdbc bind S_1 jdbc execute LOG: statement: EXECUTE unnamed [PREPARE: SELECT * from pg_proc] jdbc bind S_1 jdbc execute LOG: statement: EXECUTE unnamed [PREPARE: SELECT * from pg_proc] ...I wonder if unnamed just confuses what is going on here? I've left it in for now, but suggest that we take that out again? What do you want to replace it with? A missing name seems confusing. (3) Parse (named statement S_2) SELECT * from pg_proc repeatedly: Bind (named statement S_2 - named portal
