Too short termination may cause CH return a worse solution than the best solution

Open winklerm opened this issue 1 year ago • 0 comments

Describe the bug When running Timefold Solver with a very short termination (spent-limit=1s, unimproved-spent-limit=1s), the following behaviour occurs - please notice the CH step (12) that selects a move changing the score to -1hard, worse than the previous score:

16:23:10.638 DEBUG [pool-8-thread-1]     CH step (0), time spent (246), score (0hard/-626medium/-1538soft), selected move count (46), picked move (SolverVisit{id=da0bbce4, visitGroup=null} {null -> SolverVehicleShift{id=6b814f3e}[0]}).
16:23:10.787 DEBUG [pool-8-thread-1]     CH step (1), time spent (395), score (0hard/-622medium/-1830soft), selected move count (47), picked move (SolverVisit{id=12744b72, visitGroup=null} {null -> SolverVehicleShift{id=6b814f3e}[0]}).
16:23:10.892 DEBUG [pool-8-thread-1]     CH step (2), time spent (500), score (0hard/-606medium/-3550soft), selected move count (48), picked move (SolverVisit{id=bb0fc8ab, visitGroup=null} {null -> SolverVehicleShift{id=a51f8828}[0]}).
16:23:10.947 DEBUG [pool-8-thread-1]     CH step (3), time spent (554), score (0hard/-602medium/-3657soft), selected move count (49), picked move (SolverVisit{id=43a7bff8, visitGroup=null} {null -> SolverVehicleShift{id=a51f8828}[0]}).
16:23:11.021 DEBUG [pool-8-thread-1]     CH step (4), time spent (629), score (0hard/-598medium/-3663soft), selected move count (50), picked move (SolverVisit{id=21b51c4e, visitGroup=null} {null -> SolverVehicleShift{id=a51f8828}[2]}).
16:23:11.079 DEBUG [pool-8-thread-1]     CH step (5), time spent (686), score (0hard/-594medium/-4152soft), selected move count (51), picked move (SolverVisit{id=c5def3d2, visitGroup=null} {null -> SolverVehicleShift{id=a51f8828}[0]}).
16:23:11.124 DEBUG [pool-8-thread-1]     CH step (6), time spent (732), score (0hard/-590medium/-4285soft), selected move count (52), picked move (SolverVisit{id=20ca1ec6, visitGroup=null} {null -> SolverVehicleShift{id=6b814f3e}[2]}).
16:23:11.186 DEBUG [pool-8-thread-1]     CH step (7), time spent (794), score (0hard/-574medium/-4411soft), selected move count (53), picked move (SolverVisit{id=ab86f7f4, visitGroup=null} {null -> SolverVehicleShift{id=88403ee1}[0]}).
16:23:11.233 DEBUG [pool-8-thread-1]     CH step (8), time spent (841), score (0hard/-570medium/-4853soft), selected move count (54), picked move (SolverVisit{id=9a75b159, visitGroup=null} {null -> SolverVehicleShift{id=6f87cf48}[0]}).
16:23:11.284 DEBUG [pool-8-thread-1]     CH step (9), time spent (892), score (0hard/-566medium/-5198soft), selected move count (55), picked move (SolverVisit{id=ae753509, visitGroup=null} {null -> SolverVehicleShift{id=6b814f3e}[0]}).
16:23:11.326 DEBUG [pool-8-thread-1]     CH step (10), time spent (934), score (0hard/-557medium/-5803soft), selected move count (56), picked move (SolverVisit{id=f36aed4f, visitGroup=null} {null -> SolverVehicleShift{id=88403ee1}[0]}).
16:23:11.367 DEBUG [pool-8-thread-1]     CH step (11), time spent (975), score (0hard/-553medium/-7997soft), selected move count (57), picked move (SolverVisit{id=44520408, visitGroup=null} {null -> SolverVehicleShift{id=6f87cf48}[1]}).
16:23:11.393 DEBUG [pool-8-thread-1]     CH step (12), time spent (1001), score (-1hard/-549medium/-8719soft), selected move count (38), picked move (SolverVisit{id=6f9a92c8, visitGroup=null} {null -> SolverVehicleShift{id=fb6f06d3}[0]}).
16:23:11.396  INFO [pool-8-thread-1] Construction Heuristic phase (1) ended: time spent (1004), best score (-1hard/-549medium/-8719soft), score calculation speed (1438/sec), step total (13).

Running the same dataset with slightly longer termination (spent-limit=2s, unimproved-spent-limit=2s) shows that no such move is picked when CH is not interrupted:

