JBossCache-1.2.4 with Hibernate-3.1.2, IdentityLock ERROR lo

[jaikiran]

Hi,
We *were* using Hibernate-2.1.3 and JBossCache-1.2 with JBoss-3.2.3. Because of PESSIMISTIC locking issues, we are in the process of upgrading to Hibernate-3.1.2 and JBossCache-1.2.4(we are still using PESSIMISTIC approach). We are currently seeing a lot of logs as below:

15:14:05,296 WARN [LRUAlgorithm] eviction timed out. Will retry later.
15:14:06,796 ERROR [IdentityLock] write lock for /com/dbdata/core/hibernateobject/SmSegmentPlanRelationship/smParentSegments/com.dbdata.core.hibernateobject.SmSegmentPlanRelationship.smParentSegments#com.dbdata.core.hibernateobject.SmSegmentPlanRelationshipId[segmentPlanId=56203, segmentPlanVersionId=1, relationshipId=6] could not be acquired a
fter 1500 ms. Locks: Read lock owners: {GlobalTransaction:<null>:357=java.lang.Object@b2e5d0}
Write lock owner: null
(caller=Thread[Thread-35,5,jboss], lock info: read owners=[GlobalTransaction:<null>:357] (activeReaders=1, activeWriter=null, waitingReaders=0, waitingWriters=0, waitingUpgrader=0))
15:14:06,796 WARN [LRUAlgorithm] eviction timed out. Will retry later.
15:14:08,296 ERROR [IdentityLock] write lock for /com/dbdata/core/hibernateobject/SmSegmentPlanRelationship/smPickBestQualifications/com.dbdata.core.hibernateobject.SmSegmentPlanRelationship.smPickBestQualifications#com.dbdata.core.hibernateobject.SmSegmentPlanRelationshipId[segmentPlanId=56203, segmentPlanVersionId=1, relationshipId=5] could n
ot be acquired after 1500 ms. Locks: Read lock owners: {GlobalTransaction:<null>:357=java.lang.Object@b2e5d0}
Write lock owner: null
(caller=Thread[Thread-35,5,jboss], lock info: read owners=[GlobalTransaction:<null>:357] (activeReaders=1, activeWriter=null, waitingReaders=0, waitingWriters=0, waitingUpgrader=0))
15:14:08,296 WARN [LRUAlgorithm] eviction timed out. Will retry later.
15:14:09,796 ERROR [IdentityLock] write lock for /com/dbdata/core/hibernateobject/SmSegmentPlanRelationship/smLogicalSegmentRuns/com.dbdata.core.hibernateobject.SmSegmentPlanRelationship.smLogicalSegmentRuns#com.dbdata.core.hibernateobject.SmSegmentPlanRelationshipId[segmentPlanId=56203, segmentPlanVersionId=1, relationshipId=5] could not be ac
quired after 1500 ms. Locks: Read lock owners: {GlobalTransaction:<null>:357=java.lang.Object@b2e5d0}
Write lock owner: null
(caller=Thread[Thread-35,5,jboss], lock info: read owners=[GlobalTransaction:<null>:357] (activeReaders=1, activeWriter=null, waitingReaders=0, waitingWriters=0, waitingUpgrader=0))
15:14:09,796 WARN [LRUAlgorithm] eviction timed out. Will retry later.
15:14:11,296 ERROR [IdentityLock] write lock for /com/dbdata/core/hibernateobject/SmSegmentPlanRelationship/smChildSegments/com.dbdata.core.hibernateobject.SmSegmentPlanRelationship.smChildSegments#com.dbdata.core.hibernateobject.SmSegmentPlanRelationshipId[segmentPlanId=56203, segmentPlanVersionId=1, relationshipId=5] could not be acquired aft
er 1500 ms. Locks: Read lock owners: {GlobalTransaction:<null>:357=java.lang.Object@b2e5d0}
Write lock owner: null
(caller=Thread[Thread-35,5,jboss], lock info: read owners=[GlobalTransaction:<null>:357] (activeReaders=1, activeWriter=null, waitingReaders=0, waitingWriters=0, waitingUpgrader=0))
15:14:11,311 WARN [LRUAlgorithm] eviction timed out. Will retry later.
15:14:12,811 ERROR [IdentityLock] write lock for /com/dbdata/core/hibernateobject/SmSegmentPlanRelationship/smParentSegments/com.dbdata.core.hibernateobject.SmSegmentPlanRelationship.smParentSegments#com.dbdata.core.hibernateobject.SmSegmentPlanRelationshipId[segmentPlanId=56203, segmentPlanVersionId=1, relationshipId=5] could not be acquired a
fter 1500 ms. Locks: Read lock owners: {GlobalTransaction:<null>:357=java.lang.Object@b2e5d0}
Write lock owner: null
(caller=Thread[Thread-35,5,jboss], lock info: read owners=[GlobalTransaction:<null>:357] (activeReaders=1, activeWriter=null, waitingReaders=0, waitingWriters=0, waitingUpgrader=0))
15:14:12,811 WARN [LRUAlgorithm] eviction timed out. Will retry later.

