Loading packages is significantly slower on recent master than on 1.9 beta and 1.8

[bvdmitri]

I'm not sure if this is something known, but I noticed quite a noticable regression on the recent master (built from source today). Julia 1.9-beta includes an awesome feature that precompiles packages better, thus reducing load times. For packages such as Plots and CairoMakie I observe almost twice faster startup times on my machine. This improvement, however, is no longer present on the recent master.

time julia +release --startup-file=no -e 'import CairoMakie'
julia +release --startup-file=no -e 'import CairoMakie'  12.46s user 1.86s system 117% cpu 12.209 total

time julia +1.9 --startup-file=no -e 'import CairoMakie'
julia +1.9 --startup-file=no -e 'import CairoMakie'  6.86s user 1.38s system 128% cpu 6.393 total

time ./julia --startup-file=no -e 'import CairoMakie'
./julia --startup-file=no -e 'import CairoMakie'  14.99s user 0.67s system 109% cpu 14.323 total

Here ./julia is the compiled master binary.
The loading time of CairoMakie is actually even slower than on the current release.

Same is happening for the Plots

time julia +release --startup-file=no -e 'import Plots'
julia +release --startup-file=no -e 'import Plots'  3.00s user 2.10s system 185% cpu 2.755 total

time julia +1.9 --startup-file=no -e 'import Plots'
julia +1.9 --startup-file=no -e 'import Plots'  2.21s user 2.08s system 219% cpu 1.952 total

time ./julia --startup-file=no -e 'import Plots'
./julia --startup-file=no -e 'import Plots'  3.11s user 0.53s system 157% cpu 2.313 total

I executed each command at least 3-4 times, just to ensure everything is precompiled. The pattern repeats, the master is always slower than 1.8 and 1.9-beta.

These are timings with some "workload":

time julia +release --startup-file=no -e 'import CairoMakie; CairoMakie.plot(1:5)'
julia +release --startup-file=no -e 'import CairoMakie; CairoMakie.plot(1:5)'  17.58s user 2.06s system 112% cpu 17.458 total

time julia +1.9 --startup-file=no -e 'import CairoMakie; CairoMakie.plot(1:5)'
julia +1.9 --startup-file=no -e 'import CairoMakie; CairoMakie.plot(1:5)'  6.66s user 2.14s system 136% cpu 6.453 total

time ./julia --startup-file=no -e 'import CairoMakie; CairoMakie.plot(1:5)'
./julia --startup-file=no -e 'import CairoMakie; CairoMakie.plot(1:5)'  15.43s user 0.79s system 108% cpu 14.896 total

time julia +release --startup-file=no -e 'import Plots; Plots.plot(1:5)'
julia +release --startup-file=no -e 'import Plots; Plots.plot(1:5)'  3.54s user 2.10s system 170% cpu 3.305 total

time julia +1.9 --startup-file=no -e 'import Plots; Plots.plot(1:5)'
julia +1.9 --startup-file=no -e 'import Plots; Plots.plot(1:5)'  2.21s user 2.16s system 219% cpu 1.989 total

time ./julia --startup-file=no -e 'import Plots; Plots.plot(1:5)'
./julia --startup-file=no -e 'import Plots; Plots.plot(1:5)'  3.00s user 0.66s system 156% cpu 2.333 total

With some workload timings for the master are better than on 1.8, but still worse than on the 1.9-beta (especially for CairoMakie).

versions:

+release installed from juliaup

julia> versioninfo()
Julia Version 1.8.5
Commit 17cfb8e65ea (2023-01-08 06:45 UTC)
Platform Info:
  OS: macOS (arm64-apple-darwin21.5.0)
  CPU: 10 × Apple M2 Pro
  WORD_SIZE: 64
  LIBM: libopenlibm
  LLVM: libLLVM-13.0.1 (ORCJIT, apple-m1)
  Threads: 1 on 6 virtual cores

+1.9 installed from juliaup

julia> versioninfo()
Julia Version 1.9.0-beta4
Commit b75ddb787ff (2023-02-07 21:53 UTC)
Platform Info:
  OS: macOS (arm64-apple-darwin21.5.0)
  CPU: 10 × Apple M2 Pro
  WORD_SIZE: 64
  LIBM: libopenlibm
  LLVM: libLLVM-14.0.6 (ORCJIT, apple-m1)
  Threads: 1 on 6 virtual cores

