0

I was building a web apps for nurse rostering based on Optaplanner vehicle routing web example. When I tried to run it from my Eclipse inside a JBoss WildFly 8.x, it only running to Construction Heuristic phase, and then stuck there without any more progress. The funny things is, the code was actually moved from my nurse rostering example from optaplanner 6.3.0-final distribution. In the windows apps, it running smooth, without any trouble or stuck.

Update

I finally got to set the log level to TRACE, and here is the log that come out: 

2016-04-06 23:10:49,930 INFO  [org.optaplanner.webexamples.nurserostering.rest.persistence.NurseRosteringDao] (default task-11) Opened: D:\Users\Administrator\wildfly-8.2.1.Final\standalone\deployments\optaplanner-webexamples.war\WEB-INF\classes\org\optaplanner\webexamples\nurserostering\data\team-machine1.xml
2016-04-06 23:10:59,194 TRACE [org.optaplanner.core.impl.domain.solution.descriptor.SolutionDescriptor] (default task-12)     Model annotations parsed for Solution NurseRoster:
2016-04-06 23:10:59,195 TRACE [org.optaplanner.core.impl.domain.solution.descriptor.SolutionDescriptor] (default task-12)         Entity ShiftAssignment:
2016-04-06 23:10:59,195 TRACE [org.optaplanner.core.impl.domain.solution.descriptor.SolutionDescriptor] (default task-12)             Variable employee (genuine)
2016-04-06 23:11:03,850 INFO  [org.drools.compiler.kie.builder.impl.KieRepositoryImpl] (default task-12) KieModule was added: MemoryKieModule[releaseId=org.default:artifact:1.0.0-SNAPSHOT]
2016-04-06 23:11:04,499 INFO  [org.optaplanner.core.impl.solver.DefaultSolver] (pool-6-thread-1) Solving started: time spent (395), best score (uninitialized/0hard/-260soft), environment mode (REPRODUCIBLE), random (JDK with seed 0).
2016-04-06 23:11:04,505 TRACE [org.optaplanner.core.impl.heuristic.selector.value.decorator.SortingValueSelector] (pool-6-thread-1)     Created cachedValueList: size (10), valueSelector (Sorting(FromSolutionPropertyValueSelector(employee))).
2016-04-06 23:11:04,508 TRACE [org.optaplanner.core.impl.heuristic.selector.value.decorator.SortingValueSelector] (pool-6-thread-1)     Sorted cachedValueList: size (10), valueSelector (Sorting(FromSolutionPropertyValueSelector(employee))).
2016-04-06 23:11:04,665 TRACE [org.optaplanner.core.impl.constructionheuristic.decider.ConstructionHeuristicDecider] (pool-6-thread-1)         Move index (0), score (0hard/-260soft), move (2010-01-01(Fri)_E@null {null -> A(A)}).
2016-04-06 23:11:04,676 TRACE [org.optaplanner.core.impl.constructionheuristic.decider.ConstructionHeuristicDecider] (pool-6-thread-1)         Move index (1), score (-1hard/-259soft), move (2010-01-01(Fri)_E@null {null -> B(B)}).
2016-04-06 23:11:04,682 TRACE [org.optaplanner.core.impl.constructionheuristic.decider.ConstructionHeuristicDecider] (pool-6-thread-1)         Move index (2), score (-1hard/-260soft), move (2010-01-01(Fri)_E@null {null -> C(C)}).
2016-04-06 23:11:04,699 TRACE [org.optaplanner.core.impl.constructionheuristic.decider.ConstructionHeuristicDecider] (pool-6-thread-1)         Move index (3), score (0hard/-260soft), move (2010-01-01(Fri)_E@null {null -> D(D)}).
2016-04-06 23:11:04,707 TRACE [org.optaplanner.core.impl.constructionheuristic.decider.ConstructionHeuristicDecider] (pool-6-thread-1)         Move index (4), score (-1hard/-260soft), move (2010-01-01(Fri)_E@null {null -> E(E)}).
2016-04-06 23:11:04,713 TRACE [org.optaplanner.core.impl.constructionheuristic.decider.ConstructionHeuristicDecider] (pool-6-thread-1)         Move index (5), score (-1hard/-259soft), move (2010-01-01(Fri)_E@null {null -> F(F)}).
2016-04-06 23:11:04,718 TRACE [org.optaplanner.core.impl.constructionheuristic.decider.ConstructionHeuristicDecider] (pool-6-thread-1)         Move index (6), score (0hard/-259soft), move (2010-01-01(Fri)_E@null {null -> G(G)}).
2016-04-06 23:11:04,726 TRACE [org.optaplanner.core.impl.constructionheuristic.decider.ConstructionHeuristicDecider] (pool-6-thread-1)         Move index (7), score (-1hard/-259soft), move (2010-01-01(Fri)_E@null {null -> H(H)}).
2016-04-06 23:11:04,732 TRACE [org.optaplanner.core.impl.constructionheuristic.decider.ConstructionHeuristicDecider] (pool-6-thread-1)         Move index (8), score (-1hard/-258soft), move (2010-01-01(Fri)_E@null {null -> I(I)}).
2016-04-06 23:11:04,738 TRACE [org.optaplanner.core.impl.constructionheuristic.decider.ConstructionHeuristicDecider] (pool-6-thread-1)         Move index (9), score (0hard/-258soft), move (2010-01-01(Fri)_E@null {null -> J(J)}).
2016-04-06 23:11:04,739 DEBUG [org.optaplanner.core.impl.constructionheuristic.DefaultConstructionHeuristicPhase] (pool-6-thread-1)     CH step (0), time spent (634), score (0hard/-258soft), selected move count (10), picked move (2010-01-01(Fri)_E@null {null -> J(J)}).
...
2016-04-06 23:11:07,274 DEBUG [org.optaplanner.core.impl.constructionheuristic.DefaultConstructionHeuristicPhase] (pool-6-thread-1)     CH step (150), time spent (3170), score (-1hard/-103soft), selected move count (10), picked move (2010-01-28(Thu)_L@null {null -> C(C)}).
2016-04-06 23:11:07,275 TRACE [org.optaplanner.core.impl.constructionheuristic.decider.ConstructionHeuristicDecider] (pool-6-thread-1)         Move index (0), score (-3hard/-104soft), move (2010-01-28(Thu)_D@null {null -> A(A)}).
2016-04-06 23:11:07,276 TRACE [org.optaplanner.core.impl.constructionheuristic.decider.ConstructionHeuristicDecider] (pool-6-thread-1)         Move index (1), score (-2hard/-104soft), move (2010-01-28(Thu)_D@null {null -> B(B)}).
2016-04-06 23:11:07,276 TRACE [org.optaplanner.core.impl.constructionheuristic.decider.ConstructionHeuristicDecider] (pool-6-thread-1)         Move index (2), score (-3hard/-103soft), move (2010-01-28(Thu)_D@null {null -> C(C)}).
2016-04-06 23:11:07,277 TRACE [org.optaplanner.core.impl.constructionheuristic.decider.ConstructionHeuristicDecider] (pool-6-thread-1)         Move index (3), score (-2hard/-103soft), move (2010-01-28(Thu)_D@null {null -> D(D)}).
2016-04-06 23:11:07,278 TRACE [org.optaplanner.core.impl.constructionheuristic.decider.ConstructionHeuristicDecider] (pool-6-thread-1)         Move index (4), score (-1hard/-107soft), move (2010-01-28(Thu)_D@null {null -> E(E)}).
2016-04-06 23:11:07,279 TRACE [org.optaplanner.core.impl.constructionheuristic.decider.ConstructionHeuristicDecider] (pool-6-thread-1)         Move index (5), score (-2hard/-105soft), move (2010-01-28(Thu)_D@null {null -> F(F)}).
2016-04-06 23:11:07,280 TRACE [org.optaplanner.core.impl.constructionheuristic.decider.ConstructionHeuristicDecider] (pool-6-thread-1)         Move index (6), score (-2hard/-106soft), move (2010-01-28(Thu)_D@null {null -> G(G)}).
2016-04-06 23:11:07,288 TRACE [org.optaplanner.core.impl.constructionheuristic.decider.ConstructionHeuristicDecider] (pool-6-thread-1)         Move index (7), score (-2hard/-104soft), move (2010-01-28(Thu)_D@null {null -> H(H)}).
2016-04-06 23:11:07,289 TRACE [org.optaplanner.core.impl.constructionheuristic.decider.ConstructionHeuristicDecider] (pool-6-thread-1)         Move index (8), score (-2hard/-104soft), move (2010-01-28(Thu)_D@null {null -> I(I)}).
2016-04-06 23:11:07,290 TRACE [org.optaplanner.core.impl.constructionheuristic.decider.ConstructionHeuristicDecider] (pool-6-thread-1)         Move index (9), score (-2hard/-104soft), move (2010-01-28(Thu)_D@null {null -> J(J)}).
2016-04-06 23:11:07,290 DEBUG [org.optaplanner.core.impl.constructionheuristic.DefaultConstructionHeuristicPhase] (pool-6-thread-1)     CH step (151), time spent (3186), score (-1hard/-107soft), selected move count (10), picked move (2010-01-28(Thu)_D@null {null -> E(E)}).
2016-04-06 23:11:07,291 TRACE [org.optaplanner.core.impl.constructionheuristic.decider.ConstructionHeuristicDecider] (pool-6-thread-1)         Move index (0), score (-2hard/-108soft), move (2010-01-28(Thu)_N@null {null -> A(A)}).
2016-04-06 23:11:07,292 TRACE [org.optaplanner.core.impl.constructionheuristic.decider.ConstructionHeuristicDecider] (pool-6-thread-1)         Move index (1), score (-3hard/-108soft), move (2010-01-28(Thu)_N@null {null -> B(B)}).
2016-04-06 23:11:07,293 TRACE [org.optaplanner.core.impl.constructionheuristic.decider.ConstructionHeuristicDecider] (pool-6-thread-1)         Move index (2), score (-3hard/-107soft), move (2010-01-28(Thu)_N@null {null -> C(C)}).
2016-04-06 23:11:07,293 TRACE [org.optaplanner.core.impl.constructionheuristic.decider.ConstructionHeuristicDecider] (pool-6-thread-1)         Move index (3), score (-1hard/-107soft), move (2010-01-28(Thu)_N@null {null -> D(D)}).
2016-04-06 23:11:07,294 TRACE [org.optaplanner.core.impl.constructionheuristic.decider.ConstructionHeuristicDecider] (pool-6-thread-1)         Move index (4), score (-3hard/-109soft), move (2010-01-28(Thu)_N@null {null -> E(E)}).
2016-04-06 23:11:07,295 TRACE [org.optaplanner.core.impl.constructionheuristic.decider.ConstructionHeuristicDecider] (pool-6-thread-1)         Move index (5), score (-2hard/-109soft), move (2010-01-28(Thu)_N@null {null -> F(F)}).
2016-04-06 23:11:07,296 TRACE [org.optaplanner.core.impl.constructionheuristic.decider.ConstructionHeuristicDecider] (pool-6-thread-1)         Move index (6), score (-1hard/-110soft), move (2010-01-28(Thu)_N@null {null -> G(G)}).
2016-04-06 23:11:07,297 TRACE [org.optaplanner.core.impl.constructionheuristic.decider.ConstructionHeuristicDecider] (pool-6-thread-1)         Move index (7), score (-3hard/-108soft), move (2010-01-28(Thu)_N@null {null -> H(H)}).
2016-04-06 23:11:07,299 TRACE [org.optaplanner.core.impl.constructionheuristic.decider.ConstructionHeuristicDecider] (pool-6-thread-1)         Move index (8), score (-2hard/-109soft), move (2010-01-28(Thu)_N@null {null -> I(I)}).
2016-04-06 23:11:07,300 TRACE [org.optaplanner.core.impl.constructionheuristic.decider.ConstructionHeuristicDecider] (pool-6-thread-1)         Move index (9), score (-1hard/-107soft), move (2010-01-28(Thu)_N@null {null -> J(J)}).
2016-04-06 23:11:07,300 DEBUG [org.optaplanner.core.impl.constructionheuristic.DefaultConstructionHeuristicPhase] (pool-6-thread-1)     CH step (152), time spent (3196), score (-1hard/-107soft), selected move count (10), picked move (2010-01-28(Thu)_N@null {null -> D(D)}).
2016-04-06 23:11:07,330 INFO  [org.optaplanner.core.impl.constructionheuristic.DefaultConstructionHeuristicPhase] (pool-6-thread-1) Construction Heuristic phase (0) ended: step total (153), time spent (3226), best score (-1hard/-107soft).
2016-04-06 23:11:07,400 TRACE [org.optaplanner.core.impl.heuristic.selector.move.factory.MoveListFactoryToMoveSelectorBridge] (pool-6-thread-1)     Created cachedMoveList: size (1530), moveSelector (MoveListFactory(class org.optaplanner.webexamples.nurserostering.rest.solver.move.factory.EmployeeChangeMoveFactory)).
2016-04-06 23:11:07,405 TRACE [org.optaplanner.core.impl.heuristic.selector.move.factory.MoveListFactoryToMoveSelectorBridge] (pool-6-thread-1)     Created cachedMoveList: size (11628), moveSelector (MoveListFactory(class org.optaplanner.webexamples.nurserostering.rest.solver.move.factory.ShiftAssignmentSwapMoveFactory)).
2016-04-06 23:11:07,411 TRACE [org.optaplanner.core.impl.heuristic.selector.move.factory.MoveListFactoryToMoveSelectorBridge] (pool-6-thread-1)     Created cachedMoveList: size (268), moveSelector (MoveListFactory(class org.optaplanner.webexamples.nurserostering.rest.solver.move.factory.ShiftAssignmentPillarPartSwapMoveFactory)).
2016-04-06 23:13:58,592 INFO  [org.optaplanner.core.impl.solver.BasicPlumbingTermination] (default task-36) Terminating solver early.

