Monday, July 7, 2008

Bug in GAMS/Cplex link

GAMS/Cplex destroys here a perfectly good integer solution in the final LP. In that final LP the integers are fixed and the resulting LP is solved to get some dual information. In this case a resource limit is hit during this final LP and all is thrown away. Of course this is not what we want to see. The code in the GAMS/Cplex link related to this final LP solve need some careful inspection as we have seen problems with this part before.

Repeating presolve.
Tried aggregator 2 times.
MIP Presolve eliminated 1679 rows and 1752 columns.
MIP Presolve modified 4 coefficients.
Aggregator did 23 substitutions.
Reduced MIP has 184571 rows, 180577 columns, and 758788 nonzeros.
Represolve time = 1.63 sec.
Clique table members: 37.
MIP emphasis: optimality.
MIP search method: dynamic search.
Parallel mode: opportunistic, using up to 4 threads.
Root relaxation solution time = 137.66 sec.

Nodes Cuts/
Node Left Objective IInf Best Integer Best Node ItCnt Gap

0 0 14462.2442 195 14527.9285 14462.2442 178843 0.45%
Heuristic still looking.
Heuristic still looking.
* 0+ 0 14525.7851 14462.2442 178843 0.44%
0 2 14462.2442 195 14525.7851 14462.2442 178843 0.44%
Elapsed real time = 4637.89 sec. (tree size = 0.00 MB, solutions = 8)
100 99 14479.0518 197 14525.7851 14463.9712 232491 0.43%
Cuts: 15
200 197 14490.7443 197 14525.7851 14463.9712 277649 0.43%
* 295+ 286 14525.5834 14463.9712 344217 0.42%
300 295 14505.3123 147 14525.5834 14463.9712 336888 0.42%
400 395 14514.1868 145 14525.5834 14463.9712 368746 0.42%
* 433+ 408 14525.5412 14463.9712 378611 0.42%
500 476 14494.6548 134 14525.5412 14463.9712 420167 0.42%
Impl Bds: 1
* 544+ 497 14515.8473 14463.9712 437352 0.36%
* 545+ 498 14515.3114 14465.4987 441214 0.34%
Fixing integer variables, and solving final LP...
Tried aggregator 1 time.
LP Presolve eliminated 188052 rows and 205219 columns.
Aggregator did 6758 substitutions.
Reduced LP has 157128 rows, 152946 columns, and 633350 nonzeros.
Presolve time = 1.13 sec.
Initializing dual steep norms . . .

