add total time to @time_imports

[Moelf]

fix #46850

julia> @time_imports using Revise
      6.1 ms  OrderedCollections
      2.4 ms  CodeTracking
    105.0 ms  JuliaInterpreter 27.35% compilation time
     79.2 ms  LoweredCodeUtils
    242.2 ms  Revise 27.35% compilation time
Total imports time: 0.630051 seconds (1.11 M allocations: 79.053 MiB, 10.82% gc time, 44.82% compilation time)

[IanButterworth]

What causes the total to be so much bigger??

[Moelf]

Peek.2022-10-08.12-57.mp4

don't know, it seems there's something going on after importing the last item in the list, and that time is not accounted for in the list

[Moelf]

Peek.2022-10-08.13-00.mp4

seems to be a fixed overhead

julia> @time_imports using Plots
      0.7 ms  Statistics
      0.2 ms  Requires
      0.1 ms  Reexport
      4.7 ms  Unzip
      0.1 ms  SnoopPrecompile
     27.5 ms  RecipesBase
     39.2 ms  FixedPointNumbers
     59.1 ms  ColorTypes 9.15% compilation time
    204.8 ms  Colors
      5.6 ms  IrrationalConstants
      0.1 ms  Compat
     61.0 ms  ChainRulesCore
      3.7 ms  DocStringExtensions 75.23% compilation time
      0.8 ms  ChangesOfVariables
      0.7 ms  InverseFunctions
      0.6 ms  LogExpFunctions
      0.1 ms  OpenLibm_jll
     20.0 ms  Preferences
      0.3 ms  JLLWrappers
      3.1 ms  OpenSpecFun_jll 87.58% compilation time
     17.1 ms  SpecialFunctions
      0.3 ms  TensorCore
    153.5 ms  ColorVectorSpace 3.50% compilation time
      8.7 ms  ColorSchemes
    234.4 ms  PlotUtils
     28.3 ms  PlotThemes
      0.3 ms  NaNMath
     72.9 ms  RecipesPipeline
      1.1 ms  UnicodeFun
      0.8 ms  DataAPI
      6.5 ms  OrderedCollections
     65.7 ms  DataStructures
      0.4 ms  SortingAlgorithms
      8.0 ms  Missings
      0.3 ms  StatsAPI
     25.5 ms  StatsBase
      0.2 ms  Showoff
      0.2 ms  fzf_jll
      0.1 ms  Pipe
      0.1 ms  JLFzf
     58.9 ms  Parsers 10.96% compilation time
     21.8 ms  JSON
      6.7 ms  Measures
      0.4 ms  Bzip2_jll
      0.1 ms  Zlib_jll
      0.2 ms  FreeType2_jll
      0.2 ms  FriBidi_jll
      0.3 ms  Libiconv_jll
      0.2 ms  Libffi_jll
      0.3 ms  XML2_jll
      0.3 ms  Gettext_jll
      0.1 ms  PCRE2_jll
      0.3 ms  Libmount_jll
      0.8 ms  Glib_jll
      0.3 ms  Pixman_jll
      0.2 ms  libpng_jll
      0.2 ms  Libuuid_jll
      0.2 ms  Expat_jll
      3.9 ms  Fontconfig_jll 87.04% compilation time
      0.3 ms  Libgpg_error_jll
      0.2 ms  Libgcrypt_jll
      0.4 ms  XSLT_jll
      0.2 ms  Xorg_libXau_jll
      0.2 ms  Xorg_libXdmcp_jll
      0.1 ms  Xorg_libpthread_stubs_jll
      1.4 ms  Xorg_libxcb_jll
      0.1 ms  Xorg_xtrans_jll
      0.3 ms  Xorg_libX11_jll
      0.3 ms  Xorg_libXext_jll
      0.2 ms  Xorg_libXrender_jll
      0.2 ms  LZO_jll
      0.7 ms  Cairo_jll
      0.2 ms  Graphite2_jll
      0.4 ms  HarfBuzz_jll
      0.3 ms  libass_jll
      0.2 ms  libfdk_aac_jll
      0.2 ms  LAME_jll
      0.2 ms  Ogg_jll
      0.4 ms  libvorbis_jll
      0.3 ms  libaom_jll
      0.2 ms  x264_jll
      0.2 ms  x265_jll
      0.4 ms  OpenSSL_jll
      0.2 ms  Opus_jll
      1.7 ms  FFMPEG_jll
      0.2 ms  FFMPEG
      0.1 ms  Scratch
      0.3 ms  RelocatableFolders
      0.8 ms  Libglvnd_jll
      0.2 ms  Xorg_libXfixes_jll
      0.3 ms  Xorg_libXcursor_jll
      0.3 ms  Xorg_libXi_jll
      0.3 ms  Xorg_libXinerama_jll
      0.2 ms  Xorg_libXrandr_jll
      0.3 ms  GLFW_jll
      0.3 ms  JpegTurbo_jll
      0.3 ms  LERC_jll
      0.3 ms  Zstd_jll
      0.3 ms  Libtiff_jll
      0.2 ms  Xorg_xcb_util_jll
      0.3 ms  Xorg_xcb_util_wm_jll
      0.2 ms  Xorg_xcb_util_image_jll
      0.2 ms  Xorg_xcb_util_keysyms_jll
      0.2 ms  Xorg_xcb_util_renderutil_jll
      0.2 ms  Xorg_libxkbfile_jll
      0.2 ms  Xorg_xkbcomp_jll
      0.2 ms  Xorg_xkeyboard_config_jll
      0.4 ms  Wayland_jll
      0.1 ms  Wayland_protocols_jll
      0.3 ms  xkbcommon_jll
      3.4 ms  Qt5Base_jll
      0.8 ms  GR_jll
     73.2 ms  GR 48.61% compilation time
   2026.6 ms  Plots 31.53% compilation time (65% recompilation)
Total imports time: 3.377671 seconds (6.49 M allocations: 451.861 MiB, 6.86% gc time, 22.08% compilation time: 56% of which was recompilation)

[nickrobinson251]

I think "total imports time" gives the impression its a sum of import times

For instance, it's possible to do
@time_imports include("foo.jl")

It seems confusing (to me) for this to show a "total" that's not the sum of the individual import times. In fact it's just timing a different thing. Personally I think it'd be better to just recommend @time @time_imports ... for this so it's explicit what's going on -- perhaps this idiom can be noted prominently in the docs related to @time_imports. As is, I expect this to result in a lot of questions like "What causes the total to be so much bigger??".

In contrast, I think showing the sum would be a useful addition -- i know i've wished for that a few times! -- and maybe was the intended request of #46850 (idk, @baggepinnen would have to clarify 😄)

[Moelf]

the reality is there' 's a gap:

|<--------@time---------------------------->|
   |<-----------@time_imports ------->|
|? |import1, import2..................| gap |

we can either document it, add another time, or just let it be. I mean the current total time is the total time, the @time_imports is just... the imports time?

it's also not true the "time" reported is exactly your wall time anyway, so if perfect is the enemy of better in this case, I can close this PR

[oscardssmith]

Is it worth profiling to see what's actually happening in the gap?

[Moelf]

can we profile this from just Julia side?

[gbaraldi]

Doesn't @time do some extra work or am I mistaken?

[KristofferC]

I agree that a timing here that is not the sum of the load times just above would be confusing. An implementation that accumulates the times (and perhaps also shows all the "in-between time") could make sense though.