Skip to content
New issue

Have a question about this project? Sign up for a free GitHub account to open an issue and contact its maintainers and the community.

Sign up for GitHub

By clicking “Sign up for GitHub”, you agree to our terms of service and privacy statement. We’ll occasionally send you account related emails.

Already on GitHub? Sign in to your account

Jump to bottom

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

Closed
bvdmitri opened this issue Feb 27, 2023 · 10 comments
Closed

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

bvdmitri opened this issue Feb 27, 2023 · 10 comments
Labels
compiler:latency Compiler latency regression Regression in behavior compared to a previous version
Milestone
1.10

Comments

@bvdmitri
Copy link
Contributor

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
Copy link
Member

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)''

@JeffBezanson JeffBezanson added regression Regression in behavior compared to a previous version compiler:latency Compiler latency labels Feb 28, 2023
@aviatesk aviatesk mentioned this issue Mar 2, 2023
Closed
@KristofferC KristofferC added this to the 1.10 milestone Mar 2, 2023
@staticfloat
Copy link
Member

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

aviatesk added a commit that referenced this issue Mar 3, 2023
@aviatesk
bail out call inference when return type is maximized
1ba1011 
We made the condition to bail out call inference a bit more strict
in #48263 by looking at the inferred effects. It turns out that it slows
down package loading time as reported at #48811.

This commit simply remove the condition. In particular, the loading time
of `CairoMakie` is reduced to 40s from 48s (on master).

External `AbstractInterpreter` can use the current condition by
overloading `bail_out_call`.
@aviatesk aviatesk mentioned this issue Mar 3, 2023
Open
@timholy
Copy link
Member

timholy commented Mar 24, 2023

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

@d-netto
Copy link
Member

d-netto commented Mar 24, 2023

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
Copy link
Member

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

@bvdmitri
Copy link
Contributor Author

bvdmitri commented Mar 26, 2023 •
edited
Loading

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
Copy link

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?

@KristofferC
Copy link
Member

A lot of work has been done on load times but it doesn't mean that the regressions identified in #48811 (comment) are fixed.

@vtjnash
Copy link
Member

vtjnash commented May 14, 2023

I don't think any of those commits are expected to be "fixed" more. The GC did have an error that was fixed and possibly related. But the others were supposed to replace fast path code with better inference results, so seem to be working as intended when we merged those.

@ufechner7
Copy link

@KristofferC Can this issue be closed? If not, what would be the action points?

Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment
Assignees
No one assigned
Labels
compiler:latency Compiler latency regression Regression in behavior compared to a previous version
Projects
None yet
Milestone
1.10
Development

No branches or pull requests
9 participants
@staticfloat @vtjnash @JeffBezanson @KristofferC @timholy @ufechner7 @inkydragon @bvdmitri @d-netto