search

JuliaLang / julia

The Julia Programming Language
https://julialang.org/
MIT License
45.85k stars 5.49k forks source link

Huge precompilation overhead in Julia 1.11 #56080

Open ronisbr opened 1 month ago

ronisbr commented 1 month ago

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.

giordano commented 1 month ago

Assuming this is reproducible on master, --trace-compile-timing is useful to quickly identify major compilation offenders.

KristofferC commented 1 month ago

I cannot understand why I am seeing recompilation of functions like:

Seems to have gotten invalidated (yellow):

Image

Assuming this is reproducible on master

Master seems a bit better:

0.097520 seconds (283.15 k allocations: 15.748 MiB, 99.31% compilation time: 58% of which was recompilation)

ronisbr commented 1 month ago

I do not know if there is a relationship, but I am seeing less specializations of external methods in cache using Julia 1.11:

Julia 1.11

julia> info_cachefile("PrettyTables")
Contents of /Users/ronan.arraes/.julia/compiled/v1.11/PrettyTables/kRdcL_Ky7mn.dylib:
  modules: Any[PrettyTables]
  145 external methods
  3962 new specializations of external methods (Base 88.3%, Base.Broadcast 6.0%, Base.Sort 1.7%, ...)
  436 external methods with new roots
  11111 external targets
  8519 edges
  file size:   13715664 (13.080 MiB)
  Segment sizes (bytes):
    system:      5035516 ( 41.39%)
    isbits:      6515800 ( 53.55%)
    symbols:       29689 (  0.24%)
    tags:          83253 (  0.68%)
    relocations:  475609 (  3.91%)
    gvars:         10088 (  0.08%)
    fptrs:         17400 (  0.14%)
  Image targets:
    apple-m2; flags=0; features_en=(aes, sha2, crc, lse, fullfp16, rdm, jsconv, complxnum, rcpc, ccpp, sha3, dotprod, fp16fml, dit, rcpc-immo, flagm, sb, ccdp, altnzcv, fptoint, i8mm, bf16, v8_1a, v8_2a, v8_3a, v8_4a, v8_5a)

Julia 1.10

julia> info_cachefile("PrettyTables")
Contents of /Users/ronan.arraes/.julia/compiled/v1.10/PrettyTables/kRdcL_YgcFH.dylib:
  modules: Any[PrettyTables]
  145 external methods
  8279 new specializations of external methods (Base 77.5%, PrettyTables 11.3%, Base.Broadcast 5.5%, ...)
  425 external methods with new roots
  10904 external targets
  8294 edges
  file size:   10029936 (9.565 MiB)
  Segment sizes (bytes):
    system:      3889388 ( 44.37%)
    isbits:      4355632 ( 49.69%)
    symbols:       29427 (  0.34%)
    tags:          54666 (  0.62%)
    relocations:  409523 (  4.67%)
    gvars:          9632 (  0.11%)
    fptrs:         16720 (  0.19%)
  Image targets:
    apple-m1; flags=0; features_en=(aes, sha2, crc, lse, fullfp16, rdm, jsconv, complxnum, rcpc, ccpp, sha3, dotprod, fp16fml, dit, rcpc-immo, flagm, sb, ccdp, altnzcv, fptoint, v8_1a, v8_2a, v8_3a, v8_4a, v8_5a)

@KristofferC I will check why the invalidations are happening. Is it expected due to some internal change in Julia 1.11?

KristofferC commented 1 month ago

Is it expected due to some internal change in Julia 1.11?

Potentially due to https://github.com/JuliaLang/StyledStrings.jl/issues/61 but I haven't verified.

ronisbr commented 1 month ago

There are a lot of new invalidations:

Julia 1.11

