How much is spent in optimizer vs in inference? (Answer: about a half)

base/Base.jl

@@ -487,6 +487,10 @@ function __init__()
     if haskey(ENV, "JULIA_MAX_NUM_PRECOMPILE_FILES")
         MAX_NUM_PRECOMPILE_FILES[] = parse(Int, ENV["JULIA_MAX_NUM_PRECOMPILE_FILES"])
     end
+    Core.Compiler.enable_stopwatches()
+    atexit() do
+        show_compiler_stopwatches(stderr)
+    end
     nothing
 end
 

base/compiler/typeinfer.jl

@@ -190,6 +190,51 @@ end
 
 end  # module Timings
 
+module StopWatches
+
+using ..Timings: _time_ns
+using ..Compiler: -, +
+
+mutable struct StopWatch
+    nested::Bool
+    time::UInt64
+    count::Int64
+end
+
+# Disable stopwatches by default by pretending it's nested.
+StopWatch() = StopWatch(true, UInt64(0), Int64(0))
+
+function start!(sw::StopWatch)
+    if sw.nested
+        swtoken = (false, UInt64(0))
+    else
+        sw.nested = true
+        swtoken = (true, _time_ns())
+    end
+    return swtoken
+end
+
+function stop!(sw::StopWatch, swtoken)
+    (isroot, start) = swtoken
+    if isroot
+        sw.time += _time_ns() - start
+        sw.count += 1
+        sw.nested = false
+    end
+    return
+end
+
+end # module StopWatches
+
+const STOPWATCH_INF = StopWatches.StopWatch()
+const STOPWATCH_OPT = StopWatches.StopWatch()
+
+function enable_stopwatches()
+    STOPWATCH_INF.nested = false
+    STOPWATCH_OPT.nested = false
+    return
+end
+
 """
     Core.Compiler.__set_measure_typeinf(onoff::Bool)
 
@@ -206,7 +251,10 @@ function typeinf(interp::AbstractInterpreter, frame::InferenceState)
         Timings.exit_current_timer(frame)
         return v
     else
-        return _typeinf(interp, frame)
+        swtoken = StopWatches.start!(STOPWATCH_INF)
+        v = _typeinf(interp, frame)
+        StopWatches.stop!(STOPWATCH_INF, swtoken)
+        return v
     end
 end
 
@@ -252,7 +300,9 @@ function _typeinf(interp::AbstractInterpreter, frame::InferenceState)
         if opt isa OptimizationState # implies `may_optimize(interp) === true`
             result_type = caller.result
             @assert !(result_type isa LimitedAccuracy)
+            swtoken = StopWatches.start!(STOPWATCH_OPT)
             optimize(interp, opt, OptimizationParams(interp), result_type)
+            StopWatches.stop!(STOPWATCH_OPT, swtoken)
             if opt.const_api
                 # XXX: The work in ir_to_codeinf! is essentially wasted. The only reason
                 # we're doing it is so that code_llvm can return the code

base/util.jl

@@ -574,3 +574,14 @@ function runtests(tests = ["all"]; ncores::Int = ceil(Int, Sys.CPU_THREADS::Int
               "including error messages above and the output of versioninfo():\n$(read(buf, String))")
     end
 end
+
+function show_compiler_stopwatches(io::IO = stdout)
+    inftime = Core.Compiler.STOPWATCH_INF.time / 1e9
+    opttime = Core.Compiler.STOPWATCH_OPT.time / 1e9
+    meanopt = opttime / Core.Compiler.STOPWATCH_OPT.count
+    ratio = opttime / inftime
+    print(
+        io,
+        "Compiler.StopWatches: inf=$inftime opt=$opttime ratio=$ratio meanopt=$meanopt\n",
+    )
+end