Skip to content
New issue

Have a question about this project? Sign up for a free GitHub account to open an issue and contact its maintainers and the community.

By clicking “Sign up for GitHub”, you agree to our terms of service and privacy statement. We’ll occasionally send you account related emails.

Already on GitHub? Sign in to your account

Performance regression from v9.7 -> v9.8-v9.11 #4166

Open
hanno-becker opened this issue Mar 31, 2024 · 55 comments
Open

Performance regression from v9.7 -> v9.8-v9.11 #4166

hanno-becker opened this issue Mar 31, 2024 · 55 comments
Assignees
Labels
Solver: CP-SAT Solver Relates to the CP-SAT solver
Milestone

Comments

@hanno-becker
Copy link

hanno-becker commented Mar 31, 2024

What version of OR-Tools and what language are you using?
Version: v9.7, v9.8, v9.9, v9.10, v9.11
Language: Python

Which solver are you using (e.g. CP-SAT, Routing Solver, GLOP, BOP, Gurobi)

CP-SAT

What operating system (Linux, Windows, ...) and version?

Apple M1 Pro, MacOS Sonoma Version 14.3.1

What did you do?

Updated OR-Tools from v9.7 to v9.8 and v9.9 when used as the backend for the SLOTHY assembly superoptimizer.

What did you expect to see

CP-SAT performance that is similar or better in terms of runtime and consistency.

What did you see instead?

Significant inconsistency in the runtime of CP-SAT.

Steps to reproduce:

  1. Save the attached model.txt (5.4MB) and the following as run_model.py:
# Following https://groups.google.com/g/or-tools-discuss/c/jg-LYSWAgZA/m/QMsyJQI-AgAJ

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

TIMEOUT=15 # In the good case, the model solves in ~8s on an Apple M1
ITERATIONS=30

def load_and_solve(i):
    model = cp_model.CpModel()
    with open("model.txt", "r") as file:
        text_format.Parse(file.read(), model.Proto())
    print (f"[{i}]: Solve using OR-Tools v{ortools.__version__} ... ", end='', flush=True)
    solver = cp_model.CpSolver()
    solver.parameters.max_time_in_seconds = TIMEOUT
    status = solver.Solve(model)
    status_str = solver.StatusName(status)
    print(f"{status_str}, wall time: {solver.WallTime():.4f} s")

for i in range(ITERATIONS):
    load_and_solve(i)
  1. In an environment with OR-Tools v9.7/v9.8/v9.9 setup, do
python3 run_model.py
  1. Observe
    • High consistency in performance for v9.7
    • Low consistency in performance for v9.8 and v9.9

Here are the outputs on my local machine (see above):

[0]: Solve using OR-Tools v9.7.2996 ... OPTIMAL, wall time: 7.7095 s
[1]: Solve using OR-Tools v9.7.2996 ... OPTIMAL, wall time: 7.6358 s
[2]: Solve using OR-Tools v9.7.2996 ... OPTIMAL, wall time: 7.6029 s
[3]: Solve using OR-Tools v9.7.2996 ... OPTIMAL, wall time: 7.6173 s
[4]: Solve using OR-Tools v9.7.2996 ... OPTIMAL, wall time: 7.6677 s
[5]: Solve using OR-Tools v9.7.2996 ... OPTIMAL, wall time: 7.6342 s
[6]: Solve using OR-Tools v9.7.2996 ... OPTIMAL, wall time: 7.6091 s
[7]: Solve using OR-Tools v9.7.2996 ... OPTIMAL, wall time: 7.6222 s
[8]: Solve using OR-Tools v9.7.2996 ... OPTIMAL, wall time: 7.6853 s
[9]: Solve using OR-Tools v9.7.2996 ... OPTIMAL, wall time: 7.6149 s
[10]: Solve using OR-Tools v9.7.2996 ... OPTIMAL, wall time: 7.6368 s
[11]: Solve using OR-Tools v9.7.2996 ... OPTIMAL, wall time: 7.6400 s
[12]: Solve using OR-Tools v9.7.2996 ... OPTIMAL, wall time: 7.6311 s
[13]: Solve using OR-Tools v9.7.2996 ... OPTIMAL, wall time: 7.6256 s
[14]: Solve using OR-Tools v9.7.2996 ... OPTIMAL, wall time: 7.6580 s
[15]: Solve using OR-Tools v9.7.2996 ... OPTIMAL, wall time: 7.6790 s
[16]: Solve using OR-Tools v9.7.2996 ... OPTIMAL, wall time: 7.5866 s
[17]: Solve using OR-Tools v9.7.2996 ... OPTIMAL, wall time: 7.6641 s
[18]: Solve using OR-Tools v9.7.2996 ... OPTIMAL, wall time: 7.6367 s
[19]: Solve using OR-Tools v9.7.2996 ... OPTIMAL, wall time: 7.5504 s
[20]: Solve using OR-Tools v9.7.2996 ... OPTIMAL, wall time: 7.6438 s
[21]: Solve using OR-Tools v9.7.2996 ... OPTIMAL, wall time: 7.6866 s
[22]: Solve using OR-Tools v9.7.2996 ... OPTIMAL, wall time: 7.6646 s
[23]: Solve using OR-Tools v9.7.2996 ... OPTIMAL, wall time: 7.6997 s
[24]: Solve using OR-Tools v9.7.2996 ... OPTIMAL, wall time: 7.7523 s
[25]: Solve using OR-Tools v9.7.2996 ... OPTIMAL, wall time: 7.6659 s
[26]: Solve using OR-Tools v9.7.2996 ... OPTIMAL, wall time: 7.6842 s
[27]: Solve using OR-Tools v9.7.2996 ... OPTIMAL, wall time: 7.6527 s
[28]: Solve using OR-Tools v9.7.2996 ... OPTIMAL, wall time: 7.6678 s
[29]: Solve using OR-Tools v9.7.2996 ... OPTIMAL, wall time: 7.6791 s

