JuMP is slow *before* creating model

Specific Domains Optimization (Mathematical)
1

I have a function, say A(), that calls a function B(). B() creates a JuMP model (using Gurobi) and returns a mutable struct containing the model and other things. All JuMP macro calls are in B(). A() is called from the top level. However if I print a string right before calling A() and another string as the first expression in A(), I observe 5+ seconds between the two prints. I would like to understand why. I suppose it is related to macro expansion somehow but I do not understand what is going on. Maybe there is a better way to design my program? Is this normal behaviour or is it a symptom of something wrong somewhere else? Note: after the second print, the call to B() takes 3-4 seconds.

Here is an MWE:


using Random, Dates

using JuMP, Gurobi

const solverObject = GurobiSolver(Threads=1, OutputFlag=0)

struct InputData{ MI<:Matrix{Int}, VI<:Vector{Int} }
    N::VI
    H::VI
    c::VI
    d::MI
    q::VI
    Q::VI
end

mutable struct ModelStruct{ Mod<:Model}
    model::Mod
    x::JuMP.JuMPArray{JuMP.Variable}
    y::JuMP.JuMPArray{JuMP.Variable}
    obj::JuMP.AffExpr
end

function B(d::InputData)
    m = Model(solver=solverObject)
    y = @variable( m, [ d.H ], basename="y")
    x = @variable( m, [ d.N, d.H ], basename="x")
    @constraint( m, coverage[i=d.N], sum( x[i,j] for j in d.H ) == 1)
    @constraint( m, capacity[j=d.H],
                 sum( x[i,j] * d.q[i] for i in d.N ) <= d.Q[j] )
    @constraint( m, xylink[i=d.N, j=d.H], x[i,j] <= y[j] )
    openingCost = sum( y[j] * d.c[j] for j in d.H )
    assignmentCost = sum( x[i,j] * d.d[i,j] for i in d.N, j in d.H )
    @objective(m, Min, openingCost + assignmentCost)
    ModelStruct(m, x, y, openingCost + assignmentCost)
end

function A(d::InputData)
    println(Dates.now(), " Creating model")
    B(d)
end

n = 100
h = 30
c = rand(1:100, h)
d = rand(1:30, n, h)
q = rand(1:20, n)
Q = rand(1:100, h)

id = InputData( collect(1:n), collect(1:h), c, d, q, Q )
println(Dates.now(), " About to create model")
A(id)
2

Can you please post an MWE (Minimum Working Example)? This could easily be any number of things, so having an example that we could run locally would allow us to narrow down the source of the issue.

3

I added an MWE in the original post, with a simple facility location model. On my laptop the time difference between the two timestamps is about two seconds.

4

This just looks like function compilation time. Try doing the combined print(...); A(id) statement twice, and I’m sure the second call will be much quicker.

Also, instead of using print(Dates.now, ...), I recommend using @time or BenchmarkTools’ @btime.

5

I use Dates.now() in this specific case to track time from different scopes, otherwise I use @time or @elapsed.

Indeed the second time it is almost instant, so it looks like it is function compilation time. I still do not understand why this compilation time is necessary though: in my code everything is inside a module that is precompiled. Why do I have to pay this function’s compilation time every time the program is re-run? (sorry if my question sounds silly, I’m learning both Julia and JuMP at the same time)

6

Think about it like this: you’re the compiler, and you’re walking through a module executing code as you see it. Even though you hit the function definitions first, you don’t know what arguments they’ll be called with, so you just save their ASTs somewhere, to be compiled later (during JIT time).

Now, you come upon some code which needs to be immediately executed (such as n = 100, a print statement, or an A(id)). You have no other choice but to execute it immediately (that’s the whole point), so you do so. However, some of the functions you depend on, like A or B, haven’t been compiled yet. Well, no time like the present, especially since at this point you can easily get the types of their arguments (since you’re calling them at this present moment). So, you compile them, which as I’m sure you know, is a rather slow process, due to all the magical optimizations done by Julia and LLVM. After that’s done, you execute your functions (doing JIT compiles along the way, as needed), and then return.

Now, you hit another print(...) or A(id) statement. It would be wasteful to re-compile the function when you’ve already done so for previous calls with the same argument types, so we just lookup the cached, compiled function, and call the function of interest very, very quickly.

Hopefully the above makes sense and fully explains (from a super high level) how Julia’s JIT mechanics sort-of work :slight_smile:

EDIT: Pre-compilation is something of a misnomer (currently, at least): the precompilation that occurs only does some basic parsing, lowering, and other things; you don’t actually get native assembly (and I don’t even think LLVM IR, although I could be wrong). So it doesn’t save much time, other than that required for parsing and lowering. The sysimage, on the other hand, is compiled down to native code, but takes a very long time to generate, hence why it’s only done once: when building Julia itself. That extra time that the sysimage takes to generate is essentially all the extra stuff we walked through above.

7

Thank you for the very informative answer!

1 Like