3 Replies Latest reply on Jan 8, 2008 11:21 AM by manik

    TimoutException when reading/writing from cache

    haribaasha

      on looking into the logs we noticed that there
      was a locktimeout when trying to retrieve from the cache.

      from the log :

      22:49:49,850 WARN [Thread-4]
      [com.arjuna.ats.arjuna.coordinator.CheckedAction_2] - CheckedAction::check -
      atomic action -3f57eb7a:9d61:4750012b:5e13 aborting with 1 threads active!
      22:49:49,850 WARN [Thread-4]
      [com.arjuna.ats.arjuna.coordinator.BasicAction_58] - Abort of action id
      -3f57eb7a:9d61:4750012b:5e14 invoked while multiple threads active within it.
      22:49:49,851 WARN [Thread-4]
      [com.arjuna.ats.arjuna.coordinator.CheckedAction_2] - CheckedAction::check -
      atomic action -3f57eb7a:9d61:4750012b:5e14 aborting with 1 threads active!
      22:49:49,851 WARN [Thread-4]
      [com.arjuna.ats.arjuna.coordinator.BasicAction_58] - Abort of action id
      -3f57eb7a:9d61:4750012b:5e15 invoked while multiple threads active within it.
      22:49:49,851 WARN [Thread-4]
      [com.arjuna.ats.arjuna.coordinator.CheckedAction_2] - CheckedAction::check -
      atomic action -3f57eb7a:9d61:4750012b:5e15 aborting with 1 threads active!
      22:49:49,851 WARN [Thread-4]
      [com.arjuna.ats.arjuna.coordinator.BasicAction_58] - Abort of action id
      -3f57eb7a:9d61:4750012b:5e17 invoked while multiple threads active within it.
      22:49:49,851 WARN [Thread-4]
      [com.arjuna.ats.arjuna.coordinator.CheckedAction_2] - CheckedAction::check -
      atomic action -3f57eb7a:9d61:4750012b:5e17 aborting with 1 threads active!
      23:01:33,101 INFO [WorkerThread#3[192.168.20.142:57945]] Indicative Request
      : FGCI 9.0
      23:01:33,103 INFO [WorkerThread#6[192.168.20.142:57946]] Indicative Request
      : GNSF 6 2004
      23:01:33,120 INFO [WorkerThread#9[192.168.20.142:57947]] Indicative Request
      : GNSF 5 2004
      23:01:33,227 INFO [WorkerThread#1[192.168.20.142:57948]] Indicative Request
      : FNCL 8.0 2001
      23:01:33,297 INFO [WorkerThread#5[192.168.20.142:57949]] Indicative Request
      : FNCI 6.5 2000
      23:01:33,297 INFO [WorkerThread#5[192.168.20.142:57949]] in loadSeasonedTBA
      Date : 20071130
      RESPONSE in C++ : 12/05/2007
      Date : 20071217
      Date : 20071130
      23:01:43,104 ERROR [WorkerThread#3[192.168.20.142:57945]] read lock for
      /Indicatives/FGCI 9.0 could not be acquired by
      WorkerThread#3[192.168.20.142:57945]
      after 10000 ms. Locks: Read lock owners: []
      Write lock owner: WorkerThread#8[192.168.20.142:57822]
      , lock info: write owner=WorkerThread#8[192.168.20.142:57822] (activeReaders=0,
      activeWriter=WorkerThread#8[192.168.20.142:57822], waitingReaders=0,
      waitingWriters=0, waitingUpgrader=0)
      23:01:43,106 ERROR [WorkerThread#6[192.168.20.142:57946]] read lock for
      /Indicatives/GNSF 6 2004 could not be acquired by
      WorkerThread#6[192.168.20.142:57946] after 10000 ms. Locks: Read lock owners:
      []
      Write lock owner: WorkerThread#2[192.168.20.142:57825]
      , lock info: write owner=WorkerThread#2[192.168.20.142:57825] (activeReaders=0,
      activeWriter=WorkerThread#2[192.168.20.142:57825], waitingReaders=0,
      waitingWriters=0, waitingUpgrader=0)
      23:01:43,108 INFO [WorkerThread#3[192.168.20.142:57945]] There was a problem
      handling this request
      org.jboss.cache.lock.TimeoutException: failure acquiring lock:
      fqn=/Indicatives/FGCI 9.0, caller=WorkerThread#3[192.168.20.142:57945],
      lock=write owner=WorkerThread#8[192.168.20.142:57822] (activeReaders=0,
      activeWriter=WorkerThread#8[192.168.20.142:57822], waitingReaders=0,
      waitingWriters=0, waitingUpgrader=0) at
      org.jboss.cache.Node.acquire(Node.java:407)
      at
      org.jboss.cache.interceptors.PessimisticLockInterceptor.lock(PessimisticLockInterceptor.java:231)
      at
      org.jboss.cache.interceptors.PessimisticLockInterceptor.invoke(PessimisticLockInterceptor.java:166)
      at org.jboss.cache.interceptors.Interceptor.invoke(Interceptor.java:68)
      at
      org.jboss.cache.interceptors.CacheStoreInterceptor.invoke(CacheStoreInterceptor.java:186)
      at org.jboss.cache.interceptors.Interceptor.invoke(Interceptor.java:68)
      at
      org.jboss.cache.interceptors.CacheLoaderInterceptor.invoke(CacheLoaderInterceptor.java:197)



      It seems like there are two threads, The thread 1 is writing
      to the cache (hence has acquired the write lock). The second load thread is
      trying to acquire a read lock and throws the locktimeout exception. This
      cascades into all the subsequents threads throwing timout exceptions.

      I am using jboss version 4.2.1 with jboss cache 1.4.SP1

      the code which puts and retrieves from cache is :

      MBeanServer server = MBeanServerLocator.locate();
      tree = (TreeCacheMBean) MBeanProxyExt.create(TreeCacheMBean.class, "jboss.cache:service=TreeCache", server);


      for putting:
      tree.put(key, tradeDate_, responseString_);

      for retrieving:
      responseString = (String) tree.get(key, tradeDate_);