[0]: Solve using OR-Tools v9.8.3296 ... UNKNOWN, wall time: 15.0477 s
[1]: Solve using OR-Tools v9.8.3296 ... UNKNOWN, wall time: 15.0498 s
[2]: Solve using OR-Tools v9.8.3296 ... OPTIMAL, wall time: 8.0398 s
[3]: Solve using OR-Tools v9.8.3296 ... UNKNOWN, wall time: 15.0509 s
[4]: Solve using OR-Tools v9.8.3296 ... UNKNOWN, wall time: 15.0495 s
[5]: Solve using OR-Tools v9.8.3296 ... OPTIMAL, wall time: 7.7925 s
[6]: Solve using OR-Tools v9.8.3296 ... UNKNOWN, wall time: 15.0494 s
[7]: Solve using OR-Tools v9.8.3296 ... UNKNOWN, wall time: 15.0490 s
[8]: Solve using OR-Tools v9.8.3296 ... UNKNOWN, wall time: 15.0499 s
[9]: Solve using OR-Tools v9.8.3296 ... UNKNOWN, wall time: 15.0521 s
[10]: Solve using OR-Tools v9.8.3296 ... UNKNOWN, wall time: 15.0441 s
[11]: Solve using OR-Tools v9.8.3296 ... OPTIMAL, wall time: 7.5001 s
[12]: Solve using OR-Tools v9.8.3296 ... UNKNOWN, wall time: 15.0480 s
[13]: Solve using OR-Tools v9.8.3296 ... OPTIMAL, wall time: 7.7570 s
[14]: Solve using OR-Tools v9.8.3296 ... UNKNOWN, wall time: 15.0510 s
[15]: Solve using OR-Tools v9.8.3296 ... UNKNOWN, wall time: 15.0435 s
[16]: Solve using OR-Tools v9.8.3296 ... UNKNOWN, wall time: 15.0512 s
[17]: Solve using OR-Tools v9.8.3296 ... UNKNOWN, wall time: 15.0548 s
[18]: Solve using OR-Tools v9.8.3296 ... UNKNOWN, wall time: 15.0482 s
[19]: Solve using OR-Tools v9.8.3296 ... UNKNOWN, wall time: 15.0505 s
[20]: Solve using OR-Tools v9.8.3296 ... OPTIMAL, wall time: 7.7389 s
[21]: Solve using OR-Tools v9.8.3296 ... UNKNOWN, wall time: 15.0518 s
[22]: Solve using OR-Tools v9.8.3296 ... UNKNOWN, wall time: 15.0549 s
[23]: Solve using OR-Tools v9.8.3296 ... UNKNOWN, wall time: 15.0517 s
[24]: Solve using OR-Tools v9.8.3296 ... OPTIMAL, wall time: 8.5971 s
[25]: Solve using OR-Tools v9.8.3296 ... UNKNOWN, wall time: 15.0511 s
[26]: Solve using OR-Tools v9.8.3296 ... UNKNOWN, wall time: 15.0454 s
[27]: Solve using OR-Tools v9.8.3296 ... UNKNOWN, wall time: 15.0479 s
[28]: Solve using OR-Tools v9.8.3296 ... UNKNOWN, wall time: 15.0486 s
[29]: Solve using OR-Tools v9.8.3296 ... UNKNOWN, wall time: 15.0584 s

[0]: Solve using OR-Tools v9.9.3963 ... OPTIMAL, wall time: 7.5733 s
[1]: Solve using OR-Tools v9.9.3963 ... UNKNOWN, wall time: 15.1111 s
[2]: Solve using OR-Tools v9.9.3963 ... UNKNOWN, wall time: 15.1614 s
[3]: Solve using OR-Tools v9.9.3963 ... OPTIMAL, wall time: 8.0639 s
[4]: Solve using OR-Tools v9.9.3963 ... OPTIMAL, wall time: 8.1368 s
[5]: Solve using OR-Tools v9.9.3963 ... OPTIMAL, wall time: 7.9110 s
[6]: Solve using OR-Tools v9.9.3963 ... UNKNOWN, wall time: 15.1061 s
[7]: Solve using OR-Tools v9.9.3963 ... UNKNOWN, wall time: 15.1078 s
[8]: Solve using OR-Tools v9.9.3963 ... UNKNOWN, wall time: 15.1067 s
[9]: Solve using OR-Tools v9.9.3963 ... OPTIMAL, wall time: 7.9369 s
[10]: Solve using OR-Tools v9.9.3963 ... OPTIMAL, wall time: 8.0701 s
[11]: Solve using OR-Tools v9.9.3963 ... OPTIMAL, wall time: 7.9486 s
[12]: Solve using OR-Tools v9.9.3963 ... OPTIMAL, wall time: 7.9123 s
[13]: Solve using OR-Tools v9.9.3963 ... UNKNOWN, wall time: 15.1139 s
[14]: Solve using OR-Tools v9.9.3963 ... UNKNOWN, wall time: 15.1011 s
[15]: Solve using OR-Tools v9.9.3963 ... OPTIMAL, wall time: 7.5487 s
[16]: Solve using OR-Tools v9.9.3963 ... OPTIMAL, wall time: 7.9708 s
[17]: Solve using OR-Tools v9.9.3963 ... UNKNOWN, wall time: 15.1062 s
[18]: Solve using OR-Tools v9.9.3963 ... UNKNOWN, wall time: 15.1557 s
[19]: Solve using OR-Tools v9.9.3963 ... UNKNOWN, wall time: 15.1104 s
[20]: Solve using OR-Tools v9.9.3963 ... UNKNOWN, wall time: 15.1042 s
[21]: Solve using OR-Tools v9.9.3963 ... UNKNOWN, wall time: 15.1049 s
[22]: Solve using OR-Tools v9.9.3963 ... OPTIMAL, wall time: 7.9224 s
[23]: Solve using OR-Tools v9.9.3963 ... OPTIMAL, wall time: 8.0476 s
[24]: Solve using OR-Tools v9.9.3963 ... UNKNOWN, wall time: 15.1151 s
[25]: Solve using OR-Tools v9.9.3963 ... OPTIMAL, wall time: 7.9463 s
[26]: Solve using OR-Tools v9.9.3963 ... UNKNOWN, wall time: 15.1065 s
[27]: Solve using OR-Tools v9.9.3963 ... OPTIMAL, wall time: 7.9260 s
[28]: Solve using OR-Tools v9.9.3963 ... OPTIMAL, wall time: 7.9473 s
[29]: Solve using OR-Tools v9.9.3963 ... OPTIMAL, wall time: 7.9736 s

