From fe864374d50b121aeb3ce5473c206338b21df5e5 Mon Sep 17 00:00:00 2001 From: Ian Butterworth Date: Fri, 4 Oct 2024 20:28:31 -0400 Subject: [PATCH] InteractiveUtils: add `@trace_compile` and `@trace_dispatch` (#55915) --- NEWS.md | 4 ++ doc/src/manual/performance-tips.md | 6 +- src/gf.c | 54 ++++++++++++++++-- src/julia_internal.h | 6 ++ stdlib/InteractiveUtils/docs/src/index.md | 2 + .../InteractiveUtils/src/InteractiveUtils.jl | 2 +- stdlib/InteractiveUtils/src/macros.jl | 55 +++++++++++++++++++ stdlib/InteractiveUtils/test/runtests.jl | 34 +++++++++++- 8 files changed, 151 insertions(+), 12 deletions(-) diff --git a/NEWS.md b/NEWS.md index fb1fcf381cc7f..bb22c9f940a78 100644 --- a/NEWS.md +++ b/NEWS.md @@ -182,6 +182,10 @@ Standard library changes #### InteractiveUtils +* New macros `@trace_compile` and `@trace_dispatch` for running an expression with + `--trace-compile=stderr --trace-compile-timing` and `--trace-dispatch=stderr` respectively enabled. + ([#55915]) + Deprecated or removed --------------------- diff --git a/doc/src/manual/performance-tips.md b/doc/src/manual/performance-tips.md index 417d5ac7a4ca1..3033720b5df8c 100644 --- a/doc/src/manual/performance-tips.md +++ b/doc/src/manual/performance-tips.md @@ -1486,11 +1486,11 @@ from the manifest, then revert the change with `pkg> undo`. If loading time is dominated by slow `__init__()` methods having compilation, one verbose way to identify what is being compiled is to use the julia args `--trace-compile=stderr --trace-compile-timing` which will report a [`precompile`](@ref) -statement each time a method is compiled, along with how long compilation took. For instance, the full setup would be: +statement each time a method is compiled, along with how long compilation took. The InteractiveUtils macro +[`@trace_compile`](@ref) provides a way to enable those args for a specific call. So a call for a complete report report would look like: ``` -$ julia --startup-file=no --trace-compile=stderr --trace-compile-timing -julia> @time @time_imports using CustomPackage +julia> @time @time_imports @trace_compile using CustomPackage ... ``` diff --git a/src/gf.c b/src/gf.c index 56ebe6fe2fa84..fc2e62ebff96b 100644 --- a/src/gf.c +++ b/src/gf.c @@ -2513,12 +2513,32 @@ jl_code_instance_t *jl_method_inferred_with_abi(jl_method_instance_t *mi JL_PROP jl_mutex_t precomp_statement_out_lock; +_Atomic(uint8_t) jl_force_trace_compile_timing_enabled = 0; + +/** + * @brief Enable force trace compile to stderr with timing. + */ +JL_DLLEXPORT void jl_force_trace_compile_timing_enable(void) +{ + // Increment the flag to allow reentrant callers to `@trace_compile`. + jl_atomic_fetch_add(&jl_force_trace_compile_timing_enabled, 1); +} +/** + * @brief Disable force trace compile to stderr with timing. + */ +JL_DLLEXPORT void jl_force_trace_compile_timing_disable(void) +{ + // Increment the flag to allow reentrant callers to `@trace_compile`. + jl_atomic_fetch_add(&jl_force_trace_compile_timing_enabled, -1); +} + static void record_precompile_statement(jl_method_instance_t *mi, double compilation_time, int is_recompile) { static ios_t f_precompile; static JL_STREAM* s_precompile = NULL; jl_method_t *def = mi->def.method; - if (jl_options.trace_compile == NULL) + uint8_t force_trace_compile = jl_atomic_load_relaxed(&jl_force_trace_compile_timing_enabled); + if (force_trace_compile == 0 && jl_options.trace_compile == NULL) return; if (!jl_is_method(def)) return; @@ -2528,7 +2548,7 @@ static void record_precompile_statement(jl_method_instance_t *mi, double compila JL_LOCK(&precomp_statement_out_lock); if (s_precompile == NULL) { const char *t = jl_options.trace_compile; - if (!strncmp(t, "stderr", 6)) { + if (force_trace_compile || !strncmp(t, "stderr", 6)) { s_precompile = JL_STDERR; } else { @@ -2540,7 +2560,7 @@ static void record_precompile_statement(jl_method_instance_t *mi, double compila if (!jl_has_free_typevars(mi->specTypes)) { if (is_recompile && s_precompile == JL_STDERR && jl_options.color != JL_OPTIONS_COLOR_OFF) jl_printf(s_precompile, "\e[33m"); - if (jl_options.trace_compile_timing) + if (force_trace_compile || jl_options.trace_compile_timing) jl_printf(s_precompile, "#= %6.1f ms =# ", compilation_time / 1e6); jl_printf(s_precompile, "precompile("); jl_static_show(s_precompile, mi->specTypes); @@ -2562,6 +2582,25 @@ static void record_precompile_statement(jl_method_instance_t *mi, double compila jl_mutex_t dispatch_statement_out_lock; +_Atomic(uint8_t) jl_force_trace_dispatch_enabled = 0; + +/** + * @brief Enable force trace dispatch to stderr. + */ +JL_DLLEXPORT void jl_force_trace_dispatch_enable(void) +{ + // Increment the flag to allow reentrant callers to `@trace_dispatch`. + jl_atomic_fetch_add(&jl_force_trace_dispatch_enabled, 1); +} +/** + * @brief Disable force trace dispatch to stderr. + */ +JL_DLLEXPORT void jl_force_trace_dispatch_disable(void) +{ + // Increment the flag to allow reentrant callers to `@trace_dispatch`. + jl_atomic_fetch_add(&jl_force_trace_dispatch_enabled, -1); +} + static void record_dispatch_statement(jl_method_instance_t *mi) { static ios_t f_dispatch; @@ -2570,10 +2609,11 @@ static void record_dispatch_statement(jl_method_instance_t *mi) if (!jl_is_method(def)) return; + uint8_t force_trace_dispatch = jl_atomic_load_relaxed(&jl_force_trace_dispatch_enabled); JL_LOCK(&dispatch_statement_out_lock); if (s_dispatch == NULL) { const char *t = jl_options.trace_dispatch; - if (!strncmp(t, "stderr", 6)) { + if (force_trace_dispatch || !strncmp(t, "stderr", 6)) { s_dispatch = JL_STDERR; } else { @@ -3393,7 +3433,8 @@ STATIC_INLINE jl_method_instance_t *jl_lookup_generic_(jl_value_t *F, jl_value_t // unreachable } // mfunc is about to be dispatched - if (jl_options.trace_dispatch != NULL) { + uint8_t force_trace_dispatch = jl_atomic_load_relaxed(&jl_force_trace_dispatch_enabled); + if (force_trace_dispatch || jl_options.trace_dispatch != NULL) { uint8_t miflags = jl_atomic_load_relaxed(&mfunc->flags); uint8_t was_dispatched = miflags & JL_MI_FLAGS_MASK_DISPATCHED; if (!was_dispatched) { @@ -3524,7 +3565,8 @@ jl_value_t *jl_gf_invoke_by_method(jl_method_t *method, jl_value_t *gf, jl_value jl_gc_sync_total_bytes(last_alloc); // discard allocation count from compilation } JL_GC_PROMISE_ROOTED(mfunc); - if (jl_options.trace_dispatch != NULL) { + uint8_t force_trace_dispatch = jl_atomic_load_relaxed(&jl_force_trace_dispatch_enabled); + if (force_trace_dispatch || jl_options.trace_dispatch != NULL) { uint8_t miflags = jl_atomic_load_relaxed(&mfunc->flags); uint8_t was_dispatched = miflags & JL_MI_FLAGS_MASK_DISPATCHED; if (!was_dispatched) { diff --git a/src/julia_internal.h b/src/julia_internal.h index 9a61c3d18356f..20d90fede3d5e 100644 --- a/src/julia_internal.h +++ b/src/julia_internal.h @@ -1171,6 +1171,12 @@ JL_DLLEXPORT jl_code_instance_t *jl_cache_uninferred(jl_method_instance_t *mi, j JL_DLLEXPORT jl_code_instance_t *jl_new_codeinst_for_uninferred(jl_method_instance_t *mi, jl_code_info_t *src); JL_DLLEXPORT extern jl_value_t *(*const jl_rettype_inferred_addr)(jl_method_instance_t *mi JL_PROPAGATES_ROOT, size_t min_world, size_t max_world) JL_NOTSAFEPOINT; +JL_DLLEXPORT void jl_force_trace_compile_timing_enable(void); +JL_DLLEXPORT void jl_force_trace_compile_timing_disable(void); + +JL_DLLEXPORT void jl_force_trace_dispatch_enable(void); +JL_DLLEXPORT void jl_force_trace_dispatch_disable(void); + uint32_t jl_module_next_counter(jl_module_t *m) JL_NOTSAFEPOINT; jl_tupletype_t *arg_type_tuple(jl_value_t *arg1, jl_value_t **args, size_t nargs); diff --git a/stdlib/InteractiveUtils/docs/src/index.md b/stdlib/InteractiveUtils/docs/src/index.md index dbfb42b9a931d..69b68a27e4e81 100644 --- a/stdlib/InteractiveUtils/docs/src/index.md +++ b/stdlib/InteractiveUtils/docs/src/index.md @@ -33,5 +33,7 @@ InteractiveUtils.@code_llvm InteractiveUtils.code_native InteractiveUtils.@code_native InteractiveUtils.@time_imports +InteractiveUtils.@trace_compile +InteractiveUtils.@trace_dispatch InteractiveUtils.clipboard ``` diff --git a/stdlib/InteractiveUtils/src/InteractiveUtils.jl b/stdlib/InteractiveUtils/src/InteractiveUtils.jl index 835988ddf149f..f3c1ff7fba59f 100644 --- a/stdlib/InteractiveUtils/src/InteractiveUtils.jl +++ b/stdlib/InteractiveUtils/src/InteractiveUtils.jl @@ -11,7 +11,7 @@ Base.Experimental.@optlevel 1 export apropos, edit, less, code_warntype, code_llvm, code_native, methodswith, varinfo, versioninfo, subtypes, supertypes, @which, @edit, @less, @functionloc, @code_warntype, - @code_typed, @code_lowered, @code_llvm, @code_native, @time_imports, clipboard + @code_typed, @code_lowered, @code_llvm, @code_native, @time_imports, clipboard, @trace_compile, @trace_dispatch import Base.Docs.apropos diff --git a/stdlib/InteractiveUtils/src/macros.jl b/stdlib/InteractiveUtils/src/macros.jl index bb56c47b4f9ca..211687df47954 100644 --- a/stdlib/InteractiveUtils/src/macros.jl +++ b/stdlib/InteractiveUtils/src/macros.jl @@ -256,6 +256,28 @@ macro time_imports(ex) end end +macro trace_compile(ex) + quote + try + ccall(:jl_force_trace_compile_timing_enable, Cvoid, ()) + $(esc(ex)) + finally + ccall(:jl_force_trace_compile_timing_disable, Cvoid, ()) + end + end +end + +macro trace_dispatch(ex) + quote + try + ccall(:jl_force_trace_dispatch_enable, Cvoid, ()) + $(esc(ex)) + finally + ccall(:jl_force_trace_dispatch_disable, Cvoid, ()) + end + end +end + """ @functionloc @@ -409,3 +431,36 @@ julia> @time_imports using CSV """ :@time_imports + +""" + @trace_compile + +A macro to execute an expression and show any methods that were compiled (or recompiled in yellow), +like the julia args `--trace-compile=stderr --trace-compile-timing` but specifically for a call. + +```julia-repl +julia> @trace_compile rand(2,2) * rand(2,2) +#= 39.1 ms =# precompile(Tuple{typeof(Base.rand), Int64, Int64}) +#= 102.0 ms =# precompile(Tuple{typeof(Base.:(*)), Array{Float64, 2}, Array{Float64, 2}}) +2×2 Matrix{Float64}: + 0.421704 0.864841 + 0.211262 0.444366 +``` + +!!! compat "Julia 1.12" + This macro requires at least Julia 1.12 + +""" +:@trace_compile + +""" + @trace_dispatch + +A macro to execute an expression and report methods that were compiled via dynamic dispatch, +like the julia arg `--trace-dispatch=stderr` but specifically for a call. + +!!! compat "Julia 1.12" + This macro requires at least Julia 1.12 + +""" +:@trace_dispatch diff --git a/stdlib/InteractiveUtils/test/runtests.jl b/stdlib/InteractiveUtils/test/runtests.jl index 424564b70384c..8e7090cb53020 100644 --- a/stdlib/InteractiveUtils/test/runtests.jl +++ b/stdlib/InteractiveUtils/test/runtests.jl @@ -708,7 +708,7 @@ let length((@code_lowered sum(1:10)).code) end -@testset "@time_imports" begin +@testset "@time_imports, @trace_compile, @trace_dispatch" begin mktempdir() do dir cd(dir) do try @@ -717,7 +717,16 @@ end write(foo_file, """ module Foo3242 - foo() = 1 + function foo() + Base.Experimental.@force_compile + foo(1) + end + foo(x) = x + function bar() + Base.Experimental.@force_compile + bar(1) + end + bar(x) = x end """) @@ -734,6 +743,27 @@ end @test occursin("ms Foo3242", String(buf)) + fname = tempname() + f = open(fname, "w") + redirect_stderr(f) do + @trace_compile @eval Foo3242.foo() + end + close(f) + buf = read(fname) + rm(fname) + + @test occursin("ms =# precompile(", String(buf)) + + fname = tempname() + f = open(fname, "w") + redirect_stderr(f) do + @trace_dispatch @eval Foo3242.bar() + end + close(f) + buf = read(fname) + rm(fname) + + @test occursin("precompile(", String(buf)) finally filter!((≠)(dir), LOAD_PATH) end