jBatchにてjava.sql.SQLTransactionRollbackExceptionが発生する。

126 views

Skip to first unread message

Kenji Shimizu

unread,

Dec 5, 2016, 7:38:09 AM12/5/16

to glassfish

お世話になります。

清水と申します。

jBatch(Batchlet)につきまして、Exceptionが発生しており、

解決策が見つからないため、投稿させていただきました。

【環境】

CentOS : CentOS Linux release 7.1.1503 (Core)

Java : java version "1.8.0_77"

Glassfish : GlassFish Server Open Source Edition 4.1.1 (build 1)

DB : PostgreSQL 9.5

【実行状況】

・起動は、WebserviceでHTTPリクエストを受けて起動する。

・Batchlet内で、2つのトランザクション処理を行っている。

・トランザクション管理はコンテナ管理としており、

　@Transactional(Transactional.TxType.REQUIRES_NEW)

　を付与したメソッドにて、トランザクションを開始している。

・1つのトランザクション処理(tran A)内で、もう一つのトランザクション処理(tran B)が呼び出されている。

・tran Bの結果により、tran AでUPDATE/COMMITが発生する場合と、発生しない場合がある。

【事象】

・tran AでUPDATE/COMMITが発生すると問題が発生しないが、

　tran AでUPDATE/COMMITが発生しない場合、次の例外が発生する。

[2016-12-05T21:11:28.118+0900] [glassfish 4.1] [INFO] [] [] [tid: _ThreadID=35 _ThreadName=Thread-8] [timeMillis: 1480939888118] [levelValue: 800] [[

[231629], [http-listener-1(5)], ERROR, ZzzTest#batchStart error.

com.ibm.jbatch.container.exception.PersistenceException: java.sql.SQLTransactionRollbackException: 要求時間内にロックを獲得できませんでした

at com.ibm.jbatch.container.services.impl.JDBCPersistenceManagerImpl.jobOperatorQueryJobExecutionBatchStatus(JDBCPersistenceManagerImpl.java:847)

at com.ibm.jbatch.container.jobinstance.JobOperatorJobExecution.getCurrentBatchStatus(JobOperatorJobExecution.java:102)

at com.ibm.jbatch.container.jobinstance.JobOperatorJobExecution.getBatchStatus(JobOperatorJobExecution.java:81)

at batchtest.rest.ZzzTest.batchStart(ZzzTest.java:41)

at batchtest.rest.ZzzTest$Proxy$_$$_WeldSubclass.batchStart$$super(Unknown Source)

at sun.reflect.NativeMethodAccessorImpl.invoke0(Native Method)

at sun.reflect.NativeMethodAccessorImpl.invoke(NativeMethodAccessorImpl.java:62)

at sun.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:43)

at java.lang.reflect.Method.invoke(Method.java:498)

at org.jboss.weld.interceptor.proxy.TerminalAroundInvokeInvocationContext.proceedInternal(TerminalAroundInvokeInvocationContext.java:49)

at org.jboss.weld.interceptor.proxy.AroundInvokeInvocationContext.proceed(AroundInvokeInvocationContext.java:77)

at batchtest.common.interceptor.LoggedInterceptor.logMethodEntry(LoggedInterceptor.java:40)

at sun.reflect.NativeMethodAccessorImpl.invoke0(Native Method)

at sun.reflect.NativeMethodAccessorImpl.invoke(NativeMethodAccessorImpl.java:62)

at sun.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:43)

at java.lang.reflect.Method.invoke(Method.java:498)

at org.jboss.weld.interceptor.reader.SimpleInterceptorInvocation$SimpleMethodInvocation.invoke(SimpleInterceptorInvocation.java:74)

at org.jboss.weld.interceptor.proxy.InterceptorMethodHandler.executeAroundInvoke(InterceptorMethodHandler.java:84)

at org.jboss.weld.interceptor.proxy.InterceptorMethodHandler.executeInterception(InterceptorMethodHandler.java:72)

at org.jboss.weld.interceptor.proxy.InterceptorMethodHandler.invoke(InterceptorMethodHandler.java:56)

at org.jboss.weld.bean.proxy.CombinedInterceptorAndDecoratorStackMethodHandler.invoke(CombinedInterceptorAndDecoratorStackMethodHandler.java:79)

at org.jboss.weld.bean.proxy.CombinedInterceptorAndDecoratorStackMethodHandler.invoke(CombinedInterceptorAndDecoratorStackMethodHandler.java:68)

at batchtest.rest.ZzzTest$Proxy$_$$_WeldSubclass.batchStart(Unknown Source)

at batchtest.rest.ZzzTest$Proxy$_$$_WeldClientProxy.batchStart(Unknown Source)

at sun.reflect.NativeMethodAccessorImpl.invoke0(Native Method)

at sun.reflect.NativeMethodAccessorImpl.invoke(NativeMethodAccessorImpl.java:62)

at sun.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:43)

at java.lang.reflect.Method.invoke(Method.java:498)

