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
[email protected] | (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
