| Author |
Message |
![[Post New]](../../templates/default/images/icon_minipost_new.gif) 12/27/2011 13:38:32
|
gekko959
neo
Joined: 12/08/2011 12:45:44
Messages: 6
Offline
|
Okay, I posted this message earlier, but then some spambot replied with spam. The moderator was nice enough to not only delete the one reply that was spam, but to delete the entire thread. Thanks. 
So here it is again. Moderator: if someone replies with spam again could you only delete the spam reply and not the entire thread?
I've got Terracotta 3.4 running and some apache instances in the cloud are hitting it. Over time, the threads that are trying to hit the instance start to "lock". They just hang until they build up in Tomcat and crash.
Here is a thread dump from a locked instance:
Code:
"tomcat-myrz-184" daemon prio=10 tid=0x00000000413dd800 nid=0x424a waiting on condition [0x00007fc49021b000]
java.lang.Thread.State: WAITING (parking)
at sun.misc.Unsafe.park(Native Method)
- parking to wait for <0x000000078bdea508> (a java.util.concurrent.Semaphore$NonfairSync)
at java.util.concurrent.locks.LockSupport.park(LockSupport.java:158)
at java.util.concurrent.locks.AbstractQueuedSynchronizer.parkAndCheckInterrupt(AbstractQueuedSynchronizer.java:811)
at java.util.concurrent.locks.AbstractQueuedSynchronizer.doAcquireSharedInterruptibly(AbstractQueuedSynchronizer.java:969)
at java.util.concurrent.locks.AbstractQueuedSynchronizer.acquireSharedInterruptibly(AbstractQueuedSynchronizer.java:1281)
at java.util.concurrent.Semaphore.acquire(Semaphore.java:286)
at com.tc.object.locks.LockStateNode$PendingLockHold.park(LockStateNode.java:179)
at com.tc.object.locks.ClientLockImpl.acquireQueued(ClientLockImpl.java:723)
at com.tc.object.locks.ClientLockImpl.acquireQueued(ClientLockImpl.java:701)
at com.tc.object.locks.ClientLockImpl.lock(ClientLockImpl.java:52)
at com.tc.object.locks.ClientLockManagerImpl.lock(ClientLockManagerImpl.java:98)
at com.tc.object.bytecode.ManagerImpl.lock(ManagerImpl.java:747)
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.SessionDataStore.find(SessionDataStore.java:141)
at com.terracotta.session.TerracottaSessionManager.getSessionIfExists(TerracottaSessionManager.java:567)
at com.terracotta.session.SessionRequest.getTerracottaSession(SessionRequest.java:150)
at com.terracotta.session.SessionRequest.getSession(SessionRequest.java:109)
at org.springframework.security.web.context.HttpSessionSecurityContextRepository.loadContext(HttpSessionSecurityContextRepository.java:81)
at org.springframework.security.web.context.SecurityContextPersistenceFilter.doFilter(SecurityContextPersistenceFilter.java:74)
at org.springframework.security.web.FilterChainProxy$VirtualFilterChain.doFilter(FilterChainProxy.java:355)
at org.springframework.security.web.FilterChainProxy.doFilter(FilterChainProxy.java:149)
at org.springframework.web.filter.DelegatingFilterProxy.invokeDelegate(DelegatingFilterProxy.java:237)
at org.springframework.web.filter.DelegatingFilterProxy.doFilter(DelegatingFilterProxy.java:167)
at org.apache.catalina.core.ApplicationFilterChain.internalDoFilter(ApplicationFilterChain.java:235)
at org.apache.catalina.core.ApplicationFilterChain.doFilter(ApplicationFilterChain.java:206)
at com.jamonapi.JAMonFilter.doFilter(JAMonFilter.java:57)
at org.apache.catalina.core.ApplicationFilterChain.internalDoFilter(ApplicationFilterChain.java:235)
at org.apache.catalina.core.ApplicationFilterChain.doFilter(ApplicationFilterChain.java:206)
at com.bestbuy.myrz.site.filter.MyRzFilter.doFilter(MyRzFilter.java:78)
at org.springframework.web.filter.DelegatingFilterProxy.invokeDelegate(DelegatingFilterProxy.java:237)
at org.springframework.web.filter.DelegatingFilterProxy.doFilter(DelegatingFilterProxy.java:167)
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:86)
at org.terracotta.session.ModernTomcatSessionValve.invoke(ModernTomcatSessionValve.java:66)
at org.apache.catalina.core.StandardHostValve.invoke(StandardHostValve.java:127)
at com.googlecode.psiprobe.Tomcat60AgentValve.invoke(Tomcat60AgentValve.java:30)
at org.apache.catalina.valves.ErrorReportValve.invoke(ErrorReportValve.java:102)
at org.apache.catalina.core.StandardEngineValve.invoke(StandardEngineValve.java:109)
at org.apache.catalina.connector.CoyoteAdapter.service(CoyoteAdapter.java:298)
at org.apache.coyote.http11.Http11AprProcessor.process(Http11AprProcessor.java:861)
at org.apache.coyote.http11.Http11AprProtocol$Http11ConnectionHandler.process(Http11AprProtocol.java:579)
at org.apache.tomcat.util.net.AprEndpoint$SocketProcessor.run(AprEndpoint.java:2087)
at java.util.concurrent.ThreadPoolExecutor$Worker.runTask(ThreadPoolExecutor.java:886)
at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:908)
at java.lang.Thread.run(Thread.java:662)
Here are some broadcast logs. Why is there so much broadcasting around ConcurrentDistributedMapDso?
Code:
2011-12-21 10:42:47,363 [Stats Printer Aggregator] INFO com.tc.statistics.util.StatsPrinter - Broadcasted in the Last 5,000 ms
2011-12-21 10:42:47,364 [Stats Printer Aggregator] INFO com.tc.statistics.util.StatsPrinter - ==========================================================
2011-12-21 10:42:47,364 [Stats Printer Aggregator] INFO com.tc.statistics.util.StatsPrinter - com.terracotta.session.util.Timestamp : 13677 instances
2011-12-21 10:42:47,364 [Stats Printer Aggregator] INFO com.tc.statistics.util.StatsPrinter - com.terracotta.toolkit.collections.ConcurrentDistributedMapDso : 16968 instances
2011-12-21 10:42:47,364 [Stats Printer Aggregator] INFO com.tc.statistics.util.StatsPrinter - com.terracotta.session.SessionData : 2 instances
2011-12-21 10:42:47,364 [Stats Printer Aggregator] INFO com.tc.statistics.util.StatsPrinter - TOTAL : 30647 instances
2011-12-21 10:42:52,376 [Stats Printer Aggregator] INFO com.tc.statistics.util.StatsPrinter - Broadcasted in the Last 5,000 ms
2011-12-21 10:42:52,376 [Stats Printer Aggregator] INFO com.tc.statistics.util.StatsPrinter - ==========================================================
2011-12-21 10:42:52,376 [Stats Printer Aggregator] INFO com.tc.statistics.util.StatsPrinter - com.terracotta.session.util.Timestamp : 13083 instances
2011-12-21 10:42:52,377 [Stats Printer Aggregator] INFO com.tc.statistics.util.StatsPrinter - com.terracotta.toolkit.collections.ConcurrentDistributedMapDso : 14439 instances
2011-12-21 10:42:52,377 [Stats Printer Aggregator] INFO com.tc.statistics.util.StatsPrinter - com.terracotta.session.SessionData : 1 instances
2011-12-21 10:42:52,377 [Stats Printer Aggregator] INFO com.tc.statistics.util.StatsPrinter - TOTAL : 27523 instances
2011-12-21 10:42:57,384 [Stats Printer Aggregator] INFO com.tc.statistics.util.StatsPrinter - Broadcasted in the Last 5,000 ms
2011-12-21 10:42:57,384 [Stats Printer Aggregator] INFO com.tc.statistics.util.StatsPrinter - ==========================================================
2011-12-21 10:42:57,384 [Stats Printer Aggregator] INFO com.tc.statistics.util.StatsPrinter - com.terracotta.session.util.Timestamp : 6486 instances
2011-12-21 10:42:57,384 [Stats Printer Aggregator] INFO com.tc.statistics.util.StatsPrinter - com.terracotta.toolkit.collections.ConcurrentDistributedMapDso : 12051 instances
2011-12-21 10:42:57,384 [Stats Printer Aggregator] INFO com.tc.statistics.util.StatsPrinter - TOTAL : 18537 instances
Nothing too strange in the server logs:
Code:
2011-12-27 13:25:05,383 [WorkerThread(gc_result_processing_stage, 0)] INFO com.tc.l2.handler.GCResultHandler - Scheduling to process GC results when all current transactions are completed : DGCResultMessage@1495514739 : DGC Info = GarbageCollectionInfo [ Iteration = 345 ] = type = full, startTime = 1325013845156 begin object count = 1670110 end object count = 939211 markStageTime = 58448 pauseStageTime = 220 totalMarkCycleTime = 59069 candiate garabage count = 750235 actual garbage count = 750235 pre rescue count = 1093097 rescue1Time = 29943 rescue 1 Count = 750235 rescue2Time = 220 Result size = 750235
2011-12-27 13:25:05,949 [WorkerThread(gc_result_processing_stage, 0)] INFO com.tc.l2.objectserver.ReplicatedObjectManagerImpl - Removed 750235 objects from passive ObjectManager from last DGC from Active
2011-12-27 13:25:07,561 [WorkerThread(gc_delete_from_disk_stage, 0)] INFO com.tc.objectserver.persistence.db.DBPersistorImpl - Removed 5000 objects in 332 ms.
2011-12-27 13:25:09,015 [WorkerThread(gc_delete_from_disk_stage, 0)] INFO com.tc.objectserver.persistence.db.DBPersistorImpl - Removed 5000 objects in 328 ms.
2011-12-27 13:25:10,444 [WorkerThread(gc_delete_from_disk_stage, 0)] INFO com.tc.objectserver.persistence.db.DBPersistorImpl - Removed 5000 objects in 343 ms.
2011-12-27 13:25:12,070 [WorkerThread(gc_delete_from_disk_stage, 0)] INFO com.tc.objectserver.persistence.db.DBPersistorImpl - Removed 5000 objects in 577 ms.
2011-12-27 13:25:14,966 [WorkerThread(gc_delete_from_disk_stage, 0)] INFO com.tc.objectserver.persistence.db.DBPersistorImpl - Removed 5000 objects in 555 ms.
2011-12-27 13:25:15,762 [WorkerThread(gc_delete_from_disk_stage, 0)] INFO com.tc.objectserver.persistence.db.DBPersistorImpl - Removed 5000 objects in 562 ms.
2011-12-27 13:25:17,282 [WorkerThread(gc_delete_from_disk_stage, 0)] INFO com.tc.objectserver.persistence.db.DBPersistorImpl - Removed 5000 objects in 590 ms.
2011-12-27 13:25:18,403 [WorkerThread(gc_delete_from_disk_stage, 0)] INFO com.tc.objectserver.persistence.db.DBPersistorImpl - Removed 5000 objects in 308 ms.
2011-12-27 13:25:21,297 [WorkerThread(gc_delete_from_disk_stage, 0)] INFO com.tc.objectserver.persistence.db.DBPersistorImpl - Removed 5000 objects in 322 ms.
2011-12-27 13:25:22,552 [WorkerThread(gc_delete_from_disk_stage, 0)] INFO com.tc.objectserver.persistence.db.DBPersistorImpl - Removed 5000 objects in 1073 ms.
2011-12-27 13:25:23,358 [WorkerThread(gc_delete_from_disk_stage, 0)] INFO com.tc.objectserver.persistence.db.DBPersistorImpl - Removed 5000 objects in 542 ms.
2011-12-27 13:25:24,366 [WorkerThread(gc_delete_from_disk_stage, 0)] INFO com.tc.objectserver.persistence.db.DBPersistorImpl - Removed 5000 objects in 1008 ms.
2011-12-27 13:25:24,874 [WorkerThread(gc_delete_from_disk_stage, 0)] INFO com.tc.objectserver.persistence.db.DBPersistorImpl - Removed 5000 objects in 508 ms.
2011-12-27 13:25:26,212 [WorkerThread(gc_delete_from_disk_stage, 0)] INFO com.tc.objectserver.persistence.db.DBPersistorImpl - Removed 5000 objects in 792 ms.
2011-12-27 13:25:29,579 [WorkerThread(gc_delete_from_disk_stage, 0)] INFO com.tc.objectserver.persistence.db.DBPersistorImpl - Removed 5000 objects in 3228 ms.
2011-12-27 13:25:30,123 [WorkerThread(gc_delete_from_disk_stage, 0)] INFO com.tc.objectserver.persistence.db.DBPersistorImpl - Removed 5000 objects in 544 ms.
2011-12-27 13:25:30,470 [WorkerThread(gc_delete_from_disk_stage, 0)] INFO com.tc.objectserver.persistence.db.DBPersistorImpl - Removed 5000 objects in 346 ms.
2011-12-27 13:25:36,000 [WorkerThread(gc_delete_from_disk_stage, 0)] INFO com.tc.objectserver.persistence.db.DBPersistorImpl - Removed 5000 objects in 442 ms.
2011-12-27 13:25:37,482 [WorkerThread(gc_delete_from_disk_stage, 0)] INFO com.tc.objectserver.persistence.db.DBPersistorImpl - Removed 5000 objects in 369 ms.
2011-12-27 13:25:37,908 [WorkerThread(gc_delete_from_disk_stage, 0)] INFO com.tc.objectserver.persistence.db.DBPersistorImpl - Removed 5000 objects in 321 ms.
2011-12-27 13:25:38,292 [WorkerThread(gc_delete_from_disk_stage, 0)] INFO com.tc.objectserver.persistence.db.DBPersistorImpl - Removed 5000 objects in 384 ms.
2011-12-27 13:38:55,344 [Statistics Logger] INFO com.terracottatech.dso - memory free : 799340184
2011-12-27 13:38:55,344 [Statistics Logger] INFO com.terracottatech.dso - memory used : 1301416296
2011-12-27 13:38:55,344 [Statistics Logger] INFO com.terracottatech.dso - memory max : 2100756480
2011-12-27 13:53:55,350 [Statistics Logger] INFO com.terracottatech.dso - memory free : 658848592
2011-12-27 13:53:55,350 [Statistics Logger] INFO com.terracottatech.dso - memory used : 1440597168
2011-12-27 13:53:55,351 [Statistics Logger] INFO com.terracottatech.dso - memory max : 2099445760
2011-12-27 14:08:55,347 [Statistics Logger] INFO com.terracottatech.dso - memory free : 474232336
2011-12-27 14:08:55,347 [Statistics Logger] INFO com.terracottatech.dso - memory used : 1569442288
2011-12-27 14:08:55,347 [Statistics Logger] INFO com.terracottatech.dso - memory max : 2043674624
2011-12-27 14:22:03,626 [WorkerThread(channel_life_cycle_stage, 0)] INFO com.tc.objectserver.handler.ChannelLifeCycleHandler - : Received transport disconnect. Shutting down client ClientID[2998]
2011-12-27 14:22:03,627 [WorkerThread(channel_life_cycle_stage, 0)] INFO com.tc.objectserver.persistence.inmemory.TransactionStoreImpl - shutdownClient() : Removing txns from DB : 682
2011-12-27 14:22:47,268 [WorkerThread(channel_life_cycle_stage, 0)] INFO com.tc.objectserver.handler.ChannelLifeCycleHandler - : Received transport disconnect. Shutting down client ClientID[2995]
2011-12-27 14:22:47,268 [WorkerThread(channel_life_cycle_stage, 0)] INFO com.tc.objectserver.persistence.inmemory.TransactionStoreImpl - shutdownClient() : Removing txns from DB : 0
2011-12-27 14:22:47,269 [WorkerThread(channel_life_cycle_stage, 0)] INFO com.tc.objectserver.handler.ChannelLifeCycleHandler - : Received transport disconnect. Shutting down client ClientID[2999]
2011-12-27 14:22:47,269 [WorkerThread(channel_life_cycle_stage, 0)] INFO com.tc.objectserver.persistence.inmemory.TransactionStoreImpl - shutdownClient() : Removing txns from DB : 0
2011-12-27 14:22:47,272 [WorkerThread(channel_life_cycle_stage, 0)] INFO com.tc.objectserver.handler.ChannelLifeCycleHandler - : Received transport disconnect. Shutting down client ClientID[2997]
2011-12-27 14:22:47,272 [WorkerThread(channel_life_cycle_stage, 0)] INFO com.tc.objectserver.persistence.inmemory.TransactionStoreImpl - shutdownClient() : Removing txns from DB : 0
2011-12-27 14:23:55,343 [Statistics Logger] INFO com.terracottatech.dso - memory free : 793319384
2011-12-27 14:23:55,343 [Statistics Logger] INFO com.terracottatech.dso - memory used : 1293871144
2011-12-27 14:23:55,343 [Statistics Logger] INFO com.terracottatech.dso - memory max : 2087190528
2011-12-27 14:26:45,145 [WorkerThread(gc_result_processing_stage, 0)] INFO com.tc.l2.handler.GCResultHandler - Scheduling to process GC results when all current transactions are completed : DGCResultMessage@705664808 : DGC Info = GarbageCollectionInfo [ Iteration = 346 ] = type = full, startTime = 1325017504254 begin object count = 2091530 end object count = 1318193 markStageTime = 99891 pauseStageTime = 285 totalMarkCycleTime = 100603 candiate garabage count = 803623 actual garbage count = 803623 pre rescue count = 1454211 rescue1Time = 66827 rescue 1 Count = 803623 rescue2Time = 285 Result size = 803623
2011-12-27 14:26:45,832 [WorkerThread(gc_result_processing_stage, 0)] INFO com.tc.l2.objectserver.ReplicatedObjectManagerImpl - Removed 803623 objects from passive ObjectManager from last DGC from Active
2011-12-27 14:26:48,265 [WorkerThread(gc_delete_from_disk_stage, 0)] INFO com.tc.objectserver.persistence.db.DBPersistorImpl - Removed 5000 objects in 373 ms.
2011-12-27 14:26:51,951 [WorkerThread(gc_delete_from_disk_stage, 0)] INFO com.tc.objectserver.persistence.db.DBPersistorImpl - Removed 5000 objects in 688 ms.
2011-12-27 14:26:52,424 [WorkerThread(gc_delete_from_disk_stage, 0)] INFO com.tc.objectserver.persistence.db.DBPersistorImpl - Removed 5000 objects in 473 ms.
2011-12-27 14:26:54,891 [WorkerThread(gc_delete_from_disk_stage, 0)] INFO com.tc.objectserver.persistence.db.DBPersistorImpl - Removed 5000 objects in 546 ms.
2011-12-27 14:26:55,728 [WorkerThread(gc_delete_from_disk_stage, 0)] INFO com.tc.objectserver.persistence.db.DBPersistorImpl - Removed 5000 objects in 544 ms.
2011-12-27 14:27:00,231 [WorkerThread(gc_delete_from_disk_stage, 0)] INFO com.tc.objectserver.persistence.db.DBPersistorImpl - Removed 5000 objects in 3282 ms.
2011-12-27 14:27:00,831 [WorkerThread(gc_delete_from_disk_stage, 0)] INFO com.tc.objectserver.persistence.db.DBPersistorImpl - Removed 5000 objects in 600 ms.
2011-12-27 14:27:02,195 [WorkerThread(gc_delete_from_disk_stage, 0)] INFO com.tc.objectserver.persistence.db.DBPersistorImpl - Removed 5000 objects in 349 ms.
2011-12-27 14:27:04,554 [WorkerThread(gc_delete_from_disk_stage, 0)] INFO com.tc.objectserver.persistence.db.DBPersistorImpl - Removed 5000 objects in 534 ms.
2011-12-27 14:27:06,659 [WorkerThread(gc_delete_from_disk_stage, 0)] INFO com.tc.objectserver.persistence.db.DBPersistorImpl - Removed 5000 objects in 2105 ms.
2011-12-27 14:27:07,222 [WorkerThread(gc_delete_from_disk_stage, 0)] INFO com.tc.objectserver.persistence.db.DBPersistorImpl - Removed 5000 objects in 563 ms.
2011-12-27 14:27:07,632 [WorkerThread(gc_delete_from_disk_stage, 0)] INFO com.tc.objectserver.persistence.db.DBPersistorImpl - Removed 5000 objects in 410 ms.
2011-12-27 14:27:08,035 [WorkerThread(gc_delete_from_disk_stage, 0)] INFO com.tc.objectserver.persistence.db.DBPersistorImpl - Removed 5000 objects in 403 ms.
2011-12-27 14:27:08,587 [WorkerThread(gc_delete_from_disk_stage, 0)] INFO com.tc.objectserver.persistence.db.DBPersistorImpl - Removed 5000 objects in 305 ms.
2011-12-27 14:27:09,402 [WorkerThread(gc_delete_from_disk_stage, 0)] INFO com.tc.objectserver.persistence.db.DBPersistorImpl - Removed 5000 objects in 555 ms.
2011-12-27 14:27:12,216 [WorkerThread(gc_delete_from_disk_stage, 0)] INFO com.tc.objectserver.persistence.db.DBPersistorImpl - Removed 5000 objects in 2814 ms.
2011-12-27 14:27:15,160 [WorkerThread(gc_delete_from_disk_stage, 0)] INFO com.tc.objectserver.persistence.db.DBPersistorImpl - Removed 5000 objects in 568 ms.
2011-12-27 14:27:15,778 [WorkerThread(gc_delete_from_disk_stage, 0)] INFO com.tc.objectserver.persistence.db.DBPersistorImpl - Removed 5000 objects in 432 ms.
2011-12-27 14:27:17,121 [WorkerThread(gc_delete_from_disk_stage, 0)] INFO com.tc.objectserver.persistence.db.DBPersistorImpl - Removed 5000 objects in 335 ms.
2011-12-27 14:27:18,668 [WorkerThread(gc_delete_from_disk_stage, 0)] INFO com.tc.objectserver.persistence.db.DBPersistorImpl - Removed 5000 objects in 311 ms.
2011-12-27 14:27:20,530 [WorkerThread(gc_delete_from_disk_stage, 0)] INFO com.tc.objectserver.persistence.db.DBPersistorImpl - Removed 5000 objects in 467 ms.
2011-12-27 14:27:22,890 [WorkerThread(gc_delete_from_disk_stage, 0)] INFO com.tc.objectserver.persistence.db.DBPersistorImpl - Removed 5000 objects in 340 ms.
2011-12-27 14:38:55,351 [Statistics Logger] INFO com.terracottatech.dso - memory free : 625607832
2011-12-27 14:38:55,351 [Statistics Logger] INFO com.terracottatech.dso - memory used : 1475214184
2011-12-27 14:38:55,351 [Statistics Logger] INFO com.terracottatech.dso - memory max : 2100822016
2011-12-27 14:53:55,353 [Statistics Logger] INFO com.terracottatech.dso - memory free : 1031827920
2011-12-27 14:53:55,353 [Statistics Logger] INFO com.terracottatech.dso - memory used : 1032490544
2011-12-27 14:53:55,353 [Statistics Logger] INFO com.terracottatech.dso - memory max : 2064318464
Any help on this would be greatly appreciated as we can't figure out why it would do this. We're thinking maybe it's not correctly configured? Here is the config file:
Code:
<?xml version="1.0" encoding="UTF-8"?>
<con:tc-config xmlns:con="http://www.terracotta.org/config">
<servers>
<server host="hostname.com" name="hostname.com">
<data>/var/terracotta/server-data</data>
<dso-port bind="0.0.0.0">9510</dso-port>
<jmx-port bind="0.0.0.0">9520</jmx-port>
<l2-group-port>9530</l2-group-port>
<logs>/var/log/terracotta/server-logs</logs>
<statistics>/var/log/terracotta/cluster-statistics</statistics>
<dso>
<persistence>
<mode>permanent-store</mode>
</persistence>
</dso>
</server>
<server host="hostname.com" name="hostname.com">
<data>/var/terracotta/server-data</data>
<dso-port bind="0.0.0.0">9510</dso-port>
<jmx-port bind="0.0.0.0">9520</jmx-port>
<l2-group-port>9530</l2-group-port>
<logs>/var/log/terracotta/server-logs</logs>
<statistics>/var/log/terracotta/cluster-statistics</statistics>
<dso>
<persistence>
<mode>permanent-store</mode>
</persistence>
</dso>
</server>
<ha>
<mode>networked-active-passive</mode>
<networked-active-passive>
<election-time>5</election-time>
</networked-active-passive>
</ha>
</servers>
<clients>
<logs>/usr/local/tomcat6/logs/terracotta/client-logs</logs>
</clients>
</con:tc-config>
Thank you and any help would be appreciated!
Vincent
|
|
|
 |
