statement logging / extended query protocol issues

From: Oliver Jowett <oliver(at)opencloud(dot)com>
To: pgsql-hackers <pgsql-hackers(at)postgresql(dot)org>
Subject: statement logging / extended query protocol issues
Date: 2005-08-31 02:34:49
Message-ID: 43151749.6050002@opencloud.com
Views: Raw Message | Whole Thread | Download mbox | Resend email
Thread:
Lists: pgsql-hackers pgsql-patches

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

Attachment Content-Type Size
TestStatementLogging.java text/plain 743 bytes

Responses

Browse pgsql-hackers by date

  From Date Subject
Next Message Simon Riggs 2005-08-31 06:41:13 Re: Pre-allocated free space for row updating
Previous Message Andrew Dunstan 2005-08-31 00:35:44 Re: Intermittent stats test failures on buildfarm

Browse pgsql-patches by date

  From Date Subject
Next Message Marc G. Fournier 2005-08-31 02:36:51 Re: [BUGS] PSQL commands not backwards-compatible
Previous Message Bruce Momjian 2005-08-31 02:20:07 Re: [BUGS] PSQL commands not backwards-compatible