compile time of using ApproxFun is almost 10x slower

[dlfivefifty]

using ApproxFun is significantly slower in 0.6. This is with ApproxFun 0.6, which has already been precompiled in both cases:

julia> @time using ApproxFun  # ApproxFun 0.6 on Julia 0.5.1
  1.700994 seconds (2.66 M allocations: 113.410 MB, 7.48% gc time) 

julia> versioninfo()
Julia Version 0.5.1
Commit 6445c82 (2017-03-05 13:25 UTC)
Platform Info:
  OS: macOS (x86_64-apple-darwin16.4.0)
  CPU: Intel(R) Core(TM) i7-3820QM CPU @ 2.70GHz
  WORD_SIZE: 64
  BLAS: libgfortblas
  LAPACK: liblapack
  LIBM: libopenlibm
  LLVM: libLLVM-3.7.1 (ORCJIT, ivybridge)

julia> @time using ApproxFun # ApproxFun 0.6 on Julia 0.6.0-pre
 14.575842 seconds (13.43 M allocations: 633.749 MiB, 2.66% gc time)

julia> versioninfo()
Julia Version 0.6.0-pre.alpha.263
Commit 55f4417 (2017-03-27 00:01 UTC)
Platform Info:
  OS: macOS (x86_64-apple-darwin16.4.0)
  CPU: Intel(R) Core(TM) i7-3820QM CPU @ 2.70GHz
  WORD_SIZE: 64
  BLAS: libgfortblas
  LAPACK: liblapack
  LIBM: libopenlibm
  LLVM: libLLVM-3.9.1 (ORCJIT, ivybridge)

See also discourse discussion: https://discourse.julialang.org/t/is-compile-time-significantly-slower-in-0-6/2764

[JeffBezanson]

Could be related to #20793 (comment)
We are seeing various compile time regressions.

[JeffBezanson]

Adding to milestone as a reminder to try to address compile time regressions before 0.6.0. If ApproxFun turns out to be a special case and doesn't get fixed, we can keep this open even though we might move the issue to another milestone.

[jpsamaroo]

This can also be seen with OpenCL master between 0.5 and 0.6:

julia> @time using OpenCL
  2.932006 seconds (943.10 k allocations: 41.470 MB, 1.28% gc time)

julia> versioninfo()
Julia Version 0.5.1-pre+2
Commit f0d40ec (2016-09-20 03:34 UTC)
Platform Info:
  System: Linux (x86_64-linux-gnu)
  CPU: Intel(R) Xeon(R) CPU           L5640  @ 2.27GHz
  WORD_SIZE: 64
  BLAS: libopenblas (USE64BITINT DYNAMIC_ARCH NO_AFFINITY Nehalem)
  LAPACK: libopenblas64_
  LIBM: libopenlibm
  LLVM: libLLVM-3.7.1 (ORCJIT, westmere)

julia> @time using OpenCL
 14.768079 seconds (11.06 M allocations: 513.404 MiB, 4.49% gc time)

julia> versioninfo()
Julia Version 0.6.0-pre.alpha.0
Commit 29bc2ac (2017-02-28 13:15 UTC)
Platform Info:
  OS: Linux (x86_64-linux-gnu)
  CPU: Intel(R) Xeon(R) CPU           L5640  @ 2.27GHz
  WORD_SIZE: 64
  BLAS: libopenblas (USE64BITINT DYNAMIC_ARCH NO_AFFINITY Nehalem)
  LAPACK: libopenblas64_
  LIBM: libopenlibm
  LLVM: libLLVM-3.9.1 (ORCJIT, westmere)

The 10x explosion in allocations between 0.5 and 0.6 is absolutely stellar as well (as can be seen above).

[vtjnash]

It looks like this one is almost entirely due to the type system (specifically jl_has_bound_typevars / has_free_typevars appear to account for about half of the time)

[JeffBezanson]

Any sense of where those calls are coming from?

[JeffBezanson]

Update: this is time spent inserting methods, which tests specificity and computes intersections to check for ambiguities.

[ViralBShah]

ApproxFuns always shakes out some interesting bugs in every Julia Release. We should make its test and perf suites mandatory for every release. :-)

[dlfivefifty]

Probably the quality of the code would need to be improved for that... but I suppose if the quality of the code was improved, it wouldn't be triggering so many bugs 😉

[JeffBezanson]

The time should now be within a factor of 2 of the time on 0.5.

[jpsamaroo]

Using Julia master pulled about 15 minutes ago, OpenCL master loads in 4.48 seconds, while Julia 0.5.1-pre+2 loads it in 2.69 seconds. 😄

[JeffBezanson]

We will try to keep improving this, but it doesn't need to block the release any more.

[dlfivefifty]

Yes I'm also seeing it now only 2x slower, thank! Should we close this issue, or rename it "compile time of using ApproxFun is over 2x slower"?

[timholy]

I'm seeing a big slowdown in Images. If you first say using Images on both 0.5 and 0.6 to make sure all dependencies are precompiled, and then execute

julia> run(`touch $(Pkg.dir("Images","src","Images.jl"))`)

julia> @elapsed using Images
INFO: Recompiling stale cache file /home/tim/.julia/lib/v0.6/Images.ji for module Images.
37.379356289

whereas on 0.5 it's around 8 seconds.

[KristofferC]

Some results from my own packages (results in seconds):

Tensors.jl

v0.5

Precompile: 1.75
Load when precompiled: 0.18

v0.6

Precompile: 5.2
Load when precompiled: 1.07

JuAFEM.jl

v0.5:

Precompile: 2.20
Load when precompiled: 0.21

v0.6

Precompile 6.14
Load when precompiled: 1.1

Tokenize.jl

v0.5:

Precompile: 1.5
Load when precompiled: 0.01

v0.6:

Precompile: 1.3
Load when precompiled: 0.06

NearestNeighbors.jl:

v0.5

Precompile: 1.18
Load when precompiled: 0.1

v0.6:

Precompile: 2.62
Load when precompiled: 0.2s

[timholy]

I've boiled down at least a part of the Images problem:

julia> @time using CoordinateTransformations
  0.801925 seconds (915.97 k allocations: 49.765 MiB, 1.63% gc time)

Then hit a key, TAB, and another key. Watch how long it takes the second key to appear (presumably #265-related?). Interestingly,

julia> @time using Compat, Rotations, StaticArrays
  0.338590 seconds (574.33 k allocations: 32.500 MiB, 2.29% gc time)

(the three other modules loaded by CoordinateTransformations) does not trigger this problem.

I'm on the 0.4.1 release of CoordinateTransformations, in case it matters.

[KristofferC]

Perhaps more of #20780 going on?

[timholy]

Continued in #21449

[KristofferC]

Don't think we need two ApproxFun compilation time issues: #28823.