4x regression for loading JLLs in 1.11, or likely the first one, such as micromamba_jll

[PallHaraldsson]

@cdoris, Probably needs only this one additionally: precompile(Tuple{typeof(Base.first), Array{Any, 1}}) impacting e.g. CondaPkg, and therefore PythonCall.

or all of them, at least somewhere? Might then improve on 1.10 timing? JLLWrappers takes most, 53%, of this time (well because of Dates), and itself has 2.7x regression.

$ time julia +1.11 --trace-compile=stderr -e "using micromamba_jll"
precompile(Tuple{typeof(Base.setindex!), Base.EnvDict, Bool, String})
precompile(Tuple{typeof(micromamba_jll.find_artifact_dir)})
precompile(Tuple{typeof(Base.invokelatest), Any})
precompile(Tuple{typeof(JLLWrappers.get_julia_libpaths)})
precompile(Tuple{typeof(Base.first), Array{Any, 1}})

real	0m0,957s
user	0m1,717s
sys	0m0,133s

$ time julia +1.10 --trace-compile=stderr -e "using micromamba_jll"
precompile(Tuple{typeof(Base.setindex!), Base.EnvDict, Bool, String})
precompile(Tuple{typeof(micromamba_jll.find_artifact_dir)})
precompile(Tuple{typeof(Base.invokelatest), Any})
precompile(Tuple{typeof(JLLWrappers.get_julia_libpaths)})

real	0m0,295s
user	0m0,417s
sys	0m0,232s

$ time julia +1.11 -e "using JLLWrappers"

real	0m0,293s
user	0m0,921s
sys	0m0,087s

$ time julia +1.10 -e "using JLLWrappers"

real	0m0,268s
user	0m0,342s
sys	0m0,180s

[giordano]

You know right that with time julia -e 'using ...' you're including julia startup and if you want to measure something more meaningful you should instead look at julia -e '@time using ...'?

[giordano]

Also, most of the time loading JLLWrappers comes from loading Dates, which isn't in the sysimage anymore:

# Julia 1.10.5
julia> @time_imports using JLLWrappers
     14.2 ms  Preferences
      0.7 ms  JLLWrappers

# julia 1.11.0-rc3
julia> @time_imports using JLLWrappers
      1.0 ms  Printf
     23.4 ms  Dates
      0.7 ms  TOML
      8.4 ms  Preferences
      0.5 ms  JLLWrappers

[giordano]

And most of the time to load micromamba_jll comes from loading Pkg and other stdlibs, which also aren't in the sysimage anymore:

# Julia 1.10.5
julia> @time_imports using micromamba_jll
      0.6 ms  LazyArtifacts
     13.6 ms  Preferences
      0.9 ms  JLLWrappers
               ┌ 3.4 ms micromamba_jll.__init__() 93.99% compilation time
     25.5 ms  micromamba_jll 95.53% compilation time

# julia 1.11.0-rc3
julia> @time_imports using micromamba_jll
      0.7 ms  Printf
     16.4 ms  Dates
      0.6 ms  TOML
               ┌ 0.0 ms NetworkOptions.__init__()
      1.8 ms  NetworkOptions
               ┌ 1.0 ms MbedTLS_jll.__init__()
      2.8 ms  MbedTLS_jll
               ┌ 0.4 ms LibSSH2_jll.__init__()
      2.1 ms  LibSSH2_jll
               ┌ 0.8 ms LibGit2_jll.__init__()
      2.5 ms  LibGit2_jll
      6.2 ms  LibGit2
      6.2 ms  ArgTools
               ┌ 0.3 ms nghttp2_jll.__init__()
      2.0 ms  nghttp2_jll
               ┌ 0.7 ms LibCURL_jll.__init__()
      2.3 ms  LibCURL_jll
               ┌ 0.0 ms MozillaCACerts_jll.__init__()
      1.7 ms  MozillaCACerts_jll
               ┌ 0.0 ms LibCURL.__init__()
      1.0 ms  LibCURL
               ┌ 2.9 ms Downloads.Curl.__init__()
     14.5 ms  Downloads
      0.7 ms  Tar
               ┌ 0.0 ms p7zip_jll.__init__()
      2.4 ms  p7zip_jll
      0.3 ms  UUIDs
      0.3 ms  Logging
               ┌ 0.0 ms Pkg.__init__()
    204.8 ms  Pkg
      0.4 ms  LazyArtifacts
      5.2 ms  Preferences
      0.4 ms  JLLWrappers
               ┌ 2.0 ms micromamba_jll.__init__() 95.06% compilation time
     86.5 ms  micromamba_jll 99.02% compilation time (52% recompilation)

Unless you want to suggest putting the stdlibs back in the sysimage which isn't going to happen, I'm not sure there's much to do here.

[PallHaraldsson]

I have nothing in my startup, but @time actually messes up my timings or at least emits more precompile statements (also for some reason I can only use @time_imports, my previously preferred way to see what's happening, only in the REPL, and I'm also not sure it shows everything), why I time the other way.

Yes, Dates slower:

$ time julia +1.11 --trace-compile=stderr -e "using Dates"
precompile(Tuple{typeof(Base.setindex!), Base.EnvDict, Bool, String})

real	0m0,263s
user	0m0,713s
sys	0m0,078s

$ time julia +1.10 --trace-compile=stderr -e "using Dates"
precompile(Tuple{typeof(Base.setindex!), Base.EnvDict, Bool, String})

real	0m0,256s
user	0m0,257s
sys	0m0,139s

while for some reason nothing Dates related shown to precompile, also that one seems like a misdirection, with it not affecting e.g. this much:

$ time julia +1.11 --trace-compile=stderr -e "using Pidfile"
precompile(Tuple{typeof(Base.setindex!), Base.EnvDict, Bool, String})

real	0m0,209s
user	0m0,264s
sys	0m0,083s

$ time julia +1.10 --trace-compile=stderr -e "using Pidfile"
precompile(Tuple{typeof(Base.setindex!), Base.EnvDict, Bool, String})

real	0m0,252s
user	0m0,236s
sys	0m0,143s

[PallHaraldsson]

Unless you want to suggest putting the stdlibs back in the sysimage which isn't going to happen, I'm not sure there's much to do here.

I'm not suggesting that, though Dates, or at least most important parts of it arguable should be there. Stdlibs DO have their own pkgimage, each, right (I've been looking into locating where exactly), like any other package. I've already fixed Markdown without putting anything (I think!) in the sysimage.

[KristofferC]

Everything here seems to be explained by some stdlibs not being in the sysimage.

@PallHaraldsson, you seem to be very focused on what is emitted by --trace-compile without checking how long time those actually take, for example:

julia> @time precompile(Tuple{typeof(Base.first), Array{Any, 1}})
  0.003785 seconds (16 allocations: 944 bytes, 99.53% compilation time)

[PallHaraldsson]

Yes, thanks, I'm learning and believe I found the root cause, made an issue, and see this answer: #55725 (comment) It's still a regression, so maybe shouldn't have been closed, but ok, since the other newer issue still open and likely the root cause. At least this was a regression, just (was) unclear the cause.