Anything else we should know about your project / environment

  • The issue was observed when trying to update OR-Tools from v9.7 to v9.8 (PR) or v9.9 (PR) in SLOTHY, which led to CI failing because of timeouts.
  • The model provided here is representative of what seems to be a general slowdown / increase of performance variability of CP-SAT for the kinds of models generated by SLOTHY. It can be generated as logs/ntt_dilithium_45678_a55_model.txt via python3 example.py --examples ntt_dilithium_45678_a55 --log-model based off the SLOTHY main branch.
  • Thank you for your work! CP-SAT has so far worked amazingly well as SLOTHY's backend.

If you need any more information, please let me know.

@lperron
Copy link
Collaborator

lperron commented Apr 1, 2024

how many workers are you using ?

@lperron
Copy link
Collaborator

lperron commented Apr 1, 2024

the hint is incomplete. Can you improve it ?

@lperron
Copy link
Collaborator

lperron commented Apr 1, 2024

I have consistent results with these parameters:

fix_variables_to_their_hinted_value:true,num_workers:10,use_feasibility_jump:false,use_rins_lns:false,use_feasibility_pump:false,cp_model_probing_level:0

It seems to solve consistently in 6-7s.

@hanno-becker
Copy link
Author

how many workers are you using ?

The minimal example above does not set them explicitly, so I assume it's determined by the number of cores on the system? In my case, that's 8.

the hint is incomplete. Can you improve it ?

Can you elaborate? Should one either give no hints at all or hints to all variables?

I have consistent results with these parameters:
fix_variables_to_their_hinted_value:true,num_workers:10,use_feasibility_jump:false,use_rins_lns:false,use_feasibility_pump:false,cp_model_probing_level:0

The configurationfix_variables_to_their_hinted_value:true does not seem like an option in my case, because the hints really are only hints -- I set them based on an expectation that for the majority of variables of a certain kind the hinted property will be true, but there will be exceptions (in more detail: SLOTHY can interleave neighbouring loop iterations, and there are booleans indicating if an instruction is pulled forward into the previous iteration (e.g. an early load), or deferred to the next iteration (e.g. late store) -- most instructions will stay in their original iteration and hence the tool is hinting at that, but without early/late instructions altogether, the tool would be much less powerful).

Can you comment further on the configuration options you have set to force consistency? It does look like search either succeeds quickly, or some search strategy leads the solver astray entirely (because where the usual ~8s solution is missed, solution are often not even found with a significantly larger budget.

@lperron
Copy link
Collaborator

lperron commented Apr 1, 2024 via email

@hanno-becker
Copy link
Author

hanno-becker commented Apr 1, 2024

The closer to completeness the hint is, the less effort is needed in search.

There are usually simple solutions which follow the (incomplete) hints, but they won't minimize the given objective (stall minimization, in SLOTHY's case) -- are those still useful hints in your experience, or should they be removed?

@lperron
Copy link
Collaborator

lperron commented Apr 1, 2024

can you try num_workers:24 ?

@lperron
Copy link
Collaborator

lperron commented Apr 1, 2024

or just num_workers:1,search_branching:FIXED_SEARCH

@hanno-becker
Copy link
Author

  • num_workers=24 does not seem to help
  • num_workers=1, search_braching=FIXED_SEARCH gives consistently fast results in ~7s
  • search_branching=FIXED_SEARCH gives consistent results ~8-9s.

What is the takeaway here? When should I consider setting search_branching=FIXED_SEARCH and/or num_workers=1?

I will start a SLOTHY CI run using search_branching=FIXED_SEARCH and see how other workloads fare.

hanno-becker added a commit to slothy-optimizer/slothy that referenced this issue Apr 1, 2024
hanno-becker added a commit to slothy-optimizer/slothy that referenced this issue Apr 1, 2024
@hanno-becker
Copy link
Author

@lperron Unfortunately, unconditionally setting search_branching=FIXED_SEARCH (with or without num_workers=1) does lead to performance problems in other SLOTHY CI workloads.

How would you suggest to proceed here? Do you have a sense of what v9.7->v9.8 change might have triggered this performance change? Has some new search strategy been added in v9.8 that might lead the solver astray in the models produced by SLOTHY?

