-
1. Re: Deja Vu.... Unable to passivate due to ctx lock
gavinandrews Feb 1, 2005 12:23 PM (in response to gavinandrews)<container-configuration>
<container-name>Standard CMP 2.x EntityBean</container-name>
<call-logging>false</call-logging>
<invoker-proxy-binding-name>entity-rmi-invoker</invoker-proxy-binding-name>
<sync-on-commit-only>false</sync-on-commit-only>
<insert-after-ejb-post-create>false</insert-after-ejb-post-create>
<container-interceptors>
org.jboss.ejb.plugins.ProxyFactoryFinderInterceptor
org.jboss.ejb.plugins.LogInterceptor
org.jboss.ejb.plugins.SecurityInterceptor
org.jboss.ejb.plugins.TxInterceptorCMT
org.jboss.ejb.plugins.MetricsInterceptor
org.jboss.ejb.plugins.EntityCreationInterceptor
org.jboss.ejb.plugins.EntityLockInterceptor
org.jboss.ejb.plugins.EntityInstanceInterceptor
org.jboss.ejb.plugins.EntityReentranceInterceptor
org.jboss.resource.connectionmanager.CachedConnectionInterceptor
org.jboss.ejb.plugins.EntitySynchronizationInterceptor
org.jboss.ejb.plugins.cmp.jdbc.JDBCRelationInterceptor
</container-interceptors>
<instance-pool>org.jboss.ejb.plugins.EntityInstancePool</instance-pool>
<instance-cache>org.jboss.ejb.plugins.InvalidableEntityInstanceCache</instance-cache>
<persistence-manager>org.jboss.ejb.plugins.cmp.jdbc.JDBCStoreManager</persistence-manager>
<locking-policy>org.jboss.ejb.plugins.lock.QueuedPessimisticEJBLock</locking-policy>
<container-cache-conf>
<cache-policy>org.jboss.ejb.plugins.LRUEnterpriseContextCachePolicy</cache-policy>
<cache-policy-conf>
<min-capacity>50</min-capacity>
<max-capacity>1000000</max-capacity>
<overager-period>300</overager-period>
<max-bean-age>600</max-bean-age>
<resizer-period>400</resizer-period>
<max-cache-miss-period>60</max-cache-miss-period>
<min-cache-miss-period>1</min-cache-miss-period>
<cache-load-factor>0.75</cache-load-factor>
</cache-policy-conf>
</container-cache-conf>
<container-pool-conf>
100
</container-pool-conf>
<commit-option>D</commit-option>
<optiond-refresh-rate>120</optiond-refresh-rate>
</container-configuration> -
2. Re: Deja Vu.... Unable to passivate due to ctx lock
gavinandrews Feb 1, 2005 12:24 PM (in response to gavinandrews)I have used...
<instance-cache>org.jboss.ejb.plugins.InvalidableEntityInstanceCache</instance-cache>
Perhaps this is not appropriate for <commit-option>D</commit-option>
??? -
3. Re: Deja Vu.... Unable to passivate due to ctx lock
gavinandrews Apr 11, 2005 8:09 AM (in response to gavinandrews)Back to this topic after a while away....
It seems that when JBOSS goes to flush the cache it causes the "Unable to passivate due to ctx lock" warning. At the same time a transaction is in progress. The second part of the transaction seems to see a version of the entity bean that pre-dates the changes made early in the transaction.
This suggests that somewhere along the line a new bean instance has been created which is now out of date with respect to the running transaction.
Anyone else using Commit Option D and not seeing dirty reads??
TIA,
Gavin -
4. Re: Deja Vu.... Unable to passivate due to ctx lock
cbradbury Apr 12, 2005 11:21 AM (in response to gavinandrews)I have performed some testing on Gavin's system using an application that performs alot of UPDATEs on a single entity. It basically sets and unsets a ReservedBy field, as shown in the logs below.
Eventually one of the updates appears to collide with the cache's timer process that is set by the <optiond-refresh-rate> configuration parameter. The cache seems to be trying to reload the bean whilst the UPDATE process still has a lock on it, or vice versa.
This seems to be an ineffeciency of the JBoss cache that needs addressing.
Here are the Log4j logs. My comments are in brackets {}.
{Here's an UPDATE performing smoothly...}
15:17:06,003 DEBUG [JDBCStoreEntityCommand.BorisOrderEntity] Executing SQL: UPDATE BorisOrder SET ReservedBy=? WHERE OrderId=?
15:17:06,003 TRACE [JDBCCMP2xFieldBridge.BorisOrderEntity#reservedBy] Set parameter: index=1, jdbcType=VARCHAR, value=testuser
15:17:06,003 TRACE [JDBCCMP2xFieldBridge.BorisOrderEntity#orderId] Set parameter: index=2, jdbcType=INTEGER, value=59856
{Now the cache refresh kicks in, but the update still has the lock?...}
15:17:06,050 WARN [AbstractInstanceCache] Unable to passivate due to ctx lock, id=59856
15:17:06,128 DEBUG [JDBCFindByPrimaryKeyQuery.BorisOrderEntity#findByPrimaryKey] Executing SQL: SELECT t0_BorisOrderEntity.OrderId FROM BorisOrder t0_BorisOrderEntity
WHERE t0_BorisOrderEntity.OrderId=?
15:17:06,128 TRACE [JDBCFindByPrimaryKeyQuery.BorisOrderEntity#findByPrimaryKey] Set parameter: index=1, jdbcType=INTEGER, value=59856
15:17:06,128 TRACE [JDBCStoreManager.BorisOrderEntity] RESET PERSISTENCE CONTEXT: id=59856
15:17:06,128 TRACE [ReadAheadCache.BorisOrderEntity] load data: entity=BorisOrderEntity pk=59856
15:17:06,128 TRACE [ReadAheadCache.BorisOrderEntity] No preload data found: entity=BorisOrderEntity pk=59856
15:17:06,128 TRACE [JDBCEntityBridge.BorisOrderEntity] Default eager-load for entity: readahead=null
15:17:06,128 DEBUG [JDBCLoadEntityCommand.BorisOrderEntity] Executing SQL: SELECT {snip! params removed for brevity} FROM BorisOrder WHERE (OrderId=?)
15:17:06,144 TRACE [JDBCCMP2xFieldBridge.BorisOrderEntity#orderId] Set parameter: index=1, jdbcType=INTEGER, value=59856
15:17:06,144 TRACE [JDBCCMRFieldBridge.orderProperties] Read ahead cahce load: cmrField=orderProperties pk=59856
15:17:06,144 TRACE [ReadAheadCache.BorisOrderEntity] load data: entity=BorisOrderEntity pk=59856
15:17:06,144 TRACE [ReadAheadCache.BorisOrderEntity] No preload data found: entity=BorisOrderEntity pk=59856
15:17:06,144 DEBUG [JDBCLoadRelationCommand.BorisOrderEntity] load relation SQL: SELECT OrderPropertyId FROM BorisOrderProperty WHERE (OrderEntity=?)
15:17:06,144 TRACE [JDBCCMP2xFieldBridge.BorisOrderPropertyEntity#orderId] Set parameter: index=1, jdbcType=INTEGER, value=59856
{Danger over. Next UPDATE proceeds as planned...}
15:17:06,144 DEBUG [JDBCStoreEntityCommand.BorisOrderEntity] Executing SQL: UPDATE BorisOrder SET ReservedBy=? WHERE OrderId=?
15:17:06,160 TRACE [JDBCCMP2xFieldBridge.BorisOrderEntity#reservedBy] Set parameter: index=1, jdbcType=VARCHAR, value=
15:17:06,160 TRACE [JDBCCMP2xFieldBridge.BorisOrderEntity#orderId] Set parameter: index=2, jdbcType=INTEGER, value=59856
{And the next one too, etc, etc...}
15:17:06,191 DEBUG [JDBCStoreEntityCommand.BorisOrderEntity] Executing SQL: UPDATE BorisOrder SET ReservedBy=? WHERE OrderId=?
15:17:06,191 TRACE [JDBCCMP2xFieldBridge.BorisOrderEntity#reservedBy] Set parameter: index=1, jdbcType=VARCHAR, value=testuser
15:17:06,191 TRACE [JDBCCMP2xFieldBridge.BorisOrderEntity#orderId] Set parameter: index=2, jdbcType=INTEGER, value=59856 -
5. Re: Deja Vu.... Unable to passivate due to ctx lock
cbradbury Apr 12, 2005 12:35 PM (in response to gavinandrews)A bit of further testing on JBoss 4.0.1 revealed that this problem still occurs, but It seems it's not just limited to the one entity being updated by my test class.
Our decision to use Commit Option D and QueuedPessimisticEJBLock might have something to do with it.
The error seems to occur more often in JBoss 4.0.1 than it did in 3.2.5. Here's an example of where the BeanLockManager takes out a lock on the InstrumentPriceEntity EJB, the AbstractInstanceCache tries to preload the bean in the cache (causing the error) and then the lock is released by the BeanLockManager.
This explains why we are seeing some strange behavior. The locked version of the entity is what gets updated and sent via JMS. The version in the cache is left empty, because the AbstractInstanceCache couldn't preload it, therefore the next time our application tries to via that entity, it sees an empty version.
Needless to say the affected entity is invalid in this state which causes a great deal of havoc.
We can't give JBoss sole access to the database, so commit option A is not an option. Is there any way we can change the locking mechanism to avoid this?
17:04:14,294 TRACE [BeanLockManager] Added ref to lock: org.jboss.ejb.plugins.lock.QueuedPessimisticEJBLock@344422, bean=InstrumentPriceEntity, id=1, refs=2, tx=TransactionImpl:XidImpl[FormatId=257, GlobalId=, BranchQual=, localId=], synched=null, timeout=5000, queue=[]
17:04:14,294 TRACE [InstrumentPriceEntity] Preloading data: entity=InstrumentPriceEntity pk=2614 cmpField=manualMaxSellAutoExec2
17:04:14,294 WARN [AbstractInstanceCache] Unable to passivate due to ctx lock, id=1
17:04:14,294 TRACE [InstrumentPriceEntity] Preloading data: entity=InstrumentPriceEntity pk=2614 cmpField=manualMaxBuyAutoQuote1
17:04:14,294 TRACE [BeanLockManager] Remove ref lock:org.jboss.ejb.plugins.lock.QueuedPessimisticEJBLock@344422, bean=InstrumentPriceEntity, id=1, refs=1, tx=TransactionImpl:XidImpl[FormatId=257, GlobalId=, BranchQual=, localId=], synched=null, timeout=5000, queue=[]