master built from source with just git clone & make. No special configuration.

julia> versioninfo()
Julia Version 1.10.0-DEV.664
Commit bfacf2cdf9 (2023-02-27 08:30 UTC)
Platform Info:
  OS: macOS (arm64-apple-darwin22.3.0)
  CPU: 10 × Apple M2 Pro
  WORD_SIZE: 64
  LIBM: libopenlibm
  LLVM: libLLVM-14.0.6 (ORCJIT, apple-m1)
  Threads: 1 on 6 virtual cores

[inkydragon]

tldr:

• -e '0': DEV.0 > DEV.600 > DEV.333 > DEV.669 > 1.9 > 1.8
• import CairoMakie / CairoMakie.plot: 1.8 > DEV.669 > DEV.600 > DEV.333 > DEV.0 > 1.9

exec 0

> hyperfine --ignore-failure `
>> --parameter-list JULIA_EXEC  'V:/julia-nightly/DEV.669-85709517be/bin/julia.exe','V:/julia-nightly/DEV.600-1541519457/bin/julia.exe','V:/julia-nightly/DEV.333-00b0a7b7b1/bin/julia.exe','V:/julia-nightly/DEV.0-7fe6b16f40/bin/julia.exe','julia +1.9','julia +1.8'  `
>> "{JULIA_EXEC} -e '0'"
Benchmark 1: V:/julia-nightly/DEV.669-85709517be/bin/julia.exe -e '0'
  Time (mean ± σ):     185.0 ms ±   4.6 ms    [User: 2.7 ms, System: 7.7 ms]
  Range (min … max):   180.6 ms … 197.3 ms    14 runs

Benchmark 2: V:/julia-nightly/DEV.600-1541519457/bin/julia.exe -e '0'
  Time (mean ± σ):     182.0 ms ±   3.0 ms    [User: 1.8 ms, System: 5.8 ms]
  Range (min … max):   179.6 ms … 191.7 ms    14 runs

Benchmark 3: V:/julia-nightly/DEV.333-00b0a7b7b1/bin/julia.exe -e '0'
  Time (mean ± σ):     182.5 ms ±   2.4 ms    [User: 1.7 ms, System: 6.2 ms]
  Range (min … max):   178.9 ms … 189.4 ms    15 runs

Benchmark 4: V:/julia-nightly/DEV.0-7fe6b16f40/bin/julia.exe -e '0'
  Time (mean ± σ):     177.0 ms ±   2.4 ms    [User: 1.7 ms, System: 6.2 ms]
  Range (min … max):   174.6 ms … 185.1 ms    15 runs

Benchmark 5: julia +1.9 -e '0'
  Time (mean ± σ):     239.1 ms ±   4.1 ms    [User: 6.3 ms, System: 31.4 ms]
  Range (min … max):   235.8 ms … 250.7 ms    11 runs

Benchmark 6: julia +1.8 -e '0'
  Time (mean ± σ):     241.2 ms ±   2.6 ms    [User: 3.5 ms, System: 22.9 ms]
  Range (min … max):   237.9 ms … 247.1 ms    11 runs

Summary
  'V:/julia-nightly/DEV.0-7fe6b16f40/bin/julia.exe -e '0'' ran
    1.03 ± 0.02 times faster than 'V:/julia-nightly/DEV.600-1541519457/bin/julia.exe -e '0''
    1.03 ± 0.02 times faster than 'V:/julia-nightly/DEV.333-00b0a7b7b1/bin/julia.exe -e '0''
    1.05 ± 0.03 times faster than 'V:/julia-nightly/DEV.669-85709517be/bin/julia.exe -e '0''
    1.35 ± 0.03 times faster than 'julia +1.9 -e '0''
    1.36 ± 0.02 times faster than 'julia +1.8 -e '0''

import CairoMakie

