Slow Julia startup time after sysimage creation (and an unbelievable observation!)

Tooling
, ,
23

Just stumbled upon this interesting thread and decided to see if I can also see the speedup effect when using the double sysimg compile. And I do. Based on @Marcell_Havlik’s script I stripped away some of the larger packages like Zygote and Flux to only leave this (note that this also gets rid of the replacement of the default sysimg and the precompile execution script):

$ cat sysimage_awesome.jl
import Pkg;
installed_pkgs = Pkg.installed()
function add_pkg(name; kw...)
        !(haskey(installed_pkgs, name) && (!(:version in keys(kw)) || installed_pkgs[name] == kw[:version])) && Pkg.add(Pkg.PackageSpec(;name=name, kw...))
end 
add_pkg("Revise")
add_pkg("BenchmarkTools")
add_pkg("Distributions")
add_pkg("OhMyREPL")
add_pkg("EllipsisNotation")
add_pkg("LanguageServer")
add_pkg("Parameters")
add_pkg("JSON2")
add_pkg("JuliaFormatter")
add_pkg("LightGraphs")
add_pkg("GraphPlot")
add_pkg("Plots")
add_pkg("PackageCompiler")
# SymbolServer
using PackageCompiler
@show "Build starting..."

create_sysimage([:Revise, :JuliaFormatter, 
                :LanguageServer, 
                :PackageCompiler,
                :EllipsisNotation, :Parameters, :JSON2,
                :Distributions,
                :OhMyREPL,
                :Plots,
                ];
        replace_default=false,
        sysimage_path="mysysimage.so")

Then compiling the sysimg twice, the second time using the first sysimg:

$ julia sysimage_awesome.jl 
┌ Warning: Pkg.installed() is deprecated
└ @ Pkg /build/julia/src/julia-1.6.1/usr/share/julia/stdlib/v1.6/Pkg/src/Pkg.jl:566
"Build starting..." = "Build starting..."
[ Info: PackageCompiler: creating system image object file, this might take a while...

$ ls -l *.so
-rwxr-xr-x 1 melis users 315158440 Jun 23 11:39 mysysimage.so
$ mv mysysimage.so mysysimage.first.so

$ julia -J mysysimage.first.so sysimage_awesome.jl 
┌ Warning: Pkg.installed() is deprecated
└ @ Pkg /build/julia/src/julia-1.6.1/usr/share/julia/stdlib/v1.6/Pkg/src/Pkg.jl:566
"Build starting..." = "Build starting..."
[ Info: PackageCompiler: creating system image object file, this might take a while...
$ mv mysysimage.so mysysimage.second.so

$ ls -l *.so
-rwxr-xr-x 1 melis users 315158440 Jun 23 11:39 mysysimage.first.so
-rwxr-xr-x 1 melis users 316299536 Jun 23 11:44 mysysimage.second.so

Differences in runtime (for the second time running these commands):

$ time julia -J mysysimage.first.so -E 'print("Julia $(VERSION) with $(length(Base.loaded_modules)) module");'
Julia 1.6.1 with 137 modulenothing

real	0m0.691s
user	0m0.559s
sys	0m0.130s

$ time julia -J mysysimage.second.so -E 'print("Julia $(VERSION) with $(length(Base.loaded_modules)) module");'
Julia 1.6.1 with 137 modulenothing

real	0m0.306s
user	0m0.192s
sys	0m0.106s

Of course, this is a much smaller speedup than OP observes, but it’s still interesting to figure out why this occurs.

Differences in precompile statements:

$ julia -J mysysimage.first.so -E 'print("Julia $(VERSION) with $(length(Base.loaded_modules)) module");' --trace=stderr
precompile(Tuple{typeof(Base.Threads.resize_nthreads!), Array{URIs.RegexAndMatchData, 1}, URIs.RegexAndMatchData})
precompile(Tuple{typeof(Base.Threads.resize_nthreads!), Array{Base.MPFR.BigFloat, 1}, Base.MPFR.BigFloat})
precompile(Tuple{typeof(Base.Threads.resize_nthreads!), Array{Base.GMP.BigInt, 1}, Base.GMP.BigInt})
precompile(Tuple{ArrayInterface.var"#53#80"})
precompile(Tuple{ArrayInterface.var"#56#83"})
precompile(Tuple{ArrayInterface.var"#110#114"})
precompile(Tuple{ArrayInterface.var"#111#115"})
precompile(Tuple{ArrayInterface.var"#112#116"})
precompile(Tuple{typeof(Base.Libc.Libdl.dlopen), String, UInt32})
precompile(Tuple{typeof(Base.invokelatest), Any})
precompile(Tuple{typeof(Base.Threads.resize_nthreads!), Array{Array{Grisu.Bignums.Bignum, 1}, 1}, Array{Grisu.Bignums.Bignum, 1}})
precompile(Tuple{typeof(Base.setindex!), Base.Dict{Symbol, PlotThemes.PlotTheme}, PlotThemes.PlotTheme, Symbol})
precompile(Tuple{typeof(Base.merge), NamedTuple{(), Tuple{}}, Base.Dict{Symbol, Any}})
precompile(Tuple{typeof(Base.foreach), Function, Array{Base.Dict{Symbol, Any}, 1}, Array{Base.Dict{Symbol, Any}, 1}})
precompile(Tuple{typeof(Base.setindex!), Base.Dict{Symbol, Any}, Nothing, Symbol})
precompile(Tuple{typeof(Base.setindex!), Base.Dict{Symbol, Any}, Tuple{Int64, Int64}, Symbol})
precompile(Tuple{typeof(Base.setindex!), Base.Dict{Symbol, Any}, Base.Dict{Any, Any}, Symbol})
precompile(Tuple{typeof(Base.setindex!), Base.Dict{Symbol, Any}, ColorTypes.RGB{FixedPointNumbers.Normed{UInt8, 8}}, Symbol})
precompile(Tuple{typeof(Base.setindex!), Base.Dict{Symbol, Any}, Float64, Symbol})
precompile(Tuple{typeof(Base.setindex!), Base.Dict{Symbol, Any}, Array{Any, 1}, Symbol})
precompile(Tuple{typeof(Base.setindex!), Base.Dict{Symbol, Any}, Array{Float64, 1}, Symbol})
precompile(Tuple{typeof(Base.setindex!), Base.Dict{Symbol, Any}, Measures.Length{:mm, Float64}, Symbol})
precompile(Tuple{typeof(Base.copyto!), Array{Symbol, 1}, Base.KeySet{Symbol, Base.Dict{Symbol, Any}}})
precompile(Tuple{typeof(Plots.treats_y_as_x), Symbol})
precompile(Tuple{typeof(Base.length), Base.Dict{Base.PkgId, Module}})
precompile(Tuple{typeof(Base.string), String, Base.VersionNumber, Vararg{Any, N} where N})
Julia 1.6.1 with 137 moduleprecompile(Tuple{typeof(Base.show), Nothing})
precompile(Tuple{typeof(Base.show), Base.TTY, Nothing})
nothing
precompile(Tuple{typeof(FileWatching.uvfinalize), FileWatching.FileMonitor})

$ julia -J mysysimage.second.so -E 'print("Julia $(VERSION) with $(length(Base.loaded_modules)) module");' --trace=stderr
precompile(Tuple{ArrayInterface.var"#110#114"})
precompile(Tuple{ArrayInterface.var"#111#115"})
precompile(Tuple{ArrayInterface.var"#112#116"})
precompile(Tuple{typeof(Base.length), Base.Dict{Base.PkgId, Module}})
precompile(Tuple{typeof(Base.string), String, Base.VersionNumber, Vararg{Any, N} where N})
Julia 1.6.1 with 137 moduleprecompile(Tuple{typeof(Base.show), Nothing})
precompile(Tuple{typeof(Base.show), Base.TTY, Nothing})
nothing
precompile(Tuple{typeof(FileWatching.uvfinalize), FileWatching.FileMonitor})

Julia Version 1.6.1
Commit 6aaedecc44* (2021-04-23 05:59 UTC)
Platform Info:
  OS: Linux (x86_64-pc-linux-gnu)
  CPU: Intel(R) Core(TM) i5-4460  CPU @ 3.20GHz
  WORD_SIZE: 64
  LIBM: libopenlibm
  LLVM: libLLVM-11.1.0 (ORCJIT, haswell)
1 Like