What happens during "Total elapsed time"?
Answered
Good 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!
0
-
Official comment
This post is more than three years old. Some information may not be up to date. For current information, please check the Gurobi Documentation or Knowledge Base. If you need more help, please create a new post in the community forum. Or why not try our AI Gurobot?. -
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
Post is closed for comments.
Comments
4 comments