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 : 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 : 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 : 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 : SHOW 
TRANSACTION ISOLATION LEVEL
2009-01-15 14:59:55 LOG:  duration: 0.000 ms  bind : SHOW 
TRANSACTION ISOLATION LEVEL
2009-01-15 14:59:55 LOG:  execute : 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 : 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 : 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 : 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 : select 
count(*) from t0
2009-01-15 14:59:55 LOG:  duration: 0.000 ms  bind : select 
count(*) from t0
2009-01-15 14:59:55 LOG:  execute : 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 : 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 : 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 : 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 : PREPARE 
TRANSACTION '48801_AF7jVNS8Z6MjBA==_Q3ZoYXZyYW5la2pkYmNEU1BhcmFt'
2009-01-15 14:59:56 LOG:  duration: 0.000 ms  bind : PREPARE 
TRANSACTION '48801_AF7jVNS8Z6MjBA==_Q3ZoYXZyYW5la2pkYmNEU1BhcmFt'
2009-01-15 14:59:56 LOG:  execute : PREPARE TRANSACTION 
'48801_AF7jVNS8Z6MjBA==_Q3ZoYXZyYW5la2pkYmNEU1BhcmFt'
2009-01-15 14:59:56 LOG:  duration: 0.000 ms  parse : PREPARE 
TRANSACTION '48801_AF7jVNS8Z6MjBA==_Q3ZoYXZyYW5la2pkYmNEU0xpdmU='
2009-01-15 14:59:56 LOG:  duration: 0.000 ms  bind : PREPARE 
TRANSACTION '48801_AF7jVNS8Z6MjBA==_Q3ZoYXZyYW5la2pkYmNEU0xpdmU='
2009-01-15 14:59:56 LOG:  execute : 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 : COMMIT 
PREPARED '48801_AF7jVNS8Z6MjBA==_Q3ZoYXZyYW5la2pkYmNEU1BhcmFt'
2009-01-15 14:59:56 LOG:  duration: 0.000 ms  bind : COMMIT 
PREPARED '48801_AF7jVNS8Z6MjBA==_Q3ZoYXZyYW5la2pkYmNEU1BhcmFt'
2009-01-15 14:59:56 LOG:  execute : COMMIT PREPARED 
'48801_AF7jVNS8Z6MjBA==_Q3ZoYXZyYW5la2pkYmNEU1BhcmFt'
2009-01-15 14:59:56 LOG:  duration: 0.000 ms  parse : COMMIT 
PREPARED '48801_AF7jVNS8Z6MjBA==_Q3ZoYXZyYW5la2pkYmNEU0xpdmU='
2009-01-15 14:59:56 LOG:  duration: 0.000 ms  bind : COMMIT 
PREPARED '48801_AF7jVNS8Z6MjBA==_Q3ZoYXZyYW5la2pkYmNEU0xpdmU='
2009-01-15 14:59:56 LOG:  execute : 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 : SHOW 
TRANSACTION ISOLATION LEVEL
2009-01-15 14:59:56 LOG:  duration: 0.000 ms  bind : SHOW 
TRANSACTION ISOLATION LEVEL
2009-01-15 14:59:56 LOG:  execute : 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 : SHOW 
TRANSACTION ISOLATION LEVEL
2009-01-15 14:59:56 LOG:  duration: 0.000 ms  bind : SHOW 
TRANSACTION ISOLATION LEVEL
2009-01-15 14:59:56 LOG:  execute : 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 : 
>> PREPARE TRANSACTION 
>> '48801_AQeOE4t3Z6MjBA==_Q3ZoYXZyYW5la2pkYmNEU0xpdmU='
>>    2009-01-13 13:37:50 LOG:  duration: 0.000 ms  bind : 
>> PREPARE TRANSACTION 
>> '48801_AQeOE4t3Z6MjBA==_Q3ZoYXZyYW5la2pkYmNEU0xpdmU='
>>    2009-01-13 13:37:50 LOG:  duration: 0.000 ms  execute : 
>> PREPARE TRANSACTION 
>> '48801_AQeOE4t3Z6MjBA==_Q3ZoYXZyYW5la2pkYmNEU0xpdmU='
>>    2009-01-13 13:37:51 LOG:  duration: 0.000 ms  parse : 
>> COMMIT PREPARED '48801_AQeOE4t3Z6MjBA==_Q3ZoYXZyYW5la2pkYmNEU0xpdmU='
>>    2009-01-13 13:37:51 LOG:  duration: 0.000 ms  bind : 
>> 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 : 
>> COMMIT PREPARED '48801_AQeOE4t3Z6MjBA==_Q3ZoYXZyYW5la2pkYmNEU0xpdmU='
>>    2009-01-13 13:38:51 LOG:  duration: 0.000 ms  bind : 
>> 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
-------------------------------------------------------------