[Cbc] Long time waiting to start

[John Forrest]

Waiting to start is when a thread is idle and has not been given a 
problem to solve.  Locks are when we need to make sure we don't 
overwrite shared data.

Initially just one thread has a problem so 15 threads have to wait.  If 
that branch is feasible then we can use two threads and so on.  If many 
branches are infeasible then it may be difficult to use 16 threads.  You 
can see behaviour by looking at log (if it runs long enough) e.g. with

Cbc0010I After 0 nodes, 1 on tree, 1e+50 best solution, best possible 
79.854439 (4.58 seconds)
Cbc0010I After 100 nodes, 30 on tree, 1e+50 best solution, best possible 
151 (6.82 seconds)

then 4 threads will be happy and with 16 you will get some inefficiency.

The real problem is why is it taking so many iterations per node - 3000 
iterations a node seems a lot on a problem with 12000 rows. If you can 
put the problem somewhere I can download it, then I can see what the 
problem is.

John Forrest
On 04/03/15 21:29, fpeng wrote:
> 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
>
> _______________________________________________
> Cbc mailing list
> Cbc at list.coin-or.org
> http://list.coin-or.org/mailman/listinfo/cbc
>
>