upgrading Optaplanner to 8.25+ results in very slow performances

Question

After a while, I'm working again on a side-project which was using Optaplanner 8.20.

Since we now are in V8.42 (or 9.42 with quakus 3/java17) I tried to upgrade the app to the latest version (I would love to use quarkus 3) but I ran into multiple problems.

One of them is a huge drop in resulting performances.

The calculated scores on a specific dataset used to be like that (optaplanner v8.24.1.Final):

2023-08-10 15:28:44,678 INFO  [io.fde.pla.bac.sol.ser.sch.SolverService] (executor-thread-0) running schedule problem febd43c7-54ae-4a9e-aea6-05e52ef8a175
2023-08-10 15:28:44,781 INFO  [org.opt.cor.imp.sol.DefaultSolver] (pool-10-thread-1) Solving started: time spent (92), best score (-2544hard/-1116medium/0soft), environment mode (REPRODUCIBLE), move thread count (NONE), random (JDK with seed 0).
2023-08-10 15:28:47,842 INFO  [org.opt.cor.imp.con.DefaultConstructionHeuristicPhase] (pool-10-thread-1) Construction Heuristic phase (0) ended: time spent (3153), best score (-1569hard/-682medium/-2314921soft), score calculation speed (25529/sec), step total (1116).
2023-08-10 15:28:47,843 INFO  [io ... thread-1)) -1569hard/-682medium/-2314921soft
2023-08-10 15:28:48,210 INFO  [io ... thread-1) -1520hard/-698medium/-2266062soft
2023-08-10 15:28:50,369 INFO  [io ... thread-1) -1201hard/-762medium/-2057769soft
2023-08-10 15:28:52,706 INFO  [io ... thread-1) -904hard/-808medium/-1914728soft
2023-08-10 15:28:55,170 INFO  [io ... thread-1) -685hard/-818medium/-2005894soft
2023-08-10 15:28:56,964 INFO  [io ... thread-1) -567hard/-827medium/-1899323soft
2023-08-10 15:28:58,717 INFO  [io ... thread-1) -485hard/-831medium/-2032438soft
2023-08-10 15:29:00,482 INFO  [io ... thread-1) -409hard/-833medium/-1994180soft
2023-08-10 15:29:02,220 INFO  [io ... thread-1) -350hard/-830medium/-1949107soft
2023-08-10 15:29:03,913 INFO  [io ... thread-1) -303hard/-831medium/-1908639soft
2023-08-10 15:29:05,689 INFO  [io ... thread-1) -263hard/-835medium/-1944460soft
2023-08-10 15:29:07,442 INFO  [io ... thread-1) -210hard/-836medium/-2005530soft
2023-08-10 15:29:09,693 INFO  [io ... thread-1) -186hard/-833medium/-1966828soft
2023-08-10 15:29:11,538 INFO  [io ... thread-1) -155hard/-833medium/-1953647soft
2023-08-10 15:29:13,601 INFO  [io ... thread-1) -139hard/-826medium/-2065612soft
2023-08-10 15:29:15,684 INFO  [io ... thread-1) -120hard/-829medium/-2059968soft
2023-08-10 15:29:17,603 INFO  [io ... thread-1) -106hard/-840medium/-1835454soft
2023-08-10 15:29:19,450 INFO  [io ... thread-1) -96hard/-823medium/-2125307soft
...

