Re: statement logging / extended query protocol issues

8.1-beta1 produces some odd results with statement logging enabled when
the extended query protocol is used (e.g. when using the JDBC driver).
Repeatedly running a simple query with log_statement = 'all' produces this:

LOG: statement: PREPARE AS SELECT 'dummy statement'
LOG: statement: <BIND>
LOG: statement: EXECUTE [PREPARE: SELECT 'dummy statement']
[...]
LOG: statement: PREPARE S_2 AS SELECT 'dummy statement'
LOG: statement: <BIND>
LOG: statement: EXECUTE [PREPARE: SELECT 'dummy statement']
LOG: statement: <BIND>
LOG: statement: EXECUTE [PREPARE: SELECT 'dummy statement']
LOG: statement: <BIND>
[...]

Comments:
- The PREPARE lines are misleading as the query actually sent does not
include PREPARE at all.
- The driver never sends EXECUTE as a statement, but it is logged as one.
- "PREPARE AS" is a confusing way of saying "the unnamed statement"
- The <BIND> lines are content-free.

Secondly, running a query that uses portals produces output like this:

LOG: statement: PREPARE S_3 AS SELECT * from pg_proc
LOG: statement: <BIND> C_4
LOG: statement: EXECUTE C_4 [PREPARE: SELECT * from pg_proc]
LOG: statement: EXECUTE C_4 [PREPARE: SELECT * from pg_proc]
LOG: statement: EXECUTE C_4 [PREPARE: SELECT * from pg_proc]
LOG: statement: EXECUTE C_4 [PREPARE: SELECT * from pg_proc]
LOG: statement: EXECUTE C_4 [PREPARE: SELECT * from pg_proc]
LOG: statement: EXECUTE C_4 [PREPARE: SELECT * from pg_proc]
LOG: statement: EXECUTE C_4 [PREPARE: SELECT * from pg_proc]

Comments:
- The <BIND> is still fairly content-free.
- The EXECUTEs are a bit misleading as the SELECT was actually only run
once (there are multiple Execute messages for the same portal). You
could infer that there is only one SELECT from the repeated portal name
and the lack of an intervening <BIND>, I suppose.

8.1 is admittedly better than 8.0 here (8.0 had no logging in this case
at all).. but it's not very user-friendly as it stands. I'm sure the
JDBC list is going to get lots of "why does statement logging give me
this weird output" questions :/

I've attached the Java code I used to produce this. It expects a single
argument, the JDBC URL to use, e.g.
'jdbc:postgresql://localhost:8101/test?user=oliver'

-O

I have applied the following patch to output "<unnamed>" for unnamed
prepared statements. As far as your other issues, how would you want
server-side statements to be logged? "statement:" is a log label for a
statement. What else should we use?

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

Oliver Jowett wrote:
> 8.1-beta1 produces some odd results with statement logging enabled when
> the extended query protocol is used (e.g. when using the JDBC driver).
> Repeatedly running a simple query with log_statement = 'all' produces this:
>
> LOG: statement: PREPARE AS SELECT 'dummy statement'
> LOG: statement: <BIND>
> LOG: statement: EXECUTE [PREPARE: SELECT 'dummy statement']
> [...]
> LOG: statement: PREPARE S_2 AS SELECT 'dummy statement'
> LOG: statement: <BIND>
> LOG: statement: EXECUTE [PREPARE: SELECT 'dummy statement']
> LOG: statement: <BIND>
> LOG: statement: EXECUTE [PREPARE: SELECT 'dummy statement']
> LOG: statement: <BIND>
> [...]
>
> Comments:
> - The PREPARE lines are misleading as the query actually sent does not
> include PREPARE at all.
> - The driver never sends EXECUTE as a statement, but it is logged as one.
> - "PREPARE AS" is a confusing way of saying "the unnamed statement"
> - The <BIND> lines are content-free.
>
> Secondly, running a query that uses portals produces output like this:
>
> LOG: statement: PREPARE S_3 AS SELECT * from pg_proc
> LOG: statement: <BIND> C_4
> LOG: statement: EXECUTE C_4 [PREPARE: SELECT * from pg_proc]
> LOG: statement: EXECUTE C_4 [PREPARE: SELECT * from pg_proc]
> LOG: statement: EXECUTE C_4 [PREPARE: SELECT * from pg_proc]
> LOG: statement: EXECUTE C_4 [PREPARE: SELECT * from pg_proc]
> LOG: statement: EXECUTE C_4 [PREPARE: SELECT * from pg_proc]
> LOG: statement: EXECUTE C_4 [PREPARE: SELECT * from pg_proc]
> LOG: statement: EXECUTE C_4 [PREPARE: SELECT * from pg_proc]
>
> Comments:
> - The <BIND> is still fairly content-free.
> - The EXECUTEs are a bit misleading as the SELECT was actually only run
> once (there are multiple Execute messages for the same portal). You
> could infer that there is only one SELECT from the repeated portal name
> and the lack of an intervening <BIND>, I suppose.
>
> 8.1 is admittedly better than 8.0 here (8.0 had no logging in this case
> at all).. but it's not very user-friendly as it stands. I'm sure the
> JDBC list is going to get lots of "why does statement logging give me
> this weird output" questions :/
>
> I've attached the Java code I used to produce this. It expects a single
> argument, the JDBC URL to use, e.g.
> 'jdbc:postgresql://localhost:8101/test?user=oliver'
>
> -O

> import java.sql.*;
> import java.util.*;
>
> public class TestStatementLogging {
> public static void main(String[] args) throws Exception {
> Class.forName("org.postgresql.Driver");
>
> Connection conn = DriverManager.getConnection(args[0]);
> conn.setAutoCommit(false);
>
> PreparedStatement stmt = conn.prepareStatement("SELECT 'dummy statement'");
> for (int j = 0; j < 10; ++j)
> stmt.executeQuery();
> stmt.close();
>
> stmt = conn.prepareStatement("SELECT * from pg_proc");
> stmt.setFetchSize(1);
> ResultSet rs = stmt.executeQuery();
> while (rs.next())
> ;
> stmt.close();
>
> conn.createStatement().execute("I am a syntax error");
> }
> }

>
> ---------------------------(end of broadcast)---------------------------
> TIP 2: Don't 'kill -9' the postmaster

--
Bruce Momjian | http://candle.pha.pa.us
pgman(at)candle(dot)pha(dot)pa(dot)us | (610) 359-1001
+ If your life is a hard drive, | 13 Roberts Road
+ Christ can be your backup. | Newtown Square, Pennsylvania 19073

