Atomikos Forum |
|
We are using Atomikos 3.6.5 + Hibernate 3.3.2+ JBoss cache2 in our product. I found this strange error message from "tm.out":
"com.atomikos.icatch.SysException: Error in prepare: null" The error message in "tm.out" didn't anything what might cause the error. This problem didn't always happen. Other transactions seems fine, only this transaction sometime failed. The problem happened with both MySql and Oracle. So it seems not a database specific problem. Here is the snapshot of "tm.out": 10-08-23 22:00:00,927 [pool-4-thread-21-ff8080812aa1fe85012aa2002b5c0011] atomikos connection proxy for com.mysql.jdbc.jdbc2.optional.JDBC4ConnectionWrapper@292cb2: calling prepareStatement... 10-08-23 22:00:00,927 [pool-4-thread-21-ff8080812aa1fe85012aa2002b5c0011] atomikos connection proxy for com.mysql.jdbc.jdbc2.optional.JDBC4ConnectionWrapper@292cb2: prepareStatement returning com.mysql.jdbc.jdbc2.optional.JDBC4PreparedStatementWrapper@f74f5f 10-08-23 22:00:00,928 [pool-4-thread-21-ff8080812aa1fe85012aa2002b5c0011] getCompositeTransaction() returning instance with id 127.0.0.1.tm0282900122 10-08-23 22:00:00,928 [pool-4-thread-21-ff8080812aa1fe85012aa2002b5c0011] getCompositeTransaction() returning instance with id 127.0.0.1.tm0282900122 10-08-23 22:00:00,928 [pool-4-thread-21-ff8080812aa1fe85012aa2002b5c0011] getCompositeTransaction() returning instance with id 127.0.0.1.tm0282900122 10-08-23 22:00:00,928 [pool-4-thread-21-ff8080812aa1fe85012aa2002b5c0011] getCompositeTransaction() returning instance with id 127.0.0.1.tm0282900122 10-08-23 22:00:00,928 [pool-4-thread-21-ff8080812aa1fe85012aa2002b5c0011] getCompositeTransaction() returning instance with id 127.0.0.1.tm0282900122 10-08-23 22:00:00,928 [pool-4-thread-21-ff8080812aa1fe85012aa2002b5c0011] getCompositeTransaction() returning instance with id 127.0.0.1.tm0282900122 10-08-23 22:00:00,928 [pool-4-thread-21-ff8080812aa1fe85012aa2002b5c0011] getCompositeTransaction() returning instance with id 127.0.0.1.tm0282900122 10-08-23 22:00:00,929 [pool-4-thread-21-ff8080812aa1fe85012aa2002b5c0011] commit() done (by application) of transaction 127.0.0.1.tm0282900122 10-08-23 22:00:00,929 [pool-4-thread-21-ff8080812aa1fe85012aa2002b5c0011] Coordinator 127.0.0.1.tm0282900122 entering state: PREPARING 10-08-23 22:00:00,929 [pool-4-thread-21-ff8080812aa1fe85012aa2002b5c0011] Coordinator 127.0.0.1.tm0282900122 entered state: PREPARING 10-08-23 22:00:00,929 [pool-4-thread-21-ff8080812aa1fe85012aa2002b5c0011] (1.5) executing task: com.atomikos.icatch.imp.Propagator$PropagatorThread@58fe78 10-08-23 22:00:00,929 [pool-4-thread-21-ff8080812aa1fe85012aa2002b5c0011] ThreadFactory: creating new thread: Atomikos:33 10-08-23 22:00:00,929 [pool-4-thread-21-ff8080812aa1fe85012aa2002b5c0011] (1.5) executing task: com.atomikos.icatch.imp.Propagator$PropagatorThread@15804cd 10-08-23 22:00:00,929 [pool-4-thread-21-ff8080812aa1fe85012aa2002b5c0011] ThreadFactory: creating new thread: Atomikos:34 10-08-23 22:00:00,930 [pool-4-thread-21-ff8080812aa1fe85012aa2002b5c0011] Error in prepare: null com.atomikos.icatch.SysException: Error in prepare: null at com.atomikos.icatch.imp.ActiveStateHandler.prepare(ActiveStateHandler.java:287) at com.atomikos.icatch.imp.CoordinatorImp.prepare(CoordinatorImp.java:803) at com.atomikos.icatch.imp.CoordinatorImp.terminate(CoordinatorImp.java:1124) at com.atomikos.icatch.imp.CompositeTerminatorImp.commit(CompositeTerminatorImp.java:151) at com.atomikos.icatch.jta.TransactionImp.commit(TransactionImp.java:298) at com.atomikos.icatch.jta.TransactionManagerImp.commit(TransactionManagerImp.java:612) at com.atomikos.icatch.jta.UserTransactionImp.commit(UserTransactionImp.java:168) at com.resolve.persistence.util.HibernateUtil.commitTransaction(HibernateUtil.java:480) at com.resolve.rscontrol.ProcessExecution.abortProcess(ProcessExecution.java:549) at com.resolve.rscontrol.MAction.abortProcess(MAction.java:364) at sun.reflect.NativeMethodAccessorImpl.invoke0(Native Method) at sun.reflect.NativeMethodAccessorImpl.invoke(NativeMethodAccessorImpl.java:39) at sun.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:25) at java.lang.reflect.Method.invoke(Method.java:597) at com.resolve.thread.ExecutorTask.execute(ExecutorTask.java:285) at com.resolve.thread.ExecutorTask.call(ExecutorTask.java:127) at java.util.concurrent.FutureTask$Sync.innerRun(FutureTask.java:303) at java.util.concurrent.FutureTask.run(FutureTask.java:138) 10-08-23 22:00:00,934 [Atomikos:34] XAResource.end ( 3132372E302E302E312E746D30323832393030313232:3132372E302E302E312E746D32343539 , XAResource.TMSUCCESS ) on resource F2D11751C0ED4A80734787689719BA80 represented by XAResource instance com.mysql.jdbc.jdbc2.optional.JDBC4SuspendableXAConnection@1712a80 10-08-23 22:00:00,938 [pool-4-thread-21-ff8080812aa1fe85012aa2002b5c0011] getCompositeTransaction() returning NULL! 10-08-23 22:00:00,938 [pool-4-thread-21-ff8080812aa1fe85012aa2002b5c0011] getCompositeTransaction() returning NULL! Just wondering if anybody knows anything about this strange error?Any help is greatly appreciated! Yu
Our product is a runbook automation system:http://resolve-systems.com/index.html. Multiple members are running in a cluster which all access a backend database for storage. Atomikos is used as a JTA manager to manage transactions at each cluster member, and also coordinate distributed cache managed by JBoss.
Atomikos works fine when workload is light. But under stress tests, where lots of tasks are running in parallel and database is heavilly contented, we started to see this error manage after running about 10-15 minutes. Then more and more transactions failed with this error message which we don't have a clue at all. No other exceptions were found in our system. Here is "jta.properities" file: com.atomikos.icatch.service=com.atomikos.icatch.standalone.UserTransactionServiceFactory com.atomikos.icatch.automatic_resource_registration=true com.atomikos.icatch.console_log_level=DEBUG com.atomikos.icatch.serial_jta_transactions=true com.atomikos.icatch.enable_logging=true com.atomikos.icatch.max_timeout=180000 com.atomikos.icatch.default_jta_timeout=180000 com.atomikos.icatch.log_base_dir=/opt/resolve/rscontrol/log com.atomikos.icatch.output_dir=/opt/resolve/rscontrol/log Any hint for debugging this error? Thanks, Yu
We found the cause of the problem. It was a bug in our code. It seems Atomikos transaction manager tried to start a new thread when started 2PC commit procedure. But the original pool thread sometimes might be interrupted (canceled) because of race conditions in our code. So basically commit process was interrupted by thread death in our code. Atomikos code actually caught InterruptedException when this happened, but failed to print out meaningful error message to log.
|