Recompilation and load time

[oschulz]

According to @time and @time_imports, DocStringExtensions seems to recompile on every load, resulting in comparatively long load time (seems to vary a lot, but I've seen up to 75 ms). Now that very low level packages like SpecialFunctions depend on DocStringExtensions, this is becoming more noticeable. Is this inherent (recompilation) to the way DocStringExtensions works, or can we do something about this?

[MichaelHatherly]

Is this inherent (recompilation) to the way DocStringExtensions works, or can we do something about this?

We should be able to do something about it.

[oschulz]

We should be able to do something about it.

Merci!

[MichaelHatherly]

I thought perhaps it was some invalidations causing recompilation since

julia> @time_imports using DocStringExtensions
               ┌ 0.0 ms DocStringExtensions.__init__() 
     15.2 ms  DocStringExtensions 84.18% compilation time

But SnoopCompile isn't giving me anything useful right now :)

julia> using SnoopCompileCore

julia> invs = @snoop_invalidations using DocStringExtensions
Any[]

[oscardssmith]

I'm seeing much worse than this in some cases:

julia> @time @time_imports using OrdinaryDiffEqFIRK
               ┌ 0.0 ms DocStringExtensions.__init__() 
    174.0 ms  DocStringExtensions 99.30% compilation time

[MichaelHatherly]

Any invalidations showing up in that particular case that can be traced back to DocStringExtensions?

[MichaelHatherly]

I spent a little more time looking at this one @oschulz @oscardssmith. Not sure this is actually being caused by anything that DocStringExtensions is doing...

First I commented out

DocStringExtensions.jl/src/DocStringExtensions.jl

Line 113 in f65720c

__init__() = (hook!(template_hook); nothing)

completely, and it resolved the compilation issue:

julia> @time_imports using DocStringExtensions
      2.2 ms  DocStringExtensions

That's not surprising I would think.

So then I just swapped the body of the __init__ with a noop:

__init__ = nothing # (hook!(template_hook); nothing)

That was under the assumption that it was calling hook! that was causing the trouble. But that resulted in

julia> @time_imports using DocStringExtensions
               ┌ 0.0 ms DocStringExtensions.__init__()
    119.5 ms  DocStringExtensions 97.81% compilation time

Which, for me, is no different to the timings of the original __init__:

julia> @time_imports using DocStringExtensions
               ┌ 0.0 ms DocStringExtensions.__init__()
    117.6 ms  DocStringExtensions 97.64% compilation time

Bit weird. So then I just made a MWE package with just

module InitTest

__init__() = nothing

end # module InitTest

And that resulted in the exact same behaviour:

__init__ commented out:

julia> @time_imports using InitTest
      1.0 ms  InitTest

__init__ uncommented:

julia> @time_imports using InitTest
               ┌ 0.0 ms InitTest.__init__()
    120.0 ms  InitTest 98.78% compilation time

---

To me this doesn't look like anything to do with this package, but rather a Julia issue. I'd be grateful if anyone else is able to replicate the above behaviour.

[oschulz]

Maybe we need one of the compiler experts on this ...

[oscardssmith]

Gabriel is looking into this. Current suspicion is that it might be an issue with the timing.

[KristofferC]

Edit: What is written below seems to only be true on macOS.

This regressed in 1.11.3:

❯ julia +1.11.3 --project -q
julia> @time_imports using InitTest
               ┌ 0.0 ms InitTest.__init__() 
     63.8 ms  InitTest 98.75% compilation time

❯ julia +1.11.2 --project -q
julia> @time_imports using InitTest
               ┌ 0.0 ms InitTest.__init__() 
      1.1 ms  InitTest

Looks fixed on JuliaLang/julia#57871, probably due to this: JuliaLang/julia@56909d7.

[MichaelHatherly]

Thanks @KristofferC.

[KristofferC]

I am still not sure this is completely resolved.