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 in main after an optimal solution already found #4268

Closed
magneticflux- opened this issue Jun 11, 2024 · 8 comments
Closed
Assignees
Labels
Bug Lang: Java Java wrapper issue Solver: CP-SAT Solver Relates to the CP-SAT solver
Milestone

Comments

@magneticflux-
Copy link

What version of OR-Tools and what language are you using?
Version: main
Language: Java

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

CP-SAT

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

I noticed a recent performance regression and bisected it to this commit: 766ada1
It only occurs between the end of solve and the final result being printed. Example:

#15     11.24s best:812821 next:[812818,812820] rins_lp_lns (d=0.03 s=192 t=0.10 p=0.18 stall=1 h=auto_l0)
#16     12.37s best:812818 next:[]         rnd_cst_lns (d=0.74 s=195 t=0.10 p=0.60 stall=0 h=auto_l0)
#Model  12.69s var:18892/19174 constraints:18429/18788 compo:18888,1,1,1,1

// Why the 4 second delay for reduced_costs to finish when we already have an optimal solution?

#Done   16.42s reduced_costs

// Another mysterious 5.68s gap before the stats get printed

Task timing (...)

I checked out the commit and added additional logging before and after the calls to subsolvers[i].reset(); and LogFinalStatistics(shared); which indicates they complete quickly and are not the cause. Setting log_search_progress = false and log_subsolver_statistics = false doesn't appear to do anything either.

These gaps end up doubling the solve time after the optimal solution has been printed, which leads me to believe this isn't a minor change in the search algorithm randomization 😅.

A full log showing a 7.5s solve turn into a 19.1s solve
Starting CP-SAT solver v10.0.9999
Parameters: log_search_progress: true linearization_level: 2 max_num_cuts: 100000 stop_after_first_solution: false min_orthogonality_for_lp_constraints: 0 pseudo_cost_reliability_threshold: 5 diversify_lns_params: true max_presolve_iterations: 1 use_feasibility_pump: false symmetry_level: 2 log_subsolver_statistics: true num_workers: 20 subsolvers: "max_lp" subsolvers: "reduced_costs" probing_deterministic_time_limit: 0 use_feasibility_jump: false

Initial optimization model '': (model_fingerprint: 0x1ca7298b705274a5)
Search strategy: on 2946 variables, CHOOSE_MAX_DOMAIN_SIZE, SELECT_MIN_VALUE
Search strategy: on 5280 variables, CHOOSE_MAX_DOMAIN_SIZE, SELECT_MIN_VALUE
#Variables: 112'330 (#bools: 7'737 #ints: 1'750 in objective)
  - 90'949 Booleans in [0,1]
  - 9 in [0,17]
  - 4'828 in [0,20]
  - 5'409 in [0,75]
  - 11'088 in [0,100]
  - 45 in [0,150]
  - 1 in [1,8]
  - 1 constants in {0} 
#kAtMostOne: 19'710 (#literals: 42'805)
#kBoolAnd: 13'963 (#enforced: 13'962) (#literals: 54'952)
#kBoolOr: 38'806 (#enforced: 8'514) (#literals: 90'798)
#kLinMax: 3'213 (#expressions: 16'563)
#kLinear0: 8'070 (#enforced: 1'361)
#kLinear1: 57'789 (#enforced: 44'982)
#kLinear2: 61'354 (#enforced: 17'405)
#kLinear3: 23'580 (#enforced: 129)
#kLinearN: 7'116 (#enforced: 792) (#terms: 235'772)

Starting presolve at 0.04s
  3.72e-02s  0.00e+00d  [DetectDominanceRelations] 
  5.88e-01s  0.00e+00d  [PresolveToFixPoint] #num_loops=24 #num_dual_strengthening=9 
  4.18e-03s  0.00e+00d  [ExtractEncodingFromLinear] #potential_supersets=18'346 #potential_subsets=969 #amo_encodings=363 #literals=1'143 
[Symmetry] Graph for symmetry has 204'030 nodes and 327'297 arcs.
[Symmetry] Symmetry computation done. time: 0.0696269 dtime: 0.0772636
[Symmetry] #generators: 491, average support size: 19.9185
[Symmetry] The model contains 6274 duplicate constraints !
[Symmetry] 2018 orbits with sizes: 42,42,42,42,42,42,42,42,24,24,...
[Symmetry] Found orbitope of size 16 x 14
[SAT presolve] num removable Booleans: 546 / 23743
[SAT presolve] num trivial clauses: 0
[SAT presolve] [0s] clauses:20606 literals:50748 vars:18294 one_side_vars:11262 simple_definition:4508 singleton_clauses:0
[SAT presolve] [0.00501523s] clauses:20589 literals:50571 vars:18294 one_side_vars:11264 simple_definition:4532 singleton_clauses:0
[SAT presolve] [0.00694499s] clauses:20125 literals:49867 vars:17825 one_side_vars:11264 simple_definition:4065 singleton_clauses:0
  9.62e-02s  6.60e-03d  [Probe] #probed=2 #new_bounds=172 #equiv=94 
  1.34e-01s  0.00e+00d  [MaxClique] Merged 37196(87802 literals) into 15553(40458 literals) at_most_ones. 
  3.29e-02s  0.00e+00d  [DetectDominanceRelations] 
  1.32e-01s  0.00e+00d  [PresolveToFixPoint] #num_loops=5 #num_dual_strengthening=4 
  3.71e-02s  0.00e+00d  [ProcessAtMostOneAndLinear] #num_changes=916 
  1.92e-02s  0.00e+00d  [DetectDuplicateConstraints] #duplicates=2'690 #without_enforcements=303 
  2.95e-02s  1.96e-03d  [DetectDominatedLinearConstraints] #relevant_constraints=2'877 #num_inclusions=27'119 #num_redundant=206 
  2.27e-03s  0.00e+00d  [DetectDifferentVariables] 
  1.34e-02s  4.47e-03d  [ProcessSetPPC] #relevant_constraints=20'003 #num_inclusions=5'716 
  3.58e-03s  1.63e-04d  [FindAlmostIdenticalLinearConstraints] #num_tested_pairs=1'846 #found=270 
  1.91e-01s  6.77e-01d  [FindBigAtMostOneAndLinearOverlap] 
  5.09e-02s  2.81e-01d  [FindBigVerticalLinearOverlap] #blocks=99 #saved_nz=23'449 
  2.67e-02s  5.62e-02d  [FindBigHorizontalLinearOverlap] #blocks=27 #saved_nz=23'408 #linears=1'291 
  4.88e-03s  7.82e-05d  [MergeClauses] #num_collisions=299 #num_merges=299 #num_saved_literals=933 
  2.83e-02s  0.00e+00d  [DetectDominanceRelations] 
  1.76e-01s  0.00e+00d  [PresolveToFixPoint] #num_loops=14 #num_dual_strengthening=9 
  6.58e-03s  0.00e+00d  [ExpandObjective] #entries=45'429 #tight_variables=3'222 #tight_constraints=1'468 

Presolve summary:
  - 23027 affine relations were detected.
  - rule 'TODO dual: make linear1 equiv' was applied 422 times.
  - rule 'TODO dual: only one blocking constraint?' was applied 30'606 times.
  - rule 'TODO dual: only one blocking enforced constraint?' was applied 9'361 times.
  - rule 'TODO dual: only one unspecified blocking constraint?' was applied 13 times.
  - rule 'TODO dual: tighten at most one' was applied 60 times.
  - rule 'TODO duplicate: identical constraint with different enforcements' was applied 303 times.
  - rule 'TODO linear inclusion: superset is equality' was applied 361 times.
  - rule 'TODO linear2: contains a Boolean.' was applied 15'146 times.
  - rule 'TODO symmetry: add symmetry breaking inequalities?' was applied 1 time.
  - rule 'affine: fixed' was applied 160 times.
  - rule 'affine: new relation' was applied 23'027 times.
  - rule 'at_most_one: empty or all false' was applied 6'312 times.
  - rule 'at_most_one: removed literals' was applied 7'110 times.
  - rule 'at_most_one: satisfied' was applied 3'075 times.
  - rule 'at_most_one: size one' was applied 63 times.
  - rule 'at_most_one: transformed into max clique.' was applied 1 time.
  - rule 'bool and: empty' was applied 207 times.
  - rule 'bool_and: always false' was applied 7'146 times.
  - rule 'bool_and: fixed literals' was applied 322 times.
  - rule 'bool_and: non-reified.' was applied 8'767 times.
  - rule 'bool_and: x => x' was applied 6'701 times.
  - rule 'bool_or: always true' was applied 1'269 times.
  - rule 'bool_or: fixed literals' was applied 612 times.
  - rule 'bool_or: implications' was applied 36'275 times.
  - rule 'bool_or: only one literal' was applied 16'473 times.
  - rule 'bool_or: removed enforcement literal' was applied 2'764 times.
  - rule 'bool_or: singleton' was applied 4'491 times.
  - rule 'deductions: 37497 stored' was applied 1 time.
  - rule 'dual: add implication' was applied 2'792 times.
  - rule 'dual: enforced equivalence' was applied 6'811 times.
  - rule 'dual: equivalent Boolean in near-duplicate constraints' was applied 74 times.
  - rule 'dual: fix variable' was applied 995 times.
  - rule 'dual: make encoding equiv' was applied 5'403 times.
  - rule 'dual: reduced domain' was applied 4 times.
  - rule 'duplicate: merged rhs of linear constraint' was applied 590 times.
  - rule 'duplicate: removed constraint' was applied 2'690 times.
  - rule 'encoding: candidate linear is all Boolean now.' was applied 363 times.
  - rule 'encoding: extracted from linear' was applied 363 times.
  - rule 'encoding: reduced target domain' was applied 363 times.
  - rule 'enforcement: always false' was applied 1'353 times.
  - rule 'enforcement: false literal' was applied 30'384 times.
  - rule 'enforcement: literal not used' was applied 4'352 times.
  - rule 'enforcement: removed duplicate literal' was applied 7 times.
  - rule 'enforcement: true literal' was applied 11'992 times.
  - rule 'exactly_one: removed literals' was applied 3 times.
  - rule 'exactly_one: singleton' was applied 3 times.
  - rule 'incompatible linear: add implication' was applied 15 times.
  - rule 'lin_max: affine_max target domain reduced' was applied 1 time.
  - rule 'lin_max: converted to equality' was applied 1 time.
  - rule 'lin_max: divising by gcd' was applied 1'360 times.
  - rule 'lin_max: removed exprs' was applied 1'471 times.
  - rule 'lin_max: x = max(x, ...)' was applied 522 times.
  - rule 'linear + amo: empty after processing' was applied 11 times.
  - rule 'linear + amo: extracted enforcement literal' was applied 2'043 times.
  - rule 'linear + amo: trivial linear constraint' was applied 14 times.
  - rule 'linear inclusion: redundant containing constraint' was applied 2 times.
  - rule 'linear inclusion: redundant included constraint' was applied 197 times.
  - rule 'linear inclusion: subset + singleton is equality' was applied 7 times.
  - rule 'linear matrix: common horizontal rectangle' was applied 27 times.
  - rule 'linear matrix: common vertical rectangle' was applied 99 times.
  - rule 'linear matrix: defining equation for common rectangle' was applied 1 time.
  - rule 'linear1: always true' was applied 4'859 times.
  - rule 'linear1: transformed to implication' was applied 2'678 times.
  - rule 'linear2: contains a Boolean.' was applied 1 time.
  - rule 'linear2: implied ax + by = cte has only one solution' was applied 21 times.
  - rule 'linear: advanced affine relation from 2 constraints.' was applied 270 times.
  - rule 'linear: always true' was applied 40'702 times.
  - rule 'linear: divide by GCD' was applied 19'224 times.
  - rule 'linear: doubleton free' was applied 50 times.
  - rule 'linear: empty' was applied 30'091 times.
  - rule 'linear: enforcement literal in expression' was applied 28'455 times.
  - rule 'linear: extracted at most one (max).' was applied 354 times.
  - rule 'linear: extracted at most one (min).' was applied 9 times.
  - rule 'linear: fixed or dup variables' was applied 124'831 times.
  - rule 'linear: infeasible' was applied 7'924 times.
  - rule 'linear: negative at most one' was applied 11'386 times.
  - rule 'linear: negative clause' was applied 159 times.
  - rule 'linear: negative equal one' was applied 11 times.
  - rule 'linear: positive at most one' was applied 162 times.
  - rule 'linear: positive clause' was applied 6'469 times.
  - rule 'linear: positive equal one' was applied 352 times.
  - rule 'linear: positive reified and' was applied 16 times.
  - rule 'linear: reduced variable domains' was applied 41'853 times.
  - rule 'linear: reduced variable domains in derived constraint' was applied 879 times.
  - rule 'linear: remapped using affine relations' was applied 20'560 times.
  - rule 'linear: remove irrelevant part' was applied 4 times.
  - rule 'linear: simplified rhs' was applied 44'673 times.
  - rule 'linear: singleton column' was applied 20 times.
  - rule 'linear: small Boolean expression' was applied 16 times.
  - rule 'linear: variable substitution 0' was applied 126 times.
  - rule 'linear: variable substitution 1' was applied 1'582 times.
  - rule 'linear: variable substitution 2' was applied 3'936 times.
  - rule 'linear: variable substitution 3' was applied 661 times.
  - rule 'objective: shifted cost with exactly ones' was applied 135 times.
  - rule 'objective: variable not used elsewhere' was applied 3'253 times.
  - rule 'presolve: 66922 unused variables removed.' was applied 1 time.
  - rule 'presolve: iteration' was applied 1 time.
  - rule 'setppc: bool_or in at_most_one.' was applied 172 times.
  - rule 'setppc: removed dominated constraints' was applied 277 times.
  - rule 'variables: canonicalize affine domain' was applied 8 times.
  - rule 'variables: canonicalize domain' was applied 1 time.
  - rule 'variables: detect fully reified value encoding' was applied 3'489 times.
  - rule 'variables: detect half reified value encoding' was applied 20'935 times.
  - rule 'variables: removable enforcement literal' was applied 31 times.

