Performance drop when Panache/Hibernate is involved

[xputerax]

What I'm trying to achieve

I'm moving away from in-memory storage (using a global Map) to MariaDB for persistence

What problems I'm facing

After implementing the DB storage, the solver never manages to get the correct solution (negative hard score)

Fast code:

ExamTimetable problem = new ExamTimetable(timeslots, exams, venues, studentGroups, request.getSubjects());
problem.setUnusableDates(request.unusableDates);

QuarkusTransaction.joiningExisting().run(() -> {
    Job newJob = new Job(jobId, problem, null, null, null);
    jobRepository.persist(newJob);
});

solverManager.solveBuilder()
        .withProblemId(jobId)
        .withProblemFinder(id -> {
            // return problem;
            Job job = jobRepository.findByIdOptional(jobId)
                .orElseThrow(() -> new NotFoundException(String.format("No exam timetable job with ID '%s'", jobId)));
            return job.getTimetable();
        })
      // .withSolverJobStartedConsumer(consumerFactory.solverJobStartedConsumer(jobId))
      // .withBestSolutionConsumer(consumerFactory.bestSolutionConsumer(jobId))
      // .withFinalBestSolutionConsumer(consumerFactory.finalBestSolutionConsumer(jobId))
      // .withExceptionHandler(consumerFactory.exceptionHandler(jobId))
      .withConfigOverride(solverConfigOverride)
      .run();

For the sake of simplicity, I just commented the lines where I passed the callback/consumer to the solver to bypass Hibernate.

Slow code:

        ExamTimetable problem = new ExamTimetable(timeslots, exams, venues, studentGroups, request.getSubjects());
        problem.setUnusableDates(request.unusableDates);

        QuarkusTransaction.joiningExisting().run(() -> {
            Job newJob = new Job(jobId, problem, null, null, null);
            jobRepository.persist(newJob);
        });

        solverManager.solveBuilder()
                .withProblemId(jobId)
                .withProblemFinder(id -> {
                    Job job = jobRepository.findByIdOptional(jobId)
                        .orElseThrow(() -> new NotFoundException(String.format("No exam timetable job with ID '%s'", jobId)));
                    return job.getTimetable();
                })
                .withSolverJobStartedConsumer(consumerFactory.solverJobStartedConsumer(jobId))
                .withBestSolutionConsumer(consumerFactory.bestSolutionConsumer(jobId))
                .withFinalBestSolutionConsumer(consumerFactory.finalBestSolutionConsumer(jobId))
                .withExceptionHandler(consumerFactory.exceptionHandler(jobId))
                .withConfigOverride(solverConfigOverride)
                .run();

ConsumerFactory.java:

import java.time.LocalDateTime;
import java.util.Map;
import java.util.function.BiConsumer;
import java.util.function.Consumer;

import org.slf4j.Logger;
import org.slf4j.LoggerFactory;

import ai.timefold.solver.core.api.score.analysis.ScoreAnalysis;
import ai.timefold.solver.core.api.score.buildin.hardsoft.HardSoftScore;
import ai.timefold.solver.core.api.solver.SolutionManager;
import ai.timefold.solver.core.api.solver.SolverManager;
import ai.timefold.solver.core.api.solver.SolverStatus;
import io.quarkus.narayana.jta.QuarkusTransaction;
import jakarta.enterprise.context.ApplicationScoped;
import jakarta.inject.Inject;
import jakarta.inject.Named;

@ApplicationScoped
public class SolverConsumerFactory {
    private final Logger log = LoggerFactory.getLogger(getClass());
    private JobRepository jobRepository; // Panache repository
    private SolutionManager<ExamTimetable, HardSoftScore> solutionManager;
    private SolverManager<ExamTimetable, String> solverManager;

    @Inject
    public SolverConsumerFactory(
        JobRepository jobRepository,
        SolutionManager<ExamTimetable, HardSoftScore> solutionManager,
        @Named("examSolver") SolverManager<ExamTimetable, String> solverManager
    ) {
        this.jobRepository = jobRepository;
        this.solutionManager = solutionManager;
        this.solverManager = solverManager;
    }

    public Consumer<ExamTimetable> solverJobStartedConsumer(String jobId) {
        return (solution) -> {
            log.info("Exam timetable job " + jobId + " started");

            QuarkusTransaction.joiningExisting().run(() -> {
                jobRepository.update("set timetable=:timetable, startAt=:startAt where id=:id",
                    Map.of("id", jobId, "timetable", solution, "startAt", LocalDateTime.now())
                );
            });
        };
    }

