Re: statement logging / extended query protocol issues

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@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 : "")));
      }