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