[rules-dev] memory issue (memory leak?) on trunk (probably due true modify changes)

[Geoffrey De Smet]

Hi guys,

With great improvements usually come instability for a while :)
Trunk has memory issue, probably a memory leak of a small object.

I've run ExmaminationBenchmarkApp with the program arg "short" 3 times
with the exact same configuration (it is a 100% reproducible run):

1) Before the true modify changes with 512m max memory
Succeeds (100 steps but even 10000 steps work) with no slow down.

2) After true modify changes with 512m max memory
Fails after 27 steps, starts slowing down at 24 steps.

3) After true modify changes with 1024m max memory
Fails after 57 steps, starts slowing down at 54 steps.

Both 2) and 3) fail with the exception:
Exception in thread "main" java.lang.OutOfMemoryError: GC overhead limit 
exceeded

So it's not a heap space error or a perm space error, but a GC overhead 
limit instead. Literally this means it's doing more GC then running,
but 99% of the time this means that the heap is so full that the GC has 
little or no free space to work with.
This kind of memory leak happens when the iteration make 101 objects but 
only removes 100 objects and the iteration is run a lot (like 10000+ times).
You don't get a heap space error, because before that happens,
there is point where you have a garbaged collected free memory for 10 
objects and a ungarbaged collected free memory for 100 objects. At that 
point the GC is running over 98% of the time, which is a VM treshold and 
the error is thrown,
even though 10 iterations later you would get a heap space error.


Logs:

1)
TODO

2)
2010-03-13 09:28:36,973 [main] INFO  Step index (21), time spend (37245) 
taking step (323 {D180|S9} @ 9 {D210} + 5 {C65} => 52 {D210}) out of 
1402 accepted moves.
2010-03-13 09:28:38,454 [main] INFO  Step index (22), time spend (38727) 
taking step (367 {D190|S40} @ 28 {D210} + 5 {C65} => 19 {D210}) out of 
1366 accepted moves.
2010-03-13 09:28:39,903 [main] INFO  Step index (23), time spend (40176) 
taking step (230 {D120|S15} @ 7 {D210} + 3 {C60} => 12 {D210}) out of 
1366 accepted moves.
2010-03-13 09:28:43,901 [main] INFO  Step index (24), time spend (44174) 
taking step (190 {D90|S6} @ 1 {D210} + 3 {C60} <=> 205 {D120|S6} @ 8 
{D210} + 6 {C111}) out of 1392 accepted moves.
2010-03-13 09:28:50,631 [main] INFO  Step index (25), time spend (50904) 
taking step (420 {D180|S6} @ 46 {D210} + 2 {C129} => 25 {D210}) out of 
1396 accepted moves.
2010-03-13 09:29:06,184 [main] INFO  Step index (26), time spend (66457) 
taking step (211 {D180|S53} @ 15 {D210} + 0 {C260} => 23 {D210}) out of 
1383 accepted moves.
2010-03-13 09:29:46,589 [main] INFO  Step index (27), time spend 
(106862) taking step (39 {D120|S15} @ 50 {D210} + 2 {C129} => 43 {D210}) 
out of 1383 accepted moves.
Exception in thread "main" java.lang.OutOfMemoryError: GC overhead limit 
exceeded
	at java.util.HashMap.addEntry(HashMap.java:753)
	at java.util.HashMap.put(HashMap.java:385)
	at java.util.HashMap.putAll(HashMap.java:524)
	at 
org.drools.rule.GroupElement$Type.getOuterDeclarations(GroupElement.java:406)
	at org.drools.rule.GroupElement.getOuterDeclarations(GroupElement.java:109)
	at 
org.drools.base.DefaultKnowledgeHelper.getDeclaration(DefaultKnowledgeHelper.java:213)
	at 
org.drools.planner.examples.examination.solver.Rule_periodSpread_0DefaultConsequenceInvoker.evaluate(Rule_periodSpread_0DefaultConsequenceInvoker.java:21)
	at org.drools.common.DefaultAgenda.fireActivation(DefaultAgenda.java:903)
	at org.drools.common.DefaultAgenda.fireNextItem(DefaultAgenda.java:850)
	at org.drools.common.DefaultAgenda.fireAllRules(DefaultAgenda.java:1061)
	at 
org.drools.common.AbstractWorkingMemory.fireAllRules(AbstractWorkingMemory.java:741)
	at 
org.drools.common.AbstractWorkingMemory.fireAllRules(AbstractWorkingMemory.java:707)
...

3)
2010-03-13 09:47:38,303 [main] INFO  Step index (55), time spend 
(114213) taking step (186 {D90|S17} @ 24 {D210} + 5 {C65} <=> 516 
{D180|S12} @ 15 {D210} + 0 {C260}) out of 1382 accepted moves.
2010-03-13 09:48:02,062 [main] INFO  Step index (56), time spend 
(137972) taking step (498 {D120|S17} @ 28 {D210} + 0 {C260} => 1 {C100}) 
out of 1389 accepted moves.
2010-03-13 09:48:35,748 [main] INFO  Step index (57), time spend 
(171658) taking step (15 {D135|S96} @ 16 {D210} + 1 {C100} <=> 164 
{D180|S48} @ 3 {D210} + 0 {C260}) out of 1378 accepted moves.
Exception in thread "main" java.lang.OutOfMemoryError: GC overhead limit 
exceeded
	at java.lang.Integer.valueOf(Integer.java:625)
	at 
org.drools.common.TruthMaintenanceSystem.removeLogicalDependencies(TruthMaintenanceSystem.java:180)
	at 
org.drools.common.AbstractWorkingMemory.removeLogicalDependencies(AbstractWorkingMemory.java:1455)
	at 
org.drools.reteoo.RuleTerminalNode.retractLeftTuple(RuleTerminalNode.java:266)
	at 
org.drools.reteoo.SingleLeftTupleSinkAdapter.doPropagateRetractLeftTuple(SingleLeftTupleSinkAdapter.java:176)
	at 
org.drools.reteoo.SingleLeftTupleSinkAdapter.propagateRetractLeftTuple(SingleLeftTupleSinkAdapter.java:57)
	at 
org.drools.reteoo.EvalConditionNode.modifyLeftTuple(EvalConditionNode.java:250)
	at 
org.drools.reteoo.SingleLeftTupleSinkAdapter.propagateModifyChildLeftTuple(SingleLeftTupleSinkAdapter.java:198)
	at org.drools.reteoo.JoinNode.modifyLeftTuple(JoinNode.java:304)
	at 
org.drools.reteoo.SingleLeftTupleSinkAdapter.propagateModifyChildLeftTuple(SingleLeftTupleSinkAdapter.java:209)
	at org.drools.reteoo.JoinNode.modifyRightTuple(JoinNode.java:221)
	at org.drools.reteoo.BetaNode.modifyObject(BetaNode.java:317)
	at 
org.drools.reteoo.CompositeObjectSinkAdapter.doPropagateModifyObject(CompositeObjectSinkAdapter.java:444)
	at 
org.drools.reteoo.CompositeObjectSinkAdapter.propagateModifyObject(CompositeObjectSinkAdapter.java:412)
	at org.drools.reteoo.ObjectTypeNode.modifyObject(ObjectTypeNode.java:262)
	at org.drools.reteoo.EntryPointNode.modifyObject(EntryPointNode.java:174)
	at 
org.drools.common.AbstractWorkingMemory.update(AbstractWorkingMemory.java:1392)
	at 
org.drools.common.AbstractWorkingMemory.update(AbstractWorkingMemory.java:1288)


-- 
With kind regards,
Geoffrey De Smet