Add pretty-printing for Core.Compiler.Timings objects (JuliaLang#38596)

* Add minimal printing for Core.Compiler.Timings.Timing

These objects are huge when printed with `show_default`.
This makes the printing very brief. More detail is available with
with AbstractTrees.print_tree.

* Add nice printing for Core.Compiler.Timings.InferenceFrameInfo

This inlines the `Core.Const` args into the signature, which
results in a very compact display of both the type and the value, when applicable.

Co-authored-by: Nathan Daly <[email protected]>

base/show.jl

@@ -999,6 +999,33 @@ function show(io::IO, l::Core.MethodInstance)
  end
 end
 
+# These sometimes show up as Const-values in InferenceFrameInfo signatures
+show(io::IO, r::Core.Compiler.UnitRange) = show(io, r.start : r.stop)
+show(io::IO, mime::MIME{Symbol("text/plain")}, r::Core.Compiler.UnitRange) = show(io, mime, r.start : r.stop)
+
+function show(io::IO, mi_info::Core.Compiler.Timings.InferenceFrameInfo)
+ mi = mi_info.mi
+ def = mi.def
+ if isa(def, Method)
+ if isdefined(def, :generator) && mi === def.generator
+ print(io, "InferenceFrameInfo generator for ")
+ show(io, def)
+ else
+ print(io, "InferenceFrameInfo for ")
+ argnames = [isa(a, Core.Const) ? (isa(a.val, Type) ? "" : a.val) : "" for a in mi_info.slottypes[1:mi_info.nargs]]
+ show_tuple_as_call(io, def.name, mi.specTypes, false, nothing, argnames, true)
+ end
+ else
+ linetable = mi.uninferred.linetable
+ line = isempty(linetable) ? "" : (lt = linetable[1]; string(lt.file) * ':' * string(lt.line))
+ print(io, "Toplevel InferenceFrameInfo thunk from ", def, " starting at ", line)
+ end
+end
+
+function show(io::IO, tinf::Core.Compiler.Timings.Timing)
+ print(io, "Core.Compiler.Timings.Timing(", tinf.mi_info, ") with ", length(tinf.children), " children")
+end
+
 function show_delim_array(io::IO, itr::Union{AbstractArray,SimpleVector}, op, delim, cl,
  delim_one, i1=first(LinearIndices(itr)), l=last(LinearIndices(itr)))
  print(io, op)
@@ -2103,11 +2130,14 @@ end
 
 # show the called object in a signature, given its type `ft`
 # `io` should contain the UnionAll env of the signature
-function show_signature_function(io::IO, @nospecialize(ft), demangle=false, fargname="", html=false)
+function show_signature_function(io::IO, @nospecialize(ft), demangle=false, fargname="", html=false, qualified=false)
  uw = unwrap_unionall(ft)
  if ft <: Function && isa(uw, DataType) && isempty(uw.parameters) &&
  isdefined(uw.name.module, uw.name.mt.name) &&
  ft == typeof(getfield(uw.name.module, uw.name.mt.name))
+ if qualified && !is_exported_from_stdlib(uw.name.mt.name, uw.name.module) && uw.name.module !== Main
+ print_within_stacktrace(io, uw.name.module, '.', bold=true)
+ end
  s = sprint(show_sym, (demangle ? demangle_function_name : identity)(uw.name.mt.name), context=io)
  print_within_stacktrace(io, s, bold=true)
  elseif isa(ft, DataType) && ft.name === Type.body.name &&
@@ -2135,7 +2165,7 @@ function print_within_stacktrace(io, s...; color=:normal, bold=false)
  end
 end
 
-function show_tuple_as_call(io::IO, name::Symbol, sig::Type, demangle=false, kwargs=nothing, argnames=nothing)
+function show_tuple_as_call(io::IO, name::Symbol, sig::Type, demangle=false, kwargs=nothing, argnames=nothing, qualified=false)
  # print a method signature tuple for a lambda definition
  if sig === Tuple
  print(io, demangle ? demangle_function_name(name) : name, "(...)")
@@ -2149,7 +2179,7 @@ function show_tuple_as_call(io::IO, name::Symbol, sig::Type, demangle=false, kwa
  sig = sig.body
  end
  sig = (sig::DataType).parameters
- show_signature_function(env_io, sig[1], demangle)
+ show_signature_function(env_io, sig[1], demangle, "", false, qualified)
  first = true
  print_within_stacktrace(io, "(", bold=true)
  show_argnames = argnames !== nothing && length(argnames) == length(sig)

test/compiler/inference.jl

@@ -2879,6 +2879,7 @@ end
  timing1 = time_inference() do
  @eval M.g(2, 3.0)
  end
+ @test occursin(r"Core.Compiler.Timings.Timing\(InferenceFrameInfo for Core.Compiler.Timings.ROOT\(\)\) with \d+ children", sprint(show, timing1))
  # The last two functions to be inferred should be `i` and `i2`, inferred at runtime with
  # their concrete types.
  @test sort([mi_info.mi.def.name for (time,mi_info) in flatten_times(timing1)[end-1:end]]) == [:i, :i2]
@@ -2889,6 +2890,23 @@ end
  @eval M.g(2, 3.0)
  end
  @test length(flatten_times(timing2)) < length(flatten_times(timing1))
+ # Printing of InferenceFrameInfo for mi.def isa Module
+ @eval 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
+ # BEGIN LINE NUMBER SENSITIVITY (adjust the line offset below as needed)
+ timingmod = time_inference() do
+ @eval @testset "Outer" begin
+ @testset "Inner" begin
+ for i = 1:2 M.g(2, 3.0) end
+ end
+ end
+ end
+ @test occursin("thunk from $(@__MODULE__) starting at $(@__FILE__):$((@__LINE__) - 5)", string(timingmod.children))
+ # END LINE NUMBER SENSITIVITY
 
  # Recursive function
  @eval module _Recursive f(n::Integer) = n == 0 ? 0 : f(n-1) + 1 end
@@ -2903,12 +2921,38 @@ end
  i(x) = x === 0 ? 0 : 1 / x
  a(x) = i(0) * i(x)
  b() = i(0) * i(1) * i(0)
+ function loopc(n)
+ s = 0
+ for i = 1:n
+ s += i
+ end
+ return s
+ end
+ call_loopc() = loopc(5)
+ myfloor(::Type{T}, x) where T = floor(T, x)
+ d(x) = myfloor(Int16, x)
  end
  timing = time_inference() do
  @eval C.a(2)
  @eval C.b()
- end
- @test !isempty(flatten_times(timing))
+ @eval C.call_loopc()
+ @eval C.d(3.2)
+ end
+ ft = flatten_times(timing)
+ @test !isempty(ft)
+ str = sprint(show, ft)
+ @test occursin("InferenceFrameInfo for /(1::$Int, ::$Int)", str) # inference constants
+ @test occursin("InferenceFrameInfo for Core.Compiler.Timings.ROOT()", str) # qualified
+ # loopc has internal slots, check constant printing in this case
+ sel = filter(ti -> ti.second.mi.def.name === :loopc, ft)
+ ifi = sel[end].second
+ @test length(ifi.slottypes) > ifi.nargs
+ str = sprint(show, sel)
+ @test occursin("InferenceFrameInfo for $(@__MODULE__).C.loopc(5::$Int)", str)
+ # check that types aren't double-printed as `T::Type{T}`
+ sel = filter(ti -> ti.second.mi.def.name === :myfloor, ft)
+ str = sprint(show, sel)
+ @test occursin("InferenceFrameInfo for $(@__MODULE__).C.myfloor(::Type{Int16}, ::Float64)", str)
 end
 
 # issue #37638
@@ -2919,4 +2963,3 @@ f37943(x::Any, i::Int) = getfield((x::Pair{false, Int}), i)
 g37943(i::Int) = fieldtype(Pair{false, T} where T, i)
 @test only(Base.return_types(f37943, Tuple{Any, Int})) === Union{}
 @test only(Base.return_types(g37943, Tuple{Int})) === Union{Type{Union{}}, Type{Any}}
-