Pkg.jl: precompile misses many packages

[timholy]

I ran with @show pkg stale in Pkg.API.precompile and verified that many packages that need precompilation are not getting it. For example, I can do the following:

pkg> precompile
pkg> dev ColorTypes
pkg> precompile  # ColorTypes properly precompiles, but none of its dependencies do
pkg> precompile  # this doesn't help
julia> using Images
[ Info: Precompiling Images [916415d5-f1e6-5110-898d-aaa5f9f070e0]

The latter should happen with the precompile statement, not the using statement.

[KristofferC]

Hm, the code there should mimic how loading itself determines if it needs to precompile but maybe it has bitrotted a bit?

[KristofferC]

When you say

# ColorTypes properly precompiles, but none of its dependencies do

You mean FixedPointNumbers doesn't precompile again? Did it have to?

Also, is Images.jl in the current project or available through the global project?

A bit more detailed reproduction steps would be great here.

[timholy]

Sorry, I should have said "dependents," meant the packages that depend on ColorTypes.

Here's more info. Quite a few of the packages that show up during the precompile step are not yet public. (You'll be interested in MethodCompiler when I get around to finishing it, it's an alternative to https://github.com/JuliaDebug/JuliaInterpreter.jl/pull/309. The goal is to allow you to compile individual frames. It compiles in builtins, ccalls, and llvmcalls, but breaks long inference chains by replacing all other :call exprs in lowered code with do_call(f, args), where do_call is not specialized on f. Hence you basically compile each method as a standalone object.)

julia> versioninfo()
Julia Version 1.3.1-pre.20
Commit 90620af6b9* (2019-12-19 17:59 UTC)
Platform Info:
  OS: Linux (x86_64-linux-gnu)
  CPU: Intel(R) Core(TM) i7-8850H CPU @ 2.60GHz
  WORD_SIZE: 64
  LIBM: libopenlibm
  LLVM: libLLVM-6.0.1 (ORCJIT, skylake)
Environment:
  JULIA_CPU_THREADS = 4

julia> using Images
[ Info: Precompiling Images [916415d5-f1e6-5110-898d-aaa5f9f070e0]

(v1.3) pkg> st ColorTypes
    Status `~/.julia/environments/v1.3/Project.toml`
  [3da002f7] ColorTypes v0.9.0 [`~/.julia/dev/ColorTypes`]

shell> touch ~/.julia/dev/ColorTypes/src/ColorTypes.jl

julia> 
tim@diva:~/.julia/dev/FlameGraphs$ julia
               _
   _       _ _(_)_     |  Documentation: https://docs.julialang.org
  (_)     | (_) (_)    |
   _ _   _| |_  __ _   |  Type "?" for help, "]?" for Pkg help.
  | | | | | | |/ _` |  |
  | | |_| | | | (_| |  |  Version 1.3.1-pre.20 (2019-12-19)
 _/ |\__'_|_|_|\__'_|  |  release-1.3/90620af6b9* (fork: 116 commits, 143 days)
|__/                   |

(v1.3) pkg> precompile
Precompiling project...
Precompiling MethodCompiler
[ Info: Precompiling MethodCompiler [0125340c-fd8a-460d-909b-0475a239bc5b]
ERROR: LoadError: LoadError: UndefVarError: CodeInfo not defined
Stacktrace:
 [1] top-level scope at /home/tim/.julia/dev/MethodCompiler/src/types.jl:3
 [2] include at ./boot.jl:328 [inlined]
 [3] include_relative(::Module, ::String) at ./loading.jl:1105
 [4] include at ./Base.jl:31 [inlined]
 [5] include(::String) at /home/tim/.julia/dev/MethodCompiler/src/MethodCompiler.jl:1
 [6] top-level scope at /home/tim/.julia/dev/MethodCompiler/src/MethodCompiler.jl:5
 [7] include at ./boot.jl:328 [inlined]
 [8] include_relative(::Module, ::String) at ./loading.jl:1105
 [9] include(::Module, ::String) at ./Base.jl:31
 [10] top-level scope at none:2
 [11] eval at ./boot.jl:330 [inlined]
 [12] eval(::Expr) at ./client.jl:425
 [13] top-level scope at ./none:3
in expression starting at /home/tim/.julia/dev/MethodCompiler/src/types.jl:3
in expression starting at /home/tim/.julia/dev/MethodCompiler/src/MethodCompiler.jl:5
Precompiling TableReader
[ Info: Precompiling TableReader [70df011a-6618-58d7-8e16-3cf9e384cb47]
ERROR: LoadError: UndefVarError: ##24#29 not defined
Stacktrace:
 [1] _precompile_() at /home/tim/.julia/packages/TableReader/XQZpf/src/TableReader.jl:784
 [2] top-level scope at /home/tim/.julia/packages/TableReader/XQZpf/src/TableReader.jl:817
 [3] include at ./boot.jl:328 [inlined]
 [4] include_relative(::Module, ::String) at ./loading.jl:1105
 [5] include(::Module, ::String) at ./Base.jl:31
 [6] top-level scope at none:2
 [7] eval at ./boot.jl:330 [inlined]
 [8] eval(::Expr) at ./client.jl:425
 [9] top-level scope at ./none:3
in expression starting at /home/tim/.julia/packages/TableReader/XQZpf/src/TableReader.jl:817
Precompiling JLD2
[ Info: Precompiling JLD2 [033835bb-8acc-5ee8-8aae-3f567f8a3819]
Precompiling FlameGraphs
[ Info: Precompiling FlameGraphs [08572546-2f56-4bcf-ba4e-bab62c3a3f89]
Precompiling ColorTypes
[ Info: Precompiling ColorTypes [3da002f7-5984-5a60-b8a6-cbb66c0b333f]
Precompiling JuMPExtraDiff
[ Info: Precompiling JuMPExtraDiff [be86722b-9116-4f9b-bbe4-285775ac3318]
ERROR: LoadError: UndefVarError: _eval_objective_gradient not defined
Stacktrace:
 [1] getproperty(::Module, ::Symbol) at ./Base.jl:13
 [2] top-level scope at /home/tim/.julia/dev/JuMPExtraDiff/src/JuMPExtraDiff.jl:176
 [3] include at ./boot.jl:328 [inlined]
 [4] include_relative(::Module, ::String) at ./loading.jl:1105
 [5] include(::Module, ::String) at ./Base.jl:31
 [6] top-level scope at none:2
 [7] eval at ./boot.jl:330 [inlined]
 [8] eval(::Expr) at ./client.jl:425
 [9] top-level scope at ./none:3
in expression starting at /home/tim/.julia/dev/JuMPExtraDiff/src/JuMPExtraDiff.jl:176
Precompiling AlgorithmicTaylorBounds
[ Info: Precompiling AlgorithmicTaylorBounds [c58d724d-a8a3-481e-8ea7-19dbd0e83332]
┌ Warning: Package AlgorithmicTaylorBounds does not have LinearAlgebra in its dependencies:
│ - If you have AlgorithmicTaylorBounds checked out for development and have
│   added LinearAlgebra as a dependency but haven't updated your primary
│   environment's manifest file, try `Pkg.resolve()`.
│ - Otherwise you may need to report an issue with AlgorithmicTaylorBounds
└ Loading LinearAlgebra into AlgorithmicTaylorBounds from project dependency, future warnings for AlgorithmicTaylorBounds are suppressed.
ERROR: LoadError: UndefVarError: Reflection not defined
Stacktrace:
 [1] top-level scope at /home/tim/.julia/dev/AlgorithmicTaylorBounds/src/AlgorithmicTaylorBounds.jl:11
 [2] include at ./boot.jl:328 [inlined]
 [3] include_relative(::Module, ::String) at ./loading.jl:1105
 [4] include(::Module, ::String) at ./Base.jl:31
 [5] top-level scope at none:2
 [6] eval at ./boot.jl:330 [inlined]
 [7] eval(::Expr) at ./client.jl:425
 [8] top-level scope at ./none:3
in expression starting at /home/tim/.julia/dev/AlgorithmicTaylorBounds/src/AlgorithmicTaylorBounds.jl:11
Precompiling ProfileView
[ Info: Precompiling ProfileView [c46f51b8-102a-5cf2-8d2c-8597cb0e0da7]
ERROR: LoadError: UndefVarError: Node not defined
Stacktrace:
 [1] top-level scope at /home/tim/.julia/dev/ProfileView/src/ProfileView.jl:217
 [2] include at ./boot.jl:328 [inlined]
 [3] include_relative(::Module, ::String) at ./loading.jl:1105
 [4] include(::Module, ::String) at ./Base.jl:31
 [5] top-level scope at none:2
 [6] eval at ./boot.jl:330 [inlined]
 [7] eval(::Expr) at ./client.jl:425
 [8] top-level scope at ./none:3
in expression starting at /home/tim/.julia/dev/ProfileView/src/ProfileView.jl:217
Precompiling ProfileAnalysis
[ Info: Precompiling ProfileAnalysis [3170ab74-e52f-4abd-bac1-4424d52bd0b4]

julia> using ColorTypes

julia> using Images
[ Info: Precompiling Images [916415d5-f1e6-5110-898d-aaa5f9f070e0]

[KristofferC]

The only thing that changed in 1.4 with precompile is AFAIK https://github.com/JuliaLang/julia/commit/962634d263b491eb6390536d07bb8dce9a4a0639#diff-a03d5ce5729a81495000698e643fce27.

I don't really see how that could be related though.

I guess someone would have to plow through the loading code and figure out why compilecache gets called even when we find a non stale cache file:

https://github.com/JuliaLang/Pkg.jl/blob/4a74692277c462c3d4dd655ec431373284a48a92/src/API.jl#L709-L728

I still don't have a reliable way to trigger this locally.

[KristofferC]

Can you try:

pkg = Base.PkgId(Base.UUID("916415d5-f1e6-5110-898d-aaa5f9f070e0"), "Images")
path = Base.locate_package(pkg)
m = Base._require_search_from_serialized(pkg, path)

where you think Images should be precompiled but it isn't.

[KristofferC]

Also please run with ENV["JULIA_DEBUG"] = "Base" or ENV["JULIA_DEBUG"] = "loading" (not sure of the exact way to get loading to spit out debug messages).

[timholy]

$ julia-master
               _
   _       _ _(_)_     |  Documentation: https://docs.julialang.org
  (_)     | (_) (_)    |
   _ _   _| |_  __ _   |  Type "?" for help, "]?" for Pkg help.
  | | | | | | |/ _` |  |
  | | |_| | | | (_| |  |  Version 1.5.0-DEV.11 (2020-01-04)
 _/ |\__'_|_|_|\__'_|  |  Commit 18783434e9* (3 days old master)
|__/                   |

julia> ENV["JULIA_DEBUG"] = "Base"
"Base"

shell> touch ~/.julia/dev/ColorTypes/src/ColorTypes.jl

(@v1.5) pkg> precompile
Precompiling project...
┌ Debug: Rejecting stale cache file /home/tim/.julia/compiled/v1.5/ColorTypes/db21U_Zgv4n.ji (mtime 1.5784011567977707e9) because file /home/tim/.julia/dev/ColorTypes/src/ColorTypes.jl (mtime 1.5784013944951787e9) has changed
└ @ Base loading.jl:1461
[ Info: Precompiling ColorTypes [3da002f7-5984-5a60-b8a6-cbb66c0b333f]

(@v1.5) pkg> precompile
Precompiling project...

julia> pkg = Base.PkgId(Base.UUID("916415d5-f1e6-5110-898d-aaa5f9f070e0"), "Images")
Images [916415d5-f1e6-5110-898d-aaa5f9f070e0]

julia> path = Base.locate_package(pkg)
"/home/tim/.julia/packages/Images/En3aE/src/Images.jl"

julia> m = Base._require_search_from_serialized(pkg, path)
┌ Debug: Required dependency ColorTypes [3da002f7-5984-5a60-b8a6-cbb66c0b333f] failed to load from cache file for /home/tim/.julia/dev/ColorTypes/src/ColorTypes.jl.
└ @ Base loading.jl:772
┌ Debug: Required dependency Graphics [a2bd30eb-e257-5431-a919-1863eab51364] failed to load from cache file for /home/tim/.julia/packages/Graphics/hXu8y/src/Graphics.jl.
└ @ Base loading.jl:772
true

(@v1.5) pkg> precompile
Precompiling project...
┌ Debug: Rejecting cache file /home/tim/.julia/compiled/v1.5/ImageMagick/0LbNX_Zgv4n.ji because module ColorTypes [3da002f7-5984-5a60-b8a6-cbb66c0b333f] is already loaded and incompatible.
└ @ Base loading.jl:1414
[ Info: Precompiling ImageMagick [6218d12a-5da1-5696-b52f-db25d2ecc6d1]
┌ Debug: Required dependency ColorTypes [3da002f7-5984-5a60-b8a6-cbb66c0b333f] failed to load from cache file for /home/tim/.julia/dev/ColorTypes/src/ColorTypes.jl.
└ @ Base loading.jl:772
┌ Debug: Required dependency Graphics [a2bd30eb-e257-5431-a919-1863eab51364] failed to load from cache file for /home/tim/.julia/packages/Graphics/hXu8y/src/Graphics.jl.
└ @ Base loading.jl:772
┌ Debug: Precompiling ImageCore [a09fc81d-aa75-5fe9-8630-4744c3626534]
└ @ Base loading.jl:1260
┌ Debug: Required dependency ColorTypes [3da002f7-5984-5a60-b8a6-cbb66c0b333f] failed to load from cache file for /home/tim/.julia/dev/ColorTypes/src/ColorTypes.jl.
└ @ Base loading.jl:772
┌ Debug: Precompiling Colors [5ae59095-9a9b-59fe-a467-6f913c188581]
└ @ Base loading.jl:1260
┌ Debug: Rejecting cache file /home/tim/.julia/compiled/v1.5/Graphics/DwlUf_Zgv4n.ji because module ColorTypes [3da002f7-5984-5a60-b8a6-cbb66c0b333f] is already loaded and incompatible.
└ @ Base loading.jl:1414
┌ Debug: Precompiling Graphics [a2bd30eb-e257-5431-a919-1863eab51364]
└ @ Base loading.jl:1260
┌ Debug: Rejecting cache file /home/tim/.julia/compiled/v1.5/Images/H8Vxc_Zgv4n.ji because module ColorTypes [3da002f7-5984-5a60-b8a6-cbb66c0b333f] is already loaded and incompatible.
└ @ Base loading.jl:1414
[ Info: Precompiling Images [916415d5-f1e6-5110-898d-aaa5f9f070e0]
┌ Debug: Rejecting cache file /home/tim/.julia/compiled/v1.5/ColorVectorSpace/7uC4N_Zgv4n.ji because module Colors [5ae59095-9a9b-59fe-a467-6f913c188581] is already loaded and incompatible.
└ @ Base loading.jl:1414
┌ Debug: Precompiling ColorVectorSpace [c3611d14-8923-5661-9e6a-0046d554d3a4]
└ @ Base loading.jl:1260
┌ Debug: Rejecting cache file /home/tim/.julia/compiled/v1.5/ImageTransformations/Pfac4_Zgv4n.ji because module Graphics [a2bd30eb-e257-5431-a919-1863eab51364] is already loaded and incompatible.
└ @ Base loading.jl:1414
┌ Debug: Precompiling ImageTransformations [02fcd773-0e25-5acc-982a-7f6622650795]
└ @ Base loading.jl:1260
┌ Debug: Rejecting cache file /home/tim/.julia/compiled/v1.5/ImageAxes/5b2UE_Zgv4n.ji because module Graphics [a2bd30eb-e257-5431-a919-1863eab51364] is already loaded and incompatible.
└ @ Base loading.jl:1414
┌ Debug: Precompiling ImageAxes [2803e5a7-5153-5ecf-9a86-9b4c37f5f5ac]
└ @ Base loading.jl:1260
┌ Debug: Rejecting cache file /home/tim/.julia/compiled/v1.5/ImageMetadata/dSTEq_Zgv4n.ji because module Graphics [a2bd30eb-e257-5431-a919-1863eab51364] is already loaded and incompatible.
└ @ Base loading.jl:1414
┌ Debug: Precompiling ImageMetadata [bc367c6b-8a6b-528e-b4bd-a4b897500b49]
└ @ Base loading.jl:1260
┌ Debug: Rejecting cache file /home/tim/.julia/compiled/v1.5/ImageFiltering/MN5uU_Zgv4n.ji because module Graphics [a2bd30eb-e257-5431-a919-1863eab51364] is already loaded and incompatible.
└ @ Base loading.jl:1414
┌ Debug: Precompiling ImageFiltering [6a3955dd-da59-5b1f-98d4-e7296123deb5]
└ @ Base loading.jl:1260
┌ Debug: Rejecting cache file /home/tim/.julia/compiled/v1.5/ImageMorphology/TCrac_Zgv4n.ji because module Graphics [a2bd30eb-e257-5431-a919-1863eab51364] is already loaded and incompatible.
└ @ Base loading.jl:1414
┌ Debug: Precompiling ImageMorphology [787d08f9-d448-5407-9aad-5290dd7ab264]
└ @ Base loading.jl:1260
┌ Debug: Rejecting cache file /home/tim/.julia/compiled/v1.5/ImageDistances/lg0Xg_Zgv4n.ji because module Graphics [a2bd30eb-e257-5431-a919-1863eab51364] is already loaded and incompatible.
└ @ Base loading.jl:1414
┌ Debug: Precompiling ImageDistances [51556ac3-7006-55f5-8cb3-34580c88182d]
└ @ Base loading.jl:1260
┌ Debug: Rejecting cache file /home/tim/.julia/compiled/v1.5/ImageShow/76qZM_Zgv4n.ji because module Graphics [a2bd30eb-e257-5431-a919-1863eab51364] is already loaded and incompatible.
└ @ Base loading.jl:1414
┌ Debug: Precompiling ImageShow [4e3cecfd-b093-5904-9786-8bbb286a6a31]
└ @ Base loading.jl:1260
┌ Debug: Rejecting cache file /home/tim/.julia/compiled/v1.5/PyPlot/oatAj_Zgv4n.ji because module ColorTypes [3da002f7-5984-5a60-b8a6-cbb66c0b333f] is already loaded and incompatible.
└ @ Base loading.jl:1414
[ Info: Precompiling PyPlot [d330b81b-6aea-500a-939a-2ce795aea3ee]
┌ Debug: Rejecting cache file /home/tim/.julia/compiled/v1.5/ImagineFormat/CrjpI_Zgv4n.ji because module ColorTypes [3da002f7-5984-5a60-b8a6-cbb66c0b333f] is already loaded and incompatible.
└ @ Base loading.jl:1414
[ Info: Precompiling ImagineFormat [4bab44a2-5ff2-5a6b-8e10-825fb9ac126a]
┌ Debug: Rejecting cache file /home/tim/.julia/compiled/v1.5/ProfileView/GJsyc_Zgv4n.ji because module ColorTypes [3da002f7-5984-5a60-b8a6-cbb66c0b333f] is already loaded and incompatible.
└ @ Base loading.jl:1414
[ Info: Precompiling ProfileView [c46f51b8-102a-5cf2-8d2c-8597cb0e0da7]

[bjarthur]

the JIT compilation lag is such a pain in julia that it'd be nice to see this issue prioritized

[StefanKarpinski]

the JIT compilation lag is such a pain in julia that it'd be nice to see this issue prioritized

It is literally the only thing the compiler team has been working on for the past four months and the top priority for the past year and more. Moreover latency has improved by more than a factor of 2x in that time.

[KristofferC]

the JIT compilation lag is such a pain in julia that it'd be nice to see this issue prioritized

This issue has nothing to do with this.

[bjarthur]

sorry, i should've been more specific that i was referring to this precompile issue that timholy filed. i know you guys have been working hard on the compiler and i'm looking forward to 1.5!

as it stands now i frequently have to precompile twice, and then suffer through the JIT lag. fixing the precompile issue would help a lot, and be easier i would think than the compiler.

[IanButterworth]

Might have a fix over in https://github.com/JuliaLang/Pkg.jl/pull/2018#issuecomment-691766768

[IanButterworth]

It does seem to me that #2018 is a fix for this issue.

In that PR, Pkg.precompile triggers dependents after a dependent is recompiled within the precompile session.

I thought there was an edge case if a dep would be recompiled during code load then a Pkg.precompile was tried again, as illustrated below, but it seems to not be a problem.
The 2nd Pkg.precompile here catches that Images needs recompiling because ColorTypes was recompiled via code load into Main, so the heuristic in Base.stale_cachefile works as it should

pkg> add Images
pkg> dev ColorTypes
pkg> precompile            # all good here
[ Info: Precompiling ColorTypes...
[ Info: Precompiling Images...

# user edits ColorTypes

julia> using ColorTypes
[ Info: Precompiling ColorTypes...

pkg> precompile
[ Info: Precompiling Images...

julia> using Images

[IanButterworth]

Although, there is this case which fails

pkg> precompile
[ Info: Precompiling ColorTypes...
[ Info: Precompiling Images...

# user edits ColorTypes

julia> using ColorTypes
[ Info: Precompiling ColorTypes...

julia> exit()

$ julia

pkg> precompile

julia> using Images
[ Info: Precompiling Images...

[tkf]

there is this case which fails

Do you mean even after #2018?

[IanButterworth]

Indeed. If there's a session restart after a dep has been individually precompiled via code load, Pkg.precompile fails to detect that the dependents need recompiling due to this bug.

The fix only works if the depdendency was precompiled in the Pkg.precompile() session, or is loaded into Main

[tkf]

Hmm... interesting. I thought #2018 is doing everything right.

[IanButterworth]

I think things are still much better than they were.

What's needed is to make stale_cachefile be able to detect the edge case where a package has been recompiled, but isn't in Main.
I thought forcing skip_timecheck = false might work here, but it doesn't
https://github.com/JuliaLang/julia/blob/2bd31a0b2ac23165d3dcda569e04bdd32283c3bd/base/loading.jl#L1474

The only thing I thought of is if Pkg.precompile loaded packages into Main as it processes them.. but that seems like it would be unwanted behavior

[IanButterworth]

This issue is largely fixed with the new Pkg.precompile, which does its own tracking of whether dependencies have been updated, without relying on stale_cachefile.

There is an edge case that remains though, which I've opened as a separate issue https://github.com/JuliaLang/Pkg.jl/issues/2361