Interpreting the log file for the branch-and-cut tree search
Answered
Hi everyone,
I've been trying to solve a very large pure binary LP problem with no ('constant') objective function. After much experimentation I found parameters that vastly decreased the solution time of a smaller test problem. With these parameters I have been running my large problem for some 5 days now. I was wondering if any conclusions can be made about the progress (to find a single optimal solution) from the log file for the branch and search tree pasted below. I did not find the explanation on the Gurobi website for MIP logging very informative. I am happy to wait for a month or two to get a solution. I just want to make sure things don't look hopeless. (By the way - I am looking into 'tuning' the smaller model for a couple of days in case that gives me a better parameter set.)
Thank you,
Marcus Garvie.
Nodes | Current Node | Objective Bounds | Work
Expl Unexpl | Obj Depth IntInf | Incumbent BestBd Gap | It/Node Time
0 0 209.00000 0 4908 - 209.00000 - - 921s
0 0 209.00000 0 4913 - 209.00000 - - 2742s
0 0 209.00000 0 4900 - 209.00000 - - 3238s
0 0 209.00000 0 4933 - 209.00000 - - 4606s
0 0 209.00000 0 4924 - 209.00000 - - 5112s
0 0 209.00000 0 5128 - 209.00000 - - 6159s
0 0 209.00000 0 4612 - 209.00000 - - 6973s
0 0 209.00000 0 5038 - 209.00000 - - 7959s
0 0 209.00000 0 4920 - 209.00000 - - 8750s
0 0 209.00000 0 4958 - 209.00000 - - 10030s
0 0 209.00000 0 4948 - 209.00000 - - 10499s
0 0 209.00000 0 4988 - 209.00000 - - 11659s
0 0 209.00000 0 4920 - 209.00000 - - 12128s
0 0 209.00000 0 5018 - 209.00000 - - 13183s
0 0 209.00000 0 4942 - 209.00000 - - 13718s
0 0 209.00000 0 5125 - 209.00000 - - 14689s
0 2 209.00000 0 5125 - 209.00000 - - 159750s
1 5 209.00000 1 5009 - 209.00000 - 8273 160239s
3 8 209.00000 2 5027 - 209.00000 - 7430 160975s
7 16 209.00000 3 5037 - 209.00000 - 7339 161828s
15 26 209.00000 4 4961 - 209.00000 - 9060 163644s
25 36 209.00000 5 5031 - 209.00000 - 14507 163736s
35 46 209.00000 5 5024 - 209.00000 - 11711 163833s
45 56 209.00000 6 5044 - 209.00000 - 10103 163906s
55 70 209.00000 6 5026 - 209.00000 - 8747 164033s
69 89 209.00000 7 5042 - 209.00000 - 7799 164133s
88 105 209.00000 8 5041 - 209.00000 - 6613 164244s
104 165 209.00000 9 5046 - 209.00000 - 6149 164591s
164 286 209.00000 11 5045 - 209.00000 - 5065 165382s
285 521 209.00000 16 5005 - 209.00000 - 4481 166999s
520 738 209.00000 29 4904 - 209.00000 - 4390 168607s
737 923 209.00000 38 4838 - 209.00000 - 4484 170349s
922 1113 209.00000 50 4810 - 209.00000 - 4840 172089s
1116 1305 209.00000 61 4816 - 209.00000 - 5111 173903s
1308 1473 209.00000 66 4590 - 209.00000 - 5393 176768s
1476 1642 209.00000 67 4614 - 209.00000 - 5632 178917s
1645 1804 209.00000 71 4590 - 209.00000 - 5994 182544s
1807 1970 209.00000 74 4597 - 209.00000 - 6294 185149s
1973 2116 209.00000 77 4600 - 209.00000 - 6607 188706s
2121 2271 209.00000 78 4597 - 209.00000 - 6800 191097s
2276 2426 209.00000 80 4604 - 209.00000 - 7070 193963s
2431 2541 209.00000 84 4584 - 209.00000 - 7417 196756s
2548 2635 209.00000 86 4561 - 209.00000 - 7651 199034s
2642 2758 209.00000 87 4567 - 209.00000 - 7716 203105s
2765 2858 209.00000 88 4566 - 209.00000 - 7955 207474s
2865 2928 209.00000 90 4571 - 209.00000 - 8224 211357s
2935 3008 209.00000 92 4492 - 209.00000 - 8475 219566s
3015 3082 209.00000 94 4516 - 209.00000 - 8762 227684s
3089 3150 209.00000 96 4473 - 209.00000 - 9219 250004s
3157 3212 209.00000 99 4472 - 209.00000 - 9567 254023s
3221 3272 209.00000 100 4439 - 209.00000 - 9575 258520s
3281 3324 209.00000 104 4407 - 209.00000 - 9837 327066s
3335 3369 209.00000 105 4418 - 209.00000 - 10571 331467s
3380 3424 209.00000 108 4408 - 209.00000 - 10711 336330s
3435 3470 209.00000 111 4395 - 209.00000 - 10866 422490s
3481 3542 209.00000 114 4358 - 209.00000 - 11622 425978s
3555 3603 209.00000 116 4383 - 209.00000 - 11539 435370s
-
Hi Marcus,
It's not too easy to give advice just by seeing this (incomplete) log file. Could you please edit your post and also include the problem statistics from the beginning?
What I noticed is that the node throughput is pretty bad, most likely due to the relatively high iteration count per node (second to last column). Root node processing is also taking quite a long time, so you might try disabling cutting planes - especially since there is no objective function to guide the process.
Judging by the number of integer infeasibilities, your shared log does not seem to be close to being finished with the optimization.
You might want to give the NoRel heuristic a shot (NoRelHeurTime).
It could also very well be that this is simply a very hard problem that is not solvable in an acceptable time frame.
Best regards,
Matthias0 -
Hi Mathias,
thank you for your comments. Yes I do know that the problem I am trying to solve was deliberately constructed to be difficult. When you suggest disabling cutting planes do you mean set Cuts=0 ? What value do you suggest for the NoRelHeurTime? I have included the full (up-to-date) log file below.
Marcus.
PS I should mention that although the natural objective function for my problem is zero, I found improved performance by adding an 'artificial' objective function equal to the sum of the variables (which I know for a feasible solution is 209).
marcusgarvie@Marcuss-MacBook-Pro LPfiles % gurobi_cl ResultFile=subregion6_alt.sol SolutionLimit=1 Method=3 MIPFocus=1 Heuristics=1 subregion6_alt.lpSet parameter UsernameSet parameter SolutionLimit to value 1Set parameter Method to value 3Set parameter Heuristics to value 1Set parameter MIPFocus to value 1Set parameter LogFile to value "gurobi.log"Gurobi Optimizer version 9.5.0Read LP format model from file subregion6_alt.lpReading time = 7.84 secondsObj: 7733 rows, 1372296 columns, 50774952 nonzerosThread count: 10 physical cores, 10 logical processors, using up to 10 threadsOptimize a model with 7733 rows, 1372296 columns and 50774952 nonzerosModel fingerprint: 0x789d375fVariable types: 0 continuous, 1372296 integer (1372296 binary)Coefficient statistics:Matrix range [1e+00, 1e+00]Objective range [1e+00, 1e+00]Bounds range [1e+00, 1e+00]RHS range [1e+00, 1e+00]Presolve removed 96 rows and 0 columns (presolve time = 6s) ...Presolve removed 96 rows and 97704 columns (presolve time = 10s) ...Presolve removed 96 rows and 97704 columns (presolve time = 15s) ...Presolve removed 96 rows and 97704 columns (presolve time = 20s) ...Presolve removed 96 rows and 97704 columns (presolve time = 25s) ...Presolve removed 504 rows and 97704 columns (presolve time = 30s) ...Presolve removed 504 rows and 97704 columns (presolve time = 35s) ...Presolve removed 504 rows and 97704 columns (presolve time = 40s) ...Presolve removed 504 rows and 97704 columns (presolve time = 45s) ...Presolve removed 504 rows and 97704 columns (presolve time = 51s) ...Presolve removed 504 rows and 97704 columnsPresolve time: 52.18sPresolved: 7229 rows, 1274592 columns, 46970412 nonzerosVariable types: 0 continuous, 1274592 integer (1274592 binary)Concurrent LP optimizer: primal simplex, dual simplex, and barrierShowing barrier log only...Root barrier log...Ordering time: 0.03sBarrier statistics:AA' NZ : 1.412e+06Factor NZ : 3.275e+06 (roughly 500 MB of memory)Factor Ops : 2.402e+09 (less than 1 second per iteration)Threads : 8Objective ResidualIter Primal Dual Primal Dual Compl Time0 8.56184000e+04 2.09000000e+02 7.52e+02 8.52e-14 2.50e-03 86s1 9.91639026e+02 1.98823220e+02 6.89e+00 8.88e-16 2.68e-05 87s2 2.47693217e+02 2.01312109e+02 3.41e-01 6.66e-16 3.97e-06 87s3 2.09000000e+02 2.08252626e+02 4.23e-14 9.99e-16 2.93e-07 88s4 2.09000000e+02 2.08999253e+02 1.10e-13 8.88e-16 2.93e-10 88s5 2.09000000e+02 2.09000000e+02 1.14e-13 7.99e-16 2.95e-16 89sBarrier solved model in 5 iterations and 88.94 seconds (188.88 work units)Optimal objective 2.09000000e+02Building initial crossover basis 102sBuilding initial crossover basis 105sBuilding initial crossover basis 111sBuilding initial crossover basis 115sRoot crossover log...3420 variables added to crossover basis 120s289 DPushes remaining with DInf 0.0000000e+00 124s0 DPushes remaining with DInf 0.0000000e+00 125s1 PPushes remaining with PInf 0.0000000e+00 125s0 PPushes remaining with PInf 0.0000000e+00 125sPush phase complete: Pinf 0.0000000e+00, Dinf 2.1177851e-09 125sRoot simplex log...Iteration Objective Primal Inf. Dual Inf. Time128 2.0900000e+02 0.000000e+00 0.000000e+00 125s128 2.0900000e+02 0.000000e+00 0.000000e+00 126sSolved with barrierRoot relaxation: objective 2.090000e+02, 128 iterations, 64.40 seconds (98.46 work units)Nodes | Current Node | Objective Bounds | WorkExpl Unexpl | Obj Depth IntInf | Incumbent BestBd Gap | It/Node Time0 0 209.00000 0 4908 - 209.00000 - - 921s0 0 209.00000 0 4913 - 209.00000 - - 2742s0 0 209.00000 0 4900 - 209.00000 - - 3238s0 0 209.00000 0 4933 - 209.00000 - - 4606s0 0 209.00000 0 4924 - 209.00000 - - 5112s0 0 209.00000 0 5128 - 209.00000 - - 6159s0 0 209.00000 0 4612 - 209.00000 - - 6973s0 0 209.00000 0 5038 - 209.00000 - - 7959s0 0 209.00000 0 4920 - 209.00000 - - 8750s0 0 209.00000 0 4958 - 209.00000 - - 10030s0 0 209.00000 0 4948 - 209.00000 - - 10499s0 0 209.00000 0 4988 - 209.00000 - - 11659s0 0 209.00000 0 4920 - 209.00000 - - 12128s0 0 209.00000 0 5018 - 209.00000 - - 13183s0 0 209.00000 0 4942 - 209.00000 - - 13718s0 0 209.00000 0 5125 - 209.00000 - - 14689s0 2 209.00000 0 5125 - 209.00000 - - 159750s1 5 209.00000 1 5009 - 209.00000 - 8273 160239s3 8 209.00000 2 5027 - 209.00000 - 7430 160975s7 16 209.00000 3 5037 - 209.00000 - 7339 161828s15 26 209.00000 4 4961 - 209.00000 - 9060 163644s25 36 209.00000 5 5031 - 209.00000 - 14507 163736s35 46 209.00000 5 5024 - 209.00000 - 11711 163833s45 56 209.00000 6 5044 - 209.00000 - 10103 163906s55 70 209.00000 6 5026 - 209.00000 - 8747 164033s69 89 209.00000 7 5042 - 209.00000 - 7799 164133s88 105 209.00000 8 5041 - 209.00000 - 6613 164244s104 165 209.00000 9 5046 - 209.00000 - 6149 164591s164 286 209.00000 11 5045 - 209.00000 - 5065 165382s285 521 209.00000 16 5005 - 209.00000 - 4481 166999s520 738 209.00000 29 4904 - 209.00000 - 4390 168607s737 923 209.00000 38 4838 - 209.00000 - 4484 170349s922 1113 209.00000 50 4810 - 209.00000 - 4840 172089s1116 1305 209.00000 61 4816 - 209.00000 - 5111 173903s1308 1473 209.00000 66 4590 - 209.00000 - 5393 176768s1476 1642 209.00000 67 4614 - 209.00000 - 5632 178917s1645 1804 209.00000 71 4590 - 209.00000 - 5994 182544s1807 1970 209.00000 74 4597 - 209.00000 - 6294 185149s1973 2116 209.00000 77 4600 - 209.00000 - 6607 188706s2121 2271 209.00000 78 4597 - 209.00000 - 6800 191097s2276 2426 209.00000 80 4604 - 209.00000 - 7070 193963s2431 2541 209.00000 84 4584 - 209.00000 - 7417 196756s2548 2635 209.00000 86 4561 - 209.00000 - 7651 199034s2642 2758 209.00000 87 4567 - 209.00000 - 7716 203105s2765 2858 209.00000 88 4566 - 209.00000 - 7955 207474s2865 2928 209.00000 90 4571 - 209.00000 - 8224 211357s2935 3008 209.00000 92 4492 - 209.00000 - 8475 219566s3015 3082 209.00000 94 4516 - 209.00000 - 8762 227684s3089 3150 209.00000 96 4473 - 209.00000 - 9219 250004s3157 3212 209.00000 99 4472 - 209.00000 - 9567 254023s3221 3272 209.00000 100 4439 - 209.00000 - 9575 258520s3281 3324 209.00000 104 4407 - 209.00000 - 9837 327066s3335 3369 209.00000 105 4418 - 209.00000 - 10571 331467s3380 3424 209.00000 108 4408 - 209.00000 - 10711 336330s3435 3470 209.00000 111 4395 - 209.00000 - 10866 422490s3481 3542 209.00000 114 4358 - 209.00000 - 11622 425978s3555 3603 209.00000 116 4383 - 209.00000 - 11539 435370s3616 3646 209.00000 117 4379 - 209.00000 - 11825 514786s3663 3731 209.00000 120 4367 - 209.00000 - 12570 520098s3750 3802 209.00000 123 4387 - 209.00000 - 12725 529575s3821 3864 209.00000 125 4395 - 209.00000 - 12903 561905s3883 3923 209.00000 126 4362 - 209.00000 - 13245 600795s3944 3998 209.00000 128 4380 - 209.00000 - 13676 605973s0 -
Hi Marcus,
You are trying to solve a feasibility problem and apparently a pretty hard one. As you can see from the node log, there is no visible progress and you might be still very far away from a solution. I suggest focussing on heuristics for this model, so MIPFOCUS=1 or Heuristics=0.2.
Yes, Cuts=0 disables cutting planes and is the parameter I was referring to earlier.
Since you don't have a meaningful objective, it is difficult to guide Gurobi towards a solution using some parameter settings.
If your deliberate goal was to come up with a hard model instance, then I guess you succeeded :-)
Cheers,
Matthias0 -
Hi Matthias,
we didn't deliberately construct a hard model. After a years' worth of work we managed to convert the Eternity puzzle into an LP problem. This is a notoriously difficult tiling problem. You say that there is 'no visible progress' in the node log. Which column of data is telling you this and why?
Thank you,
Marcus.
0 -
Hi Marcus,
Well, the first column shows the number of explored nodes, while the second shows the number of yet to be inspected nodes. It looks like the numbers are still increasing, so there is no end in sight, yet.
The column that counts the integer infeasibilities is also not decreasing significantly.
And to make matters worse, the node throughput is very bad with every (later) new line in the log (roughly 100 nodes) taking several hours.
By the way, I was only quoting you concerning the difficulty of the problem:
"Yes I do know that the problem I am trying to solve was deliberately constructed to be difficult."And I suppose the no-free-lunch-theorem also applies here: reformulating the problem does not necessarily make it any easier to solve.
Cheers,
Matthias0 -
Thank you Matthias,
that is very helpful. So as I explore the effect of different parameter sets I know what to look for.
Best,
Marcus.
0
Please sign in to leave a comment.
Comments
6 comments