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

95 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.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ではないトランザクションで発生していたため、こちらに投稿しました。)

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


以上、よろしくお願いいたします。

Reply all
Reply to author
Forward
0 new messages