at org.glassfish.jersey.server.model.internal.ResourceMethodInvocationHandlerFactory$1.invoke(ResourceMethodInvocationHandlerFactory.java:81)

at org.glassfish.jersey.server.model.internal.AbstractJavaResourceMethodDispatcher$1.run(AbstractJavaResourceMethodDispatcher.java:144)

at org.glassfish.jersey.server.model.internal.AbstractJavaResourceMethodDispatcher.invoke(AbstractJavaResourceMethodDispatcher.java:161)

at org.glassfish.jersey.server.model.internal.JavaResourceMethodDispatcherProvider$ResponseOutInvoker.doDispatch(JavaResourceMethodDispatcherProvider.java:160)

at org.glassfish.jersey.server.model.internal.AbstractJavaResourceMethodDispatcher.dispatch(AbstractJavaResourceMethodDispatcher.java:99)

at org.glassfish.jersey.server.model.ResourceMethodInvoker.invoke(ResourceMethodInvoker.java:389)

at org.glassfish.jersey.server.model.ResourceMethodInvoker.apply(ResourceMethodInvoker.java:347)

at org.glassfish.jersey.server.model.ResourceMethodInvoker.apply(ResourceMethodInvoker.java:102)

at org.glassfish.jersey.server.ServerRuntime$2.run(ServerRuntime.java:309)

at org.glassfish.jersey.internal.Errors$1.call(Errors.java:271)

at org.glassfish.jersey.internal.Errors$1.call(Errors.java:267)

at org.glassfish.jersey.internal.Errors.process(Errors.java:315)

at org.glassfish.jersey.internal.Errors.process(Errors.java:297)

at org.glassfish.jersey.internal.Errors.process(Errors.java:267)

at org.glassfish.jersey.process.internal.RequestScope.runInScope(RequestScope.java:317)

at org.glassfish.jersey.server.ServerRuntime.process(ServerRuntime.java:292)

at org.glassfish.jersey.server.ApplicationHandler.handle(ApplicationHandler.java:1139)

at org.glassfish.jersey.servlet.WebComponent.service(WebComponent.java:460)

at org.glassfish.jersey.servlet.ServletContainer.service(ServletContainer.java:386)

at org.glassfish.jersey.servlet.ServletContainer.service(ServletContainer.java:334)

at org.glassfish.jersey.servlet.ServletContainer.service(ServletContainer.java:221)

at org.apache.catalina.core.StandardWrapper.service(StandardWrapper.java:1682)

at org.apache.catalina.core.ApplicationFilterChain.internalDoFilter(ApplicationFilterChain.java:344)

at org.apache.catalina.core.ApplicationFilterChain.doFilter(ApplicationFilterChain.java:214)

at org.apache.logging.log4j.web.Log4jServletFilter.doFilter(Log4jServletFilter.java:71)

at org.apache.catalina.core.ApplicationFilterChain.internalDoFilter(ApplicationFilterChain.java:256)

at org.apache.catalina.core.ApplicationFilterChain.doFilter(ApplicationFilterChain.java:214)

at org.apache.catalina.core.StandardWrapperValve.invoke(StandardWrapperValve.java:316)

at org.apache.catalina.core.StandardContextValve.invoke(StandardContextValve.java:160)

at org.apache.catalina.core.StandardPipeline.doInvoke(StandardPipeline.java:734)

at org.apache.catalina.core.StandardPipeline.invoke(StandardPipeline.java:673)

at com.sun.enterprise.web.WebPipeline.invoke(WebPipeline.java:99)

at org.apache.catalina.core.StandardHostValve.invoke(StandardHostValve.java:174)

at org.apache.catalina.connector.CoyoteAdapter.doService(CoyoteAdapter.java:416)

at org.apache.catalina.connector.CoyoteAdapter.service(CoyoteAdapter.java:283)

at com.sun.enterprise.v3.services.impl.ContainerMapper$HttpHandlerCallable.call(ContainerMapper.java:459)

at com.sun.enterprise.v3.services.impl.ContainerMapper.service(ContainerMapper.java:167)

at org.glassfish.grizzly.http.server.HttpHandler.runService(HttpHandler.java:206)

at org.glassfish.grizzly.http.server.HttpHandler.doHandle(HttpHandler.java:180)

at org.glassfish.grizzly.http.server.HttpServerFilter.handleRead(HttpServerFilter.java:235)

at org.glassfish.grizzly.filterchain.ExecutorResolver$9.execute(ExecutorResolver.java:119)

at org.glassfish.grizzly.filterchain.DefaultFilterChain.executeFilter(DefaultFilterChain.java:283)

at org.glassfish.grizzly.filterchain.DefaultFilterChain.executeChainPart(DefaultFilterChain.java:200)

at org.glassfish.grizzly.filterchain.DefaultFilterChain.execute(DefaultFilterChain.java:132)

at org.glassfish.grizzly.filterchain.DefaultFilterChain.process(DefaultFilterChain.java:111)

