What happens after root relaxation has been solved? Long time before exploring further nodes according to log
Answered
Hello Gurobi Team!
I have a quick question: What happens in the MIP-log after the root node has been solved?
[I provide (parts of) the logfile and a screen shot below]
My intuition would be that the algorithm immediatley starts branching, however the number of "explored" and "unexplored nodes" remains 0 for quite a long time. At the same time however, the best bound of our minimization problem is drastically increasing. My assumption is that gurobi tests some general cutting plane algorithms in this phase to strengthen the best bound quickly?
My question is referring to the solid line ("full model") in the provided plot, and how this desirable increase of the best bound can be explained even though there is no progress on the number of explored nodes (in roughly the first 1500 seconds or so). But please also see log provided below. I shortened it to only depict the relevant part.
Looking forward to your help and thanks in advance!
Hendrik
Concurrent spin time: 211.04s
Solved with primal simplex (dual model)
Root relaxation: objective 0.000000e+00, 201519 iterations, 536.25 seconds
Total elapsed time = 633.07s
Total elapsed time = 656.46s
Total elapsed time = 670.98s
Total elapsed time = 677.84s
Nodes | Current Node | Objective Bounds | Work
Expl Unexpl | Obj Depth IntInf | Incumbent BestBd Gap | It/Node Time
0 0 0.00000 0 6404 - 0.00000 - - 682s
0 0 58.60904 0 5418 - 58.60904 - - 857s
0 0 59.10039 0 5595 - 59.10039 - - 863s
0 0 59.10039 0 5563 - 59.10039 - - 865s
0 0 68.30880 0 5559 - 68.30880 - - 898s
0 0 68.71430 0 5528 - 68.71430 - - 912s
0 0 68.71728 0 5376 - 68.71728 - - 921s
0 0 72.54779 0 5483 - 72.54779 - - 942s
0 0 73.30517 0 5455 - 73.30517 - - 958s
0 0 73.31335 0 5478 - 73.31335 - - 963s
0 0 76.36053 0 5542 - 76.36053 - - 993s
0 0 77.46796 0 5550 - 77.46796 - - 1021s
0 0 77.52343 0 5405 - 77.52343 - - 1026s
0 0 77.52710 0 5378 - 77.52710 - - 1029s
0 0 79.12081 0 5723 - 79.12081 - - 1051s
0 0 79.20448 0 5706 - 79.20448 - - 1063s
0 0 79.20749 0 5581 - 79.20749 - - 1068s
0 0 79.99996 0 5930 - 79.99996 - - 1100s
0 0 80.05979 0 5908 - 80.05979 - - 1112s
0 0 80.11139 0 5886 - 80.11139 - - 1121s
0 0 80.11412 0 5692 - 80.11412 - - 1123s
0 0 80.22920 0 5792 - 80.22920 - - 1136s
0 0 80.24145 0 5749 - 80.24145 - - 1146s
0 0 80.38522 0 5854 - 80.38522 - - 1168s
0 0 80.41165 0 5635 - 80.41165 - - 1176s
0 0 80.41211 0 5545 - 80.41211 - - 1179s
0 0 80.48658 0 5861 - 80.48658 - - 1191s
0 0 80.49254 0 5595 - 80.49254 - - 1197s
0 0 80.50981 0 5587 - 80.50981 - - 1211s
0 0 80.50981 0 2947 - 80.50981 - - 1234s
0 2 80.50981 0 2601 - 80.50981 - - 1253s
1 4 88.53533 1 3271 - 80.57809 - 19002 1259s
3 8 97.23586 2 2709 - 82.87271 - 12770 1272s
7 14 108.42747 3 2435 - 84.56375 - 11011 1284s
13 20 108.98689 4 2330 - 84.56480 - 9175 1293s
19 26 112.03430 5 3235 - 84.56480 - 10565 1313s
25 32 118.97783 5 2040 - 84.56480 - 12468 1323s
31 38 120.38083 6 2073 - 84.56480 - 11388 1332s
37 44 121.35558 7 1944 - 84.56480 - 10785 1347s
43 50 123.45317 8 1914 - 84.56480 - 10740 1354s
49 59 123.80742 9 2086 - 84.56480 - 10129 1365s
58 68 127.49723 10 2260 - 84.56480 - 9216 1371s
67 79 132.05592 11 1977 - 84.56480 - 8569 1378s
78 87 132.65482 12 1917 - 84.56480 - 7903 1384s
86 97 133.95077 13 2072 - 84.56480 - 7568 1392s
96 103 134.15772 14 1918 - 84.56480 - 7122 1400s
102 120 134.52788 15 1958 - 84.56480 - 6859 1406s
119 137 141.50911 18 1926 - 84.56480 - 6261 1412s
136 159 141.77910 20 1772 - 84.56480 - 5827 1418s
158 183 147.83958 24 1446 - 84.56480 - 5277 1423s
182 214 152.90708 29 1320 - 84.56480 - 4807 1429s
213 238 158.60179 34 1479 - 84.56480 - 4310 1434s
237 276 159.12515 35 1499 - 84.56480 - 4061 1439s
275 316 161.99774 43 1480 - 84.56480 - 3635 1444s
315 363 164.94842 45 1784 - 84.56480 - 3301 1449s
364 416 164.20954 47 1397 - 84.56480 - 2946 1453s
417 474 165.80353 53 1480 - 84.56480 - 2669 1458s
477 537 175.70396 65 1405 - 84.56480 - 2424 1462s
540 629 172.54361 78 1314 - 84.56480 - 2196 1467s
632 721 173.24613 95 1302 - 84.56480 - 1910 1472s
728 796 174.49528 112 1231 - 84.56480 - 1701 1476s
805 872 176.31538 119 1142 - 84.56480 - 1583 1481s
885 941 177.00000 124 1110 - 84.56480 - 1496 1488s
964 1034 177.00000 130 1104 - 84.56480 - 1432 1492s
1069 1149 178.00000 143 974 - 84.56480 - 1326 1505s
1190 1265 178.00000 160 948 - 84.56480 - 1238 1510s
1318 1350 179.00000 175 904 - 84.56480 - 1158 1515s
1431 1459 179.00000 192 824 - 84.56480 - 1102 1521s
1548 1585 181.00000 207 758 - 84.56480 - 1046 1533s
1688 1712 182.10003 228 752 - 86.38603 - 998 1541s
1848 1784 93.40552 4 2664 - 86.38603 - 945 1550s
1945 1824 98.84531 5 3393 - 86.38603 - 933 1565s
2005 1886 101.43365 5 2533 - 86.38603 - 931 1576s
2075 1948 106.46388 7 2277 - 86.38603 - 929 1589s
2149 2006 108.39675 9 2391 - 86.38603 - 931 1598s
2232 2026 116.88810 10 2125 - 86.38603 - 927 1608s
-
Hi Hendrik,
Yes, Gurobi is processing the root node while printing those "0 0" lines. Here's an excerpt from our MIP Logging documentation:
Note that the explored node count often stays at 0 for an extended period. This means that the Gurobi MIP solver is processing the root node. The Gurobi solver can often expend a significant amount of effort on the root node, generating cutting planes and trying various heuristics in order to reduce the size of the subsequent branch-and-cut tree.
I hope that answers your question. To reduce the time spent in the root node and start with the branch-and-bound process earlier, you can try reducing the number of cuts being added to the problem via parameters Cuts and CutPasses.
Cheers,
Matthias1 -
Ah yes, thank you so much for the quick response. I probably should have read the documentation first :)
Thanks!
Hendrik0 -
Hi Matthias Miltenberger,
I'm running a model and it seems to be stuck at the same stage for a long time. What does that mean exactly? Did the model find a feasible solution?Thanks in advance!
Optimize a model with 443880 rows, 125280 columns and 86978853 nonzeros
Model fingerprint: 0x73f15bd1
Variable types: 0 continuous, 125280 integer (125280 binary)
Coefficient statistics:
Matrix range [1e+00, 5e+00]
Objective range [1e+00, 7e+02]
Bounds range [1e+00, 1e+00]
RHS range [1e+00, 3e+02]
Presolve removed 41398 rows and 70660 columns (presolve time = 6s) ...
Presolve removed 248410 rows and 70795 columns (presolve time = 10s) ...
Presolve removed 272651 rows and 70795 columns (presolve time = 15s) ...
Presolve removed 324353 rows and 77561 columns (presolve time = 20s) ...
Presolve removed 327660 rows and 77562 columns (presolve time = 25s) ...
Presolve removed 327660 rows and 77562 columns (presolve time = 30s) ...
Presolve removed 374148 rows and 82836 columns (presolve time = 35s) ...
Presolve removed 379194 rows and 82867 columns (presolve time = 40s) ...
Presolve removed 379250 rows and 82895 columns (presolve time = 45s) ...
Presolve removed 379250 rows and 82895 columns (presolve time = 50s) ...
Presolve removed 389075 rows and 82947 columns (presolve time = 55s) ...
Presolve removed 389075 rows and 82983 columns (presolve time = 60s) ...
Presolve removed 389181 rows and 83032 columns (presolve time = 65s) ...
Presolve removed 390498 rows and 83073 columns (presolve time = 70s) ...
Presolve removed 390498 rows and 83073 columns (presolve time = 75s) ...
Presolve removed 390787 rows and 83111 columns (presolve time = 80s) ...
Presolve removed 390799 rows and 83111 columns (presolve time = 85s) ...
Presolve removed 380919 rows and 73231 columns
Presolve time: 85.94s
Presolved: 62961 rows, 52049 columns, 8357376 nonzeros
Variable types: 0 continuous, 52049 integer (52022 binary)
Deterministic concurrent LP optimizer: primal simplex, dual simplex, and barrier
Showing barrier log only...
Root barrier log...
Barrier performed 0 iterations in 92.98 seconds (332.38 work units)
Barrier solve interrupted - model solved by another algorithm
Concurrent spin time: 0.32s (can be avoided by choosing Method=3)
Solved with dual simplex
Root simplex log...
Iteration Objective Primal Inf. Dual Inf. Time
2222 1.8998000e+04 0.000000e+00 0.000000e+00 93s
Root relaxation: objective 1.899800e+04, 2222 iterations, 2.26 seconds (4.49 work units)
Total elapsed time = 95.37s
Nodes | Current Node | Objective Bounds | Work
Expl Unexpl | Obj Depth IntInf | Incumbent BestBd Gap | It/Node Time
0 0 18998.0000 0 903 - 18998.0000 - - 98s
0 0 18998.0000 0 839 - 18998.0000 - - 103s
0 0 18998.0000 0 812 - 18998.0000 - - 105s
0 0 18998.0000 0 732 - 18998.0000 - - 112s
0 0 18998.0000 0 745 - 18998.0000 - - 113s
0 0 18998.0000 0 710 - 18998.0000 - - 120s
0 0 18998.0000 0 709 - 18998.0000 - - 121s
0 0 18998.0000 0 707 - 18998.0000 - - 127s
0 0 18998.0000 0 713 - 18998.0000 - - 128s
0 0 18998.0000 0 695 - 18998.0000 - - 135s
0 0 18998.0000 0 695 - 18998.0000 - - 142s
0 2 18998.0000 0 695 - 18998.0000 - - 180s
39 24 18998.0000 7 717 - 18998.0000 - 287 185s
114 84 18998.0000 15 710 - 18998.0000 - 132 190s
228 136 18998.0000 27 710 - 18998.0000 - 76.0 197s
282 183 infeasible 33 - 18998.0000 - 69.2 202s
385 278 18998.0000 40 709 - 18998.0000 - 67.5 209s
533 316 infeasible 52 - 18998.0000 - 60.6 217s
672 386 19002.0580 61 733 - 18998.0000 - 65.6 227s
876 485 19005.0882 76 703 - 18998.0000 - 62.8 238s
1085 592 infeasible 94 - 18998.0000 - 59.6 249s
1299 729 19021.0000 107 680 - 18998.0000 - 58.2 261s
1561 858 19024.0250 129 685 - 18998.0000 - 53.9 274s
1813 1042 19077.0000 145 630 - 18998.0000 - 51.6 287s0 -
Hi Youssef,
Gurobi does not find a feasible solution to this model instance. You can see this from the \(\texttt{Incumbent}\) column and also that there is no gap - we need a primal solution (incumbent) and a dual bound (LP solution) to compute the gap.
You can play around with different settings, e.g., MIPFocus, Heuristics, NoRelHeurTime, to make Gurobi spend more time and effort finding solutions.
I hope that helps.
Cheers,
Matthias0
Please sign in to leave a comment.
Comments
4 comments