> hyperfine --ignore-failure `
>> --parameter-list JULIA_EXEC  'V:/julia-nightly/DEV.669-85709517be/bin/julia.exe','V:/julia-nightly/DEV.600-1541519457/bin/julia.exe','V:/julia-nightly/DEV.333-00b0a7b7b1/bin/julia.exe','V:/julia-nightly/DEV.0-7fe6b16f40/bin/julia.exe','julia +1.9','julia +1.8'  `
>> "{JULIA_EXEC} --startup-file=no -e 'import CairoMakie'"
Benchmark 1: V:/julia-nightly/DEV.669-85709517be/bin/julia.exe --startup-file=no -e 'import CairoMakie'
  Time (mean ± σ):      1.641 s ±  0.008 s    [User: 0.001 s, System: 0.006 s]
  Range (min … max):    1.633 s …  1.659 s    10 runs

  Warning: Ignoring non-zero exit code.

Benchmark 2: V:/julia-nightly/DEV.600-1541519457/bin/julia.exe --startup-file=no -e 'import CairoMakie'
  Time (mean ± σ):      1.643 s ±  0.008 s    [User: 0.001 s, System: 0.004 s]
  Range (min … max):    1.635 s …  1.662 s    10 runs

  Warning: Ignoring non-zero exit code.

Benchmark 3: V:/julia-nightly/DEV.333-00b0a7b7b1/bin/julia.exe --startup-file=no -e 'import CairoMakie'
  Time (mean ± σ):      1.686 s ±  0.008 s    [User: 0.000 s, System: 0.006 s]
  Range (min … max):    1.674 s …  1.703 s    10 runs

  Warning: Ignoring non-zero exit code.

Benchmark 4: V:/julia-nightly/DEV.0-7fe6b16f40/bin/julia.exe --startup-file=no -e 'import CairoMakie'
  Time (mean ± σ):      1.691 s ±  0.008 s    [User: 0.000 s, System: 0.007 s]
  Range (min … max):    1.679 s …  1.708 s    10 runs

  Warning: Ignoring non-zero exit code.

Benchmark 5: julia +1.9 --startup-file=no -e 'import CairoMakie'
  Time (mean ± σ):      1.717 s ±  0.016 s    [User: 0.007 s, System: 0.019 s]
  Range (min … max):    1.705 s …  1.759 s    10 runs

  Warning: Ignoring non-zero exit code.

Benchmark 6: julia +1.8 --startup-file=no -e 'import CairoMakie'
  Time (mean ± σ):      1.508 s ±  0.006 s    [User: 0.003 s, System: 0.035 s]
  Range (min … max):    1.503 s …  1.523 s    10 runs

  Warning: Ignoring non-zero exit code.

Summary
  'julia +1.8 --startup-file=no -e 'import CairoMakie'' ran
    1.09 ± 0.01 times faster than 'V:/julia-nightly/DEV.669-85709517be/bin/julia.exe --startup-file=no -e 'import CairoMakie''
    1.09 ± 0.01 times faster than 'V:/julia-nightly/DEV.600-1541519457/bin/julia.exe --startup-file=no -e 'import CairoMakie''
    1.12 ± 0.01 times faster than 'V:/julia-nightly/DEV.333-00b0a7b7b1/bin/julia.exe --startup-file=no -e 'import CairoMakie''
    1.12 ± 0.01 times faster than 'V:/julia-nightly/DEV.0-7fe6b16f40/bin/julia.exe --startup-file=no -e 'import CairoMakie''
    1.14 ± 0.01 times faster than 'julia +1.9 --startup-file=no -e 'import CairoMakie''

CairoMakie.plot

CairoMakie.plot:

> hyperfine --ignore-failure `
>> --parameter-list JULIA_EXEC  'V:/julia-nightly/DEV.669-85709517be/bin/julia.exe','V:/julia-nightly/DEV.600-1541519457/bin/julia.exe','V:/julia-nightly/DEV.333-00b0a7b7b1/bin/julia.exe','V:/julia-nightly/DEV.0-7fe6b16f40/bin/julia.exe','julia +1.9','julia +1.8'  `
>> "{JULIA_EXEC} --startup-file=no -e 'import CairoMakie; CairoMakie.plot(1:5)'"
Benchmark 1: V:/julia-nightly/DEV.669-85709517be/bin/julia.exe --startup-file=no -e 'import CairoMakie; CairoMakie.plot(1:5)'
  Time (mean ± σ):      1.640 s ±  0.013 s    [User: 0.003 s, System: 0.004 s]
  Range (min … max):    1.630 s …  1.676 s    10 runs

  Warning: Ignoring non-zero exit code.

