Overhead of deprecation warnings increased with 500x (linux) and ~10x (mac) vs 1.11

[KristofferC]

Linux:

# 1.12
$  julia +1.12-nightly --depwarn=yes -q
julia> using SpecialFunctions, BenchmarkTools

julia> @btime lgamma(2.0)
┌ Warning: `lgamma(x::Real)` is deprecated, use `(logabsgamma(x))[1]` instead.
│   caller = var"##core#279"() at execution.jl:598
└ @ Core ~/.julia/packages/BenchmarkTools/1i1mY/src/execution.jl:598
  36.587 ms (95 allocations: 12.99 KiB)

#1.11
$  julia +1.11 --depwarn=yes -q
julia> using SpecialFunctions, BenchmarkTools

julia> @btime lgamma(2.0)
┌ Warning: `lgamma(x::Real)` is deprecated, use `(logabsgamma(x))[1]` instead.
│   caller = var"##core#235"() at execution.jl:598
└ @ Main ~/.julia/packages/BenchmarkTools/1i1mY/src/execution.jl:598
  57.840 μs (111 allocations: 12.23 KiB)
0.0

Mac:

# 1.12
❯ julia +1.12-nightly --depwarn=yes -q
julia> using SpecialFunctions, BenchmarkTools

julia> @btime lgamma(2.0)
┌ Warning: `lgamma(x::Real)` is deprecated, use `(logabsgamma(x))[1]` instead.
│   caller = var"##core#279"() at execution.jl:598
└ @ Core ~/.julia/packages/BenchmarkTools/1i1mY/src/execution.jl:598
  660.375 μs (90 allocations: 11.66 KiB)
0.0

# 1.11
❯ julia +1.11 --depwarn=yes -q
julia> using SpecialFunctions, BenchmarkTools

julia> @btime lgamma(2.0)
┌ Warning: `lgamma(x::Real)` is deprecated, use `(logabsgamma(x))[1]` instead.
│   caller = var"##core#235"() at execution.jl:598
└ @ Main ~/.julia/packages/BenchmarkTools/1i1mY/src/execution.jl:598
  69.916 μs (107 allocations: 12.34 KiB)
0.0

This might be the reason that quite a few packages time out on 1.12 PkgEval?

[giordano]

I had seen issues a few months ago: Team-RADDISH/ParticleDA.jl#286 (comment)

[gbaraldi]

Debugging fun:
Ok, so talking with
@topolarity we figured out that the reason for the slowdown is that in the backtrace that is taken on every single call to depwarn (this is already bad but 🤷 ) we do some debuginfo lookups, and those lookups are incredibly slow on mac, like multi ms long calls. We seem to have a happy path for JIT code and others (and I thought that our sysimages were supposed to hit this). The reason for the slowdown is that there's a new apply_gr call that takes 10ms to suceed

julia> @btime Base.StackTraces.lookup(bt[1])
  4.300 μs (6 allocations: 448 bytes)
3-element Vector{Base.StackTraces.StackFrame}:
 macro expansion at REPL[30]:13 [inlined]
 macro expansion at logging.jl:401 [inlined]
 _depwarn(msg::Any, funcsym::Any, force::Bool) at REPL[30]:9

julia> @btime Base.StackTraces.lookup(bt[2])
  223.721 ns (4 allocations: 208 bytes)
1-element Vector{Base.StackTraces.StackFrame}:
 _depwarn(msg::Any, funcsym::Any, force::Bool)

julia> @btime Base.StackTraces.lookup(bt[3])
  10.624 ms (5 allocations: 224 bytes)
1-element Vector{Base.StackTraces.StackFrame}:
 apply_gr(::GlobalRef, ::Any, ::Vararg{Any}) at reflection.jl:1278

The slowdown on mac is caused by something different (maybe inference issues due to this being defined early) and redefining it brings the performance back to what it was before) .