Is there something wrong in the log? Please kindly help me, thanks and regards.

Update 2

I update my desktop app nurse roster to optaplanner 6.3.0-final, and then run it, the result was it stuck at score -1hard/-107soft. It also prompt me an exception, here is the stack trace: 

Exception in thread "AWT-EventQueue-0" java.lang.IllegalStateException: Solving failed.
    at com.employee.scheduler.common.swingui.SolverAndPersistenceFrame$SolveWorker.done(SolverAndPersistenceFrame.java:299)
    at javax.swing.SwingWorker$5.run(SwingWorker.java:737)
    at javax.swing.SwingWorker$DoSubmitAccumulativeRunnable.run(SwingWorker.java:832)
    at sun.swing.AccumulativeRunnable.run(AccumulativeRunnable.java:112)
    at javax.swing.SwingWorker$DoSubmitAccumulativeRunnable.actionPerformed(SwingWorker.java:842)
    at javax.swing.Timer.fireActionPerformed(Timer.java:313)
    at javax.swing.Timer$DoPostEvent.run(Timer.java:245)
    at java.awt.event.InvocationEvent.dispatch(InvocationEvent.java:311)
    at java.awt.EventQueue.dispatchEventImpl(EventQueue.java:756)
    at java.awt.EventQueue.access$500(EventQueue.java:97)
    at java.awt.EventQueue$3.run(EventQueue.java:709)
    at java.awt.EventQueue$3.run(EventQueue.java:703)
    at java.security.AccessController.doPrivileged(Native Method)
    at java.security.ProtectionDomain$1.doIntersectionPrivilege(ProtectionDomain.java:75)
    at java.awt.EventQueue.dispatchEvent(EventQueue.java:726)
    at java.awt.EventDispatchThread.pumpOneEventForFilters(EventDispatchThread.java:201)
    at java.awt.EventDispatchThread.pumpEventsForFilter(EventDispatchThread.java:116)
    at java.awt.EventDispatchThread.pumpEventsForHierarchy(EventDispatchThread.java:105)
    at java.awt.EventDispatchThread.pumpEvents(EventDispatchThread.java:101)
    at java.awt.EventDispatchThread.pumpEvents(EventDispatchThread.java:93)
    at java.awt.EventDispatchThread.run(EventDispatchThread.java:82)