julia> trees = invalidation_trees(invalidations)
9-element Vector{SnoopCompile.MethodInvalidations}:
 inserting match(re::Regex, s::LaTeXStrings.LaTeXString, idx::Integer, add_opts::UInt32) @ LaTeXStrings ~/.julia/packages/LaTeXStrings/ZtSdh/src/LaTeXStrings.jl:132 invalidated:
   mt_backedges: 1: signature Tuple{typeof(match), Regex, AbstractString, Any, UInt32} triggered MethodInstance for iterate(::Base.RegexMatchIterator, ::Tuple{Int64, Bool}) (0 children)
                 2: signature Tuple{typeof(match), Regex, AbstractString, Any, UInt32} triggered MethodInstance for iterate(::Base.RegexMatchIterator, ::Tuple{Any, Bool}) (0 children)
                 3: signature Tuple{typeof(match), Regex, AbstractString, Any, UInt32} triggered MethodInstance for iterate(::Base.RegexMatchIterator, ::Tuple{Any, Any}) (0 children)
                 4: signature Tuple{typeof(match), Regex, AbstractString, Int64, UInt32} triggered MethodInstance for match(::Regex, ::Base.AnnotatedString, ::Int64, ::UInt32) (1 children)
                 5: signature Tuple{typeof(match), Regex, AbstractString, Integer, UInt32} triggered MethodInstance for match(::Regex, ::Base.AnnotatedString, ::Integer, ::UInt32) (4 children)

 inserting convert(::Type{Vector{String}}, sa::LibGit2.StrArrayStruct) @ LibGit2 ~/.julia/juliaup/julia-1.11.0+0.aarch64.apple.darwin14/share/julia/stdlib/v1.11/LibGit2/src/strarray.jl:13 invalidated:
   mt_backedges: 1: signature Tuple{typeof(convert), Type{Vector{String}}, Any} triggered MethodInstance for PrettyTables._text_fill_string_matrix!(::IOContext, ::Matrix{Vector{String}}, ::PrettyTables.ProcessedTable, ::Vector{Int64}, ::PrettyTables.Display, ::Ref{Any}, ::Vector{Int64}, ::Bool, ::Bool, ::Vector{Int64}, ::Bool, ::Bool, ::Bool, ::Bool, ::Vector{Int64}, ::Vector{Int64}, ::Val{:print}, ::Symbol) (9 children)
                 2: signature Tuple{typeof(convert), Type{Vector{String}}, Any} triggered MethodInstance for PrettyTables._preprocess_row_tables_jl(::Any, ::Nothing) (0 children)
                 3: signature Tuple{typeof(convert), Type{Vector{String}}, Any} triggered MethodInstance for PrettyTables._preprocess_column_tables_jl(::Any, ::Nothing) (0 children)
                 4: signature Tuple{typeof(convert), Type{Vector{String}}, Any} triggered MethodInstance for PrettyTables._text_fill_string_matrix!(::IOContext, ::Matrix{Vector{String}}, ::PrettyTables.ProcessedTable, ::Vector{Int64}, ::PrettyTables.Display, ::Ref{Any}, ::Vector{Int64}, ::Bool, ::Bool, ::Vector{Int64}, ::Bool, ::Bool, ::Bool, ::Bool, ::Vector{Int64}, ::Vector{Int64}, ::Val{:show}, ::Symbol) (0 children)

 inserting firstindex(s::LaTeXStrings.LaTeXString) @ LaTeXStrings ~/.julia/packages/LaTeXStrings/ZtSdh/src/LaTeXStrings.jl:108 invalidated:
   backedges: 1: superseding firstindex(s::AbstractString) @ Base strings/basic.jl:178 with MethodInstance for firstindex(::AbstractString) (17 children)

 inserting print(io::IO, c::Base.AnnotatedChar) @ StyledStrings ~/.julia/juliaup/julia-1.11.0+0.aarch64.apple.darwin14/share/julia/stdlib/v1.11/StyledStrings/src/io.jl:281 invalidated:
   backedges: 1: superseding print(io::IO, c::AbstractChar) @ Base char.jl:253 with MethodInstance for print(::IOBuffer, ::AbstractChar) (13 children)
              2: superseding print(io::IO, c::AbstractChar) @ Base char.jl:253 with MethodInstance for print(::IOContext{IOBuffer}, ::AbstractChar) (5 children)
              3: superseding print(io::IO, c::AbstractChar) @ Base char.jl:253 with MethodInstance for print(::IOContext{IOBuffer}, ::AbstractChar) (1 children)
              4: superseding print(io::IO, c::AbstractChar) @ Base char.jl:253 with MethodInstance for print(::IOBuffer, ::AbstractChar) (1 children)
              5: superseding print(io::IO, c::AbstractChar) @ Base char.jl:253 with MethodInstance for print(::IOContext{IOBuffer}, ::AbstractChar) (1 children)
              6: superseding print(io::IO, c::AbstractChar) @ Base char.jl:253 with MethodInstance for print(::IOBuffer, ::AbstractChar) (3 children)
              7: superseding print(io::IO, c::AbstractChar) @ Base char.jl:253 with MethodInstance for print(::IOBuffer, ::AbstractChar) (7 children)

 inserting lastindex(s::LaTeXStrings.LaTeXString) @ LaTeXStrings ~/.julia/packages/LaTeXStrings/ZtSdh/src/LaTeXStrings.jl:109 invalidated:
   backedges: 1: superseding lastindex(s::AbstractString) @ Base strings/basic.jl:179 with MethodInstance for lastindex(::AbstractString) (44 children)

 inserting sizeof(s::LaTeXStrings.LaTeXString) @ LaTeXStrings ~/.julia/packages/LaTeXStrings/ZtSdh/src/LaTeXStrings.jl:127 invalidated:
   backedges: 1: superseding sizeof(s::AbstractString) @ Base strings/basic.jl:177 with MethodInstance for sizeof(::AbstractString) (75 children)

 inserting displaysize(t::REPL.Terminals.UnixTerminal) @ REPL.Terminals ~/.julia/juliaup/julia-1.11.0+0.aarch64.apple.darwin14/share/julia/stdlib/v1.11/REPL/src/Terminals.jl:153 invalidated:
   backedges: 1: superseding displaysize(io::IO) @ Base stream.jl:568 with MethodInstance for displaysize(::IO) (77 children)

 inserting displaysize(::REPL.Terminals.TextTerminal) @ REPL.Terminals ~/.julia/juliaup/julia-1.11.0+0.aarch64.apple.darwin14/share/julia/stdlib/v1.11/REPL/src/Terminals.jl:48 invalidated:
   backedges: 1: superseding displaysize(io::IO) @ Base stream.jl:568 with MethodInstance for displaysize(::IO) (77 children)

 inserting convert(::Type{String}, d::StringManipulation.Decoration) @ StringManipulation ~/.julia/packages/StringManipulation/bMZ2A/src/decorations.jl:365 invalidated:
   mt_backedges:  1: signature Tuple{typeof(convert), Type{String}, Any} triggered MethodInstance for setindex!(::Dict{String, Base.UUID}, ::Any, ::Any) (0 children)
                  2: signature Tuple{typeof(convert), Type{String}, Any} triggered MethodInstance for setindex!(::Dict{String, Union{Bool, String}}, ::Any, ::Any) (0 children)
                  3: signature Tuple{typeof(convert), Type{String}, Any} triggered MethodInstance for setindex!(::Dict{String, Union{Nothing, String}}, ::Any, ::Any) (0 children)
                  4: signature Tuple{typeof(convert), Type{String}, Any} triggered MethodInstance for setindex!(::Dict{String, Nothing}, ::Nothing, ::Any) (0 children)
                  5: signature Tuple{typeof(convert), Type{String}, Any} triggered MethodInstance for setindex!(::Dict{String, Union{Nothing, Tuple{Base.PkgId, String}}}, ::Any, ::Any) (0 children)
                  6: signature Tuple{typeof(convert), Type{String}, Any} triggered MethodInstance for push!(::Vector{String}, ::Any) (0 children)
                  7: signature Tuple{typeof(convert), Type{String}, Any} triggered MethodInstance for setindex!(::Dict{String, Pkg.Types.Compat}, ::Any, ::Any) (0 children)
                  8: signature Tuple{typeof(convert), Type{String}, Any} triggered MethodInstance for setindex!(::Vector{String}, ::Any, ::Int64) (7 children)
                  9: signature Tuple{typeof(convert), Type{String}, Any} triggered MethodInstance for Base.RegexMatchIterator(::Regex, ::AbstractString, ::Bool) (11 children)
                 10: signature Tuple{typeof(convert), Type{String}, Any} triggered MethodInstance for convert(::Type{Union{Nothing, String}}, ::Any) (19 children)
                 11: signature Tuple{typeof(convert), Type{String}, Any} triggered MethodInstance for Base.Precompilation.ExplicitEnv(::String) (84 children)

