Expose changes to Julia via @snoopi_deep to report timing profile breakdown of _all MethodInstances_ that are inferred during type inference

Project.toml

@@ -5,6 +5,8 @@ version = "2.1.1"
 
 [deps]
 Cthulhu = "f68482b8-f384-11e8-15f7-abe071a5a75f"
+FlameGraphs = "08572546-2f56-4bcf-ba4e-bab62c3a3f89"
+LeftChildRightSiblingTrees = "1d6d02ad-be62-4b6b-8a6d-2f90e265016e"
 OrderedCollections = "bac558e1-5e72-5ebc-8fee-abe8a469f55d"
 Pkg = "44cfe95a-1eb2-52ea-b672-e2afdf69b78f"
 Serialization = "9e88b42a-f829-5b0c-bbe9-9e923198166b"

SnoopCompileCore/src/snoopi.jl

@@ -1,6 +1,7 @@
 export @snoopi
 
 const __inf_timing__ = Tuple{Float64,MethodInstance}[]
+const __inner_timings__ = Ref{Vector{Any}}()
 
 if isdefined(Core.Compiler, :Params)
     function typeinf_ext_timed(linfo::Core.MethodInstance, params::Core.Compiler.Params)
@@ -17,7 +18,9 @@ if isdefined(Core.Compiler, :Params)
         push!(__inf_timing__, (tstop-tstart, linfo))
         return ret
     end
-    @noinline stop_timing() = ccall(:jl_set_typeinf_func, Cvoid, (Any,), Core.Compiler.typeinf_ext)
+    @noinline stop_timing() = begin
+        ccall(:jl_set_typeinf_func, Cvoid, (Any,), Core.Compiler.typeinf_ext)
+    end
 else
     function typeinf_ext_timed(interp::Core.Compiler.AbstractInterpreter, linfo::Core.MethodInstance)
         tstart = time()
@@ -33,10 +36,14 @@ else
         push!(__inf_timing__, (tstop-tstart, linfo))
         return ret
     end
-    @noinline stop_timing() = ccall(:jl_set_typeinf_func, Cvoid, (Any,), Core.Compiler.typeinf_ext_toplevel)
+    @noinline stop_timing() = begin
+        ccall(:jl_set_typeinf_func, Cvoid, (Any,), Core.Compiler.typeinf_ext_toplevel)
+    end
 end
 
-@noinline start_timing() = ccall(:jl_set_typeinf_func, Cvoid, (Any,), typeinf_ext_timed)
+@noinline start_timing() = begin
+    ccall(:jl_set_typeinf_func, Cvoid, (Any,), typeinf_ext_timed)
+end
 
 function sort_timed_inf(tmin)
     data = __inf_timing__
@@ -76,6 +83,7 @@ end
 function _snoopi(cmd::Expr, tmin = 0.0)
     return quote
         empty!(__inf_timing__)
+        Core.Compiler.Timings.reset_timings()
         start_timing()
         try
             $(esc(cmd))
@@ -86,6 +94,57 @@ function _snoopi(cmd::Expr, tmin = 0.0)
     end
 end
 
+function start_deep_timing()
+    Core.Compiler.Timings.reset_timings()
+    Core.Compiler.__set_measure_typeinf(true)
+end
+function stop_deep_timing()
+    Core.Compiler.__set_measure_typeinf(false)
+    Core.Compiler.Timings.close_current_timer()
+end
+
+function finish_snoopi_deep()
+    return Core.Compiler.Timings._timings[1]
+end
+
+function _snoopi_deep(cmd::Expr)
+    return quote
+        start_deep_timing()
+        try
+            $(esc(cmd))
+        finally
+            stop_deep_timing()
+        end
+        finish_snoopi_deep()
+    end
+end
+
+macro snoopi_deep(cmd)
+    return _snoopi_deep(cmd)
+end
+
+function flatten_times(timing::Core.Compiler.Timings.Timing, tmin_secs = 0.0)
+    tmin_ns = tmin_secs * 1e9
+    out = Any[]
+    frontier = [timing]
+    while !isempty(frontier)
+        t = popfirst!(frontier)
+        if t.time < tmin_ns
+            continue
+        end
+        exclusive_time = (t.time / 1e9)
+        if exclusive_time >= tmin_secs
+            push!(out, exclusive_time => t.mi_info)
+        end
+        for c in t.children
+            push!(frontier, c)
+        end
+    end
+    return sort(out; by=tl->tl[1])
+end
+
+
+
 function __init__()
     # typeinf_ext_timed must be compiled before it gets run
     # We do this in __init__ to make sure it gets compiled to native code
