Add pretty-printing for inference timing

[timholy]

This adds pretty-printing for Core.Compiler.Timings objects. Let's see this in action.

Old printing:

julia> x = (0x01, Float16(1))
(0x01, Float16(1.0))

julia> 2x[1]+2x[2]         # warmup
Float16(4.0)

julia> using SnoopCompile  # currently you have to `dev` both SnoopCompile and SnoopCompileCore

julia> twice(x) = 2x
twice (generic function with 1 method)

julia> f(x) = twice(x[1]) + twice(x[2])
f (generic function with 1 method)

julia> tinf = @snoopi_deep f(x)  # note LOOONG output line
Core.Compiler.Timings.Timing(Core.Compiler.Timings.InferenceFrameInfo(MethodInstance for ROOT(), 0x0000000000000000, Any[], Any[Core.Const(Core.Compiler.Timings.ROOT)], 1, false), 0x000dc0b9fbccf869, 0x000dc0b9fbd473de, 0x00000000007b65e2, Core.Compiler.Timings.Timing[Core.Compiler.Timings.Timing(Core.Compiler.Timings.InferenceFrameInfo(MethodInstance for f(::Tuple{UInt8, Float16}), 0x000000000000732d, Any[], Any[Core.Const(f), Tuple{UInt8, Float16}], 2, false), 0x000dc0b9fbcdd021, 0x000dc0b9fbd18730, 0x0000000000029799, Core.Compiler.Timings.Timing[Core.Compiler.Timings.Timing(Core.Compiler.Timings.InferenceFrameInfo(MethodInstance for getindex(::Tuple{UInt8, Float16}, ::Int64), 0x000000000000732d, Any[], Any[Core.Const(getindex), Tuple{UInt8, Float16}, Core.Const(1)], 3, true), 0x000dc0b9fbce23d8, 0x000dc0b9fbce23d8, 0x00000000000099ba, Core.Compiler.Timings.Timing[], nothing), Core.Compiler.Timings.Timing(Core.Compiler.Timings.InferenceFrameInfo(MethodInstance for twice(::UInt8), 0x000000000000732d, Any[], Any[Core.Const(twice), UInt8], 2, false), 0x000dc0b9fbcefdb7, 0x000dc0b9fbcefdb7, 0x000000000000ecbd, Core.Compiler.Timings.Timing[], nothing), Core.Compiler.Timings.Timing(Core.Compiler.Timings.InferenceFrameInfo(MethodInstance for getindex(::Tuple{UInt8, Float16}, ::Int64), 0x000000000000732d, Any[], Any[Core.Const(getindex), Tuple{UInt8, Float16}, Core.Const(2)], 3, true), 0x000dc0b9fbd011a1, 0x000dc0b9fbd011a1, 0x000000000000788a, Core.Compiler.Timings.Timing[], nothing), Core.Compiler.Timings.Timing(Core.Compiler.Timings.InferenceFrameInfo(MethodInstance for twice(::Float16), 0x000000000000732d, Any[], Any[Core.Const(twice), Float16], 2, false), 0x000dc0b9fbd0b325, 0x000dc0b9fbd0b325, 0x000000000000d374, Core.Compiler.Timings.Timing[], nothing)], Union{Ptr{Nothing}, Core.Compiler.InterpreterIP}[Ptr{Nothing} @0x00007fe9fd5f6fca, Ptr{Nothing} @0x00007fe9fd6176e8, Ptr{Nothing} @0x00007fe9fd3cf2af, Ptr{Nothing} @0x00007fe9fd3cf6a1, Ptr{Nothing} @0x00007fe9fd3cf6df, Ptr{Nothing} @0x00007fea0af8751b, Ptr{Nothing} @0x00007fea0af87f83, Ptr{Nothing} @0x00007fea0b00c314, Ptr{Nothing} @0x00007fea0af850bc, Ptr{Nothing} @0x00007fea0af875e1  …  Ptr{Nothing} @0x00007fe9fd2f6ea8, Ptr{Nothing} @0x00007fe9fd307b01, Ptr{Nothing} @0x00007fe9fd3085d1, Ptr{Nothing} @0x00007fe9fd308745, Ptr{Nothing} @0x00007fea0af8751b, Ptr{Nothing} @0x00007fea0afe3ae4, Ptr{Nothing} @0x00007fea0afe44ba, Ptr{Nothing} @0x0000563744f26c6e, Ptr{Nothing} @0x00007fea0baf2bf6, Ptr{Nothing} @0x0000563744f26ca9])], nothing)