Presolved optimization model '': (model_fingerprint: 0xbd59603823ae8793)
Search strategy: on 2405 variables, CHOOSE_MAX_DOMAIN_SIZE, SELECT_MIN_VALUE
#Variables: 19'174 (#bools: 5'354 #ints: 78 in objective)
  - 17'844 Booleans in [0,1]
  - 1 in [0,1][3,4][6,7][9,10][12,13][15,16]
  - 179 in [0,2]
  - 199 in [0,3]
  - 154 in [0,4]
  - 140 in [0,5]
  - 219 in [0,6]
  - 18 in [0,7]
  - 75 in [0,8]
  - 25 in [0,9]
  - 22 in [0,10]
  - 14 in [0,11]
  - 18 in [0,12]
  - 7 in [0,13]
  - 8 in [0,14]
  - 9 in [0,15]
  - 17 in [0,16]
  - 19 in [0,17]
  - 3 in [0,18]
  - 9 in [0,19]
  - 6 in [0,20]
  - 5 in [0,21]
  - 2 in [0,22]
  - 2 in [0,23]
  - 8 in [0,24]
  - 1 in [0,25]
  - 3 in [0,26]
  - 9 in [0,27]
  - 5 in [0,28]
  - 2 in [0,29]
  - 4 in [0,30]
  - 3 in [0,31]
  - 4 in [0,32]
  - 4 in [0,33]
  - 5 in [0,34]
  - 2 in [0,35]
  - 3 in [0,36]
  - 1 in [0,37]
  - 2 in [0,38]
  - 4 in [0,39]
  - 3 in [0,40]
  - 3 in [0,41]
  - 3 in [0,42]
  - 2 in [0,43]
  - 2 in [0,44]
  - 2 in [0,45]
  - 4 in [0,46]
  - 4 in [0,47]
  - 3 in [0,48]
  - 3 in [0,50]
  - 6 in [0,51]
  - 2 in [0,52]
  - 2 in [0,55]
  - 2 in [0,56]
  - 2 in [0,57]
  - 1 in [0,59]
  - 1 in [0,61]
  - 1 in [0,62]
  - 3 in [0,64]
  - 1 in [0,66]
  - 2 in [0,68]
  - 2 in [0,70]
  - 3 in [0,73]
  - 27 in [0,75]
  - 1 in [0,76]
  - 2 in [0,85]
  - 1 in [0,89]
  - 1 in [0,93]
  - 2 in [0,102]
  - 1 in [0,108]
  - 1 in [0,119]
  - 1 in [0,121]
  - 1 in [0,127]
  - 1 in [0,136]
  - 1 in [0,138]
  - 1 in [0,150]
  - 1 in [1,64]
  - 1 in [3,50]
  - 1 in [4,150]
  - 1 in [6,146]
  - 1 in [6,150]
  - 11 in [9,17]
  - 1 in [43,51]
  - 1 in [77,85]
  - 1 in [94,102]
  - 1 in [111,119]
  - 1 in [128,136]
#kAtMostOne: 5'981 (#literals: 20'535)
#kBoolAnd: 4'686 (#enforced: 4'686 #multi: 162) (#literals: 16'320)
#kBoolOr: 1'817 (#literals: 13'529)
#kExactlyOne: 360 (#literals: 1'496)
#kLinMax: 1'350 (#expressions: 5'446)
#kLinear1: 2'242 (#enforced: 2'242 #multi: 698)
#kLinear2: 366 (#enforced: 336 #multi: 58)
#kLinear3: 420 (#enforced: 65 #multi: 3)
#kLinearN: 1'566 (#enforced: 42 #multi: 1) (#terms: 49'039)

Preloading model.
#Bound   2.02s best:inf   next:[800000,2383280] initial_domain
[Symmetry] Graph for symmetry has 72'909 nodes and 163'545 arcs.
[Symmetry] Symmetry computation done. time: 0.022535 dtime: 0.0346599
[Symmetry] #generators: 460, average support size: 19.8826
[Symmetry] The model contains 3 duplicate constraints !
[Symmetry] Found orbitope of size 16 x 14
#Model   2.06s var:19174/19174 constraints:18788/18788

Starting search at 2.06s with 20 workers.
2 full problem subsolvers: [max_lp, reduced_costs]
16 first solution subsolvers: [fs_random(4), fs_random_no_lp(4), fs_random_quick_restart(4), fs_random_quick_restart_no_lp(4)]
10 incomplete subsolvers: [graph_arc_lns, graph_cst_lns, graph_dec_lns, graph_var_lns, rins/rens, rnd_cst_lns, rnd_var_lns, violation_ls(3)]
3 helper subsolvers: [neighborhood_helper, synchronization_agent, update_gap_integral]

#Bound   5.24s best:inf   next:[800300,2378180] fs_random_quick_restart_no_lp (initial_propagation)
#Model   5.29s var:18933/19174 constraints:18578/18788 compo:18929,1,1,1,1
#Bound   5.31s best:inf   next:[801903,2378180] fs_random
#1       5.46s best:812824 next:[801903,812823] fs_random_quick_restart_no_lp (fixed_bools=255/18393)
#Model   5.56s var:18923/19174 constraints:18525/18788 compo:18919,1,1,1,1
#2       6.02s best:812823 next:[801903,812822] graph_arc_lns (d=0.50 s=37 t=0.10 p=0.00 stall=0 h=auto_l0)
#3       6.13s best:812821 next:[801903,812820] graph_var_lns (d=0.50 s=36 t=0.10 p=0.00 stall=0 h=auto_l0)
#Bound   6.97s best:812821 next:[812818,812820] max_lp
#4       7.12s best:812818 next:[]         rnd_var_lns (d=0.81 s=50 t=0.10 p=1.00 stall=2 h=auto_l0)
#Done    7.51s reduced_costs

Task timing                                n [     min,      max]      avg      dev     time         n [     min,      max]      avg      dev    dtime
                      'fs_random':         1 [   3.45s,    3.45s]    3.45s   0.00ns    3.45s         1 [  3.24ms,   3.24ms]   3.24ms   0.00ns   3.24ms
                      'fs_random':         1 [   3.60s,    3.60s]    3.60s   0.00ns    3.60s         1 [ 20.00ns,  20.00ns]  20.00ns   0.00ns  20.00ns
                      'fs_random':         1 [   3.60s,    3.60s]    3.60s   0.00ns    3.60s         1 [ 20.00ns,  20.00ns]  20.00ns   0.00ns  20.00ns
                      'fs_random':         1 [   3.60s,    3.60s]    3.60s   0.00ns    3.60s         1 [ 20.00ns,  20.00ns]  20.00ns   0.00ns  20.00ns
                'fs_random_no_lp':         1 [   3.45s,    3.45s]    3.45s   0.00ns    3.45s         0 [  0.00ns,   0.00ns]   0.00ns   0.00ns   0.00ns
                'fs_random_no_lp':         1 [   3.46s,    3.46s]    3.46s   0.00ns    3.46s         0 [  0.00ns,   0.00ns]   0.00ns   0.00ns   0.00ns
                'fs_random_no_lp':         1 [   3.46s,    3.46s]    3.46s   0.00ns    3.46s         0 [  0.00ns,   0.00ns]   0.00ns   0.00ns   0.00ns
                'fs_random_no_lp':         1 [   3.46s,    3.46s]    3.46s   0.00ns    3.46s         0 [  0.00ns,   0.00ns]   0.00ns   0.00ns   0.00ns
        'fs_random_quick_restart':         1 [   3.60s,    3.60s]    3.60s   0.00ns    3.60s         1 [ 20.00ns,  20.00ns]  20.00ns   0.00ns  20.00ns
        'fs_random_quick_restart':         1 [   3.65s,    3.65s]    3.65s   0.00ns    3.65s         1 [ 20.00ns,  20.00ns]  20.00ns   0.00ns  20.00ns
        'fs_random_quick_restart':         1 [   3.65s,    3.65s]    3.65s   0.00ns    3.65s         1 [ 20.00ns,  20.00ns]  20.00ns   0.00ns  20.00ns
        'fs_random_quick_restart':         1 [   3.65s,    3.65s]    3.65s   0.00ns    3.65s         1 [ 20.00ns,  20.00ns]  20.00ns   0.00ns  20.00ns
  'fs_random_quick_restart_no_lp':         1 [   3.43s,    3.43s]    3.43s   0.00ns    3.43s         1 [  5.78ms,   5.78ms]   5.78ms   0.00ns   5.78ms
  'fs_random_quick_restart_no_lp':         1 [   3.47s,    3.47s]    3.47s   0.00ns    3.47s         0 [  0.00ns,   0.00ns]   0.00ns   0.00ns   0.00ns
  'fs_random_quick_restart_no_lp':         1 [   3.47s,    3.47s]    3.47s   0.00ns    3.47s         0 [  0.00ns,   0.00ns]   0.00ns   0.00ns   0.00ns
  'fs_random_quick_restart_no_lp':         1 [   3.48s,    3.48s]    3.48s   0.00ns    3.48s         0 [  0.00ns,   0.00ns]   0.00ns   0.00ns   0.00ns
                  'graph_arc_lns':         6 [280.53ms,    3.32s]    1.01s    1.10s    6.03s         5 [ 47.12us, 100.35ms]  40.43ms  48.79ms 202.13ms
                  'graph_cst_lns':         6 [155.14ms,    1.00s] 534.57ms 344.52ms    3.21s         6 [928.00ns, 100.73ms]  51.61ms  48.95ms 309.63ms
                  'graph_dec_lns':         6 [220.82ms,    1.29s] 627.40ms 455.12ms    3.76s         5 [127.00ns, 100.47ms]  40.11ms  49.13ms 200.57ms
                  'graph_var_lns':         7 [249.98ms,    1.33s] 616.25ms 439.84ms    4.31s         5 [428.42us, 100.31ms]  46.04ms  45.12ms 230.19ms
                         'max_lp':         1 [  17.13s,   17.13s]   17.13s   0.00ns   17.13s         0 [  0.00ns,   0.00ns]   0.00ns   0.00ns   0.00ns
                  'reduced_costs':         1 [   5.45s,    5.45s]    5.45s   0.00ns    5.45s         1 [ 25.87ms,  25.87ms]  25.87ms   0.00ns  25.87ms
                      'rins/rens':         0 [  0.00ns,   0.00ns]   0.00ns   0.00ns   0.00ns         0 [  0.00ns,   0.00ns]   0.00ns   0.00ns   0.00ns
                    'rnd_cst_lns':         7 [165.61ms,    1.23s] 658.52ms 467.89ms    4.61s         5 [  2.72us, 100.80ms]  60.26ms  49.16ms 301.29ms
                    'rnd_var_lns':         7 [ 93.36ms,    1.17s] 601.09ms 408.24ms    4.21s         6 [215.00ns, 100.94ms]  51.12ms  49.32ms 306.69ms
                   'violation_ls':         6 [175.14ms, 389.13ms] 281.41ms  67.71ms    1.69s         6 [ 23.82ms,  95.47ms]  55.70ms  29.48ms 334.20ms
                   'violation_ls':         6 [260.30ms, 376.70ms] 313.20ms  36.55ms    1.88s         6 [ 71.26ms, 104.17ms]  88.86ms  12.84ms 533.17ms
                   'violation_ls':         7 [123.63ms, 286.50ms] 212.27ms  55.23ms    1.49s         7 [ 12.16ms,  31.46ms]  24.76ms   6.30ms 173.35ms

