Обсуждение: 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@ejurka.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@ejurka.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