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.
You control how information in the log file is recorded and displayed, through two CPLEX parameters. The 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 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)In 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:
Variable records 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.
B specifies the branching direction:
D means the variables was restricted to a lower value;
U means the variable was restricted to a higher value;
L means the left subset of the special ordered set was restricted to 0 (zero);
R means the right subset of the special ordered set was restricted to 0 (zero);
A means that constraints were added or more than one variable was restricted;
N means that cuts added to the node LP resulted in an integer feasible solution; no branching was required;
NodeID specifies the node identifier.
Parent specifies the NodeID of the parent.
Depth tells 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.
Selected objective sense: MINIMIZE
Selected objective name: total_costs
Selected RHS name: rhs
Selected bound name: bnd
Problem 'anothersample.mps' read.
Read time = 0.01 sec. (0.23 ticks)
Tried aggregator 2 times.
Aggregator did 24 substitutions.
Reduced MIP has 455 rows, 818 columns, and 2043 nonzeros.
Reduced MIP has 397 binaries, 0 generals, 0 SOSs, and 0 indicators.
Presolve time = 0.02 sec. (1.54 ticks)
Probing time = 0.00 sec. (0.56 ticks)
Cover probing fixed 0 vars, tightened 5 bounds.
Tried aggregator 1 time.
MIP Presolve modified 5 coefficients.
Reduced MIP has 455 rows, 818 columns, and 2043 nonzeros.
Reduced MIP has 397 binaries, 0 generals, 0 SOSs, and 0 indicators.
Presolve time = 0.01 sec. (1.20 ticks)
Probing time = 0.00 sec. (0.56 ticks)
Clique table members: 29.
MIP emphasis: balance optimality and feasibility.
MIP search method: dynamic search.
Parallel mode: deterministic, using up to 2 threads.
Root relaxation solution time = 0.01 sec. (1.64 ticks)
Nodes Cuts/
Node Left Objective IInf Best Integer Best Bound ItCnt Gap
0 0 983.1674 24 983.1674 125
0 0 1032.1317 35 Cuts: 82 216
0 0 1062.8654 43 Cuts: 105 304
0 0 1075.9744 52 Cuts: 65 388
* 0+ 0 1264.0000 1075.9744 486 14.88%
0 0 1081.5806 58 1264.0000 Cuts: 66 486 14.43%
0 0 1086.2299 51 1264.0000 Cuts: 52 546 14.06%
0 0 1088.8063 52 1264.0000 Cuts: 34 596 13.86%
* 0+ 0 1240.0000 1088.8063 637 12.19%
0 0 1090.8727 53 1240.0000 Cuts: 40 637 12.03%
0 0 1091.5433 53 1240.0000 Cuts: 35 667 11.97%
0 0 1091.8490 56 1240.0000 Cuts: 17 694 11.95%
0 0 1092.0247 52 1240.0000 Cuts: 13 707 11.93%
0 0 1092.1376 55 1240.0000 Cuts: 13 719 11.92%
0 0 1092.5211 58 1240.0000 Cuts: 9 741 11.89%
* 0+ 0 1197.0000 1092.5211 760 8.73%
0 0 1092.6120 55 1197.0000 Cuts: 14 760 8.72%
* 0+ 0 1173.0000 1092.6120 760 6.85%
* 0+ 0 1172.0000 1092.6120 760 6.77%
* 0+ 0 1160.0000 1092.6120 760 5.81%
0 2 1092.6120 55 1160.0000 1092.6120 760 5.81%
Elapsed time = 4.68 sec. (996.95 ticks, tree = 0.01 MB, solutions = 6)
181 99 1123.4828 28 1160.0000 1107.0342 9274 4.57%
376 221 1150.4582 33 1160.0000 1112.6850 17065 4.08%
581 325 1133.1086 24 1160.0000 1120.3812 25477 3.42%
822 465 1137.1711 39 1160.0000 1123.6613 33378 3.13%
1006 561 1135.3554 32 1160.0000 1126.4741 41813 2.89%
1288 690 1137.5743 36 1160.0000 1129.7101 48613 2.61%
1545 768 cutoff 1160.0000 1131.9613 56928 2.42%
1840 901 1156.9766 22 1160.0000 1134.5757 64644 2.19%
2078 982 1153.6714 25 1160.0000 1136.2144 72322 2.05%
3108 1102 1154.4286 1 1160.0000 1144.4474 105611 1.34%
Elapsed time = 11.03 sec. (4111.73 ticks, tree = 1.43 MB, solutions = 6)
* 3112 1101 integral 0 1158.0000 1144.4474 105704 1.17%
3380 946 1109.1909 49 1158.0000 1146.4790 114211 0.99%
4335 368 cutoff 1158.0000 1146.4790 147638 0.99%
GUB cover cuts applied: 3
Cover cuts applied: 12
Implied bound cuts applied: 32
Flow cuts applied: 67
Mixed integer rounding cuts applied: 54
Flow path cuts applied: 4
Zero-half cuts applied: 6
Multi commodity flow cuts applied: 8
Gomory fractional cuts applied: 5
Root node processing (before b&c):
Real time = 4.63 sec. (991.49 ticks)
Parallel b&c, 2 threads:
Real time = 16.83 sec. (5417.26 ticks)
Sync time (average) = 0.01 sec.
Wait time (average) = 0.00 sec.
------------
Total (root+branch&cut) = 21.46 sec. (6408.75 ticks)
Solution pool: 7 solutions saved.
MIP - Integer optimal solution: Objective = 1.1580000000e+03
Solution time = 21.51 sec. Iterations = 164313 Nodes = 5078
Deterministic time = 6413.71 ticks (298.22 ticks/sec)