Report per-MethodInstance inference timings during a single inference call, via SnoopCompile

base/compiler/typeinfer.jl

@@ -8,7 +8,134 @@ function typeinf(interp::AbstractInterpreter, result::InferenceResult, cached::B
     return typeinf(interp, frame)
 end
 
+module Timings
+
+using Core.Compiler: -, +, length, push!, pop!, @inline
+
+struct Timing
+    name::Any
+    start_time::UInt64
+    cur_start_time::UInt64
+    time::UInt64
+    children::Core.Array{Timing,1}
+    Timing(name, start_time, cur_start_time, time, children) = new(name, start_time, cur_start_time, time, children)
+    Timing(name, start_time) = new(name, start_time, start_time, UInt64(0), Timing[])
+end
+
+time_ns() = ccall(:jl_hrtime, UInt64, ())
+
+const _timings = Timing[]
+function reset_timings()
+    Core.Compiler.empty!(_timings)
+    Core.Compiler.push!(_timings, Timing("root", time_ns()))
+    nothing
+end
+reset_timings()
+
+function close_current_timer()
+    stop_time = time_ns()
+    parent_timer = _timings[end]
+    accum_time = Core.Compiler.:(-)(stop_time, parent_timer.cur_start_time)
+end
+
+@inline function enter_new_timer(name)
+    # Stop the current timer before recursing into the child
+    stop_time = Timings.time_ns()
+
+    _timings = Timings._timings
+    parent_timer = _timings[end]
+    accum_time = stop_time - parent_timer.cur_start_time
+
+    # Add in accum_time ("modify" the immutable struct)
+    _timings[end] = Timings.Timing(
+        parent_timer.name,
+        parent_timer.start_time,
+        parent_timer.cur_start_time,
+        parent_timer.time + accum_time,
+        parent_timer.children,
+    )
+
+    # Start the new timer right before returning
+    push!(_timings, Timings.Timing(name, UInt64(0)))
+    len = length(_timings)
+    new_timer = _timings[len]
+    # Set the current time _after_ appending the node, to try to exclude the
+    # overhead from measurement.
+    start = Timings.time_ns()
+
+    Core.Compiler.@inbounds begin
+        _timings[len] = Timings.Timing(
+            new_timer.name,
+            start,
+            start,
+            new_timer.time,
+            new_timer.children,
+        )
+    end
+
+    # IDEA:
+    # _timings_values[end] = Timings.time_ns()
+end
+
+@inline function exit_current_timer(_expected_name_)
+    # Finish the new timer
+    stop_time = Timings.time_ns()
+
+    # Grab the new timer again because it might have been modified in _timings
+    # (since it's an immutable struct)
+    # And remove it from the current timings stack
+    _timings = Timings._timings
+    new_timer = pop!(_timings)
+    Core.Compiler.@assert new_timer.name === _expected_name_ (new_timer.name, _expected_name_)
+
+    accum_time = stop_time - new_timer.cur_start_time
+    # Add in accum_time ("modify" the immutable struct)
+    new_timer = Timings.Timing(
+        new_timer.name,
+        new_timer.start_time,
+        new_timer.cur_start_time,
+        new_timer.time + accum_time,
+        new_timer.children
+    )
+    # Record the final timing with the original parent timer
+    parent_timer = _timings[end]
+    push!(parent_timer.children, new_timer)
+
+    # And finally restart the parent timer:
+    len = length(_timings)
+    Core.Compiler.@inbounds begin
+        _timings[len] = Timings.Timing(
+            parent_timer.name,
+            parent_timer.start_time,
+            Timings.time_ns(),
+            parent_timer.time,
+            parent_timer.children,
+        )
+    end
+end
+
+
+end  # module Timings
+
+# TODO(PR): What's the right way to do a global const mutable boolean in Core.Compiler?
+const __measure_typeinf__ = fill(false)
+__toggle_measure_typeinf(onoff::Bool) = __measure_typeinf__[] = onoff
+
 function typeinf(interp::AbstractInterpreter, frame::InferenceState)
+    if __measure_typeinf__[]
+        Timings.enter_new_timer(frame.linfo.specTypes)
+
+        v = _typeinf(interp, frame)
+
+        Timings.exit_current_timer(frame.linfo.specTypes)
+
+        return v
+    else
+        return _typeinf(interp, frame)
+    end
+end
+
+function _typeinf(interp::AbstractInterpreter, frame::InferenceState)
     typeinf_nocycle(interp, frame) || return false # frame is now part of a higher cycle
     # with no active ip's, frame is done
     frames = frame.callers_in_cycle