Our LockAcquisitionTimeout is 1500ms in treecache.xml.
Can these logs be ignored? Or are they indicating any serious issues?

Thank you.

[ben.wang]

Looks like the eviction thread tried to evict/remove the nodes but it times out because someone is holding the read lock for more than 15 secs.

So I'd say this is an anomaly. Is this re-producible?

[jaikiran]

Is this re-producible?

Very much. Our server log is completely filled with these logs.

Looks like the eviction thread tried to evict/remove the nodes but it times out because someone is holding the read lock for more than 15 secs.

I believe, you meant 1.5 secs and not 15 sec, since my LockAcquisitionTimeout is 1500ms, right?

[jaikiran]

Looks like the eviction thread tried to evict/remove the nodes but it times out because someone is holding the read lock

One question, if the node is being used by someone, then why is this node considered as a candidate for eviction, by the LRU algorithm?

Also, these logs are flooding the server log. Do you think there is some major issue involved here?

[jaikiran]

Any updates on this?

[ben.wang]

Sorry. Here is my additiona comments:

1. So you turn on eviction specifically on your own? Can you post the xml config then?

2. Why do you use such a short lock timeout value, just curious. The default is 15sec actually. If it is just 1.5 second, then it is hard to say whether there is definite problem or not.

-Ben

[jaikiran]

2. Why do you use such a short lock timeout value, just curious. The default is 15sec actually.

Sorry, that's my mistake. I was under the impression that the default value was 1.5 sec. I will change this to 15 sec and try out the application.

Can you post the xml config then?

Here's the treecahe.xml that we are using:

<?xml version="1.0" encoding="UTF-8"?>

<!-- ===================================================================== -->
<!-- -->
<!-- Sample TreeCache Service Configuration -->
<!-- -->
<!-- ===================================================================== -->