    public Consumer<ExamTimetable> bestSolutionConsumer(String jobId) {
        return (solution) -> {
            log.info("Exam timetable job " + jobId + " score updated: " + solution.getScore());

            ScoreAnalysis<HardSoftScore> analysis = solutionManager.analyze(solution);
            SolverStatus solverStatus = solverManager.getSolverStatus(jobId);

            solution.setScoreAnalysis(analysis);
            solution.setSolverStatus(solverStatus);

            QuarkusTransaction.joiningExisting().run(() -> {
                jobRepository.updateSolutionById(jobId, solution);
            });
        };
    }

    public Consumer<ExamTimetable> finalBestSolutionConsumer(String jobId) {
        return (solution) -> {
            log.info("Exam timetable job " + jobId + " final score: " + solution.getScore());

            ScoreAnalysis<HardSoftScore> analysis = solutionManager.analyze(solution);
            SolverStatus solverStatus = solverManager.getSolverStatus(jobId);

            solution.setScoreAnalysis(analysis);
            solution.setSolverStatus(solverStatus);

            // TODO: will this be called when an error occurs?
            log.info("Job {} finished with no errors", jobId);

            QuarkusTransaction.joiningExisting().run(() -> {
                jobRepository.update("set timetable=:timetable, endAt=:endAt where id=:id",
                    Map.of("id", jobId, "endAt", LocalDateTime.now(), "timetable", solution)
                );
            });
        };
    }

    public BiConsumer<String, Throwable> exceptionHandler(String jobId) {
        return (id, exception) -> {
            Job updatedJob = jobRepository.findById(jobId);
            updatedJob.setException(exception);
            updatedJob.setEndAt(LocalDateTime.now());
            updatedJob.setTimetable(null);

            QuarkusTransaction.joiningExisting().run(() -> {
                jobRepository.updateById(jobId, updatedJob);
            });

            log.error("Exam timetable job {} finished with errors: {}", id, exception.getMessage());
            exception.printStackTrace();
        };
    }
}

JobRepository.java:

import io.quarkus.hibernate.orm.panache.PanacheQuery;
import io.quarkus.hibernate.orm.panache.PanacheRepositoryBase;
import io.quarkus.panache.common.Parameters;
import jakarta.enterprise.context.ApplicationScoped;
import jakarta.enterprise.context.control.ActivateRequestContext;

@ApplicationScoped
@ActivateRequestContext
public class JobRepository implements PanacheRepositoryBase<Job, String> {
    public Job findById(String id) {
        return find("id", id).firstResult();
    }

    public int updateById(String id, Job job) {
        return update("set timetable = :timetable, startAt = :startAt, endAt = :endAt where id = :id ",
            Parameters.with("id", job.getId())
                .and("timetable", job.getTimetable())
                .and("startAt", job.getStartAt())
                .and("endAt", job.getEndAt())
        );
    }

    public int updateSolutionById(String id, ExamTimetable solution) {
        return update("set timetable = :timetable  where id = :id ",
            Parameters.with("id", id)
                .and("timetable", solution)
        );
    }
}

Without Panache/Hibernate, it managed to solve the problem (0 hard score) during the construction heuristic phase in 12 seconds:

Generated Timeslots: 248
Generated Exams: 218
2025-05-23 16:09:37,290 INFO  [ai.tim.sol.cor.imp.sol.DefaultSolver] (pool-17-thread-1) Solving started: time spent (3), best score (0hard/0soft), environment mode (PHASE_ASSERT), move thread count (NONE), random (JDK with seed 0).
2025-05-23 16:09:37,291 INFO  [ai.tim.sol.cor.imp.sol.DefaultSolver] (pool-17-thread-1) Problem scale: entity count (218), variable count (436), approximate value count (260), approximate problem scale (1.786865 × 10^757).
2025-05-23 16:09:50,163 INFO  [ai.tim.sol.cor.imp.con.DefaultConstructionHeuristicPhase] (pool-17-thread-1) Construction Heuristic phase (0) ended: time spent (12876), best score (0hard/-7soft), move evaluation speed (50405/sec), step total (218).
2025-05-23 16:10:37,300 INFO  [ai.tim.sol.cor.imp.loc.DefaultLocalSearchPhase] (pool-17-thread-1) Local Search phase (1) ended: time spent (60012), best score (0hard/-4soft), move evaluation speed (11107/sec), step total (86153).
2025-05-23 16:10:37,302 INFO  [ai.tim.sol.cor.imp.sol.DefaultSolver] (pool-17-thread-1) Solving ended: time spent (60015), best score (0hard/-4soft), move evaluation speed (19533/sec), phase total (2), environment mode (PHASE_ASSERT), move thread count (NONE).

--
Tests paused
Press [e] to edit command line args (currently ''), [r] to resume testing, [o] Toggle test output, [:] for the terminal, [h] for more options>

When Hibernate is involved, it never managed to solve the problem after the deadline has reached:

