Second "using" is slow (slower than third, can even be slower than the first)

[PallHaraldsson]

Even on my recent:

$ ~/julia-1.6.0-DEV-8f512f3f6d/bin/julia -O3

julia> @time using Plots
 10.669931 seconds (11.02 M allocations: 655.843 MiB, 3.90% gc time)

julia> @time using Plots  # for some other packages if I recall I've seen up to 1+ sec.
  0.611072 seconds (935.63 k allocations: 45.940 MiB, 2.12% gc time)

julia> @time using Plots
  0.000317 seconds (230 allocations: 14.219 KiB)

Second and all subsequent using should all be as fast (not only about Plots.jl). You could ask yourself, why do them, but could well happen in real-world code, and anyway this seems like a low-hanging fruit that should be fixed.

Note, this doesn't happen with all packages, so first I thought it would be a problem with those packages, but I'm not sure. At least none of those I've informed knew of this or have any idea why it happens.

I'm not complaining--here--about the first slow using (a whole separate issue), nor the the even worse (i.e. first one above is not that):

julia> @time using Plots
[ Info: Precompiling Plots [91a5bcdd-55d7-5caf-9e0b-520d859cae80]
122.433167 seconds (11.63 M allocations: 684.720 MiB, 0.18% gc time)

JuliaPlots/Plots.jl#2590

[KristofferC]

This is because loading eg Plots invalidates some of the code loading code itself.

[PallHaraldsson]

Ok, good to know, even better would be to know what that means and how to fix. Is this documented?

[timholy]

Great question. There's lots of attention to this issue right now, and after a few issues are fixed in Julia itself there will be a blog post: JuliaLang/www.julialang.org#794.

[PallHaraldsson]

I'm not sure it's invalidations as Kristoffer states. Why does it happen (I guess your blog explains, if that's the fact), or more importantly why doesn't it happen for 3rd and all subsequent?

I took a look at the very long (that's not bad, I want to read it eventually) blog post as you can see from my review, but I admit I did so far only scan it (and neither read most comments to it).

I was a bit surprised to see using SIMD can invalidate previous code. That's a different package. But we're seeing self-invalidation? Can it for sure happen if you use a module and then again (assuming no dependencies), or is it about e.g. in that case dependencies and those trigger this somehow?

[KristofferC]

why doesn't it happen for 3rd and all subsequent?

Because then the invalidations have resolved.

I was a bit surprised to see using SIMD can invalidate previous code. That's a different package.

All julia code in a session share a global method table so being in a different package isn't really relevant.

[PallHaraldsson]

It at least feels like a bug, and second should be the fastest, from then on (as nothing was done, in-between). I don't have to understand this fully, but like to, most will not care why or even realize, those extra cumulative seconds.

[KristofferC]

and second should be the fastest, from then on (as nothing was done, in-between)

Loading code was done and loading code can invalidate old code (as the blog post describes).

[JeffBezanson]

It's not a bug. The first using loads the package. The second using doesn't add any code, but is slower because the first one invalidated stuff. Then the third one is fast because the second one didn't change anything, and the invalidations have already been resolved. But, we could fix it with this:

--- a/src/toplevel.c
+++ b/src/toplevel.c
@@ -417,7 +417,7 @@ static jl_module_t *call_require(jl_module_t *mod, jl_sym_t *var) JL_GLOBALLY_RO
     }
     if (require_func != NULL) {
         size_t last_age = ptls->world_age;
-        ptls->world_age = (build_mode ? jl_base_module->primary_world : jl_world_counter);
+        ptls->world_age = jl_base_module->primary_world;
         jl_value_t *reqargs[3];

At one time we did something like that. @vtjnash changed it but I don't remember why. Any reason we can't always use primary_world here? I think the cases inside loading that need to already use invokelatest.

[PallHaraldsson]

Ok that makes more sense, than my understanding of what Kristoffer said. I thought he was referring to the second loading, so I thought why not the third then too.

Anyway I was trying new:

(@v1.6) pkg> add SnoopCompile#1185a7517395f

and cot this interesting error (so I guess snoopr is still in development):

julia> @snoopr using Revise
ERROR: ReadOnlyMemoryError()

You seem to know how to "fix" this "non-bug" (I meant "bug" as in could be improved, not like a serious wrong-results problem), so I leave it to you guys (and gals), as maybe not most important "bug", but something/anything to help slow compile situation a bit.

[KristofferC]

At one time we did something like that

I think it got partly reverted in #28290 because it caused problems with loggers (JuliaLang/IJulia.jl#677, JunoLab/Juno.jl#171).

[PallHaraldsson]

Same symptom of invalidations, just additionally slower than first using, so even weirder:

julia> @time using Plumber
  0.090761 seconds (61.81 k allocations: 4.620 MiB)

julia> @time using Plumber
  0.644427 seconds (1.18 M allocations: 58.257 MiB, 3.43% gc time)

julia> @time using Plumber
  0.000383 seconds (463 allocations: 27.734 KiB)

[KristofferC]

Ref #36005 (comment)

[mbauman]

So is this actionable? If we're not going to freeze the loading world age, I suppose someone could investigate which call-sites are causing this in the package loading code and potentially fix/avoid instabilities. Otherwise, this seems to be well-covered by the more general reducing-invalidation issues.