package precompile is slow

[JeffBezanson]

Precompiling DataFrames takes ~47 seconds:

jeff@gurren:~/src/julia$ time ./julia -e 'using DataFrames'
INFO: Recompiling stale cache file /home/jeff/.julia/lib/v0.5/DataFrames.ji for module DataFrames.
INFO: Recompiling stale cache file /home/jeff/.julia/lib/v0.5/Reexport.ji for module Reexport.
INFO: Recompiling stale cache file /home/jeff/.julia/lib/v0.5/StatsBase.ji for module StatsBase.
INFO: Recompiling stale cache file /home/jeff/.julia/lib/v0.5/ArrayViews.ji for module ArrayViews.
WARNING: Method definition (::Type{ArrayViews.UnsafeContiguousView})(Ptr{#T<:Any}, Int64, NTuple{#N<:Any, Int64}) in module ArrayViews at /home/jeff/.julia/v0.5/ArrayViews/src/arrviews.jl:18 overwritten at /home/jeff/.julia/v0.5/ArrayViews/src/arrviews.jl:26.
INFO: Recompiling stale cache file /home/jeff/.julia/lib/v0.5/StatsFuns.ji for module StatsFuns.
INFO: Recompiling stale cache file /home/jeff/.julia/lib/v0.5/DataArrays.ji for module DataArrays.
WARNING: Method definition (::Type{DataArrays.FastPerm})(#O<:Base.Order.Ordering, #V<:AbstractArray{T<:Any, 1}) in module DataArrays at /home/jeff/.julia/v0.5/DataArrays/src/pooleddataarray.jl:598 overwritten at /home/jeff/.julia/v0.5/DataArrays/src/pooleddataarray.jl:601.
WARNING: Method definition PooledDataVecs(DataArrays.PooledDataArray{#S<:Any, #R<:Integer, #N<:Any}, AbstractArray{#S<:Any, #N<:Any}) in module DataArrays at /home/jeff/.julia/v0.5/DataArrays/src/pooleddataarray.jl:645 overwritten at /home/jeff/.julia/v0.5/DataArrays/src/pooleddataarray.jl:650.
WARNING: Method definition map!(Union{Function, DataType}, DataArrays.DataArray, Base.Range) in module DataArrays at /home/jeff/.julia/v0.5/DataArrays/src/broadcast.jl:211 overwritten at /home/jeff/.julia/v0.5/DataArrays/src/broadcast.jl:211.
WARNING: Method definition map!(Union{Function, DataType}, DataArrays.PooledDataArray, Base.Range) in module DataArrays at /home/jeff/.julia/v0.5/DataArrays/src/broadcast.jl:211 overwritten at /home/jeff/.julia/v0.5/DataArrays/src/broadcast.jl:211.
WARNING: Method definition rep(AbstractArray{T<:Any, 1}) in module DataArrays at /home/jeff/.julia/v0.5/DataArrays/src/extras.jl:83 overwritten at /home/jeff/.julia/v0.5/DataArrays/src/extras.jl:98.
INFO: Recompiling stale cache file /home/jeff/.julia/lib/v0.5/GZip.ji for module GZip.
WARNING: Base.FileOffset is deprecated, use Int64 instead.
  likely near /home/jeff/.julia/v0.5/GZip/src/zlib_h.jl:86
WARNING: Base.FileOffset is deprecated, use Int64 instead.
  likely near /home/jeff/.julia/v0.5/GZip/src/zlib_h.jl:88
WARNING: Base.FileOffset is deprecated, use Int64 instead.
  likely near /home/jeff/.julia/v0.5/GZip/src/zlib_h.jl:88
WARNING: New definition 
    write(GZip.GZipStream, Array{#T<:Any, N<:Any}) at /home/jeff/.julia/v0.5/GZip/src/GZip.jl:456
is ambiguous with: 
    write(Base.IO, Array{UInt8, N<:Any}) at io.jl:154.
To fix, define 
    write(GZip.GZipStream, Array{UInt8, N<:Any})
before the new definition.
WARNING: New definition 
    write(GZip.GZipStream, Array{#T<:Any, N<:Any}) at /home/jeff/.julia/v0.5/GZip/src/GZip.jl:456
is ambiguous with: 
    write(Base.IO, Array{UInt8, N<:Any}) at io.jl:154.
To fix, define 
    write(GZip.GZipStream, Array{UInt8, N<:Any})
before the new definition.
INFO: Recompiling stale cache file /home/jeff/.julia/lib/v0.5/SortingAlgorithms.ji for module SortingAlgorithms.
INFO: Recompiling stale cache file /home/jeff/.julia/lib/v0.5/Docile.ji for module Docile.
WARNING: Base.LambdaStaticData is deprecated, use LambdaInfo instead.
  likely near /home/jeff/.julia/v0.5/Docile/src/Utilities.jl:122
WARNING: Method definition unstack(DataFrames.AbstractDataFrame, Int64, Int64) in module DataFrames at /home/jeff/.julia/v0.5/DataFrames/src/abstractdataframe/reshape.jl:201 overwritten at /home/jeff/.julia/v0.5/DataFrames/src/abstractdataframe/reshape.jl:216.
WARNING: New definition 
    write(GZip.GZipStream, Array{#T<:Any, N<:Any}) at /home/jeff/.julia/v0.5/GZip/src/GZip.jl:456
is ambiguous with: 
    write(Base.IO, Array{UInt8, N<:Any}) at io.jl:154.
To fix, define 
    write(GZip.GZipStream, Array{UInt8, N<:Any})
before the new definition.

real    0m47.418s
user    0m47.248s
sys 0m6.021s

However if I just load it without precompilation, it takes only ~12 seconds:

jeff@gurren:~/src/julia$ time ./julia --compilecache=no -e 'using DataFrames'
WARNING: Method definition get_splatinfo(Expr, Symbol) in module CompatCartesian at /home/jeff/.julia/v0.5/Compat/src/ngenerate.jl:66 overwritten at /home/jeff/.julia/v0.5/Compat/src/ngenerate.jl:123.
WARNING: Method definition isfuncexpr(Expr) in module CompatCartesian at /home/jeff/.julia/v0.5/Compat/src/ngenerate.jl:106 overwritten at /home/jeff/.julia/v0.5/Compat/src/ngenerate.jl:140.
WARNING: Method definition isfuncexpr(Any) in module CompatCartesian at /home/jeff/.julia/v0.5/Compat/src/ngenerate.jl:108 overwritten at /home/jeff/.julia/v0.5/Compat/src/ngenerate.jl:142.
WARNING: Method definition (::Type{ArrayViews.UnsafeContiguousView})(Ptr{#T<:Any}, Int64, NTuple{#N<:Any, Int64}) in module ArrayViews at /home/jeff/.julia/v0.5/ArrayViews/src/arrviews.jl:18 overwritten at /home/jeff/.julia/v0.5/ArrayViews/src/arrviews.jl:26.
WARNING: Method definition (::Type{DataArrays.FastPerm})(#O<:Base.Order.Ordering, #V<:AbstractArray{T<:Any, 1}) in module DataArrays at /home/jeff/.julia/v0.5/DataArrays/src/pooleddataarray.jl:598 overwritten at /home/jeff/.julia/v0.5/DataArrays/src/pooleddataarray.jl:601.
WARNING: Method definition PooledDataVecs(DataArrays.PooledDataArray{#S<:Any, #R<:Integer, #N<:Any}, AbstractArray{#S<:Any, #N<:Any}) in module DataArrays at /home/jeff/.julia/v0.5/DataArrays/src/pooleddataarray.jl:645 overwritten at /home/jeff/.julia/v0.5/DataArrays/src/pooleddataarray.jl:650.

WARNING: deprecated syntax "call(f::MapReduceDim2ArgHelperFun, ...)".
Use "(f::MapReduceDim2ArgHelperFun)(...)" instead.

WARNING: deprecated syntax "call(f::Abs2MinusFun, ...)".
Use "(f::Abs2MinusFun)(...)" instead.
WARNING: Method definition map!(Union{Function, DataType}, DataArrays.DataArray, Base.Range) in module DataArrays at /home/jeff/.julia/v0.5/DataArrays/src/broadcast.jl:211 overwritten at /home/jeff/.julia/v0.5/DataArrays/src/broadcast.jl:211.
WARNING: Method definition map!(Union{Function, DataType}, DataArrays.PooledDataArray, Base.Range) in module DataArrays at /home/jeff/.julia/v0.5/DataArrays/src/broadcast.jl:211 overwritten at /home/jeff/.julia/v0.5/DataArrays/src/broadcast.jl:211.
WARNING: Method definition rep(AbstractArray{T<:Any, 1}) in module DataArrays at /home/jeff/.julia/v0.5/DataArrays/src/extras.jl:83 overwritten at /home/jeff/.julia/v0.5/DataArrays/src/extras.jl:98.
WARNING: Base.FileOffset is deprecated, use Int64 instead.
  likely near /home/jeff/.julia/v0.5/GZip/src/zlib_h.jl:86
WARNING: Base.FileOffset is deprecated, use Int64 instead.
  likely near /home/jeff/.julia/v0.5/GZip/src/zlib_h.jl:88
WARNING: Base.FileOffset is deprecated, use Int64 instead.
  likely near /home/jeff/.julia/v0.5/GZip/src/zlib_h.jl:88
WARNING: New definition 
    write(GZip.GZipStream, Array{#T<:Any, N<:Any}) at /home/jeff/.julia/v0.5/GZip/src/GZip.jl:456
is ambiguous with: 
    write(Base.IO, Array{UInt8, N<:Any}) at io.jl:154.
To fix, define 
    write(GZip.GZipStream, Array{UInt8, N<:Any})
before the new definition.
WARNING: Base.LambdaStaticData is deprecated, use LambdaInfo instead.
  likely near /home/jeff/.julia/v0.5/Docile/src/Utilities.jl:122
WARNING: Method definition unstack(DataFrames.AbstractDataFrame, Int64, Int64) in module DataFrames at /home/jeff/.julia/v0.5/DataFrames/src/abstractdataframe/reshape.jl:201 overwritten at /home/jeff/.julia/v0.5/DataFrames/src/abstractdataframe/reshape.jl:216.

real    0m11.925s
user    0m11.466s
sys 0m0.792s

[vtjnash]

this probably due to some code that DataFrames is conditionally including when it detects precompile mode

[JeffBezanson]

Really?

[stevengj]

If you have a dependency chain of N stale modules (module n depends on module n–1 for n=2…N), loading them without compilation is O(N), but precompiling them currently seems to be O(N^2): my understanding is that N precompilation processes are launched, and the n-th process needs to load (from cache) the previous n-1 modules, so that O(N^2) modules are reconstituted from the cache overall.

Maybe we can do something like what Pkg.build does: require could launch only a single process to precompile all the modules in a chain of stale dependencies. But this would involve some changes in how --output-ji worked?

[vtjnash]

I think part of the problem here is warmup cost. Precompilation assumes that will be very low (because it shouldn't require any actual work), but master is much slower (3x) than v0.4 was. Since startup costs are applied n^2 times, this could quickly become significant:

  | | |_| | | | (_| |  |  Version 0.4.3 (2016-01-12 21:37 UTC)
 _/ |\__'_|_|_|\__'_|  |  Official http://julialang.org/ release
|__/                   |  x86_64-apple-darwin13.4.0

julia> @time @eval using Compat
  0.346696 seconds (167.22 k allocations: 8.441 MB, 7.86% gc time)

julia> @time @eval using FixedPointNumbers
  0.031285 seconds (50.32 k allocations: 1.736 MB)

  | | |_| | | | (_| |  |  Version 0.5.0-dev+3366 (2016-04-01 18:54 UTC)
 _/ |\__'_|_|_|\__'_|  |  master/eb05d6b* (fork: 1 commits, 3 days)
|__/                   |  x86_64-apple-darwin15.3.0

julia> @time @eval using Compat
  1.040900 seconds (229.41 k allocations: 10.556 MB)

julia> @time @eval using FixedPointNumbers
  0.098878 seconds (56.40 k allocations: 2.322 MB)

[JeffBezanson]

I do see a bit of improvement; precompiling DataFrames now takes 38 sec instead of 47, but this is still far slower than the 11 seconds taken to load it without precompiling.