Logging#
The Gurobi Optimizer produces a log that allows you to track the
progress of the optimization. The Gurobi command-line tool and the
Gurobi Interactive Shell put the log to both the screen and to a file
named gurobi.log by default. The other interfaces just put the log
to the screen. Screen output can be controlled using the
OutputFlag parameter, and file output can be controlled
using the LogFile parameter.
Header#
When you solve a model, the first part of the resulting log contains basic information about the model you are solving and the machine you are solving it on. You will first see a line that looks like this:
Thread count: 4 physical cores, 8 logical processors, using up to 8 threads
This shows the number of physical cores and logical processors in the machine. The latter may be larger than the former due to Simultaneous Multi Threading (SMT), which allows one physical core to appear as multiple logical processors. This log line also shows the maximum number of threads that the solver will use in this instance. This depends on the number of (logical) processors in the machine, but also on the number requested (through the Threads parameter), and for some license types on the number enabled by your license.
Next you will see summary information about the model you are solving:
Optimize a model with 755 rows, 2756 columns and 8937 nonzeros
Model fingerprint: 0x22935346
Variable types: 0 continuous, 2756 integer (0 binary)
The first line shows the size of the model. The second shows the model fingerprint, which is a hash value that takes into account the values of all attributes of all components of the model. The intent is that models that differ in any way will most always have different fingerprints. The last log line above provides additional information about variable integrality (for MIP models).
The final portion of the header contains statistics about the constraint matrix:
Coefficient statistics:
Matrix range [1e+00, 1e+04]
Objective range [1e+00, 1e+04]
Bounds range [1e+00, 1e+00]
RHS range [1e+00, 1e+04]
This information gives a very rough indication of whether you can expect numerical issues when solving your model. Please consult the numerical guidelines section to learn more.
The format of the remainder of the log depends on the algorithm that is invoked (simplex, barrier, sifting, branch-and-cut, or IIS). We now describe the contents of the log for each.
Simplex Logging#
The simplex log can be divided into three sections: the presolve section, the simplex progress section, and the summary section.
Presolve Section#
The first thing the Gurobi Optimizer does when optimizing a model is to
apply a presolve algorithm in order to simplify the model. The first
section of the Gurobi log provides information on the extent to which
presolve succeeds in this effort. Consider the following example output
from NETLIB model dfl001:
Presolve removed 2349 rows and 3378 columns
Presolve time: 0.04s
Presolved: 3722 rows, 8852 columns, 30908 nonzeros
The example output shows that presolve was able to remove 2349 rows and 3378 columns, and it required 0.04 seconds. The final line in the presolve section shows the size of the model after presolve. This is size of the model that is passed to the simplex optimizer. Note that the solution that is computed for this model is automatically transformed into a solution for the original problem once simplex finishes (in a process often called uncrushing), but this uncrush step is transparent and produces no log output.
Progress Section#
The second section of the Gurobi simplex output provides information on the progress of the simplex method:
Iteration Objective Primal Inf. Dual Inf. Time
0 -2.4571000e+32 4.000000e+30 2.457100e+02 0s
18420 1.1265574e+07 1.655263e+03 0.000000e+00 5s
20370 1.1266393e+07 0.000000e+00 0.000000e+00 6s
The five columns in each output row show the number of simplex iterations performed to that point, the objective value for the current basis, the magnitude of the primal infeasibility for the current basis (computed as the sum of the absolute values of all constraint and bound violations), the magnitude of the dual infeasibility (computed as the sum of the absolute values of all dual constraint violations), and the amount of time expended to that point (measured using wall clock time). The default simplex algorithm in the Gurobi solver is dual simplex, which tries to maintain dual feasibility while performing simplex pivots to improve the objective. Thus, once the dual simplex algorithm has found a dual feasible basis, you will generally see a dual infeasibility value of zero. When the primal and dual infeasibilities both reach zero, the basis is optimal and optimization is complete.
By default, the Gurobi Optimizer produces a log line every 5 seconds. The frequency of log lines can be changed by modifying the DisplayInterval parameter (see the Parameters section of this document for more information).
Summary Section#
The third section of the simplex log provides summary information. It provides a summary of the work that the simplex algorithm performed, including the iteration count and the runtime, and it provides information on outcome of the optimization. The summary for a model that is solved to optimality would look like this:
Solved in 20370 iterations and 5.75 seconds
Optimal objective 1.126639304e+07
Other termination states produce different summaries. For example, a user interrupt would produce a summary that looks like:
Stopped in 7482 iterations and 3.41 seconds
Solve interrupted
Hitting a time limit would produce a summary that looks like:
Stopped in 18082 iterations and 5.00 seconds
Time limit reached
Barrier Logging#
The barrier log can be divided into five sections: the presolve section, the barrier preprocessing section, the barrier progress section, the crossover progress section, and the summary section.
Presolve Section#
As mentioned earlier, the first thing the Gurobi Optimizer does when
optimizing a model is to apply a presolve algorithm in order to
simplify the model. The first section of the Gurobi log provides
information on the extent to which presolve succeeds in this effort.
Consider the following example output from NETLIB model dfl001:
Presolve removed 2349 rows and 3378 columns
Presolve time: 0.04s
Presolved: 3722 rows, 8852 columns, 30908 nonzeros
The example output shows that presolve was able to remove 2349 rows and 3378 columns, and it required 0.04 seconds. The final line in the presolve section shows the size of the model after presolve. This is size of the model that is passed to the barrier optimizer. Note that the solution that is computed for this model is automatically transformed into a solution for the original problem once barrier finishes (in a process often called uncrushing), but this uncrush step is transparent and produces no log output.
Barrier Preprocessing Section#
The factor matrix for the linear system solved in each iteration of the barrier method can be quite large and quite expensive to compute. In order to reduce the cost of this computation, the first step of the barrier algorithm is to compute a fill-reducing reordering of the rows and columns of this matrix. This step can be quite expensive, but the cost is recouped in the lower cost of the subsequent barrier iterations.
Once this fill-reducing reordering has been computed, the Gurobi Optimizer outputs information related to the barrier factor matrix:
Barrier statistics:
AA' NZ : 3.657e+04
Factor NZ : 8.450e+05 (roughly 12 MBytes of memory)
Factor Ops : 3.944e+08 (less than 1 second per iteration)
Threads : 8
The First line shows the number of off-diagonal entries in the lower triangle of \(AA^T\). A scaled version of this matrix is factored in each iteration of the barrier algorithm, so the structure of the Cholesky factor depends on the structure of \(AA^T\).
The next two lines indicate the number of non-zero values in the factor matrix, and the number of floating-point operations required to factor it. Note that the log also provides an estimate of how much memory will be needed by the barrier algorithm, and how long each barrier iteration will require: These are rough estimates that are meant to provide a general sense of how difficult the model will be to solve. If you want to obtain an estimate of overall solution time, note that most models achieve convergence in roughly 50 iterations, but there are many exceptions. Crossover runtime is typically comparable to the cost of a few barrier iterations, but this time can vary considerably, depending on the model characteristics.
The final line shows the number of threads that will be used to perform the barrier iterations.
You may sometimes see two other lines in this section:
Dense cols : 3
Free vars : 20
The first indicates how many columns from the constraint matrix were treated as dense. The second indicates how many variables in the model are free. Dense columns and free variables can sometimes lead to numerical difficulties in the barrier solver, so it is useful to know when they are present.
Progress Section#
The third section of the Gurobi barrier output provides information on the progress of the barrier method:
Objective Residual
Iter Primal Dual Primal Dual Compl Time
0 1.47340463e+12 -1.05838204e+09 1.49e+04 2.46e+02 1.94e+09 0s
1 6.13234163e+11 -3.97417254e+10 5.97e+03 5.98e+06 8.82e+08 0s
2 2.89634303e+11 -9.20268188e+10 2.54e+03 2.24e+06 3.81e+08 0s
3 6.57753936e+10 -9.40746258e+10 2.39e+02 2.87e+05 5.17e+07 0s
4 2.44710457e+10 -2.59852944e+10 3.16e+01 3.01e+04 9.00e+06 0s
5 6.74069830e+09 -1.78169224e+10 4.01e+00 2.01e+04 3.17e+06 0s
6 1.93163205e+09 -3.10778084e+09 2.46e-01 3.13e+03 5.62e+05 0s
7 6.54973737e+08 -6.89946649e+08 4.40e-02 5.35e+02 1.47e+05 0s
8 2.44764500e+08 -3.47987016e+08 1.47e-02 4.02e+02 6.46e+04 0s
9 1.35906001e+08 -1.41063037e+08 7.16e-03 1.66e+02 3.01e+04 0s
10 9.29132721e+07 -6.69973369e+07 4.58e-03 7.60e+01 1.73e+04 0s
The seven columns in each output row show the number of barrier iterations performed to that point, the primal and dual objective values for the current barrier iterate, the magnitude of the primal and dual infeasibilities for the current iterate (computed as the infinity-norms of the primal and dual residual vectors, respectively), the magnitude of the complementarity violation of the current primal and dual iterates (the dot product of the primal solution and the dual reduced cost vector), and the amount of time expended to that point (measured using wall clock time). When the primal infeasibility, dual infeasibility, and complementarity satisfy barrier convergence tolerances (controlled using the BarConvTol parameter), the solution is declared optimal and optimization is complete.
Unlike the simplex and MIP optimizers, the barrier optimizer produces a log line for each iterate, independent of the value of the DisplayInterval parameter.
You may sometimes see a star after the iteration count in the barrier progress log:
15 2.42800468e+03 8.54543324e+04 1.68e+02 1.02e-09 8.30e+04 0s
16 4.05292006e+03 4.65997441e+04 1.82e+02 2.50e-01 4.25e+04 0s
17* 4.88742259e+08 4.30781025e+10 5.17e+00 1.31e-01 2.52e-02 0s
18* 1.21709951e+06 3.39471138e+13 8.55e-06 3.14e-06 3.14e-05 0s
19* -1.38021972e+06 3.31580578e+16 3.42e-08 8.20e-09 3.22e-08 0s
20* 1.25182178e+06 3.31575855e+19 6.54e-12 7.34e-09 3.22e-11 0s
This indicates that the model may be primal or dual infeasible. Note that these intermediate indications of infeasibility won’t necessarily turn into an infeasibility proof, so the star may disappear in later iterations.
Crossover Section#
The fourth section of the barrier log provides information on the crossover step. This section is only present when crossover is selected (as controlled through the Crossover parameter. Crossover converts the interior point solution produced by the barrier algorithm to a basic solution.
The first stage in crossover is to push variables to bounds in order to obtain a valid basic solution. By default, this is done for dual variables first, then for primal variables. Progress of this phase is tracked with this portion of the crossover log…
Crossover log...
1610 DPushes remaining with DInf 0.0000000e+00 1s
0 DPushes remaining with DInf 0.0000000e+00 1s
144 PPushes remaining with PInf 5.7124800e-03 1s
0 PPushes remaining with PInf 5.7124800e-03 1s
Push phase complete: Pinf 5.7124800e-03, Dinf 8.1488315e-07 1s
Each line indicates how many push steps remain, the amount of infeasibility in the current solution, and the elapsed barrier time.
Upon completion of the push phase, crossover has a basic solution that isn’t necessarily optimal. The resulting basis is passed to simplex, and simplex completes the optimization…
Iteration Objective Primal Inf. Dual Inf. Time
1700 1.1266352e+07 5.712480e-03 0.000000e+00 1s
1868 1.1266393e+07 0.000000e+00 0.000000e+00 1s
The five columns in each output row of the simplex log show the number of simplex iterations performed to that point in the crossover algorithm (including the push steps), the objective value for the current basis, the magnitude of the primal infeasibility for the current basis (computed as the sum of the absolute values of all constraint and bound violations), the magnitude of the dual infeasibility (computed as the sum of the absolute values of all dual constraint violations), and the amount of time expended by the crossover algorithm to that point (measured using wall clock time). When the primal and dual infeasibilities both reach zero, the basis is optimal and optimization is complete.
Summary Section#
The final section of the barrier log provides summary information. It provides a summary of the work that the barrier algorithm performed, including the iteration count and the runtime, and it provides information on outcome of the optimization. The summary for a model that is solved to optimality would look like this:
Solved in 1868 iterations and 1.05 seconds
Optimal objective 1.126639304e+07
Other termination states produce different summaries. For example, a user interrupt would produce a summary that looks like:
Stopped in 7482 iterations and 3.41 seconds
Solve interrupted
Hitting a time limit would produce a summary that looks like:
Stopped in 9221 iterations and 5.00 seconds
Time limit exceeded
Sifting Logging#
Sifting will sometimes be used within the dual simplex method, either as a result of an automatic choice by the Gurobi Optimizer or because the user selected it through the Sifting parameter. The sifting log consists of three sections: the presolve section, the sifting progress section, and the summary section. The first and last are identical to those for simplex, so we’ll only discuss the middle section here.
Sifting Progress Section#
As we mentioned, output for sifting and dual simplex are indistinguishable until the progress section begins. For sifting, the progress section begins with a clear indication that sifting has been selected:
Starting sifting (using dual simplex for sub-problems)...
The sifting algorithm performs a number of major iterations, where each iteration solves a smaller LP sub-problem. It uses the result to update the current primal and dual solution. The sifting log prints one line per major iteration, with information on the current primal and dual objective values:
Iter Pivots Primal Obj Dual Obj Time
0 0 infinity 2.0000000e+01 11s
1 4662 1.5220652e+03 2.7034420e+02 12s
2 8917 1.3127217e+03 4.6530259e+02 13s
3 16601 1.1651147e+03 6.4767742e+02 17s
4 30060 1.0881514e+03 7.8842688e+02 29s
5 45169 1.0618879e+03 8.8656855e+02 46s
6 59566 1.0549766e+03 9.5404159e+02 64s
7 73614 1.0540577e+03 1.0172213e+03 82s
The first column in the log gives the major iteration number. The second shows the total number of simplex iterations performed in solving the sifting sub-problems. The third and fourth columns show the primal and dual objective values for the current solution. The final column shows elapsed runtime.
The completion of sifting is indicated with the following message:
Sifting complete
The basis computed by sifting is then handed back to dual simplex, and the log from that point forward comes from the dual simplex algorithm.
MIP Logging#
The MIP log can be divided into three sections: the presolve section, the 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 nonzeros
Variable types: 1 continuous, 147 integer (145 binary)
In this example, presolve was able to remove 3 columns. The last two lines show the size of the model that is passed to the branch-and-cut algorithm and the types of remaining variables.
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 this line:
Found heuristic solution: objective 157344.61033
It indicates that the Gurobi heuristics found an integer-feasible solution 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 seconds
To be more precise, this more detailed log is triggered whenever the time to solve the root relaxation exceeds 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 38939.3131 0 15 40005.0541 38939.3131 2.66% - 0s
0 0 38964.7042 0 13 40005.0541 38964.7042 2.60% - 0s
0 0 39004.6387 0 15 40005.0541 39004.6387 2.50% - 0s
0 0 39008.7922 0 15 40005.0541 39008.7922 2.49% - 0s
0 0 39008.9356 0 12 40005.0541 39008.9356 2.49% - 0s
0 0 39008.9356 0 14 40005.0541 39008.9356 2.49% - 0s
0 0 39008.9356 0 15 40005.0541 39008.9356 2.49% - 0s
0 0 39008.9356 0 15 40005.0541 39008.9356 2.49% - 0s
0 0 39008.9356 0 16 40005.0541 39008.9356 2.49% - 0s
0 0 39008.9356 0 17 40005.0541 39008.9356 2.49% - 0s
0 0 39008.9356 0 17 40005.0541 39008.9356 2.49% - 0s
0 0 39008.9356 0 19 40005.0541 39008.9356 2.49% - 0s
0 0 39008.9356 0 18 40005.0541 39008.9356 2.49% - 0s
0 0 39008.9356 0 18 40005.0541 39008.9356 2.49% - 0s
0 0 39008.9356 0 19 40005.0541 39008.9356 2.49% - 0s
0 0 39008.9356 0 19 40005.0541 39008.9356 2.49% - 0s
0 0 39008.9356 0 18 40005.0541 39008.9356 2.49% - 0s
0 0 39008.9356 0 18 40005.0541 39008.9356 2.49% - 0s
0 0 39008.9356 0 18 40005.0541 39008.9356 2.49% - 0s
0 0 39008.9356 0 18 40005.0541 39008.9356 2.49% - 0s
0 0 39008.9356 0 18 40005.0541 39008.9356 2.49% - 0s
0 0 39008.9356 0 19 40005.0541 39008.9356 2.49% - 0s
0 0 39008.9356 0 21 40005.0541 39008.9356 2.49% - 0s
0 0 39008.9356 0 21 40005.0541 39008.9356 2.49% - 0s
0 0 39008.9356 0 19 40005.0541 39008.9356 2.49% - 0s
0 2 39008.9356 0 19 40005.0541 39008.9356 2.49% - 0s
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 Parameters 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: 1
MIR: 17
Explored 313128 nodes (1741251 simplex iterations) in 4.80 seconds
Thread count was 8 (of 8 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%
The first part of the summary reports the cutting planes that are in the LP relaxation at the end of the MIP search. In this example, there are 18 cuts: 1 of type Gomory, and 17 of the type MIR (Mixed Integer Rounding). Note that more cuts and cuts of other types may have been separated and used by Gurobi but if they are not in the last LP formulation they are not reported here. The different types of cuts are listed in the MIP Cuts section of the parameter manual.
The solver required just under 5 seconds to solve the model to optimality, and it used 8 threads to do so (the thread count can be limited with the Threads parameter).
The solution count provides the number of solutions found during the optimization process and stored in the Solution Pool (7 in this case), as well as the objective values of these solutions. The maximum number of solutions stored in the pool is the value of the PoolSolutions parameter.
The gap between the best feasible solution objective and the best bound
is 0.0%, which produces an Optimal termination status, since the
achieved gap is smaller than the default MIPGap
parameter value.
Solution Pool and Multi-Scenario Logging#
Populating a solution pool or solving for multiple scenarios involves looking for more than one solution, which leads to different logging output. In particular, logging for these methods comes in two phases. In the first, the log shows progress towards finding one provably optimal solution (for multi-scenario optimization, this is the best solution over all scenarios). The log for this first phase is identical to the standard MIP log. It shows progress in the lower and upper bounds, and the phase terminates when these are sufficiently close to each other.
The second phase starts once attention has shifted towards finding solutions beyond that one optimal solution. You will see a message indicating that a new phase has begun. When populating a solution pool, you will see:
Optimal solution found at node 7407 - now completing solution pool...
When solving for multiple scenarios, you will see:
Optimal solution found at node 15203 - now completing multiple scenarios...
You will also see an additional header, which is slightly different from the standard MIP header. For a solution pool:
Nodes | Current Node | Pool Obj. Bounds | Work
| | Worst |
Expl Unexpl | Obj Depth IntInf | Incumbent BestBd Gap | It/Node Time
For multiple scenarios:
Nodes | Current Node | Scenario Obj. Bounds | Work
| | Worst |
Expl Unexpl | Obj Depth IntInf | Incumbent BestBd Gap | It/Node Time
The most important difference versus the standard header is in the
Incumbent column. In the standard MIP log, this column shows the
objective value for the best solution found so far. For a solution
pool or multiple scenarios, this column shows the objective value for
the worst solution. This of course isn’t the worst solution ever
found. Rather, it shows the objective value for the worst solution among
all the solutions that the MIP solver has been asked to find. For
example, if you have set the PoolSolutions parameter to
100 to ask for the 100 best solutions, this column will show the
objective value for the 100th best solution found so far. If you are
solving a multi-scenario model, this column shows the worst solution
found over all scenarios. As the search progresses, the value in this
column will improve monotonically as the MIP solver replaces this worst
solution with better solutions.
One other important difference in this second phase log is in the
meaning of the BestBd column. In the standard MIP log, this column
gives a bound on the best possible objective value for any solution. In
this log, this column shows the best possible objective value for any
solution that has not yet been found. To give an example, if a
minimization model has a unique optimal solution at objective 100, the
second phase will begin once the lower bound reaches 100, and the
BestBd column will show a value larger than 100 once the solver has
determined that only one solution exists at objective 100.
The BestBd and Incumbent columns allow you to track progress
towards completion of the solution pool or multi-scenario solve.
Specifically, once the best bound for any solution that has not yet been
found reaches the objective value for the worst solution, we know that
we can’t improve that solution and we can stop.
Multi-Objective Logging#
The contents of the log for a multi-objective solve will depend on the approach you use to solve the model. As noted in the section on multi-objective models, you have two options. In a blended approach, where the objectives are combined into a single objective, the log will be the same as what you’d see for a single-objective model. When using a hierarchical approach, a series of models is solved, one for each objective priority level. If your model is a pure hierarchical multi-objective problem with three objectives, the optimization process log will start with
---------------------------------------------------------------------------
Multi-objectives: starting optimization with 3 objectives ...
---------------------------------------------------------------------------
If your model is a mixed hierarchical-blended multi-objective problem with five objectives but only three priorities, the optimization log will start with
---------------------------------------------------------------------------
Multi-objectives: starting optimization with 5 objectives (3 combined) ...
---------------------------------------------------------------------------
You will also see a log for each solve, introduced by a small header
---------------------------------------------------------------------------
Multi-objectives: optimize objective 1 Name ...
---------------------------------------------------------------------------
Where Name will be the name of the objective function being
optimize, or (weighted) if the objective function is the result of
blending more than one objective function.
The logs for the individual solves will again be the same as what you’d see for a single-objective model.
Distributed MIP Logging#
Logging for distributed MIP is very similar to the standard MIP logging. The main difference is in the progress section. The header for the standard MIP logging looks like this:
Nodes | Current Node | Objective Bounds | Work
Expl Unexpl | Obj Depth IntInf | Incumbent BestBd Gap | It/Node Time
In contrast, the distributed MIP header has a different label for the second-to-last field:
Nodes | Current Node | Objective Bounds | Work
Expl Unexpl | Obj Depth IntInf | Incumbent BestBd Gap | ParUtil Time
Instead of showing iterations per node, this field in the distributed log shows parallel utilization. Specifically, it shows the fraction of the preceding time period (the time since the previous progress log line) that the workers spent actively processing MIP nodes.
Here is an example of a distributed MIP progress log:
Nodes | Current Node | Objective Bounds | Work
Expl Unexpl | Obj Depth IntInf | Incumbent BestBd Gap | ParUtil Time
H 0 157344.61033 - - 0s
H 0 40707.729144 - - 0s
H 0 28468.534497 - - 0s
H 0 18150.083886 - - 0s
H 0 14372.871258 - - 0s
H 0 13725.475382 - - 0s
0 0 10543.7611 0 19 13725.4754 10543.7611 23.2% 99% 0s
* 266 12988.468031 10543.7611 18.8% 0s
H 1503 12464.099984 10630.6187 14.7% 0s
* 2350 12367.608657 10632.7061 14.0% 1s
* 3360 12234.641804 10641.4586 13.0% 1s
H 3870 11801.185729 10641.4586 9.83% 1s
Ramp-up phase complete - continuing with instance 2 (best bd 10661)
16928 2731 10660.9626 0 12 11801.1857 10660.9635 9.66% 99% 2s
135654 57117 11226.5449 19 12 11801.1857 11042.3036 6.43% 98% 5s
388736 135228 11693.0268 23 12 11801.1857 11182.6300 5.24% 96% 10s
705289 196412 cutoff 11801.1857 11248.8963 4.68% 98% 15s
1065224 232839 11604.6587 28 10 11801.1857 11330.2111 3.99% 98% 20s
1412054 238202 11453.2202 31 12 11801.1857 11389.7119 3.49% 99% 25s
1782362 209060 cutoff 11801.1857 11437.2670 3.08% 97% 30s
2097018 158137 11773.6235 20 11 11801.1857 11476.1690 2.75% 92% 35s
2468495 11516 cutoff 11801.1857 11699.9393 0.86% 78% 40s
2481830 0 cutoff 11801.1857 11801.1857 0.00% 54% 40s
One thing you may find in the progress section is that node counts may not increase monotonically. Distributed MIP tries to create a single, unified view of node numbers, but with multiple machines processing nodes independently, possibly at different rates, some inconsistencies are inevitable.
Another difference is the line that indicates that the distributed ramp-up phase is complete. At this point, the distributed strategy transitions from a concurrent approach to a distributed approach. The log line indicates which worker was the winner in the concurrent approach. Distributed MIP continues by dividing the partially explored MIP search tree from this worker among all of the workers.
Another difference in the distributed log is in the summary section. The distributed MIP log includes a breakdown of how runtime was spent:
Runtime breakdown:
Active: 37.85s (93%)
Sync: 2.43s (6%)
Comm: 0.34s (1%)
This is an aggregated view of the utilization data that is displayed in the progress log lines. In this example, the workers spent 93% of runtime actively working on MIP nodes, 6% waiting to synchronize with other workers, and 1% communicating data between machines.
IIS Logging#
Recall that an Irreducible Infeasible Subsystem (IIS) is a subset of the constraints and variable bounds in your infeasible model with the following properties:
It is still infeasible, and
If a single constraint or bound is removed, the subsystem becomes feasible.
The process of identifying an IIS is one of addition and subtraction. The algorithm grows a set of constraints and bounds that are known to be part of an IIS, and also a set that are known not to be. You can track the progress of this process in the IIS log.
Computing Irreducible Inconsistent Subsystem (IIS)...
Constraints | Bounds | Runtime
Min Max Guess | Min Max Guess |
--------------------------------------------------------------------------
0 17509 - 0 4 - 0s
0 12996 - 0 4 - 5s
0 10398 20 0 0 - 10s
0 9749 20 0 0 - 15s
1 9584 20 0 0 - 20s
4 9576 20 0 0 - 25s
6 9406 20 0 0 - 30s
8 8432 40 0 0 - 35s
11 8422 40 0 0 - 40s
15 8413 60 0 0 - 45s
18 8241 60 0 0 - 50s
21 7908 50 0 0 - 55s
24 7735 50 0 0 - 60s
...
The first two columns show the minimum and maximum sizes of the set of constraints in the IIS. The fourth and fifth column give the same information for the set of variable bounds. The final column shows elapsed runtime.
The third and sixth columns in the IIS log provide guesses at the final size of the IIS. Computing an IIS can be quite time-consuming, and it is often useful to have a sense of how large the result will be. These guesses can be quite accurate in some cases, but unfortunately there are some models that can fool our heuristic. You should treat these as very rough estimates.
When the process completes, the algorithm outputs the size of the IIS (the number of constraints and bounds in the irreducible subsystem):
IIS computed: 102 constraints, 0 bounds
IIS runtime: 129.91 seconds
Note in this case that early guesses were in the neighborhood of 50 constraints, but the IIS contained 102.
If you terminate the process early, you will get a non-minimal infeasible subsystem instead:
Non-minimal IIS computed: 3179 constraints, 0 bounds
IIS runtime: 120.29 seconds