What happens during "Total elapsed time"?
AnsweredGood morning!
I have noticed the following pattern in many of my models: after the root relaxation of my Binary Problem is solved (be it by Primal/Dual Simplex or Barrier), Gurobi takes some time before proceeding to Branch and Bound.
The only information logged is "Total elapsed time = x.xx s".
Usually, the log looks something like this:
Gurobi 9.0.1 (linux64) logging started Wed Jun 10 10:25:21 2020
Changed value of parameter LogFile to gurobi_20200609_1M_Freq_broadwell_driver.log
Prev: Default:
Gurobi Optimizer version 9.0.1 build v9.0.1rc0 (linux64)
Optimize a model with 369876 rows, 167606 columns and 17998440 nonzeros
Model fingerprint: 0x27291dc9
Variable types: 0 continuous, 167606 integer (167606 binary)
Coefficient statistics:
Matrix range [1e+00, 4e+00]
Objective range [1e+00, 1e+00]
Bounds range [1e+00, 1e+00]
RHS range [1e+00, 3e+00]
Found heuristic solution: objective -0.0000000
Presolve removed 35808 rows and 9367 columns (presolve time = 6s) ...
Presolve removed 49694 rows and 12284 columns (presolve time = 12s) ...
Presolve removed 49694 rows and 12289 columns (presolve time = 15s) ...
Presolve removed 57405 rows and 20000 columns (presolve time = 20s) ...
Presolve removed 68357 rows and 26927 columns (presolve time = 25s) ...
Presolve removed 73452 rows and 27237 columns (presolve time = 30s) ...
Presolve removed 75598 rows and 27252 columns (presolve time = 35s) ...
Presolve removed 76010 rows and 27455 columns (presolve time = 44s) ...
Presolve removed 76010 rows and 27455 columns (presolve time = 45s) ...
Presolve removed 76319 rows and 27551 columns (presolve time = 52s) ...
Presolve removed 76390 rows and 27622 columns (presolve time = 55s) ...
Presolve removed 76666 rows and 27716 columns (presolve time = 61s) ...
Presolve removed 76736 rows and 27782 columns (presolve time = 65s) ...
Presolve removed 81465 rows and 27825 columns (presolve time = 79s) ...
Presolve removed 81753 rows and 28159 columns (presolve time = 80s) ...
Presolve removed 81882 rows and 28288 columns (presolve time = 88s) ...
Presolve removed 81882 rows and 28288 columns (presolve time = 90s) ...
Presolve removed 82146 rows and 28288 columns (presolve time = 104s) ...
Presolve removed 82146 rows and 28288 columns (presolve time = 107s) ...
Presolve removed 81925 rows and 28067 columns
Presolve time: 107.35s
Presolved: 287951 rows, 139539 columns, 15641459 nonzeros
Found heuristic solution: objective 137.0000000
Variable types: 0 continuous, 139539 integer (139500 binary)
Deterministic concurrent LP optimizer: primal simplex, dual simplex, and barrier
Showing barrier log only...
Root barrier log...
Elapsed ordering time = 5s
Elapsed ordering time = 10s
Elapsed ordering time = 15s
Elapsed ordering time = 20s
Ordering time: 32.60s
Barrier statistics:
Dense cols : 860
AA' NZ : 8.171e+07
Factor NZ : 1.793e+08 (roughly 1.6 GBytes of memory)
Factor Ops : 1.824e+11 (roughly 1 second per iteration)
Threads : 10
Objective Residual
Iter Primal Dual Primal Dual Compl Time
0 1.34162560e+05 1.40847039e+04 2.38e+03 2.16e-01 2.01e+00 180s
1 1.02448527e+05 1.72060626e+04 1.80e+03 3.12e-01 1.50e+00 182s
2 4.56887579e+04 1.96264357e+04 8.12e+02 1.66e-01 7.01e-01 184s
3 1.97480541e+04 1.65909454e+04 3.36e+02 6.27e-02 3.06e-01 186s
4 9.46468754e+03 1.26775090e+04 1.45e+02 2.21e-02 1.35e-01 188s
5 4.70867274e+03 9.01592493e+03 5.83e+01 7.09e-03 5.58e-02 191s
6 2.52604180e+03 5.82995415e+03 1.88e+01 1.91e-03 1.90e-02 193s
7 1.61020677e+03 3.56413615e+03 2.17e+00 6.03e-04 5.29e-03 195s
8 1.52942558e+03 2.04349994e+03 5.66e-01 1.31e-04 1.25e-03 197s
9 1.50698101e+03 1.57653232e+03 3.72e-02 1.41e-05 1.53e-04 199s
10 1.50599852e+03 1.50619711e+03 5.02e-05 2.05e-08 3.99e-07 201s
11 1.50600000e+03 1.50600000e+03 2.05e-13 4.16e-13 1.57e-11 203s
Barrier solved model in 11 iterations and 203.26 seconds
Optimal objective 1.50600000e+03
Root crossover log...
137745 PPushes remaining with PInf 0.0000000e+00 205s
25059 PPushes remaining with PInf 0.0000000e+00 210s
11732 PPushes remaining with PInf 0.0000000e+00 215s
9806 PPushes remaining with PInf 0.0000000e+00 221s
8631 PPushes remaining with PInf 0.0000000e+00 226s
7615 PPushes remaining with PInf 0.0000000e+00 231s
6724 PPushes remaining with PInf 0.0000000e+00 236s
5985 PPushes remaining with PInf 0.0000000e+00 241s
5255 PPushes remaining with PInf 0.0000000e+00 246s
4575 PPushes remaining with PInf 0.0000000e+00 251s
3938 PPushes remaining with PInf 0.0000000e+00 256s
3332 PPushes remaining with PInf 0.0000000e+00 262s
2830 PPushes remaining with PInf 0.0000000e+00 267s
2458 PPushes remaining with PInf 0.0000000e+00 271s
1754 PPushes remaining with PInf 0.0000000e+00 279s
1395 PPushes remaining with PInf 0.0000000e+00 283s
1062 PPushes remaining with PInf 0.0000000e+00 287s
731 PPushes remaining with PInf 0.0000000e+00 291s
404 PPushes remaining with PInf 0.0000000e+00 296s
94 PPushes remaining with PInf 0.0000000e+00 300s
0 PPushes remaining with PInf 0.0000000e+00 302s
Push phase complete: Pinf 0.0000000e+00, Dinf 4.2624971e-10 302s
Root simplex log...
Iteration Objective Primal Inf. Dual Inf. Time
137748 1.5060000e+03 0.000000e+00 0.000000e+00 303s
137748 1.5060000e+03 0.000000e+00 0.000000e+00 305s
Concurrent spin time: 62.44s (can be avoided by choosing Method=3)
Solved with barrier
Root relaxation: objective 1.506000e+03, 137748 iterations, 254.92 seconds
Total elapsed time = 475.16s
Total elapsed time = 880.96s
Total elapsed time = 895.95s
Total elapsed time = 901.08s
Total elapsed time = 905.13s
Nodes | Current Node | Objective Bounds | Work
Expl Unexpl | Obj Depth IntInf | Incumbent BestBd Gap | It/Node Time
0 0 1506.00000 0 256 137.00000 1506.00000 999% - 911s
H 0 0 1505.0000000 1506.00000 0.07% - 913s
H 0 0 1506.0000000 1506.00000 0.00% - 915s
0 0 1506.00000 0 256 1506.00000 1506.00000 0.00% - 915s
Explored 1 nodes (239134 simplex iterations) in 915.71 seconds
Thread count was 24 (of 24 available processors)
Solution count 4: 1506 1505 137 -0
Optimal solution found (tolerance 1.00e-04)
Best objective 1.506000000000e+03, best bound 1.506000000000e+03, gap 0.0000%
In many cases, this is a significant time (here it is 430 seconds out of the total of 915 seconds, but at times it could be well in excess of 1000 seconds). I was wondering - what happens in that phase? Is there any way to make these processes shorter? Thanks in advance for your support!
-
Hi Jonasz - Most likely Gurobi is trying to improve the integrality of the current relaxation solution.
Can you try setting the parameter DegenMoves to 0, 1, or 2 and see if that improves the performance?
Thanks!
2 -
Hi Gwyneth,
This comment has been a gold mine for me. Working on a problem where the root node relaxation is very complicated to solve, but the solver spends little time solving the branch and bound tree, I always wondered how to remove the time spent between the root node and the start of the branching tree. Setting DegenMoves to 0 cut off about 2/3 of the time spent for solving my problem.
0 -
Hi Alexander - Glad we could help! Thanks for letting us know! Gwyneth
0
Please sign in to leave a comment.
Comments
3 comments