@time always shows reports compilation times while SnoopCompile does not

[bvdmitri]

I observe a very weird behaviour where the @time macro constantly reports "compilation time", even though SnoopCompile does not report any inference or invalidation problems.

MWE

] activate --temp
] add RxInfer
] add SnoopCompile

Status `/private/var/folders/x3/rqw10ky529915v7_l4t7vz0m0000gn/T/jl_sMtvPu/Project.toml`
  [86711068] RxInfer v3.3.1
  [aa65fe97] SnoopCompile v2.10.8

using RxInfer, Random

@model function mymodel(y)
    t  ~ Beta(1, 1)
    y .~ Bernoulli(t)
end

function foo()
    y = rand(MersenneTwister(42), Bernoulli(0.5), 10);
    return infer(model = mymodel(), data = (y = y, ))
end

If I call @time foo() several times it consistently reports some "compilation time"

@time foo() # 0.001380 seconds (3.66 k allocations: 194.656 KiB, 0.03% compilation time)
@time foo() # 0.001291 seconds (3.66 k allocations: 194.656 KiB, 0.07% compilation time)
@time foo() # 0.001618 seconds (3.66 k allocations: 194.656 KiB, 0.14% compilation time)

The SnoopCompile package does not report any problems

@snoopi_deep foo() # InferenceTimingNode: 0.019876/0.019876 on Core.Compiler.Timings.ROOT() with 0 direct children
@snoopr foo() # Any[]

Basically the issue here is that there is presumably no way to track the source of those "compilation time"? I guess it recompiles something every time, which is far from ideal, but I'm unsure how to track/fix those.

[bvdmitri]

julia> versioninfo()
Julia Version 1.10.4
Commit 48d4fd48430 (2024-06-04 10:41 UTC)
Build Info:
  Official https://julialang.org/ release
Platform Info:
  OS: macOS (arm64-apple-darwin22.4.0)
  CPU: 11 × Apple M3 Pro
  WORD_SIZE: 64
  LIBM: libopenlibm
  LLVM: libLLVM-15.0.7 (ORCJIT, apple-m1)
Threads: 1 default, 0 interactive, 1 GC (on 5 virtual cores)

Installed via juliaup

[IanButterworth]

Try running with --trace-compile=stderr to see what method is being compiled

[bvdmitri]

Hey, thanks @IanButterworth , running with --trace-compile=stderr does not report any methods begin compiled. But the "compilation time" is still present.

# ...
# truncated first run
# ...
precompile(Tuple{typeof(Core.kwcall), NamedTuple{(:msg,), Tuple{Nothing}}, typeof(Base.time_print), Base.TTY, UInt64, Int64, Int64, Int64, UInt64, UInt64, Bool})
precompile(Tuple{typeof(Base.Ryu.writefixed), Float64, Int64})
  2.905427 seconds (11.25 M allocations: 755.766 MiB, 6.14% gc time, 99.27% compilation time)
precompile(Tuple{typeof(Base.signed), Int64})
precompile(Tuple{typeof(Base.convert), Type{UInt32}, Char})
precompile(Tuple{typeof(Base.show), Base.IOContext{Base.TTY}, Base.Multimedia.MIME{Symbol("text/plain")}, RxInfer.InferenceResult{Base.Dict{Symbol, Distributions.Beta{Float64}}, Base.Dict{Any, Any}, Nothing, RxInfer.ProbabilisticModel{GraphPPL.Model{MetaGraphsNext.MetaGraph{Int64, Graphs.SimpleGraphs.SimpleGraph{Int64}, GraphPPL.NodeLabel, GraphPPL.NodeData, GraphPPL.EdgeLabel, GraphPPL.Context, MetaGraphsNext.var"#4#8", Float64}, GraphPPL.PluginsCollection{Tuple{GraphPPL.VariationalConstraintsPlugin{GraphPPL.NoConstraints}, GraphPPL.MetaPlugin{GraphPPL.MetaSpecification}, RxInfer.InitializationPlugin{RxInfer.NoInit}, RxInfer.ReactiveMPInferencePlugin{RxInfer.ReactiveMPInferenceOptions{Nothing, Nothing}}}}, RxInfer.ReactiveMPGraphPPLBackend}}, Nothing}})
Inference results:
  Posteriors       | available for (t)

julia> @time foo()
  0.001288 seconds (3.66 k allocations: 194.656 KiB, 0.05% compilation time)
Inference results:
  Posteriors       | available for (t)

julia> @time foo()
  0.001082 seconds (3.66 k allocations: 194.656 KiB, 0.10% compilation time)
Inference results:
  Posteriors       | available for (t)

[IanButterworth]

Huh. It does seem like a timing bug then.

[IanButterworth]

Could what's happening here be that we're entering the code that orchestrates compilation because it seems like compilation is needed, and timing is done at that level, but not ending up compiling the method because of a finer grained check? Might that make sense @JeffBezanson ?

[bvdmitri]

fyi also happens on

julia> versioninfo()
Julia Version 1.11.0-beta2
Commit edb3c92d6a6 (2024-05-29 09:37 UTC)

and --trace-compile=stderr doesn't show anything either