> Oliver Jowett wrote:
> > 8.1-beta1 produces some odd results with statement logging enabled when
> > the extended query protocol is used (e.g. when using the JDBC driver).
> > Repeatedly running a simple query with log_statement = 'all' produces this:
...

> > Secondly, running a query that uses portals produces output like this:
> >
> > LOG: statement: PREPARE S_3 AS SELECT * from pg_proc
> > LOG: statement: <BIND> C_4
> > LOG: statement: EXECUTE C_4 [PREPARE: SELECT * from pg_proc]
> > LOG: statement: EXECUTE C_4 [PREPARE: SELECT * from pg_proc]
> > LOG: statement: EXECUTE C_4 [PREPARE: SELECT * from pg_proc]
> > LOG: statement: EXECUTE C_4 [PREPARE: SELECT * from pg_proc]
> > LOG: statement: EXECUTE C_4 [PREPARE: SELECT * from pg_proc]
> > LOG: statement: EXECUTE C_4 [PREPARE: SELECT * from pg_proc]
> > LOG: statement: EXECUTE C_4 [PREPARE: SELECT * from pg_proc]
> >
> > Comments:
> > - The <BIND> is still fairly content-free.
> > - The EXECUTEs are a bit misleading as the SELECT was actually only run
> > once (there are multiple Execute messages for the same portal). You
> > could infer that there is only one SELECT from the repeated portal name
> > and the lack of an intervening <BIND>, I suppose.

I've put together this prototype to offer more useful messages in the
situation Oliver describes.

Subsequent calls to the same portal are described as FETCHes rather than
as EXECUTEs. The portal name is still given and number of rows is
provided also.

I haven't tested this with the java program supplied, since this is a
fairly short-hack for comments. I'll correct any mistakes before
submission to patches.

Comments?

Best Regards, Simon Riggs

Simon Riggs <simon(at)2ndquadrant(dot)com> writes:
> + /*
> + * If we re-issue an Execute protocol request against an existing
> + * portal, then we are only fetching more rows rather than
> + * completely re-executing the query from the start
> + */
> + if (!portal->atEnd)
> + subsequent_fetch = true;

That strikes me as a completely bogus test for a "re-issued" execute.
Did you mean !atStart?

Also, why is it a good idea to report the number of rows fetched in
some cases (and not others)?

regards, tom lane

Simon Riggs wrote:

> Subsequent calls to the same portal are described as FETCHes rather than
> as EXECUTEs. The portal name is still given and number of rows is
> provided also.

I wonder if it might be better to only log the first Execute.. It's not
immediately clear to me that it's useful to see all the individual
fetches when they're logically part of a single query.

-O

On Mon, 2005-09-05 at 15:38 -0400, Tom Lane wrote:
> Simon Riggs <simon(at)2ndquadrant(dot)com> writes:
> > + /*
> > + * If we re-issue an Execute protocol request against an existing
> > + * portal, then we are only fetching more rows rather than
> > + * completely re-executing the query from the start
> > + */
> > + if (!portal->atEnd)
> > + subsequent_fetch = true;
>
> That strikes me as a completely bogus test for a "re-issued" execute.
> Did you mean !atStart?

Looking more closely, I don't think either is correct. Both can be reset
according to rewind operations - see DoPortalRewind().

We'd need to add another bool onto the Portal status data structure.

> Also, why is it a good idea to report the number of rows fetched in
> some cases (and not others)?

The number of rows fetched seemed particularly important on a FETCH
operation. Although they are logically part of the same query, some
queries have a lengthy pre-execution preparation time (e.g. sort) and
others don't.

(To Oliver:)
If queries are short and yet there is much fetching, we may see a
program whose main delay is because of program-to-server delay because
of fetching. So, I'd like to see that in the log, but I agree with your
earlier comments that it should be a shorter log line.

If we see

FETCH unnamed ROWS 1
FETCH unnamed ROWS 1
FETCH unnamed ROWS 1

we'd know the fetchsize was inappropriately set and correct it.

I guess we could add in a number of rows on the other log lines also if
people want that. I like the idea... it would tell us which queries are
causing huge retrievals.

Best Regards, Simon Riggs

Simon Riggs wrote:

> Looking more closely, I don't think either is correct. Both can be reset
> according to rewind operations - see DoPortalRewind().
>
> We'd need to add another bool onto the Portal status data structure.

AFAIK this is only an issue with SCROLLABLE cursors, which v3 portals
aren't.

> If queries are short and yet there is much fetching, we may see a
> program whose main delay is because of program-to-server delay because
> of fetching. So, I'd like to see that in the log, but I agree with your
> earlier comments that it should be a shorter log line.

I'm coming from the point of view of a user who wants to "just turn on
query logging". The mechanics of the portals aren't of interest to them.
Currently, "log_statement = all" produces markedly different output
depending on whether the extended query protocol is used or not, which
is very much an implementation detail..

How about "log_statement = verbose" or something similar to enable
logging of all the details, and have "all" just log Parse and the first
Execute?

Ideally, even Parse wouldn't be logged, but then we'd need a way to log
statements that error during Parse.

-O

On Tue, 2005-09-06 at 07:47 +0000, Oliver Jowett wrote:
> Simon Riggs wrote:
>
> > Looking more closely, I don't think either is correct. Both can be reset
> > according to rewind operations - see DoPortalRewind().
> >
> > We'd need to add another bool onto the Portal status data structure.
>
> AFAIK this is only an issue with SCROLLABLE cursors, which v3 portals
> aren't.

OK, that may be so, but the internals don't know that. If I use atEnd or
atStart then messages would differ from v3 to v2. It would then be easy
to confuse v2 cursor actions with multiple re-executions in v3. I want
to be able to look at the log and work out what happened, not to start
asking questions like "do you use v2, v3 or a mix of both?".

> > If queries are short and yet there is much fetching, we may see a
> > program whose main delay is because of program-to-server delay because
> > of fetching. So, I'd like to see that in the log, but I agree with your
> > earlier comments that it should be a shorter log line.
>
> I'm coming from the point of view of a user who wants to "just turn on
> query logging". The mechanics of the portals aren't of interest to them.
> Currently, "log_statement = all" produces markedly different output
> depending on whether the extended query protocol is used or not, which
> is very much an implementation detail..

...and I hope it would, since the impact on the server differs. I want
the log to reflect what has happened on the server.