Benchmark 2: V:/julia-nightly/DEV.600-1541519457/bin/julia.exe --startup-file=no -e 'import CairoMakie; CairoMakie.plot(1:5)'
  Time (mean ± σ):      1.642 s ±  0.004 s    [User: 0.001 s, System: 0.007 s]
  Range (min … max):    1.637 s …  1.651 s    10 runs

  Warning: Ignoring non-zero exit code.

Benchmark 3: V:/julia-nightly/DEV.333-00b0a7b7b1/bin/julia.exe --startup-file=no -e 'import CairoMakie; CairoMakie.plot(1:5)'
  Time (mean ± σ):      1.680 s ±  0.007 s    [User: 0.003 s, System: 0.007 s]
  Range (min … max):    1.664 s …  1.695 s    10 runs

  Warning: Ignoring non-zero exit code.

Benchmark 4: V:/julia-nightly/DEV.0-7fe6b16f40/bin/julia.exe --startup-file=no -e 'import CairoMakie; CairoMakie.plot(1:5)'
  Time (mean ± σ):      1.691 s ±  0.010 s    [User: 0.000 s, System: 0.002 s]
  Range (min … max):    1.677 s …  1.708 s    10 runs

  Warning: Ignoring non-zero exit code.

Benchmark 5: julia +1.9 --startup-file=no -e 'import CairoMakie; CairoMakie.plot(1:5)'
  Time (mean ± σ):      1.708 s ±  0.004 s    [User: 0.007 s, System: 0.018 s]
  Range (min … max):    1.701 s …  1.714 s    10 runs

  Warning: Ignoring non-zero exit code.

Benchmark 6: julia +1.8 --startup-file=no -e 'import CairoMakie; CairoMakie.plot(1:5)'
  Time (mean ± σ):      1.508 s ±  0.007 s    [User: 0.007 s, System: 0.021 s]
  Range (min … max):    1.499 s …  1.521 s    10 runs

  Warning: Ignoring non-zero exit code.

Summary
  'julia +1.8 --startup-file=no -e 'import CairoMakie; CairoMakie.plot(1:5)'' ran
    1.09 ± 0.01 times faster than 'V:/julia-nightly/DEV.669-85709517be/bin/julia.exe --startup-file=no -e 'import CairoMakie; CairoMakie.plot(1:5)''
    1.09 ± 0.01 times faster than 'V:/julia-nightly/DEV.600-1541519457/bin/julia.exe --startup-file=no -e 'import CairoMakie; CairoMakie.plot(1:5)''
    1.11 ± 0.01 times faster than 'V:/julia-nightly/DEV.333-00b0a7b7b1/bin/julia.exe --startup-file=no -e 'import CairoMakie; CairoMakie.plot(1:5)''
    1.12 ± 0.01 times faster than 'V:/julia-nightly/DEV.0-7fe6b16f40/bin/julia.exe --startup-file=no -e 'import CairoMakie; CairoMakie.plot(1:5)''
    1.13 ± 0.01 times faster than 'julia +1.9 --startup-file=no -e 'import CairoMakie; CairoMakie.plot(1:5)''

[staticfloat]

Performing an excruciating timing-dependent git bisect, I have narrowed it down to three commits that contributed to the overall slowdown:

5f40f15 moves loading time from 10s -> 13s
dfab7be moves loading time from 13s -> 16s
51e3bc3 moves loading time from 16s -> 23s

[timholy]

Bump @Keno, @d-netto, @aviatesk.

[d-netto]

I can't reproduce this:

• 1.8.5:

time ./julia-1.8/julia --startup-file=no -e '@time import CairoMakie'
 32.174845 seconds (65.80 M allocations: 3.966 GiB, 4.65% gc time, 2.37% compilation time: 60% of which was recompilation)

real	0m32.498s
user	0m33.814s
sys	0m12.300s

time ./julia-1.8/julia --startup-file=no -e '@time import CairoMakie; CairoMakie.plot(1:5)'
 32.221793 seconds (65.80 M allocations: 3.966 GiB, 4.62% gc time, 2.37% compilation time: 60% of which was recompilation)

real	0m48.042s
user	0m48.660s
sys	0m13.068s

• 1.9.0-beta4:

