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.

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