Caused by: " java.lang.IllegalStateException: The notificationQueues might not be empty (false) so any shadow variables might be stale so score calculation is unreliable.
Maybe a ScoreDirector.before*() method was called without calling ScoreDirector.triggerVariableListeners(), before calling ScoreDirector.calculateScore().
    at com.employee.scheduler.common.swingui.SolverAndPersistenceFrame$SolveWorker.done(SolverAndPersistenceFrame.java:299)
    at javax.swing.SwingWorker$5.run(SwingWorker.java:737)
    at javax.swing.SwingWorker$DoSubmitAccumulativeRunnable.run(SwingWorker.java:832)
    at sun.swing.AccumulativeRunnable.run(AccumulativeRunnable.java:112)
    at javax.swing.SwingWorker$DoSubmitAccumulativeRunnable.actionPerformed(SwingWorker.java:842)
    at javax.swing.Timer.fireActionPerformed(Timer.java:313)
    at javax.swing.Timer$DoPostEvent.run(Timer.java:245)
    at java.awt.event.InvocationEvent.dispatch(InvocationEvent.java:311)
    at java.awt.EventQueue.dispatchEventImpl(EventQueue.java:756)
    at java.awt.EventQueue.access$500(EventQueue.java:97)
    at java.awt.EventQueue$3.run(EventQueue.java:709)
    at java.awt.EventQueue$3.run(EventQueue.java:703)
    at java.security.AccessController.doPrivileged(Native Method)
    at java.security.ProtectionDomain$1.doIntersectionPrivilege(ProtectionDomain.java:75)
    at java.awt.EventQueue.dispatchEvent(EventQueue.java:726)
    at java.awt.EventDispatchThread.pumpOneEventForFilters(EventDispatchThread.java:201)
    at java.awt.EventDispatchThread.pumpEventsForFilter(EventDispatchThread.java:116)
    at java.awt.EventDispatchThread.pumpEventsForHierarchy(EventDispatchThread.java:105)
    at java.awt.EventDispatchThread.pumpEvents(EventDispatchThread.java:101)
    at java.awt.EventDispatchThread.pumpEvents(EventDispatchThread.java:93)
    at java.awt.EventDispatchThread.run(EventDispatchThread.java:82)