julia> flatten_times(tinf)
6-element Vector{Pair{Float64, Core.Compiler.Timings.InferenceFrameInfo}}:
   3.0858e-5 => Core.Compiler.Timings.InferenceFrameInfo(MethodInstance for getindex(::Tuple{UInt8, Float16}, ::Int64), 0x000000000000732d, Any[], Any[Core.Const(getindex), Tuple{UInt8, Float16}, Core.Const(2)], 3, true)
   3.9354e-5 => Core.Compiler.Timings.InferenceFrameInfo(MethodInstance for getindex(::Tuple{UInt8, Float16}, ::Int64), 0x000000000000732d, Any[], Any[Core.Const(getindex), Tuple{UInt8, Float16}, Core.Const(1)], 3, true)
   5.4132e-5 => Core.Compiler.Timings.InferenceFrameInfo(MethodInstance for twice(::Float16), 0x000000000000732d, Any[], Any[Core.Const(twice), Float16], 2, false)
   6.0605e-5 => Core.Compiler.Timings.InferenceFrameInfo(MethodInstance for twice(::UInt8), 0x000000000000732d, Any[], Any[Core.Const(twice), UInt8], 2, false)
 0.000169881 => Core.Compiler.Timings.InferenceFrameInfo(MethodInstance for f(::Tuple{UInt8, Float16}), 0x000000000000732d, Any[], Any[Core.Const(f), Tuple{UInt8, Float16}], 2, false)
  0.00808701 => Core.Compiler.Timings.InferenceFrameInfo(MethodInstance for ROOT(), 0x0000000000000000, Any[], Any[Core.Const(Core.Compiler.Timings.ROOT)], 1, false)

With the new printing:

julia> Revise.track(Base)

julia> tinf
Core.Compiler.Timings.Timing(InferenceFrameInfo for Core.Compiler.Timings.ROOT()) with 1 children

julia> tinf.children
1-element Vector{Core.Compiler.Timings.Timing}:
 Core.Compiler.Timings.Timing(InferenceFrameInfo for f(::Tuple{UInt8, Float16})) with 4 children

Much shorter, but note that the unqualified ROOT() has become Core.Compiler.Timings.ROOT() to help people find the method. If you do want to see the whole thing at once, you can get that with JuliaCollections/AbstractTrees.jl#65.

Also:

julia> flatten_times(tinf)
6-element Vector{Pair{Float64, Core.Compiler.Timings.InferenceFrameInfo}}:
   3.0858e-5 => InferenceFrameInfo for getindex(::Tuple{UInt8, Float16}, 2::Int64)
   3.9354e-5 => InferenceFrameInfo for getindex(::Tuple{UInt8, Float16}, 1::Int64)
   5.4132e-5 => InferenceFrameInfo for twice(::Float16)
   6.0605e-5 => InferenceFrameInfo for twice(::UInt8)
 0.000169881 => InferenceFrameInfo for f(::Tuple{UInt8, Float16})
  0.00808701 => InferenceFrameInfo for Core.Compiler.Timings.ROOT()

A key feature to notice here is that the Core.Const values are integrated into the signature: getindex(::Tuple{UInt8, Float16}, 2::Int64) means that we inferred x[2] where x::Tuple{UInt8, Float16}.

Review requested from @NHDaly.

EDIT: the original version made changes to MethodInstance printing. I'll submit that separately.

[NHDaly]

👍 Thanks, love this! I've left a small suggestion, but otherwise LGTM

[NHDaly]

Is there nothing else that can be usefully printed, here?

[timholy]

I figured something out. Now it prints thunk from $module starting at $file:$line which seems like an improvement.

[NHDaly]

Amazing. Me too. Thanks!