ロック試行がタイムアウト


簡単なトランザクションができたところで、この前jfluteさんが言っていた
更新系の処理の後の検索をやるようなテストケースを試してみたところ、
見事同じエラーが出た。

調査は後ほど暇を見つけて。
やっと2日前のjfluteさんに追いついた感じ^^;


ログ

10:52:37 [http-8080-1] INFO  atomikos - createCompositeTransaction ( 300000 ): created new ROOT transaction with id 192.168.0.3.tm0000100005
10:52:37 [http-8080-1] INFO  atomikos - getCompositeTransaction()  returning instance with id 192.168.0.3.tm0000100005
10:52:37 [http-8080-1] INFO  atomikos - getCompositeTransaction()  returning instance with id 192.168.0.3.tm0000100005
10:52:37 [http-8080-1] INFO  atomikos - getCompositeTransaction()  returning instance with id 192.168.0.3.tm0000100005
10:52:37 [http-8080-1] INFO  atomikos - addParticipant ( 192.168.0.3.tm0000100005192.168.0.3.tm1 ) for transaction 192.168.0.3.tm0000100005
10:52:37 [http-8080-1] INFO  atomikos - XAResource.start ( 192.168.0.3.tm0000100005192.168.0.3.tm1 , XAResource.TMNOFLAGS ) called on resource jdbc/h2/xaDatasource represented by XAResource instance xads1: url=jdbc:h2:tcp://127.0.0.1:9095/t2db user=sa
10:52:37 [http-8080-1] INFO  atomikos - getCompositeTransaction()  returning instance with id 192.168.0.3.tm0000100005
10:52:37 [http-8080-1] INFO  atomikos - XAResource.end ( 192.168.0.3.tm0000100005192.168.0.3.tm1 , XAResource.TMSUCCESS ) called on resource jdbc/h2/xaDatasource represented by XAResource instance xads1: url=jdbc:h2:tcp://127.0.0.1:9095/t2db user=sa
10:52:37 [http-8080-1] INFO  atomikos - getCompositeTransaction()  returning instance with id 192.168.0.3.tm0000100005
10:52:37 [http-8080-1] INFO  atomikos - getCompositeTransaction()  returning instance with id 192.168.0.3.tm0000100005
10:52:37 [http-8080-1] INFO  atomikos - getCompositeTransaction()  returning instance with id 192.168.0.3.tm0000100005
10:52:37 [http-8080-1] INFO  atomikos - addParticipant ( 192.168.0.3.tm0000100005192.168.0.3.tm1 ) for transaction 192.168.0.3.tm0000100005
10:52:37 [http-8080-1] INFO  atomikos - XAResource.start ( 192.168.0.3.tm0000100005192.168.0.3.tm1 , XAResource.TMJOIN ) called on resource jdbc/h2/xaDatasource represented by XAResource instance xads2: url=jdbc:h2:tcp://127.0.0.1:9095/t2db user=sa
10:52:38 [http-8080-1] INFO  atomikos - getCompositeTransaction()  returning instance with id 192.168.0.3.tm0000100005
10:52:38 [http-8080-1] INFO  atomikos - XAResource.end ( 192.168.0.3.tm0000100005192.168.0.3.tm1 , XAResource.TMSUCCESS ) called on resource jdbc/h2/xaDatasource represented by XAResource instance xads2: url=jdbc:h2:tcp://127.0.0.1:9095/t2db user=sa
10:52:38 [http-8080-1] INFO  atomikos - getCompositeTransaction()  returning instance with id 192.168.0.3.tm0000100005
10:52:38 [http-8080-1] INFO  atomikos - getCompositeTransaction()  returning instance with id 192.168.0.3.tm0000100005
10:52:38 [http-8080-1] INFO  atomikos - getCompositeTransaction()  returning instance with id 192.168.0.3.tm0000100005
10:52:38 [http-8080-1] INFO  atomikos - setRollbackOnly() called for transaction 192.168.0.3.tm0000100005
10:52:38 [http-8080-1] INFO  atomikos - getCompositeTransaction()  returning instance with id 192.168.0.3.tm0000100005
10:52:38 [http-8080-1] INFO  atomikos - getCompositeTransaction()  returning instance with id 192.168.0.3.tm0000100005
10:52:38 [http-8080-1] INFO  atomikos - getCompositeTransaction()  returning instance with id 192.168.0.3.tm0000100005
10:52:38 [http-8080-1] INFO  atomikos - getCompositeTransaction()  returning instance with id 192.168.0.3.tm0000100005
10:52:39 [Atomikos:2] INFO  atomikos - XAResource.rollback ( 192.168.0.3.tm0000100005192.168.0.3.tm1 ) called on resource jdbc/h2/xaDatasource represented by XAResource instance xads2: url=jdbc:h2:tcp://127.0.0.1:9095/t2db user=sa
10:52:39 [http-8080-1] INFO  atomikos - rollback() done of transaction 192.168.0.3.tm0000100005
10:52:39 [http-8080-1] ERROR o.t.t.h.i.GlobalExceptionHandlerImpl - Look! Read the message below.
/* * * * * * * * * * * * * * * * * * * * * * * * * * * * * * * * * *
The SQL failed to execute!

[Advice]
Please confirm the SQLException message.

[SQLState]
HYT00

[ErrorCode]
50200

[SQLException]
org.h2.jdbc.JdbcSQLException
テーブル EMPLOYEE のロック試行がタイムアウトしました
Timeout trying to lock table EMPLOYEE [50200-69]

[Behavior]
EmployeePage.update() --> EmployeeServiceImpl.update() --> EmployeeBhv.selectList()...

[ConditionBean]
org.t2framework.samples.todo.dbflute.cbean.EmployeeCB

[Statement]
org.h2.jdbc.JdbcPreparedStatement

[Display SQL]
select dflocal.SAL as SAL, dflocal.VERSIONNO as VERSIONNO, dflocal.DEPTNO as DEPTNO, dflocal.MGR as MGR, dflocal.JOB as JOB, dflocal.ENAME as ENAME, dflocal.HIREDATE as HIREDATE, dflocal.EMPNO as EMPNO, dflocal.COMM as COMM 
  from EMPLOYEE dflocal  
 order by dflocal.EMPNO asc
* * * * * * * * * */
2009/01/20 10:52:39 org.apache.catalina.core.StandardWrapperValve invoke
致命的: サーブレット default のServlet.service()が例外を投げました
org.h2.jdbc.JdbcSQLException: テーブル EMPLOYEE のロック試行がタイムアウトしました
Timeout trying to lock table EMPLOYEE [50200-69]
	at org.h2.message.Message.getSQLException(Message.java:91)
	at org.h2.message.Message.getSQLException(Message.java:95)
	at org.h2.message.Message.getSQLException(Message.java:73)
	at org.h2.table.TableData.lock(TableData.java:377)
	at org.h2.table.TableFilter.lock(TableFilter.java:84)
	at org.h2.command.dml.Select.queryWithoutCache(Select.java:525)
	at org.h2.command.dml.Query.query(Query.java:231)
	at org.h2.command.CommandContainer.query(CommandContainer.java:78)
	at org.h2.command.Command.executeQueryLocal(Command.java:139)
	at org.h2.server.TcpServerThread.process(TcpServerThread.java:228)
	at org.h2.server.TcpServerThread.run(TcpServerThread.java:104)
	at java.lang.Thread.run(Thread.java:619)

	at org.h2.engine.SessionRemote.done(SessionRemote.java:319)
	at org.h2.command.CommandRemote.executeQuery(CommandRemote.java:137)
	at org.h2.jdbc.JdbcPreparedStatement.executeQuery(JdbcPreparedStatement.java:91)
	at org.seasar.dbflute.s2dao.sqlhandler.TnBasicSelectHandler.createResultSet(TnBasicSelectHandler.java:83)
	at org.seasar.dbflute.s2dao.sqlhandler.TnBasicSelectHandler.execute(TnBasicSelectHandler.java:75)
	at org.seasar.dbflute.s2dao.sqlhandler.TnBasicSelectHandler.execute(TnBasicSelectHandler.java:60)
	at org.seasar.dbflute.s2dao.sqlhandler.TnBasicSelectHandler.execute(TnBasicSelectHandler.java:48)
	at org.seasar.dbflute.bhv.core.execution.SelectCBExecution.execute(SelectCBExecution.java:59)
	at org.seasar.dbflute.bhv.core.BehaviorCommandInvoker.executeSql(BehaviorCommandInvoker.java:236)
	at org.seasar.dbflute.bhv.core.BehaviorCommandInvoker.doInvoke(BehaviorCommandInvoker.java:155)
	at org.seasar.dbflute.bhv.core.BehaviorCommandInvoker.invoke(BehaviorCommandInvoker.java:100)
	at org.seasar.dbflute.bhv.AbstractBehaviorReadable.invoke(AbstractBehaviorReadable.java:875)
	at org.t2framework.samples.todo.dbflute.bsbhv.BsEmployeeBhv.invoke(<generated>)
	at org.t2framework.samples.todo.dbflute.exbhv.EmployeeBhv.invoke(<generated>)
	at org.t2framework.samples.todo.dbflute.bsbhv.BsEmployeeBhv$$M$27ffc841.delegateSelectList(BsEmployeeBhv.java:462)
	at org.t2framework.samples.todo.dbflute.bsbhv.BsEmployeeBhv$$A$27ffc841.delegateSelectList(<generated>)
	at org.t2framework.samples.todo.dbflute.bsbhv.BsEmployeeBhv.delegateSelectList(<generated>)
	at org.t2framework.samples.todo.dbflute.exbhv.EmployeeBhv.delegateSelectList(<generated>)
	at org.t2framework.samples.todo.dbflute.bsbhv.BsEmployeeBhv$$M$27ffc841.selectList(BsEmployeeBhv.java:165)
	at org.t2framework.samples.todo.dbflute.bsbhv.BsEmployeeBhv$$A$27ffc841.selectList(<generated>)
	at org.t2framework.samples.todo.dbflute.bsbhv.BsEmployeeBhv.selectList(<generated>)
	at org.t2framework.samples.todo.dbflute.exbhv.EmployeeBhv.selectList(<generated>)
	at org.t2framework.samples.todo.service.impl.EmployeeServiceImpl$$M$cdf69e1a.update(EmployeeServiceImpl.java:39)
	at org.t2framework.samples.todo.service.impl.EmployeeServiceImpl$$A$cdf69e1a.update(<generated>)
	at org.t2framework.samples.todo.service.impl.EmployeeServiceImpl.update(<generated>)
	at org.t2framework.samples.todo.service.impl.EmployeeServiceImpl$$LucyAop$$13e584.update$$(EmployeeServiceImpl$$LucyAop$$13e584.java)
	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 org.t2framework.lucy.aop.impl.InvocationImpl.proceed(InvocationImpl.java:137)
	at org.t2framework.lucy.tx.interceptor.InvocationWorker.work(InvocationWorker.java:20)
	at org.t2framework.lucy.tx.JTATransactionProcesser.required(JTATransactionProcesser.java:28)
	at org.t2framework.lucy.tx.interceptor.RequiredInterceptor.process(RequiredInterceptor.java:11)
	at org.t2framework.lucy.tx.interceptor.AbstractTxInterceptor.intercept(AbstractTxInterceptor.java:38)
	at org.t2framework.lucy.aop.impl.InvocationImpl.proceed(InvocationImpl.java:134)
	at org.t2framework.lucy.aop.impl.InvocationImpl.doProceed(InvocationImpl.java:112)
	at org.t2framework.samples.todo.service.impl.EmployeeServiceImpl$$LucyAop$$13e584.update(EmployeeServiceImpl$$LucyAop$$13e584.java)
	at org.t2framework.samples.todo.page.EmployeePage$$M$bd026ad5.update(EmployeePage.java:69)
	at org.t2framework.samples.todo.page.EmployeePage$$A$bd026ad5.update(<generated>)
	at org.t2framework.samples.todo.page.EmployeePage.update(<generated>)
	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 org.t2framework.commons.util.Reflections$MethodUtil.invoke(Reflections.java:468)
	at org.t2framework.commons.meta.impl.MethodDescImpl.invoke(MethodDescImpl.java:87)
	at org.t2framework.t2.action.impl.ActionInvokerImpl.invokeAction(ActionInvokerImpl.java:199)
	at org.t2framework.t2.action.impl.ActionInvokerImpl.invoke(ActionInvokerImpl.java:143)
	at org.t2framework.t2.filter.T2Filter.doFilter(T2Filter.java:134)
	at org.apache.catalina.core.ApplicationFilterChain.internalDoFilter(ApplicationFilterChain.java:235)
	at org.apache.catalina.core.ApplicationFilterChain.doFilter(ApplicationFilterChain.java:206)
	at org.t2framework.t2.filter.MultiPartRequestFilter.doFilter(MultiPartRequestFilter.java:94)
	at org.apache.catalina.core.ApplicationFilterChain.internalDoFilter(ApplicationFilterChain.java:235)
	at org.apache.catalina.core.ApplicationFilterChain.doFilter(ApplicationFilterChain.java:206)
	at org.apache.catalina.core.StandardWrapperValve.invoke(StandardWrapperValve.java:233)
	at org.apache.catalina.core.StandardContextValve.invoke(StandardContextValve.java:191)
	at org.apache.catalina.core.StandardHostValve.invoke(StandardHostValve.java:128)
	at org.apache.catalina.valves.ErrorReportValve.invoke(ErrorReportValve.java:102)
	at org.apache.catalina.core.StandardEngineValve.invoke(StandardEngineValve.java:109)
	at org.apache.catalina.connector.CoyoteAdapter.service(CoyoteAdapter.java:286)
	at org.apache.coyote.http11.Http11Processor.process(Http11Processor.java:845)
	at org.apache.coyote.http11.Http11Protocol$Http11ConnectionHandler.process(Http11Protocol.java:583)
	at org.apache.tomcat.util.net.JIoEndpoint$Worker.run(JIoEndpoint.java:447)
	at java.lang.Thread.run(Thread.java:619)