Terracotta Discussion Forums (LEGACY READ-ONLY ARCHIVE)

Thank you.

I need to download Terracotta 3.7.7, but the download links does not work anymore. Can anyone help me with a working set of download links?

This has happened a few times again, and just restarting Terracotta and the Tomcat instances does not help.

We deleted the entire Terracotta cache through the developer console and this has proved to stop the crashes that happens from time to time.

gyan10 wrote:

You will need the -s to turn SSL on, then use valid credentials to authenticate.
You need to explicitly tell it you'll be connecting to a secured environment.

Hope this will help. If this will nto resolve your problem, please come back with your TC version.

Cheers!!

Not sure if I get what you mean, as I set up an SSH tunnel so localhost:9520 on my machine is transparently tunneled to the Terracotta-server. Do you mean to use the -s option to the ssh-client when I setup the tunnel?

We are using Terracotta 3.5.4.

I can't get it working. Is there any other ports I need forwarded apart from TCP:9520?

My scheme is this:

Workstation -> Login server -> Terracotta server

So I setup a SSH tunnel through the login server to the terracotta server instance at port 9520.

klalithr wrote:

From first look it seems like an issue with the version of TSA you are using and would recommend an upgrade to the latest version.

But in the meantime can you add to this community JIRA (https://jira.terracotta.org/jira/browse/CDV-1637) with the complete Terracotta Server and Client logs from the date and time of the incident. Also indicate what you are using TSA for (I suspect that its WebSessions module that you are using). Are you using Hibernate in your app by any chance? Please indicate all this in the JIRA

Thanks, I will do it right over the weekend.

From the terracotta-client log I got the following entries

Code:

 2012-11-01 19:56:23,436 [WorkerThread(receive_server_map_eviction_broadcast_stage, 0)] ERROR com.tc.object.DistributedObjectClient - Thread:Thread[WorkerThread(receive_server_map_eviction_broadcast_stage, 0),5
 ,TC Thread Group] got an uncaught exception. calling CallbackOnExitDefaultHandlers.
 net.sf.ehcache.CacheException: java.lang.NullPointerException
         at org.terracotta.modules.ehcache.store.ValueModeHandlerSerialization.getRealKeyObject(ValueModeHandlerSerialization.java:128)
         at org.terracotta.modules.ehcache.store.ValueModeHandlerSoftLockAwareSerialization.getRealKeyObject(ValueModeHandlerSoftLockAwareSerialization.java:68)
         at org.terracotta.modules.ehcache.store.ClusteredStoreBackendImpl$TDCWithEvents.onEvict(ClusteredStoreBackendImpl.java:204)
         at org.terracotta.cache.TerracottaDistributedCache.evicted(TerracottaDistributedCache.java:447)
         at com.terracotta.toolkit.collections.ConcurrentDistributedServerMapDso.notifyElementEvicted(ConcurrentDistributedServerMapDso.java:436)
         at com.terracotta.toolkit.collections.ConcurrentDistributedServerMapDso.evictedInServer(ConcurrentDistributedServerMapDso.java:425)
         at com.tc.object.handler.ReceiveServerMapEvictionBroadcastHandler.handleEvent(ReceiveServerMapEvictionBroadcastHandler.java:39)
         at com.tc.async.impl.StageImpl$WorkerThread.run(StageImpl.java:135)
 Caused by: java.lang.NullPointerException
 2012-11-01 19:56:24,572 [WorkerThread(receive_server_map_eviction_broadcast_stage, 0)] ERROR com.tc.logging.ThreadDumpHandler - Thu Nov 01 19:56:23 CET 2012
 Full thread dump Java HotSpot(TM) 64-Bit Server VM (20.4-b02 mixed mode):

We are running Terracotta 3.5.4 and Tomcat 6.0.35. Yesterday our tomcat application servers seemed to stop randomly, complaining about "Terracotta is not running". Terracotta was running. Restarting the Tomcat got the application started again.

I've looked at the GC logs, and the GC patterns looks fine.

Does anyone in here have any suggestions on what could be the problem or how to further debug this?

Code:

net.sf.ehcache.CacheException: java.lang.NullPointerException
         at org.terracotta.modules.ehcache.store.ValueModeHandlerSerialization.getRealKeyObject(ValueModeHandlerSerialization.java:128)
         at org.terracotta.modules.ehcache.store.ValueModeHandlerSoftLockAwareSerialization.getRealKeyObject(ValueModeHandlerSoftLockAwareSerialization.java:68)
         at org.terracotta.modules.ehcache.store.ClusteredStoreBackendImpl$TDCWithEvents.onEvict(ClusteredStoreBackendImpl.java:204)
         at org.terracotta.cache.TerracottaDistributedCache.evicted(TerracottaDistributedCache.java:447)
         at com.terracotta.toolkit.collections.ConcurrentDistributedServerMapDso.notifyElementEvicted(ConcurrentDistributedServerMapDso.java:436)
         at com.terracotta.toolkit.collections.ConcurrentDistributedServerMapDso.evictedInServer(ConcurrentDistributedServerMapDso.java:425)
         at com.tc.object.handler.ReceiveServerMapEvictionBroadcastHandler.handleEvent(ReceiveServerMapEvictionBroadcastHandler.java:39)
         at com.tc.async.impl.StageImpl$WorkerThread.run(StageImpl.java:135)
 Caused by: java.lang.NullPointerException
         at java.util.concurrent.ConcurrentHashMap.get(ConcurrentHashMap.java:768)
         at org.hibernate.impl.SessionFactoryObjectFactory.getNamedInstance(SessionFactoryObjectFactory.java:159)
         at org.hibernate.impl.SessionFactoryImpl.readResolve(SessionFactoryImpl.java:753)
         at sun.reflect.GeneratedMethodAccessor616.invoke(Unknown Source)
         at sun.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:25)
         at java.lang.reflect.Method.invoke(Method.java:597)
         at java.io.ObjectStreamClass.invokeReadResolve(ObjectStreamClass.java:1061)
         at java.io.ObjectInputStream.readOrdinaryObject(ObjectInputStream.java:1761)
         at java.io.ObjectInputStream.readObject0(ObjectInputStream.java:1328)
         at java.io.ObjectInputStream.defaultReadFields(ObjectInputStream.java:1946)
         at java.io.ObjectInputStream.readSerialData(ObjectInputStream.java:1870)
         at java.io.ObjectInputStream.readOrdinaryObject(ObjectInputStream.java:1752)
         at java.io.ObjectInputStream.readObject0(ObjectInputStream.java:1328)
         at java.io.ObjectInputStream.defaultReadFields(ObjectInputStream.java:1946)
         at java.io.ObjectInputStream.readSerialData(ObjectInputStream.java:1870)
         at java.io.ObjectInputStream.readOrdinaryObject(ObjectInputStream.java:1752)
         at java.io.ObjectInputStream.readObject0(ObjectInputStream.java:1328)
         at java.io.ObjectInputStream.defaultReadFields(ObjectInputStream.java:1946)
         at java.io.ObjectInputStream.readSerialData(ObjectInputStream.java:1870)
         at java.io.ObjectInputStream.readOrdinaryObject(ObjectInputStream.java:1752)
         at java.io.ObjectInputStream.readObject0(ObjectInputStream.java:1328)
         at java.io.ObjectInputStream.readObject(ObjectInputStream.java:350)
         at java.util.HashMap.readObject(HashMap.java:1030)
         at sun.reflect.GeneratedMethodAccessor121.invoke(Unknown Source)
         at sun.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:25)
         at java.lang.reflect.Method.invoke(Method.java:597)
         at java.io.ObjectStreamClass.invokeReadObject(ObjectStreamClass.java:974)
         at java.io.ObjectInputStream.readSerialData(ObjectInputStream.java:1848)
         at java.io.ObjectInputStream.readOrdinaryObject(ObjectInputStream.java:1752)
         at java.io.ObjectInputStream.readObject0(ObjectInputStream.java:1328)
         at java.io.ObjectInputStream.defaultReadFields(ObjectInputStream.java:1946)
         at java.io.ObjectInputStream.defaultReadObject(ObjectInputStream.java:479)
         at org.hibernate.cache.QueryKey.readObject(QueryKey.java:192)
         at sun.reflect.GeneratedMethodAccessor448.invoke(Unknown Source)
         at sun.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:25)
         at java.lang.reflect.Method.invoke(Method.java:597)
         at java.io.ObjectStreamClass.invokeReadObject(ObjectStreamClass.java:974)
         at java.io.ObjectInputStream.readSerialData(ObjectInputStream.java:1848)
         at java.io.ObjectInputStream.readOrdinaryObject(ObjectInputStream.java:1752)
         at java.io.ObjectInputStream.readObject0(ObjectInputStream.java:1328)
         at java.io.ObjectInputStream.readObject(ObjectInputStream.java:350)
         at org.terracotta.cache.serialization.DsoSerializationStrategy2.deserializeStringKey(DsoSerializationStrategy2.java:73)
         at org.terracotta.modules.ehcache.store.HibernateElementSerializationStrategy.deserializeStringKey(HibernateElementSerializationStrategy.java:36)
         at org.terracotta.modules.ehcache.store.ValueModeHandlerSerialization.getRealKeyObject(ValueModeHandlerSerialization.java:126)
         ... 7 more
 Nov 1, 2012 2:26:24 PM org.apache.coyote.http11.Http11Protocol pause
 INFO: Pausing Coyote HTTP/1.1 on http-8090
 Nov 1, 2012 2:26:24 PM org.apache.catalina.core.StandardWrapperValve invoke
 SEVERE: Servlet.service() for servlet Spring MVC Dispatcher Servlet threw exception
 com.tc.exception.TCNotRunningException: Terracotta is not running.
         at com.tc.object.locks.ClientLockManagerImpl.waitUntilRunning(ClientLockManagerImpl.java:628)
         at com.tc.object.locks.ClientLockManagerImpl.lock(ClientLockManagerImpl.java:92)
         at com.tc.object.bytecode.ManagerImpl.lock(ManagerImpl.java:796)
         at com.tc.object.bytecode.ManagerImpl.monitorEnter(ManagerImpl.java:930)
         at com.tc.object.bytecode.ManagerUtil.instrumentationMonitorEnter(ManagerUtil.java:590)
         at com.terracotta.session.SessionData.getAttribute(SessionData.java:332)
         at org.springframework.security.web.context.HttpSessionSecurityContextRepository$SaveToSessionResponseWrapper.saveContext(HttpSessionSecurityContextRepository.java:287)
         at org.springframework.security.web.context.HttpSessionSecurityContextRepository.saveContext(HttpSessionSecurityContextRepository.java:104)
         at org.springframework.security.web.context.SecurityContextPersistenceFilter.doFilter(SecurityContextPersistenceFilter.java:93)
         at org.springframework.security.web.FilterChainProxy$VirtualFilterChain.doFilter(FilterChainProxy.java:323)
         at org.springframework.security.web.session.ConcurrentSessionFilter.doFilter(ConcurrentSessionFilter.java:125)
         at org.springframework.security.web.FilterChainProxy$VirtualFilterChain.doFilter(FilterChainProxy.java:323)
         at org.springframework.security.web.FilterChainProxy.doFilter(FilterChainProxy.java:173)
         at org.springframework.web.filter.DelegatingFilterProxy.invokeDelegate(DelegatingFilterProxy.java:346)
         at org.springframework.web.filter.DelegatingFilterProxy.doFilter(DelegatingFilterProxy.java:259)
         at org.apache.catalina.core.ApplicationFilterChain.internalDoFilter(ApplicationFilterChain.java:235)
         at org.apache.catalina.core.ApplicationFilterChain.doFilter(ApplicationFilterChain.java:206)
         at org.springframework.web.filter.HiddenHttpMethodFilter.doFilterInternal(HiddenHttpMethodFilter.java:77)
         at org.springframework.web.filter.OncePerRequestFilter.doFilter(OncePerRequestFilter.java:76)
         at org.apache.catalina.core.ApplicationFilterChain.internalDoFilter(ApplicationFilterChain.java:235)
         at org.apache.catalina.core.ApplicationFilterChain.doFilter(ApplicationFilterChain.java:206)
         at org.springframework.web.filter.CharacterEncodingFilter.doFilterInternal(CharacterEncodingFilter.java:88)
         at org.springframework.web.filter.OncePerRequestFilter.doFilter(OncePerRequestFilter.java:76)
         at org.apache.catalina.core.ApplicationFilterChain.internalDoFilter(ApplicationFilterChain.java:235)
         at org.apache.catalina.core.ApplicationFilterChain.doFilter(ApplicationFilterChain.java:206)
         at no.mintra.trainingportal.interfaces.web.logging.session.HttpSessionSizeMonitoringFilter.doFilter(HttpSessionSizeMonitoringFilter.java:52)
         at org.apache.catalina.core.ApplicationFilterChain.internalDoFilter(ApplicationFilterChain.java:235)
         at org.apache.catalina.core.ApplicationFilterChain.doFilter(ApplicationFilterChain.java:206)
         at org.apache.catalina.core.StandardWrapperValve.invoke(StandardWrapperValve.java:233)
         at org.apache.catalina.core.StandardContextValve.invoke(StandardContextValve.java:191)
         at org.terracotta.modules.tomcat.tomcat_5_5.SessionValve55.tcInvoke(SessionValve55.java:99)
         at org.terracotta.modules.tomcat.tomcat_5_5.SessionValve55.invoke(SessionValve55.java:85)
         at org.terracotta.session.ModernTomcatSessionValve.invoke(ModernTomcatSessionValve.java:66)
         at org.apache.catalina.core.StandardHostValve.invoke(StandardHostValve.java:127)
         at org.apache.catalina.valves.ErrorReportValve.invoke(ErrorReportValve.java:102)
         at org.apache.catalina.core.StandardEngineValve.invoke(StandardEngineValve.java:109)
         at org.apache.catalina.valves.AccessLogValve.invoke(AccessLogValve.java:615)
         at org.apache.catalina.connector.CoyoteAdapter.service(CoyoteAdapter.java:293)
         at org.apache.coyote.http11.Http11Processor.process(Http11Processor.java:859)
         at org.apache.coyote.http11.Http11Protocol$Http11ConnectionHandler.process(Http11Protocol.java:602)
         at org.apache.tomcat.util.net.JIoEndpoint$Worker.run(JIoEndpoint.java:489)
         at java.lang.Thread.run(Thread.java:662)
 Nov 1, 2012 2:26:24 PM org.apache.coyote.http11.Http11Processor process
 SEVERE: Error processing request
 com.tc.exception.TCNotRunningException: Terracotta is not running.
         at com.tc.object.locks.ClientLockManagerImpl.waitUntilRunning(ClientLockManagerImpl.java:628)
         at com.tc.object.locks.ClientLockManagerImpl.lock(ClientLockManagerImpl.java:92)
         at com.tc.object.bytecode.ManagerImpl.lock(ManagerImpl.java:796)
         at com.tc.object.bytecode.ManagerUtil.beginLock(ManagerUtil.java:221)
         at com.terracotta.session.util.Lock.getWriteLock(Lock.java:40)
         at com.terracotta.session.util.DefaultSessionId.getWriteLock(DefaultSessionId.java:64)
         at com.terracotta.session.TerracottaSessionManager.postprocessSession(TerracottaSessionManager.java:497)
         at com.terracotta.session.TerracottaSessionManager.basicPostprocess(TerracottaSessionManager.java:462)
         at com.terracotta.session.TerracottaSessionManager.postprocess(TerracottaSessionManager.java:443)
         at org.terracotta.modules.tomcat.tomcat_5_5.SessionValve55.tcInvoke(SessionValve55.java:101)
         at org.terracotta.modules.tomcat.tomcat_5_5.SessionValve55.invoke(SessionValve55.java:85)
         at org.terracotta.session.ModernTomcatSessionValve.invoke(ModernTomcatSessionValve.java:66)
         at org.apache.catalina.core.StandardHostValve.invoke(StandardHostValve.java:127)
         at org.apache.catalina.valves.ErrorReportValve.invoke(ErrorReportValve.java:102)
         at org.apache.catalina.core.StandardEngineValve.invoke(StandardEngineValve.java:109)
         at org.apache.catalina.valves.AccessLogValve.invoke(AccessLogValve.java:615)
         at org.apache.catalina.connector.CoyoteAdapter.service(CoyoteAdapter.java:293)
         at org.apache.coyote.http11.Http11Processor.process(Http11Processor.java:859)
         at org.apache.coyote.http11.Http11Protocol$Http11ConnectionHandler.process(Http11Protocol.java:602)
         at org.apache.tomcat.util.net.JIoEndpoint$Worker.run(JIoEndpoint.java:489)
         at java.lang.Thread.run(Thread.java:662)

