Wednesday, September 16, 2009

GAMS/COINCBC: missing log

In releases 23.1 and 23.2 the log of the branch & bound algorithm is disappeared. After reporting about generated cuts no more information is displayed.

Log of 23.0:

GAMS/CoinCbc 2.2 LP/MIP Solver
written by J. Forrest
Problem statistics: 127 columns and 126 rows.
                    108 variables have integrality restrictions.

Calling CBC main solution routine...
Coin Cbc and Clp Solver version 2.20.00, build Sep 20 2008
command line - GAMS/CBC -solve -quit
Continuous objective value is 32.7059 - 0.00 seconds
Optimal - objective value 32.7059
6 fixed, 0 tightened bounds, 0 strengthened rows, 0 substitutions
processed model has 114 rows, 115 columns (98 integer) and 448 elements
Objective coefficients multiple of 1
Cutoff increment increased from 1e-005 to 0.999
Pass   1: suminf.   10.30302 (63) obj. -29.2323 iterations 18
Pass   2: suminf.   10.30302 (63) obj. -29.2323 iterations 0
Pass   3: suminf.    8.39496 (51) obj. -26.535 iterations 43
Pass   4: suminf.    7.85121 (55) obj. -26.7163 iterations 4
Pass   5: suminf.    7.85121 (55) obj. -26.7163 iterations 0
Pass   6: suminf.    5.84706 (39) obj. -22 iterations 33
Pass   7: suminf.    5.84706 (39) obj. -22 iterations 0
Pass   8: suminf.    5.84706 (39) obj. -22 iterations 0
Pass   9: suminf.    5.03167 (39) obj. -19.6561 iterations 71
Pass  10: suminf.    5.03167 (39) obj. -19.6561 iterations 0
Pass  11: suminf.    5.03167 (39) obj. -19.6561 iterations 0
Pass  12: suminf.    3.05294 (26) obj. -15.2353 iterations 50
Pass  13: suminf.    3.05294 (26) obj. -15.2353 iterations 0
Pass  14: suminf.    3.05294 (26) obj. -15.2353 iterations 0
Pass  15: suminf.    3.63051 (27) obj. -15.1232 iterations 26
Pass  16: suminf.    3.63051 (27) obj. -15.1232 iterations 0
Pass  17: suminf.    3.63051 (27) obj. -15.1232 iterations 0
Pass  18: suminf.    2.75294 (21) obj. -13.4235 iterations 26
Pass  19: suminf.    2.74866 (20) obj. -13.4171 iterations 6
Pass  20: suminf.    2.74866 (20) obj. -13.4171 iterations 0
No solution found this major pass
Before mini branch and bound, 7 integers at bound fixed and 0 continuous
Full problem 114 rows 115 columns, reduced to 113 rows 108 columns - too large
Mini branch and bound did not improve solution (0.11 seconds)
Full problem 115 rows 115 columns, reduced to 115 rows 115 columns - too large
After 0.11 seconds - Feasibility pump exiting - took 0.11 seconds
59 added rows had average density of 50.6441
At root node, 59 cuts changed objective from -29.8813 to -26.7458 in 100 passes
Cut generator 0 (Probing) - 1834 row cuts, 0 column cuts (53 active)  in 0.775 seconds - new frequency is 1
Cut generator 1 (Gomory) - 5566 row cuts, 0 column cuts (6 active)  in 0.226 seconds - new frequency is 1
Cut generator 2 (Knapsack) - 14 row cuts, 0 column cuts (0 active)  in 0.007 seconds - new frequency is -100
Cut generator 3 (Clique) - 0 row cuts, 0 column cuts (0 active)  in 0.009 seconds - new frequency is -100
Cut generator 4 (MixedIntegerRounding2) - 643 row cuts, 0 column cuts (0 active)  in 0.020 seconds - new frequency is 1
Cut generator 5 (FlowCover) - 90 row cuts, 0 column cuts (0 active)  in 0.144 seconds - new frequency is -100
Cut generator 6 (TwoMirCuts) - 990 row cuts, 0 column cuts (0 active)  in 0.044 seconds - new frequency is -100
Optimal - objective value 26.7458
Optimal - objective value 26.7458
After 0 nodes, 1 on tree, 1e+050 best solution, best possible -26.7458 (2.22 seconds)
Integer solution of -18 found after 11709 iterations and 84 nodes (4.46 seconds)
Full problem 114 rows 115 columns, reduced to 98 rows 94 columns
Integer solution of -21 found after 17199 iterations and 205 nodes (6.05 seconds)
Full problem 114 rows 115 columns, reduced to 103 rows 99 columns - too large
Search completed - best objective -21, took 25825 iterations and 367 nodes (7.34 seconds)
Strong branching done 5428 times (117137 iterations), fathomed 39 nodes and fixed 233 variables
Maximum depth 26, 1719 variables fixed on reduced cost
Cuts at root node changed objective from 29.8813 to -26.7458
Probing was tried 660 times and created 7528 cuts of which 1317 were active after adding rounds of cuts (1.204 seconds)
Gomory was tried 611 times and created 10689 cuts of which 626 were active after adding rounds of cuts (0.429 seconds)
Knapsack was tried 100 times and created 14 cuts of which 0 were active after adding rounds of cuts (0.007 seconds)
Clique was tried 100 times and created 0 cuts of which 0 were active after adding rounds of cuts (0.009 seconds)
MixedIntegerRounding2 was tried 651 times and created 2491 cuts of which 123 were active after adding rounds of cuts (0.090 seconds)
FlowCover was tried 100 times and created 90 cuts of which 0 were active after adding rounds of cuts (0.144 seconds)
TwoMirCuts was tried 100 times and created 990 cuts of which 0 were active after adding rounds of cuts (0.044 seconds)
implication was tried 551 times and created 0 cuts of which 0 were active after adding rounds of cuts
5 bounds tightened after postprocessing
Result - Finished objective 21 after 367 nodes and 25825 iterations - took 7.35 seconds (total time 7.39)
Total time 7.39