@Mizux Mizux added this to the v10.0 milestone Apr 2, 2024
@Mizux Mizux added the Solver: CP-SAT Solver Relates to the CP-SAT solver label Apr 2, 2024
@lperron
Copy link
Collaborator

lperron commented Apr 5, 2024

OK. I have no quick solution.
Stay and 9.7 for the time being.

If you could send me a collection of models, I can integrate those into out benchmark suite.

@hanno-becker
Copy link
Author

@lperron I will prepare a set of models representative of SLOTHY workloads and share them in the coming days.

@hanno-becker
Copy link
Author

hanno-becker commented Apr 9, 2024

@lperron @Mizux I have exported some of the models exercised in the SLOTHY CI here: https://github.com/slothy-optimizer/slothy/tree/ci_models/paper/scripts/models Performance numbers as observed on my local Apple M1 are in https://github.com/slothy-optimizer/slothy/blob/ci_models/paper/scripts/models/results.txt. Some of them are solved/refuted very quickly, so one should probably hand-select a few that can be solved in seconds-minutes.

Please let me know if this is useful to you, or what kind of models/format you would prefer otherwise.

@lperron
Copy link
Collaborator

lperron commented Apr 17, 2024

can you try with these parameters ?

um_workers:10,linearization_level:0,use_rins_lns:false,use_feasibility_pump:false,cp_model_probing_level:0

@lperron
Copy link
Collaborator

lperron commented Apr 19, 2024

I ran all the models with 15 runs per model with different settings

16 workers, 20s:

    problems      optimal     feasible   infeasible      unknown
        1440          945           15          465           15

12 workers, 20s, linearization_level:0,use_rins_lns:false,use_feasibility_pump:false,cp_model_probing_level:0

    problems      optimal     feasible   infeasible      unknown
        1440          950           15          465           10

@hanno-becker
Copy link
Author

@lperron Thank you for investigating! What do your measurements tell you?

@lperron
Copy link
Collaborator

lperron commented Apr 20, 2024

The second set of parameters is stable, and solve all the set of problems reliably.

@hanno-becker
Copy link
Author

@lperron Thank you very much for investigating. Are you going to make changes in CP-SAT to make the behaviour the default, or what are next steps?

@lperron
Copy link
Collaborator

lperron commented Apr 23, 2024 via email

@hanno-becker
Copy link
Author

@lperron I'll run the CI on the proposed parameters and get back to you.

@Mizux Mizux modified the milestones: v10.0, Backlog Apr 26, 2024
@hanno-becker
Copy link
Author

Unfortunately, the parameters didn't help -- the tests were still timing out.

@lperron @Mizux How can we move forward here? I tried v9.10 in the meantime, but am still seeing CI failing because of timeouts.

@hanno-becker
Copy link
Author

@lperron Thanks! Should I read this as "Wait for 9.11, it may solve your issues"?

@lperron
Copy link
Collaborator

lperron commented Jul 8, 2024 via email

@hanno-becker
Copy link
Author

@lperron Ok, let's wait and see :-)

@hanno-becker hanno-becker changed the title Performance regression from v9.7 -> v9.8/v9.9/v9.10 Performance regression from v9.7 -> v9.8-v9.11 Sep 29, 2024
@lperron
Copy link
Collaborator

lperron commented Sep 30, 2024 via email

@hanno-becker
Copy link
Author

Hi @lperron. Unfortunately, we still observe the performance regression on 9.11 that prevent us from updating, which is increasingly an issue. We will get back to you shortly with the problematic models.

@mkannwischer
Copy link

@lperron

I've looked into this again, and something else must be going on. The models generated with v9.7 solve fine with v9.11,
but if I generate the model for the same example with v9.11, it's VEEERY slow on both v9.7 or v9.11.

I ran the same example as the one Hanno used: python3 example.py --examples ntt_dilithium_45678_a55.
For v9.11 it gets stuck at ntt_dilithium_123_45678_a55.layer45678_start.slothy (160 stalls) - so that's the model I extract.
I've extracted it with v9.7, v9.11, and the current version in the stable branch (8edc858).
Happy to try other versions if you send me the commits.

I've attached the 3 models:
model_v9.11.txt
model_v9.7.txt
model_8edc858e5cbe8902801d846899dc0de9be748b2c.txt

Note thtat the v9.7 one seems to be quite a bit larger than v9.11 and 8edc858 for some reason. Something must have changed in how these models are generated. Do you have any idea what has changed that may cause this? v9.8 release notes states something about Reduce memory footprint for large model - maybe it's related to that?

I ran each of the models with {v9.7, v9.11, 8edc858} with a timeout of 60 seconds (I did some other experiments with 300 seconds and also was not enough).

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

TIMEOUT=60
ITERATIONS=5

def load_and_solve(file, i):
    model = cp_model.CpModel()
    with open(file, "r") as file:
        text_format.Parse(file.read(), model.Proto())
    print (f"[{i}]: Solve using OR-Tools v{ortools.__version__} ... ", end='', flush=True)
    solver = cp_model.CpSolver()
    solver.parameters.max_time_in_seconds = TIMEOUT

    status = solver.Solve(model)
    status_str = solver.StatusName(status)
    print(f"{status_str}, wall time: {solver.WallTime():.4f} s")


def do_it(file):
    print(file)
    for i in range(ITERATIONS):
        load_and_solve(file, i)


do_it("model_v9.7.txt")
do_it("model_v9.11.txt")
do_it("model_8edc858e5cbe8902801d846899dc0de9be748b2c.11.txt")

