PoolShrinkingTask Exception

classic Classic list List threaded Threaded
6 messages Options
Reply | Threaded
Open this post in threaded view
|

PoolShrinkingTask Exception

greenbean
This exception below started popping up recently.  Does anyone have any ideas what could cause this problem?  Is it harmless?
 
2011-06-17 01:47:39,557 WARN  [bitronix.tm.timer.TaskScheduler] (bitronix-scheduler) error running a PoolShrinkingTask scheduled for Fri Jun 17 01:47:29 GM
T 2011 on an XAPool of resource oracle with 4 connection(s) (2 still available)
bitronix.tm.timer.TaskException: error while trying to shrink an XAPool of resource oracle with 4 connection(s) (2 still available)
        at bitronix.tm.timer.PoolShrinkingTask.execute(PoolShrinkingTask.java:49)
        at bitronix.tm.timer.TaskScheduler.executeElapsedTasks(TaskScheduler.java:217)
        at bitronix.tm.timer.TaskScheduler.run(TaskScheduler.java:193)
Caused by: java.lang.NullPointerException
        at bitronix.tm.resource.jdbc.JdbcPooledConnection.<init>(JdbcPooledConnection.java:72)
        at bitronix.tm.resource.jdbc.PoolingDataSource.createPooledConnection(PoolingDataSource.java:288)
        at bitronix.tm.resource.common.XAPool.createPooledObject(XAPool.java:291)
        at bitronix.tm.resource.common.XAPool.growUntilMinPoolSize(XAPool.java:80)
        at bitronix.tm.resource.common.XAPool.shrink(XAPool.java:261)
        at bitronix.tm.timer.PoolShrinkingTask.execute(PoolShrinkingTask.java:47)
        ... 2 more
 
 
 
 
Reply | Threaded
Open this post in threaded view
|

Re: PoolShrinkingTask Exception

Ludovic Orban-2
This looks like a memory visibility issue. Fortunately, it's rather harmless in this case: after the pool was emptied by the shrinking task, it could not be restored to the minimal pool size so further calls to PoolingDataSource will compensate for that the next time getConnection() is called.

A lot of those issues appeared recently due to the more and more aggressive optimizations added in the latest JDK 1.6's JIT. I've tracked all the ones I could find a fixed them in trunk so the next release should be much more robust in this regard.

In the meantime, you can rely on BTM's self-healing design: as long as something isn't definitely unusable, BTM will try to restore its internal state at every possible step. I suppose you didn't notice anything wrong in your app except for these stack traces or you would have complained. ;-)
 

2011/6/21 Urciolo, Kevin J (IS) <[hidden email]>
This exception below started popping up recently.  Does anyone have any ideas what could cause this problem?  Is it harmless?
 
2011-06-17 01:47:39,557 WARN  [bitronix.tm.timer.TaskScheduler] (bitronix-scheduler) error running a PoolShrinkingTask scheduled for Fri Jun 17 01:47:29 GM
T 2011 on an XAPool of resource oracle with 4 connection(s) (2 still available)
bitronix.tm.timer.TaskException: error while trying to shrink an XAPool of resource oracle with 4 connection(s) (2 still available)
        at bitronix.tm.timer.PoolShrinkingTask.execute(PoolShrinkingTask.java:49)
        at bitronix.tm.timer.TaskScheduler.executeElapsedTasks(TaskScheduler.java:217)
        at bitronix.tm.timer.TaskScheduler.run(TaskScheduler.java:193)
Caused by: java.lang.NullPointerException
        at bitronix.tm.resource.jdbc.JdbcPooledConnection.<init>(JdbcPooledConnection.java:72)
        at bitronix.tm.resource.jdbc.PoolingDataSource.createPooledConnection(PoolingDataSource.java:288)
        at bitronix.tm.resource.common.XAPool.createPooledObject(XAPool.java:291)
        at bitronix.tm.resource.common.XAPool.growUntilMinPoolSize(XAPool.java:80)
        at bitronix.tm.resource.common.XAPool.shrink(XAPool.java:261)
        at bitronix.tm.timer.PoolShrinkingTask.execute(PoolShrinkingTask.java:47)
        ... 2 more
 
 
 
 

