3:21 a.m.
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