Performance regression (speed, alloc) in `string` and `Symbol` in Julia 1.12

[fingolfin]

With Julia 1.11.5 on a MacBook Pro M1:

julia> @b string(1)
15.014 ns (2 allocs: 56 bytes)

julia> @b Symbol("foo", 5)
127.793 ns (5 allocs: 176 bytes)

With Julia 1.12.0-beta3 on the same machine:

julia> @b string(1)
17.764 ns (2 allocs: 64 bytes)

julia> @b Symbol("foo", 5)
139.245 ns (7 allocs: 256 bytes)

[Seelengrab]

Does this show up outside of microbenchmarks as well? 2/10ns regressions can be an artifact from a whole bunch of things that changed from 1.11 to 1.12.

[fingolfin]

Yes it shows up for me, which is how I found it. Using the Nemo package:

Julia 1.11.5:

julia> using Nemo

Welcome to Nemo version 0.50.0-dev

Nemo comes with absolutely no warranty whatsoever

julia> @b polynomial_ring(QQ, :x => 1:100; cached=false)
35.250 μs (914 allocs: 47.781 KiB)

Julia 1.12.0-beta3:

julia> using Nemo

Welcome to Nemo version 0.50.0-dev

Nemo comes with absolutely no warranty whatsoever

julia> @b polynomial_ring(QQ, :x => 1:100; cached=false)
41.750 μs (1515 allocs: 76.719 KiB)

I am not claiming all of this slowdown is due to this issue, but part of the allocations definitely is.

(In general lots of things are slower in 1.12, and even 1.11 is a regression over 1.10 for me in almost every regard :-/).

Here is another micro-benchmark that is slightly less micro: Julia 1.11:

julia> f(x,n) = [vcat(x,string(i)) for i in 1:n];

julia> g(x,n) = [Symbol(x,i) for i in 1:n];

julia> @b f("foobar", 500)
15.250 μs (2003 allocs: 70.469 KiB)

julia> @b g("foobar", 500)
117.083 μs (2503 allocs: 93.836 KiB)

versus Julia 1.12:

julia> f(x,n) = [vcat(x,string(i)) for i in 1:n];

julia> g(x,n) = [Symbol(x,i) for i in 1:n];

julia> @b f("foobar", 500)
13.750 μs (2003 allocs: 74.375 KiB)

julia> @b g("foobar", 500)
127.292 μs (3503 allocs: 129.062 KiB)

[adienes]

I bisected the increase in allocations of @b Symbol("foo", 5) to 44bef0df7a115334c10abac88aeba333b12cce2d (https://github.com/JuliaLang/julia/pull/55754)

notably, I'm emphasizing allocations because the time does not seem stable over different sessions on any of 1.11, 1.12, nightly, and seems fairly comparable over all 3 versions (maybe 1.11 is less variable, but the minimums I see are comparable at least)

➜  julia git:(44bef0df7a) ✗ julia +nightly -q
julia> using Chairmarks

julia> @b Symbol("foo", 5)
149.890 ns (7 allocs: 256 bytes)

julia> @b Symbol("foo", 5)
148.722 ns (7 allocs: 256 bytes)

julia> @b Symbol("foo", 5)
148.566 ns (7 allocs: 256 bytes)

julia>^D


➜  julia git:(44bef0df7a) ✗ julia +nightly -q
julia> using Chairmarks

julia> @b Symbol("foo", 5)
134.831 ns (7 allocs: 256 bytes)

julia> @b Symbol("foo", 5)
134.832 ns (7 allocs: 256 bytes)

curiously, it looks like that PR was reverted in https://github.com/JuliaLang/julia/pull/55894, so given that I still see 256 bytes allocated on nightly, I wonder if this regressed a separate time as well

[dpanigo]

I would like to add that I also experience a runtime regression starting from Julia 1.9.4 — which seems to get worse in Julia 1.10 LTS (partially reverted in 1.11 release), and worsens again in the latest beta (1.12).

To test this, I ran the following PowerShell script to compare execution times across Julia versions:

# Ruta al script de Julia
$JULIA_SCRIPT = 'C:\gsreg.jl'

# Lista de versiones
$versions = @(
    '+1.8.5',
    '+1.9.4',
    '+lts',
    '+release',
    '+beta'
)

# Archivo de resultados
$resultsFile = 'timing_results.txt'
"Julia version timings for $JULIA_SCRIPT" | Out-File -FilePath $resultsFile
"---------------------------------------" | Out-File -FilePath $resultsFile -Append

# Loop sobre versiones
foreach ($version in $versions) {
    Write-Host "Running Julia $version..."
    $time = Measure-Command {
        & julia $version -p auto $JULIA_SCRIPT
    }
    $realTime = '{0:mm\:ss\.fff}' -f $time
    "Julia $version - Time: $realTime" | Out-File -FilePath $resultsFile -Append
}

"---------------------------------------" | Out-File -FilePath $resultsFile -Append
Write-Host "Timing results saved to $resultsFile"

This script calls the following Julia code:

# This is the gsreg.jl file
using GlobalSearchRegression, DataFrames, Distributions
# Insert here your working directory path
data = DataFrame(rand(100, 21), :auto)
headers = [ :y ; [ Symbol("x$i") for i = 1:size(data,2) - 1 ] ]
rename!(data, headers)
gsreg("y x*", data; parallel=16)
exit()

I obtained these results:

Julia version timings for C:\gsreg.jl
---------------------------------------
Julia +1.8.5 - Time:      01:04.563
Julia +1.9.4 - Time:      01:03.225
Julia +lts - Time:        01:23.469
Julia +release - Time:    01:12.619
Julia +beta - Time:       01:26.860
---------------------------------------

Observations:

In my case, the slowdown seems to start with 1.10 LTS, is partially improved in 1.11, but worsens again in 1.12 beta 4. The observed regressions are not massive, but clearly measurable and consistent across multiple runs. The task performs one million OLS estimations with artificial data, so it might be related to the underlying discussion here. I hope this helps contribute to the diagnosis.

[gbaraldi]

@dpanigo please don't spam this on every issue. Could you open a separate issue so this gets tracked properly And it would be nice ifthis could be minimized to what specific piece of code that's slower (this can happen on the dedicated issue)

[vtjnash]

From profiling, it looks like (similar to #55894 that was reverted), that 97ecdb8595c4a1fbe68ba6f39b3244e8cdabc2c6 also disabled the same heuristic which was preventing those extra allocations and performance loss.

Removing this line again should remove the extra allocations (I didn't measure the effect on performance):

setfield!(typeof(print_to_string).name, :max_args, Int32(10), :monotonic)