Reply | Threaded
Open this post in threaded view
|

RE: EXT :Re: [btm-user] PoolShrinkingTask Exception

greenbean

Thank you for the prompt reply.  We are currently running Java 6u23 64-bit for Linux.

 

We did encounter an issue recently where an Oracle 10 resource returned the exception below.  Nothing showed up in the Oracle alert logs, or any other logs on Oracle that  the DBA could find.  I could not find a prepared transaction sitting in Oracle, nor could I find any indication that the BTM recovery thread went back and tried the commit again.  We were able to trace the transaction down to a specific row that should have been inserted in to the Oracle database.  The row does not exist.

 

I am not sure what happened at the moment.  The complexity of the events, and lack of logging in Oracle make tracking down the root cause pretty much impossible.

 

2011-06-17 09:08:39,011 WARN  [bitronix.tm.twopc.Committer] (midasReconReqProcessorThreadPoolExecutor-2) resource 'oracle' reported XAER_RMFAIL when asked

to commit transaction branch. Transaction is prepared and will commit via recovery service when resource availability allows.

oracle.jdbc.xa.OracleXAException

        at oracle.jdbc.xa.OracleXAResource.checkError(OracleXAResource.java:1126)

        at oracle.jdbc.xa.client.OracleXAResource.commit(OracleXAResource.java:585)

        at bitronix.tm.twopc.Committer$CommitJob.commitResource(Committer.java:194)

        at bitronix.tm.twopc.Committer$CommitJob.execute(Committer.java:183)

        at bitronix.tm.twopc.executor.Job.run(Job.java:70)

        at bitronix.tm.twopc.executor.SyncExecutor.submit(SyncExecutor.java:31)

        at bitronix.tm.twopc.AbstractPhaseEngine.runJobsForPosition(AbstractPhaseEngine.java:129)

        at bitronix.tm.twopc.AbstractPhaseEngine.executePhase(AbstractPhaseEngine.java:90)

        at bitronix.tm.twopc.Committer.commit(Committer.java:82)

        at bitronix.tm.BitronixTransaction.commit(BitronixTransaction.java:239)

        at bitronix.tm.BitronixTransactionManager.commit(BitronixTransactionManager.java:120)

        at org.springframework.transaction.jta.JtaTransactionManager.doCommit(JtaTransactionManager.java:1009)

 

 

From: [hidden email] [mailto:[hidden email]] On Behalf Of Ludovic Orban
Sent: Tuesday, June 21, 2011 1:10 PM
To: [hidden email]
Subject: EXT :Re: [btm-user] PoolShrinkingTask Exception

 

This looks like a memory visibility issue. Fortunately, it's rather harmless in this case: after the pool was emptied by the shrinking task, it could not be restored to the minimal pool size so further calls to PoolingDataSource will compensate for that the next time getConnection() is called.

A lot of those issues appeared recently due to the more and more aggressive optimizations added in the latest JDK 1.6's JIT. I've tracked all the ones I could find a fixed them in trunk so the next release should be much more robust in this regard.

In the meantime, you can rely on BTM's self-healing design: as long as something isn't definitely unusable, BTM will try to restore its internal state at every possible step. I suppose you didn't notice anything wrong in your app except for these stack traces or you would have complained. ;-)
 

2011/6/21 Urciolo, Kevin J (IS) <[hidden email]>

This exception below started popping up recently.  Does anyone have any ideas what could cause this problem?  Is it harmless?

 

2011-06-17 01:47:39,557 WARN  [bitronix.tm.timer.TaskScheduler] (bitronix-scheduler) error running a PoolShrinkingTask scheduled for Fri Jun 17 01:47:29 GM

T 2011 on an XAPool of resource oracle with 4 connection(s) (2 still available)

