Julia: 1.2: 5x using time slow down

[dlfivefifty]

Julia v1.2-rc1:

julia> @time using BandedMatrices
 35.992443 seconds (28.97 M allocations: 1.977 GiB, 0.80% gc time)

Julia v1.1:

julia> @time using BandedMatrices
  6.413619 seconds (30.84 M allocations: 2.027 GiB, 6.87% gc time)

[JeffBezanson]

Is this using a fixed set of package versions on both 1.1 and 1.2? I know that might not be possible, but checking just in case.

[JeffBezanson]

Some observations: Seems to be ok on master, so this could potentially be bisected. Also all the time is in method insertion / check_ambiguous.

[dlfivefifty]

I tried it on a fresh environment and it's still there, both in precompile time and using time. On Julia v1.2:

julia> @time using BandedMatrices
[ Info: Recompiling stale cache file /Users/solver/.julia/compiled/v1.2/BandedMatrices/OxlqV.ji for BandedMatrices [aae01518-5342-5314-be14-df237901396f]
 77.619873 seconds (31.16 M allocations: 2.201 GiB, 0.67% gc time)

julia> 
[solver-mbook:~/Projects/julia-1.2] solver% ./julia
ArgumentError("Package SpecialFunctions not found in current path:\n- Run `import Pkg; Pkg.add(\"SpecialFunctions\")` to install the SpecialFunctions package.\n") thrown during startup
               _
   _       _ _(_)_     |  Documentation: https://docs.julialang.org
  (_)     | (_) (_)    |
   _ _   _| |_  __ _   |  Type "?" for help, "]?" for Pkg help.
  | | | | | | |/ _` |  |
  | | |_| | | | (_| |  |  Version 1.2.0-rc1.0 (2019-05-30)
 _/ |\__'_|_|_|\__'_|  |  
|__/                   |

julia> @time using BandedMatrices
 35.583281 seconds (30.82 M allocations: 2.184 GiB, 1.48% gc time)

and on 1.1:

julia> @time using BandedMatrices
[ Info: Recompiling stale cache file /Users/solver/.julia/compiled/v1.1/BandedMatrices/OxlqV.ji for BandedMatrices [aae01518-5342-5314-be14-df237901396f]
 30.717259 seconds (31.74 M allocations: 2.070 GiB, 1.34% gc time)

julia> 
[solver-mbook:~] solver% julia
ArgumentError("Package SpecialFunctions not found in current path:\n- Run `import Pkg; Pkg.add(\"SpecialFunctions\")` to install the SpecialFunctions package.\n") thrown during startup
               _
   _       _ _(_)_     |  Documentation: https://docs.julialang.org
  (_)     | (_) (_)    |
   _ _   _| |_  __ _   |  Type "?" for help, "]?" for Pkg help.
  | | | | | | |/ _` |  |
  | | |_| | | | (_| |  |  Version 1.1.0 (2019-01-21)
 _/ |\__'_|_|_|\__'_|  |  
|__/                   |

julia> @time using BandedMatrices
  7.231549 seconds (30.56 M allocations: 2.015 GiB, 7.46% gc time)

The package versions are:

[aae01518] + BandedMatrices v0.9.1
  [00ebfdb7] + CSTParser v0.5.2
  [34da2185] + Compat v2.1.0
  [864edb3b] + DataStructures v0.15.0
  [1a297f60] + FillArrays v0.6.3
  [5078a376] + LazyArrays v0.8.1
  [1914dd2f] + MacroTools v0.5.0
  [a3b82374] + MatrixFactorizations v0.0.4
  [bac558e1] + OrderedCollections v1.1.0
  [90137ffa] + StaticArrays v0.10.3
  [0796e94c] + Tokenize v0.5.3
  [2a0f44e3] + Base64 
  [ade2ca70] + Dates 
  [8bb1440f] + DelimitedFiles 
  [8ba89e20] + Distributed 
  [b77e0a4c] + InteractiveUtils 
  [76f85450] + LibGit2 
  [8f399da3] + Libdl 
  [37e2e46d] + LinearAlgebra 
  [56ddb016] + Logging 
  [d6f4376e] + Markdown 
  [a63ad114] + Mmap 
  [44cfe95a] + Pkg 
  [de0858da] + Printf 
  [3fa0cd96] + REPL 
  [9a3f8284] + Random 
  [ea8e919c] + SHA 
  [9e88b42a] + Serialization 
  [1a1011a3] + SharedArrays 
  [6462fe0b] + Sockets 
  [2f01184e] + SparseArrays 
  [10745b16] + Statistics 
  [8dfed614] + Test 
  [cf7118a7] + UUIDs 
  [4ec0a83e] + Unicode 

[dlfivefifty]

Master is the best 🎉!

julia> @time using BandedMatrices
[ Info: Precompiling BandedMatrices [aae01518-5342-5314-be14-df237901396f]
WARNING: could not import LinearAlgebra._apply_ipiv! into BandedMatrices
 25.883376 seconds (19.21 M allocations: 1.431 GiB, 1.27% gc time)

julia> 
[solver-mbook:~/Projects/julia-master] solver% ./julia
ArgumentError("Package SpecialFunctions not found in current path:\n- Run `import Pkg; Pkg.add(\"SpecialFunctions\")` to install the SpecialFunctions package.\n") thrown during startup
               _
   _       _ _(_)_     |  Documentation: https://docs.julialang.org
  (_)     | (_) (_)    |
   _ _   _| |_  __ _   |  Type "?" for help, "]?" for Pkg help.
  | | | | | | |/ _` |  |
  | | |_| | | | (_| |  |  Version 1.3.0-DEV.324 (2019-06-01)
 _/ |\__'_|_|_|\__'_|  |  Commit de3401908a (0 days old master)
|__/                   |

julia> @time using BandedMatrices
  4.736207 seconds (18.54 M allocations: 1.399 GiB, 6.32% gc time)

[giordano]

If it can help the bisection, on 852d084f3da36f3eb22866d67a126c81ce385a92 loading the package takes about 20 seconds for me, and 6 on current master (de3401908a).

[JeffBezanson]

Anybody willing to bisect this?

[KristofferC]

I'll do it.

[KristofferC]

I only see a 2x slowdown and the numbers are quite different (60s and 30s (edit: this was because of a misunderstanding of what was timed)) but the commit that made the improvement is 217507fe58e5b8be0196c7.

[JeffBezanson]

Interesting. I think that should be safe to backport.

[KristofferC]

I thought this was only about precompilation time so that is what I checked. Re-reading I see that this is about loading time. Will check if the same commit applies for fixing the loading time as well.

[KristofferC]

Yes, the same commit also improves loading time.

[KristofferC]

FWIW, I ran my "latency checker" script (https://gist.github.com/KristofferC/8f970ca4630b036cc04770421bc56844) on 1.1, this branch and 217507f and got

Prec DataFrames [s] | Load DataFrames [s] | Prec Gadfly [s] | Load Gadfly [s] | Plot Gadfly [s] |
|---------------------|---------------------|-----------------|-----------------|-----------------|
| 27.861 | 3.549 | 96.689 | 7.147 | 36.269 |
| 21.681 | 3.324 | 83.772 | 6.174 | 32.933 |
| 21.691 | 3.418 | 79.281 | 5.612 | 32.113 |