From d19deabbfb59ef4176b20903f5fac548463eb36e Mon Sep 17 00:00:00 2001
From: Nathan Daly <nhdaly@gmail.com>
Date: Fri, 11 Sep 2020 15:53:57 -0400
Subject: [PATCH 01/49] First pass at snoopi collecting the full inferrable set
 from julia

---
 SnoopCompileCore/src/snoopi.jl | 29 +++++++++++++++++++++++++----
 1 file changed, 25 insertions(+), 4 deletions(-)

diff --git a/SnoopCompileCore/src/snoopi.jl b/SnoopCompileCore/src/snoopi.jl
index e3700422c..3df60e9a1 100644
--- a/SnoopCompileCore/src/snoopi.jl
+++ b/SnoopCompileCore/src/snoopi.jl
@@ -1,49 +1,69 @@
 export @snoopi
 
 const __inf_timing__ = Tuple{Float64,MethodInstance}[]
+const __inf_callees__ = Dict{MethodInstance, Vector{MethodInstance}}()
 
 if isdefined(Core.Compiler, :Params)
     function typeinf_ext_timed(linfo::Core.MethodInstance, params::Core.Compiler.Params)
+        empty!(Core.Compiler.__inference_callees__)
         tstart = time()
         ret = Core.Compiler.typeinf_ext(linfo, params)
         tstop = time()
         push!(__inf_timing__, (tstop-tstart, linfo))
+        __inf_callees__[linfo] = Core.Compiler.__inference_callees__
         return ret
     end
     function typeinf_ext_timed(linfo::Core.MethodInstance, world::UInt)
+        empty!(Core.Compiler.__inference_callees__)
         tstart = time()
         ret = Core.Compiler.typeinf_ext(linfo, world)
         tstop = time()
         push!(__inf_timing__, (tstop-tstart, linfo))
+        __inf_callees__[linfo] = Core.Compiler.__inference_callees__
         return ret
     end
-    @noinline stop_timing() = ccall(:jl_set_typeinf_func, Cvoid, (Any,), Core.Compiler.typeinf_ext)
+    @noinline function stop_timing()
+        ccall(:jl_set_typeinf_func, Cvoid, (Any,), Core.Compiler.typeinf_ext)
+        #Core.Compiler.__collect_inference_callees__[] = false
+    end
 else
     function typeinf_ext_timed(interp::Core.Compiler.AbstractInterpreter, linfo::Core.MethodInstance)
+        empty!(Core.Compiler.__inference_callees__)
         tstart = time()
         ret = Core.Compiler.typeinf_ext_toplevel(interp, linfo)
         tstop = time()
         push!(__inf_timing__, (tstop-tstart, linfo))
+        __inf_callees__[linfo] = Core.Compiler.__inference_callees__
         return ret
     end
     function typeinf_ext_timed(linfo::Core.MethodInstance, world::UInt)
+        empty!(Core.Compiler.__inference_callees__)
         tstart = time()
         ret = Core.Compiler.typeinf_ext_toplevel(linfo, world)
         tstop = time()
         push!(__inf_timing__, (tstop-tstart, linfo))
+        __inf_callees__[linfo] = Core.Compiler.__inference_callees__
         return ret
     end
-    @noinline stop_timing() = ccall(:jl_set_typeinf_func, Cvoid, (Any,), Core.Compiler.typeinf_ext_toplevel)
+    @noinline function stop_timing()
+        ccall(:jl_set_typeinf_func, Cvoid, (Any,), Core.Compiler.typeinf_ext_toplevel)
+        #Core.Compiler.__collect_inference_callees__[] = false
+    end
 end
 
-@noinline start_timing() = ccall(:jl_set_typeinf_func, Cvoid, (Any,), typeinf_ext_timed)
+@noinline function start_timing()
+    ccall(:jl_set_typeinf_func, Cvoid, (Any,), typeinf_ext_timed)
+    #Core.Compiler.__collect_inference_callees__[] = true
+end
 
 function sort_timed_inf(tmin)
     data = __inf_timing__
     if tmin > 0.0
         data = filter(tl->tl[1] >= tmin, data)
     end
-    return sort(data; by=tl->tl[1])
+    data = sort(data; by=tl->tl[1])
+    out = Tuple{Float64,Vector{MethodInstance}}[(tl[1], __inf_callees__[tl[2]]) for tl in data]
+    return out
 end
 
 """
@@ -76,6 +96,7 @@ end
 function _snoopi(cmd::Expr, tmin = 0.0)
     return quote
         empty!(__inf_timing__)
+        empty!(__inf_callees__)
         start_timing()
         try
             $(esc(cmd))

From ac15b226263a866977acad40450835d72a517dd7 Mon Sep 17 00:00:00 2001
From: Nathan Daly <nhdaly@gmail.com>
Date: Fri, 11 Sep 2020 16:18:38 -0400
Subject: [PATCH 02/49] Update to use bool to control julia "collect inference
 callees" feature

---
 SnoopCompileCore/src/snoopi.jl | 6 +++---
 1 file changed, 3 insertions(+), 3 deletions(-)

diff --git a/SnoopCompileCore/src/snoopi.jl b/SnoopCompileCore/src/snoopi.jl
index 3df60e9a1..bdcc926f1 100644
--- a/SnoopCompileCore/src/snoopi.jl
+++ b/SnoopCompileCore/src/snoopi.jl
@@ -24,7 +24,7 @@ if isdefined(Core.Compiler, :Params)
     end
     @noinline function stop_timing()
         ccall(:jl_set_typeinf_func, Cvoid, (Any,), Core.Compiler.typeinf_ext)
-        #Core.Compiler.__collect_inference_callees__[] = false
+        Core.Compiler.__collect_inference_callees__[] = false
     end
 else
     function typeinf_ext_timed(interp::Core.Compiler.AbstractInterpreter, linfo::Core.MethodInstance)
@@ -47,13 +47,13 @@ else
     end
     @noinline function stop_timing()
         ccall(:jl_set_typeinf_func, Cvoid, (Any,), Core.Compiler.typeinf_ext_toplevel)
-        #Core.Compiler.__collect_inference_callees__[] = false
+        Core.Compiler.__collect_inference_callees__[] = false
     end
 end
 
 @noinline function start_timing()
     ccall(:jl_set_typeinf_func, Cvoid, (Any,), typeinf_ext_timed)
-    #Core.Compiler.__collect_inference_callees__[] = true
+    Core.Compiler.__collect_inference_callees__[] = true
 end
 
 function sort_timed_inf(tmin)

From b9f07fe81421cc307a23dd1690b2da59f24125c9 Mon Sep 17 00:00:00 2001
From: Nathan Daly <nhdaly@gmail.com>
Date: Mon, 14 Sep 2020 13:58:19 -0400
Subject: [PATCH 03/49] Use commit `97b5cde769` from Julia to return dep graph
 from snoopi

```julia
julia> module M
           i(x) = x+3
           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> SnoopCompileCore.@snoopi begin
           M.g(2,3.0)
       end
3-element Vector{Tuple{Float64,Core.MethodInstance,Vector{Pair{Core.MethodInstance,Core.MethodInstance}}}}:
 (0.00024819374084472656, MethodInstance for i(::Int64), [])
 (0.0003299713134765625, MethodInstance for i2(::Int64), [])
 (0.001934051513671875, MethodInstance for g(::Int64, ::Float64), [MethodInstance for g(::Int64, ::Float64) => MethodInstance for h(::Vector{Any}), MethodInstance for h(::Vector{Any}) => MethodInstance for i2(::Integer), MethodInstance for h(::Vector{Any}) => MethodInstance for i(::Integer)])
 ```
---
 SnoopCompileCore/src/snoopi.jl | 35 +++++++++++++++++++++++++++++++++-
 1 file changed, 34 insertions(+), 1 deletion(-)

diff --git a/SnoopCompileCore/src/snoopi.jl b/SnoopCompileCore/src/snoopi.jl
index bdcc926f1..ac9ec33d9 100644
--- a/SnoopCompileCore/src/snoopi.jl
+++ b/SnoopCompileCore/src/snoopi.jl
@@ -2,24 +2,36 @@ export @snoopi
 
 const __inf_timing__ = Tuple{Float64,MethodInstance}[]
 const __inf_callees__ = Dict{MethodInstance, Vector{MethodInstance}}()
+const __inf_callee_edges4__ = Dict{MethodInstance, Vector{Any}}()
 
 if isdefined(Core.Compiler, :Params)
     function typeinf_ext_timed(linfo::Core.MethodInstance, params::Core.Compiler.Params)
+        #Core.println("starting $linfo")
         empty!(Core.Compiler.__inference_callees__)
+        #empty!(Core.Compiler.__inference_callee_edges4__)
+        push!(Core.Compiler.__inference_callee_edges4__, (linfo, Tuple{MethodInstance,MethodInstance}[]))
         tstart = time()
         ret = Core.Compiler.typeinf_ext(linfo, params)
         tstop = time()
         push!(__inf_timing__, (tstop-tstart, linfo))
         __inf_callees__[linfo] = Core.Compiler.__inference_callees__
+        @assert Core.Compiler.__inference_callee_edges4__[end][1] == linfo
+        __inf_callee_edges4__[linfo] = pop!(Core.Compiler.__inference_callee_edges4__)[2]
+        #Core.println("push: ", Core.Compiler.__inference_callee_edges4__)
         return ret
     end
     function typeinf_ext_timed(linfo::Core.MethodInstance, world::UInt)
+        #Core.println("starting $linfo")
         empty!(Core.Compiler.__inference_callees__)
+        push!(Core.Compiler.__inference_callee_edges4__, (linfo, Tuple{MethodInstance,MethodInstance}[]))
         tstart = time()
         ret = Core.Compiler.typeinf_ext(linfo, world)
         tstop = time()
         push!(__inf_timing__, (tstop-tstart, linfo))
         __inf_callees__[linfo] = Core.Compiler.__inference_callees__
+        @assert Core.Compiler.__inference_callee_edges4__[end][1] == linfo
+        __inf_callee_edges4__[linfo] = pop!(Core.Compiler.__inference_callee_edges4__)[2]
+        #Core.println("push: ", Core.Compiler.__inference_callee_edges4__)
         return ret
     end
     @noinline function stop_timing()
@@ -28,21 +40,31 @@ if isdefined(Core.Compiler, :Params)
     end
 else
     function typeinf_ext_timed(interp::Core.Compiler.AbstractInterpreter, linfo::Core.MethodInstance)
+        #Core.println("starting $linfo")
         empty!(Core.Compiler.__inference_callees__)
+        push!(Core.Compiler.__inference_callee_edges4__, (linfo, Tuple{MethodInstance,MethodInstance}[]))
         tstart = time()
         ret = Core.Compiler.typeinf_ext_toplevel(interp, linfo)
         tstop = time()
         push!(__inf_timing__, (tstop-tstart, linfo))
         __inf_callees__[linfo] = Core.Compiler.__inference_callees__
+        @assert Core.Compiler.__inference_callee_edges4__[end][1] == linfo
+        __inf_callee_edges4__[linfo] = pop!(Core.Compiler.__inference_callee_edges4__)[2]
+        #Core.println("push: ", Core.Compiler.__inference_callee_edges4__)
         return ret
     end
     function typeinf_ext_timed(linfo::Core.MethodInstance, world::UInt)
+        #Core.println("starting $linfo")
         empty!(Core.Compiler.__inference_callees__)
+        push!(Core.Compiler.__inference_callee_edges4__, (linfo, Tuple{MethodInstance,MethodInstance}[]))
         tstart = time()
         ret = Core.Compiler.typeinf_ext_toplevel(linfo, world)
         tstop = time()
         push!(__inf_timing__, (tstop-tstart, linfo))
         __inf_callees__[linfo] = Core.Compiler.__inference_callees__
+        @assert Core.Compiler.__inference_callee_edges4__[end][1] == linfo
+        __inf_callee_edges4__[linfo] = pop!(Core.Compiler.__inference_callee_edges4__)[2]
+        #Core.println("push: ", Core.Compiler.__inference_callee_edges4__)
         return ret
     end
     @noinline function stop_timing()
@@ -62,7 +84,17 @@ function sort_timed_inf(tmin)
         data = filter(tl->tl[1] >= tmin, data)
     end
     data = sort(data; by=tl->tl[1])
-    out = Tuple{Float64,Vector{MethodInstance}}[(tl[1], __inf_callees__[tl[2]]) for tl in data]
+    #@show __inf_callee_edges4__
+    out = Tuple{Float64,MethodInstance,
+                #Vector{MethodInstance},
+                Vector{Pair{MethodInstance,MethodInstance}}}[
+        (tl[1], tl[2],
+            # Another (incorrect) view on all MethodInstances compiled during this inferable set
+            #__inf_callees__[tl[2]],
+            # The dependency graph of those compilations.
+            [a=>b for (a,b) in __inf_callee_edges4__[tl[2]]]
+        ) for (i,tl) in enumerate(data)
+    ]
     return out
 end
 
@@ -97,6 +129,7 @@ function _snoopi(cmd::Expr, tmin = 0.0)
     return quote
         empty!(__inf_timing__)
         empty!(__inf_callees__)
+        empty!(__inf_callee_edges4__)
         start_timing()
         try
             $(esc(cmd))

From 9b5f04a244f57b66370279250f888b717ebeb38f Mon Sep 17 00:00:00 2001
From: Nathan Daly <nhdaly@gmail.com>
Date: Mon, 14 Sep 2020 17:14:38 -0400
Subject: [PATCH 04/49] Almost working parcel per_method_instance_timings --
 need to fix serialization

---
 src/parcel_snoopi.jl | 78 ++++++++++++++++++++++++++++++++++++++++++++
 1 file changed, 78 insertions(+)

diff --git a/src/parcel_snoopi.jl b/src/parcel_snoopi.jl
index 775e6f40d..4461140ba 100644
--- a/src/parcel_snoopi.jl
+++ b/src/parcel_snoopi.jl
@@ -1,3 +1,7 @@
+#using LightGraph
+#using AbstractTrees
+using Serialization
+
 function topmodule(mods)
     function ischild(c, mod)
         ok = false
@@ -380,3 +384,77 @@ end
 const default_exclusions = Set([
     r"\bMain\b",
 ])
+
+
+function collect_per_method_inference_timings(snoopi_results::Vector)
+    total_time, root, mi_dep_graph = snoopi_results[1]
+    tt_deps = [a.specTypes => b.specTypes for (a,b) in mi_dep_graph]
+
+    per_method_instance_timings(root.specTypes, tt_deps)
+end
+
+struct Node{T}
+    key::T
+    children::Vector{Node{T}}
+    Node(key::T) where T = new{T}(key, Node{T}[])
+    Node{T}(key::T) where T = new{T}(key, Node{T}[])
+end
+function per_method_instance_timings(root, deps)
+    tree = Node(root)
+    nodes = Dict(root => tree)
+    for (k,v) in deps
+        knode = get!(nodes, k, Node(k))
+        vnode = get!(nodes, v, Node(v))
+        push!(knode.children, vnode)
+    end
+    tree
+
+    # Now start timing how long it takes to compile each of them starting from the bottom
+    # working the way up.
+    # Do this timing measurement in a different process so that the functions will be
+    # compiled fresh.
+    tree_f, timings_f = tempname(), tempname()
+    serialize(tree_f, tree)
+    _measure_inference_timings(tree_f, timings_f)
+    return deserialize(timings_f)
+end
+
+
+function _measure_inference_timings(infilename, outfilename, flags = String[])
+    println("Launching new julia process to run commands...")
+    # addprocs will run the unmodified version of julia, so we
+    # launch it as a command.
+    code_object = """
+            using Serialization
+            while !eof(stdin)
+                Core.eval(Main, deserialize(stdin))
+            end
+            """
+    process = open(`$(Base.julia_cmd()) $flags --eval $code_object`, stdout, write=true)
+    serialize(process, quote
+        let tree = deserialize($infilename)
+            try
+                out_times = Dict{typeof(root), Float64}()
+                function time_all_nodes(root, out_times::Dict)
+                    for n in root.children
+                        time_all_nodes(n, out_times)
+                    end
+                    time_type_inference(root.key, out_times)
+                end
+                function time_type_inference(tt::Type, out_times::Dict)
+                    _, time = @timed code_typed(tt)
+                    out_times[tt] = time
+                end
+
+                time_all_nodes(tree, out_times)
+                serialize($outfilename, out_times)
+            finally
+                close(io)
+            end
+        end
+        exit()
+    end)
+    wait(process)
+    println("done.")
+    nothing
+end

From 1eb4214f6a0e182734662433538c5df52c185637 Mon Sep 17 00:00:00 2001
From: Nathan Daly <nhdaly@gmail.com>
Date: Mon, 14 Sep 2020 17:34:59 -0400
Subject: [PATCH 05/49] Working per-method timings, i think (though overly
 complicated and overly verbose)

I _think_ this now does what we want?
```julia
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> out = SnoopCompileCore.@snoopi begin
           M.g(2,3.0)
       end
3-element Vector{Tuple{Float64,Core.MethodInstance,Vector{Pair{Core.MethodInstance,Core.MethodInstance}}}}:
 (0.00022411346435546875, MethodInstance for i(::Int64), [])
 (0.00024890899658203125, MethodInstance for i2(::Int64), [])
 (0.0016169548034667969, MethodInstance for g(::Int64, ::Float64), [MethodInstance for g(::Int64, ::Float64) => MethodInstance for h(::Vector{Any}), MethodInstance for h(::Vector{Any}) => MethodInstance for i2(::Integer), MethodInstance for h(::Vector{Any}) => MethodInstance for i(::Integer)])

julia> SnoopCompile.collect_per_method_inference_timings(out, :(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))
Launching new julia process to run commands...
done.
[ Info: MethodInstance for i(::Int64):  total: 0.00022411346435546875   : 0.034790221
Dict{Any,Float64} with 1 entry:
  Tuple{typeof(i),Int64} => 0.0347902
Launching new julia process to run commands...
done.
[ Info: MethodInstance for i2(::Int64): total: 0.00024890899658203125   : 0.035098683
Dict{Any,Float64} with 1 entry:
  Tuple{typeof(i2),Int64} => 0.0350987
Launching new julia process to run commands...
done.
[ Info: MethodInstance for g(::Int64, ::Float64):       total: 0.0016169548034667969    : 0.046937507
Dict{Any,Float64} with 4 entries:
  Tuple{typeof(i2),Integer}      => 0.0110619
  Tuple{typeof(h),Vector{Any}}   => 0.025103
  Tuple{typeof(i),Integer}       => 0.00563928
  Tuple{typeof(g),Int64,Float64} => 0.00513329
[ Info: Returning merged results:
Dict{Any,Float64} with 6 entries:
  Tuple{typeof(i2),Integer}      => 0.0110619
  Tuple{typeof(h),Vector{Any}}   => 0.025103
  Tuple{typeof(i),Integer}       => 0.00563928
  Tuple{typeof(i2),Int64}        => 0.0350987
  Tuple{typeof(g),Int64,Float64} => 0.00513329
  Tuple{typeof(i),Int64}         => 0.0347902

julia>
```
---
 src/parcel_snoopi.jl | 80 +++++++++++++++++++++++++++-----------------
 1 file changed, 49 insertions(+), 31 deletions(-)

diff --git a/src/parcel_snoopi.jl b/src/parcel_snoopi.jl
index 4461140ba..1571a7a1f 100644
--- a/src/parcel_snoopi.jl
+++ b/src/parcel_snoopi.jl
@@ -386,20 +386,28 @@ const default_exclusions = Set([
 ])
 
 
-function collect_per_method_inference_timings(snoopi_results::Vector)
-    total_time, root, mi_dep_graph = snoopi_results[1]
-    tt_deps = [a.specTypes => b.specTypes for (a,b) in mi_dep_graph]
-
-    per_method_instance_timings(root.specTypes, tt_deps)
+function collect_per_method_inference_timings(snoopi_results::Vector, init_commands)
+    outd = Dict{Any, Float64}()
+    for (total_time, root, mi_dep_graph) = snoopi_results
+        tt_deps = [a.specTypes => b.specTypes for (a,b) in mi_dep_graph]
+
+        timings = per_method_instance_timings(init_commands, root.specTypes, tt_deps)
+        @info "$root:\ttotal: $total_time\t: $(sum(values(timings)))"
+        display(timings)
+        merge!(outd, timings)
+    end
+    @info "Returning merged results:"
+    outd
 end
 
-struct Node{T}
-    key::T
-    children::Vector{Node{T}}
-    Node(key::T) where T = new{T}(key, Node{T}[])
-    Node{T}(key::T) where T = new{T}(key, Node{T}[])
-end
-function per_method_instance_timings(root, deps)
+#struct Node{T}
+#    key::T
+#    children::Vector{Node{T}}
+#    Node(key::T) where T = new{T}(key, Node{T}[])
+#    Node{T}(key::T) where T = new{T}(key, Node{T}[])
+#end
+Node(root) = (; key=root, children=Any[])
+function per_method_instance_timings(init_commands, root, deps)
     tree = Node(root)
     nodes = Dict(root => tree)
     for (k,v) in deps
@@ -415,12 +423,12 @@ function per_method_instance_timings(root, deps)
     # compiled fresh.
     tree_f, timings_f = tempname(), tempname()
     serialize(tree_f, tree)
-    _measure_inference_timings(tree_f, timings_f)
+    _measure_inference_timings(init_commands, tree_f, timings_f)
     return deserialize(timings_f)
 end
 
 
-function _measure_inference_timings(infilename, outfilename, flags = String[])
+function _measure_inference_timings(init_commands, infilename, outfilename, flags = String[])
     println("Launching new julia process to run commands...")
     # addprocs will run the unmodified version of julia, so we
     # launch it as a command.
@@ -432,25 +440,35 @@ function _measure_inference_timings(infilename, outfilename, flags = String[])
             """
     process = open(`$(Base.julia_cmd()) $flags --eval $code_object`, stdout, write=true)
     serialize(process, quote
-        let tree = deserialize($infilename)
-            try
-                out_times = Dict{typeof(root), Float64}()
-                function time_all_nodes(root, out_times::Dict)
-                    for n in root.children
-                        time_all_nodes(n, out_times)
-                    end
-                    time_type_inference(root.key, out_times)
-                end
-                function time_type_inference(tt::Type, out_times::Dict)
-                    _, time = @timed code_typed(tt)
-                    out_times[tt] = time
-                end
+        let
+            # First, run user-defined commands to load the namespace
+            Core.eval(Main, $(QuoteNode(init_commands)))
+
+            # Load the serialized results
+            tree = deserialize($infilename)
 
-                time_all_nodes(tree, out_times)
-                serialize($outfilename, out_times)
-            finally
-                close(io)
+            # warm up type inference machinery:
+            let
+                foo(x,y) = (x,y)
+                _ = code_typed(Tuple{foo, Int,Int})
             end
+
+
+            # Then, run the timings
+            function time_all_nodes(root, out_times::Dict)
+                for n in root.children
+                    time_all_nodes(n, out_times)
+                end
+                time_type_inference(root.key, out_times)
+            end
+            function time_type_inference(tt::Type, out_times::Dict)
+                _, time = @timed code_typed(tt)
+                out_times[tt] = time
+            end
+
+            out_times = Dict{Any, Float64}()
+            time_all_nodes(tree, out_times)
+            serialize($outfilename, out_times)
         end
         exit()
     end)

