@time always shows reports compilation times while SnoopCompile does not about julia

[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