> How about "log_statement = verbose" or something similar to enable
> logging of all the details, and have "all" just log Parse and the first
> Execute?

I think I like that suggestion. IMHO the client/server interaction is
often worth reviewing as part of a performance analysis, so I do want to
include all of that detail, but it sounds like a good idea to be able to
turn off the noise once that aspect has been examined.

How would that suggestion work when we use log_min_duration_statement?

Oliver, would it be possible to show a simplified call sequence and what
you would like to see logged for each call? That would simplify the
process of gaining agreement and would give a simple spec for me to
code. We're into beta now, so I don't want to stretch people's patience
too much further by changes in this area. I ask you since I think you
have a better grasp on the various protocols than I do.

I'll work on a further recoding of what we have been discussing.

Best Regards, Simon Riggs

Simon Riggs wrote:
> On Tue, 2005-09-06 at 07:47 +0000, Oliver Jowett wrote:
>
>>Simon Riggs wrote:
>>
>>
>>>Looking more closely, I don't think either is correct. Both can be reset
>>>according to rewind operations - see DoPortalRewind().
>>>
>>>We'd need to add another bool onto the Portal status data structure.
>>
>>AFAIK this is only an issue with SCROLLABLE cursors, which v3 portals
>>aren't.
>
> OK, that may be so, but the internals don't know that. If I use atEnd or
> atStart then messages would differ from v3 to v2. It would then be easy
> to confuse v2 cursor actions with multiple re-executions in v3. I want
> to be able to look at the log and work out what happened, not to start
> asking questions like "do you use v2, v3 or a mix of both?".

Uh, but the logging in question only runs from exec_execute_message,
which is explicitly handling a v3 Execute message, not an EXECUTE or
FETCH from somewhere else? If that can be confused with a v2 query, then
we should be logging it in such a way that it doesn't get confused (this
is one reason why I don't like your approach of synthesizing
FETCH/EXECUTE statements that were never actually submitted by the client).

I don't think we should worry about trying to support v3 Execute against
a SCROLLABLE cursor created via DECLARE that has been rewound -- that's
a strange case and there was some discussion previously about separating
the v3 portal vs. cursor namespaces anyway.

> Oliver, would it be possible to show a simplified call sequence and what
> you would like to see logged for each call?

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)

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.

Syntax error case (on Parse):
LOG: statement: I AM A SYNTAX ERROR
ERROR: syntax error ....

or something like this if it's easier:
ERROR: syntax error ....
LOG: failing statement: I AM A SYNTAX ERROR

This would require special handling of Parse messages to grab the error
case somehow.

Second best would be something like:

(1) LOG: parse statement: SELECT 1
LOG: exec statement: SELECT 1

(2) LOG: parse statement: SELECT 1
LOG: exec statement: SELECT 1
LOG: exec statement: SELECT 1
LOG: exec statement: SELECT 1

(3) LOG: parse statement: SELECT 1
LOG: exec statement: SELECT 1
LOG: exec statement: SELECT 1
LOG: exec statement: SELECT 1

Same notes apply to (3) here.

Syntax error case:
LOG: parse statement: I AM A SYNTAX ERROR
ERROR: syntax error ....

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.

As you can see from the output I'd like, I don't think that synthesizing
FETCH / EXECUTE queries that don't actually exist or logging statement /
portal names are useful things to do, at least at the Joe Average User
level.

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.

-O

Oh, I didn't realize a FETCH would show up as an EXECUTE. That is wrong
and should be fixed because a user-level FETCH shows up as a fetch, not
as the original query.

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

Simon Riggs wrote:
> > Oliver Jowett wrote:
> > > 8.1-beta1 produces some odd results with statement logging enabled when
> > > the extended query protocol is used (e.g. when using the JDBC driver).
> > > Repeatedly running a simple query with log_statement = 'all' produces this:
> ...
>
> > > Secondly, running a query that uses portals produces output like this:
> > >
> > > LOG: statement: PREPARE S_3 AS SELECT * from pg_proc
> > > LOG: statement: <BIND> C_4
> > > LOG: statement: EXECUTE C_4 [PREPARE: SELECT * from pg_proc]
> > > LOG: statement: EXECUTE C_4 [PREPARE: SELECT * from pg_proc]
> > > LOG: statement: EXECUTE C_4 [PREPARE: SELECT * from pg_proc]
> > > LOG: statement: EXECUTE C_4 [PREPARE: SELECT * from pg_proc]
> > > LOG: statement: EXECUTE C_4 [PREPARE: SELECT * from pg_proc]
> > > LOG: statement: EXECUTE C_4 [PREPARE: SELECT * from pg_proc]
> > > LOG: statement: EXECUTE C_4 [PREPARE: SELECT * from pg_proc]
> > >
> > > Comments:
> > > - The <BIND> is still fairly content-free.
> > > - The EXECUTEs are a bit misleading as the SELECT was actually only run
> > > once (there are multiple Execute messages for the same portal). You
> > > could infer that there is only one SELECT from the repeated portal name
> > > and the lack of an intervening <BIND>, I suppose.
>
> I've put together this prototype to offer more useful messages in the
> situation Oliver describes.
>
> Subsequent calls to the same portal are described as FETCHes rather than
> as EXECUTEs. The portal name is still given and number of rows is
> provided also.
>
> I haven't tested this with the java program supplied, since this is a
> fairly short-hack for comments. I'll correct any mistakes before
> submission to patches.
>
> Comments?
>
> Best Regards, Simon Riggs

[ Attachment, skipping... ]

--
Bruce Momjian | http://candle.pha.pa.us
pgman(at)candle(dot)pha(dot)pa(dot)us | (610) 359-1001
+ If your life is a hard drive, | 13 Roberts Road
+ Christ can be your backup. | Newtown Square, Pennsylvania 19073

