Odd behavior from ControlSystemIdentification and JuMP on version 1.6

Hello, I am preparing a short tutorial on how to use Julia for Control Systems and I was using Julia 1.5 and it was working ok. Then I decided to test version 1.6 to see if it would make it load faster (considering that most people will be using Julia for the first time it would be nice if it installs the packages and loads them in a reasonable amount of time.)

Problem is, once I tried to use the new version it did install and load the packages faster but it then got stuck in the optimize!(m) line. Initially I was using Ipopt but I get the same problem with GLPK, so I got a minimal example of the bug (is it a bug?) that I am facing. It seems to be caused by the combination of packages I am using, because if I only load JuMP and GLPK it works very fast.

using Pkg
Pkg.activate("temp_env1")

@time begin
       Pkg.add(["ControlSystems","ControlSystemIdentification","JuMP",
            "GLPK","Ipopt","DifferentialEquations","Plots",
            "SymPy","NLsolve","ForwardDiff","LaTeXStrings"])
end

@time begin
       using ControlSystems
       using ControlSystemIdentification
       using JuMP
       using GLPK
       using Ipopt
       using DifferentialEquations
       using Plots
       using SymPy
       using LinearAlgebra
       using NLsolve
       using ForwardDiff
       using LaTeXStrings
end


#m = Model(Ipopt.Optimizer);
m = Model(GLPK.Optimizer);
JuMP.@variable(m,m_x); 
optimize!(m)

