Julia 1.11 is slower than 1.10?

jling · October 9, 2024, 10:42pm

we have the same CPU, so why is this time double of mine? do you have startup script?

also are you sure you’re not running rc4? rc4 is stable for me:

akako@frame16 ~> hyperfine --warmup 1 'julia +1.11.0-rc4 --startup-file=no -e "1+1"'
Benchmark 1: julia +1.11.0-rc4 --startup-file=no -e "1+1"
  Time (mean ± σ):      99.7 ms ±   7.9 ms    [User: 64.4 ms, System: 54.6 ms]
  Range (min … max):    89.0 ms … 120.7 ms    29 runs

akako@frame16 ~> hyperfine --warmup 1 'julia +1.11.0 --startup-file=no -e "1+1"'
Benchmark 1: julia +1.11.0 --startup-file=no -e "1+1"
  Time (mean ± σ):     124.9 ms ±  59.2 ms    [User: 309.2 ms, System: 44.7 ms]
  Range (min … max):    80.4 ms … 206.4 ms    14 runs

Ronis_BR · October 9, 2024, 11:56pm

I am also seeing a huge pre-compilation increase in 1.11 compared to 1.10.

Julia 1.10

julia> using PrettyTables

julia> A = ones(2, 2)
2×2 Matrix{Float64}:
 1.0  1.0
 1.0  1.0

julia> @time pretty_table(A)
┌────────┬────────┐
│ Col. 1 │ Col. 2 │
├────────┼────────┤
│    1.0 │    1.0 │
│    1.0 │    1.0 │
└────────┴────────┘
  0.032161 seconds (42.28 k allocations: 3.059 MiB, 97.47% compilation time)

Julia 1.11

julia> using PrettyTables

julia> A = ones(2, 2)
2×2 Matrix{Float64}:
 1.0  1.0
 1.0  1.0

julia> @time pretty_table(A)
┌────────┬────────┐
│ Col. 1 │ Col. 2 │
├────────┼────────┤
│    1.0 │    1.0 │
│    1.0 │    1.0 │
└────────┴────────┘
  0.125523 seconds (784.80 k allocations: 42.458 MiB, 34.03% gc time, 99.67% compilation time: 78% of which was recompilation)

Any ideas where should I start to look for possible fixes?

lmiq · October 10, 2024, 12:20am

Maybe that’s related to the StyledStrings package.

giordano · October 10, 2024, 12:21am

--trace-compile

ufechner7 · October 10, 2024, 4:58am

ufechner@framework:~$ hyperfine --warmup 1 'julia +1.11 --startup-file=no -e "1+1"'
Benchmark 1: julia +1.11 --startup-file=no -e "1+1"
  Time (mean ± σ):     205.9 ms ±   2.8 ms    [User: 719.6 ms, System: 57.0 ms]
  Range (min … max):   201.9 ms … 212.2 ms    14 runs

This is on grid power. If I see it correctly you have a framework16, I have framework14 which does not have the same CPU.