From bb8324368ad5a1bfdb0d15aaeab1fdbbc5bafebf Mon Sep 17 00:00:00 2001
From: Nathan Daly <nhdaly@gmail.com>
Date: Mon, 14 Sep 2020 18:13:31 -0400
Subject: [PATCH 06/49] Fix now that i've disabled my first attempt in julia

---
 SnoopCompileCore/src/snoopi.jl | 20 ++++++++++----------
 src/parcel_snoopi.jl           | 16 +++++++++++-----
 2 files changed, 21 insertions(+), 15 deletions(-)

diff --git a/SnoopCompileCore/src/snoopi.jl b/SnoopCompileCore/src/snoopi.jl
index ac9ec33d9..5bd2c8682 100644
--- a/SnoopCompileCore/src/snoopi.jl
+++ b/SnoopCompileCore/src/snoopi.jl
@@ -1,20 +1,20 @@
 export @snoopi
 
 const __inf_timing__ = Tuple{Float64,MethodInstance}[]
-const __inf_callees__ = Dict{MethodInstance, Vector{MethodInstance}}()
+#const __inf_callees__ = Dict{MethodInstance, Vector{MethodInstance}}()
 const __inf_callee_edges4__ = Dict{MethodInstance, Vector{Any}}()
 
 if isdefined(Core.Compiler, :Params)
     function typeinf_ext_timed(linfo::Core.MethodInstance, params::Core.Compiler.Params)
         #Core.println("starting $linfo")
-        empty!(Core.Compiler.__inference_callees__)
+        #empty!(Core.Compiler.__inference_callees__)
         #empty!(Core.Compiler.__inference_callee_edges4__)
         push!(Core.Compiler.__inference_callee_edges4__, (linfo, Tuple{MethodInstance,MethodInstance}[]))
         tstart = time()
         ret = Core.Compiler.typeinf_ext(linfo, params)
         tstop = time()
         push!(__inf_timing__, (tstop-tstart, linfo))
-        __inf_callees__[linfo] = Core.Compiler.__inference_callees__
+        #__inf_callees__[linfo] = Core.Compiler.__inference_callees__
         @assert Core.Compiler.__inference_callee_edges4__[end][1] == linfo
         __inf_callee_edges4__[linfo] = pop!(Core.Compiler.__inference_callee_edges4__)[2]
         #Core.println("push: ", Core.Compiler.__inference_callee_edges4__)
@@ -22,13 +22,13 @@ if isdefined(Core.Compiler, :Params)
     end
     function typeinf_ext_timed(linfo::Core.MethodInstance, world::UInt)
         #Core.println("starting $linfo")
-        empty!(Core.Compiler.__inference_callees__)
+        #empty!(Core.Compiler.__inference_callees__)
         push!(Core.Compiler.__inference_callee_edges4__, (linfo, Tuple{MethodInstance,MethodInstance}[]))
         tstart = time()
         ret = Core.Compiler.typeinf_ext(linfo, world)
         tstop = time()
         push!(__inf_timing__, (tstop-tstart, linfo))
-        __inf_callees__[linfo] = Core.Compiler.__inference_callees__
+        #__inf_callees__[linfo] = Core.Compiler.__inference_callees__
         @assert Core.Compiler.__inference_callee_edges4__[end][1] == linfo
         __inf_callee_edges4__[linfo] = pop!(Core.Compiler.__inference_callee_edges4__)[2]
         #Core.println("push: ", Core.Compiler.__inference_callee_edges4__)
@@ -41,13 +41,13 @@ if isdefined(Core.Compiler, :Params)
 else
     function typeinf_ext_timed(interp::Core.Compiler.AbstractInterpreter, linfo::Core.MethodInstance)
         #Core.println("starting $linfo")
-        empty!(Core.Compiler.__inference_callees__)
+        #empty!(Core.Compiler.__inference_callees__)
         push!(Core.Compiler.__inference_callee_edges4__, (linfo, Tuple{MethodInstance,MethodInstance}[]))
         tstart = time()
         ret = Core.Compiler.typeinf_ext_toplevel(interp, linfo)
         tstop = time()
         push!(__inf_timing__, (tstop-tstart, linfo))
-        __inf_callees__[linfo] = Core.Compiler.__inference_callees__
+        #__inf_callees__[linfo] = Core.Compiler.__inference_callees__
         @assert Core.Compiler.__inference_callee_edges4__[end][1] == linfo
         __inf_callee_edges4__[linfo] = pop!(Core.Compiler.__inference_callee_edges4__)[2]
         #Core.println("push: ", Core.Compiler.__inference_callee_edges4__)
@@ -55,13 +55,13 @@ else
     end
     function typeinf_ext_timed(linfo::Core.MethodInstance, world::UInt)
         #Core.println("starting $linfo")
-        empty!(Core.Compiler.__inference_callees__)
+        #empty!(Core.Compiler.__inference_callees__)
         push!(Core.Compiler.__inference_callee_edges4__, (linfo, Tuple{MethodInstance,MethodInstance}[]))
         tstart = time()
         ret = Core.Compiler.typeinf_ext_toplevel(linfo, world)
         tstop = time()
         push!(__inf_timing__, (tstop-tstart, linfo))
-        __inf_callees__[linfo] = Core.Compiler.__inference_callees__
+        #__inf_callees__[linfo] = Core.Compiler.__inference_callees__
         @assert Core.Compiler.__inference_callee_edges4__[end][1] == linfo
         __inf_callee_edges4__[linfo] = pop!(Core.Compiler.__inference_callee_edges4__)[2]
         #Core.println("push: ", Core.Compiler.__inference_callee_edges4__)
@@ -128,7 +128,7 @@ end
 function _snoopi(cmd::Expr, tmin = 0.0)
     return quote
         empty!(__inf_timing__)
-        empty!(__inf_callees__)
+        #empty!(__inf_callees__)
         empty!(__inf_callee_edges4__)
         start_timing()
         try
