Analyzing the log of CBC solver in pulp

Question

I am trying to solve an optimization problem in pulp using the CBC solver.

Here is the log and few questions that I would like to know from the logs :

Welcome to the CBC MILP Solver 
Version: 2.9.9 
Build Date: Aug 21 2017 

command line - /usr/bin/cbc /tmp/ae38591e7b4f4185adc4ac18aa1c8361-pulp.mps max threads 4 timeMode elapsed branch printingOptions all solution /tmp/ae38591e7b4f4185adc4ac18aa1c8361-pulp.sol (default strategy 1)
At line 2 NAME          MODEL
At line 3 ROWS
At line 2681 COLUMNS
At line 126513 RHS
At line 129190 BOUNDS
At line 153239 ENDATA
Problem MODEL has 2676 rows, 24048 columns and 72144 elements
Coin0008I MODEL read with 0 errors
threads was changed from 0 to 4
Option for timeMode changed from cpu to elapsed
Continuous objective value is 72032.6 - 0.15 seconds
Cgl0008I 2672 inequality constraints converted to equality constraints
Cgl0004I processed model has 2676 rows, 10688 columns (10688 integer (10688 of which binary)) and 26720 elements
Cutoff increment increased from 1e-05 to 4.9999
Cbc0038I Initial state - 4 integers unsatisfied sum - 1.3913
Cbc0038I Pass   1: suminf.    0.69565 (2) obj. -72018.7 iterations 763
Cbc0038I Solution found of -71960
Cbc0038I Before mini branch and bound, 10682 integers at bound fixed and 0 continuous
Cbc0038I Full problem 2676 rows 10688 columns, reduced to 2 rows 3 columns
Cbc0038I Mini branch and bound improved solution from -71960 to -72000 (2.00 seconds)
Cbc0038I Round again with cutoff of -72007.8
Cbc0038I Reduced cost fixing fixed 3805 variables on major pass 2
Cbc0038I Pass   2: suminf.    0.69565 (2) obj. -72029.1 iterations 17
Cbc0038I Pass   3: suminf.    0.59203 (2) obj. -72007.8 iterations 850
Cbc0038I Pass   4: suminf.    1.39130 (6) obj. -72007.8 iterations 417
Cbc0038I Pass   5: suminf.    0.69565 (2) obj. -72009.1 iterations 556
Cbc0038I Pass   6: suminf.    0.74131 (2) obj. -72007.8 iterations 588
Cbc0038I Pass   7: suminf.    0.69565 (2) obj. -72009.1 iterations 610
Cbc0038I Pass   8: suminf.    1.81303 (8) obj. -72007.8 iterations 504
Cbc0038I Pass   9: suminf.    0.69565 (2) obj. -72009.1 iterations 922
Cbc0038I Pass  10: suminf.    0.74131 (2) obj. -72007.8 iterations 636
Cbc0038I Pass  11: suminf.    1.79138 (8) obj. -72007.8 iterations 340
Cbc0038I Pass  12: suminf.    0.69565 (2) obj. -72009.1 iterations 409
Cbc0038I Pass  13: suminf.    0.74131 (2) obj. -72007.8 iterations 584
Cbc0038I Pass  14: suminf.    2.90875 (8) obj. -72007.8 iterations 260
Cbc0038I Pass  15: suminf.    0.69565 (2) obj. -72009.1 iterations 1376
Cbc0038I Pass  16: suminf.    0.74131 (2) obj. -72007.8 iterations 597
Cbc0038I Pass  17: suminf.    1.79138 (8) obj. -72007.8 iterations 349
Cbc0038I Pass  18: suminf.    0.69565 (2) obj. -72009.1 iterations 449
Cbc0038I Pass  19: suminf.    0.74131 (2) obj. -72007.8 iterations 621
Cbc0038I Pass  20: suminf.    2.90875 (8) obj. -72007.8 iterations 311
Cbc0038I Pass  21: suminf.    0.69565 (2) obj. -72009.1 iterations 931
Cbc0038I Pass  22: suminf.    0.74131 (2) obj. -72007.8 iterations 627
Cbc0038I Pass  23: suminf.    2.90875 (8) obj. -72007.8 iterations 302
Cbc0038I Pass  24: suminf.    0.69565 (2) obj. -72009.1 iterations 554
Cbc0038I Pass  25: suminf.    0.74131 (2) obj. -72007.8 iterations 552
Cbc0038I Pass  26: suminf.    1.81303 (8) obj. -72007.8 iterations 303
Cbc0038I Pass  27: suminf.    0.69565 (2) obj. -72009.1 iterations 791
Cbc0038I Pass  28: suminf.    0.74131 (2) obj. -72007.8 iterations 575
Cbc0038I Pass  29: suminf.    2.63482 (8) obj. -72007.8 iterations 387
Cbc0038I Pass  30: suminf.    0.69565 (2) obj. -72009.1 iterations 801
Cbc0038I Pass  31: suminf.    0.74131 (2) obj. -72007.8 iterations 582
Cbc0038I No solution found this major pass
Cbc0038I Before mini branch and bound, 10134 integers at bound fixed and 0 continuous
Cbc0038I Full problem 2676 rows 10688 columns, reduced to 15 rows 45 columns
Cbc0038I Mini branch and bound did not improve solution (3.51 seconds)
Cbc0038I After 3.51 seconds - Feasibility pump exiting with objective of -72000 - took 1.65 seconds
Cbc0012I Integer solution of -72000 found by feasibility pump after 0 iterations and 0 nodes (3.52 seconds)
Cbc0038I Full problem 2676 rows 10688 columns, reduced to 2 rows 2 columns
Cbc0013I At root node, 0 cuts changed objective from -72032.609 to -72032.609 in 1 passes
Cbc0014I Cut generator 0 (Probing) - 0 row cuts average 0.0 elements, 0 column cuts (0 active)  in 0.012 seconds - new frequency is -100
Cbc0014I Cut generator 1 (Gomory) - 0 row cuts average 0.0 elements, 0 column cuts (0 active)  in 0.004 seconds - new frequency is -100
Cbc0014I Cut generator 2 (Knapsack) - 0 row cuts average 0.0 elements, 0 column cuts (0 active)  in 0.004 seconds - new frequency is -100
Cbc0014I Cut generator 3 (Clique) - 0 row cuts average 0.0 elements, 0 column cuts (0 active)  in 0.000 seconds - new frequency is -100
Cbc0014I Cut generator 4 (MixedIntegerRounding2) - 0 row cuts average 0.0 elements, 0 column cuts (0 active)  in 0.002 seconds - new frequency is -100
Cbc0014I Cut generator 5 (FlowCover) - 0 row cuts average 0.0 elements, 0 column cuts (0 active)  in 0.000 seconds - new frequency is -100
Cbc0010I After 0 nodes, 1 on tree, -72000 best solution, best possible -72032.609 (4.57 seconds)
Cbc0038I Full problem 2676 rows 10688 columns, reduced to 955 rows 3443 columns
Cbc0044I Reduced cost fixing - 955 rows, 3443 columns - restarting search
Cbc0038I Unable to insert previous solution - using cutoff of -72000
Cbc0038I Initial state - 3 integers unsatisfied sum - 1.04348
Cbc0038I Pass   1: suminf.    0.68801 (4) obj. -72000 iterations 750
Cbc0038I Pass   2: suminf.    0.00018 (1) obj. -72000 iterations 531
Cbc0038I Solution found of -72000
Cbc0038I After further testing solution no better than previous of -72000
Cbc0038I Before mini branch and bound, 3437 integers at bound fixed and 0 continuous
Cbc0038I Full problem 955 rows 3443 columns, reduced to 2 rows 3 columns
Cbc0038I Mini branch and bound did not improve solution (18.74 seconds)
Cbc0038I Round again with cutoff of -72007.8
Cbc0038I Pass   3: suminf.    1.01084 (4) obj. -72007.8 iterations 0
Cbc0038I Pass   4: suminf.    0.46565 (3) obj. -72007.8 iterations 864
Cbc0038I Pass   5: suminf.    1.01084 (4) obj. -72007.8 iterations 976
Cbc0038I Pass   6: suminf.    1.65441 (7) obj. -72007.8 iterations 882
Cbc0038I Pass   7: suminf.    1.13162 (4) obj. -72007.8 iterations 813
Cbc0038I Pass   8: suminf.    0.92536 (2) obj. -72007.8 iterations 858
Cbc0038I Pass   9: suminf.    1.31344 (4) obj. -72007.8 iterations 1029
Cbc0038I Pass  10: suminf.    1.06565 (3) obj. -72007.8 iterations 857
Cbc0038I Pass  11: suminf.    1.31344 (4) obj. -72007.8 iterations 971
Cbc0038I Pass  12: suminf.    1.28587 (7) obj. -72007.8 iterations 980
Cbc0038I No solution found this major pass
Cbc0038I Before mini branch and bound, 3156 integers at bound fixed and 0 continuous
Cbc0038I Full problem 955 rows 3443 columns, reduced to 12 rows 37 columns
Cbc0038I Mini branch and bound did not improve solution (19.03 seconds)
Cbc0038I After 19.03 seconds - Feasibility pump exiting with objective of -72000 - took 0.97 seconds
Cbc0012I Integer solution of -72000 found by feasibility pump after 0 iterations and 0 nodes (19.03 seconds)
Cbc0038I Full problem 955 rows 3443 columns, reduced to 2 rows 2 columns
Cbc0013I At root node, 0 cuts changed objective from -72032.609 to -72032.609 in 1 passes
Cbc0014I Cut generator 0 (Probing) - 0 row cuts average 0.0 elements, 0 column cuts (0 active)  in 0.005 seconds - new frequency is -100
Cbc0014I Cut generator 1 (Gomory) - 0 row cuts average 0.0 elements, 0 column cuts (0 active)  in 0.001 seconds - new frequency is -100
Cbc0014I Cut generator 2 (Knapsack) - 0 row cuts average 0.0 elements, 0 column cuts (0 active)  in 0.003 seconds - new frequency is -100
Cbc0014I Cut generator 3 (Clique) - 0 row cuts average 0.0 elements, 0 column cuts (0 active)  in 0.000 seconds - new frequency is -100
Cbc0014I Cut generator 4 (MixedIntegerRounding2) - 0 row cuts average 0.0 elements, 0 column cuts (0 active)  in 0.001 seconds - new frequency is -100
Cbc0014I Cut generator 5 (FlowCover) - 0 row cuts average 0.0 elements, 0 column cuts (0 active)  in 0.001 seconds - new frequency is -100
Cbc0014I Cut generator 6 (TwoMirCuts) - 0 row cuts average 0.0 elements, 0 column cuts (0 active)  in 0.002 seconds - new frequency is -100
Cbc0010I After 0 nodes, 1 on tree, -72000 best solution, best possible -72029.13 (19.57 seconds)
Cbc0010I After 100 nodes, 45 on tree, -72000 best solution, best possible -72029.13 (21.76 seconds)
Cbc0010I After 200 nodes, 93 on tree, -72000 best solution, best possible -72029.13 (22.35 seconds)
Cbc0010I After 300 nodes, 146 on tree, -72000 best solution, best possible -72029.13 (22.91 seconds)
Cbc0010I After 400 nodes, 200 on tree, -72000 best solution, best possible -72029.13 (23.29 seconds)
Cbc0010I After 500 nodes, 249 on tree, -72000 best solution, best possible -72029.13 (23.73 seconds)
Cbc0010I After 600 nodes, 306 on tree, -72000 best solution, best possible -72029.13 (24.16 seconds)
Cbc0010I After 700 nodes, 356 on tree, -72000 best solution, best possible -72029.13 (24.55 seconds)
Cbc0010I After 800 nodes, 403 on tree, -72000 best solution, best possible -72029.13 (24.91 seconds)
.
.