Update 3

I turn on environmentMode to FULL_ASSERT, here is my config.xml: 

<solver>
  <environmentMode>FULL_ASSERT</environmentMode>
  ...
</solver>

Then I tried to run it, and it still stuck in local search phase (just similar to the previous log I have posted). Here is the log: 

11:29:21,671 DEBUG [org.optaplanner.core.impl.constructionheuristic.DefaultConstructionHeuristicPhase] (pool-6-thread-1)     CH step (151), time spent (10808), score (-1hard/-107soft), selected move count (10), picked move (2010-01-28(Thu)_D@null {null -> E(E)}).
11:29:21,676 TRACE [org.optaplanner.core.impl.constructionheuristic.decider.ConstructionHeuristicDecider] (pool-6-thread-1)         Move index (0), score (-2hard/-108soft), move (2010-01-28(Thu)_N@null {null -> A(A)}).
11:29:21,680 TRACE [org.optaplanner.core.impl.constructionheuristic.decider.ConstructionHeuristicDecider] (pool-6-thread-1)         Move index (1), score (-3hard/-108soft), move (2010-01-28(Thu)_N@null {null -> B(B)}).
11:29:21,684 TRACE [org.optaplanner.core.impl.constructionheuristic.decider.ConstructionHeuristicDecider] (pool-6-thread-1)         Move index (2), score (-3hard/-107soft), move (2010-01-28(Thu)_N@null {null -> C(C)}).
11:29:21,689 TRACE [org.optaplanner.core.impl.constructionheuristic.decider.ConstructionHeuristicDecider] (pool-6-thread-1)         Move index (3), score (-1hard/-107soft), move (2010-01-28(Thu)_N@null {null -> D(D)}).
11:29:21,693 TRACE [org.optaplanner.core.impl.constructionheuristic.decider.ConstructionHeuristicDecider] (pool-6-thread-1)         Move index (4), score (-3hard/-109soft), move (2010-01-28(Thu)_N@null {null -> E(E)}).
11:29:21,699 TRACE [org.optaplanner.core.impl.constructionheuristic.decider.ConstructionHeuristicDecider] (pool-6-thread-1)         Move index (5), score (-2hard/-109soft), move (2010-01-28(Thu)_N@null {null -> F(F)}).
11:29:21,706 TRACE [org.optaplanner.core.impl.constructionheuristic.decider.ConstructionHeuristicDecider] (pool-6-thread-1)         Move index (6), score (-1hard/-110soft), move (2010-01-28(Thu)_N@null {null -> G(G)}).
11:29:21,714 TRACE [org.optaplanner.core.impl.constructionheuristic.decider.ConstructionHeuristicDecider] (pool-6-thread-1)         Move index (7), score (-3hard/-108soft), move (2010-01-28(Thu)_N@null {null -> H(H)}).
11:29:21,721 TRACE [org.optaplanner.core.impl.constructionheuristic.decider.ConstructionHeuristicDecider] (pool-6-thread-1)         Move index (8), score (-2hard/-109soft), move (2010-01-28(Thu)_N@null {null -> I(I)}).
11:29:21,728 TRACE [org.optaplanner.core.impl.constructionheuristic.decider.ConstructionHeuristicDecider] (pool-6-thread-1)         Move index (9), score (-1hard/-107soft), move (2010-01-28(Thu)_N@null {null -> J(J)}).
11:29:21,733 DEBUG [org.optaplanner.core.impl.constructionheuristic.DefaultConstructionHeuristicPhase] (pool-6-thread-1)     CH step (152), time spent (10870), score (-1hard/-107soft), selected move count (10), picked move (2010-01-28(Thu)_N@null {null -> D(D)}).
11:29:21,739 INFO  [org.optaplanner.core.impl.constructionheuristic.DefaultConstructionHeuristicPhase] (pool-6-thread-1) Construction Heuristic phase (0) ended: step total (153), time spent (10876), best score (-1hard/-107soft).
11:29:21,754 TRACE [org.optaplanner.core.impl.heuristic.selector.move.factory.MoveListFactoryToMoveSelectorBridge] (pool-6-thread-1)     Created cachedMoveList: size (1530), moveSelector (MoveListFactory(class org.optaplanner.webexamples.nurserostering.rest.solver.move.factory.EmployeeChangeMoveFactory)).
11:29:21,759 TRACE [org.optaplanner.core.impl.heuristic.selector.move.factory.MoveListFactoryToMoveSelectorBridge] (pool-6-thread-1)     Created cachedMoveList: size (11628), moveSelector (MoveListFactory(class org.optaplanner.webexamples.nurserostering.rest.solver.move.factory.ShiftAssignmentSwapMoveFactory)).
11:29:21,765 TRACE [org.optaplanner.core.impl.heuristic.selector.move.factory.MoveListFactoryToMoveSelectorBridge] (pool-6-thread-1)     Created cachedMoveList: size (268), moveSelector (MoveListFactory(class org.optaplanner.webexamples.nurserostering.rest.solver.move.factory.ShiftAssignmentPillarPartSwapMoveFactory)).
11:33:26,137 INFO  [org.optaplanner.core.impl.solver.BasicPlumbingTermination] (default task-17) Terminating solver early.