Search stats                         Bools  Conflicts  Branches  Restarts  BoolPropag  IntegerPropag
                      'fs_random':  18'392         54    28'831    28'831     888'945      2'860'785
                      'fs_random':  18'392         54    29'559    29'559     902'270      2'939'826
                      'fs_random':  18'392         54    29'751    29'751     907'419      2'961'144
                      'fs_random':  18'392         69    36'393    36'393   1'146'468      3'729'360
                'fs_random_no_lp':  18'392         54    30'465    30'465     928'953      2'861'343
                'fs_random_no_lp':  18'392         54    31'185    31'185     944'632      2'937'523
                'fs_random_no_lp':  18'392         54    31'253    31'253     945'093      2'943'416
                'fs_random_no_lp':  18'392         54    32'045    32'045     964'587      3'019'538
        'fs_random_quick_restart':  18'392         54    29'157    29'157     895'053      2'900'282
        'fs_random_quick_restart':  18'392         54    29'815    29'815     909'277      2'969'224
        'fs_random_quick_restart':  18'392         54    29'819    29'819     909'380      2'969'702
        'fs_random_quick_restart':  18'392         54    34'359    34'359   1'010'552      3'474'168
  'fs_random_quick_restart_no_lp':  18'392         54    30'691    30'691     935'171      2'886'836
  'fs_random_quick_restart_no_lp':  18'392         54    31'417    31'417     946'192      2'957'362
  'fs_random_quick_restart_no_lp':  18'392         54    31'533    31'533     948'384      2'967'299
  'fs_random_quick_restart_no_lp':  18'393         78    40'985    36'394   1'160'464      3'540'809
                         'max_lp':  18'392         69    36'393    36'393   1'146'469      3'729'414
                  'reduced_costs':  18'392         69    36'393    36'393   1'146'470      3'729'372

SAT stats                           ClassicMinim  LitRemoved  LitLearned  LitForgotten  Subsumed  MClauses  MDecisions  MLitTrue  MSubsumed  MLitRemoved  MReused
                      'fs_random':             0           0          54             0         0         0           0         0          0            0        0
                      'fs_random':             0           0          54             0         0         0           0         0          0            0        0
                      'fs_random':             0           0          54             0         0         0           0         0          0            0        0
                      'fs_random':             0           0          69             0         0         0           0         0          0            0        0
                'fs_random_no_lp':             0           0          54             0         0         0           0         0          0            0        0
                'fs_random_no_lp':             0           0          54             0         0         0           0         0          0            0        0
                'fs_random_no_lp':             0           0          54             0         0         0           0         0          0            0        0
                'fs_random_no_lp':             0           0          54             0         0         0           0         0          0            0        0
        'fs_random_quick_restart':             0           0          54             0         0         0           0         0          0            0        0
        'fs_random_quick_restart':             0           0          54             0         0         0           0         0          0            0        0
        'fs_random_quick_restart':             0           0          54             0         0         0           0         0          0            0        0
        'fs_random_quick_restart':             0           0          54             0         0         0           0         0          0            0        0
  'fs_random_quick_restart_no_lp':             0           0          54             0         0         0           0         0          0            0        0
  'fs_random_quick_restart_no_lp':             0           0          54             0         0         0           0         0          0            0        0
  'fs_random_quick_restart_no_lp':             0           0          54             0         0         0           0         0          0            0        0
  'fs_random_quick_restart_no_lp':             9      11'780      29'373             0         0         0           0         0          0            0        0
                         'max_lp':             0           0          69             0         0         0           0         0          0            0        0
                  'reduced_costs':             0           0          69             0         0         0           0         0          0            0        0

Lp stats                      Component  Iterations  AddedCuts  OPTIMAL  DUAL_F.  DUAL_U.
                'fs_random':          1           0          0        0        0        0
                'fs_random':          1           0          0        0        0        0
                'fs_random':          1           0          0        0        0        0
                'fs_random':          1         303        317        7        0        0
  'fs_random_quick_restart':          1           0          0        0        0        0
  'fs_random_quick_restart':          1           0          0        0        0        0
  'fs_random_quick_restart':          1           0          0        0        0        0
  'fs_random_quick_restart':          1           0          0        0        0        0
                   'max_lp':          1       8'314      4'439        8        2        0
            'reduced_costs':          1         790      1'365       18        0        0

Lp dimension                                                                        Final dimension of first component
                'fs_random':           0 rows, 19174 columns, 0 entries with magnitude in [0.000000e+00, 0.000000e+00]
                'fs_random':           0 rows, 19174 columns, 0 entries with magnitude in [0.000000e+00, 0.000000e+00]
                'fs_random':           0 rows, 19174 columns, 0 entries with magnitude in [0.000000e+00, 0.000000e+00]
                'fs_random':     205 rows, 19174 columns, 20481 entries with magnitude in [2.886751e-01, 1.000000e+00]
  'fs_random_quick_restart':           0 rows, 19174 columns, 0 entries with magnitude in [0.000000e+00, 0.000000e+00]
  'fs_random_quick_restart':           0 rows, 19174 columns, 0 entries with magnitude in [0.000000e+00, 0.000000e+00]
  'fs_random_quick_restart':           0 rows, 19174 columns, 0 entries with magnitude in [0.000000e+00, 0.000000e+00]
  'fs_random_quick_restart':           0 rows, 19174 columns, 0 entries with magnitude in [0.000000e+00, 0.000000e+00]
                   'max_lp':  17758 rows, 19174 columns, 116784 entries with magnitude in [2.193457e-02, 1.000000e+00]
            'reduced_costs':     505 rows, 19174 columns, 22655 entries with magnitude in [2.041241e-01, 1.000000e+00]

Lp debug                      CutPropag  CutEqPropag  Adjust  Overflow     Bad  BadScaling
                'fs_random':          0            0       0         0       0           0
                'fs_random':          0            0       0         0       0           0
                'fs_random':          0            0       0         0       0           0
                'fs_random':          7            0       6         0      22           0
  'fs_random_quick_restart':          0            0       0         0       0           0
  'fs_random_quick_restart':          0            0       0         0       0           0
  'fs_random_quick_restart':          0            0       0         0       0           0
  'fs_random_quick_restart':          0            0       0         0       0           0
                   'max_lp':         57            0      10         0  19'009           0
            'reduced_costs':         12            0      17         0     887           0

Lp pool                       Constraints  Updates  Simplif  Merged  Shortened  Split  Strenghtened     Cuts/Call
                'fs_random':       17'824        9      441       1      6'211      0           305       317/471
                'fs_random':       22'809        0        0       0        462      0             0           0/0
                'fs_random':       22'809        0        0       0        462      0             0           0/0
                'fs_random':       22'809        0        0       0        462      0             0           0/0
  'fs_random_quick_restart':       22'809        0        0       0        462      0             0           0/0
  'fs_random_quick_restart':       22'809        0        0       0        462      0             0           0/0
  'fs_random_quick_restart':       22'809        0        0       0        462      0             0           0/0
  'fs_random_quick_restart':       22'809        0        0       0        462      0             0           0/0
                   'max_lp':       21'946      176      802       1      6'318     18         2'920  4'439/15'007
            'reduced_costs':       18'870       16    1'172       3      6'211      2           958   1'365/2'477

Lp Cut            fs_random  max_lp  reduced_costs
          CG_FF:         24     232             92
           CG_K:         17     129             50
          CG_KL:          -      48              1
           CG_R:         21     315            134
          CG_RB:          -     289            157
         CG_RBP:          -     171             44
         Clique:          1      46              9
             IB:        127     214            307
       MIR_1_FF:         44     400            110
        MIR_1_K:         22     367             56
       MIR_1_KL:          5      44              8
        MIR_1_R:         41      57            106
       MIR_1_RB:          4      48             36
      MIR_1_RBP:          -       8              5
      MIR_1_RLT:          5       4             23
       MIR_2_FF:          1     231             32
        MIR_2_K:          1     109             14
       MIR_2_KL:          -      15              2
        MIR_2_R:          2     164             24
       MIR_2_RB:          -      52             11
      MIR_2_RBP:          -      17              5
       MIR_3_FF:          1     116             15
        MIR_3_K:          -      45              7
       MIR_3_KL:          -       9              2
        MIR_3_R:          1     186             15
       MIR_3_RB:          -      42              4
      MIR_3_RBP:          -      16              3
       MIR_4_FF:          -      47             17
        MIR_4_K:          -      22              9
       MIR_4_KL:          -       9              3
        MIR_4_R:          -     133             16
       MIR_4_RB:          -      28              5
      MIR_4_RBP:          -       8              2
       MIR_5_FF:          -      23              6
        MIR_5_K:          -      14              1
       MIR_5_KL:          -       5              -
        MIR_5_R:          -      78              5
       MIR_5_RB:          -      23              1
      MIR_5_RBP:          -      11              -
       MIR_6_FF:          -      14              2
        MIR_6_K:          -       4              -
       MIR_6_KL:          -       1              -
        MIR_6_R:          -      70              3
       MIR_6_RB:          -      15              -
      MIR_6_RBP:          -       3              2
   ZERO_HALF_FF:          -     207              7
    ZERO_HALF_K:          -      60              1
   ZERO_HALF_KL:          -      60              -
    ZERO_HALF_R:          -     166              8
   ZERO_HALF_RB:          -      40              5
  ZERO_HALF_RBP:          -      24              -

