Progress reports: interpreting the node log
Describes the progress reports issued in the node log during MIP optimization.
As explained in other topics, when CPLEX optimizes mixed integer programs, it builds a tree with the linear relaxation of the original MIP at the root and subproblems to optimize at the nodes of the tree. CPLEX reports its progress in optimizing the original problem in a node log file as it traverses this tree.
MIPDisplay parameter
controls the general nature of the output that goes to the node log.
The table Table 1 summarizes
its possible values and their effects.| Value | Effect |
|---|---|
0 |
No display until optimal solution has been found |
1 |
Display integer feasible solutions |
2 |
Display integer feasible solutions plus an entry for every n-th node; default |
3 |
Display integer feasible solutions, every n-th node entry, number of cuts added, and information about the processing of each successful MIP start |
4 |
Display integer feasible solutions, every n-th node entry, number of cuts added, information about the processing of each successful MIP start, and information about the LP subproblem at root |
5 |
Display integer feasible solutions, every n-th node entry, number of cuts added, information about the processing of each successful MIP start, and information about the LP subproblem at root and at nodes |
The MIP node log interval parameter
(MIPInterval, CPX_PARAM_MIPINTERVAL)
controls how frequently node log lines are printed. Its default is
100; it can be set to any positive integer value, as documented in
the CPLEX Parameters Reference Manual. CPLEX records a line
in the node log for every node with an integer solution if the parameter
controlling MIP node log display information (MIPDisplay,
CPX_PARAM_MIPDISPLAY) is set to 1 (one) or higher. Likewise,
if the MIPDisplay is set to 2 or higher, then for
any node whose number is a multiple of the MIPInterval value,
a line is recorded in the node log for every node with an integer
solution.
Here is an example of a log file from the Interactive Optimizer,
where the MIPInterval parameter has been set to 10:
Tried aggregator 1 time.
Presolve time = 0.00 sec. (0.00 ticks)
MIP emphasis: balance optimality and feasibility.
MIP search method: dynamic search.
Parallel mode: none, using 1 thread.
Root relaxation solution time = 0.00 sec (0.00 ticks)
Nodes Cuts/
Node Left Objective IInf Best Integer Best Bound ItCnt Gap
* 0+ 0 0.0000 3261.8212 8 ---
* 0+ 0 3148.0000 3261.8212 8 3.62%
0 0 3254.5370 7 3148.0000 Cuts: 5 14 3.38%
0 0 3246.0185 7 3148.0000 Cuts: 3 24 3.11%
* 0+ 0 3158.0000 3246.0185 24 2.79%
0 0 3245.3465 9 3158.0000 Cuts: 5 27 2.77%
0 0 3243.4477 9 3158.0000 Cuts: 5 32 2.71%
0 0 3242.9809 10 3158.0000 Covers: 3 36 2.69%
0 0 3242.8397 11 3158.0000 Covers: 1 37 2.69%
0 0 3242.7428 11 3158.0000 Cuts: 3 39 2.68%
0 2 3242.7428 11 3158.0000 3242.7428 39 2.68%
10 11 3199.1875 2 3158.0000 3215.1261 73 1.81%
* 20+ 11 3168.0000 3215.1261 89 1.49%
20 13 3179.0028 5 3168.0000 3215.1261 89 1.49%
30 15 3179.9091 3 3168.0000 3197.5227 113 0.93%
* 39 3 integral 0 3186.0000 3197.3990 126 0.36%
40 3 3193.7500 1 3186.0000 3197.3990 128 0.36%
Cover cuts applied: 9
Zero-half cuts applied: 2
Gomory fractional cuts applied: 1
Solution pool: 5 solutions saved.
MIP-Integer optimal solution: Objective = 3.1860000000e+03
Solution time = 0.01 sec. (0.00 ticks) Iterations = 131 Nodes = 44In that example, CPLEX found the optimal objective function value of 3.1860000000e+03 after exploring 44 nodes and performing 131 (dual simplex) iterations, and CPLEX found an integral LP solution, designated by the star (*) and the word integral at node 39. That log reports a heuristic solution, designated by a star (*) and a plus (+) after the node number, at the root and at node 20. The MIP interval parameter was set at 10, so every tenth node was logged, in addition to the node where an integer solution was found.
As you can see in that example, CPLEX logs an asterisk (* )
in the left-most column for any node where it finds an
integer-feasible solution (that is, a new incumbent).
In the next column, it logs
the node number. It next logs the number of nodes left to explore.
In the next column, Objective, CPLEX either records
the objective value at the node or a reason to fathom the node. (A
node is fathomed if the solution of a subproblem at the node
is infeasible; or if the value of the objective function at the node
is worse than the cutoff value for branch & cut; or if the linear
programming relaxation at the node supplies an integer solution.)
This column is left blank for lines that report that CPLEX found a new
incumbent by primal heuristics. A plus (+) after the node number
distinguishes such lines.
In the column labeled IInf, CPLEX records the
number of integer-infeasible variables and special ordered sets. If
no solution has been found, the column titled Best Integer is
blank; otherwise, it records the objective value of the best integer solution
found so far.
The column labeled Cuts/Best Bound records the
best objective function value achievable. If the word Cuts appears
in this column, it means various cuts were generated; if a particular
name of a cut appears, then only that kind of cut was generated.
The column labeled ItCnt records the cumulative iteration
count of the algorithm solving the subproblems. Until a solution
has been found, the column labeled Gap is blank.
If a solution has been found, the relative gap value is printed: when
it is less than 999.99 , the value is printed; otherwise,
hyphens are printed. The gap is computed as:
(best integer - best node) * objsen / (abs (best integer)
+ 1e-10)
Consequently, the printed gap value may not always move smoothly. In particular, there may be sharp improvements whenever a new best integer solution is found. Moreover, if the populate procedure of the solution pool is invoked, the printed gap value may become negative after the optimal solution has been found and proven optimal.
CPLEX also logs its addition of cuts to a model. In the previous sample node log file, CPLEX reports that it added a variety of cuts (cover cuts, zero-half cuts, Gomory fractional cuts).
CPLEX also logs the number of clique inequalities in the clique table at the beginning of optimization. Cuts generated at intermediate nodes are not logged individually unless they happen to be generated at a node logged for other reasons. CPLEX logs the number of applied cuts of all classes at the end.
CPLEX also shows, in the node log file, each instance of a successful application of the node heuristic. The previous sample node log file shows that a heuristic found a solution at node 20. The + denotes an incumbent generated by the heuristic.
Periodically, if the MIP display parameter is 2 or
greater, CPLEX records the cumulative time spent since the
beginning of the current MIP optimization and the amount of memory used
by branch & cut. (Periodically means that time and memory information
appear either every 20 nodes or ten times the MIP
interval parameter, whichever is greater.)
The Interactive Optimizer prints an additional summary line in the log if optimization stops before it is complete. This summary line shows the best MIP bound, that is, the best objective value among all the remaining node subproblems. The following example shows you lines from a node log file where an integer solution has not yet been found, and the best remaining objective value is 2973.9912281.
MIP-Node limit, no integer solution.
Current MIP best bound = 2.9739912281e+03 (gap is infinite)
Solution time = 0.01 sec. (0.00 ticks) Iterations = 68 Nodes = 7 (7)
Stating a MIP problem presents a typical MIP problem. Here is the node log file for that problem with the default setting of the MIP display parameter and two threads:
Selected objective sense: MINIMIZE
Selected objective name: obj
Selected RHS name: rhs
Selected bound name: bnd
Problem 'samples.mps' read.
Read time = 0.03 sec. (0.00 ticks)
Tried aggregator 2 times.
Aggregator did 1 substitutions.
Reduced MIP has 2 rows, 3 columns, and 6 nonzeros.
Reduced MIP has 0 binaries, 1 generals, 0 SOSs, and 0 indicators.
Presolve time = 0.03 sec. (0.01 ticks)
Found incumbent of value -34.000000 after 0.05 sec. (0.02 ticks)
Probing time = 0.00 sec. (0.00 ticks)
Tried aggregator 1 time.
Presolve time = 0.00 sec. (0.00 ticks)
Probing time = 0.00 sec. (0.00 ticks)
MIP emphasis: balance optimality and feasibility.
MIP search method: dynamic search.
Parallel mode: deterministic, using up to 2 threads.
Root relaxation solution time = 0.03 sec. (0.00 ticks)
Nodes Cuts/
Node Left Objective IInf Best Integer Best Bound ItCnt Gap
* 0+ 0 -34.0000 -163.0000 3 379.41%
0 0 -125.2083 1 -34.0000 -125.2083 3 268.26%
* 0+ 0 -122.5000 -125.2083 3 2.21%
0 0 cutoff -122.5000 3 0.00%
Elapsed time = 0.11 sec. (0.04 ticks, tree = 0.00 MB, solutions = 2)
Root node processing (before b&c):
Real time = 0.06 sec. (0.02 ticks)
Parallel b&c, 2 threads:
Real time = 0.00 sec. (0.00 ticks)
Sync time (average) = 0.00 sec.
Wait time (average) = 0.00 sec.
------------
Total (root+branch&cut) = 0.06 sec. (0.02 ticks)
Solution pool: 2 solutions saved.
MIP - Integer optimal solution: Objective = -1.2250000000e+02
Solution time = 0.13 sec. Iterations = 3 Nodes = 0
Deterministic time = 0.04 ticks (0.35 ticks/sec)
These additional items appear only in the node log file (not on screen) in conventional branch & cut:
Variablerecords the name of the variable where CPLEX branched to create this node. If the branch was due to a special ordered set, the name listed here will be the right-most variable in the left subset.Bspecifies the branching direction:Dmeans the variables was restricted to a lower value;Umeans the variable was restricted to a higher value;Lmeans the left subset of the special ordered set was restricted to 0 (zero);Rmeans the right subset of the special ordered set was restricted to 0 (zero);Ameans that constraints were added or more than one variable was restricted;Nmeans that cuts added to the node LP resulted in an integer feasible solution; no branching was required;NodeIDspecifies the node identifier.
Parentspecifies theNodeIDof the parent.Depthtells the depth of this node in the branch & cut tree.
Those additional items are not applicable in dynamic search. Here is a sample session in the Interactive Optimizer showing the log file typical in dynamic search. In this log file, you see activity at the root node, a variety of cuts added to the model, and accumulation of solutions in the solution pool.
Tried aggregator 2 times.
MIP Presolve added 27 rows and 0 columns.
Aggregator did 24 substitutions.
Reduced MIP has 482 rows, 818 columns, and 2097 nonzeros.
Reduced MIP has 397 binaries, 0 generals, 0 SOSs, and 0 indicators.
Presolve time = 0.01 sec. (1.70 ticks)
Probing time = 0.00 sec. (1.41 ticks)
Cover probing fixed 0 vars, tightened 5 bounds.
Tried aggregator 1 time.
MIP Presolve modified 5 coefficients.
Reduced MIP has 482 rows, 818 columns, and 2097 nonzeros.
Reduced MIP has 397 binaries, 0 generals, 0 SOSs, and 0 indicators.
Presolve time = 0.00 sec. (1.29 ticks)
Probing time = 0.00 sec. (1.39 ticks)
Clique table members: 53.
MIP emphasis: balance optimality and feasibility.
MIP search method: dynamic search.
Parallel mode: deterministic, using up to 2 threads.
Root relaxation solution time = 0.00 sec. (1.65 ticks)
Nodes Cuts/
Node Left Objective IInf Best Integer Best Bound ItCnt Gap
0 0 983.1674 24 983.1674 108
0 0 1032.3085 30 Cuts: 82 183
0 0 1061.4365 41 Cuts: 107 270
0 0 1074.7841 50 Cuts: 75 346
* 0+ 0 1321.0000 1074.7841 18.64%
0 0 1084.1042 55 1321.0000 Cuts: 76 455 17.93%
0 0 1089.1343 52 1321.0000 Cuts: 58 532 17.55%
* 0+ 0 1239.0000 1089.1343 12.10%
0 0 1090.6995 51 1239.0000 Cuts: 23 569 11.97%
0 0 1093.3703 53 1239.0000 Cuts: 35 637 11.75%
0 0 1094.6468 50 1239.0000 Cuts: 34 664 11.65%
0 0 1097.2024 53 1239.0000 Cuts: 39 718 11.44%
0 0 1097.8618 53 1239.0000 Cuts: 19 745 11.39%
* 0+ 0 1238.0000 1097.8618 11.32%
0 0 1098.3075 49 1238.0000 Cuts: 22 764 11.28%
0 0 1098.3656 53 1238.0000 Cuts: 14 780 11.28%
0 0 1098.3784 53 1238.0000 Cuts: 6 788 11.28%
* 0+ 0 1188.0000 1098.3784 7.54%
* 0+ 0 1187.0000 1098.3784 7.47%
* 0+ 0 1186.0000 1098.3784 7.39%
* 0+ 0 1184.0000 1098.3784 7.23%
* 0+ 0 1175.0000 1098.3784 6.52%
* 0+ 0 1168.0000 1098.3784 5.96%
0 2 1098.3784 53 1168.0000 1098.3784 788 5.96%
Elapsed time = 1.10 sec. (774.96 ticks, tree = 0.01 MB, solutions = 9)
275 196 1139.0374 29 1168.0000 1108.0676 8246 5.13%
* 403+ 268 1160.0000 1109.0629 4.39%
609 358 1132.1591 31 1160.0000 1114.5957 16324 3.91%
915 510 1157.3197 20 1160.0000 1120.9789 23862 3.36%
1177 656 1138.3457 17 1160.0000 1125.3344 31906 2.99%
1472 783 1152.7317 16 1160.0000 1129.5898 39883 2.62%
1781 894 1142.3663 31 1160.0000 1132.1594 46810 2.40%
2062 1009 1148.8845 15 1160.0000 1135.6469 54218 2.10%
* 2202 1056 integral 0 1158.0000 1136.1895 57689 1.88%
2359 990 cutoff 1158.0000 1137.5694 62331 1.76%
2709 984 1154.9875 24 1158.0000 1141.1918 70633 1.45%
Cover cuts applied: 19
Implied bound cuts applied: 61
Flow cuts applied: 83
Mixed integer rounding cuts applied: 44
Flow path cuts applied: 4
Zero-half cuts applied: 4
Multi commodity flow cuts applied: 7
Lift and project cuts applied: 2
Root node processing (before b&c):
Real time = 1.10 sec. (774.54 ticks)
Parallel b&c, 2 threads:
Real time = 3.08 sec. (2875.90 ticks)
Sync time (average) = 0.13 sec.
Wait time (average) = 0.00 sec.
------------
Total (root+branch&cut) = 4.18 sec. (3650.45 ticks)
Solution pool: 11 solutions saved.
MIP - Integer optimal solution: Objective = 1.1580000000e+03
Solution time = 4.18 sec. Iterations = 91263 Nodes = 4235
Deterministic time = 3650.45 ticks (872.98 ticks/sec)