TimeoutException in 2-node Spring Cache Hazelcast setup

289 views

Skip to first unread message

jens.g...@gmail.com

unread,

Oct 2, 2014, 11:51:06 AM10/2/14

to haze...@googlegroups.com

Hi,

We recently decided to add Spring caching to our application and decided to use Hazelcast 3.3 as a backend for our product (public website, peaks of 10.000 concurrent sessions, JBoss application server). We configure the cluster manually (no multicast), including port numbers, no other/special/advanced configuration was done. For now we're only using 2 nodes, so the Mancenter is also running on one of the 2 servers, so we can monitor what's in the caches, how much items, etc. The amount of items in the cache is limited by a memory restriction for items groups that have a limited number of total items (up to 100), but we use heap percentages to set boundaries on items that are typically unique per user (the maps for those items contain up to 10.000 items). JVM parameters:

-XX:PermSize=512m -XX:MaxPermSize=1024m -Xms2048m -Xmx8192m -Xss512k -XX:+UseLargePages -XX:+UseParNewGC -XX:ParallelGCThreads=4 -XX:MaxNewSize=32m -XX:NewSize=32m -XX:SurvivorRatio=128 -XX:MaxTenuringThreshold=0 -XX:+UseTLAB -Dsun.rmi.dgc.server.gcInterval=0x7FFFFFFFFFFFFFFE -Dsun.rmi.dgc.client.gcInterval=0x7FFFFFFFFFFFFFFE -Dsun.rmi.dgc.client.gcInterval=3600000 -Dsun.rmi.dgc.server.gcInterval=3600000

This morning our application grinded to a halt because the connections to our Hazelcast cluster started timing out. Our logging contained many entries like:

[pool-10-thread-586] WARN c.hazelcast.spi.impl.BasicInvocation - [*.*.*.211]:5701 [X] [3.3] While asking 'is-executing': BasicInvocationFuture{invocation=BasicInvocation{ serviceName='hz:impl:mapService', op=
GetOperation{}, partitionId=135, replicaIndex=0, tryCount=250, tryPauseMillis=500, invokeCount=1, callTimeout=60000, target=Address[*.*.*.212]:5701}, done=false}
java.util.concurrent.TimeoutException: Call BasicInvocation{ serviceName='hz:impl:mapService', op=com.hazelcast.spi.impl.IsStillExecutingOperation@5e666b8c, partitionId=-1, replicaIndex=0, tryCount=0, tryPauseMillis=0, invokeCount=
1, callTimeout=5000, target=Address[*.*.*.212]:5701} encountered a timeout

When using the mancenter to investigate the problem, everything seemed normal, but we kept getting timeouts in the application. In the end we restarted our JBoss hosts and things were back to normal, but I would like to find the cause of these issues. Does anyone have any ideas?

Kind Regards,

Jens

Cleber Muramoto

unread,

Oct 11, 2014, 4:03:47 PM10/11/14

to haze...@googlegroups.com

Hi I can't say for sure, but I think you might be experiencing long GC pauses.

If node A calls node B, and B is in a long GC cycle this kind of behavior is be expected, otherwise node B would block node A.

Could you do a jstat -gc <PID> and post the results?

By the way, your config explicitly enables ParNew. I can't recall now, but are you sure CMS is enabled if you just specify ParNew?

anton.iv...@gmail.com

unread,

Jan 18, 2015, 8:32:54 AM1/18/15

to haze...@googlegroups.com, jens.g...@gmail.com

Hi have you already solved this issue? I have the same one and have no idea how I can fix it.

regards,

Anton

четверг, 2 октября 2014 г., 18:51:06 UTC+3 пользователь jens.g...@gmail.com написал:

Jens Geiregat

unread,

Jan 20, 2015, 7:45:34 AM1/20/15

to anton.iv...@gmail.com, haze...@googlegroups.com

Hi Anton,

No we didn't find the cause of the problem unfortunately. After it happened a second time we decided to disable Hazelcast caching.

Regards,

Jens

Peter F.

unread,

Jan 21, 2015, 2:30:42 PM1/21/15

to haze...@googlegroups.com, jens.g...@gmail.com

Hi ,

I upgraded my Spring app. to Hazelcast 3.4 and suddenly started getting this issue.

If I start both nodes at the same time, than they form a cluster and load the data. But if I start one node, wait until it loads all the data and then start another node, the second node shows the following exception in log and never completes initialization as seems partition service hangs for ever trying to migrate (repartition) the data

