Jump.jl: Performance/discussion: generating variables names is expensive

[IainNZ]

I was trying to figure out why the tests take so long to run. Turns out operator.jl is a big offender, and in there, higher-level-ops/dot/tests for #943 stood out.
In that inner-most test set I thought it might be the dot overloads themselves, which are certainly not cheap, but actually creating the variables themselves takes a lot of time and memory. In particular,

import JuMP

function run_test()
    model = JuMP.Model()
    JuMP.@variable(model, vars[1:10^6])
    return model
end

@time run_test()
@time run_test()
@time run_test()

Outputs

  4.755034 seconds (21.81 M allocations: 905.383 MiB, 36.35% gc time)
  4.378748 seconds (20.56 M allocations: 837.200 MiB, 57.16% gc time)
  4.387611 seconds (20.56 M allocations: 837.200 MiB, 58.15% gc time)

In macros.jl, if I change the variable name generation code to

if isempty(basename_kwargs)
        # basename = anonvar ? "" : string(getname(var))
        basename = ""
    else

it becomes

  1.637160 seconds (8.46 M allocations: 355.028 MiB, 13.05% gc time)
  0.644029 seconds (7.28 M allocations: 290.591 MiB, 34.08% gc time)
  0.655611 seconds (7.28 M allocations: 290.591 MiB, 37.75% gc time)

I suspect all this adds up to a lot over the entire test suite, although its tough to test because this change makes the tests fail.

[IainNZ]

Possibly not the full story:

import JuMP

function run_test()
    model = JuMP.Model()
    JuMP.@variable(model, vars[1:10^6])
    return model
end

@time run_test()
@time run_test()
@time run_test()

function run_other_test()
    foo = [string("vars", "[", i, "]") for i in 1:10^6]
    return foo
end

@time run_other_test()
@time run_other_test()
@time run_other_test()

function run_moi_test()
    model = JuMP.Model()
    for i in 1:10^6
        varref = JuMP.VariableRef(model)
    end
end

@time run_moi_test()
@time run_moi_test()
@time run_moi_test()

function run_moi_str_test()
    model = JuMP.Model()
    for i in 1:10^6
        varref = JuMP.VariableRef(model)
        JuMP.setname(varref, string("vars", "[", i, "]"))
    end
end

@time run_moi_str_test()
@time run_moi_str_test()
@time run_moi_str_test()

Gives

5.249690 seconds (21.81 M allocations: 905.275 MiB, 35.90% gc time)
  4.726216 seconds (20.56 M allocations: 837.200 MiB, 56.92% gc time)
  4.604013 seconds (20.56 M allocations: 837.200 MiB, 58.68% gc time)
  0.897642 seconds (8.01 M allocations: 343.825 MiB, 54.15% gc time)
  0.585621 seconds (8.00 M allocations: 343.311 MiB, 40.22% gc time)
  0.591946 seconds (8.00 M allocations: 343.311 MiB, 40.62% gc time)
  0.348399 seconds (4.28 M allocations: 115.178 MiB, 8.82% gc time)
  0.424949 seconds (4.28 M allocations: 115.114 MiB, 28.29% gc time)
  0.314685 seconds (4.28 M allocations: 115.114 MiB, 2.69% gc time)
  2.939458 seconds (17.56 M allocations: 661.803 MiB, 41.55% gc time)
  2.906473 seconds (17.56 M allocations: 661.723 MiB, 42.51% gc time)
  3.013391 seconds (17.56 M allocations: 661.723 MiB, 44.27% gc time)

Implying setting the name itself is responsible for the bulk of the time.

[IainNZ]

So attacked this again today, with this script

import Printf

import BenchmarkTools: @benchmark, allocs
import JuMP

NUM_VAR_EXPONENT = (1, 2, 3, 4, 5, 6)

function create_many_vars(num_vars)
    model = JuMP.Model()
    JuMP.@variable(model, vars[1:num_vars])
    return model
end

_times = []
_allocs = []
for num_vars_exp in NUM_VAR_EXPONENT
    num_vars = 10 ^ num_vars_exp
    result = @benchmark create_many_vars($num_vars) gcsample=true
    push!(_times, time(result))
    push!(_allocs, allocs(result))
    println(num_vars)
    display(result)
    println()
end

for (num_vars_exp, t, a) in zip(NUM_VAR_EXPONENT, _times, _allocs)
    num_vars = 10 ^ num_vars_exp
    Printf.@printf("10^%d: %6.3f s, %6f ns/var, %d a, %f a/var\n", num_vars_exp, t / 10^9, t / num_vars, a, a / num_vars)
end

JuMP master:

10^1:  0.000 s, 3762.200000 ns/var, 371 a, 37.100000 a/var
10^2:  0.000 s, 1333.020000 ns/var, 1758 a, 17.580000 a/var
10^3:  0.001 s, 1022.893000 ns/var, 17899 a, 17.899000 a/var
10^4:  0.011 s, 1114.020700 ns/var, 176379 a, 17.637900 a/var
10^5:  0.247 s, 2474.640010 ns/var, 1815641 a, 18.156410 a/var
10^6:  3.774 s, 3773.585553 ns/var, 19562372 a, 19.562372 a/var

JuMP release-0.18

10^1:  0.000 s, 444.062500 ns/var, 85 a, 8.500000 a/var
10^2:  0.000 s, 201.460000 ns/var, 193 a, 1.930000 a/var
10^3:  0.000 s, 77.200000 ns/var, 1111 a, 1.111000 a/var
10^4:  0.001 s, 61.328400 ns/var, 10137 a, 1.013700 a/var
10^5:  0.009 s, 88.937660 ns/var, 100155 a, 1.001550 a/var
10^6:  0.153 s, 153.322289 ns/var, 1000173 a, 1.000173 a/var

