performance regression at 9.11.4210

[dimbleby]

ortools-regression.tar.gz

the attached code (one python file and one input file) is solving a toy puzzle about tiling a board with 2x2 pieces, where each corner of each 2x2 piece has a label and labels on touching pieces have to match up

at 9.10.4067 it finds the unique solution in about 3 seconds and then is done, presumably having proved that there are no further solutions

at 9.11.4210 it quickly spits out that same solution - four times - and then sits around burning CPU for I dont know how long.

Maybe it is not a performance regression as such but a plain bug getting stuck in a tight loop somewhere.

[dimbleby]

ah, perhaps this is the same as:

• Performance regression in main after an optimal solution already found #4268.

As in that one - if I do not provide the solution printer to the model then the code finishes quickly.

[marenaud]

Just piggybacking on this issue to confirm that we've also noticed large performance regressions in our test suite for 9.11 using the python CP SAT API. Toy models that used to finish instantly are now taking up the entire max_time_in_seconds and returning OPTIMAL which implies that the solver has been sitting there doing nothing for some time otherwise it would return FEASIBLE instead.

[lperron]

We have a bug in our code.
On satisfiability problems, having a callback makes it enumerates all solutions.

Call StopSearch() after the first solution to exit as a workaround

[lperron]

does this happen with optimization models too ?

[marenaud]

Yep. Our models define a maximization objective, we do register a solution callback but only for logging purposes. I can confirm on our end that removing this callback resolves the performance regression issue.

[lperron]

can you send me a python code that exhibits the issue ?

[aleberr]

Here's a code that exhibits the issue on this model (ORtools 9.11, windows 11):

from google.protobuf.text_format import Parse
from ortools.sat.python import cp_model
from ortools.sat.python.cp_model import CpSolverSolutionCallback


class SolutionLogger(CpSolverSolutionCallback):
    def __init__(self) -> None:
        CpSolverSolutionCallback.__init__(self)
        self.soln_n = 0

    def OnSolutionCallback(self):
        self.soln_n += 1


file_path = "model9p11.txt"

with open(file_path, "r") as file:
    s = file.read()

model = cp_model.CpModel()
Parse(s, model.Proto())
print("Model has an objective:", model.has_objective())

solver = cp_model.CpSolver()

status = solver.Solve(model)
print(
    f"No callback: Solved the model with status {status} in {solver.WallTime()} seconds"
)

status = solver.Solve(model, solution_callback=SolutionLogger())
print(
    f"With callback: Solved the model with status {status} in {solver.WallTime()} seconds"
)

I confirmed that the issue is not present in ORtools 9.9 (although the model that gets written to file is slightly different for 9.9)
If I reduce the model size, I can get it to terminate eventually, but it still takes much longer than in other versions.

[marenaud]

^ if you take the above code and slightly modify it to have a max runtime

solver = cp_model.CpSolver()

status = solver.Solve(model)
print(
    f"No callback: Solved the model with status {solver.StatusName(status)} in {solver.WallTime()} seconds"
)

solver.parameters.max_time_in_seconds = 10

status = solver.Solve(model, solution_callback=SolutionLogger())
print(
    f"With callback: Solved the model with status {solver.StatusName(status)} in {solver.WallTime()} seconds"
)

You should get it to terminate with something similar to this:

Model has an objective: True
No callback: Solved the model with status OPTIMAL in 0.081585 seconds
With callback: Solved the model with status OPTIMAL in 10.002345 seconds

[lperron]

what parameters ?

[marenaud]

is there anything you're looking for that isn't in the model proto dump? @aleberr and I's model construction is difficult to turn into a shareable example so we hoped that sharing the protobuf would be enough

[lperron]

What is happening is that search finishes normally, then it waits until the time limit is crossed.

I am debugging.

[lperron]

Fixed. Thanks for the report.