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.
'jdbcostgresql://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

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.
> 'jdbcostgresql://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@candle.pha.pa.us | (610) 359-1001
+ If your life is a hard drive, | 13 Roberts Road
+ Christ can be your backup. | Newtown Square, Pennsylvania 19073


Index: src/backend/tcop/postgres.c
================================================== =================
RCS file: /cvsroot/pgsql/src/backend/tcop/postgres.c,v
retrieving revision 1.457
diff -c -c -r1.457 postgres.c
*** src/backend/tcop/postgres.c 11 Aug 2005 21:11:45 -0000 1.457
--- src/backend/tcop/postgres.c 2 Sep 2005 21:46:20 -0000
***************
*** 1164,1170 ****

if (log_statement == LOGSTMT_ALL)
ereport(LOG,
! (errmsg("statement: PREPARE %s AS %s", stmt_name, query_string)));

/*
* Start up a transaction command so we can run parse analysis etc.
--- 1164,1172 ----

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.
***************
*** 1732,1738 ****
if (log_statement == LOGSTMT_ALL)
/* We have the portal, so output the source query. */
ereport(LOG,
! (errmsg("statement: EXECUTE %s [PREPARE: %s]", portal_name,
portal->sourceText ? portal->sourceText : "")));

BeginCommand(portal->commandTag, dest);
--- 1734,1741 ----
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);
***************
*** 1867,1873 ****
(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 : "")));
}

--- 1870,1876 ----
(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 : "")));
}



---------------------------(end of broadcast)---------------------------
TIP 3: Have you checked our extensive FAQ?

http://www.postgresql.org/docs/faq

> 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


---------------------------(end of broadcast)---------------------------
TIP 9: In versions below 8.0, the planner will ignore your desire to
choose an index scan if your joining column's datatypes do not
match

Simon Riggs <simon@2ndquadrant.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

---------------------------(end of broadcast)---------------------------
TIP 4: Have you searched our list archives?

http://archives.postgresql.org

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

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

On Mon, 2005-09-05 at 15:38 -0400, Tom Lane wrote:
> Simon Riggs <simon@2ndquadrant.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


---------------------------(end of broadcast)---------------------------
TIP 3: Have you checked our extensive FAQ?

http://www.postgresql.org/docs/faq

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

---------------------------(end of broadcast)---------------------------
TIP 6: explain analyze is your friend

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


---------------------------(end of broadcast)---------------------------
TIP 3: Have you checked our extensive FAQ?

http://www.postgresql.org/docs/faq

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@candle.pha.pa.us | (610) 359-1001
+ If your life is a hard drive, | 13 Roberts Road
+ Christ can be your backup. | Newtown Square, Pennsylvania 19073

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

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


---------------------------(end of broadcast)---------------------------
TIP 4: Have you searched our list archives?

http://archives.postgresql.org