v9.7

model_v9.7.txt
[0]: Solve using OR-Tools v9.7.2996 ... OPTIMAL, wall time: 20.1114 s
[1]: Solve using OR-Tools v9.7.2996 ... OPTIMAL, wall time: 19.7626 s
[2]: Solve using OR-Tools v9.7.2996 ... OPTIMAL, wall time: 16.9000 s
[3]: Solve using OR-Tools v9.7.2996 ... OPTIMAL, wall time: 21.7891 s
[4]: Solve using OR-Tools v9.7.2996 ... OPTIMAL, wall time: 16.0108 s
model_v9.11.txt
[0]: Solve using OR-Tools v9.7.2996 ... UNKNOWN, wall time: 60.1689 s
[1]: Solve using OR-Tools v9.7.2996 ... UNKNOWN, wall time: 60.1938 s
[2]: Solve using OR-Tools v9.7.2996 ... UNKNOWN, wall time: 60.1931 s
[3]: Solve using OR-Tools v9.7.2996 ... UNKNOWN, wall time: 60.1643 s
[4]: Solve using OR-Tools v9.7.2996 ... UNKNOWN, wall time: 60.1502 s
model_8edc858e5cbe8902801d846899dc0de9be748b2c.txt
[0]: Solve using OR-Tools v9.7.2996 ... UNKNOWN, wall time: 60.1764 s
[1]: Solve using OR-Tools v9.7.2996 ... UNKNOWN, wall time: 60.3204 s
[2]: Solve using OR-Tools v9.7.2996 ... UNKNOWN, wall time: 60.2146 s
[3]: Solve using OR-Tools v9.7.2996 ... UNKNOWN, wall time: 60.1442 s
[4]: Solve using OR-Tools v9.7.2996 ... UNKNOWN, wall time: 60.0729 s

v9.11

model_v9.7.txt
[0]: Solve using OR-Tools v9.11.4210 ... OPTIMAL, wall time: 14.6964 s
[1]: Solve using OR-Tools v9.11.4210 ... OPTIMAL, wall time: 15.1049 s
[2]: Solve using OR-Tools v9.11.4210 ... OPTIMAL, wall time: 13.9518 s
[3]: Solve using OR-Tools v9.11.4210 ... OPTIMAL, wall time: 16.2707 s
[4]: Solve using OR-Tools v9.11.4210 ... OPTIMAL, wall time: 14.6126 s
model_v9.11.txt
[0]: Solve using OR-Tools v9.11.4210 ... UNKNOWN, wall time: 63.0134 s
[1]: Solve using OR-Tools v9.11.4210 ... UNKNOWN, wall time: 61.6885 s
[2]: Solve using OR-Tools v9.11.4210 ... OPTIMAL, wall time: 40.2420 s
[3]: Solve using OR-Tools v9.11.4210 ... UNKNOWN, wall time: 62.5499 s
[4]: Solve using OR-Tools v9.11.4210 ... UNKNOWN, wall time: 62.2716 s
model_8edc858e5cbe8902801d846899dc0de9be748b2c.txt
[0]: Solve using OR-Tools v9.11.4210 ... UNKNOWN, wall time: 62.2912 s
[1]: Solve using OR-Tools v9.11.4210 ... UNKNOWN, wall time: 61.6309 s
[2]: Solve using OR-Tools v9.11.4210 ... UNKNOWN, wall time: 62.1115 s
[3]: Solve using OR-Tools v9.11.4210 ... UNKNOWN, wall time: 61.9964 s
[4]: Solve using OR-Tools v9.11.4210 ... OPTIMAL, wall time: 49.7086 s

8edc858

model_v9.7.txt
[0]: Solve using OR-Tools v9.11.4212 ... OPTIMAL, wall time: 11.0053 s
[1]: Solve using OR-Tools v9.11.4212 ... OPTIMAL, wall time: 12.9060 s
[2]: Solve using OR-Tools v9.11.4212 ... OPTIMAL, wall time: 14.0371 s
[3]: Solve using OR-Tools v9.11.4212 ... OPTIMAL, wall time: 11.9474 s
[4]: Solve using OR-Tools v9.11.4212 ... OPTIMAL, wall time: 13.0161 s
model_v9.11.txt
[0]: Solve using OR-Tools v9.11.4212 ... UNKNOWN, wall time: 62.1908 s
[1]: Solve using OR-Tools v9.11.4212 ... UNKNOWN, wall time: 61.5383 s
[2]: Solve using OR-Tools v9.11.4212 ... UNKNOWN, wall time: 61.4522 s
[3]: Solve using OR-Tools v9.11.4212 ... UNKNOWN, wall time: 61.4555 s
[4]: Solve using OR-Tools v9.11.4212 ... OPTIMAL, wall time: 33.2710 s
model_8edc858e5cbe8902801d846899dc0de9be748b2c.txt
[0]: Solve using OR-Tools v9.11.4212 ... UNKNOWN, wall time: 61.4360 s
[1]: Solve using OR-Tools v9.11.4212 ... UNKNOWN, wall time: 61.5685 s
[2]: Solve using OR-Tools v9.11.4212 ... UNKNOWN, wall time: 61.5485 s
[3]: Solve using OR-Tools v9.11.4212 ... UNKNOWN, wall time: 61.4791 s
[4]: Solve using OR-Tools v9.11.4212 ... UNKNOWN, wall time: 61.3822 s