I tried looking for the sources of allocations, leading to VariableInfo (#1525), that Base.string is kinda dumb (https://github.com/JuliaLang/julia/issues/29550, 1527), and that VariableIndex really benefits from a hash (PR coming soon). With these changes we get

10^1:  0.000 s, 3374.600000 ns/var, 291 a, 29.100000 a/var
10^2:  0.000 s, 860.520000 ns/var, 849 a, 8.490000 a/var
10^3:  0.001 s, 583.065000 ns/var, 6761 a, 6.761000 a/var
10^4:  0.006 s, 562.727000 ns/var, 69779 a, 6.977900 a/var
10^5:  0.087 s, 872.100430 ns/var, 699813 a, 6.998130 a/var
10^6:  1.445 s, 1445.424120 ns/var, 6999864 a, 6.999864 a/var

[IainNZ]

A comparison with C++ suggests that setname (i.e. shoving 10^6 strings into a dict) takes about 0.5-0.6 seconds, so that means the fastest we could ever get this is about 0.7 seconds vs JuMP18's 0.15.

[IainNZ]

#include <cstdint>
#include <unordered_map>
#include <iostream>
#include <string>
using namespace std;

int main(void) {
    unordered_map<string, int64_t> x;
    for (int64_t i = 0; i < 1000000; ++i) {
        string s = to_string(i);
        x[s] = i; 
    }
    cout << x.size() << endl;
    return 0;
}

[IainNZ]

For a nameless variable, we mostly regain JuMP 0.18 performance with this patch set, just 1 extra alloc per variable:

10^5:  0.010 s, 102.768620 ns/var, 200255 a, 2.002550 a/var
10^6:  0.234 s, 234.149566 ns/var, 2000270 a, 2.000270 a/var

[IainNZ]

One option, that'll go to MOI as its an API change: if you relax the requirement that names be unique, and don't guarantee you'll get any particular variable back for a name if there are duplicates, then you don't need to store the name->index map at all. Instead, you can just make looking up by name slower by walking through the index->name map.
This makes JuMP 19 less breaking (duplicate names are back), and speeds up the most common JuMP use case (which has very little need for looking up by name), and a cost of making looking up by name a bit slower.

[blegat]

We could create an MOI layer storing dicts for variable and constraint names and add a keyword option in the Model constructor for whether to stack this layer or not. The question is : what should be the defaut ?

[mlubin]

I'm not a fan of a new MOI layer. We already have 3 layers on top of the JuMPMOIModel (UniversalFallback, CachingOptimizer, LazyBridgeOptimizer) which makes it hard enough for someone reading the code to follow the control flow.

Two options that come to mind are:

1. If we want to support fast name lookups without the default performance hit, we could lazily build the lookup Dict on the first lookup request. This adds a bit more state to the MOIU.Model code but does not require any breaking changes in the MOI API.

2. We could stop supporting fast lookups and do a linear search through the variables instead. Users who know they need constant-time lookups for variables by name can construct their own Dict. This is a breaking change in the MOI API to document the new lookup behavior and how duplicate names would be handled.

[mlubin]

FWIW I tracked down one additional allocation when creating variables to the dynamic dispatch on JuMP's MOI model. One fix is calling MOI.add_variables, but that requires some restructuring.

[IainNZ]

To tidy this up, the benchmark in the very first post now produces on the same machine, at JuMP commit 096e65253aa8c57b4f1cc0e019babbd49e537908 (from Nov 10) and MOI commit 4cf5a73020f5bc678d7548a96740baab2dc29985 (also from Nov 10), with Julia v1.0.0.

IAINMBP:JuMP idunning$ j1 --project=. 1402.jl
  2.623406 seconds (10.50 M allocations: 481.060 MiB, 23.70% gc time)
  1.397545 seconds (7.00 M allocations: 305.680 MiB, 49.90% gc time)
  1.258547 seconds (7.00 M allocations: 305.680 MiB, 45.96% gc time)

And the one with BenchmarkTools (https://github.com/JuliaOpt/JuMP.jl/issues/1402#issuecomment-427617991) produces this:

10^1:  0.000 s, 2772.900000 ns/var, 268 a, 26.800000 a/var
10^2:  0.000 s, 674.740000 ns/var, 820 a, 8.200000 a/var
10^3:  0.000 s, 427.210000 ns/var, 6724 a, 6.724000 a/var
10^4:  0.004 s, 414.199900 ns/var, 69736 a, 6.973600 a/var
10^5:  0.066 s, 655.805200 ns/var, 699758 a, 6.997580 a/var
10^6:  0.848 s, 848.255521 ns/var, 6999791 a, 6.999791 a/var

Which, compared to JuMP 0.18 is

10^5:  0.009 s, 88.937660 ns/var, 100155 a, 1.001550 a/var
10^6:  0.153 s, 153.322289 ns/var, 1000173 a, 1.000173 a/var

So still a lot slower, but much better than the starting point of

10^5:  0.247 s, 2474.640010 ns/var, 1815641 a, 18.156410 a/var
10^6:  3.774 s, 3773.585553 ns/var, 19562372 a, 19.562372 a/var

IIRC, this is almost best we can do, apart from the dynamic dispatch thing mentioned by @mlubin . I'm not really sure what details of that are, but should be a fresh issue I think.