Change in Log Format and Prepared Statements

Hi,

Over the past year we have performed upgrades to both our PostgreSQL
server our jdbc driver over the last few months:

 From PostgreSQL 8.2.10 with pg74.216.jdbc3 driver
To PostgreSQL 8.2.10 with pg8.2-511.jdbc4 driver
To PostgreSQL 9.1.4 with pg9.1-902.jdbc4 driver

(O/S is Centos 5)

When we moved from the pg74.216.jdbc3 driver to the pg8.2-511.jdbc4 we
saw a distinct change in the logging output by the database.

Previously with the pg74.216.jdbc3 driver we saw the statement followed
by a duration:

2012-09-13 13:08:48 BST [22116] [mp_demo] [pg] LOG:  statement: SELECT
users.USERID, users.LOGINID, users.ORGID, users.FIRSTNAME,
users.LASTNAME, users.TITLE, users.TELEPHONE, users.CELLPHONE,
users.PAGER, users.FAX, users.EMAIL, users.LASTLOGIN, users.ADDRESSID,
users.USERSTATUSID, users.SHARED, users.MODDATE, users.ISPROXY FROM
users WHERE users.LOGINID='alex-admin';
2012-09-13 13:08:48 BST [22116] [mp_demo] [pg] LOG:  duration: 0.805 ms

Now with the pg8.2-511.jdbc4 and pg9.1-902.jdbc4 drivers we see the
statement issued as an execute and three durations:

2012-09-13 13:07:33 BST [21664] [mp_demo] [pg] LOG:  execute <unnamed>:
SELECT users.USERID, users.LOGINID, users.ORGID, users.FIRSTNAME,
users.LASTNAME, users.TITLE, users.TELEPHONE, users.CELLPHONE,
users.PAGER, users.FAX, users.EMAIL, users.LASTLOGIN, users.ADDRESSID,
users.USERSTATUSID, users.SHARED, users.MODDATE, users.ISPROXY FROM
users WHERE users.LOGINID='alex-admin'
2012-09-13 13:07:33 BST [21664] [mp_demo] [pg] LOG:  duration: 0.208 ms
2012-09-13 13:07:33 BST [21664] [mp_demo] [pg] LOG:  duration: 1.136 ms
2012-09-13 13:07:33 BST [21664] [mp_demo] [pg] LOG:  duration: 0.156 ms

Indeed we still see the former if I run the same statement direct from
psql. So it looks to me as though the later drivers may be making use of
prepared statements (hence the "execute"?) but why do we now see 3
durations?

Also, as far as I can every single statement coming from the jdbc driver
is being issued as "execute <unnamed>: ......". Even BEGIN, COMMIT and
ROLLBACK statements are being issued in the same way and result in 2 or
3 duration statements. Is this normal?

If so, I am not convinced that we really want to use prepared statements
all the time, as it doesn't appear that statements are being repeated
(repetition being my understanding of why you would want to make use of
prepared statements). After looking at the documentation, I have tried
using the prepareThreshold parameter on the connection string in my
Tomcat server.xml (Tomcat v.6.0.29) to disable prepared statements, e.g.:

url="jdbc:postgresql://servername:5434/mp_demo?prepareThreshold=0"

.....but this doesn't seem to have any effect. Could anyone tell me what
is going on and how to effectively control this jdbc behaviour? I am
concerned the continual use of prepared statements for one-time-only
statements could be a performance drain on our system.

Alex Stanier.


This message has been scanned for malware by SurfControl plc. www.surfcontrol.com