Cbc
Cbc copied to clipboard
coin-or
Logs not written in continous to log file for standalone solver
Hi everyone,
I am executing Cbc Solver in standalone mode through a Java wrapper (ProcessBluider library) that catches Cbc logs. I observe that for big models, my Java application does not print logs in continuous, and it can happen that logs "freeze" for several hours for some models, which increases dramatically optimisation time.
I can reproduce this behaviour on a more simple example.
For the MPS model attached (3aa654a2-899c-4ac7-aacd-b1a0dddb687f.zip), if I execute the following command, I get the logs in continuous.
Cbc-2.10.5/bin/cbc -seconds 600 -ratio 0.20 -timeM elapsed -log 1 -import 3aa654a2-899c-4ac7-aacd-b1a0dddb687f.mps -solve
However, if I want to route logs to a file, logs are written in jerks. In particular, I observe that the feasibility pump pass (Cbc0038I) is not written continuously like in the previous execution (without routing to a file) :
Cbc-2.10.5/bin/cbc -seconds 600 -ratio 0.20 -timeM elapsed -log 1 -import 3aa654a2-899c-4ac7-aacd-b1a0dddb687f.mps -solve > /tmp/my_log.log 2>&1
with the command to read logs in the file :
tail -f /tmp/my_log.log
In this example, logs stop to be written to the file after the line Cbc0038I Pass 30: (2.28 seconds) suminf. 3.49479 (35) obj. 305063 iterati for 15 seconds, and then logs resume to be written. To make concrete this behaviour, I have pressed Enter twice at this intermediate point to show that logs freeze for a while. The content of the log file is then :
Welcome to the CBC MILP Solver
Version: 2.10.5
Build Date: May 25 2020
command line - Cbc-2.10.5/bin/cbc -seconds 600 -ratio 0.20 -timeM elapsed -log 1 -import 3aa654a2-899c-4ac7-aacd-b1a0dddb687f.mps -solve (default strategy 1)
seconds was changed from 1e+100 to 600
ratioGap was changed from 0 to 0.2
Option for timeMode changed from cpu to elapsed
At line 1 NAME model
At line 3 ROWS
At line 13325 COLUMNS
At line 91424 RHS
At line 104745 BOUNDS
At line 110765 ENDATA
Problem model has 13319 rows, 22530 columns and 57091 elements
Coin0008I model read with 0 errors
Continuous objective value is 211670 - 0.10 seconds
Cgl0004I processed model has 6866 rows, 22315 columns (6006 integer (6006 of which binary)) and 44161 elements
Cbc0038I Initial state - 383 integers unsatisfied sum - 77.0602
Cbc0038I Pass 1: (0.41 seconds) suminf. 0.00000 (0) obj. 8.19526e+06 iterations 670
Cbc0038I Solution found of 8.19526e+06
Cbc0038I Relaxing continuous gives 491655
Cbc0038I Before mini branch and bound, 5615 integers at bound fixed and 15759 continuous
Cbc0038I Mini branch and bound did not improve solution (0.54 seconds)
Cbc0038I Round again with cutoff of 463838
Cbc0038I Pass 2: (1.18 seconds) suminf. 0.62204 (2) obj. 463838 iterations 3541
Cbc0038I Pass 3: (1.22 seconds) suminf. 0.28642 (5) obj. 463838 iterations 266
Cbc0038I Pass 4: (1.25 seconds) suminf. 0.00000 (0) obj. 463838 iterations 128
Cbc0038I Solution found of 463838
Cbc0038I Relaxing continuous gives 455557
Cbc0038I Before mini branch and bound, 5612 integers at bound fixed and 15679 continuous
Cbc0038I Full problem 6866 rows 22315 columns, reduced to 238 rows 360 columns
Cbc0038I Mini branch and bound improved solution from 455557 to 335803 (1.36 seconds)
Cbc0038I Freeing continuous variables gives a solution of 327957
Cbc0038I Round again with cutoff of 305063
Cbc0038I Pass 5: (1.61 seconds) suminf. 9.13061 (71) obj. 305063 iterations 756
Cbc0038I Pass 6: (1.63 seconds) suminf. 8.70822 (68) obj. 305063 iterations 37
Cbc0038I Pass 7: (1.68 seconds) suminf. 8.28899 (51) obj. 305063 iterations 335
Cbc0038I Pass 8: (1.71 seconds) suminf. 6.56688 (59) obj. 305063 iterations 139
Cbc0038I Pass 9: (1.73 seconds) suminf. 6.50090 (64) obj. 305063 iterations 45
Cbc0038I Pass 10: (1.77 seconds) suminf. 5.96250 (51) obj. 305063 iterations 196
Cbc0038I Pass 11: (1.79 seconds) suminf. 4.63122 (47) obj. 305063 iterations 96
Cbc0038I Pass 12: (1.82 seconds) suminf. 4.00375 (41) obj. 305063 iterations 88
Cbc0038I Pass 13: (1.86 seconds) suminf. 4.19358 (34) obj. 305063 iterations 156
Cbc0038I Pass 14: (1.89 seconds) suminf. 3.59497 (42) obj. 305063 iterations 110
Cbc0038I Pass 15: (1.91 seconds) suminf. 3.41290 (42) obj. 305063 iterations 88
Cbc0038I Pass 16: (1.95 seconds) suminf. 3.47466 (31) obj. 305063 iterations 149
Cbc0038I Pass 17: (1.97 seconds) suminf. 3.40996 (37) obj. 305063 iterations 47
Cbc0038I Pass 18: (1.99 seconds) suminf. 3.30312 (31) obj. 305063 iterations 111
Cbc0038I Pass 19: (2.02 seconds) suminf. 3.04935 (32) obj. 305063 iterations 33
Cbc0038I Pass 20: (2.05 seconds) suminf. 3.03050 (32) obj. 305063 iterations 97
Cbc0038I Pass 21: (2.07 seconds) suminf. 2.67961 (35) obj. 305063 iterations 31
Cbc0038I Pass 22: (2.10 seconds) suminf. 3.47721 (32) obj. 305063 iterations 61
Cbc0038I Pass 23: (2.12 seconds) suminf. 3.27155 (33) obj. 305063 iterations 20
Cbc0038I Pass 24: (2.14 seconds) suminf. 2.46887 (30) obj. 305063 iterations 46
Cbc0038I Pass 25: (2.16 seconds) suminf. 2.45105 (33) obj. 305063 iterations 5
Cbc0038I Pass 26: (2.19 seconds) suminf. 3.23001 (32) obj. 305063 iterations 68
Cbc0038I Pass 27: (2.20 seconds) suminf. 3.21083 (32) obj. 305063 iterations 21
Cbc0038I Pass 28: (2.23 seconds) suminf. 3.04609 (31) obj. 305063 iterations 59
Cbc0038I Pass 29: (2.25 seconds) suminf. 2.69520 (34) obj. 305063 iterations 33
Cbc0038I Pass 30: (2.28 seconds) suminf. 3.49479 (35) obj. 305063 iterati
ons 149
Cbc0038I Pass 31: (2.30 seconds) suminf. 3.22254 (36) obj. 305063 iterations 51
Cbc0038I Pass 32: (2.33 seconds) suminf. 3.12338 (29) obj. 305063 iterations 105
Cbc0038I Pass 33: (2.35 seconds) suminf. 3.11608 (32) obj. 305063 iterations 37
Cbc0038I Pass 34: (2.37 seconds) suminf. 3.16411 (32) obj. 305063 iterations 71
Cbc0038I No solution found this major pass
Cbc0038I Before mini branch and bound, 5555 integers at bound fixed and 15561 continuous
Cbc0038I Full problem 6866 rows 22315 columns, reduced to 280 rows 454 columns
Cbc0038I Mini branch and bound improved solution from 327957 to 314717 (2.51 seconds)
Cbc0038I Freeing continuous variables gives a solution of 313729
Cbc0038I Round again with cutoff of 277590
Cbc0038I Pass 34: (2.58 seconds) suminf. 11.34563 (88) obj. 277590 iterations 66
Cbc0038I Pass 35: (2.60 seconds) suminf. 10.68566 (86) obj. 277590 iterations 94
Cbc0038I Pass 36: (2.64 seconds) suminf. 8.77707 (77) obj. 277590 iterations 310
Cbc0038I Pass 37: (2.68 seconds) suminf. 6.77810 (78) obj. 277590 iterations 156
Cbc0038I Pass 38: (2.71 seconds) suminf. 7.93735 (69) obj. 277590 iterations 167
Cbc0038I Pass 39: (2.73 seconds) suminf. 7.62336 (72) obj. 277590 iterations 48
Cbc0038I Pass 40: (2.76 seconds) suminf. 6.45053 (79) obj. 277590 iterations 121
Cbc0038I Pass 41: (2.78 seconds) suminf. 6.14074 (79) obj. 277590 iterations 32
Cbc0038I Pass 42: (2.81 seconds) suminf. 6.10033 (64) obj. 277590 iterations 152
Cbc0038I Pass 43: (2.83 seconds) suminf. 5.69782 (68) obj. 277590 iterations 80
Cbc0038I Pass 44: (2.86 seconds) suminf. 5.35693 (67) obj. 277590 iterations 86
Cbc0038I Pass 45: (2.87 seconds) suminf. 5.18285 (67) obj. 277590 iterations 9
Cbc0038I Pass 46: (2.90 seconds) suminf. 6.16716 (65) obj. 277590 iterations 112
Cbc0038I Pass 47: (2.93 seconds) suminf. 5.60928 (65) obj. 277590 iterations 97
Cbc0038I Pass 48: (2.96 seconds) suminf. 5.02901 (61) obj. 277590 iterations 106
Cbc0038I Pass 49: (2.98 seconds) suminf. 4.90885 (66) obj. 277590 iterations 68
Cbc0038I Pass 50: (3.01 seconds) suminf. 5.93806 (64) obj. 277590 iterations 102
Cbc0038I Pass 51: (3.03 seconds) suminf. 5.62408 (68) obj. 277590 iterations 69
Cbc0038I Pass 52: (3.06 seconds) suminf. 5.74170 (65) obj. 277590 iterations 103
Cbc0038I Pass 53: (3.08 seconds) suminf. 5.47390 (68) obj. 277590 iterations 37
Cbc0038I Pass 54: (3.11 seconds) suminf. 5.04820 (69) obj. 277590 iterations 119
Cbc0038I Pass 55: (3.12 seconds) suminf. 4.86140 (70) obj. 277590 iterations 22
Cbc0038I Pass 56: (3.15 seconds) suminf. 5.45269 (62) obj. 277590 iterations 70
Cbc0038I Pass 57: (3.17 seconds) suminf. 5.34696 (65) obj. 277590 iterations 62
Cbc0038I Pass 58: (3.20 seconds) suminf. 5.59005 (67) obj. 277590 iterations 92
Cbc0038I Pass 59: (3.22 seconds) suminf. 5.00752 (67) obj. 277590 iterations 42
Cbc0038I Pass 60: (3.25 seconds) suminf. 6.15436 (69) obj. 277590 iterations 86
Cbc0038I Pass 61: (3.27 seconds) suminf. 5.98154 (73) obj. 277590 iterations 21
Cbc0038I Pass 62: (3.29 seconds) suminf. 4.86185 (71) obj. 277590 iterations 103
Cbc0038I Pass 63: (3.31 seconds) suminf. 4.40495 (69) obj. 277590 iterations 16
Cbc0038I No solution found this major pass
Cbc0038I Before mini branch and bound, 5505 integers at bound fixed and 15568 continuous
Cbc0038I Mini branch and bound did not improve solution (3.32 seconds)
Cbc0038I After 3.32 seconds - Feasibility pump exiting with objective of 313729 - took 2.95 seconds
Cbc0012I Integer solution of 313728.52 found by feasibility pump after 0 iterations and 0 nodes (3.37 seconds)
Cbc0038I Full problem 6866 rows 22315 columns, reduced to 907 rows 10958 columns - 79 fixed gives 705, 10648 - ok now
Cbc0038I Full problem 6866 rows 22315 columns, reduced to 705 rows 10648 columns
Cbc0012I Integer solution of 264182.18 found by DiveCoefficient after 5814 iterations and 0 nodes (21.70 seconds)
Cbc0031I 482 added rows had average density of 104.3195
Cbc0013I At root node, 482 cuts changed objective from 213486.39 to 263880.77 in 21 passes
Cbc0014I Cut generator 0 (Probing) - 31 row cuts average 79.8 elements, 0 column cuts (346 active) in 12.752 seconds - new frequency is -100
Cbc0014I Cut generator 1 (Gomory) - 1025 row cuts average 333.4 elements, 0 column cuts (0 active) in 1.300 seconds - new frequency is 1
Cbc0014I Cut generator 2 (Knapsack) - 0 row cuts average 0.0 elements, 0 column cuts (0 active) in 0.176 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) - 1292 row cuts average 75.1 elements, 0 column cuts (0 active) in 0.200 seconds - new frequency is 1
Cbc0014I Cut generator 5 (FlowCover) - 10 row cuts average 5.4 elements, 0 column cuts (0 active) in 0.148 seconds - new frequency is -100
Cbc0014I Cut generator 6 (TwoMirCuts) - 1373 row cuts average 195.6 elements, 0 column cuts (0 active) in 0.636 seconds - new frequency is 1
Cbc0011I Exiting as integer gap of 301.40943 less than 1e-10 or 20%
Cbc0001I Search completed - best objective 264182.1766999956, took 5814 iterations and 0 nodes (21.72 seconds)
Cbc0035I Maximum depth 0, 0 variables fixed on reduced cost
Cuts at root node changed objective from 213486 to 263881
Probing was tried 21 times and created 31 cuts of which 346 were active after adding rounds of cuts (12.752 seconds)
Gomory was tried 21 times and created 1025 cuts of which 0 were active after adding rounds of cuts (1.300 seconds)
Knapsack was tried 21 times and created 0 cuts of which 0 were active after adding rounds of cuts (0.176 seconds)
Clique was tried 21 times and created 0 cuts of which 0 were active after adding rounds of cuts (0.000 seconds)
MixedIntegerRounding2 was tried 21 times and created 1292 cuts of which 0 were active after adding rounds of cuts (0.200 seconds)
FlowCover was tried 21 times and created 10 cuts of which 0 were active after adding rounds of cuts (0.148 seconds)
TwoMirCuts was tried 21 times and created 1373 cuts of which 0 were active after adding rounds of cuts (0.636 seconds)
ZeroHalf was tried 1 times and created 0 cuts of which 0 were active after adding rounds of cuts (0.044 seconds)
Result - Optimal solution found (within gap tolerance)
Objective value: 264182.17670000
Lower bound: 263880.767
Gap: 0.00
Enumerated nodes: 0
Total iterations: 5814
Time (CPU seconds): 21.88
Time (Wallclock seconds): 22.12
Total time (CPU seconds): 21.92 (Wallclock seconds): 22.17
I use Coin Cbc 2.10.5 built from sources with parallel option on a Debian GNU/Linux 9.6 distribution.
Thank you for your help !
Having the same problem but it's freezing for hours. Don't even know if it continues afterwards as I always end up force closing it.
Using Version: 2.10.3 from PuLP on Windows.
