From 0efef7abe8eaadd5a638e9a291dd999419ec778b Mon Sep 17 00:00:00 2001 From: Valentin Churavy Date: Mon, 17 Apr 2023 15:28:11 -0400 Subject: [PATCH 1/4] [Inference] Mark timing with typeof(interp) Allows consumers to separate native inference from inference coming from a custom AbstractInterpreter. Co-authored-by: Shuhei Kadowaki <40514306+aviatesk@users.noreply.github.com> --- base/compiler/ssair/irinterp.jl | 4 ++-- base/compiler/typeinfer.jl | 24 +++++++++++++++--------- base/show.jl | 2 +- test/compiler/inference.jl | 2 +- 4 files changed, 19 insertions(+), 13 deletions(-) diff --git a/base/compiler/ssair/irinterp.jl b/base/compiler/ssair/irinterp.jl index d171cceb842e9..b8955b7d20d70 100644 --- a/base/compiler/ssair/irinterp.jl +++ b/base/compiler/ssair/irinterp.jl @@ -346,10 +346,10 @@ function ir_abstract_constant_propagation(interp::AbstractInterpreter, irsv::IRI irinterp = switch_to_irinterp(interp) if __measure_typeinf__[] inf_frame = Timings.InferenceFrameInfo(irsv.mi, irsv.world, VarState[], Any[], length(irsv.ir.argtypes)) - Timings.enter_new_timer(inf_frame) + Timings.enter_new_timer(irinterp, inf_frame) ret = _ir_abstract_constant_propagation(irinterp, irsv) append!(inf_frame.slottypes, irsv.ir.argtypes) - Timings.exit_current_timer(inf_frame) + Timings.exit_current_timer(irinterp, inf_frame) return ret else return _ir_abstract_constant_propagation(irinterp, irsv) diff --git a/base/compiler/typeinfer.jl b/base/compiler/typeinfer.jl index 1eec73d0435bd..0839d087eb2fd 100644 --- a/base/compiler/typeinfer.jl +++ b/base/compiler/typeinfer.jl @@ -23,7 +23,7 @@ being used for this purpose alone. module Timings using Core.Compiler: -, +, :, Vector, length, first, empty!, push!, pop!, @inline, - @inbounds, copy, backtrace + @inbounds, copy, backtrace, AbstractInterpreter # What we record for any given frame we infer during type inference. struct InferenceFrameInfo @@ -48,12 +48,13 @@ end _typeinf_identifier(frame::InferenceFrameInfo) = frame """ - Core.Compiler.Timing(mi_info, start_time, ...) + Core.Compiler.Timing(interpT, mi_info, start_time, ...) Internal type containing the timing result for running type inference on a single MethodInstance. """ struct Timing + interpT::DataType mi_info::InferenceFrameInfo start_time::UInt64 cur_start_time::UInt64 @@ -61,8 +62,8 @@ struct Timing children::Core.Array{Timing,1} bt # backtrace collected upon initial entry to typeinf end -Timing(mi_info, start_time, cur_start_time, time, children) = Timing(mi_info, start_time, cur_start_time, time, children, nothing) -Timing(mi_info, start_time) = Timing(mi_info, start_time, start_time, UInt64(0), Timing[]) +Timing(interpT, mi_info, start_time, cur_start_time, time, children) = Timing(interpT, mi_info, start_time, cur_start_time, time, children, nothing) +Timing(interpT, mi_info, start_time) = Timing(interpT, mi_info, start_time, start_time, UInt64(0), Timing[]) _time_ns() = ccall(:jl_hrtime, UInt64, ()) # Re-implemented here because Base not yet available. @@ -88,6 +89,7 @@ start the ROOT() timer again. `ROOT()` measures all time spent _outside_ inferen function reset_timings() empty!(_timings) push!(_timings, Timing( + AbstractInterpreter, # The MethodInstance for ROOT(), and default empty values for other fields. InferenceFrameInfo(ROOTmi, 0x0, Core.Compiler.VarState[], Any[Core.Const(ROOT)], 1), _time_ns())) @@ -108,6 +110,7 @@ reset_timings() # Add in accum_time ("modify" the immutable struct) @inbounds begin _timings[end] = Timing( + parent_timer.interpT, parent_timer.mi_info, parent_timer.start_time, parent_timer.cur_start_time, @@ -119,7 +122,7 @@ reset_timings() return nothing end -@inline function enter_new_timer(frame) +@inline function enter_new_timer(interp::AbstractInterpreter, frame) # Very first thing, stop the active timer: get the current time and add in the # time since it was last started to its aggregate exclusive time. close_current_timer() @@ -127,7 +130,7 @@ end mi_info = _typeinf_identifier(frame) # Start the new timer right before returning - push!(_timings, Timing(mi_info, UInt64(0))) + push!(_timings, Timing(typeof(interp), mi_info, UInt64(0))) len = length(_timings) new_timer = @inbounds _timings[len] # Set the current time _after_ appending the node, to try to exclude the @@ -136,6 +139,7 @@ end @inbounds begin _timings[len] = Timing( + new_timer.interpT, new_timer.mi_info, start, start, @@ -150,7 +154,7 @@ end # _expected_frame_ is not needed within this function; it is used in the `@assert`, to # assert that indeed we are always returning to a parent after finishing all of its # children (that is, asserting that inference proceeds via depth-first-search). -@inline function exit_current_timer(_expected_frame_) +@inline function exit_current_timer(interp, _expected_frame_) # Finish the new timer stop_time = _time_ns() @@ -168,6 +172,7 @@ end accum_time = stop_time - new_timer.cur_start_time # Add in accum_time ("modify" the immutable struct) new_timer = Timing( + new_timer.interpT, new_timer.mi_info, new_timer.start_time, new_timer.cur_start_time, @@ -182,6 +187,7 @@ end len = length(_timings) @inbounds begin _timings[len] = Timing( + parent_timer.interpT, parent_timer.mi_info, parent_timer.start_time, _time_ns(), @@ -208,9 +214,9 @@ const __measure_typeinf__ = fill(false) function typeinf(interp::AbstractInterpreter, frame::InferenceState) interp = switch_from_irinterp(interp) if __measure_typeinf__[] - Timings.enter_new_timer(frame) + Timings.enter_new_timer(interp, frame) v = _typeinf(interp, frame) - Timings.exit_current_timer(frame) + Timings.exit_current_timer(interp, frame) return v else return _typeinf(interp, frame) diff --git a/base/show.jl b/base/show.jl index 36f7df54d0008..26d87ec7556fe 100644 --- a/base/show.jl +++ b/base/show.jl @@ -1299,7 +1299,7 @@ function show(io::IO, mi_info::Core.Compiler.Timings.InferenceFrameInfo) end function show(io::IO, tinf::Core.Compiler.Timings.Timing) - print(io, "Core.Compiler.Timings.Timing(", tinf.mi_info, ") with ", length(tinf.children), " children") + print(io, "Core.Compiler.Timings.Timing(", tinf.interpT, ", ", tinf.mi_info, ") with ", length(tinf.children), " children") end function show_delim_array(io::IO, itr::Union{AbstractArray,SimpleVector}, op, delim, cl, diff --git a/test/compiler/inference.jl b/test/compiler/inference.jl index 8e23ca2760241..1ab3bd871309f 100644 --- a/test/compiler/inference.jl +++ b/test/compiler/inference.jl @@ -3769,7 +3769,7 @@ end timing1 = time_inference() do @eval M1.g(2, 3.0) end - @test occursin(r"Core.Compiler.Timings.Timing\(InferenceFrameInfo for Core.Compiler.Timings.ROOT\(\)\) with \d+ children", sprint(show, timing1)) + @test occursin(r"Core.Compiler.Timings.Timing\(Core.Compiler.AbstractInterpreter, 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] From 4563d1d5fd1647a2124c7fface61a030ea585998 Mon Sep 17 00:00:00 2001 From: Valentin Churavy Date: Mon, 24 Apr 2023 10:43:09 -0400 Subject: [PATCH 2/4] Revert "[Inference] Mark timing with typeof(interp)" This reverts commit 062fa0ad9380243b9d3d34c84131c049f823c79d. --- base/compiler/ssair/irinterp.jl | 4 ++-- base/compiler/typeinfer.jl | 24 +++++++++--------------- base/show.jl | 2 +- test/compiler/inference.jl | 2 +- 4 files changed, 13 insertions(+), 19 deletions(-) diff --git a/base/compiler/ssair/irinterp.jl b/base/compiler/ssair/irinterp.jl index b8955b7d20d70..d171cceb842e9 100644 --- a/base/compiler/ssair/irinterp.jl +++ b/base/compiler/ssair/irinterp.jl @@ -346,10 +346,10 @@ function ir_abstract_constant_propagation(interp::AbstractInterpreter, irsv::IRI irinterp = switch_to_irinterp(interp) if __measure_typeinf__[] inf_frame = Timings.InferenceFrameInfo(irsv.mi, irsv.world, VarState[], Any[], length(irsv.ir.argtypes)) - Timings.enter_new_timer(irinterp, inf_frame) + Timings.enter_new_timer(inf_frame) ret = _ir_abstract_constant_propagation(irinterp, irsv) append!(inf_frame.slottypes, irsv.ir.argtypes) - Timings.exit_current_timer(irinterp, inf_frame) + Timings.exit_current_timer(inf_frame) return ret else return _ir_abstract_constant_propagation(irinterp, irsv) diff --git a/base/compiler/typeinfer.jl b/base/compiler/typeinfer.jl index 0839d087eb2fd..1eec73d0435bd 100644 --- a/base/compiler/typeinfer.jl +++ b/base/compiler/typeinfer.jl @@ -23,7 +23,7 @@ being used for this purpose alone. module Timings using Core.Compiler: -, +, :, Vector, length, first, empty!, push!, pop!, @inline, - @inbounds, copy, backtrace, AbstractInterpreter + @inbounds, copy, backtrace # What we record for any given frame we infer during type inference. struct InferenceFrameInfo @@ -48,13 +48,12 @@ end _typeinf_identifier(frame::InferenceFrameInfo) = frame """ - Core.Compiler.Timing(interpT, mi_info, start_time, ...) + Core.Compiler.Timing(mi_info, start_time, ...) Internal type containing the timing result for running type inference on a single MethodInstance. """ struct Timing - interpT::DataType mi_info::InferenceFrameInfo start_time::UInt64 cur_start_time::UInt64 @@ -62,8 +61,8 @@ struct Timing children::Core.Array{Timing,1} bt # backtrace collected upon initial entry to typeinf end -Timing(interpT, mi_info, start_time, cur_start_time, time, children) = Timing(interpT, mi_info, start_time, cur_start_time, time, children, nothing) -Timing(interpT, mi_info, start_time) = Timing(interpT, mi_info, start_time, start_time, UInt64(0), Timing[]) +Timing(mi_info, start_time, cur_start_time, time, children) = Timing(mi_info, start_time, cur_start_time, time, children, nothing) +Timing(mi_info, start_time) = Timing(mi_info, start_time, start_time, UInt64(0), Timing[]) _time_ns() = ccall(:jl_hrtime, UInt64, ()) # Re-implemented here because Base not yet available. @@ -89,7 +88,6 @@ start the ROOT() timer again. `ROOT()` measures all time spent _outside_ inferen function reset_timings() empty!(_timings) push!(_timings, Timing( - AbstractInterpreter, # The MethodInstance for ROOT(), and default empty values for other fields. InferenceFrameInfo(ROOTmi, 0x0, Core.Compiler.VarState[], Any[Core.Const(ROOT)], 1), _time_ns())) @@ -110,7 +108,6 @@ reset_timings() # Add in accum_time ("modify" the immutable struct) @inbounds begin _timings[end] = Timing( - parent_timer.interpT, parent_timer.mi_info, parent_timer.start_time, parent_timer.cur_start_time, @@ -122,7 +119,7 @@ reset_timings() return nothing end -@inline function enter_new_timer(interp::AbstractInterpreter, frame) +@inline function enter_new_timer(frame) # Very first thing, stop the active timer: get the current time and add in the # time since it was last started to its aggregate exclusive time. close_current_timer() @@ -130,7 +127,7 @@ end mi_info = _typeinf_identifier(frame) # Start the new timer right before returning - push!(_timings, Timing(typeof(interp), mi_info, UInt64(0))) + push!(_timings, Timing(mi_info, UInt64(0))) len = length(_timings) new_timer = @inbounds _timings[len] # Set the current time _after_ appending the node, to try to exclude the @@ -139,7 +136,6 @@ end @inbounds begin _timings[len] = Timing( - new_timer.interpT, new_timer.mi_info, start, start, @@ -154,7 +150,7 @@ end # _expected_frame_ is not needed within this function; it is used in the `@assert`, to # assert that indeed we are always returning to a parent after finishing all of its # children (that is, asserting that inference proceeds via depth-first-search). -@inline function exit_current_timer(interp, _expected_frame_) +@inline function exit_current_timer(_expected_frame_) # Finish the new timer stop_time = _time_ns() @@ -172,7 +168,6 @@ end accum_time = stop_time - new_timer.cur_start_time # Add in accum_time ("modify" the immutable struct) new_timer = Timing( - new_timer.interpT, new_timer.mi_info, new_timer.start_time, new_timer.cur_start_time, @@ -187,7 +182,6 @@ end len = length(_timings) @inbounds begin _timings[len] = Timing( - parent_timer.interpT, parent_timer.mi_info, parent_timer.start_time, _time_ns(), @@ -214,9 +208,9 @@ const __measure_typeinf__ = fill(false) function typeinf(interp::AbstractInterpreter, frame::InferenceState) interp = switch_from_irinterp(interp) if __measure_typeinf__[] - Timings.enter_new_timer(interp, frame) + Timings.enter_new_timer(frame) v = _typeinf(interp, frame) - Timings.exit_current_timer(interp, frame) + Timings.exit_current_timer(frame) return v else return _typeinf(interp, frame) diff --git a/base/show.jl b/base/show.jl index 26d87ec7556fe..36f7df54d0008 100644 --- a/base/show.jl +++ b/base/show.jl @@ -1299,7 +1299,7 @@ function show(io::IO, mi_info::Core.Compiler.Timings.InferenceFrameInfo) end function show(io::IO, tinf::Core.Compiler.Timings.Timing) - print(io, "Core.Compiler.Timings.Timing(", tinf.interpT, ", ", tinf.mi_info, ") with ", length(tinf.children), " children") + 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, diff --git a/test/compiler/inference.jl b/test/compiler/inference.jl index 1ab3bd871309f..8e23ca2760241 100644 --- a/test/compiler/inference.jl +++ b/test/compiler/inference.jl @@ -3769,7 +3769,7 @@ end timing1 = time_inference() do @eval M1.g(2, 3.0) end - @test occursin(r"Core.Compiler.Timings.Timing\(Core.Compiler.AbstractInterpreter, InferenceFrameInfo for Core.Compiler.Timings.ROOT\(\)\) with \d+ children", sprint(show, timing1)) + @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] From 756eb7f1a230d1c00759ab41055e1a4400e5d819 Mon Sep 17 00:00:00 2001 From: Valentin Churavy Date: Mon, 24 Apr 2023 10:44:47 -0400 Subject: [PATCH 3/4] Only time for NativeInterpreter --- base/compiler/typeinfer.jl | 5 ++++- 1 file changed, 4 insertions(+), 1 deletion(-) diff --git a/base/compiler/typeinfer.jl b/base/compiler/typeinfer.jl index 1eec73d0435bd..c516c8c086350 100644 --- a/base/compiler/typeinfer.jl +++ b/base/compiler/typeinfer.jl @@ -205,7 +205,7 @@ __set_measure_typeinf(onoff::Bool) = __measure_typeinf__[] = onoff const __measure_typeinf__ = fill(false) # Wrapper around _typeinf that optionally records the exclusive time for each invocation. -function typeinf(interp::AbstractInterpreter, frame::InferenceState) +function typeinf(interp::NativeInterpreter, frame::InferenceState) interp = switch_from_irinterp(interp) if __measure_typeinf__[] Timings.enter_new_timer(frame) @@ -216,6 +216,8 @@ function typeinf(interp::AbstractInterpreter, frame::InferenceState) return _typeinf(interp, frame) end end +# disable recording timings for external `AbstractInterpreter`s +typeinf(interp::AbstractInterpreter, frame::InferenceState) = _typeinf(interp, frame) function finish!(interp::AbstractInterpreter, caller::InferenceResult) # If we didn't transform the src for caching, we may have to transform @@ -242,6 +244,7 @@ function finish!(interp::AbstractInterpreter, caller::InferenceResult) end function _typeinf(interp::AbstractInterpreter, frame::InferenceState) + interp = switch_from_irinterp(interp) typeinf_nocycle(interp, frame) || return false # frame is now part of a higher cycle # with no active ip's, frame is done frames = frame.callers_in_cycle From c2411ced028d2138d6bf064de1d4eeb07968006b Mon Sep 17 00:00:00 2001 From: Shuhei Kadowaki Date: Tue, 25 Apr 2023 15:41:09 +0900 Subject: [PATCH 4/4] fix up `ir_abstract_constant_propagation` --- base/compiler/ssair/irinterp.jl | 13 ++++++++----- base/compiler/typeinfer.jl | 5 ++--- 2 files changed, 10 insertions(+), 8 deletions(-) diff --git a/base/compiler/ssair/irinterp.jl b/base/compiler/ssair/irinterp.jl index d171cceb842e9..a479bb1f99a82 100644 --- a/base/compiler/ssair/irinterp.jl +++ b/base/compiler/ssair/irinterp.jl @@ -38,7 +38,7 @@ function concrete_eval_invoke(interp::AbstractInterpreter, newirsv = IRInterpretationState(interp, code, mi, argtypes, world) if newirsv !== nothing newirsv.parent = irsv - return _ir_abstract_constant_propagation(interp, newirsv) + return ir_abstract_constant_propagation(interp, newirsv) end return Pair{Any,Bool}(nothing, is_nothrow(effects)) end @@ -194,6 +194,8 @@ end default_reprocess(::AbstractInterpreter, ::IRInterpretationState) = nothing function _ir_abstract_constant_propagation(interp::AbstractInterpreter, irsv::IRInterpretationState; extra_reprocess::Union{Nothing,BitSet} = default_reprocess(interp, irsv)) + interp = switch_to_irinterp(interp) + (; ir, tpdum, ssa_refined) = irsv bbs = ir.cfg.blocks @@ -342,16 +344,17 @@ function _ir_abstract_constant_propagation(interp::AbstractInterpreter, irsv::IR return Pair{Any,Bool}(maybe_singleton_const(ultimate_rt), nothrow) end -function ir_abstract_constant_propagation(interp::AbstractInterpreter, irsv::IRInterpretationState) - irinterp = switch_to_irinterp(interp) +function ir_abstract_constant_propagation(interp::NativeInterpreter, irsv::IRInterpretationState) if __measure_typeinf__[] inf_frame = Timings.InferenceFrameInfo(irsv.mi, irsv.world, VarState[], Any[], length(irsv.ir.argtypes)) Timings.enter_new_timer(inf_frame) - ret = _ir_abstract_constant_propagation(irinterp, irsv) + ret = _ir_abstract_constant_propagation(interp, irsv) append!(inf_frame.slottypes, irsv.ir.argtypes) Timings.exit_current_timer(inf_frame) return ret else - return _ir_abstract_constant_propagation(irinterp, irsv) + return _ir_abstract_constant_propagation(interp, irsv) end end +ir_abstract_constant_propagation(interp::AbstractInterpreter, irsv::IRInterpretationState) = + _ir_abstract_constant_propagation(interp, irsv) diff --git a/base/compiler/typeinfer.jl b/base/compiler/typeinfer.jl index c516c8c086350..5dd0267c52a81 100644 --- a/base/compiler/typeinfer.jl +++ b/base/compiler/typeinfer.jl @@ -204,9 +204,9 @@ If set to `true`, record per-method-instance timings within type inference in th __set_measure_typeinf(onoff::Bool) = __measure_typeinf__[] = onoff const __measure_typeinf__ = fill(false) -# Wrapper around _typeinf that optionally records the exclusive time for each invocation. +# Wrapper around `_typeinf` that optionally records the exclusive time for +# each inference performed by `NativeInterpreter`. function typeinf(interp::NativeInterpreter, frame::InferenceState) - interp = switch_from_irinterp(interp) if __measure_typeinf__[] Timings.enter_new_timer(frame) v = _typeinf(interp, frame) @@ -216,7 +216,6 @@ function typeinf(interp::NativeInterpreter, frame::InferenceState) return _typeinf(interp, frame) end end -# disable recording timings for external `AbstractInterpreter`s typeinf(interp::AbstractInterpreter, frame::InferenceState) = _typeinf(interp, frame) function finish!(interp::AbstractInterpreter, caller::InferenceResult)