LNS stats           Improv/Calls  Closed  Difficulty  TimeLimit
  'graph_arc_lns':           2/5     60%        0.75       0.10
  'graph_cst_lns':           3/6     50%        0.61       0.10
  'graph_dec_lns':           0/5     60%        0.75       0.10
  'graph_var_lns':           4/6     67%        0.83       0.10
      'rins/rens':           0/0      0%        0.50       0.10
    'rnd_cst_lns':           0/6     50%        0.65       0.10
    'rnd_var_lns':           2/6     50%        0.65       0.10

LS stats           Batches  Restarts  LinMoves  GenMoves  CompoundMoves  WeightUpdates
  'violation_ls':        6         0    29'646     2'179            144            364
  'violation_ls':        6         0    57'809         0              0          2'191
  'violation_ls':        7         0         0     4'089            212             31

Solutions (4)                       Num   Rank
  'fs_random_quick_restart_no_lp':    1  [1,1]
                  'graph_arc_lns':    1  [2,2]
                  'graph_var_lns':    1  [3,3]
                    'rnd_var_lns':    1  [4,4]

Objective bounds                    Num
                      'fs_random':    1
  'fs_random_quick_restart_no_lp':    1
                 'initial_domain':    1
                         'max_lp':    1

Solution repositories    Added  Queried  Ignored  Synchro
  'feasible solutions':     34       97        0       26
        'lp solutions':      0        0        0        0
                'pump':      0        0

Improving bounds shared             Num
                      'fs_random':   22
  'fs_random_quick_restart_no_lp':  777
                         'max_lp':   32
                  'reduced_costs':   15

CpSolverResponse summary:
status: OPTIMAL
objective: 812818
best_bound: 812818
integers: 21787
booleans: 18392
conflicts: 69
branches: 36393
propagations: 1146468
integer_propagations: 3729360
restarts: 36393
lp_iterations: 303
walltime: 19.2226
usertime: 19.2226
deterministic_time: 3.6537
gap_integral: 11.3285
solution_fingerprint: 0xcfd34c3f1a3c46f
@magneticflux-
Copy link
Author

I just ran it under Async Profiler and have some more results.

During the first gap (between the optimal solve and reduced_costs finishing) one thread (the reduced_costs thread?) is calling things like this:

  • operations_research::sat::LinearPropagator::AnalyzeConstraint
  • operations_research::sat::LinearPropagator::Propagate
  • operations_research::sat::IntegerTrail::Enqueue
  • operations_research::sat::EnforcementPropagator::Propagate

During the first and second gaps, a different thread (the max_lp thread maybe, or a helper thread?) is calling things like this:

  • operations_research::sat::CoverCutHelper::TrySingleNodeFlow
  • operations_research::sat::CoverCutHelper::TryWithLetchfordSouliLifting
  • operations_research::sat::LinearProgrammingConstraint::PreprocessCut
  • operations_research::sat::LinearProgrammingConstraint::AddCutFromConstraints
  • operations_research::glop::EnteringVariable::DualChooseEnteringColumn
  • operations_research::glop::TriangularMatrix::UpperSolve
  • operations_research::glop::UpdateRow::ComputeUpdatesRowWiseHypersparse.

The possible thread identities are just based off of the time they stop running, with the first thread stopping as soon as #Done 24.65s reduced_costs is printed and the second thread stopping as soon as the solver stops.

No other threads are active after the optimal solution is found. I can provide a model that causes this, but I think it's pretty widespread.

@Mizux Mizux added Solver: CP-SAT Solver Relates to the CP-SAT solver Bug Lang: Java Java wrapper issue labels Jun 11, 2024
@lperron
Copy link
Collaborator

lperron commented Jun 11, 2024

Can you send us the model ?

@magneticflux-
Copy link
Author

Here's the model I used: model.zip
I also attached a CpSolverSolutionCallback and it immediately receives the optimal solutions and prints out a few variables.

I did some more tests that might be a clue to what's happening:

  • the standard deviation in reported walltime dropped significantly from 1.81s to 0.37s
  • the standard deviation does not appear to decrease when manually measuring time until an optimal solution is printed, implying the delay might be padding out the time until a round number?

I ran a t-test between two measures: reported walltime vs first known optimal solution (empty objective bounds) time, and on a set of 1000 runs before and after the changes. For before, it averaged to a 0.14s difference, with both measures having a standard deviation of ~1.8s. For after, it averaged a 13.2s difference (!!!), with reported walltime having a standard deviation of 0.37s and first known optimal solution time having a standard deviation of 2.33s. Finally, the difference between first known optimal solution for before and after was +1.25s, but this isn't as big of an issue.

@lperron
Copy link
Collaborator

lperron commented Jun 16, 2024

I ran it on main

#Bound   8.11s best:inf   next:[802728,2351043] objective_shaving (vars=18052 csts=17635)                                                                                                                     
#Model   8.74s var:18042/18052 constraints:17593/17634                                                                                                                                                        
#Bound   8.88s best:inf   next:[806009,2351043] pseudo_costs [skipped_logs=13]                                                                                                                                
#Model   9.15s var:18011/18052 constraints:17496/17634                                                                                                                                                        
#Bound   9.34s best:inf   next:[812818,2351043] max_lp [skipped_logs=1]                                                                                                                                       
#1      11.48s best:812933 next:[812818,812932] quick_restart_no_lp (fixed_bools=56/17366)                                                                                                                    
#2      11.63s best:812932 next:[812818,812931] quick_restart_no_lp (fixed_bools=56/17408)                                                                                                                    
#3      11.65s best:812930 next:[812818,812929] rnd_cst_lns (d=0.50 s=213 t=0.10 p=0.00 stall=0 h=auto_l0)                                                                                                    
#4      12.11s best:812924 next:[812818,812923] rnd_cst_lns (d=0.71 s=220 t=0.10 p=1.00 stall=0 h=auto_l0)                                                                                                    
#5      12.28s best:812923 next:[812818,812922] graph_arc_lns (d=0.71 s=222 t=0.10 p=1.00 stall=1 h=auto_l0)                                                                                                  
#6      12.55s best:812824 next:[812818,812823] reduced_costs (fixed_bools=51/17373)                                                                                                                          
#7      12.98s best:812821 next:[812818,812820] rnd_var_lns (d=0.69 s=233 t=0.10 p=0.67 stall=3 h=auto_l0)                                                                                                    
#8      13.68s best:812819 next:[812818,812818] graph_dec_lns (d=0.81 s=238 t=0.10 p=1.00 stall=2 h=auto_l0)                                                                                                  
#9      14.17s best:812818 next:[]         graph_cst_lns (d=0.66 s=251 t=0.10 p=0.60 stall=2 h=auto_l0)                                                                                                       
#Model  14.24s var:17942/18052 constraints:17426/17634   

and the final stats

CpSolverResponse summary:
status: OPTIMAL
objective: 812818
best_bound: 812818
integers: 19589
booleans: 17360
conflicts: 3
branches: 76581
propagations: 1342886
integer_propagations: 5434405
restarts: 49865
lp_iterations: 4801
walltime: 14.3452
usertime: 122.604
deterministic_time: 43.0259
gap_integral: 86.4245
solution_fingerprint: 0x183c4e5a6d15efb4

@magneticflux-
Copy link
Author

magneticflux- commented Jun 16, 2024

That result makes it seem like there is a subsolver that I'm excluding that is causing the difference. I'm only using reduced_costs, max_lp, and LNS workers because those are the only ones that appear "productive" during the solve, and prior tests showed adding any other single subsolver didn't improve times. Is there a subsolver that sticks out as the culprit? One that would perform whatever work is delaying the solve completion during the solve itself?

I can retest with quick_restart_no_lp, pseudo_costs, and objective_shaving tomorrow since those are at least present in your log. Maybe including one of those prevents a "backlog" of stuff to do at the end of the solve.

EDIT:
I quickly tested with main, all default settings, with 20 threads and the issue is even more pronounced: it's been stuck at #Done without printing out stats and 100%-ing a single thread for several minutes now!

Full 13-minute log that had a solution in 22 seconds:
Starting CP-SAT solver v10.0.9999
Parameters: log_search_progress: true stop_after_first_solution: false num_workers: 20

Initial optimization model '': (model_fingerprint: 0x1ca7298b705274a5)
#Variables: 112'330 (#bools: 7'737 #ints: 1'750 in objective)
  - 90'949 Booleans in [0,1]
  - 9 in [0,17]
  - 4'828 in [0,20]
  - 5'409 in [0,75]
  - 11'088 in [0,100]
  - 45 in [0,150]
  - 1 in [1,8]
  - 1 constants in {0} 
#kAtMostOne: 19'710 (#literals: 42'805)
#kBoolAnd: 13'963 (#enforced: 13'962) (#literals: 54'952)
#kBoolOr: 38'806 (#enforced: 8'514) (#literals: 90'798)
#kLinMax: 3'213 (#expressions: 16'563)
#kLinear0: 8'070 (#enforced: 1'361)
#kLinear1: 57'789 (#enforced: 44'982)
#kLinear2: 61'354 (#enforced: 17'405)
#kLinear3: 23'580 (#enforced: 129)
#kLinearN: 7'116 (#enforced: 792) (#terms: 235'772)

Starting presolve at 0.04s
  3.70e-02s  0.00e+00d  [DetectDominanceRelations] 
  5.81e-01s  0.00e+00d  [PresolveToFixPoint] #num_loops=24 #num_dual_strengthening=9 
  4.21e-03s  0.00e+00d  [ExtractEncodingFromLinear] #potential_supersets=18'346 #potential_subsets=969 #amo_encodings=363 #literals=1'143 
[Symmetry] Graph for symmetry has 204'030 nodes and 327'297 arcs.
[Symmetry] Symmetry computation done. time: 0.0650722 dtime: 0.0772636
[Symmetry] #generators: 491, average support size: 19.9185
[Symmetry] The model contains 6274 duplicate constraints !
[Symmetry] 2018 orbits with sizes: 42,42,42,42,42,42,42,42,24,24,...
[Symmetry] Found orbitope of size 16 x 14
[SAT presolve] num removable Booleans: 546 / 23743
[SAT presolve] num trivial clauses: 0
[SAT presolve] [0s] clauses:20606 literals:50748 vars:18294 one_side_vars:11262 simple_definition:4508 singleton_clauses:0
[SAT presolve] [0.00545593s] clauses:20589 literals:50571 vars:18294 one_side_vars:11264 simple_definition:4532 singleton_clauses:0
[SAT presolve] [0.00739877s] clauses:20125 literals:49867 vars:17825 one_side_vars:11264 simple_definition:4065 singleton_clauses:0
  1.98e+00s  7.76e-01d  [Probe] #probed=76'837 #fixed_bools=235 #new_bounds=1'604 #equiv=508 #new_binary_clauses=48'395 
  2.16e-01s  0.00e+00d  [MaxClique] Merged 37196(87802 literals) into 15611(46850 literals) at_most_ones. 
  3.72e-02s  0.00e+00d  [DetectDominanceRelations] 
  1.87e-01s  0.00e+00d  [PresolveToFixPoint] #num_loops=9 #num_dual_strengthening=7 
  3.61e-02s  0.00e+00d  [ProcessAtMostOneAndLinear] #num_changes=587 
  1.81e-02s  0.00e+00d  [DetectDuplicateConstraints] #duplicates=3'136 #without_enforcements=223 
  3.04e-02s  1.95e-03d  [DetectDominatedLinearConstraints] #relevant_constraints=2'322 #num_inclusions=27'097 #num_redundant=205 
  2.22e-03s  0.00e+00d  [DetectDifferentVariables] 
  1.45e-02s  3.41e-03d  [ProcessSetPPC] #relevant_constraints=20'312 #num_inclusions=4'456 
  3.37e-03s  1.75e-04d  [FindAlmostIdenticalLinearConstraints] #num_tested_pairs=2'355 #found=277 
  2.02e-01s  6.60e-01d  [FindBigAtMostOneAndLinearOverlap] 
  5.04e-02s  2.68e-01d  [FindBigVerticalLinearOverlap] #blocks=103 #saved_nz=24'365 
  2.76e-02s  5.80e-02d  [FindBigHorizontalLinearOverlap] #blocks=26 #saved_nz=22'302 #linears=1'306 
  5.53e-03s  8.45e-05d  [MergeClauses] #num_collisions=598 #num_merges=598 #num_saved_literals=1'822 
  3.34e-02s  0.00e+00d  [DetectDominanceRelations] 
  2.54e-01s  0.00e+00d  [PresolveToFixPoint] #num_loops=23 #num_dual_strengthening=14 
  3.20e-02s  0.00e+00d  [DetectDominanceRelations] 
  6.72e-02s  0.00e+00d  [PresolveToFixPoint] #num_loops=1 #num_dual_strengthening=1 
