5 Replies Latest reply on Apr 12, 2005 12:35 PM by Carl Bradbury

    Deja Vu.... Unable to passivate due to ctx lock

    gavinandrews Newbie

      We use 3.2.5 with Standard CMP but with Commit Option D on a 120 second timer...

      Once in a while (every week or so) we get very odd behaviour...

      Essentially our application processes a request, changes some entities and then sends a latest image of our entity out on a JMS message bus. 99.999% of the time this works fine however every now and again it seems that the 'before image' is the one that gets broadcast rather than the 'after image'. If I look at the database I can see the transaction completed properly; it is just the JMS image wasn't the same as the one which was eventually persisted...

      If I check the logs I always see a...

      2005-02-01 08:25:10,306 WARN [org.jboss.ejb.plugins.AbstractInstanceCache] Unable to passivate due to ctx lock, id=53961

      message... these messages *ALWAYS* co-inside with this behaviour.

      Any ideas???

      Thanks in advance,
      Gavin

        • 1. Re: Deja Vu.... Unable to passivate due to ctx lock
          gavinandrews Newbie

          <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 Newbie

            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 Newbie

              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
                Carl Bradbury Newbie

                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
                  Carl Bradbury Newbie

                  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=[]