bitronix.tm.timer.TaskException: error while trying to shrink an XAPool of resource oracle with 4 connection(s) (2 still available)

        at bitronix.tm.timer.PoolShrinkingTask.execute(PoolShrinkingTask.java:49)

        at bitronix.tm.timer.TaskScheduler.executeElapsedTasks(TaskScheduler.java:217)

        at bitronix.tm.timer.TaskScheduler.run(TaskScheduler.java:193)

Caused by: java.lang.NullPointerException

        at bitronix.tm.resource.jdbc.JdbcPooledConnection.<init>(JdbcPooledConnection.java:72)

        at bitronix.tm.resource.jdbc.PoolingDataSource.createPooledConnection(PoolingDataSource.java:288)

        at bitronix.tm.resource.common.XAPool.createPooledObject(XAPool.java:291)

        at bitronix.tm.resource.common.XAPool.growUntilMinPoolSize(XAPool.java:80)

        at bitronix.tm.resource.common.XAPool.shrink(XAPool.java:261)

        at bitronix.tm.timer.PoolShrinkingTask.execute(PoolShrinkingTask.java:47)

        ... 2 more

 

 

 

 

 

Reply | Threaded
Open this post in threaded view
|

Re: RE: EXT :Re: [btm-user] PoolShrinkingTask Exception

Ludovic Orban-2
This is a tricky problem and the most likely cause is a problem in the Oracle JDBC driver but I obviously don't have any proof to back that statement: after phase 1 successfully executed, Oracle cannot give up on that transaction without reporting a heuristic to the TM which in turn would have been reported by the recoverer. One exception to this rule is if this transaction was running only against Oracle, in that case 1PC optimization kicked in and Oracle may silently rollback the changes.

If you have the transaction's GTRID you could use the GUI tool to introspect BTM's disk journal and try to figure out what happened to that transaction. I also recommend you to add %X{btm-gtrid} to your log4j ConversionPattern to have the logs always include the GTRID which makes it much easier to troubleshoot multi-transactions problems and always have a trace of which transaction caused an error.

With so little detail there's unfortunately very little more I can do to help you.


2011/6/21 Urciolo, Kevin J (IS) <[hidden email]>

Thank you for the prompt reply.  We are currently running Java 6u23 64-bit for Linux.

 

We did encounter an issue recently where an Oracle 10 resource returned the exception below.  Nothing showed up in the Oracle alert logs, or any other logs on Oracle that  the DBA could find.  I could not find a prepared transaction sitting in Oracle, nor could I find any indication that the BTM recovery thread went back and tried the commit again.  We were able to trace the transaction down to a specific row that should have been inserted in to the Oracle database.  The row does not exist.

 

I am not sure what happened at the moment.  The complexity of the events, and lack of logging in Oracle make tracking down the root cause pretty much impossible.

 

2011-06-17 09:08:39,011 WARN  [bitronix.tm.twopc.Committer] (midasReconReqProcessorThreadPoolExecutor-2) resource 'oracle' reported XAER_RMFAIL when asked

to commit transaction branch. Transaction is prepared and will commit via recovery service when resource availability allows.

oracle.jdbc.xa.OracleXAException

        at oracle.jdbc.xa.OracleXAResource.checkError(OracleXAResource.java:1126)

        at oracle.jdbc.xa.client.OracleXAResource.commit(OracleXAResource.java:585)

        at bitronix.tm.twopc.Committer$CommitJob.commitResource(Committer.java:194)

        at bitronix.tm.twopc.Committer$CommitJob.execute(Committer.java:183)

        at bitronix.tm.twopc.executor.Job.run(Job.java:70)

        at bitronix.tm.twopc.executor.SyncExecutor.submit(SyncExecutor.java:31)

        at bitronix.tm.twopc.AbstractPhaseEngine.runJobsForPosition(AbstractPhaseEngine.java:129)

        at bitronix.tm.twopc.AbstractPhaseEngine.executePhase(AbstractPhaseEngine.java:90)

        at bitronix.tm.twopc.Committer.commit(Committer.java:82)

        at bitronix.tm.BitronixTransaction.commit(BitronixTransaction.java:239)

        at bitronix.tm.BitronixTransactionManager.commit(BitronixTransactionManager.java:120)

        at org.springframework.transaction.jta.JtaTransactionManager.doCommit(JtaTransactionManager.java:1009)

 

 

