Snoopi "misses" top-level functions if the whole block gets inferred. i.e. `@time @snoopi` breaks results.

I've been meaning to post about this issue for a while, because its behavior has been baffling me for some time.

I was finally gearing up to post about it today, but thanks to some great sleuthing work together with @sacha0, we managed to understand the situation! :) I'm not sure about a fix yet, but I'm glad to be able to understand and explain everything that's going on.

---

First, here is the bizarre behavior I've observed, which maybe others have seen before, too:

Adding @time to a @snoopi call changes the results!

Consider this example, where I create a module with some functions, where I've forced an inference barrier to let us see inference at work. It includes a forced runtime dispatch, so we see three separate results from @snoopi - one for each of the top-level calls to inference. This result is repeatable; as long as you redefine the module and resnoop, you again get [g,i,i2].

The interesting behavior is that when we then @time the call to @snoopi, we are missing the top-level inference call! We instead only get the calls for the functions called via dynamic dispatch.

julia> module M
          i(x) = x+5
          i2(x) = x+2
          h(a::Array) = i2(a[1]::Integer) + i(a[1]::Integer) + 2
          g(y::Integer, x) = h(Any[y]) + Int(x)
       end;

julia> timings = SnoopCompileCore.@snoopi let
              M.g(2,3.0)
          end;             # Run once to compile all the downstream functions (like + and getindex) to make the subsequent logs clearer.

julia> module M
          i(x) = x+5
          i2(x) = x+2
          h(a::Array) = i2(a[1]::Integer) + i(a[1]::Integer) + 2
          g(y::Integer, x) = h(Any[y]) + Int(x)
       end;
WARNING: replacing module M.

julia> timings = SnoopCompileCore.@snoopi let
              M.g(2,3.0)
          end
3-element Array{Tuple{Float64,Core.MethodInstance},1}:
 (0.0002079010009765625, MethodInstance for i(::Int64))
 (0.000225067138671875, MethodInstance for i2(::Int64))
 (0.0015878677368164062, MethodInstance for g(::Int64, ::Float64))

julia> module M
          i(x) = x+5
          i2(x) = x+2
          h(a::Array) = i2(a[1]::Integer) + i(a[1]::Integer) + 2
          g(y::Integer, x) = h(Any[y]) + Int(x)
       end;
WARNING: replacing module M.

julia> @time timings = SnoopCompileCore.@snoopi let
              M.g(2,3.0)
          end
  0.004031 seconds (1.45 k allocations: 86.355 KiB)
2-element Array{Tuple{Float64,Core.MethodInstance},1}:
 (0.00015401840209960938, MethodInstance for i(::Int64))
 (0.00024318695068359375, MethodInstance for i2(::Int64))

I found this result quite surprising! But don't worry, if you don't already see the problem, it'll be clear in the end.

---

Next, here is another very surprising behavior I've seen with the @time macro, which baffled us for a few hours:

julia> elapsedtime1 = Base.time_ns(); @time db = Delve.API.create_database();   elapsedtime = Base.time_ns() - elapsedtime1;
 29.711536 seconds (34.38 M allocations: 1.745 GiB, 2.00% gc time)

julia> elapsedtime / 1e9
98.999127862

create_database() is some internal function in our codebase that takes quite a long time to compile.

But somehow, the time reported by time is 70 seconds less than the time I measured! It's weird, right!?

---

We finally found the answer, and it's the same answer for both cases. What is happening here is that the @time macro causes its entire body to be compiled before executing it. And this includes the body of the code that we want to infer with @snoopi!

So basically, by the time we actually get to the part of the code that enables snooping within julia, we've already finished inferring the top-level call we wanted to measure!

We can of course fix this with any kind of inference barrier inside the body we're measuring. e.g. an @eval will do it:

julia> module M
          i(x) = x+5
          i2(x) = x+2
          h(a::Array) = i2(a[1]::Integer) + i(a[1]::Integer) + 2
          g(y::Integer, x) = h(Any[y]) + Int(x)
       end;
WARNING: replacing module M.

julia> @time timings = SnoopCompileCore.@snoopi let
              @eval M.g(2,3.0)   # thanks to this @eval, we now delay inferring `g()` until _after_ we've enabled snooping.
          end
  0.017935 seconds (11.62 k allocations: 569.847 KiB)
3-element Array{Tuple{Float64,Core.MethodInstance},1}:
 (0.0002300739288330078, MethodInstance for i(::Int64))
 (0.0002770423889160156, MethodInstance for i2(::Int64))
 (0.0019459724426269531, MethodInstance for g(::Int64, ::Float64))

And so in my example above, where we've always thought our create_database() function takes 30 seconds to compile the first time, it ACTUALLY takes 100 seconds! I was just only starting my timer after all the top-level inference was completed! And since it's fairly type-stable code, we were apparently able to get most of the way through it.

---

Hooray! :) It all makes sense now!

But I'm not sure what should be done about it.

It strikes me that this may surprise other users, since users of @snoopi really are intending to measure inference times of the body of the macro. So it seems to me that we should change the macro to go out of our way to prevent it from being inferred before we enable snooping.

I'm not sure if we should go as far as adding an @eval, since that does actually change the meaning of the code, but is there any other clever way to add an inference barrier that we can use?

:) Thanks!

Start by locating the implementation of SnoopCompileCore.@snoopi and reviewing how the Julia @time macro causes the body to be inferred before snooping starts. Reproduce the shown M.g example with and without @time, including the @eval workaround. Done should preserve the intended meaning of the body while capturing the top-level inference call under @time.