{"action":"created","issue":{"url":"https://api.github.com/repos/hazelcast/hazelcast/issues/6328","labels_url":"https://api.github.com/repos/hazelcast/hazelcast/issues/6328/labels{/name}","comments_url":"https://api.github.com/repos/hazelcast/hazelcast/issues/6328/comments","events_url":"https://api.github.com/repos/hazelcast/hazelcast/issues/6328/events","html_url":"https://github.com/hazelcast/hazelcast/issues/6328","id":109075383,"number":6328,"title":"TimeoutException in initializeMapStoreLoad()","user":{"login":"lukasblu","id":3501420,"avatar_url":"https://avatars.githubusercontent.com/u/3501420?v=3","gravatar_id":"","url":"https://api.github.com/users/lukasblu","html_url":"https://github.com/lukasblu","followers_url":"https://api.github.com/users/lukasblu/followers","following_url":"https://api.github.com/users/lukasblu/following{/other_user}","gists_url":"https://api.github.com/users/lukasblu/gists{/gist_id}","starred_url":"https://api.github.com/users/lukasblu/starred{/owner}{/repo}","subscriptions_url":"https://api.github.com/users/lukasblu/subscriptions","organizations_url":"https://api.github.com/users/lukasblu/orgs","repos_url":"https://api.github.com/users/lukasblu/repos","events_url":"https://api.github.com/users/lukasblu/events{/privacy}","received_events_url":"https://api.github.com/users/lukasblu/received_events","type":"User","site_admin":false},"labels":[{"url":"https://api.github.com/repos/hazelcast/hazelcast/labels/PENDING","name":"PENDING","color":"bfe5bf"},{"url":"https://api.github.com/repos/hazelcast/hazelcast/labels/Team:%20Core","name":"Team: Core","color":"eb6420"},{"url":"https://api.github.com/repos/hazelcast/hazelcast/labels/Type:%20Defect","name":"Type: Defect","color":"fc2929"}],"state":"open","locked":false,"assignee":null,"milestone":null,"comments":3,"created_at":"2015-09-30T12:21:19Z","updated_at":"2015-09-30T16:02:37Z","closed_at":null,"body":"Hi,\r\n\r\nwe discovered a timeout exception in 3.5.3-SNAPSHOT during system startup when our distributed maps with attached MapStore are initialized.\r\n\r\n```java\r\nSep 30, 2015 2:08:56 PM com.hazelcast.util.FutureUtil\r\nWARNING: Exception occurred\r\njava.util.concurrent.TimeoutException: Call Invocation{ serviceName='hz:impl:mapService', op=com.hazelcast.map.impl.operation.PartitionCheckIfLoadedOperation{serviceName='null', partitionId=228, callId=9223372036854775807, invocationTime=1443614935053, waitTimeout=-1, callTimeout=60000}, partitionId=228, replicaIndex=0, tryCount=250, tryPauseMillis=500, invokeCount=1, callTimeout=60000, target=Address[10.0.1.154]:5701, backupsExpected=0, backupsCompleted=0} encountered a timeout\r\n\tat com.hazelcast.spi.impl.operationservice.impl.InvocationFuture.resolveApplicationResponse(InvocationFuture.java:366)\r\n\tat com.hazelcast.spi.impl.operationservice.impl.InvocationFuture.resolveApplicationResponseOrThrowException(InvocationFuture.java:334)\r\n\tat com.hazelcast.spi.impl.operationservice.impl.InvocationFuture.get(InvocationFuture.java:225)\r\n\tat com.hazelcast.util.FutureUtil.executeWithDeadline(FutureUtil.java:294)\r\n\tat com.hazelcast.util.FutureUtil.waitWithDeadline(FutureUtil.java:278)\r\n\tat com.hazelcast.util.FutureUtil.waitWithDeadline(FutureUtil.java:252)\r\n\tat com.hazelcast.map.impl.proxy.MapProxySupport.waitUntilLoaded(MapProxySupport.java:675)\r\n\tat com.hazelcast.map.impl.proxy.MapProxyImpl.waitUntilLoaded(MapProxyImpl.java:71)\r\n\tat com.hazelcast.map.impl.proxy.MapProxySupport.initializeMapStoreLoad(MapProxySupport.java:179)\r\n\tat com.hazelcast.map.impl.proxy.MapProxySupport.initialize(MapProxySupport.java:171)\r\n\tat com.hazelcast.map.impl.proxy.MapProxyImpl.initialize(MapProxyImpl.java:71)\r\n\tat com.hazelcast.spi.impl.proxyservice.impl.ProxyRegistry.doCreateProxy(ProxyRegistry.java:194)\r\n\tat com.hazelcast.spi.impl.proxyservice.impl.ProxyRegistry.createProxy(ProxyRegistry.java:184)\r\n\tat com.hazelcast.spi.impl.proxyservice.impl.ProxyRegistry.getOrCreateProxy(ProxyRegistry.java:153)\r\n\tat com.hazelcast.spi.impl.proxyservice.impl.ProxyServiceImpl.getDistributedObject(ProxyServiceImpl.java:119)\r\n\tat com.hazelcast.instance.HazelcastInstanceImpl.getDistributedObject(HazelcastInstanceImpl.java:390)\r\n\tat com.hazelcast.instance.HazelcastInstanceImpl.getMap(HazelcastInstanceImpl.java:192)\r\n\tat com.hazelcast.instance.HazelcastInstanceProxy.getMap(HazelcastInstanceProxy.java:75)\r\n\tat com.nm.test.hazelcast.mapstore.TestMapStore25$MapRunnable.run(TestMapStore25.java:128)\r\n\tat java.lang.Thread.run(Thread.java:662)\r\n```\r\n\r\nThe exception occurs if the system has only very limited CPU resources available or is under load otherwise.\r\n\r\nAn exception is thrown and printed as a warning, however the maps are fully loaded anyway.\r\n\r\nNote also, that the timeout occurs already after about 1-2 seconds after hazelcast is started - which seams very strange given that the \"callTimeout\" is set to 60000 (see stacktrace above).\r\n\r\nHere is a test to reproduce the issue, however I don't know how to make the test actually fail.\r\n\r\n```java\r\npackage com.nm.test.hazelcast.mapstore;\r\n\r\nimport com.hazelcast.config.*;\r\nimport com.hazelcast.config.MapStoreConfig.InitialLoadMode;\r\nimport com.hazelcast.core.Hazelcast;\r\nimport com.hazelcast.core.HazelcastInstance;\r\nimport com.nm.test.hazelcast.TestHazelcast;\r\nimport com.nm.test.hazelcast.utils.SlowMapStore;\r\nimport com.nm.test.hazelcast.utils.Spin;\r\nimport org.apache.log4j.BasicConfigurator;\r\nimport org.apache.log4j.Logger;\r\nimport java.util.ArrayList;\r\nimport java.util.List;\r\nimport junit.framework.TestCase;\r\n\r\n/**\r\n * A test to reproduce a timeout exception while initializing the distributed maps.\r\n */\r\npublic class TestMapStore25 extends TestCase {\r\n\r\n\tprivate static final Logger logger = Logger.getLogger(TestMapStore25.class);\r\n\r\n\tprivate static final String mapName = \"testMap\" + TestMapStore25.class.getSimpleName();\r\n\r\n\t@Override\r\n\tprotected void setUp() throws Exception {\r\n\r\n\t\t// configure logging\r\n\t\tif (!TestHazelcast.loggingInitialized) {\r\n\t\t\tTestHazelcast.loggingInitialized = true;\r\n\t\t\tBasicConfigurator.configure();\r\n\t\t}\r\n\t}\r\n\r\n\tpublic void testLoad() throws Exception {\r\n\r\n\t\t// create hazelcast config\r\n\t\tConfig config = new XmlConfigBuilder().build();\r\n\t\tconfig.setProperty(\"hazelcast.logging.type\", \"log4j\");\r\n\t\tconfig.setProperty(\"hazelcast.version.check.enabled\", \"false\");\r\n\r\n\t\t// disable multicast for faster startup\r\n\t\tconfig.getNetworkConfig().getJoin().getMulticastConfig().setEnabled(false);\r\n\r\n\t\t// prepare maps\r\n\t\tfinal int numMaps = 20;\r\n\t\tfor (int i = 0; i < numMaps; i++) {\r\n\t\t\tString mapNameCur = mapName + i;\r\n\r\n\t\t\t// create map store\r\n\t\t\t// 10, 0, 0, 0 -> timeout occurs very seldom\r\n\t\t\t// 10, 0, 0, 1 -> timeout occurs 2.5 times per run\r\n\t\t\t//  0, 0, 0, 1 -> timeout occurs 2.5 times per run\r\n\t\t\tSlowMapStore store = new SlowMapStore();\r\n\t\t\tstore.setSleepMsLoadAllKeys(0);\r\n\t\t\tstore.setSleepMsLoadAll(0);\r\n\t\t\tstore.setSleepMsLoadAllPerKey(0);\r\n\t\t\tstore.preload(1); // 0 -> very seldom\r\n\r\n\t\t\t// create map store config\r\n\t\t\tMapStoreConfig mapStoreConfig = new MapStoreConfig();\r\n\t\t\tmapStoreConfig.setEnabled(true);\r\n\t\t\tmapStoreConfig.setInitialLoadMode(InitialLoadMode.EAGER);\r\n\t\t\tmapStoreConfig.setWriteDelaySeconds(5);\r\n\t\t\tmapStoreConfig.setClassName(null);\r\n\t\t\tmapStoreConfig.setImplementation(store);\r\n\r\n\t\t\t// configure map store\r\n\t\t\tMapConfig mapConfig = config.getMapConfig(mapNameCur);\r\n\t\t\tmapConfig.setMapStoreConfig(mapStoreConfig);\r\n\t\t}\r\n\r\n\t\t// start hazelcast instance\r\n\t\tHazelcastInstance hcInstance = Hazelcast.newHazelcastInstance(config);\r\n\r\n\t\t// start spinning to make race conditions more likely\r\n\t\tfor (int i = 0; i < 8; i++) {\r\n\t\t\tSpin.startSpinning(10000);\r\n\t\t}\r\n\r\n\t\t// start threads which initialize maps\r\n\t\tList<Thread> threads = new ArrayList<Thread>();\r\n\t\tfor (int i = 0; i < numMaps; i++) {\r\n\t\t\tthreads.add(new Thread(new MapRunnable(hcInstance, mapName + i)));\r\n\t\t}\r\n\t\tfor (Thread thread : threads) {\r\n\t\t\tthread.start();\r\n\t\t}\r\n\r\n\t\t// wait for init threads to finish\r\n\t\tlogger.info(\"Waiting for init threads to finish...\");\r\n\t\tfor (Thread thread : threads) {\r\n\t\t\tthread.join();\r\n\t\t}\r\n\r\n\t\t// try-finally to ensure hc shutdown\r\n\t\ttry {\r\n\r\n\t\t\t// print and check map sizes\r\n\t\t\tfor (int i = 0; i < numMaps; i++) {\r\n\t\t\t\tString mapNameCur = mapName + i;\r\n\t\t\t\tint size = hcInstance.getMap(mapNameCur).size();\r\n\t\t\t\tString msg = \"Size of '\" + mapNameCur + \"' map = \" + size;\r\n\t\t\t\tassertTrue(msg, size == 1);\r\n\t\t\t}\r\n\t\t} finally {\r\n\r\n\t\t\t// shutdown hazelcast instance\r\n\t\t\thcInstance.getLifecycleService().terminate();\r\n\t\t}\r\n\t}\r\n\r\n\tprivate static final class MapRunnable implements Runnable {\r\n\r\n\t\tprivate static final Logger logger = Logger.getLogger(MapRunnable.class);\r\n\r\n\t\tprivate final HazelcastInstance hcInstance;\r\n\r\n\t\tprivate final String mapName;\r\n\r\n\t\tpublic MapRunnable(HazelcastInstance hcInstance, String mapName) {\r\n\t\t\tthis.hcInstance = hcInstance;\r\n\t\t\tthis.mapName = mapName;\r\n\t\t}\r\n\r\n\t\tpublic void run() {\r\n\t\t\tlogger.info(\"accessing map '\" + mapName + \"'...\");\r\n\t\t\thcInstance.getMap(mapName);\r\n\t\t\tlogger.info(\"accessing map '\" + mapName + \"' done.\");\r\n\t\t}\r\n\t}\r\n\r\n}\r\n\r\npackage com.nm.test.hazelcast.utils;\r\n\r\nimport org.apache.log4j.Logger;\r\nimport java.util.concurrent.atomic.AtomicBoolean;\r\nimport java.util.concurrent.atomic.AtomicInteger;\r\n\r\n/**\r\n * A class to consume CPU resources to make race condition testing easier.\r\n */\r\npublic class Spin {\r\n\r\n\tprivate static final Logger logger = Logger.getLogger(Spin.class);\r\n\r\n\tprivate static final AtomicInteger globalSpinIndex = new AtomicInteger(0);\r\n\r\n\t/**\r\n\t * Start spinning in the background with a single core for the given amout of time.\r\n\t * \r\n\t * @param spinTimeMs time to spin.\r\n\t */\r\n\tpublic static void startSpinning(int spinTimeMs) {\r\n\t\tfinal int spinIndex = globalSpinIndex.getAndIncrement();\r\n\t\tSpinAwaitRunnable spinAwaitRunnable = new SpinAwaitRunnable(spinIndex, spinTimeMs);\r\n\t\tThread spinAwaitThread = new Thread(spinAwaitRunnable, \"spin-await-thread-\" + spinIndex);\r\n\t\tspinAwaitThread.start();\r\n\t}\r\n\r\n\t/**\r\n\t * The spin await runnable spawns a spin runnable, sleeps for a specified amount of time, and\r\n\t * then stops the spin runnable again.\r\n\t */\r\n\tprivate static class SpinAwaitRunnable implements Runnable {\r\n\r\n\t\tprivate final int spinIndex;\r\n\r\n\t\tprivate final int spinTimeMs;\r\n\r\n\t\tpublic SpinAwaitRunnable(int spinIndex, int spinTimeMs) {\r\n\t\t\tthis.spinIndex = spinIndex;\r\n\t\t\tthis.spinTimeMs = spinTimeMs;\r\n\t\t}\r\n\r\n\t\t@Override\r\n\t\tpublic void run() {\r\n\r\n\t\t\t// start spin thread\r\n\t\t\tSpinRunnable spinRunnable = new SpinRunnable();\r\n\t\t\tThread spinThread = new Thread(spinRunnable, \"spin-thread-\" + spinIndex);\r\n\t\t\tspinThread.start();\r\n\r\n\t\t\t// sleep\r\n\t\t\tlong time0 = System.currentTimeMillis();\r\n\t\t\ttry {\r\n\t\t\t\tThread.sleep(spinTimeMs);\r\n\t\t\t} catch (InterruptedException e) {\r\n\t\t\t\tlogger.error(\"Spin thread was interrupted while spinning: \" + e.getMessage());\r\n\t\t\t}\r\n\t\t\tlong time1 = System.currentTimeMillis();\r\n\r\n\t\t\t// stop spin thread\r\n\t\t\tspinRunnable.stop();\r\n\t\t\ttry {\r\n\t\t\t\tspinThread.join();\r\n\t\t\t} catch (InterruptedException e) {\r\n\t\t\t\tlogger.error(\"Spin thread was interrupted while stopping: \" + e.getMessage());\r\n\t\t\t}\r\n\r\n\t\t\tlogger.info(Thread.currentThread().getName() + \" slept for \" + (time1 - time0) + \"ms.\");\r\n\t\t}\r\n\r\n\t}\r\n\r\n\t/**\r\n\t * The spin runnable performs the actual spinning and consumes CPU resources.\r\n\t */\r\n\tprivate static class SpinRunnable implements Runnable {\r\n\r\n\t\tprivate AtomicBoolean stop = new AtomicBoolean(false);\r\n\r\n\t\tpublic void stop() {\r\n\t\t\tstop.set(true);\r\n\t\t}\r\n\r\n\t\t@Override\r\n\t\tpublic void run() {\r\n\t\t\tlogger.info(Thread.currentThread().getName() + \" starting to spin...\");\r\n\t\t\tlong count = 0;\r\n\t\t\tdouble product = 1.13;\r\n\t\t\twhile (!stop.get()) {\r\n\t\t\t\tproduct *= product;\r\n\t\t\t\tcount++;\r\n\t\t\t}\r\n\t\t\tlogger.info(Thread.currentThread().getName() + \" looped \" + count + \" times.\");\r\n\t\t}\r\n\r\n\t}\r\n\r\n}\r\n\r\npackage com.nm.test.hazelcast.utils;\r\n\r\nimport com.hazelcast.core.MapStore;\r\nimport org.apache.log4j.Logger;\r\nimport java.util.*;\r\nimport java.util.concurrent.ConcurrentHashMap;\r\n\r\n/**\r\n * A map store implementation which allows to wait in operations if configured.\r\n */\r\npublic class SlowMapStore implements MapStore<String, String> {\r\n\r\n\tprivate static final Logger logger = Logger.getLogger(SlowMapStore.class);\r\n\r\n\t// ----------------------------------------------------------------- config\r\n\r\n\tprivate int sleepMsLoad;\r\n\r\n\tprivate int sleepMsLoadAll;\r\n\r\n\tprivate int sleepMsLoadAllPerKey;\r\n\r\n\tprivate int sleepMsLoadAllKeys;\r\n\r\n\t// ------------------------------------------------------------------ state\r\n\r\n\tprivate final ConcurrentHashMap<String, String> store = new ConcurrentHashMap<String, String>();\r\n\r\n\t// ----------------------------------------------------------- construction\r\n\r\n\tpublic SlowMapStore() {\r\n\t\tthis.sleepMsLoad = 20;\r\n\t\tthis.sleepMsLoadAll = 50;\r\n\t\tthis.sleepMsLoadAllPerKey = 10;\r\n\t\tthis.sleepMsLoadAllKeys = 8000;\r\n\t}\r\n\r\n\tpublic void preload(int size) {\r\n\t\tfor (int i = 0; i < size; i++) {\r\n\t\t\tstore.put(\"k\" + i, \"v\" + i);\r\n\t\t}\r\n\t}\r\n\r\n\t// ---------------------------------------------------------------- setters\r\n\r\n\tpublic void setSleepMsLoad(int sleepMsLoad) {\r\n\t\tthis.sleepMsLoad = sleepMsLoad;\r\n\t}\r\n\r\n\tpublic void setSleepMsLoadAll(int sleepMsLoadAll) {\r\n\t\tthis.sleepMsLoadAll = sleepMsLoadAll;\r\n\t}\r\n\r\n\tpublic void setSleepMsLoadAllPerKey(int sleepMsLoadAllPerKey) {\r\n\t\tthis.sleepMsLoadAllPerKey = sleepMsLoadAllPerKey;\r\n\t}\r\n\r\n\tpublic void setSleepMsLoadAllKeys(int sleepMsLoadAllKeys) {\r\n\t\tthis.sleepMsLoadAllKeys = sleepMsLoadAllKeys;\r\n\t}\r\n\r\n\t// ----------------------------------------------------- MapStore interface\r\n\r\n\t@Override\r\n\tpublic String load(String key) {\r\n\t\tlogger.info(\"load(\" + key + \") called.\");\r\n\t\tif (sleepMsLoad > 0) {\r\n\t\t\tSleep.sleep(sleepMsLoad, false);\r\n\t\t}\r\n\t\treturn store.get(key);\r\n\t}\r\n\r\n\t@Override\r\n\tpublic Map<String, String> loadAll(Collection<String> keys) {\r\n\t\tList<String> keysList = new ArrayList<String>(keys);\r\n\t\tCollections.sort(keysList);\r\n\t\tlogger.info(\"loadAll(\" + keysList + \") called.\");\r\n\t\tif (sleepMsLoadAll > 0) {\r\n\t\t\tSleep.sleep(sleepMsLoadAll, false);\r\n\t\t}\r\n\t\tMap<String, String> result = new HashMap<String, String>();\r\n\t\tfor (String key : keys) {\r\n\t\t\tif (sleepMsLoadAllPerKey > 0) {\r\n\t\t\t\tSleep.sleep(sleepMsLoadAllPerKey, false);\r\n\t\t\t}\r\n\t\t\tString value = store.get(key);\r\n\t\t\tif (value != null) {\r\n\t\t\t\tresult.put(key, value);\r\n\t\t\t}\r\n\t\t}\r\n\t\treturn result;\r\n\t}\r\n\r\n\t@Override\r\n\tpublic Set<String> loadAllKeys() {\r\n\t\tlogger.info(\"loadAllKeys() called.\");\r\n\t\tif (sleepMsLoadAllKeys > 0) {\r\n\t\t\tSleep.sleep(sleepMsLoadAllKeys, true);\r\n\t\t}\r\n\t\tSet<String> result = new HashSet<String>(store.keySet());\r\n\t\tList<String> resultList = new ArrayList<String>(result);\r\n\t\tCollections.sort(resultList);\r\n\t\tlogger.info(\"loadAllKeys result: size = \" + result.size() + \", keys = \" + resultList + \".\");\r\n\t\treturn result;\r\n\t}\r\n\r\n\t@Override\r\n\tpublic void store(String key, String value) {\r\n\t\tlogger.info(\"store(\" + key + \") called.\");\r\n\t\tstore.put(key, value);\r\n\t}\r\n\r\n\t@Override\r\n\tpublic void storeAll(Map<String, String> map) {\r\n\t\tTreeSet<String> setSorted = new TreeSet<String>(map.keySet());\r\n\t\tlogger.info(\"storeAll(\" + setSorted + \") called.\");\r\n\t\tstore.putAll(map);\r\n\t}\r\n\r\n\t@Override\r\n\tpublic void delete(String key) {\r\n\t\tlogger.info(\"delete(\" + key + \") called.\");\r\n\t\tstore.remove(key);\r\n\t}\r\n\r\n\t@Override\r\n\tpublic void deleteAll(Collection<String> keys) {\r\n\t\tList<String> keysList = new ArrayList<String>(keys);\r\n\t\tCollections.sort(keysList);\r\n\t\tlogger.info(\"deleteAll(\" + keysList + \") called.\");\r\n\t\tfor (String key : keys) {\r\n\t\t\tstore.remove(key);\r\n\t\t}\r\n\t}\r\n\r\n}\r\n```\r\n\r\nThanks for looking into this and best,\r\nLukas"},"comment":{"url":"https://api.github.com/repos/hazelcast/hazelcast/issues/comments/144460974","html_url":"https://github.com/hazelcast/hazelcast/issues/6328#issuecomment-144460974","issue_url":"https://api.github.com/repos/hazelcast/hazelcast/issues/6328","id":144460974,"user":{"login":"jerrinot","id":158619,"avatar_url":"https://avatars.githubusercontent.com/u/158619?v=3","gravatar_id":"","url":"https://api.github.com/users/jerrinot","html_url":"https://github.com/jerrinot","followers_url":"https://api.github.com/users/jerrinot/followers","following_url":"https://api.github.com/users/jerrinot/following{/other_user}","gists_url":"https://api.github.com/users/jerrinot/gists{/gist_id}","starred_url":"https://api.github.com/users/jerrinot/starred{/owner}{/repo}","subscriptions_url":"https://api.github.com/users/jerrinot/subscriptions","organizations_url":"https://api.github.com/users/jerrinot/orgs","repos_url":"https://api.github.com/users/jerrinot/repos","events_url":"https://api.github.com/users/jerrinot/events{/privacy}","received_events_url":"https://api.github.com/users/jerrinot/received_events","type":"User","site_admin":false},"created_at":"2015-09-30T16:02:37Z","updated_at":"2015-09-30T16:02:37Z","body":"@ajermakovics: any idea what is going on there? "}}