Re: confused about transactions and connection pools

I am running a servlet on Tomcat 5.5 which talks to a PostgreSQL DB (8.1)
using the Jdbc3 driver.

The database is accessed using a DataSource, and so at the start of each
servlet doPost call I get a new connection, do a setAutoCommit( false) and
then get on with the processing. At the end if it works I do a commit
otherwise I do a rollback. Then I setAutoCommit( true) and write to a
log table (a single insert which I always want to do) and close the
connection. The servlet is entirely stateless, it keeps nothing from
one invocation to the next other than the DataSource which it opens
during its init( ) method along with a few configuration parameters.

I turned on postgresql logging and for the first request (the two requests and
their responses were identical - both failed) the postgresql log said:-

LOG: statement: BEGIN
LOG: statement: SELECT password, role, proxy, pool, company FROM users WHERE
id = $1
LOG: statement: INSERT INTO users( created, phone, password, role, origin,
xml, updated, id) VALUES( $1, $2, $3, $4, $5, $6, $7, $8)
LOG: statement: INSERT INTO users( created, phone, password, role, origin,
xml, updated, id) VALUES( $1, $2, $3, $4, $5, $6, $7, $8)
ERROR: duplicate key violates unique constraint "users_pkey"
LOG: statement: ROLLBACK
LOG: statement: INSERT INTO logs( userid, ip, request, response, at, success)
VALUES( $1, $2, $3, $4, $5, $6)
LOG: statement: SELECT 1 FROM ONLY "public"."users" x WHERE "id" = $1 FOR
UPDATE OF x
CONTEXT: SQL statement "SELECT 1 FROM ONLY "public"."users" x WHERE "id" = $1
FOR UPDATE OF x"

and for the second one it said:

LOG: statement: SELECT password, role, proxy, pool, company FROM users WHERE
id = $1
LOG: statement: INSERT INTO users( created, phone, password, role, origin,
xml, updated, id) VALUES( $1, $2, $3, $4, $5, $6, $7, $8)
LOG: statement: INSERT INTO users( created, phone, password, role, origin,
xml, updated, id) VALUES( $1, $2, $3, $4, $5, $6, $7, $8)
ERROR: duplicate key violates unique constraint "users_pkey"
LOG: statement: INSERT INTO logs( userid, ip, request, response, at, success)
VALUES( $1, $2, $3, $4, $5, $6)

which is slightly different.

Now the first thing I notice about this is that the first one has the BEGIN
I would expect, followed by a select (which I recognise) followed by the
insert that fails (quite why it logs it twice I do not know, it is certainly
not issued twice) followed by the rollback (because it failed) and the insert
into the logs table.

Then comes an odd SELECT statement (the one SELECT 1) which I do not recognise
and I can not find anywhere in my code. It is referencing one of my tables
(users) and it says both LOG: and CONTEXT: which I do not understand. Given
that the autoCommit was turned off after the rollback this should have had
no effect.

The we get to the second time through the servlet. First thing - no BEGIN
or ROLLBACK, but the code went through a call to connection.setAutoCommit(
false). Secondly this odd statement that I do not recognise id no longer
there.

My reason for investigating this is that I had an odd problem with the
log table being left with a lock on it, when none should exist as the
insert is done outside a transaction.