Hi,

Can anyone help me explain how to set this up properly and what the jvmRoute and com.tc.session.serverid means to Tomcat and Terracotta? We recently started loadbalancing our application and immediately ran into session problems.

Is jvmRoute (in Tomcat's server.xml) and the Tomcat JVM parameter -Dcom.tc.session.serverid necessary to be set for sessions to work properly when loadbalanced? Can anyone please explain how this works to me?

Our setup is as follows:

node 1: Terracotta, and Tomcat as a Terracotta-client
node 2: Tomcat as a Terracotta-client

sghose wrote:

What is your heap space? Have you performed GC tuning? Please post your GC logs. Have you considered big memory?

Heap space: -XX:MaxDirectMemorySize=64g -Xms1024m -Xmx4096m
GC tuning: No, but we increased memory parameters from -Xms512m and -Xmx2048m to what I wrote above.
GC logs:

Code:

238518.184: [GC [PSYoungGen: 517548K->15486K(949248K)] 2800396K->2306303K(3518208K), 0.0707480 secs] [Times: user=0.19 sys=0.01, real=0.08 secs] 
 238555.803: [GC [PSYoungGen: 515902K->14286K(940032K)] 2806719K->2313434K(3508992K), 0.0493740 secs] [Times: user=0.18 sys=0.01, real=0.05 secs] 
 238628.738: [GC [PSYoungGen: 515086K->30195K(944832K)] 2814234K->2335535K(3513792K), 0.0465360 secs] [Times: user=0.18 sys=0.01, real=0.05 secs] 
 238649.967: [GC [PSYoungGen: 530995K->44326K(929728K)] 2836335K->2349665K(3498688K), 0.0461340 secs] [Times: user=0.18 sys=0.00, real=0.05 secs] 
 238668.773: [GC [PSYoungGen: 564902K->55113K(939008K)] 2870241K->2360453K(3507968K), 0.0567160 secs] [Times: user=0.22 sys=0.01, real=0.05 secs] 
 238762.150: [GC [PSYoungGen: 574518K->92813K(900608K)] 2879857K->2398153K(3469568K), 0.0875090 secs] [Times: user=0.33 sys=0.00, real=0.09 secs] 
 238838.185: [GC [PSYoungGen: 646285K->184428K(929984K)] 2951625K->2489767K(3498944K), 0.0990490 secs] [Times: user=0.32 sys=0.00, real=0.10 secs] 
 238880.823: [GC [PSYoungGen: 736452K->236361K(943616K)] 3041791K->2541701K(3512576K), 0.0900120 secs] [Times: user=0.36 sys=0.00, real=0.09 secs] 
 238889.743: [GC [PSYoungGen: 803849K->251810K(960576K)] 3109189K->2557149K(3529536K), 0.0759080 secs] [Times: user=0.28 sys=0.00, real=0.07 secs] 
 238908.339: [GC [PSYoungGen: 819298K->285222K(936512K)] 3124637K->2590562K(3505472K), 0.1178390 secs] [Times: user=0.35 sys=0.10, real=0.12 secs] 
 238934.947: [GC [PSYoungGen: 810726K->323978K(849536K)] 3116066K->2629318K(3418496K), 0.0934970 secs] [Times: user=0.37 sys=0.00, real=0.10 secs] 
 238983.022: [GC [PSYoungGen: 849482K->348228K(932096K)] 3154822K->2682451K(3501056K), 0.1424660 secs] [Times: user=0.47 sys=0.08, real=0.14 secs] 
 238985.397: [GC [PSYoungGen: 811358K->420335K(932096K)] 3145581K->2779317K(3501056K), 0.1274510 secs] [Times: user=0.46 sys=0.05, real=0.12 secs] 
 238987.945: [GC [PSYoungGen: 881737K->369645K(932096K)] 3240718K->2857300K(3501056K), 0.2078420 secs] [Times: user=0.43 sys=0.37, real=0.21 secs] 
 238988.153: [Full GC [PSYoungGen: 369645K->284293K(932096K)] [PSOldGen: 2487654K->2568941K(2796224K)] 2857300K->2853234K(3728320K) [PSPermGen: 41566K->41566K(42688K)], 1.1118760 secs] [Times: user=0.98 sys=0.13, real=1.11 secs] 
 238990.365: [GC [PSYoungGen: 463120K->306578K(932096K)] 3032061K->2875520K(3728320K), 0.0972990 secs] [Times: user=0.38 sys=0.01, real=0.10 secs] 
 238992.663: [GC [PSYoungGen: 767068K->425074K(932096K)] 3336009K->2994015K(3728320K), 0.1213580 secs] [Times: user=0.33 sys=0.14, real=0.12 secs] 
 238993.991: [GC [PSYoungGen: 891157K->465857K(932096K)] 3460099K->3139527K(3728320K), 0.2041020 secs] [Times: user=0.41 sys=0.36, real=0.20 secs] 
 238994.195: [Full GC [PSYoungGen: 465857K->310061K(932096K)] [PSOldGen: 2673670K->2796195K(2796224K)] 3139527K->3106256K(3728320K) [PSPermGen: 41611K->41611K(42624K)], 1.2317020 secs] [Times: user=1.03 sys=0.20, real=1.23 secs] 
 238995.643: [Full GC [PSYoungGen: 466112K->175199K(932096K)] [PSOldGen: 2796195K->2795282K(2796224K)] 3262307K->2970482K(3728320K) [PSPermGen: 41611K->41590K(42496K)], 1.6663650 secs] [Times: user=1.66 sys=0.00, real=1.67 secs] 
 238997.767: [Full GC [PSYoungGen: 466112K->290015K(932096K)] [PSOldGen: 2795282K->2795282K(2796224K)] 3261394K->3085298K(3728320K) [PSPermGen: 41592K->41592K(42368K)], 0.8176170 secs] [Times: user=0.82 sys=0.00, real=0.82 secs] 
 238998.980: [Full GC [PSYoungGen: 456089K->340264K(932096K)] [PSOldGen: 2795282K->2795282K(2796224K)] 3251371K->3135547K(3728320K) [PSPermGen: 41592K->41592K(42304K)], 0.8614560 secs] [Times: user=0.86 sys=0.00, real=0.86 secs] 
 239000.282: [Full GC [PSYoungGen: 463895K->338258K(932096K)] [PSOldGen: 2795282K->2795282K(2796224K)] 3259178K->3133540K(3728320K) [PSPermGen: 41592K->41592K(42240K)], 0.8564200 secs] [Times: user=0.85 sys=0.00, real=0.85 secs] 
 239002.704: [Full GC [PSYoungGen: 466112K->303211K(932096K)] [PSOldGen: 2795282K->2796206K(2796224K)] 3261394K->3099418K(3728320K) [PSPermGen: 41593K->41593K(42176K)], 1.6105050 secs] [Times: user=1.59 sys=0.00, real=1.61 secs] 
 239004.626: [Full GC [PSYoungGen: 466112K->366288K(932096K)] [PSOldGen: 2796206K->2796206K(2796224K)] 3262318K->3162495K(3728320K) [PSPermGen: 41593K->41593K(42176K)], 0.8248970 secs] [Times: user=0.83 sys=0.00, real=0.83 secs] 
 239005.503: [Full GC [PSYoungGen: 460248K->362004K(932096K)] [PSOldGen: 2796206K->2796206K(2796224K)] 3256455K->3158211K(3728320K) [PSPermGen: 41593K->41593K(42112K)], 0.8022140 secs] [Times: user=0.81 sys=0.00, real=0.80 secs] 
 239006.503: [Full GC [PSYoungGen: 464993K->388126K(932096K)] [PSOldGen: 2796206K->2796206K(2796224K)] 3261199K->3184333K(3728320K) [PSPermGen: 41593K->41593K(42048K)], 0.8165070 secs] [Times: user=0.80 sys=0.01, real=0.81 secs] 
 239007.336: [Full GC [PSYoungGen: 463207K->419989K(932096K)] [PSOldGen: 2796206K->2792020K(2796224K)] 3259413K->3212010K(3728320K) [PSPermGen: 41593K->41593K(42048K)], 1.4124090 secs] [Times: user=1.41 sys=0.00, real=1.41 secs] 
 239008.829: [Full GC [PSYoungGen: 466111K->466111K(932096K)] [PSOldGen: 2792020K->2792020K(2796224K)] 3258132K->3258132K(3728320K) [PSPermGen: 41593K->41593K(41984K)], 0.8015900 secs] [Times: user=0.80 sys=0.00, real=0.81 secs] 
 239009.634: [Full GC [PSYoungGen: 466112K->466112K(932096K)] [PSOldGen: 2792052K->2792052K(2796224K)] 3258164K->3258164K(3728320K) [PSPermGen: 41593K->41593K(41984K)], 0.8015930 secs] [Times: user=0.80 sys=0.00, real=0.80 secs] 
 239010.439: [Full GC [PSYoungGen: 466112K->466112K(932096K)] [PSOldGen: 2792053K->2792053K(2796224K)] 3258165K->3258165K(3728320K) [PSPermGen: 41593K->41593K(41984K)], 0.7898200 secs] [Times: user=0.79 sys=0.00, real=0.79 secs] 
 239011.232: [Full GC [PSYoungGen: 466112K->455240K(932096K)] [PSOldGen: 2792053K->2792020K(2796224K)] 3258165K->3247260K(3728320K) [PSPermGen: 41593K->41593K(41984K)], 0.8892080 secs] [Times: user=0.88 sys=0.00, real=0.89 secs] 
 239012.170: [Full GC [PSYoungGen: 466088K->466088K(932096K)] [PSOldGen: 2792020K->2792020K(2796224K)] 3258109K->3258109K(3728320K) [PSPermGen: 41593K->41593K(41920K)], 0.8039310 secs] [Times: user=0.80 sys=0.00, real=0.80 secs] 
 239012.978: [Full GC [PSYoungGen: 466112K->466112K(932096K)] [PSOldGen: 2792052K->2792052K(2796224K)] 3258164K->3258164K(3728320K) [PSPermGen: 41593K->41593K(41920K)], 0.8026690 secs] [Times: user=0.80 sys=0.00, real=0.80 secs] 
 239013.784: [Full GC [PSYoungGen: 466112K->466112K(932096K)] [PSOldGen: 2792084K->2792084K(2796224K)] 3258196K->3258196K(3728320K) [PSPermGen: 41593K->41593K(41920K)], 0.8219370 secs] [Times: user=0.81 sys=0.01, real=0.82 secs] 
 239014.609: [Full GC [PSYoungGen: 466112K->459510K(932096K)] [PSOldGen: 2792084K->2792051K(2796224K)] 3258196K->3251561K(3728320K) [PSPermGen: 41593K->41593K(41920K)], 1.3822780 secs] [Times: user=1.38 sys=0.00, real=1.39 secs] 
 239016.007: [Full GC [PSYoungGen: 463519K->463519K(932096K)] [PSOldGen: 2792051K->2792051K(2796224K)] 3255571K->3255571K(3728320K) [PSPermGen: 41593K->41593K(41920K)], 0.7939730 secs] [Times: user=0.79 sys=0.00, real=0.80 secs] 
 239016.819: [Full GC [PSYoungGen: 466082K->466082K(932096K)] [PSOldGen: 2796086K->2796086K(2796224K)] 3262168K->3262168K(3728320K) [PSPermGen: 41593K->41593K(41920K)], 0.7929880 secs] [Times: user=0.79 sys=0.00, real=0.80 secs] 
 239017.616: [Full GC [PSYoungGen: 466100K->466100K(932096K)] [PSOldGen: 2796118K->2796118K(2796224K)] 3262218K->3262218K(3728320K) [PSPermGen: 41593K->41593K(41920K)], 0.7838850 secs] [Times: user=0.78 sys=0.00, real=0.78 secs] 
 239018.404: [Full GC [PSYoungGen: 466112K->461632K(932096K)] [PSOldGen: 2796150K->2796149K(2796224K)] 3262262K->3257781K(3728320K) [PSPermGen: 41593K->41593K(41920K)], 1.3725830 secs] [Times: user=1.37 sys=0.00, real=1.37 secs] 
 239019.928: [Full GC [PSYoungGen: 466112K->466112K(932096K)] [PSOldGen: 2796149K->2796149K(2796224K)] 3262261K->3262261K(3728320K) [PSPermGen: 41593K->41593K(41920K)], 0.7977830 secs] [Times: user=0.80 sys=0.05, real=0.80 secs] 
 239020.729: [Full GC [PSYoungGen: 466112K->466112K(932096K)] [PSOldGen: 2796149K->2796149K(2796224K)] 3262261K->3262261K(3728320K) [PSPermGen: 41593K->41593K(41920K)], 0.8074070 secs] [Times: user=0.80 sys=0.00, real=0.81 secs] 
 239021.540: [Full GC [PSYoungGen: 466112K->466112K(932096K)] [PSOldGen: 2796149K->2796149K(2796224K)] 3262261K->3262261K(3728320K) [PSPermGen: 41593K->41593K(41920K)], 0.7993500 secs] [Times: user=0.80 sys=0.00, real=0.80 secs] 
 239022.343: [Full GC [PSYoungGen: 466112K->462388K(932096K)] [PSOldGen: 2796149K->2796145K(2796224K)] 3262261K->3258533K(3728320K) [PSPermGen: 41593K->41593K(41920K)], 1.0750880 secs] [Times: user=1.07 sys=0.00, real=1.07 secs] 
 239023.535: [Full GC [PSYoungGen: 466101K->466101K(932096K)] [PSOldGen: 2796145K->2796145K(2796224K)] 3262246K->3262246K(3728320K) [PSPermGen: 41593K->41593K(41856K)], 0.8029610 secs] [Times: user=0.80 sys=0.00, real=0.80 secs] 
 239024.342: [Full GC [PSYoungGen: 466112K->466112K(932096K)] [PSOldGen: 2796177K->2796177K(2796224K)] 3262289K->3262289K(3728320K) [PSPermGen: 41593K->41593K(41856K)], 0.8082340 secs] [Times: user=0.81 sys=0.00, real=0.81 secs] 
 239025.153: [Full GC [PSYoungGen: 466112K->466112K(932096K)] [PSOldGen: 2796177K->2796177K(2796224K)] 3262289K->3262289K(3728320K) [PSPermGen: 41593K->41593K(41856K)], 0.8052170 secs] [Times: user=0.80 sys=0.00, real=0.80 secs] 
 239025.962: [Full GC [PSYoungGen: 466112K->462795K(932096K)] [PSOldGen: 2796177K->2796139K(2796224K)] 3262289K->3258935K(3728320K) [PSPermGen: 41593K->41593K(41856K)], 0.9875750 secs] [Times: user=0.98 sys=0.00, real=0.99 secs] 
 239026.965: [Full GC [PSYoungGen: 466098K->466098K(932096K)] [PSOldGen: 2796139K->2796139K(2796224K)] 3262237K->3262237K(3728320K) [PSPermGen: 41593K->41593K(41856K)], 0.7999480 secs] [Times: user=0.80 sys=0.00, real=0.80 secs] 
 239027.769: [Full GC [PSYoungGen: 466112K->466112K(932096K)] [PSOldGen: 2796171K->2796171K(2796224K)] 3262283K->3262283K(3728320K) [PSPermGen: 41593K->41593K(41856K)], 0.8045990 secs] [Times: user=0.80 sys=0.00, real=0.81 secs] 
 239028.577: [Full GC [PSYoungGen: 466112K->466112K(932096K)] [PSOldGen: 2796203K->2796203K(2796224K)] 3262315K->3262315K(3728320K) [PSPermGen: 41593K->41593K(41856K)], 0.8038200 secs] [Times: user=0.80 sys=0.00, real=0.80 secs] 
 239029.385: [Full GC [PSYoungGen: 466112K->463921K(932096K)] [PSOldGen: 2796203K->2796171K(2796224K)] 3262315K->3260092K(3728320K) [PSPermGen: 41593K->41593K(41856K)], 1.3621940 secs] [Times: user=1.36 sys=0.00, real=1.36 secs] 
 239030.764: [Full GC [PSYoungGen: 466093K->466093K(932096K)] [PSOldGen: 2796171K->2796171K(2796224K)] 3262264K->3262264K(3728320K) [PSPermGen: 41593K->41593K(41856K)], 0.8023280 secs] [Times: user=0.80 sys=0.00, real=0.80 secs] 
 239031.570: [Full GC [PSYoungGen: 466112K->466112K(932096K)] [PSOldGen: 2796203K->2796203K(2796224K)] 3262315K->3262315K(3728320K) [PSPermGen: 41593K->41593K(41856K)], 0.8092370 secs] [Times: user=0.81 sys=0.00, real=0.81 secs] 
 239032.383: [Full GC [PSYoungGen: 466112K->466112K(932096K)] [PSOldGen: 2796203K->2796203K(2796224K)] 3262315K->3262315K(3728320K) [PSPermGen: 41593K->41593K(41856K)], 0.8088320 secs] [Times: user=0.81 sys=0.00, real=0.81 secs] 
 239033.195: [Full GC [PSYoungGen: 466112K->464624K(932096K)] [PSOldGen: 2796203K->2796201K(2796224K)] 3262315K->3260826K(3728320K) [PSPermGen: 41593K->41593K(41856K)], 0.9585350 secs] [Times: user=0.96 sys=0.00, real=0.95 secs] 
 239034.169: [Full GC [PSYoungGen: 466112K->466112K(932096K)] [PSOldGen: 2796201K->2796201K(2796224K)] 3262313K->3262313K(3728320K) [PSPermGen: 41593K->41593K(41856K)], 0.8196450 secs] [Times: user=0.82 sys=0.00, real=0.82 secs] 
 239034.992: [Full GC [PSYoungGen: 466112K->466112K(932096K)] [PSOldGen: 2796201K->2796201K(2796224K)] 3262313K->3262313K(3728320K) [PSPermGen: 41593K->41593K(41856K)], 0.8461850 secs] [Times: user=0.84 sys=0.00, real=0.85 secs] 
 239035.842: [Full GC [PSYoungGen: 466112K->466112K(932096K)] [PSOldGen: 2796201K->2796201K(2796224K)] 3262313K->3262313K(3728320K) [PSPermGen: 41593K->41593K(41856K)], 0.7983790 secs] [Times: user=0.79 sys=0.00, real=0.80 secs] 
 239036.644: [Full GC [PSYoungGen: 466112K->464979K(932096K)] [PSOldGen: 2796201K->2796201K(2796224K)] 3262313K->3261181K(3728320K) [PSPermGen: 41593K->41593K(41856K)], 0.8090020 secs] [Times: user=0.80 sys=0.00, real=0.81 secs] 
 239037.461: [Full GC [PSYoungGen: 466112K->466112K(932096K)] [PSOldGen: 2796201K->2796201K(2796224K)] 3262313K->3262313K(3728320K) [PSPermGen: 41593K->41593K(41856K)], 0.8028370 secs] [Times: user=0.80 sys=0.00, real=0.80 secs] 
 239038.267: [Full GC [PSYoungGen: 466112K->466112K(932096K)] [PSOldGen: 2796201K->2796201K(2796224K)] 3262313K->3262313K(3728320K) [PSPermGen: 41593K->41593K(41856K)], 0.8101100 secs] [Times: user=0.81 sys=0.00, real=0.81 secs] 
 239039.081: [Full GC [PSYoungGen: 466112K->466112K(932096K)] [PSOldGen: 2796201K->2796201K(2796224K)] 3262313K->3262313K(3728320K) [PSPermGen: 41593K->41593K(41856K)], 0.7964010 secs] [Times: user=0.79 sys=0.00, real=0.80 secs] 
 239039.881: [Full GC [PSYoungGen: 466112K->465360K(932096K)] [PSOldGen: 2796201K->2796174K(2796224K)] 3262313K->3261535K(3728320K) [PSPermGen: 41593K->41543K(41856K)], 1.4840910 secs] [Times: user=1.48 sys=0.00, real=1.48 secs] 
 239072.102: [Full GC [PSYoungGen: 466112K->466112K(932096K)] [PSOldGen: 2796174K->2796174K(2796224K)] 3262286K->3262286K(3728320K) [PSPermGen: 41549K->41549K(41856K)], 0.8154340 secs] [Times: user=0.81 sys=0.00, real=0.81 secs] 
 239072.921: [Full GC [PSYoungGen: 466112K->466112K(932096K)] [PSOldGen: 2796175K->2796175K(2796224K)] 3262287K->3262287K(3728320K) [PSPermGen: 41549K->41549K(41856K)], 0.8033420 secs] [Times: user=0.80 sys=0.00, real=0.81 secs] 
 239073.728: [Full GC [PSYoungGen: 466112K->466112K(932096K)] [PSOldGen: 2796175K->2796175K(2796224K)] 3262287K->3262287K(3728320K) [PSPermGen: 41549K->41549K(41856K)], 0.8031690 secs] [Times: user=0.80 sys=0.00, real=0.81 secs] 
 239074.539: [Full GC [PSYoungGen: 466112K->465308K(932096K)] [PSOldGen: 2796175K->2796146K(2796224K)] 3262287K->3261454K(3728320K) [PSPermGen: 41549K->41548K(41856K)], 1.4674890 secs] [Times: user=1.45 sys=0.01, real=2.35 secs] 
 239076.896: [Full GC [PSYoungGen: 466112K->466112K(932096K)] [PSOldGen: 2796146K->2796146K(2796224K)] 3262258K->3262258K(3728320K) [PSPermGen: 41551K->41551K(41856K)], 0.8373320 secs] [Times: user=0.83 sys=0.01, real=0.84 secs] 
 239077.737: [Full GC [PSYoungGen: 466112K->466112K(932096K)] [PSOldGen: 2796146K->2796146K(2796224K)] 3262258K->3262258K(3728320K) [PSPermGen: 41551K->41551K(41856K)], 0.8133840 secs] [Times: user=0.81 sys=0.00, real=0.81 secs] 
 239078.554: [Full GC [PSYoungGen: 466112K->466112K(932096K)] [PSOldGen: 2796146K->2796146K(2796224K)] 3262258K->3262258K(3728320K) [PSPermGen: 41551K->41551K(41856K)], 0.8286300 secs] [Times: user=0.82 sys=0.00, real=0.82 secs] 
 239079.386: [Full GC [PSYoungGen: 466112K->465494K(932096K)] [PSOldGen: 2796146K->2795921K(2796224K)] 3262258K->3261415K(3728320K) [PSPermGen: 41551K->41549K(41856K)], 1.4319630 secs] [Times: user=1.43 sys=0.00, real=1.43 secs] 
 239080.824: [Full GC [PSYoungGen: 466112K->466112K(932096K)] [PSOldGen: 2795921K->2795921K(2796224K)] 3262033K->3262033K(3728320K) [PSPermGen: 41560K->41560K(41856K)], 0.8089140 secs] [Times: user=0.80 sys=0.00, real=0.81 secs] 
 239081.637: [Full GC [PSYoungGen: 466112K->466112K(932096K)] [PSOldGen: 2795921K->2795921K(2796224K)] 3262033K->3262033K(3728320K) [PSPermGen: 41560K->41560K(41856K)], 0.8091520 secs] [Times: user=0.81 sys=0.00, real=0.81 secs] 
 239082.449: [Full GC [PSYoungGen: 466112K->466112K(932096K)] [PSOldGen: 2795921K->2795921K(2796224K)] 3262033K->3262033K(3728320K) [PSPermGen: 41560K->41560K(41856K)], 0.8086390 secs] [Times: user=0.80 sys=0.00, real=0.81 secs] 
 239083.262: [Full GC [PSYoungGen: 466112K->465371K(932096K)] [PSOldGen: 2795921K->2795866K(2796224K)] 3262033K->3261237K(3728320K) [PSPermGen: 41560K->41558K(41856K)], 1.3984410 secs] [Times: user=1.38 sys=0.00, real=1.40 secs] 
 239084.667: [Full GC [PSYoungGen: 466112K->466112K(932096K)] [PSOldGen: 2795866K->2795866K(2796224K)] 3261978K->3261978K(3728320K) [PSPermGen: 41562K->41562K(41856K)], 0.7965620 secs] [Times: user=0.79 sys=0.00, real=0.79 secs] 
 239085.467: [Full GC [PSYoungGen: 466112K->466112K(932096K)] [PSOldGen: 2795866K->2795866K(2796224K)] 3261978K->3261978K(3728320K) [PSPermGen: 41562K->41562K(41856K)], 0.7970460 secs] [Times: user=0.80 sys=0.00, real=0.80 secs] 
 239086.268: [Full GC [PSYoungGen: 466112K->466112K(932096K)] [PSOldGen: 2795866K->2795866K(2796224K)] 3261978K->3261978K(3728320K) [PSPermGen: 41562K->41562K(41856K)], 0.8018760 secs] [Times: user=0.80 sys=0.00, real=0.80 secs] 
 239087.073: [Full GC [PSYoungGen: 466112K->465332K(932096K)] [PSOldGen: 2795866K->2795848K(2796224K)] 3261978K->3261180K(3728320K) [PSPermGen: 41562K->41562K(41856K)], 1.4208720 secs] [Times: user=1.43 sys=0.00, real=1.43 secs] 
 239088.501: [Full GC [PSYoungGen: 465931K->465931K(932096K)] [PSOldGen: 2795848K->2795848K(2796224K)] 3261780K->3261780K(3728320K) [PSPermGen: 41591K->41591K(41664K)], 0.8051340 secs] [Times: user=0.81 sys=0.00, real=0.81 secs] 
 239089.759: [Full GC [PSYoungGen: 466112K->466112K(932096K)] [PSOldGen: 2796048K->2796048K(2796224K)] 3262160K->3262160K(3728320K) [PSPermGen: 41603K->41603K(41664K)], 0.8263040 secs] [Times: user=0.83 sys=0.00, real=0.83 secs] 
 239090.589: [Full GC [PSYoungGen: 466112K->466112K(932096K)] [PSOldGen: 2796048K->2796048K(2796224K)] 3262160K->3262160K(3728320K) [PSPermGen: 41603K->41603K(41664K)], 0.8105770 secs] [Times: user=0.81 sys=0.00, real=0.81 secs] 
 239091.403: [Full GC [PSYoungGen: 466112K->465459K(932096K)] [PSOldGen: 2796048K->2796043K(2796224K)] 3262160K->3261503K(3728320K) [PSPermGen: 41603K->41594K(41664K)], 1.4565910 secs] [Times: user=1.46 sys=0.00, real=1.46 secs] 
 239092.867: [Full GC [PSYoungGen: 466112K->466112K(932096K)] [PSOldGen: 2796043K->2796043K(2796224K)] 3262155K->3262155K(3728320K) [PSPermGen: 41612K->41612K(41664K)], 0.8153230 secs] [Times: user=0.82 sys=0.00, real=0.81 secs] 
 239093.686: [Full GC [PSYoungGen: 466112K->466112K(932096K)] [PSOldGen: 2796043K->2796043K(2796224K)] 3262155K->3262155K(3728320K) [PSPermGen: 41612K->41612K(41664K)], 0.8042990 secs] [Times: user=0.80 sys=0.00, real=0.80 secs] 
 239094.494: [Full GC [PSYoungGen: 466112K->466112K(932096K)] [PSOldGen: 2796043K->2796043K(2796224K)] 3262155K->3262155K(3728320K) [PSPermGen: 41612K->41612K(41664K)], 0.8184960 secs] [Times: user=0.82 sys=0.00, real=0.82 secs] 
 239095.316: [Full GC [PSYoungGen: 466112K->465459K(932096K)] [PSOldGen: 2796043K->2796022K(2796224K)] 3262155K->3261481K(3728320K) [PSPermGen: 41612K->41591K(41664K)], 1.4477210 secs] [Times: user=1.44 sys=0.00, real=1.44 secs] 
 239096.770: [Full GC [PSYoungGen: 466112K->466112K(932096K)] [PSOldGen: 2796022K->2796022K(2796224K)] 3262134K->3262134K(3728320K) [PSPermGen: 41591K->41591K(41664K)], 0.8060470 secs] [Times: user=0.81 sys=0.00, real=0.81 secs] 
 239097.580: [Full GC [PSYoungGen: 466112K->466112K(932096K)] [PSOldGen: 2796054K->2796054K(2796224K)] 3262166K->3262166K(3728320K) [PSPermGen: 41591K->41591K(41664K)], 0.8002930 secs] [Times: user=0.80 sys=0.00, real=0.80 secs] 
 239098.383: [Full GC [PSYoungGen: 466112K->466112K(932096K)] [PSOldGen: 2796054K->2796054K(2796224K)] 3262166K->3262166K(3728320K) [PSPermGen: 41591K->41591K(41664K)], 0.8132280 secs] [Times: user=0.81 sys=0.00, real=0.82 secs] 
 239099.200: [Full GC [PSYoungGen: 466112K->465515K(932096K)] [PSOldGen: 2796054K->2795865K(2796224K)] 3262166K->3261380K(3728320K) [PSPermGen: 41591K->41591K(41664K)], 1.4300020 secs] [Times: user=1.42 sys=0.00, real=1.43 secs] 
 239100.638: [Full GC [PSYoungGen: 466112K->466112K(932096K)] [PSOldGen: 2795865K->2795865K(2796224K)] 3261977K->3261977K(3728320K) [PSPermGen: 41598K->41598K(41664K)], 0.8116620 secs] [Times: user=0.81 sys=0.00, real=0.81 secs] 
 239101.453: [Full GC [PSYoungGen: 466112K->466112K(932096K)] [PSOldGen: 2795897K->2795897K(2796224K)] 3262009K->3262009K(3728320K) [PSPermGen: 41598K->41598K(41664K)], 0.8122440 secs] [Times: user=0.81 sys=0.00, real=0.81 secs] 
 239102.269: [Full GC [PSYoungGen: 466112K->466112K(932096K)] [PSOldGen: 2795897K->2795897K(2796224K)] 3262009K->3262009K(3728320K) [PSPermGen: 41598K->41598K(41664K)], 0.8032460 secs] [Times: user=0.80 sys=0.00, real=0.80 secs] 
 239103.076: [Full GC [PSYoungGen: 466112K->465644K(932096K)] [PSOldGen: 2795897K->2795672K(2796224K)] 3262009K->3261316K(3728320K) [PSPermGen: 41598K->41592K(41664K)], 1.4600290 secs] [Times: user=1.46 sys=0.00, real=1.46 secs] 
 239104.540: [Full GC [PSYoungGen: 466112K->466112K(932096K)] [PSOldGen: 2795672K->2795672K(2796224K)] 3261784K->3261784K(3728320K) [PSPermGen: 41595K->41595K(41664K)], 0.8022690 secs] [Times: user=0.80 sys=0.00, real=0.80 secs] 
 239105.346: [Full GC [PSYoungGen: 466112K->466112K(932096K)] [PSOldGen: 2795672K->2795672K(2796224K)] 3261784K->3261784K(3728320K) [PSPermGen: 41595K->41595K(41664K)], 0.8205380 secs] [Times: user=0.82 sys=0.00, real=0.82 secs] 
 239106.170: [Full GC [PSYoungGen: 466112K->466112K(932096K)] [PSOldGen: 2795672K->2795672K(2796224K)] 3261784K->3261784K(3728320K) [PSPermGen: 41595K->41595K(41664K)], 0.8147170 secs] [Times: user=0.82 sys=0.00, real=0.81 secs] 
 239106.988: [Full GC [PSYoungGen: 466112K->465849K(932096K)] [PSOldGen: 2795672K->2795529K(2796224K)] 3261784K->3261378K(3728320K) [PSPermGen: 41595K->41595K(41664K)], 1.4169660 secs] [Times: user=1.42 sys=0.00, real=1.41 secs] 
 239108.412: [Full GC [PSYoungGen: 466112K->466112K(932096K)] [PSOldGen: 2795529K->2795529K(2796224K)] 3261641K->3261641K(3728320K) [PSPermGen: 41626K->41626K(41664K)], 0.8143180 secs] [Times: user=0.81 sys=0.00, real=0.81 secs] 
 239109.230: [Full GC [PSYoungGen: 466112K->466112K(932096K)] [PSOldGen: 2795529K->2795529K(2796224K)] 3261641K->3261641K(3728320K) [PSPermGen: 41626K->41626K(41664K)], 0.8099960 secs] [Times: user=0.81 sys=0.00, real=0.81 secs] 
 239110.044: [Full GC [PSYoungGen: 466112K->466112K(932096K)] [PSOldGen: 2795529K->2795529K(2796224K)] 3261641K->3261641K(3728320K) [PSPermGen: 41626K->41626K(41664K)], 0.8032560 secs] [Times: user=0.80 sys=0.00, real=0.80 secs] 
 239110.850: [Full GC [PSYoungGen: 466112K->465876K(932096K)] [PSOldGen: 2795529K->2795529K(2796224K)] 3261641K->3261405K(3728320K) [PSPermGen: 41626K->41622K(41664K)], 1.3361390 secs] [Times: user=1.34 sys=0.00, real=1.33 secs] 
 239112.195: [Full GC [PSYoungGen: 466112K->466112K(932096K)] [PSOldGen: 2795529K->2795529K(2796224K)] 3261641K->3261641K(3728320K) [PSPermGen: 41622K->41622K(41664K)], 0.8078270 secs] [Times: user=0.80 sys=0.00, real=0.81 secs] 
 239113.007: [Full GC [PSYoungGen: 466112K->466112K(932096K)] [PSOldGen: 2795529K->2795529K(2796224K)] 3261641K->3261641K(3728320K) [PSPermGen: 41622K->41622K(41664K)], 0.8020830 secs] [Times: user=0.80 sys=0.00, real=0.81 secs] 
 239113.812: [Full GC [PSYoungGen: 466112K->466112K(932096K)] [PSOldGen: 2795529K->2795529K(2796224K)] 3261641K->3261641K(3728320K) [PSPermGen: 41622K->41622K(41664K)], 0.8010950 secs] [Times: user=0.80 sys=0.00, real=0.80 secs] 
 239114.617: [Full GC [PSYoungGen: 466112K->465900K(932096K)] [PSOldGen: 2795529K->2795516K(2796224K)] 3261641K->3261417K(3728320K) [PSPermGen: 41622K->41622K(41664K)], 1.3561760 secs] [Times: user=1.35 sys=0.00, real=1.36 secs] 
 239115.978: [Full GC [PSYoungGen: 466112K->466112K(932096K)] [PSOldGen: 2795516K->2795516K(2796224K)] 3261628K->3261628K(3728320K) [PSPermGen: 41622K->41622K(41664K)], 0.7987550 secs] [Times: user=0.79 sys=0.00, real=0.80 secs] 
 239116.780: [Full GC [PSYoungGen: 466112K->466112K(932096K)] [PSOldGen: 2795516K->2795516K(2796224K)] 3261628K->3261628K(3728320K) [PSPermGen: 41622K->41622K(41664K)], 0.8014830 secs] [Times: user=0.80 sys=0.00, real=0.80 secs] 
 239117.585: [Full GC [PSYoungGen: 466112K->466112K(932096K)] [PSOldGen: 2795516K->2795516K(2796224K)] 3261628K->3261628K(3728320K) [PSPermGen: 41622K->41622K(41664K)], 0.8028210 secs] [Times: user=0.80 sys=0.00, real=0.80 secs] 
 239118.392: [Full GC [PSYoungGen: 466112K->465905K(932096K)] [PSOldGen: 2795516K->2795516K(2796224K)] 3261628K->3261422K(3728320K) [PSPermGen: 41622K->41622K(41664K)], 0.8055940 secs] [Times: user=0.80 sys=0.00, real=0.80 secs] 
 239119.205: [Full GC [PSYoungGen: 466112K->466112K(932096K)] [PSOldGen: 2795516K->2795516K(2796224K)] 3261628K->3261628K(3728320K) [PSPermGen: 41623K->41623K(41664K)], 0.7979720 secs] [Times: user=0.80 sys=0.00, real=0.80 secs] 
 239120.006: [Full GC [PSYoungGen: 466112K->466112K(932096K)] [PSOldGen: 2795516K->2795516K(2796224K)] 3261628K->3261628K(3728320K) [PSPermGen: 41623K->41623K(41664K)], 0.8017730 secs] [Times: user=0.81 sys=0.00, real=0.80 secs] 
 239120.812: [Full GC [PSYoungGen: 466112K->466112K(932096K)] [PSOldGen: 2795516K->2795516K(2796224K)] 3261628K->3261628K(3728320K) [PSPermGen: 41623K->41623K(41664K)], 0.7996710 secs] [Times: user=0.80 sys=0.00, real=0.80 secs] 
 239121.615: [Full GC [PSYoungGen: 466112K->465928K(932096K)] [PSOldGen: 2795516K->2795504K(2796224K)] 3261628K->3261432K(3728320K) [PSPermGen: 41623K->41623K(41664K)], 1.3828530 secs] [Times: user=1.39 sys=0.00, real=1.38 secs] 
 239123.003: [Full GC [PSYoungGen: 466112K->466112K(932096K)] [PSOldGen: 2795504K->2795504K(2796224K)] 3261616K->3261616K(3728320K) [PSPermGen: 41627K->41627K(41664K)], 0.8057380 secs] [Times: user=0.81 sys=0.00, real=0.80 secs] 
 239123.812: [Full GC [PSYoungGen: 466112K->466112K(932096K)] [PSOldGen: 2795504K->2795504K(2796224K)] 3261616K->3261616K(3728320K) [PSPermGen: 41640K->41640K(41664K)], 0.8055670 secs] [Times: user=0.81 sys=0.00, real=0.80 secs] 
 239124.624: [Full GC [PSYoungGen: 466112K->466112K(932096K)] [PSOldGen: 2795504K->2795504K(2796224K)] 3261616K->3261616K(3728320K) [PSPermGen: 41640K->41640K(41664K)], 0.8072180 secs] [Times: user=0.81 sys=0.00, real=0.81 secs] 
 239125.435: [Full GC [PSYoungGen: 466112K->465872K(932096K)] [PSOldGen: 2795504K->2795504K(2796224K)] 3261616K->3261376K(3728320K) [PSPermGen: 41640K->41632K(41664K)], 0.8073740 secs] [Times: user=0.81 sys=0.00, real=0.81 secs] 
 239126.246: [Full GC [PSYoungGen: 466112K->466112K(932096K)] [PSOldGen: 2795504K->2795504K(2796224K)] 3261616K->3261616K(3728320K) [PSPermGen: 41636K->41636K(41664K)], 0.8052990 secs] [Times: user=0.81 sys=0.00, real=0.81 secs] 
 239127.055: [Full GC [PSYoungGen: 466112K->466112K(932096K)] [PSOldGen: 2795536K->2795536K(2796224K)] 3261648K->3261648K(3728320K) [PSPermGen: 41636K->41636K(41664K)], 0.8014380 secs] [Times: user=0.80 sys=0.00, real=0.80 secs] 
 239127.860: [Full GC [PSYoungGen: 466112K->466112K(932096K)] [PSOldGen: 2795536K->2795536K(2796224K)] 3261648K->3261648K(3728320K) [PSPermGen: 41636K->41636K(41664K)], 0.7971540 secs] [Times: user=0.79 sys=0.00, real=0.80 secs] 
 239128.661: [Full GC [PSYoungGen: 466112K->443891K(932096K)] [PSOldGen: 2795536K->2795504K(2796224K)] 3261648K->3239395K(3728320K) [PSPermGen: 41636K->41636K(41664K)], 0.9689470 secs] [Times: user=0.97 sys=0.00, real=0.96 secs] 
 239129.744: [Full GC [PSYoungGen: 466088K->466088K(932096K)] [PSOldGen: 2795504K->2795504K(2796224K)] 3261593K->3261593K(3728320K) [PSPermGen: 41781K->41781K(42432K)], 0.8025740 secs] [Times: user=0.80 sys=0.00, real=0.80 secs] 
 239130.550: [Full GC [PSYoungGen: 466112K->466112K(932096K)] [PSOldGen: 2795536K->2795536K(2796224K)] 3261648K->3261648K(3728320K) [PSPermGen: 41781K->41781K(42432K)], 0.8005130 secs] [Times: user=0.80 sys=0.00, real=0.80 secs] 
 239131.354: [Full GC [PSYoungGen: 466112K->466112K(932096K)] [PSOldGen: 2795536K->2795536K(2796224K)] 3261648K->3261648K(3728320K) [PSPermGen: 41781K->41781K(42432K)], 0.8039040 secs] [Times: user=0.81 sys=0.00, real=0.80 secs] 
 239132.161: [Full GC [PSYoungGen: 466112K->450816K(932096K)] [PSOldGen: 2795568K->2794206K(2796224K)] 3261680K->3245022K(3728320K) [PSPermGen: 41781K->41682K(42304K)], 1.4853000 secs] [Times: user=1.49 sys=0.00, real=1.49 secs] 
 Heap
  PSYoungGen      total 932096K, used 454495K [0x00000007aaab0000, 0x0000000800000000, 0x0000000800000000)
   eden space 466112K, 97% used [0x00000007aaab0000,0x00000007c6687d68,0x00000007c71e0000)
   from space 465984K, 0% used [0x00000007c71e0000,0x00000007c71e0000,0x00000007e38f0000)
   to   space 465984K, 0% used [0x00000007e38f0000,0x00000007e38f0000,0x0000000800000000)
  PSOldGen        total 2796224K, used 2794206K [0x0000000700000000, 0x00000007aaab0000, 0x00000007aaab0000)
   object space 2796224K, 99% used [0x0000000700000000,0x00000007aa8b79a0,0x00000007aaab0000)
  PSPermGen       total 42304K, used 41693K [0x00000006fae00000, 0x00000006fd750000, 0x0000000700000000)
   object space 42304K, 98% used [0x00000006fae00000,0x00000006fd6b77f0,0x00000006fd750000)

Big Memory: No(t yet)

Our Terracotta-server crashes and OOMs with these log-entries.

It seems that our client is sending too big objects to Terracotta.

We are using Terracotta 3.5.4, and we are using distributed EHCache 2.4.7 (as 2nd level cache configuration for hibernate) and replicated HTTP sessions.

terracotta-server.log
Code:

 ...
 2012-07-30 09:15:29,794 [L2_L1:TCWorkerComm # 0_R] WARN com.tc.bytes.TCByteBufferFactory - Asking for a large amount of memory: 11810153 bytes
 2012-07-30 09:15:29,810 [WorkerThread(apply_changes_stage, 0)] WARN com.tc.object.dna.impl.BaseDNAEncodingImpl - Attempt to read a byte array of len: 11809698; threshold=8000000
 2012-07-30 09:15:30,854 [L2_L1:TCWorkerComm # 0_R] WARN com.tc.bytes.TCByteBufferFactory - Asking for a large amount of memory: 11876952 bytes
 2012-07-30 09:15:30,870 [WorkerThread(apply_changes_stage, 0)] WARN com.tc.object.dna.impl.BaseDNAEncodingImpl - Attempt to read a byte array of len: 11876497; threshold=8000000
 2012-07-30 09:15:31,638 [L2_L1:TCWorkerComm # 0_R] WARN com.tc.bytes.TCByteBufferFactory - Asking for a large amount of memory: 11877038 bytes
 2012-07-30 09:15:31,653 [WorkerThread(apply_changes_stage, 0)] WARN com.tc.object.dna.impl.BaseDNAEncodingImpl - Attempt to read a byte array of len: 11876583; threshold=8000000
 2012-07-30 09:15:46,511 [WorkerThread(managed_object_request_stage, 1, 1)] WARN com.tc.objectserver.handler.ManagedObjectRequestHandler -  Number of repeated/wasted lookups : 1890000
 2012-07-30 09:18:03,051 [WorkerThread(managed_object_request_stage, 1, 1)] WARN com.tc.objectserver.handler.ManagedObjectRequestHandler -  Number of repeated/wasted lookups : 1900000
 2012-07-30 09:19:13,953 [Statistics Logger] INFO com.terracottatech.dso - memory free : 1098.201180 MB
 2012-07-30 09:19:13,953 [Statistics Logger] INFO com.terracottatech.dso - memory used : 2542.736320 MB
 2012-07-30 09:19:13,953 [Statistics Logger] INFO com.terracottatech.dso - memory max : 3640.937500 MB
 2012-07-30 09:21:10,793 [WorkerThread(managed_object_request_stage, 1, 1)] WARN com.tc.objectserver.handler.ManagedObjectRequestHandler -  Number of repeated/wasted lookups : 1910000
 2012-07-30 09:25:15,793 [WorkerThread(managed_object_request_stage, 1, 1)] WARN com.tc.objectserver.handler.ManagedObjectRequestHandler -  Number of repeated/wasted lookups : 1920000
 2012-07-30 09:27:07,139 [WorkerThread(managed_object_request_stage, 1, 1)] WARN com.tc.objectserver.handler.ManagedObjectRequestHandler -  Number of repeated/wasted lookups : 1930000
 2012-07-30 09:28:46,197 [WorkerThread(indexes_sync_request_stage, 0)] ERROR com.tc.server.TCServerMain - Thread:Thread[WorkerThread(indexes_sync_request_stage, 0),5,TC Thread Group] got an uncaught exception. calling CallbackOnExitDefaultHandlers.
 java.lang.OutOfMemoryError: GC overhead limit exceeded
         at java.util.concurrent.locks.AbstractQueuedSynchronizer$ConditionObject.addConditionWaiter(AbstractQueuedSynchronizer.java:1801)
         at java.util.concurrent.locks.AbstractQueuedSynchronizer$ConditionObject.awaitNanos(AbstractQueuedSynchronizer.java:2016)
         at java.util.concurrent.LinkedBlockingQueue.poll(LinkedBlockingQueue.java:424)
         at com.tc.util.concurrent.TCLinkedBlockingQueue.poll(TCLinkedBlockingQueue.java:30)
         at com.tc.async.impl.StageQueueImpl$SourceQueueImpl.poll(StageQueueImpl.java:271)
         at com.tc.async.impl.StageImpl$WorkerThread.run(StageImpl.java:130)
 2012-07-30 09:28:58,612 [L2_L1:TCComm Main Selector Thread_R (listen 0:0:0:0:0:0:0:0:9510)] ERROR com.tc.net.core.CoreNIOServices - Unhandled exception from selectLoop
 ...

terracotta-client.log
Code:

 2012-07-30 08:51:14,631 [ClientLockManager LockGC] INFO com.tc.object.locks.ClientLockManager - ClientID[1]: Lock GC collected 865 garbage locks
 2012-07-30 08:52:14,647 [ClientLockManager LockGC] INFO com.tc.object.locks.ClientLockManager - ClientID[1]: Lock GC collected 1479 garbage locks
 2012-07-30 08:53:14,658 [ClientLockManager LockGC] INFO com.tc.object.locks.ClientLockManager - ClientID[1]: Lock GC collected 3123 garbage locks
 2012-07-30 08:54:14,668 [ClientLockManager LockGC] INFO com.tc.object.locks.ClientLockManager - ClientID[1]: Lock GC collected 2021 garbage locks
 2012-07-30 08:55:14,680 [ClientLockManager LockGC] INFO com.tc.object.locks.ClientLockManager - ClientID[1]: Lock GC collected 2018 garbage locks
 2012-07-30 08:56:14,691 [ClientLockManager LockGC] INFO com.tc.object.locks.ClientLockManager - ClientID[1]: Lock GC collected 1441 garbage locks
 2012-07-30 08:57:14,703 [ClientLockManager LockGC] INFO com.tc.object.locks.ClientLockManager - ClientID[1]: Lock GC collected 492 garbage locks
 2012-07-30 08:58:14,717 [ClientLockManager LockGC] INFO com.tc.object.locks.ClientLockManager - ClientID[1]: Lock GC collected 1602 garbage locks
 2012-07-30 08:59:14,727 [ClientLockManager LockGC] INFO com.tc.object.locks.ClientLockManager - ClientID[1]: Lock GC collected 777 garbage locks
 2012-07-30 09:00:14,748 [ClientLockManager LockGC] INFO com.tc.object.locks.ClientLockManager - ClientID[1]: Lock GC collected 799 garbage locks
 2012-07-30 09:01:14,756 [ClientLockManager LockGC] INFO com.tc.object.locks.ClientLockManager - ClientID[1]: Lock GC collected 2267 garbage locks
 2012-07-30 09:02:14,781 [ClientLockManager LockGC] INFO com.tc.object.locks.ClientLockManager - ClientID[1]: Lock GC collected 13234 garbage locks
 2012-07-30 09:03:14,781 [ClientLockManager LockGC] INFO com.tc.object.locks.ClientLockManager - ClientID[1]: Lock GC collected 4695 garbage locks
 2012-07-30 09:04:14,791 [ClientLockManager LockGC] INFO com.tc.object.locks.ClientLockManager - ClientID[1]: Lock GC collected 1315 garbage locks
 2012-07-30 09:05:11,894 [Statistics Logger] INFO com.terracottatech.dso - memory free : 11114.335678 MB
 2012-07-30 09:05:11,894 [Statistics Logger] INFO com.terracottatech.dso - memory used : 3449.226822 MB
 2012-07-30 09:05:11,894 [Statistics Logger] INFO com.terracottatech.dso - memory max : 14563.562500 MB
 2012-07-30 09:05:14,802 [ClientLockManager LockGC] INFO com.tc.object.locks.ClientLockManager - ClientID[1]: Lock GC collected 918 garbage locks
 2012-07-30 09:06:14,818 [ClientLockManager LockGC] INFO com.tc.object.locks.ClientLockManager - ClientID[1]: Lock GC collected 1118 garbage locks
 2012-07-30 09:07:14,827 [ClientLockManager LockGC] INFO com.tc.object.locks.ClientLockManager - ClientID[1]: Lock GC collected 1430 garbage locks
 2012-07-30 09:08:14,844 [ClientLockManager LockGC] INFO com.tc.object.locks.ClientLockManager - ClientID[1]: Lock GC collected 744 garbage locks
 2012-07-30 09:09:14,851 [ClientLockManager LockGC] INFO com.tc.object.locks.ClientLockManager - ClientID[1]: Lock GC collected 896 garbage locks
 2012-07-30 09:10:14,866 [ClientLockManager LockGC] INFO com.tc.object.locks.ClientLockManager - ClientID[1]: Lock GC collected 650 garbage locks
 2012-07-30 09:11:14,882 [ClientLockManager LockGC] INFO com.tc.object.locks.ClientLockManager - ClientID[1]: Lock GC collected 1278 garbage locks
 2012-07-30 09:12:22,269 [ClientLockManager LockGC] INFO com.tc.object.locks.ClientLockManager - ClientID[1]: Lock GC collected 1902 garbage locks
 2012-07-30 09:13:22,281 [ClientLockManager LockGC] INFO com.tc.object.locks.ClientLockManager - ClientID[1]: Lock GC collected 1458 garbage locks
 2012-07-30 09:14:22,293 [ClientLockManager LockGC] INFO com.tc.object.locks.ClientLockManager - ClientID[1]: Lock GC collected 1444 garbage locks
 2012-07-30 09:15:22,303 [ClientLockManager LockGC] INFO com.tc.object.locks.ClientLockManager - ClientID[1]: Lock GC collected 653 garbage locks
 2012-07-30 09:16:22,321 [ClientLockManager LockGC] INFO com.tc.object.locks.ClientLockManager - ClientID[1]: Lock GC collected 1477 garbage locks
 2012-07-30 09:17:22,334 [ClientLockManager LockGC] INFO com.tc.object.locks.ClientLockManager - ClientID[1]: Lock GC collected 3611 garbage locks
 2012-07-30 09:18:22,346 [ClientLockManager LockGC] INFO com.tc.object.locks.ClientLockManager - ClientID[1]: Lock GC collected 4032 garbage locks
 2012-07-30 09:19:22,350 [ClientLockManager LockGC] INFO com.tc.object.locks.ClientLockManager - ClientID[1]: Lock GC collected 3736 garbage locks
 2012-07-30 09:20:11,895 [Statistics Logger] INFO com.terracottatech.dso - memory free : 11349.415077 MB
 2012-07-30 09:20:11,895 [Statistics Logger] INFO com.terracottatech.dso - memory used : 3214.147423 MB
 2012-07-30 09:20:11,895 [Statistics Logger] INFO com.terracottatech.dso - memory max : 14563.562500 MB
 2012-07-30 09:20:22,362 [ClientLockManager LockGC] INFO com.tc.object.locks.ClientLockManager - ClientID[1]: Lock GC collected 2459 garbage locks
 2012-07-30 09:21:22,378 [ClientLockManager LockGC] INFO com.tc.object.locks.ClientLockManager - ClientID[1]: Lock GC collected 2646 garbage locks
 2012-07-30 09:22:22,387 [ClientLockManager LockGC] INFO com.tc.object.locks.ClientLockManager - ClientID[1]: Lock GC collected 2800 garbage locks
 2012-07-30 09:23:22,400 [ClientLockManager LockGC] INFO com.tc.object.locks.ClientLockManager - ClientID[1]: Lock GC collected 1729 garbage locks
 2012-07-30 09:24:22,416 [ClientLockManager LockGC] INFO com.tc.object.locks.ClientLockManager - ClientID[1]: Lock GC collected 2588 garbage locks
 2012-07-30 09:25:22,425 [ClientLockManager LockGC] INFO com.tc.object.locks.ClientLockManager - ClientID[1]: Lock GC collected 722 garbage locks
 2012-07-30 09:26:22,442 [ClientLockManager LockGC] INFO com.tc.object.locks.ClientLockManager - ClientID[1]: Lock GC collected 1154 garbage locks
 2012-07-30 09:27:22,452 [ClientLockManager LockGC] INFO com.tc.object.locks.ClientLockManager - ClientID[1]: Lock GC collected 2330 garbage locks
 2012-07-30 09:27:46,115 [http-8090-46] WARN com.tc.object.RemoteObjectManager - ClientID[1]: Still waiting for 15512 ms to retrieve ObjectID=[10573061] depth : 500 parent : ObjectID=[-1]
 2012-07-30 09:27:52,834 [WorkerThread(tti_ttl_eviction_stage, 1, 0)] WARN com.tc.object.RemoteObjectManager - ClientID[1]: Still waiting for 21032 ms to retrieve ObjectID=[10410434] depth : 500 parent : Object
 ID=[-1]
 2012-07-30 09:28:07,838 [http-8090-61] WARN com.tc.object.RemoteObjectManager - ClientID[1]: Still waiting for 15111 ms to retrieve ObjectID=[8724160] depth : 500 parent : ObjectID=[-1]
 2012-07-30 09:28:07,841 [WorkerThread(tti_ttl_eviction_stage, 1, 0)] WARN com.tc.object.RemoteObjectManager - ClientID[1]: Still waiting for 36039 ms to retrieve ObjectID=[10410434] depth : 500 parent : Object
 ID=[-1]
 2012-07-30 09:28:07,841 [http-8090-46] WARN com.tc.object.RemoteObjectManager - ClientID[1]: Still waiting for 37239 ms to retrieve ObjectID=[10573061] depth : 500 parent : ObjectID=[-1]
 2012-07-30 09:28:15,695 [L1_L2:TCComm Main Selector Thread_R (listen 0:0:0:0:0:0:0:0:56627)] WARN com.tc.net.protocol.transport.ConnectionHealthCheckerImpl. DSO Client - min-virgo01.osl.basefarm.net:9510 might
  be in Long GC. Ping-probe cycles completed since last reply : 1
 2012-07-30 09:28:19,703 [L1_L2:TCComm Main Selector Thread_R (listen 0:0:0:0:0:0:0:0:56627)] WARN com.tc.net.protocol.transport.ConnectionHealthCheckerImpl. DSO Client - min-virgo01.osl.basefarm.net:9510 might
  be in Long GC. Ping-probe cycles completed since last reply : 2
 2012-07-30 09:28:22,466 [ClientLockManager LockGC] INFO com.tc.object.locks.ClientLockManager - ClientID[1]: Lock GC collected 2673 garbage locks
 2012-07-30 09:28:22,844 [http-8090-61] WARN com.tc.object.RemoteObjectManager - ClientID[1]: Still waiting for 30117 ms to retrieve ObjectID=[8724160] depth : 500 parent : ObjectID=[-1]
 2012-07-30 09:28:22,847 [WorkerThread(tti_ttl_eviction_stage, 1, 0)] WARN com.tc.object.RemoteObjectManager - ClientID[1]: Still waiting for 51045 ms to retrieve ObjectID=[10410434] depth : 500 parent : Object
 ID=[-1]
 2012-07-30 09:28:22,847 [http-8090-46] WARN com.tc.object.RemoteObjectManager - ClientID[1]: Still waiting for 52245 ms to retrieve ObjectID=[10573061] depth : 500 parent : ObjectID=[-1]
 2012-07-30 09:28:23,711 [L1_L2:TCComm Main Selector Thread_R (listen 0:0:0:0:0:0:0:0:56627)] WARN com.tc.net.protocol.transport.ConnectionHealthCheckerImpl. DSO Client - min-virgo01.osl.basefarm.net:9510 might
  be in Long GC. Ping-probe cycles completed since last reply : 3
 2012-07-30 09:28:27,721 [L1_L2:TCComm Main Selector Thread_R (listen 0:0:0:0:0:0:0:0:56627)] WARN com.tc.net.protocol.transport.ConnectionHealthCheckerImpl. DSO Client - min-virgo01.osl.basefarm.net:9510 might
  be in Long GC. Ping-probe cycles completed since last reply : 4
 2012-07-30 09:28:31,729 [L1_L2:TCComm Main Selector Thread_R (listen 0:0:0:0:0:0:0:0:56627)] WARN com.tc.net.protocol.transport.ConnectionHealthCheckerImpl. DSO Client - min-virgo01.osl.basefarm.net:9510 might
  be in Long GC. Ping-probe cycles completed since last reply : 5
 2012-07-30 09:28:35,741 [L1_L2:TCComm Main Selector Thread_R (listen 0:0:0:0:0:0:0:0:56627)] WARN com.tc.net.protocol.transport.ConnectionHealthCheckerImpl. DSO Client - min-virgo01.osl.basefarm.net:9510 might
  be in Long GC. Ping-probe cycles completed since last reply : 6
 2012-07-30 09:28:37,848 [http-8090-61] WARN com.tc.object.RemoteObjectManager - ClientID[1]: Still waiting for 45121 ms to retrieve ObjectID=[8724160] depth : 500 parent : ObjectID=[-1]
 2012-07-30 09:28:37,852 [WorkerThread(tti_ttl_eviction_stage, 1, 0)] WARN com.tc.object.RemoteObjectManager - ClientID[1]: Still waiting for 66050 ms to retrieve ObjectID=[10410434] depth : 500 parent : Object
 ID=[-1]
 2012-07-30 09:28:37,852 [http-8090-46] WARN com.tc.object.RemoteObjectManager - ClientID[1]: Still waiting for 67250 ms to retrieve ObjectID=[10573061] depth : 500 parent : ObjectID=[-1]
 2012-07-30 09:28:39,749 [L1_L2:TCComm Main Selector Thread_R (listen 0:0:0:0:0:0:0:0:56627)] WARN com.tc.net.protocol.transport.ConnectionHealthCheckerImpl. DSO Client - min-virgo01.osl.basefarm.net:9510 might
  be in Long GC. Ping-probe cycles completed since last reply : 7
 2012-07-30 09:28:49,778 [L1_L2:TCComm Main Selector Thread_R (listen 0:0:0:0:0:0:0:0:56627)] WARN com.tc.net.protocol.transport.ConnectionHealthCheckerImpl. DSO Client - min-virgo01.osl.basefarm.net:9510 might
  be in Long GC. Ping-probe cycles completed since last reply : 1
 2012-07-30 09:28:52,852 [http-8090-61] WARN com.tc.object.RemoteObjectManager - ClientID[1]: Still waiting for 60125 ms to retrieve ObjectID=[8724160] depth : 500 parent : ObjectID=[-1]
 2012-07-30 09:28:52,856 [WorkerThread(tti_ttl_eviction_stage, 1, 0)] WARN com.tc.object.RemoteObjectManager - ClientID[1]: Still waiting for 81054 ms to retrieve ObjectID=[10410434] depth : 500 parent : Object
 ID=[-1]
 2012-07-30 09:28:52,856 [http-8090-46] WARN com.tc.object.RemoteObjectManager - ClientID[1]: Still waiting for 82254 ms to retrieve ObjectID=[10573061] depth : 500 parent : ObjectID=[-1]
 2012-07-30 09:28:53,794 [L1_L2:TCComm Main Selector Thread_R (listen 0:0:0:0:0:0:0:0:56627)] WARN com.tc.net.protocol.transport.ConnectionHealthCheckerImpl. DSO Client - min-virgo01.osl.basefarm.net:9510 might
  be in Long GC. Ping-probe cycles completed since last reply : 2
 2012-07-30 09:29:07,858 [http-8090-61] WARN com.tc.object.RemoteObjectManager - ClientID[1]: Still waiting for 75131 ms to retrieve ObjectID=[8724160] depth : 500 parent : ObjectID=[-1]
 2012-07-30 09:29:07,862 [WorkerThread(tti_ttl_eviction_stage, 1, 0)] WARN com.tc.object.RemoteObjectManager - ClientID[1]: Still waiting for 96060 ms to retrieve ObjectID=[10410434] depth : 500 parent : Object
 ID=[-1]
 2012-07-30 09:29:07,862 [http-8090-46] WARN com.tc.object.RemoteObjectManager - ClientID[1]: Still waiting for 97260 ms to retrieve ObjectID=[10573061] depth : 500 parent : ObjectID=[-1]
 2012-07-30 09:29:18,847 [L1_L2:TCComm Main Selector Thread_R (listen 0:0:0:0:0:0:0:0:56627)] INFO com.tc.net.core.CoreNIOServices - IOException attempting to finish socket connection
 java.net.ConnectException: Connection refused
         at sun.nio.ch.SocketChannelImpl.checkConnect(Native Method)
         at sun.nio.ch.SocketChannelImpl.finishConnect(SocketChannelImpl.java:567)
         at com.tc.net.core.CoreNIOServices$CommThread.doConnect(CoreNIOServices.java:678)
         at com.tc.net.core.CoreNIOServices$CommThread.selectLoop(CoreNIOServices.java:622)
         at com.tc.net.core.CoreNIOServices$CommThread.run(CoreNIOServices.java:294)
 2012-07-30 09:29:18,914 [L1_L2:TCComm Main Selector Thread_R (listen 0:0:0:0:0:0:0:0:56627)] INFO com.tc.net.core.TCConnectionManager - error event on connection com.tc.net.core.TCConnectionImpl@607918955: con
 nected: false, closed: false connect=[no connect time] idle=67ms [0 read, 0 write]: Connection refused
 2012-07-30 09:29:18,916 [L1_L2:TCComm Main Selector Thread_R (listen 0:0:0:0:0:0:0:0:56627)] WARN com.tc.net.protocol.transport.ConnectionHealthCheckerImpl. DSO Client - Socket Connect error event:com.tc.net.c
 ore.TCConnectionImpl@607918955: connected: false, closed: true connect=[no connect time] idle=69ms [0 read, 0 write], exception: java.net.ConnectException: Connection refused, message context: [no message cont
 ext] on min-virgo01.osl.basefarm.net:9510
 2012-07-30 09:29:19,850 [HealthChecker] INFO com.tc.net.protocol.transport.ConnectionHealthCheckerImpl. DSO Client - min-virgo01.osl.basefarm.net:9510 is DEAD
 2012-07-30 09:29:19,850 [HealthChecker] ERROR com.tc.net.protocol.transport.ConnectionHealthCheckerImpl: DSO Client - Declared connection dead ConnectionID(1.c4eaf4cb17a042cb9648e1b150f44e1f) idle time 9911ms
 2012-07-30 09:29:19,856 [L1_L2:TCComm Main Selector Thread_W (listen 0:0:0:0:0:0:0:0:56627)] WARN com.tc.net.protocol.transport.ClientMessageTransport - ConnectionID(1.c4eaf4cb17a042cb9648e1b150f44e1f): CLOSE 
 EVENT : com.tc.net.core.TCConnectionImpl@678247779: connected: false, closed: true local=10.27.49.4:38575 remote=10.27.49.4:9510 connect=[Fri Jul 27 15:05:11 CEST 2012] idle=714ms [3857501979 read, 9360994624 
 write]. STATUS : DISCONNECTED
 2012-07-30 09:29:19,860 [L1_L2:TCComm Main Selector Thread_W (listen 0:0:0:0:0:0:0:0:56627)] INFO com.tc.net.protocol.tcm.ClientMessageChannel - ClientMessageChannel moves to SessionID=[1]
 2012-07-30 09:29:19,860 [WorkerThread(client_coordination_stage, 0)] INFO com.tc.object.handshakemanager.ClientHandshakeManagerImpl - ClientID[1]: Disconnected: Pausing from State[ RUNNING ] RemoteNode : Group
 ID[0]. Disconnect count: 0
 2012-07-30 09:29:19,861 [WorkerThread(client_coordination_stage, 0)] INFO com.tc.object.handshakemanager.ClientHandshakeManagerImpl - ClientID[1]: ClientHandshakeManager moves to SessionID=[1]
 2012-07-30 09:29:19,864 [ConnectionEstablisher] WARN com.tc.net.protocol.transport.ClientMessageTransport - ConnectionID(1.c4eaf4cb17a042cb9648e1b150f44e1f): Reconnect attempt 0 of unlimited reconnect tries to
  min-virgo01.osl.basefarm.net:9510:Tc-Group-0, timeout=10000

We already read this topic, but we would like to find out the reason for our problems.

http://forums.terracotta.org/forums/posts/list/6434.page

1. And how can this be solved temporarily (quick-hack)?
2. What can we do to solve this problem permanently?
3. Could our cache configuration be the main reason for the crashes?

We have GC logs from client and server, and Java heap dump from the server.

Any suggestions are appreciated.

Regards
Marek Dominiam & Pål-Kristian Hamre

sghose wrote:

Please check if your client is running full GC's. There is a health check between TSA and the client and if the client does not respond for a certain duration TSA considers it dead.

The client runs full GC's every 60 minutes.

Should I tune the Terracotta health check parameters? Or should I confirm with a GC-log prior to problems that there actually is a long GC going on?

sghose wrote:

Do you have GC logs from your client?

Yes, but unfortunately they where truncated when I restarted the client.

Any help on this would be appreciated. I am not sure if this is a Terracotta problem or an application problem. Have anyone experienced errors like this?

terracotta-server.log
Code:

 2012-07-27 02:21:24,712 [L2_L1:TCComm Main Selector Thread_R (listen 0:0:0:0:0:0:0:0:9510)] WARN com.tc.net.protocol.transport.ConnectionHealthCheckerImpl. DSO Server - foobar.example.org:45681 might
  be in Long GC. Ping-probe cycles completed since last reply : 9
 2012-07-27 02:21:25,716 [L2_L1:TCComm Main Selector Thread_R (listen 0:0:0:0:0:0:0:0:9510)] WARN com.tc.net.protocol.transport.ConnectionHealthCheckerImpl. DSO Server - foobar.example.org:45691 might
  be in Long GC. Ping-probe cycles completed since last reply : 9
 2012-07-27 02:21:28,724 [L2_L1:TCComm Main Selector Thread_R (listen 0:0:0:0:0:0:0:0:9510)] ERROR com.tc.net.protocol.transport.ConnectionHealthCheckerImpl. DSO Server - foobar.example.org:45681 migh
 t be in Long GC. Ping-probe cycles completed since last reply : 10. But its too long. No more retries
 2012-07-27 02:21:29,707 [HealthChecker] INFO com.tc.net.protocol.transport.ConnectionHealthCheckerImpl. DSO Server - foobar.example.org:45681 is DEAD
 2012-07-27 02:21:29,710 [HealthChecker] ERROR com.tc.net.protocol.transport.ConnectionHealthCheckerImpl: DSO Server - Declared connection dead ConnectionID(0.0e42f9999e4f4035845fc72d572ee92c) idle time 45204ms
 2012-07-27 02:21:29,730 [L2_L1:TCComm Main Selector Thread_R (listen 0:0:0:0:0:0:0:0:9510)] ERROR com.tc.net.protocol.transport.ConnectionHealthCheckerImpl. DSO Server - foobar.example.org:45691 migh
 t be in Long GC. Ping-probe cycles completed since last reply : 10. But its too long. No more retries
 2012-07-27 02:21:29,749 [L2_L1:TCWorkerComm # 0_R] WARN com.tc.net.protocol.transport.ServerMessageTransport - ConnectionID(0.0e42f9999e4f4035845fc72d572ee92c): CLOSE EVENT : com.tc.net.core.TCConnectionImpl@1
 849015814: connected: false, closed: true local=10.27.49.4:9510 remote=10.27.49.4:45681 connect=[Tue Jul 17 08:57:40 CEST 2012] idle=2046ms [22850422120 read, 1491035010 write]. STATUS : DISCONNECTED
 2012-07-27 02:21:29,759 [WorkerThread(channel_life_cycle_stage, 0)] INFO com.tc.objectserver.handler.ChannelLifeCycleHandler - : Received transport disconnect.  Shutting down client ClientID[0]

terracotta-client.log
Code:

 2012-07-27 02:21:35,010 [L1_L2:TCComm Main Selector Thread_R (listen 0:0:0:0:0:0:0:0:43164)] WARN com.tc.net.core.CoreNIOServices - Exception trying to shutdown socket output: Transport endpoint is not connect
 ed
 2012-07-27 02:21:35,016 [L1_L2:TCComm Main Selector Thread_R (listen 0:0:0:0:0:0:0:0:43164)] WARN com.tc.net.protocol.transport.ClientMessageTransport - ConnectionID(1.0e42f9999e4f4035845fc72d572ee92c): CLOSE 
 EVENT : com.tc.net.core.TCConnectionImpl@1463917127: connected: false, closed: true local=10.27.49.4:45691 remote=10.27.49.4:9510 connect=[Tue Jul 17 08:58:05 CEST 2012] idle=6ms [18316355771 read, 44648276356
  write]. STATUS : ESTABLISHED
 2012-07-27 02:21:35,021 [L1_L2:TCComm Main Selector Thread_R (listen 0:0:0:0:0:0:0:0:43164)] INFO com.tc.net.protocol.transport.ConnectionHealthCheckerImpl: DSO Client - Connection to [foobar.example.org:9510] DISCONNECTED. Health Monitoring for this node is now disabled.
 2012-07-27 02:21:35,040 [TC Memory Monitor] WARN com.tc.runtime.logging.LongGCLogger - Detected long GC>8,000ms. GC count:1. GC Time:49,857ms. Frequent long GC cycles cause severe performance degradation.
 2012-07-27 02:21:35,066 [L1_L2:TCComm Main Selector Thread_W (listen 0:0:0:0:0:0:0:0:43164)] INFO com.tc.net.core.TCConnectionManager - error event on connection com.tc.net.core.TCConnectionImpl@1463917127: co
 nnected: false, closed: true local=10.27.49.4:45691 remote=10.27.49.4:9510 connect=[Tue Jul 17 08:58:05 CEST 2012] idle=56ms [18316355771 read, 44648276356 write]: Broken pipe
 2012-07-27 02:21:35,070 [WorkerThread(cluster_events_stage, 0)] WARN com.tc.net.protocol.transport.ClientMessageTransport - ConnectionID(1.0e42f9999e4f4035845fc72d572ee92c): Ignoring message sent to non-establ
 ished transport: Message Class: com.tc.object.msg.LockRequestMessage
 Sealed: true, Header Length: 8, Data Length: 27, Total Length: 35
 Header (com.tc.net.protocol.tcm.TCMessageHeaderImpl)
         msgType: LOCK_REQUEST_MESSAGE (9), msgVer=0
 Payload:
         Request Type: LOCK
         DsoLockID(ObjectID=[11007]) Thread(WorkerThread(cluster_events_stage, 0)) ID[207] Lock Type: WRITE
 
 2012-07-27 02:21:35,074 [http-8090-68] WARN com.tc.net.protocol.transport.ClientMessageTransport - ConnectionID(1.0e42f9999e4f4035845fc72d572ee92c): Ignoring message sent to non-established transport: Message 
 Class: com.tc.object.msg.LockRequestMessage
 Sealed: true, Header Length: 8, Data Length: 27, Total Length: 35
 Header (com.tc.net.protocol.tcm.TCMessageHeaderImpl)
         msgType: LOCK_REQUEST_MESSAGE (9), msgVer=0
 Payload:
         Request Type: LOCK
         LongLockID(8799327921809448810) Thread(http-8090-68) ID[159] Lock Type: READ
 
 2012-07-27 02:21:35,155 [L1_L2:TCComm Main Selector Thread_R (listen 0:0:0:0:0:0:0:0:43164)] INFO com.tc.net.protocol.tcm.ClientMessageChannel - ClientMessageChannel moves to SessionID=[1]
 2012-07-27 02:21:35,163 [WorkerThread(client_coordination_stage, 0)] INFO com.tc.object.handshakemanager.ClientHandshakeManagerImpl - ClientID[1]: Disconnected: Pausing from State[ RUNNING ] RemoteNode : Group
 ID[0]. Disconnect count: 0
 
 2012-07-27 02:21:35,164 [terracottaSchedulerBean_QuartzSchedulerThread] WARN com.tc.net.protocol.transport.ClientMessageTransport - ConnectionID(1.0e42f9999e4f4035845fc72d572ee92c): Ignoring message sent to no
 n-established transport: Message Class: com.tc.object.msg.CommitTransactionMessageImpl
 Sealed: true, Header Length: 8, Data Length: 320, Total Length: 328
 Header (com.tc.net.protocol.tcm.TCMessageHeaderImpl)
         msgType: COMMIT_TRANSACTION_MESSAGE (10), msgVer=0
 Payload:
         Buffer 0: TCByteBufferJDK14@2062981915(java.nio.HeapByteBuffer[pos=0 lim=320 cap=320])
         320 bytes:
         00000000: 0000 0002 0200 0000 0200 0100 3a6f 7267  ............:org
         00000010: 2e74 6572 7261 636f 7474 612e 7175 6172  .terracotta.quar
         00000020: 747a 2e54 7269 6767 6572 5772 6170 7065  tz.TriggerWrappe
         00000030: 722e 6c61 7374 5465 7272 6163 6f74 6143  r.lastTerracotaC
         00000040: 6c69 656e 7449 6400 0000 0100 0100 2a6f  lientId.......*o
         00000050: 7267 2e74 6572 7261 636f 7474 612e 7175  rg.terracotta.qu
         00000060: 6172 747a 2e54 7269 6767 6572 5772 6170  artz.TriggerWrap
         00000070: 7065 722e 7374 6174 6500 0000 0200 0000  per.state.......
         00000080: 0001 0000 0000 0318 cb38 0000 0001 0000  .........8......
         00000090: 0000 0003 2da5 e202 0000 0001 0000 0000  ....-...........
         000000a0: 032d a5e2 0000 0002 0200 0000 0000 012e  .-..............
         000000b0: 8102 0000 0000 0001 2e81 0000 0000 0000  ................
         000000c0: 0000 0000 0000 0000 0000 0000 0001 0000  ................
         000000d0: 0072 0000 0002 0000 0000 0400 0000 0000  .r..............
         000000e0: 012f de02 0000 0001 0c00 0000 000b 436c  ./............Cl
         000000f0: 6965 6e74 4944 5b31 5d02 0000 0002 1600  ientID[1].......
         00000100: 0000 226f 7267 2e74 6572 7261 636f 7474  .."org.terracott
         00000110: 612e 7175 6172 747a 2e54 7269 6767 6572  a.quartz.Trigger
         00000120: 5374 6174 6500 0000 0c25 2573 7461 6e64  State....%%stand
         00000130: 616c 6f6e 6500 0000 0757 4149 5449 4e47  alone....WAITING
 
 2012-07-27 02:21:35,164 [terracottaSchedulerBean_QuartzSchedulerThread] INFO com.tc.net.protocol.tcm.ClientMessageChannel - Drop old message: COMMIT_TRANSACTION_MESSAGE (10) Expected SessionID=[1] but got Sess
 ionID=[-1]
 2012-07-27 02:21:35,175 [WorkerThread(client_coordination_stage, 0)] INFO com.tc.object.handshakemanager.ClientHandshakeManagerImpl - ClientID[1]: ClientHandshakeManager moves to SessionID=[1]
 2012-07-27 02:21:35,176 [Batch Recall Timer] INFO com.tc.net.protocol.tcm.ClientMessageChannel - Drop old message: LOCK_REQUEST_MESSAGE (9) Expected SessionID=[1] but got SessionID=[-1]
 2012-07-27 02:21:35,250 [ConnectionEstablisher] WARN com.tc.net.protocol.transport.ClientMessageTransport - ConnectionID(1.0e42f9999e4f4035845fc72d572ee92c): Reconnect attempt 0 of unlimited reconnect tries to
  foobar.example.org:9510:Tc-Group-0, timeout=10000
 2012-07-27 02:21:35,266 [ConnectionEstablisher] INFO com.tc.net.protocol.transport.ClientMessageTransport - ConnectionID(1.0e42f9999e4f4035845fc72d572ee92c): Attaching new connection: com.tc.net.core.TCConnect
 ionImpl@2039003447: connected: true, closed: false local=10.27.49.4:56687 remote=10.27.49.4:9510 connect=[Fri Jul 27 02:21:35 CEST 2012] idle=1ms [0 read, 0 write]
 2012-07-27 02:21:35,413 [L1_L2:TCComm Main Selector Thread_R (listen 0:0:0:0:0:0:0:0:43164)] ERROR com.terracottatech.console - com.tc.net.protocol.transport.TransportHandshakeErrorContext: com.tc.net.protocol
 .transport.TransportHandshakeErrorContext: "Client Cannot Reconnect ConnectionID(1.0e42f9999e4f4035845fc72d572ee92c) not found. Connection attempts from the Terracotta node at 10.27.49.4:56687 are being reject
 ed by the Terracotta server array. Restart the Client to allow it to rejoin the cluster. Many Client reconnection failures can be avoided by configuring the Terracotta server array for "permanent-store" and tu
 ning reconnection parameters. For more information, see http://www.terracotta.org/kit/reflector?kitID=default&pageID=HA"Message Class: com.tc.net.protocol.transport.TransportMessageImpl
 Sealed: true, Header Length: 32, Data Length: 615, Total Length: 647
 Header (com.tc.net.protocol.transport.WireProtocolHeader)
         Version: 2, Header Length: 8, TOS: 0, TTL: 64, Protocol: TRANSPORT HANDSHAKE
         Total Packet Length: 647
         Adler32 Checksum: 1892746728 (valid: true)
         Source Addresss: 10.27.49.4
         Destination Addresss: 10.27.49.4
         Source Port: 9510, Destination Port: 56687
         Total Msg Count: 1
         Header Validity: true (no message)
 Payload:
         type: SYN_ACK, connectionId: ConnectionID(1.0e42f9999e4f4035845fc72d572ee92c), errorContext com.tc.net.protocol.transport.TransportHandshakeErrorContext: "Client Cannot Reconnect ConnectionID(1.0e42f99
 99e4f4035845fc72d572ee92c) not found. Connection attempts from the Terracotta node at 10.27.49.4:56687 are being rejected by the Terracotta server array. Restart the Client to allow it to rejoin the cluster. M
 any Client reconnection failures can be avoided by configuring the Terracotta server array for "permanent-store" and tuning reconnection parameters. For more information, see http://www.terracotta.org/kit/refl
 ector?kitID=default&pageID=HA"