cache put stucks forever in a 3 node cluster
dex80526 Jun 22, 2012 6:48 PMI am banging my head against wall these days, and can not see what is going on with infinispan replication.
Here is my problem:
I have a 3 node cluster in (ASYNC) replication mode usging TCP with ISPN 5.1.4.Final.
I have a cache configured a jdbc cache store using Derby. I made the cache is "NO_TRANSACTIONAL".
During a test, I am loading 10K entries into the cache from one node ( and they should be stored to cache store and replicate to other 2 nodes in ASYNC). I found that the loading will be stuck after a few hundred entries (various), but never complete the load, and there is no Exception/Error in the log on both loading node and other 2 nodes. I turn on trace, and did not see any obvious problems from my eyes.
However, the same code and same ISPN configuration but with 2 node cluster, the load competes in less than one minute.
I tried to use "SKIP_LOCK" and/or "PUT_FOR_EXTERNAL_READ" flags and putAsync(), and did not see much difference.
My testing code looks like this:
....
try{
ObjectInputStream objectInputStream = new ObjectInputStream(inputStream);
Object readObject;
while ((readObject = objectInputStream.readObject()) != null){
if (readObject instanceof UserProfileData){
UserProfileData userProfileData = (UserProfileData) readObject;
cach.put(userProfileData.getUserId(),userProfileData);
importExportResults.messages.append("Imported ID: " + userProfileData.getUserId() + "\n");
importExportResults.numSuccessfulItems++;
} else {
importExportResults.numWarnings++;
}
}
} catch (Exception e){
if (e instanceof EOFException){
importExportResults.messages.append("Got EOF, assuming finished\n");
} else {
importExportResults.numErrors++;
}
}
Here is snippet of trace logs from the node is loading:
....
012-06-22/14:12:14.722/EDT [CoalescedAsyncStore-48] TRACE org.infinispan.loaders.jdbc.connectionfactory.ManagedConnectionFactory[99] - Connection checked out: ProxyConnection[PooledConnection[org.apache.derby.impl.jdbc.EmbedConnection40@1739265564 (XID = 163), (SESSIONID = 9), (DATABASE = /usr/local/test/cacheData/user/UserProfileDB), (DRDAID = null) ]]
2012-06-22/14:12:14.722/EDT [CoalescedAsyncStore-48] TRACE org.infinispan.loaders.jdbc.connectionfactory.ManagedConnectionFactory[99] - Connection checked out: ProxyConnection[PooledConnection[org.apache.derby.impl.jdbc.EmbedConnection40@1739265564 (XID = 163), (SESSIONID = 9), (DATABASE = /usr/local/test/cacheData/user/UserProfileDB), (DRDAID = null) ]]
2012-06-22/14:12:14.723/EDT [CoalescedAsyncStore-55] TRACE org.infinispan.util.concurrent.locks.StripedLock[131] - WL released for '9314e7b09e3623e128a5496e88feb36bf42db087'
2012-06-22/14:12:14.723/EDT [CoalescedAsyncStore-55] TRACE org.infinispan.util.concurrent.locks.StripedLock[131] - WL released for '9314e7b09e3623e128a5496e88feb36bf42db087'
2012-06-22/14:12:14.723/EDT [CoalescedAsyncStore-55] TRACE org.infinispan.loaders.LockSupportCacheStore[212] - exit store(ImmortalCacheEntry{key=9314e7b09e3623e128a5496e88feb36bf42db087, value=ImmortalCacheValue {value=com.test.service.shared.cache.cacheables.UserProfileData@58376d08}})
2012-06-22/14:12:14.723/EDT [CoalescedAsyncStore-55] TRACE org.infinispan.loaders.LockSupportCacheStore[212] - exit store(ImmortalCacheEntry{key=9314e7b09e3623e128a5496e88feb36bf42db087, value=ImmortalCacheValue {value=com.test.service.shared.cache.cacheables.UserProfileData@58376d08}})
2012-06-22/14:12:14.723/EDT [CoalescedAsyncStore-55] TRACE org.infinispan.loaders.decorators.AsyncStore[427] - Release lock for key 9314e7b09e3623e128a5496e88feb36bf42db087
2012-06-22/14:12:14.723/EDT [CoalescedAsyncStore-55] TRACE org.infinispan.loaders.decorators.AsyncStore[427] - Release lock for key 9314e7b09e3623e128a5496e88feb36bf42db087
2012-06-22/14:12:14.724/EDT [CoalescedAsyncStore-48] TRACE org.infinispan.util.concurrent.locks.StripedLock[131] - WL released for 'c415505dca69be631ca5d391b3ccd2b44b52d017'
2012-06-22/14:12:14.724/EDT [CoalescedAsyncStore-48] TRACE org.infinispan.util.concurrent.locks.StripedLock[131] - WL released for 'c415505dca69be631ca5d391b3ccd2b44b52d017'
2012-06-22/14:12:14.724/EDT [CoalescedAsyncStore-48] TRACE org.infinispan.loaders.LockSupportCacheStore[212] - exit store(ImmortalCacheEntry{key=c415505dca69be631ca5d391b3ccd2b44b52d017, value=ImmortalCacheValue {value=com.test.service.shared.cache.cacheables.UserProfileData@4c86380a}})
2012-06-22/14:12:14.724/EDT [CoalescedAsyncStore-48] TRACE org.infinispan.loaders.LockSupportCacheStore[212] - exit store(ImmortalCacheEntry{key=c415505dca69be631ca5d391b3ccd2b44b52d017, value=ImmortalCacheValue {value=com.test.service.shared.cache.cacheables.UserProfileData@4c86380a}})
2012-06-22/14:12:14.724/EDT [CoalescedAsyncStore-48] TRACE org.infinispan.loaders.decorators.AsyncStore[427] - Release lock for key de0230a7787926f4d061dd366c132af3a9ee33f6
2012-06-22/14:12:14.724/EDT [CoalescedAsyncStore-48] TRACE org.infinispan.loaders.decorators.AsyncStore[427] - Release lock for key de0230a7787926f4d061dd366c132af3a9ee33f6
2012-06-22/14:12:14.724/EDT [CoalescedAsyncStore-48] TRACE org.infinispan.loaders.decorators.AsyncStore[427] - Release lock for key c415505dca69be631ca5d391b3ccd2b44b52d017
2012-06-22/14:12:14.724/EDT [CoalescedAsyncStore-48] TRACE org.infinispan.loaders.decorators.AsyncStore[427] - Release lock for key c415505dca69be631ca5d391b3ccd2b44b52d017
2012-06-22/14:12:14.724/EDT [CoalescedAsyncStore-48] TRACE org.infinispan.loaders.decorators.AsyncStore[427] - Release lock for key 01901175a7e99c387566ac191743e0d6156c0d34
2012-06-22/14:12:14.724/EDT [CoalescedAsyncStore-48] TRACE org.infinispan.loaders.decorators.AsyncStore[427] - Release lock for key 01901175a7e99c387566ac191743e0d6156c0d34
2012-06-22/14:12:15.466/EDT [CacheViewTrigger,portal3.testme.com-12013] TRACE org.infinispan.cacheviews.CacheViewsManagerImpl[817] - Woke up, shouldRecoverViews=false
2012-06-22/14:12:15.466/EDT [CacheViewTrigger,portal3.testme.com-12013] TRACE org.infinispan.cacheviews.CacheViewsManagerImpl[817] - Woke up, shouldRecoverViews=false
2012-06-22/14:12:16.471/EDT [CacheViewTrigger,portal3.testme.com-12013] TRACE org.infinispan.cacheviews.CacheViewsManagerImpl[817] - Woke up, shouldRecoverViews=false
...
After this, the put is not returning any more. I did not see timeout either. Jstack does not detect "DEADLOCK", but I saw lot of threas (ColaescedAsynStore...) in WATING.
Any idea? what else should I try?