Module loading slow due to method insertion and external target verification

[topolarity]

Now that #47184 is landed (🎉 ), load time has become a significant fraction of TTFX. At @staticfloat's recommendation, I wanted to share some early profiling results.

Command: using CairoMakie
Platform: x86_64-darwin
Total load time: 11.78s

The big contributors to load time appear to be:

1. jl_verify_edges, 56% (6.54s): These calls are fast, but we are severely strained by their quantity. In total, 180k external targets in CairoMakie and its dependencies trigger 180k calls to jl_matching_methods.
2. jl_insert_methods, 21% (2.44s): The slowest (>40ms, up to 500ms) calls to insert new methods make the biggest contribution here, accounting for more than 80% of the total call time.

The next major contributor would be jl_restore_package_image_from_stream_at 0.95s (8% of load time), but I haven't instrumented it in detail. Depending on I/O and dyld cache details, I've also measured up to 20% of load time spent in jl_dlopen. I doubt too much can be done to improve that number, and once caches are warm it typically falls to ~1%.

Tracing was done with Tracy. You can examine the trace file locally or in the browser.

To see what was instrumented, take a look at this commit.

[topolarity]

Some misc. thoughts on which packages are most likely to be affected:

(1) is where we verify edge targets in external modules, and it strongly dominates the load time for packages with many types that use definitions in external packages (e.g. Tuples, Generators, and Arrays using definitions provided by Base).

For example, Makie eventually calls Base.iterate with over 217 Generator types and 385 Tuple types. The result is thousands of external targets to defs in Base:

julia> using PkgCacheInspector
julia> cf = info_cachefile("Makie")
julia> mis = cf.external_targets[2:3:end]
# Print the (5) most commonly-targeted external defs for Makie
julia> last(sort(collect(countmap([(mi.def.module, mi.def.name) for mi in mis if typeof(mi) === Core.MethodInstance])), by=x->x[2]), 5)
5-element Vector{Pair{Tuple{Module, Symbol}, Int64}}:
               (Base, :iterate) => 1535
           (Base, :getproperty) => 1996
              (Base, :getindex) => 2257
               (Base, :convert) => 2401
 (Base.Broadcast, :Broadcasted) => 2570

(2) is responsible for >90% of the load time for small packages with many simple methods, such as Distributions.jl, FillArrays.jl, and DataStructures.jl. These packages have few edges or external targets, making (1) a non-issue.

[KristofferC]