I've also noticed that in v9.7, if no objective it passed, it will stop once it finds the first solution, while in the newer versions it will keep searching more solutions until it hits the timeout. That's not very useful for us, but I can tweak the callback in SLOTHY to just stop once one solution is found.

@lperron
Copy link
Collaborator

lperron commented Nov 27, 2024 via email

@lperron
Copy link
Collaborator

lperron commented Nov 27, 2024 via email

@lperron
Copy link
Collaborator

lperron commented Nov 27, 2024 via email

@mkannwischer
Copy link

We are using Python.

I've attached two simpler models obtained by using python3 example.py --examples fixedpoint_radix4_fft_m55 --log-model
fixedpoint_radix4_fft_m55_v9.11.txt
fixedpoint_radix4_fft_m55_v9.7.txt

If I run this with

    solver.parameters.search_branching = cp_model.FIXED_SEARCH
    solver.parameters.num_workers = 1

it's clear that the v9.11 model performs much worse:

$ python3 run_model.py 
fixedpoint_radix4_fft_m55_v9.7.txt
[0]: Solve using OR-Tools v9.11.4210 ... OPTIMAL, wall time: 1.8248 s
[1]: Solve using OR-Tools v9.11.4210 ... OPTIMAL, wall time: 1.7799 s
[2]: Solve using OR-Tools v9.11.4210 ... OPTIMAL, wall time: 1.7804 s
[3]: Solve using OR-Tools v9.11.4210 ... OPTIMAL, wall time: 1.7740 s
[4]: Solve using OR-Tools v9.11.4210 ... OPTIMAL, wall time: 1.7762 s
fixedpoint_radix4_fft_m55_v9.11.txt
[0]: Solve using OR-Tools v9.11.4210 ... OPTIMAL, wall time: 44.2290 s
[1]: Solve using OR-Tools v9.11.4210 ... OPTIMAL, wall time: 7.9812 s
[2]: Solve using OR-Tools v9.11.4210 ... OPTIMAL, wall time: 17.2137 s
[3]: Solve using OR-Tools v9.11.4210 ... OPTIMAL, wall time: 43.6993 s
[4]: Solve using OR-Tools v9.11.4210 ... OPTIMAL, wall time: 17.8757 s

If I run it without the parameters, it's hard to tell (maybe the example is too small).

$ python3 run_model.py 
fixedpoint_radix4_fft_m55_v9.7.txt
[0]: Solve using OR-Tools v9.11.4210 ... OPTIMAL, wall time: 1.8357 s
[1]: Solve using OR-Tools v9.11.4210 ... OPTIMAL, wall time: 1.8599 s
[2]: Solve using OR-Tools v9.11.4210 ... OPTIMAL, wall time: 2.6001 s
[3]: Solve using OR-Tools v9.11.4210 ... OPTIMAL, wall time: 3.6007 s
[4]: Solve using OR-Tools v9.11.4210 ... OPTIMAL, wall time: 3.3738 s
fixedpoint_radix4_fft_m55_v9.11.txt
[0]: Solve using OR-Tools v9.11.4210 ... OPTIMAL, wall time: 3.6041 s
[1]: Solve using OR-Tools v9.11.4210 ... OPTIMAL, wall time: 3.3039 s
[2]: Solve using OR-Tools v9.11.4210 ... OPTIMAL, wall time: 3.8779 s
[3]: Solve using OR-Tools v9.11.4210 ... OPTIMAL, wall time: 3.8803 s
[4]: Solve using OR-Tools v9.11.4210 ... OPTIMAL, wall time: 3.8195 s

@lperron
Copy link
Collaborator

lperron commented Nov 27, 2024 via email

@mkannwischer
Copy link

Something is fishy. in 9.7, creating an interval adds the linear constraint. This is not happening in the v9.7 model. in the v9.11 model, I see all linears close to the intervals. Which should not happen. Loading model with linears in 9.7 should work, without it should not. loading model with linears in 9.11 should just be slower, without it should be fine. It seems versions are mixed up. Comment: a lot of intervals have a fixed size, use the new_fixed_size_interval or new_optional_fixed_size_interval. If you need the end object, just store start + size. This will speed up everything. Laurent Perron | Operations Research | @.*** | (33) 1 42 68 53 00 Le mer. 27 nov. 2024 à 10:10, Matthias J. Kannwischer < @.> a écrit :

