Major slowdown in package load time #466

timholy · 2019-12-10T12:21:24Z

On Julia 1.2:

julia> @time using Gtk
  0.942820 seconds (1.12 M allocations: 59.659 MiB, 2.51% gc time)

On Julia 1.3:

julia> @time using Gtk
Gtk-Message: 06:20:49.607: Failed to load module "canberra-gtk-module"
Gtk-Message: 06:20:49.608: Failed to load module "canberra-gtk-module"
 14.152626 seconds (37.38 M allocations: 1.838 GiB, 3.19% gc time)

On julia-master (1.4.0-DEV.568 (2019-12-09)):

julia> @time using Gtk
Gtk-Message: 05:55:21.966: Failed to load module "canberra-gtk-module"
Gtk-Message: 05:55:21.967: Failed to load module "canberra-gtk-module"
  9.269185 seconds (18.55 M allocations: 940.923 MiB, 2.65% gc time)

tknopp · 2019-12-10T12:29:36Z

Yes, this is very bad. There has been some discussions on slack yesterday on that (ping @KristofferC @vtjnash and @staticfloat). It boils down to package loading being slow as far as I understand. The huge amount of memory allocation looks like some type instabilities during package loading.

timholy · 2019-12-10T12:30:49Z

It's mostly dump.c: jl_recache_method_instance. The dark underbelly of caching more inference results?

tknopp · 2019-12-10T12:35:35Z

The interesting bit here is, if there is so much more new code to be inferred with the new artifact system. If yes that could be an architectural problem of the system. If not it would be more the module loading where there is room for improvement.

timholy · 2019-12-10T12:49:15Z

Here's a gist of the methods. A lot of those seem unnecessary. Tuple{typeof(Base.getindex), Array{T, N} where N where T, Int64}, why is that there? Tuple{typeof(Base.:(==)), Float64, Float64}, really?

For the record, the output was created by building Julia with this diff:

diff --git a/src/dump.c b/src/dump.c
index 9fd00e5f52..1d8a4638c0 100644
--- a/src/dump.c
+++ b/src/dump.c
@@ -3098,6 +3098,7 @@ static jl_method_instance_t *jl_recache_method_instance(jl_method_instance_t *mi
 {
     jl_datatype_t *sig = (jl_datatype_t*)mi->def.value;
     assert(jl_is_datatype(sig) || jl_is_unionall(sig));
+    jl_(sig);
     jl_methtable_t *mt = jl_method_table_for((jl_value_t*)sig);
     assert((jl_value_t*)mt != jl_nothing);
     jl_method_t *m = jl_lookup_method_worldset(mt, sig, dependent_worlds);

timholy · 2019-12-10T12:55:06Z

There is some overhead from artifacts, see JuliaLang/Pkg.jl#1521 (comment). But that's not remotely the major issue, this jl_recache_method_instance is by far the main contribution.

tknopp · 2019-12-10T12:58:16Z

Can one verify easily if Tuple{typeof(Base.:(==)), Float64, Float64} is in the system image, where I would assume it to be?

timholy · 2019-12-10T13:03:41Z

Seems like it:

julia> using SnoopCompile

julia> tinf = @snoopi 1.2 == 1.3
0-element Array{Tuple{Float64,Core.MethodInstance},1}

EDIT: though this is uncertain due to the interpreter running quite a lot more code lately.

Let's try this instead:

$ julia-master --startup-file=no -q
julia> m = which(==, (Float64, Float64))
==(x::Float64, y::Float64) in Base at float.jl:454

julia> m.specializations
Core.TypeMapEntry(nothing, Tuple{typeof(==),Float64,Float64}, nothing, svec(), 0x0000000000000001, 0xffffffffffffffff, MethodInstance for ==(::Float64, ::Float64), true, true, false)

tknopp · 2019-12-10T13:09:17Z

Ok, so what is the purpose of recache is it recompiling functions? If yes, then this looks like a bug in Julia, right? Recompilation should only kick in, if the world has change.

giordano · 2019-12-10T13:22:39Z

Yes, yesterday we had some discussions about how to improve this in the #binarybuilder Slack channel.

One thing that seems to badly affect performance is having 75 JLL packages. I manually created https://github.com/giordano/TestGtkMegaJLL.jl which installs the same artifacts as Gtk.jl, but loads them in a single JLL. Loading this on Julia 1.3.0 takes for me 6.4 seconds, compared to 14.7 seconds for using GTK3_jll.

Here you can see a comparison of profile of loading the two packages on backports-release-1.3: https://gist.github.com/giordano/e9bdb50314825be41fd4b96823983089.

Precompilation time difference is also huge:

julia> @time using TestGtkMegaJLL
[ Info: Precompiling TestGtkMegaJLL [05f542c5-fd2e-4f6f-a354-1fd7cae9a8d6]
  9.759602 seconds (6.54 M allocations: 376.568 MiB, 2.88% gc time)

julia> @time using GTK3_jll
[ Info: Precompiling GTK3_jll [77ec8976-b24b-556a-a1bf-49a033a670a6]
160.784716 seconds (12.32 M allocations: 643.697 MiB, 0.12% gc time)

timholy · 2019-12-10T13:33:22Z

On Julia 1.3, the module __init__ functions take a huge amount of inference time. Demo:

julia> using SnoopCompile

julia> tinf = @snoopi(using Gtk);
Gtk-Message: 07:27:42.676: Failed to load module "canberra-gtk-module"
Gtk-Message: 07:27:42.677: Failed to load module "canberra-gtk-module"

julia> tinf_init = filter(ti->ti[2].def.name == :__init__, tinf)
55-element Array{Tuple{Float64,Core.MethodInstance},1}:
 (0.003771066665649414, MethodInstance for __init__()) 
 (0.0038309097290039062, MethodInstance for __init__())
 (0.003856182098388672, MethodInstance for __init__()) 
 (0.0038878917694091797, MethodInstance for __init__())
 (0.004130125045776367, MethodInstance for __init__()) 
 (0.00421905517578125, MethodInstance for __init__())  
 (0.004297018051147461, MethodInstance for __init__()) 
 (0.004312992095947266, MethodInstance for __init__()) 
 (0.00441288948059082, MethodInstance for __init__())  
 (0.004434823989868164, MethodInstance for __init__()) 
 (0.004436016082763672, MethodInstance for __init__()) 
 (0.004615068435668945, MethodInstance for __init__()) 
 (0.004637956619262695, MethodInstance for __init__()) 
 (0.0053288936614990234, MethodInstance for __init__())
 (0.005736827850341797, MethodInstance for __init__()) 
 (0.007604837417602539, MethodInstance for __init__()) 
 (0.00795602798461914, MethodInstance for __init__())  
 (0.008533000946044922, MethodInstance for __init__()) 
 (0.015301942825317383, MethodInstance for __init__()) 
 (0.015435218811035156, MethodInstance for __init__()) 
 (0.01696920394897461, MethodInstance for __init__())  
 (0.017121076583862305, MethodInstance for __init__()) 
 (0.017448902130126953, MethodInstance for __init__()) 
 (0.017663955688476562, MethodInstance for __init__()) 
 (0.020895004272460938, MethodInstance for __init__()) 
 ⋮                                                     
 (0.024278879165649414, MethodInstance for __init__()) 
 (0.026558876037597656, MethodInstance for __init__()) 
 (0.027850866317749023, MethodInstance for __init__()) 
 (0.028738975524902344, MethodInstance for __init__()) 
 (0.02926778793334961, MethodInstance for __init__())  
 (0.029626131057739258, MethodInstance for __init__()) 
 (0.029721975326538086, MethodInstance for __init__()) 
 (0.030618906021118164, MethodInstance for __init__()) 
 (0.03087306022644043, MethodInstance for __init__())  
 (0.03187108039855957, MethodInstance for __init__())  
 (0.03188586235046387, MethodInstance for __init__())  
 (0.03224515914916992, MethodInstance for __init__())  
 (0.03488278388977051, MethodInstance for __init__())  
 (0.04364299774169922, MethodInstance for __init__())  
 (0.043882131576538086, MethodInstance for __init__()) 
 (0.04580998420715332, MethodInstance for __init__())  
 (0.059014081954956055, MethodInstance for __init__()) 
 (0.06346702575683594, MethodInstance for __init__())  
 (0.07057499885559082, MethodInstance for __init__())  
 (0.07920098304748535, MethodInstance for __init__())  
 (0.08695387840270996, MethodInstance for __init__())  
 (0.09126591682434082, MethodInstance for __init__())  
 (0.13810110092163086, MethodInstance for __init__())  
 (0.1540839672088623, MethodInstance for __init__())   
 (0.3740198612213135, MethodInstance for __init__())   

julia> sum(first, tinf_init)
1.9639902114868164

So on my machine, 2 seconds are spent inferring the __init__ functions of the various modules, almost all of which are JLL modules. Consequently, reducing to one big module is certain to improve performance. Interestingly, only one registers on 1.4, and it's Gtk's own __init__:

julia> tinf_init = filter(ti->ti[2].def.name == :__init__, tinf)
1-element Array{Tuple{Float64,Core.MethodInstance},1}:
 (0.13563799858093262, MethodInstance for __init__())

julia> tinf_init[1][2].def
__init__() in Gtk at /home/tim/.julia/packages/Gtk/u6VBX/src/Gtk.jl:74

This only takes 130ms, so you're likely to see far less benefit from squashing the JLLs together on Julia 1.4. (Unless the __init__ functions are interpreted, in which case they still might take time.)

But that build time difference is amazing!

So this is definitely one factor. But as @tknopp says, I also suspect a bug that's causing jl_recache_method_instance to be called on more things than is really necessary.

giordano · 2019-12-10T13:40:22Z

I must stress that https://github.com/giordano/TestGtkMegaJLL.jl is very manually crafted and doesn't include all operations performed in all JLL packages. In particular, the __init__ function only does the artifacts"..." calls, which as far as I can tell is by far the most time-consuming operation in JLL's __init__ functions.

KristofferC · 2019-12-10T15:01:11Z

FWIW, with julia master and JuliaLang/Pkg.jl#1521 I get

  6.876820 seconds (14.60 M allocations: 761.300 MiB, 2.36% gc time)

vs on 1.3

 10.728664 seconds (16.72 M allocations: 923.099 MiB, 1.86% gc time)

In the first case, the sum of @snoopis is only 0.16 so that doesn't seem to be a big factor anymore.

With the mega-jll (master and Pkg PR again) I get:

julia> @time using TestGtkMegaJLL
  1.703740 seconds (6.59 M allocations: 381.041 MiB, 8.81% gc time)

For this the sum of @snoopi`s is 0.6 which is significant.

vtjnash · 2019-12-10T15:28:06Z

I don’t think JuliaLang/Pkg.jl#1521 is a good idea (thanks @KristofferC for measuring actual numbers!). I had opened JuliaPackaging/BinaryBuilder.jl#538 to track this.

timholy · 2019-12-10T17:09:20Z

Yes, like I said, this isn't mostly about inference, this is about jl_recache_method_instance, i.e., loading the *.ji file(s).

KristofferC · 2019-12-10T17:23:05Z

@timholy, could you try the same analysis on JuliaLang/julia#33979 where there are some inference barriers put in to hopefully reduce the number of backedges etc

timholy · 2019-12-10T19:58:56Z

Are those the same barriers on master? I did test master (see #466 (comment)), which is better but still far worse than 1.2.

But I will start building it. Busy day so it may be a while.

KristofferC · 2019-12-10T20:00:36Z

I don't think that is on master.

timholy · 2019-12-10T23:02:12Z

That 1.3.1 backports branch is considerably faster than 1.3.0 (9s instead of 14s), though still dreadfully slow compared to 1.2 (~1s). Moreover, the profile is considerably different. On that branch here are the main bottlenecks:

~35% from https://github.com/JuliaLang/julia/blob/8639e5771d6cf5e0e70a359674232f4884a052ac/src/toplevel.c#L74
~30% from https://github.com/JuliaLang/julia/blob/8639e5771d6cf5e0e70a359674232f4884a052ac/src/gf.c#L1803
~20% from jl_recache_method_instance (a dramatic decrease compared to my profile in the OP), scattered across 4 lines

timholy · 2019-12-11T00:34:18Z

Hmm, bizarrely having rebuilt everything I'm getting much more consistent profiles across versions. They pretty much all look like #466 (comment) now (in both Julia 1.3.0 and julia-master). The total time is different, but the distribution of resources is about the same. And all between 20-28% on jl_recache_method_instance, which is not what I was seeing earlier. I wonder if I was on a branch for 1.3? Anyway, the total time is about the same, it's just the cause that's different.

KristofferC · 2019-12-11T08:04:55Z

On the mega JLL package I put @time in front of all the artifact"" macros and got on 1.3.0:

  0.877816 seconds (3.87 M allocations: 194.444 MiB, 2.54% gc time)
  0.032678 seconds (76.97 k allocations: 5.094 MiB)
  0.032699 seconds (76.97 k allocations: 5.094 MiB)
  0.160977 seconds (572.15 k allocations: 29.871 MiB, 19.79% gc time)
  0.032302 seconds (77.02 k allocations: 5.097 MiB)
  0.164856 seconds (576.34 k allocations: 30.126 MiB, 15.57% gc time)
  0.032874 seconds (76.97 k allocations: 5.094 MiB)
  0.032714 seconds (76.97 k allocations: 5.094 MiB)
  0.032419 seconds (76.97 k allocations: 5.094 MiB)
  0.032321 seconds (76.97 k allocations: 5.094 MiB)
  0.035085 seconds (76.97 k allocations: 5.094 MiB, 9.32% gc time)
  0.031713 seconds (76.97 k allocations: 5.094 MiB)
...

and on 1.3.1 branch

  0.957174 seconds (3.65 M allocations: 181.921 MiB, 9.36% gc time)
  0.000227 seconds (965 allocations: 60.703 KiB)
  0.000215 seconds (965 allocations: 60.703 KiB)
  0.171062 seconds (496.07 k allocations: 24.829 MiB, 34.15% gc time)
  0.000200 seconds (1.01 k allocations: 63.141 KiB)
  0.109326 seconds (500.29 k allocations: 25.089 MiB)
  0.000157 seconds (965 allocations: 60.703 KiB)
  0.000173 seconds (965 allocations: 60.703 KiB)
  0.000128 seconds (965 allocations: 60.703 KiB)

So in both cases, the first call is slow but the median is much faster on 1.3.1. There are still times where artifact"" (randomly?) takes takes a lot longer than average. Running julia with --trace-compile=stderr we get:

 0.000225 seconds (965 allocations: 60.703 KiB)
  0.000151 seconds (965 allocations: 60.703 KiB)
precompile(Tuple{Type{Base.Dict{Pkg.BinaryPlatforms.Linux, Base.Dict{String, Any}}}})
precompile(Tuple{typeof(Base.empty), Base.Dict{Any, Any}, Type{Pkg.BinaryPlatforms.Linux}, Type{Base.Dict{String, Any}}})
precompile(Tuple{typeof(Base.rehash!), Base.Dict{Pkg.BinaryPlatforms.Linux, Base.Dict{String, Any}}, Int64})
precompile(Tuple{typeof(Base.ht_keyindex2!), Base.Dict{Pkg.BinaryPlatforms.Linux, Base.Dict{String, Any}}, Pkg.BinaryPlatforms.Linux})
precompile(Tuple{typeof(Base.setindex!), Base.Dict{Pkg.BinaryPlatforms.Linux, Base.Dict{String, Any}}, Base.Dict{String, Any}, Pkg.BinaryPlatforms.Linux})
precompile(Tuple{typeof(Base.grow_to!), Base.Dict{Pkg.BinaryPlatforms.Linux, Base.Dict{String, Any}}, Base.Generator{Array{Base.Dict{String, Any}, 1}, getfield(Pkg.Artifacts, Symbol("#21#22")){String, String}}, Int64})
precompile(Tuple{typeof(Base.empty), Base.Dict{Pkg.BinaryPlatforms.Linux, Base.Dict{String, Any}}, Type{Pkg.BinaryPlatforms.Platform}, Type{Base.Dict{String, Any}}})
precompile(Tuple{typeof(Base.merge!), Base.Dict{Pkg.BinaryPlatforms.Platform, Base.Dict{String, Any}}, Base.Dict{Pkg.BinaryPlatforms.Linux, Base.Dict{String, Any}}})
  0.172876 seconds (496.07 k allocations: 24.829 MiB, 33.53% gc time)
  0.000210 seconds (1.01 k allocations: 63.141 KiB)
precompile(Tuple{Type{Base.Dict{Pkg.BinaryPlatforms.Windows, Base.Dict{String, Any}}}})
precompile(Tuple{typeof(Base.empty), Base.Dict{Any, Any}, Type{Pkg.BinaryPlatforms.Windows}, Type{Base.Dict{String, Any}}})
precompile(Tuple{typeof(Base.rehash!), Base.Dict{Pkg.BinaryPlatforms.Windows, Base.Dict{String, Any}}, Int64})
precompile(Tuple{typeof(Base.ht_keyindex2!), Base.Dict{Pkg.BinaryPlatforms.Windows, Base.Dict{String, Any}}, Pkg.BinaryPlatforms.Windows})
precompile(Tuple{typeof(Base.setindex!), Base.Dict{Pkg.BinaryPlatforms.Windows, Base.Dict{String, Any}}, Base.Dict{String, Any}, Pkg.BinaryPlatforms.Windows})
precompile(Tuple{typeof(Base.grow_to!), Base.Dict{Pkg.BinaryPlatforms.Windows, Base.Dict{String, Any}}, Base.Generator{Array{Base.Dict{String, Any}, 1}, getfield(Pkg.Artifacts, Symbol("#21#22")){String, String}}, Int64})
precompile(Tuple{typeof(Base.empty), Base.Dict{Pkg.BinaryPlatforms.Windows, Base.Dict{String, Any}}, Type{Pkg.BinaryPlatforms.Platform}, Type{Base.Dict{String, Any}}})
precompile(Tuple{typeof(Base.merge!), Base.Dict{Pkg.BinaryPlatforms.Platform, Base.Dict{String, Any}}, Base.Dict{Pkg.BinaryPlatforms.Windows, Base.Dict{String, Any}}})
  0.108545 seconds (500.29 k allocations: 25.089 MiB)
  0.000157 seconds (965 allocations: 60.703 KiB)
....

So the slow artifact"" calls are associated with compilation of methods and many of them seem related to that the different platforms have different types and get specialized on?

KristofferC · 2019-12-11T09:09:58Z

I did an experiment where I tweaked the artifact macro and tried push more stuff to compile time and tried to simplify what the macro is allowed to do: JuliaLang/Pkg.jl@e07a2df.

With that branch I get

Gtk:

@time using Gtk
Gtk-Message: 10:07:06.749: Failed to load module "canberra-gtk-module"
Gtk-Message: 10:07:06.749: Failed to load module "canberra-gtk-module"
  4.473285 seconds (6.62 M allocations: 358.467 MiB, 1.30% gc time)

@time using TestGtkMegaJLL
 0.688373 seconds (1.20 M allocations: 61.661 MiB)

KristofferC · 2019-12-11T09:21:16Z

Including the PR to Pkg that precompiles the artfiact code with the simplified artifact macro I get

julia> @time using TestGtkMegaJLL
  0.277852 seconds (195.38 k allocations: 11.309 MiB)

doesn't seem to really help with Gtk though.

giordano · 2019-12-11T09:26:51Z

doesn't seem to really help with Gtk though

Is that because the first invocation of artifact"..." in each package is slow? Or maybe there is something I left out of the mega package that is slowing things down?

KristofferC · 2019-12-11T09:37:35Z

I think it is just overhead of many package, some profile output:

   867         0 /home/kc/juliamaster/src/codegen.cpp                                                          1481 jl_generate_fptr
   879         0 /home/kc/juliamaster/src/jitlayers.cpp                                                         759 jl_add_to_ee
   879         0 /home/kc/juliamaster/src/jitlayers.cpp                                                         767 jl_finalize_function
   879         0 /home/kc/juliamaster/src/codegen.cpp                                                          1387 getAddressForFunction
   879         0 /home/kc/juliamaster/src/gf.c                                                                 1912 jl_compile_method_internal
   952         0 /home/kc/juliamaster/src/gf.c                                                                 2322 jl_apply_generic
   961         0 /home/kc/juliamaster/src/gf.c                                                                 2153 _jl_invoke
  1013         0 /home/kc/juliamaster/src/toplevel.c                                                             74 jl_module_run_initializer
  1014         0 /home/kc/juliamaster/src/dump.c                                                               2468 jl_init_restored_modules
  1014         0 @Base/loading.jl                                                                               690 _include_from_serialized(::String, ::Array{Any,1})
  1335         0 /home/kc/juliamaster/src/typemap.c                                                             572 jl_typemap_intersection_visitor
  1369         5 /home/kc/juliamaster/src/typemap.c                                                             484 jl_typemap_intersection_node_visitor
  1372         0 /home/kc/juliamaster/src/dump.c                                                               3130 jl_recache_other
  1373         0 /home/kc/juliamaster/src/gf.c                                                                 2723 ml_matches
  1378         0 /home/kc/juliamaster/src/dump.c                                                               3219 _jl_restore_incremental
  1380         1 /home/kc/juliamaster/src/gf.c                                                                 1811 jl_matching_methods
  1386         0 /home/kc/juliamaster/src/dump.c                                                               2261 jl_insert_backedges
  1464         0 /home/kc/juliamaster/src/dump.c                                                               3225 _jl_restore_incremental
  3559         0 /home/kc/juliamaster/src/dump.c                                                               3263 jl_restore_incremental
  3559         0 @Base/loading.jl                                                                               674 _include_from_serialized(::String, ::Array{Any,1})
  4453         0 @Base/loading.jl                                                                               705 _tryrequire_from_serialized(::Base.PkgId, ::UInt64, ::String)
  4453         0 @Base/loading.jl                                                                               763 _require_search_from_serialized(::Base.PkgId, ::String)
  4573         0 @Base/loading.jl                                                                               774 _require_search_from_serialized(::Base.PkgId, ::String)
  4917         0 @Base/loading.jl                                                                               999 _require(::Base.PkgId)
  4917         0 @Base/loading.jl                                                                               920 require(::Base.PkgId)
  4917         0 @Base/loading.jl                                                                               915 require(::Module, ::Symbol)
  4917         0 /home/kc/juliamaster/src/toplevel.c                                                            399 call_require
  4917         0 /home/kc/juliamaster/src/toplevel.c                                                            436 eva

so quite a lot is in e.g. backedges

staticfloat · 2019-12-11T16:37:24Z

@KristofferC in that PR, it looks to me like you're not processing the overrides properly anymore; so it may not be an apples-to-apples comparison. I don't really expect that to be a time-heavy part, but it would be good to make sure that's true.

staticfloat · 2019-12-11T16:38:20Z

So the slow artifact"" calls are associated with compilation of methods and many of them seem related to that the different platforms have different types and get specialized on?

This makes a lot of sense; it may be worthwhile to sprinkle @nospecialize around platform objects.

KristofferC · 2019-12-11T20:02:26Z

@KristofferC in that PR, it looks to me like you're not processing the overrides properly anymore; so it may not be an apples-to-apples comparison

Yeah, I didn't know exactly how things worked but I saw that load_artifacts_toml already did an override check so I thought it was perhaps already included somehow.

https://github.com/JuliaLang/Pkg.jl/blob/258d74ecd4104aadb34ff65f384782eb9a8eacd5/src/Artifacts.jl#L472

Anyway, we can add back the override check and make sure that we shield as much away with inference barriers. I do think we can do more at compile time than we currently do though.

IanButterworth · 2019-12-23T20:33:31Z

If the performance report is helpful, I just tried the 1.3.1 pre-release binaries on MacOS and got this:

   _       _ _(_)_     |  Documentation: https://docs.julialang.org
  (_)     | (_) (_)    |
   _ _   _| |_  __ _   |  Type "?" for help, "]?" for Pkg help.
  | | | | | | |/ _` |  |
  | | |_| | | | (_| |  |  Version 1.3.1 (2019-12-19)
 _/ |\__'_|_|_|\__'_|  |  refs/pull/33820/merge/ee4a096f62 (fork: 117 commits, 128 days)
|__/                   |

julia> @time using Gtk
[ Info: Precompiling Gtk [4c0ca9eb-093a-5379-98c5-f87ac0bbbf44]
 83.912350 seconds (11.89 M allocations: 597.312 MiB, 0.36% gc time)

julia> @time using Gtk
  4.749830 seconds (6.88 M allocations: 362.573 MiB, 1.16% gc time)

julia> @time using Gtk
  6.485853 seconds (11.26 M allocations: 568.069 MiB, 4.15% gc time)

julia> @time using Gtk
  6.114788 seconds (11.26 M allocations: 568.028 MiB, 3.85% gc time)

Not sure why that first using after restart was faster and different in footprint..

timholy · 2020-05-07T17:57:08Z

Things are a lot better with Julia 1.5 than when I first reported this, I'm down to about 6s on the same laptop. If I disable method invalidation, it's around 5s, so invalidation is significant but not massive.

If I look at the remainder, about 95% is two ccalls, from loading.jl to jl_restore_incremental and jl_init_restored_modules. If we break that down further

about 45% of actual overhead is from type-related stuff (subtype.c, jltypes.c, julia.h, typemap.c), presumably mostly for method tables and backedges
about 30% of actual overhead is LLVM
only 0.4s is due to inference. One method instance, do_artifact_str(::String, ::Dict{String,Any}, ::String, ::Module), takes 0.3s of this 0.4s. Nothing else is above 20ms, and the vast majority are a bunch of foreach methods (you'll see those below).
the rest is pretty scattered without obvious pattern

I've looked at the methods that are getting compiled by putting jl_(mi); in jl_compile_method_internal:

julia> using Gtk
__init__()
getindex(Base.Dict{Symbol, Base.Dict{K, V} where V where K}, Symbol)
haskey(Base.Dict{Base.UUID, Base.Dict{String, Union{Base.SHA1, String}}}, Base.UUID)
Type##kw(NamedTuple{(:libc, :compiler_abi), Tuple{Nothing, Pkg.BinaryPlatforms.CompilerABI}}, Type{Pkg.BinaryPlatforms.FreeBSD}, Symbol)
(::Type{Base.Pair{A, B} where B where A})(Pkg.BinaryPlatforms.FreeBSD, Base.Dict{String, Any})
setindex!(Base.Dict{Pkg.BinaryPlatforms.Platform, Base.Dict{String, Any}}, Base.Dict{String, Any}, Pkg.BinaryPlatforms.FreeBSD)
(::getfield(Pkg.BinaryPlatforms, Symbol("#32#34")){Pkg.BinaryPlatforms.Linux})(Pkg.BinaryPlatforms.FreeBSD)
(::getfield(Pkg.BinaryPlatforms, Symbol("#32#34")){Pkg.BinaryPlatforms.Linux})(Pkg.BinaryPlatforms.Windows)
(::getfield(Pkg.BinaryPlatforms, Symbol("#32#34")){Pkg.BinaryPlatforms.Linux})(Pkg.BinaryPlatforms.MacOS)
dlopen(String)
__init__()
__init__()
__init__()
__init__()
foreach(getfield(Libgcrypt_jll, Symbol("#7#9")), Tuple{Array{String, 1}})
foreach(getfield(Libgcrypt_jll, Symbol("#8#10")), Tuple{Array{String, 1}})
__init__()
__init__()
__init__()
foreach(getfield(XML2_jll, Symbol("#13#15")), Tuple{Array{String, 1}, Array{String, 1}})
foreach(getfield(XML2_jll, Symbol("#14#16")), Tuple{Array{String, 1}, Array{String, 1}})
__init__()
foreach(getfield(XSLT_jll, Symbol("#7#9")), Tuple{Array{String, 1}, Array{String, 1}})
foreach(getfield(XSLT_jll, Symbol("#8#10")), Tuple{Array{String, 1}, Array{String, 1}})
__init__()
__init__()
foreach(getfield(Xorg_libxcb_jll, Symbol("#7#9")), Tuple{Array{String, 1}, Array{String, 1}, Array{String, 1}, Array{String, 1}})
foreach(getfield(Xorg_libxcb_jll, Symbol("#8#10")), Tuple{Array{String, 1}, Array{String, 1}, Array{String, 1}, Array{String, 1}})
__init__()
foreach(getfield(Xorg_libX11_jll, Symbol("#7#9")), Tuple{Array{String, 1}, Array{String, 1}})
foreach(getfield(Xorg_libX11_jll, Symbol("#8#10")), Tuple{Array{String, 1}, Array{String, 1}})
__init__()
foreach(getfield(Xorg_libXrender_jll, Symbol("#7#9")), Tuple{Array{String, 1}})
foreach(getfield(Xorg_libXrender_jll, Symbol("#8#10")), Tuple{Array{String, 1}})
__init__()
foreach(getfield(Xorg_libXfixes_jll, Symbol("#7#9")), Tuple{Array{String, 1}})
foreach(getfield(Xorg_libXfixes_jll, Symbol("#8#10")), Tuple{Array{String, 1}})
__init__()
foreach(getfield(Xorg_libXdamage_jll, Symbol("#7#9")), Tuple{Array{String, 1}})
foreach(getfield(Xorg_libXdamage_jll, Symbol("#8#10")), Tuple{Array{String, 1}})
__init__()
register_error_hint(Function, Type{T} where T)
__init__()
__init__()
__init__()
__init__()
__init__()
__init__()
foreach(getfield(Gettext_jll, Symbol("#7#9")), Tuple{Array{String, 1}, Array{String, 1}})
foreach(getfield(Gettext_jll, Symbol("#8#10")), Tuple{Array{String, 1}, Array{String, 1}})
__init__()
__init__()
foreach(getfield(Glib_jll, Symbol("#7#9")), Tuple{Array{String, 1}, Array{String, 1}, Array{String, 1}, Array{String, 1}, Array{String, 1}, Array{String, 1}})
foreach(getfield(Glib_jll, Symbol("#8#10")), Tuple{Array{String, 1}, Array{String, 1}, Array{String, 1}, Array{String, 1}, Array{String, 1}, Array{String, 1}})
__init__()
__init__()
__init__()
foreach(getfield(Libtiff_jll, Symbol("#7#9")), Tuple{Array{String, 1}, Array{String, 1}, Array{String, 1}})
foreach(getfield(Libtiff_jll, Symbol("#8#10")), Tuple{Array{String, 1}, Array{String, 1}, Array{String, 1}})
__init__()
foreach(getfield(libpng_jll, Symbol("#7#9")), Tuple{Array{String, 1}})
foreach(getfield(libpng_jll, Symbol("#8#10")), Tuple{Array{String, 1}})
__init__()
foreach(getfield(gdk_pixbuf_jll, Symbol("#10#12")), Tuple{Array{String, 1}, Array{String, 1}, Array{String, 1}, Array{String, 1}, Array{String, 1}})
foreach(getfield(gdk_pixbuf_jll, Symbol("#11#13")), Tuple{Array{String, 1}, Array{String, 1}, Array{String, 1}, Array{String, 1}, Array{String, 1}})
__init__()
foreach(getfield(Xorg_libXext_jll, Symbol("#7#9")), Tuple{Array{String, 1}})
foreach(getfield(Xorg_libXext_jll, Symbol("#8#10")), Tuple{Array{String, 1}})
__init__()
__init__()
__init__()
__init__()
foreach(getfield(FreeType2_jll, Symbol("#7#9")), Tuple{Array{String, 1}, Array{String, 1}})
foreach(getfield(FreeType2_jll, Symbol("#8#10")), Tuple{Array{String, 1}, Array{String, 1}})
__init__()
__init__()
foreach(getfield(Fontconfig_jll, Symbol("#34#36")), Tuple{Array{String, 1}, Array{String, 1}, Array{String, 1}, Array{String, 1}, Array{String, 1}})
foreach(getfield(Fontconfig_jll, Symbol("#35#37")), Tuple{Array{String, 1}, Array{String, 1}, Array{String, 1}, Array{String, 1}, Array{String, 1}})
__init__()
__init__()
foreach(getfield(Cairo_jll, Symbol("#7#9")), Tuple{Array{String, 1}, Array{String, 1}, Array{String, 1}, Array{String, 1}, Array{String, 1}, Array{String, 1}, Array{String, 1}, Array{String, 1}, Array{String, 1}, Array{String, 1}})
foreach(getfield(Cairo_jll, Symbol("#8#10")), Tuple{Array{String, 1}, Array{String, 1}, Array{String, 1}, Array{String, 1}, Array{String, 1}, Array{String, 1}, Array{String, 1}, Array{String, 1}, Array{String, 1}, Array{String, 1}})
__init__()
foreach(getfield(HarfBuzz_jll, Symbol("#7#9")), Tuple{Array{String, 1}, Array{String, 1}, Array{String, 1}, Array{String, 1}, Array{String, 1}, Array{String, 1}, Array{String, 1}})
foreach(getfield(HarfBuzz_jll, Symbol("#8#10")), Tuple{Array{String, 1}, Array{String, 1}, Array{String, 1}, Array{String, 1}, Array{String, 1}, Array{String, 1}, Array{String, 1}})
__init__()
__init__()
foreach(getfield(Xorg_libxkbfile_jll, Symbol("#7#9")), Tuple{Array{String, 1}})
foreach(getfield(Xorg_libxkbfile_jll, Symbol("#8#10")), Tuple{Array{String, 1}})
__init__()
foreach(getfield(Xorg_xkbcomp_jll, Symbol("#10#12")), Tuple{Array{String, 1}})
foreach(getfield(Xorg_xkbcomp_jll, Symbol("#11#13")), Tuple{Array{String, 1}})
__init__()
foreach(getfield(Xorg_xkeyboard_config_jll, Symbol("#7#9")), Tuple{Array{String, 1}})
foreach(getfield(Xorg_xkeyboard_config_jll, Symbol("#8#10")), Tuple{Array{String, 1}})
__init__()
foreach(getfield(Wayland_jll, Symbol("#10#12")), Tuple{Array{String, 1}, Array{String, 1}, Array{String, 1}})
foreach(getfield(Wayland_jll, Symbol("#11#13")), Tuple{Array{String, 1}, Array{String, 1}, Array{String, 1}})
__init__()
__init__()
__init__()
foreach(getfield(Xorg_libXi_jll, Symbol("#7#9")), Tuple{Array{String, 1}, Array{String, 1}})
foreach(getfield(Xorg_libXi_jll, Symbol("#8#10")), Tuple{Array{String, 1}, Array{String, 1}})
__init__()
foreach(getfield(Xorg_libXtst_jll, Symbol("#7#9")), Tuple{Array{String, 1}, Array{String, 1}, Array{String, 1}})
foreach(getfield(Xorg_libXtst_jll, Symbol("#8#10")), Tuple{Array{String, 1}, Array{String, 1}, Array{String, 1}})
__init__()
foreach(getfield(at_spi2_core_jll, Symbol("#7#9")), Tuple{Array{String, 1}, Array{String, 1}, Array{String, 1}})
foreach(getfield(at_spi2_core_jll, Symbol("#8#10")), Tuple{Array{String, 1}, Array{String, 1}, Array{String, 1}})
__init__()
foreach(getfield(at_spi2_atk_jll, Symbol("#7#9")), Tuple{Array{String, 1}, Array{String, 1}, Array{String, 1}, Array{String, 1}})
foreach(getfield(at_spi2_atk_jll, Symbol("#8#10")), Tuple{Array{String, 1}, Array{String, 1}, Array{String, 1}, Array{String, 1}})
__init__()
foreach(getfield(Libglvnd_jll, Symbol("#7#9")), Tuple{Array{String, 1}, Array{String, 1}})
foreach(getfield(Libglvnd_jll, Symbol("#8#10")), Tuple{Array{String, 1}, Array{String, 1}})
__init__()
foreach(getfield(Xorg_libXrandr_jll, Symbol("#7#9")), Tuple{Array{String, 1}, Array{String, 1}})
foreach(getfield(Xorg_libXrandr_jll, Symbol("#8#10")), Tuple{Array{String, 1}, Array{String, 1}})
__init__()
foreach(getfield(Xorg_libXcursor_jll, Symbol("#7#9")), Tuple{Array{String, 1}, Array{String, 1}})
foreach(getfield(Xorg_libXcursor_jll, Symbol("#8#10")), Tuple{Array{String, 1}, Array{String, 1}})
__init__()
foreach(getfield(Xorg_libXcomposite_jll, Symbol("#7#9")), Tuple{Array{String, 1}})
foreach(getfield(Xorg_libXcomposite_jll, Symbol("#8#10")), Tuple{Array{String, 1}})
__init__()
__init__()
foreach(getfield(Pango_jll, Symbol("#7#9")), Tuple{Array{String, 1}, Array{String, 1}, Array{String, 1}, Array{String, 1}, Array{String, 1}, Array{String, 1}})
foreach(getfield(Pango_jll, Symbol("#8#10")), Tuple{Array{String, 1}, Array{String, 1}, Array{String, 1}, Array{String, 1}, Array{String, 1}, Array{String, 1}})
__init__()
foreach(getfield(Xorg_libXinerama_jll, Symbol("#7#9")), Tuple{Array{String, 1}})
foreach(getfield(Xorg_libXinerama_jll, Symbol("#8#10")), Tuple{Array{String, 1}})
__init__()
__init__()
__init__()
foreach(getfield(Libepoxy_jll, Symbol("#7#9")), Tuple{Array{String, 1}, Array{String, 1}})
foreach(getfield(Libepoxy_jll, Symbol("#8#10")), Tuple{Array{String, 1}, Array{String, 1}})
__init__()
foreach(getfield(GTK3_jll, Symbol("#7#9")), Tuple{Array{String, 1}, Array{String, 1}, Array{String, 1}, Array{String, 1}, Array{String, 1}, Array{String, 1}, Array{String, 1}, Array{String, 1}, Array{String, 1}, Array{String, 1}, Array{String, 1}, Array{String, 1}, Array{String, 1}, Array{String, 1}, Array{String, 1}, Array{String, 1}, Array{String, 1}, Array{String, 1}, Array{String, 1}, Array{String, 1}, Array{String, 1}, Array{String, 1}, Array{String, 1}, Array{String, 1}})
foreach(getfield(GTK3_jll, Symbol("#8#10")), Tuple{Array{String, 1}, Array{String, 1}, Array{String, 1}, Array{String, 1}, Array{String, 1}, Array{String, 1}, Array{String, 1}, Array{String, 1}, Array{String, 1}, Array{String, 1}, Array{String, 1}, Array{String, 1}, Array{String, 1}, Array{String, 1}, Array{String, 1}, Array{String, 1}, Array{String, 1}, Array{String, 1}, Array{String, 1}, Array{String, 1}, Array{String, 1}, Array{String, 1}, Array{String, 1}, Array{String, 1}})
__init__()
__init__()
GClosureMarshal(Ptr{Nothing}, Ptr{Gtk.GLib.GValue}, UInt32, Ptr{Gtk.GLib.GValue}, Ptr{Nothing}, Ptr{Nothing})
uv_prepare(Ptr{Nothing}, Ptr{Int32})
uv_check(Ptr{Nothing})
uv_dispatch(Ptr{Nothing}, Ptr{Nothing}, Int64)
g_yield(UInt64)
__init__()
filter(getfield(Gtk, Symbol("#299#305")), Array{String, 1})
artifact_hash(String, String)
#artifact_hash#23(Pkg.BinaryPlatforms.Platform, Nothing, typeof(Pkg.Artifacts.artifact_hash), String, String)
artifact_meta##kw(NamedTuple{(:platform,), Tuple{Pkg.BinaryPlatforms.Linux}}, typeof(Pkg.Artifacts.artifact_meta), String, String)
Gtk-Message: 12:43:18.784: Failed to load module "canberra-gtk-module"
Gtk-Message: 12:43:18.784: Failed to load module "canberra-gtk-module"
gtk_main()
g_sigatom(Any)
#237()
g_siginterruptible(typeof(Base.yield), Function)

Looking at the pacing with which these appear, it's pretty uniform throughout the list; it's not like it's 95% of the time on the last 3 items or anything.

I still can't be sure without further analysis, but it seems plausible that compiling the Julia code that loads all the libraries is taking a bunch of the time, because there's not much there other than __init__() and foreach signatures that are clearly due to the DLL packages. OTOH, I could be failing to intercept some important costs. Moreover, the times on Julia 1.5 are similar to those that @giordano posted for his "Mega" approach which, IIUC, shouldn't have much of this overhead. Any updates on that, @giordano?

timholy · 2020-05-07T19:06:44Z

Ooh, I just tried this!

julia> @time using Gtk
Gtk-Message: 13:59:49.072: Failed to load module "canberra-gtk-module"
Gtk-Message: 13:59:49.072: Failed to load module "canberra-gtk-module"
  1.478291 seconds (1.49 M allocations: 90.705 MiB, 4.80% gc time)

Yay!

You need this Project.toml file:

uuid = "bcac8185-d704-4266-a2ba-bdabfb5c6013"

[deps]
Cairo_jll = "83423d85-b0ee-5818-9007-b63ccbeb887a"
GTK3_jll = "77ec8976-b24b-556a-a1bf-49a033a670a6"
Glib_jll = "7746bdde-850d-59dc-9ae8-88ece973131d"
PackageCompiler = "9b87118b-4619-50d2-8e1e-99f35a4d4d9d"
Xorg_xkeyboard_config_jll = "33bec58e-1273-512f-9401-5d533626f822"
adwaita_icon_theme_jll = "b437f822-2cd6-5e08-a15c-8bac984d38ee"
gdk_pixbuf_jll = "da03df04-f53b-5353-a52f-6a8b0620ced0"
hicolor_icon_theme_jll = "059c91fe-1bad-52ad-bddd-f7b78713c282"

[compat]
Cairo_jll = "1.16.0"
GTK3_jll = "3.24.11"
Glib_jll = "2.59.0"
Xorg_xkeyboard_config_jll = "2.27.0"
adwaita_icon_theme_jll = "3.33.92"
gdk_pixbuf_jll = "2.38.2"
hicolor_icon_theme_jll = "0.17.0"
julia = "1.3"

and you need to activate and instantiate it.

Then you just include this script:

using PackageCompiler
create_sysimage([:Cairo_jll, :GTK3_jll, :Glib_jll, :Xorg_xkeyboard_config_jll, :adwaita_icon_theme_jll, :gdk_pixbuf_jll, :hicolor_icon_theme_jll]; replace_default=true)

You only need to do these steps once, from that point forward using Gtk should be a lot faster. And you should be able to still develop the Julia packages (untested).

I'm going to run this way for a while and see if I like it.

davidanthoff · 2020-05-07T19:19:33Z

@timholy are you a VS Code user at this point? We have support for compiling custom sysimages in the extension. They get stored parallel to the environment that you compiled into a sysimage (i.e. no replacing of the default sysimage), and then whenver you start a Julia REPL inside VS Code it will automatically use that sysimage if it is still up-to-date with the Manifest.toml.

timholy · 2020-05-08T00:36:10Z

I alternate among vscode, Juno, and emacs. I'll have to give that a try. Docs seem a bit thin 😄, any tips on how I activate it?

tknopp · 2020-05-08T06:44:18Z

Thanks for this Tim. So you bake just the JLL packages into the system image, right? Thats clever. I once tried PackageCompiler with Gtk but never got it working. In my case I would actually be more interested in the time to first "plot", i.e. the first Winston drawing requires quite some time.

timholy · 2020-05-08T10:32:46Z

Yep. I didn't want to bake in the regular Julia packages because once you do so, you can't update or dev them anymore (or at least, I don't know how you do that). But the libraries seem pretty safe. You can pick how much you want to bake in, though, including all the way up to and including Winston, as long as you don't mind rebuilding Julia whenever you want to make an update.

tknopp · 2020-05-08T10:44:16Z

will have a look and certainly try this out for myself. It seems that this area is slowly converging into something that solves the latency issues but is usable without being a Julia dev for the last 8 years. Things like JuliaLang/julia#35794 make me hope that in Julia 1.5 or 1.6 the user interface for this kind of stuff is streamlined (similar to Revise, i.e. "just work")

davidanthoff · 2020-05-08T10:56:29Z

@timholy Fair enough :) But, you triggered me to write that section, take a look again: https://www.julia-vscode.org/docs/dev/userguide/compilesysimage/.

Not sure it generally helps here, because I guess the clue here is that only a select number of packages get compiled into the sysimage, right? What we have in VS Code is more blunt: it just includes everything from your env.

KristofferC · 2020-06-25T09:04:58Z

1.4:

julia> @time using Gtk
  5.719041 seconds (9.25 M allocations: 495.444 MiB, 2.32% gc time)

master:

julia> @time using Gtk
  3.750200 seconds (6.09 M allocations: 360.235 MiB, 3.10% gc time)

tknopp · 2020-06-25T11:43:04Z

This goes into the right direction! just a factor of 4 slowdown compared to Julia 1.2. ;-)
But actually TTFP is a more important metric hear, not just package loading time.

PallHaraldsson · 2020-10-16T23:09:33Z

Faster than ever, in any Julia version?

~~Not quite the original time, but almost now (and I read more improvements in the pipeline, literally just waiting for some process to run)~~: JuliaPackaging/Yggdrasil#1881 (comment)

Maybe close this issue, declare success?

Not my own timing from the other thread:

% julia-master --project=. --startup-file=no -e '@time using Gtk'
  0.774766 seconds (1.09 M allocations: 76.501 MiB, 1.70% gc time, 21.71% compilation time)

I have 4 days old master, maybe explaining and/or his faster machine:

I get 1.46 sec on defaults, OhMyREPL and/or Revise used to slow using other packages, and with those in my startup, no longer (or if a tiny bit), but I to get Warning: error while importing Revise. And possible:

$ ./julia -O0 --compile=min --startup-file=no -q
julia> @time @time usinjulia> @time using Gtk
Gtk-Message: 23:15:23.243: Failed to load module "canberra-gtk-module"
Gtk-Message: 23:15:23.244: Failed to load module "canberra-gtk-module"
  1.157111 seconds (1.37 M allocations: 92.693 MiB, 5.45% compilation time)

FYI, a low bar to compare to (on defaults):
julia> @time using TestGtkMegaJLL
  0.549481 seconds (1.47 M allocations: 125.909 MiB, 39.89% compilation time)

giordano · 2020-10-17T11:42:43Z

With the latest packages in the General registry:

% for jl in julia-13 julia-14 julia julia-master; do ${jl} --project=. --startup-file=no -e '@time using Gtk'; done
  7.285339 seconds (7.15 M allocations: 391.143 MiB, 1.60% gc time)
  7.955436 seconds (7.73 M allocations: 426.365 MiB, 2.36% gc time)
  5.091835 seconds (5.69 M allocations: 345.626 MiB, 1.12% gc time)
  0.764136 seconds (1.11 M allocations: 79.067 MiB, 22.51% compilation time)
% for jl in julia-13 julia-14 julia julia-master; do ${jl} --project=. --startup-file=no -e '@time using GTK3_jll'; done
  5.715055 seconds (5.84 M allocations: 319.246 MiB, 0.87% gc time)
  5.625304 seconds (5.59 M allocations: 309.978 MiB, 0.87% gc time)
  3.318841 seconds (3.50 M allocations: 221.176 MiB, 0.82% gc time)
  0.206161 seconds (282.85 k allocations: 21.616 MiB, 28.20% compilation time)

There are about 3-4 more JLL packages in the stack of Gtk that can be sped up by switching to the new wrappers and shave off a few milliseconds more, but we need to fix some issues in Yggdrasil first.

Note that the new wrappers are faster than the old ones across all versions of Julia. However the largest speedup can be appreciated in Julia v1.6. Using a version of the registry of 3-4 weeks ago:

% for jl in julia-13 julia-14 julia julia-master; do ${jl} --project=. --startup-file=no -e '@time using GTK3_jll'; done
  6.453987 seconds (6.02 M allocations: 326.237 MiB, 0.51% gc time)
  6.731943 seconds (5.91 M allocations: 322.945 MiB, 1.60% gc time)
  4.050202 seconds (3.75 M allocations: 233.177 MiB, 0.84% gc time)
  2.342763 seconds (2.20 M allocations: 150.511 MiB, 0.84% gc time, 47.12% compilation time)

timholy · 2020-10-17T18:35:45Z

Even though I still look forward to those few extra milliseconds (I'm already making plans for how to spend them!), I think we can close this now. Thanks @giordano, @staticfloat, and @KristofferC for pulling the rabbit out of a hat---truly remarkable work!

giordano · 2020-10-24T21:38:22Z

I believe now all JLL packages related to Gtk have been updated with the new wrappers, as promised this is a bit faster in Julia v1.6:

% for jl in julia-13 julia-14 julia julia-master; do ${jl} --project=. --startup-file=no -e '@time using Gtk'; done
  7.556586 seconds (7.12 M allocations: 388.389 MiB, 0.80% gc time)
  8.012082 seconds (7.66 M allocations: 422.410 MiB, 1.76% gc time)
  5.240457 seconds (5.72 M allocations: 347.154 MiB, 1.62% gc time)
  0.730751 seconds (1.07 M allocations: 75.361 MiB, 1.72% gc time, 23.76% compilation time)
% for jl in julia-13 julia-14 julia julia-master; do ${jl} --project=. --startup-file=no -e '@time using GTK3_jll'; done
  6.054858 seconds (5.81 M allocations: 316.974 MiB, 0.89% gc time)
  6.056752 seconds (5.53 M allocations: 306.182 MiB, 0.58% gc time)
  3.480045 seconds (3.64 M allocations: 229.398 MiB, 0.88% gc time)
  0.138238 seconds (193.44 k allocations: 15.118 MiB, 5.70% compilation time)

For convenience, I'm reporting here the timings of using GTK3_jll with the old wrappers given above

% for jl in julia-13 julia-14 julia julia-master; do ${jl} --project=. --startup-file=no -e '@time using GTK3_jll'; done
  6.453987 seconds (6.02 M allocations: 326.237 MiB, 0.51% gc time)
  6.731943 seconds (5.91 M allocations: 322.945 MiB, 1.60% gc time)
  4.050202 seconds (3.75 M allocations: 233.177 MiB, 0.84% gc time)
  2.342763 seconds (2.20 M allocations: 150.511 MiB, 0.84% gc time, 47.12% compilation time)

timholy · 2020-10-25T08:05:02Z

Unbelievable! For the record,

julia> @time using Gtk
Gtk-Message: 03:00:34.924: Failed to load module "canberra-gtk-module"
Gtk-Message: 03:00:34.924: Failed to load module "canberra-gtk-module"
  0.589590 seconds (1.07 M allocations: 74.742 MiB, 21.68% compilation time)

which is considerably faster than the time I posted in the OP for Julia 1.2, prior to the artifact transition.

Interestingly, I get these fast timings in a fresh package depot but longer times in my regular one, despite pkg> st showing the same version of GTK3_jll in both. Anything I need to do to get the goodness in my main environment?

giordano · 2020-10-25T10:19:17Z

Interestingly, I get these fast timings in a fresh package depot but longer times in my regular one, despite pkg> st showing the same version of GTK3_jll in both. Anything I need to do to get the goodness in my main environment?

I don't know if it makes any sense, but I've noticed that the number of files in the .julia/compiled/ directory slightly affects loading time (maybe julia needs some time to find the right files to load? 🤷). Try deleting .julia/compiled/v1.6/ in your main depot

KristofferC · 2020-10-25T11:14:19Z

It's possible that searching for the correct ji file could take some time. Perhaps we can be smarter in what order we search them to increase the likelihood of a hit early...?

timholy · 2020-10-25T11:15:56Z

Ah, nvm, it was a Revise thing. Usually I don't see much measurable overhead for Revise (v3, that is), but loading GTK3_jll loads a lot of other packages:

julia> Revise.pkgdatas
Dict{Base.PkgId, Revise.PkgData} with 62 entries:
  libpng_jll [b53b4c65-9356-5827-b1ea-8c7a1a84506f]                => PkgData("/home/tim/.julia/packages/libpng_jll/LVH6r", 0/2 parsed files, 0 expressions, 0 signatures)
  PCRE_jll [2f80f16e-611a-54ab-bc61-aa92de5b98fc]                  => PkgData("/home/tim/.julia/packages/PCRE_jll/vuLCN", 0/2 parsed files, 0 expressions, 0 signatures)
   [top-level]                                                     => PkgData("", 0/0 parsed files, 0 expressions, 0 signatures)
  Xorg_libxcb_jll [c7cfdc94-dc32-55de-ac96-5a1b8d977c5b]           => PkgData("/home/tim/.julia/packages/Xorg_libxcb_jll/nMYKH", 0/2 parsed files, 0 expressions, 0 signatures)
  Libgcrypt_jll [d4300ac3-e22c-5743-9152-c294e39db1e4]             => PkgData("/home/tim/.julia/packages/Libgcrypt_jll/j9Ba6", 0/2 parsed files, 0 expressions, 0 signatures)
  Libepoxy_jll [42c93a91-0102-5b3f-8f9d-e41de60ac950]              => PkgData("/home/tim/.julia/packages/Libepoxy_jll/DVgDS", 0/2 parsed files, 0 expressions, 0 signatures)
  Zstd_jll [3161d3a3-bdf6-5164-811a-617609db77b4]                  => PkgData("/home/tim/.julia/packages/Zstd_jll/sixZt", 0/2 parsed files, 0 expressions, 0 signatures)
  Xorg_libXinerama_jll [d1454406-59df-5ea1-beac-c340f2130bc3]      => PkgData("/home/tim/.julia/packages/Xorg_libXinerama_jll/DWlLt", 0/2 parsed files, 0 expressions, 0 signatures)
  Fontconfig_jll [a3f928ae-7b40-5064-980b-68af3947d34b]            => PkgData("/home/tim/.julia/packages/Fontconfig_jll/FLYqL", 0/2 parsed files, 0 expressions, 0 signatures)
  at_spi2_core_jll [0fc3237b-ac94-5853-b45c-d43d59a06200]          => PkgData("/home/tim/.julia/packages/at_spi2_core_jll/53Vwo", 0/2 parsed files, 0 expressions, 0 signatures)
  Xorg_libXtst_jll [b6f176f1-7aea-5357-ad67-1d3e565ea1c6]          => PkgData("/home/tim/.julia/packages/Xorg_libXtst_jll/0Nk3z", 0/2 parsed files, 0 expressions, 0 signatures)
  Xorg_libXdamage_jll [0aeada51-83db-5f97-b67e-184615cfc6f6]       => PkgData("/home/tim/.julia/packages/Xorg_libXdamage_jll/lP9oq", 0/2 parsed files, 0 expressions, 0 signatures)
  FriBidi_jll [559328eb-81f9-559d-9380-de523a88c83c]               => PkgData("/home/tim/.julia/packages/FriBidi_jll/sTQCm", 0/2 parsed files, 0 expressions, 0 signatures)
  FreeType2_jll [d7e528f0-a631-5988-bf34-fe36492bcfd7]             => PkgData("/home/tim/.julia/packages/FreeType2_jll/K7fyn", 0/2 parsed files, 0 expressions, 0 signatures)
  Pixman_jll [30392449-352a-5448-841d-b1acce4e97dc]                => PkgData("/home/tim/.julia/packages/Pixman_jll/jaedt", 0/2 parsed files, 0 expressions, 0 signatures)
  iso_codes_jll [bf975903-5238-5d20-8243-bc370bc1e7e5]             => PkgData("/home/tim/.julia/packages/iso_codes_jll/RQRgy", 0/2 parsed files, 0 expressions, 0 signatures)
  Xorg_libXi_jll [a51aa0fd-4e3c-5386-b890-e753decda492]            => PkgData("/home/tim/.julia/packages/Xorg_libXi_jll/b3siQ", 0/2 parsed files, 0 expressions, 0 signatures)
  Libmount_jll [4b2f31a3-9ecc-558c-b454-b3730dcb73e9]              => PkgData("/home/tim/.julia/packages/Libmount_jll/tMiNq", 0/2 parsed files, 0 expressions, 0 signatures)
  Xorg_libX11_jll [4f6342f7-b3d2-589e-9d20-edeb45f2b2bc]           => PkgData("/home/tim/.julia/packages/Xorg_libX11_jll/ICRWq", 0/2 parsed files, 0 expressions, 0 signatures)
  Xorg_libpthread_stubs_jll [14d82f49-176c-5ed1-bb49-ad3f5cbd8c74] => PkgData("/home/tim/.julia/packages/Xorg_libpthread_stubs_jll/zqOOX", 0/2 parsed files, 0 expressions, 0 signatures)
  Dbus_jll [ee1fde0b-3d02-5ea6-8484-8dfef6360eab]                  => PkgData("/home/tim/.julia/packages/Dbus_jll/chcYw", 0/2 parsed files, 0 expressions, 0 signatures)
  Libffi_jll [e9f186c6-92d2-5b65-8a66-fee21dc1b490]                => PkgData("/home/tim/.julia/packages/Libffi_jll/qmD6A", 0/2 parsed files, 0 expressions, 0 signatures)
  Glib_jll [7746bdde-850d-59dc-9ae8-88ece973131d]                  => PkgData("/home/tim/.julia/packages/Glib_jll/nZezQ", 0/2 parsed files, 0 expressions, 0 signatures)
  Xorg_libXrender_jll [ea2f1a96-1ddc-540d-b46f-429655e07cfa]       => PkgData("/home/tim/.julia/packages/Xorg_libXrender_jll/kA0MM", 0/2 parsed files, 0 expressions, 0 signatures)
  Xorg_libXcursor_jll [935fb764-8cf2-53bf-bb30-45bb1f8bf724]       => PkgData("/home/tim/.julia/packages/Xorg_libXcursor_jll/fjJH1", 0/2 parsed files, 0 expressions, 0 signatures)
  Xorg_libxkbfile_jll [cc61e674-0454-545c-8b26-ed2c68acab7a]       => PkgData("/home/tim/.julia/packages/Xorg_libxkbfile_jll/9Z72B", 0/2 parsed files, 0 expressions, 0 signatures)
  JLLWrappers [692b3bcd-3c85-4b1f-b108-f13ce0eb3210]               => PkgData("/home/tim/.julia/packages/JLLWrappers/KuIwt", 0/7 parsed files, 0 expressions, 0 signatures)
  Graphite2_jll [3b182d85-2403-5c21-9c21-1e1f0cc25472]             => PkgData("/home/tim/.julia/packages/Graphite2_jll/ELCSt", 0/2 parsed files, 0 expressions, 0 signatures)
  Libiconv_jll [94ce4f54-9a6c-5748-9c1c-f9c7231a4531]              => PkgData("/home/tim/.julia/packages/Libiconv_jll/bLsPg", 0/2 parsed files, 0 expressions, 0 signatures)
  XML2_jll [02c8fc9c-b97f-50b9-bbe4-9be30ff0a78a]                  => PkgData("/home/tim/.julia/packages/XML2_jll/KicVA", 0/2 parsed files, 0 expressions, 0 signatures)
  gdk_pixbuf_jll [da03df04-f53b-5353-a52f-6a8b0620ced0]            => PkgData("/home/tim/.julia/packages/gdk_pixbuf_jll/KNpyb", 0/2 parsed files, 0 expressions, 0 signatures)
  Xorg_xkeyboard_config_jll [33bec58e-1273-512f-9401-5d533626f822] => PkgData("/home/tim/.julia/packages/Xorg_xkeyboard_config_jll/1s8HN", 0/2 parsed files, 0 expressions, 0 signatures)
  Xorg_libXau_jll [0c0b7dd1-d40b-584c-a123-a41640f87eec]           => PkgData("/home/tim/.julia/packages/Xorg_libXau_jll/z2hT9", 0/2 parsed files, 0 expressions, 0 signatures)
  Expat_jll [2e619515-83b5-522b-bb60-26c02a35a201]                 => PkgData("/home/tim/.julia/packages/Expat_jll/InUJD", 0/2 parsed files, 0 expressions, 0 signatures)
  Xorg_libXfixes_jll [d091e8ba-531a-589c-9de9-94069b037ed8]        => PkgData("/home/tim/.julia/packages/Xorg_libXfixes_jll/1LNSm", 0/2 parsed files, 0 expressions, 0 signatures)
  Xorg_libXext_jll [1082639a-0dae-5f34-9b06-72781eeb8cb3]          => PkgData("/home/tim/.julia/packages/Xorg_libXext_jll/2vwNw", 0/2 parsed files, 0 expressions, 0 signatures)
  Xorg_libXrandr_jll [ec84b674-ba8e-5d96-8ba1-2a689ba10484]        => PkgData("/home/tim/.julia/packages/Xorg_libXrandr_jll/J277R", 0/2 parsed files, 0 expressions, 0 signatures)
  Zlib_jll [83775a58-1f1d-513f-b197-d71354ab007a]                  => PkgData("/home/tim/.julia/packages/Zlib_jll/BGVLi", 0/2 parsed files, 0 expressions, 0 signatures)
  ATK_jll [7b86fcea-f67b-53e1-809c-8f1719c154e8]                   => PkgData("/home/tim/.julia/packages/ATK_jll/2W2rG", 0/2 parsed files, 0 expressions, 0 signatures)
  Libtiff_jll [89763e89-9b03-5906-acba-b20f662cd828]               => PkgData("/home/tim/.julia/packages/Libtiff_jll/XbRB0", 0/2 parsed files, 0 expressions, 0 signatures)
  LZO_jll [dd4b983a-f0e5-5f8d-a1b7-129d4a5fb1ac]                   => PkgData("/home/tim/.julia/packages/LZO_jll/JPctN", 0/2 parsed files, 0 expressions, 0 signatures)
  Wayland_protocols_jll [2381bf8a-dfd0-557d-9999-79630e7b1b91]     => PkgData("/home/tim/.julia/packages/Wayland_protocols_jll/LbAxv", 0/2 parsed files, 0 expressions, 0 signatures)
  Libglvnd_jll [7e76a0d4-f3c7-5321-8279-8d96eeed0f29]              => PkgData("/home/tim/.julia/packages/Libglvnd_jll/pJrjy", 0/2 parsed files, 0 expressions, 0 signatures)
  GTK3_jll [77ec8976-b24b-556a-a1bf-49a033a670a6]                  => PkgData("/home/tim/.julia/packages/GTK3_jll/8K2nw", 0/2 parsed files, 0 expressions, 0 signatures)
  Xorg_libXcomposite_jll [3c9796d7-64a0-5134-86ad-79f8eb684845]    => PkgData("/home/tim/.julia/packages/Xorg_libXcomposite_jll/LuFsN", 0/2 parsed files, 0 expressions, 0 signatures)
  at_spi2_atk_jll [de012916-1e3f-58c2-8f29-df3ef51d412d]           => PkgData("/home/tim/.julia/packages/at_spi2_atk_jll/89oOP", 0/2 parsed files, 0 expressions, 0 signatures)
  Xorg_xtrans_jll [c5fb5394-a638-5e4d-96e5-b29de1b5cf10]           => PkgData("/home/tim/.julia/packages/Xorg_xtrans_jll/E34UR", 0/2 parsed files, 0 expressions, 0 signatures)
  xkbcommon_jll [d8fb68d0-12a3-5cfd-a85a-d49703b185fd]             => PkgData("/home/tim/.julia/packages/xkbcommon_jll/Bc3mg", 0/2 parsed files, 0 expressions, 0 signatures)
  ⋮                                                                => ⋮

timholy · 2020-10-25T11:25:22Z

And besides, you're getting so fast at JLL loading you're making me look bad 😆 (Bring it on, I say.)

Revise's overhead comes down to about 60ms of inference time, a total of about 240ms additional compilation time (almost entirely OrderedDict methods, as usual), and about 300ms of runtime under require(uuidkey::Base.PkgId). I'm a bit confused about why the latter is longer when running under Revise than without it.

Without Revise:

julia> using Profile

julia> @profile using GTK3_jll

julia> Profile.print(noisefloor=2)
Overhead ╎ [+additional indent] Count File:Line; Function
=========================================================
  ╎190 @Base/client.jl:485; _start()
  ╎ 190 @Base/client.jl:302; exec_options(opts::Base.JLOptions)
  ╎  190 @Base/client.jl:372; run_main_repl(interactive::Bool, quiet::Bool, banner::Bool, history_file::Bool, color_set::Bool)
  ╎   190 @Base/essentials.jl:706; invokelatest
  ╎    190 @Base/essentials.jl:707; #invokelatest#2
  ╎     190 @Base/client.jl:387; (::Base.var"#862#864"{Bool, Bool, Bool})(REPL::Module)
  ╎    ╎ 190 @REPL/src/REPL.jl:305; run_repl(repl::REPL.AbstractREPL, consumer::Any)
  ╎    ╎  190 @REPL/src/REPL.jl:317; run_repl(repl::REPL.AbstractREPL, consumer::Any; backend_on_current_task::Bool)
  ╎    ╎   190 @REPL/src/REPL.jl:185; start_repl_backend(backend::REPL.REPLBackend, consumer::Any)
  ╎    ╎    190 @REPL/src/REPL.jl:200; repl_backend_loop(backend::REPL.REPLBackend)
  ╎    ╎     190 @REPL/src/REPL.jl:139; eval_user_input(ast::Any, backend::REPL.REPLBackend)
 1╎    ╎    ╎ 190 @Base/boot.jl:360; eval(m::Module, e::Any)
  ╎    ╎    ╎  189 @Base/loading.jl:913; require(into::Module, mod::Symbol)
  ╎    ╎    ╎   189 @Base/loading.jl:926; require(uuidkey::Base.PkgId)
  ╎    ╎    ╎    182 @Base/loading.jl:1010; _require(pkg::Base.PkgId)
  ╎    ╎    ╎     159 @Base/loading.jl:761; _require_search_from_serialized(pkg::Base.PkgId, sourcepath::String)
  ╎    ╎    ╎    ╎ 159 @Base/loading.jl:701; _tryrequire_from_serialized(modkey::Base.PkgId, build_id::UInt64, modpath::String)
  ╎    ╎    ╎    ╎  53  @Base/loading.jl:748; _require_search_from_serialized(pkg::Base.PkgId, sourcepath::String)
  ╎    ╎    ╎    ╎   47  @Base/loading.jl:1607; stale_cachefile(modpath::String, cachefile::String)
  ╎    ╎    ╎    ╎    47  @Base/loading.jl:254; identify_package(where::Base.PkgId, name::String)
  ╎    ╎    ╎    ╎     44  @Base/loading.jl:373; manifest_deps_get(env::String, where::Base.PkgId, name::String)
  ╎    ╎    ╎    ╎    ╎ 22  @Base/loading.jl:518; explicit_manifest_deps_get(project_file::String, where::Base.UUID, name::String)
  ╎    ╎    ╎    ╎    ╎  22  @Base/array.jl:785; iterate(A::Vector{Any})
20╎    ╎    ╎    ╎    ╎   22  @Base/array.jl:785; iterate
  ╎    ╎    ╎    ╎  89  @Base/loading.jl:761; _require_search_from_serialized(pkg::Base.PkgId, sourcepath::String)
  ╎    ╎    ╎    ╎   89  @Base/loading.jl:701; _tryrequire_from_serialized(modkey::Base.PkgId, build_id::UInt64, modpath::String)
  ╎    ╎    ╎    ╎    27  @Base/loading.jl:748; _require_search_from_serialized(pkg::Base.PkgId, sourcepath::String)
  ╎    ╎    ╎    ╎     22  @Base/loading.jl:1607; stale_cachefile(modpath::String, cachefile::String)
  ╎    ╎    ╎    ╎    ╎ 22  @Base/loading.jl:254; identify_package(where::Base.PkgId, name::String)
 1╎    ╎    ╎    ╎    ╎  20  @Base/loading.jl:373; manifest_deps_get(env::String, where::Base.PkgId, name::String)
  ╎    ╎    ╎    ╎    ╎   8   @Base/loading.jl:522; explicit_manifest_deps_get(project_file::String, where::Base.UUID, name::String)
  ╎    ╎    ╎    ╎    ╎    8   @Base/uuid.jl:82; UUID
  ╎    ╎    ╎    ╎    ╎     8   @Base/uuid.jl:77; parse
  ╎    ╎    ╎    ╎    45  @Base/loading.jl:772; _require_search_from_serialized(pkg::Base.PkgId, sourcepath::String)
25╎    ╎    ╎    ╎     37  @Base/loading.jl:686; _include_from_serialized(path::String, depmods::Vector{Any})
Total snapshots: 203

With Revise:

julia> Profile.print(noisefloor=2)
Overhead ╎ [+additional indent] Count File:Line; Function
=========================================================
   ╎386  @Base/client.jl:485; _start()
   ╎ 386  @Base/client.jl:302; exec_options(opts::Base.JLOptions)
   ╎  386  @Base/client.jl:372; run_main_repl(interactive::Bool, quiet::Bool, banner::Bool, history_file::Bool, color_set::Bool)
   ╎   386  @Base/essentials.jl:706; invokelatest
   ╎    386  @Base/essentials.jl:707; #invokelatest#2
   ╎     386  @Base/client.jl:387; (::Base.var"#862#864"{Bool, Bool, Bool})(REPL::Module)
   ╎    ╎ 386  @REPL/src/REPL.jl:305; run_repl(repl::REPL.AbstractREPL, consumer::Any)
   ╎    ╎  386  @REPL/src/REPL.jl:317; run_repl(repl::REPL.AbstractREPL, consumer::Any; backend_on_current_task::Bool)
   ╎    ╎   386  @REPL/src/REPL.jl:185; start_repl_backend(backend::REPL.REPLBackend, consumer::Any)
   ╎    ╎    386  @REPL/src/REPL.jl:200; repl_backend_loop(backend::REPL.REPLBackend)
   ╎    ╎     386  @REPL/src/REPL.jl:139; eval_user_input(ast::Any, backend::REPL.REPLBackend)
 16╎    ╎    ╎ 386  @Base/boot.jl:360; eval(m::Module, e::Any)
   ╎    ╎    ╎  370  @Base/loading.jl:913; require(into::Module, mod::Symbol)
   ╎    ╎    ╎   370  @Base/loading.jl:926; require(uuidkey::Base.PkgId)
   ╎    ╎    ╎    370  @Base/loading.jl:1010; _require(pkg::Base.PkgId)
   ╎    ╎    ╎     300  @Base/loading.jl:761; _require_search_from_serialized(pkg::Base.PkgId, sourcepath::String)
   ╎    ╎    ╎    ╎ 300  @Base/loading.jl:701; _tryrequire_from_serialized(modkey::Base.PkgId, build_id::UInt64, modpath::String)
   ╎    ╎    ╎    ╎  117  @Base/loading.jl:748; _require_search_from_serialized(pkg::Base.PkgId, sourcepath::String)
   ╎    ╎    ╎    ╎   97   @Base/loading.jl:1607; stale_cachefile(modpath::String, cachefile::String)
   ╎    ╎    ╎    ╎    85   @Base/loading.jl:254; identify_package(where::Base.PkgId, name::String)
  1╎    ╎    ╎    ╎     80   @Base/loading.jl:373; manifest_deps_get(env::String, where::Base.PkgId, name::String)
  6╎    ╎    ╎    ╎    ╎ 17   @Base/loading.jl:518; explicit_manifest_deps_get(project_file::String, where::Base.UUID, name::String)
  1╎    ╎    ╎    ╎    ╎  11   @Base/array.jl:785; iterate(A::Vector{Any})
  9╎    ╎    ╎    ╎    ╎   10   @Base/array.jl:785; iterate
 10╎    ╎    ╎    ╎    ╎ 18   @Base/loading.jl:520; explicit_manifest_deps_get(project_file::String, where::Base.UUID, name::String)
   ╎    ╎    ╎    ╎    ╎  8    @Base/dict.jl:505; get(h::Dict{String, Any}, key::String, default::Nothing)
  2╎    ╎    ╎    ╎    ╎ 23   @Base/loading.jl:522; explicit_manifest_deps_get(project_file::String, where::Base.UUID, name::String)
   ╎    ╎    ╎    ╎    ╎  21   @Base/uuid.jl:82; UUID
   ╎    ╎    ╎    ╎    ╎   21   @Base/uuid.jl:77; parse
   ╎    ╎    ╎    ╎  130  @Base/loading.jl:761; _require_search_from_serialized(pkg::Base.PkgId, sourcepath::String)
   ╎    ╎    ╎    ╎   126  @Base/loading.jl:701; _tryrequire_from_serialized(modkey::Base.PkgId, build_id::UInt64, modpath::String)
   ╎    ╎    ╎    ╎    49   @Base/loading.jl:748; _require_search_from_serialized(pkg::Base.PkgId, sourcepath::String)
   ╎    ╎    ╎    ╎     45   @Base/loading.jl:1607; stale_cachefile(modpath::String, cachefile::String)
   ╎    ╎    ╎    ╎    ╎ 43   @Base/loading.jl:254; identify_package(where::Base.PkgId, name::String)
   ╎    ╎    ╎    ╎    ╎  37   @Base/loading.jl:373; manifest_deps_get(env::String, where::Base.PkgId, name::String)
   ╎    ╎    ╎    ╎    ╎   16   @Base/loading.jl:522; explicit_manifest_deps_get(project_file::String, where::Base.UUID, name::String)
   ╎    ╎    ╎    ╎    ╎    16   @Base/uuid.jl:82; UUID
   ╎    ╎    ╎    ╎    ╎     16   @Base/uuid.jl:77; parse
   ╎    ╎    ╎    ╎    31   @Base/loading.jl:761; _require_search_from_serialized(pkg::Base.PkgId, sourcepath::String)
   ╎    ╎    ╎    ╎     31   @Base/loading.jl:701; _tryrequire_from_serialized(modkey::Base.PkgId, build_id::UInt64, modpath::String)
   ╎    ╎    ╎    ╎    ╎ 13   @Base/loading.jl:748; _require_search_from_serialized(pkg::Base.PkgId, sourcepath::String)
   ╎    ╎    ╎    ╎    ╎  9    @Base/loading.jl:1607; stale_cachefile(modpath::String, cachefile::String)
   ╎    ╎    ╎    ╎    ╎   9    @Base/loading.jl:254; identify_package(where::Base.PkgId, name::String)
   ╎    ╎    ╎    ╎    ╎    8    @Base/loading.jl:373; manifest_deps_get(env::String, where::Base.PkgId, name::String)
   ╎    ╎    ╎    ╎    ╎ 15   @Base/loading.jl:772; _require_search_from_serialized(pkg::Base.PkgId, sourcepath::String)
  1╎    ╎    ╎    ╎    ╎  10   @Base/loading.jl:686; _include_from_serialized(path::String, depmods::Vector{Any})
   ╎    ╎    ╎    ╎    ╎   8    @Base/libdl.jl:114; dlopen(s::String, flags::UInt32)
  8╎    ╎    ╎    ╎    ╎    8    @Base/libdl.jl:114; dlopen(s::String, flags::UInt32; throw_error::Bool)
   ╎    ╎    ╎    ╎    40   @Base/loading.jl:772; _require_search_from_serialized(pkg::Base.PkgId, sourcepath::String)
 17╎    ╎    ╎    ╎     33   @Base/loading.jl:686; _include_from_serialized(path::String, depmods::Vector{Any})
   ╎    ╎    ╎    ╎  48   @Base/loading.jl:772; _require_search_from_serialized(pkg::Base.PkgId, sourcepath::String)
  6╎    ╎    ╎    ╎   37   @Base/loading.jl:686; _include_from_serialized(path::String, depmods::Vector{Any})
   ╎    ╎    ╎    ╎    22   @Base/libdl.jl:114; dlopen(s::String, flags::UInt32)
 22╎    ╎    ╎    ╎     22   @Base/libdl.jl:114; dlopen(s::String, flags::UInt32; throw_error::Bool)
   ╎    ╎    ╎     47   @Base/loading.jl:772; _require_search_from_serialized(pkg::Base.PkgId, sourcepath::String)
  1╎    ╎    ╎    ╎ 43   @Base/loading.jl:686; _include_from_serialized(path::String, depmods::Vector{Any})
   ╎    ╎    ╎    ╎  41   @Base/libdl.jl:114; dlopen(s::String, flags::UInt32)
 41╎    ╎    ╎    ╎   41   @Base/libdl.jl:114; dlopen(s::String, flags::UInt32; throw_error::Bool)
  1╎1    @Base/dict.jl:505; get(h::Dict{String, Any}, key::String, default::Nothing)
   ╎112  @Base/task.jl:478; task_done_hook(t::Task)
   ╎ 112  @Base/task.jl:752; wait
112╎  112  @Base/task.jl:744; poptask(W::Base.InvasiveLinkedListSynchronized{Task})
 55╎311  @Revise/src/types.jl:272; (::Revise.TaskThunk)()
   ╎ 242  @Revise/src/pkgs.jl:359; _watch_package(id::Base.PkgId)
   ╎  117  @Revise/src/loading.jl:39; parse_pkg_files(id::Base.PkgId)
   ╎   117  @Revise/src/types.jl:107; FileInfo
  3╎    117  @Revise/src/types.jl:73; OrderedDict
   ╎     30   @Base/compiler/typeinfer.jl:860; typeinf_ext_toplevel(mi::Core.MethodInstance, world::UInt64)
   ╎    ╎ 30   @Base/compiler/typeinfer.jl:864; typeinf_ext_toplevel(interp::Core.Compiler.NativeInterpreter, linfo::Core.MethodInstance)
   ╎    ╎  30   @Base/compiler/typeinfer.jl:831; typeinf_ext(interp::Core.Compiler.NativeInterpreter, mi::Core.MethodInstance)
   ╎    ╎   30   @Base/compiler/typeinfer.jl:207; typeinf(interp::Core.Compiler.NativeInterpreter, frame::Core.Compiler.InferenceState)
   ╎    ╎    29   @Base/compiler/typeinfer.jl:212; _typeinf(interp::Core.Compiler.NativeInterpreter, frame::Core.Compiler.InferenceState)
   ╎    ╎     29   @Base/compiler/abstractinterpretation.jl:1442; typeinf_nocycle(interp::Core.Compiler.NativeInterpreter, frame::Core.Compiler.InferenceState)
   ╎    ╎    ╎ 29   @Base/compiler/abstractinterpretation.jl:1386; typeinf_local(interp::Core.Compiler.NativeInterpreter, frame::Core.Compiler.InferenceState)
   ╎    ╎    ╎  29   @Base/compiler/abstractinterpretation.jl:1132; abstract_eval_statement(interp::Core.Compiler.NativeInterpreter, e::Any, vtypes::Vector{Any}, sv::...
   ╎    ╎    ╎   29   @Base/compiler/abstractinterpretation.jl:1010; abstract_call(interp::Core.Compiler.NativeInterpreter, fargs::Vector{Any}, argtypes::Vector{Any},...
   ╎    ╎    ╎    29   @Base/compiler/abstractinterpretation.jl:1026; abstract_call(interp::Core.Compiler.NativeInterpreter, fargs::Vector{Any}, argtypes::Vector{Any},...
   ╎    ╎    ╎     29   @Base/compiler/abstractinterpretation.jl:1003; abstract_call_known(interp::Core.Compiler.NativeInterpreter, f::Any, fargs::Vector{Any}, argtype...
   ╎    ╎    ╎    ╎ 29   @Base/compiler/abstractinterpretation.jl:154; abstract_call_gf_by_type(interp::Core.Compiler.NativeInterpreter, f::Any, argtypes::Vector{Any},...
   ╎    ╎    ╎    ╎  28   @Base/compiler/abstractinterpretation.jl:307; abstract_call_method_with_const_args(interp::Core.Compiler.NativeInterpreter, rettype::Any, f::A...
   ╎    ╎    ╎    ╎   28   @Base/compiler/typeinfer.jl:207; typeinf(interp::Core.Compiler.NativeInterpreter, frame::Core.Compiler.InferenceState)
   ╎    ╎    ╎    ╎    28   @Base/compiler/typeinfer.jl:212; _typeinf(interp::Core.Compiler.NativeInterpreter, frame::Core.Compiler.InferenceState)
   ╎    ╎    ╎    ╎     28   @Base/compiler/abstractinterpretation.jl:1442; typeinf_nocycle(interp::Core.Compiler.NativeInterpreter, frame::Core.Compiler.InferenceState)
   ╎    ╎    ╎    ╎    ╎ 28   @Base/compiler/abstractinterpretation.jl:1386; typeinf_local(interp::Core.Compiler.NativeInterpreter, frame::Core.Compiler.InferenceState)
   ╎    ╎    ╎    ╎    ╎  28   @Base/compiler/abstractinterpretation.jl:1132; abstract_eval_statement(interp::Core.Compiler.NativeInterpreter, e::Any, vtypes::Vector{Any}...
   ╎    ╎    ╎    ╎    ╎   28   @Base/compiler/abstractinterpretation.jl:1010; abstract_call(interp::Core.Compiler.NativeInterpreter, fargs::Vector{Any}, argtypes::Vector...
   ╎    ╎    ╎    ╎    ╎    28   @Base/compiler/abstractinterpretation.jl:1026; abstract_call(interp::Core.Compiler.NativeInterpreter, fargs::Vector{Any}, argtypes::Vector...
   ╎    ╎    ╎    ╎    ╎     28   @Base/compiler/abstractinterpretation.jl:1003; abstract_call_known(interp::Core.Compiler.NativeInterpreter, f::Any, fargs::Vector{Any}, a...
   ╎    ╎    ╎    ╎    ╎    ╎ 28   @Base/compiler/abstractinterpretation.jl:154; abstract_call_gf_by_type(interp::Core.Compiler.NativeInterpreter, f::Any, argtypes::Vector...
   ╎    ╎    ╎    ╎    ╎    ╎  28   @Base/compiler/abstractinterpretation.jl:307; abstract_call_method_with_const_args(interp::Core.Compiler.NativeInterpreter, rettype::Any...
   ╎    ╎    ╎    ╎    ╎    ╎   28   @Base/compiler/typeinfer.jl:207; typeinf(interp::Core.Compiler.NativeInterpreter, frame::Core.Compiler.InferenceState)
   ╎    ╎    ╎    ╎    ╎    ╎    27   @Base/compiler/typeinfer.jl:235; _typeinf(interp::Core.Compiler.NativeInterpreter, frame::Core.Compiler.InferenceState)
   ╎    ╎    ╎    ╎    ╎    ╎     27   @Base/compiler/optimize.jl:186; optimize(opt::Core.Compiler.OptimizationState, params::Core.Compiler.OptimizationParams,...
   ╎    ╎    ╎    ╎    ╎    ╎    ╎ 27   @Base/compiler/ssair/driver.jl:132; run_passes(ci::Core.CodeInfo, nargs::Int64, sv::Core.Compiler.OptimizationState)
   ╎    ╎    ╎    ╎    ╎    ╎    ╎  27   @Base/compiler/ssair/passes.jl:715; getfield_elim_pass!(ir::Core.Compiler.IRCode)
   ╎    ╎    ╎    ╎    ╎    ╎    ╎   27   @Base/compiler/ssair/ir.jl:1246; iterate(compact::Core.Compiler.IncrementalCompact, ::Tuple{Int64, Int64})
   ╎    ╎    ╎    ╎    ╎    ╎    ╎    27   @Base/compiler/ssair/ir.jl:1005; process_node!(compact::Core.Compiler.IncrementalCompact, result_idx::Int64, inst::Cor...
   ╎    ╎    ╎    ╎    ╎    ╎    ╎     27   @Base/compiler/ssair/ir.jl:853; renumber_ssa2!(stmt::Any, ssanums::Vector{Any}, used_ssas::Vector{Int64}, late_fixup:...
   ╎    ╎    ╎    ╎    ╎    ╎    ╎    ╎ 27   @Base/compiler/ssair/ir.jl:430; iterate
 27╎    ╎    ╎    ╎    ╎    ╎    ╎    ╎  27   @Base/compiler/ssair/ir.jl:438; iterate(it::Core.Compiler.UseRefIterator, #unused#::Nothing)
 62╎     84   @OrderedCollections/src/ordered_dict.jl:26; OrderedDict
   ╎    ╎ 22   @Base/compiler/typeinfer.jl:860; typeinf_ext_toplevel(mi::Core.MethodInstance, world::UInt64)
   ╎    ╎  22   @Base/compiler/typeinfer.jl:864; typeinf_ext_toplevel(interp::Core.Compiler.NativeInterpreter, linfo::Core.MethodInstance)
   ╎    ╎   22   @Base/compiler/typeinfer.jl:831; typeinf_ext(interp::Core.Compiler.NativeInterpreter, mi::Core.MethodInstance)
   ╎    ╎    22   @Base/compiler/typeinfer.jl:207; typeinf(interp::Core.Compiler.NativeInterpreter, frame::Core.Compiler.InferenceState)
   ╎    ╎     21   @Base/compiler/typeinfer.jl:212; _typeinf(interp::Core.Compiler.NativeInterpreter, frame::Core.Compiler.InferenceState)
   ╎    ╎    ╎ 21   @Base/compiler/abstractinterpretation.jl:1442; typeinf_nocycle(interp::Core.Compiler.NativeInterpreter, frame::Core.Compiler.InferenceState)
   ╎    ╎    ╎  17   @Base/compiler/abstractinterpretation.jl:1371; typeinf_local(interp::Core.Compiler.NativeInterpreter, frame::Core.Compiler.InferenceState)
   ╎    ╎    ╎   17   @Base/compiler/abstractinterpretation.jl:1132; abstract_eval_statement(interp::Core.Compiler.NativeInterpreter, e::Any, vtypes::Vector{Any}, sv:...
   ╎    ╎    ╎    17   @Base/compiler/abstractinterpretation.jl:1010; abstract_call(interp::Core.Compiler.NativeInterpreter, fargs::Vector{Any}, argtypes::Vector{Any},...
   ╎    ╎    ╎     17   @Base/compiler/abstractinterpretation.jl:1026; abstract_call(interp::Core.Compiler.NativeInterpreter, fargs::Vector{Any}, argtypes::Vector{Any}...
   ╎    ╎    ╎    ╎ 17   @Base/compiler/abstractinterpretation.jl:1003; abstract_call_known(interp::Core.Compiler.NativeInterpreter, f::Any, fargs::Vector{Any}, argtype...
   ╎    ╎    ╎    ╎  17   @Base/compiler/abstractinterpretation.jl:130; abstract_call_gf_by_type(interp::Core.Compiler.NativeInterpreter, f::Any, argtypes::Vector{Any},...
   ╎    ╎    ╎    ╎   17   @Base/compiler/abstractinterpretation.jl:466; abstract_call_method(interp::Core.Compiler.NativeInterpreter, method::Method, sig::Any, sparams...
   ╎    ╎    ╎    ╎    17   @Base/compiler/typeinfer.jl:741; typeinf_edge(interp::Core.Compiler.NativeInterpreter, method::Method, atypes::Any, sparams::Co...
   ╎    ╎    ╎    ╎     17   @Base/compiler/typeinfer.jl:207; typeinf(interp::Core.Compiler.NativeInterpreter, frame::Core.Compiler.InferenceState)
   ╎    ╎    ╎    ╎    ╎ 16   @Base/compiler/typeinfer.jl:212; _typeinf(interp::Core.Compiler.NativeInterpreter, frame::Core.Compiler.InferenceState)
   ╎    ╎    ╎    ╎    ╎  16   @Base/compiler/abstractinterpretation.jl:1442; typeinf_nocycle(interp::Core.Compiler.NativeInterpreter, frame::Core.Compiler.InferenceState)
   ╎    ╎    ╎    ╎    ╎   15   @Base/compiler/abstractinterpretation.jl:1386; typeinf_local(interp::Core.Compiler.NativeInterpreter, frame::Core.Compiler.InferenceState)
   ╎    ╎    ╎    ╎    ╎    15   @Base/compiler/abstractinterpretation.jl:1132; abstract_eval_statement(interp::Core.Compiler.NativeInterpreter, e::Any, vtypes::Vector{Any...
   ╎    ╎    ╎    ╎    ╎     15   @Base/compiler/abstractinterpretation.jl:1010; abstract_call(interp::Core.Compiler.NativeInterpreter, fargs::Vector{Any}, argtypes::Vecto...
   ╎    ╎    ╎    ╎    ╎    ╎ 15   @Base/compiler/abstractinterpretation.jl:1026; abstract_call(interp::Core.Compiler.NativeInterpreter, fargs::Vector{Any}, argtypes::Vecto...
   ╎    ╎    ╎    ╎    ╎    ╎  15   @Base/compiler/abstractinterpretation.jl:1003; abstract_call_known(interp::Core.Compiler.NativeInterpreter, f::Any, fargs::Vector{Any}, ...
   ╎    ╎    ╎    ╎    ╎    ╎   15   @Base/compiler/abstractinterpretation.jl:130; abstract_call_gf_by_type(interp::Core.Compiler.NativeInterpreter, f::Any, argtypes::Vecto...
   ╎    ╎    ╎    ╎    ╎    ╎    15   @Base/compiler/abstractinterpretation.jl:466; abstract_call_method(interp::Core.Compiler.NativeInterpreter, method::Method, sig::Any, ...
   ╎    ╎    ╎    ╎    ╎    ╎     15   @Base/compiler/typeinfer.jl:741; typeinf_edge(interp::Core.Compiler.NativeInterpreter, method::Method, atypes::Any, spara...
   ╎    ╎    ╎    ╎    ╎    ╎    ╎ 15   @Base/compiler/typeinfer.jl:207; typeinf(interp::Core.Compiler.NativeInterpreter, frame::Core.Compiler.InferenceState)
   ╎    ╎    ╎    ╎    ╎    ╎    ╎  11   @Base/compiler/typeinfer.jl:212; _typeinf(interp::Core.Compiler.NativeInterpreter, frame::Core.Compiler.InferenceState)
   ╎    ╎    ╎    ╎    ╎    ╎    ╎   11   @Base/compiler/abstractinterpretation.jl:1442; typeinf_nocycle(interp::Core.Compiler.NativeInterpreter, frame::Core.Compiler.Inferen...
   ╎    ╎    ╎    ╎    ╎    ╎    ╎    8    @Base/compiler/abstractinterpretation.jl:1386; typeinf_local(interp::Core.Compiler.NativeInterpreter, frame::Core.Compiler.Inference...
   ╎    ╎    ╎    ╎    ╎    ╎    ╎     8    @Base/compiler/abstractinterpretation.jl:1132; abstract_eval_statement(interp::Core.Compiler.NativeInterpreter, e::Any, vtypes::Vec...
   ╎    ╎    ╎    ╎    ╎    ╎    ╎    ╎ 8    @Base/compiler/abstractinterpretation.jl:1010; abstract_call(interp::Core.Compiler.NativeInterpreter, fargs::Vector{Any}, argtypes:...
   ╎    ╎    ╎    ╎    ╎    ╎    ╎    ╎  8    @Base/compiler/abstractinterpretation.jl:1026; abstract_call(interp::Core.Compiler.NativeInterpreter, fargs::Vector{Any}, argtypes...
   ╎    ╎    ╎    ╎    ╎    ╎    ╎    ╎   8    @Base/compiler/abstractinterpretation.jl:1003; abstract_call_known(interp::Core.Compiler.NativeInterpreter, f::Any, fargs::Vector...
   ╎    ╎    ╎    ╎    ╎    ╎    ╎    ╎    5    @Base/compiler/abstractinterpretation.jl:130; abstract_call_gf_by_type(interp::Core.Compiler.NativeInterpreter, f::Any, argtypes...
   ╎    ╎    ╎    ╎    ╎    ╎    ╎    ╎     5    @Base/compiler/abstractinterpretation.jl:466; abstract_call_method(interp::Core.Compiler.NativeInterpreter, method::Method, sig:...
   ╎    ╎    ╎    ╎    ╎    ╎    ╎    ╎    ╎ 5    @Base/compiler/typeinfer.jl:741; typeinf_edge(interp::Core.Compiler.NativeInterpreter, method::Method, atypes::Any...
   ╎    ╎    ╎    ╎    ╎    ╎    ╎    ╎    ╎  5    @Base/compiler/typeinfer.jl:207; typeinf(interp::Core.Compiler.NativeInterpreter, frame::Core.Compiler.InferenceSt...
   ╎    ╎    ╎    ╎    ╎    ╎    ╎    ╎    ╎   4    @Base/compiler/typeinfer.jl:212; _typeinf(interp::Core.Compiler.NativeInterpreter, frame::Core.Compiler.Inference...
   ╎    ╎    ╎    ╎    ╎    ╎    ╎    ╎    ╎    4    @Base/compiler/abstractinterpretation.jl:1442; typeinf_nocycle(interp::Core.Compiler.NativeInterpreter, frame::Core.Compiler.I...
   ╎    ╎    ╎    ╎    ╎    ╎    ╎    ╎    ╎     4    @Base/compiler/abstractinterpretation.jl:1386; typeinf_local(interp::Core.Compiler.NativeInterpreter, frame::Core.Compiler.In...
   ╎    ╎    ╎    ╎    ╎    ╎    ╎    ╎    ╎    ╎ 4    @Base/compiler/abstractinterpretation.jl:1132; abstract_eval_statement(interp::Core.Compiler.NativeInterpreter, e::Any, vtype...
   ╎    ╎    ╎    ╎    ╎    ╎    ╎    ╎    ╎    ╎  4    @Base/compiler/abstractinterpretation.jl:1010; abstract_call(interp::Core.Compiler.NativeInterpreter, fargs::Vector{Any}, ar...
   ╎    ╎    ╎    ╎    ╎    ╎    ╎    ╎    ╎    ╎   4    @Base/compiler/abstractinterpretation.jl:1026; abstract_call(interp::Core.Compiler.NativeInterpreter, fargs::Vector{Any}, a...
   ╎    ╎    ╎    ╎    ╎    ╎    ╎    ╎    ╎    ╎    4    @Base/compiler/abstractinterpretation.jl:1003; abstract_call_known(interp::Core.Compiler.NativeInterpreter, f::Any, fargs::...
   ╎    ╎    ╎    ╎    ╎    ╎    ╎    ╎    ╎    ╎     4    @Base/compiler/abstractinterpretation.jl:71; abstract_call_gf_by_type(interp::Core.Compiler.NativeInterpreter, f::Any, ar...
   ╎    ╎    ╎    ╎    ╎    ╎    ╎    ╎    ╎    ╎    ╎ 4    @Base/compiler/methodtable.jl:65; (::Core.Compiler.var"#findall##kw")(::NamedTuple{(:limit,), Tuple{Int64}}, :...
   ╎    ╎    ╎    ╎    ╎    ╎    ╎    ╎    ╎    ╎    ╎  4    @Base/compiler/methodtable.jl:66; #findall#209
   ╎    ╎    ╎    ╎    ╎    ╎    ╎    ╎    ╎    ╎    ╎   4    @Base/iddict.jl:163; get!
   ╎    ╎    ╎    ╎    ╎    ╎    ╎    ╎    ╎    ╎    ╎    4    @Base/compiler/methodtable.jl:67; (::Core.Compiler.var"#210#211"{Int64, Core.Compiler.CachedMethodTable{Core...
   ╎    ╎    ╎    ╎    ╎    ╎    ╎    ╎    ╎    ╎    ╎     4    @Base/compiler/methodtable.jl:54; (::Core.Compiler.var"#findall##kw")(::NamedTuple{(:limit,), Tuple{Int64}}...
   ╎    ╎    ╎    ╎    ╎    ╎    ╎    ╎    ╎    ╎    ╎    ╎ 4    @Base/compiler/methodtable.jl:57; #findall#208
  4╎    ╎    ╎    ╎    ╎    ╎    ╎    ╎    ╎    ╎    ╎    ╎  4    @Base/reflection.jl:821; _methods_by_ftype
 52╎  64   @Revise/src/loading.jl:41; parse_pkg_files(id::Base.PkgId)
Total snapshots: 1339

IanButterworth · 2021-07-21T23:05:23Z

Thought I'd use a new tool to look at a classic issue. This is on julia 1.8.0-DEV.240 (2021-07-21) 61b6994884

julia> @time_imports using Gtk
      0.5 ms      ┌ Zlib_jll
      0.6 ms          ┌ Preferences
      1.5 ms        ┌ JLLWrappers
     14.5 ms      ┌ Libiconv_jll
     35.1 ms    ┌ XML2_jll
      1.1 ms    ┌ CompilerSupportLibraries_jll
     38.8 ms  ┌ Gettext_jll
      0.9 ms      ┌ Libgpg_error_jll
      2.1 ms    ┌ Libgcrypt_jll
      0.7 ms      ┌ Xorg_libXau_jll
      0.7 ms      ┌ Xorg_xtrans_jll
      0.8 ms      ┌ Xorg_libXdmcp_jll
      1.5 ms        ┌ XSLT_jll
      0.7 ms          ┌ Xorg_libpthread_stubs_jll
      3.7 ms        ┌ Xorg_libxcb_jll
      6.6 ms      ┌ Xorg_libX11_jll
     10.2 ms    ┌ Xorg_libXfixes_jll
      0.9 ms      ┌ Libmount_jll
      0.9 ms      ┌ PCRE_jll
      0.9 ms      ┌ Libffi_jll
      5.3 ms    ┌ Glib_jll
      1.1 ms    ┌ Xorg_libXext_jll
      0.8 ms      ┌ Expat_jll
      1.9 ms    ┌ Dbus_jll
      1.0 ms      ┌ Xorg_libXi_jll
      2.2 ms    ┌ Xorg_libXtst_jll
     25.5 ms  ┌ at_spi2_core_jll
      1.6 ms  ┌ Wayland_jll
      1.2 ms  ┌ Xorg_libxkbfile_jll
      0.8 ms  ┌ NaNMath
      2.6 ms  ┌ Libglvnd_jll
      0.8 ms  ┌ iso_codes_jll
      0.9 ms  ┌ Xorg_libXcomposite_jll
      1.3 ms  ┌ JpegTurbo_jll
     68.3 ms  ┌ FixedPointNumbers
      0.9 ms      ┌ Bzip2_jll
      2.0 ms    ┌ FreeType2_jll
      0.9 ms    ┌ libpng_jll
      0.8 ms    ┌ Graphite2_jll
      0.8 ms      ┌ LZO_jll
      0.8 ms      ┌ Pixman_jll
      0.9 ms      ┌ Xorg_libXrender_jll
      0.8 ms        ┌ Libuuid_jll
      5.8 ms      ┌ Fontconfig_jll
      2.9 ms      ┌ Cairo_jll
     13.4 ms    ┌ HarfBuzz_jll
      0.9 ms    ┌ FriBidi_jll
     21.1 ms  ┌ Pango_jll
      1.5 ms  ┌ Libepoxy_jll
      1.0 ms  ┌ Xorg_libXrandr_jll
      0.9 ms    ┌ ATK_jll
      2.2 ms  ┌ at_spi2_atk_jll
      0.8 ms  ┌ Xorg_xkbcomp_jll
      1.3 ms  ┌ Xorg_libXinerama_jll
      1.2 ms  ┌ Zstd_jll
      0.3 ms  ┌ Reexport
    237.0 ms    ┌ ColorTypes
    138.1 ms    ┌ Colors
    377.5 ms  ┌ Graphics
      1.1 ms  ┌ Libtiff_jll
      2.5 ms  ┌ Cairo
      0.8 ms  ┌ Xorg_libXdamage_jll
      0.6 ms  ┌ Wayland_protocols_jll
      0.6 ms    ┌ Xorg_xkeyboard_config_jll
      1.7 ms  ┌ xkbcommon_jll
      0.8 ms  ┌ Xorg_libXcursor_jll
      0.5 ms  ┌ hicolor_icon_theme_jll
      0.6 ms  ┌ adwaita_icon_theme_jll
      1.3 ms  ┌ gdk_pixbuf_jll
      7.0 ms  ┌ GTK3_jll
   1104.9 ms  Gtk

staticfloat · 2021-07-21T23:12:58Z

ColorTypes... What are you doing in there....

timholy · 2021-07-22T00:13:26Z

ColorTypes and Colors are probably the only ones with a substantial number of MethodInstances to retrieve from the cache:

Those take quite a long time because Julia has to insert all the backedges while it deserializes the cache. But it dramatically reduces latency on first use, and on balance it's not even close: it's a convincing win.

The more packages add precompilation (either through precompile statements or just by executing code during package build), the slower loading will be but still latency in practice should reduce substantially overall.

Graphics, though, is a mystery. I don't understand that one.

giordano · 2021-07-22T00:16:29Z

Graphics, though, is a mystery. I don't understand that one.

That should be pretty fast, you need to subtract from 377.5 the time to load Colors and ColorTypes

timholy · 2021-07-22T00:20:47Z

Oh I see, thanks for explaining what should have been obvious 😬

KristofferC · 2021-08-03T11:28:30Z

FWIW, around 0.2 out of 0.8 seconds load time comes from inferring and running the __init__ method.

timholy · 2021-08-03T12:39:34Z

I think I've noticed that we can't precompile-cache __init__, either. (I don't know why not.)

timholy mentioned this issue Dec 10, 2019

Major package load slowdown, perhaps unnecessary calls to jl_recache_method_instance JuliaLang/julia#34070

Closed

giordano mentioned this issue May 19, 2020

using SDL2_jll is slow JuliaPackaging/Yggdrasil#1050

Closed

KristofferC mentioned this issue Jun 25, 2020

Feature request: scan subdirs for updated versions/projects JuliaLang/Pkg.jl#1874

Closed

timholy closed this as completed Oct 17, 2020

giordano mentioned this issue Jul 29, 2021

UndefVarError: libgdk3 not defined #584

Closed

timholy mentioned this issue Aug 9, 2021

Reduce the first time to solve from 5 seconds to 1 second for Tsit5 SciML/OrdinaryDiffEq.jl#1465

Merged

Major slowdown in package load time #466

Major slowdown in package load time #466

Comments

timholy commented Dec 10, 2019

tknopp commented Dec 10, 2019

timholy commented Dec 10, 2019 • edited Loading

tknopp commented Dec 10, 2019

timholy commented Dec 10, 2019 • edited Loading

timholy commented Dec 10, 2019

tknopp commented Dec 10, 2019

timholy commented Dec 10, 2019 • edited Loading

tknopp commented Dec 10, 2019

giordano commented Dec 10, 2019 • edited Loading

timholy commented Dec 10, 2019

giordano commented Dec 10, 2019

KristofferC commented Dec 10, 2019 • edited Loading

vtjnash commented Dec 10, 2019 • edited Loading

timholy commented Dec 10, 2019 • edited Loading

KristofferC commented Dec 10, 2019

timholy commented Dec 10, 2019

KristofferC commented Dec 10, 2019

timholy commented Dec 10, 2019

timholy commented Dec 11, 2019

KristofferC commented Dec 11, 2019 • edited Loading

KristofferC commented Dec 11, 2019

KristofferC commented Dec 11, 2019 • edited Loading

giordano commented Dec 11, 2019

KristofferC commented Dec 11, 2019

staticfloat commented Dec 11, 2019

staticfloat commented Dec 11, 2019

KristofferC commented Dec 11, 2019

IanButterworth commented Dec 23, 2019

timholy commented May 7, 2020 • edited Loading

timholy commented May 7, 2020 • edited Loading

davidanthoff commented May 7, 2020

timholy commented May 8, 2020

tknopp commented May 8, 2020

timholy commented May 8, 2020

tknopp commented May 8, 2020

davidanthoff commented May 8, 2020

KristofferC commented Jun 25, 2020

tknopp commented Jun 25, 2020

PallHaraldsson commented Oct 16, 2020 • edited Loading

giordano commented Oct 17, 2020 • edited Loading

timholy commented Oct 17, 2020

giordano commented Oct 24, 2020 • edited Loading

timholy commented Oct 25, 2020

giordano commented Oct 25, 2020 • edited Loading

KristofferC commented Oct 25, 2020

timholy commented Oct 25, 2020

timholy commented Oct 25, 2020

IanButterworth commented Jul 21, 2021

staticfloat commented Jul 21, 2021

timholy commented Jul 22, 2021

giordano commented Jul 22, 2021

timholy commented Jul 22, 2021

KristofferC commented Aug 3, 2021

timholy commented Aug 3, 2021

timholy commented Dec 10, 2019 •

edited

Loading

timholy commented Dec 10, 2019 •

edited

Loading

timholy commented Dec 10, 2019 •

edited

Loading

giordano commented Dec 10, 2019 •

edited

Loading

KristofferC commented Dec 10, 2019 •

edited

Loading

vtjnash commented Dec 10, 2019 •

edited

Loading

timholy commented Dec 10, 2019 •

edited

Loading

KristofferC commented Dec 11, 2019 •

edited

Loading

KristofferC commented Dec 11, 2019 •

edited

Loading

timholy commented May 7, 2020 •

edited

Loading

timholy commented May 7, 2020 •

edited

Loading

PallHaraldsson commented Oct 16, 2020 •

edited

Loading

giordano commented Oct 17, 2020 •

edited

Loading

giordano commented Oct 24, 2020 •

edited

Loading

giordano commented Oct 25, 2020 •

edited

Loading