ufechner@framework:~$ julia +1.11
               _
   _       _ _(_)_     |  Documentation: https://docs.julialang.org
  (_)     | (_) (_)    |
   _ _   _| |_  __ _   |  Type "?" for help, "]?" for Pkg help.
  | | | | | | |/ _` |  |
  | | |_| | | | (_| |  |  Version 1.11.0 (2024-10-07)
 _/ |\__'_|_|_|\__'_|  |  Official https://julialang.org/ release
|__/                   |

Ronis_BR · October 10, 2024, 10:41am

Thanks!

I opened an issue:

github.com/JuliaLang/julia

Huge precompilation overhead in Julia 1.11

opened 10:37AM - 10 Oct 24 UTC

ronisbr

Hi! I am seeing a huge precompilation overhead using Julia 1.11: **Julia 1.10*…* ``` julia> using PrettyTables julia> A = ones(2, 2) 2×2 Matrix{Float64}: 1.0 1.0 1.0 1.0 julia> @time pretty_table(A) ┌────────┬────────┐ │ Col. 1 │ Col. 2 │ ├────────┼────────┤ │ 1.0 │ 1.0 │ │ 1.0 │ 1.0 │ └────────┴────────┘ 0.032161 seconds (42.28 k allocations: 3.059 MiB, 97.47% compilation time) ``` **Julia 1.11** ``` julia> using PrettyTables julia> A = ones(2, 2) 2×2 Matrix{Float64}: 1.0 1.0 1.0 1.0 julia> @time pretty_table(A) ┌────────┬────────┐ │ Col. 1 │ Col. 2 │ ├────────┼────────┤ │ 1.0 │ 1.0 │ │ 1.0 │ 1.0 │ └────────┴────────┘ 0.125523 seconds (784.80 k allocations: 42.458 MiB, 34.03% gc time, 99.67% compilation time: 78% of which was recompilation) ``` This issue leads to a very large time to print the first table in PrettyTables.jl. Unfortunately, I could not obtain a minimum working example. Using `--track-compilation`, as suggested by @giordano, leads to: **Julia 1.10** ``` precompile(Tuple{typeof(Base.seek), Base.GenericIOBuffer{Array{UInt8, 1}}, Int64}) precompile(Tuple{typeof(Base.something), REPL.LineEdit.Prompt, REPL.LineEdit.Prompt}) precompile(Tuple{typeof(Base.ones), Int64, Int64}) precompile(Tuple{typeof(Base.show), Base.IOContext{Base.TTY}, Base.Multimedia.MIME{Symbol("text/plain")}, Array{Float64, 2}}) precompile(Tuple{typeof(Base.alignment), Base.IOContext{Base.TTY}, Float64}) precompile(Tuple{typeof(Base.show), Base.IOContext{Base.GenericIOBuffer{Array{UInt8, 1}}}, String, Float64}) precompile(Tuple{typeof(Base.replace_in_print_matrix), Array{Float64, 2}, Int64, Int64, String}) precompile(Tuple{Type{Base.IOContext{IO_t} where IO_t<:IO}, Base.TTY, Pair{Symbol, Bool}}) precompile(Tuple{typeof(PrettyTables._preprocess_vec_or_mat), Array{Float64, 2}, Nothing}) precompile(Tuple{typeof(Base.get), Base.IOContext{Base.TTY}, Symbol, Nothing}) precompile(Tuple{typeof(PrettyTables._getdata), Array{Float64, 2}}) precompile(Tuple{Type{Base.IOContext{IO_t} where IO_t<:IO}, Base.IOContext{Base.TTY}, Pair{Symbol, Array{Any, 1}}}) precompile(Tuple{typeof(Base.sym_in), Symbol, NTuple{17, Symbol}}) precompile(Tuple{typeof(Core.kwcall), NamedTuple{(:alignment, :cell_alignment, :header_alignment, :header_cell_alignment, :max_num_of_columns, :max_num_of_rows, :show_header, :show_subheader), Tuple{Symbol, Nothing, Symbol, Nothing, Int64, Int64, Bool, Bool}}, Type{PrettyTables.ProcessedTable}, Array{Float64, 2}, Tuple{Array{String, 1}}}) precompile(Tuple{typeof(Base.escape_string), Base.GenericIOBuffer{Array{UInt8, 1}}, String, String}) precompile(Tuple{typeof(PrettyTables._convert_axes), Array{Float64, 2}, Int64, Int64}) precompile(Tuple{Type{Base.IOContext{IO_t} where IO_t<:IO}, Base.IOContext{Base.TTY}, Pair{Symbol, Bool}, Pair{Symbol, Bool}}) precompile(Tuple{typeof(Core.kwcall), NamedTuple{(:context,), Tuple{Base.IOContext{Base.TTY}}}, typeof(Base.sprint), Function, Float64}) precompile(Tuple{typeof(PrettyTables._flush_display!), Base.IOContext{Base.TTY}, PrettyTables.Display, Bool, Bool, Int64}) precompile(Tuple{typeof(Base.Ryu.writefixed), Float64, Int64}) ``` **Julia 1.11** ``` precompile(Tuple{typeof(Base.seek), Base.GenericIOBuffer{GenericMemory{:not_atomic, UInt8, Core.AddrSpace{Core}(0x00)}}, Int64}) precompile(Tuple{typeof(Base.something), REPL.LineEdit.Prompt, REPL.LineEdit.Prompt}) precompile(Tuple{typeof(Base.in), String, Array{String, 1}}) precompile(Tuple{typeof(REPL.LineEdit.history_prev_prefix), REPL.LineEdit.PrefixSearchState, REPL.REPLHistoryProvider, AbstractString}) precompile(Tuple{typeof(Base.ones), Int64, Int64}) precompile(Tuple{typeof(Base.show), Base.IOContext{Base.TTY}, Base.Multimedia.MIME{:var"text/plain"}, Array{Float64, 2}}) precompile(Tuple{typeof(Base.alignment), Base.IOContext{Base.TTY}, Float64}) precompile(Tuple{typeof(Base.show), Base.IOContext{Base.GenericIOBuffer{GenericMemory{:not_atomic, UInt8, Core.AddrSpace{Core}(0x00)}}}, String, Float64}) precompile(Tuple{typeof(Base.replace_in_print_matrix), Array{Float64, 2}, Int64, Int64, String}) precompile(Tuple{typeof(Base.repeat), Char, Int64}) precompile(Tuple{Type{NamedTuple{(:sortkeys,), T} where T<:Tuple}, Tuple{Bool}}) precompile(Tuple{typeof(Base.:(==)), Bool, Bool}) precompile(Tuple{Type{NamedTuple{(:foreground,), T} where T<:Tuple}, Tuple{Symbol}}) precompile(Tuple{typeof(Core.memoryref), GenericMemory{:not_atomic, NamedTuple{(:pos, :active, :index), Tuple{Int64, Bool, Int64}}, Core.AddrSpace{Core}(0x00)}}) precompile(Tuple{typeof(Core.memoryref), GenericMemory{:not_atomic, Array{Pair{Symbol, Any}, 1}, Core.AddrSpace{Core}(0x00)}}) precompile(Tuple{typeof(PrettyTables.pretty_table), Any}) precompile(Tuple{Type{Base.IOContext{IO_t} where IO_t<:IO}, Base.TTY, Pair{Symbol, Bool}}) precompile(Tuple{typeof(PrettyTables._preprocess_vec_or_mat), Array{Float64, 2}, Nothing}) precompile(Tuple{typeof(Core.kwcall), NamedTuple{(:header,), Tuple{Tuple{Array{String, 1}}}}, typeof(PrettyTables._print_table), IO, Any}) precompile(Tuple{typeof(Base.get), Base.IOContext{Base.TTY}, Symbol, Nothing}) precompile(Tuple{typeof(PrettyTables._getdata), Array{Float64, 2}}) precompile(Tuple{Type{Base.IOContext{IO_t} where IO_t<:IO}, Base.IOContext{Base.TTY}, Pair{Symbol, Array{Any, 1}}}) precompile(Tuple{typeof(Core.kwcall), NamedTuple{(:alignment, :cell_alignment, :header_alignment, :header_cell_alignment, :max_num_of_columns, :max_num_of_rows, :show_header, :show_subheader), Tuple{Symbol, Nothing, Symbol, Nothing, Int64, Int64, Bool, Bool}}, Type{PrettyTables.ProcessedTable}, Array{Float64, 2}, Tuple{Array{String, 1}}}) precompile(Tuple{typeof(Base.setindex!), GenericMemory{:not_atomic, Int64, Core.AddrSpace{Core}(0x00)}, Int64, Int64}) precompile(Tuple{typeof(Base.escape_string), Base.GenericIOBuffer{GenericMemory{:not_atomic, UInt8, Core.AddrSpace{Core}(0x00)}}, String, String}) precompile(Tuple{typeof(PrettyTables._convert_axes), Array{Float64, 2}, Int64, Int64}) precompile(Tuple{Type{Base.IOContext{IO_t} where IO_t<:IO}, Base.IOContext{Base.TTY}, Pair{Symbol, Bool}, Pair{Symbol, Bool}}) precompile(Tuple{typeof(Core.kwcall), NamedTuple{(:context,), Tuple{Base.IOContext{Base.TTY}}}, typeof(Base.sprint), Function, Float64}) precompile(Tuple{typeof(PrettyTables._flush_display!), Base.IOContext{Base.TTY}, PrettyTables.Display, Bool, Bool, Int64}) precompile(Tuple{Type{NamedTuple{(:value, :time, :bytes, :gctime, :gcstats, :lock_conflicts, :compile_time, :recompile_time), T} where T<:Tuple}, Tuple{Nothing, Float64, Int64, Float64, Base.GC_Diff, Int64, Float64, Float64}}) precompile(Tuple{typeof(Base.getproperty), NamedTuple{(:value, :time, :bytes, :gctime, :gcstats, :lock_conflicts, :compile_time, :recompile_time), Tuple{Nothing, Float64, Int64, Float64, Base.GC_Diff, Int64, Float64, Float64}}, Symbol}) ``` Is this expected? Is there anything I can do to improve it? Although I am not 100% sure, I remember testing it in a very earlier version of 1.11 and found not big discrepancy. **EDIT:** I cannot understand why I am seeing recompilation of functions like: ``` precompile(Tuple{typeof(PrettyTables.pretty_table), Any}) ``` since I am using PrecompileTools.jl and it should be already precompiled.

Julia 1.11 is recompiling a lot of functions that it should not. For example, I am using PrecompileTools.jl and a very basic call:

precompile(Tuple{typeof(PrettyTables.pretty_table), Any})

is being recompiled.

tecosaur · October 10, 2024, 10:48am

I’ve hit a bunch of seemingly excessive recompilation in 1.11 too, in one of my packages it takes the load time from ~80ms to ~400ms

Ronis_BR · October 10, 2024, 5:40pm

Good to know that I am not alone Can you please comment on that issue stating the packages with problems so that we can track the issue?

Ronis_BR · October 10, 2024, 9:47pm

I found a “workaround” (that probably is not good to solve the problem). If I add REPL.jl as dependency of PrettyTables.jl and add using REPL, all the overhead is gone. Can you please test if this works for you too?

tecosaur · October 11, 2024, 2:02am

The “package” I’m working on is a group of several interdependent development-version packages after large refactors, which makes it a bit hard to use as a MWE . I might once they’re released if I can’t fix the latency.

tecosaur · October 13, 2024, 2:56pm

Just FWIW, while it takes a bit of effort to reproduce (you’ll need to clone my new monorepo and dev the package + dependencies), here’s the shift I’m seeing and worried by:

~$ julia +1.10 --startup-file=no -q
julia> @time using DataToolkitBase
  0.129546 seconds (206.15 k allocations: 16.930 MiB, 8.77% compilation time)

~$ julia +1.11 --startup-file=no -q
julia> @time using DataToolkitBase
  0.387633 seconds (1.33 M allocations: 68.664 MiB, 2.82% gc time, 63.12% compilation time: 95% of which was recompilation)

~$ julia +nightly --startup-file=no -q
julia> @time using DataToolkitBase
  0.520751 seconds (2.43 M allocations: 127.553 MiB, 5.86% gc time, 73.58% compilation time: 39% of which was recompilation)

Ronis_BR · October 13, 2024, 4:24pm

Hi @tecosaur !

Can you please do one test? Add REPL.jl as dependency to DataToolkitBase and add using REPL at the beginning of DataToolKitBase.jl. If the amount of recompilation reduces a lot, you are facing the same issue that I am. Otherwise, it is something different.

tecosaur · October 13, 2024, 4:31pm

Sure . For this, adding REPL makes no difference. I also see large latency increases with other packages that don’t do anything with display code (e.g. DataDeps, which goes from 0.07s to 0.16s).

I mention this because I think there’s a bit more happening with latency in 1.11/nightly than just what you’ve observed with REPL.

ufechner7 · October 13, 2024, 4:37pm

This are the known issues:

https://github.com/JuliaLang/julia/issues?q=is%3Aopen+label%3A%22regression+1.11%22+label%3Acompiler%3Alatency

This link does not work, but if you copy and past the link into the browser it works.

Ronis_BR · October 13, 2024, 4:38pm

Yes! So my problem seems completely unrelated. Anyway, at least I have a good (but bad) workaround: adding REPL until we can figure out how to fix those issues.

mgkuhn · October 16, 2024, 9:20pm

Seems to be fixed in 1.11.1 (128 ms) compared to 1.10.5 (160 ms).

sijo · October 17, 2024, 8:06am

What seems really slower for me, also in 1.11.1, is the startup time for the interactive session. I don’t know how to measure it properly: evaluating “exit()” seems to force non-interactive mode even when the -i flag is passed to julia so I can’t use the shell time or hyperfine. But my impression is:

julia +1.10 --startup-file=no: loads basically instantly

julia +1.11 --startup-file=no: takes about 1 second!

julia +1.11.1 --startup-file=no: same as 1.11

Does anyone else see the same thing?

nsajko · October 17, 2024, 9:09am

Not here. Try with --trace-compile=stderr.

sijo · October 17, 2024, 9:57am

With 1.11 and 1.11.1 this reports precompile(Tuple{typeof(Base.print), Base.TTY, String}), while 1.10 reports nothing…

nsajko · October 17, 2024, 11:22am

What’s the versioninfo()? Probably you want to report an issue.