and after upgrading to 8.25 (or higher version, I tried with 8.42 for instance) I got that:

    2023-08-10 15:31:17,032 INFO  [io.fde.pla.bac.sol.ser.sch.SolverService] (executor-thread-0) running schedule problem a164dcde-393f-42e2-a2e3-c19b967b12f5
    2023-08-10 15:31:17,140 INFO  [org.opt.cor.imp.sol.DefaultSolver] (pool-10-thread-1) Solving started: time spent (96), best score (-2544hard/-1116medium/0soft), environment mode (REPRODUCIBLE), move thread count (NONE), random (JDK with seed 0).
    2023-08-10 15:31:20,343 INFO  [org.opt.cor.imp.con.DefaultConstructionHeuristicPhase] (pool-10-thread-1) Construction Heuristic phase (0) ended: time spent (3298), best score (-1569hard/-682medium/-2314921soft), score calculation speed (24405/sec), step total (1116).
    2023-08-10 15:31:20,343 INFO  [io ... thread-1) -1569hard/-682medium/-2314921soft
    2023-08-10 15:31:20,856 INFO  [io ... thread-1) -1569hard/-682medium/-2314603soft
    2023-08-10 15:31:23,609 INFO  [io ... thread-1) -1569hard/-682medium/-2307795soft
    2023-08-10 15:31:25,961 INFO  [io ... thread-1) -1569hard/-682medium/-2303770soft
    2023-08-10 15:31:28,604 INFO  [io ... thread-1) -1569hard/-682medium/-2301149soft
    2023-08-10 15:31:32,712 INFO  [io ... thread-1) -1569hard/-682medium/-2301060soft
    2023-08-10 15:31:35,349 INFO  [io ... thread-1) -1569hard/-682medium/-2296655soft
    2023-08-10 15:31:38,208 INFO  [io ... thread-1) -1569hard/-681medium/-2313953soft
    2023-08-10 15:31:51,813 INFO  [io ... thread-1) -1569hard/-680medium/-2351427soft
    2023-08-10 15:32:17,974 INFO  [io ... thread-1) -1569hard/-679medium/-2550884soft
    2023-08-10 15:32:20,601 INFO  [io ... thread-1) -1569hard/-679medium/-2545967soft
    2023-08-10 15:32:23,293 INFO  [io ... thread-1) -1569hard/-679medium/-2535134soft
    2023-08-10 15:32:45,319 INFO  [io ... thread-1) -1569hard/-678medium/-2607937soft
    2023-08-10 15:32:48,158 INFO  [io ... thread-1) -1569hard/-678medium/-2600937soft
    2023-08-10 15:32:50,932 INFO  [io ... thread-1) -1569hard/-678medium/-2578577soft
    2023-08-10 15:33:47,104 INFO  [io ... thread-1) -1569hard/-678medium/-2543732soft
    2023-08-10 15:33:53,129 INFO  [io ... thread-1) -1569hard/-678medium/-2542668soft
...

I can't find any changelog about the 8.25 optaplanner version.

Do you have any idea of where to start to look at?

I imagine it's related to the method used by the solver to try to optimize the problem but... I can't say why.

I was thinking to migrate to timefold 1.0, but I need to fix this major performance drop first on my app

This is the full changelog between 8.24 and 8.25: https://github.com/kiegroup/optaplanner/compare/8.24.x...8.25.x Nothing affecting performance stands out, unless you chose to use Constraint Streams Bavet (not default); in that case, there were a lot of changes, any of which could have caused this. However, there are regression tests on CS performance, so I find it unlikely something as massive as this would slip through the cracks. Without a reproducer, I won't be able to help. — Lukáš Petrovický, Aug 10 '23 at 13:50
thanks for you quick answer, Providing a reproducer will require quite a bit of work to get something minimal. I will do it, and maybe find the problem in the process... If I don't I will provide you the reproducer. — minioim, Aug 10 '23 at 15:06

Geoffrey De Smet · Answer 1 · 2023-08-15T05:24:58.853

From your before log:

2023-08-10 15:28:47,842 INFO  [org.opt.cor.imp.con.DefaultConstructionHeuristicPhase] (pool-10-thread-1) Construction Heuristic phase (0) ended: ..., score calculation speed (25529/sec), ...

From your after log:

2023-08-10 15:31:20,343 INFO  [org.opt.cor.imp.con.DefaultConstructionHeuristicPhase] (pool-10-thread-1) Construction Heuristic phase (0) ended: ... score calculation speed (24405/sec) ...

Those 2 score calculation speeds are similar. Do you see a difference in the score calculation speed for "solving ended"?

Things to check:

environment mode (REPRODUCIBLE) as your "solver started" log indicates is good. If either would be using FAST_ASSERT or FULL_ASSERT, that one would be artificially slow.
log level should be info (or maybe debug). Not trace. For org.optaplanner, org.drools and org.kie.
The fact that you have a bunch of System.out's in there could also slow down solving.

Things to do:

Try optaplanner 8.38. I haven't benchmarked 8.42 yet and it's not unfathomable that a change in drools had a performance impact on optaplanner. Looking at the commit logs: even though the OptaPlanner code doesn't change any more, it does get updated to the latest version of Drools and optaplanner is released with that every month.
Try Timefold 0.8 or 1.0. It takes 2 minutes, run these instructions. It doesn't use drools and the team has verified the quality of every release. Timefold is significantly faster than OptaPlanner out of the box.

thanks for you interest, I'm currently reworking the architecture of my app (I was getting stuck with a too simple architecture) and it was hard to isolate a potential problem. Once it's done, I will try you suggestions and keep you informed here. Thanks — minioim, Aug 16 '23 at 21:19

upgrading Optaplanner to 8.25+ results in very slow performances

1 Answers1