@@ -99,5 +158,12 @@ function __init__()
     end
     precompile(start_timing, ())
     precompile(stop_timing, ())
+
+    @assert precompile(Core.Compiler.Timings.reset_timings, ())
+    @assert precompile(start_deep_timing, ())
+    @assert precompile(stop_deep_timing, ())
+    @assert precompile(finish_snoopi_deep, ())
+
+    @assert precompile(flatten_times, (Core.Compiler.Timings.Timing, Float64))
     nothing
 end

src/parcel_snoopi.jl

@@ -380,3 +380,99 @@ end
 const default_exclusions = Set([
     r"\bMain\b",
 ])
+
+
+import FlameGraphs
+#import AbstractTrees
+
+using Base.StackTraces: StackFrame
+using LeftChildRightSiblingTrees: Node, addchild
+using Core.Compiler.Timings: Timing
+
+# TODO(PR): It would maybe be better to build up this inclusive timings information
+#   directly in julia so that we don't have to build a second graph structure? But I wanted
+#   to keep the amount of work done inside the snooping itself to a minimum? Not sure.
+struct InclusiveTiming
+    name::Any
+    inclusive_time::UInt64
+    start_time::UInt64
+    children::Vector{InclusiveTiming}
+end
+#AbstractTrees.printnode(io::IO, t::InclusiveTiming) = print(io, (t.inclusive_time / 1e9 => t.name))
+#AbstractTrees.children(t::InclusiveTiming) = t.children
+
+inclusive_time(t::InclusiveTiming) = t.inclusive_time
+
+function build_inclusive_times(t::Timing)
+    child_times = InclusiveTiming[
+        build_inclusive_times(child)
+        for child in t.children
+    ]
+    incl_time = t.time + sum(inclusive_time.(child_times); init=UInt64(0))
+    return InclusiveTiming(t.mi_info, incl_time, t.start_time, child_times)
+end
+
+function frame_name(mi_info::Tuple)
+    frame_name(mi_info[1]::Core.Compiler.MethodInstance)
+end
+function frame_name(mi::Core.Compiler.MethodInstance)
+    frame_name(mi.def.name, mi.specTypes)
+end
+# Special printing for Type Tuples so they're less ugly in the FlameGraph
+function frame_name(name, ::Type{TT}) where TT<:Tuple
+    #io = IOBuffer()
+    #Base.show_tuple_as_call(io, name, TT)
+    #v = String(take!(io))
+    #if v[1] == '('  # ugh, pprof isn't going to like this leading `(`...
+    #    return string(TT)  # return the ugly thing >.<
+    #else
+    #    return v
+    #end
+
+    # For now, since PProf name mangles strings that parse as functions, we'll just use the
+    # full Type Tuple string :|
+    return string(TT)
+end
+
+# NOTE: The "root" node doesn't cover th whole profile, because it's only the _complement_
+# of the inference times (so it's missing the _overhead_ from the measurement).
+# SO we need to manually create a root node that covers the whole thing.
+function max_end_time(t::InclusiveTiming)
+    return maximum(child.start_time + child.inclusive_time for child in t.children)
+end
+
+# Make a flat frame for this Timing
+function _flamegraph_frame(to::InclusiveTiming, start_ns; toplevel)
+    # TODO: Use a better conversion to a StackFrame so this contains the right kind of data
+    tt = Symbol(frame_name(to.name))
+    sf = StackFrame(tt, Symbol("none"), 0, nothing, false, false, UInt64(0x0))
+    status = 0x0  # "default" status -- See FlameGraphs.jl
+    start = to.start_time - start_ns
+    if toplevel
+        # Compute a range over the whole profile for the top node.
+        range = Int(start) : max_end_time(to) - start_ns
+    else
+        range = Int(start) : Int(start + to.inclusive_time)
+    end
+    return FlameGraphs.NodeData(sf, status, range)
+end
+
+function to_flamegraph(t::Timing)
+    it = build_inclusive_times(t)
+    to_flamegraph(it)
+end
+
+function to_flamegraph(to::InclusiveTiming)
+    # Compute a "root" frame for the top-level node, to cover the whole profile
+    node_data = _flamegraph_frame(to, to.start_time; toplevel=true)
+    root = Node(node_data)
+    return _to_flamegraph(to, root, to.start_time)
+end
+function _to_flamegraph(to::InclusiveTiming, root, start_ns)
+    for child in to.children
+        node_data = _flamegraph_frame(child, start_ns; toplevel=false)
+        node = addchild(root, node_data)
+        _to_flamegraph(child, node, start_ns)
+    end
+    return root
+end