Thread: Re: Problem with committing in XA mode
Vlastimil Havranek wrote: > I am facing tx timeout problem when committing certain tx in XA mode > using pure postgre jdbc type 4 driver. The tx is issued/started from > within backend deployed on AS BEA Weblogic 10 MP1. > Ive tried the postgresql-jdbc-8.3-603 jdbc driver, the one bundled with > weblogic and also edb jdbc driver. > In all cases, i see this in db server log: > -- > 2009-01-13 13:37:50 LOG: duration: 0.000 ms parse <unnamed>: > PREPARE TRANSACTION '48801_AQeOE4t3Z6MjBA==_Q3ZoYXZyYW5la2pkYmNEU0xpdmU=' > 2009-01-13 13:37:50 LOG: duration: 0.000 ms bind <unnamed>: PREPARE > TRANSACTION '48801_AQeOE4t3Z6MjBA==_Q3ZoYXZyYW5la2pkYmNEU0xpdmU=' > 2009-01-13 13:37:50 LOG: duration: 0.000 ms execute <unnamed>: > PREPARE TRANSACTION '48801_AQeOE4t3Z6MjBA==_Q3ZoYXZyYW5la2pkYmNEU0xpdmU=' > 2009-01-13 13:37:51 LOG: duration: 0.000 ms parse <unnamed>: COMMIT > PREPARED '48801_AQeOE4t3Z6MjBA==_Q3ZoYXZyYW5la2pkYmNEU0xpdmU=' > 2009-01-13 13:37:51 LOG: duration: 0.000 ms bind <unnamed>: COMMIT > PREPARED '48801_AQeOE4t3Z6MjBA==_Q3ZoYXZyYW5la2pkYmNEU0xpdmU=' > 2009-01-13 13:37:51 ERROR: prepared transaction with identifier > "48801_AQeOE4t3Z6MjBA==_Q3ZoYXZyYW5la2pkYmNEU0xpdmU=" does not exist > 2009-01-13 13:37:51 STATEMENT: COMMIT PREPARED > '48801_AQeOE4t3Z6MjBA==_Q3ZoYXZyYW5la2pkYmNEU0xpdmU=' > 2009-01-13 13:38:51 LOG: duration: 0.000 ms parse <unnamed>: COMMIT > PREPARED '48801_AQeOE4t3Z6MjBA==_Q3ZoYXZyYW5la2pkYmNEU0xpdmU=' > 2009-01-13 13:38:51 LOG: duration: 0.000 ms bind <unnamed>: COMMIT > PREPARED '48801_AQeOE4t3Z6MjBA==_Q3ZoYXZyYW5la2pkYmNEU0xpdmU=' > 2009-01-13 13:38:51 ERROR: prepared transaction with identifier > "48801_AQeOE4t3Z6MjBA==_Q3ZoYXZyYW5la2pkYmNEU0xpdmU=" *does not exist* > 2009-01-13 13:38:51 STATEMENT: COMMIT PREPARED > '48801_AQeOE4t3Z6MjBA==_Q3ZoYXZyYW5la2pkYmNEU0xpdmU=' Hmm, that's odd. A PREPARE TRANSACTION is clearly being run, and followed by a COMMIT PREPARED with the same transaction id, which fails. This raises two questions: 1. Why does it say the transaction doesn't exist, and 2. why doesn't Weblogic report error when the first COMMIT PREPARED fails? Is there anything in the PostgreSQL server log? Could you set log_statement='all' so that we get a trace of the statements from the server side? (that logs *all* queries to the log, so will generate a lot of log if the system is busy) A possible explanation for 2. is that since the transaction was successfully prepared, the RM should be able to commit it eventually. So instead of propagating errors in commit, WebLogic just retries. -- Heikki Linnakangas EnterpriseDB http://www.enterprisedb.com
Vlastimil Havranek wrote: > Thx a lot for prompt answer, here is a slightly more detailed log: > > -- > 2009-01-15 14:59:56 LOG: duration: 0.000 ms parse <unnamed>: PREPARE > TRANSACTION '48801_AF7jVNS8Z6MjBA==_Q3ZoYXZyYW5la2pkYmNEU1BhcmFt' > 2009-01-15 14:59:56 LOG: duration: 0.000 ms bind <unnamed>: PREPARE > TRANSACTION '48801_AF7jVNS8Z6MjBA==_Q3ZoYXZyYW5la2pkYmNEU1BhcmFt' > 2009-01-15 14:59:56 LOG: execute <unnamed>: PREPARE TRANSACTION > '48801_AF7jVNS8Z6MjBA==_Q3ZoYXZyYW5la2pkYmNEU1BhcmFt' > 2009-01-15 14:59:56 LOG: duration: 0.000 ms parse <unnamed>: PREPARE > TRANSACTION '48801_AF7jVNS8Z6MjBA==_Q3ZoYXZyYW5la2pkYmNEU0xpdmU=' > 2009-01-15 14:59:56 LOG: duration: 0.000 ms bind <unnamed>: PREPARE > TRANSACTION '48801_AF7jVNS8Z6MjBA==_Q3ZoYXZyYW5la2pkYmNEU0xpdmU=' > 2009-01-15 14:59:56 LOG: execute <unnamed>: PREPARE TRANSACTION > '48801_AF7jVNS8Z6MjBA==_Q3ZoYXZyYW5la2pkYmNEU0xpdmU=' > 2009-01-15 14:59:56 LOG: duration: 0.000 ms > 2009-01-15 14:59:56 LOG: duration: 0.000 ms > 2009-01-15 14:59:56 LOG: duration: 0.000 ms parse <unnamed>: COMMIT > PREPARED '48801_AF7jVNS8Z6MjBA==_Q3ZoYXZyYW5la2pkYmNEU1BhcmFt' > 2009-01-15 14:59:56 LOG: duration: 0.000 ms bind <unnamed>: COMMIT > PREPARED '48801_AF7jVNS8Z6MjBA==_Q3ZoYXZyYW5la2pkYmNEU1BhcmFt' > 2009-01-15 14:59:56 LOG: execute <unnamed>: COMMIT PREPARED > '48801_AF7jVNS8Z6MjBA==_Q3ZoYXZyYW5la2pkYmNEU1BhcmFt' > 2009-01-15 14:59:56 LOG: duration: 0.000 ms parse <unnamed>: COMMIT > PREPARED '48801_AF7jVNS8Z6MjBA==_Q3ZoYXZyYW5la2pkYmNEU0xpdmU=' > 2009-01-15 14:59:56 LOG: duration: 0.000 ms bind <unnamed>: COMMIT > PREPARED '48801_AF7jVNS8Z6MjBA==_Q3ZoYXZyYW5la2pkYmNEU0xpdmU=' > 2009-01-15 14:59:56 LOG: execute <unnamed>: COMMIT PREPARED > '48801_AF7jVNS8Z6MjBA==_Q3ZoYXZyYW5la2pkYmNEU0xpdmU=' > 2009-01-15 14:59:56 ERROR: prepared transaction with identifier > "48801_AF7jVNS8Z6MjBA==_Q3ZoYXZyYW5la2pkYmNEU0xpdmU=" does not exist > 2009-01-15 14:59:56 STATEMENT: COMMIT PREPARED > '48801_AF7jVNS8Z6MjBA==_Q3ZoYXZyYW5la2pkYmNEU0xpdmU=' Hmm, it looks like the server is getting a COMMIT, followed by two PREPARE TRANSACTION commands in a row: BEGIN ... COMMIT PREPARE TRANSACTION '48801_AF7jVNS8Z6MjBA==_Q3ZoYXZyYW5la2pkYmNEU0xpdmU=' PREPARE TRANSACTION '48801_AF7jVNS8Z6MjBA==_Q3ZoYXZyYW5la2pkYmNEU0xpdmU=' I presume there's multiple backends issuing these commands concurrently, otherwise both PREPARE TRANSACTION commands should fail with "there is no transaction in progress" warning. One theory is that the 2nd PREPARE TRANSACTION *is* failing, and gives a WARNING, but we're not seeing that in any of the logs. I don't know why that might happen, but I notice that we don't have a check for that case in the JDBC driver's prepare() method, so the application server would think that the transaction prepare succeeded. Please make sure you have log_min_messages set to "warning" (or lower, e.g "notice") and try again. Also, %c would be very helpful in log_line_prefix, so that we could tell apart actions of different backends in the log. -- Heikki Linnakangas EnterpriseDB http://www.enterprisedb.com
Thx a lot for prompt answer, here is a slightly more detailed log: -- 2009-01-15 14:59:55 LOG: duration: 0.000 ms bind S_1: BEGIN 2009-01-15 14:59:55 LOG: execute S_1: BEGIN 2009-01-15 14:59:55 LOG: duration: 0.000 ms 2009-01-15 14:59:55 LOG: duration: 0.000 ms parse <unnamed>: SELECT t0.X, t0.Y FROM TAB_0 t0 WHERE (t0.X = $1 AND t0.Y = $2) 2009-01-15 14:59:55 LOG: duration: 0.000 ms bind <unnamed>: SELECT t0.X, t0.Y FROM TAB_0 t0 WHERE (t0.X = $1 AND t0.Y = $2) 2009-01-15 14:59:55 DETAIL: parameters: $1 = 'abcd', $2 = 'EFGH' 2009-01-15 14:59:55 LOG: execute <unnamed>: SELECT t0.X, t0.Y FROM TAB_0 t0 WHERE (t0.X = $1 AND t0.Y = $2) 2009-01-15 14:59:55 DETAIL: parameters: $1 = 'abcd', $2 = 'EFGH' 2009-01-15 14:59:55 LOG: duration: 0.000 ms 2009-01-15 14:59:55 LOG: duration: 0.000 ms bind S_2: COMMIT 2009-01-15 14:59:55 LOG: execute S_2: COMMIT 2009-01-15 14:59:55 LOG: duration: 0.000 ms 2009-01-15 14:59:55 LOG: duration: 0.000 ms parse <unnamed>: SHOW TRANSACTION ISOLATION LEVEL 2009-01-15 14:59:55 LOG: duration: 0.000 ms bind <unnamed>: SHOW TRANSACTION ISOLATION LEVEL 2009-01-15 14:59:55 LOG: execute <unnamed>: SHOW TRANSACTION ISOLATION LEVEL 2009-01-15 14:59:55 LOG: duration: 0.000 ms 2009-01-15 14:59:55 LOG: duration: 0.000 ms bind S_1: BEGIN 2009-01-15 14:59:55 LOG: execute S_1: BEGIN 2009-01-15 14:59:55 LOG: duration: 0.000 ms 2009-01-15 14:59:55 LOG: duration: 0.000 ms parse <unnamed>: SELECT t0.* FROM t0 WHERE t0.X=$1 AND t0.Y=$2 FOR UPDATE 2009-01-15 14:59:55 LOG: duration: 0.000 ms bind <unnamed>: SELECT t0.* FROM t0 WHERE t0.X=$1 AND t0.Y=$2 FOR UPDATE 2009-01-15 14:59:55 DETAIL: parameters: $1 = 'abcd', $2 = 'EFGH' 2009-01-15 14:59:55 LOG: execute <unnamed>: SELECT t0.* FROM t0 WHERE t0.X=$1 AND t0.Y=$2 FOR UPDATE 2009-01-15 14:59:55 DETAIL: parameters: $1 = 'abcd', $2 = 'EFGH' 2009-01-15 14:59:55 LOG: duration: 0.000 ms 2009-01-15 14:59:55 LOG: duration: 0.000 ms bind S_1: BEGIN 2009-01-15 14:59:55 LOG: execute S_1: BEGIN 2009-01-15 14:59:55 LOG: duration: 0.000 ms 2009-01-15 14:59:55 LOG: duration: 0.000 ms parse <unnamed>: select count(*) from t0 2009-01-15 14:59:55 LOG: duration: 0.000 ms bind <unnamed>: select count(*) from t0 2009-01-15 14:59:55 LOG: execute <unnamed>: select count(*) from t0 2009-01-15 14:59:55 LOG: duration: 0.000 ms 2009-01-15 14:59:55 LOG: duration: 0.000 ms bind S_2: COMMIT 2009-01-15 14:59:55 LOG: execute S_2: COMMIT 2009-01-15 14:59:55 LOG: duration: 0.000 ms 2009-01-15 14:59:55 LOG: duration: 0.000 ms bind S_1: BEGIN 2009-01-15 14:59:55 LOG: execute S_1: BEGIN 2009-01-15 14:59:55 LOG: duration: 0.000 ms 2009-01-15 14:59:55 LOG: duration: 14.999 ms parse <unnamed>: SELECT t0.XY, t0.Y FROM TAB_0 t0 WHERE (t0.XY = $1 AND t0.Y = $2) 2009-01-15 14:59:55 LOG: duration: 31.000 ms bind <unnamed>: SELECT t0.XY, t0.Y FROM TAB_0 t0 WHERE (t0.XY = $1 AND t0.Y = $2) 2009-01-15 14:59:55 DETAIL: parameters: $1 = 'abcd', $2 = 'EFGH' 2009-01-15 14:59:55 LOG: execute <unnamed>: SELECT t0.XY, t0.Y FROM TAB_0 t0 WHERE (t0.XY = $1 AND t0.Y = $2) 2009-01-15 14:59:55 DETAIL: parameters: $1 = 'abcd', $2 = 'EFGH' 2009-01-15 14:59:55 LOG: duration: 32.000 ms 2009-01-15 14:59:55 LOG: duration: 0.000 ms bind S_2: COMMIT 2009-01-15 14:59:55 LOG: execute S_2: COMMIT 2009-01-15 14:59:55 LOG: duration: 0.000 ms 2009-01-15 14:59:56 LOG: duration: 0.000 ms parse <unnamed>: PREPARE TRANSACTION '48801_AF7jVNS8Z6MjBA==_Q3ZoYXZyYW5la2pkYmNEU1BhcmFt' 2009-01-15 14:59:56 LOG: duration: 0.000 ms bind <unnamed>: PREPARE TRANSACTION '48801_AF7jVNS8Z6MjBA==_Q3ZoYXZyYW5la2pkYmNEU1BhcmFt' 2009-01-15 14:59:56 LOG: execute <unnamed>: PREPARE TRANSACTION '48801_AF7jVNS8Z6MjBA==_Q3ZoYXZyYW5la2pkYmNEU1BhcmFt' 2009-01-15 14:59:56 LOG: duration: 0.000 ms parse <unnamed>: PREPARE TRANSACTION '48801_AF7jVNS8Z6MjBA==_Q3ZoYXZyYW5la2pkYmNEU0xpdmU=' 2009-01-15 14:59:56 LOG: duration: 0.000 ms bind <unnamed>: PREPARE TRANSACTION '48801_AF7jVNS8Z6MjBA==_Q3ZoYXZyYW5la2pkYmNEU0xpdmU=' 2009-01-15 14:59:56 LOG: execute <unnamed>: PREPARE TRANSACTION '48801_AF7jVNS8Z6MjBA==_Q3ZoYXZyYW5la2pkYmNEU0xpdmU=' 2009-01-15 14:59:56 LOG: duration: 0.000 ms 2009-01-15 14:59:56 LOG: duration: 0.000 ms 2009-01-15 14:59:56 LOG: duration: 0.000 ms parse <unnamed>: COMMIT PREPARED '48801_AF7jVNS8Z6MjBA==_Q3ZoYXZyYW5la2pkYmNEU1BhcmFt' 2009-01-15 14:59:56 LOG: duration: 0.000 ms bind <unnamed>: COMMIT PREPARED '48801_AF7jVNS8Z6MjBA==_Q3ZoYXZyYW5la2pkYmNEU1BhcmFt' 2009-01-15 14:59:56 LOG: execute <unnamed>: COMMIT PREPARED '48801_AF7jVNS8Z6MjBA==_Q3ZoYXZyYW5la2pkYmNEU1BhcmFt' 2009-01-15 14:59:56 LOG: duration: 0.000 ms parse <unnamed>: COMMIT PREPARED '48801_AF7jVNS8Z6MjBA==_Q3ZoYXZyYW5la2pkYmNEU0xpdmU=' 2009-01-15 14:59:56 LOG: duration: 0.000 ms bind <unnamed>: COMMIT PREPARED '48801_AF7jVNS8Z6MjBA==_Q3ZoYXZyYW5la2pkYmNEU0xpdmU=' 2009-01-15 14:59:56 LOG: execute <unnamed>: COMMIT PREPARED '48801_AF7jVNS8Z6MjBA==_Q3ZoYXZyYW5la2pkYmNEU0xpdmU=' 2009-01-15 14:59:56 ERROR: prepared transaction with identifier "48801_AF7jVNS8Z6MjBA==_Q3ZoYXZyYW5la2pkYmNEU0xpdmU=" does not exist 2009-01-15 14:59:56 STATEMENT: COMMIT PREPARED '48801_AF7jVNS8Z6MjBA==_Q3ZoYXZyYW5la2pkYmNEU0xpdmU=' 2009-01-15 14:59:56 LOG: duration: 0.000 ms 2009-01-15 14:59:56 LOG: duration: 0.000 ms parse <unnamed>: SHOW TRANSACTION ISOLATION LEVEL 2009-01-15 14:59:56 LOG: duration: 0.000 ms bind <unnamed>: SHOW TRANSACTION ISOLATION LEVEL 2009-01-15 14:59:56 LOG: execute <unnamed>: SHOW TRANSACTION ISOLATION LEVEL 2009-01-15 14:59:56 LOG: duration: 0.000 ms 2009-01-15 14:59:56 LOG: duration: 0.000 ms parse <unnamed>: SHOW TRANSACTION ISOLATION LEVEL 2009-01-15 14:59:56 LOG: duration: 0.000 ms bind <unnamed>: SHOW TRANSACTION ISOLATION LEVEL 2009-01-15 14:59:56 LOG: execute <unnamed>: SHOW TRANSACTION ISOLATION LEVEL 2009-01-15 14:59:56 LOG: duration: 0.000 ms -- VH. Heikki Linnakangas wrote: > Vlastimil Havranek wrote: >> I am facing tx timeout problem when committing certain tx in XA mode >> using pure postgre jdbc type 4 driver. The tx is issued/started from >> within backend deployed on AS BEA Weblogic 10 MP1. >> Ive tried the postgresql-jdbc-8.3-603 jdbc driver, the one bundled >> with weblogic and also edb jdbc driver. >> In all cases, i see this in db server log: >> -- >> 2009-01-13 13:37:50 LOG: duration: 0.000 ms parse <unnamed>: >> PREPARE TRANSACTION >> '48801_AQeOE4t3Z6MjBA==_Q3ZoYXZyYW5la2pkYmNEU0xpdmU=' >> 2009-01-13 13:37:50 LOG: duration: 0.000 ms bind <unnamed>: >> PREPARE TRANSACTION >> '48801_AQeOE4t3Z6MjBA==_Q3ZoYXZyYW5la2pkYmNEU0xpdmU=' >> 2009-01-13 13:37:50 LOG: duration: 0.000 ms execute <unnamed>: >> PREPARE TRANSACTION >> '48801_AQeOE4t3Z6MjBA==_Q3ZoYXZyYW5la2pkYmNEU0xpdmU=' >> 2009-01-13 13:37:51 LOG: duration: 0.000 ms parse <unnamed>: >> COMMIT PREPARED '48801_AQeOE4t3Z6MjBA==_Q3ZoYXZyYW5la2pkYmNEU0xpdmU=' >> 2009-01-13 13:37:51 LOG: duration: 0.000 ms bind <unnamed>: >> COMMIT PREPARED '48801_AQeOE4t3Z6MjBA==_Q3ZoYXZyYW5la2pkYmNEU0xpdmU=' >> 2009-01-13 13:37:51 ERROR: prepared transaction with identifier >> "48801_AQeOE4t3Z6MjBA==_Q3ZoYXZyYW5la2pkYmNEU0xpdmU=" does not exist >> 2009-01-13 13:37:51 STATEMENT: COMMIT PREPARED >> '48801_AQeOE4t3Z6MjBA==_Q3ZoYXZyYW5la2pkYmNEU0xpdmU=' >> 2009-01-13 13:38:51 LOG: duration: 0.000 ms parse <unnamed>: >> COMMIT PREPARED '48801_AQeOE4t3Z6MjBA==_Q3ZoYXZyYW5la2pkYmNEU0xpdmU=' >> 2009-01-13 13:38:51 LOG: duration: 0.000 ms bind <unnamed>: >> COMMIT PREPARED '48801_AQeOE4t3Z6MjBA==_Q3ZoYXZyYW5la2pkYmNEU0xpdmU=' >> 2009-01-13 13:38:51 ERROR: prepared transaction with identifier >> "48801_AQeOE4t3Z6MjBA==_Q3ZoYXZyYW5la2pkYmNEU0xpdmU=" *does not exist* >> 2009-01-13 13:38:51 STATEMENT: COMMIT PREPARED >> '48801_AQeOE4t3Z6MjBA==_Q3ZoYXZyYW5la2pkYmNEU0xpdmU=' > > Hmm, that's odd. A PREPARE TRANSACTION is clearly being run, and > followed by a COMMIT PREPARED with the same transaction id, which > fails. This raises two questions: > > 1. Why does it say the transaction doesn't exist, and > 2. why doesn't Weblogic report error when the first COMMIT PREPARED > fails? > > Is there anything in the PostgreSQL server log? Could you set > log_statement='all' so that we get a trace of the statements from the > server side? (that logs *all* queries to the log, so will generate a > lot of log if the system is busy) > > A possible explanation for 2. is that since the transaction was > successfully prepared, the RM should be able to commit it eventually. > So instead of propagating errors in commit, WebLogic just retries. > -- ------------------------------------------------------------- Vlastimil Havránek Software Developer xitee k.s. || www.xitee.com || vlastimil.havranek@xitee.com Phone: office +420 234262342, mobile +420 775366990 -------------------------------------------------------------
Here is the log with the settings zou have suggested: -- database_A SID:496f4f4d.454 16:12:09.578 LOG: duration: 0.000 ms bind S_1: BEGIN database_A SID:496f4f4d.454 16:12:09.578 LOG: execute S_1: BEGIN database_A SID:496f4f4d.454 16:12:09.578 LOG: duration: 0.000 ms database_A SID:496f4f4d.454 16:12:09.578 LOG: duration: 0.000 ms parse <unnamed>: select count(*) from t0 database_A SID:496f4f4d.454 16:12:09.578 LOG: duration: 0.000 ms bind <unnamed>: select count(*) from t0 database_A SID:496f4f4d.454 16:12:09.578 LOG: execute <unnamed>: select count(*) from t0 database_A SID:496f4f4d.454 16:12:09.578 LOG: duration: 0.000 ms database_A SID:496f4f4d.454 16:12:09.578 LOG: duration: 0.000 ms bind S_2: COMMIT database_A SID:496f4f4d.454 16:12:09.578 LOG: execute S_2: COMMIT database_A SID:496f4f4d.454 16:12:09.578 LOG: duration: 0.000 ms database_A SID:496f4f4d.454 16:12:09.593 LOG: duration: 0.000 ms bind S_1: BEGIN database_A SID:496f4f4d.454 16:12:09.593 LOG: execute S_1: BEGIN database_A SID:496f4f4d.454 16:12:09.593 LOG: duration: 0.000 ms database_A SID:496f4f4d.454 16:12:09.593 LOG: duration: 0.000 ms parse <unnamed>: SELECT SOME_SEQ.nextval FROM dual database_A SID:496f4f4d.454 16:12:09.593 LOG: duration: 0.000 ms bind <unnamed>: SELECT SOME_SEQ.nextval FROM dual database_A SID:496f4f4d.454 16:12:09.593 LOG: execute <unnamed>: SELECT SOME_SEQ.nextval FROM dual database_A SID:496f4f4d.454 16:12:09.593 LOG: duration: 0.000 ms database_A SID:496f4f4d.454 16:12:09.609 LOG: duration: 0.000 ms bind S_2: COMMIT database_A SID:496f4f4d.454 16:12:09.609 LOG: execute S_2: COMMIT database_A SID:496f4f4d.454 16:12:09.609 LOG: duration: 0.000 ms database_A SID:496f4f4d.454 16:12:09.609 LOG: duration: 0.000 ms parse <unnamed>: SHOW TRANSACTION ISOLATION LEVEL database_A SID:496f4f4d.454 16:12:09.609 LOG: duration: 0.000 ms bind <unnamed>: SHOW TRANSACTION ISOLATION LEVEL database_A SID:496f4f4d.454 16:12:09.609 LOG: execute <unnamed>: SHOW TRANSACTION ISOLATION LEVEL database_A SID:496f4f4d.454 16:12:09.609 LOG: duration: 0.000 ms database_A SID:496f4f4d.454 16:12:09.625 LOG: duration: 0.000 ms bind S_1: BEGIN database_A SID:496f4f4d.454 16:12:09.625 LOG: execute S_1: BEGIN database_A SID:496f4f4d.454 16:12:09.625 LOG: duration: 0.000 ms database_A SID:496f4f4d.454 16:12:09.625 LOG: duration: 0.000 ms parse <unnamed>: SOME SELECT database_A SID:496f4f4d.454 16:12:09.625 LOG: duration: 0.000 ms bind <unnamed>: SOME SELECT database_A SID:496f4f4d.454 16:12:09.625 LOG: execute <unnamed>: SOME SELECT database_A SID:496f4f4d.454 16:12:09.625 LOG: duration: 0.000 ms database_A SID:496f4f4d.454 16:12:09.656 LOG: duration: 0.000 ms parse <unnamed>: SOME SELECT database_A SID:496f4f4d.454 16:12:09.656 LOG: duration: 0.000 ms bind <unnamed>: SOME SELECT database_A SID:496f4f4d.454 16:12:09.656 DETAIL: parameters: $1 = '1234' database_A SID:496f4f4d.454 16:12:09.656 LOG: execute <unnamed>: SOME SELECT database_A SID:496f4f4d.454 16:12:09.656 DETAIL: parameters: $1 = '1234' database_A SID:496f4f4d.454 16:12:09.656 LOG: duration: 0.000 ms database_A SID:496f4f4d.454 16:12:09.671 LOG: duration: 0.000 ms bind S_2: COMMIT database_A SID:496f4f4d.454 16:12:09.671 LOG: execute S_2: COMMIT database_A SID:496f4f4d.454 16:12:09.671 LOG: duration: 0.000 ms database_A SID:496f4ed6.200 16:12:09.671 LOG: duration: 0.000 ms bind S_1: BEGIN database_A SID:496f4ed6.200 16:12:09.671 LOG: execute S_1: BEGIN database_A SID:496f4ed6.200 16:12:09.671 LOG: duration: 0.000 ms database_A SID:496f4ed6.200 16:12:09.671 LOG: duration: 0.000 ms parse <unnamed>: select count(*) from t0 database_A SID:496f4ed6.200 16:12:09.671 LOG: duration: 0.000 ms bind <unnamed>: select count(*) from t0 database_A SID:496f4ed6.200 16:12:09.671 LOG: execute <unnamed>: select count(*) from t0 database_A SID:496f4ed6.200 16:12:09.671 LOG: duration: 0.000 ms database_A SID:496f4ed6.200 16:12:09.671 LOG: duration: 0.000 ms bind S_2: COMMIT database_A SID:496f4ed6.200 16:12:09.671 LOG: execute S_2: COMMIT database_A SID:496f4ed6.200 16:12:09.671 LOG: duration: 0.000 ms database_A SID:496f4ed6.200 16:12:09.687 LOG: duration: 0.000 ms bind S_1: BEGIN database_A SID:496f4ed6.200 16:12:09.687 LOG: execute S_1: BEGIN database_A SID:496f4ed6.200 16:12:09.687 LOG: duration: 0.000 ms database_A SID:496f4ed6.200 16:12:09.687 LOG: duration: 0.000 ms parse <unnamed>: SOME UPDATE database_A SID:496f4ed6.200 16:12:09.687 LOG: duration: 0.000 ms bind <unnamed>: SOME UPDATE database_A SID:496f4ed6.200 16:12:09.687 DETAIL: parameters: $1 = 'a', $2 = '1234', $3 = '2008-01-01 00:00:00' database_A SID:496f4ed6.200 16:12:09.687 LOG: execute <unnamed>: SOME UPDATE database_A SID:496f4ed6.200 16:12:09.687 DETAIL: parameters: $1 = 'A', $2 = '1234', $3 = '2008-01-01 00:00:00' database_A SID:496f4ed6.200 16:12:09.687 LOG: duration: 0.000 ms database_A SID:496f4ed6.200 16:12:09.687 LOG: duration: 0.000 ms bind S_2: COMMIT database_A SID:496f4ed6.200 16:12:09.687 LOG: execute S_2: COMMIT database_A SID:496f4ed6.200 16:12:09.687 LOG: duration: 0.000 ms database_A SID:496f4ed6.200 16:12:09.687 LOG: duration: 0.000 ms parse <unnamed>: SHOW TRANSACTION ISOLATION LEVEL database_A SID:496f4ed6.200 16:12:09.687 LOG: duration: 0.000 ms bind <unnamed>: SHOW TRANSACTION ISOLATION LEVEL database_A SID:496f4ed6.200 16:12:09.687 LOG: execute <unnamed>: SHOW TRANSACTION ISOLATION LEVEL database_A SID:496f4ed6.200 16:12:09.687 LOG: duration: 0.000 ms database_A SID:496f4f4d.454 16:12:09.703 LOG: duration: 0.000 ms parse <unnamed>: SHOW TRANSACTION ISOLATION LEVEL database_A SID:496f4f4d.454 16:12:09.703 LOG: duration: 0.000 ms bind <unnamed>: SHOW TRANSACTION ISOLATION LEVEL database_A SID:496f4f4d.454 16:12:09.703 LOG: execute <unnamed>: SHOW TRANSACTION ISOLATION LEVEL database_A SID:496f4f4d.454 16:12:09.703 LOG: duration: 0.000 ms database_A SID:496f4f4d.454 16:12:10.062 LOG: duration: 0.000 ms bind S_1: BEGIN database_A SID:496f4f4d.454 16:12:10.062 LOG: execute S_1: BEGIN database_A SID:496f4f4d.454 16:12:10.062 LOG: duration: 0.000 ms database_A SID:496f4f4d.454 16:12:10.062 LOG: duration: 0.000 ms parse <unnamed>: SOME SELECT database_A SID:496f4f4d.454 16:12:10.062 LOG: duration: 0.000 ms bind <unnamed>: SOME SELECT database_A SID:496f4f4d.454 16:12:10.062 LOG: execute <unnamed>: SOME SELECT database_A SID:496f4f4d.454 16:12:10.062 LOG: duration: 0.000 ms database_A SID:496f4f4d.454 16:12:10.171 LOG: duration: 0.000 ms bind S_2: COMMIT database_A SID:496f4f4d.454 16:12:10.171 LOG: execute S_2: COMMIT database_A SID:496f4f4d.454 16:12:10.171 LOG: duration: 0.000 ms database_A SID:496f4f4d.454 16:12:10.171 LOG: duration: 0.000 ms parse <unnamed>: SHOW TRANSACTION ISOLATION LEVEL database_A SID:496f4f4d.454 16:12:10.171 LOG: duration: 0.000 ms bind <unnamed>: SHOW TRANSACTION ISOLATION LEVEL database_A SID:496f4f4d.454 16:12:10.171 LOG: execute <unnamed>: SHOW TRANSACTION ISOLATION LEVEL database_A SID:496f4f4d.454 16:12:10.171 LOG: duration: 0.000 ms database_A SID:496f4f4d.454 16:12:27.531 LOG: duration: 0.000 ms bind S_1: BEGIN database_A SID:496f4f4d.454 16:12:27.531 LOG: execute S_1: BEGIN database_A SID:496f4f4d.454 16:12:27.531 LOG: duration: 0.000 ms database_A SID:496f4f4d.454 16:12:27.531 LOG: duration: 0.000 ms parse <unnamed>: select count(*) from t0 database_A SID:496f4f4d.454 16:12:27.531 LOG: duration: 0.000 ms bind <unnamed>: select count(*) from t0 database_A SID:496f4f4d.454 16:12:27.531 LOG: execute <unnamed>: select count(*) from t0 database_A SID:496f4f4d.454 16:12:27.531 LOG: duration: 0.000 ms database_A SID:496f4f4d.454 16:12:27.531 LOG: duration: 0.000 ms bind S_2: COMMIT database_A SID:496f4f4d.454 16:12:27.531 LOG: execute S_2: COMMIT database_A SID:496f4f4d.454 16:12:27.531 LOG: duration: 0.000 ms database_A SID:496f4f4d.454 16:12:27.546 LOG: duration: 0.000 ms bind S_1: BEGIN database_A SID:496f4f4d.454 16:12:27.546 LOG: execute S_1: BEGIN database_A SID:496f4f4d.454 16:12:27.546 LOG: duration: 0.000 ms database_A SID:496f4f4d.454 16:12:27.546 LOG: duration: 0.000 ms parse <unnamed>: SOME SELECT database_A SID:496f4f4d.454 16:12:27.546 LOG: duration: 0.000 ms bind <unnamed>: SOME SELECT database_A SID:496f4f4d.454 16:12:27.546 DETAIL: parameters: $1 = 'abcd', $2 = 'EFGH' database_A SID:496f4f4d.454 16:12:27.546 LOG: execute <unnamed>: SOME SELECT database_A SID:496f4f4d.454 16:12:27.546 DETAIL: parameters: $1 = 'abcd', $2 = 'EFGH' database_A SID:496f4f4d.454 16:12:27.546 LOG: duration: 0.000 ms database_A SID:496f4f4d.454 16:12:27.578 LOG: duration: 0.000 ms bind S_2: COMMIT database_A SID:496f4f4d.454 16:12:27.578 LOG: execute S_2: COMMIT database_A SID:496f4f4d.454 16:12:27.578 LOG: duration: 0.000 ms database_A SID:496f4f4d.454 16:12:27.578 LOG: duration: 0.000 ms parse <unnamed>: SHOW TRANSACTION ISOLATION LEVEL database_A SID:496f4f4d.454 16:12:27.578 LOG: duration: 0.000 ms bind <unnamed>: SHOW TRANSACTION ISOLATION LEVEL database_A SID:496f4f4d.454 16:12:27.578 LOG: execute <unnamed>: SHOW TRANSACTION ISOLATION LEVEL database_A SID:496f4f4d.454 16:12:27.578 LOG: duration: 0.000 ms database_A SID:496f4f4d.454 16:12:27.625 LOG: duration: 0.000 ms bind S_1: BEGIN database_A SID:496f4f4d.454 16:12:27.625 LOG: execute S_1: BEGIN database_A SID:496f4f4d.454 16:12:27.625 LOG: duration: 0.000 ms database_A SID:496f4f4d.454 16:12:27.625 LOG: duration: 0.000 ms parse <unnamed>: SOME SELECT FOR UPDATE database_A SID:496f4f4d.454 16:12:27.625 LOG: duration: 0.000 ms bind <unnamed>: SOME SELECT FOR UPDATE database_A SID:496f4f4d.454 16:12:27.625 DETAIL: parameters: $1 = 'abcd', $2 = 'EFGH' database_A SID:496f4f4d.454 16:12:27.625 LOG: execute <unnamed>: SOME SELECT FOR UPDATE database_A SID:496f4f4d.454 16:12:27.625 DETAIL: parameters: $1 = 'abcd', $2 = 'EFGH' database_A SID:496f4f4d.454 16:12:27.625 LOG: duration: 0.000 ms database_B SID:496f4ed7.e04 16:12:27.859 LOG: duration: 0.000 ms bind S_1: BEGIN database_B SID:496f4ed7.e04 16:12:27.859 LOG: execute S_1: BEGIN database_B SID:496f4ed7.e04 16:12:27.859 LOG: duration: 0.000 ms database_B SID:496f4ed7.e04 16:12:27.859 LOG: duration: 0.000 ms parse <unnamed>: select count(*) from t0 database_B SID:496f4ed7.e04 16:12:27.859 LOG: duration: 0.000 ms bind <unnamed>: select count(*) from t0 database_B SID:496f4ed7.e04 16:12:27.859 LOG: execute <unnamed>: select count(*) from t0 database_B SID:496f4ed7.e04 16:12:27.875 LOG: duration: 15.999 ms database_B SID:496f4ed7.e04 16:12:27.875 LOG: duration: 0.000 ms bind S_2: COMMIT database_B SID:496f4ed7.e04 16:12:27.875 LOG: execute S_2: COMMIT database_B SID:496f4ed7.e04 16:12:27.875 LOG: duration: 0.000 ms database_B SID:496f4ed7.e04 16:12:27.875 LOG: duration: 0.000 ms bind S_1: BEGIN database_B SID:496f4ed7.e04 16:12:27.875 LOG: execute S_1: BEGIN database_B SID:496f4ed7.e04 16:12:27.875 LOG: duration: 0.000 ms database_B SID:496f4ed7.e04 16:12:27.875 LOG: duration: 0.000 ms parse <unnamed>: SOME SELECT database_B SID:496f4ed7.e04 16:12:27.890 LOG: duration: 14.999 ms bind <unnamed>: SOME SELECT database_B SID:496f4ed7.e04 16:12:27.890 DETAIL: parameters: $1 = 'abcd', $2 = 'EFGH' database_B SID:496f4ed7.e04 16:12:27.890 LOG: execute <unnamed>: SOME SELECT FOR UPDATE database_B SID:496f4ed7.e04 16:12:27.890 DETAIL: parameters: $1 = 'abcd', $2 = 'EFGH' database_B SID:496f4ed7.e04 16:12:27.890 LOG: duration: 0.000 ms database_A SID:496f4f4d.454 16:12:27.937 LOG: duration: 0.000 ms bind S_2: COMMIT database_A SID:496f4f4d.454 16:12:27.937 LOG: execute S_2: COMMIT database_A SID:496f4f4d.454 16:12:27.937 LOG: duration: 0.000 ms database_B SID:496f4ed7.e04 16:12:27.953 LOG: duration: 0.000 ms parse <unnamed>: PREPARE TRANSACTION '48801_AOiMyUwnZ6MjBA==_Q3ZoYXZyYW5la2pkYmNEU1BhcmFt' database_A SID:496f4f4d.454 16:12:27.953 LOG: duration: 0.000 ms parse <unnamed>: PREPARE TRANSACTION '48801_AOiMyUwnZ6MjBA==_Q3ZoYXZyYW5la2pkYmNEU0xpdmU=' database_A SID:496f4f4d.454 16:12:27.953 LOG: duration: 0.000 ms bind <unnamed>: PREPARE TRANSACTION '48801_AOiMyUwnZ6MjBA==_Q3ZoYXZyYW5la2pkYmNEU0xpdmU=' database_B SID:496f4ed7.e04 16:12:27.953 LOG: duration: 0.000 ms bind <unnamed>: PREPARE TRANSACTION '48801_AOiMyUwnZ6MjBA==_Q3ZoYXZyYW5la2pkYmNEU1BhcmFt' database_A SID:496f4f4d.454 16:12:27.953 LOG: execute <unnamed>: PREPARE TRANSACTION '48801_AOiMyUwnZ6MjBA==_Q3ZoYXZyYW5la2pkYmNEU0xpdmU=' database_B SID:496f4ed7.e04 16:12:27.953 LOG: execute <unnamed>: PREPARE TRANSACTION '48801_AOiMyUwnZ6MjBA==_Q3ZoYXZyYW5la2pkYmNEU1BhcmFt' database_A SID:496f4f4d.454 16:12:27.953 LOG: duration: 0.000 ms database_B SID:496f4ed7.e04 16:12:27.968 LOG: duration: 14.999 ms database_A SID:496f4f4d.454 16:12:28.000 LOG: duration: 0.000 ms parse <unnamed>: COMMIT PREPARED '48801_AOiMyUwnZ6MjBA==_Q3ZoYXZyYW5la2pkYmNEU0xpdmU=' database_A SID:496f4f4d.454 16:12:28.000 LOG: duration: 0.000 ms bind <unnamed>: COMMIT PREPARED '48801_AOiMyUwnZ6MjBA==_Q3ZoYXZyYW5la2pkYmNEU0xpdmU=' database_B SID:496f4ed7.e04 16:12:28.000 LOG: duration: 0.000 ms parse <unnamed>: COMMIT PREPARED '48801_AOiMyUwnZ6MjBA==_Q3ZoYXZyYW5la2pkYmNEU1BhcmFt' database_A SID:496f4f4d.454 16:12:28.000 LOG: execute <unnamed>: COMMIT PREPARED '48801_AOiMyUwnZ6MjBA==_Q3ZoYXZyYW5la2pkYmNEU0xpdmU=' database_B SID:496f4ed7.e04 16:12:28.000 LOG: duration: 0.000 ms bind <unnamed>: COMMIT PREPARED '48801_AOiMyUwnZ6MjBA==_Q3ZoYXZyYW5la2pkYmNEU1BhcmFt' database_A SID:496f4f4d.454 16:12:28.000 ERROR: prepared transaction with identifier "48801_AOiMyUwnZ6MjBA==_Q3ZoYXZyYW5la2pkYmNEU0xpdmU=" does not exist database_A SID:496f4f4d.454 16:12:28.000 STATEMENT: COMMIT PREPARED '48801_AOiMyUwnZ6MjBA==_Q3ZoYXZyYW5la2pkYmNEU0xpdmU=' database_B SID:496f4ed7.e04 16:12:28.000 LOG: execute <unnamed>: COMMIT PREPARED '48801_AOiMyUwnZ6MjBA==_Q3ZoYXZyYW5la2pkYmNEU1BhcmFt' database_A SID:496f4f4d.454 16:12:28.015 LOG: duration: 0.000 ms parse <unnamed>: SHOW TRANSACTION ISOLATION LEVEL database_A SID:496f4f4d.454 16:12:28.015 LOG: duration: 0.000 ms bind <unnamed>: SHOW TRANSACTION ISOLATION LEVEL database_A SID:496f4f4d.454 16:12:28.015 LOG: execute <unnamed>: SHOW TRANSACTION ISOLATION LEVEL database_A SID:496f4f4d.454 16:12:28.015 LOG: duration: 0.000 ms database_B SID:496f4ed7.e04 16:12:28.015 LOG: duration: 14.999 ms database_B SID:496f4ed7.e04 16:12:28.015 LOG: duration: 0.000 ms parse <unnamed>: SHOW TRANSACTION ISOLATION LEVEL database_B SID:496f4ed7.e04 16:12:28.015 LOG: duration: 0.000 ms bind <unnamed>: SHOW TRANSACTION ISOLATION LEVEL database_B SID:496f4ed7.e04 16:12:28.015 LOG: execute <unnamed>: SHOW TRANSACTION ISOLATION LEVEL database_B SID:496f4ed7.e04 16:12:28.015 LOG: duration: 0.000 ms database_A SID:496f4f4d.454 16:12:29.421 LOG: duration: 0.000 ms parse <unnamed>: COMMIT PREPARED '48801_AF7jVNS8Z6MjBA==_Q3ZoYXZyYW5la2pkYmNEU0xpdmU=' database_B SID:496f4ed7.e04 16:12:29.421 LOG: duration: 0.000 ms parse <unnamed>: COMMIT PREPARED '48801_AF7jVNS8Z6MjBA==_Q3ZoYXZyYW5la2pkYmNEU1BhcmFt' database_A SID:496f4f4d.454 16:12:29.421 LOG: duration: 0.000 ms bind <unnamed>: COMMIT PREPARED '48801_AF7jVNS8Z6MjBA==_Q3ZoYXZyYW5la2pkYmNEU0xpdmU=' database_B SID:496f4ed7.e04 16:12:29.421 LOG: duration: 0.000 ms bind <unnamed>: COMMIT PREPARED '48801_AF7jVNS8Z6MjBA==_Q3ZoYXZyYW5la2pkYmNEU1BhcmFt' database_A SID:496f4f4d.454 16:12:29.421 LOG: execute <unnamed>: COMMIT PREPARED '48801_AF7jVNS8Z6MjBA==_Q3ZoYXZyYW5la2pkYmNEU0xpdmU=' database_B SID:496f4ed7.e04 16:12:29.421 LOG: execute <unnamed>: COMMIT PREPARED '48801_AF7jVNS8Z6MjBA==_Q3ZoYXZyYW5la2pkYmNEU1BhcmFt' database_A SID:496f4f4d.454 16:12:29.421 ERROR: prepared transaction with identifier "48801_AF7jVNS8Z6MjBA==_Q3ZoYXZyYW5la2pkYmNEU0xpdmU=" does not exist database_A SID:496f4f4d.454 16:12:29.421 STATEMENT: COMMIT PREPARED '48801_AF7jVNS8Z6MjBA==_Q3ZoYXZyYW5la2pkYmNEU0xpdmU=' database_B SID:496f4ed7.e04 16:12:29.421 ERROR: prepared transaction with identifier "48801_AF7jVNS8Z6MjBA==_Q3ZoYXZyYW5la2pkYmNEU1BhcmFt" does not exist database_B SID:496f4ed7.e04 16:12:29.421 STATEMENT: COMMIT PREPARED '48801_AF7jVNS8Z6MjBA==_Q3ZoYXZyYW5la2pkYmNEU1BhcmFt' database_B SID:496f4ed7.e04 16:12:29.421 LOG: duration: 0.000 ms parse <unnamed>: SHOW TRANSACTION ISOLATION LEVEL database_B SID:496f4ed7.e04 16:12:29.421 LOG: duration: 0.000 ms bind <unnamed>: SHOW TRANSACTION ISOLATION LEVEL database_B SID:496f4ed7.e04 16:12:29.421 LOG: execute <unnamed>: SHOW TRANSACTION ISOLATION LEVEL database_A SID:496f4f4d.454 16:12:29.421 LOG: duration: 0.000 ms parse <unnamed>: SHOW TRANSACTION ISOLATION LEVEL database_B SID:496f4ed7.e04 16:12:29.421 LOG: duration: 0.000 ms database_A SID:496f4f4d.454 16:12:29.421 LOG: duration: 0.000 ms bind <unnamed>: SHOW TRANSACTION ISOLATION LEVEL database_A SID:496f4f4d.454 16:12:29.421 LOG: execute <unnamed>: SHOW TRANSACTION ISOLATION LEVEL database_A SID:496f4f4d.454 16:12:29.421 LOG: duration: 0.000 ms -- Thx in advance, Regards VH Heikki Linnakangas wrote: > Vlastimil Havranek wrote: >> Thx a lot for prompt answer, here is a slightly more detailed log: >> >> -- >> 2009-01-15 14:59:56 LOG: duration: 0.000 ms parse <unnamed>: >> PREPARE TRANSACTION >> '48801_AF7jVNS8Z6MjBA==_Q3ZoYXZyYW5la2pkYmNEU1BhcmFt' >> 2009-01-15 14:59:56 LOG: duration: 0.000 ms bind <unnamed>: PREPARE >> TRANSACTION '48801_AF7jVNS8Z6MjBA==_Q3ZoYXZyYW5la2pkYmNEU1BhcmFt' >> 2009-01-15 14:59:56 LOG: execute <unnamed>: PREPARE TRANSACTION >> '48801_AF7jVNS8Z6MjBA==_Q3ZoYXZyYW5la2pkYmNEU1BhcmFt' >> 2009-01-15 14:59:56 LOG: duration: 0.000 ms parse <unnamed>: >> PREPARE TRANSACTION >> '48801_AF7jVNS8Z6MjBA==_Q3ZoYXZyYW5la2pkYmNEU0xpdmU=' >> 2009-01-15 14:59:56 LOG: duration: 0.000 ms bind <unnamed>: PREPARE >> TRANSACTION '48801_AF7jVNS8Z6MjBA==_Q3ZoYXZyYW5la2pkYmNEU0xpdmU=' >> 2009-01-15 14:59:56 LOG: execute <unnamed>: PREPARE TRANSACTION >> '48801_AF7jVNS8Z6MjBA==_Q3ZoYXZyYW5la2pkYmNEU0xpdmU=' >> 2009-01-15 14:59:56 LOG: duration: 0.000 ms >> 2009-01-15 14:59:56 LOG: duration: 0.000 ms >> 2009-01-15 14:59:56 LOG: duration: 0.000 ms parse <unnamed>: COMMIT >> PREPARED '48801_AF7jVNS8Z6MjBA==_Q3ZoYXZyYW5la2pkYmNEU1BhcmFt' >> 2009-01-15 14:59:56 LOG: duration: 0.000 ms bind <unnamed>: COMMIT >> PREPARED '48801_AF7jVNS8Z6MjBA==_Q3ZoYXZyYW5la2pkYmNEU1BhcmFt' >> 2009-01-15 14:59:56 LOG: execute <unnamed>: COMMIT PREPARED >> '48801_AF7jVNS8Z6MjBA==_Q3ZoYXZyYW5la2pkYmNEU1BhcmFt' >> 2009-01-15 14:59:56 LOG: duration: 0.000 ms parse <unnamed>: COMMIT >> PREPARED '48801_AF7jVNS8Z6MjBA==_Q3ZoYXZyYW5la2pkYmNEU0xpdmU=' >> 2009-01-15 14:59:56 LOG: duration: 0.000 ms bind <unnamed>: COMMIT >> PREPARED '48801_AF7jVNS8Z6MjBA==_Q3ZoYXZyYW5la2pkYmNEU0xpdmU=' >> 2009-01-15 14:59:56 LOG: execute <unnamed>: COMMIT PREPARED >> '48801_AF7jVNS8Z6MjBA==_Q3ZoYXZyYW5la2pkYmNEU0xpdmU=' >> 2009-01-15 14:59:56 ERROR: prepared transaction with identifier >> "48801_AF7jVNS8Z6MjBA==_Q3ZoYXZyYW5la2pkYmNEU0xpdmU=" does not exist >> 2009-01-15 14:59:56 STATEMENT: COMMIT PREPARED >> '48801_AF7jVNS8Z6MjBA==_Q3ZoYXZyYW5la2pkYmNEU0xpdmU=' > > Hmm, it looks like the server is getting a COMMIT, followed by two > PREPARE TRANSACTION commands in a row: > > BEGIN > ... > COMMIT > PREPARE TRANSACTION '48801_AF7jVNS8Z6MjBA==_Q3ZoYXZyYW5la2pkYmNEU0xpdmU=' > PREPARE TRANSACTION '48801_AF7jVNS8Z6MjBA==_Q3ZoYXZyYW5la2pkYmNEU0xpdmU=' > > I presume there's multiple backends issuing these commands > concurrently, otherwise both PREPARE TRANSACTION commands should fail > with "there is no transaction in progress" warning. > > One theory is that the 2nd PREPARE TRANSACTION *is* failing, and gives > a WARNING, but we're not seeing that in any of the logs. I don't know > why that might happen, but I notice that we don't have a check for > that case in the JDBC driver's prepare() method, so the application > server would think that the transaction prepare succeeded. > > Please make sure you have log_min_messages set to "warning" (or lower, > e.g "notice") and try again. Also, %c would be very helpful in > log_line_prefix, so that we could tell apart actions of different > backends in the log. > -- ------------------------------------------------------------- Vlastimil Havránek Software Developer xitee k.s. || www.xitee.com || vlastimil.havranek@xitee.com Phone: office +420 234262342, mobile +420 775366990 -------------------------------------------------------------
Vlastimil Havranek <vlastimil.havranek@xitee.com> writes: > Here is the log with the settings zou have suggested: [ extracted... ] > database_A SID:496f4f4d.454 16:12:27.953 LOG: duration: 0.000 ms > parse <unnamed>: PREPARE TRANSACTION > '48801_AOiMyUwnZ6MjBA==_Q3ZoYXZyYW5la2pkYmNEU0xpdmU=' > database_A SID:496f4f4d.454 16:12:27.953 LOG: duration: 0.000 ms bind > <unnamed>: PREPARE TRANSACTION > '48801_AOiMyUwnZ6MjBA==_Q3ZoYXZyYW5la2pkYmNEU0xpdmU=' > database_A SID:496f4f4d.454 16:12:27.953 LOG: execute <unnamed>: > PREPARE TRANSACTION '48801_AOiMyUwnZ6MjBA==_Q3ZoYXZyYW5la2pkYmNEU0xpdmU=' > database_A SID:496f4f4d.454 16:12:27.953 LOG: duration: 0.000 ms > database_A SID:496f4f4d.454 16:12:28.000 LOG: duration: 0.000 ms > parse <unnamed>: COMMIT PREPARED > '48801_AOiMyUwnZ6MjBA==_Q3ZoYXZyYW5la2pkYmNEU0xpdmU=' > database_A SID:496f4f4d.454 16:12:28.000 LOG: duration: 0.000 ms bind > <unnamed>: COMMIT PREPARED > '48801_AOiMyUwnZ6MjBA==_Q3ZoYXZyYW5la2pkYmNEU0xpdmU=' > database_A SID:496f4f4d.454 16:12:28.000 LOG: execute <unnamed>: > COMMIT PREPARED '48801_AOiMyUwnZ6MjBA==_Q3ZoYXZyYW5la2pkYmNEU0xpdmU=' > database_A SID:496f4f4d.454 16:12:28.000 ERROR: prepared transaction > with identifier "48801_AOiMyUwnZ6MjBA==_Q3ZoYXZyYW5la2pkYmNEU0xpdmU=" > does not exist Well, this clearly shows the same GID being committed twice --- and by the same session, so my early thoughts about a race condition are out. So either Weblogic is broken, or there's a bug in the JDBC driver that somehow causes this, or we've misread the spec and should allow this. regards, tom lane
Tom Lane wrote: > Vlastimil Havranek <vlastimil.havranek@xitee.com> writes: >> Here is the log with the settings zou have suggested: > > [ extracted... ] > >> database_A SID:496f4f4d.454 16:12:27.953 LOG: duration: 0.000 ms >> parse <unnamed>: PREPARE TRANSACTION >> '48801_AOiMyUwnZ6MjBA==_Q3ZoYXZyYW5la2pkYmNEU0xpdmU=' >> database_A SID:496f4f4d.454 16:12:27.953 LOG: duration: 0.000 ms bind >> <unnamed>: PREPARE TRANSACTION >> '48801_AOiMyUwnZ6MjBA==_Q3ZoYXZyYW5la2pkYmNEU0xpdmU=' >> database_A SID:496f4f4d.454 16:12:27.953 LOG: execute <unnamed>: >> PREPARE TRANSACTION '48801_AOiMyUwnZ6MjBA==_Q3ZoYXZyYW5la2pkYmNEU0xpdmU=' >> database_A SID:496f4f4d.454 16:12:27.953 LOG: duration: 0.000 ms >> database_A SID:496f4f4d.454 16:12:28.000 LOG: duration: 0.000 ms >> parse <unnamed>: COMMIT PREPARED >> '48801_AOiMyUwnZ6MjBA==_Q3ZoYXZyYW5la2pkYmNEU0xpdmU=' >> database_A SID:496f4f4d.454 16:12:28.000 LOG: duration: 0.000 ms bind >> <unnamed>: COMMIT PREPARED >> '48801_AOiMyUwnZ6MjBA==_Q3ZoYXZyYW5la2pkYmNEU0xpdmU=' >> database_A SID:496f4f4d.454 16:12:28.000 LOG: execute <unnamed>: >> COMMIT PREPARED '48801_AOiMyUwnZ6MjBA==_Q3ZoYXZyYW5la2pkYmNEU0xpdmU=' >> database_A SID:496f4f4d.454 16:12:28.000 ERROR: prepared transaction >> with identifier "48801_AOiMyUwnZ6MjBA==_Q3ZoYXZyYW5la2pkYmNEU0xpdmU=" >> does not exist > > Well, this clearly shows the same GID being committed twice --- and by > the same session, so my early thoughts about a race condition are out. > > So either Weblogic is broken, or there's a bug in the JDBC driver that > somehow causes this, or we've misread the spec and should allow this. No, you misread the log. There's a parse, bind, and execute for COMMIT PREPARED for that GID, but only once. Here's a reduced log with a lot of lines removed to make the problem obvious: > database_A SID:496f4f4d.454 16:12:27.625 LOG: execute S_1: BEGIN > database_A SID:496f4f4d.454 16:12:27.625 LOG: execute <unnamed>: SOME SELECT FOR UPDATE > database_A SID:496f4f4d.454 16:12:27.937 LOG: execute S_2: COMMIT (so far so good) > database_A SID:496f4f4d.454 16:12:27.953 LOG: execute <unnamed>: PREPARE TRANSACTION '48801_AOiMyUwnZ6MjBA==_Q3ZoYXZyYW5la2pkYmNEU0xpdmU=' > database_A SID:496f4f4d.454 16:12:28.000 LOG: execute <unnamed>: COMMIT PREPARED '48801_AOiMyUwnZ6MjBA==_Q3ZoYXZyYW5la2pkYmNEU0xpdmU=' > database_A SID:496f4f4d.454 16:12:28.000 ERROR: prepared transaction with identifier "48801_AOiMyUwnZ6MjBA==_Q3ZoYXZyYW5la2pkYmNEU0xpdmU="does not exist > database_A SID:496f4f4d.454 16:12:28.000 STATEMENT: COMMIT PREPARED '48801_AOiMyUwnZ6MjBA==_Q3ZoYXZyYW5la2pkYmNEU0xpdmU=' It's trying to PREPARE a TRANSACTION right after regular 1-phase COMMIT. You should get a "WARNING: there is no transaction in progress", and rollback; I'm not sure why we're not seeing that in the log. Vlastimil, did you check the log_min_messages setting? If you run "PREPARE TRANSACTION 'foo'" manually, without a BEGIN, do you get that warning both on the screen and in the log? Now, why we're getting those commands from the JDBC driver, I don't know. I concur that either WebLogic is broken, or there's a bug in the JDBC driver. -- Heikki Linnakangas EnterpriseDB http://www.enterprisedb.com
Heikki Linnakangas <heikki.linnakangas@enterprisedb.com> writes: > No, you misread the log. There's a parse, bind, and execute for COMMIT > PREPARED for that GID, but only once. Better read it again. regards, tom lane
Tom Lane wrote: > Heikki Linnakangas <heikki.linnakangas@enterprisedb.com> writes: >> No, you misread the log. There's a parse, bind, and execute for COMMIT >> PREPARED for that GID, but only once. > > Better read it again. grep "COMMIT PREPARED" /tmp/a | grep execute database_A SID:496f4f4d.454 16:12:28.000 LOG: execute <unnamed>: COMMIT PREPARED '48801_AOiMyUwnZ6MjBA==_Q3ZoYXZyYW5la2pkYmNEU0xpdmU=' database_B SID:496f4ed7.e04 16:12:28.000 LOG: execute <unnamed>: COMMIT PREPARED '48801_AOiMyUwnZ6MjBA==_Q3ZoYXZyYW5la2pkYmNEU1BhcmFt' database_A SID:496f4f4d.454 16:12:29.421 LOG: execute <unnamed>: COMMIT PREPARED '48801_AF7jVNS8Z6MjBA==_Q3ZoYXZyYW5la2pkYmNEU0xpdmU=' database_B SID:496f4ed7.e04 16:12:29.421 LOG: execute <unnamed>: COMMIT PREPARED '48801_AF7jVNS8Z6MjBA==_Q3ZoYXZyYW5la2pkYmNEU1BhcmFt' Those are four different GIDs. -- Heikki Linnakangas EnterpriseDB http://www.enterprisedb.com
Vlastimil Havranek wrote: > yes the log_min_messages is set to notice. I've just rechecked it. Ok, thanks. One theory is that WebLogic, or your application code, is calling setAutoCommit on the XA connection. I can reproduce a similar error with a stand-alone test case by doing that: XAConnection xaconn1 = ds.getXAConnection(); XAResource xares1 = xaconn1.getXAResource(); Connection conn1 = xaconn1.getConnection(); xares1.start(initxid, XAResource.TMNOFLAGS); Statement stmt = conn1.createStatement(); stmt.executeUpdate("INSERT INTO foo VALUES (1234)"); // 1. conn1.setAutoCommit(true); xares1.end(initxid, XAResource.TMSUCCESS); // 2. conn1.setAutoCommit(true); xares1.prepare(initxid); xares1.commit(initxid, false); Uncommenting either of the commented lines will cause a similar error as you're seeing. Since the end() call is made by WebLogic, the 1st case would be an explicit setAutoCommit call in your application. You don't have one, do you? That's forbidden by the JTA spec. The 2nd call would be a call made by WebLogic. We've seen WebLogic do strange call patterns before (see http://archives.postgresql.org/pgsql-jdbc/2006-10/msg00011.php), so I wouldn't be surprised if it was doing that. It's allowed by the JTA spec, but not by the PostgreSQL driver because we don't support transaction interleaving. We could try modifying the driver to tolerate it like the aforementioned "end then join" case, by not passing the setAutoCommit call immediately to the underlying connection object, but delay it until prepare-call. Whether that would work depends on what else the application server is trying to do with the connection between end and prepare. Calling commit or rollback at those points will also trigger the same error. JTA spec also forbids setSavePoint, but I'm not sure if that would actually be a problem for PostgreSQL. There's some options in WebLogic to dumb-down the interaction with the JDBC XA driver, see http://edocs.bea.com/wls/docs100/ConsoleHelp/pagehelp/JDBCjdbcdatasourcesjdbcdatasourceconfigtransactiontitle.html. At least "Keep Connection Open On Release" is required for PostgreSQL driver, and setting the other settings marked with "Use this setting to work around specific problems with JDBC XA drivers" might help too. Please make sure you have those set. Now, it would be very good if we threw an error immediately at the offending call, regardless of whether it's allowed by JTA or not. I've been trying to figure out how to do that. We could create a proxy for the Connection object handed to the application in PGXAConnection, and throw an error if you call one of those functions while an XA-transaction is open. That would be fairly simple, but wouldn't catch the pattern: start(xid) // do stuff in XA transaction executeUpdate("UPDATE ..."); end(xid) // do stuff outside the XA transaction executeUpdate("UPDATE ..."); prepare(xid); It would be better than nothing, but it would be even better if we could catch all the cases we can't handle properly. If we could inject a proxy to check that at lower level, around QueryExecutor, it would be more robust, but I don't see any easy way to do that. Another check that we really ought to do is to check the command tag that PREPARE TRANSACTION returns. If it returns ROLLBACK, the driver should throw an error. I'll write a patch for that. -- Heikki Linnakangas EnterpriseDB http://www.enterprisedb.com
Hi Heikki, yes the log_min_messages is set to notice. I've just rechecked it. Vlastimil Havranek Vl. Heikki Linnakangas wrote: > Tom Lane wrote: >> Heikki Linnakangas <heikki.linnakangas@enterprisedb.com> writes: >>> No, you misread the log. There's a parse, bind, and execute for >>> COMMIT PREPARED for that GID, but only once. >> >> Better read it again. > > grep "COMMIT PREPARED" /tmp/a | grep execute > > database_A SID:496f4f4d.454 16:12:28.000 LOG: execute <unnamed>: > COMMIT PREPARED '48801_AOiMyUwnZ6MjBA==_Q3ZoYXZyYW5la2pkYmNEU0xpdmU=' > database_B SID:496f4ed7.e04 16:12:28.000 LOG: execute <unnamed>: > COMMIT PREPARED '48801_AOiMyUwnZ6MjBA==_Q3ZoYXZyYW5la2pkYmNEU1BhcmFt' > database_A SID:496f4f4d.454 16:12:29.421 LOG: execute <unnamed>: > COMMIT PREPARED '48801_AF7jVNS8Z6MjBA==_Q3ZoYXZyYW5la2pkYmNEU0xpdmU=' > database_B SID:496f4ed7.e04 16:12:29.421 LOG: execute <unnamed>: > COMMIT PREPARED '48801_AF7jVNS8Z6MjBA==_Q3ZoYXZyYW5la2pkYmNEU1BhcmFt' > > Those are four different GIDs. > -- ------------------------------------------------------------- Vlastimil Havránek Software Developer xitee k.s. || www.xitee.com || vlastimil.havranek@xitee.com Phone: office +420 234262342, mobile +420 775366990 -------------------------------------------------------------
Hi, regarding the autocommit, we do not use it in our application, we use the EJBs mostly with CMP, some with BMP, which are accessing several dbs via XA driver. The EJB on which it gets stuck runs with CMP. Ive found that weblogic provides some monitoring of tx, the tx was there in state 'comitting' but both force local and force global commit failed with xaexception: someDataSource: null. Ive tried all the XA related data source settings, but it didnt help. So maybe if you could modify the driver to tolerate the strange WL XA pattern, then I would try that one out. Anyway, thx for your great cooperation, Vlastimil Havranek Heikki Linnakangas wrote: > Vlastimil Havranek wrote: >> yes the log_min_messages is set to notice. I've just rechecked it. > > Ok, thanks. > > One theory is that WebLogic, or your application code, is calling > setAutoCommit on the XA connection. I can reproduce a similar error > with a stand-alone test case by doing that: > > XAConnection xaconn1 = ds.getXAConnection(); > XAResource xares1 = xaconn1.getXAResource(); > Connection conn1 = xaconn1.getConnection(); > > xares1.start(initxid, XAResource.TMNOFLAGS); > Statement stmt = conn1.createStatement(); > stmt.executeUpdate("INSERT INTO foo VALUES (1234)"); > // 1. conn1.setAutoCommit(true); > xares1.end(initxid, XAResource.TMSUCCESS); > // 2. conn1.setAutoCommit(true); > xares1.prepare(initxid); > xares1.commit(initxid, false); > > Uncommenting either of the commented lines will cause a similar error > as you're seeing. Since the end() call is made by WebLogic, the 1st > case would be an explicit setAutoCommit call in your application. You > don't have one, do you? That's forbidden by the JTA spec. > > The 2nd call would be a call made by WebLogic. We've seen WebLogic do > strange call patterns before (see > http://archives.postgresql.org/pgsql-jdbc/2006-10/msg00011.php), so I > wouldn't be surprised if it was doing that. It's allowed by the JTA > spec, but not by the PostgreSQL driver because we don't support > transaction interleaving. We could try modifying the driver to > tolerate it like the aforementioned "end then join" case, by not > passing the setAutoCommit call immediately to the underlying > connection object, but delay it until prepare-call. Whether that would > work depends on what else the application server is trying to do with > the connection between end and prepare. > > Calling commit or rollback at those points will also trigger the same > error. JTA spec also forbids setSavePoint, but I'm not sure if that > would actually be a problem for PostgreSQL. > > There's some options in WebLogic to dumb-down the interaction with the > JDBC XA driver, see > http://edocs.bea.com/wls/docs100/ConsoleHelp/pagehelp/JDBCjdbcdatasourcesjdbcdatasourceconfigtransactiontitle.html. > At least "Keep Connection Open On Release" is required for PostgreSQL > driver, and setting the other settings marked with "Use this setting > to work around specific problems with JDBC XA drivers" might help too. > Please make sure you have those set. > > > Now, it would be very good if we threw an error immediately at the > offending call, regardless of whether it's allowed by JTA or not. I've > been trying to figure out how to do that. We could create a proxy for > the Connection object handed to the application in PGXAConnection, and > throw an error if you call one of those functions while an > XA-transaction is open. That would be fairly simple, but wouldn't > catch the pattern: > > start(xid) > // do stuff in XA transaction > executeUpdate("UPDATE ..."); > end(xid) > // do stuff outside the XA transaction > executeUpdate("UPDATE ..."); > prepare(xid); > > It would be better than nothing, but it would be even better if we > could catch all the cases we can't handle properly. If we could inject > a proxy to check that at lower level, around QueryExecutor, it would > be more robust, but I don't see any easy way to do that. > > > Another check that we really ought to do is to check the command tag > that PREPARE TRANSACTION returns. If it returns ROLLBACK, the driver > should throw an error. I'll write a patch for that. > -- ------------------------------------------------------------- Vlastimil Havránek Software Developer xitee k.s. || www.xitee.com || vlastimil.havranek@xitee.com Phone: office +420 234262342, mobile +420 775366990 -------------------------------------------------------------
Hi, Ive just tried the patched driver and at first look it seems to have solved the issue! I will check the logs and do more tests tomorow. VH Heikki Linnakangas wrote: > Vlastimil Havranek wrote: >> Hi, >> regarding the autocommit, we do not use it in our application, we use >> the EJBs mostly with CMP, some with BMP, which are accessing several >> dbs via XA driver. >> The EJB on which it gets stuck runs with CMP. >> >> Ive found that weblogic provides some monitoring of tx, the tx was >> there in state 'comitting' but both force local and force global >> commit failed with xaexception: someDataSource: null. >> >> Ive tried all the XA related data source settings, but it didnt help. >> >> So maybe if you could modify the driver to tolerate the strange WL XA >> pattern, then I would try that one out. >> >> Anyway, thx for your great cooperation, > > Ok, here's a patch to tighten up the XA state handling in the driver, > in two different ways: > 1. More cases of illegal (per JTA spec) calls and calls we can't > handle because of lack of transaction interleaving are explicitly > checked for, and an error is thrown. > 2. The returned command tag of PREPARE TRANSACTION/COMMIT > PREPARED/ROLLBACK PREPARED are checked, and an exception is thrown if > it's not what was expected. > > This makes the XA part of the driver much more robust. > > Vlastimil, can you try what this patch does to your test case? It > won't solve your problem, but you should get a more descriptive error > message, showing more clearly what WebLogic is doing. Then we can > hopefully see if there's something we can do in the driver to make it > work. > > I can send you a patched postgresql.jar offlist. If you need one, just > drop me a note. > -- ------------------------------------------------------------- Vlastimil Havránek Software Developer xitee k.s. || www.xitee.com || vlastimil.havranek@xitee.com Phone: office +420 234262342, mobile +420 775366990 -------------------------------------------------------------
Vlastimil Havranek wrote: > Ive just tried the patched driver and at first look it seems to have > solved the issue! I will check the logs and do more tests tomorow. Huh, that's odd. It really shouldn't have solved it! It should've just given a different error message. -- Heikki Linnakangas EnterpriseDB http://www.enterprisedb.com
It has not solve the issue completely, but really made it appear less often. Currently we are preparing to start using jboss, so I will leave the issue to the community now. Thx for your help anyway, Vl. Heikki Linnakangas wrote: > Vlastimil Havranek wrote: >> Ive just tried the patched driver and at first look it seems to have >> solved the issue! I will check the logs and do more tests tomorow. > > Huh, that's odd. It really shouldn't have solved it! It should've just > given a different error message. > -- ------------------------------------------------------------- Vlastimil Havránek Software Developer xitee k.s. || www.xitee.com || vlastimil.havranek@xitee.com Phone: office +420 234262342, mobile +420 775366990 -------------------------------------------------------------