[Cbc] Long time waiting to start

[fpeng]

Hello cbc community,

I have a not-so-big problem that was given to cbc (with a custom 
heuristic that found an initial solution, and a different custom 
heuristic given to cbc as a cbcHeuristic). It solved for quite a while 
and actually exceeded my time limit of 900s. It looks like most of this 
time is spent "waiting to start", and only 78 nodes have been explored 
when it terminated. Can someone explain what's the difference between 
waiting to start and waiting for locks, and why this could have 
happened?

Thanks!
Fei Peng


Cbc0038I Full problem 12105 rows 100182 columns, reduced to 211 rows 
1166 columns
Cbc0031I 115 added rows had average density of 117.26957
Cbc0013I At root node, 115 cuts changed objective from -84283.25 to 
-84240.644 in 11 passes
Cbc0014I Cut generator 0 (Probing) - 112 row cuts average 2.0 elements, 
0 column cuts (0 active)
Cbc0014I Cut generator 1 (Gomory) - 0 row cuts average 0.0 elements, 0 
column cuts (0 active)
Cbc0014I Cut generator 2 (FlowCover) - 23 row cuts average 3.5 elements, 
0 column cuts (0 active)
Cbc0014I Cut generator 3 (MixedIntegerRounding) - 31 row cuts average 
531.2 elements, 0 column cuts (0 active)
Cbc0014I Cut generator 4 (ZeroHalf) - 2 row cuts average 472.5 elements, 
0 column cuts (0 active)
Cbc0010I After 0 nodes, 1 on tree, -71992.677 best solution, best 
possible -84240.644 (75.85 seconds)
Cbc0030I Thread 0 used 25 times,  waiting to start 89.973153,  188 
locks, 0.30886984 locked, 0.10045528 waiting for locks
Cbc0030I Thread 1 used 25 times,  waiting to start 445.67125,  192 
locks, 0.27866268 locked, 0.046955347 waiting for locks
Cbc0030I Thread 2 used 4 times,  waiting to start 524.39783,  55 locks, 
0.064212084 locked, 0.00049233437 waiting for locks
Cbc0030I Thread 3 used 4 times,  waiting to start 429.53649,  42 locks, 
0.051061392 locked, 0.001335144 waiting for locks
Cbc0030I Thread 4 used 5 times,  waiting to start 764.31872,  30 locks, 
0.058888197 locked, 0.0016386509 waiting for locks
Cbc0030I Thread 5 used 3 times,  waiting to start 786.5109,  18 locks, 
0.047199249 locked, 2.0265579e-05 waiting for locks
Cbc0030I Thread 6 used 3 times,  waiting to start 629.67802,  13 locks, 
0.047616482 locked, 0.013681173 waiting for locks
Cbc0030I Thread 7 used 4 times,  waiting to start 777.10115,  23 locks, 
0.061481237 locked, 0.013557196 waiting for locks
Cbc0030I Thread 8 used 4 times,  waiting to start 675.5297,  23 locks, 
0.074279547 locked, 0.00095534325 waiting for locks
Cbc0030I Thread 9 used 1 times,  waiting to start 687.876,  5 locks, 
0.028675079 locked, 0.029424429 waiting for locks
Cbc0030I Thread 10 used 1 times,  waiting to start 864.1456,  8 locks, 
0.031708479 locked, 0.013075113 waiting for locks
Cbc0030I Thread 11 used 6 times,  waiting to start 702.49968,  31 locks, 
0.12669396 locked, 0.063187122 waiting for locks
Cbc0030I Thread 12 used 5 times,  waiting to start 841.02625,  24 locks, 
0.1313715 locked, 0.0071282387 waiting for locks
Cbc0030I Thread 13 used 1 times,  waiting to start 746.89347,  4 locks, 
0.028902531 locked, 4.529953e-06 waiting for locks
Cbc0030I Thread 14 used 1 times,  waiting to start 877.92013,  4 locks, 
0.032623291 locked, 0.011171103 waiting for locks
Cbc0030I Thread 15 used 1 times,  waiting to start 984.92224,  3 locks, 
0.032584429 locked, 4.2915344e-06 waiting for locks
Cbc0030I Main thread 588.77125 waiting for threads,  189 locks, 
0.00040817261 locked, 0.045080185 waiting for locks
Cbc0020I Exiting on maximum time
Cbc0005I Partial search - best objective -71992.677 (best possible 
-84240.644), took 214997 iterations and 78 nodes (1087.32 seconds)
Cbc0032I Strong branching done 1788 times (1216302 iterations), fathomed 
3 nodes and fixed 0 variables
Cbc0035I Maximum depth 19, 0 variables fixed on reduced cost