(Truncated)
.
.
Cbc0010I After 256800 nodes, 12117 on tree, -72000 best solution, best possible -72029.13 (822.34 seconds)
C

1. How can we estimate the time required to complete the computations?
2. What's the current progress , how can i interpret this line - for ex

Cbc0010I After 800 nodes, 403 on tree, -72000 best solution, best possible -72029.13 (24.91 seconds)

3. It appears to be that this problem is stuck in a local optima , is there a way to finetune / find the most feasible solution within some gap/interval?

Kindly let me know if you have any questions?

Answer 1

1. How can we estimate the time required to complete the computations?

We can't. Just run your models with different data sets. That gives you some sense of what the solution time can be.

2. What's the current progress, how can i interpret this line - for ex `Cbc0010I After 800 nodes, 403 on tree, -72000 best solution, best possible -72029.13 (24.91 seconds).

This means CBC is busy for 25 seconds. The node counts (number of processed nodes and waiting nodes) are a bit technical to explain. Basically, we need to wait until the tree size starts to shrink. Unfortunately that happens typically quite near the end of the search. When the tree size has become zero the solver is done. The best found solution is the current best solution. The best possible is what is says: there can't be any solution better than this. These two numbers should get closer to each other. When the gap is zero, the solver is done.

3. It appears to be that this problem is stuck in a local optima , is there a way to finetune / find the most feasible solution within some gap/interval?

The term local optimum is more used in non-linear programming. But yes, sometimes the two bounds (best found and best possible) don't move for a while. Better formulations, and better solvers can help. Your problem has > 10k integer variables. That is not small anymore, and may need some work on the formulation side and/or better solvers with more powerful hardware (more threads).

Typically only integer feasible solutions are reported. If you are interested in the best non-feasible solution at any time, then you need to make the model elastic. (Always make it feasible but with a large penalty). Note that CBC found a feasibly integer solution after 19 seconds. After that it will always return the best integer solution if you stop early (e.g. on gap or time limit).