Databroadcasting with Terracotta

Questions and Answers on installation, deployment, management, locking, tranasactions of Servoy Application Server

Databroadcasting with Terracotta

Postby antonio » Mon Nov 12, 2012 9:28 am

Anyone got much experience with Terracotta?
I'm trying out purely for databroadcasting between two instances of servoy (not for load balancing), on a Debian Linux server with 12 GB of RAM
It works just fine for days at a time, but then the databroadcasting dies. Both servoy clients are alive and well, I can see them writing to MySQL, but each is unaware of the datachanges made by the other. Restarting servoy server without restarting Terracotta will often fix it.

What might cause this? I'm seeing some warnings in terracotta-server.log but these are happening many times a day without the databroadcasting falling over. e.g.
WARN tc.operator.event - NODE : localhost:9510 Subsystem: MEMORY_MANAGER Message: Current Memory usage(92%) crossed critical threshold(90%).


Databroadcasting died sometime between 16:50 and 17:00 in the logs below

terracotta-server.log
Code: Select all
2012-11-12 16:23:49,973 [Statistics Logger] INFO com.terracottatech.dso - memory free : 221.216827 MB
2012-11-12 16:23:49,973 [Statistics Logger] INFO com.terracottatech.dso - memory used : 275.720673 MB
2012-11-12 16:23:49,973 [Statistics Logger] INFO com.terracottatech.dso - memory max : 496.937500 MB
2012-11-12 16:23:58,431 [Server Map Periodic Evictor] INFO tc.operator.event - NODE : localhost:9510  Subsystem: DCV2 Message: DCV2 Eviction - Time taken (msecs)=0, Number of entries evicted=0, Number of segments over threshold=0, Total Overshoot=0
2012-11-12 16:23:58,431 [Server Map Periodic Evictor] INFO com.tc.objectserver.impl.ServerMapEvictionStatsManager - Server Map Periodic eviction - Time taken (msecs): 0, Number of segments under threshold: 0, Number of segments over threshold: 0, Total overshoot: 0, Total number of samples requested: 0, Number of segments where eviction happened: 0, Total number of evicted entries: 0
2012-11-12 16:26:46,505 [WorkerThread(managed_object_request_stage, 0, 0)] INFO com.tc.objectserver.handler.ManagedObjectRequestHandler -  Number of repeated/wasted lookups : 1600000
2012-11-12 16:26:46,507 [WorkerThread(managed_object_request_stage, 3, 3)] INFO com.tc.objectserver.handler.ManagedObjectRequestHandler -  Number of repeated/wasted lookups : 1600000
2012-11-12 16:26:46,511 [WorkerThread(managed_object_request_stage, 3, 3)] INFO com.tc.objectserver.handler.ManagedObjectRequestHandler -  Number of repeated/wasted lookups : 1600000
2012-11-12 16:38:49,972 [Statistics Logger] INFO com.terracottatech.dso - memory free : 164.553955 MB
2012-11-12 16:38:49,972 [Statistics Logger] INFO com.terracottatech.dso - memory used : 325.446045 MB
2012-11-12 16:38:49,972 [Statistics Logger] INFO com.terracottatech.dso - memory max : 490.000000 MB
2012-11-12 16:41:28,577 [TC Memory Monitor] WARN tc.operator.event - NODE : localhost:9510  Subsystem: MEMORY_MANAGER Message: Current Memory usage(92%) crossed critical threshold(90%).
2012-11-12 16:53:49,973 [Statistics Logger] INFO com.terracottatech.dso - memory free : 133.155716 MB
2012-11-12 16:53:49,973 [Statistics Logger] INFO com.terracottatech.dso - memory used : 355.031784 MB
2012-11-12 16:53:49,973 [Statistics Logger] INFO com.terracottatech.dso - memory max : 488.187500 MB
2012-11-12 16:53:58,430 [Server Map Periodic Evictor] INFO tc.operator.event - NODE : localhost:9510  Subsystem: DCV2 Message: DCV2 Eviction - Time taken (msecs)=0, Number of entries evicted=0, Number of segments over threshold=0, Total Overshoot=0
2012-11-12 16:53:58,431 [Server Map Periodic Evictor] INFO com.tc.objectserver.impl.ServerMapEvictionStatsManager - Server Map Periodic eviction - Time taken (msecs): 0, Number of segments under threshold: 0, Number of segments over threshold: 0, Total overshoot: 0, Total number of samples requested: 0, Number of segments where eviction happened: 0, Total number of evicted entries: 0
2012-11-12 17:08:37,952 [WorkerThread(garbage_collect_stage, 0)] INFO tc.operator.event - NODE : localhost:9510  Subsystem: DGC Message: DGC[ 102 ] started.
2012-11-12 17:08:49,972 [Statistics Logger] INFO com.terracottatech.dso - memory free : 117.682968 MB
2012-11-12 17:08:49,973 [Statistics Logger] INFO com.terracottatech.dso - memory used : 366.129532 MB
2012-11-12 17:08:49,973 [Statistics Logger] INFO com.terracottatech.dso - memory max : 483.812500 MB
2012-11-12 17:09:08,487 [WorkerThread(garbage_collect_stage, 0)] INFO com.tc.objectserver.dgc.impl.MarkAndSweepGarbageCollector - DGC[ 102 ] complete : GarbageCollectionInfo [ Iteration = 102 ] =  type  = FULL_GC startTime = 1352700517952 begin object count = 3916043 end object count = 307309 markStageTime = 28328 pauseStageTime = 242 totalMarkCycleTime = 30535 candidate garabage  count = 3627675 actual garbage count = 3627675 pre rescue count = 3914713 rescue1Time = 27967 rescue 1 Count = 3627675 rescue2Time = 242
2012-11-12 17:09:14,200 [WorkerThread(gc_delete_from_disk_stage, 0)] INFO com.tc.objectserver.persistence.db.DBPersistorImpl - Removed 5000 objects in 771 ms.
2012-11-12 17:09:15,473 [WorkerThread(gc_delete_from_disk_stage, 0)] INFO com.tc.objectserver.persistence.db.DBPersistorImpl - Removed 5000 objects in 305 ms.
2012-11-12 17:09:21,551 [WorkerThread(gc_delete_from_disk_stage, 0)] INFO com.tc.objectserver.persistence.db.DBPersistorImpl - Removed 5000 objects in 314 ms.
2012-11-12 17:09:23,143 [WorkerThread(gc_delete_from_disk_stage, 0)] INFO com.tc.objectserver.persistence.db.DBPersistorImpl - Removed 5000 objects in 435 ms.
2012-11-12 17:09:38,316 [WorkerThread(gc_delete_from_disk_stage, 0)] INFO com.tc.objectserver.persistence.db.DBPersistorImpl - Removed 5000 objects in 325 ms.
2012-11-12 17:09:38,713 [WorkerThread(gc_delete_from_disk_stage, 0)] INFO com.tc.objectserver.persistence.db.DBPersistorImpl - Removed 5000 objects in 397 ms.
2012-11-12 17:09:49,340 [WorkerThread(gc_delete_from_disk_stage, 0)] INFO tc.operator.event - NODE : localhost:9510  Subsystem: DGC Message: DGC[ 102 ] finished. Begin Count : 3,916,043 Collected : 3,627,675 Time Taken : 71,388 ms Live Objects : 325,045
2012-11-12 17:11:28,578 [TC Memory Monitor] WARN tc.operator.event - NODE : localhost:9510  Subsystem: MEMORY_MANAGER Message: Current Memory usage(92%) crossed critical threshold(90%).
2012-11-12 17:23:49,972 [Statistics Logger] INFO com.terracottatech.dso - memory free : 248.999077 MB
2012-11-12 17:23:49,972 [Statistics Logger] INFO com.terracottatech.dso - memory used : 236.125923 MB
2012-11-12 17:23:49,972 [Statistics Logger] INFO com.terracottatech.dso - memory max : 485.125000 MB
2012-11-12 17:23:58,430 [Server Map Periodic Evictor] INFO tc.operator.event - NODE : localhost:9510  Subsystem: DCV2 Message: DCV2 Eviction - Time taken (msecs)=0, Number of entries evicted=0, Number of segments over threshold=0, Total Overshoot=0
2012-11-12 17:23:58,430 [Server Map Periodic Evictor] INFO com.tc.objectserver.impl.ServerMapEvictionStatsManager - Server Map Periodic eviction - Time taken (msecs): 0, Number of segments under threshold: 0, Number of segments over threshold: 0, Total overshoot: 0, Total number of samples requested: 0, Number of segments where eviction happened: 0, Total number of evicted entries: 0


