Regression in latency from loading StyledStrings

[KristofferC]

On e892948 (Version 1.12.0-DEV.2136 (2025-03-26))

julia> using Pkg

julia> Pkg.UPDATED_REGISTRY_THIS_SESSION[] = true
true

julia> ENV["JULIA_PKG_PRECOMPILE_AUTO"] = 0
0

julia> @time @eval Pkg.add("Example")
  Resolving package versions...
No packages added to or removed from `~/.julia/environments/v1.12/Project.toml`
No packages added to or removed from `~/.julia/environments/v1.12/Manifest.toml`
 0.290076 seconds (1.25 M allocations: 77.722 MiB, 5.93% gc time, 89.65% compilation time: 79% of which was recompilation)

On (c175ace) 1.12.0-beta1

julia> using Pkg

julia> Pkg.UPDATED_REGISTRY_THIS_SESSION[] = true
true

julia> ENV["JULIA_PKG_PRECOMPILE_AUTO"] = 0
0

julia> @time @eval Pkg.add("Example")
   Resolving package versions...
No packages added to or removed from `~/.julia/environments/v1.12/Project.toml`
No packages added to or removed from `~/.julia/environments/v1.12/Manifest.toml`
  1.267370 seconds (6.99 M allocations: 377.474 MiB, 7.84% gc time, 98.18% compilation time: 82% of which was recompilation)

[KristofferC]

As far as I can see, bisected to 42e5e47. cc @jakobnissen

If I avoid loading the REPL, the regression seems to go away:

$ julia -e 'using Pkg; Pkg.UPDATED_REGISTRY_THIS_SESSION[] = true; ENV["JULIA_AUTO_PRECOMPILE"] = 0; @time @eval Pkg.add("Example")'
No packages added to or removed from `~/.julia/environments/v1.12/Project.toml`
No packages added to or removed from `~/.julia/environments/v1.12/Manifest.toml`
  0.871763 seconds (1.86 M allocations: 137.632 MiB, 20.29% gc time, 64.57% compilation time: 78% of which was recompilation)

[KristofferC]

It seems it is StyledStrings that causes a lot of this (as it always is). I made a branch so that StyledStrings is not loaded by default by the REPL (and deps) in https://github.com/JuliaLang/julia/tree/kc/no_styled. And we get:

No StyledStrings:

julia> using Pkg

julia> Pkg.UPDATED_REGISTRY_THIS_SESSION[] = true;

julia> ENV["JULIA_AUTO_PRECOMPILE"] = 0;

julia> @time @eval Pkg.add("Example")
   Resolving package versions...
No packages added to or removed from `~/.julia/environments/v1.12/Project.toml`
No packages added to or removed from `~/.julia/environments/v1.12/Manifest.toml`
  0.443519 seconds (2.97 M allocations: 170.194 MiB, 6.73% gc time, 94.00% compilation time: 68% of which was recompilation)

With StyledStrings

julia> using StyledStrings

julia> using Pkg

julia> Pkg.UPDATED_REGISTRY_THIS_SESSION[] = true;

julia> ENV["JULIA_AUTO_PRECOMPILE"] = 0;

julia> @time @eval Pkg.add("Example")
   Resolving package versions...
No packages added to or removed from `~/.julia/environments/v1.12/Project.toml`
No packages added to or removed from `~/.julia/environments/v1.12/Manifest.toml`
  1.769898 seconds (11.39 M allocations: 610.943 MiB, 7.10% gc time, 98.41% compilation time: 76% of which was recompilation)

