Mismatch between solution returned and best found solution in solver log

[zolanaj]

We encountered a difference between the best found solution in the solver log for Xpress 9.2:

Concurrent statistics:
      Dual: 116729 simplex iterations, 64.75s
   Barrier: 500 barrier and 63482 simplex iterations, 192.05s
            Barrier used 11 threads 6 cores
            Barrier used AVX support, crossover used 8 thread
Optimal solution found

   Its         Obj Value      S   Ninf  Nneg        Sum Inf  
116729       33552689.03      P      0     0        .000000  
Dual solved problem
  116729 simplex iterations in 192.09 seconds at time 194

Final objective                       : 3.355268902586088e+07
  Max primal violation      (abs/rel) :       0.0 /       0.0
  Max dual violation        (abs/rel) : 4.547e-13 / 1.238e-14
  Max complementarity viol. (abs/rel) :       0.0 /       0.0
High attention level predicted from matrix features

Starting root cutting & heuristics
Deterministic mode with up to 1 additional thread

 Its Type    BestSoln    BestBound   Sols    Add    Del     G
k         35670343.87  33552689.03      1                  5.
Heuristic search 'R' started
Heuristic R running (50000 LP iterations in   10.1 seconds)
R         33552689.03  33552689.03      2                 -0.
STOPPING - MIPRELSTOP target reached (MIPRELSTOP=0.01  gap=-2
Heuristic search 'R' stopped
 *** Search completed ***
Uncrunching matrix
Final MIP objective                   : 3.355268902585221e+07
Final MIP bound                       : 3.355268902586088e+07
  Solution time / primaldual integral :    301.62s/ 70.306447
  Number of solutions found / nodes   :         2 /         1
  Max primal violation      (abs/rel) : 9.095e-13 / 8.633e-13
  Max integer violation     (abs    ) : 1.912e-07

And what's in the the solution summary for our instance (copy-pasted from the REPL):

julia> solution_summary(model)
* Solver : Xpress      

* Status
  Result count       : 1
  Termination status : OPTIMAL
  Message from the solver:
  "6 Global search complete - integer solution found ( XPRS_MIP_OPTIMAL). - MIP gap is sufficiently small"

* Candidate solution (result 1)
  Primal status      : FEASIBLE_POINT
  Dual status        : NO_SOLUTION   
  Objective value    : 3.56703e+07  
  Objective bound    : 3.35527e+07  
  Relative gap       : 5.93674e-02  
  Dual objective value : 3.56703e+07

* Work counters
  Solve time (sec)   : 3.09471e+02  

It appears to return the first solution found instead of the optimal solution for our MILP.

[zolanaj]

cc @odow

[odow]

I've a bit limited debugging this because I only have the community license, and this problem is too big, but...

First impression

In JuMP's Objective value : 3.56703e+07 output, we're querying:

Xpress.jl/src/MOI/MOI_wrapper.jl

Lines 3196 to 3200 in 4d70faf

	function MOI.get(model::Optimizer, attr::MOI.ObjectiveValue)
	_throw_if_optimize_in_progress(model, attr)
	MOI.check_result_index_bounds(model, attr)
	if is_mip(model)
	return @_invoke Lib.XPRSgetdblattrib(model.inner, Lib.XPRS_MIPOBJVAL, _)::Float64

There's not a lot to go wrong here, so if this doesn't return the optimal solution, but the first solution from

k         35670343.87  33552689.03      1                  5.

then it seems that this is a bug in Xpress. (Unless we need to set some options for returning multiple solutions?)

More info

Here's the MPS file that Maddie sent me via email:
problematic_mps.mps.zip

Could you:

Provide the output of versioninfo()

Provide the versions of Xpress that you tried (9.2 buggy, others not so?)

Try running with heuristics turned off JuMP.set_attribute(model, "HEUREMPHASIS", 0)

Confirm that we can reproduce this outside of REopt with just the MPS file.

import JuMP, Xpress
model = JuMP.read_from_file("problematic_mps.mps")
JuMP.set_optimizer(model, Xpress.Optimizer)
JuMP.set_attribute(model, "MIPRELSTOP", 0.01)  # Or whatever option you set?
JuMP.optimize!(model)
JuMP.solution_summary(model)

[odow]

So this doesn't seem related to multiple solutions, because there's a special set of functions for that:

• https://www.fico.com/fico-xpress-optimization/docs/latest/solver/optimizer/mipsolpool/HTML/chapter2.html
• https://www.fico.com/fico-xpress-optimization/docs/latest/examples/solver/optimizer/GUID-B7908372-2149-3FFC-AEFF-6A766B3ECF73.html

So I'm going to guess that this is a bug in Xpress.

[odow]

@joaquimg could you try reproducing this? The community license is too small.

[odow]

So now that I've spent a bit of time in the code, I really think this is an upstream issue. I can't see how this would be a bug in Xpress.jl.

[joaquimg]

I ran the basic thing it was taking forever:

julia> import JuMP, Xpress

julia> model = JuMP.read_from_file("problematic_mps.mps")
A JuMP Model
Minimization problem with:
Variables: 315397
Objective function type: JuMP.AffExpr
`JuMP.AffExpr`-in-`MathOptInterface.EqualTo{Float64}`: 87604 constraints
`JuMP.AffExpr`-in-`MathOptInterface.GreaterThan{Float64}`: 61339 constraints
`JuMP.AffExpr`-in-`MathOptInterface.LessThan{Float64}`: 105137 constraints
`JuMP.VariableRef`-in-`MathOptInterface.EqualTo{Float64}`: 43801 constraints
`JuMP.VariableRef`-in-`MathOptInterface.GreaterThan{Float64}`: 254073 constraints
`JuMP.VariableRef`-in-`MathOptInterface.ZeroOne`: 17523 constraints
Model mode: AUTOMATIC
CachingOptimizer state: NO_OPTIMIZER
Solver name: No optimizer attached.

julia> JuMP.set_optimizer(model, Xpress.Optimizer)

julia> JuMP.set_attribute(model, "MIPRELSTOP", 0.01)  # Or whatever option you set?

julia> JuMP.optimize!(model)
FICO Xpress v9.1.0, Hyper, solve started 13:21:25, Apr 10, 2024
Heap usage: 85MB (peak 85MB, 72KB system)
Minimizing MILP  using up to 8 threads and up to 15GB memory, with these control settings:
OUTPUTLOG = 1
MPSNAMELENGTH = 64
CALLBACKFROMMASTERTHREAD = 1
MIPRELSTOP = .01
Original problem has:
    254080 rows       315397 cols       837299 elements     17523 entities
Presolved problem has:
    118895 rows        78496 cols       419614 elements      8763 entities
Presolve finished in 2 seconds
Heap usage: 137MB (peak 298MB, 72KB system)

Coefficient range                    original                 solved
  Coefficients   [min,max] : [ 9.97e-05,  1.00e+12] / [ 1.40e-04,  1.49e+04]
  RHS and bounds [min,max] : [ 1.00e+00,  1.00e+14] / [ 5.98e-04,  2.50e+12]
  Objective      [min,max] : [ 1.14e-04,  1.51e+04] / [ 1.08e-04,  2.92e+10]
Autoscaling applied Curtis-Reid scaling

Symmetric problem: generators: 431, support set: 432
 Number of orbits: 2, largest orbit: 432
 Row orbits: 3, row support: 1296
Will try to keep branch and bound tree memory usage below 5.8GB
Starting concurrent solve with dual (1 thread) and barrier (7 threads)

              Concurrent-Solve,   2s
            Dual                      Barrier
    objective   dual inf        p.obj.     d.obj.
 D  3889143.2   .0000000 |  B -1.549E+21  40745228.
 D  4486696.4   .0000000 |  B -1.228E+20 -2.704E+19
 D  6333675.2   .0000000 |  B -7.017E+17 -3.763E+15
 D  8299850.7   .0000000 |  B -7.499E+15  1.945E+15
 D  9805099.7   .0000000 |  B -1.028E+09  5.558E+09
 D  11576278.   .0000000 |  B  24101024.  50274176.
 D  12609770.   .0000000 |  B  32900675.  33795727.
 D  13218450.   .0000000 |  B  33381914.  33486821.
 D  13317250.   .0000000 |  B  33446195.  33446811.
 D  14755373.   .0000000 |           crossover
----- interrupted ------ | ------- optimal --------
Concurrent statistics:
      Dual: 31832 simplex iterations, 5.13s
   Barrier: 62 barrier and 28543 simplex iterations, 5.10s
            Barrier used 7 threads 4 cores, L1\L2 cache: 48K\12288K
            Barrier used AVX support, crossover used 7 threads
Optimal solution found

   Its         Obj Value      S   Ninf  Nneg        Sum Inf  Time
     1       33446472.64      P      0     0        .000000     7
Barrier solved problem
  62 barrier and 28543 simplex iterations in 5.18 seconds at time 7

Final objective                       : 3.344647264049235e+07
  Max primal violation      (abs/rel) : 9.417e-10 / 5.056e-13
  Max dual violation        (abs/rel) : 3.553e-15 / 1.776e-15
  Max complementarity viol. (abs/rel) :       0.0 /       0.0
High attention level predicted from matrix features

Starting root cutting & heuristics
Deterministic mode with up to 1 additional thread

 Its Type    BestSoln    BestBound   Sols    Add    Del     Gap     GInf   Time
k         35578106.66  33446472.64      1                  5.99%       0     21
Heuristic search 'R' started
Heuristic R running (50000 LP iterations in    8.6 seconds)
Heuristic search 'R' stopped
Heuristic M running (50000 LP iterations in  931.1 seconds)

Then a I ran with HEUREMPHASIS = 0 got:

julia> import JuMP, Xpress

julia> model = JuMP.read_from_file("problematic_mps.mps")
A JuMP Model
Minimization problem with:
Variables: 315397
Objective function type: JuMP.AffExpr
`JuMP.AffExpr`-in-`MathOptInterface.EqualTo{Float64}`: 87604 constraints
`JuMP.AffExpr`-in-`MathOptInterface.GreaterThan{Float64}`: 61339 constraints
`JuMP.AffExpr`-in-`MathOptInterface.LessThan{Float64}`: 105137 constraints
`JuMP.VariableRef`-in-`MathOptInterface.EqualTo{Float64}`: 43801 constraints
`JuMP.VariableRef`-in-`MathOptInterface.GreaterThan{Float64}`: 254073 constraints
`JuMP.VariableRef`-in-`MathOptInterface.ZeroOne`: 17523 constraints
Model mode: AUTOMATIC
CachingOptimizer state: NO_OPTIMIZER
Solver name: No optimizer attached.

julia> JuMP.set_optimizer(model, Xpress.Optimizer)

julia> JuMP.set_attribute(model, "MIPRELSTOP", 0.01)  # Or whatever option you set?JuMP.set_attribute(model, "HEUREMPHASIS", 0)

julia> JuMP.set_attribute(model, "HEUREMPHASIS", 0)

julia> JuMP.optimize!(model)
FICO Xpress v9.1.0, Hyper, solve started 13:43:46, Apr 10, 2024
Heap usage: 85MB (peak 85MB, 72KB system)
Minimizing MILP  using up to 8 threads and up to 15GB memory, with these control settings:
OUTPUTLOG = 1
MPSNAMELENGTH = 64
CALLBACKFROMMASTERTHREAD = 1
HEUREMPHASIS = 0
MIPRELSTOP = .01
Original problem has:
    254080 rows       315397 cols       837299 elements     17523 entities
Presolved problem has:
    118895 rows        78496 cols       419614 elements      8763 entities
Presolve finished in 2 seconds
Heap usage: 137MB (peak 298MB, 72KB system)

Coefficient range                    original                 solved
  Coefficients   [min,max] : [ 9.97e-05,  1.00e+12] / [ 1.40e-04,  1.49e+04]
  RHS and bounds [min,max] : [ 1.00e+00,  1.00e+14] / [ 5.98e-04,  2.50e+12]
  Objective      [min,max] : [ 1.14e-04,  1.51e+04] / [ 1.08e-04,  2.92e+10]
Autoscaling applied Curtis-Reid scaling

Symmetric problem: generators: 431, support set: 432
 Number of orbits: 2, largest orbit: 432
 Row orbits: 3, row support: 1296
Will try to keep branch and bound tree memory usage below 6.5GB
Starting concurrent solve with dual (1 thread) and barrier (7 threads)

              Concurrent-Solve,   3s
            Dual                      Barrier
    objective   dual inf        p.obj.     d.obj.
 D  3889143.2   .0000000 |  B -1.549E+21  40745228.
 D  4486696.4   .0000000 |  B -1.228E+20 -2.704E+19
 D  6333675.2   .0000000 |  B -7.017E+17 -3.763E+15
 D  8299850.7   .0000000 |  B -7.499E+15  1.945E+15
 D  9805099.7   .0000000 |  B -1.028E+09  5.558E+09
 D  11576278.   .0000000 |  B  24101024.  50274176.
 D  12609770.   .0000000 |  B  32900675.  33795727.
 D  13218450.   .0000000 |  B  33381914.  33486821.
 D  13317250.   .0000000 |  B  33446195.  33446811.
 D  14755373.   .0000000 |           crossover
----- interrupted ------ | ------- optimal --------
Concurrent statistics:
      Dual: 31654 simplex iterations, 6.78s
   Barrier: 62 barrier and 28543 simplex iterations, 6.75s
            Barrier used 7 threads 4 cores, L1\L2 cache: 48K\12288K
            Barrier used AVX support, crossover used 7 threads
Optimal solution found

   Its         Obj Value      S   Ninf  Nneg        Sum Inf  Time
     1       33446472.64      P      0     0        .000000     9
Barrier solved problem
  62 barrier and 28543 simplex iterations in 6.84 seconds at time 9

Final objective                       : 3.344647264049235e+07
  Max primal violation      (abs/rel) : 9.417e-10 / 5.056e-13
  Max dual violation        (abs/rel) : 3.553e-15 / 1.776e-15
  Max complementarity viol. (abs/rel) :       0.0 /       0.0
High attention level predicted from matrix features

Starting root cutting & heuristics

 Its Type    BestSoln    BestBound   Sols    Add    Del     Gap     GInf   Time
*         33446472.64  33446472.64      1                  0.00%       0     10
 *** Search completed ***
Uncrunching matrix
Final MIP objective                   : 3.344647264049235e+07
Final MIP bound                       : 3.344647264049235e+07
  Solution time / primaldual integral :     10.17s/ 99.803440%
  Number of solutions found / nodes   :         1 /         1
  Max primal violation      (abs/rel) : 9.095e-13 / 9.077e-13
  Max integer violation     (abs    ) : 1.818e-07
Refined MIP solution (0.0 fractionality 6.812e-13 abs infeasibility)

julia> JuMP.solution_summary(model)
* Solver : Xpress

* Status
  Result count       : 1
  Termination status : OPTIMAL
  Message from the solver:
  "6 Global search complete - integer solution found ( XPRS_MIP_OPTIMAL). - no interruption - the solve completed normally"

* Candidate solution (result #1)
  Primal status      : FEASIBLE_POINT
  Dual status        : NO_SOLUTION
  Objective value    : 3.55781e+07
  Objective bound    : 3.34465e+07
  Relative gap       : 5.99142e-02
  Dual objective value : 3.55781e+07

* Work counters
  Solve time (sec)   : 2.50390e+01