Servoy32 terracotta-client.log
Code: Select all
2012-11-12 16:38:59,577 [Statistics Logger] INFO com.terracottatech.dso - memory free : 190.859726 MB
2012-11-12 16:38:59,578 [Statistics Logger] INFO com.terracottatech.dso - memory used : 264.265274 MB
2012-11-12 16:38:59,578 [Statistics Logger] INFO com.terracottatech.dso - memory max : 455.125000 MB
2012-11-12 16:39:17,709 [ClientLockManager LockGC] INFO com.tc.object.locks.ClientLockManager - ClientID[0]: Lock GC collected 5 garbage locks
2012-11-12 16:40:17,709 [ClientLockManager LockGC] INFO com.tc.object.locks.ClientLockManager - ClientID[0]: Lock GC collected 2 garbage locks
2012-11-12 16:41:30,302 [pool-1699-thread-1] INFO com.tc.object.locks.ClientLockImpl - Retrying flush on DsoLockID(ObjectID=[87530579]) as flush level moved from READ to WRITE during flush operation
2012-11-12 16:41:30,302 [TaskExecuter[11]] INFO com.tc.object.locks.ClientLockImpl - Retrying flush on DsoLockID(ObjectID=[87530579]) as flush level moved from READ to WRITE during flush operation
2012-11-12 16:42:17,709 [ClientLockManager LockGC] INFO com.tc.object.locks.ClientLockManager - ClientID[0]: Lock GC collected 6 garbage locks
2012-11-12 16:45:17,710 [ClientLockManager LockGC] INFO com.tc.object.locks.ClientLockManager - ClientID[0]: Lock GC collected 6 garbage locks
2012-11-12 16:46:17,709 [ClientLockManager LockGC] INFO com.tc.object.locks.ClientLockManager - ClientID[0]: Lock GC collected 1 garbage locks
2012-11-12 16:47:17,710 [ClientLockManager LockGC] INFO com.tc.object.locks.ClientLockManager - ClientID[0]: Lock GC collected 6 garbage locks
2012-11-12 16:48:17,709 [ClientLockManager LockGC] INFO com.tc.object.locks.ClientLockManager - ClientID[0]: Lock GC collected 1 garbage locks
2012-11-12 16:50:17,709 [ClientLockManager LockGC] INFO com.tc.object.locks.ClientLockManager - ClientID[0]: Lock GC collected 3 garbage locks
2012-11-12 16:51:17,709 [ClientLockManager LockGC] INFO com.tc.object.locks.ClientLockManager - ClientID[0]: Lock GC collected 1 garbage locks
2012-11-12 16:53:37,217 [pool-1-thread-2] INFO com.tc.object.tx.RemoteTransactionManagerImpl - ClientID[0]: TransactionID=[-1] : Took more than 1000ms to add to sequencer  : 1540 ms
2012-11-12 16:53:59,577 [Statistics Logger] INFO com.terracottatech.dso - memory free : 159.455223 MB
2012-11-12 16:53:59,577 [Statistics Logger] INFO com.terracottatech.dso - memory used : 315.857277 MB
2012-11-12 16:53:59,577 [Statistics Logger] INFO com.terracottatech.dso - memory max : 475.312500 MB
2012-11-12 16:55:17,710 [ClientLockManager LockGC] INFO com.tc.object.locks.ClientLockManager - ClientID[0]: Lock GC collected 3 garbage locks
2012-11-12 16:56:17,711 [ClientLockManager LockGC] INFO com.tc.object.locks.ClientLockManager - ClientID[0]: Lock GC collected 2 garbage locks
2012-11-12 16:57:17,711 [ClientLockManager LockGC] INFO com.tc.object.locks.ClientLockManager - ClientID[0]: Lock GC collected 1 garbage locks
2012-11-12 16:59:17,712 [ClientLockManager LockGC] INFO com.tc.object.locks.ClientLockManager - ClientID[0]: Lock GC collected 4 garbage locks
2012-11-12 17:02:00,757 [TaskExecuter[2]] INFO com.tc.object.locks.ClientLockImpl - Retrying flush on DsoLockID(ObjectID=[1001]) as flush level moved from READ to WRITE during flush operation
2012-11-12 17:02:00,758 [pool-1-thread-2] INFO com.tc.object.locks.ClientLockImpl - Retrying flush on DsoLockID(ObjectID=[1001]) as flush level moved from READ to WRITE during flush operation
2012-11-12 17:03:17,715 [ClientLockManager LockGC] INFO com.tc.object.locks.ClientLockManager - ClientID[0]: Lock GC collected 2 garbage locks
2012-11-12 17:04:17,713 [ClientLockManager LockGC] INFO com.tc.object.locks.ClientLockManager - ClientID[0]: Lock GC collected 12 garbage locks
2012-11-12 17:05:17,713 [ClientLockManager LockGC] INFO com.tc.object.locks.ClientLockManager - ClientID[0]: Lock GC collected 6 garbage locks
2012-11-12 17:06:17,713 [ClientLockManager LockGC] INFO com.tc.object.locks.ClientLockManager - ClientID[0]: Lock GC collected 1 garbage locks
2012-11-12 17:07:17,713 [ClientLockManager LockGC] INFO com.tc.object.locks.ClientLockManager - ClientID[0]: Lock GC collected 1 garbage locks
2012-11-12 17:08:17,714 [ClientLockManager LockGC] INFO com.tc.object.locks.ClientLockManager - ClientID[0]: Lock GC collected 1 garbage locks
2012-11-12 17:08:59,578 [Statistics Logger] INFO com.terracottatech.dso - memory free : 86.226685 MB
2012-11-12 17:08:59,578 [Statistics Logger] INFO com.terracottatech.dso - memory used : 401.648315 MB
2012-11-12 17:08:59,578 [Statistics Logger] INFO com.terracottatech.dso - memory max : 487.875000 MB
2012-11-12 17:10:17,713 [ClientLockManager LockGC] INFO com.tc.object.locks.ClientLockManager - ClientID[0]: Lock GC collected 1 garbage locks
2012-11-12 17:11:18,386 [ClientLockManager LockGC] INFO com.tc.object.locks.ClientLockManager - ClientID[0]: Lock GC collected 1 garbage locks
2012-11-12 17:12:08,301 [MessagePreHandler] INFO com.tc.object.tx.RemoteTransactionManagerImpl - ClientID[0]: TransactionID=[6574362] : Took more than 1000ms to add to sequencer  : 1275 ms
2012-11-12 17:12:18,385 [ClientLockManager LockGC] INFO com.tc.object.locks.ClientLockManager - ClientID[0]: Lock GC collected 2 garbage locks
2012-11-12 17:13:18,386 [ClientLockManager LockGC] INFO com.tc.object.locks.ClientLockManager - ClientID[0]: Lock GC collected 7 garbage locks
2012-11-12 17:14:18,385 [ClientLockManager LockGC] INFO com.tc.object.locks.ClientLockManager - ClientID[0]: Lock GC collected 1 garbage locks
2012-11-12 17:15:18,386 [ClientLockManager LockGC] INFO com.tc.object.locks.ClientLockManager - ClientID[0]: Lock GC collected 4 garbage locks
2012-11-12 17:16:18,385 [ClientLockManager LockGC] INFO com.tc.object.locks.ClientLockManager - ClientID[0]: Lock GC collected 2 garbage locks
2012-11-12 17:17:18,386 [ClientLockManager LockGC] INFO com.tc.object.locks.ClientLockManager - ClientID[0]: Lock GC collected 6 garbage locks
2012-11-12 17:18:18,386 [ClientLockManager LockGC] INFO com.tc.object.locks.ClientLockManager - ClientID[0]: Lock GC collected 1 garbage locks
2012-11-12 17:19:18,386 [ClientLockManager LockGC] INFO com.tc.object.locks.ClientLockManager - ClientID[0]: Lock GC collected 1 garbage locks
2012-11-12 17:20:18,386 [ClientLockManager LockGC] INFO com.tc.object.locks.ClientLockManager - ClientID[0]: Lock GC collected 3 garbage locks
2012-11-12 17:21:18,386 [ClientLockManager LockGC] INFO com.tc.object.locks.ClientLockManager - ClientID[0]: Lock GC collected 4 garbage locks
2012-11-12 17:22:18,386 [ClientLockManager LockGC] INFO com.tc.object.locks.ClientLockManager - ClientID[0]: Lock GC collected 2 garbage locks
2012-11-12 17:23:18,387 [ClientLockManager LockGC] INFO com.tc.object.locks.ClientLockManager - ClientID[0]: Lock GC collected 4 garbage locks
2012-11-12 17:23:59,578 [Statistics Logger] INFO com.terracottatech.dso - memory free : 80.608398 MB
2012-11-12 17:23:59,578 [Statistics Logger] INFO com.terracottatech.dso - memory used : 392.141602 MB
2012-11-12 17:23:59,578 [Statistics Logger] INFO com.terracottatech.dso - memory max : 472.750000 MB
2012-11-12 17:24:18,387 [ClientLockManager LockGC] INFO com.tc.object.locks.ClientLockManager - ClientID[0]: Lock GC collected 3 garbage locks
2012-11-12 17:25:18,388 [ClientLockManager LockGC] INFO com.tc.object.locks.ClientLockManager - ClientID[0]: Lock GC collected 1 garbage locks
2012-11-12 17:26:18,389 [ClientLockManager LockGC] INFO com.tc.object.locks.ClientLockManager - ClientID[0]: Lock GC collected 9 garbage locks