Solved to optimality (within gap tolerances).
MIP solution:                    21   (367 nodes, 7.395 seconds)
Best possible:                   21
Absolute gap:                     0   (absolute tolerance optca: 0)
Relative gap:                     0   (relative tolerance optcr: 0.1)

In gams 23.2 we see:

GAMS/CoinCbc 2.3 LP/MIP Solver
written by J. Forrest
Problem statistics: 127 columns and 126 rows.
                    108 variables have integrality restrictions.

Calling CBC main solution routine...
Coin Cbc and Clp Solver version 2.3pre, build Apr 17 2009
command line - GAMS/CBC -solve -quit (default strategy 1)
Continuous objective value is 32.7059 - 0.00 seconds
0 fixed, 0 tightened bounds, 91 strengthened rows, 0 substitutions
0 fixed, 0 tightened bounds, 4 strengthened rows, 0 substitutions
0 fixed, 0 tightened bounds, 4 strengthened rows, 0 substitutions
0 fixed, 0 tightened bounds, 4 strengthened rows, 0 substitutions
0 fixed, 0 tightened bounds, 4 strengthened rows, 0 substitutions
0 fixed, 0 tightened bounds, 4 strengthened rows, 0 substitutions
0 fixed, 0 tightened bounds, 4 strengthened rows, 0 substitutions
0 fixed, 0 tightened bounds, 4 strengthened rows, 0 substitutions
0 fixed, 0 tightened bounds, 4 strengthened rows, 0 substitutions
processed model has 114 rows, 115 columns (98 integer) and 448 elements
Objective coefficients multiple of 1
Cutoff increment increased from 1e-005 to 0.999
Pass   1: suminf.   11.18775 (60) obj. -28.9374 iterations 12
Pass   2: suminf.   11.18775 (60) obj. -28.9374 iterations 0
Pass   3: suminf.    7.03271 (40) obj. -21.3003 iterations 77
Pass   4: suminf.    6.88899 (42) obj. -21.037 iterations 4
Pass   5: suminf.    6.88899 (42) obj. -21.037 iterations 0
Pass   6: suminf.    4.86728 (32) obj. -17.0442 iterations 43
Pass   7: suminf.    4.86728 (32) obj. -17.0442 iterations 0
Pass   8: suminf.    4.86728 (32) obj. -17.0442 iterations 0
Pass   9: suminf.    3.82450 (18) obj. -14.6103 iterations 32
Pass  10: suminf.    3.82450 (18) obj. -14.6103 iterations 0
Pass  11: suminf.    3.82450 (18) obj. -14.6103 iterations 0
Pass  12: suminf.    4.04428 (12) obj. -9.88475 iterations 35
Pass  13: suminf.    2.36084 (11) obj. -9.87972 iterations 4
Pass  14: suminf.    2.36084 (11) obj. -9.87972 iterations 0
Pass  15: suminf.    5.41816 (25) obj. -14.5273 iterations 42
Pass  16: suminf.    4.90619 (25) obj. -14.6979 iterations 3
Pass  17: suminf.    4.90619 (25) obj. -14.6979 iterations 0
Pass  18: suminf.    5.63976 (21) obj. -11.9286 iterations 43
Pass  19: suminf.    5.63976 (21) obj. -11.9286 iterations 0
Pass  20: suminf.    5.63976 (21) obj. -11.9286 iterations 0
Pass  21: suminf.    5.60993 (28) obj. -13.8754 iterations 45
Pass  22: suminf.    5.60993 (28) obj. -13.8754 iterations 0
Pass  23: suminf.    5.60993 (28) obj. -13.8754 iterations 0
Pass  24: suminf.    4.23841 (23) obj. -14.553 iterations 48
Pass  25: suminf.    4.23841 (23) obj. -14.553 iterations 0
Pass  26: suminf.    4.23841 (23) obj. -14.553 iterations 0
Pass  27: suminf.    2.62284 (12) obj. -13 iterations 37
Pass  28: suminf.    2.62284 (12) obj. -13 iterations 0
Pass  29: suminf.    2.62284 (12) obj. -13 iterations 0
Pass  30: suminf.    4.52424 (26) obj. -13.3305 iterations 39
No solution found this major pass
Before mini branch and bound, 1 integers at bound fixed and 0 continuous
Full problem 114 rows 115 columns, reduced to 114 rows 114 columns - too large
Mini branch and bound did not improve solution (0.10 seconds)
Full problem 115 rows 115 columns, reduced to 115 rows 115 columns - too large
After 0.11 seconds - Feasibility pump exiting - took 0.11 seconds
47 added rows had average density of 55.5957
At root node, 47 cuts changed objective from -29.7355 to -26.6652 in 100 passes
Cut generator 0 (Probing) - 1402 row cuts, 0 column cuts (46 active)  in 0.755 seconds - new frequency is 1
Cut generator 1 (Gomory) - 5871 row cuts, 0 column cuts (1 active)  in 0.228 seconds - new frequency is 1
Cut generator 2 (Knapsack) - 0 row cuts, 0 column cuts (0 active)  in 0.013 seconds - new frequency is -100
Cut generator 3 (Clique) - 0 row cuts, 0 column cuts (0 active)  in 0.003 seconds - new frequency is -100
Cut generator 4 (MixedIntegerRounding2) - 389 row cuts, 0 column cuts (0 active)  in 0.020 seconds - new frequency is 1
Cut generator 5 (FlowCover) - 33 row cuts, 0 column cuts (0 active)  in 0.149 seconds - new frequency is -100
Cut generator 6 (TwoMirCuts) - 743 row cuts, 0 column cuts (0 active)  in 0.039 seconds - new frequency is -100

Solved to optimality (within gap tolerances).
MIP solution:                    21   (98 nodes, 4.061 seconds)
Best possible:                   21
Absolute gap:                     0   (absolute tolerance optca: 0)
Relative gap:                     0   (relative tolerance optcr: 0.1)

With larger problems you have no clue how cbc is doing. The log is 100% of the “user interface” of a solver, so it is more important for a user than many developers think.