at org.glassfish.grizzly.ProcessorExecutor.execute(ProcessorExecutor.java:77)

at org.glassfish.grizzly.nio.transport.TCPNIOTransport.fireIOEvent(TCPNIOTransport.java:536)

at org.glassfish.grizzly.strategies.AbstractIOStrategy.fireIOEvent(AbstractIOStrategy.java:112)

at org.glassfish.grizzly.strategies.WorkerThreadIOStrategy.run0(WorkerThreadIOStrategy.java:117)

at org.glassfish.grizzly.strategies.WorkerThreadIOStrategy.access$100(WorkerThreadIOStrategy.java:56)

at org.glassfish.grizzly.strategies.WorkerThreadIOStrategy$WorkerThreadRunnable.run(WorkerThreadIOStrategy.java:137)

at org.glassfish.grizzly.threadpool.AbstractThreadPool$Worker.doWork(AbstractThreadPool.java:591)

at org.glassfish.grizzly.threadpool.AbstractThreadPool$Worker.run(AbstractThreadPool.java:571)

at java.lang.Thread.run(Thread.java:745)

Caused by: java.sql.SQLTransactionRollbackException: 要求時間内にロックを獲得できませんでした

at org.apache.derby.impl.jdbc.SQLExceptionFactory40.getSQLException(Unknown Source)

at org.apache.derby.impl.jdbc.Util.generateCsSQLException(Unknown Source)

at org.apache.derby.impl.jdbc.TransactionResourceImpl.wrapInSQLException(Unknown Source)

at org.apache.derby.impl.jdbc.TransactionResourceImpl.handleException(Unknown Source)

at org.apache.derby.impl.jdbc.EmbedConnection.handleException(Unknown Source)

at org.apache.derby.impl.jdbc.ConnectionChild.handleException(Unknown Source)

at org.apache.derby.impl.jdbc.EmbedResultSet.closeOnTransactionError(Unknown Source)

at org.apache.derby.impl.jdbc.EmbedResultSet.movePosition(Unknown Source)

at org.apache.derby.impl.jdbc.EmbedResultSet.next(Unknown Source)

at com.sun.gjc.spi.base.ResultSetWrapper.next(ResultSetWrapper.java:103)

at com.ibm.jbatch.container.services.impl.JDBCPersistenceManagerImpl.jobOperatorQueryJobExecutionBatchStatus(JDBCPersistenceManagerImpl.java:843)

... 81 more

Caused by: java.sql.SQLException: 要求時間内にロックを獲得できませんでした

at org.apache.derby.impl.jdbc.SQLExceptionFactory.getSQLException(Unknown Source)

at org.apache.derby.impl.jdbc.SQLExceptionFactory40.wrapArgsForTransportAcrossDRDA(Unknown Source)

... 92 more

Caused by: ERROR 40XL1: 要求時間内にロックを獲得できませんでした

at org.apache.derby.iapi.error.StandardException.newException(Unknown Source)

at org.apache.derby.impl.services.locks.ConcurrentLockSet.lockObject(Unknown Source)

at org.apache.derby.impl.services.locks.AbstractPool.lockObject(Unknown Source)

at org.apache.derby.impl.services.locks.ConcurrentPool.lockObject(Unknown Source)

at org.apache.derby.impl.store.raw.xact.RowLocking2.lockRecordForRead(Unknown Source)

at org.apache.derby.impl.store.access.heap.HeapController.lockRow(Unknown Source)

at org.apache.derby.impl.store.access.btree.index.B2IRowLocking3.lockRowOnPage(Unknown Source)

at org.apache.derby.impl.store.access.btree.index.B2IRowLocking3._lockScanRow(Unknown Source)

at org.apache.derby.impl.store.access.btree.index.B2IRowLockingRR.lockScanRow(Unknown Source)

at org.apache.derby.impl.store.access.btree.BTreeForwardScan.fetchRows(Unknown Source)

at org.apache.derby.impl.store.access.btree.BTreeScan.fetchNext(Unknown Source)

at org.apache.derby.impl.sql.execute.TableScanResultSet.getNextRowCore(Unknown Source)

at org.apache.derby.impl.sql.execute.IndexRowToBaseRowResultSet.getNextRowCore(Unknown Source)

at org.apache.derby.impl.sql.execute.ProjectRestrictResultSet.getNextRowCore(Unknown Source)

at org.apache.derby.impl.sql.execute.BasicNoPutResultSetImpl.getNextRow(Unknown Source)

... 85 more]]

上記の例外が発生した場合、リソースのモニタリングを行ったところ、

「jdbc/__TimerPool」の「NumConnUsed」が増えていき、「NumConnFree」が0となったところで、

バッチの起動に失敗します。

（ユーザアプリで利用しているPostgreSQLではないトランザクションで発生していたため、こちらに投稿しました。）

＃もし、投稿先が違うようでしたら、ポスト先をお教えいただければと思います。