Servoy64 terracotta-client.log
Code: Select all
2012-11-12 16:31:06,421 [Statistics Logger] INFO com.terracottatech.dso - memory free : 1585.806114 MB
2012-11-12 16:31:06,421 [Statistics Logger] INFO com.terracottatech.dso - memory used : 1466.756386 MB
2012-11-12 16:31:06,421 [Statistics Logger] INFO com.terracottatech.dso - memory max : 3052.562500 MB
2012-11-12 16:31:24,211 [ClientLockManager LockGC] INFO com.tc.object.locks.ClientLockManager - ClientID[3]: Lock GC collected 2 garbage locks
2012-11-12 16:32:24,211 [ClientLockManager LockGC] INFO com.tc.object.locks.ClientLockManager - ClientID[3]: Lock GC collected 2 garbage locks
2012-11-12 16:33:24,212 [ClientLockManager LockGC] INFO com.tc.object.locks.ClientLockManager - ClientID[3]: Lock GC collected 2 garbage locks
2012-11-12 16:34:24,213 [ClientLockManager LockGC] INFO com.tc.object.locks.ClientLockManager - ClientID[3]: Lock GC collected 4 garbage locks
2012-11-12 16:35:24,212 [ClientLockManager LockGC] INFO com.tc.object.locks.ClientLockManager - ClientID[3]: Lock GC collected 8 garbage locks
2012-11-12 16:36:24,213 [ClientLockManager LockGC] INFO com.tc.object.locks.ClientLockManager - ClientID[3]: Lock GC collected 2 garbage locks
2012-11-12 16:37:24,213 [ClientLockManager LockGC] INFO com.tc.object.locks.ClientLockManager - ClientID[3]: Lock GC collected 2 garbage locks
2012-11-12 16:38:24,214 [ClientLockManager LockGC] INFO com.tc.object.locks.ClientLockManager - ClientID[3]: Lock GC collected 3 garbage locks
2012-11-12 16:39:24,214 [ClientLockManager LockGC] INFO com.tc.object.locks.ClientLockManager - ClientID[3]: Lock GC collected 6 garbage locks
2012-11-12 16:40:24,213 [ClientLockManager LockGC] INFO com.tc.object.locks.ClientLockManager - ClientID[3]: Lock GC collected 3 garbage locks
2012-11-12 16:41:24,214 [ClientLockManager LockGC] INFO com.tc.object.locks.ClientLockManager - ClientID[3]: Lock GC collected 7 garbage locks
2012-11-12 16:41:30,335 [TaskExecuter[12]] INFO com.tc.object.locks.ClientLockImpl - Retrying flush on DsoLockID(ObjectID=[1001]) as flush level moved from READ to WRITE during flush operation
2012-11-12 16:41:30,335 [pool-1-thread-1] INFO com.tc.object.locks.ClientLockImpl - Retrying flush on DsoLockID(ObjectID=[1001]) as flush level moved from READ to WRITE during flush operation
2012-11-12 16:41:30,335 [pool-1-thread-2] INFO com.tc.object.locks.ClientLockImpl - Retrying flush on DsoLockID(ObjectID=[1001]) as flush level moved from READ to WRITE during flush operation
2012-11-12 16:41:30,337 [http-8080-12] INFO com.tc.object.locks.ClientLockImpl - Retrying flush on DsoLockID(ObjectID=[1001]) as flush level moved from READ to WRITE during flush operation
2012-11-12 16:42:24,213 [ClientLockManager LockGC] INFO com.tc.object.locks.ClientLockManager - ClientID[3]: Lock GC collected 4 garbage locks
2012-11-12 16:43:24,213 [ClientLockManager LockGC] INFO com.tc.object.locks.ClientLockManager - ClientID[3]: Lock GC collected 2 garbage locks
2012-11-12 16:44:24,214 [ClientLockManager LockGC] INFO com.tc.object.locks.ClientLockManager - ClientID[3]: Lock GC collected 4 garbage locks
2012-11-12 16:45:24,213 [ClientLockManager LockGC] INFO com.tc.object.locks.ClientLockManager - ClientID[3]: Lock GC collected 5 garbage locks
2012-11-12 16:46:06,422 [Statistics Logger] INFO com.terracottatech.dso - memory free : 1441.976227 MB
2012-11-12 16:46:06,422 [Statistics Logger] INFO com.terracottatech.dso - memory used : 1620.523773 MB
2012-11-12 16:46:06,422 [Statistics Logger] INFO com.terracottatech.dso - memory max : 3062.500000 MB
2012-11-12 16:46:24,214 [ClientLockManager LockGC] INFO com.tc.object.locks.ClientLockManager - ClientID[3]: Lock GC collected 2 garbage locks
2012-11-12 16:47:24,213 [ClientLockManager LockGC] INFO com.tc.object.locks.ClientLockManager - ClientID[3]: Lock GC collected 5 garbage locks
2012-11-12 16:48:24,213 [ClientLockManager LockGC] INFO com.tc.object.locks.ClientLockManager - ClientID[3]: Lock GC collected 5 garbage locks
2012-11-12 16:49:24,214 [ClientLockManager LockGC] INFO com.tc.object.locks.ClientLockManager - ClientID[3]: Lock GC collected 7 garbage locks
2012-11-12 16:50:24,213 [ClientLockManager LockGC] INFO com.tc.object.locks.ClientLockManager - ClientID[3]: Lock GC collected 1 garbage locks
2012-11-12 16:51:23,642 [http-8080-27] INFO com.tc.object.locks.ClientLockImpl - Retrying flush on DsoLockID(ObjectID=[85691698]) as flush level moved from READ to WRITE during flush operation
2012-11-12 16:51:24,214 [ClientLockManager LockGC] INFO com.tc.object.locks.ClientLockManager - ClientID[3]: Lock GC collected 3 garbage locks
2012-11-12 16:51:55,108 [http-8080-19] INFO com.tc.object.locks.ClientLockImpl - Retrying flush on DsoLockID(ObjectID=[83076985]) as flush level moved from READ to WRITE during flush operation
2012-11-12 16:51:55,164 [http-8080-19] INFO com.tc.object.locks.ClientLockImpl - Retrying flush on DsoLockID(ObjectID=[83076985]) as flush level moved from READ to WRITE during flush operation
2012-11-12 16:52:24,215 [ClientLockManager LockGC] INFO com.tc.object.locks.ClientLockManager - ClientID[3]: Lock GC collected 4 garbage locks
2012-11-12 16:53:24,216 [ClientLockManager LockGC] INFO com.tc.object.locks.ClientLockManager - ClientID[3]: Lock GC collected 2 garbage locks
2012-11-12 16:54:24,215 [ClientLockManager LockGC] INFO com.tc.object.locks.ClientLockManager - ClientID[3]: Lock GC collected 4 garbage locks
2012-11-12 16:55:24,216 [ClientLockManager LockGC] INFO com.tc.object.locks.ClientLockManager - ClientID[3]: Lock GC collected 3 garbage locks
2012-11-12 16:55:52,606 [MessagePreHandler] INFO com.tc.object.locks.ClientLockImpl - Retrying flush on DsoLockID(ObjectID=[72638634]) as flush level moved from READ to WRITE during flush operation
2012-11-12 16:56:24,215 [ClientLockManager LockGC] INFO com.tc.object.locks.ClientLockManager - ClientID[3]: Lock GC collected 2 garbage locks
2012-11-12 16:57:24,216 [ClientLockManager LockGC] INFO com.tc.object.locks.ClientLockManager - ClientID[3]: Lock GC collected 4 garbage locks
2012-11-12 16:58:24,215 [ClientLockManager LockGC] INFO com.tc.object.locks.ClientLockManager - ClientID[3]: Lock GC collected 4 garbage locks
2012-11-12 16:59:24,216 [ClientLockManager LockGC] INFO com.tc.object.locks.ClientLockManager - ClientID[3]: Lock GC collected 4 garbage locks
2012-11-12 17:00:24,217 [ClientLockManager LockGC] INFO com.tc.object.locks.ClientLockManager - ClientID[3]: Lock GC collected 7 garbage locks
2012-11-12 17:00:44,611 [http-8080-1] INFO com.tc.object.locks.ClientLockImpl - Retrying flush on DsoLockID(ObjectID=[88353517]) as flush level moved from READ to WRITE during flush operation
2012-11-12 17:01:06,421 [Statistics Logger] INFO com.terracottatech.dso - memory free : 1870.187050 MB
2012-11-12 17:01:06,421 [Statistics Logger] INFO com.terracottatech.dso - memory used : 1190.812950 MB
2012-11-12 17:01:06,421 [Statistics Logger] INFO com.terracottatech.dso - memory max : 3061.000000 MB
2012-11-12 17:01:24,168 [http-8080-7] INFO com.tc.object.locks.ClientLockImpl - Retrying flush on DsoLockID(ObjectID=[88248877]) as flush level moved from READ to WRITE during flush operation
2012-11-12 17:01:24,216 [ClientLockManager LockGC] INFO com.tc.object.locks.ClientLockManager - ClientID[3]: Lock GC collected 7 garbage locks
2012-11-12 17:02:24,217 [ClientLockManager LockGC] INFO com.tc.object.locks.ClientLockManager - ClientID[3]: Lock GC collected 3 garbage locks
2012-11-12 17:03:24,216 [ClientLockManager LockGC] INFO com.tc.object.locks.ClientLockManager - ClientID[3]: Lock GC collected 4 garbage locks
2012-11-12 17:04:24,216 [ClientLockManager LockGC] INFO com.tc.object.locks.ClientLockManager - ClientID[3]: Lock GC collected 5 garbage locks
2012-11-12 17:05:24,217 [ClientLockManager LockGC] INFO com.tc.object.locks.ClientLockManager - ClientID[3]: Lock GC collected 4 garbage locks
2012-11-12 17:06:24,217 [ClientLockManager LockGC] INFO com.tc.object.locks.ClientLockManager - ClientID[3]: Lock GC collected 2 garbage locks
2012-11-12 17:07:24,216 [ClientLockManager LockGC] INFO com.tc.object.locks.ClientLockManager - ClientID[3]: Lock GC collected 2 garbage locks
2012-11-12 17:07:37,022 [http-8080-29] INFO com.tc.object.locks.ClientLockImpl - Retrying flush on DsoLockID(ObjectID=[86962721]) as flush level moved from READ to WRITE during flush operation
2012-11-12 17:08:24,217 [ClientLockManager LockGC] INFO com.tc.object.locks.ClientLockManager - ClientID[3]: Lock GC collected 3 garbage locks
2012-11-12 17:09:24,217 [ClientLockManager LockGC] INFO com.tc.object.locks.ClientLockManager - ClientID[3]: Lock GC collected 6 garbage locks
2012-11-12 17:10:24,216 [ClientLockManager LockGC] INFO com.tc.object.locks.ClientLockManager - ClientID[3]: Lock GC collected 2 garbage locks
2012-11-12 17:11:24,217 [ClientLockManager LockGC] INFO com.tc.object.locks.ClientLockManager - ClientID[3]: Lock GC collected 3 garbage locks
2012-11-12 17:12:24,218 [ClientLockManager LockGC] INFO com.tc.object.locks.ClientLockManager - ClientID[3]: Lock GC collected 5 garbage locks
2012-11-12 17:13:24,217 [ClientLockManager LockGC] INFO com.tc.object.locks.ClientLockManager - ClientID[3]: Lock GC collected 4 garbage locks
2012-11-12 17:14:24,218 [ClientLockManager LockGC] INFO com.tc.object.locks.ClientLockManager - ClientID[3]: Lock GC collected 5 garbage locks
2012-11-12 17:15:24,217 [ClientLockManager LockGC] INFO com.tc.object.locks.ClientLockManager - ClientID[3]: Lock GC collected 4 garbage locks
2012-11-12 17:15:55,061 [http-8080-26] INFO com.tc.object.locks.ClientLockImpl - Retrying flush on DsoLockID(ObjectID=[88727199]) as flush level moved from READ to WRITE during flush operation
2012-11-12 17:16:06,422 [Statistics Logger] INFO com.terracottatech.dso - memory free : 1339.809471 MB
2012-11-12 17:16:06,422 [Statistics Logger] INFO com.terracottatech.dso - memory used : 1689.878029 MB
2012-11-12 17:16:06,422 [Statistics Logger] INFO com.terracottatech.dso - memory max : 3029.687500 MB
2012-11-12 17:16:24,223 [ClientLockManager LockGC] INFO com.tc.object.locks.ClientLockManager - ClientID[3]: Lock GC collected 5 garbage locks
2012-11-12 17:18:24,223 [ClientLockManager LockGC] INFO com.tc.object.locks.ClientLockManager - ClientID[3]: Lock GC collected 3 garbage locks
2012-11-12 17:19:24,224 [ClientLockManager LockGC] INFO com.tc.object.locks.ClientLockManager - ClientID[3]: Lock GC collected 5 garbage locks
2012-11-12 17:20:24,223 [ClientLockManager LockGC] INFO com.tc.object.locks.ClientLockManager - ClientID[3]: Lock GC collected 4 garbage locks
2012-11-12 17:21:24,224 [ClientLockManager LockGC] INFO com.tc.object.locks.ClientLockManager - ClientID[3]: Lock GC collected 3 garbage locks
2012-11-12 17:22:24,223 [ClientLockManager LockGC] INFO com.tc.object.locks.ClientLockManager - ClientID[3]: Lock GC collected 4 garbage locks
2012-11-12 17:23:24,224 [ClientLockManager LockGC] INFO com.tc.object.locks.ClientLockManager - ClientID[3]: Lock GC collected 4 garbage locks
2012-11-12 17:24:24,225 [ClientLockManager LockGC] INFO com.tc.object.locks.ClientLockManager - ClientID[3]: Lock GC collected 7 garbage locks
2012-11-12 17:24:44,837 [http-8080-4] INFO com.tc.object.locks.ClientLockImpl - Retrying flush on DsoLockID(ObjectID=[88805220]) as flush level moved from READ to WRITE during flush operation
2012-11-12 17:25:24,224 [ClientLockManager LockGC] INFO com.tc.object.locks.ClientLockManager - ClientID[3]: Lock GC collected 2 garbage locks
2012-11-12 17:26:24,224 [ClientLockManager LockGC] INFO com.tc.object.locks.ClientLockManager - ClientID[3]: Lock GC collected 3 garbage locks
2012-11-12 17:27:24,224 [ClientLockManager LockGC] INFO com.tc.object.locks.ClientLockManager - ClientID[3]: Lock GC collected 2 garbage locks
2012-11-12 17:28:24,224 [ClientLockManager LockGC] INFO com.tc.object.locks.ClientLockManager - ClientID[3]: Lock GC collected 2 garbage locks
Tony
Servoy 8 - 2022.03 LTS
antonio
 
