Re: Change in Log Format and Prepared Statements

Yes, the new driver uses V3 protocol which uses prepared statements,
named and un-named. I think the 3 durations may be due to the prepare
and execute.

Dave Cramer

dave.cramer(at)credativ(dot)ca
http://www.credativ.ca

On Thu, Sep 13, 2012 at 8:47 AM, Alexander Stanier
<alexander(dot)stanier(at)egsgroup(dot)com> wrote:
> 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
>
>
> --
> Sent via pgsql-jdbc mailing list (pgsql-jdbc(at)postgresql(dot)org)
> To make changes to your subscription:
> http://www.postgresql.org/mailpref/pgsql-jdbc