What causes CPU time to significantly exceed wall time? #577

spkelle2 · 2023-03-11T20:31:37Z

spkelle2
Mar 11, 2023

Hi there, I have a cross platform project that uses CBC as a dependency, and I'm wondering why my linux build doesn't appear to have the respect for time limits that I would expect (and am seeing from my mac build.) On both platforms, I run the following command:

./cbc -import <path_to_mps_files>/rhs_s2_i01.mps -seconds 50 -solve -quit

Could anyone tell me what might cause the difference in the outputs below? Here is the problem I am solving if it helps.

Mac compiler:

(base) sean@Seans-MBP vws % clang++ --version
Apple clang version 14.0.0 (clang-1400.0.29.202)
Target: arm64-apple-darwin22.2.0
Thread model: posix
InstalledDir: /Library/Developer/CommandLineTools/usr/bin

Linux compiler:

(vws) sek519@polyp15:~/warm_starting/vws/Debug$ g++ --version
g++ (conda-forge gcc 12.2.0-19) 12.2.0
Copyright (C) 2022 Free Software Foundation, Inc.
This is free software; see the source for copying conditions.  There is NO
warranty; not even for MERCHANTABILITY or FITNESS FOR A PARTICULAR PURPOSE.

Coinbrew build commands (same on both platforms):

./coinbrew fetch Cbc@master --no-prompt
./coinbrew build Cbc --no-prompt --prefix=<path_to_home>/coin-or/dist --enable-debug --enable-shared --tests=none ADD_CXXFLAGS="-DSAVE_NODE_INFO"

Mac output:

/Users/sean/coin-or/dist/bin/cbc -import /Users/sean/Documents/school/phd/research/warm_starting/vws/src/test/datasets/vary_rhs/series_2/rhs_s2_i01.mps -seconds 50 -solve -quit
Welcome to the CBC MILP Solver
Version: Devel (unstable)
Build Date: Mar  2 2023
command line - -import /Users/sean/Documents/school/phd/research/warm_starting/vws/src/test/datasets/vary_rhs/series_2/rhs_s2_i01.mps -seconds 50 -solve -quit (default strategy 1)
At line 1 NAME          rhs_s2_i01
At line 2 ROWS
At line 1254 COLUMNS
At line 128712 RHS
At line 128963 BOUNDS
At line 129964 ENDATA
Problem rhs_s2_i01 has 1250 rows, 1000 columns and 126955 elements
Coin0008I rhs_s2_i01 read with 0 errors
seconds was changed from 1e+08 to 50
Continuous objective value is -17228 - 0.267229 seconds
Cgl0004I processed model has 726 rows, 738 columns (238 integer (238 of which binary)) and 125908 elements
Coin3009W Conflict graph built in 0.001 seconds, density: 0.022%
Cgl0015I Clique Strengthening extended 0 cliques, 0 were dominated
Cbc0038I Initial state - 47 integers unsatisfied sum - 12.7297
Cbc0038I Pass   1: suminf.    0.00000 (1) obj. -14316 iterations 252
Cbc0038I Pass   2: suminf.    0.00000 (0) obj. -14316 iterations 0
Cbc0038I Solution found of -14316
Cbc0038I Relaxing continuous gives -16824.7
Cbc0038I Before mini branch and bound, 190 integers at bound fixed and 297 continuous
Cbc0038I Full problem 726 rows 738 columns, reduced to 346 rows 251 columns
Cbc0038I Mini branch and bound improved solution from -16824.7 to -17123.7 (6.16 seconds)
Cbc0038I Freeing continuous variables gives a solution of -17131.5
Cbc0038I Round again with cutoff of -17141.1
Cbc0038I Reduced cost fixing fixed 47 variables on major pass 2
Cbc0038I Pass   3: suminf.    2.53566 (15) obj. -17141.1 iterations 1074
Cbc0038I Pass   4: suminf.    0.30875 (5) obj. -17141.1 iterations 246
Cbc0038I Pass   5: suminf.    0.69577 (3) obj. -17141.1 iterations 190
Cbc0038I Pass   6: suminf.    0.12492 (3) obj. -17141.1 iterations 159
Cbc0038I Pass   7: suminf.    0.80266 (4) obj. -17141.1 iterations 125
Cbc0038I Pass   8: suminf.    0.25634 (2) obj. -17141.1 iterations 142
Cbc0038I Pass   9: suminf.    0.22427 (1) obj. -17141.1 iterations 149
Cbc0038I Pass  10: suminf.    0.13453 (2) obj. -17141.1 iterations 116
Cbc0038I Pass  11: suminf.    0.33973 (2) obj. -17141.1 iterations 129
Cbc0038I Pass  12: suminf.    3.61932 (16) obj. -17141.1 iterations 178
Cbc0038I Pass  13: suminf.    2.19361 (13) obj. -17141.1 iterations 54
Cbc0038I Pass  14: suminf.    1.25920 (8) obj. -17141.1 iterations 137
Cbc0038I Pass  15: suminf.    0.81783 (8) obj. -17141.1 iterations 41
Cbc0038I Pass  16: suminf.    2.88511 (9) obj. -17141.1 iterations 101
Cbc0038I Pass  17: suminf.    1.52568 (11) obj. -17141.1 iterations 64
Cbc0038I Pass  18: suminf.    2.52316 (11) obj. -17141.1 iterations 142
Cbc0038I Pass  19: suminf.    1.30537 (7) obj. -17141.1 iterations 55
Cbc0038I Pass  20: suminf.    0.76207 (5) obj. -17141.1 iterations 21
Cbc0038I Pass  21: suminf.    1.66171 (8) obj. -17141.1 iterations 100
Cbc0038I Pass  22: suminf.    0.95551 (7) obj. -17141.1 iterations 85
Cbc0038I Pass  23: suminf.    2.19214 (9) obj. -17141.1 iterations 105
Cbc0038I Pass  24: suminf.    1.23464 (4) obj. -17141.1 iterations 46
Cbc0038I Pass  25: suminf.    0.97357 (6) obj. -17141.1 iterations 67
Cbc0038I Pass  26: suminf.    1.23194 (7) obj. -17141.1 iterations 137
Cbc0038I Pass  27: suminf.    1.73619 (10) obj. -17141.1 iterations 97
Cbc0038I Pass  28: suminf.    1.37660 (6) obj. -17141.1 iterations 40
Cbc0038I Pass  29: suminf.    5.44105 (25) obj. -17141.1 iterations 101
Cbc0038I Pass  30: suminf.    3.01978 (16) obj. -17141.1 iterations 73
Cbc0038I Pass  31: suminf.    3.43831 (13) obj. -17141.1 iterations 108
Cbc0038I Pass  32: suminf.    2.51971 (10) obj. -17141.1 iterations 45
Cbc0038I No solution found this major pass
Cbc0038I Before mini branch and bound, 160 integers at bound fixed and 283 continuous
Cbc0038I Full problem 726 rows 738 columns, reduced to 406 rows 295 columns - 23 fixed gives 360, 272 - ok now
Cbc0038I Full problem 726 rows 738 columns, reduced to 360 rows 272 columns
Cbc0038I Mini branch and bound improved solution from -17131.5 to -17159.6 (17.63 seconds)
Cbc0038I Round again with cutoff of -17173.3
Cbc0038I Reduced cost fixing fixed 74 variables on major pass 3
Cbc0038I Pass  32: suminf.    3.48231 (19) obj. -17173.3 iterations 58
Cbc0038I Pass  33: suminf.    1.32671 (9) obj. -17173.3 iterations 136
Cbc0038I Pass  34: suminf.    1.09748 (7) obj. -17173.3 iterations 165
Cbc0038I Pass  35: suminf.    1.81485 (7) obj. -17173.3 iterations 125
Cbc0038I Pass  36: suminf.    1.41164 (6) obj. -17173.3 iterations 21
Cbc0038I Pass  37: suminf.    0.92864 (5) obj. -17173.3 iterations 54
Cbc0038I Pass  38: suminf.    0.60133 (5) obj. -17173.3 iterations 31
Cbc0038I Pass  39: suminf.    1.57858 (5) obj. -17173.3 iterations 75
Cbc0038I Pass  40: suminf.    0.79262 (7) obj. -17173.3 iterations 48
Cbc0038I Pass  41: suminf.    1.06726 (7) obj. -17173.3 iterations 130
Cbc0038I Pass  42: suminf.    0.61391 (4) obj. -17173.3 iterations 48
Cbc0038I Pass  43: suminf.    1.97460 (7) obj. -17173.3 iterations 58
Cbc0038I Pass  44: suminf.    0.98015 (5) obj. -17173.3 iterations 55
Cbc0038I Pass  45: suminf.    1.67565 (7) obj. -17173.3 iterations 136
Cbc0038I Pass  46: suminf.    1.00031 (6) obj. -17173.3 iterations 106
Cbc0038I Pass  47: suminf.    0.78704 (6) obj. -17173.3 iterations 29
Cbc0038I Pass  48: suminf.    2.17705 (9) obj. -17173.3 iterations 100
Cbc0038I Pass  49: suminf.    1.70789 (9) obj. -17173.3 iterations 40
Cbc0038I Pass  50: suminf.    1.19355 (8) obj. -17173.3 iterations 70
Cbc0038I Pass  51: suminf.    2.36632 (13) obj. -17173.3 iterations 148
Cbc0038I Pass  52: suminf.    1.80821 (8) obj. -17173.3 iterations 37
Cbc0038I Pass  53: suminf.    1.46349 (9) obj. -17173.3 iterations 36
Cbc0038I Pass  54: suminf.    2.47820 (11) obj. -17173.3 iterations 157
Cbc0038I Pass  55: suminf.    1.77259 (8) obj. -17173.3 iterations 47
Cbc0038I Pass  56: suminf.    2.51336 (9) obj. -17173.3 iterations 126
Cbc0038I Pass  57: suminf.    1.27213 (7) obj. -17173.3 iterations 40
Cbc0038I Pass  58: suminf.    2.02738 (10) obj. -17173.3 iterations 95
Cbc0038I Pass  59: suminf.    1.98688 (8) obj. -17173.3 iterations 6
Cbc0038I Pass  60: suminf.    1.00863 (6) obj. -17173.3 iterations 129
Cbc0038I Pass  61: suminf.    0.78432 (6) obj. -17173.3 iterations 21
Cbc0038I No solution found this major pass
Cbc0038I Before mini branch and bound, 180 integers at bound fixed and 304 continuous
Cbc0038I Full problem 726 rows 738 columns, reduced to 366 rows 254 columns
Cbc0038I Mini branch and bound did not improve solution (27.68 seconds)
Cbc0038I After 27.68 seconds - Feasibility pump exiting with objective of -17159.6 - took 27.11 seconds
Cbc0012I Integer solution of -17159.568 found by feasibility pump after 0 iterations and 0 nodes (28.60 seconds)
Cbc0038I Full problem 726 rows 738 columns, reduced to 348 rows 437 columns - 16 fixed gives 316, 421 - ok now
Cbc0038I Full problem 726 rows 738 columns, reduced to 316 rows 421 columns
Cbc0012I Integer solution of -17160.772 found by RINS after 0 iterations and 0 nodes (42.43 seconds)
Cbc0031I 25 added rows had average density of 546.56
Cbc0013I At root node, 25 cuts changed objective from -17228.024 to -17224.182 in 18 passes
Cbc0014I Cut generator 0 (Probing) - 0 row cuts average 0.0 elements, 0 column cuts (0 active)  in 0.010 seconds - new frequency is -100
Cbc0014I Cut generator 1 (Gomory) - 477 row cuts average 545.2 elements, 0 column cuts (0 active)  in 2.024 seconds - new frequency is -100
Cbc0014I Cut generator 2 (Knapsack) - 0 row cuts average 0.0 elements, 0 column cuts (0 active)  in 0.023 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 (OddWheel) - 0 row cuts average 0.0 elements, 0 column cuts (0 active)  in 0.000 seconds - new frequency is -100
Cbc0014I Cut generator 5 (MixedIntegerRounding2) - 0 row cuts average 0.0 elements, 0 column cuts (0 active)  in 0.312 seconds - new frequency is -100
Cbc0014I Cut generator 6 (FlowCover) - 0 row cuts average 0.0 elements, 0 column cuts (0 active)  in 0.045 seconds - new frequency is -100
Cbc0010I After 0 nodes, 1 on tree, -17160.772 best solution, best possible -17224.182 (49.98 seconds)
Cbc0020I Exiting on maximum time
Cbc0005I Partial search - best objective -17160.772 (best possible -17224.182), took 913 iterations and 1 nodes (50.05 seconds)
Cbc0032I Strong branching done 92 times (4391 iterations), fathomed 0 nodes and fixed 0 variables
Cbc0035I Maximum depth 1, 69 variables fixed on reduced cost
Cuts at root node changed objective from -17228 to -17224.2
Probing was tried 18 times and created 0 cuts of which 0 were active after adding rounds of cuts (0.009924 seconds)
Gomory was tried 18 times and created 477 cuts of which 0 were active after adding rounds of cuts (2.02414 seconds)
Knapsack was tried 18 times and created 0 cuts of which 0 were active after adding rounds of cuts (0.023499 seconds)
Clique was tried 18 times and created 0 cuts of which 0 were active after adding rounds of cuts (0.000124 seconds)
OddWheel was tried 18 times and created 0 cuts of which 0 were active after adding rounds of cuts (0.000188 seconds)
MixedIntegerRounding2 was tried 18 times and created 0 cuts of which 0 were active after adding rounds of cuts (0.31215 seconds)
FlowCover was tried 18 times and created 0 cuts of which 0 were active after adding rounds of cuts (0.045001 seconds)
TwoMirCuts was tried 1 times and created 0 cuts of which 0 were active after adding rounds of cuts (0.055235 seconds)
ZeroHalf was tried 1 times and created 0 cuts of which 0 were active after adding rounds of cuts (1e-06 seconds)