Posts: 638
Joined: Sun Apr 02, 2006 2:14 am
Location: Australia

Re: Databroadcasting with Terracotta

Postby Andrei Costescu » Tue Nov 13, 2012 3:03 pm

After databroadcasting "dies", does it remain dead, or does it come back after a few minutes?

You can try to add <property name="l2.objectmanager.dgc.young.enabled" value="true" /> inside the <tc-properties> of your tc-config.xml.
DGC takes a long time to execute... the distributed garbage-collection interval can also be changed. You can lower it to see if that makes a difference.

Further reading for terracotta cluster tuning (you must make an account to see it): http://www.terracotta.org/confluence/display/docs/DSO+Tuning+Guide.
Andrei Costescu
Servoy
Andrei Costescu
 
Posts: 1018
Joined: Tue Jun 26, 2007 3:14 pm

Re: Databroadcasting with Terracotta

Postby antonio » Tue Nov 13, 2012 3:17 pm

Thanks Andrei,

It seems to remain dead. I've increased the RAM settings, so far no recurrences. I'll try some of the tuning you've suggested if it recurs.

Tony
Tony
Servoy 8 - 2022.03 LTS
antonio
 
Posts: 638
Joined: Sun Apr 02, 2006 2:14 am
Location: Australia

Re: Databroadcasting with Terracotta

Postby Andrei Costescu » Tue Nov 13, 2012 4:26 pm

If you see it happening again check for any relevant exceptions in the log files of the 2 servers. A thread stack dump from the 2 servers might help (or not) diagnose the problem - after making a change that requires databroadcast. Also check the logs you posted above exactly before and after doing an operation that requires databroadcast to see if it generates any new entries.
Andrei Costescu
Servoy
Andrei Costescu
 
Posts: 1018
Joined: Tue Jun 26, 2007 3:14 pm

Re: Databroadcasting with Terracotta

Postby antonio » Mon Nov 19, 2012 11:32 am