Any idea anyone? What is exactly I should expect from turning on the environment mode?

the.wizard
  • 1,079
  • 1
  • 9
  • 25
  • When deployed in wildfly, the wildfly logger will overrule your logger basically, so that logback.xml file is ignored. [See a similar problem here](https://groups.google.com/forum/#!topic/optaplanner-dev/scdaYDEMzyA) Fix that to get debug logging and you'll have a better idea what's going on. Maybe the CH is just taking longer on that dataset (which is fixable) or you got a race condition in your servlet thread to solver thread code or ... Get the log first. – Geoffrey De Smet Apr 04 '16 at 06:58
  • I have try to exclude the slf4j-api dependency from optaplanner-core, optaplanner-benchmark and the logback-classic, then try to run it again. But still the log was from jboss, not from my own logback.xml file. Is there something I missing? – the.wizard Apr 05 '16 at 16:33
  • I have finally got the log after setting the logger config inside jboss standalone.xml. I have post the log above. Please help me solve this problem. – the.wizard Apr 05 '16 at 17:28
  • Turn on trace logging. From this log, I would conclude that the Local Search phase starts, but no steps are being done, I presume no move is being accepted. **In any case, it's not stuck in the Construction Heuristic, but after it.** – Geoffrey De Smet Apr 06 '16 at 06:50
  • I have post the trace log, please @GeoffreyDeSmet give me advice to solve this problem. Thanks. – the.wizard Apr 06 '16 at 16:22
  • This question just became very interesting, this seems like a real bug. Would it be possible to [create a jira](https://issues.jboss.org/browse/PLANNER) and attach a reproducer (preferably one that doesn't need wildfly to reproduce)? – Geoffrey De Smet Apr 07 '16 at 06:18
  • I think you're right about this. This seems like a real bug. I change the optaplanner version to 6.2.0-final (previously 6.3.0-final), and the local search phase running normally as I expected. I just realize my previous desktop apps was build on 6.2.0-final version. I will create a jira for this bug and hopefully I could create a reproducer for you @GeoffreyDeSmet :) – the.wizard Apr 07 '16 at 15:44

1 Answers1

0

Analysis from your log:

23:11:07,411 TRACE...     Created cachedMoveList: ...
// 2 minutes and not a single move selected. That's impossible.
// It must be stuck in a infinite loop somehow.
// Do a thread dump (ctrl-break) 20 seconds after that "Created cachedMoveList" line. Before terminating it to see where it's spending it's time.
// 
// Terminated asynchronously. This means it's actually in a loop that does checks the termination status
23:13:58,592 INFO ...     Terminating solver early.

This tells a lot:

  • It's not that all moves are tabu or that all moves are undoable, because no moves are being selected (otherwise we'd see TRACE log messages of those).
  • It's not you have a custom MoveFactoryList that gets into a infinite loop, because otherwise the terminateEarly() call wouldn't be honored immediately - it would be ignored instead.
  • It's not that all your move selectors are empty, there are least 3 cached ones which log that they have sizes above 1k moves. And in that case we'd also see debug step log messages, which we don't.

So I don't know what's going on. But it looks like a genuine bug or at the very least a unique situation I haven't seen yet. Send me a reproducer by creating a new jira and attaching a reproducer there and I 'll take a look. A good reproducer has a pom.xml I can open and has main class or a test class I can run to reproduce the problem (so I don't need waste time deploying it to wildfly etc).

Geoffrey De Smet
  • 26,223
  • 11
  • 73
  • 120
  • 1
    I will create a new jira for you, and try to move my web code to java desktop app. It probably will take some time for me to create a reproducer. Btw, I have tried to update my desktop app to use 6.3.0-final, and it give me the same score, plus it show a stack trace, and of course, I have put it in my question above. – the.wizard Apr 07 '16 at 16:16
  • Hmm, update 2 is a clear corruption issue, which is usually not a bug in optaplanner itself. Turn on environmentMode full assert. But I am still wondering what's happening in those 2 minutes between the LS start and the terminate early. – Geoffrey De Smet Apr 08 '16 at 07:12
  • What environmentMode should I turn on? Is FAST_ASSERT enough? I really confused, if the bug is not in optaplanner, then why my same code running well with optaplanner 6.2.0-final? Please guide me to solve this problem @Geoffrey De Smet – the.wizard Apr 10 '16 at 04:08
  • I have tried to turn on my environmentMode to FULL_ASSERT, and nothing really change, is still stuck in local search phase, and the log still similar to to previous log. I have updated my post with the newest log (after environmentMode FULL_ASSERT turn on). Any idea @Geoffrey De Smet? – the.wizard Apr 10 '16 at 04:59
  • If the ASSERT modes give the same behavior as before - no exception is thrown - then NO score corruption nor variable listener corruption is happening. At this point, I 'd definitely be interested in that reproducer and jira issue. – Geoffrey De Smet Apr 11 '16 at 06:38
  • Any luck with creating that jira? Link it here please. – Geoffrey De Smet Apr 25 '16 at 08:20
  • I just finished create a reproducer for you yesterday. When I have my next free time, I will create a jira, attach my reproducer, and link it here. Until then, please be patient :) – the.wizard Apr 26 '16 at 03:14
  • 1
    I have created a jira issue, here is the link : https://issues.jboss.org/browse/PLANNER-569 – the.wizard Apr 27 '16 at 23:04