In some cases, but not always, seemingly randomly, and using the exact same configuration, Optaplanner doesn't terminate after it's secondsSpentLimit course. it just hangs with "INFO --- [ main] .c.i.c.DefaultConstructionHeuristicPhase : Construction Heuristic phase (1) ended: step total (0), time spent (1507), best score (-9hard/0soft)"
Here's my config:
<solver>
<environmentMode>FULL_ASSERT</environmentMode>
<!-- Domain model configuration -->
<solutionClass>com.rdthree.plenty.services.activities.planner.ActivitySolution</solutionClass>
<entityClass>com.rdthree.plenty.services.activities.helpers.dtos.TaskPlannerDto</entityClass>
<entityClass>com.rdthree.plenty.services.activities.helpers.dtos.TaskResourceAllocationPlannerDto</entityClass>
<!-- Score configuration -->
<scoreDirectorFactory>
<scoreDefinitionType>HARD_SOFT</scoreDefinitionType>
<scoreDrl>com/rdthree/plenty/services/activities/planner/activity-scoring.drl</scoreDrl>
<initializingScoreTrend>ONLY_DOWN</initializingScoreTrend>
</scoreDirectorFactory>
<!-- Optimization algorithms configuration -->
<termination>
<terminationCompositionStyle>OR</terminationCompositionStyle>
<bestScoreLimit>0hard/0soft</bestScoreLimit>
<secondsSpentLimit>60</secondsSpentLimit>
</termination>
<constructionHeuristic>
<queuedEntityPlacer>
<entitySelector id="resourceAllocationSelector">
<entityClass>com.rdthree.plenty.services.activities.helpers.dtos.TaskResourceAllocationPlannerDto</entityClass>
<cacheType>PHASE</cacheType>
<selectionOrder>SORTED</selectionOrder>
<sorterManner>DECREASING_DIFFICULTY_IF_AVAILABLE</sorterManner>
</entitySelector>
<changeMoveSelector>
<entitySelector mimicSelectorRef="resourceAllocationSelector" />
<valueSelector>
<variableName>resource</variableName>
<cacheType>PHASE</cacheType>
</valueSelector>
</changeMoveSelector>
</queuedEntityPlacer>
</constructionHeuristic>
<constructionHeuristic>
<queuedEntityPlacer>
<entitySelector id="taskSelector">
<entityClass>com.rdthree.plenty.services.activities.helpers.dtos.TaskPlannerDto</entityClass>
<cacheType>PHASE</cacheType>
<selectionOrder>SORTED</selectionOrder>
<sorterManner>DECREASING_DIFFICULTY_IF_AVAILABLE</sorterManner>
</entitySelector>
<changeMoveSelector>
<entitySelector mimicSelectorRef="taskSelector" />
<filterClass>com.rdthree.plenty.services.activities.planner.TaskLengthChnageFilter</filterClass>
<valueSelector>
<variableName>interval</variableName>
<cacheType>PHASE</cacheType>
</valueSelector>
</changeMoveSelector>
</queuedEntityPlacer>
</constructionHeuristic>
<localSearch>
<unionMoveSelector>
<moveListFactory>
<moveListFactoryClass>com.rdthree.plenty.services.activities.planner.MoveResourceAllocationMoveFactory</moveListFactoryClass>
</moveListFactory>
<changeMoveSelector>
<fixedProbabilityWeight>1.0</fixedProbabilityWeight>
<filterClass>com.rdthree.plenty.services.activities.planner.TaskLengthChnageFilter</filterClass>
<entitySelector id="taskMoveSelector">
<entityClass>com.rdthree.plenty.services.activities.helpers.dtos.TaskPlannerDto</entityClass>
</entitySelector>
<valueSelector>
<variableName>interval</variableName>
</valueSelector>
</changeMoveSelector>
</unionMoveSelector>
<acceptor>
<valueTabuSize>7</valueTabuSize>
</acceptor>
<forager>
<acceptedCountLimit>2000</acceptedCountLimit>
</forager>
</localSearch>
I also have a move filter:
public class TaskLengthChnageFilter implements SelectionFilter<ChangeMove> {
@SuppressWarnings("unchecked")
@Override
public boolean accept(ScoreDirector scoreDirector, ChangeMove selection) {
// get the solution
Solution<HardSoftScore> solution = scoreDirector.getWorkingSolution();
List<TaskRequirementsMapper> taskRequirementsMappers = new ArrayList<>();
// find the taskRequirementsMappers in the problem facts
for (Object fact : solution.getProblemFacts()) {
if (fact instanceof TaskRequirementsMapper) {
taskRequirementsMappers.add((TaskRequirementsMapper) fact);
}
}
for (Object obj : selection.getPlanningEntities()) {
TaskPlannerDto task;
Interval interval = null;
// get a task move
if (TaskPlannerDto.class.equals(obj.getClass())) {
// get the planning value (i.e the resource that is being changed in the allocation)
for (Object thePvalue : selection.getPlanningValues()) {
// the collection should only hold one value so take it and break
interval = (Interval) thePvalue;
break;
}
task = (TaskPlannerDto) obj;
// iterate over all the task requirement mappers
for (TaskRequirementsMapper taskRequirementsMapper : taskRequirementsMappers) {
// and find the one relevant for this allocation
if (task.getId().equals(taskRequirementsMapper.getTaskId())) {
// check
int newLength = interval.toPeriod().getDays();
int oldLength = taskRequirementsMapper.getLength();
if (newLength != oldLength) {
return false;
} else {
return true;
}
}
}
}
else {
return false;
}
}
return true;
}
}
Here's my thread dump after killing the process with kill -3 PID. Also, the trace logging messages:
2015-09-18 12:36:05.079 INFO --- [ main] o.d.c.k.builder.impl.KieRepositoryImpl : KieModule was added:MemoryKieModule[ ReleaseId=org.default:artifact:1.0.0-SNAPSHOT]
2015-09-18 12:36:05.414 INFO --- [ main] o.o.core.impl.solver.DefaultSolver : Solving started: time spent (155), best score (-9hard/0soft), environment mode (FULL_ASSERT), random (JDK with seed 0).
2015-09-18 12:36:05.425 INFO --- [ main] o.o.c.a.s.event.SolverEventListener : New Best Solution Found with score : -9hard/0soft
2015-09-18 12:36:05.426 INFO --- [ main] .c.i.c.DefaultConstructionHeuristicPhase : Construction Heuristic phase (0) ended: step total (0), time spent (167), best score (-9hard/0soft).
2015-09-18 12:36:05.436 INFO --- [ main] o.o.c.a.s.event.SolverEventListener : New Best Solution Found with score : -9hard/0soft
2015-09-18 12:36:05.436 INFO --- [ main] .c.i.c.DefaultConstructionHeuristicPhase : Construction Heuristic phase (1) ended: step total (0), time spent (177), best score (-9hard/0soft).
2015-09-18 12:36:05.446 TRACE --- [ main] .m.f.MoveListFactoryToMoveSelectorBridge : Created cachedMoveList: size (60), moveSelector (MoveListFactory(class com.rdthree.plenty.services.activities.planner.MoveResourceAllocationMoveFactory)).
2015-09-18 12:39:16
Full thread dump Java HotSpot(TM) 64-Bit Server VM (24.79-b02 mixed mode):
"WeakCollectionCleaner" daemon prio=5 tid=0x00007f954e143800 nid=0xd507 in Object.wait() [0x0000000115f09000]
java.lang.Thread.State: WAITING (on object monitor)
at java.lang.Object.wait(Native Method)
- waiting on <0x00000007840964c0> (a java.lang.ref.ReferenceQueue$Lock)
at java.lang.ref.ReferenceQueue.remove(ReferenceQueue.java:135)
- locked <0x00000007840964c0> (a java.lang.ref.ReferenceQueue$Lock)
at java.lang.ref.ReferenceQueue.remove(ReferenceQueue.java:151)
at org.geotools.util.WeakCollectionCleaner.run(WeakCollectionCleaner.java:77)
"GT authority factory disposer" daemon prio=5 tid=0x00007f954ca1e800 nid=0xd207 in Object.wait() [0x0000000116093000]
java.lang.Thread.State: TIMED_WAITING (on object monitor)
at java.lang.Object.wait(Native Method)
- waiting on <0x00000007840ea820> (a java.util.TaskQueue)
at java.util.TimerThread.mainLoop(Timer.java:552)
- locked <0x00000007840ea820> (a java.util.TaskQueue)
at java.util.TimerThread.run(Timer.java:505)
"AWT-AppKit" daemon prio=5 tid=0x00007f954e552800 nid=0x713 runnable [0x0000000000000000]
java.lang.Thread.State: RUNNABLE
"java-sdk-http-connection-reaper" daemon prio=5 tid=0x00007f954d69a000 nid=0x5b03 waiting on condition [0x0000000115667000]
java.lang.Thread.State: TIMED_WAITING (sleeping)
at java.lang.Thread.sleep(Native Method)
at com.amazonaws.http.IdleConnectionReaper.run(IdleConnectionReaper.java:112)
"Abandoned connection cleanup thread" daemon prio=5 tid=0x00007f954e0b5800 nid=0x5903 in Object.wait() [0x0000000115bba000]
java.lang.Thread.State: TIMED_WAITING (on object monitor)
at java.lang.Object.wait(Native Method)
- waiting on <0x00000007816e4b98> (a java.lang.ref.ReferenceQueue$Lock)
at java.lang.ref.ReferenceQueue.remove(ReferenceQueue.java:135)
- locked <0x00000007816e4b98> (a java.lang.ref.ReferenceQueue$Lock)
at com.mysql.jdbc.AbandonedConnectionCleanupThread.run(AbandonedConnectionCleanupThread.java:43)
"Tomcat JDBC Pool Cleaner[1625026637:1442568952184]" daemon prio=5 tid=0x00007f954e11e800 nid=0x5807 in Object.wait() [0x00000001157d3000]
java.lang.Thread.State: TIMED_WAITING (on object monitor)
at java.lang.Object.wait(Native Method)
- waiting on <0x00000007814885e0> (a java.util.TaskQueue)
at java.util.TimerThread.mainLoop(Timer.java:552)
- locked <0x00000007814885e0> (a java.util.TaskQueue)
at java.util.TimerThread.run(Timer.java:505)
"ReaderThread" prio=5 tid=0x00007f954e08d800 nid=0x5103 runnable [0x00000001152ed000]
java.lang.Thread.State: RUNNABLE
at java.net.SocketInputStream.socketRead0(Native Method)
at java.net.SocketInputStream.read(SocketInputStream.java:152)
at java.net.SocketInputStream.read(SocketInputStream.java:122)
at sun.nio.cs.StreamDecoder.readBytes(StreamDecoder.java:283)
at sun.nio.cs.StreamDecoder.implRead(StreamDecoder.java:325)
at sun.nio.cs.StreamDecoder.read(StreamDecoder.java:177)
- locked <0x000000078056f568> (a java.io.InputStreamReader)
at java.io.InputStreamReader.read(InputStreamReader.java:184)
at java.io.BufferedReader.fill(BufferedReader.java:154)
at java.io.BufferedReader.readLine(BufferedReader.java:317)
- locked <0x000000078056f568> (a java.io.InputStreamReader)
at java.io.BufferedReader.readLine(BufferedReader.java:382)
at org.eclipse.jdt.internal.junit.runner.RemoteTestRunner$ReaderThread.run(RemoteTestRunner.java:135)
"Service Thread" daemon prio=5 tid=0x00007f954e011000 nid=0x4d03 runnable [0x0000000000000000]
java.lang.Thread.State: RUNNABLE
"C2 CompilerThread1" daemon prio=5 tid=0x00007f954c089000 nid=0x4b03 waiting on condition [0x0000000000000000]
java.lang.Thread.State: RUNNABLE
"C2 CompilerThread0" daemon prio=5 tid=0x00007f954c072000 nid=0x4903 waiting on condition [0x0000000000000000]
java.lang.Thread.State: RUNNABLE
"Signal Dispatcher" daemon prio=5 tid=0x00007f954c02a000 nid=0x3c13 waiting on condition [0x0000000000000000]
java.lang.Thread.State: RUNNABLE
"Finalizer" daemon prio=5 tid=0x00007f954c06f800 nid=0x3503 in Object.wait() [0x00000001125db000]
java.lang.Thread.State: WAITING (on object monitor)
at java.lang.Object.wait(Native Method)
- waiting on <0x000000078056a588> (a java.lang.ref.ReferenceQueue$Lock)
at java.lang.ref.ReferenceQueue.remove(ReferenceQueue.java:135)
- locked <0x000000078056a588> (a java.lang.ref.ReferenceQueue$Lock)
at java.lang.ref.ReferenceQueue.remove(ReferenceQueue.java:151)
at java.lang.ref.Finalizer$FinalizerThread.run(Finalizer.java:209)
"Reference Handler" daemon prio=5 tid=0x00007f954c06f000 nid=0x3303 in Object.wait() [0x00000001124d8000]
java.lang.Thread.State: WAITING (on object monitor)
at java.lang.Object.wait(Native Method)
- waiting on <0x0000000780597940> (a java.lang.ref.Reference$Lock)
at java.lang.Object.wait(Object.java:503)
at java.lang.ref.Reference$ReferenceHandler.run(Reference.java:133)
- locked <0x0000000780597940> (a java.lang.ref.Reference$Lock)
"main" prio=5 tid=0x00007f954c02c800 nid=0x1303 runnable [0x0000000103374000]
java.lang.Thread.State: RUNNABLE
at org.optaplanner.core.impl.heuristic.selector.move.generic.ChangeMoveSelector$RandomChangeMoveIterator.createUpcomingSelection(ChangeMoveSelector.java:166)
at org.optaplanner.core.impl.heuristic.selector.move.generic.ChangeMoveSelector$RandomChangeMoveIterator.createUpcomingSelection(ChangeMoveSelector.java:129)
at org.optaplanner.core.impl.heuristic.selector.common.iterator.UpcomingSelectionIterator.hasNext(UpcomingSelectionIterator.java:40)
at org.optaplanner.core.impl.heuristic.selector.move.decorator.FilteringMoveSelector$JustInTimeFilteringMoveIterator.createUpcomingSelection(FilteringMoveSelector.java:90)
at org.optaplanner.core.impl.heuristic.selector.move.decorator.FilteringMoveSelector$JustInTimeFilteringMoveIterator.createUpcomingSelection(FilteringMoveSelector.java:77)
at org.optaplanner.core.impl.heuristic.selector.common.iterator.UpcomingSelectionIterator.hasNext(UpcomingSelectionIterator.java:40)
at org.optaplanner.core.impl.heuristic.selector.move.composite.UnionMoveSelector$RandomUnionMoveIterator.refreshMoveIteratorMap(UnionMoveSelector.java:183)
at org.optaplanner.core.impl.heuristic.selector.move.composite.UnionMoveSelector$RandomUnionMoveIterator.hasNext(UnionMoveSelector.java:159)
at org.optaplanner.core.impl.localsearch.decider.LocalSearchDecider.decideNextStep(LocalSearchDecider.java:112)
at org.optaplanner.core.impl.localsearch.DefaultLocalSearchPhase.solve(DefaultLocalSearchPhase.java:66)
at org.optaplanner.core.impl.solver.DefaultSolver.runPhases(DefaultSolver.java:213)
at org.optaplanner.core.impl.solver.DefaultSolver.solve(DefaultSolver.java:176)
at com.rdthree.plenty.services.activities.auto_scheduler.AutoSchedulerServiceBean.autoSchedule(AutoSchedulerServiceBean.java:138)
at sun.reflect.NativeMethodAccessorImpl.invoke0(Native Method)
at sun.reflect.NativeMethodAccessorImpl.invoke(NativeMethodAccessorImpl.java:57)
at sun.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:43)
at java.lang.reflect.Method.invoke(Method.java:606)
at org.springframework.aop.support.AopUtils.invokeJoinpointUsingReflection(AopUtils.java:317)
at org.springframework.aop.framework.ReflectiveMethodInvocation.invokeJoinpoint(ReflectiveMethodInvocation.java:190)
at org.springframework.aop.framework.ReflectiveMethodInvocation.proceed(ReflectiveMethodInvocation.java:157)
at org.springframework.transaction.interceptor.TransactionInterceptor$1.proceedWithInvocation(TransactionInterceptor.java:99)
at org.springframework.transaction.interceptor.TransactionAspectSupport.invokeWithinTransaction(TransactionAspectSupport.java:281)
at org.springframework.transaction.interceptor.TransactionInterceptor.invoke(TransactionInterceptor.java:96)
at org.springframework.aop.framework.ReflectiveMethodInvocation.proceed(ReflectiveMethodInvocation.java:179)
at org.springframework.aop.framework.JdkDynamicAopProxy.invoke(JdkDynamicAopProxy.java:207)
at com.sun.proxy.$Proxy227.autoSchedule(Unknown Source)
at com.rdthree.plenty.threads.SchedulerThread.run(SchedulerThread.java:104)
at org.springframework.core.task.SyncTaskExecutor.execute(SyncTaskExecutor.java:50)
at com.rdthree.plenty.services.notifications.TestNotificationService.testSchedulerThreadFailNotification(TestNotificationService.java:578)
at sun.reflect.NativeMethodAccessorImpl.invoke0(Native Method)
at sun.reflect.NativeMethodAccessorImpl.invoke(NativeMethodAccessorImpl.java:57)
at sun.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:43)
at java.lang.reflect.Method.invoke(Method.java:606)
at org.junit.runners.model.FrameworkMethod$1.runReflectiveCall(FrameworkMethod.java:50)
at org.junit.internal.runners.model.ReflectiveCallable.run(ReflectiveCallable.java:12)
at org.junit.runners.model.FrameworkMethod.invokeExplosively(FrameworkMethod.java:47)
at org.junit.internal.runners.statements.InvokeMethod.evaluate(InvokeMethod.java:17)
at org.springframework.test.context.junit4.statements.RunBeforeTestMethodCallbacks.evaluate(RunBeforeTestMethodCallbacks.java:73)
at org.junit.internal.runners.statements.RunAfters.evaluate(RunAfters.java:27)
at org.springframework.test.context.junit4.statements.RunAfterTestMethodCallbacks.evaluate(RunAfterTestMethodCallbacks.java:82)
at com.rdthree.plenty.PlentyGeneralTest$RetryRule$1.eval(PlentyGeneralTest.java:46)
at com.rdthree.plenty.PlentyGeneralTest$RetryRule$1.evaluate(PlentyGeneralTest.java:56)
at org.springframework.test.context.junit4.statements.SpringRepeat.evaluate(SpringRepeat.java:73)
at org.junit.runners.ParentRunner.runLeaf(ParentRunner.java:325)
at org.springframework.test.context.junit4.SpringJUnit4ClassRunner.runChild(SpringJUnit4ClassRunner.java:224)
at org.springframework.test.context.junit4.SpringJUnit4ClassRunner.runChild(SpringJUnit4ClassRunner.java:83)
at org.junit.runners.ParentRunner$3.run(ParentRunner.java:290)
at org.junit.runners.ParentRunner$1.schedule(ParentRunner.java:71)
at org.junit.runners.ParentRunner.runChildren(ParentRunner.java:288)
at org.junit.runners.ParentRunner.access$000(ParentRunner.java:58)
at org.junit.runners.ParentRunner$2.evaluate(ParentRunner.java:268)
at org.springframework.test.context.junit4.statements.RunBeforeTestClassCallbacks.evaluate(RunBeforeTestClassCallbacks.java:61)
at org.springframework.test.context.junit4.statements.RunAfterTestClassCallbacks.evaluate(RunAfterTestClassCallbacks.java:68)
at org.junit.runners.ParentRunner.run(ParentRunner.java:363)
at org.springframework.test.context.junit4.SpringJUnit4ClassRunner.run(SpringJUnit4ClassRunner.java:163)
at org.eclipse.jdt.internal.junit4.runner.JUnit4TestReference.run(JUnit4TestReference.java:50)
at org.eclipse.jdt.internal.junit.runner.TestExecution.run(TestExecution.java:38)
at org.eclipse.jdt.internal.junit.runner.RemoteTestRunner.runTests(RemoteTestRunner.java:459)
at org.eclipse.jdt.internal.junit.runner.RemoteTestRunner.runTests(RemoteTestRunner.java:675)
at org.eclipse.jdt.internal.junit.runner.RemoteTestRunner.run(RemoteTestRunner.java:382)
at org.eclipse.jdt.internal.junit.runner.RemoteTestRunner.main(RemoteTestRunner.java:192)
"VM Thread" prio=5 tid=0x00007f954d00d800 nid=0x3103 runnable
"GC task thread#0 (ParallelGC)" prio=5 tid=0x00007f954c038800 nid=0x2103 runnable
"GC task thread#1 (ParallelGC)" prio=5 tid=0x00007f954c039000 nid=0x2303 runnable
"GC task thread#2 (ParallelGC)" prio=5 tid=0x00007f954c03a000 nid=0x2503 runnable
"GC task thread#3 (ParallelGC)" prio=5 tid=0x00007f954c03a800 nid=0x2703 runnable
"GC task thread#4 (ParallelGC)" prio=5 tid=0x00007f954d000800 nid=0x2903 runnable
"GC task thread#5 (ParallelGC)" prio=5 tid=0x00007f954d001000 nid=0x2b03 runnable
"GC task thread#6 (ParallelGC)" prio=5 tid=0x00007f954d001800 nid=0x2d03 runnable
"GC task thread#7 (ParallelGC)" prio=5 tid=0x00007f954d002800 nid=0x2f03 runnable
"VM Periodic Task Thread" prio=5 tid=0x00007f954e010000 nid=0x4f03 waiting on condition
JNI global references: 697
Heap
PSYoungGen total 698880K, used 154259K [0x00000007d5500000, 0x0000000800000000, 0x0000000800000000)
eden space 698368K, 22% used [0x00000007d5500000,0x00000007deba4f78,0x00000007fff00000)
from space 512K, 0% used [0x00000007fff00000,0x00000007fff00000,0x00000007fff80000)
to space 512K, 0% used [0x00000007fff80000,0x00000007fff80000,0x0000000800000000)
ParOldGen total 349696K, used 92182K [0x0000000780000000, 0x0000000795580000, 0x00000007d5500000)
object space 349696K, 26% used [0x0000000780000000,0x0000000785a05be8,0x0000000795580000)
PSPermGen total 131072K, used 85162K [0x0000000700000000, 0x0000000708000000, 0x0000000780000000)
object space 131072K, 64% used [0x0000000700000000,0x000000070532ab80,0x0000000708000000)