Databroadcasting to Servoy64 was working at 16:30 and died by 16:50. There's nothing exciting in the terracotta-server.log until 17:46 when I restarted servoy64 and databroadcasting resumed, without restarting either TC or Servoy32.
Here's the terracotta-server.log
Code: Select all
2012-11-19 16:25:28,780 [Statistics Logger] INFO com.terracottatech.dso - memory free : 442.414284 MB
2012-11-19 16:25:28,780 [Statistics Logger] INFO com.terracottatech.dso - memory used : 572.335716 MB
2012-11-19 16:25:28,780 [Statistics Logger] INFO com.terracottatech.dso - memory max : 1014.750000 MB
2012-11-19 16:25:36,923 [Server Map Periodic Evictor] INFO tc.operator.event - NODE : localhost:9510  Subsystem: DCV2 Message: DCV2 Eviction - Time taken (msecs)=0, Number of entries evicted=0, Number of segments over threshold=0, Total Overshoot=0
2012-11-19 16:25:36,923 [Server Map Periodic Evictor] INFO com.tc.objectserver.impl.ServerMapEvictionStatsManager - Server Map Periodic eviction - Time taken (msecs): 0, Number of segments under threshold: 0, Number of segments over threshold: 0, Total overshoot: 0, Total number of samples requested: 0, Number of segments where eviction happened: 0, Total number of evicted entries: 0
2012-11-19 16:40:28,780 [Statistics Logger] INFO com.terracottatech.dso - memory free : 359.594040 MB
2012-11-19 16:40:28,780 [Statistics Logger] INFO com.terracottatech.dso - memory used : 614.968460 MB
2012-11-19 16:40:28,780 [Statistics Logger] INFO com.terracottatech.dso - memory max : 974.562500 MB
2012-11-19 16:50:11,350 [TC Memory Monitor] WARN tc.operator.event - NODE : localhost:9510  Subsystem: MEMORY_MANAGER Message: Current Memory usage(90%) crossed critical threshold(90%).
2012-11-19 16:55:28,779 [Statistics Logger] INFO com.terracottatech.dso - memory free : 155.172150 MB
2012-11-19 16:55:28,779 [Statistics Logger] INFO com.terracottatech.dso - memory used : 829.702850 MB
2012-11-19 16:55:28,779 [Statistics Logger] INFO com.terracottatech.dso - memory max : 984.875000 MB
2012-11-19 16:55:36,924 [Server Map Periodic Evictor] INFO tc.operator.event - NODE : localhost:9510  Subsystem: DCV2 Message: DCV2 Eviction - Time taken (msecs)=0, Number of entries evicted=0, Number of segments over threshold=0, Total Overshoot=0
2012-11-19 16:55:36,924 [Server Map Periodic Evictor] INFO com.tc.objectserver.impl.ServerMapEvictionStatsManager - Server Map Periodic eviction - Time taken (msecs): 0, Number of segments under threshold: 0, Number of segments over threshold: 0, Total overshoot: 0, Total number of samples requested: 0, Number of segments where eviction happened: 0, Total number of evicted entries: 0
2012-11-19 17:00:24,335 [WorkerThread(garbage_collect_stage, 0)] INFO tc.operator.event - NODE : localhost:9510  Subsystem: DGC Message: DGC[ 95 ] started.
2012-11-19 17:02:55,437 [WorkerThread(garbage_collect_stage, 0)] INFO com.tc.objectserver.dgc.impl.MarkAndSweepGarbageCollector - DGC[ 95 ] complete : GarbageCollectionInfo [ Iteration = 95 ] =  type  = FULL_GC startTime = 1353304824335 begin object count = 4465361 end object count = 1514329 markStageTime = 149186 pauseStageTime = 333 totalMarkCycleTime = 151102 candidate garabage  count = 2971853 actual garbage count = 2971853 pre rescue count = 4464204 rescue1Time = 148917 rescue 1 Count = 2971853 rescue2Time = 333
2012-11-19 17:02:57,128 [WorkerThread(gc_delete_from_disk_stage, 0)] INFO com.tc.objectserver.persistence.db.DBPersistorImpl - Removed 5000 objects in 657 ms.
2012-11-19 17:03:02,843 [WorkerThread(gc_delete_from_disk_stage, 0)] INFO com.tc.objectserver.persistence.db.DBPersistorImpl - Removed 5000 objects in 364 ms.
2012-11-19 17:03:12,456 [WorkerThread(gc_delete_from_disk_stage, 0)] INFO com.tc.objectserver.persistence.db.DBPersistorImpl - Removed 5000 objects in 348 ms.
2012-11-19 17:03:35,256 [WorkerThread(gc_delete_from_disk_stage, 0)] INFO tc.operator.event - NODE : localhost:9510  Subsystem: DGC Message: DGC[ 95 ] finished. Begin Count : 4,465,361 Collected : 2,971,853 Time Taken : 190,921 ms Live Objects : 1,514,694
2012-11-19 17:05:10,760 [L2_L1:TCComm Main Selector Thread_R (listen 0:0:0:0:0:0:0:0:9510)] WARN com.tc.net.protocol.transport.ConnectionHealthCheckerImpl. DSO Server - localhost:46380 might be in Long GC. Ping-probe cycles completed since last reply : 1
2012-11-19 17:10:28,780 [Statistics Logger] INFO com.terracottatech.dso - memory free : 120.145187 MB
2012-11-19 17:10:28,780 [Statistics Logger] INFO com.terracottatech.dso - memory used : 875.167313 MB
2012-11-19 17:10:28,780 [Statistics Logger] INFO com.terracottatech.dso - memory max : 995.312500 MB
2012-11-19 17:25:28,780 [Statistics Logger] INFO com.terracottatech.dso - memory free : 306.836311 MB
2012-11-19 17:25:28,780 [Statistics Logger] INFO com.terracottatech.dso - memory used : 680.413689 MB
2012-11-19 17:25:28,780 [Statistics Logger] INFO com.terracottatech.dso - memory max : 987.250000 MB
2012-11-19 17:25:36,925 [Server Map Periodic Evictor] INFO tc.operator.event - NODE : localhost:9510  Subsystem: DCV2 Message: DCV2 Eviction - Time taken (msecs)=0, Number of entries evicted=0, Number of segments over threshold=0, Total Overshoot=0
2012-11-19 17:25:36,925 [Server Map Periodic Evictor] INFO com.tc.objectserver.impl.ServerMapEvictionStatsManager - Server Map Periodic eviction - Time taken (msecs): 0, Number of segments under threshold: 0, Number of segments over threshold: 0, Total overshoot: 0, Total number of samples requested: 0, Number of segments where eviction happened: 0, Total number of evicted entries: 0
2012-11-19 17:28:54,969 [TC Memory Monitor] WARN tc.operator.event - NODE : localhost:9510  Subsystem: MEMORY_MANAGER Message: Current Memory usage(90%) crossed critical threshold(90%).
2012-11-19 17:40:28,779 [Statistics Logger] INFO com.terracottatech.dso - memory free : 478.011169 MB
2012-11-19 17:40:28,779 [Statistics Logger] INFO com.terracottatech.dso - memory used : 492.551331 MB
2012-11-19 17:40:28,780 [Statistics Logger] INFO com.terracottatech.dso - memory max : 970.562500 MB
2012-11-19 17:46:34,132 [L2_L1:TCWorkerComm # 5_R] INFO com.tc.net.protocol.transport.ConnectionPolicyImpl - Removed connection [4] from jvm a5d9b927-f8c8-4fe0-acaa-268c760d3080-13b0ac4268c
2012-11-19 17:46:34,132 [L2_L1:TCWorkerComm # 5_R] INFO com.tc.net.protocol.transport.ConnectionPolicyImpl - De-allocated connection license for jvm a5d9b927-f8c8-4fe0-acaa-268c760d3080-13b0ac4268c; ConnectionPolicy[maxConnections=2147483647, connectedJvmCount=1]
2012-11-19 17:46:34,132 [L2_L1:TCWorkerComm # 5_R] INFO com.tc.net.protocol.transport.ConnectionHealthCheckerImpl: DSO Server - Connection to [localhost:46380] CLOSED. Health Monitoring for this node is now disabled.
2012-11-19 17:46:34,135 [L2_L1:TCWorkerComm # 5_R] WARN com.tc.net.protocol.transport.ServerMessageTransport - ConnectionID(4.6f34179124074b41b294d21a3c71ffd3.a5d9b927-f8c8-4fe0-acaa-268c760d3080-13b0ac4268c)[]: CLOSE EVENT : com.tc.net.core.TCConnectionImpl@893747557: connected: false, closed: true local=127.0.0.1:9510 remote=127.0.0.1:46380 connect=[Sat Nov 17 06:48:47 EST 2012] idle=4ms [4235598452 read, 7671516661 write]. STATUS : CLOSED
2012-11-19 17:46:34,135 [L2_L1:TCWorkerComm # 5_R] WARN com.tc.net.protocol.transport.ServerMessageTransport - ConnectionID(4.6f34179124074b41b294d21a3c71ffd3.a5d9b927-f8c8-4fe0-acaa-268c760d3080-13b0ac4268c)[]: closing down connection - com.tc.net.core.TCConnectionImpl@893747557: connected: false, closed: true local=127.0.0.1:9510 remote=127.0.0.1:46380 connect=[Sat Nov 17 06:48:47 EST 2012] idle=4ms [4235598452 read, 7671516661 write]
2012-11-19 17:46:34,135 [L2_L1:TCWorkerComm # 5_R] WARN com.tc.net.protocol.transport.ServerMessageTransport - ConnectionID(4.6f34179124074b41b294d21a3c71ffd3.a5d9b927-f8c8-4fe0-acaa-268c760d3080-13b0ac4268c)[]: Can only close an open connection
2012-11-19 17:46:34,141 [L2_L1:TCWorkerComm # 5_R] WARN tc.operator.event - NODE : localhost:9510  Subsystem: CLUSTER_TOPOLOGY Message: Node ClientID[4] left the cluster
2012-11-19 17:46:34,142 [WorkerThread(channel_life_cycle_stage, 0)] INFO com.tc.objectserver.handler.ChannelLifeCycleHandler - : Received transport disconnect.  Shutting down client ClientID[4]
2012-11-19 17:46:34,142 [L2_L1:TCWorkerComm # 5_R] INFO com.tc.net.core.CoreNIOServices - selection key cancelled key@1649286391
2012-11-19 17:46:34,142 [WorkerThread(channel_life_cycle_stage, 0)] INFO com.tc.objectserver.persistence.db.TransactionStoreImpl - shutdownClient() : Removing txns from DB : 2427
2012-11-19 17:46:40,090 [L2_L1:TCComm Main Selector Thread_R (listen 0:0:0:0:0:0:0:0:9510)] INFO com.tc.net.protocol.transport.ServerMessageTransport - ConnectionID(5.6f34179124074b41b294d21a3c71ffd3.e992efd1-568a-4a64-b76f-5a3253729acc-13b176b2ab3)[]: Attaching new connection: com.tc.net.core.TCConnectionImpl@2074973519: connected: true, closed: false local=127.0.0.1:9510 remote=127.0.0.1:41829 connect=[Mon Nov 19 17:46:40 EST 2012] idle=0ms [0 read, 0 write]
2012-11-19 17:46:40,096 [L2_L1:TCComm Main Selector Thread_R (listen 0:0:0:0:0:0:0:0:9510)] INFO com.tc.net.protocol.transport.ConnectionPolicyImpl - Allocated connection license for jvm e992efd1-568a-4a64-b76f-5a3253729acc-13b176b2ab3; ConnectionPolicy[maxConnections=2147483647, connectedJvmCount=2]
2012-11-19 17:46:40,097 [L2_L1:TCComm Main Selector Thread_R (listen 0:0:0:0:0:0:0:0:9510)] INFO com.tc.net.protocol.transport.ConnectionPolicyImpl - New connection [5] from jvm e992efd1-568a-4a64-b76f-5a3253729acc-13b176b2ab3
2012-11-19 17:46:40,097 [L2_L1:TCComm Main Selector Thread_R (listen 0:0:0:0:0:0:0:0:9510)] INFO com.tc.net.protocol.transport.ServerStackProvider - User null successfully authenticated
2012-11-19 17:46:40,097 [L2_L1:TCComm Main Selector Thread_R (listen 0:0:0:0:0:0:0:0:9510)] INFO com.tc.net.core.CoreNIOServices - selection key cancelled key@1092990200
2012-11-19 17:46:40,152 [L2_L1:TCWorkerComm # 6_R] INFO com.tc.net.protocol.transport.ConnectionHealthCheckerImpl. DSO Server - Health monitoring agent started for localhost:41829
2012-11-19 17:46:40,177 [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 PASSED for localhost:41829(callbackport: 52428)
2012-11-19 17:46:40,200 [WorkerThread(client_handshake_stage, 0)] INFO com.tc.objectserver.handshakemanager.ServerClientHandshakeManager - Client connected ClientID[5]
2012-11-19 17:46:40,201 [WorkerThread(client_handshake_stage, 0)] INFO tc.operator.event - NODE : localhost:9510  Subsystem: CLUSTER_TOPOLOGY Message: Node ClientID[5] joined the cluster
2012-11-19 17:46:40,213 [WorkerThread(jmxremote_tunnel_stage, 0)] INFO com.tc.management.remote.protocol.terracotta.ClientTunnelingEventHandler - L1[ChannelID=[5]] notified us that their JMX server is now available
2012-11-19 17:49:02,979 [WorkerThread(managed_object_request_stage, 3, 3)] INFO com.tc.objectserver.handler.ManagedObjectRequestHandler -  Number of repeated/wasted lookups : 1200000
2012-11-19 17:49:02,980 [WorkerThread(managed_object_request_stage, 5, 5)] INFO com.tc.objectserver.handler.ManagedObjectRequestHandler -  Number of repeated/wasted lookups : 1200000
2012-11-19 17:55:28,779 [Statistics Logger] INFO com.terracottatech.dso - memory free : 416.325378 MB
2012-11-19 17:55:28,779 [Statistics Logger] INFO com.terracottatech.dso - memory used : 558.549622 MB
2012-11-19 17:55:28,779 [Statistics Logger] INFO com.terracottatech.dso - memory max : 974.875000 MB
2012-11-19 17:55:36,925 [Server Map Periodic Evictor] INFO tc.operator.event - NODE : localhost:9510  Subsystem: DCV2 Message: DCV2 Eviction - Time taken (msecs)=0, Number of entries evicted=0, Number of segments over threshold=0, Total Overshoot=0
2012-11-19 17:55:36,925 [Server Map Periodic Evictor] INFO com.tc.objectserver.impl.ServerMapEvictionStatsManager - Server Map Periodic eviction - Time taken (msecs): 0, Number of segments under threshold: 0, Number of segments over threshold: 0, Total overshoot: 0, Total number of samples requested: 0, Number of segments where eviction happened: 0, Total number of evicted entries: 0
2012-11-19 18:02:55,441 [WorkerThread(garbage_collect_stage, 0)] INFO tc.operator.event - NODE : localhost:9510  Subsystem: DGC Message: DGC[ 96 ] started.
2012-11-19 18:02:57,725 [WorkerThread(garbage_collect_stage, 0)] INFO com.tc.objectserver.dgc.impl.MarkAndSweepGarbageCollector - DGC[ 96 ] complete : GarbageCollectionInfo [ Iteration = 96 ] =  type  = FULL_GC startTime = 1353308575441 begin object count = 2452862 end object count = 71358 markStageTime = 526 pauseStageTime = 99 totalMarkCycleTime = 2284 candidate garabage  count = 2381504 actual garbage count = 2381504 pre rescue count = 2451901 rescue1Time = 432 rescue 1 Count = 2381504 rescue2Time = 99
2012-11-19 18:03:03,073 [WorkerThread(gc_delete_from_disk_stage, 0)] INFO com.tc.objectserver.persistence.db.DBPersistorImpl - Removed 5000 objects in 614 ms.
2012-11-19 18:03:03,526 [WorkerThread(gc_delete_from_disk_stage, 0)] INFO com.tc.objectserver.persistence.db.DBPersistorImpl - Removed 5000 objects in 452 ms.
2012-11-19 18:03:04,348 [WorkerThread(gc_delete_from_disk_stage, 0)] INFO com.tc.objectserver.persistence.db.DBPersistorImpl - Removed 5000 objects in 318 ms.
2012-11-19 18:03:05,255 [WorkerThread(gc_delete_from_disk_stage, 0)] INFO com.tc.objectserver.persistence.db.DBPersistorImpl - Removed 5000 objects in 312 ms.
2012-11-19 18:03:05,649 [WorkerThread(gc_delete_from_disk_stage, 0)] INFO com.tc.objectserver.persistence.db.DBPersistorImpl - Removed 5000 objects in 393 ms.
2012-11-19 18:03:21,166 [WorkerThread(gc_delete_from_disk_stage, 0)] INFO tc.operator.event - NODE : localhost:9510  Subsystem: DGC Message: DGC[ 96 ] finished. Begin Count : 2,452,862 Collected : 2,381,504 Time Taken : 25,725 ms Live Objects : 71,597
2012-11-19 18:10:28,780 [Statistics Logger] INFO com.terracottatech.dso - memory free : 218.175400 MB
2012-11-19 18:10:28,780 [Statistics Logger] INFO com.terracottatech.dso - memory used : 792.199600 MB
2012-11-19 18:10:28,780 [Statistics Logger] INFO com.terracottatech.dso - memory max : 1010.375000 MB
2012-11-19 18:25:28,779 [Statistics Logger] INFO com.terracottatech.dso - memory free : 180.311165 MB
2012-11-19 18:25:28,780 [Statistics Logger] INFO com.terracottatech.dso - memory used : 824.501335 MB
2012-11-19 18:25:28,780 [Statistics Logger] INFO com.terracottatech.dso - memory max : 1004.812500 MB
2012-11-19 18:25:36,924 [Server Map Periodic Evictor] INFO tc.operator.event - NODE : localhost:9510  Subsystem: DCV2 Message: DCV2 Eviction - Time taken (msecs)=0, Number of entries evicted=0, Number of segments over threshold=0, Total Overshoot=0
2012-11-19 18:25:36,925 [Server Map Periodic Evictor] INFO com.tc.objectserver.impl.ServerMapEvictionStatsManager - Server Map Periodic eviction - Time taken (msecs): 0, Number of segments under threshold: 0, Number of segments over threshold: 0, Total overshoot: 0, Total number of samples requested: 0, Number of segments where eviction happened: 0, Total number of evicted entries: 0
2012-11-19 18:40:28,779 [Statistics Logger] INFO com.terracottatech.dso - memory free : 206.179337 MB
2012-11-19 18:40:28,779 [Statistics Logger] INFO com.terracottatech.dso - memory used : 767.258163 MB
2012-11-19 18:40:28,779 [Statistics Logger] INFO com.terracottatech.dso - memory max : 973.437500 MB
2012-11-19 18:55:28,780 [Statistics Logger] INFO com.terracottatech.dso - memory free : 232.961700 MB
2012-11-19 18:55:28,780 [Statistics Logger] INFO com.terracottatech.dso - memory used : 743.288300 MB
2012-11-19 18:55:28,780 [Statistics Logger] INFO com.terracottatech.dso - memory max : 976.250000 MB
2012-11-19 18:55:36,924 [Server Map Periodic Evictor] INFO tc.operator.event - NODE : localhost:9510  Subsystem: DCV2 Message: DCV2 Eviction - Time taken (msecs)=0, Number of entries evicted=0, Number of segments over threshold=0, Total Overshoot=0
2012-11-19 18:55:36,924 [Server Map Periodic Evictor] INFO com.tc.objectserver.impl.ServerMapEvictionStatsManager - Server Map Periodic eviction - Time taken (msecs): 0, Number of segments under threshold: 0, Number of segments over threshold: 0, Total overshoot: 0, Total number of samples requested: 0, Number of segments where eviction happened: 0, Total number of evicted entries: 0
2012-11-19 19:02:57,729 [WorkerThread(garbage_collect_stage, 0)] INFO tc.operator.event - NODE : localhost:9510  Subsystem: DGC Message: DGC[ 97 ] started.
2012-11-19 19:02:58,493 [WorkerThread(garbage_collect_stage, 0)] INFO com.tc.objectserver.dgc.impl.MarkAndSweepGarbageCollector - DGC[ 97 ] complete : GarbageCollectionInfo [ Iteration = 97 ] =  type  = FULL_GC startTime = 1353312177729 begin object count = 488338 end object count = 17902 markStageTime = 144 pauseStageTime = 17 totalMarkCycleTime = 764 candidate garabage  count = 470436 actual garbage count = 470436 pre rescue count = 487280 rescue1Time = 109 rescue 1 Count = 470436 rescue2Time = 17
2012-11-19 19:02:59,618 [WorkerThread(gc_delete_from_disk_stage, 0)] INFO tc.operator.event - NODE : localhost:9510  Subsystem: DGC Message: DGC[ 97 ] finished. Begin Count : 488,338 Collected : 470,436 Time Taken : 1,888 ms Live Objects : 17,976
2012-11-19 19:06:56,602 [TC Memory Monitor] WARN tc.operator.event - NODE : localhost:9510  Subsystem: MEMORY_MANAGER Message: Current Memory usage(90%) crossed critical threshold(90%).
2012-11-19 19:10:28,779 [Statistics Logger] INFO com.terracottatech.dso - memory free : 262.305969 MB
2012-11-19 19:10:28,780 [Statistics Logger] INFO com.terracottatech.dso - memory used : 717.694031 MB
2012-11-19 19:10:28,780 [Statistics Logger] INFO com.terracottatech.dso - memory max : 980.000000 MB
2012-11-19 19:25:28,779 [Statistics Logger] INFO com.terracottatech.dso - memory free : 116.245316 MB
2012-11-19 19:25:28,779 [Statistics Logger] INFO com.terracottatech.dso - memory used : 836.754684 MB
2012-11-19 19:25:28,779 [Statistics Logger] INFO com.terracottatech.dso - memory max : 953.000000 MB
2012-11-19 19:25:36,925 [Server Map Periodic Evictor] INFO tc.operator.event - NODE : localhost:9510  Subsystem: DCV2 Message: DCV2 Eviction - Time taken (msecs)=0, Number of entries evicted=0, Number of segments over threshold=0, Total Overshoot=0
2012-11-19 19:25:36,925 [Server Map Periodic Evictor] INFO com.tc.objectserver.impl.ServerMapEvictionStatsManager - Server Map Periodic eviction - Time taken (msecs): 0, Number of segments under threshold: 0, Number of segments over threshold: 0, Total overshoot: 0, Total number of samples requested: 0, Number of segments where eviction happened: 0, Total number of evicted entries: 0


The terracotta-client.log for Servoy32 has a message Retrying flush on DsoLockID(ObjectID=[1005]) as flush level moved from READ to WRITE during flush operation then Retrying flush on DsoLockID(ObjectID=[1005]) as flush level moved from READ to WRITE during flush operation repeatedly until servoy64 restart.
Code: Select all
2012-11-19 16:28:01,787 [Statistics Logger] INFO com.terracottatech.dso - memory free : 204.086891 MB
2012-11-19 16:28:01,788 [Statistics Logger] INFO com.terracottatech.dso - memory used : 271.225609 MB
2012-11-19 16:28:01,788 [Statistics Logger] INFO com.terracottatech.dso - memory max : 475.312500 MB
2012-11-19 16:28:06,532 [ClientLockManager LockGC] INFO com.tc.object.locks.ClientLockManager - ClientID[3]: Lock GC collected 2 garbage locks
2012-11-19 16:29:06,533 [ClientLockManager LockGC] INFO com.tc.object.locks.ClientLockManager - ClientID[3]: Lock GC collected 2 garbage locks
2012-11-19 16:30:06,532 [ClientLockManager LockGC] INFO com.tc.object.locks.ClientLockManager - ClientID[3]: Lock GC collected 2 garbage locks
2012-11-19 16:31:46,776 [pool-1-thread-1] INFO com.tc.object.locks.ClientLockImpl - Retrying flush on DsoLockID(ObjectID=[1005]) as flush level moved from READ to WRITE during flush operation
2012-11-19 16:31:46,778 [pool-1-thread-2] INFO com.tc.object.locks.ClientLockImpl - Retrying flush on DsoLockID(ObjectID=[1005]) as flush level moved from READ to WRITE during flush operation
2012-11-19 16:31:46,778 [pool-1-thread-3] INFO com.tc.object.locks.ClientLockImpl - Retrying flush on DsoLockID(ObjectID=[1005]) as flush level moved from READ to WRITE during flush operation
2012-11-19 16:31:49,622 [pool-718-thread-11] INFO com.tc.object.locks.ClientLockImpl - Retrying flush on DsoLockID(ObjectID=[51268043]) as flush level moved from READ to WRITE during flush operation
2012-11-19 16:31:49,622 [MessagePreHandler] INFO com.tc.object.locks.ClientLockImpl - Retrying flush on DsoLockID(ObjectID=[51268043]) as flush level moved from READ to WRITE during flush operation
2012-11-19 16:32:38,460 [pool-718-thread-11] INFO com.tc.object.locks.ClientLockImpl - Retrying flush on DsoLockID(ObjectID=[51268043]) as flush level moved from READ to WRITE during flush operation
2012-11-19 16:33:06,533 [ClientLockManager LockGC] INFO com.tc.object.locks.ClientLockManager - ClientID[3]: Lock GC collected 2 garbage locks
2012-11-19 16:33:07,684 [pool-718-thread-11] INFO com.tc.object.locks.ClientLockImpl - Retrying flush on DsoLockID(ObjectID=[51268043]) as flush level moved from READ to WRITE during flush operation
2012-11-19 16:34:06,534 [ClientLockManager LockGC] INFO com.tc.object.locks.ClientLockManager - ClientID[3]: Lock GC collected 1 garbage locks
2012-11-19 16:34:51,089 [WorkerThread(receive_transaction_stage, 0)] WARN com.tc.object.gtx.ClientGlobalTransactionManagerImpl - Current Low water Mark = GlobalTransactionID=[17575722] Server sent GlobalTransactionID=[17575722]
2012-11-19 16:34:51,090 [WorkerThread(receive_transaction_stage, 0)] WARN com.tc.object.gtx.ClientGlobalTransactionManagerImpl - Server didnt send a Low water mark higher than ALLOWED_LWM_DELTA for 10002 times. applied.size() = 10221 Resetting count.
2012-11-19 16:35:01,500 [WorkerThread(receive_transaction_stage, 0)] WARN com.tc.object.gtx.ClientGlobalTransactionManagerImpl - Current Low water Mark = GlobalTransactionID=[17592130] Server sent GlobalTransactionID=[17592130]
2012-11-19 16:35:01,500 [WorkerThread(receive_transaction_stage, 0)] WARN com.tc.object.gtx.ClientGlobalTransactionManagerImpl - Server didnt send a Low water mark higher than ALLOWED_LWM_DELTA for 10002 times. applied.size() = 10004 Resetting count.
2012-11-19 16:35:55,980 [WorkerThread(receive_transaction_stage, 0)] WARN com.tc.object.gtx.ClientGlobalTransactionManagerImpl - Current Low water Mark = GlobalTransactionID=[17638100] Server sent GlobalTransactionID=[17638100]
2012-11-19 16:35:55,981 [WorkerThread(receive_transaction_stage, 0)] WARN com.tc.object.gtx.ClientGlobalTransactionManagerImpl - Server didnt send a Low water mark higher than ALLOWED_LWM_DELTA for 10002 times. applied.size() = 10097 Resetting count.
2012-11-19 16:36:21,480 [WorkerThread(receive_transaction_stage, 0)] WARN com.tc.object.gtx.ClientGlobalTransactionManagerImpl - Current Low water Mark = GlobalTransactionID=[17649348] Server sent GlobalTransactionID=[17649348]


The terracotta-client.log for Servoy64 has similar messages and [MessagePreHandler] INFO messages which also turn up in servoy_log from 16:34 until servoy64 restart.
Code: Select all
2012-11-19 16:27:02,263 [ClientLockManager LockGC] INFO com.tc.object.locks.ClientLockManager - ClientID[4]: Lock GC collected 4 garbage locks
2012-11-19 16:28:02,262 [ClientLockManager LockGC] INFO com.tc.object.locks.ClientLockManager - ClientID[4]: Lock GC collected 3 garbage locks
2012-11-19 16:29:02,263 [ClientLockManager LockGC] INFO com.tc.object.locks.ClientLockManager - ClientID[4]: Lock GC collected 4 garbage locks
2012-11-19 16:30:02,263 [ClientLockManager LockGC] INFO com.tc.object.locks.ClientLockManager - ClientID[4]: Lock GC collected 4 garbage locks
2012-11-19 16:31:02,262 [ClientLockManager LockGC] INFO com.tc.object.locks.ClientLockManager - ClientID[4]: Lock GC collected 4 garbage locks
2012-11-19 16:31:31,581 [TaskExecuter[20]] INFO com.tc.object.tx.RemoteTransactionManagerImpl - ClientID[4]: TransactionID=[6211746] : Took more than 1000ms to add to sequencer  : 6347 ms
2012-11-19 16:32:02,262 [ClientLockManager LockGC] INFO com.tc.object.locks.ClientLockManager - ClientID[4]: Lock GC collected 4 garbage locks
2012-11-19 16:33:02,263 [ClientLockManager LockGC] INFO com.tc.object.locks.ClientLockManager - ClientID[4]: Lock GC collected 2 garbage locks
2012-11-19 16:33:47,643 [Statistics Logger] INFO com.terracottatech.dso - memory free : 2642.056847 MB
2012-11-19 16:33:47,643 [Statistics Logger] INFO com.terracottatech.dso - memory used : 1909.068153 MB
2012-11-19 16:33:47,643 [Statistics Logger] INFO com.terracottatech.dso - memory max : 4551.125000 MB
2012-11-19 16:34:02,262 [ClientLockManager LockGC] INFO com.tc.object.locks.ClientLockManager - ClientID[4]: Lock GC collected 4 garbage locks
2012-11-19 16:35:02,263 [ClientLockManager LockGC] INFO com.tc.object.locks.ClientLockManager - ClientID[4]: Lock GC collected 4 garbage locks
2012-11-19 16:35:02,619 [MessagePreHandler] INFO com.tc.object.locks.ClientLockImpl - Retrying flush on DsoLockID(ObjectID=[50096648]) as flush level moved from READ to WRITE during flush operation
2012-11-19 16:35:02,622 [http-8080-1] INFO com.tc.object.locks.ClientLockImpl - Retrying flush on DsoLockID(ObjectID=[50096648]) as flush level moved from READ to WRITE during flush operation
2012-11-19 16:35:02,639 [http-8080-7] INFO com.tc.object.locks.ClientLockImpl - Retrying flush on DsoLockID(ObjectID=[48128573]) as flush level moved from READ to WRITE during flush operation
2012-11-19 16:35:02,640 [MessagePreHandler] INFO com.tc.object.locks.ClientLockImpl - Retrying flush on DsoLockID(ObjectID=[48128573]) as flush level moved from READ to WRITE during flush operation
2012-11-19 16:36:02,262 [ClientLockManager LockGC] INFO com.tc.object.locks.ClientLockManager - ClientID[4]: Lock GC collected 3 garbage locks
2012-11-19 16:37:02,262 [ClientLockManager LockGC] INFO com.tc.object.locks.ClientLockManager - ClientID[4]: Lock GC collected 4 garbage locks
2012-11-19 16:38:00,186 [MessagePreHandler] INFO com.tc.object.locks.ClientLockImpl - Retrying flush on DsoLockID(ObjectID=[46035677]) as flush level moved from READ to WRITE during flush operation
2012-11-19 16:38:00,186 [http-8080-6] INFO com.tc.object.locks.ClientLockImpl - Retrying flush on DsoLockID(ObjectID=[46035677]) as flush level moved from READ to WRITE during flush operation
2012-11-19 16:38:00,285 [http-8080-6] INFO com.tc.object.locks.ClientLockImpl - Retrying flush on DsoLockID(ObjectID=[46035677]) as flush level moved from READ to WRITE during flush operation
2012-11-19 16:38:00,285 [MessagePreHandler] INFO com.tc.object.locks.ClientLockImpl - Retrying flush on DsoLockID(ObjectID=[46035677]) as flush level moved from READ to WRITE during flush operation
2012-11-19 16:38:02,263 [ClientLockManager LockGC] INFO com.tc.object.locks.ClientLockManager - ClientID[4]: Lock GC collected 3 garbage locks
2012-11-19 16:39:02,263 [ClientLockManager LockGC] INFO com.tc.object.locks.ClientLockManager - ClientID[4]: Lock GC collected 2 garbage locks
2012-11-19 16:40:32,108 [MessagePreHandler] INFO com.tc.object.locks.ClientLockImpl - Retrying flush on DsoLockID(ObjectID=[48956976]) as flush level moved from READ to WRITE during flush operation
2012-11-19 16:40:32,164 [MessagePreHandler] INFO com.tc.object.locks.ClientLockImpl - Retrying flush on DsoLockID(ObjectID=[48956976]) as flush level moved from READ to WRITE during flush operation
2012-11-19 16:40:47,642 [MessagePreHandler] INFO com.tc.object.locks.ClientLockImpl - Retrying flush on DsoLockID(ObjectID=[44728778]) as flush level moved from READ to WRITE during flush operation
2012-11-19 16:40:47,643 [MessageScheduler] INFO com.tc.object.locks.ClientLockImpl - Retrying flush on DsoLockID(ObjectID=[44728778]) as flush level moved from READ to WRITE during flush operation
2012-11-19 16:40:47,699 [MessagePreHandler] INFO com.tc.object.locks.ClientLockImpl - Retrying flush on DsoLockID(ObjectID=[44728778]) as flush level moved from READ to WRITE during flush operation
2012-11-19 16:40:47,699 [http-8080-20] INFO com.tc.object.locks.ClientLockImpl - Retrying flush on DsoLockID(ObjectID=[44728778]) as flush level moved from READ to WRITE during flush operation
2012-11-19 16:41:00,052 [TaskExecuter[2]] INFO com.tc.object.locks.ClientLockImpl - Retrying flush on DsoLockID(ObjectID=[39717415]) as flush level moved from READ to WRITE during flush operation
2012-11-19 16:41:00,053 [MessagePreHandler] INFO com.tc.object.locks.ClientLockImpl - Retrying flush on DsoLockID(ObjectID=[39717415]) as flush level moved from READ to WRITE during flush operation
2012-11-19 16:41:00,080 [MessagePreHandler] INFO com.tc.object.locks.ClientLockImpl - Retrying flush on DsoLockID(ObjectID=[44728778]) as flush level moved from READ to WRITE during flush operation
2012-11-19 16:41:00,083 [http-8080-14] INFO com.tc.object.locks.ClientLockImpl - Retrying flush on DsoLockID(ObjectID=[44728778]) as flush level moved from READ to WRITE during flush operation
2012-11-19 16:41:00,135 [http-8080-14] INFO com.tc.object.locks.ClientLockImpl - Retrying flush on DsoLockID(ObjectID=[44728778]) as flush level moved from READ to WRITE during flush operation
2012-11-19 16:41:00,136 [TaskExecuter[6]] INFO com.tc.object.locks.ClientLockImpl - Retrying flush on DsoLockID(ObjectID=[44728778]) as flush level moved from READ to WRITE during flush operation
2012-11-19 16:41:00,136 [MessagePreHandler] INFO com.tc.object.locks.ClientLockImpl - Retrying flush on DsoLockID(ObjectID=[44728778]) as flush level moved from READ to WRITE during flush operation
2012-11-19 16:41:01,802 [MessagePreHandler] INFO com.tc.object.locks.ClientLockImpl - Retrying flush on DsoLockID(ObjectID=[45376317]) as flush level moved from READ to WRITE during flush operation
2012-11-19 16:41:01,803 [http-8080-8] INFO com.tc.object.locks.ClientLockImpl - Retrying flush on DsoLockID(ObjectID=[45376317]) as flush level moved from READ to WRITE during flush operation
2012-11-19 16:41:02,263 [ClientLockManager LockGC] INFO com.tc.object.locks.ClientLockManager - ClientID[4]: Lock GC collected 3 garbage locks
2012-11-19 16:42:01,003 [MessageScheduler] INFO com.tc.object.locks.ClientLockImpl - Retrying flush on DsoLockID(ObjectID=[45376317]) as flush level moved from READ to WRITE during flush operation
2012-11-19 16:42:01,004 [MessagePreHandler] INFO com.tc.object.locks.ClientLockImpl - Retrying flush on DsoLockID(ObjectID=[45376317]) as flush level moved from READ to WRITE during flush operation
2012-11-19 16:42:01,004 [http-8080-27] INFO com.tc.object.locks.ClientLockImpl - Retrying flush on DsoLockID(ObjectID=[45376317]) as flush level moved from READ to WRITE during flush operation
2012-11-19 16:42:02,263 [ClientLockManager LockGC] INFO com.tc.object.locks.ClientLockManager - ClientID[4]: Lock GC collected 8 garbage locks
2012-11-19 16:43:02,264 [ClientLockManager LockGC] INFO com.tc.object.locks.ClientLockManager - ClientID[4]: Lock GC collected 3 garbage locks
2012-11-19 16:44:02,263 [ClientLockManager LockGC] INFO com.tc.object.locks.ClientLockManager - ClientID[4]: Lock GC collected 2 garbage locks
2012-11-19 16:45:02,264 [ClientLockManager LockGC] INFO com.tc.object.locks.ClientLockManager - ClientID[4]: Lock GC collected 2 garbage locks
2012-11-19 16:46:02,265 [ClientLockManager LockGC] INFO com.tc.object.locks.ClientLockManager - ClientID[4]: Lock GC collected 3 garbage locks
2012-11-19 16:47:02,265 [ClientLockManager LockGC] INFO com.tc.object.locks.ClientLockManager - ClientID[4]: Lock GC collected 10 garbage locks
2012-11-19 16:48:02,264 [ClientLockManager LockGC] INFO com.tc.object.locks.ClientLockManager - ClientID[4]: Lock GC collected 3 garbage locks
2012-11-19 16:48:47,642 [Statistics Logger] INFO com.terracottatech.dso - memory free : 1802.996117 MB
2012-11-19 16:48:47,642 [Statistics Logger] INFO com.terracottatech.dso - memory used : 2748.128883 MB
2012-11-19 16:48:47,642 [Statistics Logger] INFO com.terracottatech.dso - memory max : 4551.125000 MB
2012-11-19 16:49:02,265 [ClientLockManager LockGC] INFO com.tc.object.locks.ClientLockManager - ClientID[4]: Lock GC collected 2 garbage locks
2012-11-19 16:49:03,373 [TaskExecuter[32]] INFO com.tc.object.locks.ClientLockImpl - Retrying flush on DsoLockID(ObjectID=[46035677]) as flush level moved from READ to WRITE during flush operation
2012-11-19 16:49:03,374 [MessagePreHandler] INFO com.tc.object.locks.ClientLockImpl - Retrying flush on DsoLockID(ObjectID=[46035677]) as flush level moved from READ to WRITE during flush operation
2012-11-19 16:50:02,266 [ClientLockManager LockGC] INFO com.tc.object.locks.ClientLockManager - ClientID[4]: Lock GC collected 2 garbage locks
2012-11-19 16:50:11,517 [http-8080-28] INFO com.tc.object.locks.ClientLockImpl - Retrying flush on DsoLockID(ObjectID=[44728778]) as flush level moved from READ to WRITE during flush operation
2012-11-19 16:50:11,517 [MessagePreHandler] INFO com.tc.object.locks.ClientLockImpl - Retrying flush on DsoLockID(ObjectID=[44728778]) as flush level moved from READ to WRITE during flush operation
2012-11-19 16:51:01,485 [http-8080-6] INFO com.tc.object.locks.ClientLockImpl - Retrying flush on DsoLockID(ObjectID=[45589514]) as flush level moved from READ to WRITE during flush operation
2012-11-19 16:51:02,266 [ClientLockManager LockGC] INFO com.tc.object.locks.ClientLockManager - ClientID[4]: Lock GC collected 4 garbage locks
2012-11-19 16:51:57,624 [TaskExecuter[24]] INFO com.tc.object.locks.ClientLockImpl - Retrying flush on DsoLockID(ObjectID=[45589514]) as flush level moved from READ to WRITE during flush operation
2012-11-19 16:51:57,625 [MessageScheduler] INFO com.tc.object.locks.ClientLockImpl - Retrying flush on DsoLockID(ObjectID=[45589514]) as flush level moved from READ to WRITE during flush operation
2012-11-19 16:52:01,497 [MessagePreHandler] INFO com.tc.object.locks.ClientLockImpl - Retrying flush on DsoLockID(ObjectID=[51374927]) as flush level moved from READ to WRITE during flush operation
2012-11-19 16:52:02,265 [ClientLockManager LockGC] INFO com.tc.object.locks.ClientLockManager - ClientID[4]: Lock GC collected 2 garbage locks
2012-11-19 16:52:22,536 [TaskExecuter[3]] INFO com.tc.object.locks.ClientLockImpl - Retrying flush on DsoLockID(ObjectID=[51317656]) as flush level moved from READ to WRITE during flush operation
2012-11-19 16:52:22,536 [MessageScheduler] INFO com.tc.object.locks.ClientLockImpl - Retrying flush on DsoLockID(ObjectID=[51317656]) as flush level moved from READ to WRITE during flush operation
2012-11-19 16:52:22,617 [http-8080-27] INFO com.tc.object.locks.ClientLockImpl - Retrying flush on DsoLockID(ObjectID=[51317656]) as flush level moved from READ to WRITE during flush operation
2012-11-19 16:52:22,618 [MessagePreHandler] INFO com.tc.object.locks.ClientLockImpl - Retrying flush on DsoLockID(ObjectID=[51317656]) as flush level moved from READ to WRITE during flush operation
2012-11-19 16:53:02,265 [ClientLockManager LockGC] INFO com.tc.object.locks.ClientLockManager - ClientID[4]: Lock GC collected 2 garbage locks
2012-11-19 16:54:02,266 [ClientLockManager LockGC] INFO com.tc.object.locks.ClientLockManager - ClientID[4]: Lock GC collected 3 garbage locks
2012-11-19 16:55:02,265 [ClientLockManager LockGC] INFO com.tc.object.locks.ClientLockManager - ClientID[4]: Lock GC collected 3 garbage locks
2012-11-19 16:56:02,266 [ClientLockManager LockGC] INFO com.tc.object.locks.ClientLockManager - ClientID[4]: Lock GC collected 5 garbage locks
2012-11-19 16:57:02,266 [ClientLockManager LockGC] INFO com.tc.object.locks.ClientLockManager - ClientID[4]: Lock GC collected 4 garbage locks
2012-11-19 16:58:02,006 [TaskExecuter[25]] INFO com.tc.object.locks.ClientLockImpl - Retrying flush on DsoLockID(ObjectID=[46035677]) as flush level moved from READ to WRITE during flush operation
2012-11-19 16:58:02,006 [MessagePreHandler] INFO com.tc.object.locks.ClientLockImpl - Retrying flush on DsoLockID(ObjectID=[46035677]) as flush level moved from READ to WRITE during flush operation
2012-11-19 16:58:02,006 [MessageScheduler] INFO com.tc.object.locks.ClientLockImpl - Retrying flush on DsoLockID(ObjectID=[46035677]) as flush level moved from READ to WRITE during flush operation


servoy_log
Code: Select all
2012-11-19 16:33:00,830 WARN [http-8080-20] org.apache.wicket.request.target.component.listener.BehaviorRequestTarget - behavior not enabled; ignoring call. behavior: com.servoy.j2db.server.headlessclient.MainPage$1@6caf49ea at index: 1 on component: [Page class = com.servoy.j2db.server.headlessclient.MainPage, id = 5, version = 0, ajax = 1]
2012-11-19 16:33:31,829 WARN [http-8080-8] org.apache.wicket.request.target.component.listener.BehaviorRequestTarget - behavior not enabled; ignoring call. behavior: com.servoy.j2db.server.headlessclient.MainPage$1@66539f6b at index: 1 on component: [Page class = com.servoy.j2db.server.headlessclient.MainPage, id = 6, version = 0, ajax = 1]
2012-11-19 16:33:37,421 WARN [http-8080-17] org.apache.wicket.request.target.component.listener.BehaviorRequestTarget - behavior not enabled; ignoring call. behavior: com.servoy.j2db.server.headlessclient.MainPage$1@797f41da at index: 1 on component: [Page class = com.servoy.j2db.server.headlessclient.MainPage, id = 7, version = 0, ajax = 1]
2012-11-19 16:34:19,636 WARN [MessagePreHandler] com.servoy.j2db.util.Debug - Throwable
java.lang.NullPointerException
   at com.servoy.j2db.dataprocessing.ClientProxy.Zb(ClientProxy.java:26)
   at com.servoy.j2db.dataprocessing.ClientMessagePreQueueHandler.run(ClientMessagePreQueueHandler.java:7)
   at java.lang.Thread.run(Thread.java:662)
2012-11-19 16:34:22,066 WARN [MessagePreHandler] com.servoy.j2db.util.Debug - Throwable
java.lang.NullPointerException
   at com.servoy.j2db.dataprocessing.ClientProxy.Zb(ClientProxy.java:26)
   at com.servoy.j2db.dataprocessing.ClientMessagePreQueueHandler.run(ClientMessagePreQueueHandler.java:7)
   at java.lang.Thread.run(Thread.java:662)
2012-11-19 16:34:24,215 WARN [MessagePreHandler] com.servoy.j2db.util.Debug - Throwable
java.lang.NullPointerException
   at com.servoy.j2db.dataprocessing.ClientProxy.Zb(ClientProxy.java:26)
   at com.servoy.j2db.dataprocessing.ClientMessagePreQueueHandler.run(ClientMessagePreQueueHandler.java:7)
   at java.lang.Thread.run(Thread.java:662)
2012-11-19 16:34:27,895 WARN [MessagePreHandler] com.servoy.j2db.util.Debug - Throwable
java.lang.NullPointerException
2012-11-19 16:34:31,078 WARN [MessagePreHandler] com.servoy.j2db.util.Debug - Throwable
java.lang.NullPointerException
2012-11-19 16:34:31,869 WARN [http-8080-27] org.apache.wicket.request.target.component.listener.BehaviorRequestTarget - behavior not enabled; ignoring call. behavior: com.servoy.j2db.server.headlessclient.MainPage$1@605bf76c at index: 1 on component: [Page class = com.servoy.j2db.server.headlessclient.MainPage, id = 7, version = 0, ajax = 1]
2012-11-19 16:34:33,145 WARN [MessagePreHandler] com.servoy.j2db.util.Debug - Throwable
java.lang.NullPointerException
2012-11-19 16:34:33,691 WARN [http-8080-6] org.apache.wicket.request.target.component.listener.BehaviorRequestTarget - behavior not enabled; ignoring call. behavior: com.servoy.j2db.server.headlessclient.PageContributor$2@4cbe2ed2 at index: 1 on component: [MarkupContainer [Component id = contribution]]
2012-11-19 16:34:36,462 WARN [MessagePreHandler] com.servoy.j2db.util.Debug - Throwable
java.lang.NullPointerException
2012-11-19 16:34:40,273 WARN [MessagePreHandler] com.servoy.j2db.util.Debug - Throwable
java.lang.NullPointerException
2012-11-19 16:34:42,891 WARN [MessagePreHandler] com.servoy.j2db.util.Debug - Throwable
java.lang.NullPointerException
2012-11-19 16:34:44,482 WARN [http-8080-7] org.apache.wicket.request.target.component.listener.BehaviorRequestTarget - behavior not enabled; ignoring call. behavior: com.servoy.j2db.server.headlessclient.MainPage$1@52cca21f at index: 1 on component: [Page class = com.servoy.j2db.server.headlessclient.MainPage, id = 8, version = 0, ajax = 1]
2012-11-19 16:34:47,079 WARN [MessagePreHandler] com.servoy.j2db.util.Debug - Throwable
java.lang.NullPointerException
2012-11-19 16:34:51,406 WARN [MessagePreHandler] com.servoy.j2db.util.Debug - Throwable
java.lang.NullPointerException
2012-11-19 16:34:53,469 WARN [MessagePreHandler] com.servoy.j2db.util.Debug - Throwable
java.lang.NullPointerException
2012-11-19 16:34:56,149 WARN [MessagePreHandler] com.servoy.j2db.util.Debug - Throwable
java.lang.NullPointerException
2012-11-19 16:34:59,816 WARN [MessagePreHandler] com.servoy.j2db.util.Debug - Throwable
java.lang.NullPointerException
2012-11-19 16:35:03,820 WARN [MessagePreHandler] com.servoy.j2db.util.Debug - Throwable
java.lang.NullPointerException
2012-11-19 16:35:06,402 WARN [MessagePreHandler] com.servoy.j2db.util.Debug - Throwable
java.lang.NullPointerException
Attachments
Servoy32StackDump.txt
Servoy 32 Stack Dump
(50.39 KiB) Downloaded 250 times
Servoy64StackDump.txt
Servoy 64 Stack Dump
(83.22 KiB) Downloaded 241 times
Tony
Servoy 8 - 2022.03 LTS
antonio
 
Posts: 638
Joined: Sun Apr 02, 2006 2:14 am
Location: Australia


Return to Servoy Server

Who is online

Users browsing this forum: No registered users and 7 guests