MOI is slow querying solution information again

[DrChainsaw]

I'm getting the same slow performance as in #102 on Cbc 0.8.1 (I'm pretty sure that it was on 0.8.0 too).

 pkg> add JuMP,Cbc
   Resolving package versions...
  [9961bab8] + Cbc v0.8.1
  [4076af6c] + JuMP v0.21.9

julia> using JuMP, Cbc, BenchmarkTools

julia> function bench(optimizer, N = 30_000)
           model = Model(with_optimizer(optimizer))
           @variable(model, x[i = 1:N] >= i)
           @objective(model, Min, sum(x))
           optimize!(model)
           @benchmark value.($x)
        end
bench (generic function with 2 methods)

julia> bench(Cbc.Optimizer)
Optimal - objective value 4.50015e+08
Optimal objective 450015000 - 0 iterations time 0.002
BenchmarkTools.Trial: 2 samples with 1 evaluation.
 Range (min … max):  4.568 s …   4.631 s  ┊ GC (min … max): 0.00% … 0.00%
 Time  (median):     4.600 s              ┊ GC (median):    0.00%        
 Time  (mean ± σ):   4.600 s ± 44.846 ms  ┊ GC (mean ± σ):  0.00% ± 0.00%

  █                                                       █  
  █▁▁▁▁▁▁▁▁▁▁▁▁▁▁▁▁▁▁▁▁▁▁▁▁▁▁▁▁▁▁▁▁▁▁▁▁▁▁▁▁▁▁▁▁▁▁▁▁▁▁▁▁▁▁▁█ ▁
  4.57 s         Histogram: frequency by time        4.63 s <

 Memory estimate: 8.93 MiB, allocs estimate: 390002.

[odow]

Looks like this is an upstream change in Cbc. Before Cbc_getColSolution used to return a pointer to the solution vector without making a copy. But now it takes much longer, so I guess it is making an internal copy? Seems safer, but slower. We probably need to refactor the solution query stuff to cache the solution once, rather than looking it up every time. PRs accepted.

using Cbc, JuMP

function bench(optimizer, N = 30_000)
    model = Model(optimizer; bridge_constraints = false)
    @variable(model, x[i = 1:N] >= i)
    @objective(model, Min, sum(x))
    optimize!(model)
    cbc = backend(model).optimizer
    @time begin
        for i in 1:N
            Cbc.Cbc_getColSolution(cbc.inner)
        end
    end
end

Before

julia> bench(Cbc.Optimizer);
Welcome to the CBC MILP Solver 
Version: 2.10.3 
Build Date: Nov  9 2020 

command line - Cbc_C_Interface -solve -quit (default strategy 1)
Empty problem - 0 rows, 30000 columns and 0 elements
Optimal - objective value 4.50015e+08
Optimal objective 450015000 - 0 iterations time 0.002
Total time (CPU seconds):       0.00   (Wallclock seconds):       0.00

  0.007475 seconds (61.06 k allocations: 1006.072 KiB, 75.01% compilation time)

After

julia> bench(Cbc.Optimizer);
Optimal - objective value 4.50015e+08
Optimal objective 450015000 - 0 iterations time 0.002
  2.020699 seconds (61.06 k allocations: 1006.400 KiB, 0.28% compilation time)

[DrChainsaw]

PRs accepted.

I'd be happy to do some grunt work for this, especially given how much mileage I have gotten out of this package. Unfortunately I don't know much of the MOI-wrapping stuff, but if it is just a matter of porting #103 I think I can manage.

Would it be better to have a lazier cache which only populates once user queries the first variable, or are there risks associated with that?

[odow]

HiGHS.jl does something similar.

There is a solution struct:
https://github.com/jump-dev/HiGHS.jl/blob/eb4cf3c509dc8be4ee952b7a7e56b283b7aeb9d1/src/MOI_wrapper.jl#L239-L273

Then the solution gets stored after optimize!
https://github.com/jump-dev/HiGHS.jl/blob/eb4cf3c509dc8be4ee952b7a7e56b283b7aeb9d1/src/MOI_wrapper.jl#L1553-L1602

So when we query, it just happens here:
https://github.com/jump-dev/HiGHS.jl/blob/eb4cf3c509dc8be4ee952b7a7e56b283b7aeb9d1/src/MOI_wrapper.jl#L1729-L1736

We probably only need to store Cbc_getColSolution and Cbc_getRowActivity (the things that call _unsafe_wrap_cbc_array) so it should be simpler than HiGHS.jl.

[odow]

Ah. I didn't look at #103. Yes, porting that + getRowActivity should do the job.

[DrChainsaw]

Yes, porting that + getRowActivity should do the job.

