add `--trace-compile-timing` arg to add compile timing comments #54662

IanButterworth · 2024-06-03T20:12:32Z

% ./julia --trace-compile=stderr --trace-compile-timing --start=no -e "using ProfileView"
#=   0.0 ms =# precompile(Tuple{typeof(Requires.__init__)})
#=  19.4 ms =# precompile(Tuple{typeof(Requires.isprecompiling)})
#=   0.0 ms =# precompile(Tuple{typeof(Requires.listenpkg), Any, Base.PkgId})
#=   0.0 ms =# precompile(Tuple{typeof(Requires.loaded), Base.PkgId})
#=  13.4 ms =# precompile(Tuple{typeof(Base.haskey), Base.Dict{Base.PkgId, Module}, Base.PkgId})
#=   0.0 ms =# precompile(Tuple{typeof(Requires.callbacks), Base.PkgId})
#=   0.0 ms =# precompile(Tuple{typeof(Libiconv_jll.__init__)})
#=   0.0 ms =# precompile(Tuple{typeof(Libiconv_jll.find_artifact_dir)})
#=  32.0 ms =# precompile(Tuple{typeof(Artifacts._artifact_str), Module, String, Base.SubString{String}, String, Base.Dict{String, Any}, Base.SHA1, Base.BinaryPlatforms.Platform, Any})
#=   1.5 ms =# precompile(Tuple{typeof(Base.invokelatest), Any})
...

tecosaur · 2024-06-06T02:30:13Z

Love the look of this, the only improvement that comes to mind is rounding the timings printed to 3 sig fig.

tecosaur · 2024-06-06T02:31:36Z

src/jloptions.c

-       case opt_polly:
+        case opt_polly:


Unrelated whitespace change?

Yeah, flyby formatting fix

tecosaur · 2024-06-06T02:31:59Z

With how short and easy to read these changes are, I'd say this LGTM.

IanButterworth · 2024-06-09T16:27:38Z

Updated to 3 d.p.