<server>

 <classpath codebase="./lib" archives="jboss-cache.jar, jgroups.jar"/>


 <!-- ==================================================================== -->
 <!-- Defines TreeCache configuration -->
 <!-- ==================================================================== -->

 <mbean code="org.jboss.cache.TreeCache" name="jboss.cache:service=TreeCache">

 <depends>jboss:service=Naming</depends>
 <depends>jboss:service=TransactionManager</depends>

 <!--
 Configure the TransactionManager
 -->
 <attribute name="TransactionManagerLookupClass">org.jboss.cache.GenericTransactionManagerLookup</attribute>

 <!--
 Node locking scheme:
 OPTIMISTIC
 PESSIMISTIC (default)
 -->
 <attribute name="NodeLockingScheme">PESSIMISTIC</attribute>

 <!--
 Isolation level : SERIALIZABLE
 REPEATABLE_READ (default)
 READ_COMMITTED
 READ_UNCOMMITTED
 NONE
 -->
 <attribute name="IsolationLevel">REPEATABLE_READ</attribute>

 <!--
 Valid modes are LOCAL, REPL_ASYNC and REPL_SYNC
 -->
 <attribute name="CacheMode">LOCAL</attribute>

 <!--
 Just used for async repl: use a replication queue
 -->
 <attribute name="UseReplQueue">false</attribute>

 <!--
 Replication interval for replication queue (in ms)
 -->
 <attribute name="ReplQueueInterval">0</attribute>

 <!--
 Max number of elements which trigger replication
 -->
 <attribute name="ReplQueueMaxElements">0</attribute>

 <!-- Name of cluster. Needs to be the same for all clusters, in order
 to find each other
 -->
 <attribute name="ClusterName">TAP-ApplicationCache</attribute>

 <!-- JGroups protocol stack properties. Can also be a URL,
 e.g. file:/home/bela/default.xml
 <attribute name="ClusterProperties"></attribute>
 -->

 <attribute name="ClusterConfig">
 <config>
 <!-- UDP: if you have a multihomed machine,
 set the bind_addr attribute to the appropriate NIC IP address -->
 <!-- UDP: On Windows machines, because of the media sense feature
 being broken with multicast (even after disabling media sense)
 set the loopback attribute to true -->
 <UDP mcast_addr="228.1.2.3" mcast_port="48866"
 ip_ttl="64" ip_mcast="true"
 mcast_send_buf_size="150000" mcast_recv_buf_size="80000"
 ucast_send_buf_size="150000" ucast_recv_buf_size="80000"
 loopback="false"/>
 <PING timeout="2000" num_initial_members="3"
 up_thread="false" down_thread="false"/>
 <MERGE2 min_interval="10000" max_interval="20000"/>
 <!-- <FD shun="true" up_thread="true" down_thread="true" />-->
 <FD_SOCK/>
 <VERIFY_SUSPECT timeout="1500"
 up_thread="false" down_thread="false"/>
 <pbcast.NAKACK gc_lag="50" retransmit_timeout="600,1200,2400,4800"
 max_xmit_size="8192" up_thread="false" down_thread="false"/>
 <UNICAST timeout="600,1200,2400" window_size="100" min_threshold="10"
 down_thread="false"/>
 <pbcast.STABLE desired_avg_gossip="20000"
 up_thread="false" down_thread="false"/>
 <FRAG frag_size="8192"
 down_thread="false" up_thread="false"/>
 <pbcast.GMS join_timeout="5000" join_retry_timeout="2000"
 shun="true" print_local_addr="true"/>
 <pbcast.STATE_TRANSFER up_thread="true" down_thread="true"/>
 </config>
 </attribute>

 <!--
 Whether or not to fetch state on joining a cluster
 -->
 <attribute name="FetchStateOnStartup">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">5000</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">1500</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="timeToIdleSeconds">1000</attribute>
 </region>
 <region name="/com/teradata/tap/system/folder/FolderService">
 <attribute name="maxNodes">5000</attribute>
 <attribute name="timeToIdleSeconds">600</attribute>
 </region>
 </config>
 </attribute>
 </mbean>


 <!-- Uncomment to get a graphical view of the TreeCache MBean above -->
 <!-- <mbean code="org.jboss.cache.TreeCacheView" name="jboss.cache:service=TreeCacheView">-->
 <!-- <depends>jboss.cache:service=TreeCache</depends>-->
 <!-- <attribute name="CacheService">jboss.cache:service=TreeCache</attribute>-->
 <!-- </mbean>-->


</server>

So you turn on eviction specifically on your own?

We have specified the :

<attribute name="EvictionPolicyClass">org.jboss.cache.eviction.LRUPolicy</attribute>

in the treecache.xml. Not doing anything else on our own, relating to eviction.

[ben.wang]

well, you actually also created a Region under com/teradata. But it seems they all fall under __default__.

[jaikiran]

Here's the latest update. After changing the LockAcquisitionTimeoutValue to 15 seconds, this ERROR log has stopped.

well, you actually also created a Region under com/teradata. But it seems they all fall under __default__.

I guess, we will have to create a separate region for the nodes that we were seeing in the earlier error logs, so that they dont fall under __default__

[jaikiran]

Thank you for all the help :-)