add __init__() calls to time_imports macro (JuliaLang#49529)

NEWS.md

@@ -122,6 +122,7 @@ Standard library changes
 #### InteractiveUtils
 
  * `code_native` and `@code_native` now default to intel syntax instead of AT&T.
+ * `@time_imports` now shows the timing of any module `__init__()`s that are run ([#49529])
 
 Deprecated or removed
 ---------------------

base/loading.jl

@@ -1071,14 +1071,48 @@ function register_restored_modules(sv::SimpleVector, pkg::PkgId, path::String)
  if !isempty(inits)
  unlock(require_lock) # temporarily _unlock_ during these callbacks
  try
- ccall(:jl_init_restored_modules, Cvoid, (Any,), inits)
+ for (i, mod) in pairs(inits)
+ run_module_init(mod, i)
+ end
  finally
  lock(require_lock)
  end
  end
  return restored
 end
 
+function run_module_init(mod::Module, i::Int=1)
+ # `i` informs ordering for the `@time_imports` report formatting
+ if TIMING_IMPORTS[] == 0
+ ccall(:jl_init_restored_module, Cvoid, (Any,), mod)
+ else
+ if isdefined(mod, :__init__)
+ connector = i > 1 ? "├" : "┌"
+ printstyled(" $connector ", color = :light_black)
+
+ elapsedtime = time_ns()
+ cumulative_compile_timing(true)
+ compile_elapsedtimes = cumulative_compile_time_ns()
+
+ ccall(:jl_init_restored_module, Cvoid, (Any,), mod)
+
+ elapsedtime = (time_ns() - elapsedtime) / 1e6
+ cumulative_compile_timing(false);
+ comp_time, recomp_time = (cumulative_compile_time_ns() .- compile_elapsedtimes) ./ 1e6
+
+ print(round(elapsedtime, digits=1), " ms $mod.__init__() ")
+ if comp_time > 0
+ printstyled(Ryu.writefixed(Float64(100 * comp_time / elapsedtime), 2), "% compilation time", color = Base.info_color())
+ end
+ if recomp_time > 0
+ perc = Float64(100 * recomp_time / comp_time)
+ printstyled(" (", perc < 1 ? "<1" : Ryu.writefixed(perc, 0), "% recompilation)", color = Base.warn_color())
+ end
+ println()
+ end
+ end
+end
+
 function run_package_callbacks(modkey::PkgId)
  run_extension_callbacks(modkey)
  assert_havelock(require_lock)

contrib/generate_precompile.jl

@@ -56,6 +56,7 @@ precompile(Base.CoreLogging.current_logger_for_env, (Base.CoreLogging.LogLevel,
 precompile(Base.CoreLogging.current_logger_for_env, (Base.CoreLogging.LogLevel, Symbol, Module))
 precompile(Base.CoreLogging.env_override_minlevel, (Symbol, Module))
 precompile(Base.StackTraces.lookup, (Ptr{Nothing},))
+precompile(Tuple{typeof(Base.run_module_init), Module, Int})
 """
 
 for T in (Float16, Float32, Float64), IO in (IOBuffer, IOContext{IOBuffer}, Base.TTY, IOContext{Base.TTY})

doc/src/devdocs/init.md

@@ -118,7 +118,7 @@ Other signals (`SIGINFO, SIGBUS, SIGILL, SIGTERM, SIGABRT, SIGQUIT, SIGSYS` and
 hooked up to [`sigdie_handler()`](https://github.com/JuliaLang/julia/blob/master/src/signals-unix.c)
 which prints a backtrace.
 
-[`jl_init_restored_modules()`](https://github.com/JuliaLang/julia/blob/master/src/staticdata.c) calls
+[`jl_init_restored_module()`](https://github.com/JuliaLang/julia/blob/master/src/staticdata.c) calls
 [`jl_module_run_initializer()`](https://github.com/JuliaLang/julia/blob/master/src/module.c) for
 each deserialized module to run the `__init__()` function.
 

src/jl_exported_funcs.inc

@@ -258,7 +258,7 @@
  XX(jl_infer_thunk) \
  XX(jl_init) \
  XX(jl_init_options) \
- XX(jl_init_restored_modules) \
+ XX(jl_init_restored_module) \
  XX(jl_init_with_image) \
  XX(jl_init_with_image__threading) \
  XX(jl_init__threading) \

src/module.c

@@ -972,19 +972,15 @@ JL_DLLEXPORT void jl_clear_implicit_imports(jl_module_t *m)
  JL_UNLOCK(&m->lock);
 }
 
-JL_DLLEXPORT void jl_init_restored_modules(jl_array_t *init_order)
+JL_DLLEXPORT void jl_init_restored_module(jl_value_t *mod)
 {
- int i, l = jl_array_len(init_order);
- for (i = 0; i < l; i++) {
- jl_value_t *mod = jl_array_ptr_ref(init_order, i);
- if (!jl_generating_output() || jl_options.incremental) {
- jl_module_run_initializer((jl_module_t*)mod);
- }
- else {
- if (jl_module_init_order == NULL)
- jl_module_init_order = jl_alloc_vec_any(0);
- jl_array_ptr_1d_push(jl_module_init_order, mod);
- }
+ if (!jl_generating_output() || jl_options.incremental) {
+ jl_module_run_initializer((jl_module_t*)mod);
+ }
+ else {
+ if (jl_module_init_order == NULL)
+ jl_module_init_order = jl_alloc_vec_any(0);
+ jl_array_ptr_1d_push(jl_module_init_order, mod);
  }
 }