From: [hidden email] [mailto:[hidden email]] On Behalf Of Ludovic Orban
Sent: Tuesday, June 21, 2011 1:10 PM
To: [hidden email]
Subject: EXT :Re: [btm-user] PoolShrinkingTask Exception

 

This looks like a memory visibility issue. Fortunately, it's rather harmless in this case: after the pool was emptied by the shrinking task, it could not be restored to the minimal pool size so further calls to PoolingDataSource will compensate for that the next time getConnection() is called.

A lot of those issues appeared recently due to the more and more aggressive optimizations added in the latest JDK 1.6's JIT. I've tracked all the ones I could find a fixed them in trunk so the next release should be much more robust in this regard.

In the meantime, you can rely on BTM's self-healing design: as long as something isn't definitely unusable, BTM will try to restore its internal state at every possible step. I suppose you didn't notice anything wrong in your app except for these stack traces or you would have complained. ;-)
 

2011/6/21 Urciolo, Kevin J (IS) <[hidden email]>

This exception below started popping up recently.  Does anyone have any ideas what could cause this problem?  Is it harmless?

 

2011-06-17 01:47:39,557 WARN  [bitronix.tm.timer.TaskScheduler] (bitronix-scheduler) error running a PoolShrinkingTask scheduled for Fri Jun 17 01:47:29 GM

T 2011 on an XAPool of resource oracle with 4 connection(s) (2 still available)

bitronix.tm.timer.TaskException: error while trying to shrink an XAPool of resource oracle with 4 connection(s) (2 still available)

        at bitronix.tm.timer.PoolShrinkingTask.execute(PoolShrinkingTask.java:49)

        at bitronix.tm.timer.TaskScheduler.executeElapsedTasks(TaskScheduler.java:217)

        at bitronix.tm.timer.TaskScheduler.run(TaskScheduler.java:193)

Caused by: java.lang.NullPointerException

        at bitronix.tm.resource.jdbc.JdbcPooledConnection.<init>(JdbcPooledConnection.java:72)

        at bitronix.tm.resource.jdbc.PoolingDataSource.createPooledConnection(PoolingDataSource.java:288)

        at bitronix.tm.resource.common.XAPool.createPooledObject(XAPool.java:291)

        at bitronix.tm.resource.common.XAPool.growUntilMinPoolSize(XAPool.java:80)

        at bitronix.tm.resource.common.XAPool.shrink(XAPool.java:261)

        at bitronix.tm.timer.PoolShrinkingTask.execute(PoolShrinkingTask.java:47)

        ... 2 more

 

 

 

 

 


Reply | Threaded
Open this post in threaded view
|

RE: RE: EXT :Re: [btm-user] PoolShrinkingTask Exception

greenbean

To provide an update…

 

We upgraded our Oracle JDBC driver to 10.2.0.5 from 10.2.0.4.  We received this error recently in a test environment.  The transaction was rolled back and replayed.  However, again Oracle did not log anything relating to this event.  It is indeed a pickle of a problem.

 

Caused by: bitronix.tm.internal.BitronixHeuristicMixedException: transaction failed during commit of a Bitronix Transaction with GTRID [737072696E672D62746D00000130FFB4219C0005FAB3], status=UNKNOWN, 2 resource(s) enlisted (started Wed Jul 06 13:47:33 GMT 2011): resource(s) [oracle] improperly unilaterally rolled back (or hazard happened)

        at bitronix.tm.twopc.Committer.throwException(Committer.java:147)

        at bitronix.tm.twopc.Committer.commit(Committer.java:86)

        at bitronix.tm.BitronixTransaction.commit(BitronixTransaction.java:239)

        at bitronix.tm.BitronixTransactionManager.commit(BitronixTransactionManager.java:120)

        at org.springframework.transaction.jta.JtaTransactionManager.doCommit(JtaTransactionManager.java:1009)

        ... 26 more

