Recompilation time isn't reported for non-top-level compilations

This example is the classic example for invalidation, yet it fails to report the recompilation time:

julia> f(x::Int) = 1
f (generic function with 1 method)

julia> applyf(container::Vector{Any}) = f(container[1])
applyf (generic function with 1 method)

julia> @time @eval applyf(Any[1])
  0.008801 seconds (1.02 k allocations: 66.281 KiB, 33.30% compilation time)
1

julia> f(::Bool) = 2
f (generic function with 2 methods)

julia> function test()
           container = Any[1]
           @assert applyf(container) == 1
           container[1] = true
           @assert applyf(container) == 2
       end
test (generic function with 1 method)

julia> @time @eval test()
  0.007886 seconds (6.17 k allocations: 425.781 KiB, 97.99% compilation time)

julia> @time @eval applyf(Any[1])
  0.000118 seconds (51 allocations: 2.531 KiB)
1

You can see that the test() function compiles applyf() as a direct dependency, which has been invalidated, yet it doesn't report the recompilation time. We also attempt to compile it again immediately afterwards, but it's already been compiled, and so again we don't get the recompilation report.

So, erroneously, no invalidation is reported!

Compare that to this example, which invokes applyf at the top-level:

julia> f(x::Int) = 1
f (generic function with 2 methods)

julia> applyf(container::Vector{Any}) = f(container[1])
applyf (generic function with 1 method)

julia> @time @eval applyf(Any[1])
  0.005087 seconds (854 allocations: 59.359 KiB, 96.38% compilation time)
1

julia> f(::Bool) = 2
f (generic function with 2 methods)

julia> @time @eval applyf(Any[1])
  0.004712 seconds (849 allocations: 59.016 KiB, 94.77% compilation time: 100% of which was recompilation)
1

Here we get the recompilation report.

Finally, we can see that this is indeed the culprit by forcing a dynamic dispatch inside test() to make the compilation top-level again:

julia> f(x::Int) = 1
f (generic function with 2 methods)

julia> applyf(container::Vector{Any}) = f(container[1])
applyf (generic function with 1 method)

julia> @time @eval applyf(Any[1])
  0.004714 seconds (853 allocations: 59.281 KiB, 96.77% compilation time)
1

julia> f(::Bool) = 2
f (generic function with 2 methods)

julia> function test()
           container = Any[1]
           @assert Base.inferencebarrier(applyf)(container) == 1
           container[1] = true
           @assert Base.inferencebarrier(applyf)(container) == 2
       end
test (generic function with 1 method)

julia> @time @eval test()
  0.009894 seconds (4.71 k allocations: 325.398 KiB, 98.55% compilation time: 36% of which was recompilation)

(This appears to be true on both 1.9 and v"1.11.0-DEV.638".)

I believe that this bug contributed to us heading down the wrong direction when trying to enable package images in our codebase. We were pretty sure that the issue was not invalidation, since we didn't see any reported recompilation, however I believe that most likely invalidation is the explanation, but it was being masked by this bug.

Thanks!

JuliaLang / julia

Recompilation time isn't reported for non-top-level compilations #52603