I have tried the same thing with a transaction that works (you just do not
get the ERROR: and in the first case you get a COMMIT not a ROLLBACK. Also
in that case the INSERT is not repeated in the log so I guess that is an
artifact of the failure.

Obviously I am doing something wrong, but for the life of me I can not see
what. Anyone got any ideas?

David

On 30-Oct-06, at 6:17 AM, David Goodenough wrote:

> I am running a servlet on Tomcat 5.5 which talks to a PostgreSQL DB
> (8.1)
> using the Jdbc3 driver.
>
> The database is accessed using a DataSource, and so at the start of
> each
> servlet doPost call I get a new connection, do a setAutoCommit
> ( false) and
> then get on with the processing. At the end if it works I do a commit
> otherwise I do a rollback. Then I setAutoCommit( true) and write to a
> log table (a single insert which I always want to do) and close the
> connection. The servlet is entirely stateless, it keeps nothing from
> one invocation to the next other than the DataSource which it opens
> during its init( ) method along with a few configuration parameters.
>
> I turned on postgresql logging and for the first request (the two
> requests and
> their responses were identical - both failed) the postgresql log
> said:-
>
> LOG: statement: BEGIN
> LOG: statement: SELECT password, role, proxy, pool, company FROM
> users WHERE
> id = $1
> LOG: statement: INSERT INTO users( created, phone, password, role,
> origin,
> xml, updated, id) VALUES( $1, $2, $3, $4, $5, $6, $7, $8)
> LOG: statement: INSERT INTO users( created, phone, password, role,
> origin,
> xml, updated, id) VALUES( $1, $2, $3, $4, $5, $6, $7, $8)
> ERROR: duplicate key violates unique constraint "users_pkey"
> LOG: statement: ROLLBACK
> LOG: statement: INSERT INTO logs( userid, ip, request, response,
> at, success)
> VALUES( $1, $2, $3, $4, $5, $6)
> LOG: statement: SELECT 1 FROM ONLY "public"."users" x WHERE "id" =
> $1 FOR
> UPDATE OF x
> CONTEXT: SQL statement "SELECT 1 FROM ONLY "public"."users" x
> WHERE "id" = $1
> FOR UPDATE OF x"
>
> and for the second one it said:
>
> LOG: statement: SELECT password, role, proxy, pool, company FROM
> users WHERE
> id = $1
> LOG: statement: INSERT INTO users( created, phone, password, role,
> origin,
> xml, updated, id) VALUES( $1, $2, $3, $4, $5, $6, $7, $8)
> LOG: statement: INSERT INTO users( created, phone, password, role,
> origin,
> xml, updated, id) VALUES( $1, $2, $3, $4, $5, $6, $7, $8)
> ERROR: duplicate key violates unique constraint "users_pkey"
> LOG: statement: INSERT INTO logs( userid, ip, request, response,
> at, success)
> VALUES( $1, $2, $3, $4, $5, $6)
>
> which is slightly different.
>
> Now the first thing I notice about this is that the first one has
> the BEGIN
> I would expect, followed by a select (which I recognise) followed
> by the
> insert that fails (quite why it logs it twice I do not know, it is
> certainly
> not issued twice) followed by the rollback (because it failed) and
> the insert
> into the logs table.
>
> Then comes an odd SELECT statement (the one SELECT 1) which I do
> not recognise
> and I can not find anywhere in my code.

Are you using hibernate ? Either way the select 1 is locking the
users table.
> It is referencing one of my tables
> (users) and it says both LOG: and CONTEXT: which I do not
> understand. Given
> that the autoCommit was turned off after the rollback this should
> have had
> no effect.
>
> The we get to the second time through the servlet. First thing -
> no BEGIN
> or ROLLBACK, but the code went through a call to
> connection.setAutoCommit(
> false). Secondly this odd statement that I do not recognise id no
> longer
> there.
>
> My reason for investigating this is that I had an odd problem with the
> log table being left with a lock on it, when none should exist as the
> insert is done outside a transaction.
>
> I have tried the same thing with a transaction that works (you just
> do not
> get the ERROR: and in the first case you get a COMMIT not a
> ROLLBACK. Also
> in that case the INSERT is not repeated in the log so I guess that
> is an
> artifact of the failure.
>
> Obviously I am doing something wrong, but for the life of me I can
> not see
> what. Anyone got any ideas?
First of all I'd suggest you add pid to the logs so you can see which
connection is doing what. The server logs sequentially in the order
it sees things. You could have 2 connections logs interleaved there.

Dave
>
> David
>
> ---------------------------(end of
> broadcast)---------------------------
> TIP 2: Don't 'kill -9' the postmaster
>

On Monday 30 October 2006 11:35, Dave Cramer wrote:
> On 30-Oct-06, at 6:17 AM, David Goodenough wrote:
> > I am running a servlet on Tomcat 5.5 which talks to a PostgreSQL DB
> > (8.1)
> > using the Jdbc3 driver.
> >
> > The database is accessed using a DataSource, and so at the start of
> > each
> > servlet doPost call I get a new connection, do a setAutoCommit
> > ( false) and
> > then get on with the processing. At the end if it works I do a commit
> > otherwise I do a rollback. Then I setAutoCommit( true) and write to a
> > log table (a single insert which I always want to do) and close the
> > connection. The servlet is entirely stateless, it keeps nothing from
> > one invocation to the next other than the DataSource which it opens
> > during its init( ) method along with a few configuration parameters.
> >
> > I turned on postgresql logging and for the first request (the two
> > requests and
> > their responses were identical - both failed) the postgresql log
> > said:-
> >
> > LOG: statement: BEGIN
> > LOG: statement: SELECT password, role, proxy, pool, company FROM
> > users WHERE
> > id = $1
> > LOG: statement: INSERT INTO users( created, phone, password, role,
> > origin,
> > xml, updated, id) VALUES( $1, $2, $3, $4, $5, $6, $7, $8)
> > LOG: statement: INSERT INTO users( created, phone, password, role,
> > origin,
> > xml, updated, id) VALUES( $1, $2, $3, $4, $5, $6, $7, $8)
> > ERROR: duplicate key violates unique constraint "users_pkey"
> > LOG: statement: ROLLBACK
> > LOG: statement: INSERT INTO logs( userid, ip, request, response,
> > at, success)
> > VALUES( $1, $2, $3, $4, $5, $6)
> > LOG: statement: SELECT 1 FROM ONLY "public"."users" x WHERE "id" =
> > $1 FOR
> > UPDATE OF x
> > CONTEXT: SQL statement "SELECT 1 FROM ONLY "public"."users" x
> > WHERE "id" = $1
> > FOR UPDATE OF x"
> >
> > and for the second one it said:
> >
> > LOG: statement: SELECT password, role, proxy, pool, company FROM
> > users WHERE
> > id = $1
> > LOG: statement: INSERT INTO users( created, phone, password, role,
> > origin,
> > xml, updated, id) VALUES( $1, $2, $3, $4, $5, $6, $7, $8)
> > LOG: statement: INSERT INTO users( created, phone, password, role,
> > origin,
> > xml, updated, id) VALUES( $1, $2, $3, $4, $5, $6, $7, $8)
> > ERROR: duplicate key violates unique constraint "users_pkey"
> > LOG: statement: INSERT INTO logs( userid, ip, request, response,
> > at, success)
> > VALUES( $1, $2, $3, $4, $5, $6)
> >
> > which is slightly different.
> >
> > Now the first thing I notice about this is that the first one has
> > the BEGIN
> > I would expect, followed by a select (which I recognise) followed
> > by the
> > insert that fails (quite why it logs it twice I do not know, it is
> > certainly
> > not issued twice) followed by the rollback (because it failed) and
> > the insert
> > into the logs table.
> >
> > Then comes an odd SELECT statement (the one SELECT 1) which I do
> > not recognise
> > and I can not find anywhere in my code.
>
> Are you using hibernate ? Either way the select 1 is locking the
> users table.

No, no hibernate. I was using ha-jdbc but I turned it off for this
test am I am using the Postgresql JDBC driver directly.

>
> > It is referencing one of my tables
> > (users) and it says both LOG: and CONTEXT: which I do not
> > understand. Given
> > that the autoCommit was turned off after the rollback this should
> > have had
> > no effect.
> >
> > The we get to the second time through the servlet. First thing -
> > no BEGIN
> > or ROLLBACK, but the code went through a call to
> > connection.setAutoCommit(
> > false). Secondly this odd statement that I do not recognise id no
> > longer
> > there.
> >
> > My reason for investigating this is that I had an odd problem with the
> > log table being left with a lock on it, when none should exist as the
> > insert is done outside a transaction.
> >
> > I have tried the same thing with a transaction that works (you just
> > do not
> > get the ERROR: and in the first case you get a COMMIT not a
> > ROLLBACK. Also
> > in that case the INSERT is not repeated in the log so I guess that
> > is an
> > artifact of the failure.
> >
> > Obviously I am doing something wrong, but for the life of me I can
> > not see
> > what. Anyone got any ideas?
>
> First of all I'd suggest you add pid to the logs so you can see which
> connection is doing what. The server logs sequentially in the order
> it sees things. You could have 2 connections logs interleaved there.

This is on a test machine, and I am submitting the requests to it manually
(they are XML and I have a testrig that submits them), so I know that there
is only one thing going on at the time of the test.

However for completeness it would be good to turn on the pid, I guess I
need the log_line_prefix set up. I will give it a go.

David

>
> Dave
>
> > David
> >
> > ---------------------------(end of
> > broadcast)---------------------------
> > TIP 2: Don't 'kill -9' the postmaster
>
> ---------------------------(end of broadcast)---------------------------
> TIP 2: Don't 'kill -9' the postmaster

On Mon, 30 Oct 2006, David Goodenough wrote:

> The we get to the second time through the servlet. First thing - no BEGIN
> or ROLLBACK, but the code went through a call to connection.setAutoCommit(
> false). Secondly this odd statement that I do not recognise id no longer
> there.
>

For each connection the statements BEGIN, ROLLBACK, and COMMIT are only
prepared once and after that they are executed again and again. This can
be very confusing when looking at the logs which only show the preparation
step, but not execution. So even though you can't see them, they're being
executed. The 8.2 release will be the first release that can accurately
log this usage pattern.

Kris Jurka

On Monday 30 October 2006 18:40, Kris Jurka wrote:
> On Mon, 30 Oct 2006, David Goodenough wrote:
> > The we get to the second time through the servlet. First thing - no
> > BEGIN or ROLLBACK, but the code went through a call to
> > connection.setAutoCommit( false). Secondly this odd statement that I do
> > not recognise id no longer there.
>
> For each connection the statements BEGIN, ROLLBACK, and COMMIT are only
> prepared once and after that they are executed again and again. This can
> be very confusing when looking at the logs which only show the preparation
> step, but not execution. So even though you can't see them, they're being
> executed. The 8.2 release will be the first release that can accurately
> log this usage pattern.
>
> Kris Jurka
is it only the BEGIN, ROLLBACK and COMMIT that are only shown when being
prepared? I ask because all the statement are PreparedStatements and they
get prepared each time we get a new connection, which I understand means
that they prepared for real first time they are used, but are then cached
and therefore that one should always use substitutable ? paramaters so that
the statement is always the same. If only the prepares are being logged
then the pool is obviously not working as the insert into the logs table
get logged each time through.

I am now more confused.

David

On Mon, 30 Oct 2006, David Goodenough wrote:

> On Monday 30 October 2006 18:40, Kris Jurka wrote:
>> For each connection the statements BEGIN, ROLLBACK, and COMMIT are only
>> prepared once and after that they are executed again and again. This can
>> be very confusing when looking at the logs which only show the preparation
>> step, but not execution. So even though you can't see them, they're being
>> executed. The 8.2 release will be the first release that can accurately
>> log this usage pattern.
>>
> is it only the BEGIN, ROLLBACK and COMMIT that are only shown when being
> prepared? I ask because all the statement are PreparedStatements and they
> get prepared each time we get a new connection, which I understand means
> that they prepared for real first time they are used, but are then cached
> and therefore that one should always use substitutable ? paramaters so that
> the statement is always the same. If only the prepares are being logged
> then the pool is obviously not working as the insert into the logs table
> get logged each time through.
>

The driver handles BEGIN, ROLLBACK, and COMMIT slightly differently than
regular PreparedStatement objects. For user PreparedStatements, the
driver only avoids reparsing it on the fifth execution. This is
configurable via the prepareThreshold URL parameter. So after you use
it five times you won't see it being logged any more. For these
transaction handling commands the driver knows it will be reusing them
often, so it switches over right away, not on the fifth exectuion. The
execution count is kept in the PreparedStatement object so if you do
something like:

get connection from pool
create PreparedStatement
execute PreparedStatement
close PreparedStatement
return connection to pool

Then no matter how many times you do the above the it will never switch
to avoiding the reparse because the count is kept in the
PreparedStatement which is continually created and destroyed,
reinitializing the counter. The driver/connection manages the reference
to the transaction handling commands so it can keep them around across
connections the pool hands out.

Kris Jurka

Kris Jurka <books(at)ejurka(dot)com> writes:
> For each connection the statements BEGIN, ROLLBACK, and COMMIT are only
> prepared once and after that they are executed again and again. This can
> be very confusing when looking at the logs which only show the preparation
> step, but not execution. So even though you can't see them, they're being
> executed. The 8.2 release will be the first release that can accurately
> log this usage pattern.

BTW, have you verified that it's actually worth the trouble to prepare
these commands? Given that there's no planning cost for a utility
statement, and hardly any parsing cost for one-word commands, I'm a bit
dubious that the prepared-statement machinery actually results in a win
compared to just issuing simple Query messages.

regards, tom lane

On 30-Oct-06, at 5:25 PM, Tom Lane wrote:

> Kris Jurka <books(at)ejurka(dot)com> writes:
>> For each connection the statements BEGIN, ROLLBACK, and COMMIT are
>> only
>> prepared once and after that they are executed again and again.
>> This can
>> be very confusing when looking at the logs which only show the
>> preparation
>> step, but not execution. So even though you can't see them,
>> they're being
>> executed. The 8.2 release will be the first release that can
>> accurately
>> log this usage pattern.
>
> BTW, have you verified that it's actually worth the trouble to prepare
> these commands? Given that there's no planning cost for a utility
> statement, and hardly any parsing cost for one-word commands, I'm a
> bit
> dubious that the prepared-statement machinery actually results in a
> win
> compared to just issuing simple Query messages.

Yeah, the driver needs to be taught to not prepare *everything* in v3
mode

Dave
>
> regards, tom lane
>
> ---------------------------(end of
> broadcast)---------------------------
> TIP 4: Have you searched our list archives?
>
> http://archives.postgresql.org
>

Tom Lane wrote:
> I'm a bit
> dubious that the prepared-statement machinery actually results in a win
> compared to just issuing simple Query messages.

The driver has no infrastructure for issuing simple Query messages in v3
mode, and anyway we want to batch the BEGIN up with the query that
follows it.

COMMIT/ROLLBACK might be of dubious value but I don't know if it's worth
having a completely separate code path in the driver just for that one case.

-O

Dave Cramer wrote:

> Yeah, the driver needs to be taught to not prepare *everything* in v3 mode

What do you want to avoid preparing, other than BEGIN/COMMIT/ROLLBACK?

-O

On 31-Oct-06, at 6:55 AM, Oliver Jowett wrote:

> Dave Cramer wrote:
>
>> Yeah, the driver needs to be taught to not prepare *everything* in
>> v3 mode
>
> What do you want to avoid preparing, other than BEGIN/COMMIT/ROLLBACK?
>
We also use it for setting the transaction mode
> -O
>
> ---------------------------(end of
> broadcast)---------------------------
> TIP 2: Don't 'kill -9' the postmaster
>

On Wed, 1 Nov 2006, Oliver Jowett wrote:

> Tom Lane wrote:
>> I'm a bit
>> dubious that the prepared-statement machinery actually results in a win
>> compared to just issuing simple Query messages.
>
> The driver has no infrastructure for issuing simple Query messages in v3
> mode, and anyway we want to batch the BEGIN up with the query that follows
> it.
>

We could easily use QueryExecutor.QUERY_ONESHOT for these, but I'm not
sure what the point would be. The 8.2 release can log this correctly so
I'm not sure why bother changing it for the 8.2 driver. Some quick
testing shows that using ONESHOT results in a 4-5% hit using the attached
test case of a BEGIN; SELECT 1; COMMIT loop.

Kris Jurka