We are using Python. I've attached two simpler models obtained by using python3 example.py --examples fixedpoint_radix4_fft_m55 --log-model fixedpoint_radix4_fft_m55_v9.11.txt https://github.com/user-attachments/files/17931760/fixedpoint_radix4_fft_m55_v9.11.txt fixedpoint_radix4_fft_m55_v9.7.txt https://github.com/user-attachments/files/17931761/fixedpoint_radix4_fft_m55_v9.7.txt If I run this with solver.parameters.search_branching = cp_model.FIXED_SEARCH solver.parameters.num_workers = 1 it's clear that the v9.11 model performs much worse: $ python3 run_model.py fixedpoint_radix4_fft_m55_v9.7.txt [0]: Solve using OR-Tools v9.11.4210 ... OPTIMAL, wall time: 1.8248 s [1]: Solve using OR-Tools v9.11.4210 ... OPTIMAL, wall time: 1.7799 s [2]: Solve using OR-Tools v9.11.4210 ... OPTIMAL, wall time: 1.7804 s [3]: Solve using OR-Tools v9.11.4210 ... OPTIMAL, wall time: 1.7740 s [4]: Solve using OR-Tools v9.11.4210 ... OPTIMAL, wall time: 1.7762 s fixedpoint_radix4_fft_m55_v9.11.txt [0]: Solve using OR-Tools v9.11.4210 ... OPTIMAL, wall time: 44.2290 s [1]: Solve using OR-Tools v9.11.4210 ... OPTIMAL, wall time: 7.9812 s [2]: Solve using OR-Tools v9.11.4210 ... OPTIMAL, wall time: 17.2137 s [3]: Solve using OR-Tools v9.11.4210 ... OPTIMAL, wall time: 43.6993 s [4]: Solve using OR-Tools v9.11.4210 ... OPTIMAL, wall time: 17.8757 s If I run it without the parameters, it's hard to tell (maybe the example is too small). $ python3 run_model.py fixedpoint_radix4_fft_m55_v9.7.txt [0]: Solve using OR-Tools v9.11.4210 ... OPTIMAL, wall time: 1.8357 s [1]: Solve using OR-Tools v9.11.4210 ... OPTIMAL, wall time: 1.8599 s [2]: Solve using OR-Tools v9.11.4210 ... OPTIMAL, wall time: 2.6001 s [3]: Solve using OR-Tools v9.11.4210 ... OPTIMAL, wall time: 3.6007 s [4]: Solve using OR-Tools v9.11.4210 ... OPTIMAL, wall time: 3.3738 s fixedpoint_radix4_fft_m55_v9.11.txt [0]: Solve using OR-Tools v9.11.4210 ... OPTIMAL, wall time: 3.6041 s [1]: Solve using OR-Tools v9.11.4210 ... OPTIMAL, wall time: 3.3039 s [2]: Solve using OR-Tools v9.11.4210 ... OPTIMAL, wall time: 3.8779 s [3]: Solve using OR-Tools v9.11.4210 ... OPTIMAL, wall time: 3.8803 s [4]: Solve using OR-Tools v9.11.4210 ... OPTIMAL, wall time: 3.8195 s — Reply to this email directly, view it on GitHub <#4166 (comment)>, or unsubscribe https://github.com/notifications/unsubscribe-auth/ACUPL3JPNVAPBBTP7A5VQBD2CWEBNAVCNFSM6AAAAABFQV5KC6VHI2DSMVQWIX3LMV43OSLTON2WKQ3PNVWWK3TUHMZDKMBTGMZDAMJSGI . You are receiving this because you were mentioned.Message ID: </issues/4166/2503320122 @.
>

Yes, deliberartely mixed up versions. I only ran with v9.11 while models were generated with two versions.
Will try the new_fixed_size_interval and new_optional_fixed_size_interval.

@hanno-becker
Copy link
Author

hanno-becker commented Nov 27, 2024

@lperron I don't yet follow. @mkannwischer's numbers from #4166 (comment) shows that when solving a v9.11-generated model in v9.11 performs much worse than solving the v9.7-generated model for the same underlying example in v9.11. That seems unexpected?

@lperron
Copy link
Collaborator

lperron commented Nov 27, 2024 via email

@lperron
Copy link
Collaborator

lperron commented Nov 27, 2024 via email

@lperron
Copy link
Collaborator

lperron commented Nov 27, 2024 via email

@hanno-becker
Copy link
Author

hanno-becker commented Nov 27, 2024

@lperron Thank you for your reply. I'm struggling to reconcile this -- our tool is unchanged, we merely changed OR-Tools underneath. All hints are registered via the Python binding cp_model.AddHint().

We will add logging on our end in the wrapper that calls cp_model.AddHint(), but is there any chance the information is lost at some point between registering the Hint and dumping the model? Could it be related to the model size optimizations that happened in v9.8 (which is the first version we saw this peformance issue with)?

@lperron
Copy link
Collaborator

lperron commented Nov 27, 2024 via email

@mkannwischer
Copy link

Okay, sorry - this was a stupid mistake.
What's happening is that SLOTHY adds hints after a solution has been found (as we sometimes run the same model multiple times with different objectives). The model was written to file after these hints were added which is stupid.
This explains why the v9.7 models were always very easy to solve regardless of the version - they had already been solved after all.

This also voids some previous experiments in this thread as @hanno-becker was using the same code for exporting models as far as I can tell.
I've moved the writing of the model now (slothy-optimizer/slothy#110) and I've attached two new models.

fixedpoint_radix4_fft_m55_attempt2_v9.11.txt
fixedpoint_radix4_fft_m55_attempt2_v9.7.txt

Solving both with v9.11:

$ python3 run_model.py 
fixedpoint_radix4_fft_m55_attempt2_v9.7.txt
[0]: Solve using OR-Tools v9.11.4210 ... OPTIMAL, wall time: 5.7778 s
[1]: Solve using OR-Tools v9.11.4210 ... OPTIMAL, wall time: 48.1576 s
[2]: Solve using OR-Tools v9.11.4210 ... OPTIMAL, wall time: 42.9583 s
[3]: Solve using OR-Tools v9.11.4210 ... OPTIMAL, wall time: 18.2195 s
[4]: Solve using OR-Tools v9.11.4210 ... OPTIMAL, wall time: 52.2018 s
fixedpoint_radix4_fft_m55_attempt2_v9.11.txt
[0]: Solve using OR-Tools v9.11.4210 ... OPTIMAL, wall time: 40.2191 s
[1]: Solve using OR-Tools v9.11.4210 ... OPTIMAL, wall time: 8.4385 s
[2]: Solve using OR-Tools v9.11.4210 ... OPTIMAL, wall time: 49.7734 s
[3]: Solve using OR-Tools v9.11.4210 ... OPTIMAL, wall time: 50.2480 s
[4]: Solve using OR-Tools v9.11.4210 ... OPTIMAL, wall time: 49.7217 s