Using a tracing profiler (which I've mostly seemed used for profiling games) like Tracy is a good idea which I thought about using in Julia since I saw it (actually Telemetry instead of Tracy but same thing) used by Jonathan Blow for his compiler, e.g. https://youtu.be/iD08Vpkie8Q?t=1639.

I think we should fill Julia with profiling zones so you can get a very accurate view of how the system behaves over time.

[quinnj]

(@kpamnany has ideas on tracing instrumentation as well, but not sure if there's another issue/discussion where those ideas can come together)

[StefanKarpinski]

A couple of possibly un/helpful thoughts:

1. Could we not verify edges and instead trust that they are correct? The failure mode if invalid edges would be crashing, but I'm not sure if that's a case we expect in normal operation or not.
2. Barring that, could the work be deferred until required? Not sure how feasible/complex that would be.
3. Would this work benefit from batching? If there's any work that is shared in the very large number of calls, then it might help. The loading process could construct lists of edges to be verified and methods to be inserted and then do a batch call instead of individual calls. Might be possible to sort the batched edges/methods to make the verification/insertion processes faster.

[IanButterworth]

Could we not verify edges and instead trust that they are correct?

I happened to look into this yesterday with Makie too, and observed that if you force jl_verify_edges to immediately return all as valid, a simple Makie plot window renders successfully quickly. I also saw very few invalid edges when enabling that debug printing. Obviously that's not correct to do, but the speed up is motivating.. There was some discussion in the #ttfx slack channel

[timholy]

We need to call verify_edges. I'm repeating/expanding on things I've said previously, but Julia has (amazingly cool) features that require us to expect invalidation in the normal course of business:

• we aggressively and automatically specialize
• we allow arbitrary downstream users to add new methods to external functions
• we are interactive and thus can't control exactly what's in the user's environment
• we attempt guarantee that you "get the same result no matter how you got there": whether you load all the code/packages at the beginning and then trigger compilation, or whether you load, compile, load more, compile more, ..., we try to make sure that the end result is the same.

The last property was the fix to #265 and is also what makes Revise possible. I don't think that's a property we want to give up. Therefore we have to check whether calls that we precompiled in a "clean" environment (the minimal one that was used for precompilation) are also valid in the user's "dirty" environment.

While profiling is a nice idea, I'd be surprised if big gains can be found. The trick, I think, will be to do less work rather than making that work faster. Quoting myself on slack:

I suspect that the main savings are to be had by deferring checking edges. If you load PkgB, any call that dispatches to a function PkgA.f owned by PkgA is external and must be checked. But if you had said using PkgC and both PkgA and PkgB were loaded because they are dependencies of PkgC, then from the standpoint of PkgC those are all internal edges and may not need to be checked; you might be able to just cache the result of jl_verify_edges. Note you may not be able to do this if PkgA had already been loaded into your session before you said using PkgC, because at that point you can't rule out the possibility that some other package added new methods to PkgA.f. I haven't thought through all the details carefully though.

[StefanKarpinski]

What about batching? Could that perhaps help?

[topolarity]

Adding an interesting data point (thanks to @maleadt for requesting):
CUDA.jl's load time is dominated by method insertion (2) rather than (1).

In CUDA's case, we spend 78% (3.81s) of 4.90s load time in jl_insert_methods. Only 12% (0.59s) is spent verifying external targets. So it looks like we'll almost certainly want to try to improve both of these load time contributors.

What about batching? Could that perhaps help?

It might be fruitful to aggregate related external targets into a combined data structure (most likely, something tree-ish) for bulk-checking intersections, so that e.g. all iterate(::Tuple, ...) targets in a package can be verified "at once" based on the non-existence of new iterate(::Tuple, ...) definitions, etc.

The intersection would necessarily become more expensive to compute in "dirtier" environments and the implementation would likely be complex, but for common scenarios this might save a lot of work.

[timholy]

@topolarity I think method insertion is also largely about edges...when you insert a new method in an existing method table, you have to check any callers with edges to things that might be superseded by the new method. But I haven't looked at this in detail; is that consistent with what the profiling shows?

@StefanKarpinski,

What about batching? Could that perhaps help?

Yes, that is a way of saying something similar to my point above about "deferring work." Anything that can be deemed "internal" doesn't need to be checked; likewise if you were in control of when a package got loaded, that effectively makes calls to that package "internal-izable" since it seems plausible we could cache the outcome of edge-checking rather than needing to do it at load time. It's only when a package got loaded sometime in the distant past (and Base is one such "package"... 😮) that you lose control and have to check from scratch.

If someone wants to start tackling this, a potential battle plan would be to hack together a mode of base/loading.jl where you can collect the two edge-related arrays of pkgimages (external_targets and edges in the nomenclature of PkgCacheInspector) for every package that gets loaded when you do something like using GLMakie. Then you could write analysis code to figure out how many of them are effectively internal to GLMakie vs connecting to something external like Base. That would give you a pretty good guess about what fraction of the work you can save. It wouldn't be a ton of work to do this, either; PkgCacheInspector is pretty small and much of the code is stolen/modified from base/loading.jl.

[topolarity]

@topolarity I think method insertion is also largely about edges...when you insert a new method in an existing method table, you have to check any callers with edges to things that might be superseded by the new method. But I haven't looked at this in detail; is that consistent with what the profiling shows?

It looks like we spend most of the method insertion time computing a few very expensive type intersections, actually.

78% (3.85s) of CUDA load time is spent in jl_typemap_intersection_visitor. In fact, more than half of that time is spent computing type intersections for just the 20 most expensive method insertions (out of 6615).

Here's the trace file and in-browser viewer from loading CUDA.jl.

[KristofferC]

I bet 5$ that mul! is among those expensive methods.

[oscardssmith]

I'm guessing \ is also another.

[topolarity]

Updated the CUDA trace to annotate jl_method_table_insert with the inserted method name

mul! methods are indeed very expensive to intersect, along with lmul!, ldiv!, copyto! and dot

[oscardssmith]

Ah, in other words, it's exactly what we would expect.

[oscardssmith]

possibly dumb question, but what is the differeence between lmul! and *? (i.e. isn't Matrix .= Number*Matrix already good?