12/28/2011 05:33:40
|
dpope
master
Joined: 12/11/2007 10:16:33
Messages: 74
Location: Wesley Chapel, NC
Offline
|
1. I see that you are using Terracotta 3.4. Exactly which version are you running?
2. Can you post your full terracotta-server.logs and terracotta-client.logs?
Thanks,
Darin
|
|
|
|
12/28/2011 09:55:21
|
gekko959
neo
Joined: 12/08/2011 12:45:44
Messages: 6
Offline
|
The version of terracotta is 3.4.0.
Here is the last 24 hours of the server log. The entire log is more than a mb and is too big to post.
Code:
2011-12-27 10:08:55,344 [Statistics Logger] INFO com.terracottatech.dso - memory free : 628418432
2011-12-27 10:08:55,344 [Statistics Logger] INFO com.terracottatech.dso - memory used : 1450842240
2011-12-27 10:08:55,344 [Statistics Logger] INFO com.terracottatech.dso - memory max : 2079260672
2011-12-27 10:22:31,821 [WorkerThread(gc_result_processing_stage, 0)] INFO com.tc.l2.handler.GCResultHandler - Scheduling to process GC results when all current transactions are completed : DGCResultMessage@1298141198 : DGC Info = GarbageCollectionInfo [ Iteration = 342 ] = type = full, startTime = 1325002909097 begin object count = 1403246 end object count = 771939 markStageTime = 42089 pauseStageTime = 182 totalMarkCycleTime = 42639 candiate garabage count = 638474 actual garbage count = 638474 pre rescue count = 939582 rescue1Time = 22169 rescue 1 Count = 638474 rescue2Time = 182 Result size = 638474
2011-12-27 10:22:32,509 [WorkerThread(gc_result_processing_stage, 0)] INFO com.tc.l2.objectserver.ReplicatedObjectManagerImpl - Removed 638474 objects from passive ObjectManager from last DGC from Active
2011-12-27 10:22:37,548 [WorkerThread(gc_delete_from_disk_stage, 0)] INFO com.tc.objectserver.persistence.db.DBPersistorImpl - Removed 5000 objects in 2628 ms.
2011-12-27 10:22:40,204 [WorkerThread(gc_delete_from_disk_stage, 0)] INFO com.tc.objectserver.persistence.db.DBPersistorImpl - Removed 5000 objects in 326 ms.
2011-12-27 10:22:40,526 [WorkerThread(gc_delete_from_disk_stage, 0)] INFO com.tc.objectserver.persistence.db.DBPersistorImpl - Removed 5000 objects in 322 ms.
2011-12-27 10:22:40,922 [WorkerThread(gc_delete_from_disk_stage, 0)] INFO com.tc.objectserver.persistence.db.DBPersistorImpl - Removed 5000 objects in 396 ms.
2011-12-27 10:22:43,170 [WorkerThread(gc_delete_from_disk_stage, 0)] INFO com.tc.objectserver.persistence.db.DBPersistorImpl - Removed 5000 objects in 310 ms.
2011-12-27 10:22:43,845 [WorkerThread(gc_delete_from_disk_stage, 0)] INFO com.tc.objectserver.persistence.db.DBPersistorImpl - Removed 5000 objects in 377 ms.
2011-12-27 10:22:49,945 [WorkerThread(gc_delete_from_disk_stage, 0)] INFO com.tc.objectserver.persistence.db.DBPersistorImpl - Removed 5000 objects in 419 ms.
2011-12-27 10:22:50,270 [WorkerThread(gc_delete_from_disk_stage, 0)] INFO com.tc.objectserver.persistence.db.DBPersistorImpl - Removed 5000 objects in 325 ms.
2011-12-27 10:22:51,573 [WorkerThread(gc_delete_from_disk_stage, 0)] INFO com.tc.objectserver.persistence.db.DBPersistorImpl - Removed 5000 objects in 1303 ms.
2011-12-27 10:22:52,136 [WorkerThread(gc_delete_from_disk_stage, 0)] INFO com.tc.objectserver.persistence.db.DBPersistorImpl - Removed 5000 objects in 345 ms.
2011-12-27 10:22:52,970 [WorkerThread(gc_delete_from_disk_stage, 0)] INFO com.tc.objectserver.persistence.db.DBPersistorImpl - Removed 5000 objects in 385 ms.
2011-12-27 10:22:53,882 [WorkerThread(gc_delete_from_disk_stage, 0)] INFO com.tc.objectserver.persistence.db.DBPersistorImpl - Removed 5000 objects in 425 ms.
2011-12-27 10:22:54,190 [WorkerThread(gc_delete_from_disk_stage, 0)] INFO com.tc.objectserver.persistence.db.DBPersistorImpl - Removed 5000 objects in 308 ms.
2011-12-27 10:22:54,769 [WorkerThread(gc_delete_from_disk_stage, 0)] INFO com.tc.objectserver.persistence.db.DBPersistorImpl - Removed 5000 objects in 390 ms.
2011-12-27 10:22:55,380 [WorkerThread(gc_delete_from_disk_stage, 0)] INFO com.tc.objectserver.persistence.db.DBPersistorImpl - Removed 5000 objects in 325 ms.
2011-12-27 10:22:58,554 [WorkerThread(gc_delete_from_disk_stage, 0)] INFO com.tc.objectserver.persistence.db.DBPersistorImpl - Removed 5000 objects in 2888 ms.
2011-12-27 10:23:55,350 [Statistics Logger] INFO com.terracottatech.dso - memory free : 503051648
2011-12-27 10:23:55,352 [Statistics Logger] INFO com.terracottatech.dso - memory used : 1590233728
2011-12-27 10:23:55,353 [Statistics Logger] INFO com.terracottatech.dso - memory max : 2093285376
2011-12-27 10:38:55,346 [Statistics Logger] INFO com.terracottatech.dso - memory free : 1122379184
2011-12-27 10:38:55,347 [Statistics Logger] INFO com.terracottatech.dso - memory used : 979032656
2011-12-27 10:38:55,347 [Statistics Logger] INFO com.terracottatech.dso - memory max : 2101411840
2011-12-27 10:53:55,352 [Statistics Logger] INFO com.terracottatech.dso - memory free : 515179440
2011-12-27 10:53:55,352 [Statistics Logger] INFO com.terracottatech.dso - memory used : 1579285584
2011-12-27 10:53:55,353 [Statistics Logger] INFO com.terracottatech.dso - memory max : 2094465024
2011-12-27 11:08:55,347 [Statistics Logger] INFO com.terracottatech.dso - memory free : 545331328
2011-12-27 11:08:55,347 [Statistics Logger] INFO com.terracottatech.dso - memory used : 1525344128
2011-12-27 11:08:55,347 [Statistics Logger] INFO com.terracottatech.dso - memory max : 2070675456
2011-12-27 11:23:13,111 [WorkerThread(gc_result_processing_stage, 0)] INFO com.tc.l2.handler.GCResultHandler - Scheduling to process GC results when all current transactions are completed : DGCResultMessage@2145050949 : DGC Info = GarbageCollectionInfo [ Iteration = 343 ] = type = full, startTime = 1325006551768 begin object count = 1375817 end object count = 784524 markStageTime = 40626 pauseStageTime = 180 totalMarkCycleTime = 41190 candiate garabage count = 598360 actual garbage count = 598360 pre rescue count = 903496 rescue1Time = 22455 rescue 1 Count = 598360 rescue2Time = 180 Result size = 598360
2011-12-27 11:23:13,644 [WorkerThread(gc_result_processing_stage, 0)] INFO com.tc.l2.objectserver.ReplicatedObjectManagerImpl - Removed 598360 objects from passive ObjectManager from last DGC from Active
2011-12-27 11:23:15,422 [WorkerThread(gc_delete_from_disk_stage, 0)] INFO com.tc.objectserver.persistence.db.DBPersistorImpl - Removed 5000 objects in 344 ms.
2011-12-27 11:23:17,487 [WorkerThread(gc_delete_from_disk_stage, 0)] INFO com.tc.objectserver.persistence.db.DBPersistorImpl - Removed 5000 objects in 532 ms.
2011-12-27 11:23:17,931 [WorkerThread(gc_delete_from_disk_stage, 0)] INFO com.tc.objectserver.persistence.db.DBPersistorImpl - Removed 5000 objects in 444 ms.
2011-12-27 11:23:18,275 [WorkerThread(gc_delete_from_disk_stage, 0)] INFO com.tc.objectserver.persistence.db.DBPersistorImpl - Removed 5000 objects in 343 ms.
2011-12-27 11:23:21,135 [WorkerThread(gc_delete_from_disk_stage, 0)] INFO com.tc.objectserver.persistence.db.DBPersistorImpl - Removed 5000 objects in 1116 ms.
2011-12-27 11:23:22,011 [WorkerThread(gc_delete_from_disk_stage, 0)] INFO com.tc.objectserver.persistence.db.DBPersistorImpl - Removed 5000 objects in 333 ms.
2011-12-27 11:23:25,980 [WorkerThread(gc_delete_from_disk_stage, 0)] INFO com.tc.objectserver.persistence.db.DBPersistorImpl - Removed 5000 objects in 2680 ms.
2011-12-27 11:23:31,553 [WorkerThread(gc_delete_from_disk_stage, 0)] INFO com.tc.objectserver.persistence.db.DBPersistorImpl - Removed 5000 objects in 414 ms.
2011-12-27 11:23:31,953 [WorkerThread(gc_delete_from_disk_stage, 0)] INFO com.tc.objectserver.persistence.db.DBPersistorImpl - Removed 5000 objects in 400 ms.
2011-12-27 11:23:32,287 [WorkerThread(gc_delete_from_disk_stage, 0)] INFO com.tc.objectserver.persistence.db.DBPersistorImpl - Removed 5000 objects in 334 ms.
2011-12-27 11:23:34,522 [WorkerThread(gc_delete_from_disk_stage, 0)] INFO com.tc.objectserver.persistence.db.DBPersistorImpl - Removed 5000 objects in 346 ms.
2011-12-27 11:23:37,441 [WorkerThread(gc_delete_from_disk_stage, 0)] INFO com.tc.objectserver.persistence.db.DBPersistorImpl - Removed 3360 objects in 1785 ms.
2011-12-27 11:23:55,343 [Statistics Logger] INFO com.terracottatech.dso - memory free : 884296792
2011-12-27 11:23:55,343 [Statistics Logger] INFO com.terracottatech.dso - memory used : 1201779624
2011-12-27 11:23:55,343 [Statistics Logger] INFO com.terracottatech.dso - memory max : 2086076416
2011-12-27 11:38:55,349 [Statistics Logger] INFO com.terracottatech.dso - memory free : 629906080
2011-12-27 11:38:55,349 [Statistics Logger] INFO com.terracottatech.dso - memory used : 1469670752
2011-12-27 11:38:55,349 [Statistics Logger] INFO com.terracottatech.dso - memory max : 2099576832
2011-12-27 11:53:55,345 [Statistics Logger] INFO com.terracottatech.dso - memory free : 888421904
2011-12-27 11:53:55,346 [Statistics Logger] INFO com.terracottatech.dso - memory used : 1180615152
2011-12-27 11:53:55,346 [Statistics Logger] INFO com.terracottatech.dso - memory max : 2069037056
2011-12-27 12:08:55,342 [Statistics Logger] INFO com.terracottatech.dso - memory free : 848075752
2011-12-27 12:08:55,342 [Statistics Logger] INFO com.terracottatech.dso - memory used : 1242129432
2011-12-27 12:08:55,342 [Statistics Logger] INFO com.terracottatech.dso - memory max : 2090205184
2011-12-27 12:23:55,348 [Statistics Logger] INFO com.terracottatech.dso - memory free : 447416080
2011-12-27 12:23:55,348 [Statistics Logger] INFO com.terracottatech.dso - memory used : 1643641072
2011-12-27 12:23:55,348 [Statistics Logger] INFO com.terracottatech.dso - memory max : 2091057152
2011-12-27 12:24:05,223 [WorkerThread(gc_result_processing_stage, 0)] INFO com.tc.l2.handler.GCResultHandler - Scheduling to process GC results when all current transactions are completed : DGCResultMessage@899336826 : DGC Info = GarbageCollectionInfo [ Iteration = 344 ] = type = full, startTime = 1325010193060 begin object count = 1493091 end object count = 878517 markStageTime = 51542 pauseStageTime = 192 totalMarkCycleTime = 52074 candiate garabage count = 626332 actual garbage count = 626332 pre rescue count = 979022 rescue1Time = 30396 rescue 1 Count = 626332 rescue2Time = 192 Result size = 626332
2011-12-27 12:24:05,787 [WorkerThread(gc_result_processing_stage, 0)] INFO com.tc.l2.objectserver.ReplicatedObjectManagerImpl - Removed 626332 objects from passive ObjectManager from last DGC from Active
2011-12-27 12:24:06,725 [WorkerThread(gc_delete_from_disk_stage, 0)] INFO com.tc.objectserver.persistence.db.DBPersistorImpl - Removed 5000 objects in 460 ms.
2011-12-27 12:24:08,684 [WorkerThread(gc_delete_from_disk_stage, 0)] INFO com.tc.objectserver.persistence.db.DBPersistorImpl - Removed 5000 objects in 336 ms.
2011-12-27 12:24:11,126 [WorkerThread(gc_delete_from_disk_stage, 0)] INFO com.tc.objectserver.persistence.db.DBPersistorImpl - Removed 5000 objects in 355 ms.
2011-12-27 12:24:12,677 [WorkerThread(gc_delete_from_disk_stage, 0)] INFO com.tc.objectserver.persistence.db.DBPersistorImpl - Removed 5000 objects in 301 ms.
2011-12-27 12:24:14,197 [WorkerThread(gc_delete_from_disk_stage, 0)] INFO com.tc.objectserver.persistence.db.DBPersistorImpl - Removed 5000 objects in 304 ms.
2011-12-27 12:24:18,285 [WorkerThread(gc_delete_from_disk_stage, 0)] INFO com.tc.objectserver.persistence.db.DBPersistorImpl - Removed 5000 objects in 2828 ms.
2011-12-27 12:24:18,880 [WorkerThread(gc_delete_from_disk_stage, 0)] INFO com.tc.objectserver.persistence.db.DBPersistorImpl - Removed 5000 objects in 594 ms.
2011-12-27 12:24:19,229 [WorkerThread(gc_delete_from_disk_stage, 0)] INFO com.tc.objectserver.persistence.db.DBPersistorImpl - Removed 5000 objects in 349 ms.
2011-12-27 12:24:19,665 [WorkerThread(gc_delete_from_disk_stage, 0)] INFO com.tc.objectserver.persistence.db.DBPersistorImpl - Removed 5000 objects in 435 ms.
2011-12-27 12:24:20,360 [WorkerThread(gc_delete_from_disk_stage, 0)] INFO com.tc.objectserver.persistence.db.DBPersistorImpl - Removed 5000 objects in 453 ms.
2011-12-27 12:24:20,684 [WorkerThread(gc_delete_from_disk_stage, 0)] INFO com.tc.objectserver.persistence.db.DBPersistorImpl - Removed 5000 objects in 324 ms.
2011-12-27 12:24:21,014 [WorkerThread(gc_delete_from_disk_stage, 0)] INFO com.tc.objectserver.persistence.db.DBPersistorImpl - Removed 5000 objects in 330 ms.
2011-12-27 12:24:22,057 [WorkerThread(gc_delete_from_disk_stage, 0)] INFO com.tc.objectserver.persistence.db.DBPersistorImpl - Removed 5000 objects in 321 ms.
2011-12-27 12:24:23,440 [WorkerThread(gc_delete_from_disk_stage, 0)] INFO com.tc.objectserver.persistence.db.DBPersistorImpl - Removed 5000 objects in 318 ms.
2011-12-27 12:24:25,451 [WorkerThread(gc_delete_from_disk_stage, 0)] INFO com.tc.objectserver.persistence.db.DBPersistorImpl - Removed 5000 objects in 769 ms.
2011-12-27 12:24:26,483 [WorkerThread(gc_delete_from_disk_stage, 0)] INFO com.tc.objectserver.persistence.db.DBPersistorImpl - Removed 5000 objects in 551 ms.
2011-12-27 12:24:27,238 [WorkerThread(gc_delete_from_disk_stage, 0)] INFO com.tc.objectserver.persistence.db.DBPersistorImpl - Removed 5000 objects in 755 ms.
2011-12-27 12:24:29,665 [WorkerThread(gc_delete_from_disk_stage, 0)] INFO com.tc.objectserver.persistence.db.DBPersistorImpl - Removed 5000 objects in 1340 ms.
2011-12-27 12:24:33,722 [WorkerThread(gc_delete_from_disk_stage, 0)] INFO com.tc.objectserver.persistence.db.DBPersistorImpl - Removed 5000 objects in 712 ms.
2011-12-27 12:38:55,344 [Statistics Logger] INFO com.terracottatech.dso - memory free : 896699312
2011-12-27 12:38:55,344 [Statistics Logger] INFO com.terracottatech.dso - memory used : 1200321616
2011-12-27 12:38:55,344 [Statistics Logger] INFO com.terracottatech.dso - memory max : 2097020928
2011-12-27 12:53:55,345 [Statistics Logger] INFO com.terracottatech.dso - memory free : 812126736
2011-12-27 12:53:55,345 [Statistics Logger] INFO com.terracottatech.dso - memory used : 1273622000
2011-12-27 12:53:55,345 [Statistics Logger] INFO com.terracottatech.dso - memory max : 2085748736
2011-12-27 13:08:55,342 [Statistics Logger] INFO com.terracottatech.dso - memory free : 959221560
2011-12-27 13:08:55,342 [Statistics Logger] INFO com.terracottatech.dso - memory used : 1075736776
2011-12-27 13:08:55,342 [Statistics Logger] INFO com.terracottatech.dso - memory max : 2034958336
2011-12-27 13:23:55,348 [Statistics Logger] INFO com.terracottatech.dso - memory free : 254046752
2011-12-27 13:23:55,348 [Statistics Logger] INFO com.terracottatech.dso - memory used : 1807977952
2011-12-27 13:23:55,348 [Statistics Logger] INFO com.terracottatech.dso - memory max : 2062024704
2011-12-27 13:25:05,383 [WorkerThread(gc_result_processing_stage, 0)] INFO com.tc.l2.handler.GCResultHandler - Scheduling to process GC results when all current transactions are completed : DGCResultMessage@1495514739 : DGC Info = GarbageCollectionInfo [ Iteration = 345 ] = type = full, startTime = 1325013845156 begin object count = 1670110 end object count = 939211 markStageTime = 58448 pauseStageTime = 220 totalMarkCycleTime = 59069 candiate garabage count = 750235 actual garbage count = 750235 pre rescue count = 1093097 rescue1Time = 29943 rescue 1 Count = 750235 rescue2Time = 220 Result size = 750235
2011-12-27 13:25:05,949 [WorkerThread(gc_result_processing_stage, 0)] INFO com.tc.l2.objectserver.ReplicatedObjectManagerImpl - Removed 750235 objects from passive ObjectManager from last DGC from Active
2011-12-27 13:25:07,561 [WorkerThread(gc_delete_from_disk_stage, 0)] INFO com.tc.objectserver.persistence.db.DBPersistorImpl - Removed 5000 objects in 332 ms.
2011-12-27 13:25:09,015 [WorkerThread(gc_delete_from_disk_stage, 0)] INFO com.tc.objectserver.persistence.db.DBPersistorImpl - Removed 5000 objects in 328 ms.
2011-12-27 13:25:10,444 [WorkerThread(gc_delete_from_disk_stage, 0)] INFO com.tc.objectserver.persistence.db.DBPersistorImpl - Removed 5000 objects in 343 ms.
2011-12-27 13:25:12,070 [WorkerThread(gc_delete_from_disk_stage, 0)] INFO com.tc.objectserver.persistence.db.DBPersistorImpl - Removed 5000 objects in 577 ms.
2011-12-27 13:25:14,966 [WorkerThread(gc_delete_from_disk_stage, 0)] INFO com.tc.objectserver.persistence.db.DBPersistorImpl - Removed 5000 objects in 555 ms.
2011-12-27 13:25:15,762 [WorkerThread(gc_delete_from_disk_stage, 0)] INFO com.tc.objectserver.persistence.db.DBPersistorImpl - Removed 5000 objects in 562 ms.
2011-12-27 13:25:17,282 [WorkerThread(gc_delete_from_disk_stage, 0)] INFO com.tc.objectserver.persistence.db.DBPersistorImpl - Removed 5000 objects in 590 ms.
2011-12-27 13:25:18,403 [WorkerThread(gc_delete_from_disk_stage, 0)] INFO com.tc.objectserver.persistence.db.DBPersistorImpl - Removed 5000 objects in 308 ms.
2011-12-27 13:25:21,297 [WorkerThread(gc_delete_from_disk_stage, 0)] INFO com.tc.objectserver.persistence.db.DBPersistorImpl - Removed 5000 objects in 322 ms.
2011-12-27 13:25:22,552 [WorkerThread(gc_delete_from_disk_stage, 0)] INFO com.tc.objectserver.persistence.db.DBPersistorImpl - Removed 5000 objects in 1073 ms.
2011-12-27 13:25:23,358 [WorkerThread(gc_delete_from_disk_stage, 0)] INFO com.tc.objectserver.persistence.db.DBPersistorImpl - Removed 5000 objects in 542 ms.
2011-12-27 13:25:24,366 [WorkerThread(gc_delete_from_disk_stage, 0)] INFO com.tc.objectserver.persistence.db.DBPersistorImpl - Removed 5000 objects in 1008 ms.
2011-12-27 13:25:24,874 [WorkerThread(gc_delete_from_disk_stage, 0)] INFO com.tc.objectserver.persistence.db.DBPersistorImpl - Removed 5000 objects in 508 ms.
2011-12-27 13:25:26,212 [WorkerThread(gc_delete_from_disk_stage, 0)] INFO com.tc.objectserver.persistence.db.DBPersistorImpl - Removed 5000 objects in 792 ms.
2011-12-27 13:25:29,579 [WorkerThread(gc_delete_from_disk_stage, 0)] INFO com.tc.objectserver.persistence.db.DBPersistorImpl - Removed 5000 objects in 3228 ms.
2011-12-27 13:25:30,123 [WorkerThread(gc_delete_from_disk_stage, 0)] INFO com.tc.objectserver.persistence.db.DBPersistorImpl - Removed 5000 objects in 544 ms.
2011-12-27 13:25:30,470 [WorkerThread(gc_delete_from_disk_stage, 0)] INFO com.tc.objectserver.persistence.db.DBPersistorImpl - Removed 5000 objects in 346 ms.
2011-12-27 13:25:36,000 [WorkerThread(gc_delete_from_disk_stage, 0)] INFO com.tc.objectserver.persistence.db.DBPersistorImpl - Removed 5000 objects in 442 ms.
2011-12-27 13:25:37,482 [WorkerThread(gc_delete_from_disk_stage, 0)] INFO com.tc.objectserver.persistence.db.DBPersistorImpl - Removed 5000 objects in 369 ms.
2011-12-27 13:25:37,908 [WorkerThread(gc_delete_from_disk_stage, 0)] INFO com.tc.objectserver.persistence.db.DBPersistorImpl - Removed 5000 objects in 321 ms.
2011-12-27 13:25:38,292 [WorkerThread(gc_delete_from_disk_stage, 0)] INFO com.tc.objectserver.persistence.db.DBPersistorImpl - Removed 5000 objects in 384 ms.
2011-12-27 13:38:55,344 [Statistics Logger] INFO com.terracottatech.dso - memory free : 799340184
2011-12-27 13:38:55,344 [Statistics Logger] INFO com.terracottatech.dso - memory used : 1301416296
2011-12-27 13:38:55,344 [Statistics Logger] INFO com.terracottatech.dso - memory max : 2100756480
2011-12-27 13:53:55,350 [Statistics Logger] INFO com.terracottatech.dso - memory free : 658848592
2011-12-27 13:53:55,350 [Statistics Logger] INFO com.terracottatech.dso - memory used : 1440597168
2011-12-27 13:53:55,351 [Statistics Logger] INFO com.terracottatech.dso - memory max : 2099445760
2011-12-27 14:08:55,347 [Statistics Logger] INFO com.terracottatech.dso - memory free : 474232336
2011-12-27 14:08:55,347 [Statistics Logger] INFO com.terracottatech.dso - memory used : 1569442288
2011-12-27 14:08:55,347 [Statistics Logger] INFO com.terracottatech.dso - memory max : 2043674624
2011-12-27 14:22:03,626 [WorkerThread(channel_life_cycle_stage, 0)] INFO com.tc.objectserver.handler.ChannelLifeCycleHandler - : Received transport disconnect. Shutting down client ClientID[2998]
2011-12-27 14:22:03,627 [WorkerThread(channel_life_cycle_stage, 0)] INFO com.tc.objectserver.persistence.inmemory.TransactionStoreImpl - shutdownClient() : Removing txns from DB : 682
2011-12-27 14:22:47,268 [WorkerThread(channel_life_cycle_stage, 0)] INFO com.tc.objectserver.handler.ChannelLifeCycleHandler - : Received transport disconnect. Shutting down client ClientID[2995]
2011-12-27 14:22:47,268 [WorkerThread(channel_life_cycle_stage, 0)] INFO com.tc.objectserver.persistence.inmemory.TransactionStoreImpl - shutdownClient() : Removing txns from DB : 0
2011-12-27 14:22:47,269 [WorkerThread(channel_life_cycle_stage, 0)] INFO com.tc.objectserver.handler.ChannelLifeCycleHandler - : Received transport disconnect. Shutting down client ClientID[2999]
2011-12-27 14:22:47,269 [WorkerThread(channel_life_cycle_stage, 0)] INFO com.tc.objectserver.persistence.inmemory.TransactionStoreImpl - shutdownClient() : Removing txns from DB : 0
2011-12-27 14:22:47,272 [WorkerThread(channel_life_cycle_stage, 0)] INFO com.tc.objectserver.handler.ChannelLifeCycleHandler - : Received transport disconnect. Shutting down client ClientID[2997]
2011-12-27 14:22:47,272 [WorkerThread(channel_life_cycle_stage, 0)] INFO com.tc.objectserver.persistence.inmemory.TransactionStoreImpl - shutdownClient() : Removing txns from DB : 0
2011-12-27 14:23:55,343 [Statistics Logger] INFO com.terracottatech.dso - memory free : 793319384
2011-12-27 14:23:55,343 [Statistics Logger] INFO com.terracottatech.dso - memory used : 1293871144
2011-12-27 14:23:55,343 [Statistics Logger] INFO com.terracottatech.dso - memory max : 2087190528
2011-12-27 14:26:45,145 [WorkerThread(gc_result_processing_stage, 0)] INFO com.tc.l2.handler.GCResultHandler - Scheduling to process GC results when all current transactions are completed : DGCResultMessage@705664808 : DGC Info = GarbageCollectionInfo [ Iteration = 346 ] = type = full, startTime = 1325017504254 begin object count = 2091530 end object count = 1318193 markStageTime = 99891 pauseStageTime = 285 totalMarkCycleTime = 100603 candiate garabage count = 803623 actual garbage count = 803623 pre rescue count = 1454211 rescue1Time = 66827 rescue 1 Count = 803623 rescue2Time = 285 Result size = 803623
2011-12-27 14:26:45,832 [WorkerThread(gc_result_processing_stage, 0)] INFO com.tc.l2.objectserver.ReplicatedObjectManagerImpl - Removed 803623 objects from passive ObjectManager from last DGC from Active
2011-12-27 14:26:48,265 [WorkerThread(gc_delete_from_disk_stage, 0)] INFO com.tc.objectserver.persistence.db.DBPersistorImpl - Removed 5000 objects in 373 ms.
2011-12-27 14:26:51,951 [WorkerThread(gc_delete_from_disk_stage, 0)] INFO com.tc.objectserver.persistence.db.DBPersistorImpl - Removed 5000 objects in 688 ms.
2011-12-27 14:26:52,424 [WorkerThread(gc_delete_from_disk_stage, 0)] INFO com.tc.objectserver.persistence.db.DBPersistorImpl - Removed 5000 objects in 473 ms.
2011-12-27 14:26:54,891 [WorkerThread(gc_delete_from_disk_stage, 0)] INFO com.tc.objectserver.persistence.db.DBPersistorImpl - Removed 5000 objects in 546 ms.
2011-12-27 14:26:55,728 [WorkerThread(gc_delete_from_disk_stage, 0)] INFO com.tc.objectserver.persistence.db.DBPersistorImpl - Removed 5000 objects in 544 ms.
2011-12-27 14:27:00,231 [WorkerThread(gc_delete_from_disk_stage, 0)] INFO com.tc.objectserver.persistence.db.DBPersistorImpl - Removed 5000 objects in 3282 ms.
2011-12-27 14:27:00,831 [WorkerThread(gc_delete_from_disk_stage, 0)] INFO com.tc.objectserver.persistence.db.DBPersistorImpl - Removed 5000 objects in 600 ms.
2011-12-27 14:27:02,195 [WorkerThread(gc_delete_from_disk_stage, 0)] INFO com.tc.objectserver.persistence.db.DBPersistorImpl - Removed 5000 objects in 349 ms.
2011-12-27 14:27:04,554 [WorkerThread(gc_delete_from_disk_stage, 0)] INFO com.tc.objectserver.persistence.db.DBPersistorImpl - Removed 5000 objects in 534 ms.
2011-12-27 14:27:06,659 [WorkerThread(gc_delete_from_disk_stage, 0)] INFO com.tc.objectserver.persistence.db.DBPersistorImpl - Removed 5000 objects in 2105 ms.
2011-12-27 14:27:07,222 [WorkerThread(gc_delete_from_disk_stage, 0)] INFO com.tc.objectserver.persistence.db.DBPersistorImpl - Removed 5000 objects in 563 ms.
2011-12-27 14:27:07,632 [WorkerThread(gc_delete_from_disk_stage, 0)] INFO com.tc.objectserver.persistence.db.DBPersistorImpl - Removed 5000 objects in 410 ms.
2011-12-27 14:27:08,035 [WorkerThread(gc_delete_from_disk_stage, 0)] INFO com.tc.objectserver.persistence.db.DBPersistorImpl - Removed 5000 objects in 403 ms.
2011-12-27 14:27:08,587 [WorkerThread(gc_delete_from_disk_stage, 0)] INFO com.tc.objectserver.persistence.db.DBPersistorImpl - Removed 5000 objects in 305 ms.
2011-12-27 14:27:09,402 [WorkerThread(gc_delete_from_disk_stage, 0)] INFO com.tc.objectserver.persistence.db.DBPersistorImpl - Removed 5000 objects in 555 ms.
2011-12-27 14:27:12,216 [WorkerThread(gc_delete_from_disk_stage, 0)] INFO com.tc.objectserver.persistence.db.DBPersistorImpl - Removed 5000 objects in 2814 ms.
2011-12-27 14:27:15,160 [WorkerThread(gc_delete_from_disk_stage, 0)] INFO com.tc.objectserver.persistence.db.DBPersistorImpl - Removed 5000 objects in 568 ms.
2011-12-27 14:27:15,778 [WorkerThread(gc_delete_from_disk_stage, 0)] INFO com.tc.objectserver.persistence.db.DBPersistorImpl - Removed 5000 objects in 432 ms.
2011-12-27 14:27:17,121 [WorkerThread(gc_delete_from_disk_stage, 0)] INFO com.tc.objectserver.persistence.db.DBPersistorImpl - Removed 5000 objects in 335 ms.
2011-12-27 14:27:18,668 [WorkerThread(gc_delete_from_disk_stage, 0)] INFO com.tc.objectserver.persistence.db.DBPersistorImpl - Removed 5000 objects in 311 ms.
2011-12-27 14:27:20,530 [WorkerThread(gc_delete_from_disk_stage, 0)] INFO com.tc.objectserver.persistence.db.DBPersistorImpl - Removed 5000 objects in 467 ms.
2011-12-27 14:27:22,890 [WorkerThread(gc_delete_from_disk_stage, 0)] INFO com.tc.objectserver.persistence.db.DBPersistorImpl - Removed 5000 objects in 340 ms.
2011-12-27 14:38:55,351 [Statistics Logger] INFO com.terracottatech.dso - memory free : 625607832
2011-12-27 14:38:55,351 [Statistics Logger] INFO com.terracottatech.dso - memory used : 1475214184
2011-12-27 14:38:55,351 [Statistics Logger] INFO com.terracottatech.dso - memory max : 2100822016
2011-12-27 14:53:55,353 [Statistics Logger] INFO com.terracottatech.dso - memory free : 1031827920
2011-12-27 14:53:55,353 [Statistics Logger] INFO com.terracottatech.dso - memory used : 1032490544
2011-12-27 14:53:55,353 [Statistics Logger] INFO com.terracottatech.dso - memory max : 2064318464
2011-12-27 15:08:55,342 [Statistics Logger] INFO com.terracottatech.dso - memory free : 313031296
2011-12-27 15:08:55,343 [Statistics Logger] INFO com.terracottatech.dso - memory used : 1686734208
2011-12-27 15:08:55,343 [Statistics Logger] INFO com.terracottatech.dso - memory max : 1999765504
2011-12-27 15:23:55,344 [Statistics Logger] INFO com.terracottatech.dso - memory free : 535220064
2011-12-27 15:23:55,345 [Statistics Logger] INFO com.terracottatech.dso - memory used : 1474637984
2011-12-27 15:23:55,345 [Statistics Logger] INFO com.terracottatech.dso - memory max : 2009858048
2011-12-27 15:28:14,851 [WorkerThread(gc_result_processing_stage, 0)] INFO com.tc.l2.handler.GCResultHandler - Scheduling to process GC results when all current transactions are completed : DGCResultMessage@268870775 : DGC Info = GarbageCollectionInfo [ Iteration = 347 ] = type = full, startTime = 1325021204878 begin object count = 2459845 end object count = 1221996 markStageTime = 88915 pauseStageTime = 264 totalMarkCycleTime = 89916 candiate garabage count = 1265222 actual garbage count = 1265222 pre rescue count = 1837891 rescue1Time = 54057 rescue 1 Count = 1265222 rescue2Time = 264 Result size = 1265222
2011-12-27 15:28:15,938 [WorkerThread(gc_result_processing_stage, 0)] INFO com.tc.l2.objectserver.ReplicatedObjectManagerImpl - Removed 1265222 objects from passive ObjectManager from last DGC from Active
2011-12-27 15:28:17,758 [WorkerThread(gc_delete_from_disk_stage, 0)] INFO com.tc.objectserver.persistence.db.DBPersistorImpl - Removed 5000 objects in 392 ms.
2011-12-27 15:28:18,086 [WorkerThread(gc_delete_from_disk_stage, 0)] INFO com.tc.objectserver.persistence.db.DBPersistorImpl - Removed 5000 objects in 327 ms.
2011-12-27 15:28:18,457 [WorkerThread(gc_delete_from_disk_stage, 0)] INFO com.tc.objectserver.persistence.db.DBPersistorImpl - Removed 5000 objects in 371 ms.
2011-12-27 15:28:18,911 [WorkerThread(gc_delete_from_disk_stage, 0)] INFO com.tc.objectserver.persistence.db.DBPersistorImpl - Removed 5000 objects in 454 ms.
2011-12-27 15:28:19,922 [WorkerThread(gc_delete_from_disk_stage, 0)] INFO com.tc.objectserver.persistence.db.DBPersistorImpl - Removed 5000 objects in 472 ms.
2011-12-27 15:28:20,494 [WorkerThread(gc_delete_from_disk_stage, 0)] INFO com.tc.objectserver.persistence.db.DBPersistorImpl - Removed 5000 objects in 340 ms.
2011-12-27 15:28:20,844 [WorkerThread(gc_delete_from_disk_stage, 0)] INFO com.tc.objectserver.persistence.db.DBPersistorImpl - Removed 5000 objects in 350 ms.
2011-12-27 15:28:22,204 [WorkerThread(gc_delete_from_disk_stage, 0)] INFO com.tc.objectserver.persistence.db.DBPersistorImpl - Removed 5000 objects in 402 ms.
2011-12-27 15:28:22,533 [WorkerThread(gc_delete_from_disk_stage, 0)] INFO com.tc.objectserver.persistence.db.DBPersistorImpl - Removed 5000 objects in 329 ms.
2011-12-27 15:28:23,195 [WorkerThread(gc_delete_from_disk_stage, 0)] INFO com.tc.objectserver.persistence.db.DBPersistorImpl - Removed 5000 objects in 363 ms.
2011-12-27 15:28:24,775 [WorkerThread(gc_delete_from_disk_stage, 0)] INFO com.tc.objectserver.persistence.db.DBPersistorImpl - Removed 5000 objects in 325 ms.
2011-12-27 15:28:25,548 [WorkerThread(gc_delete_from_disk_stage, 0)] INFO com.tc.objectserver.persistence.db.DBPersistorImpl - Removed 5000 objects in 617 ms.
2011-12-27 15:28:29,632 [WorkerThread(gc_delete_from_disk_stage, 0)] INFO com.tc.objectserver.persistence.db.DBPersistorImpl - Removed 5000 objects in 474 ms.
2011-12-27 15:28:30,712 [WorkerThread(gc_delete_from_disk_stage, 0)] INFO com.tc.objectserver.persistence.db.DBPersistorImpl - Removed 5000 objects in 1080 ms.
2011-12-27 15:28:31,174 [WorkerThread(gc_delete_from_disk_stage, 0)] INFO com.tc.objectserver.persistence.db.DBPersistorImpl - Removed 5000 objects in 462 ms.
2011-12-27 15:28:31,572 [WorkerThread(gc_delete_from_disk_stage, 0)] INFO com.tc.objectserver.persistence.db.DBPersistorImpl - Removed 5000 objects in 394 ms.
2011-12-27 15:28:33,003 [WorkerThread(gc_delete_from_disk_stage, 0)] INFO com.tc.objectserver.persistence.db.DBPersistorImpl - Removed 5000 objects in 1431 ms.
2011-12-27 15:28:33,572 [WorkerThread(gc_delete_from_disk_stage, 0)] INFO com.tc.objectserver.persistence.db.DBPersistorImpl - Removed 5000 objects in 569 ms.
2011-12-27 15:28:33,967 [WorkerThread(gc_delete_from_disk_stage, 0)] INFO com.tc.objectserver.persistence.db.DBPersistorImpl - Removed 5000 objects in 395 ms.
2011-12-27 15:28:34,595 [WorkerThread(gc_delete_from_disk_stage, 0)] INFO com.tc.objectserver.persistence.db.DBPersistorImpl - Removed 5000 objects in 359 ms.
2011-12-27 15:28:36,886 [WorkerThread(gc_delete_from_disk_stage, 0)] INFO com.tc.objectserver.persistence.db.DBPersistorImpl - Removed 5000 objects in 2290 ms.
2011-12-27 15:28:37,364 [WorkerThread(gc_delete_from_disk_stage, 0)] INFO com.tc.objectserver.persistence.db.DBPersistorImpl - Removed 5000 objects in 478 ms.
2011-12-27 15:28:38,717 [WorkerThread(gc_delete_from_disk_stage, 0)] INFO com.tc.objectserver.persistence.db.DBPersistorImpl - Removed 5000 objects in 501 ms.
2011-12-27 15:28:39,142 [WorkerThread(gc_delete_from_disk_stage, 0)] INFO com.tc.objectserver.persistence.db.DBPersistorImpl - Removed 5000 objects in 425 ms.
2011-12-27 15:28:39,701 [WorkerThread(gc_delete_from_disk_stage, 0)] INFO com.tc.objectserver.persistence.db.DBPersistorImpl - Removed 5000 objects in 346 ms.
2011-12-27 15:28:41,738 [WorkerThread(gc_delete_from_disk_stage, 0)] INFO com.tc.objectserver.persistence.db.DBPersistorImpl - Removed 5000 objects in 2036 ms.
2011-12-27 15:28:42,474 [WorkerThread(gc_delete_from_disk_stage, 0)] INFO com.tc.objectserver.persistence.db.DBPersistorImpl - Removed 5000 objects in 383 ms.
2011-12-27 15:28:43,234 [WorkerThread(gc_delete_from_disk_stage, 0)] INFO com.tc.objectserver.persistence.db.DBPersistorImpl - Removed 5000 objects in 464 ms.
2011-12-27 15:28:44,243 [WorkerThread(gc_delete_from_disk_stage, 0)] INFO com.tc.objectserver.persistence.db.DBPersistorImpl - Removed 5000 objects in 388 ms.
2011-12-27 15:28:46,610 [WorkerThread(gc_delete_from_disk_stage, 0)] INFO com.tc.objectserver.persistence.db.DBPersistorImpl - Removed 5000 objects in 2047 ms.
2011-12-27 15:28:51,707 [WorkerThread(gc_delete_from_disk_stage, 0)] INFO com.tc.objectserver.persistence.db.DBPersistorImpl - Removed 5000 objects in 356 ms.
2011-12-27 15:28:53,055 [WorkerThread(gc_delete_from_disk_stage, 0)] INFO com.tc.objectserver.persistence.db.DBPersistorImpl - Removed 5000 objects in 367 ms.
2011-12-27 15:28:53,415 [WorkerThread(gc_delete_from_disk_stage, 0)] INFO com.tc.objectserver.persistence.db.DBPersistorImpl - Removed 5000 objects in 360 ms.
2011-12-27 15:28:53,792 [WorkerThread(gc_delete_from_disk_stage, 0)] INFO com.tc.objectserver.persistence.db.DBPersistorImpl - Removed 5000 objects in 377 ms.
2011-12-27 15:28:54,273 [WorkerThread(gc_delete_from_disk_stage, 0)] INFO com.tc.objectserver.persistence.db.DBPersistorImpl - Removed 5000 objects in 481 ms.
2011-12-27 15:28:54,661 [WorkerThread(gc_delete_from_disk_stage, 0)] INFO com.tc.objectserver.persistence.db.DBPersistorImpl - Removed 5000 objects in 388 ms.
2011-12-27 15:28:56,568 [WorkerThread(gc_delete_from_disk_stage, 0)] INFO com.tc.objectserver.persistence.db.DBPersistorImpl - Removed 5000 objects in 1906 ms.
2011-12-27 15:29:00,284 [WorkerThread(gc_delete_from_disk_stage, 0)] INFO com.tc.objectserver.persistence.db.DBPersistorImpl - Removed 5000 objects in 3024 ms.
2011-12-27 15:29:01,565 [WorkerThread(gc_delete_from_disk_stage, 0)] INFO com.tc.objectserver.persistence.db.DBPersistorImpl - Removed 5000 objects in 897 ms.
2011-12-27 15:29:01,871 [WorkerThread(gc_delete_from_disk_stage, 0)] INFO com.tc.objectserver.persistence.db.DBPersistorImpl - Removed 5000 objects in 306 ms.
2011-12-27 15:29:02,199 [WorkerThread(gc_delete_from_disk_stage, 0)] INFO com.tc.objectserver.persistence.db.DBPersistorImpl - Removed 5000 objects in 328 ms.
2011-12-27 15:29:02,573 [WorkerThread(gc_delete_from_disk_stage, 0)] INFO com.tc.objectserver.persistence.db.DBPersistorImpl - Removed 5000 objects in 373 ms.
2011-12-27 15:29:02,891 [WorkerThread(gc_delete_from_disk_stage, 0)] INFO com.tc.objectserver.persistence.db.DBPersistorImpl - Removed 5000 objects in 318 ms.
2011-12-27 15:29:03,470 [WorkerThread(gc_delete_from_disk_stage, 0)] INFO com.tc.objectserver.persistence.db.DBPersistorImpl - Removed 5000 objects in 579 ms.
2011-12-27 15:29:06,711 [WorkerThread(gc_delete_from_disk_stage, 0)] INFO com.tc.objectserver.persistence.db.DBPersistorImpl - Removed 5000 objects in 1758 ms.
2011-12-27 15:29:10,354 [WorkerThread(gc_delete_from_disk_stage, 0)] INFO com.tc.objectserver.persistence.db.DBPersistorImpl - Removed 5000 objects in 650 ms.
2011-12-27 15:29:13,506 [WorkerThread(gc_delete_from_disk_stage, 0)] INFO com.tc.objectserver.persistence.db.DBPersistorImpl - Removed 5000 objects in 425 ms.
2011-12-27 15:29:15,036 [WorkerThread(gc_delete_from_disk_stage, 0)] INFO com.tc.objectserver.persistence.db.DBPersistorImpl - Removed 5000 objects in 367 ms.
2011-12-27 15:29:16,583 [WorkerThread(gc_delete_from_disk_stage, 0)] INFO com.tc.objectserver.persistence.db.DBPersistorImpl - Removed 5000 objects in 331 ms.
2011-12-27 15:38:55,351 [Statistics Logger] INFO com.terracottatech.dso - memory free : 160688504
2011-12-27 15:38:55,351 [Statistics Logger] INFO com.terracottatech.dso - memory used : 1937577608
2011-12-27 15:38:55,351 [Statistics Logger] INFO com.terracottatech.dso - memory max : 2098266112
2011-12-27 15:53:31,413 [WorkerThread(channel_life_cycle_stage, 0)] INFO com.tc.objectserver.handler.ChannelLifeCycleHandler - : Received transport disconnect. Shutting down client ClientID[2906]
2011-12-27 15:53:31,413 [WorkerThread(channel_life_cycle_stage, 0)] INFO com.tc.objectserver.persistence.inmemory.TransactionStoreImpl - shutdownClient() : Removing txns from DB : 0
2011-12-27 15:53:55,347 [Statistics Logger] INFO com.terracottatech.dso - memory free : 469274208
2011-12-27 15:53:55,347 [Statistics Logger] INFO com.terracottatech.dso - memory used : 1487303072
2011-12-27 15:53:55,347 [Statistics Logger] INFO com.terracottatech.dso - memory max : 1956577280
2011-12-27 15:54:06,466 [WorkerThread(channel_life_cycle_stage, 0)] INFO com.tc.objectserver.handler.ChannelLifeCycleHandler - : Received transport disconnect. Shutting down client ClientID[2907]
2011-12-27 15:54:06,466 [WorkerThread(channel_life_cycle_stage, 0)] INFO com.tc.objectserver.persistence.inmemory.TransactionStoreImpl - shutdownClient() : Removing txns from DB : 0
2011-12-27 15:54:06,486 [WorkerThread(channel_life_cycle_stage, 0)] INFO com.tc.objectserver.handler.ChannelLifeCycleHandler - : Received transport disconnect. Shutting down client ClientID[2905]
2011-12-27 15:54:06,486 [WorkerThread(channel_life_cycle_stage, 0)] INFO com.tc.objectserver.persistence.inmemory.TransactionStoreImpl - shutdownClient() : Removing txns from DB : 0
2011-12-27 15:54:06,489 [WorkerThread(channel_life_cycle_stage, 0)] INFO com.tc.objectserver.handler.ChannelLifeCycleHandler - : Received transport disconnect. Shutting down client ClientID[2904]
2011-12-27 15:54:06,489 [WorkerThread(channel_life_cycle_stage, 0)] INFO com.tc.objectserver.persistence.inmemory.TransactionStoreImpl - shutdownClient() : Removing txns from DB : 0
2011-12-27 16:08:55,343 [Statistics Logger] INFO com.terracottatech.dso - memory free : 567859304
2011-12-27 16:08:55,343 [Statistics Logger] INFO com.terracottatech.dso - memory used : 1375676312
2011-12-27 16:08:55,343 [Statistics Logger] INFO com.terracottatech.dso - memory max : 1943535616
2011-12-27 16:23:55,349 [Statistics Logger] INFO com.terracottatech.dso - memory free : 932241328
2011-12-27 16:23:55,349 [Statistics Logger] INFO com.terracottatech.dso - memory used : 1013260368
2011-12-27 16:23:55,350 [Statistics Logger] INFO com.terracottatech.dso - memory max : 1945501696
2011-12-27 16:29:52,572 [WorkerThread(gc_result_processing_stage, 0)] INFO com.tc.l2.handler.GCResultHandler - Scheduling to process GC results when all current transactions are completed : DGCResultMessage@1033906338 : DGC Info = GarbageCollectionInfo [ Iteration = 348 ] = type = full, startTime = 1325024894818 begin object count = 2314989 end object count = 1316073 markStageTime = 96755 pauseStageTime = 279 totalMarkCycleTime = 97564 candiate garabage count = 1020366 actual garbage count = 1020366 pre rescue count = 1701726 rescue1Time = 64967 rescue 1 Count = 1020366 rescue2Time = 279 Result size = 1020366
2011-12-27 16:29:53,536 [WorkerThread(gc_result_processing_stage, 0)] INFO com.tc.l2.objectserver.ReplicatedObjectManagerImpl - Removed 1020366 objects from passive ObjectManager from last DGC from Active
2011-12-27 16:29:55,631 [WorkerThread(gc_delete_from_disk_stage, 0)] INFO com.tc.objectserver.persistence.db.DBPersistorImpl - Removed 5000 objects in 388 ms.
2011-12-27 16:29:56,834 [WorkerThread(gc_delete_from_disk_stage, 0)] INFO com.tc.objectserver.persistence.db.DBPersistorImpl - Removed 5000 objects in 353 ms.
2011-12-27 16:29:58,581 [WorkerThread(gc_delete_from_disk_stage, 0)] INFO com.tc.objectserver.persistence.db.DBPersistorImpl - Removed 5000 objects in 356 ms.
2011-12-27 16:29:59,954 [WorkerThread(gc_delete_from_disk_stage, 0)] INFO com.tc.objectserver.persistence.db.DBPersistorImpl - Removed 5000 objects in 365 ms.
2011-12-27 16:30:00,532 [WorkerThread(gc_delete_from_disk_stage, 0)] INFO com.tc.objectserver.persistence.db.DBPersistorImpl - Removed 5000 objects in 341 ms.
2011-12-27 16:30:01,164 [WorkerThread(gc_delete_from_disk_stage, 0)] INFO com.tc.objectserver.persistence.db.DBPersistorImpl - Removed 5000 objects in 383 ms.
2011-12-27 16:30:05,476 [WorkerThread(gc_delete_from_disk_stage, 0)] INFO com.tc.objectserver.persistence.db.DBPersistorImpl - Removed 5000 objects in 1086 ms.
2011-12-27 16:30:06,688 [WorkerThread(gc_delete_from_disk_stage, 0)] INFO com.tc.objectserver.persistence.db.DBPersistorImpl - Removed 5000 objects in 434 ms.
2011-12-27 16:30:07,276 [WorkerThread(gc_delete_from_disk_stage, 0)] INFO com.tc.objectserver.persistence.db.DBPersistorImpl - Removed 5000 objects in 328 ms.
2011-12-27 16:30:08,028 [WorkerThread(gc_delete_from_disk_stage, 0)] INFO com.tc.objectserver.persistence.db.DBPersistorImpl - Removed 5000 objects in 467 ms.
2011-12-27 16:30:08,626 [WorkerThread(gc_delete_from_disk_stage, 0)] INFO com.tc.objectserver.persistence.db.DBPersistorImpl - Removed 5000 objects in 598 ms.
2011-12-27 16:30:11,478 [WorkerThread(gc_delete_from_disk_stage, 0)] INFO com.tc.objectserver.persistence.db.DBPersistorImpl - Removed 5000 objects in 2852 ms.
2011-12-27 16:30:11,844 [WorkerThread(gc_delete_from_disk_stage, 0)] INFO com.tc.objectserver.persistence.db.DBPersistorImpl - Removed 5000 objects in 365 ms.
2011-12-27 16:30:12,289 [WorkerThread(gc_delete_from_disk_stage, 0)] INFO com.tc.objectserver.persistence.db.DBPersistorImpl - Removed 5000 objects in 445 ms.
2011-12-27 16:30:13,143 [WorkerThread(gc_delete_from_disk_stage, 0)] INFO com.tc.objectserver.persistence.db.DBPersistorImpl - Removed 5000 objects in 329 ms.
2011-12-27 16:30:13,657 [WorkerThread(gc_delete_from_disk_stage, 0)] INFO com.tc.objectserver.persistence.db.DBPersistorImpl - Removed 5000 objects in 339 ms.
2011-12-27 16:30:14,383 [WorkerThread(gc_delete_from_disk_stage, 0)] INFO com.tc.objectserver.persistence.db.DBPersistorImpl - Removed 5000 objects in 352 ms.
2011-12-27 16:30:15,771 [WorkerThread(gc_delete_from_disk_stage, 0)] INFO com.tc.objectserver.persistence.db.DBPersistorImpl - Removed 5000 objects in 1388 ms.
2011-12-27 16:30:16,094 [WorkerThread(gc_delete_from_disk_stage, 0)] INFO com.tc.objectserver.persistence.db.DBPersistorImpl - Removed 5000 objects in 323 ms.
2011-12-27 16:30:18,088 [WorkerThread(gc_delete_from_disk_stage, 0)] INFO com.tc.objectserver.persistence.db.DBPersistorImpl - Removed 5000 objects in 327 ms.
2011-12-27 16:30:21,885 [WorkerThread(gc_delete_from_disk_stage, 0)] INFO com.tc.objectserver.persistence.db.DBPersistorImpl - Removed 5000 objects in 358 ms.
2011-12-27 16:30:25,221 [WorkerThread(gc_delete_from_disk_stage, 0)] INFO com.tc.objectserver.persistence.db.DBPersistorImpl - Removed 5000 objects in 3336 ms.
2011-12-27 16:30:25,705 [WorkerThread(gc_delete_from_disk_stage, 0)] INFO com.tc.objectserver.persistence.db.DBPersistorImpl - Removed 5000 objects in 309 ms.
2011-12-27 16:30:29,837 [WorkerThread(gc_delete_from_disk_stage, 0)] INFO com.tc.objectserver.persistence.db.DBPersistorImpl - Removed 5000 objects in 317 ms.
2011-12-27 16:30:31,397 [WorkerThread(gc_delete_from_disk_stage, 0)] INFO com.tc.objectserver.persistence.db.DBPersistorImpl - Removed 5000 objects in 1432 ms.
2011-12-27 16:30:31,936 [WorkerThread(gc_delete_from_disk_stage, 0)] INFO com.tc.objectserver.persistence.db.DBPersistorImpl - Removed 5000 objects in 389 ms.
2011-12-27 16:30:32,275 [WorkerThread(gc_delete_from_disk_stage, 0)] INFO com.tc.objectserver.persistence.db.DBPersistorImpl - Removed 5000 objects in 339 ms.
2011-12-27 16:30:32,692 [WorkerThread(gc_delete_from_disk_stage, 0)] INFO com.tc.objectserver.persistence.db.DBPersistorImpl - Removed 5000 objects in 417 ms.
2011-12-27 16:30:33,917 [WorkerThread(gc_delete_from_disk_stage, 0)] INFO com.tc.objectserver.persistence.db.DBPersistorImpl - Removed 5000 objects in 380 ms.
2011-12-27 16:30:34,984 [WorkerThread(gc_delete_from_disk_stage, 0)] INFO com.tc.objectserver.persistence.db.DBPersistorImpl - Removed 5000 objects in 332 ms.
2011-12-27 16:30:37,159 [WorkerThread(gc_delete_from_disk_stage, 0)] INFO com.tc.objectserver.persistence.db.DBPersistorImpl - Removed 5000 objects in 2175 ms.
2011-12-27 16:30:37,871 [WorkerThread(gc_delete_from_disk_stage, 0)] INFO com.tc.objectserver.persistence.db.DBPersistorImpl - Removed 5000 objects in 491 ms.
2011-12-27 16:30:39,109 [WorkerThread(gc_delete_from_disk_stage, 0)] INFO com.tc.objectserver.persistence.db.DBPersistorImpl - Removed 5000 objects in 1238 ms.
2011-12-27 16:30:39,463 [WorkerThread(gc_delete_from_disk_stage, 0)] INFO com.tc.objectserver.persistence.db.DBPersistorImpl - Removed 5000 objects in 354 ms.
2011-12-27 16:30:39,825 [WorkerThread(gc_delete_from_disk_stage, 0)] INFO com.tc.objectserver.persistence.db.DBPersistorImpl - Removed 5000 objects in 362 ms.
2011-12-27 16:30:41,329 [WorkerThread(gc_delete_from_disk_stage, 0)] INFO com.tc.objectserver.persistence.db.DBPersistorImpl - Removed 5000 objects in 1504 ms.
2011-12-27 16:30:41,880 [WorkerThread(gc_delete_from_disk_stage, 0)] INFO com.tc.objectserver.persistence.db.DBPersistorImpl - Removed 5000 objects in 325 ms.
2011-12-27 16:30:42,724 [WorkerThread(gc_delete_from_disk_stage, 0)] INFO com.tc.objectserver.persistence.db.DBPersistorImpl - Removed 5000 objects in 371 ms.
2011-12-27 16:30:45,300 [WorkerThread(gc_delete_from_disk_stage, 0)] INFO com.tc.objectserver.persistence.db.DBPersistorImpl - Removed 5000 objects in 352 ms.
2011-12-27 16:38:55,345 [Statistics Logger] INFO com.terracottatech.dso - memory free : 541713064
2011-12-27 16:38:55,345 [Statistics Logger] INFO com.terracottatech.dso - memory used : 1547771224
2011-12-27 16:38:55,345 [Statistics Logger] INFO com.terracottatech.dso - memory max : 2089484288
2011-12-27 16:53:55,342 [Statistics Logger] INFO com.terracottatech.dso - memory free : 425399896
2011-12-27 16:53:55,342 [Statistics Logger] INFO com.terracottatech.dso - memory used : 1628760488
2011-12-27 16:53:55,342 [Statistics Logger] INFO com.terracottatech.dso - memory max : 2054160384
2011-12-27 17:08:55,348 [Statistics Logger] INFO com.terracottatech.dso - memory free : 407498160
2011-12-27 17:08:55,349 [Statistics Logger] INFO com.terracottatech.dso - memory used : 1501434448
2011-12-27 17:08:55,349 [Statistics Logger] INFO com.terracottatech.dso - memory max : 1908932608
2011-12-27 17:23:55,345 [Statistics Logger] INFO com.terracottatech.dso - memory free : 691004792
2011-12-27 17:23:55,345 [Statistics Logger] INFO com.terracottatech.dso - memory used : 1217927816
2011-12-27 17:23:55,345 [Statistics Logger] INFO com.terracottatech.dso - memory max : 1908932608
2011-12-27 17:30:40,346 [WorkerThread(gc_result_processing_stage, 0)] INFO com.tc.l2.handler.GCResultHandler - Scheduling to process GC results when all current transactions are completed : DGCResultMessage@661751269 : DGC Info = GarbageCollectionInfo [ Iteration = 349 ] = type = full, startTime = 1325028592416 begin object count = 1884345 end object count = 804860 markStageTime = 47067 pauseStageTime = 182 totalMarkCycleTime = 47833 candiate garabage count = 1086085 actual garbage count = 1086085 pre rescue count = 1449874 rescue1Time = 27133 rescue 1 Count = 1086085 rescue2Time = 182 Result size = 1086085
2011-12-27 17:30:41,632 [WorkerThread(gc_result_processing_stage, 0)] INFO com.tc.l2.objectserver.ReplicatedObjectManagerImpl - Removed 1086085 objects from passive ObjectManager from last DGC from Active
2011-12-27 17:30:43,146 [WorkerThread(gc_delete_from_disk_stage, 0)] INFO com.tc.objectserver.persistence.db.DBPersistorImpl - Removed 5000 objects in 421 ms.
2011-12-27 17:30:43,832 [WorkerThread(gc_delete_from_disk_stage, 0)] INFO com.tc.objectserver.persistence.db.DBPersistorImpl - Removed 5000 objects in 395 ms.
2011-12-27 17:30:47,246 [WorkerThread(gc_delete_from_disk_stage, 0)] INFO com.tc.objectserver.persistence.db.DBPersistorImpl - Removed 5000 objects in 387 ms.
2011-12-27 17:30:47,643 [WorkerThread(gc_delete_from_disk_stage, 0)] INFO com.tc.objectserver.persistence.db.DBPersistorImpl - Removed 5000 objects in 397 ms.
2011-12-27 17:30:51,188 [WorkerThread(gc_delete_from_disk_stage, 0)] INFO com.tc.objectserver.persistence.db.DBPersistorImpl - Removed 5000 objects in 433 ms.
2011-12-27 17:30:51,526 [WorkerThread(gc_delete_from_disk_stage, 0)] INFO com.tc.objectserver.persistence.db.DBPersistorImpl - Removed 5000 objects in 337 ms.
2011-12-27 17:30:52,201 [WorkerThread(gc_delete_from_disk_stage, 0)] INFO com.tc.objectserver.persistence.db.DBPersistorImpl - Removed 5000 objects in 414 ms.
2011-12-27 17:30:55,119 [WorkerThread(gc_delete_from_disk_stage, 0)] INFO com.tc.objectserver.persistence.db.DBPersistorImpl - Removed 5000 objects in 2503 ms.
2011-12-27 17:30:57,643 [WorkerThread(gc_delete_from_disk_stage, 0)] INFO com.tc.objectserver.persistence.db.DBPersistorImpl - Removed 5000 objects in 310 ms.
2011-12-27 17:30:58,331 [WorkerThread(gc_delete_from_disk_stage, 0)] INFO com.tc.objectserver.persistence.db.DBPersistorImpl - Removed 5000 objects in 506 ms.
2011-12-27 17:30:58,707 [WorkerThread(gc_delete_from_disk_stage, 0)] INFO com.tc.objectserver.persistence.db.DBPersistorImpl - Removed 5000 objects in 376 ms.
2011-12-27 17:30:59,545 [WorkerThread(gc_delete_from_disk_stage, 0)] INFO com.tc.objectserver.persistence.db.DBPersistorImpl - Removed 5000 objects in 838 ms.
2011-12-27 17:31:00,033 [WorkerThread(gc_delete_from_disk_stage, 0)] INFO com.tc.objectserver.persistence.db.DBPersistorImpl - Removed 5000 objects in 488 ms.
2011-12-27 17:31:00,366 [WorkerThread(gc_delete_from_disk_stage, 0)] INFO com.tc.objectserver.persistence.db.DBPersistorImpl - Removed 5000 objects in 333 ms.
2011-12-27 17:31:01,859 [WorkerThread(gc_delete_from_disk_stage, 0)] INFO com.tc.objectserver.persistence.db.DBPersistorImpl - Removed 5000 objects in 1493 ms.
2011-12-27 17:31:02,437 [WorkerThread(gc_delete_from_disk_stage, 0)] INFO com.tc.objectserver.persistence.db.DBPersistorImpl - Removed 5000 objects in 316 ms.
2011-12-27 17:31:02,765 [WorkerThread(gc_delete_from_disk_stage, 0)] INFO com.tc.objectserver.persistence.db.DBPersistorImpl - Removed 5000 objects in 328 ms.
2011-12-27 17:31:04,239 [WorkerThread(gc_delete_from_disk_stage, 0)] INFO com.tc.objectserver.persistence.db.DBPersistorImpl - Removed 5000 objects in 348 ms.
2011-12-27 17:31:07,657 [WorkerThread(gc_delete_from_disk_stage, 0)] INFO com.tc.objectserver.persistence.db.DBPersistorImpl - Removed 5000 objects in 2433 ms.
2011-12-27 17:31:13,337 [WorkerThread(gc_delete_from_disk_stage, 0)] INFO com.tc.objectserver.persistence.db.DBPersistorImpl - Removed 5000 objects in 440 ms.
2011-12-27 17:31:14,387 [WorkerThread(gc_delete_from_disk_stage, 0)] INFO com.tc.objectserver.persistence.db.DBPersistorImpl - Removed 5000 objects in 343 ms.
2011-12-27 17:31:14,822 [WorkerThread(gc_delete_from_disk_stage, 0)] INFO com.tc.objectserver.persistence.db.DBPersistorImpl - Removed 5000 objects in 435 ms.
2011-12-27 17:31:16,124 [WorkerThread(gc_delete_from_disk_stage, 0)] INFO com.tc.objectserver.persistence.db.DBPersistorImpl - Removed 5000 objects in 600 ms.
2011-12-27 17:31:20,756 [WorkerThread(gc_delete_from_disk_stage, 0)] INFO com.tc.objectserver.persistence.db.DBPersistorImpl - Removed 5000 objects in 599 ms.
2011-12-27 17:31:21,115 [WorkerThread(gc_delete_from_disk_stage, 0)] INFO com.tc.objectserver.persistence.db.DBPersistorImpl - Removed 5000 objects in 359 ms.
2011-12-27 17:31:22,123 [WorkerThread(gc_delete_from_disk_stage, 0)] INFO com.tc.objectserver.persistence.db.DBPersistorImpl - Removed 5000 objects in 466 ms.
2011-12-27 17:31:22,567 [WorkerThread(gc_delete_from_disk_stage, 0)] INFO com.tc.objectserver.persistence.db.DBPersistorImpl - Removed 5000 objects in 444 ms.
2011-12-27 17:31:23,070 [WorkerThread(gc_delete_from_disk_stage, 0)] INFO com.tc.objectserver.persistence.db.DBPersistorImpl - Removed 5000 objects in 503 ms.
2011-12-27 17:31:23,529 [WorkerThread(gc_delete_from_disk_stage, 0)] INFO com.tc.objectserver.persistence.db.DBPersistorImpl - Removed 5000 objects in 459 ms.
2011-12-27 17:31:24,647 [WorkerThread(gc_delete_from_disk_stage, 0)] INFO com.tc.objectserver.persistence.db.DBPersistorImpl - Removed 5000 objects in 359 ms.
2011-12-27 17:31:25,366 [WorkerThread(gc_delete_from_disk_stage, 0)] INFO com.tc.objectserver.persistence.db.DBPersistorImpl - Removed 5000 objects in 539 ms.
2011-12-27 17:31:28,442 [WorkerThread(gc_delete_from_disk_stage, 0)] INFO com.tc.objectserver.persistence.db.DBPersistorImpl - Removed 5000 objects in 3075 ms.
2011-12-27 17:38:55,351 [Statistics Logger] INFO com.terracottatech.dso - memory free : 504279704
2011-12-27 17:38:55,351 [Statistics Logger] INFO com.terracottatech.dso - memory used : 1582845288
2011-12-27 17:38:55,351 [Statistics Logger] INFO com.terracottatech.dso - memory max : 2087124992
2011-12-27 17:53:55,347 [Statistics Logger] INFO com.terracottatech.dso - memory free : 509887488
2011-12-27 17:53:55,347 [Statistics Logger] INFO com.terracottatech.dso - memory used : 1575009280
2011-12-27 17:53:55,347 [Statistics Logger] INFO com.terracottatech.dso - memory max : 2084896768
2011-12-27 18:08:55,343 [Statistics Logger] INFO com.terracottatech.dso - memory free : 525272680
2011-12-27 18:08:55,344 [Statistics Logger] INFO com.terracottatech.dso - memory used : 1483209112
2011-12-27 18:08:55,344 [Statistics Logger] INFO com.terracottatech.dso - memory max : 2008481792
2011-12-27 18:23:55,343 [Statistics Logger] INFO com.terracottatech.dso - memory free : 793329752
2011-12-27 18:23:55,344 [Statistics Logger] INFO com.terracottatech.dso - memory used : 1135984552
2011-12-27 18:23:55,344 [Statistics Logger] INFO com.terracottatech.dso - memory max : 1929314304
2011-12-27 18:31:21,981 [WorkerThread(gc_result_processing_stage, 0)] INFO com.tc.l2.handler.GCResultHandler - Scheduling to process GC results when all current transactions are completed : DGCResultMessage@1502722280 : DGC Info = GarbageCollectionInfo [ Iteration = 350 ] = type = full, startTime = 1325032240265 begin object count = 1330491 end object count = 730960 markStageTime = 41151 pauseStageTime = 166 totalMarkCycleTime = 41643 candiate garabage count = 605715 actual garbage count = 605715 pre rescue count = 878210 rescue1Time = 19634 rescue 1 Count = 605715 rescue2Time = 166 Result size = 605715
2011-12-27 18:31:22,584 [WorkerThread(gc_result_processing_stage, 0)] INFO com.tc.l2.objectserver.ReplicatedObjectManagerImpl - Removed 605715 objects from passive ObjectManager from last DGC from Active
2011-12-27 18:31:23,428 [WorkerThread(gc_delete_from_disk_stage, 0)] INFO com.tc.objectserver.persistence.db.DBPersistorImpl - Removed 5000 objects in 359 ms.
2011-12-27 18:31:25,719 [WorkerThread(gc_delete_from_disk_stage, 0)] INFO com.tc.objectserver.persistence.db.DBPersistorImpl - Removed 5000 objects in 360 ms.
2011-12-27 18:31:26,099 [WorkerThread(gc_delete_from_disk_stage, 0)] INFO com.tc.objectserver.persistence.db.DBPersistorImpl - Removed 5000 objects in 380 ms.
2011-12-27 18:31:27,919 [WorkerThread(gc_delete_from_disk_stage, 0)] INFO com.tc.objectserver.persistence.db.DBPersistorImpl - Removed 5000 objects in 398 ms.
2011-12-27 18:31:28,896 [WorkerThread(gc_delete_from_disk_stage, 0)] INFO com.tc.objectserver.persistence.db.DBPersistorImpl - Removed 5000 objects in 327 ms.
2011-12-27 18:31:29,829 [WorkerThread(gc_delete_from_disk_stage, 0)] INFO com.tc.objectserver.persistence.db.DBPersistorImpl - Removed 5000 objects in 431 ms.
2011-12-27 18:31:30,537 [WorkerThread(gc_delete_from_disk_stage, 0)] INFO com.tc.objectserver.persistence.db.DBPersistorImpl - Removed 5000 objects in 707 ms.
2011-12-27 18:31:31,408 [WorkerThread(gc_delete_from_disk_stage, 0)] INFO com.tc.objectserver.persistence.db.DBPersistorImpl - Removed 5000 objects in 871 ms.
2011-12-27 18:31:31,999 [WorkerThread(gc_delete_from_disk_stage, 0)] INFO com.tc.objectserver.persistence.db.DBPersistorImpl - Removed 5000 objects in 333 ms.
2011-12-27 18:31:32,351 [WorkerThread(gc_delete_from_disk_stage, 0)] INFO com.tc.objectserver.persistence.db.DBPersistorImpl - Removed 5000 objects in 350 ms.
2011-12-27 18:31:33,028 [WorkerThread(gc_delete_from_disk_stage, 0)] INFO com.tc.objectserver.persistence.db.DBPersistorImpl - Removed 5000 objects in 354 ms.
2011-12-27 18:31:34,396 [WorkerThread(gc_delete_from_disk_stage, 0)] INFO com.tc.objectserver.persistence.db.DBPersistorImpl - Removed 5000 objects in 303 ms.
2011-12-27 18:31:36,508 [WorkerThread(gc_delete_from_disk_stage, 0)] INFO com.tc.objectserver.persistence.db.DBPersistorImpl - Removed 5000 objects in 1534 ms.
2011-12-27 18:31:37,227 [WorkerThread(gc_delete_from_disk_stage, 0)] INFO com.tc.objectserver.persistence.db.DBPersistorImpl - Removed 5000 objects in 562 ms.
2011-12-27 18:31:37,561 [WorkerThread(gc_delete_from_disk_stage, 0)] INFO com.tc.objectserver.persistence.db.DBPersistorImpl - Removed 5000 objects in 334 ms.
2011-12-27 18:31:40,637 [WorkerThread(gc_delete_from_disk_stage, 0)] INFO com.tc.objectserver.persistence.db.DBPersistorImpl - Removed 5000 objects in 383 ms.
2011-12-27 18:31:41,060 [WorkerThread(gc_delete_from_disk_stage, 0)] INFO com.tc.objectserver.persistence.db.DBPersistorImpl - Removed 5000 objects in 314 ms.
2011-12-27 18:31:43,541 [WorkerThread(gc_delete_from_disk_stage, 0)] INFO com.tc.objectserver.persistence.db.DBPersistorImpl - Removed 5000 objects in 413 ms.
2011-12-27 18:31:44,716 [WorkerThread(gc_delete_from_disk_stage, 0)] INFO com.tc.objectserver.persistence.db.DBPersistorImpl - Removed 5000 objects in 377 ms.
2011-12-27 18:38:55,349 [Statistics Logger] INFO com.terracottatech.dso - memory free : 969443680
2011-12-27 18:38:55,350 [Statistics Logger] INFO com.terracottatech.dso - memory used : 1089828512
2011-12-27 18:38:55,350 [Statistics Logger] INFO com.terracottatech.dso - memory max : 2059272192
2011-12-27 18:53:55,347 [Statistics Logger] INFO com.terracottatech.dso - memory free : 532109608
2011-12-27 18:53:55,347 [Statistics Logger] INFO com.terracottatech.dso - memory used : 1553376984
2011-12-27 18:53:55,347 [Statistics Logger] INFO com.terracottatech.dso - memory max : 2085486592
2011-12-27 19:08:55,343 [Statistics Logger] INFO com.terracottatech.dso - memory free : 187860712
2011-12-27 19:08:55,343 [Statistics Logger] INFO com.terracottatech.dso - memory used : 1894152472
2011-12-27 19:08:55,343 [Statistics Logger] INFO com.terracottatech.dso - memory max : 2082013184
2011-12-27 19:23:55,349 [Statistics Logger] INFO com.terracottatech.dso - memory free : 771943616
2011-12-27 19:23:55,349 [Statistics Logger] INFO com.terracottatech.dso - memory used : 1266946880
2011-12-27 19:23:55,349 [Statistics Logger] INFO com.terracottatech.dso - memory max : 2038890496
2011-12-27 19:32:15,836 [WorkerThread(gc_result_processing_stage, 0)] INFO com.tc.l2.handler.GCResultHandler - Scheduling to process GC results when all current transactions are completed : DGCResultMessage@347390510 : DGC Info = GarbageCollectionInfo [ Iteration = 351 ] = type = full, startTime = 1325035881945 begin object count = 1390969 end object count = 886732 markStageTime = 53333 pauseStageTime = 195 totalMarkCycleTime = 53818 candiate garabage count = 518474 actual garbage count = 518474 pre rescue count = 812928 rescue1Time = 24819 rescue 1 Count = 518474 rescue2Time = 195 Result size = 518474
2011-12-27 19:32:16,284 [WorkerThread(gc_result_processing_stage, 0)] INFO com.tc.l2.objectserver.ReplicatedObjectManagerImpl - Removed 518474 objects from passive ObjectManager from last DGC from Active
2011-12-27 19:32:17,543 [WorkerThread(gc_delete_from_disk_stage, 0)] INFO com.tc.objectserver.persistence.db.DBPersistorImpl - Removed 5000 objects in 466 ms.
2011-12-27 19:32:20,862 [WorkerThread(gc_delete_from_disk_stage, 0)] INFO com.tc.objectserver.persistence.db.DBPersistorImpl - Removed 5000 objects in 353 ms.
2011-12-27 19:32:22,188 [WorkerThread(gc_delete_from_disk_stage, 0)] INFO com.tc.objectserver.persistence.db.DBPersistorImpl - Removed 5000 objects in 910 ms.
2011-12-27 19:32:26,482 [WorkerThread(gc_delete_from_disk_stage, 0)] INFO com.tc.objectserver.persistence.db.DBPersistorImpl - Removed 5000 objects in 301 ms.
2011-12-27 19:32:27,666 [WorkerThread(gc_delete_from_disk_stage, 0)] INFO com.tc.objectserver.persistence.db.DBPersistorImpl - Removed 5000 objects in 304 ms.
2011-12-27 19:32:29,248 [WorkerThread(gc_delete_from_disk_stage, 0)] INFO com.tc.objectserver.persistence.db.DBPersistorImpl - Removed 5000 objects in 465 ms.
2011-12-27 19:32:29,608 [WorkerThread(gc_delete_from_disk_stage, 0)] INFO com.tc.objectserver.persistence.db.DBPersistorImpl - Removed 5000 objects in 360 ms.
2011-12-27 19:32:30,438 [WorkerThread(gc_delete_from_disk_stage, 0)] INFO com.tc.objectserver.persistence.db.DBPersistorImpl - Removed 5000 objects in 409 ms.
2011-12-27 19:32:30,983 [WorkerThread(gc_delete_from_disk_stage, 0)] INFO com.tc.objectserver.persistence.db.DBPersistorImpl - Removed 5000 objects in 545 ms.
2011-12-27 19:32:33,608 [WorkerThread(gc_delete_from_disk_stage, 0)] INFO com.tc.objectserver.persistence.db.DBPersistorImpl - Removed 5000 objects in 2222 ms.
2011-12-27 19:32:33,948 [WorkerThread(gc_delete_from_disk_stage, 0)] INFO com.tc.objectserver.persistence.db.DBPersistorImpl - Removed 5000 objects in 339 ms.
2011-12-27 19:32:34,291 [WorkerThread(gc_delete_from_disk_stage, 0)] INFO com.tc.objectserver.persistence.db.DBPersistorImpl - Removed 5000 objects in 343 ms.
2011-12-27 19:32:34,809 [WorkerThread(gc_delete_from_disk_stage, 0)] INFO com.tc.objectserver.persistence.db.DBPersistorImpl - Removed 5000 objects in 517 ms.
2011-12-27 19:32:35,469 [WorkerThread(gc_delete_from_disk_stage, 0)] INFO com.tc.objectserver.persistence.db.DBPersistorImpl - Removed 5000 objects in 660 ms.
2011-12-27 19:38:55,352 [Statistics Logger] INFO com.terracottatech.dso - memory free : 1046575296
2011-12-27 19:38:55,352 [Statistics Logger] INFO com.terracottatech.dso - memory used : 1033209664
2011-12-27 19:38:55,352 [Statistics Logger] INFO com.terracottatech.dso - memory max : 2079784960
2011-12-27 19:53:55,342 [Statistics Logger] INFO com.terracottatech.dso - memory free : 429325304
2011-12-27 19:53:55,342 [Statistics Logger] INFO com.terracottatech.dso - memory used : 1673266184
2011-12-27 19:53:55,342 [Statistics Logger] INFO com.terracottatech.dso - memory max : 2102591488
2011-12-27 20:08:55,348 [Statistics Logger] INFO com.terracottatech.dso - memory free : 1135465464
2011-12-27 20:08:55,348 [Statistics Logger] INFO com.terracottatech.dso - memory used : 956705800
2011-12-27 20:08:55,348 [Statistics Logger] INFO com.terracottatech.dso - memory max : 2092171264
2011-12-27 20:23:55,354 [Statistics Logger] INFO com.terracottatech.dso - memory free : 854377144
2011-12-27 20:23:55,354 [Statistics Logger] INFO com.terracottatech.dso - memory used : 1246510408
2011-12-27 20:23:55,354 [Statistics Logger] INFO com.terracottatech.dso - memory max : 2100887552
2011-12-27 20:33:35,760 [WorkerThread(gc_result_processing_stage, 0)] INFO com.tc.l2.handler.GCResultHandler - Scheduling to process GC results when all current transactions are completed : DGCResultMessage@1756380682 : DGC Info = GarbageCollectionInfo [ Iteration = 352 ] = type = full, startTime = 1325039535778 begin object count = 1830242 end object count = 1189906 markStageTime = 79338 pauseStageTime = 241 totalMarkCycleTime = 79939 candiate garabage count = 660241 actual garbage count = 660241 pre rescue count = 1247507 rescue1Time = 48216 rescue 1 Count = 660241 rescue2Time = 241 Result size = 660241
2011-12-27 20:33:36,309 [WorkerThread(gc_result_processing_stage, 0)] INFO com.tc.l2.objectserver.ReplicatedObjectManagerImpl - Removed 660241 objects from passive ObjectManager from last DGC from Active
2011-12-27 20:33:40,490 [WorkerThread(gc_delete_from_disk_stage, 0)] INFO com.tc.objectserver.persistence.db.DBPersistorImpl - Removed 5000 objects in 2922 ms.
2011-12-27 20:33:44,927 [WorkerThread(gc_delete_from_disk_stage, 0)] INFO com.tc.objectserver.persistence.db.DBPersistorImpl - Removed 5000 objects in 385 ms.
2011-12-27 20:33:45,963 [WorkerThread(gc_delete_from_disk_stage, 0)] INFO com.tc.objectserver.persistence.db.DBPersistorImpl - Removed 5000 objects in 475 ms.
2011-12-27 20:33:46,965 [WorkerThread(gc_delete_from_disk_stage, 0)] INFO com.tc.objectserver.persistence.db.DBPersistorImpl - Removed 5000 objects in 479 ms.
2011-12-27 20:33:48,662 [WorkerThread(gc_delete_from_disk_stage, 0)] INFO com.tc.objectserver.persistence.db.DBPersistorImpl - Removed 5000 objects in 344 ms.
2011-12-27 20:33:50,748 [WorkerThread(gc_delete_from_disk_stage, 0)] INFO com.tc.objectserver.persistence.db.DBPersistorImpl - Removed 5000 objects in 419 ms.
2011-12-27 20:33:51,762 [WorkerThread(gc_delete_from_disk_stage, 0)] INFO com.tc.objectserver.persistence.db.DBPersistorImpl - Removed 5000 objects in 774 ms.
2011-12-27 20:33:53,384 [WorkerThread(gc_delete_from_disk_stage, 0)] INFO com.tc.objectserver.persistence.db.DBPersistorImpl - Removed 5000 objects in 327 ms.
2011-12-27 20:33:55,289 [WorkerThread(gc_delete_from_disk_stage, 0)] INFO com.tc.objectserver.persistence.db.DBPersistorImpl - Removed 5000 objects in 418 ms.
2011-12-27 20:33:57,660 [WorkerThread(gc_delete_from_disk_stage, 0)] INFO com.tc.objectserver.persistence.db.DBPersistorImpl - Removed 5000 objects in 1941 ms.
2011-12-27 20:33:59,411 [WorkerThread(gc_delete_from_disk_stage, 0)] INFO com.tc.objectserver.persistence.db.DBPersistorImpl - Removed 5000 objects in 324 ms.
2011-12-27 20:34:03,503 [WorkerThread(gc_delete_from_disk_stage, 0)] INFO com.tc.objectserver.persistence.db.DBPersistorImpl - Removed 5000 objects in 2762 ms.
2011-12-27 20:34:03,842 [WorkerThread(gc_delete_from_disk_stage, 0)] INFO com.tc.objectserver.persistence.db.DBPersistorImpl - Removed 5000 objects in 339 ms.
2011-12-27 20:38:55,352 [Statistics Logger] INFO com.terracottatech.dso - memory free : 687376504
2011-12-27 20:38:55,354 [Statistics Logger] INFO com.terracottatech.dso - memory used : 1408333704
2011-12-27 20:38:55,354 [Statistics Logger] INFO com.terracottatech.dso - memory max : 2095710208
2011-12-27 20:53:55,349 [Statistics Logger] INFO com.terracottatech.dso - memory free : 1132610800
2011-12-27 20:53:55,349 [Statistics Logger] INFO com.terracottatech.dso - memory used : 974961424
2011-12-27 20:53:55,349 [Statistics Logger] INFO com.terracottatech.dso - memory max : 2107572224
2011-12-27 21:08:55,342 [Statistics Logger] INFO com.terracottatech.dso - memory free : 900354880
2011-12-27 21:08:55,342 [Statistics Logger] INFO com.terracottatech.dso - memory used : 1199942848
2011-12-27 21:08:55,342 [Statistics Logger] INFO com.terracottatech.dso - memory max : 2100297728
2011-12-27 21:23:55,341 [Statistics Logger] INFO com.terracottatech.dso - memory free : 1111817880
2011-12-27 21:23:55,341 [Statistics Logger] INFO com.terracottatech.dso - memory used : 980746600
2011-12-27 21:23:55,341 [Statistics Logger] INFO com.terracottatech.dso - memory max : 2092564480
2011-12-27 21:34:41,310 [WorkerThread(gc_result_processing_stage, 0)] INFO com.tc.l2.handler.GCResultHandler - Scheduling to process GC results when all current transactions are completed : DGCResultMessage@1893072572 : DGC Info = GarbageCollectionInfo [ Iteration = 353 ] = type = full, startTime = 1325043215741 begin object count = 2111556 end object count = 1054953 markStageTime = 64786 pauseStageTime = 229 totalMarkCycleTime = 65580 candiate garabage count = 1072425 actual garbage count = 1072425 pre rescue count = 1534641 rescue1Time = 37101 rescue 1 Count = 1072425 rescue2Time = 229 Result size = 1072425
2011-12-27 21:34:42,247 [WorkerThread(gc_result_processing_stage, 0)] INFO com.tc.l2.objectserver.ReplicatedObjectManagerImpl - Removed 1072425 objects from passive ObjectManager from last DGC from Active
2011-12-27 21:34:44,029 [WorkerThread(gc_delete_from_disk_stage, 0)] INFO com.tc.objectserver.persistence.db.DBPersistorImpl - Removed 5000 objects in 441 ms.
2011-12-27 21:34:47,557 [WorkerThread(gc_delete_from_disk_stage, 0)] INFO com.tc.objectserver.persistence.db.DBPersistorImpl - Removed 5000 objects in 349 ms.
2011-12-27 21:34:49,893 [WorkerThread(gc_delete_from_disk_stage, 0)] INFO com.tc.objectserver.persistence.db.DBPersistorImpl - Removed 5000 objects in 1056 ms.
2011-12-27 21:34:50,265 [WorkerThread(gc_delete_from_disk_stage, 0)] INFO com.tc.objectserver.persistence.db.DBPersistorImpl - Removed 5000 objects in 372 ms.
2011-12-27 21:34:50,579 [WorkerThread(gc_delete_from_disk_stage, 0)] INFO com.tc.objectserver.persistence.db.DBPersistorImpl - Removed 5000 objects in 314 ms.
2011-12-27 21:34:52,296 [WorkerThread(gc_delete_from_disk_stage, 0)] INFO com.tc.objectserver.persistence.db.DBPersistorImpl - Removed 5000 objects in 381 ms.
2011-12-27 21:34:52,650 [WorkerThread(gc_delete_from_disk_stage, 0)] INFO com.tc.objectserver.persistence.db.DBPersistorImpl - Removed 5000 objects in 353 ms.
2011-12-27 21:34:53,693 [WorkerThread(gc_delete_from_disk_stage, 0)] INFO com.tc.objectserver.persistence.db.DBPersistorImpl - Removed 5000 objects in 311 ms.
2011-12-27 21:34:55,348 [WorkerThread(gc_delete_from_disk_stage, 0)] INFO com.tc.objectserver.persistence.db.DBPersistorImpl - Removed 5000 objects in 1353 ms.
2011-12-27 21:34:58,229 [WorkerThread(gc_delete_from_disk_stage, 0)] INFO com.tc.objectserver.persistence.db.DBPersistorImpl - Removed 5000 objects in 391 ms.
2011-12-27 21:35:00,918 [WorkerThread(gc_delete_from_disk_stage, 0)] INFO com.tc.objectserver.persistence.db.DBPersistorImpl - Removed 5000 objects in 328 ms.
2011-12-27 21:35:01,237 [WorkerThread(gc_delete_from_disk_stage, 0)] INFO com.tc.objectserver.persistence.db.DBPersistorImpl - Removed 5000 objects in 319 ms.
2011-12-27 21:35:04,645 [WorkerThread(gc_delete_from_disk_stage, 0)] INFO com.tc.objectserver.persistence.db.DBPersistorImpl - Removed 5000 objects in 3067 ms.
2011-12-27 21:35:05,254 [WorkerThread(gc_delete_from_disk_stage, 0)] INFO com.tc.objectserver.persistence.db.DBPersistorImpl - Removed 5000 objects in 609 ms.
2011-12-27 21:35:05,597 [WorkerThread(gc_delete_from_disk_stage, 0)] INFO com.tc.objectserver.persistence.db.DBPersistorImpl - Removed 5000 objects in 343 ms.
2011-12-27 21:35:11,238 [WorkerThread(gc_delete_from_disk_stage, 0)] INFO com.tc.objectserver.persistence.db.DBPersistorImpl - Removed 5000 objects in 412 ms.
2011-12-27 21:35:12,249 [WorkerThread(gc_delete_from_disk_stage, 0)] INFO com.tc.objectserver.persistence.db.DBPersistorImpl - Removed 5000 objects in 527 ms.
2011-12-27 21:35:12,954 [WorkerThread(gc_delete_from_disk_stage, 0)] INFO com.tc.objectserver.persistence.db.DBPersistorImpl - Removed 5000 objects in 705 ms.
2011-12-27 21:35:13,959 [WorkerThread(gc_delete_from_disk_stage, 0)] INFO com.tc.objectserver.persistence.db.DBPersistorImpl - Removed 5000 objects in 1005 ms.
2011-12-27 21:35:14,320 [WorkerThread(gc_delete_from_disk_stage, 0)] INFO com.tc.objectserver.persistence.db.DBPersistorImpl - Removed 5000 objects in 361 ms.
2011-12-27 21:35:16,478 [WorkerThread(gc_delete_from_disk_stage, 0)] INFO com.tc.objectserver.persistence.db.DBPersistorImpl - Removed 5000 objects in 1962 ms.
2011-12-27 21:35:16,912 [WorkerThread(gc_delete_from_disk_stage, 0)] INFO com.tc.objectserver.persistence.db.DBPersistorImpl - Removed 5000 objects in 434 ms.
2011-12-27 21:35:17,275 [WorkerThread(gc_delete_from_disk_stage, 0)] INFO com.tc.objectserver.persistence.db.DBPersistorImpl - Removed 5000 objects in 363 ms.
2011-12-27 21:35:17,787 [WorkerThread(gc_delete_from_disk_stage, 0)] INFO com.tc.objectserver.persistence.db.DBPersistorImpl - Removed 5000 objects in 311 ms.
2011-12-27 21:35:18,295 [WorkerThread(gc_delete_from_disk_stage, 0)] INFO com.tc.objectserver.persistence.db.DBPersistorImpl - Removed 5000 objects in 307 ms.
2011-12-27 21:35:19,075 [WorkerThread(gc_delete_from_disk_stage, 0)] INFO com.tc.objectserver.persistence.db.DBPersistorImpl - Removed 5000 objects in 331 ms.
2011-12-27 21:35:19,919 [WorkerThread(gc_delete_from_disk_stage, 0)] INFO com.tc.objectserver.persistence.db.DBPersistorImpl - Removed 5000 objects in 427 ms.
2011-12-27 21:35:21,664 [WorkerThread(gc_delete_from_disk_stage, 0)] INFO com.tc.objectserver.persistence.db.DBPersistorImpl - Removed 5000 objects in 1745 ms.
2011-12-27 21:35:25,220 [WorkerThread(gc_delete_from_disk_stage, 0)] INFO com.tc.objectserver.persistence.db.DBPersistorImpl - Removed 5000 objects in 663 ms.
2011-12-27 21:38:55,347 [Statistics Logger] INFO com.terracottatech.dso - memory free : 948326088
2011-12-27 21:38:55,348 [Statistics Logger] INFO com.terracottatech.dso - memory used : 1155445048
2011-12-27 21:38:55,348 [Statistics Logger] INFO com.terracottatech.dso - memory max : 2103771136
2011-12-27 21:53:55,343 [Statistics Logger] INFO com.terracottatech.dso - memory free : 274691448
2011-12-27 21:53:55,344 [Statistics Logger] INFO com.terracottatech.dso - memory used : 1833273992
2011-12-27 21:53:55,344 [Statistics Logger] INFO com.terracottatech.dso - memory max : 2107965440
2011-12-27 22:08:55,350 [Statistics Logger] INFO com.terracottatech.dso - memory free : 684702624
2011-12-27 22:08:55,350 [Statistics Logger] INFO com.terracottatech.dso - memory used : 1406485600
2011-12-27 22:08:55,350 [Statistics Logger] INFO com.terracottatech.dso - memory max : 2091188224
2011-12-27 22:23:55,349 [Statistics Logger] INFO com.terracottatech.dso - memory free : 700843456
2011-12-27 22:23:55,349 [Statistics Logger] INFO com.terracottatech.dso - memory used : 1377958464
2011-12-27 22:23:55,349 [Statistics Logger] INFO com.terracottatech.dso - memory max : 2078801920
2011-12-27 22:35:43,691 [WorkerThread(gc_result_processing_stage, 0)] INFO com.tc.l2.handler.GCResultHandler - Scheduling to process GC results when all current transactions are completed : DGCResultMessage@1918782169 : DGC Info = GarbageCollectionInfo [ Iteration = 354 ] = type = full, startTime = 1325046881343 begin object count = 1914797 end object count = 1001589 markStageTime = 61729 pauseStageTime = 214 totalMarkCycleTime = 62424 candiate garabage count = 928321 actual garbage count = 928321 pre rescue count = 1354900 rescue1Time = 34400 rescue 1 Count = 928321 rescue2Time = 214 Result size = 928321
2011-12-27 22:35:44,524 [WorkerThread(gc_result_processing_stage, 0)] INFO com.tc.l2.objectserver.ReplicatedObjectManagerImpl - Removed 928321 objects from passive ObjectManager from last DGC from Active
2011-12-27 22:35:46,616 [WorkerThread(gc_delete_from_disk_stage, 0)] INFO com.tc.objectserver.persistence.db.DBPersistorImpl - Removed 5000 objects in 364 ms.
2011-12-27 22:35:50,370 [WorkerThread(gc_delete_from_disk_stage, 0)] INFO com.tc.objectserver.persistence.db.DBPersistorImpl - Removed 5000 objects in 421 ms.
2011-12-27 22:35:50,700 [WorkerThread(gc_delete_from_disk_stage, 0)] INFO com.tc.objectserver.persistence.db.DBPersistorImpl - Removed 5000 objects in 330 ms.
2011-12-27 22:35:51,235 [WorkerThread(gc_delete_from_disk_stage, 0)] INFO com.tc.objectserver.persistence.db.DBPersistorImpl - Removed 5000 objects in 535 ms.
2011-12-27 22:35:51,790 [WorkerThread(gc_delete_from_disk_stage, 0)] INFO com.tc.objectserver.persistence.db.DBPersistorImpl - Removed 5000 objects in 307 ms.
2011-12-27 22:35:52,151 [WorkerThread(gc_delete_from_disk_stage, 0)] INFO com.tc.objectserver.persistence.db.DBPersistorImpl - Removed 5000 objects in 360 ms.
2011-12-27 22:35:53,076 [WorkerThread(gc_delete_from_disk_stage, 0)] INFO com.tc.objectserver.persistence.db.DBPersistorImpl - Removed 5000 objects in 373 ms.
2011-12-27 22:35:54,670 [WorkerThread(gc_delete_from_disk_stage, 0)] INFO com.tc.objectserver.persistence.db.DBPersistorImpl - Removed 5000 objects in 744 ms.
2011-12-27 22:35:55,226 [WorkerThread(gc_delete_from_disk_stage, 0)] INFO com.tc.objectserver.persistence.db.DBPersistorImpl - Removed 5000 objects in 556 ms.
2011-12-27 22:35:56,460 [WorkerThread(gc_delete_from_disk_stage, 0)] INFO com.tc.objectserver.persistence.db.DBPersistorImpl - Removed 5000 objects in 336 ms.
2011-12-27 22:36:02,550 [WorkerThread(gc_delete_from_disk_stage, 0)] INFO com.tc.objectserver.persistence.db.DBPersistorImpl - Removed 5000 objects in 355 ms.
2011-12-27 22:36:04,613 [WorkerThread(gc_delete_from_disk_stage, 0)] INFO com.tc.objectserver.persistence.db.DBPersistorImpl - Removed 5000 objects in 319 ms.
2011-12-27 22:36:07,185 [WorkerThread(gc_delete_from_disk_stage, 0)] INFO com.tc.objectserver.persistence.db.DBPersistorImpl - Removed 5000 objects in 2172 ms.
2011-12-27 22:36:10,718 [WorkerThread(gc_delete_from_disk_stage, 0)] INFO com.tc.objectserver.persistence.db.DBPersistorImpl - Removed 5000 objects in 348 ms.
2011-12-27 22:36:12,878 [WorkerThread(gc_delete_from_disk_stage, 0)] INFO com.tc.objectserver.persistence.db.DBPersistorImpl - Removed 5000 objects in 2160 ms.
2011-12-27 22:36:15,934 [WorkerThread(gc_delete_from_disk_stage, 0)] INFO com.tc.objectserver.persistence.db.DBPersistorImpl - Removed 5000 objects in 321 ms.
2011-12-27 22:38:55,347 [Statistics Logger] INFO com.terracottatech.dso - memory free : 944481648
2011-12-27 22:38:55,347 [Statistics Logger] INFO com.terracottatech.dso - memory used : 1150769808
2011-12-27 22:38:55,347 [Statistics Logger] INFO com.terracottatech.dso - memory max : 2095251456
2011-12-27 22:53:55,343 [Statistics Logger] INFO com.terracottatech.dso - memory free : 731361704
2011-12-27 22:53:55,343 [Statistics Logger] INFO com.terracottatech.dso - memory used : 1375424088
2011-12-27 22:53:55,343 [Statistics Logger] INFO com.terracottatech.dso - memory max : 2106785792
2011-12-27 23:08:55,349 [Statistics Logger] INFO com.terracottatech.dso - memory free : 477850248
2011-12-27 23:08:55,349 [Statistics Logger] INFO com.terracottatech.dso - memory used : 1635030392
2011-12-27 23:08:55,349 [Statistics Logger] INFO com.terracottatech.dso - memory max : 2112880640
2011-12-27 23:23:55,345 [Statistics Logger] INFO com.terracottatech.dso - memory free : 300080336
2011-12-27 23:23:55,346 [Statistics Logger] INFO com.terracottatech.dso - memory used : 1768301360
2011-12-27 23:23:55,346 [Statistics Logger] INFO com.terracottatech.dso - memory max : 2068381696
2011-12-27 23:36:43,895 [WorkerThread(gc_result_processing_stage, 0)] INFO com.tc.l2.handler.GCResultHandler - Scheduling to process GC results when all current transactions are completed : DGCResultMessage@20018816 : DGC Info = GarbageCollectionInfo [ Iteration = 355 ] = type = full, startTime = 1325050543785 begin object count = 1791927 end object count = 993462 markStageTime = 59251 pauseStageTime = 224 totalMarkCycleTime = 59894 candiate garabage count = 810682 actual garbage count = 810682 pre rescue count = 1248323 rescue1Time = 31819 rescue 1 Count = 810682 rescue2Time = 224 Result size = 810682
2011-12-27 23:36:44,719 [WorkerThread(gc_result_processing_stage, 0)] INFO com.tc.l2.objectserver.ReplicatedObjectManagerImpl - Removed 810682 objects from passive ObjectManager from last DGC from Active
2011-12-27 23:36:50,303 [WorkerThread(gc_delete_from_disk_stage, 0)] INFO com.tc.objectserver.persistence.db.DBPersistorImpl - Removed 5000 objects in 381 ms.
2011-12-27 23:36:53,319 [WorkerThread(gc_delete_from_disk_stage, 0)] INFO com.tc.objectserver.persistence.db.DBPersistorImpl - Removed 5000 objects in 589 ms.
2011-12-27 23:36:53,670 [WorkerThread(gc_delete_from_disk_stage, 0)] INFO com.tc.objectserver.persistence.db.DBPersistorImpl - Removed 5000 objects in 351 ms.
2011-12-27 23:36:57,588 [WorkerThread(gc_delete_from_disk_stage, 0)] INFO com.tc.objectserver.persistence.db.DBPersistorImpl - Removed 5000 objects in 457 ms.
2011-12-27 23:36:58,531 [WorkerThread(gc_delete_from_disk_stage, 0)] INFO com.tc.objectserver.persistence.db.DBPersistorImpl - Removed 5000 objects in 943 ms.
2011-12-27 23:36:59,421 [WorkerThread(gc_delete_from_disk_stage, 0)] INFO com.tc.objectserver.persistence.db.DBPersistorImpl - Removed 5000 objects in 337 ms.
2011-12-27 23:37:00,188 [WorkerThread(gc_delete_from_disk_stage, 0)] INFO com.tc.objectserver.persistence.db.DBPersistorImpl - Removed 5000 objects in 340 ms.
2011-12-27 23:37:01,330 [WorkerThread(gc_delete_from_disk_stage, 0)] INFO com.tc.objectserver.persistence.db.DBPersistorImpl - Removed 5000 objects in 379 ms.
2011-12-27 23:37:02,489 [WorkerThread(gc_delete_from_disk_stage, 0)] INFO com.tc.objectserver.persistence.db.DBPersistorImpl - Removed 5000 objects in 390 ms.
2011-12-27 23:37:04,821 [WorkerThread(gc_delete_from_disk_stage, 0)] INFO com.tc.objectserver.persistence.db.DBPersistorImpl - Removed 5000 objects in 2224 ms.
2011-12-27 23:37:05,420 [WorkerThread(gc_delete_from_disk_stage, 0)] INFO com.tc.objectserver.persistence.db.DBPersistorImpl - Removed 5000 objects in 320 ms.
2011-12-27 23:37:05,886 [WorkerThread(gc_delete_from_disk_stage, 0)] INFO com.tc.objectserver.persistence.db.DBPersistorImpl - Removed 5000 objects in 466 ms.
2011-12-27 23:37:06,301 [WorkerThread(gc_delete_from_disk_stage, 0)] INFO com.tc.objectserver.persistence.db.DBPersistorImpl - Removed 5000 objects in 414 ms.
2011-12-27 23:37:06,612 [WorkerThread(gc_delete_from_disk_stage, 0)] INFO com.tc.objectserver.persistence.db.DBPersistorImpl - Removed 5000 objects in 311 ms.
2011-12-27 23:37:08,860 [WorkerThread(gc_delete_from_disk_stage, 0)] INFO com.tc.objectserver.persistence.db.DBPersistorImpl - Removed 5000 objects in 379 ms.
2011-12-27 23:38:55,342 [Statistics Logger] INFO com.terracottatech.dso - memory free : 863687216
2011-12-27 23:38:55,342 [Statistics Logger] INFO com.terracottatech.dso - memory used : 1219243472
2011-12-27 23:38:55,342 [Statistics Logger] INFO com.terracottatech.dso - memory max : 2082930688
2011-12-27 23:53:55,348 [Statistics Logger] INFO com.terracottatech.dso - memory free : 565077568
2011-12-27 23:53:55,348 [Statistics Logger] INFO com.terracottatech.dso - memory used : 1538496960
2011-12-27 23:53:55,348 [Statistics Logger] INFO com.terracottatech.dso - memory max : 2103574528
2011-12-28 00:08:55,344 [Statistics Logger] INFO com.terracottatech.dso - memory free : 893321064
2011-12-28 00:08:55,344 [Statistics Logger] INFO com.terracottatech.dso - memory used : 1197736088
2011-12-28 00:08:55,344 [Statistics Logger] INFO com.terracottatech.dso - memory max : 2091057152
2011-12-28 00:23:55,343 [Statistics Logger] INFO com.terracottatech.dso - memory free : 556692520
2011-12-28 00:23:55,344 [Statistics Logger] INFO com.terracottatech.dso - memory used : 1521257432
2011-12-28 00:23:55,344 [Statistics Logger] INFO com.terracottatech.dso - memory max : 2077949952
2011-12-28 00:37:43,447 [WorkerThread(gc_result_processing_stage, 0)] INFO com.tc.l2.handler.GCResultHandler - Scheduling to process GC results when all current transactions are completed : DGCResultMessage@1722716145 : DGC Info = GarbageCollectionInfo [ Iteration = 356 ] = type = full, startTime = 1325054203704 begin object count = 1685582 end object count = 967031 markStageTime = 59032 pauseStageTime = 212 totalMarkCycleTime = 59649 candiate garabage count = 730252 actual garbage count = 730252 pre rescue count = 1148909 rescue1Time = 32669 rescue 1 Count = 730252 rescue2Time = 212 Result size = 730252
2011-12-28 00:37:44,236 [WorkerThread(gc_result_processing_stage, 0)] INFO com.tc.l2.objectserver.ReplicatedObjectManagerImpl - Removed 730252 objects from passive ObjectManager from last DGC from Active
2011-12-28 00:37:45,644 [WorkerThread(gc_delete_from_disk_stage, 0)] INFO com.tc.objectserver.persistence.db.DBPersistorImpl - Removed 5000 objects in 517 ms.
2011-12-28 00:37:47,906 [WorkerThread(gc_delete_from_disk_stage, 0)] INFO com.tc.objectserver.persistence.db.DBPersistorImpl - Removed 5000 objects in 312 ms.
2011-12-28 00:37:50,182 [WorkerThread(gc_delete_from_disk_stage, 0)] INFO com.tc.objectserver.persistence.db.DBPersistorImpl - Removed 5000 objects in 510 ms.
2011-12-28 00:37:53,723 [WorkerThread(gc_delete_from_disk_stage, 0)] INFO com.tc.objectserver.persistence.db.DBPersistorImpl - Removed 5000 objects in 3277 ms.
2011-12-28 00:37:55,292 [WorkerThread(gc_delete_from_disk_stage, 0)] INFO com.tc.objectserver.persistence.db.DBPersistorImpl - Removed 5000 objects in 542 ms.
2011-12-28 00:38:00,113 [WorkerThread(gc_delete_from_disk_stage, 0)] INFO com.tc.objectserver.persistence.db.DBPersistorImpl - Removed 5000 objects in 415 ms.
2011-12-28 00:38:01,247 [WorkerThread(gc_delete_from_disk_stage, 0)] INFO com.tc.objectserver.persistence.db.DBPersistorImpl - Removed 5000 objects in 338 ms.
2011-12-28 00:38:01,584 [WorkerThread(gc_delete_from_disk_stage, 0)] INFO com.tc.objectserver.persistence.db.DBPersistorImpl - Removed 5000 objects in 337 ms.
2011-12-28 00:38:02,586 [WorkerThread(gc_delete_from_disk_stage, 0)] INFO com.tc.objectserver.persistence.db.DBPersistorImpl - Removed 5000 objects in 510 ms.
2011-12-28 00:38:02,930 [WorkerThread(gc_delete_from_disk_stage, 0)] INFO com.tc.objectserver.persistence.db.DBPersistorImpl - Removed 5000 objects in 344 ms.
2011-12-28 00:38:03,300 [WorkerThread(gc_delete_from_disk_stage, 0)] INFO com.tc.objectserver.persistence.db.DBPersistorImpl - Removed 5000 objects in 369 ms.
2011-12-28 00:38:06,673 [WorkerThread(gc_delete_from_disk_stage, 0)] INFO com.tc.objectserver.persistence.db.DBPersistorImpl - Removed 5000 objects in 2131 ms.
2011-12-28 00:38:09,210 [WorkerThread(gc_delete_from_disk_stage, 0)] INFO com.tc.objectserver.persistence.db.DBPersistorImpl - Removed 5000 objects in 406 ms.
2011-12-28 00:38:10,320 [WorkerThread(gc_delete_from_disk_stage, 0)] INFO com.tc.objectserver.persistence.db.DBPersistorImpl - Removed 5000 objects in 572 ms.
2011-12-28 00:38:11,231 [WorkerThread(gc_delete_from_disk_stage, 0)] INFO com.tc.objectserver.persistence.db.DBPersistorImpl - Removed 5000 objects in 911 ms.
2011-12-28 00:38:55,350 [Statistics Logger] INFO com.terracottatech.dso - memory free : 935817112
2011-12-28 00:38:55,350 [Statistics Logger] INFO com.terracottatech.dso - memory used : 1116967016
2011-12-28 00:38:55,350 [Statistics Logger] INFO com.terracottatech.dso - memory max : 2052784128
2011-12-28 00:53:55,346 [Statistics Logger] INFO com.terracottatech.dso - memory free : 909109136
2011-12-28 00:53:55,346 [Statistics Logger] INFO com.terracottatech.dso - memory used : 1183586416
2011-12-28 00:53:55,346 [Statistics Logger] INFO com.terracottatech.dso - memory max : 2092695552
2011-12-28 01:08:55,342 [Statistics Logger] INFO com.terracottatech.dso - memory free : 579166544
2011-12-28 01:08:55,342 [Statistics Logger] INFO com.terracottatech.dso - memory used : 1525522096
2011-12-28 01:08:55,342 [Statistics Logger] INFO com.terracottatech.dso - memory max : 2104688640
2011-12-28 01:13:04,270 [WorkerThread(channel_life_cycle_stage, 0)] INFO com.tc.objectserver.handler.ChannelLifeCycleHandler - : Received transport disconnect. Shutting down client ClientID[2989]
2011-12-28 01:13:04,271 [WorkerThread(channel_life_cycle_stage, 0)] INFO com.tc.objectserver.persistence.inmemory.TransactionStoreImpl - shutdownClient() : Removing txns from DB : 0
2011-12-28 01:13:48,099 [WorkerThread(channel_life_cycle_stage, 0)] INFO com.tc.objectserver.handler.ChannelLifeCycleHandler - : Received transport disconnect. Shutting down client ClientID[2985]
2011-12-28 01:13:48,100 [WorkerThread(channel_life_cycle_stage, 0)] INFO com.tc.objectserver.persistence.inmemory.TransactionStoreImpl - shutdownClient() : Removing txns from DB : 0
2011-12-28 01:13:48,102 [WorkerThread(channel_life_cycle_stage, 0)] INFO com.tc.objectserver.handler.ChannelLifeCycleHandler - : Received transport disconnect. Shutting down client ClientID[2991]
2011-12-28 01:13:48,102 [WorkerThread(channel_life_cycle_stage, 0)] INFO com.tc.objectserver.persistence.inmemory.TransactionStoreImpl - shutdownClient() : Removing txns from DB : 0
2011-12-28 01:13:48,119 [WorkerThread(channel_life_cycle_stage, 0)] INFO com.tc.objectserver.handler.ChannelLifeCycleHandler - : Received transport disconnect. Shutting down client ClientID[2988]
2011-12-28 01:13:48,119 [WorkerThread(channel_life_cycle_stage, 0)] INFO com.tc.objectserver.persistence.inmemory.TransactionStoreImpl - shutdownClient() : Removing txns from DB : 0
2011-12-28 01:23:55,348 [Statistics Logger] INFO com.terracottatech.dso - memory free : 728088240
2011-12-28 01:23:55,349 [Statistics Logger] INFO com.terracottatech.dso - memory used : 1357660496
2011-12-28 01:23:55,349 [Statistics Logger] INFO com.terracottatech.dso - memory max : 2085748736
2011-12-28 01:38:39,110 [WorkerThread(gc_result_processing_stage, 0)] INFO com.tc.l2.handler.GCResultHandler - Scheduling to process GC results when all current transactions are completed : DGCResultMessage@177914944 : DGC Info = GarbageCollectionInfo [ Iteration = 357 ] = type = full, startTime = 1325057863377 begin object count = 1638359 end object count = 967651 markStageTime = 55097 pauseStageTime = 192 totalMarkCycleTime = 55675 candiate garabage count = 680968 actual garbage count = 680968 pre rescue count = 1132867 rescue1Time = 32456 rescue 1 Count = 680968 rescue2Time = 192 Result size = 680968
2011-12-28 01:38:39,757 [WorkerThread(gc_result_processing_stage, 0)] INFO com.tc.l2.objectserver.ReplicatedObjectManagerImpl - Removed 680968 objects from passive ObjectManager from last DGC from Active
2011-12-28 01:38:45,160 [WorkerThread(gc_delete_from_disk_stage, 0)] INFO com.tc.objectserver.persistence.db.DBPersistorImpl - Removed 5000 objects in 3306 ms.
2011-12-28 01:38:47,338 [WorkerThread(gc_delete_from_disk_stage, 0)] INFO com.tc.objectserver.persistence.db.DBPersistorImpl - Removed 5000 objects in 639 ms.
2011-12-28 01:38:49,800 [WorkerThread(gc_delete_from_disk_stage, 0)] INFO com.tc.objectserver.persistence.db.DBPersistorImpl - Removed 5000 objects in 317 ms.
2011-12-28 01:38:52,652 [WorkerThread(gc_delete_from_disk_stage, 0)] INFO com.tc.objectserver.persistence.db.DBPersistorImpl - Removed 5000 objects in 643 ms.
2011-12-28 01:38:53,518 [WorkerThread(gc_delete_from_disk_stage, 0)] INFO com.tc.objectserver.persistence.db.DBPersistorImpl - Removed 5000 objects in 384 ms.
2011-12-28 01:38:55,109 [WorkerThread(gc_delete_from_disk_stage, 0)] INFO com.tc.objectserver.persistence.db.DBPersistorImpl - Removed 5000 objects in 343 ms.
2011-12-28 01:38:55,345 [Statistics Logger] INFO com.terracottatech.dso - memory free : 1158979328
2011-12-28 01:38:55,346 [Statistics Logger] INFO com.terracottatech.dso - memory used : 909730048
2011-12-28 01:38:55,346 [Statistics Logger] INFO com.terracottatech.dso - memory max : 2068709376
2011-12-28 01:38:56,397 [WorkerThread(gc_delete_from_disk_stage, 0)] INFO com.tc.objectserver.persistence.db.DBPersistorImpl - Removed 5000 objects in 1288 ms.
2011-12-28 01:38:57,357 [WorkerThread(gc_delete_from_disk_stage, 0)] INFO com.tc.objectserver.persistence.db.DBPersistorImpl - Removed 5000 objects in 401 ms.
2011-12-28 01:38:58,943 [WorkerThread(gc_delete_from_disk_stage, 0)] INFO com.tc.objectserver.persistence.db.DBPersistorImpl - Removed 5000 objects in 387 ms.
2011-12-28 01:39:02,114 [WorkerThread(gc_delete_from_disk_stage, 0)] INFO com.tc.objectserver.persistence.db.DBPersistorImpl - Removed 5000 objects in 1618 ms.
2011-12-28 01:39:04,100 [WorkerThread(gc_delete_from_disk_stage, 0)] INFO com.tc.objectserver.persistence.db.DBPersistorImpl - Removed 5000 objects in 561 ms.
2011-12-28 01:53:55,351 [Statistics Logger] INFO com.terracottatech.dso - memory free : 665391032
2011-12-28 01:53:55,352 [Statistics Logger] INFO com.terracottatech.dso - memory used : 1426387016
2011-12-28 01:53:55,352 [Statistics Logger] INFO com.terracottatech.dso - memory max : 2091778048
2011-12-28 02:08:55,348 [Statistics Logger] INFO com.terracottatech.dso - memory free : 641115576
2011-12-28 02:08:55,348 [Statistics Logger] INFO com.terracottatech.dso - memory used : 1470061128
2011-12-28 02:08:55,348 [Statistics Logger] INFO com.terracottatech.dso - memory max : 2111176704
2011-12-28 02:23:55,341 [Statistics Logger] INFO com.terracottatech.dso - memory free : 759304240
2011-12-28 02:23:55,342 [Statistics Logger] INFO com.terracottatech.dso - memory used : 1341452240
2011-12-28 02:23:55,342 [Statistics Logger] INFO com.terracottatech.dso - memory max : 2100756480
2011-12-28 02:38:55,350 [Statistics Logger] INFO com.terracottatech.dso - memory free : 406813232
2011-12-28 02:38:55,350 [Statistics Logger] INFO com.terracottatech.dso - memory used : 1679132112
2011-12-28 02:38:55,350 [Statistics Logger] INFO com.terracottatech.dso - memory max : 2085945344
2011-12-28 02:39:17,781 [WorkerThread(gc_result_processing_stage, 0)] INFO com.tc.l2.handler.GCResultHandler - Scheduling to process GC results when all current transactions are completed : DGCResultMessage@902621614 : DGC Info = GarbageCollectionInfo [ Iteration = 358 ] = type = full, startTime = 1325061519076 begin object count = 1467888 end object count = 739140 markStageTime = 38039 pauseStageTime = 202 totalMarkCycleTime = 38675 candiate garabage count = 730694 actual garbage count = 730694 pre rescue count = 1093398 rescue1Time = 21594 rescue 1 Count = 730694 rescue2Time = 202 Result size = 730694
2011-12-28 02:39:18,453 [WorkerThread(gc_result_processing_stage, 0)] INFO com.tc.l2.objectserver.ReplicatedObjectManagerImpl - Removed 730694 objects from passive ObjectManager from last DGC from Active
2011-12-28 02:39:19,363 [WorkerThread(gc_delete_from_disk_stage, 0)] INFO com.tc.objectserver.persistence.db.DBPersistorImpl - Removed 5000 objects in 339 ms.
2011-12-28 02:39:23,589 [WorkerThread(gc_delete_from_disk_stage, 0)] INFO com.tc.objectserver.persistence.db.DBPersistorImpl - Removed 5000 objects in 320 ms.
2011-12-28 02:39:25,499 [WorkerThread(gc_delete_from_disk_stage, 0)] INFO com.tc.objectserver.persistence.db.DBPersistorImpl - Removed 5000 objects in 394 ms.
2011-12-28 02:39:27,633 [WorkerThread(gc_delete_from_disk_stage, 0)] INFO com.tc.objectserver.persistence.db.DBPersistorImpl - Removed 5000 objects in 766 ms.
2011-12-28 02:39:28,155 [WorkerThread(gc_delete_from_disk_stage, 0)] INFO com.tc.objectserver.persistence.db.DBPersistorImpl - Removed 5000 objects in 521 ms.
2011-12-28 02:39:31,186 [WorkerThread(gc_delete_from_disk_stage, 0)] INFO com.tc.objectserver.persistence.db.DBPersistorImpl - Removed 5000 objects in 660 ms.
2011-12-28 02:39:33,288 [WorkerThread(gc_delete_from_disk_stage, 0)] INFO com.tc.objectserver.persistence.db.DBPersistorImpl - Removed 5000 objects in 1681 ms.
2011-12-28 02:53:55,346 [Statistics Logger] INFO com.terracottatech.dso - memory free : 233511712
2011-12-28 02:53:55,347 [Statistics Logger] INFO com.terracottatech.dso - memory used : 1837688032
2011-12-28 02:53:55,347 [Statistics Logger] INFO com.terracottatech.dso - memory max : 2071199744
2011-12-28 03:08:55,343 [Statistics Logger] INFO com.terracottatech.dso - memory free : 611280768
2011-12-28 03:08:55,343 [Statistics Logger] INFO com.terracottatech.dso - memory used : 1470994560
2011-12-28 03:08:55,343 [Statistics Logger] INFO com.terracottatech.dso - memory max : 2082275328
2011-12-28 03:23:55,349 [Statistics Logger] INFO com.terracottatech.dso - memory free : 161692040
2011-12-28 03:23:55,349 [Statistics Logger] INFO com.terracottatech.dso - memory used : 1926547064
2011-12-28 03:23:55,349 [Statistics Logger] INFO com.terracottatech.dso - memory max : 2088239104
2011-12-28 03:38:55,347 [Statistics Logger] INFO com.terracottatech.dso - memory free : 907308904
2011-12-28 03:38:55,348 [Statistics Logger] INFO com.terracottatech.dso - memory used : 1193382040
2011-12-28 03:38:55,348 [Statistics Logger] INFO com.terracottatech.dso - memory max : 2100690944
2011-12-28 03:39:37,083 [WorkerThread(gc_result_processing_stage, 0)] INFO com.tc.l2.handler.GCResultHandler - Scheduling to process GC results when all current transactions are completed : DGCResultMessage@1689254553 : DGC Info = GarbageCollectionInfo [ Iteration = 359 ] = type = full, startTime = 1325065157768 begin object count = 917443 end object count = 475780 markStageTime = 18927 pauseStageTime = 99 totalMarkCycleTime = 19348 candiate garabage count = 442527 actual garbage count = 442527 pre rescue count = 537588 rescue1Time = 3508 rescue 1 Count = 442527 rescue2Time = 99 Result size = 442527
2011-12-28 03:39:37,628 [WorkerThread(gc_result_processing_stage, 0)] INFO com.tc.l2.objectserver.ReplicatedObjectManagerImpl - Removed 442527 objects from passive ObjectManager from last DGC from Active
2011-12-28 03:53:55,344 [Statistics Logger] INFO com.terracottatech.dso - memory free : 1230965840
2011-12-28 03:53:55,345 [Statistics Logger] INFO com.terracottatech.dso - memory used : 880145328
2011-12-28 03:53:55,345 [Statistics Logger] INFO com.terracottatech.dso - memory max : 2111111168
2011-12-28 04:08:55,350 [Statistics Logger] INFO com.terracottatech.dso - memory free : 812156240
2011-12-28 04:08:55,350 [Statistics Logger] INFO com.terracottatech.dso - memory used : 1299151536
2011-12-28 04:08:55,350 [Statistics Logger] INFO com.terracottatech.dso - memory max : 2111307776
2011-12-28 04:23:55,346 [Statistics Logger] INFO com.terracottatech.dso - memory free : 938833744
2011-12-28 04:23:55,346 [Statistics Logger] INFO com.terracottatech.dso - memory used : 1174177968
2011-12-28 04:23:55,346 [Statistics Logger] INFO com.terracottatech.dso - memory max : 2113011712
2011-12-28 04:38:55,342 [Statistics Logger] INFO com.terracottatech.dso - memory free : 1098126344
2011-12-28 04:38:55,343 [Statistics Logger] INFO com.terracottatech.dso - memory used : 1018096632
2011-12-28 04:38:55,343 [Statistics Logger] INFO com.terracottatech.dso - memory max : 2116222976
2011-12-28 04:39:51,288 [WorkerThread(gc_result_processing_stage, 0)] INFO com.tc.l2.handler.GCResultHandler - Scheduling to process GC results when all current transactions are completed : DGCResultMessage@1369596749 : DGC Info = GarbageCollectionInfo [ Iteration = 360 ] = type = full, startTime = 1325068777135 begin object count = 654835 end object count = 475906 markStageTime = 13889 pauseStageTime = 94 totalMarkCycleTime = 14145 candiate garabage count = 179614 actual garbage count = 179614 pre rescue count = 283428 rescue1Time = 630 rescue 1 Count = 179614 rescue2Time = 94 Result size = 179614
2011-12-28 04:39:51,528 [WorkerThread(gc_result_processing_stage, 0)] INFO com.tc.l2.objectserver.ReplicatedObjectManagerImpl - Removed 179614 objects from passive ObjectManager from last DGC from Active
2011-12-28 04:53:55,349 [Statistics Logger] INFO com.terracottatech.dso - memory free : 722680600
2011-12-28 04:53:55,350 [Statistics Logger] INFO com.terracottatech.dso - memory used : 1393476840
2011-12-28 04:53:55,350 [Statistics Logger] INFO com.terracottatech.dso - memory max : 2116157440
2011-12-28 05:08:55,345 [Statistics Logger] INFO com.terracottatech.dso - memory free : 835076768
2011-12-28 05:08:55,345 [Statistics Logger] INFO com.terracottatech.dso - memory used : 1280556384
2011-12-28 05:08:55,345 [Statistics Logger] INFO com.terracottatech.dso - memory max : 2115633152
2011-12-28 05:23:55,344 [Statistics Logger] INFO com.terracottatech.dso - memory free : 1025131952
2011-12-28 05:23:55,344 [Statistics Logger] INFO com.terracottatech.dso - memory used : 1085848144
2011-12-28 05:23:55,344 [Statistics Logger] INFO com.terracottatech.dso - memory max : 2110980096
2011-12-28 05:38:55,348 [Statistics Logger] INFO com.terracottatech.dso - memory free : 851668000
2011-12-28 05:38:55,348 [Statistics Logger] INFO com.terracottatech.dso - memory used : 1236046816
2011-12-28 05:38:55,348 [Statistics Logger] INFO com.terracottatech.dso - memory max : 2087714816
2011-12-28 05:40:05,368 [WorkerThread(gc_result_processing_stage, 0)] INFO com.tc.l2.handler.GCResultHandler - Scheduling to process GC results when all current transactions are completed : DGCResultMessage@372225723 : DGC Info = GarbageCollectionInfo [ Iteration = 361 ] = type = full, startTime = 1325072391300 begin object count = 702273 end object count = 529895 markStageTime = 13828 pauseStageTime = 103 totalMarkCycleTime = 14101 candiate garabage count = 172984 actual garbage count = 172984 pre rescue count = 300006 rescue1Time = 751 rescue 1 Count = 172984 rescue2Time = 103 Result size = 172984
2011-12-28 05:40:05,614 [WorkerThread(gc_result_processing_stage, 0)] INFO com.tc.l2.objectserver.ReplicatedObjectManagerImpl - Removed 172984 objects from passive ObjectManager from last DGC from Active
2011-12-28 05:53:55,349 [Statistics Logger] INFO com.terracottatech.dso - memory free : 378911752
2011-12-28 05:53:55,351 [Statistics Logger] INFO com.terracottatech.dso - memory used : 1704739832
2011-12-28 05:53:55,351 [Statistics Logger] INFO com.terracottatech.dso - memory max : 2083651584
2011-12-28 06:08:55,345 [Statistics Logger] INFO com.terracottatech.dso - memory free : 525200616
2011-12-28 06:08:55,346 [Statistics Logger] INFO com.terracottatech.dso - memory used : 1573720856
2011-12-28 06:08:55,346 [Statistics Logger] INFO com.terracottatech.dso - memory max : 2098921472
2011-12-28 06:23:55,341 [Statistics Logger] INFO com.terracottatech.dso - memory free : 705944848
2011-12-28 06:23:55,342 [Statistics Logger] INFO com.terracottatech.dso - memory used : 1391862512
2011-12-28 06:23:55,342 [Statistics Logger] INFO com.terracottatech.dso - memory max : 2097807360
2011-12-28 06:38:55,348 [Statistics Logger] INFO com.terracottatech.dso - memory free : 554361184
2011-12-28 06:38:55,348 [Statistics Logger] INFO com.terracottatech.dso - memory used : 1523981984
2011-12-28 06:38:55,348 [Statistics Logger] INFO com.terracottatech.dso - memory max : 2078343168
2011-12-28 06:40:27,753 [WorkerThread(gc_result_processing_stage, 0)] INFO com.tc.l2.handler.GCResultHandler - Scheduling to process GC results when all current transactions are completed : DGCResultMessage@972156455 : DGC Info = GarbageCollectionInfo [ Iteration = 362 ] = type = full, startTime = 1325076005422 begin object count = 936809 end object count = 690452 markStageTime = 22007 pauseStageTime = 134 totalMarkCycleTime = 22376 candiate garabage count = 247864 actual garbage count = 247864 pre rescue count = 511427 rescue1Time = 9414 rescue 1 Count = 247864 rescue2Time = 134 Result size = 247864
2011-12-28 06:40:28,138 [WorkerThread(gc_result_processing_stage, 0)] INFO com.tc.l2.objectserver.ReplicatedObjectManagerImpl - Removed 247864 objects from passive ObjectManager from last DGC from Active
2011-12-28 06:40:31,946 [WorkerThread(gc_delete_from_disk_stage, 0)] INFO com.tc.objectserver.persistence.db.DBPersistorImpl - Removed 5000 objects in 2265 ms.
2011-12-28 06:53:55,344 [Statistics Logger] INFO com.terracottatech.dso - memory free : 997998784
2011-12-28 06:53:55,345 [Statistics Logger] INFO com.terracottatech.dso - memory used : 1101446976
2011-12-28 06:53:55,345 [Statistics Logger] INFO com.terracottatech.dso - memory max : 2099445760
2011-12-28 07:08:55,350 [Statistics Logger] INFO com.terracottatech.dso - memory free : 782951592
2011-12-28 07:08:55,350 [Statistics Logger] INFO com.terracottatech.dso - memory used : 1322457944
2011-12-28 07:08:55,350 [Statistics Logger] INFO com.terracottatech.dso - memory max : 2105409536
2011-12-28 07:23:55,346 [Statistics Logger] INFO com.terracottatech.dso - memory free : 1137633496
2011-12-28 07:23:55,346 [Statistics Logger] INFO com.terracottatech.dso - memory used : 951326504
2011-12-28 07:23:55,346 [Statistics Logger] INFO com.terracottatech.dso - memory max : 2088960000
2011-12-28 07:38:55,342 [Statistics Logger] INFO com.terracottatech.dso - memory free : 855764536
2011-12-28 07:38:55,342 [Statistics Logger] INFO com.terracottatech.dso - memory used : 1208160712
2011-12-28 07:38:55,342 [Statistics Logger] INFO com.terracottatech.dso - memory max : 2063925248
2011-12-28 07:40:52,608 [WorkerThread(gc_result_processing_stage, 0)] INFO com.tc.l2.handler.GCResultHandler - Scheduling to process GC results when all current transactions are completed : DGCResultMessage@1902084426 : DGC Info = GarbageCollectionInfo [ Iteration = 363 ] = type = full, startTime = 1325079627820 begin object count = 1037544 end object count = 621607 markStageTime = 24109 pauseStageTime = 126 totalMarkCycleTime = 24580 candiate garabage count = 418368 actual garbage count = 418368 pre rescue count = 622014 rescue1Time = 10418 rescue 1 Count = 418368 rescue2Time = 126 Result size = 418368
2011-12-28 07:40:53,404 [WorkerThread(gc_result_processing_stage, 0)] INFO com.tc.l2.objectserver.ReplicatedObjectManagerImpl - Removed 418368 objects from passive ObjectManager from last DGC from Active
2011-12-28 07:40:56,707 [WorkerThread(gc_delete_from_disk_stage, 0)] INFO com.tc.objectserver.persistence.db.DBPersistorImpl - Removed 5000 objects in 315 ms.
2011-12-28 07:41:00,623 [WorkerThread(gc_delete_from_disk_stage, 0)] INFO com.tc.objectserver.persistence.db.DBPersistorImpl - Removed 5000 objects in 567 ms.
2011-12-28 07:53:55,348 [Statistics Logger] INFO com.terracottatech.dso - memory free : 352528856
2011-12-28 07:53:55,348 [Statistics Logger] INFO com.terracottatech.dso - memory used : 1733547560
2011-12-28 07:53:55,348 [Statistics Logger] INFO com.terracottatech.dso - memory max : 2086076416
2011-12-28 08:08:55,351 [Statistics Logger] INFO com.terracottatech.dso - memory free : 398732640
2011-12-28 08:08:55,352 [Statistics Logger] INFO com.terracottatech.dso - memory used : 1696584352
2011-12-28 08:08:55,352 [Statistics Logger] INFO com.terracottatech.dso - memory max : 2095316992
2011-12-28 08:23:55,347 [Statistics Logger] INFO com.terracottatech.dso - memory free : 698599224
2011-12-28 08:23:55,348 [Statistics Logger] INFO com.terracottatech.dso - memory used : 1400125640
2011-12-28 08:23:55,348 [Statistics Logger] INFO com.terracottatech.dso - memory max : 2098724864
2011-12-28 08:38:55,343 [Statistics Logger] INFO com.terracottatech.dso - memory free : 463893752
2011-12-28 08:38:55,344 [Statistics Logger] INFO com.terracottatech.dso - memory used : 1638828808
2011-12-28 08:38:55,344 [Statistics Logger] INFO com.terracottatech.dso - memory max : 2102722560
2011-12-28 08:41:20,137 [WorkerThread(gc_result_processing_stage, 0)] INFO com.tc.l2.handler.GCResultHandler - Scheduling to process GC results when all current transactions are completed : DGCResultMessage@771771078 : DGC Info = GarbageCollectionInfo [ Iteration = 364 ] = type = full, startTime = 1325083252423 begin object count = 1048591 end object count = 654722 markStageTime = 27088 pauseStageTime = 137 totalMarkCycleTime = 27493 candiate garabage count = 400900 actual garbage count = 400900 pre rescue count = 597338 rescue1Time = 10328 rescue 1 Count = 400900 rescue2Time = 137 Result size = 400900
2011-12-28 08:41:20,642 [WorkerThread(gc_result_processing_stage, 0)] INFO com.tc.l2.objectserver.ReplicatedObjectManagerImpl - Removed 400900 objects from passive ObjectManager from last DGC from Active
2011-12-28 08:41:22,595 [WorkerThread(gc_delete_from_disk_stage, 0)] INFO com.tc.objectserver.persistence.db.DBPersistorImpl - Removed 5000 objects in 305 ms.
2011-12-28 08:41:25,033 [WorkerThread(gc_delete_from_disk_stage, 0)] INFO com.tc.objectserver.persistence.db.DBPersistorImpl - Removed 5000 objects in 307 ms.
2011-12-28 08:41:28,032 [WorkerThread(gc_delete_from_disk_stage, 0)] INFO com.tc.objectserver.persistence.db.DBPersistorImpl - Removed 5000 objects in 1020 ms.
2011-12-28 08:53:55,350 [Statistics Logger] INFO com.terracottatech.dso - memory free : 600162040
2011-12-28 08:53:55,350 [Statistics Logger] INFO com.terracottatech.dso - memory used : 1491681544
2011-12-28 08:53:55,350 [Statistics Logger] INFO com.terracottatech.dso - memory max : 2091843584
2011-12-28 09:08:55,346 [Statistics Logger] INFO com.terracottatech.dso - memory free : 763272264
2011-12-28 09:08:55,346 [Statistics Logger] INFO com.terracottatech.dso - memory used : 1338991544
2011-12-28 09:08:55,346 [Statistics Logger] INFO com.terracottatech.dso - memory max : 2102263808
2011-12-28 09:23:55,342 [Statistics Logger] INFO com.terracottatech.dso - memory free : 243195472
2011-12-28 09:23:55,342 [Statistics Logger] INFO com.terracottatech.dso - memory used : 1862869424
2011-12-28 09:23:55,342 [Statistics Logger] INFO com.terracottatech.dso - memory max : 2106064896
2011-12-28 09:38:55,348 [Statistics Logger] INFO com.terracottatech.dso - memory free : 438566400
2011-12-28 09:38:55,348 [Statistics Logger] INFO com.terracottatech.dso - memory used : 1667236352
2011-12-28 09:38:55,348 [Statistics Logger] INFO com.terracottatech.dso - memory max : 2105802752
2011-12-28 09:41:58,182 [WorkerThread(gc_result_processing_stage, 0)] INFO com.tc.l2.handler.GCResultHandler - Scheduling to process GC results when all current transactions are completed : DGCResultMessage@828980089 : DGC Info = GarbageCollectionInfo [ Iteration = 365 ] = type = full, startTime = 1325086879931 begin object count = 1249548 end object count = 781258 markStageTime = 37754 pauseStageTime = 160 totalMarkCycleTime = 38221 candiate garabage count = 478728 actual garbage count = 478728 pre rescue count = 765723 rescue1Time = 18937 rescue 1 Count = 478728 rescue2Time = 160 Result size = 478728
2011-12-28 09:41:58,687 [WorkerThread(gc_result_processing_stage, 0)] INFO com.tc.l2.objectserver.ReplicatedObjectManagerImpl - Removed 478728 objects from passive ObjectManager from last DGC from Active
2011-12-28 09:42:02,838 [WorkerThread(gc_delete_from_disk_stage, 0)] INFO com.tc.objectserver.persistence.db.DBPersistorImpl - Removed 5000 objects in 303 ms.
2011-12-28 09:42:09,084 [WorkerThread(gc_delete_from_disk_stage, 0)] INFO com.tc.objectserver.persistence.db.DBPersistorImpl - Removed 5000 objects in 329 ms.
2011-12-28 09:42:11,604 [WorkerThread(gc_delete_from_disk_stage, 0)] INFO com.tc.objectserver.persistence.db.DBPersistorImpl - Removed 5000 objects in 748 ms.
2011-12-28 09:53:55,344 [Statistics Logger] INFO com.terracottatech.dso - memory free : 682977176
2011-12-28 09:53:55,344 [Statistics Logger] INFO com.terracottatech.dso - memory used : 1413978216
2011-12-28 09:53:55,344 [Statistics Logger] INFO com.terracottatech.dso - memory max : 2096955392
2011-12-28 10:08:55,344 [Statistics Logger] INFO com.terracottatech.dso - memory free : 625102672
2011-12-28 10:08:55,344 [Statistics Logger] INFO com.terracottatech.dso - memory used : 1483190448
2011-12-28 10:08:55,344 [Statistics Logger] INFO com.terracottatech.dso - memory max : 2108293120
Here is a terracotta client log:
Code:
2011-12-23 08:38:06,626 [main] INFO com.terracottatech.dso - Trying to get Cluster topology from http://[hidden]:9510/groupinfo
2011-12-23 08:38:06,641 [main] INFO com.terracottatech.dso - Trying to get L1 Reconnect Properties from http://[hidden]:9510/l1reconnectproperties
2011-12-23 08:38:06,672 [main] INFO com.tc.net.core.TCComm - Comm Worker Threads NOT requested
2011-12-23 08:38:06,687 [main] INFO com.tc.net.protocol.transport.ConnectionHealthCheckerImpl: DSO Client - HealthChecker Started
2011-12-23 08:38:06,707 [main] INFO com.tc.net.protocol.tcm.CommunicationsManager - HealthCheck CallbackPort Listener started at /0:0:0:0:0:0:0:0:46424
2011-12-23 08:38:06,737 [main] INFO com.tc.object.ApplicatorDNAEncodingImpl - Compressed String constructor not present
2011-12-23 08:38:06,782 [main] INFO com.terracottatech.dso - Statistics buffer opened
2011-12-23 08:38:06,783 [Statistics Logger] INFO com.terracottatech.dso - memory free : 1527599128
2011-12-23 08:38:06,786 [Statistics Logger] INFO com.terracottatech.dso - memory used : 530427880
2011-12-23 08:38:06,786 [Statistics Logger] INFO com.terracottatech.dso - memory max : 2058027008
2011-12-23 08:38:06,811 [main] INFO com.tc.statistics.StatisticRetrievalAction - "message monitor" statistic is not enabled. Please enable the property "tcm.monitor.delay" to collect this statistics.
2011-12-23 08:38:06,873 [main] INFO com.tc.runtime.TCMemoryManagerImpl - GarbageCollector: PS Scavenge
2011-12-23 08:38:06,873 [main] INFO com.tc.runtime.TCMemoryManagerImpl - GarbageCollector: PS MarkSweep
2011-12-23 08:38:06,930 [L1Management JMX registration] INFO com.tc.management.L1Management - Terracotta JMX connector available at[service:jmx:terracotta://localhost]
2011-12-23 08:38:07,046 [main] INFO com.tc.net.core.TCConnection - Comms Message Batching enabled
2011-12-23 08:38:07,051 [main] INFO com.tc.net.protocol.transport.ClientMessageTransport - ConnectionID(-1.ffffffffffffffffffffffffffffffff): Attaching new connection: com.tc.net.core.TCConnectionJDK14@1244745831: connected: true, closed: false local=10.87.135.46:44197 remote=10.215.175.31:9510 connect=[Fri Dec 23 08:38:07 CST 2011] idle=4ms [0 read, 0 write]
2011-12-23 08:38:07,080 [main] INFO com.tc.net.protocol.transport.ConnectionHealthCheckerImpl. DSO Client - Health monitoring agent started for domU-12-31-39-0C-AC-D1.compute-1.internal:9510
2011-12-23 08:38:07,086 [WorkerThread(client_coordination_stage, 0)] INFO com.tc.object.handshakemanager.ClientHandshakeManagerImpl - ClientID[-1]: Connected: Unpausing from State[ PAUSED ] RemoteNode : GroupID[0]. Disconnect count : 1
2011-12-23 08:38:07,088 [L1_L2:TCComm Main Selector Thread_R (listen 0:0:0:0:0:0:0:0:46424)] INFO com.tc.net.protocol.transport.ConnectionHealthCheckerImpl. DSO Client - HealthCheckCallbackPort verification PASSED for domU-12-31-39-0C-AC-D1.compute-1.internal:9510(callbackport: 9510)
2011-12-23 08:38:07,109 [WorkerThread(client_coordination_stage, 0)] INFO com.tc.object.handshakemanager.ClientHandshakeManagerImpl - ClientID[3115]: Received Handshake ack for this node :GroupID[0]
2011-12-23 08:38:07,110 [WorkerThread(client_coordination_stage, 0)] INFO com.tc.management.remote.protocol.terracotta.TunnelingEventHandler - Client JMX server ready; sending notification to L2 server
2011-12-23 08:38:07,111 [main] INFO com.terracottatech.console - Connection successfully established to server at 10.215.175.31:9510
2011-12-23 08:38:07,111 [main] INFO com.terracottatech.dso - Connection successfully established to server at 10.215.175.31:9510
2011-12-23 08:38:07,473 [main] INFO org.terracotta.api.org.terracotta.modules.ehcache.store.TerracottaClusteredInstanceFactory - Ehcache Core version 2.3.0 was built on 2010-11-05 11:23:36, at revision 3141, with jdk 1.6.0_21 by cruise
2011-12-23 08:38:09,567 [main] INFO org.terracotta.api.org.terracotta.modules.ehcache.store.ClusteredStore - Clustered Store [cache=bbyCustomerAccountCache] with checkContainsKeyOnPut: true
2011-12-23 08:38:09,567 [main] INFO org.terracotta.api.org.terracotta.modules.ehcache.store.ClusteredStore - Clustered Store [cache=bbyCustomerAccountCache] with storageStrategy: CLASSIC
2011-12-23 08:38:09,783 [main] INFO org.terracotta.api.org.terracotta.modules.ehcache.store.ClusteredStore - Clustered Store [cache=myrzTransactionCache] with checkContainsKeyOnPut: true
2011-12-23 08:38:09,783 [main] INFO org.terracotta.api.org.terracotta.modules.ehcache.store.ClusteredStore - Clustered Store [cache=myrzTransactionCache] with storageStrategy: CLASSIC
2011-12-23 08:38:09,967 [main] INFO org.terracotta.api.org.terracotta.modules.ehcache.store.ClusteredStore - Clustered Store [cache=bbyPartyCache] with checkContainsKeyOnPut: true
2011-12-23 08:38:09,967 [main] INFO org.terracotta.api.org.terracotta.modules.ehcache.store.ClusteredStore - Clustered Store [cache=bbyPartyCache] with storageStrategy: CLASSIC
2011-12-23 08:38:10,441 [main] INFO org.terracotta.api.org.terracotta.modules.ehcache.store.ClusteredStore - Clustered Store [cache=myrzPromoProgressCache] with checkContainsKeyOnPut: true
2011-12-23 08:38:10,441 [main] INFO org.terracotta.api.org.terracotta.modules.ehcache.store.ClusteredStore - Clustered Store [cache=myrzPromoProgressCache] with storageStrategy: CLASSIC
2011-12-23 08:38:10,626 [main] INFO org.terracotta.api.org.terracotta.modules.ehcache.store.ClusteredStore - Clustered Store [cache=bbyCustomerListOfValuesCache] with checkContainsKeyOnPut: true
2011-12-23 08:38:10,626 [main] INFO org.terracotta.api.org.terracotta.modules.ehcache.store.ClusteredStore - Clustered Store [cache=bbyCustomerListOfValuesCache] with storageStrategy: CLASSIC
2011-12-23 08:38:10,743 [main] INFO org.terracotta.api.org.terracotta.modules.ehcache.store.ClusteredStore - Clustered Store [cache=myrzGetListOfValuesCache] with checkContainsKeyOnPut: true
2011-12-23 08:38:10,743 [main] INFO org.terracotta.api.org.terracotta.modules.ehcache.store.ClusteredStore - Clustered Store [cache=myrzGetListOfValuesCache] with storageStrategy: CLASSIC
2011-12-23 08:38:10,852 [main] INFO org.terracotta.api.org.terracotta.modules.ehcache.store.ClusteredStore - Clustered Store [cache=myrzProfileAccountCache] with checkContainsKeyOnPut: true
2011-12-23 08:38:10,852 [main] INFO org.terracotta.api.org.terracotta.modules.ehcache.store.ClusteredStore - Clustered Store [cache=myrzProfileAccountCache] with storageStrategy: CLASSIC
2011-12-23 08:38:12,494 [main] INFO com.tc.management.remote.protocol.terracotta.TunneledDomainManager - Sending current registered tunneled domains to L2 server to set up the tunneled connections for the mbeans that match.
2011-12-23 08:38:12,495 [main] INFO org.terracotta.api.org.terracotta.modules.ehcache.store.TerracottaClusteredInstanceFactory - Ehcache Core version 2.3.0 was built on 2010-11-05 11:23:36, at revision 3141, with jdk 1.6.0_21 by cruise
2011-12-23 08:38:12,546 [main] INFO org.terracotta.api.org.terracotta.modules.ehcache.store.ClusteredStore - Clustered Store [cache=myrzPromoProgressCache] with checkContainsKeyOnPut: true
2011-12-23 08:38:12,546 [main] INFO org.terracotta.api.org.terracotta.modules.ehcache.store.ClusteredStore - Clustered Store [cache=myrzPromoProgressCache] with storageStrategy: CLASSIC
2011-12-23 08:38:12,546 [main] INFO org.terracotta.api.org.terracotta.modules.ehcache.store.ClusteredStore - Clustered Store [cache=myrzProfileAccountCache] with checkContainsKeyOnPut: true
2011-12-23 08:38:12,546 [main] INFO org.terracotta.api.org.terracotta.modules.ehcache.store.ClusteredStore - Clustered Store [cache=myrzProfileAccountCache] with storageStrategy: CLASSIC
2011-12-23 08:38:12,547 [main] INFO org.terracotta.api.org.terracotta.modules.ehcache.store.ClusteredStore - Clustered Store [cache=myrzGetListOfValuesCache] with checkContainsKeyOnPut: true
2011-12-23 08:38:12,547 [main] INFO org.terracotta.api.org.terracotta.modules.ehcache.store.ClusteredStore - Clustered Store [cache=myrzGetListOfValuesCache] with storageStrategy: CLASSIC
2011-12-23 08:38:12,547 [main] INFO org.terracotta.api.org.terracotta.modules.ehcache.store.ClusteredStore - Clustered Store [cache=myrzTransactionCache] with checkContainsKeyOnPut: true
2011-12-23 08:38:12,547 [main] INFO org.terracotta.api.org.terracotta.modules.ehcache.store.ClusteredStore - Clustered Store [cache=myrzTransactionCache] with storageStrategy: CLASSIC
2011-12-23 08:38:12,548 [main] INFO org.terracotta.api.org.terracotta.modules.ehcache.store.ClusteredStore - Clustered Store [cache=bbyPartyCache] with checkContainsKeyOnPut: true
2011-12-23 08:38:12,548 [main] INFO org.terracotta.api.org.terracotta.modules.ehcache.store.ClusteredStore - Clustered Store [cache=bbyPartyCache] with storageStrategy: CLASSIC
2011-12-23 08:38:12,548 [main] INFO org.terracotta.api.org.terracotta.modules.ehcache.store.ClusteredStore - Clustered Store [cache=bbyCustomerAccountCache] with checkContainsKeyOnPut: true
2011-12-23 08:38:12,548 [main] INFO org.terracotta.api.org.terracotta.modules.ehcache.store.ClusteredStore - Clustered Store [cache=bbyCustomerAccountCache] with storageStrategy: CLASSIC
2011-12-23 08:38:12,548 [main] INFO org.terracotta.api.org.terracotta.modules.ehcache.store.ClusteredStore - Clustered Store [cache=bbyCustomerListOfValuesCache] with checkContainsKeyOnPut: true
2011-12-23 08:38:12,548 [main] INFO org.terracotta.api.org.terracotta.modules.ehcache.store.ClusteredStore - Clustered Store [cache=bbyCustomerListOfValuesCache] with storageStrategy: CLASSIC
2011-12-23 08:38:15,920 [TC Memory Monitor] INFO com.tc.runtime.TCMemoryManagerImpl - Sleep time changed to : 1200
2011-12-23 08:38:29,220 [TC Memory Monitor] INFO com.tc.runtime.TCMemoryManagerImpl - Sleep time changed to : 400
2011-12-23 08:41:06,926 [ClientLockManager LockGC] INFO com.tc.object.locks.ClientLockManager - ClientID[3115]: Lock GC collected 29 garbage locks
2011-12-23 08:42:06,929 [ClientLockManager LockGC] INFO com.tc.object.locks.ClientLockManager - ClientID[3115]: Lock GC collected 33 garbage locks
2011-12-23 08:43:06,931 [ClientLockManager LockGC] INFO com.tc.object.locks.ClientLockManager - ClientID[3115]: Lock GC collected 3 garbage locks
2011-12-23 08:44:06,933 [ClientLockManager LockGC] INFO com.tc.object.locks.ClientLockManager - ClientID[3115]: Lock GC collected 35 garbage locks
2011-12-23 08:45:06,935 [ClientLockManager LockGC] INFO com.tc.object.locks.ClientLockManager - ClientID[3115]: Lock GC collected 3 garbage locks
2011-12-23 08:46:06,937 [ClientLockManager LockGC] INFO com.tc.object.locks.ClientLockManager - ClientID[3115]: Lock GC collected 3 garbage locks
2011-12-23 08:50:06,954 [ClientLockManager LockGC] INFO com.tc.object.locks.ClientLockManager - ClientID[3115]: Lock GC collected 3 garbage locks
2011-12-23 08:51:06,959 [ClientLockManager LockGC] INFO com.tc.object.locks.ClientLockManager - ClientID[3115]: Lock GC collected 3 garbage locks
2011-12-23 08:53:06,784 [Statistics Logger] INFO com.terracottatech.dso - memory free : 1618676096
2011-12-23 08:53:06,784 [Statistics Logger] INFO com.terracottatech.dso - memory used : 439350912
2011-12-23 08:53:06,784 [Statistics Logger] INFO com.terracottatech.dso - memory max : 2058027008
2011-12-23 08:53:06,964 [ClientLockManager LockGC] INFO com.tc.object.locks.ClientLockManager - ClientID[3115]: Lock GC collected 1 garbage locks
2011-12-23 08:55:06,969 [ClientLockManager LockGC] INFO com.tc.object.locks.ClientLockManager - ClientID[3115]: Lock GC collected 6 garbage locks
2011-12-23 08:56:06,971 [ClientLockManager LockGC] INFO com.tc.object.locks.ClientLockManager - ClientID[3115]: Lock GC collected 6 garbage locks
2011-12-23 08:58:06,976 [ClientLockManager LockGC] INFO com.tc.object.locks.ClientLockManager - ClientID[3115]: Lock GC collected 36 garbage locks
2011-12-23 09:00:06,981 [ClientLockManager LockGC] INFO com.tc.object.locks.ClientLockManager - ClientID[3115]: Lock GC collected 3 garbage locks
2011-12-23 09:01:06,984 [ClientLockManager LockGC] INFO com.tc.object.locks.ClientLockManager - ClientID[3115]: Lock GC collected 3 garbage locks
2011-12-23 09:03:06,989 [ClientLockManager LockGC] INFO com.tc.object.locks.ClientLockManager - ClientID[3115]: Lock GC collected 3 garbage locks
2011-12-23 09:05:06,994 [ClientLockManager LockGC] INFO com.tc.object.locks.ClientLockManager - ClientID[3115]: Lock GC collected 3 garbage locks
2011-12-23 09:06:06,996 [ClientLockManager LockGC] INFO com.tc.object.locks.ClientLockManager - ClientID[3115]: Lock GC collected 3 garbage locks
2011-12-23 09:08:06,782 [Statistics Logger] INFO com.terracottatech.dso - memory free : 1379657672
2011-12-23 09:08:06,782 [Statistics Logger] INFO com.terracottatech.dso - memory used : 678369336
2011-12-23 09:08:06,782 [Statistics Logger] INFO com.terracottatech.dso - memory max : 2058027008
2011-12-23 09:08:07,002 [ClientLockManager LockGC] INFO com.tc.object.locks.ClientLockManager - ClientID[3115]: Lock GC collected 3 garbage locks
2011-12-23 09:10:07,007 [ClientLockManager LockGC] INFO com.tc.object.locks.ClientLockManager - ClientID[3115]: Lock GC collected 6 garbage locks
2011-12-23 09:11:07,010 [ClientLockManager LockGC] INFO com.tc.object.locks.ClientLockManager - ClientID[3115]: Lock GC collected 6 garbage locks
2011-12-23 09:13:07,015 [ClientLockManager LockGC] INFO com.tc.object.locks.ClientLockManager - ClientID[3115]: Lock GC collected 2 garbage locks
2011-12-23 09:15:07,021 [ClientLockManager LockGC] INFO com.tc.object.locks.ClientLockManager - ClientID[3115]: Lock GC collected 3 garbage locks
2011-12-23 09:16:07,024 [ClientLockManager LockGC] INFO com.tc.object.locks.ClientLockManager - ClientID[3115]: Lock GC collected 3 garbage locks
2011-12-23 09:18:07,029 [ClientLockManager LockGC] INFO com.tc.object.locks.ClientLockManager - ClientID[3115]: Lock GC collected 2 garbage locks
2011-12-23 09:20:07,035 [ClientLockManager LockGC] INFO com.tc.object.locks.ClientLockManager - ClientID[3115]: Lock GC collected 3 garbage locks
2011-12-23 09:21:07,038 [ClientLockManager LockGC] INFO com.tc.object.locks.ClientLockManager - ClientID[3115]: Lock GC collected 4 garbage locks
2011-12-23 09:23:06,783 [Statistics Logger] INFO com.terracottatech.dso - memory free : 966678200
2011-12-23 09:23:06,783 [Statistics Logger] INFO com.terracottatech.dso - memory used : 1091348808
2011-12-23 09:23:06,783 [Statistics Logger] INFO com.terracottatech.dso - memory max : 2058027008
2011-12-23 09:23:07,044 [ClientLockManager LockGC] INFO com.tc.object.locks.ClientLockManager - ClientID[3115]: Lock GC collected 18 garbage locks
2011-12-23 09:25:07,050 [ClientLockManager LockGC] INFO com.tc.object.locks.ClientLockManager - ClientID[3115]: Lock GC collected 6 garbage locks
2011-12-23 09:26:07,052 [ClientLockManager LockGC] INFO com.tc.object.locks.ClientLockManager - ClientID[3115]: Lock GC collected 22 garbage locks
2011-12-23 09:28:07,058 [ClientLockManager LockGC] INFO com.tc.object.locks.ClientLockManager - ClientID[3115]: Lock GC collected 2 garbage locks
2011-12-23 09:30:07,084 [ClientLockManager LockGC] INFO com.tc.object.locks.ClientLockManager - ClientID[3115]: Lock GC collected 3 garbage locks
2011-12-23 09:31:07,087 [ClientLockManager LockGC] INFO com.tc.object.locks.ClientLockManager - ClientID[3115]: Lock GC collected 3 garbage locks
2011-12-23 09:33:07,098 [ClientLockManager LockGC] INFO com.tc.object.locks.ClientLockManager - ClientID[3115]: Lock GC collected 1 garbage locks
2011-12-23 09:35:07,108 [ClientLockManager LockGC] INFO com.tc.object.locks.ClientLockManager - ClientID[3115]: Lock GC collected 3 garbage locks
2011-12-23 09:36:07,110 [ClientLockManager LockGC] INFO com.tc.object.locks.ClientLockManager - ClientID[3115]: Lock GC collected 3 garbage locks
2011-12-23 09:38:06,786 [Statistics Logger] INFO com.terracottatech.dso - memory free : 1618971496
2011-12-23 09:38:06,786 [Statistics Logger] INFO com.terracottatech.dso - memory used : 439776408
2011-12-23 09:38:06,786 [Statistics Logger] INFO com.terracottatech.dso - memory max : 2058747904
The rest of the client log looks like what I posted. Any help would be appreciated.
Vincent
|
|
|
|
12/28/2011 17:13:23
|
dpope
master
Joined: 12/11/2007 10:16:33
Messages: 74
Location: Wesley Chapel, NC
Offline
|
I don't see anything odd in the snippets you provided.
Can you zip up the logs and attach them to the thread?
|
|
|
|
01/03/2012 08:53:55
|
tcdpope
neo
Joined: 01/03/2012 08:53:14
Messages: 3
Offline
|
Are you still having the issue?
|
|
|
|
01/06/2012 07:22:02
|
gekko959
neo
Joined: 12/08/2011 12:45:44
Messages: 6
Offline
|
Yes, still having the issue. Am looking closely at locking.
Vincent
|
|
|
|
01/08/2012 22:53:19
|
sivam1
neo
Joined: 01/08/2012 22:44:58
Messages: 3
Offline
|
I see Terracotta client threads are getting locked at the Terracotta Server and they are not getting released. Here is the error log.
2011-12-13 00:35:05,295 [L2_L1:TCComm Main Selector Thread_R (listen 0:0:0:0:0:0:0:0:9510)] INFO com.tc.net.core.CoreNIOServices - IOException attempting to finish socket connection
java.net.ConnectException: Connection timed out
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:658)
at com.tc.net.core.CoreNIOServices$CommThread.selectLoop(CoreNIOServices.java:607)
at com.tc.net.core.CoreNIOServices$CommThread.run(CoreNIOServices.java:286)
2011-12-13 00:35:05,296 [L2_L1:TCComm Main Selector Thread_R (listen 0:0:0:0:0:0:0:0:9510)] INFO com.tc.net.core.TCConnectionManager - error event on connection com.tc.net.core.TCConnectionJDK14@1127369403: connected: false, closed: false connect=[no connect time] idle=21002ms [0 read, 0 write]: Connection timed out
2011-12-13 00:35:05,298 [L2_L1:TCComm Main Selector Thread_R (listen 0:0:0:0:0:0:0:0:9510)] INFO com.tc.net.protocol.transport.ConnectionHealthCheckerImpl. DSO Server - Config Factor updated from 1 to 3
2011-12-13 00:35:05,298 [L2_L1:TCComm Main Selector Thread_R (listen 0:0:0:0:0:0:0:0:9510)] INFO com.tc.net.protocol.transport.ConnectionHealthCheckerImpl. DSO Server - HealthCheckCallbackPort verification FAILED for 0.0.0.0:44618(callbackport: 33920)
2011-12-13 00:35:05,314 [L2_L1:TCComm Main Selector Thread_R (listen 0:0:0:0:0:0:0:0:9510)] INFO com.tc.net.core.CoreNIOServices - IOException attempting to finish socket connection
-----
----
2011-12-13 00:53:57,019 [RemoteJMXProcessor-6279] WARN com.tc.management.beans.TCServerInfo - shutdown is invoked by MBean
2011-12-13 00:53:58,020 [TCServerInfo shutdown timer] INFO com.terracottatech.console - Server exiting...
2011-12-13 00:53:58,021 [CommonShutDownHook] INFO com.terracottatech.dso - L2 Exiting...
----Thread dump logs
"tomcat-myrz-411" daemon prio=10 tid=0x00007f4545141000 nid=0x70a5 waiting on condition [0x00007f451a875000]
java.lang.Thread.State: WAITING (parking)
at sun.misc.Unsafe.park(Native Method)
- parking to wait for <0x000000078e6bee30> (a java.util.concurrent.Semaphore$NonfairSync)
at java.util.concurrent.locks.LockSupport.park(LockSupport.java:158)
at java.util.concurrent.locks.AbstractQueuedSynchronizer.parkAndCheckInterrupt(AbstractQueuedSynchronizer.java:811)
at java.util.concurrent.locks.AbstractQueuedSynchronizer.doAcquireSharedInterruptibly(AbstractQueuedSynchronizer.java:969)
at java.util.concurrent.locks.AbstractQueuedSynchronizer.acquireSharedInterruptibly(AbstractQueuedSynchronizer.java:1281)
at java.util.concurrent.Semaphore.acquire(Semaphore.java:286)
at com.tc.object.locks.LockStateNode$PendingLockHold.park(LockStateNode.java:179)
at com.tc.object.locks.ClientLockImpl.acquireQueued(ClientLockImpl.java:723)
|
|
|
|
01/08/2012 23:01:05
|
sivam1
neo
Joined: 01/08/2012 22:44:58
Messages: 3
Offline
|
I see no option to use the below code in terracotta-client.config in version 3.4.0. to avoid locking and allow re-entry of the client threads to connect the TC server again.
<locks>
<!-- annotation locking expressions -->
<autolock>
<method-expression>@org.terracotta.annotations.AutolockWrite * *(..)</method-expression>
<lock-level>write</lock-level>
</autolock>
<autolock auto-synchronized="true">
<method-expression>@org.terracotta.annotations.AutolockWriteAutoSync * *(..)</method-expression>
<lock-level>write</lock-level>
</autolock>
<autolock>
<method-expression>@org.terracotta.annotations.AutolockRead * *(..)</method-expression>
<lock-level>read</lock-level>
</autolock>
<autolock auto-synchronized="true">
<method-expression>@org.terracotta.annotations.AutolockReadAutoSync * *(..)</method-expression>
<lock-level>read</lock-level>
</autolock>
<autolock>
<method-expression>@org.terracotta.annotations.AutolockSynchronousWrite * *(..)</method-expression>
<lock-level>synchronous-write</lock-level>
</autolock>
<autolock auto-synchronized="true">
<method-expression>@org.terracotta.annotations.AutolockSynchronousWriteAutoSync * *(..)</method-expression>
<lock-level>synchronous-write</lock-level>
</autolock>
<autolock>
<method-expression>@org.terracotta.annotations.AutolockConcurrent * *(..)</method-expression>
<lock-level>concurrent</lock-level>
</autolock>
</locks>
|
|
|
|
01/09/2012 21:35:39
|
sivam1
neo
Joined: 01/08/2012 22:44:58
Messages: 3
Offline
|
I see some resolution has posted in the forums for version 3.5.1.
Here is the link for solution in version 3.5.1 [http://forums.terracotta.org/forums/posts/list/5129.page]
|
|
|
|
02/20/2013 08:55:04
|
jbriant
neo
Joined: 02/20/2013 08:48:03
Messages: 1
Offline
|
We had this problem and it proved to be caused by Spring locking the HttpSession object. This caused a deadlock.
The solution was to use org.springframework.web.util.HttpSessionMutexListener.
Doing so causes Spring to use an attribute of the HttpSession rather than the session itself as the lock, and this causes the Terracotta lock to happen first, resulting in proper synchronization.
|
|
|
|
|
|
|
|
![[Logo]](../../templates/default/images/logo.png){kind=logo}
![[Search]](../../templates/default/images/icon_mini_search.gif){kind=icon}
![[Recent Topics]](../../templates/default/images/icon_mini_recentTopics.gif){kind=icon}
![[Members]](../../templates/default/images/icon_mini_members.gif){kind=icon}
![[Groups]](../../templates/default/images/icon_mini_groups.gif){kind=icon}
![[Register]](../../templates/default/images/icon_mini_register.gif){kind=icon}
Register![[Login]](../../templates/default/images/icon_mini_login.gif){kind=icon}
Login
![[Up]](../../templates/default/images/icon_up.gif){kind=icon}