With the help of some redditors (https://www.reddit.com/r/Julia/comments/ml65zj/julia_16_gets_stuck_optimizing_with_jump_due_to/) I figured the workaround shown below. I loaded ControlSystemIdentification after running an optimization once and got it to run correctly, but I have no idea if this is a problem with JuMP or ControlSystemIdentification and I don’t know how to debug that on my own.

using Pkg
Pkg.activate("temp_env2")

@time begin    Pkg.add(["ControlSystems","ControlSystemIdentification","JuMP","GLPK","Ipopt","DifferentialEquations","Plots","SymPy","NLsolve","ForwardDiff","LaTeXStrings"])
end

@time begin
       using ControlSystems
       using JuMP
       using GLPK
       using Ipopt
       using DifferentialEquations
       using Plots
       using SymPy
       using LinearAlgebra
       using NLsolve
       using ForwardDiff
       using LaTeXStrings
end


#m = Model(Ipopt.Optimizer);
m = Model(GLPK.Optimizer);
JuMP.@variable(m,m_x); 
optimize!(m)

using ControlSystemIdentification	

m = Model(Ipopt.Optimizer);
#m = Model(GLPK.Optimizer);
JuMP.@variable(m,m_x); 
optimize!(m)

My versioninfo()

Julia Version 1.6.0
Commit f9720dc2eb (2021-03-24 12:55 UTC)
Platform Info:
  OS: Linux (x86_64-pc-linux-gnu)
  CPU: Intel(R) Core(TM) i7-5500U CPU @ 2.40GHz
  WORD_SIZE: 64
  LIBM: libopenlibm
  LLVM: libLLVM-11.0.1 (ORCJIT, broadwell)
Environment:
  JULIA_NUM_THREADS = 6

With packages

      Status `~/.julia/environments/v1.6/Project.toml`
  [3abffc1c] ControlSystemIdentification v1.6.0
  [a6e380b2] ControlSystems v0.9.2
  [0c46a032] DifferentialEquations v6.16.0
  [f6369f11] ForwardDiff v0.10.17
  [60bf3e95] GLPK v0.14.8
  [7073ff75] IJulia v1.23.2
  [b6b21f68] Ipopt v0.6.5
  [4076af6c] JuMP v0.21.6
  [b964fa9f] LaTeXStrings v1.2.1
  [2774e3e8] NLsolve v4.5.1
  [91a5bcdd] Plots v1.11.2
  [24249f21] SymPy v1.0.42

Does the optimize call finish at all? Does it work if you use less packages? (e.g., what about just JuMP, GLPK, and ControlSystemIdentification?)

I’m guessing this is a bad case of method invalidation: Analyzing sources of compiler latency in Julia: method invalidations

It works if I just use just JuMP and the optimizers. And it also works if I use the second code, where ControlSystemIdentification is loaded after a call to optimize!

In the original code, where I load all the libraries and then run optimize! it does not finish the call (I waited for 30 mins and then killed the process)

There is a lot of invalidation going on when you load ControlSystemIdentification. That means when you call a method like optimize!, Julia needs to recompile a very large amount of code.

@baggepinnen

julia> using SnoopCompileCore

julia> invalidations = @snoopr begin 
       using ControlSystemIdentification
       end
9811-element Vector{Any}:
  MethodInstance for var"#add_nested_key!#21"(::Any, ::typeof(REPL.LineEdit.add_nested_key!), ::Dict, ::Char, ::Any)
 1
  MethodInstance for (::REPL.LineEdit.var"#add_nested_key!##kw")(::Any, ::typeof(REPL.LineEdit.add_nested_key!), ::Dict, ::Union{Char, String}, ::Any)
 2
  MethodInstance for in(::Char, ::Base.KeySet)
  "jl_method_table_insert"
  in(key, v::Base.KeySet{K, T}) where {K, T<:(OrderedCollections.OrderedDict{K, V} where V)} in OrderedCollections at /Users/oscar/.julia/packages/OrderedCollections/cP9uu/src/ordered_dict.jl:394
  "jl_method_table_insert"
  MethodInstance for hash(::Any, ::UInt64)
  "invalidate_mt_cache"
  MethodInstance for hash(::Any, ::UInt64)
  "invalidate_mt_cache"
  MethodInstance for hash(::Any, ::UInt64)
  "invalidate_mt_cache"
  MethodInstance for hash(::Any, ::UInt64)
  "invalidate_mt_cache"
  MethodInstance for hash(::Any, ::UInt64)
  "invalidate_mt_cache"
  MethodInstance for hash(::Any, ::UInt64)
  "invalidate_mt_cache"
  MethodInstance for hash(::Any, ::UInt64)
  "invalidate_mt_cache"
  MethodInstance for hash(::Any, ::UInt64)
  "invalidate_mt_cache"
  MethodInstance for hash(::Any, ::UInt64)
  "invalidate_mt_cache"
  MethodInstance for hash(::Any, ::UInt64)
  "invalidate_mt_cache"
 ⋮
  "jl_method_table_insert"
  MethodInstance for gr_draw_colorbar(::Plots.GRColorbar, ::Plots.Subplot{Plots.GRBackend}, ::Tuple{Float64, Float64}, ::Vector{Float64})
 1
  MethodInstance for broadcasted(::typeof(Plots.get_linealpha), ::Any)
  "jl_method_table_insert"
  MethodInstance for gr_draw_colorbar(::Plots.GRColorbar, ::Plots.Subplot{Plots.GRBackend}, ::Tuple{Float64, Float64}, ::Vector{Float64})
 1
  MethodInstance for broadcasted(::typeof(Plots.get_fillalpha), ::Any)
  "jl_method_table_insert"
  MethodInstance for gr_draw_colorbar(::Plots.GRColorbar, ::Plots.Subplot{Plots.GRBackend}, ::Tuple{Float64, Float64}, ::Vector{Float64})
 1
  MethodInstance for broadcasted(::typeof(Plots.get_linestyle), ::Any)
  "jl_method_table_insert"
  MethodInstance for gr_draw_colorbar(::Plots.GRColorbar, ::Plots.Subplot{Plots.GRBackend}, ::Tuple{Float64, Float64}, ::Vector{Float64})
 1
  MethodInstance for broadcasted(::typeof(Plots.get_linewidth), ::Any)
  "jl_method_table_insert"
  MethodInstance for gr_draw_colorbar(::Plots.GRColorbar, ::Plots.Subplot{Plots.GRBackend}, ::Tuple{Float64, Float64}, ::Vector{Float64})
 1
  MethodInstance for broadcasted(::typeof(Plots.get_colorgradient), ::Any)
  "jl_method_table_insert"
  MethodInstance for _transform_ticks(::AbstractArray{T, N} where N) where T<:Dates.TimeType
 1
  MethodInstance for broadcasted(::typeof(Dates.value), ::AbstractArray{T, N} where {T<:Dates.TimeType, N})
  "jl_method_table_insert"
  broadcasted(f, x::ComponentArrays.ComponentArray) in ComponentArrays at /Users/oscar/.julia/packages/ComponentArrays/o9aUH/src/broadcasting.jl:72
  "jl_method_table_insert"

JuMP could also do better on this front, but it’s something we’re working on.

julia> using SnoopCompileCore

julia> invalidations = @snoopr begin 
       using JuMP, GLPK
       end
1926-element Vector{Any}:
  MethodInstance for show(::IOBuffer, ::Any)
  "invalidate_mt_cache"
  MethodInstance for jointail(::Any, ::String)
 0
  Tuple{typeof(joinpath), Any, String}
  joinpath(uri::URIs.URI, parts::String...) in URIs at /Users/oscar/.julia/packages/URIs/hubHc/src/URIs.jl:503
  "jl_method_table_insert"
  MethodInstance for var"#add_nested_key!#21"(::Any, ::typeof(REPL.LineEdit.add_nested_key!), ::Dict, ::Char, ::Any)
 1
  MethodInstance for (::REPL.LineEdit.var"#add_nested_key!##kw")(::Any, ::typeof(REPL.LineEdit.add_nested_key!), ::Dict, ::Union{Char, String}, ::Any)
 2
  MethodInstance for in(::Char, ::Base.KeySet)
  "jl_method_table_insert"
  in(key, v::Base.KeySet{K, T}) where {K, T<:(OrderedCollections.OrderedDict{K, V} where V)} in OrderedCollections at /Users/oscar/.julia/packages/OrderedCollections/cP9uu/src/ordered_dict.jl:394
  "jl_method_table_insert"
  MethodInstance for hash(::Any, ::UInt64)
  "invalidate_mt_cache"
  MethodInstance for hash(::Any, ::UInt64)
  "invalidate_mt_cache"
  MethodInstance for hash(::Any, ::UInt64)
  "invalidate_mt_cache"
  MethodInstance for hash(::Any, ::UInt64)
  "invalidate_mt_cache"
  MethodInstance for hash(::Any, ::UInt64)
  "invalidate_mt_cache"
  MethodInstance for hash(::Any, ::UInt64)
  "invalidate_mt_cache"
  MethodInstance for hash(::Any, ::UInt64)
 ⋮
 7
  MethodInstance for collect_to!(::AbstractArray, ::Base.Generator{_A, Test.var"#24#25"{Int64}} where _A, ::Any, ::Any)
 8
  MethodInstance for collect_to_with_first!(::AbstractArray, ::Any, ::Base.Generator{_A, Test.var"#24#25"{Int64}} where _A, ::Any)
 8
  MethodInstance for _collect(::Vector{T} where T, ::Base.Generator{_A, Test.var"#24#25"{Int64}} where _A, ::Base.EltypeUnknown, ::Union{Base.HasLength, Base.HasShape})
 9
  MethodInstance for grow_to!(::AbstractDict{K, V}, ::Base.Generator{_A, Test.var"#24#25"{Int64}} where _A, ::Any) where {K, V}
 7
  MethodInstance for grow_to!(::AbstractDict{K, V}, ::Base.Generator{_A, Test.var"#24#25"{Int64}} where _A, ::Any) where {K, V}
 8
  MethodInstance for collect_to_with_first!(::Any, ::Any, ::Base.Generator{_A, Test.var"#24#25"{Int64}} where _A, ::Any)
 8
  MethodInstance for print_test_results(::Test.DefaultTestSet, ::Int64)
 5
  MethodInstance for print_test_results(::Test.DefaultTestSet)
 6
  MethodInstance for finish(::Test.DefaultTestSet)
 7
  MethodInstance for collect_to_with_first!(::Any, ::Any, ::Base.Generator{_A, Test.var"#24#25"{Int64}} where _A, ::Any)
  "jl_method_table_insert"
  MethodInstance for allbindings(::Any, ::Vector{Any})
 1
  MethodInstance for collect_to_with_first!(::AbstractArray, ::Any, ::Base.Generator, ::Any)
  "jl_method_table_insert"
  collect_to_with_first!(dest::Union{JuMP.Containers.DenseAxisArray, JuMP.Containers.SparseAxisArray}, first_value, iterator, state) in JuMP.Containers at /Users/oscar/.julia/packages/JuMP/y5vgk/src/Containers/Containers.jl:37
  "jl_method_table_insert"

Hmm, thanks for the report! I have a feeling I know what the offending code is, but I’ll have a deeper look as soon as I get some time over.