Solving both with v9.7:

$ python3 run_model.py 
fixedpoint_radix4_fft_m55_attempt2_v9.7.txt
[0]: Solve using OR-Tools v9.7.2996 ... OPTIMAL, wall time: 2.8773 s
[1]: Solve using OR-Tools v9.7.2996 ... OPTIMAL, wall time: 2.8893 s
[2]: Solve using OR-Tools v9.7.2996 ... OPTIMAL, wall time: 2.9790 s
[3]: Solve using OR-Tools v9.7.2996 ... OPTIMAL, wall time: 2.9513 s
[4]: Solve using OR-Tools v9.7.2996 ... OPTIMAL, wall time: 2.9005 s
fixedpoint_radix4_fft_m55_attempt2_v9.11.txt
[0]: Solve using OR-Tools v9.7.2996 ... UNKNOWN, wall time: 60.0029 s
[1]: Solve using OR-Tools v9.7.2996 ... UNKNOWN, wall time: 60.0022 s
[2]: Solve using OR-Tools v9.7.2996 ... UNKNOWN, wall time: 60.0020 s
[3]: Solve using OR-Tools v9.7.2996 ... UNKNOWN, wall time: 60.0023 s
[4]: Solve using OR-Tools v9.7.2996 ... UNKNOWN, wall time: 60.0024 s

I think this rules out model generation, but once again confirms that v9.11 is much slower in solving these models than v9.7 was.

@mkannwischer
Copy link

mkannwischer commented Nov 28, 2024

I've also extracted the models of the ntt_dilithium_123_45678_a55 example that we looked at before again:
ntt_dilithium_123_45678_a55_v9.11.txt
ntt_dilithium_123_45678_a55_v9.7.txt

Running the v9.7 model with v9.7 this completes within around 10 seconds reliably:

ntt_dilithium_123_45678_a55_v9.7.txt
[0]: Solve using OR-Tools v9.7.2996 ... OPTIMAL, wall time: 9.2531 s
[1]: Solve using OR-Tools v9.7.2996 ... OPTIMAL, wall time: 9.2211 s
[2]: Solve using OR-Tools v9.7.2996 ... OPTIMAL, wall time: 9.5007 s
[3]: Solve using OR-Tools v9.7.2996 ... OPTIMAL, wall time: 12.4243 s
[4]: Solve using OR-Tools v9.7.2996 ... OPTIMAL, wall time: 10.9639 s

Running either of the models with v9.11 does not find any solution within 600 seconds with either of the two models. I'll let this run for a bit longer - but it's definitely much slower.

@lperron
Copy link
Collaborator

lperron commented Nov 28, 2024 via email

@mkannwischer
Copy link

Update on v9.11: Even after 1200 seconds I do not get any solutions for ntt_dilithium_123_45678_a55_v9.11.txt.

I've just tried with the v99bugfix branch (commit 78d5ba5), but I'm not seeing any difference:

$ python3 run_model.py 
ntt_dilithium_123_45678_a55_v9.11.txt
[0]: Solve using OR-Tools v9.12.4349 ... UNKNOWN, wall time: 59.9998 s
[1]: Solve using OR-Tools v9.12.4349 ... UNKNOWN, wall time: 60.0002 s
[2]: Solve using OR-Tools v9.12.4349 ... UNKNOWN, wall time: 60.0002 s
[3]: Solve using OR-Tools v9.12.4349 ... UNKNOWN, wall time: 60.0006 s
[4]: Solve using OR-Tools v9.12.4349 ... UNKNOWN, wall time: 60.0002 s

@lperron
Copy link
Collaborator

lperron commented Nov 28, 2024 via email

@hanno-becker
Copy link
Author

@lperron Sorry, can you elaborate? It is expected that there are no complete hints in the model.

@lperron
Copy link
Collaborator

lperron commented Nov 28, 2024 via email

@hanno-becker
Copy link
Author

hanno-becker commented Nov 28, 2024

Is that all we can say here? This regression persisted from 9.8 onwards and blocks our application from migrating since. We would greatly appreciate if you could help us understand the options we can explore here, since you surely know best what changed between 9.7 and 9.8 that could cause this drastic slowdown. This may also be related to the regression reported in #4189.

@lperron
Copy link
Collaborator

lperron commented Nov 28, 2024 via email

@hanno-becker
Copy link
Author

@lperron Maybe the following helps advance the discussion: We ran the problematic model again, 3x with 9.7 and 3x with 9.11, setting num_workers=16 and this time also gathering logs.

Wall times for 9.7 were 12s, 17s, 26s
Wall times for 9.11 were 152s, 201s, 330s

The logs indicate a large difference in the set of employed and successful solvers. Perhaps some solvers in 9.11 need to be disabled / deprioritized for the models we care about? If you had time to take a look, we'd be grateful.

log-97-1.txt
log-97-2.txt
log-97-3.txt
log-911-1.txt
log-911-2.txt
low-911-3.txt

@mkannwischer
Copy link

@lperron Thank you very much for your help so far with debugging this!
Unfortunately, we are still unable to upgrade from v9.7 and we are out of ideas of what to try.

Do you have any other suggestions of what we could try to track down the cause of the 10x slowdown for some of our models (e.g., the ones in Hanno's last comment) ? Happy to try the models with another commit of or-tools in case you think this could be resolved by now in some branch.

Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment
Labels
Solver: CP-SAT Solver Relates to the CP-SAT solver
Projects
None yet
Development

No branches or pull requests

4 participants