Awesome! Its getting late over here, but I'll take a stab at it tomorrow. Don't let me hold you back if you just want to get it in asap.

[odow]

Script

using Cbc_jll, BenchmarkTools
const libcbcsolver = Cbc_jll.libcbcsolver
function Cbc_newModel()
    ccall((:Cbc_newModel, libcbcsolver), Ptr{Cvoid}, ())
end
function Cbc_loadProblem(model, numcols, numrows, start, index, value, collb, colub, obj, rowlb, rowub)
    ccall((:Cbc_loadProblem, libcbcsolver), Cvoid, (Ptr{Cvoid}, Cint, Cint, Ptr{Cint}, Ptr{Cint}, Ptr{Cdouble}, Ptr{Cdouble}, Ptr{Cdouble}, Ptr{Cdouble}, Ptr{Cdouble}, Ptr{Cdouble}), model, numcols, numrows, start, index, value, collb, colub, obj, rowlb, rowub)
end
function Cbc_solve(model)
    ccall((:Cbc_solve, libcbcsolver), Cint, (Ptr{Cvoid},), model)
end
function Cbc_isProvenOptimal(model)
    ccall((:Cbc_isProvenOptimal, libcbcsolver), Cint, (Ptr{Cvoid},), model)
end
function Cbc_deleteModel(model)
    ccall((:Cbc_deleteModel, libcbcsolver), Cvoid, (Ptr{Cvoid},), model)
end

N = 30_000
ptr = Cbc_newModel()
Cbc_loadProblem(ptr, Cint(N), Cint(0), Cint[0, 0], Cint[], Cdouble[], collect(1.0:1.0:N), fill(Inf, N), ones(N), Cdouble[], Cdouble[])
Cbc_solve(ptr)
@benchmark Cbc_isProvenOptimal(ptr)
Cbc_deleteModel(ptr)

Cbc_jll@2.10.3

julia> @benchmark Cbc_isProvenOptimal(ptr)
BenchmarkTools.Trial: 10000 samples with 996 evaluations.
 Range (min … max):  19.738 ns … 96.678 ns  ┊ GC (min … max): 0.00% … 0.00%
 Time  (median):     21.451 ns              ┊ GC (median):    0.00%
 Time  (mean ± σ):   22.974 ns ±  4.462 ns  ┊ GC (mean ± σ):  0.00% ± 0.00%

    ▅█▄                                                        
  ▄▇███▇▅▄▃▃▃▃▃▃▃▃▃▃▃▄▃▃▂▂▂▂▂▂▂▂▁▂▂▂▂▂▂▂▂▂▂▂▂▂▂▂▂▂▂▂▂▂▂▂▂▂▂▂▂ ▃
  19.7 ns         Histogram: frequency by time        41.6 ns <

 Memory estimate: 0 bytes, allocs estimate: 0.

(cbc_jll) pkg> st
      Status `/private/tmp/cbc_jll/Project.toml`
  [38041ee0] Cbc_jll v2.10.3+5

Cbc_jll v2.10.5

julia> @benchmark Cbc_isProvenOptimal(ptr)
BenchmarkTools.Trial: 10000 samples with 1 evaluation.
 Range (min … max):  66.914 μs … 138.105 μs  ┊ GC (min … max): 0.00% … 0.00%
 Time  (median):     68.881 μs               ┊ GC (median):    0.00%
 Time  (mean ± σ):   70.502 μs ±   4.900 μs  ┊ GC (mean ± σ):  0.00% ± 0.00%

  ▅   ██▂   ▆▁   ▁▁     ▁     ▁     ▁      ▁       ▂           ▁
  █▅▄▄████▇▇██▇▇▅██▇▅▅▅▇█▇▆▅▅▅█▇▆▄▃▄█▇▆▆▆▆▆█▇▇▆▆▆▅▅█▆▅▂▅▂▅▄▅▅▅ █
  66.9 μs       Histogram: log(frequency) by time      90.2 μs <

 Memory estimate: 0 bytes, allocs estimate: 0.

That's a 1000x slowdown!

The main change was here: JuliaPackaging/Yggdrasil#2668. We remove a patch that forwarded LPs straight to Cbc. It seems like Cbc_getNumIntegers is slow...

cc @tkralphs is this a known issue?

[tkralphs]

is this a known issue?

Not that I know of. Looks like it might take some digging to get to the bottom of this.

[junglegobs]

Is there any progress on this front?

[odow]

We started #173, but I haven't had time to come back to this.

[SabineAuer]

I am also interested in this issue. Is there any previous version where this issue does not appear yet?

[odow]

In the near term, try ] add Cbc@0.7, or use HiGHS.jl instead.