On Thu, 2005-09-08 at 13:14 +1200, Oliver Jowett wrote:
> Simon Riggs wrote:
> > On Tue, 2005-09-06 at 07:47 +0000, Oliver Jowett wrote:
> >>Simon Riggs wrote:
> >>>Looking more closely, I don't think either is correct. Both can be reset
> >>>according to rewind operations - see DoPortalRewind().
> >>>
> >>>We'd need to add another bool onto the Portal status data structure.
> >>
> >>AFAIK this is only an issue with SCROLLABLE cursors, which v3 portals
> >>aren't.
> >
> > OK, that may be so, but the internals don't know that. If I use atEnd or
> > atStart then messages would differ from v3 to v2. It would then be easy
> > to confuse v2 cursor actions with multiple re-executions in v3. I want
> > to be able to look at the log and work out what happened, not to start
> > asking questions like "do you use v2, v3 or a mix of both?".
>
> Uh, but the logging in question only runs from exec_execute_message,
> which is explicitly handling a v3 Execute message, not an EXECUTE or
> FETCH from somewhere else? If that can be confused with a v2 query, then
> we should be logging it in such a way that it doesn't get confused (this
> is one reason why I don't like your approach of synthesizing
> FETCH/EXECUTE statements that were never actually submitted by the client).
>
> I don't think we should worry about trying to support v3 Execute against
> a SCROLLABLE cursor created via DECLARE that has been rewound -- that's
> a strange case and there was some discussion previously about separating
> the v3 portal vs. cursor namespaces anyway.

OK, if everybody is saying "dont worry", I'll switch it to use atStart.

Best Regards, Simon Riggs

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 (named portal C_2, row limit 42)

(3)
jdbc prepare S_2
LOG: statement: PREPARE S_2 AS SELECT * from pg_proc

jdbc bind S_2 to C_2
jdbc execute C_2
LOG: statement: EXECUTE C_2 ROWS 42 [PREPARE: SELECT * from pg_proc]
jdbc next (after cache has run out on 42nd row)
v3 protocol sends E for Execute, execution halts at 49 rows for this set
of bind parameters
LOG: statement: FETCH C_2 ROWS 7

jdbc bind S_2 to C_2
jdbc execute C_2
LOG: statement: EXECUTE C_2 ROWS 42 [PREPARE: SELECT * from pg_proc]
jdbc next (after cache has run out on 42nd row)
v3 protocol sends E for Execute
LOG: statement: FETCH C_2 ROWS 42
jdbc next (after cache has run out on 84th row)
v3 protocol sends E for Execute, execution halts at 95 rows for this set
of bind parameters
LOG: statement: FETCH C_2 ROWS 11

Note: log_min_duration_statement logs after execution so can give
accurate row counts of what was retrieved for first execute and
subsequent fetches. In that case we log using the word ROWS.
log_statement=all logs before execution and so only knows what the
maximum number of rows requested is, not what the actual number of rows
retrieved will be. In that case we log using the word MAXROWS.
ROWS and MAXROWS are *not* mentioned unless we specifically set max_rows
in the execute request using the v3 protocol.

If we agree, I'd suggest this goes into the docs...

I've not written a comprehensive test program that covers all of the
different settings of v2/v3, named/unnamed, allrows/restricted rows,
log_statement=all/log_min_duration_statement. I'm not sure that will fit
within the existing test framework. So this patch is still prototype.

Comments?

Best Regards, Simon Riggs

Simon Riggs wrote:

> Are we sure there is just 3 cases?

I haven't exhaustively checked, but I think those are the main cases.

> Even if case (3) is not that common, I still want to know it is
> occurring, to see what effect or overhead it has.

I don't want it to be more verbose than the other cases when I set
log_statement = all.

> We'll only see the output for case (3) when someone has programmed
> things that way by using setFetchSize.

Can we put extra output in this case into log_statement = verbose only
please?

> (1)
> 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 about the syntax error case?

> (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]

I do not like logging queries that the driver never sent (the driver
sends neither PREPARE nor EXECUTE).

I also don't see why it's useful to log the statement and portal names.

Can we reword this to what I suggested previously?

LOG: parse statement: SELECT * from pg_proc
LOG: execute statement: SELECT * from pg_proc

> (3)
> jdbc prepare S_2
> LOG: statement: PREPARE S_2 AS SELECT * from pg_proc
>
> jdbc bind S_2 to C_2
> jdbc execute C_2
> LOG: statement: EXECUTE C_2 ROWS 42 [PREPARE: SELECT * from pg_proc]
> jdbc next (after cache has run out on 42nd row)
> v3 protocol sends E for Execute, execution halts at 49 rows for this set
> of bind parameters
> LOG: statement: FETCH C_2 ROWS 7

Again I do not like logging synthetic queries that the driver never sent
(PREPARE / EXECUTE / FETCH). BTW, if you do it this way, you could get
the bizarre "PREPARE S_2 AS PREPARE xyz AS SELECT .." result if the
application used PREPARE itself.

I think that logging the second and subsequent Executes is not normally
useful and shouldn't happen when log_statement = all. In that case you
don't need to log the portal name either.

So for the normal case:

LOG: parse statement: SELECT * from pg_proc
LOG: execute statement: SELECT * from pg_proc

and for the verbose case perhaps something like:

LOG: parse statement: SELECT * from pg_proc
LOG: execute statement (C_2, 42 rows): SELECT * from pg_proc
LOG: fetch statement results (C_2, 7 rows)

-O

Your patch has been added to the PostgreSQL unapplied patches list at:

http://momjian.postgresql.org/cgi-bin/pgpatches

It will be applied as soon as one of the PostgreSQL committers reviews
and approves it.

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

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 (named portal C_2, row limit 42)
>
> (3)
> jdbc prepare S_2
> LOG: statement: PREPARE S_2 AS SELECT * from pg_proc
>
> jdbc bind S_2 to C_2
> jdbc execute C_2
> LOG: statement: EXECUTE C_2 ROWS 42 [PREPARE: SELECT * from pg_proc]
> jdbc next (after cache has run out on 42nd row)
> v3 protocol sends E for Execute, execution halts at 49 rows for this set
> of bind parameters
> LOG: statement: FETCH C_2 ROWS 7
>
> jdbc bind S_2 to C_2
> jdbc execute C_2
> LOG: statement: EXECUTE C_2 ROWS 42 [PREPARE: SELECT * from pg_proc]
> jdbc next (after cache has run out on 42nd row)
> v3 protocol sends E for Execute
> LOG: statement: FETCH C_2 ROWS 42
> jdbc next (after cache has run out on 84th row)
> v3 protocol sends E for Execute, execution halts at 95 rows for this set
> of bind parameters
> LOG: statement: FETCH C_2 ROWS 11
>
> Note: log_min_duration_statement logs after execution so can give
> accurate row counts of what was retrieved for first execute and
> subsequent fetches. In that case we log using the word ROWS.
> log_statement=all logs before execution and so only knows what the
> maximum number of rows requested is, not what the actual number of rows
> retrieved will be. In that case we log using the word MAXROWS.
> ROWS and MAXROWS are *not* mentioned unless we specifically set max_rows
> in the execute request using the v3 protocol.
>
> If we agree, I'd suggest this goes into the docs...
>
> I've not written a comprehensive test program that covers all of the
> different settings of v2/v3, named/unnamed, allrows/restricted rows,
> log_statement=all/log_min_duration_statement. I'm not sure that will fit
> within the existing test framework. So this patch is still prototype.
>
> Comments?
>
> Best Regards, Simon Riggs

