Wednesday, May 4, 2016

Cplex and counting solutions

When running MIP models I basically stare somewhat obsessively at the log. Hence I noticed:

     71    73        0.0423   292       18.1387        0.0000    87092  100.00%
     72    74        0.2139   380       18.1387        0.0000    90725  100.00%
Elapsed time = 688.25 sec. (76733.97 ticks, tree = 0.01 MB, solutions = 2)
     81    83        0.0980   354       18.1387        0.0000    98918  100.00%
*    87+   87                           17.7364        0.0000           100.00%
Found incumbent of value 17.736352 after 688.25 sec. (76733.97 ticks)
     94    96        0.1251   291       17.7364        0.0000   106148  100.00%
     98   100        0.0899   325       17.7364        0.0000   111398  100.00%
     99   101        0.0648   296       17.7364        0.0000   111683  100.00%
    103   105        0.1777   286       17.7364        0.0000   113016  100.00%
    104   106        0.1122   367       17.7364        0.0000   116380  100.00%
    111   113        0.0000   130       17.7364        0.0000   122226  100.00%
    113   115        0.1117   296       17.7364        0.0000   123107  100.00%
    114   116        0.0491   229       17.7364        0.0000   123240  100.00%
    115   117        0.0961   371       17.7364        0.0000   125152  100.00%
Elapsed time = 688.27 sec. (79705.40 ticks, tree = 0.01 MB, solutions = 2)
    116   118        0.0049   284       17.7364        0.0000   125684  100.00%
                                                 ZeroHalf: 73                 
    117   119        0.0196   352       17.7364        0.0000   127374  100.00%
    118   120        0.0000   113       17.7364        0.0000   127401  100.00%
    119   121        0.0921   383       17.7364        0.0000   130049  100.00%
    120   122        0.0029   297       17.7364        0.0000   130295  100.00%
    121   123        0.0564   400       17.7364        0.0000   134590  100.00%
    122   124        0.0029   276       17.7364        0.0000   134734  100.00%
    123   125        0.0210   391       17.7364        0.0000   142995  100.00%
    124   126        0.0319   323       17.7364        0.0000   144228  100.00%
    125   127        0.0196   334       17.7364        0.0000   144391  100.00%
Elapsed time = 866.91 sec. (91170.15 ticks, tree = 0.01 MB, solutions = 3)
    130   132        0.0114   442       17.7364        0.0000   154043  100.00%
    131   133        0.0480   292       17.7364        0.0000   155292  100.00%
    137   139        0.0539   137       17.7364        0.0000   160339  100.00%

First I thought, wow, Cplex needs a lot of time to do a single addition: the third solution only is noticed many nodes and many seconds later. But then look at the timings marked in orange. There is actually very little time between logs lines where the solution is found and where the number of solutions is reported. (This was a run with multiple threads, no doubt that played a role).