Iteration log . . .
Iteration: 1 Dual objective = 6057.310401
Perturbation started.
Iteration: 102 Dual objective = 6057.310401
Iteration: 878 Dual objective = 7666.791470
Iteration: 1500 Dual objective = 9296.038149
Iteration: 2211 Dual objective = 9824.349977
Iteration: 2889 Dual objective = 10466.849833
Iteration: 3542 Dual objective = 10641.384471
Iteration: 4170 Dual objective = 10892.599730
Iteration: 4795 Dual objective = 10929.911432
Iteration: 5399 Dual objective = 11011.407094
Iteration: 6008 Dual objective = 11026.152235
Iteration: 6591 Dual objective = 11028.613181
Iteration: 7181 Dual objective = 11037.046345
Iteration: 7736 Dual objective = 11039.881723
Iteration: 8318 Dual objective = 11042.152553
Iteration: 8957 Dual objective = 11044.445128
Iteration: 9519 Dual objective = 11046.434903
Iteration: 10119 Dual objective = 11048.475834
Iteration: 10685 Dual objective = 11054.973343
Iteration: 11233 Dual objective = 11057.071503
Iteration: 11774 Dual objective = 11059.407174
Iteration: 12324 Dual objective = 11062.135289
Iteration: 12869 Dual objective = 11064.387325
Iteration: 13434 Dual objective = 11066.637098
Iteration: 14031 Dual objective = 11074.488101
Iteration: 14579 Dual objective = 11076.981695
Iteration: 15089 Dual objective = 11079.444173
Iteration: 15621 Dual objective = 11082.365429
Iteration: 16145 Dual objective = 11084.623184
Iteration: 16667 Dual objective = 11087.253554
Iteration: 17199 Dual objective = 11091.205312
Iteration: 17715 Dual objective = 11098.091964
Iteration: 18262 Dual objective = 11102.884193
Iteration: 18788 Dual objective = 11106.328123
Iteration: 19295 Dual objective = 11109.503749
Iteration: 19815 Dual objective = 11114.531394
Iteration: 20324 Dual objective = 11117.863392
Iteration: 20829 Dual objective = 11120.704519
Iteration: 21333 Dual objective = 11123.060983
Iteration: 21830 Dual objective = 11128.551740
Iteration: 22365 Dual objective = 11134.127949
Iteration: 22899 Dual objective = 11137.954843
Iteration: 23365 Dual objective = 11141.672390
Iteration: 23912 Dual objective = 11149.342966
Iteration: 24419 Dual objective = 11158.316182
Iteration: 24957 Dual objective = 11179.374543
Iteration: 25473 Dual objective = 11188.140937
Iteration: 26019 Dual objective = 11193.656639
Iteration: 26520 Dual objective = 11198.854075
Iteration: 27113 Dual objective = 11209.155858
Iteration: 27664 Dual objective = 11220.384286
Iteration: 28172 Dual objective = 11228.944391
Iteration: 28665 Dual objective = 11240.074822
Iteration: 29163 Dual objective = 11246.180510
Iteration: 29682 Dual objective = 11257.264795
Iteration: 30218 Dual objective = 11275.780600
Iteration: 30745 Dual objective = 11286.175702
Iteration: 31223 Dual objective = 11293.826527
Iteration: 31706 Dual objective = 11322.912597
Iteration: 32242 Dual objective = 11345.656014
Iteration: 32792 Dual objective = 11355.546099
Elapsed time = 10.16 sec. (33000 iterations).
Iteration: 33340 Dual objective = 11365.028247
Iteration: 33859 Dual objective = 11378.128137
Iteration: 34425 Dual objective = 11384.719065
Iteration: 35106 Dual objective = 11400.809173
Iteration: 35714 Dual objective = 11410.512205
Iteration: 36277 Dual objective = 11418.067340
Iteration: 36899 Dual objective = 11440.861112
Iteration: 37511 Dual objective = 11449.609068
Iteration: 38161 Dual objective = 11461.996251
Iteration: 38848 Dual objective = 11466.467047
Iteration: 39434 Dual objective = 11479.910077
Iteration: 40002 Dual objective = 11493.030687
Iteration: 40642 Dual objective = 11500.724057
Iteration: 41217 Dual objective = 11521.687737
Iteration: 41825 Dual objective = 11532.637059
Iteration: 42526 Dual objective = 11536.771010
Iteration: 43171 Dual objective = 11541.448080
Iteration: 43797 Dual objective = 11552.971322
Iteration: 44466 Dual objective = 11565.311371
Iteration: 45131 Dual objective = 11569.962544
Iteration: 45787 Dual objective = 11574.606053
Iteration: 46461 Dual objective = 11578.764831
Iteration: 47118 Dual objective = 11588.017836
Iteration: 47736 Dual objective = 11618.652276
Iteration: 48420 Dual objective = 11627.910620
Iteration: 49100 Dual objective = 11639.618577
Iteration: 49705 Dual objective = 11709.154815
Iteration: 50257 Dual objective = 11724.330084
Iteration: 50890 Dual objective = 11731.428433
Iteration: 51600 Dual objective = 11736.597227
Iteration: 52294 Dual objective = 11744.978937
Iteration: 52895 Dual objective = 11753.709220
Iteration: 53467 Dual objective = 11765.418835
Iteration: 54163 Dual objective = 11773.818329
Iteration: 54869 Dual objective = 11780.943803
Iteration: 55550 Dual objective = 11786.399499
Iteration: 56219 Dual objective = 11792.327244
Iteration: 56894 Dual objective = 11796.992322
Iteration: 57548 Dual objective = 11800.527954
Iteration: 58177 Dual objective = 11825.388844
Iteration: 58846 Dual objective = 11838.119491
Iteration: 59544 Dual objective = 11853.442610
Iteration: 60147 Dual objective = 11864.848136
Iteration: 60781 Dual objective = 11891.687076
Iteration: 61425 Dual objective = 11906.740461
Iteration: 62087 Dual objective = 11940.561093
Iteration: 62737 Dual objective = 11975.219161
Elapsed time = 20.33 sec. (63000 iterations).
Iteration: 63454 Dual objective = 12002.296415
Iteration: 64108 Dual objective = 12015.440378
Iteration: 64818 Dual objective = 12022.395479
Iteration: 65509 Dual objective = 12029.058176
Iteration: 66219 Dual objective = 12037.336718
Iteration: 66913 Dual objective = 12048.634801
Iteration: 67550 Dual objective = 12098.951656
Iteration: 68233 Dual objective = 12148.667809
Iteration: 68861 Dual objective = 12204.554100
Iteration: 69489 Dual objective = 12260.068947
Iteration: 70151 Dual objective = 12271.769079
Iteration: 71067 Dual objective = 12340.904160
Iteration: 71916 Dual objective = 12469.081691
Iteration: 72832 Dual objective = 12538.397179
Iteration: 73689 Dual objective = 12573.657042
Iteration: 74580 Dual objective = 12633.804960
Iteration: 75466 Dual objective = 12671.034083
Iteration: 76282 Dual objective = 12709.759093
Iteration: 77157 Dual objective = 12731.565162
Iteration: 78006 Dual objective = 12791.001813
Iteration: 78861 Dual objective = 12826.806885
Iteration: 79716 Dual objective = 12862.410390
Iteration: 80579 Dual objective = 12894.168594
Iteration: 81454 Dual objective = 12987.178433
Iteration: 82296 Dual objective = 13103.926493
Iteration: 83211 Dual objective = 13321.544934
Iteration: 84091 Dual objective = 13443.441166
Iteration: 84973 Dual objective = 13562.343061
Iteration: 85890 Dual objective = 13644.284360
Iteration: 86698 Dual objective = 13720.220758
Iteration: 87401 Dual objective = 13816.562168
Iteration: 88221 Dual objective = 13881.829495
Iteration: 88849 Dual objective = 13929.142875
Iteration: 89610 Dual objective = 13984.379103
Iteration: 90422 Dual objective = 14047.173914
Iteration: 91270 Dual objective = 14115.140590
Iteration: 92125 Dual objective = 14171.749778
Iteration: 93089 Dual objective = 14217.148596
Iteration: 93982 Dual objective = 14263.230690
Elapsed time = 30.39 sec. (94000 iterations).
Iteration: 94826 Dual objective = 14320.598940
Iteration: 95556 Dual objective = 14345.861439
Iteration: 96804 Dual objective = 14379.439770
Iteration: 97540 Dual objective = 14399.637101
Iteration: 98353 Dual objective = 14415.843344
Iteration: 99135 Dual objective = 14486.973327
Iteration: 100230 Dual objective = 14507.696311
Iteration: 101753 Dual objective = 14524.245965
Iteration: 102889 Dual objective = 14536.589082
Iteration: 104245 Dual objective = 14546.083262
Iteration: 105151 Dual objective = 14553.547999
Iteration: 106121 Dual objective = 14558.473735
Iteration: 107058 Dual objective = 14562.528434
Iteration: 107846 Dual objective = 14564.898252
Iteration: 108562 Dual objective = 14568.707843
Iteration: 109171 Dual objective = 14569.741540
Iteration: 110267 Dual objective = 14570.230927
Iteration: 111442 Dual objective = 14570.636373
Iteration: 113264 Dual objective = 14570.833100
Iteration: 115164 Dual objective = 14571.039823
Removing perturbation.
Iteration: 115366 Scaled dual infeas = 0.068957
Iteration: 118957 Scaled dual infeas = 0.000000
Iteration: 119095 Dual objective = 14519.183719
Iteration: 119885 Dual objective = 14526.787115
Elapsed time = 40.78 sec. (120000 iterations).
Iteration: 121024 Dual objective = 14527.291310
Iteration: 121967 Dual objective = 14527.804039
Iteration: 122614 Dual objective = 14527.921795
Removing shift (76).
Iteration: 122721 Scaled dual infeas = 0.000158
Iteration: 122814 Dual objective = 14527.911155
Removing shift (3).

Resource limit exceeded.

MIP Solution: 14527.928528 (0 iterations, 0 nodes)
Final Solve: 14527.928596 (122973 iterations)

Best possible: -inf
Absolute gap: na
Relative gap: na



A workaround is to increase reslim (so we have enough time to finish the final solve) or to decrease reslim (so we stop on time and allocate extra time to do the final solve). Note: as the duals are being used, it was no option to skip the final solve using option solvefinal.


Update: the GAMS people say the reported solution (primal+dual) should be ok.
I only have the log file, so I don't have evidence otherwise.