MIP Logging
The MIP log can be divided into three sections: the presolve section, the simplex progress section, and the summary section.
Presolve Section
As with the simplex and barrier logs, the first section of the MIP log
is the presolve section. Here is presolve output for MIPLIB model
mas76:
Presolve removed 0 rows and 3 columns Presolve time: 0.01s Presolved: 12 rows, 148 columns, 1615 nonzerosIn this example, presolve was able to remove 3 columns. The final line shows the size of the model that is passed to the branch-and-cut algorithm.
Progress Section
The next section in the MIP log tracks the progress of the
branch-and-cut search. The search involves a number of different
steps, so this section typically contains a lot of detailed
information. The first thing to observe in the log for example
mas76 is these lines:
Found heuristic solution: objective 157344.61033 Found heuristic solution: objective 157344.61033These indicate that the Gurobi heuristics found three integer feasible solutions before the root relaxation was solved.
The next thing you will see in the log is the root relaxation solution display. For a model where the root solves quickly, this display contains a single line:
Root relaxation: objective 3.889390e+04, 50 iterations, 0.00 seconds
For models where the root relaxation takes more time (MIPLIB model
dano3mip, for example), the Gurobi solver will automatically
include a detailed simplex log for the relaxation itself:
Root simplex log... Iteration Objective Primal Inf. Dual Inf. Time 15338 5.7472018e+02 6.953458e+04 0.000000e+00 5s 19787 5.7623162e+02 0.000000e+00 0.000000e+00 7s Root relaxation: objective 5.762316e+02, 19787 iterations, 6.18 secondsTo be more precise, this more detailed log is triggered whenever the root relaxation requires more than the DisplayInterval parameter value (5 seconds by default).
The next section provides progress information on the branch-and-cut tree search:
Nodes | Current Node | Objective Bounds | Work
Expl Unexpl | Obj Depth IntInf | Incumbent BestBd Gap | It/Node Time
0 0 38893.9036 0 11 157344.610 38893.9036 75.3% - 0s
H 0 0 80297.610430 38893.9036 51.6% - 0s
H 0 0 60361.518931 38893.9036 35.6% - 0s
H 0 0 41203.601476 38893.9036 5.61% - 0s
0 0 38923.3264 0 12 41203.6015 38923.3264 5.53% - 0s
0 0 38923.3264 0 12 41203.6015 38923.3264 5.53% - 0s
H 0 0 40697.054142 38923.3264 4.36% - 0s
0 0 38923.3264 0 13 40697.0541 38923.3264 4.36% - 0s
H 0 0 40005.054142 38923.3264 2.70% - 0s
0 0 38923.3264 0 15 40005.0541 38923.3264 2.70% - 0s
0 0 38964.7042 0 13 40005.0541 38964.7042 2.60% - 0s
0 0 38999.8237 0 14 40005.0541 38999.8237 2.51% - 0s
0 0 39005.7057 0 16 40005.0541 39005.7057 2.50% - 0s
0 0 39005.7057 0 16 40005.0541 39005.7057 2.50% - 0s
0 0 39005.7057 0 12 40005.0541 39005.7057 2.50% - 0s
0 0 39005.7057 0 14 40005.0541 39005.7057 2.50% - 0s
0 0 39005.7057 0 16 40005.0541 39005.7057 2.50% - 0s
0 0 39005.7057 0 16 40005.0541 39005.7057 2.50% - 0s
0 0 39005.7057 0 17 40005.0541 39005.7057 2.50% - 0s
0 0 39005.7057 0 18 40005.0541 39005.7057 2.50% - 0s
0 0 39005.7057 0 16 40005.0541 39005.7057 2.50% - 0s
0 0 39005.7057 0 16 40005.0541 39005.7057 2.50% - 0s
0 0 39005.7057 0 16 40005.0541 39005.7057 2.50% - 0s
0 0 39005.7057 0 17 40005.0541 39005.7057 2.50% - 0s
0 0 39005.7057 0 18 40005.0541 39005.7057 2.50% - 0s
0 0 39005.7057 0 16 40005.0541 39005.7057 2.50% - 0s
0 0 39005.7057 0 18 40005.0541 39005.7057 2.50% - 0s
0 0 39005.7057 0 18 40005.0541 39005.7057 2.50% - 0s
0 0 39005.7057 0 19 40005.0541 39005.7057 2.50% - 0s
0 0 39005.7057 0 18 40005.0541 39005.7057 2.50% - 0s
0 0 39005.7057 0 20 40005.0541 39005.7057 2.50% - 0s
0 0 39005.7057 0 17 40005.0541 39005.7057 2.50% - 0s
0 0 39005.7057 0 19 40005.0541 39005.7057 2.50% - 0s
0 0 39005.7057 0 20 40005.0541 39005.7057 2.50% - 0s
0 0 39005.7057 0 21 40005.0541 39005.7057 2.50% - 0s
0 0 39005.7057 0 22 40005.0541 39005.7057 2.50% - 0s
0 0 39005.7057 0 18 40005.0541 39005.7057 2.50% - 0s
0 0 39005.7057 0 15 40005.0541 39005.7057 2.50% - 0s
0 0 39005.7057 0 17 40005.0541 39005.7057 2.50% - 0s
0 0 39005.7057 0 19 40005.0541 39005.7057 2.50% - 0s
0 0 39005.7057 0 18 40005.0541 39005.7057 2.50% - 0s
0 0 39005.7057 0 19 40005.0541 39005.7057 2.50% - 0s
0 0 39005.7057 0 18 40005.0541 39005.7057 2.50% - 0s
0 0 39005.7057 0 19 40005.0541 39005.7057 2.50% - 0s
0 0 39005.7057 0 19 40005.0541 39005.7057 2.50% - 0s
0 0 39005.7057 0 19 40005.0541 39005.7057 2.50% - 0s
0 0 39005.7057 0 20 40005.0541 39005.7057 2.50% - 0s
0 0 39005.7057 0 21 40005.0541 39005.7057 2.50% - 0s
0 0 39005.7057 0 20 40005.0541 39005.7057 2.50% - 0s
0 0 39005.7057 0 20 40005.0541 39005.7057 2.50% - 0s
0 0 39005.7057 0 20 40005.0541 39005.7057 2.50% - 0s
0 0 39005.7057 0 19 40005.0541 39005.7057 2.50% - 0s
0 0 39005.7057 0 20 40005.0541 39005.7057 2.50% - 0s
0 0 39005.7057 0 20 40005.0541 39005.7057 2.50% - 0s
0 0 39005.7057 0 20 40005.0541 39005.7057 2.50% - 0s
0 0 39005.7057 0 20 40005.0541 39005.7057 2.50% - 0s
0 0 39005.7057 0 20 40005.0541 39005.7057 2.50% - 0s
0 0 39005.7057 0 21 40005.0541 39005.7057 2.50% - 0s
0 0 39005.7057 0 21 40005.0541 39005.7057 2.50% - 0s
0 0 39005.7057 0 21 40005.0541 39005.7057 2.50% - 0s
0 0 39005.7057 0 20 40005.0541 39005.7057 2.50% - 0s
0 0 39020.4019 0 17 40005.0541 39020.4019 2.46% - 0s
0 0 39022.9528 0 18 40005.0541 39022.9528 2.45% - 0s
0 0 39026.2521 0 19 40005.0541 39026.2521 2.45% - 0s
0 0 39026.6391 0 19 40005.0541 39026.6391 2.45% - 0s
0 0 39028.3182 0 18 40005.0541 39028.3182 2.44% - 0s
0 0 39028.4511 0 19 40005.0541 39028.4511 2.44% - 0s
0 0 39028.8846 0 20 40005.0541 39028.8846 2.44% - 0s
0 0 39029.6078 0 20 40005.0541 39029.6078 2.44% - 0s
0 0 39029.6541 0 20 40005.0541 39029.6541 2.44% - 0s
0 0 39035.1012 0 21 40005.0541 39035.1012 2.42% - 0s
0 0 39035.3898 0 21 40005.0541 39035.3898 2.42% - 0s
0 0 39035.8084 0 21 40005.0541 39035.8084 2.42% - 0s
0 0 39036.8876 0 20 40005.0541 39036.8876 2.42% - 0s
0 0 39038.4573 0 21 40005.0541 39038.4573 2.42% - 0s
0 0 39038.6338 0 21 40005.0541 39038.6338 2.42% - 0s
0 0 39039.6058 0 21 40005.0541 39039.6058 2.41% - 0s
0 0 39040.2064 0 20 40005.0541 39040.2064 2.41% - 0s
0 0 39040.3540 0 21 40005.0541 39040.3540 2.41% - 0s
0 0 39040.4766 0 22 40005.0541 39040.4766 2.41% - 0s
0 0 39040.5673 0 22 40005.0541 39040.5673 2.41% - 0s
0 0 39040.8083 0 22 40005.0541 39040.8083 2.41% - 0s
0 0 39041.3800 0 21 40005.0541 39041.3800 2.41% - 0s
0 0 39043.7172 0 19 40005.0541 39043.7172 2.40% - 0s
0 0 39046.4067 0 20 40005.0541 39046.4067 2.40% - 0s
0 0 39046.6600 0 20 40005.0541 39046.6600 2.40% - 0s
0 0 39048.6126 0 20 40005.0541 39048.6126 2.39% - 0s
0 0 39049.1237 0 20 40005.0541 39049.1237 2.39% - 0s
0 0 39049.3336 0 20 40005.0541 39049.3336 2.39% - 0s
0 0 39050.2689 0 19 40005.0541 39050.2689 2.39% - 0s
0 0 39051.6844 0 21 40005.0541 39051.6844 2.38% - 0s
0 0 39053.2361 0 21 40005.0541 39053.2361 2.38% - 0s
0 0 39056.1733 0 19 40005.0541 39056.1733 2.37% - 0s
0 0 39056.5864 0 23 40005.0541 39056.5864 2.37% - 0s
0 0 39057.8000 0 21 40005.0541 39057.8000 2.37% - 0s
0 0 39057.9275 0 22 40005.0541 39057.9275 2.37% - 0s
0 0 39059.5673 0 22 40005.0541 39059.5673 2.36% - 0s
0 0 39059.6371 0 22 40005.0541 39059.6371 2.36% - 0s
0 0 39060.2217 0 23 40005.0541 39060.2217 2.36% - 0s
0 0 39060.5357 0 23 40005.0541 39060.5357 2.36% - 0s
0 0 39060.9630 0 23 40005.0541 39060.9630 2.36% - 0s
0 0 39061.4627 0 23 40005.0541 39061.4627 2.36% - 0s
0 0 39061.6644 0 24 40005.0541 39061.6644 2.36% - 0s
0 0 39062.7863 0 24 40005.0541 39062.7863 2.36% - 0s
0 0 39063.7989 0 25 40005.0541 39063.7989 2.35% - 0s
0 0 39064.2288 0 26 40005.0541 39064.2288 2.35% - 0s
0 0 39064.4885 0 25 40005.0541 39064.4885 2.35% - 0s
0 0 39064.9344 0 24 40005.0541 39064.9344 2.35% - 0s
0 0 39065.3660 0 25 40005.0541 39065.3660 2.35% - 0s
0 0 39065.4597 0 25 40005.0541 39065.4597 2.35% - 0s
0 0 39065.7357 0 25 40005.0541 39065.7357 2.35% - 0s
0 2 39078.2121 0 25 40005.0541 39078.2121 2.32% - 0s
162637 30691 39979.1365 51 10 40005.0541 39744.2811 0.65% 5.6 5s
This display is somewhat dense with information, but each column is
hopefully fairly easy to understand. The Nodes section (the
first two columns) provides general quantitative information on the
progress of the search. The first column shows the number of
branch-and-cut nodes that have been explored to that point, while
the second shows the number of leaf nodes in the search tree that
remain unexplored. At times, there will be an H or *
character at the beginning of the output line. These indicate that a
new feasible solution has been found, either by a MIP heuristic
(H) or by branching (*).
The Current Node section provides information on the specific
node that was explored at that point in the branch-and-cut tree. It
shows the objective of the associated relaxation, the depth of that
node in the branch-and-cut tree, and the number of integer variables
that have non-integral values in the associated relaxation.
The Objective Bounds section provides information on the best
known objective value for a feasible solution (i.e., the objective
value of the current incumbent), and the current objective bound
provided by leaf nodes of the search tree. The optimal objective
value is always between these two values. The third column in this
section (Gap) shows the relative gap between the two objective
bounds. When this gap is smaller than the
MIPGap parameter,
optimization terminates.
The Work section of the log provides information on how much
work has been performed to that point. The first column shows the
average number of simplex iterations performed per node in the
branch-and-cut tree. The final column shows the elapsed time since
the solve began.
By default, the Gurobi MIP solver prints a log line every 5 seconds (although the interval can sometimes be longer for models with particularly time-consuming nodes). The interval between log lines can be adjusted with the DisplayInterval parameter (see the Parameter section of this document for more information).
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.
Summary Section
The third section in the log provides summary information once the MIP solver has finished:
Cutting planes: Gomory: 2 MIR: 14 Explored 241338 nodes (1336406 simplex iterations) in 6.57 seconds Thread count was 4 (of 4 available processors) Solution count 7: 40005.1 40697.1 41203.6 ... 157345 Optimal solution found (tolerance 1.00e-04) Best objective 4.000505414200e+04, best bound 4.000505414200e+04, gap 0.0000%In this example, the Gurobi solver required just over 11 seconds to solve the model to optimality, and it used two processors to do so (the processor count can be limited with the Threads parameter). The gap between the best feasible solution objective and the best bound is just under 0.01%, which produces an
Optimal
termination status, since the achieved gap is smaller than the default
MIPGap
parameter value.