Result - Stopped on time limit
Objective value:                -17160.767449
Lower bound:                    -17224.2
Gap:                            0.00368172
Enumerated nodes:               1
Total iterations:               913
Time (CPU seconds):             53.1439
Time (Wallclock seconds):       54.2545
Total time (CPU seconds):       53.1883   (Wallclock seconds):       54.3021

Linux Ouput:

(vws) sek519@polyp15:~/coin-or/dist/bin$ ./cbc -import /home/sek519/warm_starting/vws/src/test/datasets/vary_rhs/series_2/rhs_s2_i01.mps -seconds 50 -solve -quit
Welcome to the CBC MILP Solver
Version: Devel (unstable)
Build Date: Mar 10 2023
command line - -import /home/sek519/warm_starting/vws/src/test/datasets/vary_rhs/series_2/rhs_s2_i01.mps -seconds 50 -solve -quit (default strategy 1)
At line 1 NAME          rhs_s2_i01
At line 2 ROWS
At line 1254 COLUMNS
At line 128712 RHS
At line 128963 BOUNDS
At line 129964 ENDATA
Problem rhs_s2_i01 has 1250 rows, 1000 columns and 126955 elements
Coin0008I rhs_s2_i01 read with 0 errors
seconds was changed from 1e+08 to 50
Continuous objective value is -17228 - 4.7 seconds
Cgl0004I processed model has 726 rows, 738 columns (238 integer (238 of which binary)) and 125908 elements
Coin3009W Conflict graph built in 0.007 seconds, density: 0.022%
Cgl0015I Clique Strengthening extended 0 cliques, 0 were dominated
Cbc0038I Initial state - 47 integers unsatisfied sum - 12.7297
Cbc0038I Pass   1: suminf.    0.00000 (1) obj. -14316 iterations 252
Cbc0038I Pass   2: suminf.    0.00000 (0) obj. -14316 iterations 0
Cbc0038I Solution found of -14316
Cbc0038I Relaxing continuous gives -16824.7
Cbc0038I Before mini branch and bound, 190 integers at bound fixed and 297 continuous
Cbc0038I Full problem 726 rows 738 columns, reduced to 346 rows 251 columns
Cbc0038I Mini branch and bound improved solution from -16824.7 to -17111.4 (165.48 seconds)
Cbc0038I Freeing continuous variables gives a solution of -17136.8
Cbc0038I After 167.83 seconds - Feasibility pump exiting with objective of -17136.8 - took 158.88 seconds
Cbc0012I Integer solution of -17136.814 found by feasibility pump after 0 iterations and 0 nodes (189.71 seconds)
Cbc0020I Exiting on maximum time
Cbc0005I Partial search - best objective -17136.814 (best possible -17228.024), took 0 iterations and 0 nodes (190.20 seconds)
Cbc0035I Maximum depth 0, 46 variables fixed on reduced cost
Cuts at root node changed objective from -17228 to -17228
Probing was tried 0 times and created 0 cuts of which 0 were active after adding rounds of cuts (0 seconds)
Gomory was tried 0 times and created 0 cuts of which 0 were active after adding rounds of cuts (0 seconds)
Knapsack was tried 0 times and created 0 cuts of which 0 were active after adding rounds of cuts (0 seconds)
Clique was tried 0 times and created 0 cuts of which 0 were active after adding rounds of cuts (0 seconds)
OddWheel was tried 0 times and created 0 cuts of which 0 were active after adding rounds of cuts (0 seconds)
MixedIntegerRounding2 was tried 0 times and created 0 cuts of which 0 were active after adding rounds of cuts (0 seconds)
FlowCover was tried 0 times and created 0 cuts of which 0 were active after adding rounds of cuts (0 seconds)
TwoMirCuts was tried 0 times and created 0 cuts of which 0 were active after adding rounds of cuts (0 seconds)
ZeroHalf was tried 0 times and created 0 cuts of which 0 were active after adding rounds of cuts (0 seconds)

Result - Stopped on time limit
Objective value:                -17136.8144069
Lower bound:                    -17228
Gap:                            0.00529423
Enumerated nodes:               0
Total iterations:               0
Time (CPU seconds):             236.64
Time (Wallclock seconds):       66.155
Total time (CPU seconds):       237.124   (Wallclock seconds):       66.3447

Provide feedback

Saved searches

Use saved searches to filter your results more quickly

What causes CPU time to significantly exceed wall time? #577

{{title}}

Replies: 0 comments

Select a reply

What causes CPU time to significantly exceed wall time? #577

spkelle2 Mar 11, 2023

Replies: 0 comments

spkelle2
Mar 11, 2023