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 JuliaDebug/JuliaInterpreter.jl#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 JuliaLang/julia@962634d#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:

Pkg.jl/src/API.jl

Lines 709 to 728 in 4a74692

	paths = Base.find_all_in_cache_path(pkg)
	sourcepath = Base.locate_package(pkg)
	sourcepath === nothing && continue
	# Heuristic for when precompilation is disabled
	occursin(r"\b__precompile__\(\s*false\s*\)", read(sourcepath, String)) && continue
	stale = true
	for path_to_try in paths::Vector{String}
	staledeps = Base.stale_cachefile(sourcepath, path_to_try)
	staledeps === true && continue
	# TODO: else, this returns a list of packages that may be loaded to make this valid (the topological list)
	stale = false
	break
	end
	if stale
	try
	Base.compilecache(pkg, sourcepath)
	catch
	end
	end
	end

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 #2018 (comment)

[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...