Flux.jl: Regression in package load time
There seems to have been a regression in package load time. I've seen this on MacOS (no CUDA) and Linux on Aarch64 (with CUDA)
_ _ _(_)_ | Documentation: https://docs.julialang.org
(_) | (_) (_) |
_ _ _| |_ __ _ | Type "?" for help, "]?" for Pkg help.
| | | | | | |/ _` | |
| | |_| | | | (_| | | Version 1.4.1 (2020-04-14)
_/ |\__'_|_|_|\__'_| | Official https://julialang.org/ release
|__/ |
julia> @time using Flux
[ Info: Precompiling Flux [587475ba-b771-5e3f-ad9e-33799f191a9c]
87.462174 seconds (55.38 M allocations: 2.974 GiB, 1.08% gc time)
julia> exit()
...
julia> @time using Flux
17.692934 seconds (54.86 M allocations: 2.950 GiB, 4.54% gc time)
Worth noting that if Revise is loaded, there's also an additional wait for the REPL to be available again, which seems to be demonstratable via. @time @time (Revise issue https://github.com/timholy/Revise.jl/issues/456):
julia> @time @time using Flux
18.218871 seconds (54.86 M allocations: 2.951 GiB, 4.66% gc time)
29.519402 seconds (93.88 M allocations: 4.444 GiB, 4.69% gc time)
[587475ba] Flux v0.10.4
[295af30f] Revise v2.6.4
ianshmean
All 14 comments
Probably related to a recent Zygote release, and related to FluxML/Zygote.jl#607
DhairyaLGandhi
on 2 May 2020
Could we try with explicitly loading flux with a few old zygote releases to help bisect the issue?
DhairyaLGandhi
on 2 May 2020
This was happening before zygote https://github.com/FluxML/Zygote.jl/pull/607. I’m happy to try to bisect it
ianshmean
on 2 May 2020
That would be really good, if you could take a look at it
Thanks @ianshmean !
DhairyaLGandhi
on 2 May 2020
Bisecting Zygote load times on 1.4.1 on MacOS (without Revise loaded). v0.4.4 hits a Deprecated syntax '(;)', so I stopped at v0.4.5
│ Row │ version │ seconds │
│ │ VersionN… │ Float64 │
├─────┼───────────┼─────────┤
│ 1 │ v"0.4.19" │ 4.51003 │
│ 2 │ v"0.4.18" │ 4.48009 │
│ 3 │ v"0.4.17" │ 4.48958 │
│ 4 │ v"0.4.16" │ 19.0388 │
│ 5 │ v"0.4.15" │ 18.8542 │
│ 6 │ v"0.4.14" │ 20.1503 │
│ 7 │ v"0.4.13" │ 20.1037 │
│ 8 │ v"0.4.12" │ 21.7398 │
│ 9 │ v"0.4.11" │ 21.6091 │
│ 10 │ v"0.4.10" │ 19.4583 │
│ 11 │ v"0.4.9" │ 19.1006 │
│ 12 │ v"0.4.8" │ 18.8055 │
│ 13 │ v"0.4.7" │ 18.7565 │
│ 14 │ v"0.4.6" │ 18.612 │
│ 15 │ v"0.4.5" │ 19.0294 │
https://github.com/FluxML/Zygote.jl/pull/607 was released in 0.4.17, so for Zygote alone it improved load time (as to be expected, given less code run during init), but that might have a knock-on detrimental effect on Flux load times
Maybe this is a 1.4.1 issue. I'll try on 1.3.1 too
Script used:
function runjulia(e)
run(`$(joinpath(Sys.BINDIR, Base.julia_exename())) --project=$(@__DIR__) --startup-file=no -e "$e"`)
end
using BenchmarkTools, Pkg, DataFrames
Pkg.activate(@__DIR__)
Pkg.up()
reg = "/home/leuko/.julia/registries/General/Z/Zygote/Versions.toml"
regdict = Pkg.TOML.parsefile(reg)
versions = reverse(sort(VersionNumber.(keys(regdict))))
df = DataFrame(version=VersionNumber[], seconds=Float64[])
for v in versions
@show v
Pkg.add(Pkg.PackageSpec(;name="Zygote", version=v))
runjulia("using Zygote") #do any precomp before @benchmark evaluates how fast the function will run
t = @benchmark runjulia("using Zygote")
@show t.times ./ 1e9
append!(df, DataFrame(version=v, seconds=median(t).time / 1e9))
end
Zygote load times on 1.3.1 on MacOS
│ Row │ version │ seconds │
│ │ VersionN… │ Float64 │
├─────┼───────────┼─────────┤
│ 1 │ v"0.4.19" │ 6.29911 │
│ 2 │ v"0.4.18" │ 6.38034 │
│ 3 │ v"0.4.17" │ 7.0203 │
│ 4 │ v"0.4.16" │ 19.6958 │
│ 5 │ v"0.4.15" │ 19.6893 │
│ 6 │ v"0.4.14" │ 20.2707 │
│ 7 │ v"0.4.13" │ 19.5318 │
│ 8 │ v"0.4.12" │ 17.4778 │
Zygote load times on 1.3.1 on Ubuntu x86_64 with an NVIDIA gpu
│ Row │ version │ seconds │
│ │ VersionN… │ Float64 │
├─────┼───────────┼─────────┤
│ 1 │ v"0.4.19" │ 5.35842 │
│ 2 │ v"0.4.18" │ 5.34299 │
│ 3 │ v"0.4.17" │ 5.33254 │
│ 4 │ v"0.4.16" │ 5.35051 │
│ 5 │ v"0.4.15" │ 5.36513 │
│ 6 │ v"0.4.14" │ 5.33799 │
│ 7 │ v"0.4.13" │ 5.32486 │
│ 8 │ v"0.4.12" │ 5.522 │
│ 9 │ v"0.4.11" │ 5.38264 │
│ 10 │ v"0.4.10" │ 5.36026 │
│ 11 │ v"0.4.9" │ 5.3674 │
│ 12 │ v"0.4.8" │ 5.34033 │
│ 13 │ v"0.4.7" │ 5.41108 │
│ 14 │ v"0.4.6" │ 5.36357 │
│ 15 │ v"0.4.5" │ 5.34436 │
│ 16 │ v"0.4.4" │ 5.3155 │
│ 17 │ v"0.4.3" │ 5.3329 │
│ 18 │ v"0.4.2" │ 5.29466 │
│ 19 │ v"0.4.1" │ 5.32087 │
│ 20 │ v"0.4.0" │ 5.34381 │
│ 21 │ v"0.3.4" │ 5.32319 │
│ 22 │ v"0.3.3" │ 5.30647 │
│ 23 │ v"0.3.2" │ 5.3183 │
Julia v1.3.1
│ Row │ version │ seconds │
│ │ VersionN… │ Float64 │
├─────┼───────────┼─────────┤
│ 1 │ v"0.4.19" │ 4.32729 │
│ 2 │ v"0.4.18" │ 4.17895 │
│ 3 │ v"0.4.17" │ 4.19689 │
│ 4 │ v"0.4.16" │ 15.3199 │
│ 5 │ v"0.4.15" │ 14.2902 │
│ 6 │ v"0.4.14" │ 14.4786 │
│ 7 │ v"0.4.13" │ 14.2482 │
│ 8 │ v"0.4.12" │ 13.0433 │
Julia v1.4.1
│ Row │ version │ seconds │
│ │ VersionN… │ Float64 │
├─────┼───────────┼─────────┤
│ 1 │ v"0.4.19" │ 2.2077 │
│ 2 │ v"0.4.18" │ 2.20337 │
│ 3 │ v"0.4.17" │ 2.20106 │
│ 4 │ v"0.4.16" │ 12.8356 │
│ 5 │ v"0.4.15" │ 12.8612 │
│ 6 │ v"0.4.14" │ 12.9725 │
│ 7 │ v"0.4.13" │ 13.0078 │
│ 8 │ v"0.4.12" │ 14.8832 │
oliver@debian:~$ uname -a
Linux debian 4.19.0-8-amd64 #1 SMP Debian 4.19.98-1+deb10u1 (2020-04-27) x86_64 GNU/Linux
oliver@debian:~$ nvidia-smi
Sat May 2 14:27:02 2020
+-----------------------------------------------------------------------------+
| NVIDIA-SMI 418.74 Driver Version: 418.74 CUDA Version: 10.1 |
|-------------------------------+----------------------+----------------------+
oliver@debian:~$ julia
julia> versioninfo()
Julia Version 1.4.1
Commit 381693d3df* (2020-04-14 17:20 UTC)
Platform Info:
OS: Linux (x86_64-pc-linux-gnu)
CPU: Intel(R) Core(TM) i5-9600K CPU @ 3.70GHz
WORD_SIZE: 64
LIBM: libopenlibm
LLVM: libLLVM-8.0.1 (ORCJIT, skylake)
kw-fn
on 2 May 2020
I've been experiencing the same load time regression (also on Ubuntu/x64/NVIDIA GPU). Using @ianshmean's method, the sum of the median times for each dependency is around 12s. For reference, Flux takes ~16s.
│ Row │ name │ seconds │
│ │ String │ Float64 │
├─────┼────────────────┼───────────┤
│ 1 │ AbstractTrees │ 0.156644 │
│ 2 │ Adapt │ 0.131289 │
│ 3 │ CodecZlib │ 0.318383 │
│ 4 │ Colors │ 0.783943 │
│ 5 │ CuArrays │ 2.91121 │
│ 6 │ DelimitedFiles │ 0.0923371 │
│ 7 │ Juno │ 0.326367 │
│ 8 │ MacroTools │ 0.238282 │
│ 9 │ NNlib │ 0.315076 │
│ 10 │ Pkg │ 0.0922212 │
│ 11 │ Printf │ 0.0922388 │
│ 12 │ Random │ 0.0922166 │
│ 13 │ Reexport │ 0.0938258 │
│ 14 │ SHA │ 0.0922245 │
│ 15 │ Statistics │ 0.0922111 │
│ 16 │ StatsBase │ 0.379776 │
│ 17 │ Test │ 0.0923305 │
│ 18 │ ZipFile │ 0.296342 │
│ 19 │ Zygote │ 5.51149 │
ToucheSir
on 2 May 2020
MacOS using Flux time for Flux 0.10.3, with all compatible Zygote versions:
│ Row │ zygote_v │ seconds │
│ │ VersionN… │ Float64 │
├─────┼───────────┼─────────┤
│ 1 │ v"0.4.19" │ 14.8627 │
│ 2 │ v"0.4.18" │ 13.8563 │
│ 3 │ v"0.4.17" │ 13.9715 │
│ 4 │ v"0.4.16" │ 27.2192 │
│ 5 │ v"0.4.15" │ 28.211 │
│ 6 │ v"0.4.14" │ 27.799 │
│ 7 │ v"0.4.13" │ 28.2803 │
Attempting to find precompile invalidations, I tried setting JL_DEBUG_METHOD_INVALIDATION=1 in src/gf.c on julia master and rebuilding, then running using Flux
https://gist.github.com/ianshmean/3c4de43322d83e31961186ec5913538e
ctrl-f on the string ">>" through that file to see the sources of invalidation. The biggest by count of functions recompiled is:
>> ColorTypes.convert(...) Tuple{typeof(Base.convert), Type{C}, Any} where C<:(ColorTypes.Colorant{T, N} where N where T)
and a third of them are from StaticArrays
ianshmean
on 3 May 2020
Interesting. First thing is that load time has come down a bit recently, which is great.
StaticArrays isn't a direct dependency, so something if off there. We could also remove the Colors dependency to investigate if that has any impact on load times.
Pinging @KristofferC for his thoughts, and @MikeInnes if he has thoughts about this
DhairyaLGandhi
on 3 May 2020
Work being done upstream that may impact this positively https://github.com/JuliaLang/julia/pull/35714
ianshmean
on 4 May 2020
This is awesome!
DhairyaLGandhi
on 4 May 2020
Related issues
davidljung
·
4Comments
pylat
·
3Comments
xiaodaigh
·
5Comments
MikeInnes
·
3Comments
mkborregaard
·
5Comments
Most helpful comment
This is awesome!