Caused by: bitronix.tm.twopc.PhaseException: collected 1 exception(s):

[oracle - bitronix.tm.internal.BitronixXAException(XA_HEURHAZ) - unknown heuristic termination, global state of this transaction is unknown - guilty: an XAResourceHolderState with uniqueName=oracle XAResource=oracle.jdbc.driver.T4CXAResource@6d498b15 (ended) with XID a Bitronix XID [737072696E672D62746D00000130FFB4219C0005FAB3 : 737072696E672D62746D00000130FFB421B90005FABC]]

        at bitronix.tm.twopc.AbstractPhaseEngine.executePhase(AbstractPhaseEngine.java:110)

        at bitronix.tm.twopc.Committer.commit(Committer.java:82)

        ... 29 more

 

 

From: [hidden email] [mailto:[hidden email]] On Behalf Of Ludovic Orban
Sent: Tuesday, June 21, 2011 1:42 PM
To: [hidden email]
Subject: Re: [btm-user] RE: EXT :Re: [btm-user] PoolShrinkingTask Exception

 

This is a tricky problem and the most likely cause is a problem in the Oracle JDBC driver but I obviously don't have any proof to back that statement: after phase 1 successfully executed, Oracle cannot give up on that transaction without reporting a heuristic to the TM which in turn would have been reported by the recoverer. One exception to this rule is if this transaction was running only against Oracle, in that case 1PC optimization kicked in and Oracle may silently rollback the changes.

If you have the transaction's GTRID you could use the GUI tool to introspect BTM's disk journal and try to figure out what happened to that transaction. I also recommend you to add %X{btm-gtrid} to your log4j ConversionPattern to have the logs always include the GTRID which makes it much easier to troubleshoot multi-transactions problems and always have a trace of which transaction caused an error.

With so little detail there's unfortunately very little more I can do to help you.

2011/6/21 Urciolo, Kevin J (IS) <[hidden email]>

Thank you for the prompt reply.  We are currently running Java 6u23 64-bit for Linux.

 

We did encounter an issue recently where an Oracle 10 resource returned the exception below.  Nothing showed up in the Oracle alert logs, or any other logs on Oracle that  the DBA could find.  I could not find a prepared transaction sitting in Oracle, nor could I find any indication that the BTM recovery thread went back and tried the commit again.  We were able to trace the transaction down to a specific row that should have been inserted in to the Oracle database.  The row does not exist.

 

I am not sure what happened at the moment.  The complexity of the events, and lack of logging in Oracle make tracking down the root cause pretty much impossible.

 

2011-06-17 09:08:39,011 WARN  [bitronix.tm.twopc.Committer] (midasReconReqProcessorThreadPoolExecutor-2) resource 'oracle' reported XAER_RMFAIL when asked

to commit transaction branch. Transaction is prepared and will commit via recovery service when resource availability allows.

oracle.jdbc.xa.OracleXAException

        at oracle.jdbc.xa.OracleXAResource.checkError(OracleXAResource.java:1126)

        at oracle.jdbc.xa.client.OracleXAResource.commit(OracleXAResource.java:585)

        at bitronix.tm.twopc.Committer$CommitJob.commitResource(Committer.java:194)

        at bitronix.tm.twopc.Committer$CommitJob.execute(Committer.java:183)

        at bitronix.tm.twopc.executor.Job.run(Job.java:70)

        at bitronix.tm.twopc.executor.SyncExecutor.submit(SyncExecutor.java:31)

        at bitronix.tm.twopc.AbstractPhaseEngine.runJobsForPosition(AbstractPhaseEngine.java:129)

        at bitronix.tm.twopc.AbstractPhaseEngine.executePhase(AbstractPhaseEngine.java:90)

        at bitronix.tm.twopc.Committer.commit(Committer.java:82)

        at bitronix.tm.BitronixTransaction.commit(BitronixTransaction.java:239)

        at bitronix.tm.BitronixTransactionManager.commit(BitronixTransactionManager.java:120)

        at org.springframework.transaction.jta.JtaTransactionManager.doCommit(JtaTransactionManager.java:1009)

 

 