[Symmetry] Graph for symmetry has 165'167 nodes and 163'103 arcs.
[Symmetry] Symmetry computation done. time: 0.0299443 dtime: 0.0403991
[Symmetry] #generators: 456, average support size: 19.8026
[Symmetry] The model contains 162 duplicate constraints !
[Symmetry] 1679 orbits with sizes: 42,42,42,42,42,42,42,42,24,24,...
[Symmetry] Found orbitope of size 16 x 14
[SAT presolve] num removable Booleans: 564 / 22608
[SAT presolve] num trivial clauses: 0
[SAT presolve] [0s] clauses:10308 literals:31729 vars:9297 one_side_vars:2669 simple_definition:5728 singleton_clauses:0
[SAT presolve] [0.00444638s] clauses:10241 literals:31494 vars:9297 one_side_vars:2673 simple_definition:5808 singleton_clauses:0
[SAT presolve] [0.00685135s] clauses:9823 literals:30794 vars:8952 one_side_vars:2675 simple_definition:5484 singleton_clauses:0
  1.22e+00s  5.17e-01d  [Probe] #probed=76'724 #fixed_bools=8 #new_bounds=62 #equiv=29 #new_binary_clauses=31'130 
  4.50e-02s  0.00e+00d  [MaxClique] Merged 15075(44706 literals) into 15052(45821 literals) at_most_ones. 
  3.07e-02s  0.00e+00d  [DetectDominanceRelations] 
  8.24e-02s  0.00e+00d  [PresolveToFixPoint] #num_loops=3 #num_dual_strengthening=2 
  1.71e-02s  0.00e+00d  [ProcessAtMostOneAndLinear] #num_changes=22 
  1.27e-02s  0.00e+00d  [DetectDuplicateConstraints] #duplicates=247 #without_enforcements=756 
  9.16e-03s  3.89e-04d  [DetectDominatedLinearConstraints] #relevant_constraints=1'500 #num_inclusions=377 #num_redundant=11 
  1.98e-03s  0.00e+00d  [DetectDifferentVariables] 
  1.05e-02s  5.64e-04d  [ProcessSetPPC] #relevant_constraints=15'405 #num_inclusions=776 
  2.93e-03s  1.06e-05d  [FindAlmostIdenticalLinearConstraints] #num_tested_pairs=356 #found=119 
  7.44e-02s  2.49e-01d  [FindBigAtMostOneAndLinearOverlap] 
  1.64e-02s  1.26e-01d  [FindBigVerticalLinearOverlap] #blocks=2 #saved_nz=127 
  2.45e-02s  8.30e-02d  [FindBigHorizontalLinearOverlap] #blocks=8 #saved_nz=3'604 #linears=1'087 
  4.75e-03s  7.78e-05d  [MergeClauses] #num_collisions=331 #num_merges=331 #num_saved_literals=1'025 
  3.12e-02s  0.00e+00d  [DetectDominanceRelations] 
  1.77e-01s  0.00e+00d  [PresolveToFixPoint] #num_loops=12 #num_dual_strengthening=10 
  3.07e-02s  0.00e+00d  [DetectDominanceRelations] 
  6.33e-02s  0.00e+00d  [PresolveToFixPoint] #num_loops=1 #num_dual_strengthening=1 
[Symmetry] Graph for symmetry has 161'103 nodes and 144'928 arcs.
[Symmetry] Symmetry computation done. time: 0.0264546 dtime: 0.0375971
[Symmetry] #generators: 453, average support size: 19.8896
[Symmetry] The model contains 58 duplicate constraints !
[Symmetry] 1655 orbits with sizes: 42,42,42,42,42,42,42,42,24,24,...
[Symmetry] Found orbitope of size 16 x 14
[SAT presolve] num removable Booleans: 205 / 22181
[SAT presolve] num trivial clauses: 0
[SAT presolve] [0s] clauses:6234 literals:23437 vars:8851 one_side_vars:5310 simple_definition:3052 singleton_clauses:0
[SAT presolve] [0.0011198s] clauses:6234 literals:23437 vars:8851 one_side_vars:5310 simple_definition:3052 singleton_clauses:0
[SAT presolve] [0.00245779s] clauses:6165 literals:23309 vars:8797 one_side_vars:5312 simple_definition:3007 singleton_clauses:0
  1.10e+00s  4.87e-01d  [Probe] #probed=76'544 #new_bounds=18 #new_binary_clauses=27'690 
  9.44e-02s  0.00e+00d  [MaxClique] Merged 11113(35702 literals) into 11104(42835 literals) at_most_ones. 
  3.29e-02s  0.00e+00d  [DetectDominanceRelations] 
  7.21e-02s  0.00e+00d  [PresolveToFixPoint] #num_loops=2 #num_dual_strengthening=1 
  1.70e-02s  0.00e+00d  [ProcessAtMostOneAndLinear] #num_changes=13 
  1.30e-02s  0.00e+00d  [DetectDuplicateConstraints] #duplicates=58 #without_enforcements=766 
  5.98e-03s  2.28e-04d  [DetectDominatedLinearConstraints] #relevant_constraints=1'355 #num_inclusions=265 
  2.12e-03s  0.00e+00d  [DetectDifferentVariables] 
  1.09e-02s  3.14e-04d  [ProcessSetPPC] #relevant_constraints=15'079 #num_inclusions=76 
  2.83e-03s  4.46e-06d  [FindAlmostIdenticalLinearConstraints] #num_tested_pairs=161 #found=21 
  5.34e-02s  1.69e-01d  [FindBigAtMostOneAndLinearOverlap] 
  1.35e-02s  8.51e-02d  [FindBigVerticalLinearOverlap] #blocks=2 #saved_nz=1'172 
  3.28e-02s  1.28e-01d  [FindBigHorizontalLinearOverlap] #linears=1'074 
  5.33e-03s  7.78e-05d  [MergeClauses] #num_collisions=414 #num_merges=414 #num_saved_literals=1'246 
  3.25e-02s  0.00e+00d  [DetectDominanceRelations] 
  1.04e-01s  0.00e+00d  [PresolveToFixPoint] #num_loops=5 #num_dual_strengthening=4 
  6.60e-03s  0.00e+00d  [ExpandObjective] #entries=46'275 #tight_variables=2'802 #tight_constraints=1'352 

Presolve summary:
  - 23687 affine relations were detected.
  - rule 'TODO dual: make linear1 equiv' was applied 1'085 times.
  - rule 'TODO dual: only one blocking constraint?' was applied 50'553 times.
  - rule 'TODO dual: only one blocking enforced constraint?' was applied 9'731 times.
  - rule 'TODO dual: only one unspecified blocking constraint?' was applied 16 times.
  - rule 'TODO dual: tighten at most one' was applied 509 times.
  - rule 'TODO duplicate: identical constraint with different enforcements' was applied 1'745 times.
  - rule 'TODO linear inclusion: superset is equality' was applied 689 times.
  - rule 'TODO linear2: contains a Boolean.' was applied 14'966 times.
  - rule 'TODO symmetry: add symmetry breaking inequalities?' was applied 3 times.
  - rule 'affine: fixed' was applied 181 times.
  - rule 'affine: new relation' was applied 23'687 times.
  - rule 'at_most_one: empty or all false' was applied 6'314 times.
  - rule 'at_most_one: removed literals' was applied 13'023 times.
  - rule 'at_most_one: resolved two constraints with opposite literal' was applied 76 times.
  - rule 'at_most_one: satisfied' was applied 3'094 times.
  - rule 'at_most_one: singleton' was applied 4 times.
  - rule 'at_most_one: size one' was applied 4'085 times.
  - rule 'at_most_one: transformed into max clique.' was applied 3 times.
  - rule 'at_most_one: x and not(x)' was applied 253 times.
  - rule 'bool and: empty' was applied 207 times.
  - rule 'bool_and: always false' was applied 7'146 times.
  - rule 'bool_and: fixed literals' was applied 317 times.
  - rule 'bool_and: non-reified.' was applied 8'788 times.
  - rule 'bool_and: removed duplicate literal' was applied 3 times.
  - rule 'bool_and: x => x' was applied 6'682 times.
  - rule 'bool_or: always true' was applied 1'415 times.
  - rule 'bool_or: fixed literals' was applied 616 times.
  - rule 'bool_or: implications' was applied 36'210 times.
  - rule 'bool_or: only one literal' was applied 16'473 times.
  - rule 'bool_or: removed enforcement literal' was applied 3'004 times.
  - rule 'bool_or: singleton' was applied 4'508 times.
  - rule 'deductions: 37673 stored' was applied 1 time.
  - rule 'dual: add implication' was applied 4'848 times.
  - rule 'dual: enforced equivalence' was applied 6'858 times.
  - rule 'dual: equivalent Boolean in near-duplicate constraints' was applied 113 times.
  - rule 'dual: fix variable' was applied 1'023 times.
  - rule 'dual: make encoding equiv' was applied 5'950 times.
  - rule 'dual: reduced domain' was applied 4 times.
  - rule 'duplicate: merged rhs of linear constraint' was applied 506 times.
  - rule 'duplicate: removed constraint' was applied 3'441 times.
  - rule 'encoding: candidate linear is all Boolean now.' was applied 363 times.
  - rule 'encoding: extracted from linear' was applied 363 times.
  - rule 'encoding: reduced target domain' was applied 363 times.
  - rule 'enforcement: always false' was applied 1'353 times.
  - rule 'enforcement: false literal' was applied 30'386 times.
  - rule 'enforcement: literal not used' was applied 4'355 times.
  - rule 'enforcement: removed duplicate literal' was applied 7 times.
  - rule 'enforcement: true literal' was applied 12'041 times.
  - rule 'exactly_one: removed literals' was applied 20 times.
  - rule 'exactly_one: simplified objective' was applied 8 times.
  - rule 'exactly_one: singleton' was applied 20 times.
  - rule 'incompatible linear: add implication' was applied 15 times.
  - rule 'lin_max: affine_max target domain reduced' was applied 1 time.
  - rule 'lin_max: converted to equality' was applied 1 time.
  - rule 'lin_max: divising by gcd' was applied 1'360 times.
  - rule 'lin_max: fixed affine_max target' was applied 2 times.
  - rule 'lin_max: removed affine_max exprs' was applied 2 times.
  - rule 'lin_max: removed exprs' was applied 1'487 times.
  - rule 'lin_max: x = max(x, ...)' was applied 522 times.
  - rule 'linear + amo: added implications' was applied 1 time.
  - rule 'linear + amo: empty after processing' was applied 10 times.
  - rule 'linear + amo: extracted enforcement literal' was applied 1'491 times.
  - rule 'linear + amo: fixed literal implied by enforcement' was applied 1 time.
  - rule 'linear + amo: infeasible enforcement' was applied 2 times.
  - rule 'linear + amo: trivial linear constraint' was applied 32 times.
  - rule 'linear inclusion: redundant containing constraint' was applied 8 times.
  - rule 'linear inclusion: redundant included constraint' was applied 200 times.
  - rule 'linear inclusion: subset + singleton is equality' was applied 8 times.
  - rule 'linear matrix: common horizontal rectangle' was applied 34 times.
  - rule 'linear matrix: common vertical rectangle' was applied 107 times.
  - rule 'linear matrix: defining equation for common rectangle' was applied 1 time.
  - rule 'linear1: always true' was applied 4'861 times.
  - rule 'linear1: transformed to implication' was applied 2'628 times.
  - rule 'linear2: implied ax + by = cte has only one solution' was applied 41 times.
  - rule 'linear: advanced affine relation from 2 constraints.' was applied 417 times.
  - rule 'linear: always true' was applied 40'811 times.
  - rule 'linear: divide by GCD' was applied 19'230 times.
  - rule 'linear: doubleton free' was applied 75 times.
  - rule 'linear: empty' was applied 30'090 times.
  - rule 'linear: enforcement literal in expression' was applied 28'453 times.
  - rule 'linear: extracted at most one (max).' was applied 354 times.
  - rule 'linear: extracted at most one (min).' was applied 9 times.
  - rule 'linear: extracted enforcement literal' was applied 1 time.
  - rule 'linear: fixed or dup variables' was applied 119'379 times.
  - rule 'linear: infeasible' was applied 7'924 times.
  - rule 'linear: negative at most one' was applied 11'386 times.
  - rule 'linear: negative clause' was applied 165 times.
  - rule 'linear: negative equal one' was applied 43 times.
  - rule 'linear: positive at most one' was applied 162 times.
  - rule 'linear: positive clause' was applied 7'084 times.
  - rule 'linear: positive equal one' was applied 855 times.
  - rule 'linear: positive reified and' was applied 16 times.
  - rule 'linear: reduced variable domains' was applied 41'853 times.
  - rule 'linear: reduced variable domains in derived constraint' was applied 807 times.
  - rule 'linear: remapped using affine relations' was applied 21'176 times.
  - rule 'linear: remove irrelevant part' was applied 10 times.
  - rule 'linear: simplified rhs' was applied 46'454 times.
  - rule 'linear: singleton column' was applied 71 times.
  - rule 'linear: small Boolean expression' was applied 16 times.
  - rule 'linear: variable substitution 0' was applied 121 times.
  - rule 'linear: variable substitution 1' was applied 1'484 times.
  - rule 'linear: variable substitution 2' was applied 3'852 times.
  - rule 'linear: variable substitution 3' was applied 447 times.
  - rule 'objective: shifted cost with exactly ones' was applied 189 times.
  - rule 'objective: variable not used elsewhere' was applied 3'272 times.
  - rule 'presolve: 67648 unused variables removed.' was applied 1 time.
  - rule 'presolve: iteration' was applied 3 times.
  - rule 'probing: bool_or reduced to implication' was applied 147 times.
  - rule 'probing: simplified clauses.' was applied 106 times.
  - rule 'setppc: bool_or in at_most_one.' was applied 338 times.
  - rule 'setppc: removed dominated constraints' was applied 257 times.
  - rule 'variables with 2 values: create encoding literal' was applied 2 times.
  - rule 'variables with 2 values: new affine relation' was applied 2 times.
  - rule 'variables: canonicalize affine domain' was applied 8 times.
  - rule 'variables: canonicalize domain' was applied 1 time.
  - rule 'variables: detect fully reified value encoding' was applied 3'499 times.
  - rule 'variables: detect half reified value encoding' was applied 20'968 times.
  - rule 'variables: removable enforcement literal' was applied 28 times.

