-
1. Re: unexplained lock in 3.2.4
Is it a deadlock in the database? Does is it hang before the invocation that resulted in the query return or after that?
-
2. Re: unexplained lock in 3.2.4
I used a trace on the querys using the spy driver package (i hope your familiar with it), it does no show this query ever being sent to the database
-
3. Re: unexplained lock in 3.2.4
This is logged just before obtaining the connection from the datasource and executing the prepared statement. Looks like a connection pooling problem.
What does the thread dump show when it hangs? -
4. Re: unexplained lock in 3.2.4
I turned on trace: here is what I have:
2004-06-11 17:43:58,978 TRACE [org.jboss.resource.connectionmanager.JBossManagedConnectionPool] Getting connection tracked by transaction org.jboss.resource.connectionmanager.TxConnectionManager$TxConnectionEventListener@1039f33[state=NORMAL mc=org.jboss.resource.adapter.jdbc.local.LocalManagedConnection@c8cdca handles=0 lastUse=1086968627491 permit=true trackByTx=true mcp=org.jboss.resource.connectionmanager.JBossManagedConnectionPool$OnePool@1a5f0f3 context=org.jboss.resource.connectionmanager.InternalManagedConnectionPool@16e0123] [InUse/Available/Max]: [2/18/20] 2004-06-11 17:43:59,098 DEBUG [org.jboss.ejb.plugins.cmp.jdbc.JDBCLoadRelationCommand.Task] load relation SQL: SELECT ROLE_VL_ID, TASK_ID FROM ROLE_FOR_TASK WHERE (ROLE_VL_ID=?) OR (ROLE_VL_ID=?) OR (ROLE_VL_ID=?) OR (ROLE_VL_ID=?) OR (ROLE_VL_ID=?) 2004-06-11 17:43:59,098 TRACE [org.jboss.resource.connectionmanager.JBossManagedConnectionPool] Getting connection tracked by transaction org.jboss.resource.connectionmanager.TxConnectionManager$TxConnectionEventListener@1039f33[state=NORMAL mc=org.jboss.resource.adapter.jdbc.local.LocalManagedConnection@c8cdca handles=0 lastUse=1086968627491 permit=true trackByTx=true mcp=org.jboss.resource.connectionmanager.JBossManagedConnectionPool$OnePool@1a5f0f3 context=org.jboss.resource.connectionmanager.InternalManagedConnectionPool@16e0123] [InUse/Available/Max]: [2/18/20] 2004-06-11 17:43:59,238 DEBUG [org.jboss.ejb.plugins.cmp.jdbc.JDBCLoadEntityCommand.Task] Executing SQL: SELECT PRIORITY, TASK_NAME, RE_ASSIGNABLE, RE_ASSIGNABLE_TO_VL_ID, CREATE_DATE, UPDATE_DATE, END_DATE, TIME_STAMP, STATUS_ID, EMI_USER_ID, FLOW_CONTEXT_ID FROM TASK WHERE (ID=?) 2004-06-11 17:43:59,238 TRACE [org.jboss.resource.connectionmanager.JBossManagedConnectionPool] supplying ManagedConnection from pool: org.jboss.resource.connectionmanager.TxConnectionManager$TxConnectionEventListener@1d0a692[state=NORMAL mc=org.jboss.resource.adapter.jdbc.local.LocalManagedConnection@167d3c4 handles=0 lastUse=1086968638567 permit=false trackByTx=false mcp=org.jboss.resource.connectionmanager.JBossManagedConnectionPool$OnePool@1a5f0f3 context=org.jboss.resource.connectionmanager.InternalManagedConnectionPool@16e0123] 2004-06-11 17:43:59,238 TRACE [org.jboss.resource.connectionmanager.JBossManagedConnectionPool] Getting connection from pool org.jboss.resource.connectionmanager.TxConnectionManager$TxConnectionEventListener@1d0a692[state=NORMAL mc=org.jboss.resource.adapter.jdbc.local.LocalManagedConnection@167d3c4 handles=0 lastUse=1086968638567 permit=true trackByTx=false mcp=org.jboss.resource.connectionmanager.JBossManagedConnectionPool$OnePool@1a5f0f3 context=org.jboss.resource.connectionmanager.InternalManagedConnectionPool@16e0123] [InUse/Available/Max]: [3/17/20] 2004-06-11 17:43:59,389 TRACE [org.jboss.resource.connectionmanager.JBossManagedConnectionPool] putting ManagedConnection back into pool kill=false cl=org.jboss.resource.connectionmanager.TxConnectionManager$TxConnectionEventListener@1d0a692[state=NORMAL mc=org.jboss.resource.adapter.jdbc.local.LocalManagedConnection@167d3c4 handles=0 lastUse=1086968638567 permit=true trackByTx=false mcp=org.jboss.resource.connectionmanager.JBossManagedConnectionPool$OnePool@1a5f0f3 context=org.jboss.resource.connectionmanager.InternalManagedConnectionPool@16e0123] 2004-06-11 17:43:59,389 TRACE [org.jboss.resource.connectionmanager.JBossManagedConnectionPool] Returning connection to pool org.jboss.resource.connectionmanager.TxConnectionManager$TxConnectionEventListener@1d0a692[state=NORMAL mc=org.jboss.resource.adapter.jdbc.local.LocalManagedConnection@167d3c4 handles=0 lastUse=1086968639389 permit=false trackByTx=false mcp=org.jboss.resource.connectionmanager.JBossManagedConnectionPool$OnePool@1a5f0f3 context=org.jboss.resource.connectionmanager.InternalManagedConnectionPool@16e0123] [InUse/Available/Max]: [2/18/20]
and after 5 minutes or so I hot this:2004-06-11 17:48:47,803 WARN [org.jboss.tm.TransactionImpl] Transaction TransactionImpl:XidImpl [FormatId=257, GlobalId=norman//19, BranchQual=] timed out. status=STATUS_ACTIVE 2004-06-11 17:48:47,803 ERROR [org.jboss.ejb.BeanLock] Thread[http-0.0.0.0-8080-Processor25,5,jboss]Saw rolled back tx=TransactionImpl:XidImpl [FormatId=257, GlobalId=norman//19, BranchQual=] waiting for txLock 2004-06-11 17:48:47,813 ERROR [org.jboss.ejb.plugins.LogInterceptor] TransactionRolledbackLocalException in method: public abstract java.sql.Date com.matrix.framework.infrastructure.workflow.TaskLocal.getUpdateDate(), causedBy: java.lang.RuntimeException: Transaction marked for rollback, possibly a timeout at org.jboss.ejb.plugins.lock.QueuedPessimisticEJBLock.waitForTx(QueuedPessimisticEJBLock.java:366) at org.jboss.ejb.plugins.lock.QueuedPessimisticEJBLock.doSchedule(QueuedPessimisticEJBLock.java:236) at org.jboss.ejb.plugins.lock.QueuedPessimisticEJBLock.schedule(QueuedPessimisticEJBLock.java:183) at org.jboss.ejb.plugins.EntityLockInterceptor.invoke(EntityLockInterceptor.java:85) at org.jboss.ejb.plugins.EntityCreationInterceptor.invoke(EntityCreationInterceptor.java:54) at org.jboss.ejb.plugins.AbstractTxInterceptor.invokeNext(AbstractTxInterceptor.java:84) at org.jboss.ejb.plugins.TxInterceptorCMT.runWithTransactions(TxInterceptorCMT.java:315) at org.jboss.ejb.plugins.TxInterceptorCMT.invoke(TxInterceptorCMT.java:148) at org.jboss.ejb.plugins.SecurityInterceptor.invoke(SecurityInterceptor.java:120) at org.jboss.ejb.plugins.LogInterceptor.invoke(LogInterceptor.java:191) at org.jboss.ejb.plugins.ProxyFactoryFinderInterceptor.invoke(ProxyFactoryFinderInterceptor.java:122) at org.jboss.ejb.EntityContainer.internalInvoke(EntityContainer.java:484) at org.jboss.ejb.Container.invoke(Container.java:723) at org.jboss.ejb.plugins.local.BaseLocalProxyFactory.invoke(BaseLocalProxyFactory.java:359) at org.jboss.ejb.plugins.local.EntityProxy.invoke(EntityProxy.java:44) at $Proxy195.getUpdateDate(Unknown Source) 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:324) at com.matrix.framework.infrastructure.reflection.ReflectionUtils.invokeGetter(ReflectionUtils.java:76) at com.matrix.framework.infrastructure.model.factory.TOFactory.passValuesFromBeanToTO(TOFactory.java:209) at com.matrix.framework.infrastructure.model.factory.TOFactory.passValuesFromBeanToTO(TOFactory.java:173) at com.matrix.framework.infrastructure.model.factory.TOFactory.createTO(TOFactory.java:89) at com.matrix.framework.infrastructure.model.factory.TOFactory.createTOs(TOFactory.java:36) at com.matrix.framework.infrastructure.controller.InnerBasicController.getTOs(InnerBasicController.java:149) at com.matrix.framework.infrastructure.model.InnerSessionBean.getTOs(InnerSessionBean.java:84) 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:324) at org.jboss.ejb.StatelessSessionContainer$ContainerInterceptor.invoke(StatelessSessionContainer.java:683) at org.jboss.resource.connectionmanager.CachedConnectionInterceptor.invoke(CachedConnectionInterceptor.java:185) at org.jboss.ejb.plugins.StatelessSessionInstanceInterceptor.invoke(StatelessSessionInstanceInterceptor.java:72) at org.jboss.ejb.plugins.AbstractTxInterceptor.invokeNext(AbstractTxInterceptor.java:84) at org.jboss.ejb.plugins.TxInterceptorCMT.runWithTransactions(TxInterceptorCMT.java:315) at org.jboss.ejb.plugins.TxInterceptorCMT.invoke(TxInterceptorCMT.java:148) at org.jboss.ejb.plugins.SecurityInterceptor.invoke(SecurityInterceptor.java:120) at org.jboss.ejb.plugins.LogInterceptor.invoke(LogInterceptor.java:191) at org.jboss.ejb.plugins.ProxyFactoryFinderInterceptor.invoke(ProxyFactoryFinderInterceptor.java:122) at org.jboss.ejb.StatelessSessionContainer.internalInvoke(StatelessSessionContainer.java:331) at org.jboss.ejb.Container.invoke(Container.java:723) at org.jboss.ejb.plugins.local.BaseLocalProxyFactory.invoke(BaseLocalProxyFactory.java:359) at org.jboss.ejb.plugins.local.StatelessSessionProxy.invoke(StatelessSessionProxy.java:83) at $Proxy237.getTOs(Unknown Source) at com.matrix.framework.infrastructure.workflow.persistance.TaskPersistanceManager.get(TaskPersistanceManager.java:139) at com.matrix.framework.infrastructure.workflow.Workflow.getTaskList(Workflow.java:218) at com.matrix.framework.infrastructure.model.TasksSessionBean.getTaskList(TasksSessionBean.java:60) 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:324) at org.jboss.ejb.StatelessSessionContainer$ContainerInterceptor.invoke(StatelessSessionContainer.java:683) at org.jboss.resource.connectionmanager.CachedConnectionInterceptor.invoke(CachedConnectionInterceptor.java:185) at org.jboss.ejb.plugins.StatelessSessionInstanceInterceptor.invoke(StatelessSessionInstanceInterceptor.java:72) at org.jboss.ejb.plugins.AbstractTxInterceptor.invokeNext(AbstractTxInterceptor.java:84) at org.jboss.ejb.plugins.TxInterceptorCMT.runWithTransactions(TxInterceptorCMT.java:315) at org.jboss.ejb.plugins.TxInterceptorCMT.invoke(TxInterceptorCMT.java:148) at org.jboss.ejb.plugins.SecurityInterceptor.invoke(SecurityInterceptor.java:120) at org.jboss.ejb.plugins.LogInterceptor.invoke(LogInterceptor.java:191) at org.jboss.ejb.plugins.ProxyFactoryFinderInterceptor.invoke(ProxyFactoryFinderInterceptor.java:122) at org.jboss.ejb.StatelessSessionContainer.internalInvoke(StatelessSessionContainer.java:331) at org.jboss.ejb.Container.invoke(Container.java:723) 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:324) at org.jboss.mx.server.ReflectedDispatcher.dispatch(ReflectedDispatcher.java:60) at org.jboss.mx.server.Invocation.dispatch(Invocation.java:61) at org.jboss.mx.server.Invocation.dispatch(Invocation.java:53) at org.jboss.mx.server.Invocation.invoke(Invocation.java:86) at org.jboss.mx.server.AbstractMBeanInvoker.invoke(AbstractMBeanInvoker.java:185) at org.jboss.mx.server.MBeanServerImpl.invoke(MBeanServerImpl.java:473) at org.jboss.invocation.local.LocalInvoker.invoke(LocalInvoker.java:97) at org.jboss.invocation.InvokerInterceptor.invoke(InvokerInterceptor.java:90) at org.jboss.proxy.TransactionInterceptor.invoke(TransactionInterceptor.java:46) at org.jboss.proxy.SecurityInterceptor.invoke(SecurityInterceptor.java:53) at org.jboss.proxy.ejb.StatelessSessionInterceptor.invoke(StatelessSessionInterceptor.java:100) at org.jboss.proxy.ClientContainer.invoke(ClientContainer.java:85) at $Proxy236.getTaskList(Unknown Source) at com.matrix.framework.client.actions.LoginAction.login(LoginAction.java:72) 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:324) at com.matrix.framework.client.actions.BaseAction.execute(BaseAction.java:95) at org.apache.struts.action.RequestProcessor.processActionPerform(RequestProcessor.java:484) at org.apache.struts.action.RequestProcessor.process(RequestProcessor.java:274) at org.apache.struts.action.ActionServlet.process(ActionServlet.java:1482) at org.apache.struts.action.ActionServlet.doPost(ActionServlet.java:525) at javax.servlet.http.HttpServlet.service(HttpServlet.java:717) at javax.servlet.http.HttpServlet.service(HttpServlet.java:810) at org.apache.catalina.core.ApplicationFilterChain.internalDoFilter(ApplicationFilterChain.java:237) at org.apache.catalina.core.ApplicationFilterChain.doFilter(ApplicationFilterChain.java:157) at org.apache.catalina.core.StandardWrapperValve.invoke(StandardWrapperValve.java:214) at org.apache.catalina.core.StandardValveContext.invokeNext(StandardValveContext.java:104) at org.apache.catalina.core.StandardPipeline.invoke(StandardPipeline.java:520) at org.apache.catalina.core.StandardContextValve.invokeInternal(StandardContextValve.java:198) at org.apache.catalina.core.StandardContextValve.invoke(StandardContextValve.java:152) at org.apache.catalina.core.StandardValveContext.invokeNext(StandardValveContext.java:104) at org.jboss.web.tomcat.security.SecurityAssociationValve.invoke(SecurityAssociationValve.java:72) at org.apache.catalina.core.StandardValveContext.invokeNext(StandardValveContext.java:102) at org.jboss.web.tomcat.security.JBossSecurityMgrRealm.invoke(JBossSecurityMgrRealm.java:275) at org.apache.catalina.core.StandardValveContext.invokeNext(StandardValveContext.java:102) at org.apache.catalina.core.StandardPipeline.invoke(StandardPipeline.java:520) at org.apache.catalina.core.StandardHostValve.invoke(StandardHostValve.java:137) at org.apache.catalina.core.StandardValveContext.invokeNext(StandardValveContext.java:104) at org.apache.catalina.valves.ErrorReportValve.invoke(ErrorReportValve.java:117) at org.apache.catalina.core.StandardValveContext.invokeNext(StandardValveContext.java:102) at org.apache.catalina.core.StandardPipeline.invoke(StandardPipeline.java:520) at org.apache.catalina.core.StandardEngineValve.invoke(StandardEngineValve.java:109) at org.apache.catalina.core.StandardValveContext.invokeNext(StandardValveContext.java:104) at org.apache.catalina.core.StandardPipeline.invoke(StandardPipeline.java:520) at org.apache.catalina.core.ContainerBase.invoke(ContainerBase.java:929) at org.apache.coyote.tomcat5.CoyoteAdapter.service(CoyoteAdapter.java:160) at org.apache.coyote.http11.Http11Processor.process(Http11Processor.java:799) at org.apache.coyote.http11.Http11Protocol$Http11ConnectionHandler.processConnection(Http11Protocol.java:705) at org.apache.tomcat.util.net.TcpWorkerThread.runIt(PoolTcpEndpoint.java:577) at org.apache.tomcat.util.threads.ThreadPool$ControlRunnable.run(ThreadPool.java:683) at java.lang.Thread.run(Thread.java:534)
Is there anything else I can look at to givr you more information? -
5. Re: unexplained lock in 3.2.4
It looks like the statement was executed successfully and connection was returned to the pool.
The stacktrace shows that tx timed out waiting for the lock to be released. So far nothing looks like a bug in JBoss. -
6. Re: unexplained lock in 3.2.4
Since this code works perfectly with JBoss 3.2.3 I'm at a loss. What is your suggestion? what should I explore next.
More over, I'm sure that this query did not reach the database since I log all driver selects and this query doesn't show. -
7. Re: unexplained lock in 3.2.4
Sorry, I stand corrected. I've recheked my self, after a short while the questioned select does show on the driver log, which means it was sent to the db.
I'm left with the wonder what could casue the lock, and why does it only happen with 3.2.4 -
8. Re: unexplained lock in 3.2.4
The connection returned to the pool since to be no the one that was obtained. Add a thread to the conversion pattern like
<param name="ConversionPattern" value="%d %-5p [%c] [%t] %m%n"/>
Try instance per transaction container to make sure it's not an EJB locking problem. -
9. Re: unexplained lock in 3.2.4
OK, some progress here. It seems that I'm experiencing some kind of bean lock. Here is the description of the cycle:
I start a transaction calling a session bean which retireves a collection of taskbeans for a user. It uses a finder on taskhome looking for tasks where user.id = the userid passed. Each TaskBean has a many to one relationship with userbean (userbean is blind to it). The first TaskBean is returned with all of it's relationship information (it has the userbean and everything...)When the iteration does the getUser on the second TaskLocal, I see the slect on all fields of the TaskBean according to the ID, I see theresultset being returned. Now I eas supposed to see the select for the user, but I don't... see the following selects generated by JBoss:
Starting from the first select.... stopping on the second:1087044981481|150|1|statement|SELECT PRIORITY, TASK_NAME, RE_ASSIGNABLE, RE_ASSIGNABLE_TO_VL_ID, CREATE_DATE, UPDATE_DATE, END_DATE, TIME_STAMP, STATUS_ID, EMI_USER_ID, FLOW_CONTEXT_ID FROM TASK WHERE (ID=?)|SELECT PRIORITY, TASK_NAME, RE_ASSIGNABLE, RE_ASSIGNABLE_TO_VL_ID, CREATE_DATE, UPDATE_DATE, END_DATE, TIME_STAMP, STATUS_ID, EMI_USER_ID, FLOW_CONTEXT_ID FROM TASK WHERE (ID='4') 1087044981602|-1||resultset|SELECT PRIORITY, TASK_NAME, RE_ASSIGNABLE, RE_ASSIGNABLE_TO_VL_ID, CREATE_DATE, UPDATE_DATE, END_DATE, TIME_STAMP, STATUS_ID, EMI_USER_ID, FLOW_CONTEXT_ID FROM TASK WHERE (ID='4')|PRIORITY = 3, RE_ASSIGNABLE_TO_VL_ID = 1, TASK_NAME = t4 1087044981742|130|0|statement|SELECT ID, EMI_USER_ID FROM TASK WHERE (ID=?) OR (ID=?) OR (ID=?) OR (ID=?) OR (ID=?)|SELECT ID, EMI_USER_ID FROM TASK WHERE (ID='4') OR (ID='1') OR (ID='2') OR (ID='3') OR (ID='5') 1087044981742|-1||resultset|SELECT ID, EMI_USER_ID FROM TASK WHERE (ID='4') OR (ID='1') OR (ID='2') OR (ID='3') OR (ID='5')| 1087044981742|-1||resultset|SELECT ID, EMI_USER_ID FROM TASK WHERE (ID='4') OR (ID='1') OR (ID='2') OR (ID='3') OR (ID='5')| 1087044981742|-1||resultset|SELECT ID, EMI_USER_ID FROM TASK WHERE (ID='4') OR (ID='1') OR (ID='2') OR (ID='3') OR (ID='5')| 1087044981742|-1||resultset|SELECT ID, EMI_USER_ID FROM TASK WHERE (ID='4') OR (ID='1') OR (ID='2') OR (ID='3') OR (ID='5')| 1087044981742|-1||resultset|SELECT ID, EMI_USER_ID FROM TASK WHERE (ID='4') OR (ID='1') OR (ID='2') OR (ID='3') OR (ID='5')| 1087044981982|130|0|statement|SELECT ID, STATUS_ID FROM TASK WHERE (ID=?) OR (ID=?) OR (ID=?) OR (ID=?) OR (ID=?)|SELECT ID, STATUS_ID FROM TASK WHERE (ID='4') OR (ID='1') OR (ID='2') OR (ID='3') OR (ID='5') 1087044981982|-1||resultset|SELECT ID, STATUS_ID FROM TASK WHERE (ID='4') OR (ID='1') OR (ID='2') OR (ID='3') OR (ID='5')| 1087044981982|-1||resultset|SELECT ID, STATUS_ID FROM TASK WHERE (ID='4') OR (ID='1') OR (ID='2') OR (ID='3') OR (ID='5')| 1087044981982|-1||resultset|SELECT ID, STATUS_ID FROM TASK WHERE (ID='4') OR (ID='1') OR (ID='2') OR (ID='3') OR (ID='5')| 1087044981982|-1||resultset|SELECT ID, STATUS_ID FROM TASK WHERE (ID='4') OR (ID='1') OR (ID='2') OR (ID='3') OR (ID='5')| 1087044981982|-1||resultset|SELECT ID, STATUS_ID FROM TASK WHERE (ID='4') OR (ID='1') OR (ID='2') OR (ID='3') OR (ID='5')| 1087044982192|140|1|statement|SELECT OBJECT_TYPE_VL_ID, DESCRIPTION, INFORMATION_SOURCE_VL_ID, STATUS_TYPE_VL_ID, START_DATE, END_DATE, CREATE_DATE, UPDATE_DATE, TIME_STAMP, CREATOR_USER_ID, UPDATOR_USER_ID, VERSION, IS_OBSOLETE FROM STATUS WHERE (ID=?)|SELECT OBJECT_TYPE_VL_ID, DESCRIPTION, INFORMATION_SOURCE_VL_ID, STATUS_TYPE_VL_ID, START_DATE, END_DATE, CREATE_DATE, UPDATE_DATE, TIME_STAMP, CREATOR_USER_ID, UPDATOR_USER_ID, VERSION, IS_OBSOLETE FROM STATUS WHERE (ID='1') 1087044982192|-1||resultset|SELECT OBJECT_TYPE_VL_ID, DESCRIPTION, INFORMATION_SOURCE_VL_ID, STATUS_TYPE_VL_ID, START_DATE, END_DATE, CREATE_DATE, UPDATE_DATE, TIME_STAMP, CREATOR_USER_ID, UPDATOR_USER_ID, VERSION, IS_OBSOLETE FROM STATUS WHERE (ID='1')|DESCRIPTION = NEW, INFORMATION_SOURCE_VL_ID = null, OBJECT_TYPE_VL_ID = null, STATUS_TYPE_VL_ID = NEW, VERSION = 0 1087044982363|151|0|statement|SELECT ID FROM REASON WHERE (STATUS_ID=?)|SELECT ID FROM REASON WHERE (STATUS_ID='1') 1087044982493|130|0|statement|SELECT ID, FLOW_CONTEXT_ID FROM TASK WHERE (ID=?) OR (ID=?) OR (ID=?) OR (ID=?) OR (ID=?)|SELECT ID, FLOW_CONTEXT_ID FROM TASK WHERE (ID='4') OR (ID='1') OR (ID='2') OR (ID='3') OR (ID='5') 1087044982493|-1||resultset|SELECT ID, FLOW_CONTEXT_ID FROM TASK WHERE (ID='4') OR (ID='1') OR (ID='2') OR (ID='3') OR (ID='5')| 1087044982493|-1||resultset|SELECT ID, FLOW_CONTEXT_ID FROM TASK WHERE (ID='4') OR (ID='1') OR (ID='2') OR (ID='3') OR (ID='5')| 1087044982493|-1||resultset|SELECT ID, FLOW_CONTEXT_ID FROM TASK WHERE (ID='4') OR (ID='1') OR (ID='2') OR (ID='3') OR (ID='5')| 1087044982493|-1||resultset|SELECT ID, FLOW_CONTEXT_ID FROM TASK WHERE (ID='4') OR (ID='1') OR (ID='2') OR (ID='3') OR (ID='5')| 1087044982493|-1||resultset|SELECT ID, FLOW_CONTEXT_ID FROM TASK WHERE (ID='4') OR (ID='1') OR (ID='2') OR (ID='3') OR (ID='5')| 1087044982673|130|1|statement|SELECT FLOW_NAME, CURRENT_STATE, CREATE_DATE, UPDATE_DATE, END_DATE, TIME_STAMP FROM FLOW_CONTEXT WHERE (ID=?)|SELECT FLOW_NAME, CURRENT_STATE, CREATE_DATE, UPDATE_DATE, END_DATE, TIME_STAMP FROM FLOW_CONTEXT WHERE (ID='1') 1087044982673|-1||resultset|SELECT FLOW_NAME, CURRENT_STATE, CREATE_DATE, UPDATE_DATE, END_DATE, TIME_STAMP FROM FLOW_CONTEXT WHERE (ID='1')|CURRENT_STATE = state, FLOW_NAME = flow 1 1087044982793|120|0|statement|SELECT FLOW_CONTEXT_ID FROM LOCAL_ATTRIB_FOR_FLOW_CONTEXT WHERE (ATTRIBUTE_ID=?)|SELECT FLOW_CONTEXT_ID FROM LOCAL_ATTRIB_FOR_FLOW_CONTEXT WHERE (ATTRIBUTE_ID='1') 1087044982923|130|0|statement|SELECT FLOW_CONTEXT_ID FROM FLOW_ATTRIB_FOR_FLOW_CONTEXT WHERE (ATTRIBUTE_ID=?)|SELECT FLOW_CONTEXT_ID FROM FLOW_ATTRIB_FOR_FLOW_CONTEXT WHERE (ATTRIBUTE_ID='1') 1087044983054|131|0|statement|SELECT FLOW_CONTEXT_ID FROM HANDLED_OBJ_FOR_FLOW_CONTEXT WHERE (HANDLED_OBJECT_ID=?)|SELECT FLOW_CONTEXT_ID FROM HANDLED_OBJ_FOR_FLOW_CONTEXT WHERE (HANDLED_OBJECT_ID='1') 1087044983184|130|0|statement|SELECT ROLE_VL_ID, TASK_ID FROM ROLE_FOR_TASK WHERE (ROLE_VL_ID=?) OR (ROLE_VL_ID=?) OR (ROLE_VL_ID=?) OR (ROLE_VL_ID=?) OR (ROLE_VL_ID=?)|SELECT ROLE_VL_ID, TASK_ID FROM ROLE_FOR_TASK WHERE (ROLE_VL_ID='4') OR (ROLE_VL_ID='1') OR (ROLE_VL_ID='2') OR (ROLE_VL_ID='3') OR (ROLE_VL_ID='5') 1087044983324|140|1|statement|SELECT PRIORITY, TASK_NAME, RE_ASSIGNABLE, RE_ASSIGNABLE_TO_VL_ID, CREATE_DATE, UPDATE_DATE, END_DATE, TIME_STAMP, STATUS_ID, EMI_USER_ID, FLOW_CONTEXT_ID FROM TASK WHERE (ID=?)|SELECT PRIORITY, TASK_NAME, RE_ASSIGNABLE, RE_ASSIGNABLE_TO_VL_ID, CREATE_DATE, UPDATE_DATE, END_DATE, TIME_STAMP, STATUS_ID, EMI_USER_ID, FLOW_CONTEXT_ID FROM TASK WHERE (ID='1') 1087044983324|-1||resultset|SELECT PRIORITY, TASK_NAME, RE_ASSIGNABLE, RE_ASSIGNABLE_TO_VL_ID, CREATE_DATE, UPDATE_DATE, END_DATE, TIME_STAMP, STATUS_ID, EMI_USER_ID, FLOW_CONTEXT_ID FROM TASK WHERE (ID='1')|PRIORITY = 1, RE_ASSIGNABLE_TO_VL_ID = 1, TASK_NAME = t2
After this it hangs.
Since the user is the same user, it may be trying to get the reference to the same userBean in cache, and maybe this is where I have a lock?
What do you think? -
10. Re: unexplained lock in 3.2.4
If it is a lock in EJB container then another concurrent transaction locked the instance. You can enable trace logging for org.jboss.ejb.plugins. Once again, if you use Instance Per Transaction, do you get the deadlock?
-
-
12. Re: unexplained lock in 3.2.4
In jboss.xml
<entity> <ejb-name>MyBean</ejb-name> <configuration-name>Instance Per Transaction CMP 2.x EntityBean</configuration-name> </entity>
-
13. Re: unexplained lock in 3.2.4
I used Instance Per Transaction on the beans involved in the transaction. I still get this dead lock, however a new message appears:
2004-06-15 11:17:19,195 222991 WARN [org.jboss.ejb.plugins.PerTxEntityInstanceCache] (http-0.0.0.0-8080-Processor20:) Unable to passivate due to ctx lock, id=37
how can I get a context lock? -
14. Re: unexplained lock in 3.2.4
I have turned on the instance per transaction on userLocal, I have also turned on the trace:
Here is a partial log.2004-06-15 15:04:58,566 204304 INFO [STDOUT] (http-0.0.0.0-8080-Processor25:) 15/06/2004 15:04:58 com.matrix.framework.ip.controller.UserController getSingleNotByPrimaryKey FINEST: ===============User Id = 'user' Password = '1' ======================= 2004-06-15 15:04:58,566 204304 TRACE [org.jboss.ejb.plugins.ProxyFactoryFinderInterceptor] (http-0.0.0.0-8080-Processor25:) invokerBInding is null in ProxyFactoryFinder 2004-06-15 15:04:58,586 204324 TRACE [org.jboss.ejb.plugins.LogInterceptor] (http-0.0.0.0-8080-Processor25:) Start method=findByUserNameAndPassword 2004-06-15 15:04:58,586 204324 TRACE [org.jboss.ejb.plugins.TxInterceptorCMT] (http-0.0.0.0-8080-Processor25:) Current transaction in MI is TransactionImpl:XidImpl [FormatId=257, GlobalId=norman//15, BranchQual=] 2004-06-15 15:04:58,586 204324 TRACE [org.jboss.ejb.plugins.TxInterceptorCMT] (http-0.0.0.0-8080-Processor25:) TX_REQUIRED for findByUserNameAndPassword timeout=0 2004-06-15 15:04:58,586 204324 TRACE [org.jboss.ejb.plugins.TxInterceptorCMT] (http-0.0.0.0-8080-Processor25:) Thread came in with tx TransactionImpl:XidImpl [FormatId=257, GlobalId=norman//15, BranchQual=] 2004-06-15 15:04:58,586 204324 TRACE [org.jboss.ejb.plugins.EntityInstancePool] (http-0.0.0.0-8080-Processor25:) Get instance org.jboss.ejb.plugins.EntityInstancePool@1ee026e#0#class com.matrix.framework.ip.model.UserBean 2004-06-15 15:04:58,606 204344 DEBUG [org.jboss.ejb.plugins.cmp.jdbc.JDBCEJBQLQuery.User#findByUserNameAndPassword] (http-0.0.0.0-8080-Processor25:) Executing SQL: SELECT DISTINCT t0_a.ID, t0_a.USER_NAME, t0_a.START_DATE, t0_a.END_DATE, t0_a.CREATE_DATE, t0_a.UPDATE_DATE, t0_a.TIME_STAMP, t0_a.CREATOR_USER_ID, t0_a.UPDATOR_USER_ID, t0_a.VERSION, t0_a.IS_OBSOLETE, t0_a.ORGANIZATION_ID, t0_a.PERSON_ID FROM EMI_USER t0_a WHERE (t0_a.USER_NAME = ? AND t0_a.USER_PASSWORD = ?) 2004-06-15 15:04:58,606 204344 TRACE [org.jboss.resource.connectionmanager.JBossManagedConnectionPool] (http-0.0.0.0-8080-Processor25:) supplying ManagedConnection from pool: org.jboss.resource.connectionmanager.TxConnectionManager$TxConnectionEventListener@591a4d[state=NORMAL mc=org.jboss.resource.adapter.jdbc.local.LocalManagedConnection@1cdd63c handles=0 lastUse=1087304638189 permit=false trackByTx=false mcp=org.jboss.resource.connectionmanager.JBossManagedConnectionPool$OnePool@ac0a60 context=org.jboss.resource.connectionmanager.InternalManagedConnectionPool@dd3147] 2004-06-15 15:04:58,606 204344 TRACE [org.jboss.resource.connectionmanager.JBossManagedConnectionPool] (http-0.0.0.0-8080-Processor25:) Getting connection from pool org.jboss.resource.connectionmanager.TxConnectionManager$TxConnectionEventListener@591a4d[state=NORMAL mc=org.jboss.resource.adapter.jdbc.local.LocalManagedConnection@1cdd63c handles=0 lastUse=1087304638189 permit=true trackByTx=true mcp=org.jboss.resource.connectionmanager.JBossManagedConnectionPool$OnePool@ac0a60 context=org.jboss.resource.connectionmanager.InternalManagedConnectionPool@dd3147] [InUse/Available/Max]: [1/19/20] 2004-06-15 15:04:58,656 204394 TRACE [org.jboss.ejb.plugins.cmp.jdbc.JDBCEJBQLQuery.User#findByUserNameAndPassword] (http-0.0.0.0-8080-Processor25:) Set parameter: index=1, jdbcType=VARCHAR, value=user 2004-06-15 15:04:58,656 204394 TRACE [org.jboss.ejb.plugins.cmp.jdbc.JDBCEJBQLQuery.User#findByUserNameAndPassword] (http-0.0.0.0-8080-Processor25:) Set parameter: index=2, jdbcType=VARCHAR, value=1 2004-06-15 15:04:58,867 204605 TRACE [org.jboss.ejb.plugins.cmp.jdbc.ReadAheadCache.User] (http-0.0.0.0-8080-Processor25:) Add preload data: entity=User pk=22 field=userName 2004-06-15 15:04:58,877 204615 TRACE [org.jboss.ejb.plugins.cmp.jdbc.ReadAheadCache.User] (http-0.0.0.0-8080-Processor25:) Add preload data: entity=User pk=22 field=startDate 2004-06-15 15:04:58,877 204615 TRACE [org.jboss.ejb.plugins.cmp.jdbc.ReadAheadCache.User] (http-0.0.0.0-8080-Processor25:) Add preload data: entity=User pk=22 field=endDate 2004-06-15 15:04:58,877 204615 TRACE [org.jboss.ejb.plugins.cmp.jdbc.ReadAheadCache.User] (http-0.0.0.0-8080-Processor25:) Add preload data: entity=User pk=22 field=createDate 2004-06-15 15:04:58,877 204615 TRACE [org.jboss.ejb.plugins.cmp.jdbc.ReadAheadCache.User] (http-0.0.0.0-8080-Processor25:) Add preload data: entity=User pk=22 field=updateDate 2004-06-15 15:04:58,877 204615 TRACE [org.jboss.ejb.plugins.cmp.jdbc.ReadAheadCache.User] (http-0.0.0.0-8080-Processor25:) Add preload data: entity=User pk=22 field=timeStamp 2004-06-15 15:04:58,877 204615 TRACE [org.jboss.ejb.plugins.cmp.jdbc.ReadAheadCache.User] (http-0.0.0.0-8080-Processor25:) Add preload data: entity=User pk=22 field=creatorUserId 2004-06-15 15:04:58,877 204615 TRACE [org.jboss.ejb.plugins.cmp.jdbc.ReadAheadCache.User] (http-0.0.0.0-8080-Processor25:) Add preload data: entity=User pk=22 field=updatorUserId 2004-06-15 15:04:58,877 204615 TRACE [org.jboss.ejb.plugins.cmp.jdbc.ReadAheadCache.User] (http-0.0.0.0-8080-Processor25:) Add preload data: entity=User pk=22 field=version 2004-06-15 15:04:58,877 204615 TRACE [org.jboss.ejb.plugins.cmp.jdbc.ReadAheadCache.User] (http-0.0.0.0-8080-Processor25:) Add preload data: entity=User pk=22 field=isObsolete 2004-06-15 15:04:58,877 204615 TRACE [org.jboss.ejb.plugins.cmp.jdbc.ReadAheadCache.User] (http-0.0.0.0-8080-Processor25:) Add preload data: entity=User pk=22 field=id 2004-06-15 15:04:58,877 204615 TRACE [org.jboss.ejb.plugins.cmp.jdbc.ReadAheadCache.User] (http-0.0.0.0-8080-Processor25:) Add preload data: entity=User pk=22 field=id 2004-06-15 15:04:58,897 204635 TRACE [org.jboss.ejb.plugins.EntityInstancePool] (http-0.0.0.0-8080-Processor25:) 0/100 Free instance:org.jboss.ejb.plugins.EntityInstancePool@1ee026e#null#null#false#class com.matrix.framework.ip.model.UserBean 2004-06-15 15:04:58,897 204635 TRACE [org.jboss.ejb.plugins.TxInterceptorCMT] (http-0.0.0.0-8080-Processor25:) TxInterceptorCMT: In finally 2004-06-15 15:04:58,897 204635 TRACE [org.jboss.ejb.plugins.LogInterceptor] (http-0.0.0.0-8080-Processor25:) End method=findByUserNameAndPassword 2004-06-15 15:04:58,907 204645 INFO [STDOUT] (http-0.0.0.0-8080-Processor25:) 15/06/2004 15:04:58 com.matrix.framework.infrastructure.controller.InnerBasicController getSingleTO INFO: in InnerBasicController.getSingleTO after finding beanLocal. 2004-06-15 15:04:59,087 204825 TRACE [org.jboss.ejb.plugins.ProxyFactoryFinderInterceptor] (http-0.0.0.0-8080-Processor25:) invokerBInding is null in ProxyFactoryFinder 2004-06-15 15:04:59,087 204825 TRACE [org.jboss.ejb.plugins.LogInterceptor] (http-0.0.0.0-8080-Processor25:) Start method=getId 2004-06-15 15:04:59,087 204825 TRACE [org.jboss.ejb.plugins.TxInterceptorCMT] (http-0.0.0.0-8080-Processor25:) Current transaction in MI is TransactionImpl:XidImpl [FormatId=257, GlobalId=norman//15, BranchQual=] 2004-06-15 15:04:59,087 204825 TRACE [org.jboss.ejb.plugins.TxInterceptorCMT] (http-0.0.0.0-8080-Processor25:) TX_NOT_SUPPORTED for getId 2004-06-15 15:04:59,087 204825 TRACE [org.jboss.ejb.plugins.TxInterceptorCMT] (http-0.0.0.0-8080-Processor25:) Thread came in with tx TransactionImpl:XidImpl [FormatId=257, GlobalId=norman//15, BranchQual=] 2004-06-15 15:04:59,087 204825 TRACE [org.jboss.ejb.plugins.EntityLockInterceptor] (http-0.0.0.0-8080-Processor25:) Begin invoke, key=22 2004-06-15 15:04:59,097 204835 TRACE [org.jboss.ejb.plugins.EntityInstancePool] (http-0.0.0.0-8080-Processor25:) Get instance org.jboss.ejb.plugins.EntityInstancePool@1ee026e#1#class com.matrix.framework.ip.model.UserBean 2004-06-15 15:04:59,117 204855 TRACE [org.jboss.ejb.plugins.EntityInstanceInterceptor] (http-0.0.0.0-8080-Processor25:) Begin invoke, key=22 2004-06-15 15:04:59,117 204855 TRACE [org.jboss.ejb.plugins.EntitySynchronizationInterceptor] (http-0.0.0.0-8080-Processor25:) invoke called for ctx User#22, tx=null 2004-06-15 15:04:59,117 204855 TRACE [org.jboss.ejb.plugins.cmp.jdbc.JDBCStoreManager.User] (http-0.0.0.0-8080-Processor25:) RESET PERSISTENCE CONTEXT: id=22 2004-06-15 15:04:59,127 204865 TRACE [org.jboss.ejb.plugins.cmp.jdbc.ReadAheadCache.User] (http-0.0.0.0-8080-Processor25:) load data: entity=User pk=22 2004-06-15 15:04:59,127 204865 TRACE [org.jboss.ejb.plugins.cmp.jdbc.ReadAheadCache.User] (http-0.0.0.0-8080-Processor25:) No preload data found: entity=User pk=22 2004-06-15 15:04:59,137 204875 TRACE [org.jboss.ejb.plugins.cmp.jdbc.bridge.JDBCEntityBridge.User] (http-0.0.0.0-8080-Processor25:) Default eager-load for entity: readahead=null 2004-06-15 15:04:59,147 204885 DEBUG [org.jboss.ejb.plugins.cmp.jdbc.JDBCLoadEntityCommand.User] (http-0.0.0.0-8080-Processor25:) Executing SQL: SELECT SIGNATURE, USER_PASSWORD, USER_NAME, START_DATE, END_DATE, CREATE_DATE, UPDATE_DATE, TIME_STAMP, CREATOR_USER_ID, UPDATOR_USER_ID, VERSION, IS_OBSOLETE, MANAGER_USER_ID, ORGANIZATION_ID, PERSON_ID FROM EMI_USER WHERE (ID=?) 2004-06-15 15:05:00,539 206277 TRACE [org.jboss.resource.connectionmanager.JBossManagedConnectionPool] (http-0.0.0.0-8080-Processor25:) supplying new ManagedConnection: org.jboss.resource.connectionmanager.TxConnectionManager$TxConnectionEventListener@164ad98[state=NORMAL mc=org.jboss.resource.adapter.jdbc.local.LocalManagedConnection@c0fee0 handles=0 lastUse=1087304700539 permit=false trackByTx=false mcp=org.jboss.resource.connectionmanager.JBossManagedConnectionPool$OnePool@ac0a60 context=org.jboss.resource.connectionmanager.InternalManagedConnectionPool@dd3147] 2004-06-15 15:05:00,539 206277 TRACE [org.jboss.resource.connectionmanager.JBossManagedConnectionPool] (http-0.0.0.0-8080-Processor25:) Getting connection from pool org.jboss.resource.connectionmanager.TxConnectionManager$TxConnectionEventListener@164ad98[state=NORMAL mc=org.jboss.resource.adapter.jdbc.local.LocalManagedConnection@c0fee0 handles=0 lastUse=1087304700539 permit=true trackByTx=false mcp=org.jboss.resource.connectionmanager.JBossManagedConnectionPool$OnePool@ac0a60 context=org.jboss.resource.connectionmanager.InternalManagedConnectionPool@dd3147] [InUse/Available/Max]: [2/18/20] 2004-06-15 15:05:00,539 206277 TRACE [org.jboss.ejb.plugins.cmp.jdbc.bridge.JDBCCMP2xFieldBridge.User#id] (http-0.0.0.0-8080-Processor25:) Set parameter: index=1, jdbcType=BIGINT, value=22 2004-06-15 15:05:00,719 206457 TRACE [org.jboss.ejb.plugins.cmp.jdbc.JDBCUtil] (http-0.0.0.0-8080-Processor25:) Get result: index=1, javaType=[B, Big Binary, value=null 2004-06-15 15:05:00,719 206457 TRACE [org.jboss.resource.connectionmanager.JBossManagedConnectionPool] (http-0.0.0.0-8080-Processor25:) putting ManagedConnection back into pool kill=false cl=org.jboss.resource.connectionmanager.TxConnectionManager$TxConnectionEventListener@164ad98[state=NORMAL mc=org.jboss.resource.adapter.jdbc.local.LocalManagedConnection@c0fee0 handles=0 lastUse=1087304700539 permit=true trackByTx=false mcp=org.jboss.resource.connectionmanager.JBossManagedConnectionPool$OnePool@ac0a60 context=org.jboss.resource.connectionmanager.InternalManagedConnectionPool@dd3147] 2004-06-15 15:05:00,719 206457 TRACE [org.jboss.resource.connectionmanager.JBossManagedConnectionPool] (http-0.0.0.0-8080-Processor25:) Returning connection to pool org.jboss.resource.connectionmanager.TxConnectionManager$TxConnectionEventListener@164ad98[state=NORMAL mc=org.jboss.resource.adapter.jdbc.local.LocalManagedConnection@c0fee0 handles=0 lastUse=1087304700719 permit=false trackByTx=false mcp=org.jboss.resource.connectionmanager.JBossManagedConnectionPool$OnePool@ac0a60 context=org.jboss.resource.connectionmanager.InternalManagedConnectionPool@dd3147] [InUse/Available/Max]: [1/19/20] 2004-06-15 15:05:00,729 206467 WARN [org.jboss.ejb.plugins.PerTxEntityInstanceCache] (http-0.0.0.0-8080-Processor25:) Unable to passivate due to ctx lock, id=22 2004-06-15 15:05:00,729 206467 TRACE [org.jboss.ejb.plugins.EntityInstanceInterceptor] (http-0.0.0.0-8080-Processor25:) End invoke, key=22, ctx=User#22 2004-06-15 15:05:00,729 206467 TRACE [org.jboss.ejb.plugins.EntityLockInterceptor] (http-0.0.0.0-8080-Processor25:) End invoke, key=22 2004-06-15 15:05:00,729 206467 TRACE [org.jboss.ejb.plugins.LogInterceptor] (http-0.0.0.0-8080-Processor25:) End method=getId 2004-06-15 15:05:00,749 206487 TRACE [org.jboss.ejb.plugins.ProxyFactoryFinderInterceptor] (http-0.0.0.0-8080-Processor25:) invokerBInding is null in ProxyFactoryFinder 2004-06-15 15:05:00,749 206487 TRACE [org.jboss.ejb.plugins.LogInterceptor] (http-0.0.0.0-8080-Processor25:) Start method=getSignature 2004-06-15 15:05:00,749 206487 TRACE [org.jboss.ejb.plugins.TxInterceptorCMT] (http-0.0.0.0-8080-Processor25:) Current transaction in MI is TransactionImpl:XidImpl [FormatId=257, GlobalId=norman//15, BranchQual=] 2004-06-15 15:05:00,749 206487 TRACE [org.jboss.ejb.plugins.TxInterceptorCMT] (http-0.0.0.0-8080-Processor25:) TX_REQUIRED for getSignature timeout=0 2004-06-15 15:05:00,749 206487 TRACE [org.jboss.ejb.plugins.TxInterceptorCMT] (http-0.0.0.0-8080-Processor25:) Thread came in with tx TransactionImpl:XidImpl [FormatId=257, GlobalId=norman//15, BranchQual=] 2004-06-15 15:05:00,749 206487 TRACE [org.jboss.ejb.plugins.EntityLockInterceptor] (http-0.0.0.0-8080-Processor25:) Begin invoke, key=22 2004-06-15 15:05:00,749 206487 TRACE [org.jboss.ejb.plugins.EntityInstancePool] (http-0.0.0.0-8080-Processor25:) Get instance org.jboss.ejb.plugins.EntityInstancePool@1ee026e#0#class com.matrix.framework.ip.model.UserBean 2004-06-15 15:05:00,749 206487 TRACE [org.jboss.ejb.plugins.EntityInstanceInterceptor] (http-0.0.0.0-8080-Processor25:) Begin invoke, key=22 2004-06-15 15:05:00,749 206487 TRACE [org.jboss.ejb.plugins.EntitySynchronizationInterceptor] (http-0.0.0.0-8080-Processor25:) invoke called for ctx User#22, tx=TransactionImpl:XidImpl [FormatId=257, GlobalId=norman//15, BranchQual=] 2004-06-15 15:05:00,749 206487 TRACE [org.jboss.ejb.plugins.cmp.jdbc.JDBCStoreManager.User] (http-0.0.0.0-8080-Processor25:) RESET PERSISTENCE CONTEXT: id=22 2004-06-15 15:05:00,749 206487 TRACE [org.jboss.ejb.plugins.cmp.jdbc.ReadAheadCache.User] (http-0.0.0.0-8080-Processor25:) load data: entity=User pk=22 2004-06-15 15:05:00,749 206487 TRACE [org.jboss.ejb.plugins.cmp.jdbc.ReadAheadCache.User] (http-0.0.0.0-8080-Processor25:) Preloading data: entity=User pk=22 cmpField=startDate 2004-06-15 15:05:00,749 206487 TRACE [org.jboss.ejb.plugins.cmp.jdbc.ReadAheadCache.User] (http-0.0.0.0-8080-Processor25:) Preloading data: entity=User pk=22 cmpField=version 2004-06-15 15:05:00,749 206487 TRACE [org.jboss.ejb.plugins.cmp.jdbc.ReadAheadCache.User] (http-0.0.0.0-8080-Processor25:) Preloading data: entity=User pk=22 cmpField=userName 2004-06-15 15:05:00,749 206487 TRACE [org.jboss.ejb.plugins.cmp.jdbc.ReadAheadCache.User] (http-0.0.0.0-8080-Processor25:) Preloading data: entity=User pk=22 cmpField=createDate 2004-06-15 15:05:00,749 206487 TRACE [org.jboss.ejb.plugins.cmp.jdbc.ReadAheadCache.User] (http-0.0.0.0-8080-Processor25:) Preloading data: entity=User pk=22 cmpField=updatorUserId 2004-06-15 15:05:00,749 206487 TRACE [org.jboss.ejb.plugins.cmp.jdbc.ReadAheadCache.User] (http-0.0.0.0-8080-Processor25:) Preloading data: entity=User pk=22 cmpField=id 2004-06-15 15:05:00,749 206487 TRACE [org.jboss.ejb.plugins.cmp.jdbc.ReadAheadCache.User] (http-0.0.0.0-8080-Processor25:) Preloading data: entity=User pk=22 cmpField=endDate 2004-06-15 15:05:00,749 206487 TRACE [org.jboss.ejb.plugins.cmp.jdbc.ReadAheadCache.User] (http-0.0.0.0-8080-Processor25:) Preloading data: entity=User pk=22 cmpField=isObsolete 2004-06-15 15:05:00,749 206487 TRACE [org.jboss.ejb.plugins.cmp.jdbc.ReadAheadCache.User] (http-0.0.0.0-8080-Processor25:) Preloading data: entity=User pk=22 cmpField=id 2004-06-15 15:05:00,749 206487 TRACE [org.jboss.ejb.plugins.cmp.jdbc.ReadAheadCache.User] (http-0.0.0.0-8080-Processor25:) Preloading data: entity=User pk=22 cmpField=creatorUserId 2004-06-15 15:05:00,749 206487 TRACE [org.jboss.ejb.plugins.cmp.jdbc.ReadAheadCache.User] (http-0.0.0.0-8080-Processor25:) Preloading data: entity=User pk=22 cmpField=timeStamp 2004-06-15 15:05:00,749 206487 TRACE [org.jboss.ejb.plugins.cmp.jdbc.ReadAheadCache.User] (http-0.0.0.0-8080-Processor25:) Preloading data: entity=User pk=22 cmpField=updateDate 2004-06-15 15:05:00,749 206487 TRACE [org.jboss.ejb.plugins.EntitySynchronizationInterceptor] (http-0.0.0.0-8080-Processor25:) register, ctx=User#22, tx=TransactionImpl:XidImpl [FormatId=257, GlobalId=norman//15, BranchQual=] 2004-06-15 15:05:00,779 206517 TRACE [org.jboss.ejb.plugins.cmp.jdbc.ReadAheadCache.User] (http-0.0.0.0-8080-Processor25:) load data: entity=User pk=22 2004-06-15 15:05:00,779 206517 TRACE [org.jboss.ejb.plugins.cmp.jdbc.ReadAheadCache.User] (http-0.0.0.0-8080-Processor25:) No preload data found: entity=User pk=22 2004-06-15 15:05:00,779 206517 DEBUG [org.jboss.ejb.plugins.cmp.jdbc.JDBCLoadEntityCommand.User] (http-0.0.0.0-8080-Processor25:) Executing SQL: SELECT SIGNATURE FROM EMI_USER WHERE (ID=?) 2004-06-15 15:05:00,779 206517 TRACE [org.jboss.resource.connectionmanager.JBossManagedConnectionPool] (http-0.0.0.0-8080-Processor25:) Getting connection tracked by transaction org.jboss.resource.connectionmanager.TxConnectionManager$TxConnectionEventListener@591a4d[state=NORMAL mc=org.jboss.resource.adapter.jdbc.local.LocalManagedConnection@1cdd63c handles=0 lastUse=1087304638189 permit=true trackByTx=true mcp=org.jboss.resource.connectionmanager.JBossManagedConnectionPool$OnePool@ac0a60 context=org.jboss.resource.connectionmanager.InternalManagedConnectionPool@dd3147] [InUse/Available/Max]: [1/19/20] 2004-06-15 15:05:00,779 206517 TRACE [org.jboss.ejb.plugins.cmp.jdbc.bridge.JDBCCMP2xFieldBridge.User#id] (http-0.0.0.0-8080-Processor25:) Set parameter: index=1, jdbcType=BIGINT, value=22 2004-06-15 15:05:00,950 206688 TRACE [org.jboss.ejb.plugins.cmp.jdbc.JDBCUtil] (http-0.0.0.0-8080-Processor25:) Get result: index=1, javaType=[B, Big Binary, value=null 2004-06-15 15:05:00,950 206688 TRACE [org.jboss.ejb.plugins.EntitySynchronizationInterceptor] (http-0.0.0.0-8080-Processor25:) register, ctx=User#22, tx=TransactionImpl:XidImpl [FormatId=257, GlobalId=norman//15, BranchQual=] 2004-06-15 15:05:00,950 206688 TRACE [org.jboss.ejb.plugins.EntityInstanceInterceptor] (http-0.0.0.0-8080-Processor25:) End invoke, key=22, ctx=User#22 2004-06-15 15:05:00,950 206688 TRACE [org.jboss.ejb.plugins.EntityLockInterceptor] (http-0.0.0.0-8080-Processor25:) End invoke, key=22 2004-06-15 15:05:00,950 206688 TRACE [org.jboss.ejb.plugins.TxInterceptorCMT] (http-0.0.0.0-8080-Processor25:) TxInterceptorCMT: In finally 2004-06-15 15:05:00,950 206688 TRACE [org.jboss.ejb.plugins.LogInterceptor] (http-0.0.0.0-8080-Processor25:) End method=getSignature
There are more lines like that ahead for each getSomething from this bean. I don't understand what's going on. what my application does is after it has the userLocal it copies parameters from this bean into a Transport object (this is why there the getId, getSignature and more like it in the log). This is done within the same transaction. The first thing I don't understand is why jboss selects from the database again each time? It has already selected the stuff on the finder? don't we have cache?