I'm guessing it is related to

 inserting write(io::IO, c::AnnotatedChar) @ StyledStrings ~/julia1.12/usr/share/julia/stdlib/v1.12/StyledStrings/src/io.jl:273 invalidated:
   backedges:  1: superseding print(io::IO, c::AbstractChar) @ Base char.jl:263 with MethodInstance for print(::IO, ::AnnotatedChar{Char}) (1 children)
               2: superseding print(io::IO, c::AbstractChar) @ Base char.jl:263 with MethodInstance for print(::AnnotatedIOBuffer, ::AnnotatedChar{Char}) (1 children)
               3: superseding print(io::IO, c::AbstractChar) @ Base char.jl:263 with MethodInstance for print(::IOStream, ::AbstractChar) (1 children)
               4: superseding print(io::IO, s::AbstractString) @ Base strings/io.jl:199 with MethodInstance for print(::IOContext{REPL.LimitIO{Base.TTY}}, ::AbstractString) (2 children)
               5: superseding print(io::IO, s::AbstractString) @ Base strings/io.jl:199 with MethodInstance for print(::IOContext, ::AbstractString) (4 children)
               6: superseding print(io::IO, c::AbstractChar) @ Base char.jl:263 with MethodInstance for print(::IOContext{REPL.LimitIO{Base.TTY}}, ::AnnotatedChar{Char}) (7 children)
               7: superseding write(io::IO, x) @ Base io.jl:792 with MethodInstance for write(::IOBuffer, ::AbstractChar) (7 children)
               8: superseding print(io::IO, s::AbstractString) @ Base strings/io.jl:199 with MethodInstance for print(::IOContext{IOBuffer}, ::AbstractString) (8 children)
               9: superseding print(io::IO, c::AbstractChar) @ Base char.jl:263 with MethodInstance for print(::Base.DevNull, ::AnnotatedChar{Char}) (13 children)
              10: superseding print(io::IO, s::AbstractString) @ Base strings/io.jl:199 with MethodInstance for print(::IOBuffer, ::AbstractString) (14 children)
              11: superseding print(io::IO, c::AbstractChar) @ Base char.jl:263 with MethodInstance for print(::IOContext{AnnotatedIOBuffer}, ::AnnotatedChar{Char}) (45 children)
              12: superseding print(io::IO, c::AbstractChar) @ Base char.jl:263 with MethodInstance for print(::IOContext{IOBuffer}, ::AbstractChar) (57 children)
              13: superseding print(io::IO, c::AbstractChar) @ Base char.jl:263 with MethodInstance for print(::IOContext, ::AnnotatedChar{Char}) (71 children)
              14: superseding print(io::IO, c::AbstractChar) @ Base char.jl:263 with MethodInstance for print(::IOBuffer, ::AnnotatedChar{Char}) (93 children)
              15: superseding print(io::IO, c::AbstractChar) @ Base char.jl:263 with MethodInstance for print(::IOBuffer, ::AbstractChar) (204 children)
              16: superseding print(io::IO, c::AbstractChar) @ Base char.jl:263 with MethodInstance for print(::IOContext{IO}, ::AnnotatedChar{Char}) (209 children)
              17: superseding print(io::IO, c::AbstractChar) @ Base char.jl:263 with MethodInstance for print(::IOContext{IOStream}, ::AnnotatedChar{Char}) (261 children)
              18: superseding print(io::IO, c::AbstractChar) @ Base char.jl:263 with MethodInstance for print(::IOContext{IOBuffer}, ::AnnotatedChar{Char}) (841 children)
   19 mt_cache

which was brought up a year ago in JuliaLang/StyledStrings.jl#61.

cc @tecosaur, @topolarity

[jakobnissen]

Thanks for digging into this. If I understand correctly, this is not due to inference problems in the iobuffer code (which I believe should all be well-inferred), but instead inference issues in StyledStrings, or in Base.

[KristofferC]

I don't know yet why that specific commit caused the issue. But reverting that commit on my branch that doesn't load StyledStrings doesn't change any timings so it doesn't seem like there is anything bad with that code on its own.

[tecosaur]

Wow, that's quite a large regression. Is there any way to better identify what is behind this change? I'm very sympathetic to the headaches with StyledStrings involved here, I just have a hard time identifying actionable changes to improve the situation. The only change involving StyledStrings / the annotated code that's occurred recently is #57912, but it's hard for me to see how that could be implicated here. The core issue seems to be the print/write methods you identify here, and the obvious solution in my mind is for them not to be in StyledStrings, but that's not my decision.

This leaves us with (1) abandoning the idea of a stdlib to manage rich content better across the stdlib, as per #57998 (2) adjusting the base/stdlib split (3) doing some slightly tricky work to make it work despite the split (which is what I've been speaking with Cody about, and what I sense you've run out of patience waiting for Kristoffer).

[topolarity]

I just have a hard time identifying actionable changes to improve the situation.

The actionable change is to fix the StyledStrings type-piracy.

The core issue seems to be the print/write methods you identify here, and the obvious solution in my mind is for them not to be in StyledStrings, but that's not my decision.

Yes, we'll need to fix these soon - it should have been done earlier in the 1.12 release cycle, but let's get it done now and relieve some pain for folks

[KristofferC]

I just have a hard time identifying actionable changes to improve the situation

It's ok, #57998 is very actionable, and I can take that on.

[KristofferC]

Fixed with inference barrier