From: [hidden email] [mailto:[hidden email]] On Behalf Of Ludovic Orban
Sent: Tuesday, June 21, 2011 1:10 PM
To: [hidden email]
Subject: EXT :Re: [btm-user] PoolShrinkingTask Exception

 

This looks like a memory visibility issue. Fortunately, it's rather harmless in this case: after the pool was emptied by the shrinking task, it could not be restored to the minimal pool size so further calls to PoolingDataSource will compensate for that the next time getConnection() is called.

A lot of those issues appeared recently due to the more and more aggressive optimizations added in the latest JDK 1.6's JIT. I've tracked all the ones I could find a fixed them in trunk so the next release should be much more robust in this regard.

In the meantime, you can rely on BTM's self-healing design: as long as something isn't definitely unusable, BTM will try to restore its internal state at every possible step. I suppose you didn't notice anything wrong in your app except for these stack traces or you would have complained. ;-)
 

2011/6/21 Urciolo, Kevin J (IS) <[hidden email]>

This exception below started popping up recently.  Does anyone have any ideas what could cause this problem?  Is it harmless?

 

2011-06-17 01:47:39,557 WARN  [bitronix.tm.timer.TaskScheduler] (bitronix-scheduler) error running a PoolShrinkingTask scheduled for Fri Jun 17 01:47:29 GM

T 2011 on an XAPool of resource oracle with 4 connection(s) (2 still available)

bitronix.tm.timer.TaskException: error while trying to shrink an XAPool of resource oracle with 4 connection(s) (2 still available)

        at bitronix.tm.timer.PoolShrinkingTask.execute(PoolShrinkingTask.java:49)

        at bitronix.tm.timer.TaskScheduler.executeElapsedTasks(TaskScheduler.java:217)

        at bitronix.tm.timer.TaskScheduler.run(TaskScheduler.java:193)

Caused by: java.lang.NullPointerException

        at bitronix.tm.resource.jdbc.JdbcPooledConnection.<init>(JdbcPooledConnection.java:72)

        at bitronix.tm.resource.jdbc.PoolingDataSource.createPooledConnection(PoolingDataSource.java:288)

        at bitronix.tm.resource.common.XAPool.createPooledObject(XAPool.java:291)

        at bitronix.tm.resource.common.XAPool.growUntilMinPoolSize(XAPool.java:80)

        at bitronix.tm.resource.common.XAPool.shrink(XAPool.java:261)

        at bitronix.tm.timer.PoolShrinkingTask.execute(PoolShrinkingTask.java:47)

        ... 2 more

 

 

 

 

 

 

Reply | Threaded
Open this post in threaded view
|

Re: RE: EXT :Re: [btm-user] PoolShrinkingTask Exception

Ludovic Orban-2
Since you managed to reproduce this problem in a test environment, you may be able to enable debug logs, at least a subset of them.

Having access to the debug logs of the bitronix.tm.twopc category would be very valuable but remember to configure your logger to also output the btm-gtrid MDC parameter. Here's a snippet of a log4j.xml config with the right conversion pattern and logging category:

<layout class="org.apache.log4j.PatternLayout">
        <param name="ConversionPattern" value="%d [%t] (%X{btm-gtrid}) %p - %m%n"/>
</layout>

<category name="bitronix.tm.twopc">
    <level value="DEBUG"/>
    <appender-ref ref="file"/>
</category>


The only thing I suspect at the moment is that this particular transaction is running against your Oracle DB only and makes the 1PC optimization kick in. In this case, a transaction timeout can occur and Oracle could decide to rollback the transaction unilaterally without leaving a trace in its logs. BTM can't reliably detect this particular case and may report the error you're seeing instead of a simple RollbackException.

