8 Replies Latest reply on Jan 22, 2008 3:52 PM by Manik Surtani

    org.jboss.cache.lock.TimeoutException thrown in second insta

    Russ Burke Newbie

      When we startup another one of our web applications on a second instance in a cluster we get an org.jboss.cache.lock.TimeoutException thrown by org.jboss.cache.lock.IdentityLock. It seems that IdentityLock is attempting to acquire a WL when attempting to cache the query below but there is already a lock on the node /org/hibernate/cache/StandardQueryCache/sql, probably in the first instance. This application is running on Resin 3.1.2. We are using Hibernate 3.2.3 and JBoss cache 1.4.0.SP1. We have Hibernate configured to use a query and second level cache which is org.hibernate.cache.TreeCacheProvider, the JBoss TreeCache. We have the JBoss TreeCache to use the pessimistic locking scheme, the node isolation level is REPEATABLE_READ and the cache mode is LOCAL.

      How do we resolve this problem?

      Please let me know if you need further information from me.

      Stack trace:

      [14:10:41,302] ERROR [pool-9-thread-8] IdentityLock : write lock for /org/hibernate/cache/StandardQueryCache/sql: select searchro
      ut0_.ID as ID28_, searchrout0_.hotel_code as hotel2_28_, searchrout0_.hotel_lat as hotel3_28_, searchrout0_.hotel_long as hotel4_28_
      , searchrout0_.destination_name as destinat5_28_, searchrout0_.destination_lat as destinat6_28_, searchrout0_.destination_long as de
      stinat7_28_, searchrout0_.distance_miles as distance8_28_, searchrout0_.distance_km as distance9_28_, searchrout0_.route_type as rou
      te10_28_ from UA_MQ_HOTEL_DESTINATION_ROUTE searchrout0_ where searchrout0_.hotel_code=? and searchrout0_.hotel_lat=? and searchrout
      0_.hotel_long=? and searchrout0_.destination_lat=? and searchrout0_.destination_long=? and searchrout0_.route_type=?; parameters: ;
      named parameters: {hotelCode=JMBNJ, hotelLong=-74.4783, routeType=2, hotelLat=40.3444, destinationLong=-75.164199, destinationLat=39
      .952201} could not be acquired after 0 ms. Locks: Read lock owners: []
      Write lock owner: null
      (caller=Thread[pool-9-thread-8,5,main], lock info: (activeReaders=0, activeWriter=null, waitingReaders=0, waitingWriters
      =0, waitingUpgrader=0))
      [14:10:41,305] INFO [pool-9-thread-8] TxInterceptor : There was a problem handling this request
      org.jboss.cache.lock.TimeoutException: failure acquiring lock: fqn=/org/hibernate/cache/StandardQueryCache/sql: select searchrout0_.
      ID as ID28_, searchrout0_.hotel_code as hotel2_28_, searchrout0_.hotel_lat as hotel3_28_, searchrout0_.hotel_long as hotel4_28_, sea
      rchrout0_.destination_name as destinat5_28_, searchrout0_.destination_lat as destinat6_28_, searchrout0_.destination_long as destina
      t7_28_, searchrout0_.distance_miles as distance8_28_, searchrout0_.distance_km as distance9_28_, searchrout0_.route_type as route10_
      28_ from UA_MQ_HOTEL_DESTINATION_ROUTE searchrout0_ where searchrout0_.hotel_code=? and searchrout0_.hotel_lat=? and searchrout0_.ho
      tel_long=? and searchrout0_.destination_lat=? and searchrout0_.destination_long=? and searchrout0_.route_type=?; parameters: ; named
      parameters: {hotelCode=JMBNJ, hotelLong=-74.4783, routeType=2, hotelLat=40.3444, destinationLong=-75.164199, destinationLat=39.9522
      01}, caller=Thread[pool-9-thread-8,5,main], lock= (activeReaders=0, activeWriter=null, waitingReaders=0, waitingWriters=0,
      waitingUpgrader=0)
      at org.jboss.cache.Node.acquire(Node.java:407)
      at org.jboss.cache.interceptors.PessimisticLockInterceptor.lock(PessimisticLockInterceptor.java:228)
      at org.jboss.cache.interceptors.PessimisticLockInterceptor.invoke(PessimisticLockInterceptor.java:160)
      at org.jboss.cache.interceptors.Interceptor.invoke(Interceptor.java:68)
      at org.jboss.cache.interceptors.UnlockInterceptor.invoke(UnlockInterceptor.java:32)
      at org.jboss.cache.interceptors.Interceptor.invoke(Interceptor.java:68)
      at org.jboss.cache.interceptors.TxInterceptor.handleNonTxMethod(TxInterceptor.java:345)
      at org.jboss.cache.interceptors.TxInterceptor.invoke(TxInterceptor.java:156)
      at org.jboss.cache.interceptors.Interceptor.invoke(Interceptor.java:68)
      at org.jboss.cache.interceptors.CacheMgmtInterceptor.invoke(CacheMgmtInterceptor.java:157)
      at org.jboss.cache.TreeCache.invokeMethod(TreeCache.java:5520)
      at org.jboss.cache.TreeCache.putFailFast(TreeCache.java:3643)
      at org.hibernate.cache.TreeCache.put(TreeCache.java:74)
      at org.hibernate.cache.StandardQueryCache.put(StandardQueryCache.java:87)
      at org.hibernate.loader.Loader.putResultInQueryCache(Loader.java:2194)
      at org.hibernate.loader.Loader.listUsingQueryCache(Loader.java:2138)
      at org.hibernate.loader.Loader.list(Loader.java:2096)
      at org.hibernate.loader.hql.QueryLoader.list(QueryLoader.java:378)
      at org.hibernate.hql.ast.QueryTranslatorImpl.list(QueryTranslatorImpl.java:338)
      at org.hibernate.engine.query.HQLQueryPlan.performList(HQLQueryPlan.java:172)
      at org.hibernate.impl.SessionImpl.list(SessionImpl.java:1121)
      at org.hibernate.impl.QueryImpl.list(QueryImpl.java:79)
      at com.ihg.dec.framework.dataAccessServices.hibernate.HibernateOperation.execGetListNamedQuery(HibernateOperation.java:208)
      at com.ihg.dec.framework.dataAccessServices.hibernate.destination.search.HibernateSearchResultDAO.getSearchRoute(HibernateSe
      archResultDAO.java:219)
      at com.ihg.dec.framework.dataAccessServices.cacheable.destination.search.CacheableSearchResultDAO$4.retreiveCachedObject(Cac
      heableSearchResultDAO.java:156)
      at com.ihg.dec.framework.dataAccessServices.cacheable.destination.search.CacheableSearchResultDAO$4.retreiveCachedObject(Cac
      heableSearchResultDAO.java:153)
      at com.ihg.dec.framework.dataAccessServices.cacheable.AbstractCacheableDAO.getCachedObject(AbstractCacheableDAO.java:429)
      at com.ihg.dec.framework.dataAccessServices.cacheable.AbstractProxiedCacheableDAO.getProxiedCachedObject(AbstractProxiedCach
      eableDAO.java:56)
      at com.ihg.dec.framework.dataAccessServices.cacheable.destination.search.CacheableSearchResultDAO.getSearchRoute(CacheableSe
      archResultDAO.java:150)
      at com.ihg.dec.framework.businessServices.hotel.delegates.SearchDelegate.fillDistanceFromSearchResultDAO(SearchDelegate.java
      :975)
      at com.ihg.dec.framework.businessServices.hotel.delegates.SearchDelegate.fillDistanceInformation(SearchDelegate.java:904)
      at com.ihg.dec.framework.businessServices.hotel.delegates.SearchDelegate.fillHotelInformation(SearchDelegate.java:792)
      at com.ihg.dec.framework.businessServices.hotel.delegates.SearchDelegate.constructHotelSearchResultSet(SearchDelegate.java:1
      250)
      at com.ihg.dec.framework.businessServices.hotel.delegates.SearchDelegate.search(SearchDelegate.java:159)
      at com.ihg.dec.framework.businessServices.hotel.delegates.SearchDelegate.searchWithFilterAndSort(SearchDelegate.java:1448)
      at com.ihg.dec.framework.businessServices.hotel.HotelSearchBO.findHotels(HotelSearchBO.java:65)
      at sun.reflect.GeneratedMethodAccessor195.invoke(Unknown Source)
      at sun.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:25)
      at java.lang.reflect.Method.invoke(Method.java:585)
      at com.ihg.dec.framework.businessServices.BusinessObjectProxy.invoke_aroundBody0(BusinessObjectProxy.java:111)
      at com.ihg.dec.framework.businessServices.BusinessObjectProxy$AjcClosure1.run(BusinessObjectProxy.java:1)
      at com.ihg.dec.aop.statistics.businessServices.BusinessObjectProxyStatisticCollector.ajc$around$com_ihg_dec_aop_statistics_b
      usinessServices_BusinessObjectProxyStatisticCollector$1$640f34fproceed(BusinessObjectProxyStatisticCollector.aj:1)
      at com.ihg.dec.aop.statistics.businessServices.BusinessObjectProxyStatisticCollector$1.callProceed(BusinessObjectProxyStatis
      ticCollector.aj:39)
      at com.ihg.dec.aop.statistics.AbstractStatisticCollector.callObjectProxy(AbstractStatisticCollector.aj:49)
      at com.ihg.dec.aop.statistics.businessServices.BusinessObjectProxyStatisticCollector.ajc$around$com_ihg_dec_aop_statistics_b
      usinessServices_BusinessObjectProxyStatisticCollector$1$640f34f(BusinessObjectProxyStatisticCollector.aj:36)
      at com.ihg.dec.framework.businessServices.BusinessObjectProxy.invoke(BusinessObjectProxy.java:94)
      at $Proxy15.findHotels(Unknown Source)
      at com.ihg.dec.framework.runtime.cacheWarmer.HotelSearchCacheWarmer$HotelSearchWarmTask.call(HotelSearchCacheWarmer.java:168
      )
      at com.ihg.dec.framework.runtime.cacheWarmer.HotelSearchCacheWarmer$HotelSearchWarmTask.call(HotelSearchCacheWarmer.java:128
      )
      at java.util.concurrent.FutureTask$Sync.innerRun(FutureTask.java:269)
      at java.util.concurrent.FutureTask.run(FutureTask.java:123)
      at java.util.concurrent.ThreadPoolExecutor$Worker.runTask(ThreadPoolExecutor.java:650)
      at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:675)
      at java.lang.Thread.run(Thread.java:595)
      Caused by: org.jboss.cache.lock.TimeoutException: write lock for /org/hibernate/cache/StandardQueryCache/sql: select searchrout0_.ID
      as ID28_, searchrout0_.hotel_code as hotel2_28_, searchrout0_.hotel_lat as hotel3_28_, searchrout0_.hotel_long as hotel4_28_, searc
      hrout0_.destination_name as destinat5_28_, searchrout0_.destination_lat as destinat6_28_, searchrout0_.destination_long as destinat7
      _28_, searchrout0_.distance_miles as distance8_28_, searchrout0_.distance_km as distance9_28_, searchrout0_.route_type as route10_28
      _ from UA_MQ_HOTEL_DESTINATION_ROUTE searchrout0_ where searchrout0_.hotel_code=? and searchrout0_.hotel_lat=? and searchrout0_.hote
      l_long=? and searchrout0_.destination_lat=? and searchrout0_.destination_long=? and searchrout0_.route_type=?; parameters: ; named p
      arameters: {hotelCode=JMBNJ, hotelLong=-74.4783, routeType=2, hotelLat=40.3444, destinationLong=-75.164199, destinationLat=39.952201
      } could not be acquired after 0 ms. Locks: Read lock owners: []
      Write lock owner: null
      (caller=Thread[pool-9-thread-8,5,main], lock info: (activeReaders=0, activeWriter=null, waitingReaders=0, waitingWriters
      =0, waitingUpgrader=0))
      at org.jboss.cache.lock.IdentityLock.acquireWriteLock(IdentityLock.java:202)
      at org.jboss.cache.Node.acquireWriteLock(Node.java:431)
      at org.jboss.cache.Node.acquire(Node.java:386)


      Hibernate configuration:

      <!DOCTYPE hibernate-configuration PUBLIC
       "-//Hibernate/Hibernate Configuration DTD 3.0//EN"
       "http://hibernate.sourceforge.net/hibernate-configuration-3.0.dtd">
      
      <hibernate-configuration>
       <session-factory>
       <property name="show_sql">false</property>
       <property name="connection.datasource">java:comp/env/jdbc/oracle</property>
       <property name="dialect">
       org.hibernate.dialect.Oracle9Dialect
       </property>
       <property name="cache.provider_class">
       org.hibernate.cache.TreeCacheProvider
       </property>
       <property name="cache.use_query_cache">true</property>
       <property name="cache.use_second_level_cache">true</property>
       <property name="transaction.manager_lookup_class">
       org.hibernate.transaction.ResinTransactionManagerLookup
       </property>
       <property name="transaction.factory_class">
       org.hibernate.transaction.JTATransactionFactory
       </property>
       </session-factory>
      </hibernate-configuration>
      


      JBoss TreeCache configuration:

      
      <?xml version="1.0" encoding="UTF-8"?>
      
      <!-- ===================================================================== -->
      <!-- -->
      <!-- TreeCache Service Configuration -->
      <!-- -->
      <!-- ===================================================================== -->
      
      <server>
      
       <classpath codebase="./lib" archives="jboss-cache.jar" />
      
      
       <!-- ==================================================================== -->
       <!-- Defines TreeCache configuration -->
       <!-- ==================================================================== -->
      
       <mbean code="org.jboss.cache.TreeCache"
       name="jboss.cache:service=TreeCache">
      
       <depends>jboss:service=Naming</depends>
      
       <!--
       Configure the TransactionManager
       -->
       <!--
       Node locking scheme:
       OPTIMISTIC
       PESSIMISTIC (default)
       -->
       <attribute name="NodeLockingScheme">PESSIMISTIC</attribute>
      
       <attribute name="FetchInMemoryState">false</attribute>
       <attribute name="FetchPersistentState">false</attribute>
      
       <!--
       Node isolation level : SERIALIZABLE
       REPEATABLE_READ (default)
       READ_COMMITTED
       READ_UNCOMMITTED
       NONE
       -->
       <attribute name="IsolationLevel">REPEATABLE_READ</attribute>
       <!--
       Valid modes are LOCAL
       REPL_ASYNC
       REPL_SYNC
       -->
       <attribute name="CacheMode">LOCAL</attribute>
      
       <!-- Whether each interceptor should have an mbean
       registered to capture and display its statistics. -->
       <attribute name="UseInterceptorMbeans">true</attribute>
      
       <!--
       The max amount of time (in milliseconds) we wait until the
       initial state (ie. the contents of the cache) are retrieved from
       existing members in a clustered environment
       -->
       <attribute name="InitialStateRetrievalTimeout">
       100000
       </attribute>
      
       <!--
       Number of milliseconds to wait until all responses for a
       synchronous call have been received.
       -->
       <attribute name="SyncReplTimeout">10000</attribute>
      
       <!-- Max number of milliseconds to wait for a lock acquisition -->
       <attribute name="LockAcquisitionTimeout">60000</attribute>
      
       <!-- Name of the eviction policy class. -->
       <attribute name="EvictionPolicyClass">
       org.jboss.cache.eviction.LRUPolicy
       </attribute>
      
       <!-- Specific eviction policy configurations. This is LRU -->
       <attribute name="EvictionPolicyConfig">
       <config>
       <attribute name="wakeUpIntervalSeconds">5</attribute>
       <!-- Cache wide default -->
       <region name="/_default_">
       <attribute name="maxNodes">5000</attribute>
       <attribute name="timeToLiveSeconds">3600</attribute>
       <attribute name="maxAgeSeconds">43200</attribute>
       </region>
      
       <region name="/cro/numbers">
       <attribute name="maxNodes">50000</attribute>
       <attribute name="timeToLiveSeconds">3600</attribute>
       <attribute name="maxAgeSeconds">43200</attribute>
       </region>
      
       <region name="/hotels/detail">
       <attribute name="maxNodes">2000</attribute>
       <attribute name="timeToLiveSeconds">
       14400
       </attribute>
       <attribute name="maxAgeSeconds">43200</attribute>
       </region>
      
       <!-- Vales based on that we are not properly clearing the cache after a data load -->
       <region name="/hotels/sales/features">
       <attribute name="maxNodes">5000</attribute>
       <attribute name="timeToLiveSeconds">
       14400
       </attribute>
       <attribute name="maxAgeSeconds">21600</attribute>
       </region>
      
       <region name="/hotels/sales/help">
       <attribute name="maxNodes">5000</attribute>
       <attribute name="timeToLiveSeconds">
       14400
       </attribute>
       <attribute name="maxAgeSeconds">21600</attribute>
       </region>
      
       <region name="/hotels/geocode">
       <attribute name="maxNodes">5000</attribute>
       <attribute name="timeToLiveSeconds">86400</attribute>
       <attribute name="maxAgeSeconds">86400</attribute>
       </region>
      
       <region name="/hotels/search/addresses">
       <attribute name="maxNodes">5000</attribute>
       <attribute name="timeToLiveSeconds">
       14400
       </attribute>
       <attribute name="maxAgeSeconds">43200</attribute>
       </region>
      
       <region name="/destination/searchResult">
       <attribute name="maxNodes">5000</attribute>
       <attribute name="timeToLiveSeconds">
       14400
       </attribute>
       <attribute name="maxAgeSeconds">43200</attribute>
       </region>
      
       <region name="/destination/searchRoute">
       <attribute name="maxNodes">5000</attribute>
       <attribute name="timeToLiveSeconds">
       14400
       </attribute>
       <attribute name="maxAgeSeconds">43200</attribute>
       </region>
      
       <region name="/hotels/search/hotels">
       <attribute name="maxNodes">50000</attribute>
       <attribute name="timeToLiveSeconds">
       14400
       </attribute>
       <attribute name="maxAgeSeconds">86400</attribute>
       </region>
      
       <region name="/lookup/countryCollections">
       <attribute name="maxNodes">50000</attribute>
       <attribute name="timeToLiveSeconds">
       21600
       </attribute>
       <attribute name="maxAgeSeconds">86400</attribute>
       </region>
      
       <region name="/lookup/stateCollections">
       <attribute name="maxNodes">50000</attribute>
       <attribute name="timeToLiveSeconds">
       21600
       </attribute>
       <attribute name="maxAgeSeconds">86400</attribute>
       </region>
      
       <region name="/lookup/pointsOfInterests">
       <attribute name="maxNodes">50000</attribute>
       <attribute name="timeToLiveSeconds">
       21600
       </attribute>
       <attribute name="maxAgeSeconds">86400</attribute>
       </region>
      
       <region name="/teasers">
       <attribute name="maxNodes">50000</attribute>
       <attribute name="timeToLiveSeconds">3600</attribute>
       <attribute name="maxAgeSeconds">259200</attribute>
       </region>
      
       <region name="/urlmanager">
       <attribute name="maxNodes">50000</attribute>
       <attribute name="timeToLiveSeconds">3600</attribute>
       <attribute name="maxAgeSeconds">43200</attribute>
       </region>
      
      
       <region name="/rate/RateCategory">
       <attribute name="maxNodes">1500</attribute>
       <attribute name="timeToLiveSeconds">
       604800
       </attribute>
       <attribute name="maxAgeSeconds">604800</attribute>
       </region>
       <region name="/b2b/displayableText">
       <attribute name="maxNodes">1000</attribute>
       <attribute name="timeToLiveSeconds">
       604800
       </attribute>
       <attribute name="maxAgeSeconds">604800</attribute>
       </region>
       <region name="/b2b/client">
       <attribute name="maxNodes">1000</attribute>
       <attribute name="timeToLiveSeconds">
       604800
       </attribute>
       <attribute name="maxAgeSeconds">604800</attribute>
       </region>
       <region name="/b2b/codes">
       <attribute name="maxNodes">1000</attribute>
       <attribute name="timeToLiveSeconds">
       604800
       </attribute>
       <attribute name="maxAgeSeconds">604800</attribute>
       </region>
       <region name="/b2b/errors">
       <attribute name="maxNodes">1000</attribute>
       <attribute name="timeToLiveSeconds">
       604800
       </attribute>
       <attribute name="maxAgeSeconds">604800</attribute>
       </region>
       <!--
       This region should be used for caching transaction errors from
       external systems such as 500 errors from Content servres. Nodes should
       not be stored directly to this region but should be stored in sub-regions
       such as /transactionErrors/
       -->
       <region name="/transactionErrors">
       <attribute name="maxNodes">1000</attribute>
       <attribute name="timeToLiveSeconds">60</attribute>
       <attribute name="maxAgeSeconds">60</attribute>
       </region>
      
       <!--
       This region is used as an in-memory cache for avail cache. Items in avail cache should
       not live beyond 15 minutes.
       -->
       <region name="/availCache">
       <attribute name="maxNodes">5000</attribute>
       <attribute name="timeToLiveSeconds">900</attribute>
       <attribute name="maxAgeSeconds">900</attribute>
       </region>
      
       <!-- Region to store the collection of Brand objects -->
       <region name="/lookup/brand">
       <attribute name="maxNodes">50</attribute>
       <attribute name="timeToLiveSeconds">0</attribute>
       <attribute name="maxAgeSeconds">0</attribute>
       </region>
      
       <!-- Region to store the collection of FeatureType objects -->
       <region name="/lookup/featureType">
       <attribute name="maxNodes">2000</attribute>
       <attribute name="timeToLiveSeconds">
       21600
       </attribute>
       <attribute name="maxAgeSeconds">86400</attribute>
       </region>
      
       <!-- Region to store geo destination objects -->
       <region name="/hotels/search/geoDestinations">
       <attribute name="maxNodes">5000</attribute>
       <attribute name="timeToLiveSeconds">
       14400
       </attribute>
       <attribute name="maxAgeSeconds">43200</attribute>
       </region>
      
       <!-- Region to store the RoomType objects -->
       <region name="/lookup/roomType">
       <attribute name="maxNodes">100</attribute>
       <attribute name="timeToLiveSeconds">
       21600
       </attribute>
       <attribute name="maxAgeSeconds">86400</attribute>
       </region>
      
       <!-- Region to store hotel name objects, the maxAge is 24 hours and timeToLive is 12 hours -->
       <region name="/hotels/search/hotelName">
       <attribute name="maxNodes">50000</attribute>
       <attribute name="timeToLiveSeconds">
       43200
       </attribute>
       <attribute name="maxAgeSeconds">86400</attribute>
       </region>
      
       <!-- Region to store city nick name, the maxAge is 24 hours and timeToLive is 12 hours -->
       <region name="/hotels/search/cityNickname">
       <attribute name="maxNodes">50000</attribute>
       <attribute name="timeToLiveSeconds">
       43200
       </attribute>
       <attribute name="maxAgeSeconds">86400</attribute>
       </region>
      
       <!-- Region to store the Currency objects -->
       <region name="/lookup/currency">
       <attribute name="maxNodes">200</attribute>
       <attribute name="timeToLiveSeconds">
       21600
       </attribute>
       <attribute name="maxAgeSeconds">86400</attribute>
       </region>
      
       <!-- Region to store the CurrencyDetail objects -->
       <region name="/lookup/currencyDetail">
       <attribute name="maxNodes">200</attribute>
       <attribute name="timeToLiveSeconds">3600</attribute>
       <attribute name="maxAgeSeconds">7200</attribute>
       </region>
      
       <!-- Region to store credit card identifiers -->
       <region name="/lookup/creditCard">
       <attribute name="maxNodes">10</attribute>
       <attribute name="timeToLiveSeconds">
       86400
       </attribute>
       <attribute name="maxAgeSeconds">86400</attribute>
       </region>
      
       <!-- Region to store contact centers -->
       <region name="/lookup/contactCenter">
       <attribute name="maxNodes">20</attribute>
       <attribute name="timeToLiveSeconds">
       86400
       </attribute>
       <attribute name="maxAgeSeconds">86400</attribute>
       </region>
      
       <!-- Region to store contact centers -->
       <region name="/proxy/proxyClasses">
       <attribute name="maxNodes">2000</attribute>
       <attribute name="timeToLiveSeconds">
       86400
       </attribute>
       <attribute name="maxAgeSeconds">86400</attribute>
       </region>
      
       </config>
       </attribute>
      
       </mbean>
      </server>