Below is the log from the second node (which joins the cluster later) , and thread stack dump showing that 'partition' thread is in 'blocked' state.

And I have enough of memory allocated - it is not related to GC.

Perhaps , what may happen is:

- I initialize application by creating Spring Context. Hazelcast instance is declared in Spring context and is injected / auto-wired to other beans. Data partitioning happens during Hazelcast instance initialization (?!).

P.S. If I start first node with no data loaded , than the issue does not come (because of no data to re-partition ?!?!?!).

Any help is appreciated.

Threads dump

**********************************

"hz._hzInstance_1_atlant-vc.partition-operation.thread-1" prio=6 tid=0x000000000cb9e800 nid=0xf00 waiting for monitor entry [0x000000000deae000]

java.lang.Thread.State: BLOCKED (on object monitor)

at com.hazelcast.util.ConcurrencyUtil.getOrPutSynchronized(ConcurrencyUtil.java:38)

- waiting to lock <0x00000000f4608a78> (a java.util.concurrent.ConcurrentHashMap)

at com.hazelcast.map.impl.DefaultMapServiceContext.getMapContainer(DefaultMapServiceContext.java:76)

at com.hazelcast.map.impl.PartitionContainer$1.createNew(PartitionContainer.java:39)

at com.hazelcast.map.impl.PartitionContainer$1.createNew(PartitionContainer.java:37)

at com.hazelcast.util.ConcurrencyUtil.getOrPutSynchronized(ConcurrencyUtil.java:40)

- locked <0x00000000f45eed28> (a com.hazelcast.map.impl.PartitionContainer)

at com.hazelcast.map.impl.PartitionContainer.getRecordStore(PartitionContainer.java:78)

at com.hazelcast.map.impl.DefaultMapServiceContext.getRecordStore(DefaultMapServiceContext.java:172)

at com.hazelcast.map.impl.operation.MapReplicationOperation.run(MapReplicationOperation.java:110)

at com.hazelcast.partition.impl.ReplicaSyncResponse.executeTasks(ReplicaSyncResponse.java:103)

at com.hazelcast.partition.impl.ReplicaSyncResponse.run(ReplicaSyncResponse.java:68)

at com.hazelcast.spi.impl.BasicOperationService$OperationHandler.handle(BasicOperationService.java:733)

at com.hazelcast.spi.impl.BasicOperationService$OperationHandler.access$500(BasicOperationService.java:709)

at com.hazelcast.spi.impl.BasicOperationService$OperationPacketHandler.handle(BasicOperationService.java:683)

at com.hazelcast.spi.impl.BasicOperationService$OperationPacketHandler.handle(BasicOperationService.java:627)

at com.hazelcast.spi.impl.BasicOperationService$OperationPacketHandler.access$1500(BasicOperationService.java:614)

at com.hazelcast.spi.impl.BasicOperationService$BasicDispatcherImpl.dispatch(BasicOperationService.java:566)

at com.hazelcast.spi.impl.BasicOperationScheduler$OperationThread.process(BasicOperationScheduler.java:466)

at com.hazelcast.spi.impl.BasicOperationScheduler$OperationThread.processPriorityMessages(BasicOperationScheduler.java:480)

at com.hazelcast.spi.impl.BasicOperationScheduler$OperationThread.doRun(BasicOperationScheduler.java:457)

at com.hazelcast.spi.impl.BasicOperationScheduler$OperationThread.run(BasicOperationScheduler.java:432)

Locked ownable synchronizers:

- None

"hz._hzInstance_1_atlant-vc.partition-operation.thread-0" prio=6 tid=0x000000000b0ff800 nid=0x1b9c waiting for monitor entry [0x000000000dafe000]

java.lang.Thread.State: BLOCKED (on object monitor)

at com.hazelcast.util.ConcurrencyUtil.getOrPutSynchronized(ConcurrencyUtil.java:38)

- waiting to lock <0x00000000f4608a78> (a java.util.concurrent.ConcurrentHashMap)

at com.hazelcast.map.impl.DefaultMapServiceContext.getMapContainer(DefaultMapServiceContext.java:76)

at com.hazelcast.map.impl.PartitionContainer$1.createNew(PartitionContainer.java:39)

at com.hazelcast.map.impl.PartitionContainer$1.createNew(PartitionContainer.java:37)

at com.hazelcast.util.ConcurrencyUtil.getOrPutSynchronized(ConcurrencyUtil.java:40)

- locked <0x00000000f45eeb10> (a com.hazelcast.map.impl.PartitionContainer)