time ./julia-1.9/julia --startup-file=no -e '@time import CairoMakie'
 13.922967 seconds (23.37 M allocations: 1.428 GiB, 7.90% gc time, 0.59% compilation time)

real	0m14.284s
user	0m16.320s
sys	0m11.542s

time ./julia-1.9/julia --startup-file=no -e '@time import CairoMakie; CairoMakie.plot(1:5)'
 13.930849 seconds (23.37 M allocations: 1.428 GiB, 7.88% gc time, 0.59% compilation time)

real	0m15.002s
user	0m17.005s
sys	0m11.669s

• master (commit a922b5):

time ./julia-master/julia --startup-file=no -e '@time import CairoMakie'
 11.233498 seconds (16.45 M allocations: 1.113 GiB, 19.48% gc time, 0.85% compilation time)

real	0m11.555s
user	0m12.380s
sys	0m5.951s

time ./julia-master/julia --startup-file=no -e '@time import CairoMakie; CairoMakie.plot(1:5)'
 11.165322 seconds (16.45 M allocations: 1.113 GiB, 19.53% gc time, 0.82% compilation time)

real	0m12.234s
user	0m12.811s
sys	0m6.226s

For reference:

julia> versioninfo()
Julia Version 1.10.0-DEV.882
Commit a922b5966c* (2023-03-24 21:24 UTC)
Platform Info:
  OS: Linux (x86_64-linux-gnu)
  CPU: 128 × AMD EPYC 7502 32-Core Processor
  WORD_SIZE: 64
  LIBM: libopenlibm
  LLVM: libLLVM-14.0.6 (ORCJIT, znver2)
  Threads: 1 on 128 virtual cores

[KristofferC]

Can you reproduce anything using the commits identified in the bisect above?

[bvdmitri]

On the recent master (1944ef6) I get:

→ time julia +1.9 --startup-file=no -e 'import CairoMakie'
julia +1.9 --startup-file=no -e 'import CairoMakie'  6.53s user 0.24s system 124% cpu 5.445 total

→ time ./julia --startup-file=no -e 'import CairoMakie'
./julia --startup-file=no -e 'import CairoMakie'  7.35s user 0.31s system 120% cpu 6.339 total

julia> @time import CairoMakie # 1.9-rc1
  5.397666 seconds (17.66 M allocations: 1.108 GiB, 7.08% gc time, 0.62% compilation time)

julia> @time import CairoMakie # master
  6.384992 seconds (17.65 M allocations: 1.193 GiB, 16.17% gc time, 11.87% compilation time: 95% of which was recompilation)

With some workload

→ time julia +1.9 --startup-file=no -e 'import CairoMakie; CairoMakie.plot(1:5)'
julia +1.9 --startup-file=no -e 'import CairoMakie; CairoMakie.plot(1:5)'  6.87s user 0.28s system 121% cpu 5.881 total

→ time ./julia --startup-file=no -e 'import CairoMakie; CairoMakie.plot(1:5)'
./julia --startup-file=no -e 'import CairoMakie; CairoMakie.plot(1:5)'  7.81s user 0.28s system 118% cpu 6.815 total

julia> @time CairoMakie.plot(1:5) # v1.9-rc
  0.246583 seconds (524.47 k allocations: 32.051 MiB, 3.63% gc time, 91.68% compilation time)

julia> @time CairoMakie.plot(1:5) # master
  0.364484 seconds (452.45 k allocations: 27.430 MiB, 49.01% gc time, 96.42% compilation time)

So the situation has improved indeed, still a bit slower than on 1.9 though. From the @time macro I can see that master recompiles something extra. It happens every time for me (e.g. if I restart the REPL). Could the improvement be in just a new version of CairoMakie?

These tests were made on [13f3f980] CairoMakie v0.10.3 for both 1.9-rc1 and master.

[ufechner7]

I cannot reproduce this on Linux:

ufechner@ufryzen:~/repos/julia$ time ./julia -e 'import CairoMakie'

real	0m1,897s
user	0m1,953s
sys	0m0,841s

ufechner@ufryzen:~/repos/julia$ time julia -e 'import CairoMakie'

real	0m3,283s
user	0m3,321s
sys	0m0,861s

The first one is current master (Version 1.10.0-DEV.1292 (2023-05-14)), the second one Julia 1.9.

Can this issue be closed?