Presolved optimization model '': (model_fingerprint: 0x96a5a38a34de778f)
#Variables: 18'065 (#bools: 5'205 #ints: 78 in objective)
  - 17'064 Booleans in [0,1]
  - 3 in [-2,3]
  - 1 in [0,1][3,4][6,7][9,10][12,13][15,16]
  - 117 in [0,2]
  - 105 in [0,3]
  - 78 in [0,4]
  - 90 in [0,5]
  - 188 in [0,6]
  - 36 in [0,7]
  - 61 in [0,8]
  - 21 in [0,9]
  - 14 in [0,10]
  - 11 in [0,11]
  - 9 in [0,12]
  - 9 in [0,13]
  - 6 in [0,14]
  - 6 in [0,15]
  - 13 in [0,16]
  - 20 in [0,17]
  - 6 in [0,18]
  - 4 in [0,19]
  - 4 in [0,20]
  - 5 in [0,21]
  - 5 in [0,22]
  - 1 in [0,23]
  - 10 in [0,24]
  - 4 in [0,25]
  - 7 in [0,26]
  - 4 in [0,27]
  - 5 in [0,28]
  - 2 in [0,29]
  - 2 in [0,30]
  - 3 in [0,31]
  - 13 in [0,32]
  - 1 in [0,33]
  - 3 in [0,34]
  - 3 in [0,36]
  - 3 in [0,37]
  - 3 in [0,38]
  - 2 in [0,39]
  - 9 in [0,40]
  - 2 in [0,41]
  - 3 in [0,42]
  - 3 in [0,44]
  - 2 in [0,45]
  - 4 in [0,46]
  - 1 in [0,47]
  - 9 in [0,48]
  - 2 in [0,49]
  - 1 in [0,50]
  - 2 in [0,51]
  - 1 in [0,52]
  - 1 in [0,53]
  - 5 in [0,54]
  - 4 in [0,56]
  - 1 in [0,57]
  - 1 in [0,58]
  - 1 in [0,60]
  - 1 in [0,61]
  - 2 in [0,62]
  - 2 in [0,64]
  - 3 in [0,65]
  - 2 in [0,68]
  - 1 in [0,69]
  - 3 in [0,73]
  - 3 in [0,75]
  - 1 in [0,81]
  - 2 in [0,82]
  - 1 in [0,99]
  - 1 in [0,105]
  - 1 in [0,116]
  - 1 in [0,117]
  - 1 in [0,118]
  - 3 in [1,10]
  - 1 in [1,11]
  - 8 in [1,17]
  - 1 in [1,20]
  - 1 in [1,25]
  - 1 in [1,55]
  - 1 in [1,64]
  - 1 in [2,6]
  - 1 in [2,34]
  - 1 in [3,11]
  - 1 in [3,45]
  - 1 in [3,51]
  - 1 in [4,68]
  - 1 in [4,142]
  - 1 in [6,133]
  - 1 in [6,134]
  - 1 in [7,85]
  - 1 in [8,102]
  - 12 in [9,17]
  - 1 in [9,119]
  - 1 in [10,136]
  - 1 in [43,51]
  - 1 in [77,85]
  - 1 in [94,102]
  - 1 in [111,119]
  - 1 in [128,136]
#kAtMostOne: 7'719 (#literals: 35'433)
#kBoolAnd: 3'124 (#enforced: 3'124 #multi: 197) (#literals: 8'045)
#kBoolOr: 1'685 (#literals: 13'024)
#kExactlyOne: 577 (#literals: 1'871)
#kLinMax: 1'344 (#expressions: 5'401)
#kLinear1: 1'683 (#enforced: 1'683 #multi: 470)
#kLinear2: 207 (#enforced: 174 #multi: 21)
#kLinear3: 108 (#enforced: 8)
#kLinearN: 1'195 (#enforced: 12 #multi: 2) (#terms: 40'733)

Preloading model.
#Bound   7.83s best:inf   next:[802700,2351043] initial_domain
[Symmetry] Graph for symmetry has 65'404 nodes and 147'975 arcs.
[Symmetry] Symmetry computation done. time: 0.0195907 dtime: 0.0310665
[Symmetry] #generators: 451, average support size: 19.9601
[Symmetry] The model contains 9 duplicate constraints !
[Symmetry] Found orbitope of size 16 x 14
#Model   7.86s var:18065/18065 constraints:17642/17642

Starting search at 7.87s with 20 workers.
13 full problem subsolvers: [core, default_lp, lb_tree_search, max_lp, no_lp, objective_lb_search, objective_shaving_search_max_lp, objective_shaving_search_no_lp, probing, pseudo_costs, quick_restart, quick_restart_no_lp, reduced_costs]
5 first solution subsolvers: [fj_long_default, fj_short_default, fj_short_lin_default, fs_random, fs_random_quick_restart]
9 incomplete subsolvers: [feasibility_pump, graph_arc_lns, graph_cst_lns, graph_dec_lns, graph_var_lns, rins/rens, rnd_cst_lns, rnd_var_lns, violation_ls]
3 helper subsolvers: [neighborhood_helper, synchronization_agent, update_gap_integral]