[ Attachment, skipping... ]

>
> ---------------------------(end of broadcast)---------------------------
> TIP 5: don't forget to increase your free space map settings

--
Bruce Momjian | http://candle.pha.pa.us
pgman(at)candle(dot)pha(dot)pa(dot)us | (610) 359-1001
+ If your life is a hard drive, | 13 Roberts Road
+ Christ can be your backup. | Newtown Square, Pennsylvania 19073

Oliver Jowett wrote:
> Simon Riggs wrote:
>
> > Are we sure there is just 3 cases?
>
> I haven't exhaustively checked, but I think those are the main cases.
>
> > Even if case (3) is not that common, I still want to know it is
> > occurring, to see what effect or overhead it has.
>
> I don't want it to be more verbose than the other cases when I set
> log_statement = all.

I think it is more verbose because no FETCH is logged in this type of
prepare/execute. The goal, I think, is for these type of queries to
look as similar to normal PREPARE/EXECUTE and DECLARE/FETCH as possible.

> > We'll only see the output for case (3) when someone has programmed
> > things that way by using setFetchSize.
>
> Can we put extra output in this case into log_statement = verbose only
> please?

We don't have a log_statement = verbose mode.

> > (1)
> > 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 about the syntax error case?

Good point, but when do we parse? Could you set log_min_error_statement
to error? I don't think that would work either.

> > (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]
>
> I do not like logging queries that the driver never sent (the driver
> sends neither PREPARE nor EXECUTE).
>
> I also don't see why it's useful to log the statement and portal names.
>
> Can we reword this to what I suggested previously?
>
> LOG: parse statement: SELECT * from pg_proc
> LOG: execute statement: SELECT * from pg_proc

The problem here is that scripts that look for "LOG: statement:" would
now need to look for additional words at the start. It also makes this
type of prepare/execute look different in the logs, while internally it
is quite similar.

> > (3)
> > jdbc prepare S_2
> > LOG: statement: PREPARE S_2 AS SELECT * from pg_proc
> >
> > jdbc bind S_2 to C_2
> > jdbc execute C_2
> > LOG: statement: EXECUTE C_2 ROWS 42 [PREPARE: SELECT * from pg_proc]
> > jdbc next (after cache has run out on 42nd row)
> > v3 protocol sends E for Execute, execution halts at 49 rows for this set
> > of bind parameters
> > LOG: statement: FETCH C_2 ROWS 7
>
> Again I do not like logging synthetic queries that the driver never sent
> (PREPARE / EXECUTE / FETCH). BTW, if you do it this way, you could get
> the bizarre "PREPARE S_2 AS PREPARE xyz AS SELECT .." result if the
> application used PREPARE itself.
>
> I think that logging the second and subsequent Executes is not normally
> useful and shouldn't happen when log_statement = all. In that case you
> don't need to log the portal name either.
>
> So for the normal case:
>
> LOG: parse statement: SELECT * from pg_proc
> LOG: execute statement: SELECT * from pg_proc
>
> and for the verbose case perhaps something like:
>
> LOG: parse statement: SELECT * from pg_proc
> LOG: execute statement (C_2, 42 rows): SELECT * from pg_proc
> LOG: fetch statement results (C_2, 7 rows)

We don't have a verbose case. Why should it look different from
client-side stuff?

--
Bruce Momjian | http://candle.pha.pa.us
pgman(at)candle(dot)pha(dot)pa(dot)us | (610) 359-1001
+ If your life is a hard drive, | 13 Roberts Road
+ Christ can be your backup. | Newtown Square, Pennsylvania 19073

Bruce Momjian wrote:

> We don't have a log_statement = verbose mode.

Please see my earlier email where I suggested adding one if you really
wanted all this protocol-level detail logged.

-O

Bruce Momjian wrote:

> I think it is more verbose because no FETCH is logged in this type of
> prepare/execute. The goal, I think, is for these type of queries to
> look as similar to normal PREPARE/EXECUTE and DECLARE/FETCH as possible.

I do not understand why this is a useful thing to do as part of
log_statement.

My point is that given JDBC code like this:

Statement s = connection.createStatement();
ResultSet rs = s.executeQuery("SELECT * FROM pg_proc");
while (rs.next()) {
// Process results
}

it seems that the least surprising thing to get logged is simply "SELECT
* FROM pg_proc".

I don't see how logging a synthetic PREPARE/EXECUTE/FETCH sequence (and
DECLARE, now?) is useful. They're not necessarily syntactically correct,
and they're certainly not queries that were actually sent to the
backend. I thought log_statement was meant to answer the question "what
queries were submitted to the backend?", rather than to provide a trace
of protocol-level activity..

-O

Oliver Jowett wrote:
> Bruce Momjian wrote:
>
> > We don't have a log_statement = verbose mode.
>
> Please see my earlier email where I suggested adding one if you really
> wanted all this protocol-level detail logged.

We can't add that in feature freeze/beta, at least.

--
Bruce Momjian | http://candle.pha.pa.us
pgman(at)candle(dot)pha(dot)pa(dot)us | (610) 359-1001
+ If your life is a hard drive, | 13 Roberts Road
+ Christ can be your backup. | Newtown Square, Pennsylvania 19073

Oliver Jowett wrote:
> Bruce Momjian wrote:
>
> > I think it is more verbose because no FETCH is logged in this type of
> > prepare/execute. The goal, I think, is for these type of queries to
> > look as similar to normal PREPARE/EXECUTE and DECLARE/FETCH as possible.
>
> I do not understand why this is a useful thing to do as part of
> log_statement.
>
> My point is that given JDBC code like this:
>
> Statement s = connection.createStatement();
> ResultSet rs = s.executeQuery("SELECT * FROM pg_proc");
> while (rs.next()) {
> // Process results
> }
>
> it seems that the least surprising thing to get logged is simply "SELECT
> * FROM pg_proc".
>
> I don't see how logging a synthetic PREPARE/EXECUTE/FETCH sequence (and
> DECLARE, now?) is useful. They're not necessarily syntactically correct,
> and they're certainly not queries that were actually sent to the
> backend. I thought log_statement was meant to answer the question "what
> queries were submitted to the backend?", rather than to provide a trace
> of protocol-level activity..