If you still have the two transaction log fragments (the *.tlog files) they may still contain enough information to understand the root cause of this problem so I would be glad if you could post them somewhere so I could analyze them.


2011/7/6 Urciolo, Kevin J (IS) <[hidden email]>

To provide an update…

 

We upgraded our Oracle JDBC driver to 10.2.0.5 from 10.2.0.4.  We received this error recently in a test environment.  The transaction was rolled back and replayed.  However, again Oracle did not log anything relating to this event.  It is indeed a pickle of a problem.

 

Caused by: bitronix.tm.internal.BitronixHeuristicMixedException: transaction failed during commit of a Bitronix Transaction with GTRID [737072696E672D62746D00000130FFB4219C0005FAB3], status=UNKNOWN, 2 resource(s) enlisted (started Wed Jul 06 13:47:33 GMT 2011): resource(s) [oracle] improperly unilaterally rolled back (or hazard happened)

        at bitronix.tm.twopc.Committer.throwException(Committer.java:147)

        at bitronix.tm.twopc.Committer.commit(Committer.java:86)

        at bitronix.tm.BitronixTransaction.commit(BitronixTransaction.java:239)

        at bitronix.tm.BitronixTransactionManager.commit(BitronixTransactionManager.java:120)

        at org.springframework.transaction.jta.JtaTransactionManager.doCommit(JtaTransactionManager.java:1009)

        ... 26 more

Caused by: bitronix.tm.twopc.PhaseException: collected 1 exception(s):

[oracle - bitronix.tm.internal.BitronixXAException(XA_HEURHAZ) - unknown heuristic termination, global state of this transaction is unknown - guilty: an XAResourceHolderState with uniqueName=oracle XAResource=oracle.jdbc.driver.T4CXAResource@6d498b15 (ended) with XID a Bitronix XID [737072696E672D62746D00000130FFB4219C0005FAB3 : 737072696E672D62746D00000130FFB421B90005FABC]]

        at bitronix.tm.twopc.AbstractPhaseEngine.executePhase(AbstractPhaseEngine.java:110)

        at bitronix.tm.twopc.Committer.commit(Committer.java:82)

        ... 29 more

 

 

From: [hidden email] [mailto:[hidden email]] On Behalf Of Ludovic Orban
Sent: Tuesday, June 21, 2011 1:42 PM
To: [hidden email]
Subject: Re: [btm-user] RE: EXT :Re: [btm-user] PoolShrinkingTask Exception

 

This is a tricky problem and the most likely cause is a problem in the Oracle JDBC driver but I obviously don't have any proof to back that statement: after phase 1 successfully executed, Oracle cannot give up on that transaction without reporting a heuristic to the TM which in turn would have been reported by the recoverer. One exception to this rule is if this transaction was running only against Oracle, in that case 1PC optimization kicked in and Oracle may silently rollback the changes.

If you have the transaction's GTRID you could use the GUI tool to introspect BTM's disk journal and try to figure out what happened to that transaction. I also recommend you to add %X{btm-gtrid} to your log4j ConversionPattern to have the logs always include the GTRID which makes it much easier to troubleshoot multi-transactions problems and always have a trace of which transaction caused an error.

With so little detail there's unfortunately very little more I can do to help you.

2011/6/21 Urciolo, Kevin J (IS) <[hidden email]>

Thank you for the prompt reply.  We are currently running Java 6u23 64-bit for Linux.

 

We did encounter an issue recently where an Oracle 10 resource returned the exception below.  Nothing showed up in the Oracle alert logs, or any other logs on Oracle that  the DBA could find.  I could not find a prepared transaction sitting in Oracle, nor could I find any indication that the BTM recovery thread went back and tried the commit again.  We were able to trace the transaction down to a specific row that should have been inserted in to the Oracle database.  The row does not exist.

 

I am not sure what happened at the moment.  The complexity of the events, and lack of logging in Oracle make tracking down the root cause pretty much impossible.

 