diff --git a/src/parcel_snoopi.jl b/src/parcel_snoopi.jl
index 1571a7a1f..881d5af5e 100644
--- a/src/parcel_snoopi.jl
+++ b/src/parcel_snoopi.jl
@@ -388,17 +388,23 @@ const default_exclusions = Set([
 
 function collect_per_method_inference_timings(snoopi_results::Vector, init_commands)
     outd = Dict{Any, Float64}()
-    for (total_time, root, mi_dep_graph) = snoopi_results
-        tt_deps = [a.specTypes => b.specTypes for (a,b) in mi_dep_graph]
+    for snoopi_row in snoopi_results
+        timings = collect_per_method_inference_timings(snoopi_row, init_commands)
 
-        timings = per_method_instance_timings(init_commands, root.specTypes, tt_deps)
-        @info "$root:\ttotal: $total_time\t: $(sum(values(timings)))"
+        (total_time, root, mi_dep_graph) = snoopi_row
+        @info "$root:\ttotal: $total_time\tsum:$(sum(values(timings)))"
         display(timings)
         merge!(outd, timings)
     end
     @info "Returning merged results:"
     outd
 end
+function collect_per_method_inference_timings(snoopi_row, init_commands)
+    (total_time, root, mi_dep_graph) = snoopi_row
+    tt_deps = [a.specTypes => b.specTypes for (a,b) in mi_dep_graph]
+
+    return per_method_instance_timings(init_commands, root.specTypes, tt_deps)
+end
 
 #struct Node{T}
 #    key::T
@@ -409,7 +415,7 @@ end
 Node(root) = (; key=root, children=Any[])
 function per_method_instance_timings(init_commands, root, deps)
     tree = Node(root)
-    nodes = Dict(root => tree)
+    nodes = Dict{Any,Any}(root => tree)
     for (k,v) in deps
         knode = get!(nodes, k, Node(k))
         vnode = get!(nodes, v, Node(v))

From faa3eb8bf1ba31a8be4418e60fa4e93f0386ffe9 Mon Sep 17 00:00:00 2001
From: Nathan Daly <nhdaly@gmail.com>
Date: Tue, 15 Sep 2020 02:27:11 -0400
Subject: [PATCH 07/49] Got per-method timing working on helper process! :)

Now working through some more isssues, like not missing edges and
deduplicating edges and nodes.
---
 src/parcel_snoopi.jl | 78 ++++++++++++++++++++++++++++++++++----------
 1 file changed, 60 insertions(+), 18 deletions(-)

diff --git a/src/parcel_snoopi.jl b/src/parcel_snoopi.jl
index 881d5af5e..be18ba74e 100644
--- a/src/parcel_snoopi.jl
+++ b/src/parcel_snoopi.jl
@@ -392,7 +392,7 @@ function collect_per_method_inference_timings(snoopi_results::Vector, init_comma
         timings = collect_per_method_inference_timings(snoopi_row, init_commands)
 
         (total_time, root, mi_dep_graph) = snoopi_row
-        @info "$root:\ttotal: $total_time\tsum:$(sum(values(timings)))"
+        @info "Total snoopi: $total_time\tSum all elements:$(sum(values(timings)))"
         display(timings)
         merge!(outd, timings)
     end
@@ -412,23 +412,55 @@ end
 #    Node(key::T) where T = new{T}(key, Node{T}[])
 #    Node{T}(key::T) where T = new{T}(key, Node{T}[])
 #end
-Node(root) = (; key=root, children=Any[])
-function per_method_instance_timings(init_commands, root, deps)
-    tree = Node(root)
-    nodes = Dict{Any,Any}(root => tree)
-    for (k,v) in deps
-        knode = get!(nodes, k, Node(k))
-        vnode = get!(nodes, v, Node(v))
-        push!(knode.children, vnode)
+Node(root) = (; key=root, parents=Any[])
+function per_method_instance_timings(init_commands, root, edges)
+    #NT = fieldtype(eltype(edges)::Type{<:Union{Pair,Tuple}}, 1)
+    NT = Any
+
+    # 😮 It appears that currently edges can have a lot of duplicates!
+    # Both exact duplicate edges, as well as multiple paths to the same node!
+    # We only want to time each node once, so we have to do some cleanup.
+
+    # First, let's deduplicate identical edges.
+    edges = unique(edges)
+    uniq_edges = edges
+
+    # Next, since we only care about the bottom-up paths through the tree, we'll build a
+    # tree with only parent edges, and collect all the leaves. We'll later traverse the
+    # tree bottom up starting from the leaves, and use a seen-Set to skip duplicates and
+    # time each node exactly once.
+
+    meth_instances = unique(Iterators.flatten(edges))
+
+    # Start with all nodes as leaves
+    leaves = Set(meth_instances)
+    delete!(leaves, root)
+
+    #nodes = Dict{NT,Any}(m => Node(m) for m in meth_instances)
+
+    # Build the tree by adding elements from the edges, and when we see a node as a caller,
+    # we remove it from leaves.
+    # Dict points from elements to their parents.
+    reverse_graph_dict = Dict{NT,Vector{NT}}(root=>NT[])  # The root has no parents.
+    for (k,v) in uniq_edges
+        if k in leaves
+            delete!(leaves, k)
+        end
+        #knode = nodes[k]
+        #vnode = nodes[v]
+        #push!(vnode.parents, knode)
+        push!(get!(reverse_graph_dict, v, NT[]), k)
     end
-    tree
+
+    @info "Root: $root"
+    @info "Collecting timings for $(length(meth_instances)) MethodInstances, with $(length(uniq_edges)) edges."
 
     # Now start timing how long it takes to compile each of them starting from the bottom
     # working the way up.
     # Do this timing measurement in a different process so that the functions will be
     # compiled fresh.
     tree_f, timings_f = tempname(), tempname()
-    serialize(tree_f, tree)
+    serialize(tree_f, (leaves, reverse_graph_dict))
     _measure_inference_timings(init_commands, tree_f, timings_f)
     return deserialize(timings_f)
 end
@@ -451,7 +483,7 @@ function _measure_inference_timings(init_commands, infilename, outfilename, flag
             Core.eval(Main, $(QuoteNode(init_commands)))
 
             # Load the serialized results
-            tree = deserialize($infilename)
+            (leaves, reverse_graph_dict) = deserialize($infilename)
 
             # warm up type inference machinery:
             let
@@ -461,19 +493,29 @@ function _measure_inference_timings(init_commands, infilename, outfilename, flag
 
 
             # Then, run the timings
-            function time_all_nodes(root, out_times::Dict)
-                for n in root.children
-                    time_all_nodes(n, out_times)
+            function time_all_nodes(node::Type, graph::Dict, seen::Set, out_times::Dict)
+                if node in seen
+                    return
+                end
+                push!(seen, node)
+                time_type_inference(node, out_times)
+                # TODO(PR): Switch to breadth-first search instead of function calls to avoid
+                # stackoverflow (also b/c this is doing depth-first seaerch!)
+                for p in graph[node]
+                    time_all_nodes(p, graph, seen, out_times)
                 end
-                time_type_inference(root.key, out_times)
             end
             function time_type_inference(tt::Type, out_times::Dict)
-                _, time = @timed code_typed(tt)
+                _, time = @timed precompile(tt)
                 out_times[tt] = time
             end
 
             out_times = Dict{Any, Float64}()
-            time_all_nodes(tree, out_times)
+            seen = Set{Type}()
+
+            for leaf in leaves
+                time_all_nodes(leaf, reverse_graph_dict, seen, out_times)
+            end
             serialize($outfilename, out_times)
         end
         exit()

From 9e441cdf19c853f0d40f45f4012c312e1e8808bf Mon Sep 17 00:00:00 2001
From: Nathan Daly <nhdaly@gmail.com>
Date: Tue, 15 Sep 2020 14:48:01 -0400
Subject: [PATCH 08/49] Switch to BFS instead of (recursive) DFS

- for more accurate timings, and
- prevent stackoverflow
---
 src/parcel_snoopi.jl | 30 ++++++++++++++++--------------
 1 file changed, 16 insertions(+), 14 deletions(-)

diff --git a/src/parcel_snoopi.jl b/src/parcel_snoopi.jl
index be18ba74e..7fbef2745 100644
--- a/src/parcel_snoopi.jl
+++ b/src/parcel_snoopi.jl
@@ -493,29 +493,31 @@ function _measure_inference_timings(init_commands, infilename, outfilename, flag
 
 
             # Then, run the timings
-            function time_all_nodes(node::Type, graph::Dict, seen::Set, out_times::Dict)
-                if node in seen
-                    return
-                end
-                push!(seen, node)
-                time_type_inference(node, out_times)
-                # TODO(PR): Switch to breadth-first search instead of function calls to avoid
-                # stackoverflow (also b/c this is doing depth-first seaerch!)
-                for p in graph[node]
-                    time_all_nodes(p, graph, seen, out_times)
+            function time_all_nodes(leaves, graph::Dict, seen::Set, out_times::Dict)
+                # Breadth-first search over the nodes graph, only touching each element once
+                # Start by enqueing all leaves.
+                queue = copy(leaves)
+                while !isempty(queue)
+                    node = pop!(queue)
+                    if node in seen
+                        continue
+                    end
+                    push!(seen, node)
+                    time_type_inference(node, out_times)
+                    for p in graph[node]
+                        push!(queue, p)
+                    end
                 end
             end
             function time_type_inference(tt::Type, out_times::Dict)
-                _, time = @timed precompile(tt)
+                _, time = @timed code_typed(tt)
                 out_times[tt] = time
             end
 
             out_times = Dict{Any, Float64}()
             seen = Set{Type}()
 
-            for leaf in leaves
-                time_all_nodes(leaf, reverse_graph_dict, seen, out_times)
-            end
+            time_all_nodes(leaves, reverse_graph_dict, seen, out_times)
             serialize($outfilename, out_times)
         end
         exit()

From 4cad634288ccbecae0fc3eee35aba0d5e1870c1f Mon Sep 17 00:00:00 2001
From: Nathan Daly <nhdaly@gmail.com>
Date: Wed, 16 Sep 2020 16:18:44 -0400
Subject: [PATCH 09/49] =?UTF-8?q?Fix=20`code=5Ftyped()`=20to=20`code=5Ftyp?=
 =?UTF-8?q?ed=5Fby=5Ftype(tt)`=20to=20ACTUALLY=20measure=20inference=20tim?=
 =?UTF-8?q?es=20=F0=9F=98=85?=
MIME-Version: 1.0
Content-Type: text/plain; charset=UTF-8
Content-Transfer-Encoding: 8bit

---
 src/parcel_snoopi.jl | 3 ++-
 1 file changed, 2 insertions(+), 1 deletion(-)

diff --git a/src/parcel_snoopi.jl b/src/parcel_snoopi.jl
index 7fbef2745..a921a97ec 100644
--- a/src/parcel_snoopi.jl
+++ b/src/parcel_snoopi.jl
@@ -510,7 +510,8 @@ function _measure_inference_timings(init_commands, infilename, outfilename, flag
                 end
             end
             function time_type_inference(tt::Type, out_times::Dict)
-                _, time = @timed code_typed(tt)
+                # TODO: Check how new code_typed_by_type() is, will this work in 1.5?
+                _, time = @timed Base.code_typed_by_type(tt)
                 out_times[tt] = time
             end
 

From 6a62f749b5ad3466fc80e2c4f4880a4de238ba4d Mon Sep 17 00:00:00 2001
From: Nathan Daly <nhdaly@gmail.com>
Date: Wed, 16 Sep 2020 16:21:41 -0400
Subject: [PATCH 10/49] Try randomly shuffling the leaves to get a (hopefully)
 different walk of the graph each time?

---
 src/parcel_snoopi.jl | 3 ++-
 1 file changed, 2 insertions(+), 1 deletion(-)

diff --git a/src/parcel_snoopi.jl b/src/parcel_snoopi.jl
index a921a97ec..13e31cdf3 100644
--- a/src/parcel_snoopi.jl
+++ b/src/parcel_snoopi.jl
@@ -472,6 +472,7 @@ function _measure_inference_timings(init_commands, infilename, outfilename, flag
     # launch it as a command.
     code_object = """
             using Serialization
+            import Random
             while !eof(stdin)
                 Core.eval(Main, deserialize(stdin))
             end
@@ -496,7 +497,7 @@ function _measure_inference_timings(init_commands, infilename, outfilename, flag
             function time_all_nodes(leaves, graph::Dict, seen::Set, out_times::Dict)
                 # Breadth-first search over the nodes graph, only touching each element once
                 # Start by enqueing all leaves.
-                queue = copy(leaves)
+                queue = Random.shuffle(copy(leaves))
                 while !isempty(queue)
                     node = pop!(queue)
                     if node in seen

From 4820a24ebc1dcdaf7b4893700ca228ada4860f3e Mon Sep 17 00:00:00 2001
From: Nathan Daly <nhdaly@gmail.com>
Date: Thu, 17 Sep 2020 10:56:48 -0400
Subject: [PATCH 11/49] Second attempt at per-method inf timings: TimerOutputs

Based on c2640ae / https://github.com/JuliaLang/julia/compare/master...NHDaly:nhd-snoopi-inferrable-set--TimerOutputs-profile
---
 SnoopCompileCore/Project.toml  |  1 +
 SnoopCompileCore/src/snoopi.jl | 40 ++++++++++++++++++++++++++++------
 2 files changed, 34 insertions(+), 7 deletions(-)

diff --git a/SnoopCompileCore/Project.toml b/SnoopCompileCore/Project.toml
index 8b460ddd4..272ad0228 100644
--- a/SnoopCompileCore/Project.toml
+++ b/SnoopCompileCore/Project.toml
@@ -5,6 +5,7 @@ version = "2.1.1"
 
 [deps]
 Serialization = "9e88b42a-f829-5b0c-bbe9-9e923198166b"
+TimerOutputs = "a759f4b9-e2f1-59dc-863e-4aeb61b1ea8f"
 
 [compat]
 julia = "1"
diff --git a/SnoopCompileCore/src/snoopi.jl b/SnoopCompileCore/src/snoopi.jl
index 5bd2c8682..4779f92c0 100644
--- a/SnoopCompileCore/src/snoopi.jl
+++ b/SnoopCompileCore/src/snoopi.jl
@@ -36,7 +36,9 @@ if isdefined(Core.Compiler, :Params)
     end
     @noinline function stop_timing()
         ccall(:jl_set_typeinf_func, Cvoid, (Any,), Core.Compiler.typeinf_ext)
-        Core.Compiler.__collect_inference_callees__[] = false
+        #ccall(:jl_set_typeinf_inner_func, Cvoid, (Any,), Core.Compiler.typeinf)
+        Core.Compiler._set_typeinf_func(Core.Compiler._typeinf)
+        #Core.Compiler.__collect_inference_callees__[] = false
     end
 else
     function typeinf_ext_timed(interp::Core.Compiler.AbstractInterpreter, linfo::Core.MethodInstance)
@@ -69,13 +71,35 @@ else
     end
     @noinline function stop_timing()
         ccall(:jl_set_typeinf_func, Cvoid, (Any,), Core.Compiler.typeinf_ext_toplevel)
-        Core.Compiler.__collect_inference_callees__[] = false
+        #ccall(:jl_set_typeinf_inner_func, Cvoid, (Any,), Core.Compiler.typeinf)
+        Core.Compiler._set_typeinf_func(Core.Compiler._typeinf)
+        #Core.Compiler.__collect_inference_callees__[] = false
     end
 end
 
 @noinline function start_timing()
-    ccall(:jl_set_typeinf_func, Cvoid, (Any,), typeinf_ext_timed)
-    Core.Compiler.__collect_inference_callees__[] = true
+    ccall(:jl_set_typeinf_func, Cvoid, (Any,), typeinf_ext_timed2)
+    #ccall(:jl_set_typeinf_inner_func, Cvoid, (Any,), typeinf_timed)
+    Core.Compiler._set_typeinf_func(typeinf_timed)
+    #Core.Compiler.__collect_inference_callees__[] = true
+end
+
+import TimerOutputs
+const _to_ = TimerOutputs.TimerOutput()
+function typeinf_timed(interp::Core.Compiler.AbstractInterpreter, frame::Core.Compiler.InferenceState)
+    TimerOutputs.@timeit _to_ string(frame.linfo) begin
+        Core.Compiler._typeinf(interp, frame)
+    end
+end
+function typeinf_ext_timed2(interp::Core.Compiler.AbstractInterpreter, linfo::Core.MethodInstance)
+    TimerOutputs.@timeit _to_ string(linfo) begin
+        return Core.Compiler.typeinf_ext_toplevel(interp, linfo)
+    end
+end
+function typeinf_ext_timed2(linfo::Core.MethodInstance, world::UInt)
+    TimerOutputs.@timeit _to_ string(linfo) begin
+        Core.Compiler.typeinf_ext_toplevel(linfo, world)
+    end
 end
 
 function sort_timed_inf(tmin)
@@ -127,16 +151,18 @@ end
 
 function _snoopi(cmd::Expr, tmin = 0.0)
     return quote
-        empty!(__inf_timing__)
+        #empty!(__inf_timing__)
         #empty!(__inf_callees__)
-        empty!(__inf_callee_edges4__)
+        #empty!(__inf_callee_edges4__)
+        TimerOutputs.reset_timer!(_to_)
         start_timing()
         try
             $(esc(cmd))
         finally
             stop_timing()
         end
-        $sort_timed_inf($tmin)
+        #$sort_timed_inf($tmin)
+        return deepcopy(_to_)
     end
 end
 

From 21bae6d88df5919fb77eeba5e06a1afba9fa791d Mon Sep 17 00:00:00 2001
From: Nathan Daly <nhdaly@gmail.com>
Date: Thu, 17 Sep 2020 11:20:55 -0400
Subject: [PATCH 12/49] (silly) fixups to get the linfos to print to a string

---
 SnoopCompileCore/src/snoopi.jl | 67 ++++++++++++++++++++++++++++++++--
 1 file changed, 63 insertions(+), 4 deletions(-)

diff --git a/SnoopCompileCore/src/snoopi.jl b/SnoopCompileCore/src/snoopi.jl
index 4779f92c0..c2808ea53 100644
--- a/SnoopCompileCore/src/snoopi.jl
+++ b/SnoopCompileCore/src/snoopi.jl
@@ -84,20 +84,79 @@ end
     #Core.Compiler.__collect_inference_callees__[] = true
 end
 
+# TODO(PR): This should not be needed...
+# Figure out why this was failing:
+#=
+Internal error: encountered unexpected error in runtime:
+ErrorException("type TypeVar has no field var")
+jl_errorf at /Users/nathandaly/src/julia/src/rtutils.c:77
+jl_field_index at /Users/nathandaly/src/julia/src/datatype.c:1005
+jl_f_getfield at /Users/nathandaly/src/julia/src/builtins.c:785
+getproperty at ./Base.jl:33
+show at ./show.jl:789
+unknown function (ip: 0x14b9f4048)
+show_datatype at ./show.jl:864
+show at ./show.jl:763
+unknown function (ip: 0x14b9f4048)
+show at ./show.jl:789
+print at ./strings/io.jl:35
+print_to_string at ./strings/io.jl:135
+string at ./strings/io.jl:174
+macro expansion at /Users/nathandaly/.julia/packages/TimerOutputs/dVnaw/src/TimerOutput.jl:185 [inlined]
+typeinf_timed at /Users/nathandaly/.julia/dev/SnoopCompile/SnoopCompileCore/src/snoopi.jl:90
+unknown function (ip: 0x10f21add8)
+jl_apply at /Users/nathandaly/src/julia/src/./julia.h:1752 [inlined]
+do_apply at /Users/nathandaly/src/julia/src/builtins.c:655
+jl_f__apply at /Users/nathandaly/src/julia/src/builtins.c:669 [inlined]
+jl_f__apply_latest at /Users/nathandaly/src/julia/src/builtins.c:705
+typeinf at ./compiler/typeinfer.jl:18 [inlined]
+typeinf_edge at ./compiler/typeinfer.jl:597
+=#
+function str_linfo(linfo::Core.MethodInstance)
+    try
+        string(linfo)
+    catch
+        try
+            string(linfo.specTypes)
+        catch
+            string(fieldtype(linfo.specTypes, 1))
+        end
+    end
+end
+function str_linfo(linfo)
+    @info typeof(linfo)
+    try
+        string(linfo)
+    catch
+        try
+            string(linfo.specTypes)
+        catch
+            string(fieldtype(linfo.specTypes, 1))
+        end
+    end
+end
+
+
 import TimerOutputs
 const _to_ = TimerOutputs.TimerOutput()
 function typeinf_timed(interp::Core.Compiler.AbstractInterpreter, frame::Core.Compiler.InferenceState)
-    TimerOutputs.@timeit _to_ string(frame.linfo) begin
-        Core.Compiler._typeinf(interp, frame)
+    try
+        TimerOutputs.@timeit _to_ str_linfo(frame.linfo) begin
+            Core.Compiler._typeinf(interp, frame)
+        end
+    catch
+        @info typeof(frame.linfo)
+        @info typeof(frame.linfo.specTypes)
+        rethrow()
     end
 end
 function typeinf_ext_timed2(interp::Core.Compiler.AbstractInterpreter, linfo::Core.MethodInstance)
-    TimerOutputs.@timeit _to_ string(linfo) begin
+    TimerOutputs.@timeit _to_ str_linfo(linfo) begin
         return Core.Compiler.typeinf_ext_toplevel(interp, linfo)
     end
 end
 function typeinf_ext_timed2(linfo::Core.MethodInstance, world::UInt)
-    TimerOutputs.@timeit _to_ string(linfo) begin
+    TimerOutputs.@timeit _to_ str_linfo(linfo) begin
         Core.Compiler.typeinf_ext_toplevel(linfo, world)
     end
 end

From bc20040d222aa6bf3e8aace27b17587dc38447bd Mon Sep 17 00:00:00 2001
From: Nathan Daly <nhdaly@gmail.com>
Date: Mon, 21 Sep 2020 15:30:05 -0400
Subject: [PATCH 13/49] Fix double-counting, using "$linfo" for timer name

---
 SnoopCompileCore/src/snoopi.jl | 31 +++++++------------------------
 1 file changed, 7 insertions(+), 24 deletions(-)

diff --git a/SnoopCompileCore/src/snoopi.jl b/SnoopCompileCore/src/snoopi.jl
index c2808ea53..fb8ad6e32 100644
--- a/SnoopCompileCore/src/snoopi.jl
+++ b/SnoopCompileCore/src/snoopi.jl
@@ -114,28 +114,11 @@ typeinf_edge at ./compiler/typeinfer.jl:597
 =#
 function str_linfo(linfo::Core.MethodInstance)
     try
-        string(linfo)
+        string(linfo.specTypes)
     catch
-        try
-            string(linfo.specTypes)
-        catch
-            string(fieldtype(linfo.specTypes, 1))
-        end
+        string(fieldtype(linfo.specTypes, 1))
     end
 end
-function str_linfo(linfo)
-    @info typeof(linfo)
-    try
-        string(linfo)
-    catch
-        try
-            string(linfo.specTypes)
-        catch
-            string(fieldtype(linfo.specTypes, 1))
-        end
-    end
-end
-
 
 import TimerOutputs
 const _to_ = TimerOutputs.TimerOutput()
@@ -151,14 +134,14 @@ function typeinf_timed(interp::Core.Compiler.AbstractInterpreter, frame::Core.Co
     end
 end
 function typeinf_ext_timed2(interp::Core.Compiler.AbstractInterpreter, linfo::Core.MethodInstance)
-    TimerOutputs.@timeit _to_ str_linfo(linfo) begin
+    #TimerOutputs.@timeit _to_ str_linfo(linfo) begin
         return Core.Compiler.typeinf_ext_toplevel(interp, linfo)
-    end
+    #end
 end
 function typeinf_ext_timed2(linfo::Core.MethodInstance, world::UInt)
-    TimerOutputs.@timeit _to_ str_linfo(linfo) begin
+    #TimerOutputs.@timeit _to_ str_linfo(linfo) begin
         Core.Compiler.typeinf_ext_toplevel(linfo, world)
-    end
+    #end
 end
 
 function sort_timed_inf(tmin)
@@ -221,7 +204,7 @@ function _snoopi(cmd::Expr, tmin = 0.0)
             stop_timing()
         end
         #$sort_timed_inf($tmin)
-        return deepcopy(_to_)
+        deepcopy(_to_)
     end
 end
 

From b290ec4e411f71466f334ef07d3d391b2200ee7f Mon Sep 17 00:00:00 2001
From: Nathan Daly <nhdaly@gmail.com>
Date: Mon, 21 Sep 2020 16:28:01 -0400
Subject: [PATCH 14/49] Start precompiling the TimerOutputs snoopi approach

---
 SnoopCompileCore/src/snoopi.jl | 24 +++++++++++++-----------
 1 file changed, 13 insertions(+), 11 deletions(-)

diff --git a/SnoopCompileCore/src/snoopi.jl b/SnoopCompileCore/src/snoopi.jl
index fb8ad6e32..e1065cc77 100644
--- a/SnoopCompileCore/src/snoopi.jl
+++ b/SnoopCompileCore/src/snoopi.jl
@@ -35,7 +35,7 @@ if isdefined(Core.Compiler, :Params)
         return ret
     end
     @noinline function stop_timing()
-        ccall(:jl_set_typeinf_func, Cvoid, (Any,), Core.Compiler.typeinf_ext)
+        #ccall(:jl_set_typeinf_func, Cvoid, (Any,), Core.Compiler.typeinf_ext)
         #ccall(:jl_set_typeinf_inner_func, Cvoid, (Any,), Core.Compiler.typeinf)
         Core.Compiler._set_typeinf_func(Core.Compiler._typeinf)
         #Core.Compiler.__collect_inference_callees__[] = false
@@ -70,7 +70,7 @@ else
         return ret
     end
     @noinline function stop_timing()
-        ccall(:jl_set_typeinf_func, Cvoid, (Any,), Core.Compiler.typeinf_ext_toplevel)
+        #ccall(:jl_set_typeinf_func, Cvoid, (Any,), Core.Compiler.typeinf_ext_toplevel)
         #ccall(:jl_set_typeinf_inner_func, Cvoid, (Any,), Core.Compiler.typeinf)
         Core.Compiler._set_typeinf_func(Core.Compiler._typeinf)
         #Core.Compiler.__collect_inference_callees__[] = false
@@ -78,7 +78,7 @@ else
 end
 
 @noinline function start_timing()
-    ccall(:jl_set_typeinf_func, Cvoid, (Any,), typeinf_ext_timed2)
+    #ccall(:jl_set_typeinf_func, Cvoid, (Any,), typeinf_ext_timed2)
     #ccall(:jl_set_typeinf_inner_func, Cvoid, (Any,), typeinf_timed)
     Core.Compiler._set_typeinf_func(typeinf_timed)
     #Core.Compiler.__collect_inference_callees__[] = true
@@ -123,14 +123,8 @@ end
 import TimerOutputs
 const _to_ = TimerOutputs.TimerOutput()
 function typeinf_timed(interp::Core.Compiler.AbstractInterpreter, frame::Core.Compiler.InferenceState)
-    try
-        TimerOutputs.@timeit _to_ str_linfo(frame.linfo) begin
-            Core.Compiler._typeinf(interp, frame)
-        end
-    catch
-        @info typeof(frame.linfo)
-        @info typeof(frame.linfo.specTypes)
-        rethrow()
+    TimerOutputs.@timeit _to_ str_linfo(frame.linfo) begin
+        Core.Compiler._typeinf(interp, frame)
     end
 end
 function typeinf_ext_timed2(interp::Core.Compiler.AbstractInterpreter, linfo::Core.MethodInstance)
@@ -221,5 +215,13 @@ function __init__()
     end
     precompile(start_timing, ())
     precompile(stop_timing, ())
+
+    # Precompile TimerOutputs approach
+    @assert precompile(typeinf_timed, (Core.Compiler.NativeInterpreter, Core.Compiler.InferenceState))
+    @assert precompile(str_linfo, (Core.MethodInstance,))
+
+    @assert precompile(getindex, (Type{TimerOutputs.TimerOutput},))
+    @assert precompile(TimerOutputs.TimerOutput, (String,))
+
     nothing
 end

From d77e22d7bcc71ce15f1ad1fae389c645871e0704 Mon Sep 17 00:00:00 2001
From: Nathan Daly <nhdaly@gmail.com>
Date: Fri, 25 Sep 2020 13:08:18 -0400
Subject: [PATCH 15/49] Revert changes to SnoopCompile snoopi

---
 SnoopCompileCore/Project.toml  |   1 -
 SnoopCompileCore/src/snoopi.jl | 136 ++----------------------------
 src/parcel_snoopi.jl           | 148 ---------------------------------
 3 files changed, 6 insertions(+), 279 deletions(-)

diff --git a/SnoopCompileCore/Project.toml b/SnoopCompileCore/Project.toml
index 272ad0228..8b460ddd4 100644
--- a/SnoopCompileCore/Project.toml
+++ b/SnoopCompileCore/Project.toml
@@ -5,7 +5,6 @@ version = "2.1.1"
 
 [deps]
 Serialization = "9e88b42a-f829-5b0c-bbe9-9e923198166b"
-TimerOutputs = "a759f4b9-e2f1-59dc-863e-4aeb61b1ea8f"
 
 [compat]
 julia = "1"
diff --git a/SnoopCompileCore/src/snoopi.jl b/SnoopCompileCore/src/snoopi.jl
index e1065cc77..e3700422c 100644
--- a/SnoopCompileCore/src/snoopi.jl
+++ b/SnoopCompileCore/src/snoopi.jl
@@ -1,161 +1,49 @@
 export @snoopi
 
 const __inf_timing__ = Tuple{Float64,MethodInstance}[]
-#const __inf_callees__ = Dict{MethodInstance, Vector{MethodInstance}}()
-const __inf_callee_edges4__ = Dict{MethodInstance, Vector{Any}}()
 
 if isdefined(Core.Compiler, :Params)
     function typeinf_ext_timed(linfo::Core.MethodInstance, params::Core.Compiler.Params)
-        #Core.println("starting $linfo")
-        #empty!(Core.Compiler.__inference_callees__)
-        #empty!(Core.Compiler.__inference_callee_edges4__)
-        push!(Core.Compiler.__inference_callee_edges4__, (linfo, Tuple{MethodInstance,MethodInstance}[]))
         tstart = time()
         ret = Core.Compiler.typeinf_ext(linfo, params)
         tstop = time()
         push!(__inf_timing__, (tstop-tstart, linfo))
-        #__inf_callees__[linfo] = Core.Compiler.__inference_callees__
-        @assert Core.Compiler.__inference_callee_edges4__[end][1] == linfo
-        __inf_callee_edges4__[linfo] = pop!(Core.Compiler.__inference_callee_edges4__)[2]
-        #Core.println("push: ", Core.Compiler.__inference_callee_edges4__)
         return ret
     end
     function typeinf_ext_timed(linfo::Core.MethodInstance, world::UInt)
-        #Core.println("starting $linfo")
-        #empty!(Core.Compiler.__inference_callees__)
-        push!(Core.Compiler.__inference_callee_edges4__, (linfo, Tuple{MethodInstance,MethodInstance}[]))
         tstart = time()
         ret = Core.Compiler.typeinf_ext(linfo, world)
         tstop = time()
         push!(__inf_timing__, (tstop-tstart, linfo))
-        #__inf_callees__[linfo] = Core.Compiler.__inference_callees__
-        @assert Core.Compiler.__inference_callee_edges4__[end][1] == linfo
-        __inf_callee_edges4__[linfo] = pop!(Core.Compiler.__inference_callee_edges4__)[2]
-        #Core.println("push: ", Core.Compiler.__inference_callee_edges4__)
         return ret
     end
-    @noinline function stop_timing()
-        #ccall(:jl_set_typeinf_func, Cvoid, (Any,), Core.Compiler.typeinf_ext)
-        #ccall(:jl_set_typeinf_inner_func, Cvoid, (Any,), Core.Compiler.typeinf)
-        Core.Compiler._set_typeinf_func(Core.Compiler._typeinf)
-        #Core.Compiler.__collect_inference_callees__[] = false
-    end
+    @noinline stop_timing() = ccall(:jl_set_typeinf_func, Cvoid, (Any,), Core.Compiler.typeinf_ext)
 else
     function typeinf_ext_timed(interp::Core.Compiler.AbstractInterpreter, linfo::Core.MethodInstance)
-        #Core.println("starting $linfo")
-        #empty!(Core.Compiler.__inference_callees__)
-        push!(Core.Compiler.__inference_callee_edges4__, (linfo, Tuple{MethodInstance,MethodInstance}[]))
         tstart = time()
         ret = Core.Compiler.typeinf_ext_toplevel(interp, linfo)
         tstop = time()
         push!(__inf_timing__, (tstop-tstart, linfo))
-        #__inf_callees__[linfo] = Core.Compiler.__inference_callees__
-        @assert Core.Compiler.__inference_callee_edges4__[end][1] == linfo
-        __inf_callee_edges4__[linfo] = pop!(Core.Compiler.__inference_callee_edges4__)[2]
-        #Core.println("push: ", Core.Compiler.__inference_callee_edges4__)
         return ret
     end
     function typeinf_ext_timed(linfo::Core.MethodInstance, world::UInt)
-        #Core.println("starting $linfo")
-        #empty!(Core.Compiler.__inference_callees__)
-        push!(Core.Compiler.__inference_callee_edges4__, (linfo, Tuple{MethodInstance,MethodInstance}[]))
         tstart = time()
         ret = Core.Compiler.typeinf_ext_toplevel(linfo, world)
         tstop = time()
         push!(__inf_timing__, (tstop-tstart, linfo))
-        #__inf_callees__[linfo] = Core.Compiler.__inference_callees__
-        @assert Core.Compiler.__inference_callee_edges4__[end][1] == linfo
-        __inf_callee_edges4__[linfo] = pop!(Core.Compiler.__inference_callee_edges4__)[2]
-        #Core.println("push: ", Core.Compiler.__inference_callee_edges4__)
         return ret
     end
-    @noinline function stop_timing()
-        #ccall(:jl_set_typeinf_func, Cvoid, (Any,), Core.Compiler.typeinf_ext_toplevel)
-        #ccall(:jl_set_typeinf_inner_func, Cvoid, (Any,), Core.Compiler.typeinf)
-        Core.Compiler._set_typeinf_func(Core.Compiler._typeinf)
-        #Core.Compiler.__collect_inference_callees__[] = false
-    end
-end
-
-@noinline function start_timing()
-    #ccall(:jl_set_typeinf_func, Cvoid, (Any,), typeinf_ext_timed2)
-    #ccall(:jl_set_typeinf_inner_func, Cvoid, (Any,), typeinf_timed)
-    Core.Compiler._set_typeinf_func(typeinf_timed)
-    #Core.Compiler.__collect_inference_callees__[] = true
-end
-
-# TODO(PR): This should not be needed...
-# Figure out why this was failing:
-#=
-Internal error: encountered unexpected error in runtime:
-ErrorException("type TypeVar has no field var")
-jl_errorf at /Users/nathandaly/src/julia/src/rtutils.c:77
-jl_field_index at /Users/nathandaly/src/julia/src/datatype.c:1005
-jl_f_getfield at /Users/nathandaly/src/julia/src/builtins.c:785
-getproperty at ./Base.jl:33
-show at ./show.jl:789
-unknown function (ip: 0x14b9f4048)
-show_datatype at ./show.jl:864
-show at ./show.jl:763
-unknown function (ip: 0x14b9f4048)
-show at ./show.jl:789
-print at ./strings/io.jl:35
-print_to_string at ./strings/io.jl:135
-string at ./strings/io.jl:174
-macro expansion at /Users/nathandaly/.julia/packages/TimerOutputs/dVnaw/src/TimerOutput.jl:185 [inlined]
-typeinf_timed at /Users/nathandaly/.julia/dev/SnoopCompile/SnoopCompileCore/src/snoopi.jl:90
-unknown function (ip: 0x10f21add8)
-jl_apply at /Users/nathandaly/src/julia/src/./julia.h:1752 [inlined]
-do_apply at /Users/nathandaly/src/julia/src/builtins.c:655
-jl_f__apply at /Users/nathandaly/src/julia/src/builtins.c:669 [inlined]
-jl_f__apply_latest at /Users/nathandaly/src/julia/src/builtins.c:705
-typeinf at ./compiler/typeinfer.jl:18 [inlined]
-typeinf_edge at ./compiler/typeinfer.jl:597
-=#
-function str_linfo(linfo::Core.MethodInstance)
-    try
-        string(linfo.specTypes)
-    catch
-        string(fieldtype(linfo.specTypes, 1))
-    end
+    @noinline stop_timing() = ccall(:jl_set_typeinf_func, Cvoid, (Any,), Core.Compiler.typeinf_ext_toplevel)
 end
 
-import TimerOutputs
-const _to_ = TimerOutputs.TimerOutput()
-function typeinf_timed(interp::Core.Compiler.AbstractInterpreter, frame::Core.Compiler.InferenceState)
-    TimerOutputs.@timeit _to_ str_linfo(frame.linfo) begin
-        Core.Compiler._typeinf(interp, frame)
-    end
-end
-function typeinf_ext_timed2(interp::Core.Compiler.AbstractInterpreter, linfo::Core.MethodInstance)
-    #TimerOutputs.@timeit _to_ str_linfo(linfo) begin
-        return Core.Compiler.typeinf_ext_toplevel(interp, linfo)
-    #end
-end
-function typeinf_ext_timed2(linfo::Core.MethodInstance, world::UInt)
-    #TimerOutputs.@timeit _to_ str_linfo(linfo) begin
-        Core.Compiler.typeinf_ext_toplevel(linfo, world)
-    #end
-end
+@noinline start_timing() = ccall(:jl_set_typeinf_func, Cvoid, (Any,), typeinf_ext_timed)
 
 function sort_timed_inf(tmin)
     data = __inf_timing__
     if tmin > 0.0
         data = filter(tl->tl[1] >= tmin, data)
     end
-    data = sort(data; by=tl->tl[1])
-    #@show __inf_callee_edges4__
-    out = Tuple{Float64,MethodInstance,
-                #Vector{MethodInstance},
-                Vector{Pair{MethodInstance,MethodInstance}}}[
-        (tl[1], tl[2],
-            # Another (incorrect) view on all MethodInstances compiled during this inferable set
-            #__inf_callees__[tl[2]],
-            # The dependency graph of those compilations.
-            [a=>b for (a,b) in __inf_callee_edges4__[tl[2]]]
-        ) for (i,tl) in enumerate(data)
-    ]
-    return out
+    return sort(data; by=tl->tl[1])
 end
 
 """
@@ -187,18 +75,14 @@ end
 
 function _snoopi(cmd::Expr, tmin = 0.0)
     return quote
-        #empty!(__inf_timing__)
-        #empty!(__inf_callees__)
-        #empty!(__inf_callee_edges4__)
-        TimerOutputs.reset_timer!(_to_)
+        empty!(__inf_timing__)
         start_timing()
         try
             $(esc(cmd))
         finally
             stop_timing()
         end
-        #$sort_timed_inf($tmin)
-        deepcopy(_to_)
+        $sort_timed_inf($tmin)
     end
 end
 
@@ -215,13 +99,5 @@ function __init__()
     end
     precompile(start_timing, ())
     precompile(stop_timing, ())
-
-    # Precompile TimerOutputs approach
-    @assert precompile(typeinf_timed, (Core.Compiler.NativeInterpreter, Core.Compiler.InferenceState))
-    @assert precompile(str_linfo, (Core.MethodInstance,))
-
-    @assert precompile(getindex, (Type{TimerOutputs.TimerOutput},))
-    @assert precompile(TimerOutputs.TimerOutput, (String,))
-
     nothing
 end
diff --git a/src/parcel_snoopi.jl b/src/parcel_snoopi.jl
index 13e31cdf3..775e6f40d 100644
--- a/src/parcel_snoopi.jl
+++ b/src/parcel_snoopi.jl
@@ -1,7 +1,3 @@
-#using LightGraph
-#using AbstractTrees
-using Serialization
-
 function topmodule(mods)
     function ischild(c, mod)
         ok = false
@@ -384,147 +380,3 @@ end
 const default_exclusions = Set([
     r"\bMain\b",
 ])
-
-
-function collect_per_method_inference_timings(snoopi_results::Vector, init_commands)
-    outd = Dict{Any, Float64}()
-    for snoopi_row in snoopi_results
-        timings = collect_per_method_inference_timings(snoopi_row, init_commands)
-
-        (total_time, root, mi_dep_graph) = snoopi_row
-        @info "Total snoopi: $total_time\tSum all elements:$(sum(values(timings)))"
-        display(timings)
-        merge!(outd, timings)
-    end
-    @info "Returning merged results:"
-    outd
-end
-function collect_per_method_inference_timings(snoopi_row, init_commands)
-    (total_time, root, mi_dep_graph) = snoopi_row
-    tt_deps = [a.specTypes => b.specTypes for (a,b) in mi_dep_graph]
-
-    return per_method_instance_timings(init_commands, root.specTypes, tt_deps)
-end
-
-#struct Node{T}
-#    key::T
-#    children::Vector{Node{T}}
-#    Node(key::T) where T = new{T}(key, Node{T}[])
-#    Node{T}(key::T) where T = new{T}(key, Node{T}[])
-#end
-Node(root) = (; key=root, parents=Any[])
-function per_method_instance_timings(init_commands, root, edges)
-    #NT = fieldtype(eltype(edges)::Type{<:Union{Pair,Tuple}}, 1)
-    NT = Any
-
-    # 😮 It appears that currently edges can have a lot of duplicates!
-    # Both exact duplicate edges, as well as multiple paths to the same node!
-    # We only want to time each node once, so we have to do some cleanup.
-
-    # First, let's deduplicate identical edges.
-    edges = unique(edges)
-    uniq_edges = edges
-
-    # Next, since we only care about the bottom-up paths through the tree, we'll build a
-    # tree with only parent edges, and collect all the leaves. We'll later traverse the
-    # tree bottom up starting from the leaves, and use a seen-Set to skip duplicates and
-    # time each node exactly once.
-
-    meth_instances = unique(Iterators.flatten(edges))
-
-    # Start with all nodes as leaves
-    leaves = Set(meth_instances)
-    delete!(leaves, root)
-
-    #nodes = Dict{NT,Any}(m => Node(m) for m in meth_instances)
-
-    # Build the tree by adding elements from the edges, and when we see a node as a caller,
-    # we remove it from leaves.
-    # Dict points from elements to their parents.
-    reverse_graph_dict = Dict{NT,Vector{NT}}(root=>NT[])  # The root has no parents.
-    for (k,v) in uniq_edges
-        if k in leaves
-            delete!(leaves, k)
-        end
-        #knode = nodes[k]
-        #vnode = nodes[v]
-        #push!(vnode.parents, knode)
-        push!(get!(reverse_graph_dict, v, NT[]), k)
-    end
-
-    @info "Root: $root"
-    @info "Collecting timings for $(length(meth_instances)) MethodInstances, with $(length(uniq_edges)) edges."
-
-    # Now start timing how long it takes to compile each of them starting from the bottom
-    # working the way up.
-    # Do this timing measurement in a different process so that the functions will be
-    # compiled fresh.
-    tree_f, timings_f = tempname(), tempname()
-    serialize(tree_f, (leaves, reverse_graph_dict))
-    _measure_inference_timings(init_commands, tree_f, timings_f)
-    return deserialize(timings_f)
-end
-
-
-function _measure_inference_timings(init_commands, infilename, outfilename, flags = String[])
-    println("Launching new julia process to run commands...")
-    # addprocs will run the unmodified version of julia, so we
-    # launch it as a command.
-    code_object = """
-            using Serialization
-            import Random
-            while !eof(stdin)
-                Core.eval(Main, deserialize(stdin))
-            end
-            """
-    process = open(`$(Base.julia_cmd()) $flags --eval $code_object`, stdout, write=true)
-    serialize(process, quote
-        let
-            # First, run user-defined commands to load the namespace
-            Core.eval(Main, $(QuoteNode(init_commands)))
-
-            # Load the serialized results
-            (leaves, reverse_graph_dict) = deserialize($infilename)
-
-            # warm up type inference machinery:
-            let
-                foo(x,y) = (x,y)
-                _ = code_typed(Tuple{foo, Int,Int})
-            end
-
-
-            # Then, run the timings
-            function time_all_nodes(leaves, graph::Dict, seen::Set, out_times::Dict)
-                # Breadth-first search over the nodes graph, only touching each element once
-                # Start by enqueing all leaves.
-                queue = Random.shuffle(copy(leaves))
-                while !isempty(queue)
-                    node = pop!(queue)
-                    if node in seen
-                        continue
-                    end
-                    push!(seen, node)
-                    time_type_inference(node, out_times)
-                    for p in graph[node]
-                        push!(queue, p)
-                    end
-                end
-            end
-            function time_type_inference(tt::Type, out_times::Dict)
-                # TODO: Check how new code_typed_by_type() is, will this work in 1.5?
-                _, time = @timed Base.code_typed_by_type(tt)
-                out_times[tt] = time
-            end
-
-            out_times = Dict{Any, Float64}()
-            seen = Set{Type}()
-
-            time_all_nodes(leaves, reverse_graph_dict, seen, out_times)
-            serialize($outfilename, out_times)
-        end
-        exit()
-    end)
-    wait(process)
-    println("done.")
-    nothing
-end

From 5b8603aead18711fabf2bf4bf6b1f744a1907607 Mon Sep 17 00:00:00 2001
From: Nathan Daly <nhdaly@gmail.com>
Date: Fri, 25 Sep 2020 13:42:57 -0400
Subject: [PATCH 16/49] Rewrite snoopi on top of custom Core.Compiler.Timings

---
 SnoopCompileCore/src/snoopi.jl | 37 +++++++++++++++++++++++++++++++---
 1 file changed, 34 insertions(+), 3 deletions(-)

diff --git a/SnoopCompileCore/src/snoopi.jl b/SnoopCompileCore/src/snoopi.jl
index e3700422c..addfe41f1 100644
--- a/SnoopCompileCore/src/snoopi.jl
+++ b/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,10 @@ 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)
+        Core.Compiler.__toggle_measure_typeinf(false)
+    end
 else
     function typeinf_ext_timed(interp::Core.Compiler.AbstractInterpreter, linfo::Core.MethodInstance)
         tstart = time()
@@ -33,12 +37,20 @@ 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)
+        Core.Compiler.__toggle_measure_typeinf(false)
+    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)
+    Core.Compiler.__toggle_measure_typeinf(true)
+end
 
 function sort_timed_inf(tmin)
+    return copy(Core.Compiler.Timings._timings)
+
     data = __inf_timing__
     if tmin > 0.0
         data = filter(tl->tl[1] >= tmin, data)
@@ -46,6 +58,24 @@ function sort_timed_inf(tmin)
     return sort(data; by=tl->tl[1])
 end
 
+function exclusive_times(timings::Vector, tmin = 0)
+    out = Any[]
+    frontier = copy(timings)
+    while !isempty(frontier)
+        t = popfirst!(frontier)
+        children_time = sum([0, (c.time for c in t.children)...])
+        push!(out, Float64((t.time - children_time) / 1e9) => t.name)
+        for c in t.children
+            push!(frontier, c)
+        end
+    end
+    popfirst!(out) # Skip the root node
+    if tmin > 0.0
+        out = filter(tl->tl[1] >= tmin, out)
+    end
+    return sort(out; by=tl->tl[1])
+end
+
 """
     inf_timing = @snoopi commands
     inf_timing = @snoopi tmin=0.0 commands
@@ -76,6 +106,7 @@ end
 function _snoopi(cmd::Expr, tmin = 0.0)
     return quote
         empty!(__inf_timing__)
+        Core.Compiler.Timings.reset_timings()
         start_timing()
         try
             $(esc(cmd))

From 615b1b60cb69dd3b45035e1544496d746a306985 Mon Sep 17 00:00:00 2001
From: Nathan Daly <nhdaly@gmail.com>
Date: Fri, 25 Sep 2020 14:53:13 -0400
Subject: [PATCH 17/49] Add `exclusive_timings()` to compute and list the
 per-method-instance exclusive times! :)

---
 SnoopCompileCore/src/snoopi.jl | 21 ++++++++++++++-------
 1 file changed, 14 insertions(+), 7 deletions(-)

diff --git a/SnoopCompileCore/src/snoopi.jl b/SnoopCompileCore/src/snoopi.jl
index addfe41f1..8024e3a8e 100644
--- a/SnoopCompileCore/src/snoopi.jl
+++ b/SnoopCompileCore/src/snoopi.jl
@@ -58,21 +58,28 @@ function sort_timed_inf(tmin)
     return sort(data; by=tl->tl[1])
 end
 
-function exclusive_times(timings::Vector, tmin = 0)
+function exclusive_times(timings::Vector, tmin_secs = 0.0)
+    tmin_ns = tmin_secs * 1e9
     out = Any[]
     frontier = copy(timings)
+    i = 1
     while !isempty(frontier)
         t = popfirst!(frontier)
-        children_time = sum([0, (c.time for c in t.children)...])
-        push!(out, Float64((t.time - children_time) / 1e9) => t.name)
+        if i != 1 && t.time < tmin_ns
+            continue
+        end
+        if i !== 1  # Skip "root" node
+            children_time = sum([0, (c.time for c in t.children)...])
+            exclusive_time = (t.time - children_time) / 1e9
+            if exclusive_time >= tmin_secs
+                push!(out, exclusive_time => t.name)
+            end
+        end
+        i += 1
         for c in t.children
             push!(frontier, c)
         end
     end
-    popfirst!(out) # Skip the root node
-    if tmin > 0.0
-        out = filter(tl->tl[1] >= tmin, out)
-    end
     return sort(out; by=tl->tl[1])
 end
 

From bc19fed7182b760506fab22e5dea3a2441237142 Mon Sep 17 00:00:00 2001
From: Nathan Daly <nhdaly@gmail.com>
Date: Fri, 25 Sep 2020 16:21:20 -0400
Subject: [PATCH 18/49] Now julia itself reports exclusive times

---
 SnoopCompileCore/src/snoopi.jl | 5 ++---
 1 file changed, 2 insertions(+), 3 deletions(-)

diff --git a/SnoopCompileCore/src/snoopi.jl b/SnoopCompileCore/src/snoopi.jl
index 8024e3a8e..e4392a189 100644
--- a/SnoopCompileCore/src/snoopi.jl
+++ b/SnoopCompileCore/src/snoopi.jl
@@ -58,7 +58,7 @@ function sort_timed_inf(tmin)
     return sort(data; by=tl->tl[1])
 end
 
-function exclusive_times(timings::Vector, tmin_secs = 0.0)
+function flatten_times(timings::Vector, tmin_secs = 0.0)
     tmin_ns = tmin_secs * 1e9
     out = Any[]
     frontier = copy(timings)
@@ -69,8 +69,7 @@ function exclusive_times(timings::Vector, tmin_secs = 0.0)
             continue
         end
         if i !== 1  # Skip "root" node
-            children_time = sum([0, (c.time for c in t.children)...])
-            exclusive_time = (t.time - children_time) / 1e9
+            exclusive_time = (t.time / 1e9)
             if exclusive_time >= tmin_secs
                 push!(out, exclusive_time => t.name)
             end

From c91c7d2d051d564a02a4bd97b4a68eb0fefc9566 Mon Sep 17 00:00:00 2001
From: Nathan Daly <nhdaly@gmail.com>
Date: Fri, 25 Sep 2020 17:16:57 -0400
Subject: [PATCH 19/49] Add basic flame graph printing for per-method inference
 timings!

---
 Project.toml         |  2 ++
 src/parcel_snoopi.jl | 74 ++++++++++++++++++++++++++++++++++++++++++++
 2 files changed, 76 insertions(+)

diff --git a/Project.toml b/Project.toml
index 498fd548b..1a45b5bf1 100644
--- a/Project.toml
+++ b/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"
diff --git a/src/parcel_snoopi.jl b/src/parcel_snoopi.jl
index 775e6f40d..44c8b2911 100644
--- a/src/parcel_snoopi.jl
+++ b/src/parcel_snoopi.jl
@@ -380,3 +380,77 @@ 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.name, incl_time, t.start_time, child_times)
+end
+
+#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)
+    # TODO: Use a better conversion to a StackFrame so this contains the right kind of data
+    tt = Symbol(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
+    # TODO: is this supposed to be inclusive or exclusive?
+#    if toplevel
+#        # The root frame covers the total time being measured, so start when the first node
+#        # was created, and stop when the last node was finished.
+#        range = Int(start) : Int(start + (max_end_time(to) - start_ns))
+#    else
+        #range = Int(start) : Int(start + TimerOutputs.tottime(to))
+        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)
+    # Skip the very top-level node, which contains no useful data
+    node_data = _flamegraph_frame(to, to.start_time)
+    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)
+        node = addchild(root, node_data)
+        _to_flamegraph(child, node, start_ns)
+    end
+    return root
+end

From 95b3fc294b6cf118a5549c6f0d2e114300e457fb Mon Sep 17 00:00:00 2001
From: Nathan Daly <nhdaly@gmail.com>
Date: Thu, 1 Oct 2020 17:39:31 -0400
Subject: [PATCH 20/49] Close "root" timer so `root` is an accurate measurement
 as well! :)

---
 SnoopCompileCore/src/snoopi.jl | 19 ++++++++-----------
 1 file changed, 8 insertions(+), 11 deletions(-)

diff --git a/SnoopCompileCore/src/snoopi.jl b/SnoopCompileCore/src/snoopi.jl
index e4392a189..553f4ce03 100644
--- a/SnoopCompileCore/src/snoopi.jl
+++ b/SnoopCompileCore/src/snoopi.jl
@@ -49,7 +49,8 @@ end
 end
 
 function sort_timed_inf(tmin)
-    return copy(Core.Compiler.Timings._timings)
+    Core.Compiler.Timings.close_current_timer()
+    return Core.Compiler.Timings._timings[1]
 
     data = __inf_timing__
     if tmin > 0.0
@@ -58,23 +59,19 @@ function sort_timed_inf(tmin)
     return sort(data; by=tl->tl[1])
 end
 
-function flatten_times(timings::Vector, tmin_secs = 0.0)
+function flatten_times(timing::Core.Compiler.Timings.Timing, tmin_secs = 0.0)
     tmin_ns = tmin_secs * 1e9
     out = Any[]
-    frontier = copy(timings)
-    i = 1
+    frontier = [timing]
     while !isempty(frontier)
         t = popfirst!(frontier)
-        if i != 1 && t.time < tmin_ns
+        if t.time < tmin_ns
             continue
         end
-        if i !== 1  # Skip "root" node
-            exclusive_time = (t.time / 1e9)
-            if exclusive_time >= tmin_secs
-                push!(out, exclusive_time => t.name)
-            end
+        exclusive_time = (t.time / 1e9)
+        if exclusive_time >= tmin_secs
+            push!(out, exclusive_time => t.name)
         end
-        i += 1
         for c in t.children
             push!(frontier, c)
         end

From 3b34dd698e6a79cf90e60bf734a237b1542d0571 Mon Sep 17 00:00:00 2001
From: Nathan Daly <nhdaly@gmail.com>
Date: Thu, 1 Oct 2020 17:51:00 -0400
Subject: [PATCH 21/49] Split out `@snoopi_deep`: for the per-method-instance
 snoopi timings

---
 SnoopCompileCore/src/snoopi.jl | 83 ++++++++++++++++++++++------------
 1 file changed, 54 insertions(+), 29 deletions(-)

diff --git a/SnoopCompileCore/src/snoopi.jl b/SnoopCompileCore/src/snoopi.jl
index 553f4ce03..2cea09b8a 100644
--- a/SnoopCompileCore/src/snoopi.jl
+++ b/SnoopCompileCore/src/snoopi.jl
@@ -19,8 +19,7 @@ if isdefined(Core.Compiler, :Params)
         return ret
     end
     @noinline stop_timing() = begin
-        #ccall(:jl_set_typeinf_func, Cvoid, (Any,), Core.Compiler.typeinf_ext)
-        Core.Compiler.__toggle_measure_typeinf(false)
+        ccall(:jl_set_typeinf_func, Cvoid, (Any,), Core.Compiler.typeinf_ext)
     end
 else
     function typeinf_ext_timed(interp::Core.Compiler.AbstractInterpreter, linfo::Core.MethodInstance)
@@ -38,20 +37,15 @@ else
         return ret
     end
     @noinline stop_timing() = begin
-        #ccall(:jl_set_typeinf_func, Cvoid, (Any,), Core.Compiler.typeinf_ext_toplevel)
-        Core.Compiler.__toggle_measure_typeinf(false)
+        ccall(:jl_set_typeinf_func, Cvoid, (Any,), Core.Compiler.typeinf_ext_toplevel)
     end
 end
 
 @noinline start_timing() = begin
-    #ccall(:jl_set_typeinf_func, Cvoid, (Any,), typeinf_ext_timed)
-    Core.Compiler.__toggle_measure_typeinf(true)
+    ccall(:jl_set_typeinf_func, Cvoid, (Any,), typeinf_ext_timed)
 end
 
 function sort_timed_inf(tmin)
-    Core.Compiler.Timings.close_current_timer()
-    return Core.Compiler.Timings._timings[1]
-
     data = __inf_timing__
     if tmin > 0.0
         data = filter(tl->tl[1] >= tmin, data)
@@ -59,26 +53,6 @@ function sort_timed_inf(tmin)
     return sort(data; by=tl->tl[1])
 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.name)
-        end
-        for c in t.children
-            push!(frontier, c)
-        end
-    end
-    return sort(out; by=tl->tl[1])
-end
-
 """
     inf_timing = @snoopi commands
     inf_timing = @snoopi tmin=0.0 commands
@@ -120,6 +94,57 @@ function _snoopi(cmd::Expr, tmin = 0.0)
     end
 end
 
+function start_deep_timing()
+    Core.Compiler.__toggle_measure_typeinf(true)
+end
+function stop_deep_timing()
+    Core.Compiler.__toggle_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
+        Core.Compiler.Timings.reset_timings()
+        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.name)
+        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

From 6c9de36b2df45b8b5273a66a163b41327df2aafb Mon Sep 17 00:00:00 2001
From: Nathan Daly <nhdaly@gmail.com>
Date: Sat, 3 Oct 2020 01:08:22 -0400
Subject: [PATCH 22/49] Get `to_flamegraph(::Timing)` working! :grin:

---
 SnoopCompileCore/src/snoopi.jl |  7 +++++++
 src/parcel_snoopi.jl           | 36 +++++++++++++++++-----------------
 2 files changed, 25 insertions(+), 18 deletions(-)

diff --git a/SnoopCompileCore/src/snoopi.jl b/SnoopCompileCore/src/snoopi.jl
index 2cea09b8a..6d9a0dab1 100644
--- a/SnoopCompileCore/src/snoopi.jl
+++ b/SnoopCompileCore/src/snoopi.jl
@@ -158,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
diff --git a/src/parcel_snoopi.jl b/src/parcel_snoopi.jl
index 44c8b2911..84066fd81 100644
--- a/src/parcel_snoopi.jl
+++ b/src/parcel_snoopi.jl
@@ -383,7 +383,7 @@ const default_exclusions = Set([
 
 
 import FlameGraphs
-import AbstractTrees
+#import AbstractTrees
 
 using Base.StackTraces: StackFrame
 using LeftChildRightSiblingTrees: Node, addchild
@@ -398,8 +398,8 @@ struct InclusiveTiming
     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
+#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
 
@@ -412,26 +412,26 @@ function build_inclusive_times(t::Timing)
     return InclusiveTiming(t.name, incl_time, t.start_time, child_times)
 end
 
-#function max_end_time(t::InclusiveTiming)
-#    return maximum(child.start_time + child.inclusive_time for child in t.children)
-#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)
+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(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
-    # TODO: is this supposed to be inclusive or exclusive?
-#    if toplevel
-#        # The root frame covers the total time being measured, so start when the first node
-#        # was created, and stop when the last node was finished.
-#        range = Int(start) : Int(start + (max_end_time(to) - start_ns))
-#    else
-        #range = Int(start) : Int(start + TimerOutputs.tottime(to))
+    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
+    end
     return FlameGraphs.NodeData(sf, status, range)
 end
 
@@ -441,14 +441,14 @@ function to_flamegraph(t::Timing)
 end
 
 function to_flamegraph(to::InclusiveTiming)
-    # Skip the very top-level node, which contains no useful data
-    node_data = _flamegraph_frame(to, to.start_time)
+    # 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)
+        node_data = _flamegraph_frame(child, start_ns; toplevel=false)
         node = addchild(root, node_data)
         _to_flamegraph(child, node, start_ns)
     end

From 316b8bcb93987f32e83bdff0d90fefb160d9e099 Mon Sep 17 00:00:00 2001
From: Nathan Daly <nhdaly@gmail.com>
Date: Sat, 3 Oct 2020 01:20:57 -0400
Subject: [PATCH 23/49] Print snoopi_deep flamegraph with pretty function
 syntax

Make the functions more readable by printing with a pretty-printed
function signature instead of a type tuple.

Note though that this isn't ideal since the type tuple ends up as the
_typeof_ the function, not the function instance. And not all callable
objects are singletons, so you cannot safely call instance on it.

Instead, we need to adjust the julia source to produce better records.
---
 src/parcel_snoopi.jl | 10 +++++++++-
 1 file changed, 9 insertions(+), 1 deletion(-)

diff --git a/src/parcel_snoopi.jl b/src/parcel_snoopi.jl
index 84066fd81..0b5409caf 100644
--- a/src/parcel_snoopi.jl
+++ b/src/parcel_snoopi.jl
@@ -412,6 +412,14 @@ function build_inclusive_times(t::Timing)
     return InclusiveTiming(t.name, incl_time, t.start_time, child_times)
 end
 
+# Special printing for Type Tuples so they're less ugly in the FlameGraph
+frame_name(n::Any) = n
+function frame_name(::Type{TT}) where TT<:Tuple
+    "$(fieldtype(TT, 1))(" *
+        join(String["::" * string(fieldtype(TT, i)) for i in 2:fieldcount(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.
@@ -422,7 +430,7 @@ 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(to.name)
+    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

From fb48e8af02b79cd9cb9b37b7ab0c4a0c24c92204 Mon Sep 17 00:00:00 2001
From: Nathan Daly <nhdaly@gmail.com>
Date: Fri, 9 Oct 2020 23:20:13 -0400
Subject: [PATCH 24/49] Update to work with latest version of
 https://github.com/JuliaLang/julia/pull/37749

---
 SnoopCompileCore/src/snoopi.jl |  8 ++++----
 src/parcel_snoopi.jl           | 26 ++++++++++++++++++++------
 2 files changed, 24 insertions(+), 10 deletions(-)

diff --git a/SnoopCompileCore/src/snoopi.jl b/SnoopCompileCore/src/snoopi.jl
index 6d9a0dab1..393d82725 100644
--- a/SnoopCompileCore/src/snoopi.jl
+++ b/SnoopCompileCore/src/snoopi.jl
@@ -95,10 +95,11 @@ function _snoopi(cmd::Expr, tmin = 0.0)
 end
 
 function start_deep_timing()
-    Core.Compiler.__toggle_measure_typeinf(true)
+    Core.Compiler.Timings.reset_timings()
+    Core.Compiler.__set_measure_typeinf(true)
 end
 function stop_deep_timing()
-    Core.Compiler.__toggle_measure_typeinf(false)
+    Core.Compiler.__set_measure_typeinf(false)
     Core.Compiler.Timings.close_current_timer()
 end
 
@@ -108,7 +109,6 @@ end
 
 function _snoopi_deep(cmd::Expr)
     return quote
-        Core.Compiler.Timings.reset_timings()
         start_deep_timing()
         try
             $(esc(cmd))
@@ -134,7 +134,7 @@ function flatten_times(timing::Core.Compiler.Timings.Timing, tmin_secs = 0.0)
         end
         exclusive_time = (t.time / 1e9)
         if exclusive_time >= tmin_secs
-            push!(out, exclusive_time => t.name)
+            push!(out, exclusive_time => t.mi_info)
         end
         for c in t.children
             push!(frontier, c)
diff --git a/src/parcel_snoopi.jl b/src/parcel_snoopi.jl
index 0b5409caf..887814668 100644
--- a/src/parcel_snoopi.jl
+++ b/src/parcel_snoopi.jl
@@ -409,15 +409,29 @@ function build_inclusive_times(t::Timing)
         for child in t.children
     ]
     incl_time = t.time + sum(inclusive_time.(child_times); init=UInt64(0))
-    return InclusiveTiming(t.name, incl_time, t.start_time, child_times)
+    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
-frame_name(n::Any) = n
-function frame_name(::Type{TT}) where TT<:Tuple
-    "$(fieldtype(TT, 1))(" *
-        join(String["::" * string(fieldtype(TT, i)) for i in 2:fieldcount(TT)], ", ") *
-    ")"
+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_

From 0974619a09c060aa7e50d2a68553b97152992c4d Mon Sep 17 00:00:00 2001
From: Nathan Daly <nhdaly@gmail.com>
Date: Mon, 12 Oct 2020 16:35:00 -0400
Subject: [PATCH 25/49] Move `flatten_times()` for at-snoopi_deep to
 parcel_snoopi.jl

---
 SnoopCompileCore/src/snoopi.jl | 24 +-----------------------
 src/parcel_snoopi.jl           | 27 +++++++++++++++++++++++++++
 2 files changed, 28 insertions(+), 23 deletions(-)

diff --git a/SnoopCompileCore/src/snoopi.jl b/SnoopCompileCore/src/snoopi.jl
index 393d82725..a11254367 100644
--- a/SnoopCompileCore/src/snoopi.jl
+++ b/SnoopCompileCore/src/snoopi.jl
@@ -1,4 +1,4 @@
-export @snoopi
+export @snoopi, @snoopi_deep
 
 const __inf_timing__ = Tuple{Float64,MethodInstance}[]
 const __inner_timings__ = Ref{Vector{Any}}()
@@ -123,27 +123,6 @@ 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
@@ -164,6 +143,5 @@ function __init__()
     @assert precompile(stop_deep_timing, ())
     @assert precompile(finish_snoopi_deep, ())
 
-    @assert precompile(flatten_times, (Core.Compiler.Timings.Timing, Float64))
     nothing
 end
diff --git a/src/parcel_snoopi.jl b/src/parcel_snoopi.jl
index 887814668..e4246da1d 100644
--- a/src/parcel_snoopi.jl
+++ b/src/parcel_snoopi.jl
@@ -381,6 +381,33 @@ const default_exclusions = Set([
     r"\bMain\b",
 ])
 
+"""
+    flatten_times(timing::Core.Compiler.Timings.Timing, tmin_secs = 0.0)
+
+Flatten the execution graph of Timings returned from `@snoopi_deep` into a Vector of pairs,
+with the exclusive time for each invcation of type inference within the compiler, sorted by
+the exclusive time.
+"""
+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
+
 
 import FlameGraphs
 #import AbstractTrees

From 493ae50835351fc5bd6ec3632d86bd94fd987d3f Mon Sep 17 00:00:00 2001
From: Nathan Daly <nhdaly@gmail.com>
Date: Mon, 12 Oct 2020 16:42:12 -0400
Subject: [PATCH 26/49] Reorganized parcel_snoopi.jl

---
 src/parcel_snoopi.jl | 62 +++++++++++++++++++++++---------------------
 1 file changed, 33 insertions(+), 29 deletions(-)

diff --git a/src/parcel_snoopi.jl b/src/parcel_snoopi.jl
index e4246da1d..591c4171e 100644
--- a/src/parcel_snoopi.jl
+++ b/src/parcel_snoopi.jl
@@ -381,6 +381,8 @@ const default_exclusions = Set([
     r"\bMain\b",
 ])
 
+# === @snoopi_deep helper functions ========================================================
+
 """
     flatten_times(timing::Core.Compiler.Timings.Timing, tmin_secs = 0.0)
 
@@ -410,23 +412,17 @@ end
 
 
 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
+    mi_info::Core.Compiler.Timings.InferenceFrameInfo
     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
 
@@ -439,8 +435,35 @@ function build_inclusive_times(t::Timing)
     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)
+"""
+    to_flamegraph(t::Core.Compiler.Timings.Timing)
+
+Convert the call tree of inference timings returned from `@snoopi_deep` into a FlameGraph.
+Returns a FlameGraphs.FlameGraph structure that represents the timing trace recorded for
+type inference.
+"""
+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
+
+function frame_name(mi_info::Core.Compiler.Timings.InferenceFrameInfo)
+    frame_name(mi_info.mi::Core.Compiler.MethodInstance)
 end
 function frame_name(mi::Core.Compiler.MethodInstance)
     frame_name(mi.def.name, mi.specTypes)
@@ -471,7 +494,7 @@ 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))
+    tt = Symbol(frame_name(to.mi_info))
     sf = StackFrame(tt, Symbol("none"), 0, nothing, false, false, UInt64(0x0))
     status = 0x0  # "default" status -- See FlameGraphs.jl
     start = to.start_time - start_ns
@@ -484,22 +507,3 @@ function _flamegraph_frame(to::InclusiveTiming, start_ns; toplevel)
     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

From abfc1739873aed790cbd1346dab566c34c4e3ffa Mon Sep 17 00:00:00 2001
From: Nathan Daly <nhdaly@gmail.com>
Date: Mon, 12 Oct 2020 16:43:04 -0400
Subject: [PATCH 27/49] Handle Type Tuples that can't be printed to a string

---
 src/parcel_snoopi.jl | 7 ++++++-
 1 file changed, 6 insertions(+), 1 deletion(-)

diff --git a/src/parcel_snoopi.jl b/src/parcel_snoopi.jl
index 591c4171e..66f9a23cc 100644
--- a/src/parcel_snoopi.jl
+++ b/src/parcel_snoopi.jl
@@ -481,7 +481,12 @@ function frame_name(name, ::Type{TT}) where TT<:Tuple
 
     # For now, since PProf name mangles strings that parse as functions, we'll just use the
     # full Type Tuple string :|
-    return string(TT)
+    try
+        return string(TT)
+    catch
+        # Some Type Tuples apparently cannot be printed to a string?
+        return "Unknown"
+    end
 end
 
 # NOTE: The "root" node doesn't cover th whole profile, because it's only the _complement_

From 1e4eda272511ebc10c71e19dba91190bffe183b4 Mon Sep 17 00:00:00 2001
From: Nathan Daly <nhdaly@gmail.com>
Date: Mon, 12 Oct 2020 17:38:26 -0400
Subject: [PATCH 28/49] Add tests for `@snoopi_deep`, including AbstractTrees
 tests of FlameGraph output

---
 Project.toml   |  3 ++-
 test/snoopi.jl | 36 ++++++++++++++++++++++++++++++++++++
 2 files changed, 38 insertions(+), 1 deletion(-)

diff --git a/Project.toml b/Project.toml
index 1a45b5bf1..cdb690888 100644
--- a/Project.toml
+++ b/Project.toml
@@ -19,6 +19,7 @@ SnoopCompileCore = "~2.1.1"
 julia = "1"
 
 [extras]
+AbstractTrees = "1520ce14-60c1-5f80-bbc7-55ef81b5835c"
 ColorTypes = "3da002f7-5984-5a60-b8a6-cbb66c0b333f"
 Documenter = "e30172f5-a6a5-5a46-863b-614d45cd2de4"
 FixedPointNumbers = "53c48c17-4a7d-5ca2-90c5-79b7896eea93"
@@ -30,4 +31,4 @@ SparseArrays = "2f01184e-e22b-5df5-ae63-d93ebab69eaf"
 Test = "8dfed614-e22c-5e08-85e1-65c5234f0b40"
 
 [targets]
-test = ["ColorTypes", "Documenter", "FixedPointNumbers", "InteractiveUtils", "JLD", "MethodAnalysis", "Pkg", "SparseArrays", "Test"]
+test = ["AbstractTrees", "ColorTypes", "Documenter", "FixedPointNumbers", "InteractiveUtils", "JLD", "MethodAnalysis", "Pkg", "SparseArrays", "Test"]
diff --git a/test/snoopi.jl b/test/snoopi.jl
index 9e3966c02..77c064c73 100644
--- a/test/snoopi.jl
+++ b/test/snoopi.jl
@@ -220,3 +220,39 @@ end
     pc = SnoopCompile.parcel(tinf, remove_exclusions = false)
     @test count(isequal("Base.precompile(Tuple{typeof(generated)})"), pc[:Main]) == 1
 end
+
+using AbstractTrees  # For FlameGraphs tests
+
+@testset "@snoopi_deep" begin
+    # WARMUP
+    @eval module M  # Example with some functions that include type instability
+        i(x) = x+5
+        h(a::Array) = i(a[1]::Integer) + 2
+        g(y::Integer) = h(Any[y])
+    end
+    M.g(2)  # Warmup all deeply reachable functions
+
+    # Redefine the module, so the snoop will only show these functions:
+    @eval module M  # Example with some functions that include type instability
+        i(x) = x+5
+        h(a::Array) = i(a[1]::Integer) + 2
+        g(y::Integer) = h(Any[y])
+    end
+
+    timing = SnoopCompileCore.@snoopi_deep begin
+        M.g(2)
+    end
+    times = SnoopCompile.flatten_times(timing)
+    @test length(times) == 5  # ROOT, g(...), h(...), i(::Integer), i(::Int)
+    names = [mi_info.mi.def.name for (time, mi_info) in times]
+    @test sort(names) == [:ROOT, :g, :h, :i, :i]
+
+    # Test FlameGraph export
+    fg = SnoopCompile.to_flamegraph(timing)
+    @test length(collect(AbstractTrees.PreOrderDFS(fg))) == 5
+    # Test that the span covers the whole tree.
+    for leaf in AbstractTrees.PreOrderDFS(fg)
+        @test leaf.data.span.start in fg.data.span
+        @test leaf.data.span.stop in fg.data.span
+    end
+end

From 1b6314962e3bb8faced5c15703e1a6fc2e1d2cf6 Mon Sep 17 00:00:00 2001
From: Nathan Daly <nhdaly@gmail.com>
Date: Mon, 12 Oct 2020 17:43:37 -0400
Subject: [PATCH 29/49] Add docstring for macro snoopi_deep

---
 SnoopCompileCore/src/snoopi.jl | 13 +++++++++++++
 1 file changed, 13 insertions(+)

diff --git a/SnoopCompileCore/src/snoopi.jl b/SnoopCompileCore/src/snoopi.jl
index a11254367..ed4c496c5 100644
--- a/SnoopCompileCore/src/snoopi.jl
+++ b/SnoopCompileCore/src/snoopi.jl
@@ -119,6 +119,19 @@ function _snoopi_deep(cmd::Expr)
     end
 end
 
+"""
+    timing_tree = @snoopi_deep commands
+
+Produce a profile of julia's type inference, containing the amount of time spent infering
+for every `MethodInstance` processed while executing `commands`.
+
+The top-level node in this profile tree is `ROOT`, which contains the time spent _not_ in
+julia's type inference.
+
+To make use of these results, see the processing functions in SnoopCompile:
+    - [`SnoopCompile.flatten_times(timing_tree)`](@ref)
+    - [`SnoopCompile.to_flamegraph(timing_tree)`](@ref)
+"""
 macro snoopi_deep(cmd)
     return _snoopi_deep(cmd)
 end

From 3f21529774666c0ebd04f84e2662ce057c9e1881 Mon Sep 17 00:00:00 2001
From: Nathan Daly <nhdaly@gmail.com>
Date: Mon, 12 Oct 2020 20:53:59 -0400
Subject: [PATCH 30/49] Add TODO to add `tmin=` to `to_flamegraph()`

---
 src/parcel_snoopi.jl | 1 +
 1 file changed, 1 insertion(+)

diff --git a/src/parcel_snoopi.jl b/src/parcel_snoopi.jl
index 66f9a23cc..22221db85 100644
--- a/src/parcel_snoopi.jl
+++ b/src/parcel_snoopi.jl
@@ -435,6 +435,7 @@ function build_inclusive_times(t::Timing)
     return InclusiveTiming(t.mi_info, incl_time, t.start_time, child_times)
 end
 
+# TODO: Add `tmin=` to to_flamegraph()
 """
     to_flamegraph(t::Core.Compiler.Timings.Timing)
 

From 52b414e888a0dc81255e84f612a8938b973eaa1f Mon Sep 17 00:00:00 2001
From: Nathan Daly <nhdaly@gmail.com>
Date: Mon, 12 Oct 2020 21:17:16 -0400
Subject: [PATCH 31/49] Add `tmin_secs=` param to `to_flamegraphs()` to filter
 frames by inclusive time

---
 src/parcel_snoopi.jl | 18 +++++++++++-------
 1 file changed, 11 insertions(+), 7 deletions(-)

diff --git a/src/parcel_snoopi.jl b/src/parcel_snoopi.jl
index 22221db85..162ed76f8 100644
--- a/src/parcel_snoopi.jl
+++ b/src/parcel_snoopi.jl
@@ -426,25 +426,28 @@ end
 
 inclusive_time(t::InclusiveTiming) = t.inclusive_time
 
-function build_inclusive_times(t::Timing)
+function build_inclusive_times(t::Timing, tmin_ns)
     child_times = InclusiveTiming[
-        build_inclusive_times(child)
+        build_inclusive_times(child, tmin_ns)
         for child in t.children
+        if child.time >= tmin_ns
     ]
     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
 
-# TODO: Add `tmin=` to to_flamegraph()
 """
-    to_flamegraph(t::Core.Compiler.Timings.Timing)
+    to_flamegraph(t::Core.Compiler.Timings.Timing; tmin_secs=0.0)
 
 Convert the call tree of inference timings returned from `@snoopi_deep` into a FlameGraph.
 Returns a FlameGraphs.FlameGraph structure that represents the timing trace recorded for
 type inference.
+
+Frames that take less than `tmin_secs` seconds of _inclusive time_ will not be included
+in the resultant FlameGraph (meaning total time including it and all of its children).
 """
-function to_flamegraph(t::Timing)
-    it = build_inclusive_times(t)
+function to_flamegraph(t::Timing; tmin_secs=0.0)
+    it = build_inclusive_times(t, UInt64(round(tmin_secs * 1e9)))
     to_flamegraph(it)
 end
 
@@ -494,7 +497,8 @@ end
 # 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)
+    return maximum(child.start_time + child.inclusive_time for child in t.children;
+                    init = UInt64(t.start_time + t.inclusive_time))
 end
 
 # Make a flat frame for this Timing

From 1e20614acb259225d852df13bcd6fa86c7fe2e5f Mon Sep 17 00:00:00 2001
From: Nathan Daly <nhdaly@gmail.com>
Date: Tue, 20 Oct 2020 01:27:11 -0400
Subject: [PATCH 32/49] Switch back to nice MethodInstance printing for frame
 names!

---
 src/parcel_snoopi.jl | 24 ++++++++----------------
 1 file changed, 8 insertions(+), 16 deletions(-)

diff --git a/src/parcel_snoopi.jl b/src/parcel_snoopi.jl
index 162ed76f8..51738aed2 100644
--- a/src/parcel_snoopi.jl
+++ b/src/parcel_snoopi.jl
@@ -474,23 +474,15 @@ function frame_name(mi::Core.Compiler.MethodInstance)
 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
+    #try
+        io = IOBuffer()
+        Base.show_tuple_as_call(io, name, TT)
+        v = String(take!(io))
+        return v
+    #catch  # TODO: Narrow this to only swallowing the expected exception type
+    #    # Some Type Tuples apparently cannot be printed to a string?
+    #    return name
     #end
-
-    # For now, since PProf name mangles strings that parse as functions, we'll just use the
-    # full Type Tuple string :|
-    try
-        return string(TT)
-    catch
-        # Some Type Tuples apparently cannot be printed to a string?
-        return "Unknown"
-    end
 end
 
 # NOTE: The "root" node doesn't cover th whole profile, because it's only the _complement_

From 7bb6a284a63dfda1ca9adbef4edcf5bc99fef128 Mon Sep 17 00:00:00 2001
From: Nathan Daly <nhdaly@gmail.com>
Date: Tue, 20 Oct 2020 16:11:24 -0400
Subject: [PATCH 33/49] Add file and line info to SnoopCompile.to_flamegraph

---
 src/parcel_snoopi.jl | 3 ++-
 1 file changed, 2 insertions(+), 1 deletion(-)

diff --git a/src/parcel_snoopi.jl b/src/parcel_snoopi.jl
index 51738aed2..c4689f44e 100644
--- a/src/parcel_snoopi.jl
+++ b/src/parcel_snoopi.jl
@@ -496,8 +496,9 @@ 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
+    mi = to.mi_info.mi
     tt = Symbol(frame_name(to.mi_info))
-    sf = StackFrame(tt, Symbol("none"), 0, nothing, false, false, UInt64(0x0))
+    sf = StackFrame(tt, mi.def.file, mi.def.line, mi, false, false, UInt64(0x0))
     status = 0x0  # "default" status -- See FlameGraphs.jl
     start = to.start_time - start_ns
     if toplevel

From f1fbd1a20b21df628e63c075ee51f8c88221ccdb Mon Sep 17 00:00:00 2001
From: Nathan Daly <nhdaly@gmail.com>
Date: Tue, 20 Oct 2020 16:28:31 -0400
Subject: [PATCH 34/49] Clean up: Remove debugging and experimentation cruft

---
 SnoopCompileCore/src/snoopi.jl | 14 +++-----------
 1 file changed, 3 insertions(+), 11 deletions(-)

diff --git a/SnoopCompileCore/src/snoopi.jl b/SnoopCompileCore/src/snoopi.jl
index ed4c496c5..5389bdae0 100644
--- a/SnoopCompileCore/src/snoopi.jl
+++ b/SnoopCompileCore/src/snoopi.jl
@@ -1,7 +1,6 @@
 export @snoopi, @snoopi_deep
 
 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)
@@ -18,9 +17,7 @@ if isdefined(Core.Compiler, :Params)
         push!(__inf_timing__, (tstop-tstart, linfo))
         return ret
     end
-    @noinline stop_timing() = begin
-        ccall(:jl_set_typeinf_func, Cvoid, (Any,), Core.Compiler.typeinf_ext)
-    end
+    @noinline stop_timing() = ccall(:jl_set_typeinf_func, Cvoid, (Any,), Core.Compiler.typeinf_ext)
 else
     function typeinf_ext_timed(interp::Core.Compiler.AbstractInterpreter, linfo::Core.MethodInstance)
         tstart = time()
@@ -36,14 +33,10 @@ else
         push!(__inf_timing__, (tstop-tstart, linfo))
         return ret
     end
-    @noinline stop_timing() = begin
-        ccall(:jl_set_typeinf_func, Cvoid, (Any,), Core.Compiler.typeinf_ext_toplevel)
-    end
+    @noinline stop_timing() = ccall(:jl_set_typeinf_func, Cvoid, (Any,), Core.Compiler.typeinf_ext_toplevel)
 end
 
-@noinline start_timing() = begin
-    ccall(:jl_set_typeinf_func, Cvoid, (Any,), typeinf_ext_timed)
-end
+@noinline start_timing() = ccall(:jl_set_typeinf_func, Cvoid, (Any,), typeinf_ext_timed)
 
 function sort_timed_inf(tmin)
     data = __inf_timing__
@@ -83,7 +76,6 @@ end
 function _snoopi(cmd::Expr, tmin = 0.0)
     return quote
         empty!(__inf_timing__)
-        Core.Compiler.Timings.reset_timings()
         start_timing()
         try
             $(esc(cmd))

From 2d84f1d1d5d0743d643d9d37d060f51df258b5f1 Mon Sep 17 00:00:00 2001
From: Nathan Daly <nhdaly@gmail.com>
Date: Tue, 20 Oct 2020 16:41:13 -0400
Subject: [PATCH 35/49] Fix `tmin_secs` for `to_flamegraph()` and
 `flatten_times()`

---
 src/parcel_snoopi.jl | 35 +++++++++++++++++------------------
 1 file changed, 17 insertions(+), 18 deletions(-)

diff --git a/src/parcel_snoopi.jl b/src/parcel_snoopi.jl
index c4689f44e..9a8d77b2e 100644
--- a/src/parcel_snoopi.jl
+++ b/src/parcel_snoopi.jl
@@ -384,21 +384,17 @@ const default_exclusions = Set([
 # === @snoopi_deep helper functions ========================================================
 
 """
-    flatten_times(timing::Core.Compiler.Timings.Timing, tmin_secs = 0.0)
+    flatten_times(timing::Core.Compiler.Timings.Timing; tmin_secs = 0.0)
 
 Flatten the execution graph of Timings returned from `@snoopi_deep` into a Vector of pairs,
 with the exclusive time for each invcation of type inference within the compiler, sorted by
 the exclusive time.
 """
-function flatten_times(timing::Core.Compiler.Timings.Timing, tmin_secs = 0.0)
-    tmin_ns = tmin_secs * 1e9
+function flatten_times(timing::Core.Compiler.Timings.Timing; tmin_secs = 0.0)
     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)
@@ -426,11 +422,10 @@ end
 
 inclusive_time(t::InclusiveTiming) = t.inclusive_time
 
-function build_inclusive_times(t::Timing, tmin_ns)
+function build_inclusive_times(t::Timing)
     child_times = InclusiveTiming[
-        build_inclusive_times(child, tmin_ns)
+        build_inclusive_times(child)
         for child in t.children
-        if child.time >= tmin_ns
     ]
     incl_time = t.time + sum(inclusive_time.(child_times); init=UInt64(0))
     return InclusiveTiming(t.mi_info, incl_time, t.start_time, child_times)
@@ -446,22 +441,26 @@ type inference.
 Frames that take less than `tmin_secs` seconds of _inclusive time_ will not be included
 in the resultant FlameGraph (meaning total time including it and all of its children).
 """
-function to_flamegraph(t::Timing; tmin_secs=0.0)
-    it = build_inclusive_times(t, UInt64(round(tmin_secs * 1e9)))
-    to_flamegraph(it)
+function to_flamegraph(t::Timing; tmin_secs = 0.0)
+    it = build_inclusive_times(t)
+    to_flamegraph(it; tmin_secs=tmin_secs)
 end
 
-function to_flamegraph(to::InclusiveTiming)
+function to_flamegraph(to::InclusiveTiming; tmin_secs = 0.0)
+    tmin_ns = UInt64(round(tmin_secs * 1e9))
+
     # 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)
+    return _build_flamegraph!(root, to, to.start_time, tmin_ns)
 end
-function _to_flamegraph(to::InclusiveTiming, root, start_ns)
+function _build_flamegraph!(root, to::InclusiveTiming, start_ns, tmin_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)
+        if child.inclusive_time > tmin_ns
+            node_data = _flamegraph_frame(child, start_ns; toplevel=false)
+            node = addchild(root, node_data)
+            _build_flamegraph!(node, child, start_ns, tmin_ns)
+        end
     end
     return root
 end

From 3adda6cfcb0b96504f9df4f4e79481e7932d408b Mon Sep 17 00:00:00 2001
From: Nathan Daly <nhdaly@gmail.com>
Date: Tue, 20 Oct 2020 16:56:04 -0400
Subject: [PATCH 36/49] Improve docstrings and add Examples

---
 SnoopCompileCore/src/snoopi.jl | 27 ++++++++++++++++++++++++++-
 src/parcel_snoopi.jl           | 25 ++++++++++++++++++++++++-
 2 files changed, 50 insertions(+), 2 deletions(-)

diff --git a/SnoopCompileCore/src/snoopi.jl b/SnoopCompileCore/src/snoopi.jl
index 5389bdae0..186c9a85d 100644
--- a/SnoopCompileCore/src/snoopi.jl
+++ b/SnoopCompileCore/src/snoopi.jl
@@ -118,11 +118,36 @@ Produce a profile of julia's type inference, containing the amount of time spent
 for every `MethodInstance` processed while executing `commands`.
 
 The top-level node in this profile tree is `ROOT`, which contains the time spent _not_ in
-julia's type inference.
+julia's type inference (codegen, llvm_opt, runtime, etc).
 
 To make use of these results, see the processing functions in SnoopCompile:
     - [`SnoopCompile.flatten_times(timing_tree)`](@ref)
     - [`SnoopCompile.to_flamegraph(timing_tree)`](@ref)
+
+# Examples
+```julia
+julia> timing = SnoopCompileCore.@snoopi_deep begin
+           @eval sort(rand(100))  # Evaluate some code and profile julia's type inference
+       end;
+
+julia> using SnoopCompile, ProfileView
+
+julia> times = SnoopCompile.flatten_times(timing, tmin_secs=0.001)
+4-element Vector{Any}:
+ 0.001088448 => Core.Compiler.Timings.InferenceFrameInfo(MethodInstance for fpsort!(::Vector{Float64}, ::Base.Sort.QuickSortAlg, ::Base.Order.ForwardOrdering), 0x00000000000072e4, Any[], Any[Vector{Float64}, Core.Const(Base.Sort.QuickSortAlg()), Core.Const(Base.Order.ForwardOrdering()), Union{}, Union{}, Union{}, Union{}, Union{}, Union{}, Union{}, Union{}, Union{}])
+ 0.001618478 => Core.Compiler.Timings.InferenceFrameInfo(MethodInstance for rand!(::Random.MersenneTwister, ::Random.UnsafeView{Float64}, ::Random.SamplerTrivial{Random.CloseOpen01{Float64}, Float64}), 0x00000000000072e4, Any[], Any[Random.MersenneTwister, Random.UnsafeView{Float64}, Core.Const(Random.SamplerTrivial{Random.CloseOpen01{Float64}, Float64}(Random.CloseOpen01{Float64}())), Union{}, Union{}, Union{}, Union{}, Union{}, Union{}, Union{}])
+ 0.002289655 => Core.Compiler.Timings.InferenceFrameInfo(MethodInstance for _rand_max383!(::Random.MersenneTwister, ::Random.UnsafeView{Float64}, ::Random.CloseOpen01{Float64}), 0x00000000000072e4, Any[], Any[Random.MersenneTwister, Random.UnsafeView{Float64}, Core.Const(Random.CloseOpen01{Float64}()), Union{}, Union{}, Union{}, Union{}])
+ 0.093143594 => Core.Compiler.Timings.InferenceFrameInfo(MethodInstance for ROOT(), 0x0000000000000000, Any[], Any[])
+
+julia> fg = SnoopCompile.to_flamegraph(timing)
+Node(FlameGraphs.NodeData(ROOT() at typeinfer.jl:70, 0x00, 0:15355670))
+
+julia> ProfileView.view(fg);  # Display the FlameGraph in a package that supports it
+
+julia> fg = SnoopCompile.to_flamegraph(timing; tmin_secs=0.0001)  # Skip very tiny frames
+Node(FlameGraphs.NodeData(ROOT() at typeinfer.jl:70, 0x00, 0:15355670))
+```
+
 """
 macro snoopi_deep(cmd)
     return _snoopi_deep(cmd)
diff --git a/src/parcel_snoopi.jl b/src/parcel_snoopi.jl
index 9a8d77b2e..e2e5802ac 100644
--- a/src/parcel_snoopi.jl
+++ b/src/parcel_snoopi.jl
@@ -388,7 +388,7 @@ const default_exclusions = Set([
 
 Flatten the execution graph of Timings returned from `@snoopi_deep` into a Vector of pairs,
 with the exclusive time for each invcation of type inference within the compiler, sorted by
-the exclusive time.
+the exclusive time, skipping any frames that took less than `tmin_secs` seconds.
 """
 function flatten_times(timing::Core.Compiler.Timings.Timing; tmin_secs = 0.0)
     out = Any[]
@@ -433,6 +433,7 @@ end
 
 """
     to_flamegraph(t::Core.Compiler.Timings.Timing; tmin_secs=0.0)
+    to_flamegraph(t::SnoopCompile.InclusiveTiming; tmin_secs=0.0)
 
 Convert the call tree of inference timings returned from `@snoopi_deep` into a FlameGraph.
 Returns a FlameGraphs.FlameGraph structure that represents the timing trace recorded for
@@ -440,6 +441,28 @@ type inference.
 
 Frames that take less than `tmin_secs` seconds of _inclusive time_ will not be included
 in the resultant FlameGraph (meaning total time including it and all of its children).
+This can be helpful if you have a very big profile, to save on processing time.
+
+# Examples
+```julia
+julia> timing = SnoopCompileCore.@snoopi_deep begin
+           @eval sort(rand(100))  # Evaluate some code and profile julia's type inference
+       end;
+
+julia> fg = SnoopCompile.to_flamegraph(timing)
+Node(FlameGraphs.NodeData(ROOT() at typeinfer.jl:70, 0x00, 0:15355670))
+
+julia> ProfileView.view(fg);  # Display the FlameGraph in a package that supports it
+
+julia> fg = SnoopCompile.to_flamegraph(timing; tmin_secs=0.0001)  # Skip very tiny frames
+Node(FlameGraphs.NodeData(ROOT() at typeinfer.jl:70, 0x00, 0:15355670))
+```
+
+NOTE: This function must touch every frame in the provided `Timing` to build inclusive
+timing information (`InclusiveTiming`). If you have a very large profile, and you plan to
+call this function multiple times (say with different values for `tmin_secs`), you can save
+some intermediate time by first calling [`build_inclusive_times(t)`](@ref), only once,
+and then passing in the `InclusiveTiming` object for all subsequent calls.
 """
 function to_flamegraph(t::Timing; tmin_secs = 0.0)
     it = build_inclusive_times(t)

From 11cab1629af1a06a7e1cb63e5a16bbd8e5862165 Mon Sep 17 00:00:00 2001
From: Nathan Daly <nhdaly@gmail.com>
Date: Tue, 20 Oct 2020 17:29:42 -0400
Subject: [PATCH 37/49] Clean up old cruft

---
 src/parcel_snoopi.jl | 13 ++++---------
 1 file changed, 4 insertions(+), 9 deletions(-)

diff --git a/src/parcel_snoopi.jl b/src/parcel_snoopi.jl
index e2e5802ac..95879b795 100644
--- a/src/parcel_snoopi.jl
+++ b/src/parcel_snoopi.jl
@@ -496,15 +496,10 @@ function frame_name(mi::Core.Compiler.MethodInstance)
 end
 # Special printing for Type Tuples so they're less ugly in the FlameGraph
 function frame_name(name, ::Type{TT}) where TT<:Tuple
-    #try
-        io = IOBuffer()
-        Base.show_tuple_as_call(io, name, TT)
-        v = String(take!(io))
-        return v
-    #catch  # TODO: Narrow this to only swallowing the expected exception type
-    #    # Some Type Tuples apparently cannot be printed to a string?
-    #    return name
-    #end
+    io = IOBuffer()
+    Base.show_tuple_as_call(io, name, TT)
+    v = String(take!(io))
+    return v
 end
 
 # NOTE: The "root" node doesn't cover th whole profile, because it's only the _complement_

From 54c3462d467e4e1f9e588f418fa9e62ade4d5861 Mon Sep 17 00:00:00 2001
From: Nathan Daly <nhdaly@gmail.com>
Date: Tue, 20 Oct 2020 17:42:37 -0400
Subject: [PATCH 38/49] Add tests for `tmin_secs=` param

---
 test/snoopi.jl | 7 +++++++
 1 file changed, 7 insertions(+)

diff --git a/test/snoopi.jl b/test/snoopi.jl
index 77c064c73..15eb013bb 100644
--- a/test/snoopi.jl
+++ b/test/snoopi.jl
@@ -247,6 +247,9 @@ using AbstractTrees  # For FlameGraphs tests
     names = [mi_info.mi.def.name for (time, mi_info) in times]
     @test sort(names) == [:ROOT, :g, :h, :i, :i]
 
+    longest_frame_time = times[end][1]
+    @test length(SnoopCompile.flatten_times(timing, tmin_secs=longest_frame_time)) == 1
+
     # Test FlameGraph export
     fg = SnoopCompile.to_flamegraph(timing)
     @test length(collect(AbstractTrees.PreOrderDFS(fg))) == 5
@@ -255,4 +258,8 @@ using AbstractTrees  # For FlameGraphs tests
         @test leaf.data.span.start in fg.data.span
         @test leaf.data.span.stop in fg.data.span
     end
+
+    cutoff_bottom_frame = (times[1][1] + times[2][1]) / 2
+    fg2 = SnoopCompile.to_flamegraph(timing, tmin_secs = cutoff_bottom_frame)
+    @test length(collect(AbstractTrees.PreOrderDFS(fg2))) == (length(collect(AbstractTrees.PreOrderDFS(fg))) - 1)
 end

From ceaecb25acff476a2628fe75ec8a63f9c2666acf Mon Sep 17 00:00:00 2001
From: Nathan Daly <nhdaly@gmail.com>
Date: Tue, 20 Oct 2020 20:25:56 -0400
Subject: [PATCH 39/49] Set fail-fast: false for easier CI for code review

---
 .github/workflows/ci.yml | 2 +-
 1 file changed, 1 insertion(+), 1 deletion(-)

diff --git a/.github/workflows/ci.yml b/.github/workflows/ci.yml
index 42ffd8eea..e9819c0fd 100644
--- a/.github/workflows/ci.yml
+++ b/.github/workflows/ci.yml
@@ -11,7 +11,7 @@ jobs:
     name: Julia ${{ matrix.version }} - ${{ matrix.os }} - ${{ matrix.arch }}
     runs-on: ${{ matrix.os }}
     strategy:
-      fail-fast: true
+      fail-fast: false
       matrix:
         version:
           - '1.0'

From 37ad8be1dd710e5838567130a262706f6be3281a Mon Sep 17 00:00:00 2001
From: Nathan Daly <nhdaly@gmail.com>
Date: Tue, 20 Oct 2020 20:26:59 -0400
Subject: [PATCH 40/49] Add compat bounds for FlameGraphs and
 LeftChildRightSiblingTrees

---
 Project.toml | 2 ++
 1 file changed, 2 insertions(+)

diff --git a/Project.toml b/Project.toml
index cdb690888..a79d14be8 100644
--- a/Project.toml
+++ b/Project.toml
@@ -14,6 +14,8 @@ SnoopCompileCore = "e2b509da-e806-4183-be48-004708413034"
 
 [compat]
 Cthulhu = "1.2"
+FlameGraphs = "0.2"
+LeftChildRightSiblingTrees = "0.1"
 OrderedCollections = "1"
 SnoopCompileCore = "~2.1.1"
 julia = "1"

From bfa969efe8d815d8c30adb98fb1a018cd7419bd0 Mon Sep 17 00:00:00 2001
From: Nathan Daly <NHDaly@gmail.com>
Date: Mon, 26 Oct 2020 10:02:20 -0400
Subject: [PATCH 41/49] Apply suggestions from code review

Co-authored-by: Tim Holy <tim.holy@gmail.com>
---
 src/parcel_snoopi.jl | 11 ++++-------
 1 file changed, 4 insertions(+), 7 deletions(-)

diff --git a/src/parcel_snoopi.jl b/src/parcel_snoopi.jl
index 95879b795..87fee03b3 100644
--- a/src/parcel_snoopi.jl
+++ b/src/parcel_snoopi.jl
@@ -391,7 +391,7 @@ with the exclusive time for each invcation of type inference within the compiler
 the exclusive time, skipping any frames that took less than `tmin_secs` seconds.
 """
 function flatten_times(timing::Core.Compiler.Timings.Timing; tmin_secs = 0.0)
-    out = Any[]
+    out = Pair{Float64,Core.Compiler.Timings.InferenceFrameInfo}[]
     frontier = [timing]
     while !isempty(frontier)
         t = popfirst!(frontier)
@@ -399,9 +399,7 @@ function flatten_times(timing::Core.Compiler.Timings.Timing; tmin_secs = 0.0)
         if exclusive_time >= tmin_secs
             push!(out, exclusive_time => t.mi_info)
         end
-        for c in t.children
-            push!(frontier, c)
-        end
+        append!(frontier, t.children)
     end
     return sort(out; by=tl->tl[1])
 end
@@ -427,7 +425,7 @@ function build_inclusive_times(t::Timing)
         build_inclusive_times(child)
         for child in t.children
     ]
-    incl_time = t.time + sum(inclusive_time.(child_times); init=UInt64(0))
+    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
 
@@ -502,7 +500,7 @@ function frame_name(name, ::Type{TT}) where TT<:Tuple
     return v
 end
 
-# NOTE: The "root" node doesn't cover th whole profile, because it's only the _complement_
+# NOTE: The "root" node doesn't cover the 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)
@@ -526,4 +524,3 @@ function _flamegraph_frame(to::InclusiveTiming, start_ns; toplevel)
     end
     return FlameGraphs.NodeData(sf, status, range)
 end
-

From 421593d3346070096903edc179c4e9575423550b Mon Sep 17 00:00:00 2001
From: Nathan Daly <nhdaly@gmail.com>
Date: Tue, 20 Oct 2020 22:33:17 -0400
Subject: [PATCH 42/49] Fix small type stability of `range=` in
 `_flamegraph_frame()`

---
 src/parcel_snoopi.jl | 2 +-
 1 file changed, 1 insertion(+), 1 deletion(-)

diff --git a/src/parcel_snoopi.jl b/src/parcel_snoopi.jl
index 87fee03b3..33d415708 100644
--- a/src/parcel_snoopi.jl
+++ b/src/parcel_snoopi.jl
@@ -518,7 +518,7 @@ function _flamegraph_frame(to::InclusiveTiming, start_ns; toplevel)
     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
+        range = Int(start) : Int(max_end_time(to) - start_ns)
     else
         range = Int(start) : Int(start + to.inclusive_time)
     end

From 6d3ff303b2528b50c17400fb9526bc4ae89a261a Mon Sep 17 00:00:00 2001
From: Nathan Daly <nhdaly@gmail.com>
Date: Mon, 26 Oct 2020 10:21:42 -0400
Subject: [PATCH 43/49] Simplify Project.toml: Use
 `FlameGraphs.LeftChildRightSiblingTrees`

---
 Project.toml | 2 --
 1 file changed, 2 deletions(-)

diff --git a/Project.toml b/Project.toml
index a79d14be8..4f7eeb609 100644
--- a/Project.toml
+++ b/Project.toml
@@ -6,7 +6,6 @@ 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"
@@ -15,7 +14,6 @@ SnoopCompileCore = "e2b509da-e806-4183-be48-004708413034"
 [compat]
 Cthulhu = "1.2"
 FlameGraphs = "0.2"
-LeftChildRightSiblingTrees = "0.1"
 OrderedCollections = "1"
 SnoopCompileCore = "~2.1.1"
 julia = "1"

From 74e7f69df89a955d5fa6b9ad26347457ef2cef4a Mon Sep 17 00:00:00 2001
From: Nathan Daly <nhdaly@gmail.com>
Date: Mon, 26 Oct 2020 10:23:06 -0400
Subject: [PATCH 44/49] Improve docstrings and comments (PR Review suggestions)

---
 SnoopCompileCore/src/snoopi.jl | 14 +++++++-------
 src/parcel_snoopi.jl           |  6 +++---
 2 files changed, 10 insertions(+), 10 deletions(-)

diff --git a/SnoopCompileCore/src/snoopi.jl b/SnoopCompileCore/src/snoopi.jl
index 186c9a85d..ccd89acea 100644
--- a/SnoopCompileCore/src/snoopi.jl
+++ b/SnoopCompileCore/src/snoopi.jl
@@ -51,7 +51,7 @@ end
     inf_timing = @snoopi tmin=0.0 commands
 
 Execute `commands` while snooping on inference. Returns an array of `(t, linfo)`
-tuples, where `t` is the amount of time spent infering `linfo` (a `MethodInstance`).
+tuples, where `t` is the amount of time spent inferring `linfo` (a `MethodInstance`).
 
 Methods that take less time than `tmin` will not be reported.
 """
@@ -114,8 +114,8 @@ end
 """
     timing_tree = @snoopi_deep commands
 
-Produce a profile of julia's type inference, containing the amount of time spent infering
-for every `MethodInstance` processed while executing `commands`.
+Produce a profile of julia's type inference, containing the amount of time spent inferring
+every `MethodInstance` processed while executing `commands`.
 
 The top-level node in this profile tree is `ROOT`, which contains the time spent _not_ in
 julia's type inference (codegen, llvm_opt, runtime, etc).
@@ -134,10 +134,10 @@ julia> using SnoopCompile, ProfileView
 
 julia> times = SnoopCompile.flatten_times(timing, tmin_secs=0.001)
 4-element Vector{Any}:
- 0.001088448 => Core.Compiler.Timings.InferenceFrameInfo(MethodInstance for fpsort!(::Vector{Float64}, ::Base.Sort.QuickSortAlg, ::Base.Order.ForwardOrdering), 0x00000000000072e4, Any[], Any[Vector{Float64}, Core.Const(Base.Sort.QuickSortAlg()), Core.Const(Base.Order.ForwardOrdering()), Union{}, Union{}, Union{}, Union{}, Union{}, Union{}, Union{}, Union{}, Union{}])
- 0.001618478 => Core.Compiler.Timings.InferenceFrameInfo(MethodInstance for rand!(::Random.MersenneTwister, ::Random.UnsafeView{Float64}, ::Random.SamplerTrivial{Random.CloseOpen01{Float64}, Float64}), 0x00000000000072e4, Any[], Any[Random.MersenneTwister, Random.UnsafeView{Float64}, Core.Const(Random.SamplerTrivial{Random.CloseOpen01{Float64}, Float64}(Random.CloseOpen01{Float64}())), Union{}, Union{}, Union{}, Union{}, Union{}, Union{}, Union{}])
- 0.002289655 => Core.Compiler.Timings.InferenceFrameInfo(MethodInstance for _rand_max383!(::Random.MersenneTwister, ::Random.UnsafeView{Float64}, ::Random.CloseOpen01{Float64}), 0x00000000000072e4, Any[], Any[Random.MersenneTwister, Random.UnsafeView{Float64}, Core.Const(Random.CloseOpen01{Float64}()), Union{}, Union{}, Union{}, Union{}])
- 0.093143594 => Core.Compiler.Timings.InferenceFrameInfo(MethodInstance for ROOT(), 0x0000000000000000, Any[], Any[])
+ 0.001088448 => Core.Compiler.Timings.InferenceFrameInfo(MethodInstance for fpsort!(...
+ 0.001618478 => Core.Compiler.Timings.InferenceFrameInfo(MethodInstance for rand!(...
+ 0.002289655 => Core.Compiler.Timings.InferenceFrameInfo(MethodInstance for _rand_max383!(...
+ 0.093143594 => Core.Compiler.Timings.InferenceFrameInfo(MethodInstance for ROOT(), ...
 
 julia> fg = SnoopCompile.to_flamegraph(timing)
 Node(FlameGraphs.NodeData(ROOT() at typeinfer.jl:70, 0x00, 0:15355670))
diff --git a/src/parcel_snoopi.jl b/src/parcel_snoopi.jl
index 33d415708..676287be2 100644
--- a/src/parcel_snoopi.jl
+++ b/src/parcel_snoopi.jl
@@ -387,8 +387,8 @@ const default_exclusions = Set([
     flatten_times(timing::Core.Compiler.Timings.Timing; tmin_secs = 0.0)
 
 Flatten the execution graph of Timings returned from `@snoopi_deep` into a Vector of pairs,
-with the exclusive time for each invcation of type inference within the compiler, sorted by
-the exclusive time, skipping any frames that took less than `tmin_secs` seconds.
+with the exclusive time for each invocation of type inference, skipping any frames that
+took less than `tmin_secs` seconds. Results are sorted by time.
 """
 function flatten_times(timing::Core.Compiler.Timings.Timing; tmin_secs = 0.0)
     out = Pair{Float64,Core.Compiler.Timings.InferenceFrameInfo}[]
@@ -408,7 +408,7 @@ end
 import FlameGraphs
 
 using Base.StackTraces: StackFrame
-using LeftChildRightSiblingTrees: Node, addchild
+using FlameGraphs.LeftChildRightSiblingTrees: Node, addchild
 using Core.Compiler.Timings: Timing
 
 struct InclusiveTiming

From 4e6b74faa247bf2e52cf2a004b22311a7a8997ac Mon Sep 17 00:00:00 2001
From: Nathan Daly <nhdaly@gmail.com>
Date: Mon, 26 Oct 2020 10:31:38 -0400
Subject: [PATCH 45/49] Split out `snoopi_deep` into separate, version-guarded
 files:

- src/parcel_snoopi_deep.jl
- SnoopCompileCore/src/snoopi_deep.jl
- test/snoopi_deep.jl
---
 SnoopCompileCore/src/SnoopCompileCore.jl |   3 +
 SnoopCompileCore/src/snoopi.jl           |  73 ------------
 SnoopCompileCore/src/snoopi_deep.jl      |  73 ++++++++++++
 src/SnoopCompile.jl                      |   4 +
 src/parcel_snoopi.jl                     | 144 -----------------------
 src/parcel_snoopi_deep.jl                | 140 ++++++++++++++++++++++
 test/runtests.jl                         |   9 +-
 test/snoopi.jl                           |  45 +------
 test/snoopi_deep.jl                      |  58 +++++++++
 9 files changed, 287 insertions(+), 262 deletions(-)
 create mode 100644 SnoopCompileCore/src/snoopi_deep.jl
 create mode 100644 src/parcel_snoopi_deep.jl
 create mode 100644 test/snoopi_deep.jl

diff --git a/SnoopCompileCore/src/SnoopCompileCore.jl b/SnoopCompileCore/src/SnoopCompileCore.jl
index aea1cb1bd..6eb73d059 100644
--- a/SnoopCompileCore/src/SnoopCompileCore.jl
+++ b/SnoopCompileCore/src/SnoopCompileCore.jl
@@ -11,6 +11,9 @@ if VERSION >= v"1.2.0-DEV.573"
     include("snoopi.jl")
 end
 
+if VERSION >= v"1.6.0-DEV.1190"  # https://github.com/JuliaLang/julia/pull/37749
+    include("snoopi_deep.jl")
+end
 
 if VERSION >= v"1.6.0-DEV.154"
     include("snoopr.jl")
diff --git a/SnoopCompileCore/src/snoopi.jl b/SnoopCompileCore/src/snoopi.jl
index ccd89acea..2ff0dbd9d 100644
--- a/SnoopCompileCore/src/snoopi.jl
+++ b/SnoopCompileCore/src/snoopi.jl
@@ -86,74 +86,6 @@ 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
-
-"""
-    timing_tree = @snoopi_deep commands
-
-Produce a profile of julia's type inference, containing the amount of time spent inferring
-every `MethodInstance` processed while executing `commands`.
-
-The top-level node in this profile tree is `ROOT`, which contains the time spent _not_ in
-julia's type inference (codegen, llvm_opt, runtime, etc).
-
-To make use of these results, see the processing functions in SnoopCompile:
-    - [`SnoopCompile.flatten_times(timing_tree)`](@ref)
-    - [`SnoopCompile.to_flamegraph(timing_tree)`](@ref)
-
-# Examples
-```julia
-julia> timing = SnoopCompileCore.@snoopi_deep begin
-           @eval sort(rand(100))  # Evaluate some code and profile julia's type inference
-       end;
-
-julia> using SnoopCompile, ProfileView
-
-julia> times = SnoopCompile.flatten_times(timing, tmin_secs=0.001)
-4-element Vector{Any}:
- 0.001088448 => Core.Compiler.Timings.InferenceFrameInfo(MethodInstance for fpsort!(...
- 0.001618478 => Core.Compiler.Timings.InferenceFrameInfo(MethodInstance for rand!(...
- 0.002289655 => Core.Compiler.Timings.InferenceFrameInfo(MethodInstance for _rand_max383!(...
- 0.093143594 => Core.Compiler.Timings.InferenceFrameInfo(MethodInstance for ROOT(), ...
-
-julia> fg = SnoopCompile.to_flamegraph(timing)
-Node(FlameGraphs.NodeData(ROOT() at typeinfer.jl:70, 0x00, 0:15355670))
-
-julia> ProfileView.view(fg);  # Display the FlameGraph in a package that supports it
-
-julia> fg = SnoopCompile.to_flamegraph(timing; tmin_secs=0.0001)  # Skip very tiny frames
-Node(FlameGraphs.NodeData(ROOT() at typeinfer.jl:70, 0x00, 0:15355670))
-```
-
-"""
-macro snoopi_deep(cmd)
-    return _snoopi_deep(cmd)
-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
@@ -168,10 +100,5 @@ function __init__()
     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, ())
-
     nothing
 end
diff --git a/SnoopCompileCore/src/snoopi_deep.jl b/SnoopCompileCore/src/snoopi_deep.jl
new file mode 100644
index 000000000..3c7e3d1e9
--- /dev/null
+++ b/SnoopCompileCore/src/snoopi_deep.jl
@@ -0,0 +1,73 @@
+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
+
+"""
+    timing_tree = @snoopi_deep commands
+
+Produce a profile of julia's type inference, containing the amount of time spent inferring
+every `MethodInstance` processed while executing `commands`.
+
+The top-level node in this profile tree is `ROOT`, which contains the time spent _not_ in
+julia's type inference (codegen, llvm_opt, runtime, etc).
+
+To make use of these results, see the processing functions in SnoopCompile:
+    - [`SnoopCompile.flatten_times(timing_tree)`](@ref)
+    - [`SnoopCompile.to_flamegraph(timing_tree)`](@ref)
+
+# Examples
+```julia
+julia> timing = SnoopCompileCore.@snoopi_deep begin
+           @eval sort(rand(100))  # Evaluate some code and profile julia's type inference
+       end;
+
+julia> using SnoopCompile, ProfileView
+
+julia> times = SnoopCompile.flatten_times(timing, tmin_secs=0.001)
+4-element Vector{Any}:
+ 0.001088448 => Core.Compiler.Timings.InferenceFrameInfo(MethodInstance for fpsort!(...
+ 0.001618478 => Core.Compiler.Timings.InferenceFrameInfo(MethodInstance for rand!(...
+ 0.002289655 => Core.Compiler.Timings.InferenceFrameInfo(MethodInstance for _rand_max383!(...
+ 0.093143594 => Core.Compiler.Timings.InferenceFrameInfo(MethodInstance for ROOT(), ...
+
+julia> fg = SnoopCompile.to_flamegraph(timing)
+Node(FlameGraphs.NodeData(ROOT() at typeinfer.jl:70, 0x00, 0:15355670))
+
+julia> ProfileView.view(fg);  # Display the FlameGraph in a package that supports it
+
+julia> fg = SnoopCompile.to_flamegraph(timing; tmin_secs=0.0001)  # Skip very tiny frames
+Node(FlameGraphs.NodeData(ROOT() at typeinfer.jl:70, 0x00, 0:15355670))
+```
+
+"""
+macro snoopi_deep(cmd)
+    return _snoopi_deep(cmd)
+end
+
+# These are okay to come at the top-level because we're only measuring inference, and
+# inference results will be cached in a `.ji` file.
+@assert precompile(Core.Compiler.Timings.reset_timings, ())
+@assert precompile(start_deep_timing, ())
+@assert precompile(stop_deep_timing, ())
+@assert precompile(finish_snoopi_deep, ())
diff --git a/src/SnoopCompile.jl b/src/SnoopCompile.jl
index 4419c0528..809ffd152 100644
--- a/src/SnoopCompile.jl
+++ b/src/SnoopCompile.jl
@@ -24,6 +24,10 @@ if VERSION >= v"1.2.0-DEV.573"
     include("parcel_snoopi.jl")
 end
 
+if VERSION >= v"1.6.0-DEV.1190"  # https://github.com/JuliaLang/julia/pull/37749
+    include("parcel_snoopi_deep.jl")
+end
+
 if isdefined(SnoopCompileCore, Symbol("@snoopr"))
     include("invalidations.jl")
 end
diff --git a/src/parcel_snoopi.jl b/src/parcel_snoopi.jl
index 676287be2..775e6f40d 100644
--- a/src/parcel_snoopi.jl
+++ b/src/parcel_snoopi.jl
@@ -380,147 +380,3 @@ end
 const default_exclusions = Set([
     r"\bMain\b",
 ])
-
-# === @snoopi_deep helper functions ========================================================
-
-"""
-    flatten_times(timing::Core.Compiler.Timings.Timing; tmin_secs = 0.0)
-
-Flatten the execution graph of Timings returned from `@snoopi_deep` into a Vector of pairs,
-with the exclusive time for each invocation of type inference, skipping any frames that
-took less than `tmin_secs` seconds. Results are sorted by time.
-"""
-function flatten_times(timing::Core.Compiler.Timings.Timing; tmin_secs = 0.0)
-    out = Pair{Float64,Core.Compiler.Timings.InferenceFrameInfo}[]
-    frontier = [timing]
-    while !isempty(frontier)
-        t = popfirst!(frontier)
-        exclusive_time = (t.time / 1e9)
-        if exclusive_time >= tmin_secs
-            push!(out, exclusive_time => t.mi_info)
-        end
-        append!(frontier, t.children)
-    end
-    return sort(out; by=tl->tl[1])
-end
-
-
-import FlameGraphs
-
-using Base.StackTraces: StackFrame
-using FlameGraphs.LeftChildRightSiblingTrees: Node, addchild
-using Core.Compiler.Timings: Timing
-
-struct InclusiveTiming
-    mi_info::Core.Compiler.Timings.InferenceFrameInfo
-    inclusive_time::UInt64
-    start_time::UInt64
-    children::Vector{InclusiveTiming}
-end
-
-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
-
-"""
-    to_flamegraph(t::Core.Compiler.Timings.Timing; tmin_secs=0.0)
-    to_flamegraph(t::SnoopCompile.InclusiveTiming; tmin_secs=0.0)
-
-Convert the call tree of inference timings returned from `@snoopi_deep` into a FlameGraph.
-Returns a FlameGraphs.FlameGraph structure that represents the timing trace recorded for
-type inference.
-
-Frames that take less than `tmin_secs` seconds of _inclusive time_ will not be included
-in the resultant FlameGraph (meaning total time including it and all of its children).
-This can be helpful if you have a very big profile, to save on processing time.
-
-# Examples
-```julia
-julia> timing = SnoopCompileCore.@snoopi_deep begin
-           @eval sort(rand(100))  # Evaluate some code and profile julia's type inference
-       end;
-
-julia> fg = SnoopCompile.to_flamegraph(timing)
-Node(FlameGraphs.NodeData(ROOT() at typeinfer.jl:70, 0x00, 0:15355670))
-
-julia> ProfileView.view(fg);  # Display the FlameGraph in a package that supports it
-
-julia> fg = SnoopCompile.to_flamegraph(timing; tmin_secs=0.0001)  # Skip very tiny frames
-Node(FlameGraphs.NodeData(ROOT() at typeinfer.jl:70, 0x00, 0:15355670))
-```
-
-NOTE: This function must touch every frame in the provided `Timing` to build inclusive
-timing information (`InclusiveTiming`). If you have a very large profile, and you plan to
-call this function multiple times (say with different values for `tmin_secs`), you can save
-some intermediate time by first calling [`build_inclusive_times(t)`](@ref), only once,
-and then passing in the `InclusiveTiming` object for all subsequent calls.
-"""
-function to_flamegraph(t::Timing; tmin_secs = 0.0)
-    it = build_inclusive_times(t)
-    to_flamegraph(it; tmin_secs=tmin_secs)
-end
-
-function to_flamegraph(to::InclusiveTiming; tmin_secs = 0.0)
-    tmin_ns = UInt64(round(tmin_secs * 1e9))
-
-    # 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 _build_flamegraph!(root, to, to.start_time, tmin_ns)
-end
-function _build_flamegraph!(root, to::InclusiveTiming, start_ns, tmin_ns)
-    for child in to.children
-        if child.inclusive_time > tmin_ns
-            node_data = _flamegraph_frame(child, start_ns; toplevel=false)
-            node = addchild(root, node_data)
-            _build_flamegraph!(node, child, start_ns, tmin_ns)
-        end
-    end
-    return root
-end
-
-function frame_name(mi_info::Core.Compiler.Timings.InferenceFrameInfo)
-    frame_name(mi_info.mi::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))
-    return v
-end
-
-# NOTE: The "root" node doesn't cover the 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;
-                    init = UInt64(t.start_time + t.inclusive_time))
-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
-    mi = to.mi_info.mi
-    tt = Symbol(frame_name(to.mi_info))
-    sf = StackFrame(tt, mi.def.file, mi.def.line, mi, 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) : Int(max_end_time(to) - start_ns)
-    else
-        range = Int(start) : Int(start + to.inclusive_time)
-    end
-    return FlameGraphs.NodeData(sf, status, range)
-end
diff --git a/src/parcel_snoopi_deep.jl b/src/parcel_snoopi_deep.jl
new file mode 100644
index 000000000..1836e0cac
--- /dev/null
+++ b/src/parcel_snoopi_deep.jl
@@ -0,0 +1,140 @@
+import FlameGraphs
+
+using Base.StackTraces: StackFrame
+using FlameGraphs.LeftChildRightSiblingTrees: Node, addchild
+using Core.Compiler.Timings: Timing
+
+"""
+    flatten_times(timing::Core.Compiler.Timings.Timing; tmin_secs = 0.0)
+
+Flatten the execution graph of Timings returned from `@snoopi_deep` into a Vector of pairs,
+with the exclusive time for each invocation of type inference, skipping any frames that
+took less than `tmin_secs` seconds. Results are sorted by time.
+"""
+function flatten_times(timing::Core.Compiler.Timings.Timing; tmin_secs = 0.0)
+    out = Pair{Float64,Core.Compiler.Timings.InferenceFrameInfo}[]
+    frontier = [timing]
+    while !isempty(frontier)
+        t = popfirst!(frontier)
+        exclusive_time = (t.time / 1e9)
+        if exclusive_time >= tmin_secs
+            push!(out, exclusive_time => t.mi_info)
+        end
+        append!(frontier, t.children)
+    end
+    return sort(out; by=tl->tl[1])
+end
+
+struct InclusiveTiming
+    mi_info::Core.Compiler.Timings.InferenceFrameInfo
+    inclusive_time::UInt64
+    start_time::UInt64
+    children::Vector{InclusiveTiming}
+end
+
+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
+
+"""
+    to_flamegraph(t::Core.Compiler.Timings.Timing; tmin_secs=0.0)
+    to_flamegraph(t::SnoopCompile.InclusiveTiming; tmin_secs=0.0)
+
+Convert the call tree of inference timings returned from `@snoopi_deep` into a FlameGraph.
+Returns a FlameGraphs.FlameGraph structure that represents the timing trace recorded for
+type inference.
+
+Frames that take less than `tmin_secs` seconds of _inclusive time_ will not be included
+in the resultant FlameGraph (meaning total time including it and all of its children).
+This can be helpful if you have a very big profile, to save on processing time.
+
+# Examples
+```julia
+julia> timing = SnoopCompileCore.@snoopi_deep begin
+           @eval sort(rand(100))  # Evaluate some code and profile julia's type inference
+       end;
+
+julia> fg = SnoopCompile.to_flamegraph(timing)
+Node(FlameGraphs.NodeData(ROOT() at typeinfer.jl:70, 0x00, 0:15355670))
+
+julia> ProfileView.view(fg);  # Display the FlameGraph in a package that supports it
+
+julia> fg = SnoopCompile.to_flamegraph(timing; tmin_secs=0.0001)  # Skip very tiny frames
+Node(FlameGraphs.NodeData(ROOT() at typeinfer.jl:70, 0x00, 0:15355670))
+```
+
+NOTE: This function must touch every frame in the provided `Timing` to build inclusive
+timing information (`InclusiveTiming`). If you have a very large profile, and you plan to
+call this function multiple times (say with different values for `tmin_secs`), you can save
+some intermediate time by first calling [`build_inclusive_times(t)`](@ref), only once,
+and then passing in the `InclusiveTiming` object for all subsequent calls.
+"""
+function to_flamegraph(t::Timing; tmin_secs = 0.0)
+    it = build_inclusive_times(t)
+    to_flamegraph(it; tmin_secs=tmin_secs)
+end
+
+function to_flamegraph(to::InclusiveTiming; tmin_secs = 0.0)
+    tmin_ns = UInt64(round(tmin_secs * 1e9))
+
+    # 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 _build_flamegraph!(root, to, to.start_time, tmin_ns)
+end
+function _build_flamegraph!(root, to::InclusiveTiming, start_ns, tmin_ns)
+    for child in to.children
+        if child.inclusive_time > tmin_ns
+            node_data = _flamegraph_frame(child, start_ns; toplevel=false)
+            node = addchild(root, node_data)
+            _build_flamegraph!(node, child, start_ns, tmin_ns)
+        end
+    end
+    return root
+end
+
+function frame_name(mi_info::Core.Compiler.Timings.InferenceFrameInfo)
+    frame_name(mi_info.mi::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))
+    return v
+end
+
+# NOTE: The "root" node doesn't cover the 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;
+                    init = UInt64(t.start_time + t.inclusive_time))
+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
+    mi = to.mi_info.mi
+    tt = Symbol(frame_name(to.mi_info))
+    sf = StackFrame(tt, mi.def.file, mi.def.line, mi, 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) : Int(max_end_time(to) - start_ns)
+    else
+        range = Int(start) : Int(start + to.inclusive_time)
+    end
+    return FlameGraphs.NodeData(sf, status, range)
+end
\ No newline at end of file
diff --git a/test/runtests.jl b/test/runtests.jl
index 1fda2d0a3..c2e5f75e3 100644
--- a/test/runtests.jl
+++ b/test/runtests.jl
@@ -1,11 +1,18 @@
+using Test
+
 if VERSION >= v"1.2.0-DEV.573"
     include("snoopi.jl")
 end
 
+if VERSION >= v"1.6.0-DEV.1190"  # https://github.com/JuliaLang/julia/pull/37749
+    @testset "snoopi_deep" begin
+        include("snoopi_deep.jl")
+    end
+end
+
 using SnoopCompile
 using JLD
 using SparseArrays
-using Test
 
 # issue #26
 logfile = joinpath(tempdir(), "anon.log")
diff --git a/test/snoopi.jl b/test/snoopi.jl
index 15eb013bb..f4e39b1ac 100644
--- a/test/snoopi.jl
+++ b/test/snoopi.jl
@@ -106,7 +106,7 @@ uncompiled(x) = x + 1
     @test any(str->occursin("typeof(which(FuncKinds.gen2,($Int,Any,)).generator.gen)", str), FK)
     @test any(str->occursin("precompile(Tuple{typeof(FuncKinds.genkw1)})", str), FK)
     @test !any(str->occursin("precompile(Tuple{typeof(FuncKinds.genkw2)})", str), FK)
-    @test any(str->occursin("Tuple{Core.kwftype(typeof(FuncKinds.genkw2)),NamedTuple{(:b,),Tuple{String}},typeof(FuncKinds.genkw2)}", str), FK)
+    @test any(str->occursin("Tuple{Core.kwftype(typeof(FuncKinds.genkw2)),NamedTuple{(:b,), Tuple{String}},typeof(FuncKinds.genkw2)}", str), FK)
     if VERSION >=  v"1.4.0-DEV.215"
         @test any(str->occursin("__lookup_kwbody__(which(FuncKinds.genkw1, ()))", str), FK)
         @test any(str->occursin("__lookup_kwbody__(which(FuncKinds.genkw2, ()))", str), FK)
@@ -220,46 +220,3 @@ end
     pc = SnoopCompile.parcel(tinf, remove_exclusions = false)
     @test count(isequal("Base.precompile(Tuple{typeof(generated)})"), pc[:Main]) == 1
 end
-
-using AbstractTrees  # For FlameGraphs tests
-
-@testset "@snoopi_deep" begin
-    # WARMUP
-    @eval module M  # Example with some functions that include type instability
-        i(x) = x+5
-        h(a::Array) = i(a[1]::Integer) + 2
-        g(y::Integer) = h(Any[y])
-    end
-    M.g(2)  # Warmup all deeply reachable functions
-
-    # Redefine the module, so the snoop will only show these functions:
-    @eval module M  # Example with some functions that include type instability
-        i(x) = x+5
-        h(a::Array) = i(a[1]::Integer) + 2
-        g(y::Integer) = h(Any[y])
-    end
-
-    timing = SnoopCompileCore.@snoopi_deep begin
-        M.g(2)
-    end
-    times = SnoopCompile.flatten_times(timing)
-    @test length(times) == 5  # ROOT, g(...), h(...), i(::Integer), i(::Int)
-    names = [mi_info.mi.def.name for (time, mi_info) in times]
-    @test sort(names) == [:ROOT, :g, :h, :i, :i]
-
-    longest_frame_time = times[end][1]
-    @test length(SnoopCompile.flatten_times(timing, tmin_secs=longest_frame_time)) == 1
-
-    # Test FlameGraph export
-    fg = SnoopCompile.to_flamegraph(timing)
-    @test length(collect(AbstractTrees.PreOrderDFS(fg))) == 5
-    # Test that the span covers the whole tree.
-    for leaf in AbstractTrees.PreOrderDFS(fg)
-        @test leaf.data.span.start in fg.data.span
-        @test leaf.data.span.stop in fg.data.span
-    end
-
-    cutoff_bottom_frame = (times[1][1] + times[2][1]) / 2
-    fg2 = SnoopCompile.to_flamegraph(timing, tmin_secs = cutoff_bottom_frame)
-    @test length(collect(AbstractTrees.PreOrderDFS(fg2))) == (length(collect(AbstractTrees.PreOrderDFS(fg))) - 1)
-end
diff --git a/test/snoopi_deep.jl b/test/snoopi_deep.jl
new file mode 100644
index 000000000..2d42f50f5
--- /dev/null
+++ b/test/snoopi_deep.jl
@@ -0,0 +1,58 @@
+using SnoopCompile
+using SnoopCompile.SnoopCompileCore
+using Test
+
+using AbstractTrees  # For FlameGraphs tests
+
+@testset "@snoopi_deep" begin
+    # WARMUP (to compile all the small, reachable methods)
+    @eval module M  # Example with some functions that include type instability
+        i(x) = x+5
+        h(a::Array) = i(a[1]::Integer) + 2
+        g(y::Integer) = h(Any[y])
+    end
+    M.g(2)  # Warmup all deeply reachable functions
+
+    # Redefine the module, so the snoop will only show these functions:
+    @eval module M  # Example with some functions that include type instability
+        i(x) = x+5
+        h(a::Array) = i(a[1]::Integer) + 2
+        g(y::Integer) = h(Any[y])
+    end
+
+    timing = SnoopCompileCore.@snoopi_deep begin
+        M.g(2)
+    end
+    times = SnoopCompile.flatten_times(timing)
+    @test length(times) == 5  # ROOT, g(...), h(...), i(::Integer), i(::Int)
+    names = [mi_info.mi.def.name for (time, mi_info) in times]
+    @test sort(names) == [:ROOT, :g, :h, :i, :i]
+
+    longest_frame_time = times[end][1]
+    @test length(SnoopCompile.flatten_times(timing, tmin_secs=longest_frame_time)) == 1
+end
+
+@testset "flamegraph_export" begin
+    @eval module M  # Take another timing
+        i(x) = x+5
+        h(a::Array) = i(a[1]::Integer) + 2
+        g(y::Integer) = h(Any[y])
+    end
+
+    timing = SnoopCompileCore.@snoopi_deep begin
+        M.g(2)
+    end
+    times = SnoopCompile.flatten_times(timing)
+
+    fg = SnoopCompile.to_flamegraph(timing)
+    @test length(collect(AbstractTrees.PreOrderDFS(fg))) == 5
+    # Test that the span covers the whole tree.
+    for leaf in AbstractTrees.PreOrderDFS(fg)
+        @test leaf.data.span.start in fg.data.span
+        @test leaf.data.span.stop in fg.data.span
+    end
+
+    cutoff_bottom_frame = (times[1][1] + times[2][1]) / 2
+    fg2 = SnoopCompile.to_flamegraph(timing, tmin_secs = cutoff_bottom_frame)
+    @test length(collect(AbstractTrees.PreOrderDFS(fg2))) == (length(collect(AbstractTrees.PreOrderDFS(fg))) - 1)
+end

From 49ce9f22e2a51c5fa1ceb4b69a9a95db55ae3fed Mon Sep 17 00:00:00 2001
From: Nathan Daly <nhdaly@gmail.com>
Date: Wed, 28 Oct 2020 11:28:16 -0400
Subject: [PATCH 46/49] Simplify the logic in `SnoopCompile.max_end_time()` and
 add comments

---
 src/parcel_snoopi_deep.jl | 10 ++++++++--
 1 file changed, 8 insertions(+), 2 deletions(-)

diff --git a/src/parcel_snoopi_deep.jl b/src/parcel_snoopi_deep.jl
index 1836e0cac..5d95036d1 100644
--- a/src/parcel_snoopi_deep.jl
+++ b/src/parcel_snoopi_deep.jl
@@ -118,8 +118,14 @@ end
 # 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;
-                    init = UInt64(t.start_time + t.inclusive_time))
+    # It's possible that t is already the longest-reaching node.
+    t_end = UInt64(t.start_time + t.inclusive_time)
+    # It's also possible that the last child extends past the end of t. (I think this is
+    # possible because of the small unmeasured overhead in computing these measurements.)
+    last_node = length(t.children) > 0 ? t.children[end] : t
+    child_end = last_node.start_time + last_node.inclusive_time
+    # Return the maximum end time to make sure the top node covers the entire graph.
+    return max(t_end, child_end)
 end
 
 # Make a flat frame for this Timing

From 2723e482ff6cd20be61c917c98c01a3f032e2d3a Mon Sep 17 00:00:00 2001
From: Nathan Daly <nhdaly@gmail.com>
Date: Thu, 29 Oct 2020 12:54:36 -0400
Subject: [PATCH 47/49] Change `to_flamegraph()` to `flamegraph()`

- adds method to `flamegraph()` constructor: `flamegraph(::Timing)`
---
 SnoopCompileCore/src/snoopi_deep.jl |  6 +++---
 src/SnoopCompile.jl                 |  3 +++
 src/parcel_snoopi_deep.jl           | 16 +++++++++-------
 test/snoopi_deep.jl                 |  4 ++--
 4 files changed, 17 insertions(+), 12 deletions(-)

diff --git a/SnoopCompileCore/src/snoopi_deep.jl b/SnoopCompileCore/src/snoopi_deep.jl
index 3c7e3d1e9..f3ecbf2fd 100644
--- a/SnoopCompileCore/src/snoopi_deep.jl
+++ b/SnoopCompileCore/src/snoopi_deep.jl
@@ -34,7 +34,7 @@ julia's type inference (codegen, llvm_opt, runtime, etc).
 
 To make use of these results, see the processing functions in SnoopCompile:
     - [`SnoopCompile.flatten_times(timing_tree)`](@ref)
-    - [`SnoopCompile.to_flamegraph(timing_tree)`](@ref)
+    - [`SnoopCompile.flamegraph(timing_tree)`](@ref)
 
 # Examples
 ```julia
@@ -51,12 +51,12 @@ julia> times = SnoopCompile.flatten_times(timing, tmin_secs=0.001)
  0.002289655 => Core.Compiler.Timings.InferenceFrameInfo(MethodInstance for _rand_max383!(...
  0.093143594 => Core.Compiler.Timings.InferenceFrameInfo(MethodInstance for ROOT(), ...
 
-julia> fg = SnoopCompile.to_flamegraph(timing)
+julia> fg = SnoopCompile.flamegraph(timing)
 Node(FlameGraphs.NodeData(ROOT() at typeinfer.jl:70, 0x00, 0:15355670))
 
 julia> ProfileView.view(fg);  # Display the FlameGraph in a package that supports it
 
-julia> fg = SnoopCompile.to_flamegraph(timing; tmin_secs=0.0001)  # Skip very tiny frames
+julia> fg = SnoopCompile.flamegraph(timing; tmin_secs=0.0001)  # Skip very tiny frames
 Node(FlameGraphs.NodeData(ROOT() at typeinfer.jl:70, 0x00, 0:15355670))
 ```
 
diff --git a/src/SnoopCompile.jl b/src/SnoopCompile.jl
index 809ffd152..43a41d2ca 100644
--- a/src/SnoopCompile.jl
+++ b/src/SnoopCompile.jl
@@ -3,6 +3,9 @@ module SnoopCompile
 using SnoopCompileCore
 export @snoopc
 isdefined(SnoopCompileCore, Symbol("@snoopi")) && export @snoopi
+if isdefined(SnoopCompileCore, Symbol("@snoopi_deep"))
+    export @snoopi_deep, flamegraph, flatten_times
+end
 if isdefined(SnoopCompileCore, Symbol("@snoopr"))
     export @snoopr, uinvalidated, invalidation_trees, filtermod, findcaller, ascend
 end
diff --git a/src/parcel_snoopi_deep.jl b/src/parcel_snoopi_deep.jl
index 5d95036d1..92f0106fd 100644
--- a/src/parcel_snoopi_deep.jl
+++ b/src/parcel_snoopi_deep.jl
@@ -4,6 +4,8 @@ using Base.StackTraces: StackFrame
 using FlameGraphs.LeftChildRightSiblingTrees: Node, addchild
 using Core.Compiler.Timings: Timing
 
+const flamegraph = FlameGraphs.flamegraph  # For re-export
+
 """
     flatten_times(timing::Core.Compiler.Timings.Timing; tmin_secs = 0.0)
 
@@ -44,8 +46,8 @@ function build_inclusive_times(t::Timing)
 end
 
 """
-    to_flamegraph(t::Core.Compiler.Timings.Timing; tmin_secs=0.0)
-    to_flamegraph(t::SnoopCompile.InclusiveTiming; tmin_secs=0.0)
+    flamegraph(t::Core.Compiler.Timings.Timing; tmin_secs=0.0)
+    flamegraph(t::SnoopCompile.InclusiveTiming; tmin_secs=0.0)
 
 Convert the call tree of inference timings returned from `@snoopi_deep` into a FlameGraph.
 Returns a FlameGraphs.FlameGraph structure that represents the timing trace recorded for
@@ -61,12 +63,12 @@ julia> timing = SnoopCompileCore.@snoopi_deep begin
            @eval sort(rand(100))  # Evaluate some code and profile julia's type inference
        end;
 
-julia> fg = SnoopCompile.to_flamegraph(timing)
+julia> fg = SnoopCompile.flamegraph(timing)
 Node(FlameGraphs.NodeData(ROOT() at typeinfer.jl:70, 0x00, 0:15355670))
 
 julia> ProfileView.view(fg);  # Display the FlameGraph in a package that supports it
 
-julia> fg = SnoopCompile.to_flamegraph(timing; tmin_secs=0.0001)  # Skip very tiny frames
+julia> fg = SnoopCompile.flamegraph(timing; tmin_secs=0.0001)  # Skip very tiny frames
 Node(FlameGraphs.NodeData(ROOT() at typeinfer.jl:70, 0x00, 0:15355670))
 ```
 
@@ -76,12 +78,12 @@ call this function multiple times (say with different values for `tmin_secs`), y
 some intermediate time by first calling [`build_inclusive_times(t)`](@ref), only once,
 and then passing in the `InclusiveTiming` object for all subsequent calls.
 """
-function to_flamegraph(t::Timing; tmin_secs = 0.0)
+function FlameGraphs.flamegraph(t::Timing; tmin_secs = 0.0)
     it = build_inclusive_times(t)
-    to_flamegraph(it; tmin_secs=tmin_secs)
+    flamegraph(it; tmin_secs=tmin_secs)
 end
 
-function to_flamegraph(to::InclusiveTiming; tmin_secs = 0.0)
+function FlameGraphs.flamegraph(to::InclusiveTiming; tmin_secs = 0.0)
     tmin_ns = UInt64(round(tmin_secs * 1e9))
 
     # Compute a "root" frame for the top-level node, to cover the whole profile
diff --git a/test/snoopi_deep.jl b/test/snoopi_deep.jl
index 2d42f50f5..e60e3a19a 100644
--- a/test/snoopi_deep.jl
+++ b/test/snoopi_deep.jl
@@ -44,7 +44,7 @@ end
     end
     times = SnoopCompile.flatten_times(timing)
 
-    fg = SnoopCompile.to_flamegraph(timing)
+    fg = SnoopCompile.flamegraph(timing)
     @test length(collect(AbstractTrees.PreOrderDFS(fg))) == 5
     # Test that the span covers the whole tree.
     for leaf in AbstractTrees.PreOrderDFS(fg)
@@ -53,6 +53,6 @@ end
     end
 
     cutoff_bottom_frame = (times[1][1] + times[2][1]) / 2
-    fg2 = SnoopCompile.to_flamegraph(timing, tmin_secs = cutoff_bottom_frame)
+    fg2 = SnoopCompile.flamegraph(timing, tmin_secs = cutoff_bottom_frame)
     @test length(collect(AbstractTrees.PreOrderDFS(fg2))) == (length(collect(AbstractTrees.PreOrderDFS(fg))) - 1)
 end

From 53d6bf8dfdd6b86fc45d13307cdf96e989d62cb3 Mon Sep 17 00:00:00 2001
From: Nathan Daly <nhdaly@gmail.com>
Date: Thu, 29 Oct 2020 12:57:09 -0400
Subject: [PATCH 48/49] Remove qualified names from docstring examples

Fix up docstrings; remove resolved TODO
---
 SnoopCompileCore/src/snoopi_deep.jl | 9 ++++-----
 src/parcel_snoopi_deep.jl           | 7 +++----
 2 files changed, 7 insertions(+), 9 deletions(-)

diff --git a/SnoopCompileCore/src/snoopi_deep.jl b/SnoopCompileCore/src/snoopi_deep.jl
index f3ecbf2fd..355ba6240 100644
--- a/SnoopCompileCore/src/snoopi_deep.jl
+++ b/SnoopCompileCore/src/snoopi_deep.jl
@@ -38,28 +38,27 @@ To make use of these results, see the processing functions in SnoopCompile:
 
 # Examples
 ```julia
-julia> timing = SnoopCompileCore.@snoopi_deep begin
+julia> timing = @snoopi_deep begin
            @eval sort(rand(100))  # Evaluate some code and profile julia's type inference
        end;
 
 julia> using SnoopCompile, ProfileView
 
-julia> times = SnoopCompile.flatten_times(timing, tmin_secs=0.001)
+julia> times = flatten_times(timing, tmin_secs=0.001)
 4-element Vector{Any}:
  0.001088448 => Core.Compiler.Timings.InferenceFrameInfo(MethodInstance for fpsort!(...
  0.001618478 => Core.Compiler.Timings.InferenceFrameInfo(MethodInstance for rand!(...
  0.002289655 => Core.Compiler.Timings.InferenceFrameInfo(MethodInstance for _rand_max383!(...
  0.093143594 => Core.Compiler.Timings.InferenceFrameInfo(MethodInstance for ROOT(), ...
 
-julia> fg = SnoopCompile.flamegraph(timing)
+julia> fg = flamegraph(timing)
 Node(FlameGraphs.NodeData(ROOT() at typeinfer.jl:70, 0x00, 0:15355670))
 
 julia> ProfileView.view(fg);  # Display the FlameGraph in a package that supports it
 
-julia> fg = SnoopCompile.flamegraph(timing; tmin_secs=0.0001)  # Skip very tiny frames
+julia> fg = flamegraph(timing; tmin_secs=0.0001)  # Skip very tiny frames
 Node(FlameGraphs.NodeData(ROOT() at typeinfer.jl:70, 0x00, 0:15355670))
 ```
-
 """
 macro snoopi_deep(cmd)
     return _snoopi_deep(cmd)
diff --git a/src/parcel_snoopi_deep.jl b/src/parcel_snoopi_deep.jl
index 92f0106fd..7ff2ca5eb 100644
--- a/src/parcel_snoopi_deep.jl
+++ b/src/parcel_snoopi_deep.jl
@@ -59,16 +59,16 @@ This can be helpful if you have a very big profile, to save on processing time.
 
 # Examples
 ```julia
-julia> timing = SnoopCompileCore.@snoopi_deep begin
+julia> timing = @snoopi_deep begin
            @eval sort(rand(100))  # Evaluate some code and profile julia's type inference
        end;
 
-julia> fg = SnoopCompile.flamegraph(timing)
+julia> fg = flamegraph(timing)
 Node(FlameGraphs.NodeData(ROOT() at typeinfer.jl:70, 0x00, 0:15355670))
 
 julia> ProfileView.view(fg);  # Display the FlameGraph in a package that supports it
 
-julia> fg = SnoopCompile.flamegraph(timing; tmin_secs=0.0001)  # Skip very tiny frames
+julia> fg = flamegraph(timing; tmin_secs=0.0001)  # Skip very tiny frames
 Node(FlameGraphs.NodeData(ROOT() at typeinfer.jl:70, 0x00, 0:15355670))
 ```
 
@@ -132,7 +132,6 @@ 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
     mi = to.mi_info.mi
     tt = Symbol(frame_name(to.mi_info))
     sf = StackFrame(tt, mi.def.file, mi.def.line, mi, false, false, UInt64(0x0))

From ba358cca4783f50a22ab4936f027f0819403359c Mon Sep 17 00:00:00 2001
From: Nathan Daly <NHDaly@gmail.com>
Date: Thu, 29 Oct 2020 15:42:19 -0400
Subject: [PATCH 49/49] Update src/parcel_snoopi_deep.jl

Co-authored-by: Tim Holy <tim.holy@gmail.com>
---
 src/parcel_snoopi_deep.jl | 4 ++--
 1 file changed, 2 insertions(+), 2 deletions(-)

diff --git a/src/parcel_snoopi_deep.jl b/src/parcel_snoopi_deep.jl
index 7ff2ca5eb..7e3568e26 100644
--- a/src/parcel_snoopi_deep.jl
+++ b/src/parcel_snoopi_deep.jl
@@ -75,7 +75,7 @@ Node(FlameGraphs.NodeData(ROOT() at typeinfer.jl:70, 0x00, 0:15355670))
 NOTE: This function must touch every frame in the provided `Timing` to build inclusive
 timing information (`InclusiveTiming`). If you have a very large profile, and you plan to
 call this function multiple times (say with different values for `tmin_secs`), you can save
-some intermediate time by first calling [`build_inclusive_times(t)`](@ref), only once,
+some intermediate time by first calling [`SnoopCompile.build_inclusive_times(t)`](@ref), only once,
 and then passing in the `InclusiveTiming` object for all subsequent calls.
 """
 function FlameGraphs.flamegraph(t::Timing; tmin_secs = 0.0)
@@ -144,4 +144,4 @@ function _flamegraph_frame(to::InclusiveTiming, start_ns; toplevel)
         range = Int(start) : Int(start + to.inclusive_time)
     end
     return FlameGraphs.NodeData(sf, status, range)
-end
\ No newline at end of file
+end