#Bound   7.98s best:inf   next:[802701,2351043] objective_shaving_search_no_lp (vars=18065 csts=17650)
#Bound   8.14s best:inf   next:[802702,2351043] objective_shaving_search_max_lp (vars=18065 csts=17643)
#Bound   8.24s best:inf   next:[802703,2351043] objective_shaving_search_max_lp (vars=18065 csts=17643)
#Bound   8.33s best:inf   next:[802704,2351043] objective_shaving_search_max_lp (vars=18065 csts=17643)
#Bound   8.42s best:inf   next:[802705,2351043] objective_shaving_search_max_lp (vars=18065 csts=17643)
#Bound   8.52s best:inf   next:[802706,2351043] objective_shaving_search_max_lp (vars=18065 csts=17643)
#Bound   8.62s best:inf   next:[802707,2351043] objective_shaving_search_max_lp (vars=18065 csts=17643)
#Bound   8.71s best:inf   next:[802708,2351043] objective_shaving_search_max_lp (vars=18065 csts=17643)
#Bound   8.80s best:inf   next:[802709,2351043] objective_shaving_search_max_lp (vars=18065 csts=17643)
#Bound   8.88s best:inf   next:[802710,2351043] objective_shaving_search_max_lp (vars=18065 csts=17643)
#Bound   8.98s best:inf   next:[802711,2351043] objective_shaving_search_max_lp (vars=18065 csts=17643)
#Bound   9.08s best:inf   next:[802712,2351043] objective_shaving_search_max_lp (vars=18065 csts=17643)
#Bound   9.19s best:inf   next:[802713,2351043] objective_shaving_search_max_lp (vars=18065 csts=17643)
#Bound   9.30s best:inf   next:[802714,2351043] objective_shaving_search_max_lp (vars=18065 csts=17643)
#Bound   9.41s best:inf   next:[802715,2351043] objective_shaving_search_max_lp (vars=18065 csts=17643)
#Bound   9.52s best:inf   next:[802716,2351043] objective_shaving_search_max_lp (vars=18065 csts=17643)
#Bound   9.61s best:inf   next:[802717,2351043] objective_shaving_search_max_lp (vars=18065 csts=17643)
#Bound   9.70s best:inf   next:[802718,2351043] objective_shaving_search_max_lp (vars=18065 csts=17643)
#Bound   9.79s best:inf   next:[802719,2351043] objective_shaving_search_max_lp (vars=18065 csts=17643)
#Bound   9.89s best:inf   next:[802720,2351043] objective_shaving_search_max_lp (vars=18065 csts=17643)
#Bound   9.99s best:inf   next:[802721,2351043] objective_shaving_search_max_lp (vars=18065 csts=17643)
#Bound  10.07s best:inf   next:[802722,2351043] objective_shaving_search_max_lp (vars=18065 csts=17643)
#Bound  10.16s best:inf   next:[802723,2351043] objective_shaving_search_max_lp (vars=18065 csts=17643)
#Bound  10.24s best:inf   next:[802724,2351043] objective_shaving_search_max_lp (vars=18065 csts=17643)
#Bound  10.34s best:inf   next:[802725,2351043] objective_shaving_search_max_lp (vars=18065 csts=17643)
#Bound  10.44s best:inf   next:[802726,2351043] objective_shaving_search_max_lp (vars=18065 csts=17643)
#Bound  10.54s best:inf   next:[802727,2351043] objective_shaving_search_max_lp (vars=18065 csts=17643)
#Bound  10.65s best:inf   next:[802728,2351043] objective_shaving_search_max_lp (vars=18065 csts=17643)
#Bound  10.74s best:inf   next:[802729,2351043] objective_shaving_search_max_lp (vars=18065 csts=17643)
#Bound  10.83s best:inf   next:[802730,2351043] objective_shaving_search_max_lp (vars=18065 csts=17643)
#Bound  10.94s best:inf   next:[802731,2351043] objective_shaving_search_max_lp (vars=18065 csts=17643)
#Bound  11.62s best:inf   next:[805709,2351043] reduced_costs [skipped_logs=6]
#Model  11.87s var:18055/18065 constraints:17601/17642
#1      12.11s best:813432 next:[805709,813431] core (fixed_bools=16/17361)
#2      12.49s best:813429 next:[805709,813428] rnd_cst_lns (d=0.50 s=152 t=0.10 p=0.00 stall=0 h=auto_l0)
#Model  12.55s var:18040/18065 constraints:17574/17642
#Model  12.59s var:18024/18065 constraints:17531/17642
#Bound  12.50s best:813429 next:[806009,813428] pseudo_costs [skipped_logs=0]
#3      13.71s best:813426 next:[812818,813425] rnd_var_lns (d=0.71 s=157 t=0.10 p=1.00 stall=1 h=auto_l0)
#Bound  13.39s best:813429 next:[812818,813428] max_lp [skipped_logs=2]
#4      15.22s best:812930 next:[812818,812929] rins_lp_lns (d=0.50 s=172 t=0.10 p=0.00 stall=0 h=auto_l0)
#5      15.86s best:812830 next:[812818,812829] rins_lp_lns (d=0.19 s=182 t=0.10 p=0.00 stall=0 h=auto_l0)
#6      17.32s best:812827 next:[812818,812826] graph_dec_lns (d=0.60 s=197 t=0.10 p=0.50 stall=4 h=auto_l0) [presolve]
#7      17.68s best:812826 next:[812818,812825] rnd_cst_lns (d=0.61 s=200 t=0.10 p=0.50 stall=5 h=auto_l0)
#8      17.78s best:812825 next:[812818,812824] rnd_var_lns (d=0.81 s=192 t=0.10 p=0.75 stall=0 h=auto_l0)
#9      18.02s best:812823 next:[812818,812822] graph_dec_lns (d=0.60 s=204 t=0.10 p=0.50 stall=0 h=auto_l0)
#10     18.67s best:812821 next:[812818,812820] graph_dec_lns (d=0.70 s=214 t=0.10 p=0.57 stall=0 h=auto_l0)
#11     22.19s best:812819 next:[812818,812818] graph_arc_lns (d=0.74 s=228 t=0.10 p=0.62 stall=2 h=auto_l0)
#12     22.23s best:812818 next:[]         graph_dec_lns (d=0.78 s=230 t=0.10 p=0.62 stall=0 h=auto_l0)
#Done   22.31s no_lp
#Done   22.34s quick_restart_no_lp
#Done   24.05s max_lp
#Done   24.33s quick_restart
#Done   25.13s default_lp
#Done   25.30s pseudo_costs
#Done   25.53s core
#Done   26.02s reduced_costs
#Done   26.21s objective_lb_search
#Done  822.06s probing

Task timing                                  n [     min,      max]      avg      dev     time         n [     min,      max]      avg      dev    dtime
                             'core':         1 [  17.66s,   17.66s]   17.66s   0.00ns   17.66s         1 [   2.42s,    2.42s]    2.42s   0.00ns    2.42s
                       'default_lp':         1 [  17.25s,   17.25s]   17.25s   0.00ns   17.25s         1 [   2.53s,    2.53s]    2.53s   0.00ns    2.53s
                 'feasibility_pump':         2 [142.82ms,   21.66s]   10.90s   10.76s   21.81s         1 [  10.34s,   10.34s]   10.34s   0.00ns   10.34s
                  'fj_long_default':        25 [142.41ms, 219.61ms] 168.04ms  19.17ms    4.20s        25 [ 28.92ms,  35.23ms]  30.71ms   1.35ms 767.72ms
                 'fj_short_default':        33 [105.82ms, 175.63ms] 128.01ms  15.96ms    4.22s        33 [ 11.67ms,  14.97ms]  13.25ms 721.79us 437.38ms
             'fj_short_lin_default':        33 [ 94.67ms, 217.19ms] 125.27ms  22.15ms    4.13s        33 [ 11.80ms,  15.40ms]  13.37ms 832.55us 441.20ms
                        'fs_random':         1 [   4.23s,    4.23s]    4.23s   0.00ns    4.23s         1 [  8.52ms,   8.52ms]   8.52ms   0.00ns   8.52ms
          'fs_random_quick_restart':         1 [   4.22s,    4.22s]    4.22s   0.00ns    4.22s         1 [ 11.03ms,  11.03ms]  11.03ms   0.00ns  11.03ms
                    'graph_arc_lns':        11 [174.63ms,    2.05s]    1.01s 655.96ms   11.08s        11 [168.00ns, 100.16ms]  57.80ms  47.03ms 635.85ms
                    'graph_cst_lns':        11 [234.42ms,    1.87s] 863.64ms 575.97ms    9.50s        11 [859.00ns, 100.48ms]  48.50ms  47.75ms 533.55ms
                    'graph_dec_lns':        11 [211.04ms,    1.85s]    1.03s 667.96ms   11.30s        10 [607.00ns, 100.51ms]  54.83ms  46.54ms 548.35ms
                    'graph_var_lns':        11 [218.29ms,    1.68s] 917.75ms 512.57ms   10.10s        11 [  4.78us, 102.01ms]  61.91ms  44.35ms 681.02ms
                   'lb_tree_search':         1 [  25.77s,   25.77s]   25.77s   0.00ns   25.77s         0 [  0.00ns,   0.00ns]   0.00ns   0.00ns   0.00ns
                           'max_lp':         1 [  16.18s,   16.18s]   16.18s   0.00ns   16.18s         1 [   6.85s,    6.85s]    6.85s   0.00ns    6.85s
                            'no_lp':         1 [  14.44s,   14.44s]   14.44s   0.00ns   14.44s         1 [   1.55s,    1.55s]    1.55s   0.00ns    1.55s
              'objective_lb_search':         1 [  18.34s,   18.34s]   18.34s   0.00ns   18.34s         1 [   3.14s,    3.14s]    3.14s   0.00ns    3.14s
  'objective_shaving_search_max_lp':        37 [ 82.19ms,    1.01s] 123.37ms 147.39ms    4.56s         0 [  0.00ns,   0.00ns]   0.00ns   0.00ns   0.00ns
   'objective_shaving_search_no_lp':         8 [ 85.70ms,    4.43s]    1.12s    1.33s    9.00s         1 [   2.02s,    2.02s]    2.02s   0.00ns    2.02s
                          'probing':         1 [  13.57m,   13.57m]   13.57m   0.00ns   13.57m         1 [   2.99m,    2.99m]    2.99m   0.00ns    2.99m
                     'pseudo_costs':         1 [  17.43s,   17.43s]   17.43s   0.00ns   17.43s         1 [   1.87s,    1.87s]    1.87s   0.00ns    1.87s
                    'quick_restart':         1 [  16.46s,   16.46s]   16.46s   0.00ns   16.46s         1 [   2.48s,    2.48s]    2.48s   0.00ns    2.48s
              'quick_restart_no_lp':         1 [  14.46s,   14.46s]   14.46s   0.00ns   14.46s         1 [   1.52s,    1.52s]    1.52s   0.00ns    1.52s
                    'reduced_costs':         1 [  18.15s,   18.15s]   18.15s   0.00ns   18.15s         1 [   1.96s,    1.96s]    1.96s   0.00ns    1.96s
                        'rins/rens':        12 [ 40.21ms,    1.17s] 520.55ms 381.73ms    6.25s        10 [ 46.75us, 100.29ms]  61.31ms  45.64ms 613.06ms
                      'rnd_cst_lns':        11 [331.48ms,    1.76s] 920.19ms 507.99ms   10.12s        11 [235.37us, 100.29ms]  48.90ms  47.05ms 537.94ms
                      'rnd_var_lns':        11 [200.66ms,    1.84s] 917.85ms 594.66ms   10.10s        11 [ 76.00ns, 100.17ms]  47.39ms  48.19ms 521.33ms
                     'violation_ls':        11 [142.51ms,    2.11s] 714.51ms 739.88ms    7.86s        11 [ 23.44ms, 610.47ms] 193.39ms 253.32ms    2.13s

Search stats                   Bools  Conflicts  Branches  Restarts  BoolPropag  IntegerPropag
                     'core':  17'367      3'426   349'346    55'313   7'617'391     18'552'308
               'default_lp':  17'363         50   184'386    53'171   2'949'096     12'146'404
                'fs_random':  17'361          0    34'722    34'722     722'686      3'033'803
  'fs_random_quick_restart':  17'361          0    34'722    34'722     722'686      3'033'817
           'lb_tree_search':  17'361          0    34'722    34'722     722'720      3'122'504
                   'max_lp':  17'361          0    34'722    34'722     722'673      3'122'423
                    'no_lp':  17'361      1'209   261'862    56'508   4'503'403     12'762'387
      'objective_lb_search':  17'371         50   182'562    53'174   3'018'887     12'186'887
                  'probing':  17'433         14    34'911    34'911     754'388      3'072'821
             'pseudo_costs':  17'385         73   183'052    53'091   2'917'684     11'987'878
            'quick_restart':  17'361         39   180'648    53'161   3'129'635     12'224'126
      'quick_restart_no_lp':  17'422        516   291'659    56'517   4'674'889     13'122'662
            'reduced_costs':  17'366         47   184'658    53'159   2'906'133     12'321'693

SAT stats                     ClassicMinim  LitRemoved  LitLearned  LitForgotten  Subsumed  MClauses  MDecisions  MLitTrue  MSubsumed  MLitRemoved  MReused
                     'core':         2'271     360'485   1'910'429             0        64     4'459     156'646         0        555       11'233    2'211
               'default_lp':            29       1'076      11'047             0         1     3'323     111'323         0        547        9'659    1'901
                'fs_random':             0           0           0             0         0         0           0         0          0            0        0
  'fs_random_quick_restart':             0           0           0             0         0         0           0         0          0            0        0
           'lb_tree_search':             0           0           0             0         0         0           0         0          0            0        0
                   'max_lp':             0           0           0             0         0         0           0         0          0            0        0
                    'no_lp':         1'165      79'392   3'600'104             0        25     5'199     135'200         0        614        8'633    2'713
      'objective_lb_search':            32       1'041       9'566             0         1     3'321     111'358         0        541        9'639    1'906
                  'probing':             0           0          14             0         0         0           0         0          0            0        0
             'pseudo_costs':            45       1'297      40'751             0         1     3'322     102'825         0        549        9'667    1'904
            'quick_restart':            30       1'205       9'068             0         1     3'322     111'336         0        553        9'684    1'899
      'quick_restart_no_lp':           291      34'166      70'022             0        10     5'183     135'077         0        607        8'606    2'696
            'reduced_costs':            40      23'534     101'132             0         1     3'318     111'312         0        548        9'667    1'900

