Re: Problem with committing in XA mode

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
-------------------------------------------------------------