Well, from the application writer perspective, you are right it doesn't
make sense, but this is only because jdbc is using prepare internally.
If you were to have written it in libpq, it would make sense, I think,
and internally, this is what is happening. We can't assume only
interface libraries like jdbc are using this feature.

As far as I understand things, the protocol-level prepare/execute is
identical to the SQL-level prepare/execute, except that there is no need
to parse the execute, so it should log like the SQL-level statements, if
possible.

--
Bruce Momjian | http://candle.pha.pa.us
pgman(at)candle(dot)pha(dot)pa(dot)us | (610) 359-1001
+ If your life is a hard drive, | 13 Roberts Road
+ Christ can be your backup. | Newtown Square, Pennsylvania 19073

Bruce Momjian wrote:

> Well, from the application writer perspective, you are right it doesn't
> make sense,

This is exactly what the end user is going to say.

> but this is only because jdbc is using prepare internally.

Isn't this mostly irrelevant to the result we want to see? It's a detail
of how the interface layer chooses to execute its queries, and 90% of
the time the end user is not going to know or care about it.

> If you were to have written it in libpq, it would make sense, I think,
> and internally, this is what is happening. We can't assume only
> interface libraries like jdbc are using this feature.

Wait, so is the extended query protocol the poor cousin of "what libpq
does", or what? You can do Parse/Bind using libpq, can't you?

The *meaning* of the Parse/Bind/Execute sequence is quite clear
regardless of what interface library is used. I still think that logging
just the queries that were actually executed, once per execution, is the
sensible thing to do here. I can't see a sequence of protocol messages
that would produce a strange result if we used the rules I suggested --
do you have an example where it breaks?

> As far as I understand things, the protocol-level prepare/execute is
> identical to the SQL-level prepare/execute, except that there is no need
> to parse the execute, so it should log like the SQL-level statements, if
> possible.

You can Parse any SQL statement, but you can't PREPARE any SQL
statement. So, no, they're not equivalent. That's one aspect of what I
meant about generating synthetic statements that weren't syntactially
correct (the strange FETCH syntax with ROWS/MAXROWS that Simon was
suggesting is another case).

-O

Oliver Jowett wrote:
> Bruce Momjian wrote:
>
> > Well, from the application writer perspective, you are right it doesn't
> > make sense,
>
> This is exactly what the end user is going to say.
>
> > but this is only because jdbc is using prepare internally.
>
> Isn't this mostly irrelevant to the result we want to see? It's a detail
> of how the interface layer chooses to execute its queries, and 90% of
> the time the end user is not going to know or care about it.

Right, but have no way to know if the user is using an interface that
hides prepares from them, or they are using prepares visibly in their
applications. For this reason, we should just display whatever the
backend is doing. If all interfaces used prepares invisibly like jdbc,
we would be right to suppress the log information.

> > If you were to have written it in libpq, it would make sense, I think,
> > and internally, this is what is happening. We can't assume only
> > interface libraries like jdbc are using this feature.
>
> Wait, so is the extended query protocol the poor cousin of "what libpq
> does", or what? You can do Parse/Bind using libpq, can't you?

Sure.

> The *meaning* of the Parse/Bind/Execute sequence is quite clear
> regardless of what interface library is used. I still think that logging
> just the queries that were actually executed, once per execution, is the
> sensible thing to do here. I can't see a sequence of protocol messages
> that would produce a strange result if we used the rules I suggested --
> do you have an example where it breaks?

I have no idea.

> > As far as I understand things, the protocol-level prepare/execute is
> > identical to the SQL-level prepare/execute, except that there is no need
> > to parse the execute, so it should log like the SQL-level statements, if
> > possible.
>
> You can Parse any SQL statement, but you can't PREPARE any SQL
> statement. So, no, they're not equivalent. That's one aspect of what I
> meant about generating synthetic statements that weren't syntactially
> correct (the strange FETCH syntax with ROWS/MAXROWS that Simon was
> suggesting is another case).

I am hesitant to add another log syntax to be used just for
protocol-level prepare. I think it adds complexity with little benefit,
particularly for people reading those logs with automated tools.

Simon's page is in the patches queue. What would you like changed,
exactly?

--
Bruce Momjian | http://candle.pha.pa.us
pgman(at)candle(dot)pha(dot)pa(dot)us | (610) 359-1001
+ If your life is a hard drive, | 13 Roberts Road
+ Christ can be your backup. | Newtown Square, Pennsylvania 19073

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 C_2)
> > repeatedly:
> > Execute (named portal C_2, row limit 42)
>
> (3)
> jdbc prepare S_2
> LOG: statement: PREPARE S_2 AS SELECT * from pg_proc
>
> jdbc bind S_2 to C_2
> jdbc execute C_2
> LOG: statement: EXECUTE C_2 ROWS 42 [PREPARE: SELECT * from pg_proc]
> jdbc next (after cache has run out on 42nd row)
> v3 protocol sends E for Execute, execution halts at 49 rows for this set
> of bind parameters
> LOG: statement: FETCH C_2 ROWS 7
>
> jdbc bind S_2 to C_2
> jdbc execute C_2
> LOG: statement: EXECUTE C_2 ROWS 42 [PREPARE: SELECT * from pg_proc]
> jdbc next (after cache has run out on 42nd row)
> v3 protocol sends E for Execute
> LOG: statement: FETCH C_2 ROWS 42
> jdbc next (after cache has run out on 84th row)
> v3 protocol sends E for Execute, execution halts at 95 rows for this set
> of bind parameters
> LOG: statement: FETCH C_2 ROWS 11
>
> Note: log_min_duration_statement logs after execution so can give
> accurate row counts of what was retrieved for first execute and
> subsequent fetches. In that case we log using the word ROWS.
> log_statement=all logs before execution and so only knows what the
> maximum number of rows requested is, not what the actual number of rows
> retrieved will be. In that case we log using the word MAXROWS.
> ROWS and MAXROWS are *not* mentioned unless we specifically set max_rows
> in the execute request using the v3 protocol.
>
> If we agree, I'd suggest this goes into the docs...
>
> I've not written a comprehensive test program that covers all of the
> different settings of v2/v3, named/unnamed, allrows/restricted rows,
> log_statement=all/log_min_duration_statement. I'm not sure that will fit
> within the existing test framework. So this patch is still prototype.

Here are my comments on the patch:

> Index: src/backend/tcop/postgres.c
> ===================================================================
> RCS file: /projects/cvsroot/pgsql/src/backend/tcop/postgres.c,v
> retrieving revision 1.458
> diff -c -c -r1.458 postgres.c
> *** src/backend/tcop/postgres.c 2 Sep 2005 21:50:54 -0000 1.458
> --- src/backend/tcop/postgres.c 9 Sep 2005 10:06:46 -0000
> ***************
> *** 1162,1173 ****
> if (save_log_statement_stats)
> ResetUsage();
>
> - if (log_statement == LOGSTMT_ALL)
> - ereport(LOG,
> - (errmsg("statement: PREPARE %s AS %s",
> - (*stmt_name != '\0') ? stmt_name : "<unnamed>",
> - query_string)));
> -
> /*
> * Start up a transaction command so we can run parse analysis etc.
> * (Note that this will normally change current memory context.)
> --- 1162,1167 ----
> ***************
> *** 1217,1222 ****
> --- 1211,1222 ----
>
> QueryContext = CurrentMemoryContext;
>
> +
> + /* 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.

> /*
> * 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.

> /*
> ***************
> *** 1683,1688 ****
> --- 1683,1689 ----
> bool save_log_duration = log_duration;
> int save_log_min_duration_statement = log_min_duration_statement;
> bool save_log_statement_stats = log_statement_stats;
> + bool subsequent_fetch = false;

Can we call this "execute_is_fetch". That seems clearer.

>
> /* Adjust destination to tell printtup.c what to do */
> dest = whereToSendOutput;
> ***************
> *** 1695,1700 ****
> --- 1696,1710 ----
> (errcode(ERRCODE_UNDEFINED_CURSOR),
> errmsg("portal \"%s\" does not exist", portal_name)));
>
> + /*
> + * If we re-issue an Execute protocol request against an existing
> + * portal, then we are only fetching more rows rather than
> + * completely re-executing the query from the start. atStart is never
> + * reset for a v3 portal, so we are safe to use this check.
> + */
> + if (!portal->atStart)
> + subsequent_fetch = true;
> +
> /*
> * If the original query was a null string, just return
> * EmptyQueryResponse.
> ***************
> *** 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".

> {
> debug_query_string = portal->sourceText;
> pgstat_report_activity(portal->sourceText);
> ***************
> *** 1731,1742 ****
> if (save_log_statement_stats)
> ResetUsage();
>
> if (log_statement == LOGSTMT_ALL)
> ! /* We have the portal, so output the source query. */
> ! ereport(LOG,
> ! (errmsg("statement: EXECUTE %s [PREPARE: %s]",
> ! (*portal_name != '\0') ? portal_name : "<unnamed>",
> portal->sourceText ? portal->sourceText : "")));
>
> BeginCommand(portal->commandTag, dest);
>
> --- 1746,1774 ----
> if (save_log_statement_stats)
> ResetUsage();
>
> + /*
> + * log statement details - when using log_statement=all we log the
> + * phrase MAXROWS because this occurs prior to execution
> + */
> if (log_statement == LOGSTMT_ALL)
> ! {
> ! if (subsequent_fetch)
> ! ereport(LOG,
> ! (errmsg("statement: FETCH %s MAXROWS %ld", portal_name,
> ! max_rows)));
> ! else
> ! /* We have the portal, so output the source query. */
> ! if (max_rows <= 0)
> ! ereport(LOG,
> ! (errmsg("statement: EXECUTE %s [PREPARE: %s]",
> ! portal_name,
> portal->sourceText ? portal->sourceText : "")));
> + else
> + ereport(LOG,
> + (errmsg("statement: EXECUTE %s MAXROWS %ld [PREPARE: %s]",
> + portal_name, max_rows,
> + portal->sourceText ? portal->sourceText : "")));
> + }

MAXROWS seems useful. Good.

> BeginCommand(portal->commandTag, dest);
>
> ***************
> *** 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 (save_log_min_duration_statement == 0 ||
> (save_log_min_duration_statement > 0 &&
> usecs >= save_log_min_duration_statement * 1000))
> ! {
> ! if (subsequent_fetch)

Should the duration be snprintf into a local buffer and then used in
each ereport, rather than duplicating the code three times?

> ! ereport(LOG,
> ! (errmsg("duration: %ld.%03ld ms statement: FETCH %s ROWS %ld ",
> (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,
> ! max_rows)));
> ! else
> ! if (completed)
> ! 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,
> ! portal->sourceText ? portal->sourceText : "")));
> ! else
> ! ereport(LOG,
> ! (errmsg("duration: %ld.%03ld ms statement: EXECUTE %s ROWS %ld [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, max_rows,
> ! portal->sourceText ? portal->sourceText : "")));
> ! }
> }
>
> if (save_log_statement_stats)