16:28:59.354 DEBUG [pool-8-thread-1]     CH step (0), time spent (223), score (0hard/-626medium/-1538soft), selected move count (46), picked move (SolverVisit{id=3ea7b2d5, visitGroup=null} {null -> SolverVehicleShift{id=47a75478}[0]}).
16:28:59.513 DEBUG [pool-8-thread-1]     CH step (1), time spent (382), score (0hard/-622medium/-1830soft), selected move count (47), picked move (SolverVisit{id=876e31cf, visitGroup=null} {null -> SolverVehicleShift{id=47a75478}[0]}).
16:28:59.583 DEBUG [pool-8-thread-1]     CH step (2), time spent (452), score (0hard/-606medium/-3550soft), selected move count (48), picked move (SolverVisit{id=91c2223b, visitGroup=null} {null -> SolverVehicleShift{id=3bfd7a04}[0]}).
16:28:59.661 DEBUG [pool-8-thread-1]     CH step (3), time spent (530), score (0hard/-602medium/-3657soft), selected move count (49), picked move (SolverVisit{id=19020590, visitGroup=null} {null -> SolverVehicleShift{id=3bfd7a04}[0]}).
16:28:59.724 DEBUG [pool-8-thread-1]     CH step (4), time spent (593), score (0hard/-598medium/-3663soft), selected move count (50), picked move (SolverVisit{id=4836dfb0, visitGroup=null} {null -> SolverVehicleShift{id=3bfd7a04}[2]}).
16:28:59.779 DEBUG [pool-8-thread-1]     CH step (5), time spent (648), score (0hard/-594medium/-4152soft), selected move count (51), picked move (SolverVisit{id=30eef4d3, visitGroup=null} {null -> SolverVehicleShift{id=3bfd7a04}[0]}).
16:28:59.835 DEBUG [pool-8-thread-1]     CH step (6), time spent (704), score (0hard/-590medium/-4285soft), selected move count (52), picked move (SolverVisit{id=1aa8cf6a, visitGroup=null} {null -> SolverVehicleShift{id=47a75478}[2]}).
16:28:59.884 DEBUG [pool-8-thread-1]     CH step (7), time spent (753), score (0hard/-574medium/-4411soft), selected move count (53), picked move (SolverVisit{id=ae04ae69, visitGroup=null} {null -> SolverVehicleShift{id=2be8764a}[0]}).
16:28:59.928 DEBUG [pool-8-thread-1]     CH step (8), time spent (797), score (0hard/-570medium/-4853soft), selected move count (54), picked move (SolverVisit{id=ea8365af, visitGroup=null} {null -> SolverVehicleShift{id=d694fb59}[0]}).
16:28:59.976 DEBUG [pool-8-thread-1]     CH step (9), time spent (845), score (0hard/-566medium/-5198soft), selected move count (55), picked move (SolverVisit{id=a26d2047, visitGroup=null} {null -> SolverVehicleShift{id=47a75478}[0]}).
16:29:00.018 DEBUG [pool-8-thread-1]     CH step (10), time spent (887), score (0hard/-557medium/-5803soft), selected move count (56), picked move (SolverVisit{id=98e435f7, visitGroup=null} {null -> SolverVehicleShift{id=2be8764a}[0]}).
16:29:00.083 DEBUG [pool-8-thread-1]     CH step (11), time spent (952), score (0hard/-553medium/-7997soft), selected move count (57), picked move (SolverVisit{id=840fe3d6, visitGroup=null} {null -> SolverVehicleShift{id=d694fb59}[1]}).
16:29:00.150 DEBUG [pool-8-thread-1]     CH step (12), time spent (1019), score (0hard/-549medium/-8094soft), selected move count (58), picked move (SolverVisit{id=a1374ef0, visitGroup=null} {null -> SolverVehicleShift{id=d694fb59}[2]}).
16:29:00.255 DEBUG [pool-8-thread-1]     CH step (13), time spent (1124), score (0hard/-545medium/-8541soft), selected move count (59), picked move (SolverVisit{id=46f0f369, visitGroup=null} {null -> SolverVehicleShift{id=d694fb59}[3]}).
16:29:00.316 DEBUG [pool-8-thread-1]     CH step (14), time spent (1185), score (0hard/-541medium/-9617soft), selected move count (60), picked move (SolverVisit{id=ad859e6e, visitGroup=null} {null -> SolverVehicleShift{id=d8c05cdc}[0]}).
16:29:00.356 DEBUG [pool-8-thread-1]     CH step (15), time spent (1225), score (0hard/-537medium/-19733soft), selected move count (61), picked move (SolverVisit{id=62c0a165, visitGroup=null} {null -> SolverVehicleShift{id=fb07005e}[0]}).
16:29:00.397 DEBUG [pool-8-thread-1]     CH step (16), time spent (1266), score (0hard/-533medium/-19900soft), selected move count (62), picked move (SolverVisit{id=444f2ec4, visitGroup=null} {null -> SolverVehicleShift{id=fb07005e}[0]}).
16:29:00.434 DEBUG [pool-8-thread-1]     CH step (17), time spent (1303), score (0hard/-532medium/-20300soft), selected move count (63), picked move (SolverVisit{id=b23a14a3, visitGroup=null} {null -> SolverVehicleShift{id=fb07005e}[2]}).
16:29:00.476 DEBUG [pool-8-thread-1]     CH step (18), time spent (1345), score (0hard/-532medium/-20300soft), selected move count (64), picked move (No change).
16:29:00.513 DEBUG [pool-8-thread-1]     CH step (19), time spent (1382), score (0hard/-528medium/-20821soft), selected move count (64), picked move (SolverVisit{id=3a71821c, visitGroup=null} {null -> SolverVehicleShift{id=fb07005e}[0]}).
16:29:00.550 DEBUG [pool-8-thread-1]     CH step (20), time spent (1419), score (0hard/-524medium/-22405soft), selected move count (65), picked move (SolverVisit{id=90e0c4e7, visitGroup=null} {null -> SolverVehicleShift{id=d0f48be9}[0]}).
16:29:00.600 DEBUG [pool-8-thread-1]     CH step (21), time spent (1469), score (0hard/-520medium/-23115soft), selected move count (66), picked move (SolverVisit{id=64aa6a58, visitGroup=null} {null -> SolverVehicleShift{id=6aaab5e4}[0]}).
16:29:00.644 DEBUG [pool-8-thread-1]     CH step (22), time spent (1513), score (0hard/-516medium/-23595soft), selected move count (67), picked move (SolverVisit{id=3ae8ba8d, visitGroup=null} {null -> SolverVehicleShift{id=6aaab5e4}[0]}).
16:29:00.693 DEBUG [pool-8-thread-1]     CH step (23), time spent (1562), score (0hard/-512medium/-24199soft), selected move count (68), picked move (SolverVisit{id=e05e8cf8, visitGroup=null} {null -> SolverVehicleShift{id=6aaab5e4}[2]}).
16:29:00.735 DEBUG [pool-8-thread-1]     CH step (24), time spent (1604), score (0hard/-508medium/-24675soft), selected move count (69), picked move (SolverVisit{id=2041724e, visitGroup=null} {null -> SolverVehicleShift{id=d0f48be9}[1]}).
16:29:00.775 DEBUG [pool-8-thread-1]     CH step (25), time spent (1643), score (0hard/-504medium/-24740soft), selected move count (70), picked move (SolverVisit{id=fe8bb96c, visitGroup=null} {null -> SolverVehicleShift{id=6aaab5e4}[1]}).
16:29:00.817 DEBUG [pool-8-thread-1]     CH step (26), time spent (1686), score (0hard/-503medium/-25140soft), selected move count (71), picked move (SolverVisit{id=a375efac, visitGroup=null} {null -> SolverVehicleShift{id=f040623b}[0]}).
16:29:00.866 DEBUG [pool-8-thread-1]     CH step (27), time spent (1735), score (0hard/-494medium/-27516soft), selected move count (72), picked move (SolverVisit{id=69f35090, visitGroup=null} {null -> SolverVehicleShift{id=369ee051}[0]}).
16:29:00.943 DEBUG [pool-8-thread-1]     CH step (28), time spent (1811), score (0hard/-490medium/-27784soft), selected move count (73), picked move (SolverVisit{id=ac551583, visitGroup=null} {null -> SolverVehicleShift{id=811836c2}[0]}).
16:29:01.015 DEBUG [pool-8-thread-1]     CH step (29), time spent (1884), score (0hard/-486medium/-27888soft), selected move count (74), picked move (SolverVisit{id=5aa15f73, visitGroup=null} {null -> SolverVehicleShift{id=f040623b}[1]}).
16:29:01.058 DEBUG [pool-8-thread-1]     CH step (30), time spent (1927), score (0hard/-482medium/-28890soft), selected move count (75), picked move (SolverVisit{id=5513a667, visitGroup=null} {null -> SolverVehicleShift{id=811836c2}[0]}).
16:29:01.099 DEBUG [pool-8-thread-1]     CH step (31), time spent (1968), score (0hard/-478medium/-29201soft), selected move count (76), picked move (SolverVisit{id=fae0fe9b, visitGroup=null} {null -> SolverVehicleShift{id=f040623b}[1]}).
16:29:01.132 DEBUG [pool-8-thread-1]     CH step (32), time spent (2001), score (0hard/-474medium/-29657soft), selected move count (56), picked move (SolverVisit{id=3f8c6dc6, visitGroup=null} {null -> SolverVehicleShift{id=369ee051}[0]}).
16:29:01.136  INFO [pool-8-thread-1] Construction Heuristic phase (1) ended: time spent (2004), best score (0hard/-474medium/-29657soft), score calculation speed (2115/sec), step total (33).

Expected behavior CH should never return a solution with the score worse than found previously.

Actual behavior When terminated too early, CH may return a solution with the score worse than found previously, even infeasible.

To Reproduce Run the solver with a very short termination that interrupts CH on a model using @PlanningListVariable(allowsUnassignedValues = true) (not sure if that specific information is important).

Please let me know if you need me to send a reproducer.

Environment

Timefold Solver Version or Git ref: 1.14.0

Output of java -version:

openjdk version "22.0.2" 2024-07-16
OpenJDK Runtime Environment (Red_Hat-22.0.2.0.9-2) (build 22.0.2+9)
OpenJDK 64-Bit Server VM (Red_Hat-22.0.2.0.9-2) (build 22.0.2+9, mixed mode, sharing)

Output of uname -a or ver: Linux fedora 6.10.11-100.fc39.x86_64 #1 SMP PREEMPT_DYNAMIC Wed Sep 18 21:08:06 UTC 2024 x86_64 GNU/Linux

Oct 03 '24 20:10 winklerm