2011-06-17 09:08:39,011 WARN  [bitronix.tm.twopc.Committer] (midasReconReqProcessorThreadPoolExecutor-2) resource 'oracle' reported XAER_RMFAIL when asked

to commit transaction branch. Transaction is prepared and will commit via recovery service when resource availability allows.

oracle.jdbc.xa.OracleXAException

        at oracle.jdbc.xa.OracleXAResource.checkError(OracleXAResource.java:1126)

        at oracle.jdbc.xa.client.OracleXAResource.commit(OracleXAResource.java:585)

        at bitronix.tm.twopc.Committer$CommitJob.commitResource(Committer.java:194)

        at bitronix.tm.twopc.Committer$CommitJob.execute(Committer.java:183)

        at bitronix.tm.twopc.executor.Job.run(Job.java:70)

        at bitronix.tm.twopc.executor.SyncExecutor.submit(SyncExecutor.java:31)

        at bitronix.tm.twopc.AbstractPhaseEngine.runJobsForPosition(AbstractPhaseEngine.java:129)

        at bitronix.tm.twopc.AbstractPhaseEngine.executePhase(AbstractPhaseEngine.java:90)

        at bitronix.tm.twopc.Committer.commit(Committer.java:82)

        at bitronix.tm.BitronixTransaction.commit(BitronixTransaction.java:239)

        at bitronix.tm.BitronixTransactionManager.commit(BitronixTransactionManager.java:120)

        at org.springframework.transaction.jta.JtaTransactionManager.doCommit(JtaTransactionManager.java:1009)

 

 

From: [hidden email] [mailto:[hidden email]] On Behalf Of Ludovic Orban
Sent: Tuesday, June 21, 2011 1:10 PM
To: [hidden email]
Subject: EXT :Re: [btm-user] PoolShrinkingTask Exception

 

This looks like a memory visibility issue. Fortunately, it's rather harmless in this case: after the pool was emptied by the shrinking task, it could not be restored to the minimal pool size so further calls to PoolingDataSource will compensate for that the next time getConnection() is called.

A lot of those issues appeared recently due to the more and more aggressive optimizations added in the latest JDK 1.6's JIT. I've tracked all the ones I could find a fixed them in trunk so the next release should be much more robust in this regard.

In the meantime, you can rely on BTM's self-healing design: as long as something isn't definitely unusable, BTM will try to restore its internal state at every possible step. I suppose you didn't notice anything wrong in your app except for these stack traces or you would have complained. ;-)
 

2011/6/21 Urciolo, Kevin J (IS) <[hidden email]>

This exception below started popping up recently.  Does anyone have any ideas what could cause this problem?  Is it harmless?

 

2011-06-17 01:47:39,557 WARN  [bitronix.tm.timer.TaskScheduler] (bitronix-scheduler) error running a PoolShrinkingTask scheduled for Fri Jun 17 01:47:29 GM

T 2011 on an XAPool of resource oracle with 4 connection(s) (2 still available)

bitronix.tm.timer.TaskException: error while trying to shrink an XAPool of resource oracle with 4 connection(s) (2 still available)

        at bitronix.tm.timer.PoolShrinkingTask.execute(PoolShrinkingTask.java:49)

        at bitronix.tm.timer.TaskScheduler.executeElapsedTasks(TaskScheduler.java:217)

        at bitronix.tm.timer.TaskScheduler.run(TaskScheduler.java:193)

Caused by: java.lang.NullPointerException

        at bitronix.tm.resource.jdbc.JdbcPooledConnection.<init>(JdbcPooledConnection.java:72)

        at bitronix.tm.resource.jdbc.PoolingDataSource.createPooledConnection(PoolingDataSource.java:288)

        at bitronix.tm.resource.common.XAPool.createPooledObject(XAPool.java:291)

        at bitronix.tm.resource.common.XAPool.growUntilMinPoolSize(XAPool.java:80)

        at bitronix.tm.resource.common.XAPool.shrink(XAPool.java:261)

        at bitronix.tm.timer.PoolShrinkingTask.execute(PoolShrinkingTask.java:47)

        ... 2 more