Lp stats                      Component  Iterations  AddedCuts  OPTIMAL  DUAL_F.  DUAL_U.
               'default_lp':          1       7'676      6'289      221        0       11
                'fs_random':          1         419        825       11        0        0
  'fs_random_quick_restart':          1         501      1'344       13        0        0
           'lb_tree_search':          1      31'214      2'023       10        0        0
                   'max_lp':          1      11'926        815        1        5        0
      'objective_lb_search':          1       8'540      6'099      214        0        0
                  'probing':          1     216'693     40'679    1'528       96        2
             'pseudo_costs':          1       4'690      6'072       50      170       43
            'quick_restart':          1       7'565      6'160      146        0        1
            'reduced_costs':          1       3'998      6'329       58      129       26

Lp dimension                                                                        Final dimension of first component
               'default_lp':    3491 rows, 16785 columns, 68326 entries with magnitude in [3.307244e-04, 1.000000e+00]
                'fs_random':     257 rows, 16785 columns, 12237 entries with magnitude in [1.671416e-01, 1.000000e+00]
  'fs_random_quick_restart':     307 rows, 16785 columns, 12417 entries with magnitude in [1.940445e-01, 1.000000e+00]
           'lb_tree_search':  17792 rows, 18065 columns, 163630 entries with magnitude in [9.188468e-05, 1.000000e+00]
                   'max_lp':  17636 rows, 18065 columns, 110150 entries with magnitude in [3.089506e-02, 1.000000e+00]
      'objective_lb_search':    3163 rows, 16785 columns, 91898 entries with magnitude in [1.360865e-04, 1.000000e+00]
                  'probing':   4777 rows, 16785 columns, 567689 entries with magnitude in [4.717821e-05, 1.000000e+00]
             'pseudo_costs':    1682 rows, 18065 columns, 36165 entries with magnitude in [1.667014e-04, 1.000000e+00]
            'quick_restart':    3604 rows, 16785 columns, 69307 entries with magnitude in [9.090318e-04, 1.000000e+00]
            'reduced_costs':    1610 rows, 18065 columns, 44697 entries with magnitude in [1.755444e-03, 1.000000e+00]

Lp debug                      CutPropag  CutEqPropag  Adjust  Overflow        Bad  BadScaling
               'default_lp':         27            0     220         0      2'922           0
                'fs_random':          9            0       2         0        317           0
  'fs_random_quick_restart':         16            0       0         0        932           0
           'lb_tree_search':         34            1      10         0     11'106           0
                   'max_lp':          7            1       6         0      2'956           0
      'objective_lb_search':         33            0     197         0      4'674           0
                  'probing':         99          543   1'610         0  1'758'574           0
             'pseudo_costs':         26            0     257         0      8'151           0
            'quick_restart':         29            0     130         0      4'095           0
            'reduced_costs':         14            0     204         0      8'848           0

Lp pool                       Constraints  Updates  Simplif  Merged  Shortened  Split  Strenghtened      Cuts/Call
               'default_lp':       16'236       32    2'889       4        824      0         4'809    6'289/8'915
                'fs_random':       10'773        8      321       3         99      0           119      825/1'262
  'fs_random_quick_restart':       11'292       13      442       3         98      0           318    1'344/2'274
           'lb_tree_search':       19'608      193    1'605       1        832     15           741    2'023/5'533
                   'max_lp':       18'401       69       34       0          0      2           116      815/2'403
      'objective_lb_search':       16'045       44    2'775       5        907      0         3'652    6'099/8'553
                  'probing':       19'628    3'572    7'042       3        791    534        14'208  40'679/76'577
             'pseudo_costs':       23'655       74    4'616       3        671      0         9'961   6'072/10'451
            'quick_restart':       16'108       67    2'890       3      1'011      4         6'109    6'160/8'736
            'reduced_costs':       23'909       61    5'760       6      1'829      4         8'513   6'329/12'056

Lp Cut            fs_ran  fs_ran  defaul  max_lp  quick_  reduce  pseudo  lb_tre  probin  object
          CG_FF:      69     101     244      17     294     312     342     135     807     209
           CG_K:      43      58     154       9     144     173     234      80     550     128
          CG_KL:       1       3      10       3       5       5       9      13      17       4
           CG_R:     101     170     521      16     518     522     690     145   2'806     612
          CG_RB:      78     210     547      18     573   1'062     818     156   3'419     714
         CG_RBP:      18      67     278      15     332     499     505     146   2'008     426
         Clique:       -       -       -       5       -      91     105      19       -       -
             IB:     232     273   3'051      42   2'854   1'144   1'139      54  12'578   2'555
       MIR_1_FF:      61      83     167      59     176     200     149      86     978     145
        MIR_1_K:      34      42     109      58     112     104     122      80     454     106
       MIR_1_KL:       2       4      19       8       8       5       4       8     108      17
        MIR_1_R:      55      77     181      24     187     164     158      41     956     149
       MIR_1_RB:      25      39     157      10     127     153     180      28     965     136
      MIR_1_RBP:       4       6      20       2      26      28      32       9     257      22
      MIR_1_RLT:       -       -       -       5       -     204     200       7       -       -
       MIR_2_FF:      26      40     105      46     100     188     139      64     835      87
        MIR_2_K:      11      19      53      13      52      67      66      30     403      59
       MIR_2_KL:       -       1       9       4       7       8       9       7      58      10
        MIR_2_R:      21      38     122      46     132     215     210      54   1'420     113
       MIR_2_RB:       5      24      96      14      72     133     110      43   1'277      99
      MIR_2_RBP:       -       3      14       3      22      28      43      12     549      20
       MIR_3_FF:       7       8      24      46      44      87      65      60     543      34
        MIR_3_K:       2       2      22      21      20      56      37      31     223      24
       MIR_3_KL:       -       -       4       5       1       4       4       7      43       3
        MIR_3_R:       3       8      62      48      57     149     107      87   1'078      74
       MIR_3_RB:       5      10      62      19      37      94      70      53     984      52
      MIR_3_RBP:       -       3      13       7      15      18      27      20     408      25
       MIR_4_FF:       1       6      25      27      24      45      44      49     432      14
        MIR_4_K:       -       1      15      12       8      23      19      18     230      13
       MIR_4_KL:       -       -       4       8       2       2       2       6      28       1
        MIR_4_R:       1       3      42      30      29      80      72      66     767      41
       MIR_4_RB:       3       8      22      13      17      50      46      47     772      32
      MIR_4_RBP:       1       3       9       3      10      17      18      23     254       9
       MIR_5_FF:       -       4       8      14      18      43      37      29     358      11
        MIR_5_K:       -       -       7      11       8      18      20      15     234       8
       MIR_5_KL:       -       -       -       2       -       3       2       3      17       -
        MIR_5_R:       -       -      18      22      17      50      51      48     637      28
       MIR_5_RB:       6      10      21       7      30      34      18      46     788      38
      MIR_5_RBP:       -       1       3       1       1       9       9      16     207       4
       MIR_6_FF:       -       2       3      17      13      24      19      17     317       4
        MIR_6_K:       -       -       1      10       2      17      15       7     164       1
       MIR_6_KL:       -       -       -       2       -       1       1       2       5       -
        MIR_6_R:       -       -       5      17      17      41      32      26     578      17
       MIR_6_RB:       1       2       4       5       5      19      20      29     685      14
      MIR_6_RBP:       -       -       -       -       -       8      10       3     177       4
   ZERO_HALF_FF:       2       3       9      17       6      44      22      48      58       7
    ZERO_HALF_K:       -       -       6      12       1       5       7      19       8       1
   ZERO_HALF_KL:       -       -       1       5       -       -       -       4       -       -
    ZERO_HALF_R:       5       7      23      13      24      59      22      23     151      20
   ZERO_HALF_RB:       2       5      16       3      12      22      11       4      78       8
  ZERO_HALF_RBP:       -       -       3       1       1       2       1       -      10       1

LNS stats           Improv/Calls  Closed  Difficulty  TimeLimit
  'graph_arc_lns':          3/11     45%        0.43       0.10
  'graph_cst_lns':          1/11     55%        0.65       0.10
  'graph_dec_lns':          5/11     55%        0.70       0.10
  'graph_var_lns':          2/11     45%        0.39       0.10
      'rins/rens':          5/10     50%        0.30       0.10
    'rnd_cst_lns':          3/11     55%        0.71       0.10
    'rnd_var_lns':          5/11     55%        0.72       0.10

LS stats                   Batches  Restarts  LinMoves  GenMoves  CompoundMoves  WeightUpdates
       'fj_long_default':       25         1   246'517         0              0          3'483
      'fj_short_default':       33         1         0    47'462         13'834             37
  'fj_short_lin_default':       33         1         0    47'278         12'469             36
          'violation_ls':       11         0     8'941     2'780             84         33'239

Solutions (12)      Num     Rank
           'core':    1    [1,1]
  'graph_arc_lns':    1  [11,11]
  'graph_dec_lns':    4   [6,12]
    'rins_lp_lns':    2    [4,5]
    'rnd_cst_lns':    2    [2,7]
    'rnd_var_lns':    2    [3,8]

Objective bounds                      Num
                   'initial_domain':    1
                           'max_lp':    1
  'objective_shaving_search_max_lp':   35
   'objective_shaving_search_no_lp':    1
                     'pseudo_costs':    2
                    'reduced_costs':    3

Solution repositories    Added  Queried  Ignored  Synchro
  'feasible solutions':     78      178        0       70
        'lp solutions':     51       12        0       48
                'pump':      0        0

Improving bounds shared       Num
                     'core':   23
               'default_lp':   13
  'fs_random_quick_restart':   14
           'lb_tree_search':    9
                   'max_lp':    4
                    'no_lp':    3
      'objective_lb_search':    7
                  'probing':  101
             'pseudo_costs':   41
            'quick_restart':    7
      'quick_restart_no_lp':    3
            'reduced_costs':   33

Clauses shared            Num
                 'core':   20
                'no_lp':    1
  'quick_restart_no_lp':    1

CpSolverResponse summary:
status: OPTIMAL
objective: 812818
best_bound: 812818
integers: 19596
booleans: 17361
conflicts: 0
branches: 34722
propagations: 722686
integer_propagations: 3033803
restarts: 34722
lp_iterations: 419
walltime: 822.21
usertime: 822.21
deterministic_time: 227.628
gap_integral: 38.8628
solution_fingerprint: 0x17f05885c08f3a00

@lperron
Copy link
Collaborator

lperron commented Jun 16, 2024 via email

@magneticflux-
Copy link
Author

I have a revelation to bring you: the entire issue disappears when I don't register a CpSolverSolutionCallback.

With default settings, 20 threads, main:
Registering a callback -> 13 minute solve
No callback -> 25 second solve

@lperron
Copy link
Collaborator

lperron commented Sep 27, 2024

I fixed it. It is a duplicate of #4376

@lperron lperron closed this as completed Sep 27, 2024
@Mizux Mizux added this to the v9.12 milestone Sep 28, 2024
Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment
Labels
Bug Lang: Java Java wrapper issue Solver: CP-SAT Solver Relates to the CP-SAT solver
Projects
None yet
Development

No branches or pull requests

3 participants