Julia 1.10

julia> trees = invalidation_trees(invalidations)
5-element Vector{SnoopCompile.MethodInvalidations}:
 inserting firstindex(s::LaTeXStrings.LaTeXString) @ LaTeXStrings ~/.julia/packages/LaTeXStrings/ZtSdh/src/LaTeXStrings.jl:108 invalidated:
   backedges: 1: superseding firstindex(s::AbstractString) @ Base strings/basic.jl:180 with MethodInstance for firstindex(::AbstractString) (1 children)

 inserting sizeof(s::LaTeXStrings.LaTeXString) @ LaTeXStrings ~/.julia/packages/LaTeXStrings/ZtSdh/src/LaTeXStrings.jl:127 invalidated:
   backedges: 1: superseding sizeof(s::AbstractString) @ Base strings/basic.jl:179 with MethodInstance for sizeof(::AbstractString) (4 children)

 inserting eachmatch(re::Regex, s::LaTeXStrings.LaTeXString; overlap) @ LaTeXStrings ~/.julia/packages/LaTeXStrings/ZtSdh/src/LaTeXStrings.jl:134 invalidated:
   backedges: 1: superseding eachmatch(re::Regex, str::AbstractString; overlap) @ Base regex.jl:743 with MethodInstance for eachmatch(::Regex, ::AbstractString) (9 children)

 inserting lastindex(s::LaTeXStrings.LaTeXString) @ LaTeXStrings ~/.julia/packages/LaTeXStrings/ZtSdh/src/LaTeXStrings.jl:109 invalidated:
   backedges: 1: superseding lastindex(s::AbstractString) @ Base strings/basic.jl:181 with MethodInstance for lastindex(::AbstractString) (11 children)

 inserting convert(::Type{String}, d::StringManipulation.Decoration) @ StringManipulation ~/.julia/packages/StringManipulation/bMZ2A/src/decorations.jl:365 invalidated:
   mt_backedges:  1: signature Tuple{typeof(convert), Type{String}, Any} triggered MethodInstance for setindex!(::Dict{String, Base.UUID}, ::Any, ::Any) (0 children)
                  2: signature Tuple{typeof(convert), Type{String}, Any} triggered MethodInstance for setindex!(::Dict{String, Union{Bool, String}}, ::Any, ::Any) (0 children)
                  3: signature Tuple{typeof(convert), Type{String}, Any} triggered MethodInstance for setindex!(::Dict{String, Union{Nothing, String}}, ::Any, ::Any) (0 children)
                  4: signature Tuple{typeof(convert), Type{String}, Any} triggered MethodInstance for setindex!(::Dict{String, Nothing}, ::Nothing, ::Any) (0 children)
                  5: signature Tuple{typeof(convert), Type{String}, Any} triggered MethodInstance for setindex!(::Dict{String, Union{Nothing, Tuple{Base.PkgId, Union{Nothing, String}}}}, ::Any, ::Any) (0 children)
                  6: signature Tuple{typeof(convert), Type{String}, Any} triggered MethodInstance for setindex!(::Dict{String, Union{Base.SHA1, String}}, ::Any, ::Any) (0 children)
                  7: signature Tuple{typeof(convert), Type{String}, Any} triggered MethodInstance for setindex!(::Dict{String, Function}, ::Any, ::Any) (0 children)
                  8: signature Tuple{typeof(convert), Type{String}, Any} triggered MethodInstance for setindex!(::Vector{String}, ::Any, ::Int64) (0 children)
                  9: signature Tuple{typeof(convert), Type{String}, Any} triggered MethodInstance for setindex!(::Dict{String, Any}, ::Any, ::Any) (0 children)
                 10: signature Tuple{typeof(convert), Type{String}, Any} triggered MethodInstance for setindex!(::Dict{String, Union{String, Vector{String}}}, ::Any, ::Any) (0 children)
                 11: signature Tuple{typeof(convert), Type{String}, Any} triggered MethodInstance for setindex!(::Dict{String, Pkg.Types.Compat}, ::Any, ::Any) (0 children)
                 12: signature Tuple{typeof(convert), Type{String}, Any} triggered MethodInstance for setindex!(::Dict{String, Vector{String}}, ::Any, ::Any) (0 children)
                 13: signature Tuple{typeof(convert), Type{String}, Any} triggered MethodInstance for setindex!(::Dict{String, Base.UUID}, ::Base.UUID, ::Any) (0 children)
                 14: signature Tuple{typeof(convert), Type{String}, Any} triggered MethodInstance for setindex!(::Dict{String, Vector{String}}, ::Vector{String}, ::Any) (0 children)
                 15: signature Tuple{typeof(convert), Type{String}, Any} triggered MethodInstance for push!(::Vector{String}, ::Any) (0 children)
                 16: signature Tuple{typeof(convert), Type{String}, Any} triggered MethodInstance for setindex!(::Dict{Base.PkgId, String}, ::Any, ::Base.PkgId) (0 children)
                 17: signature Tuple{typeof(convert), Type{String}, Any} triggered MethodInstance for setindex!(::IdDict{Any, String}, ::Any, ::Any) (1 children)
                 18: signature Tuple{typeof(convert), Type{String}, Any} triggered MethodInstance for convert(::Type{Union{Nothing, String}}, ::Any) (2 children)
                 19: signature Tuple{typeof(convert), Union{Type{Base.UUID}, Type{VersionNumber}, Type{String}}, Any} triggered MethodInstance for (::Base.var"#cvt1#1"{Tuple{Base.UUID, String, String, VersionNumber}, Tuple{Base.UUID, Nothing, String, VersionNumber}})(::Int64) (3 children)
                 20: signature Tuple{typeof(convert), Union{Type{Base.UUID}, Type{VersionNumber}, Type{String}}, Any} triggered MethodInstance for (::Base.var"#cvt1#1"{Tuple{Base.UUID, String, String, VersionNumber}, Tuple{Base.UUID, Nothing, String, Pkg.Versions.VersionSpec}})(::Int64) (3 children)
                 21: signature Tuple{typeof(convert), Union{Type{Base.UUID}, Type{VersionNumber}, Type{String}}, Any} triggered MethodInstance for (::Base.var"#cvt1#1"{Tuple{Base.UUID, String, String, VersionNumber}, Tuple{Base.UUID, Nothing, String, Pkg.Types.UpgradeLevel}})(::Int64) (128 children)