% ./julia -t2 --trace-compile=stderr --trace-compile-timing=yes --start=no
               _
   _       _ _(_)_     |  Documentation: https://docs.julialang.org
  (_)     | (_) (_)    |
   _ _   _| |_  __ _   |  Type "?" for help, "]?" for Pkg help.
  | | | | | | |/ _` |  |
  | | |_| | | | (_| |  |  Version 1.12.0-DEV.694 (2024-06-09)
 _/ |\__'_|_|_|\__'_|  |  ib/trace_compile_timing/a16e5a6847 (fork: 2 commits, 0 days)
|__/                   |

(......) pkg> precompile(Tuple{REPL.var"#119#137"{REPL.LineEdit.MIState, REPL.LineEditREPL, REPL.LineEdit.Prompt}}) # 4.538ms
precompile(Tuple{typeof(Base.first), Array{Any, 1}}) # 3.328ms
precompile(Tuple{typeof(Base.put!), Base.Channel{Any}, Function}) # 22.375ms
precompile(Tuple{typeof(Base.take!), Base.Channel{Any}}) # 1.911ms
precompile(Tuple{REPL.var"#120#138"{Module, REPL.LineEditREPL, REPL.LineEdit.Prompt}, REPL.LineEdit.MIState, Any}) # 5.024ms
precompile(Tuple{REPL.var"#121#139"{REPL.LineEdit.MIState, REPL.LineEdit.Prompt}}) # 2.808ms

IanButterworth · 2024-06-09T16:43:17Z

Just noting that this is quite nice in conjunction with @time_imports for attributing where the compilation time is spent

src/gf.c

IanButterworth · 2024-06-09T17:08:35Z

Looking at #51106 it's probably better to implement this as --trace-compile-timing rather than require the value --trace-compile-timing=yes

IanButterworth · 2024-06-09T17:42:55Z

Now implemented via simply --trace-compile-timing (no =yes)

Talking this through with @tecosaur, some other changes:

To make the information easier to compare, the info has been moved to before the statement, in an inline comment so that the raw output could still be loaded in a .jl.

Also the time is printed fixed width left padded, to align the decimal in the same way that our other timing tooling does

% ./julia --trace-compile=stderr --trace-compile-timing --start=no -e "using ProfileView"
#=   0.0 ms =# precompile(Tuple{typeof(Requires.__init__)})
#=  19.4 ms =# precompile(Tuple{typeof(Requires.isprecompiling)})
#=   0.0 ms =# precompile(Tuple{typeof(Requires.listenpkg), Any, Base.PkgId})
#=   0.0 ms =# precompile(Tuple{typeof(Requires.loaded), Base.PkgId})
#=  13.4 ms =# precompile(Tuple{typeof(Base.haskey), Base.Dict{Base.PkgId, Module}, Base.PkgId})
#=   0.0 ms =# precompile(Tuple{typeof(Requires.callbacks), Base.PkgId})
#=   0.0 ms =# precompile(Tuple{typeof(Libiconv_jll.__init__)})
#=   0.0 ms =# precompile(Tuple{typeof(Libiconv_jll.find_artifact_dir)})
#=  32.0 ms =# precompile(Tuple{typeof(Artifacts._artifact_str), Module, String, Base.SubString{String}, String, Base.Dict{String, Any}, Base.SHA1, Base.BinaryPlatforms.Platform, Any})
#=   1.5 ms =# precompile(Tuple{typeof(Base.invokelatest), Any})
#=   0.0 ms =# precompile(Tuple{typeof(JLLWrappers.get_julia_libpaths)})
#=   0.0 ms =# precompile(Tuple{typeof(Libffi_jll.__init__)})
#=   0.0 ms =# precompile(Tuple{typeof(Libffi_jll.find_artifact_dir)})
#=   0.0 ms =# precompile(Tuple{typeof(XML2_jll.__init__)})
#=   0.0 ms =# precompile(Tuple{typeof(XML2_jll.find_artifact_dir)})
#=   5.7 ms =# precompile(Tuple{typeof(Base.issorted), Array{String, 1}, Base.Order.ReverseOrdering{Base.Order.ForwardOrdering}})
#=   0.0 ms =# precompile(Tuple{typeof(Gettext_jll.__init__)})
#=   0.0 ms =# precompile(Tuple{typeof(Gettext_jll.find_artifact_dir)})
#=   0.0 ms =# precompile(Tuple{typeof(Glib_jll.__init__)})
#=   0.0 ms =# precompile(Tuple{typeof(Glib_jll.find_artifact_dir)})
#=   0.0 ms =# precompile(Tuple{typeof(LLVMOpenMP_jll.__init__)})
#=   0.0 ms =# precompile(Tuple{typeof(LLVMOpenMP_jll.find_artifact_dir)})
#=   0.0 ms =# precompile(Tuple{typeof(Pixman_jll.__init__)})
#=   0.0 ms =# precompile(Tuple{typeof(Pixman_jll.find_artifact_dir)})
#=   0.0 ms =# precompile(Tuple{typeof(libpng_jll.__init__)})
#=   0.0 ms =# precompile(Tuple{typeof(libpng_jll.find_artifact_dir)})
#=   0.0 ms =# precompile(Tuple{typeof(Bzip2_jll.__init__)})
#=   0.0 ms =# precompile(Tuple{typeof(Bzip2_jll.find_artifact_dir)})
#=   0.0 ms =# precompile(Tuple{typeof(FreeType2_jll.__init__)})
#=   0.0 ms =# precompile(Tuple{typeof(FreeType2_jll.find_artifact_dir)})
#=   0.0 ms =# precompile(Tuple{typeof(Expat_jll.__init__)})
#=   0.0 ms =# precompile(Tuple{typeof(Expat_jll.find_artifact_dir)})
#=   0.0 ms =# precompile(Tuple{typeof(Fontconfig_jll.__init__)})
#=   0.0 ms =# precompile(Tuple{typeof(Fontconfig_jll.find_artifact_dir)})
#=   4.1 ms =# precompile(Tuple{typeof(Base.get!), Base.EnvDict, String, String})
#=   2.1 ms =# precompile(Tuple{typeof(Base.getindex), Base.EnvDict, String})
#=   0.0 ms =# precompile(Tuple{typeof(Cairo_jll.__init__)})
#=   0.0 ms =# precompile(Tuple{typeof(Cairo_jll.find_artifact_dir)})
#=   0.0 ms =# precompile(Tuple{typeof(FriBidi_jll.__init__)})
#=   0.0 ms =# precompile(Tuple{typeof(FriBidi_jll.find_artifact_dir)})
#=   0.0 ms =# precompile(Tuple{typeof(Graphite2_jll.__init__)})
#=   0.0 ms =# precompile(Tuple{typeof(Graphite2_jll.find_artifact_dir)})
#=   0.0 ms =# precompile(Tuple{typeof(HarfBuzz_jll.__init__)})
#=   0.0 ms =# precompile(Tuple{typeof(HarfBuzz_jll.find_artifact_dir)})
#=   0.0 ms =# precompile(Tuple{typeof(Pango_jll.__init__)})
#=   0.0 ms =# precompile(Tuple{typeof(Pango_jll.find_artifact_dir)})
#=   0.0 ms =# precompile(Tuple{typeof(JpegTurbo_jll.__init__)})
#=   0.0 ms =# precompile(Tuple{typeof(JpegTurbo_jll.find_artifact_dir)})
#=   0.0 ms =# precompile(Tuple{typeof(LERC_jll.__init__)})
#=   0.0 ms =# precompile(Tuple{typeof(LERC_jll.find_artifact_dir)})
#=   0.0 ms =# precompile(Tuple{typeof(XZ_jll.__init__)})
#=   0.0 ms =# precompile(Tuple{typeof(XZ_jll.find_artifact_dir)})
#=   0.0 ms =# precompile(Tuple{typeof(Zstd_jll.__init__)})
#=   0.0 ms =# precompile(Tuple{typeof(Zstd_jll.find_artifact_dir)})
#=   0.0 ms =# precompile(Tuple{typeof(Libtiff_jll.__init__)})
#=   0.0 ms =# precompile(Tuple{typeof(Libtiff_jll.find_artifact_dir)})
#=   0.0 ms =# precompile(Tuple{typeof(gdk_pixbuf_jll.__init__)})
#=   0.0 ms =# precompile(Tuple{typeof(gdk_pixbuf_jll.find_artifact_dir)})
#=   0.0 ms =# precompile(Tuple{typeof(Libepoxy_jll.__init__)})
#=   0.0 ms =# precompile(Tuple{typeof(Libepoxy_jll.find_artifact_dir)})
#=   0.0 ms =# precompile(Tuple{typeof(ATK_jll.__init__)})
#=   0.0 ms =# precompile(Tuple{typeof(ATK_jll.find_artifact_dir)})
#=   0.0 ms =# precompile(Tuple{typeof(iso_codes_jll.__init__)})
#=   0.0 ms =# precompile(Tuple{typeof(iso_codes_jll.find_artifact_dir)})
#=   0.0 ms =# precompile(Tuple{typeof(GTK3_jll.__init__)})
#=   0.0 ms =# precompile(Tuple{typeof(GTK3_jll.find_artifact_dir)})
#=   0.0 ms =# precompile(Tuple{typeof(Xorg_xkeyboard_config_jll.__init__)})
#=   0.0 ms =# precompile(Tuple{typeof(Xorg_xkeyboard_config_jll.find_artifact_dir)})
#=   0.0 ms =# precompile(Tuple{typeof(hicolor_icon_theme_jll.__init__)})
#=   0.0 ms =# precompile(Tuple{typeof(hicolor_icon_theme_jll.find_artifact_dir)})
#=   0.0 ms =# precompile(Tuple{typeof(adwaita_icon_theme_jll.__init__)})
#=   0.0 ms =# precompile(Tuple{typeof(adwaita_icon_theme_jll.find_artifact_dir)})
#=   0.0 ms =# precompile(Tuple{typeof(Librsvg_jll.__init__)})
#=   0.0 ms =# precompile(Tuple{typeof(Librsvg_jll.find_artifact_dir)})
#=   7.5 ms =# precompile(Tuple{Gtk.var"#query_pixbuf_loaders#327"{Gtk.var"#query_pixbuf_loaders#322#328"}, String})
#=   0.0 ms =# precompile(Tuple{typeof(gdk_pixbuf_jll.gdk_pixbuf_query_loaders)})
#=   0.0 ms =# precompile(Tuple{gdk_pixbuf_jll.var"##gdk_pixbuf_query_loaders#4", Bool, Bool, typeof(gdk_pixbuf_jll.gdk_pixbuf_query_loaders)})
#=   4.1 ms =# precompile(Tuple{typeof(Base.copy), Base.EnvDict})
#=   1.4 ms =# precompile(Tuple{typeof(Base.getindex), Base.RefValue{String}})
#=   0.0 ms =# precompile(Tuple{typeof(JLLWrappers.adjust_ENV!), Base.Dict{K, V} where V where K, String, String, Bool, Bool})
#=   1.6 ms =# precompile(Tuple{typeof(Base.get), Base.Dict{String, String}, String, String})
#=   1.0 ms =# precompile(Tuple{typeof(Base.string), String, Char, Vararg{Union{Char, String, Symbol}}})
#=   1.6 ms =# precompile(Tuple{typeof(Base.getindex), Base.Dict{String, String}, String})
#=   1.6 ms =# precompile(Tuple{Type{Base.Cmd}, Array{String, 1}})
#=   1.2 ms =# precompile(Tuple{Type{NamedTuple{(:env,), T} where T<:Tuple}, Tuple{Base.Dict{String, String}}})
#=  28.5 ms =# precompile(Tuple{typeof(Base.addenv), Base.Cmd, Pair{String, String}})
#=   2.0 ms =# precompile(Tuple{typeof(Base.read), Base.PipeEndpoint})
#=   1.7 ms =# precompile(Tuple{typeof(Base.write), Base.IOStream, Base.SubString{String}})
#=   0.0 ms =# precompile(Tuple{typeof(Librsvg_jll.is_available)})
#=   2.1 ms =# precompile(Tuple{typeof(Core.kwcall), NamedTuple{(:extra_env,), Tuple{Array{Pair{String, String}, 1}}}, Gtk.var"#query_pixbuf_loaders#327"{Gtk.var"#query_pixbuf_loaders#322#328"}, String})
#=   6.5 ms =# precompile(Tuple{typeof(Base.addenv), Base.Cmd, Pair{String, String}, Pair{String, String}})
#=   1.6 ms =# precompile(Tuple{typeof(Requires.isprecompiling)})
#=   0.0 ms =# precompile(Tuple{typeof(Requires.loadpkg), Base.PkgId})
#=   2.5 ms =# precompile(Tuple{typeof(Base.first), Array{Any, 1}})
#=   1.3 ms =# precompile(Tuple{Gtk.GLib.var"#100#101"})

IanButterworth · 2024-06-09T18:01:15Z

Now only printing as a comment when sent to file

% ./julia --trace-compile=stderr --trace-compile-timing --start=no -e "using ProfileView"
  36.2 ms precompile(Tuple{typeof(Base.setindex!), Base.EnvDict, String, String})
  10.3 ms precompile(Tuple{typeof(Base.getindex), Base.EnvDict, String})
   0.0 ms precompile(Tuple{typeof(Requires.__init__)})
   7.0 ms precompile(Tuple{typeof(Requires.isprecompiling)})
   0.0 ms precompile(Tuple{typeof(Requires.listenpkg), Any, Base.PkgId})
   0.0 ms precompile(Tuple{typeof(Requires.loaded), Base.PkgId})
   4.1 ms precompile(Tuple{typeof(Base.haskey), Base.Dict{Base.PkgId, Module}, Base.PkgId})
   0.0 ms precompile(Tuple{typeof(Requires.callbacks), Base.PkgId})
   0.0 ms precompile(Tuple{typeof(Libiconv_jll.__init__)})
   0.0 ms precompile(Tuple{typeof(Libiconv_jll.find_artifact_dir)})
  48.6 ms precompile(Tuple{typeof(Artifacts._artifact_str), Module, String, Base.SubString{String}, String, Base.Dict{String, Any}, Base.SHA1, Base.BinaryPlatforms.Platform, Any})
   2.6 ms precompile(Tuple{typeof(Base.invokelatest), Any})
   0.0 ms precompile(Tuple{typeof(JLLWrappers.get_julia_libpaths)})
   0.0 ms precompile(Tuple{typeof(Libffi_jll.__init__)})
   0.0 ms precompile(Tuple{typeof(Libffi_jll.find_artifact_dir)})
   0.0 ms precompile(Tuple{typeof(XML2_jll.__init__)})
   0.0 ms precompile(Tuple{typeof(XML2_jll.find_artifact_dir)})
  10.2 ms precompile(Tuple{typeof(Base.issorted), Array{String, 1}, Base.Order.ReverseOrdering{Base.Order.ForwardOrdering}})
   0.0 ms precompile(Tuple{typeof(Gettext_jll.__init__)})
   0.0 ms precompile(Tuple{typeof(Gettext_jll.find_artifact_dir)})
   0.0 ms precompile(Tuple{typeof(Glib_jll.__init__)})
   0.0 ms precompile(Tuple{typeof(Glib_jll.find_artifact_dir)})
   0.0 ms precompile(Tuple{typeof(LLVMOpenMP_jll.__init__)})
   0.0 ms precompile(Tuple{typeof(LLVMOpenMP_jll.find_artifact_dir)})
   0.0 ms precompile(Tuple{typeof(Pixman_jll.__init__)})
   0.0 ms precompile(Tuple{typeof(Pixman_jll.find_artifact_dir)})
   0.0 ms precompile(Tuple{typeof(libpng_jll.__init__)})
   0.0 ms precompile(Tuple{typeof(libpng_jll.find_artifact_dir)})
   0.0 ms precompile(Tuple{typeof(Bzip2_jll.__init__)})
   0.0 ms precompile(Tuple{typeof(Bzip2_jll.find_artifact_dir)})
   0.0 ms precompile(Tuple{typeof(FreeType2_jll.__init__)})
   0.0 ms precompile(Tuple{typeof(FreeType2_jll.find_artifact_dir)})
   0.0 ms precompile(Tuple{typeof(Expat_jll.__init__)})
   0.0 ms precompile(Tuple{typeof(Expat_jll.find_artifact_dir)})
   0.0 ms precompile(Tuple{typeof(Fontconfig_jll.__init__)})
   0.0 ms precompile(Tuple{typeof(Fontconfig_jll.find_artifact_dir)})
   7.3 ms precompile(Tuple{typeof(Base.get!), Base.EnvDict, String, String})
   0.0 ms precompile(Tuple{typeof(Cairo_jll.__init__)})
   0.0 ms precompile(Tuple{typeof(Cairo_jll.find_artifact_dir)})
   0.0 ms precompile(Tuple{typeof(FriBidi_jll.__init__)})
   0.0 ms precompile(Tuple{typeof(FriBidi_jll.find_artifact_dir)})
   0.0 ms precompile(Tuple{typeof(Graphite2_jll.__init__)})
   0.0 ms precompile(Tuple{typeof(Graphite2_jll.find_artifact_dir)})
   0.0 ms precompile(Tuple{typeof(HarfBuzz_jll.__init__)})
   0.0 ms precompile(Tuple{typeof(HarfBuzz_jll.find_artifact_dir)})
   0.0 ms precompile(Tuple{typeof(Pango_jll.__init__)})
   0.0 ms precompile(Tuple{typeof(Pango_jll.find_artifact_dir)})
   0.0 ms precompile(Tuple{typeof(JpegTurbo_jll.__init__)})
   0.0 ms precompile(Tuple{typeof(JpegTurbo_jll.find_artifact_dir)})
   0.0 ms precompile(Tuple{typeof(LERC_jll.__init__)})
   0.0 ms precompile(Tuple{typeof(LERC_jll.find_artifact_dir)})
   0.0 ms precompile(Tuple{typeof(XZ_jll.__init__)})
   0.0 ms precompile(Tuple{typeof(XZ_jll.find_artifact_dir)})
   0.0 ms precompile(Tuple{typeof(Zstd_jll.__init__)})
   0.0 ms precompile(Tuple{typeof(Zstd_jll.find_artifact_dir)})
   0.0 ms precompile(Tuple{typeof(Libtiff_jll.__init__)})
   0.0 ms precompile(Tuple{typeof(Libtiff_jll.find_artifact_dir)})
   0.0 ms precompile(Tuple{typeof(gdk_pixbuf_jll.__init__)})
   0.0 ms precompile(Tuple{typeof(gdk_pixbuf_jll.find_artifact_dir)})
   0.0 ms precompile(Tuple{typeof(Libepoxy_jll.__init__)})
   0.0 ms precompile(Tuple{typeof(Libepoxy_jll.find_artifact_dir)})
   0.0 ms precompile(Tuple{typeof(ATK_jll.__init__)})
   0.0 ms precompile(Tuple{typeof(ATK_jll.find_artifact_dir)})
   0.0 ms precompile(Tuple{typeof(iso_codes_jll.__init__)})
   0.0 ms precompile(Tuple{typeof(iso_codes_jll.find_artifact_dir)})
   0.0 ms precompile(Tuple{typeof(GTK3_jll.__init__)})
   0.0 ms precompile(Tuple{typeof(GTK3_jll.find_artifact_dir)})
   0.0 ms precompile(Tuple{typeof(Xorg_xkeyboard_config_jll.__init__)})
   0.0 ms precompile(Tuple{typeof(Xorg_xkeyboard_config_jll.find_artifact_dir)})
   0.0 ms precompile(Tuple{typeof(hicolor_icon_theme_jll.__init__)})
   0.0 ms precompile(Tuple{typeof(hicolor_icon_theme_jll.find_artifact_dir)})
   0.0 ms precompile(Tuple{typeof(adwaita_icon_theme_jll.__init__)})
   0.0 ms precompile(Tuple{typeof(adwaita_icon_theme_jll.find_artifact_dir)})
   0.0 ms precompile(Tuple{typeof(Librsvg_jll.__init__)})
   0.0 ms precompile(Tuple{typeof(Librsvg_jll.find_artifact_dir)})
  15.6 ms precompile(Tuple{Gtk.var"#query_pixbuf_loaders#327"{Gtk.var"#query_pixbuf_loaders#322#328"}, String})
   0.0 ms precompile(Tuple{typeof(gdk_pixbuf_jll.gdk_pixbuf_query_loaders)})
   0.0 ms precompile(Tuple{gdk_pixbuf_jll.var"##gdk_pixbuf_query_loaders#4", Bool, Bool, typeof(gdk_pixbuf_jll.gdk_pixbuf_query_loaders)})
   5.7 ms precompile(Tuple{typeof(Base.copy), Base.EnvDict})
   2.5 ms precompile(Tuple{typeof(Base.getindex), Base.RefValue{String}})
   0.0 ms precompile(Tuple{typeof(JLLWrappers.adjust_ENV!), Base.Dict{K, V} where V where K, String, String, Bool, Bool})
   3.1 ms precompile(Tuple{typeof(Base.get), Base.Dict{String, String}, String, String})
   2.0 ms precompile(Tuple{typeof(Base.string), String, Char, Vararg{Union{Char, String, Symbol}}})
   3.2 ms precompile(Tuple{typeof(Base.getindex), Base.Dict{String, String}, String})
   3.2 ms precompile(Tuple{Type{Base.Cmd}, Array{String, 1}})
   2.5 ms precompile(Tuple{Type{NamedTuple{(:env,), T} where T<:Tuple}, Tuple{Base.Dict{String, String}}})
  57.7 ms precompile(Tuple{typeof(Base.addenv), Base.Cmd, Pair{String, String}})
   4.3 ms precompile(Tuple{typeof(Base.read), Base.PipeEndpoint})
   3.2 ms precompile(Tuple{typeof(Base.write), Base.IOStream, Base.SubString{String}})
   0.0 ms precompile(Tuple{typeof(Librsvg_jll.is_available)})
   4.2 ms precompile(Tuple{typeof(Core.kwcall), NamedTuple{(:extra_env,), Tuple{Array{Pair{String, String}, 1}}}, Gtk.var"#query_pixbuf_loaders#327"{Gtk.var"#query_pixbuf_loaders#322#328"}, String})
  13.5 ms precompile(Tuple{typeof(Base.addenv), Base.Cmd, Pair{String, String}, Pair{String, String}})
   3.3 ms precompile(Tuple{typeof(Requires.isprecompiling)})
   0.0 ms precompile(Tuple{typeof(Requires.loadpkg), Base.PkgId})
   3.8 ms precompile(Tuple{typeof(Base.first), Array{Any, 1}})
   2.2 ms precompile(Tuple{Gtk.GLib.var"#100#101"})

IanButterworth · 2024-06-10T13:23:09Z

@JeffBezanson I requested a review given the similarity to #51106

KristofferC · 2024-06-10T13:26:33Z

I would probably always write the comments since it is emitting Julia code after all and it is often nice to copy paste this even from a terminal output.

charleskawczynski

It’d be pretty nice if we could add an option that would sort this list by time

IanButterworth · 2024-06-14T01:23:35Z

These are output as compilation happens, nothing is stored. I believe SnoopCompile already does that kind of thing https://timholy.github.io/SnoopCompile.jl/dev/

KristofferC · 2024-06-14T07:59:33Z

Having some test code that at least exercises the new command line flag would be good.

test/cmdlineargs.jl

…aLang#54662)

NHDaly

Love this feature! 😍 Thanks Ian! :)

We're also using this in the compilation caching effort that @kpamnany and @Drvi are implementing for RelationalAI, to prioritize which methodinstances we precompile for our customers based on their compile time. Thanks for this, Ian! :)

NHDaly · 2024-10-23T14:09:31Z

src/gf.c

+        double compile_time = jl_hrtime();
        int did_compile = jl_compile_codeinst(codeinst);
+        compile_time = jl_hrtime() - compile_time;


@IanButterworth: Can you help me understand why we have so many different variants of measuring this metric (compilation time)?

I was surprised to see we had to add a new start/stop measurement here. We already have a global metric for compilation time, which has timings around inference and llvm codegen. Why didn't we add to the per-method-instance compilation time counters from those places?

Or, conversely, if this spot can correctly capture all compilation time for a given method instance, can we delete those other spots and incremental global compilation time here?

julia/src/gf.c

Lines 4390 to 4396 in fe86437

if (jl_atomic_load_relaxed(&jl_measure_compile_time_enabled)) {

uint64_t inftime = jl_hrtime() - start;

jl_atomic_fetch_add_relaxed(&jl_cumulative_compile_time, inftime);

if (is_recompile) {

jl_atomic_fetch_add_relaxed(&jl_cumulative_recompile_time, inftime);

}

}

julia/src/aotcompile.cpp

Lines 571 to 572 in a98f371

auto end = jl_hrtime();

jl_atomic_fetch_add_relaxed(&jl_cumulative_compile_time, end - compiler_start_time);

julia/src/jitlayers.cpp

Lines 578 to 579 in a98f371

auto end = jl_hrtime();

jl_atomic_fetch_add_relaxed(&jl_cumulative_compile_time, end - compiler_start_time);

... etc

What's the difference between these approaches? Can we unify them?
Thanks!

Maybe that can be reused, yeah. The timer added here seems lower cost than atomic fetches etc. but perhaps it's overcounting.

…aLang#54662) (#187) Co-authored-by: Ian Butterworth <i.r.butterworth@gmail.com>

IanButterworth mentioned this pull request Jun 3, 2024

Precompile the pkg tab completion hint JuliaLang/Pkg.jl#3910

Merged

IanButterworth added needs docs Documentation for this change is required needs news A NEWS entry is required for this change labels Jun 3, 2024

IanButterworth force-pushed the ib/trace_compile_timing branch from 6739936 to b0d7231 Compare June 4, 2024 15:11

IanButterworth removed needs docs Documentation for this change is required needs news A NEWS entry is required for this change labels Jun 4, 2024

tecosaur reviewed Jun 6, 2024

View reviewed changes

IanButterworth force-pushed the ib/trace_compile_timing branch from b0d7231 to a16e5a6 Compare June 9, 2024 16:27

IanButterworth added merge me PR is reviewed. Merge when all tests are passing profiler tooling labels Jun 9, 2024

tecosaur reviewed Jun 9, 2024

View reviewed changes

src/gf.c Outdated Show resolved Hide resolved

IanButterworth removed the merge me PR is reviewed. Merge when all tests are passing label Jun 9, 2024

IanButterworth requested a review from JeffBezanson June 10, 2024 13:22

charleskawczynski reviewed Jun 13, 2024

View reviewed changes

IanButterworth added the needs tests Unit tests are required for this change label Jun 14, 2024

IanButterworth force-pushed the ib/trace_compile_timing branch from b7e49a8 to 6fc39ef Compare June 14, 2024 19:16

IanButterworth removed the needs tests Unit tests are required for this change label Jun 14, 2024

IanButterworth force-pushed the ib/trace_compile_timing branch from 6fc39ef to df768cc Compare June 14, 2024 20:11

add trace-compile-timing arg

3f40180

IanButterworth force-pushed the ib/trace_compile_timing branch from 3455680 to 3f40180 Compare June 15, 2024 01:02

IanButterworth commented Jun 15, 2024

View reviewed changes

test/cmdlineargs.jl Outdated Show resolved Hide resolved

Update cmdlineargs.jl

c20a9fa

IanButterworth added the merge me PR is reviewed. Merge when all tests are passing label Jun 15, 2024

IanButterworth merged commit 0ae5b32 into JuliaLang:master Jun 15, 2024
8 checks passed

oscardssmith removed the merge me PR is reviewed. Merge when all tests are passing label Jun 15, 2024

topolarity pushed a commit to topolarity/julia that referenced this pull request Aug 8, 2024

add --trace-compile-timing arg to add compile timing comments (Juli…

58421a0

…aLang#54662)

kpamnany pushed a commit to RelationalAI/julia that referenced this pull request Sep 25, 2024

add --trace-compile-timing arg to add compile timing comments (Juli…

1aef47e

…aLang#54662)

kpamnany mentioned this pull request Sep 25, 2024

Backport: add --trace-compile-timing arg to add compile timing comments (#54662) RelationalAI/julia#187

Merged

3 tasks

kpamnany pushed a commit to RelationalAI/julia that referenced this pull request Oct 22, 2024

add --trace-compile-timing arg to add compile timing comments (Juli…

5c5872f

…aLang#54662)

NHDaly reviewed Oct 23, 2024

View reviewed changes

IanButterworth deleted the ib/trace_compile_timing branch October 23, 2024 14:14

kpamnany added a commit to RelationalAI/julia that referenced this pull request Oct 23, 2024

add --trace-compile-timing arg to add compile timing comments (Juli…

f481fc9

…aLang#54662) (#187) Co-authored-by: Ian Butterworth <i.r.butterworth@gmail.com>

nickrobinson251 pushed a commit to RelationalAI/julia that referenced this pull request Feb 26, 2025

add --trace-compile-timing arg to add compile timing comments (Juli…

2bb1019

…aLang#54662) (#187) Co-authored-by: Ian Butterworth <i.r.butterworth@gmail.com>

Provide feedback

Saved searches

Use saved searches to filter your results more quickly

add `--trace-compile-timing` arg to add compile timing comments #54662

add `--trace-compile-timing` arg to add compile timing comments #54662

IanButterworth commented Jun 3, 2024 •

edited

Loading

tecosaur commented Jun 6, 2024

tecosaur Jun 6, 2024

IanButterworth Jun 6, 2024

tecosaur commented Jun 6, 2024

IanButterworth commented Jun 9, 2024

IanButterworth commented Jun 9, 2024

IanButterworth commented Jun 9, 2024

IanButterworth commented Jun 9, 2024 •

edited

Loading

IanButterworth commented Jun 9, 2024

IanButterworth commented Jun 10, 2024

KristofferC commented Jun 10, 2024

charleskawczynski left a comment

IanButterworth commented Jun 14, 2024

KristofferC commented Jun 14, 2024

NHDaly left a comment

NHDaly Oct 23, 2024

IanButterworth Oct 23, 2024

	if (jl_atomic_load_relaxed(&jl_measure_compile_time_enabled)) {
	uint64_t inftime = jl_hrtime() - start;
	jl_atomic_fetch_add_relaxed(&jl_cumulative_compile_time, inftime);
	if (is_recompile) {
	jl_atomic_fetch_add_relaxed(&jl_cumulative_recompile_time, inftime);
	}
	}

	auto end = jl_hrtime();
	jl_atomic_fetch_add_relaxed(&jl_cumulative_compile_time, end - compiler_start_time);

add --trace-compile-timing arg to add compile timing comments #54662

add --trace-compile-timing arg to add compile timing comments #54662

Conversation

IanButterworth commented Jun 3, 2024 • edited Loading

tecosaur commented Jun 6, 2024

tecosaur Jun 6, 2024

Choose a reason for hiding this comment

IanButterworth Jun 6, 2024

Choose a reason for hiding this comment

tecosaur commented Jun 6, 2024

IanButterworth commented Jun 9, 2024

IanButterworth commented Jun 9, 2024

IanButterworth commented Jun 9, 2024

IanButterworth commented Jun 9, 2024 • edited Loading

IanButterworth commented Jun 9, 2024

IanButterworth commented Jun 10, 2024

KristofferC commented Jun 10, 2024

charleskawczynski left a comment

Choose a reason for hiding this comment

IanButterworth commented Jun 14, 2024

KristofferC commented Jun 14, 2024

NHDaly left a comment

Choose a reason for hiding this comment

NHDaly Oct 23, 2024

Choose a reason for hiding this comment

IanButterworth Oct 23, 2024

Choose a reason for hiding this comment

add `--trace-compile-timing` arg to add compile timing comments #54662

add `--trace-compile-timing` arg to add compile timing comments #54662

IanButterworth commented Jun 3, 2024 •

edited

Loading

IanButterworth commented Jun 9, 2024 •

edited

Loading