Generated Timeslots: 248
Generated Exams: 218
2025-05-23 16:12:51,067 INFO  [my.bay.res.exa.SolverConsumerFactory] (pool-29-thread-1) Exam timetable job a5a68fd2-86b9-4f63-bac9-e025e698ec84 started
2025-05-23 16:12:51,067 INFO  [ai.tim.sol.cor.imp.sol.DefaultSolver] (pool-27-thread-1) Solving started: time spent (2), best score (0hard/0soft), environment mode (PHASE_ASSERT), move thread count (NONE), random (JDK with seed 0).
2025-05-23 16:12:51,068 INFO  [ai.tim.sol.cor.imp.sol.DefaultSolver] (pool-27-thread-1) Problem scale: entity count (218), variable count (436), approximate value count (260), approximate problem scale (1.786865 × 10^757).
2025-05-23 16:13:03,811 INFO  [ai.tim.sol.cor.imp.con.DefaultConstructionHeuristicPhase] (pool-27-thread-1) Construction Heuristic phase (0) ended: time spent (12746), best score (-47hard/-6soft), move evaluation speed (50911/sec), step total (218).
2025-05-23 16:13:51,069 INFO  [ai.tim.sol.cor.imp.loc.DefaultLocalSearchPhase] (pool-27-thread-1) Local Search phase (1) ended: time spent (60004), best score (-22hard/-2soft), move evaluation speed (11750/sec), step total (102234).
2025-05-23 16:13:51,069 INFO  [ai.tim.sol.cor.imp.sol.DefaultSolver] (pool-27-thread-1) Solving ended: time spent (60004), best score (-22hard/-2soft), move evaluation speed (20066/sec), phase total (2), environment mode (PHASE_ASSERT), move thread count (NONE).
2025-05-23 16:13:51,071 INFO  [my.bay.res.exa.SolverConsumerFactory] (pool-29-thread-1) Exam timetable job a5a68fd2-86b9-4f63-bac9-e025e698ec84 final score: -22hard/-2soft
2025-05-23 16:13:51,075 INFO  [my.bay.res.exa.SolverConsumerFactory] (pool-29-thread-1) Job a5a68fd2-86b9-4f63-bac9-e025e698ec84 finished with no errors

--
Tests paused
Press [e] to edit command line args (currently ''), [r] to resume testing, [o] Toggle test output, [:] for the terminal, [h] for more options>

I increased the deadline to 5 minutes but the hard score is still negative (although a bit better) after the solver terminates.

At first I thought it was repeatedly hitting the DB, but VisualVM and JFR showed otherwise:

I'm currently at a loss here. What am I missing?

What I've Tried

1. Running QuarkusTransaction.joiningExisting().run(() -> { ... }) in SmallRyeManagedExecutor - no effect

What I have not tried

1. Use native MariaDB installation instead of Docker (will update later)
2. Stop using XA/JTA (I'm not sure how to change this in Quarkus)

My app config is as follows but it still uses XA:

quarkus.datasource.jdbc.transactions=ENABLED
quarkus.datasource.*.jdbc.transactions=ENABLED

3. Storing the result both in-memory and DB:

I found this StackOverflow post where this person is trying to achieve the same thing, but I wish to just store it directly in the DB (every time the score updates) to allow the user interface to poll and display the result - is this not possible?

More Info

Quarkus Version: 3.21.3
Timefold Version: 1.22.1
Docker Image: docker.io/mariadb:10.11
Docker: 27.5.1, build 9f9e405 (using OrbStack)
OrbStack: Version: 1.10.3 (1100300) Commit: 2b5dd5f580d80a3d2494b7b40dde2ef46813cfc5 (v1.10.3)
Uname: Darwin Skynet 24.2.0 Darwin Kernel Version 24.2.0: Fri Dec 6 19:01:59 PST 2024; root:xnu-11215.61.5~2/RELEASE_ARM64_T6000 arm64

I can provide the flight recording if that helps

[xputerax]

I've found a solution for now. I think it has something to do with JPA managed entity.

Change this:

  .withProblemFinder(id -> {
      Job job = jobRepository.findByIdOptional(id)
          .orElseThrow(() -> new NotFoundException(String.format("No exam timetable job with ID '%s'", id)));
      return job.getTimetable();
  })

To this:

  .withProblem(problem)

Where problem is the PlanningSolution (ExamTimetable in this case) that is constructed from the request (not fetched from the database).

However, there are cases where I still need to fetch the jobs from database:

1. Run unstarted or unfinished jobs in the case of application restart
2. Continue solving after termination (in case the problem is still unsolved)

I'll post an update after I found a solution

[triceo]

Hello @xputerax! Although I am not quite sure what is happening here, it is probably some JPA stuff - if I had to guess, every time the solver modifies an entity, the update is being processed by JPA. Hard to say without attaching a profiler.

There should be a way to detach the timetable from the session. That's what I'd do, and only reattach it when I need to persist it.

[ge0ffrey]

entityManager.detach(timetable); after getting it from the database, before calling solve() should do it