KristofferC commented 1 month ago

@ronisbr, is it intended that this is not concretely typed?

https://github.com/ronisbr/PrettyTables.jl/blob/99595fcad38a5181e5888e32267cd045fa5b8669/src/types.jl#L78

There are quite a bit of type instabilities etc in PrettyTables, fixing those should make precompilation better. Just as an example in print_table:

1000 1 ─ %1  = PrettyTables.get(io, :__PRETTY_TABLES_DATA__, PrettyTables.nothing)::Any          │   
1002 │   %2  = (%1 === PrettyTables.nothing)::Bool                                               │   
     │   %3  = Core.Intrinsics.not_int(%2)::Bool                                                 │   
     └──       goto #8 if not %3                                                                 │   
1003 2 ─ %5  = PrettyTables.IOContext(io)::IOContext                                             │   
1008 │   %6  = Base.iterate(%1)::Any                                                             │   
     │   %7  = (%6 === nothing)::Bool                                                            │   
     │   %8  = Base.not_int(%7)::Bool                                                            │   
     └──       goto #7 if not %8                                                                 │   
     3 ┄ %10 = φ (#2 => %6, #6 => %17)::Any                                                      │   
     │   %11 = Core.getfield(%10, 1)::Any                                                        │   
     │   %12 = Core.getfield(%10, 2)::Any                                                        │   
1009 │   %13 = (%11 === data)::Bool                                                              │   
     └──       goto #5 if not %13                                                                │   
1012 4 ─       invoke PrettyTables._pt_text_circular_reference(%5::IOContext)                    │   
1019 └──       return PrettyTables.nothing                                                       │   
1021 5 ─ %17 = Base.iterate(%1, %12)::Any
KristofferC commented 1 month ago

Note that compilation time should be measured with @time @eval.

ronisbr commented 1 month ago

Hi @KristofferC !

Yes, it is. When I tested those algorithms a long time ago, it was better to have those type instabilities and @nospecialize because together with PrecompileTools.jl / SnoopCompile.jl I could drastically reduce the time to print the first table. The major problem was that if I remove the type instabilities, I start to see many slowdown at each input type and each output context (stdout, a file, etc) due to the compilation.

However, since it was a long time ago, I will revisit given your suggestion. Thanks!

KristofferC commented 1 month ago

I was just checking. In Pkg we do a similar thing to avoid specializing on all IO types.

ronisbr commented 1 month ago

I found something very interesting! If I add REPL.jl as a dependency of PrettyTables.jl and add using REPL without changing anything else, the overhead disappear completely:

julia> using PrettyTables

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

julia> @time @eval pretty_table(A)
┌────────┬────────┐
│ Col. 1 │ Col. 2 │
├────────┼────────┤
│    1.0 │    1.0 │
│    1.0 │    1.0 │
└────────┴────────┘
  0.070758 seconds (40.41 k allocations: 2.201 MiB, 50.82% gc time, 99.17% compilation time)
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{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(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})

I have absolutely no idea why and I am also not sure if I can safely use this as a workaround.

ronisbr commented 1 month ago

Update: Adding only StyledStrings.jl as dependency and using StyledStrings also helps to decrease the precompilation overhead (but not as much as doing the same with REPL.jl):

julia> using PrettyTables

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

julia> @time @eval pretty_table(A)
┌────────┬────────┐
│ Col. 1 │ Col. 2 │
├────────┼────────┤
│    1.0 │    1.0 │
│    1.0 │    1.0 │
└────────┴────────┘
  0.095050 seconds (260.66 k allocations: 14.747 MiB, 39.18% gc time, 99.41% compilation time: 70% of which was recompilation)
KristofferC commented 1 month ago

I have absolutely no idea why and I am also not sure if I can safely use this as a workaround.

Probably because your methods are then defined after these https://github.com/JuliaLang/StyledStrings.jl/issues/61 so they don't get invalidated. In 1.10 this was not an issue because REPL and everything else was in the sysimage so they were effectively a dependency to all other packages.

ronisbr commented 1 month ago

I have absolutely no idea why and I am also not sure if I can safely use this as a workaround.

Probably because your methods are then defined after these JuliaLang/StyledStrings.jl#61 so they don't get invalidated. In 1.10 this was not an issue because REPL and everything else was in the sysimage so they were effectively a dependency to all other packages.

Makes sense! So, I think I can safely add REPL as dependency until it gets fixed right?

KristofferC commented 1 month ago

Your package will be slower to load though because it has to load REPL unconditionally.

ronisbr commented 1 month ago

@KristofferC I am getting some very strange results:

Before Adding REPL.jl as Dependency

julia> @time_imports using PrettyTables
      0.6 ms  Reexport
      0.3 ms  DataValueInterfaces
      0.7 ms  DataAPI
      0.4 ms  IteratorInterfaceExtensions
      0.3 ms  TableTraits
      2.3 ms  OrderedCollections
      5.2 ms  Tables
      0.5 ms  Printf
     14.7 ms  Dates
      0.4 ms  TOML
      5.5 ms  Preferences
      0.3 ms  PrecompileTools
      3.6 ms  StringManipulation
      5.8 ms  Crayons
      0.5 ms  LaTeXStrings
     39.9 ms  PrettyTables

After Adding REPL.jl as Dependency

julia> @time_imports using PrettyTables
      0.7 ms  Reexport
      0.4 ms  DataValueInterfaces
      0.7 ms  DataAPI
      0.4 ms  IteratorInterfaceExtensions
      0.4 ms  TableTraits
      2.1 ms  OrderedCollections
      4.7 ms  Tables
      0.5 ms  Printf
     14.3 ms  Dates
      0.4 ms  TOML
      5.2 ms  Preferences
      0.3 ms  PrecompileTools
      3.4 ms  StringManipulation
      5.7 ms  Crayons
      0.4 ms  LaTeXStrings
     39.6 ms  PrettyTables

Do you think it might be something related to my setup? I tested in 3 different computers with the same result.

KristofferC commented 1 month ago

You are in the REPL so the REPL is already loaded. Run it from a script for example.

ronisbr commented 1 month ago

Ah! Sorry :) My bad, I thought REPL.jl now contains only some extra functionalities and not the REPL itself.

topolarity commented 1 month ago

While investigating this morning, I noticed that the "recompilation" metric is lying to us: https://github.com/JuliaLang/julia/issues/56155

Many of the functions "re-compiled" here are actually things that were inferred when we built the sysimage. They just never got any code. For example, Base.Filesystems.contractuser(::String) is one of the things that is compiled on 1.10, and on 1.11+ it is inferred only. The difference is because contractuser(::String) became eligible for inlining..

On 1.10, inlining_cost for contractuser(::String) is UINT16_MAX which causes it to be triggered for code generation during sysimage generation. On 1.11+ the cost is 81:

using Base.Filesystem: contractuser
mi = methods(contractuser, (String,))[1].specializations::Base.MethodInstance
println(ccall(:jl_ir_inlining_cost, UInt16, (Any,), mi.cache.inferred))
$ julia +1.11 inlining_cost.jl
81
$ julia +1.10 inlining_cost.jl
65535

If the compiler sees that a method is inline-able and has not been codegen'd yet, it will decide that it is not worth compiling, under the assumption that it's most likely to end up inlined everywhere (and so generating a separate function for it would be useless).

Maybe we need to revisit that compilation decision?