build: include sysimage output in timing report (JuliaLang#45132)

* add output time to sysimage build report via new postoutput hook
alexfanqi · May 17, 2022 · eb4c757 · eb4c757
1 parent 4d5f589
commit eb4c757
Show file tree

Hide file tree

Showing 7 changed files with 68 additions and 8 deletions.
diff --git a/base/client.jl b/base/client.jl
@@ -514,6 +514,8 @@ MainInclude.include
 function _start()
     empty!(ARGS)
     append!(ARGS, Core.ARGS)
+    # clear any postoutput hooks that were saved in the sysimage
+    empty!(Base.postoutput_hooks)
     try
         exec_options(JLOptions())
     catch

diff --git a/base/initdefs.jl b/base/initdefs.jl
@@ -378,6 +378,26 @@ function _atexit()
     end
 end
 
+## postoutput: register post output hooks ##
+## like atexit but runs after any requested output.
+## any hooks saved in the sysimage are cleared in Base._start
+const postoutput_hooks = Callable[]
+
+postoutput(f::Function) = (pushfirst!(postoutput_hooks, f); nothing)
+
+function _postoutput()
+    while !isempty(postoutput_hooks)
+        f = popfirst!(postoutput_hooks)
+        try
+            f()
+        catch ex
+            showerror(stderr, ex)
+            Base.show_backtrace(stderr, catch_backtrace())
+            println(stderr)
+        end
+    end
+end
+
 ## hook for disabling threaded libraries ##
 
 library_threading_enabled = true

diff --git a/base/sysimg.jl b/base/sysimg.jl
@@ -114,12 +114,12 @@ let
     tot_time = tot_time_base + tot_time_stdlib + tot_time_userimg
 
     println("Sysimage built. Summary:")
-    print("Total ─────── "); Base.time_print(tot_time               * 10^9); print(" \n");
-    print("Base: ─────── "); Base.time_print(tot_time_base          * 10^9); print(" "); show(IOContext(stdout, :compact=>true), (tot_time_base          / tot_time) * 100); println("%")
-    print("Stdlibs: ──── "); Base.time_print(tot_time_stdlib * 10^9); print(" "); show(IOContext(stdout, :compact=>true), (tot_time_stdlib / tot_time) * 100); println("%")
+    print("Base ──────── "); Base.time_print(tot_time_base    * 10^9); print(" "); show(IOContext(stdout, :compact=>true), (tot_time_base    / tot_time) * 100); println("%")
+    print("Stdlibs ───── "); Base.time_print(tot_time_stdlib  * 10^9); print(" "); show(IOContext(stdout, :compact=>true), (tot_time_stdlib  / tot_time) * 100); println("%")
     if isfile("userimg.jl")
-    print("Userimg: ──── "); Base.time_print(tot_time_userimg       * 10^9); print(" "); show(IOContext(stdout, :compact=>true), (tot_time_userimg       / tot_time) * 100); println("%")
+    print("Userimg ───── "); Base.time_print(tot_time_userimg * 10^9); print(" "); show(IOContext(stdout, :compact=>true), (tot_time_userimg / tot_time) * 100); println("%")
     end
+    print("Total ─────── "); Base.time_print(tot_time         * 10^9); println();
 
     empty!(LOAD_PATH)
     empty!(DEPOT_PATH)

diff --git a/contrib/generate_precompile.jl b/contrib/generate_precompile.jl
@@ -421,13 +421,14 @@ function generate_precompile_statements()
         n_succeeded > 1200 || @warn "Only $n_succeeded precompile statements"
     end
 
-    tot_time = time_ns() - start_time
     include_time *= 1e9
-    gen_time = tot_time - include_time
+    gen_time = (time_ns() - start_time) - include_time
+    tot_time = time_ns() - start_time
+
     println("Precompilation complete. Summary:")
-    print("Total ─────── "); Base.time_print(tot_time); println()
-    print("Generation ── "); Base.time_print(gen_time);     print(" "); show(IOContext(stdout, :compact=>true), gen_time / tot_time * 100); println("%")
+    print("Generation ── "); Base.time_print(gen_time);     print(" "); show(IOContext(stdout, :compact=>true), gen_time / tot_time * 100);     println("%")
     print("Execution ─── "); Base.time_print(include_time); print(" "); show(IOContext(stdout, :compact=>true), include_time / tot_time * 100); println("%")
+    print("Total ─────── "); Base.time_print(tot_time);     println()
 
     return
 end
@@ -446,4 +447,13 @@ empty!(Base.ARGS)
 empty!(Core.ARGS)
 
 end # @eval
+end # if
+
+println("Outputting sysimage file...")
+let pre_output_time = time_ns()
+    # Print report after sysimage has been saved so all time spent can be captured
+    Base.postoutput() do
+        output_time = time_ns() - pre_output_time
+        print("Output ────── "); Base.time_print(output_time); println()
+    end
 end
diff --git a/src/init.c b/src/init.c
@@ -284,6 +284,32 @@ JL_DLLEXPORT void jl_atexit_hook(int exitcode)
     jl_teardown_codegen();
 }
 
+JL_DLLEXPORT void jl_postoutput_hook(void)
+{
+    if (jl_all_tls_states == NULL)
+        return;
+
+    jl_task_t *ct = jl_current_task;
+    if (jl_base_module) {
+        jl_value_t *f = jl_get_global(jl_base_module, jl_symbol("_postoutput"));
+        if (f != NULL) {
+            JL_TRY {
+                size_t last_age = ct->world_age;
+                ct->world_age = jl_get_world_counter();
+                jl_apply(&f, 1);
+                ct->world_age = last_age;
+            }
+            JL_CATCH {
+                jl_printf((JL_STREAM*)STDERR_FILENO, "\npostoutput hook threw an error: ");
+                jl_static_show((JL_STREAM*)STDERR_FILENO, jl_current_exception());
+                jl_printf((JL_STREAM*)STDERR_FILENO, "\n");
+                jlbacktrace(); // written to STDERR_FILENO
+            }
+        }
+    }
+    return;
+}
+
 static void post_boot_hooks(void);
 
 JL_DLLEXPORT void *jl_libjulia_internal_handle;

diff --git a/src/julia.h b/src/julia.h
@@ -1727,6 +1727,7 @@ JL_DLLEXPORT void jl_init_with_image(const char *julia_bindir,
 JL_DLLEXPORT const char *jl_get_default_sysimg_path(void);
 JL_DLLEXPORT int jl_is_initialized(void);
 JL_DLLEXPORT void jl_atexit_hook(int status);
+JL_DLLEXPORT void jl_postoutput_hook(void);
 JL_DLLEXPORT void JL_NORETURN jl_exit(int status);
 JL_DLLEXPORT const char *jl_pathname_for_handle(void *handle);
 

diff --git a/src/precompile.c b/src/precompile.c
@@ -97,6 +97,7 @@ void jl_write_compiler_output(void)
                            jl_options.outputo,
                            jl_options.outputasm,
                            (const char*)s->buf, (size_t)s->size);
+            jl_postoutput_hook();
         }
     }
     for (size_t i = 0; i < jl_current_modules.size; i += 2) {