--
Bruce Momjian | http://candle.pha.pa.us
pgman(at)candle(dot)pha(dot)pa(dot)us | (610) 359-1001
+ If your life is a hard drive, | 13 Roberts Road
+ Christ can be your backup. | Newtown Square, Pennsylvania 19073

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 ----
> > bool save_log_duration = log_duration;
> > int save_log_min_duration_statement = log_min_duration_statement;
> > bool save_log_statement_stats = log_statement_stats;
> > + bool subsequent_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 (save_log_min_duration_statement == 0 ||
> > (save_log_min_duration_statement > 0 &&
> > usecs >= save_log_min_duration_statement * 1000))
> > ! {
> > ! if (subsequent_fetch)
>
> Should the duration be snprintf into a local buffer and then used in
> each ereport, rather than duplicating the code three times?

Yes (this was never going to be the final patch...)

Best Regards, Simon Riggs

Bruce Momjian wrote:

> Simon's page is in the patches queue. What would you like changed,
> exactly?

I'm not going to have time to comment on this any time soon, sorry :( ..
I guess I will try to look at it for 8.2.

-O

Simon Riggs wrote:
> 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.

I am confused. I don't see SimpleQuery mentioned anywhere in our
documentation. Is it a JDBC function? Are you saying an unnamed
prepare should only be logged once? Why?

> > 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.

I see no reason they should not always be logged if we are logging
all or mod statements.

> > Should the duration be snprintf into a local buffer and then used in
> > each ereport, rather than duplicating the code three times?
>
> Yes (this was never going to be the final patch...)

OK. At this stage it should all just wait for 8.2. I think the only
missing things we have now is that BIND parameters are not logged, and a
fetch of an already-executed statement appears as another execute.

Added to TODO:

* Allow protocol-level BIND parameter values to be logged
* Allow protocol-level EXECUTE that is actually a fetch to appear
in the logs as a fetch rather than another execute

--
Bruce Momjian | http://candle.pha.pa.us
pgman(at)candle(dot)pha(dot)pa(dot)us | (610) 359-1001
+ If your life is a hard drive, | 13 Roberts Road
+ Christ can be your backup. | Newtown Square, Pennsylvania 19073

Bruce Momjian <pgman(at)candle(dot)pha(dot)pa(dot)us> writes:
> OK. At this stage it should all just wait for 8.2.

Haven't we already committed some feature changes in this area? I
dislike the idea of shipping a transient state just because "we ran out
of time". Once we ship 8.1, that will be another behavior that we have
to consider backwards compatibility with. We should either fix it
right, or revert to the 8.0 behavior for this release.

regards, tom lane

Tom Lane wrote:
> Bruce Momjian <pgman(at)candle(dot)pha(dot)pa(dot)us> writes:
> > OK. At this stage it should all just wait for 8.2.
>
> Haven't we already committed some feature changes in this area? I
> dislike the idea of shipping a transient state just because "we ran out
> of time". Once we ship 8.1, that will be another behavior that we have
> to consider backwards compatibility with. We should either fix it
> right, or revert to the 8.0 behavior for this release.

I documented in TODO what doesn't log properly in 8.1. I don't see how
logging output has to be backward compatible. To revert would be to
remove logging of server-level prepare/execute. I don't see that as a
win.

--
Bruce Momjian | http://candle.pha.pa.us
pgman(at)candle(dot)pha(dot)pa(dot)us | (610) 359-1001
+ If your life is a hard drive, | 13 Roberts Road
+ Christ can be your backup. | Newtown Square, Pennsylvania 19073

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 (named portal C_2, row limit 42)
>
> (3)
> jdbc prepare S_2
> LOG: statement: PREPARE S_2 AS SELECT * from pg_proc
>
> jdbc bind S_2 to C_2
> jdbc execute C_2
> LOG: statement: EXECUTE C_2 ROWS 42 [PREPARE: SELECT * from pg_proc]
> jdbc next (after cache has run out on 42nd row)
> v3 protocol sends E for Execute, execution halts at 49 rows for this set
> of bind parameters
> LOG: statement: FETCH C_2 ROWS 7
>
> jdbc bind S_2 to C_2
> jdbc execute C_2
> LOG: statement: EXECUTE C_2 ROWS 42 [PREPARE: SELECT * from pg_proc]
> jdbc next (after cache has run out on 42nd row)
> v3 protocol sends E for Execute
> LOG: statement: FETCH C_2 ROWS 42
> jdbc next (after cache has run out on 84th row)
> v3 protocol sends E for Execute, execution halts at 95 rows for this set
> of bind parameters
> LOG: statement: FETCH C_2 ROWS 11
>
> Note: log_min_duration_statement logs after execution so can give
> accurate row counts of what was retrieved for first execute and
> subsequent fetches. In that case we log using the word ROWS.
> log_statement=all logs before execution and so only knows what the
> maximum number of rows requested is, not what the actual number of rows
> retrieved will be. In that case we log using the word MAXROWS.
> ROWS and MAXROWS are *not* mentioned unless we specifically set max_rows
> in the execute request using the v3 protocol.
>
> If we agree, I'd suggest this goes into the docs...
>
> I've not written a comprehensive test program that covers all of the
> different settings of v2/v3, named/unnamed, allrows/restricted rows,
> log_statement=all/log_min_duration_statement. I'm not sure that will fit
> within the existing test framework. So this patch is still prototype.
>
> Comments?
>
> Best Regards, Simon Riggs

[ Attachment, skipping... ]

>
> ---------------------------(end of broadcast)---------------------------
> TIP 5: don't forget to increase your free space map settings

--
Bruce Momjian | http://candle.pha.pa.us
pgman(at)candle(dot)pha(dot)pa(dot)us | (610) 359-1001
+ If your life is a hard drive, | 13 Roberts Road
+ Christ can be your backup. | Newtown Square, Pennsylvania 19073

On Sun, Sep 25, 2005 at 11:41:11PM -0400, Bruce Momjian wrote:
> Tom Lane wrote:
> > Bruce Momjian <pgman(at)candle(dot)pha(dot)pa(dot)us> writes:
> > > OK. At this stage it should all just wait for 8.2.
> >
> > Haven't we already committed some feature changes in this area? I
> > dislike the idea of shipping a transient state just because "we
> > ran out of time". Once we ship 8.1, that will be another behavior
> > that we have to consider backwards compatibility with. We should
> > either fix it right, or revert to the 8.0 behavior for this
> > release.
>
> I documented in TODO what doesn't log properly in 8.1. I don't see
> how logging output has to be backward compatible.

Dunno about this particular case, but not having backward-compatible
logging output has already broken pqa. Proposal on logging to
-hackers follows...

Cheers,
D
--
David Fetter david(at)fetter(dot)org http://fetter.org/
phone: +1 510 893 6100 mobile: +1 415 235 3778

Remember to vote!

David Fetter wrote:
> On Sun, Sep 25, 2005 at 11:41:11PM -0400, Bruce Momjian wrote:
> > Tom Lane wrote:
> > > Bruce Momjian <pgman(at)candle(dot)pha(dot)pa(dot)us> writes:
> > > > OK. At this stage it should all just wait for 8.2.
> > >
> > > Haven't we already committed some feature changes in this area? I
> > > dislike the idea of shipping a transient state just because "we
> > > ran out of time". Once we ship 8.1, that will be another behavior
> > > that we have to consider backwards compatibility with. We should
> > > either fix it right, or revert to the 8.0 behavior for this
> > > release.
> >
> > I documented in TODO what doesn't log properly in 8.1. I don't see
> > how logging output has to be backward compatible.
>
> Dunno about this particular case, but not having backward-compatible
> logging output has already broken pqa. Proposal on logging to
> -hackers follows...

Yes, that is one area that is of concern for logging changes. What I
have done is to get minimal logging of the FETCH behavior into 8.1,
along with what we already have added in 8.1.

--
Bruce Momjian | http://candle.pha.pa.us
pgman(at)candle(dot)pha(dot)pa(dot)us | (610) 359-1001
+ If your life is a hard drive, | 13 Roberts Road
+ Christ can be your backup. | Newtown Square, Pennsylvania 19073