Fixing test timeouts

[torfjelde]

Distributions@0.12.11 makes tests grind to a halt. I still don't know why, but it's undoubtably related to MvNormal. I'm struggling to figure out exactly where things go wrong, but I've noticed the following:

1. It only happens if you start the REPL with --depwarn=yes.
2. If I interrupt it, this is the stacktrace:

Stacktrace:
  [1] lookup(pointer::Ptr{Nothing})
    @ Base.StackTraces ./stacktraces.jl:107
  [2] firstcaller(bt::Vector{Union{Ptr{Nothing}, Base.InterpreterIP}}, funcsyms::Tuple{Symbol})
    @ Base ./deprecated.jl:110
  [3] firstcaller
    @ ./deprecated.jl:105 [inlined]
  [4] macro expansion
    @ ./deprecated.jl:90 [inlined]
  [5] macro expansion
    @ ./logging.jl:355 [inlined]
  [6] depwarn(msg::String, funcsym::Symbol; force::Bool)
    @ Base ./deprecated.jl:85
  [7] depwarn(msg::String, funcsym::Symbol)
    @ Base ./deprecated.jl:80
  [8] MvNormal(μ::Vector{Float64}, σ::Vector{Float64})
    @ Distributions ./deprecated.jl:71
  [9] #23
    @ ~/Projects/public/Turing.jl/test/test_utils/models.jl:61 [inlined]
 [10] (::var"#23#24")(__model__::DynamicPPL.Model{var"#23#24", (:x, :TV), (:x, :TV), (), Tuple{Vector{Float64}, Type{Vector{Float64}}}, Tuple{Vector{Float64}, Type{Vector{Float64}}}}, __varinfo__::DynamicPPL.TypedVarInfo{NamedTuple{(:m,), Tuple{DynamicPPL.Metadata{Dict{AbstractPPL.VarName{:m, Tuple{Tuple{Int64}}}, Int64}, Vector{Normal{Float64}}, Vector{AbstractPPL.VarName{:m, Tuple{Tuple{Int64}}}}, Vector{Float64}, Vector{Set{DynamicPPL.Selector}}}}}, Float64}, __context__::DynamicPPL.SamplingContext{Sampler{ESS{()}}, DynamicPPL.DefaultContext, Random._GLOBAL_RNG}, x::Vector{Float64}, #unused#::Type{Vector{Float64}})
    @ Main ./none:0
 [11] macro expansion
    @ ~/.julia/packages/DynamicPPL/h8FWT/src/model.jl:0 [inlined]
 [12] _evaluate
    @ ~/.julia/packages/DynamicPPL/h8FWT/src/model.jl:156 [inlined]
 [13] evaluate_threadunsafe
    @ ~/.julia/packages/DynamicPPL/h8FWT/src/model.jl:129 [inlined]
 [14] Model
    @ ~/.julia/packages/DynamicPPL/h8FWT/src/model.jl:97 [inlined]
 [15] Model (repeats 2 times)
    @ ~/.julia/packages/DynamicPPL/h8FWT/src/model.jl:91 [inlined]
 [16] rand(rng::Random._GLOBAL_RNG, p::Turing.Inference.ESSPrior{DynamicPPL.Model{var"#25#26", (:x, :TV), (:x, :TV), (), Tuple{Vector{Float64}, Type{Vector{Float64}}}, Tuple{Vector{Float64}, Type{Vector{Float64}}}}, Sampler{ESS{()}}, DynamicPPL.TypedVarInfo{NamedTuple{(:m,), Tuple{DynamicPPL.Metadata{Dict{AbstractPPL.VarName{:m, Tuple{Tuple{Int64}}}, Int64}, Vector{Normal{Float64}}, Vector{AbstractPPL.VarName{:m, Tuple{Tuple{Int64}}}}, Vector{Float64}, Vector{Set{DynamicPPL.Selector}}}}}, Float64}, Vector{Float64}})

3. Running the offending model e.g. model(), is fine, but sampling causes it to halt.
4. The following works just fine, even with depwarn=yes:

julia> let model = gdemo_models[1], vi = DynamicPPL.VarInfo(model), spl = DynamicPPL.Sampler(ESS())
           essmodel = EllipticalSliceSampling.ESSModel(
               ESSPrior(model, spl, vi), ESSLogLikelihood(model, spl, vi)
           )
           rand(essmodel.prior)
       end
2-element Vector{Float64}:
 0.44483643141566265
 2.2764878459823263

[codecov]

Codecov Report

Merging #1663 (604e3e2) into master (0168d84) will increase coverage by 11.06%.
The diff coverage is 85.87%.

@@             Coverage Diff             @@
##           master    #1663       +/-   ##
===========================================
+ Coverage   68.49%   79.56%   +11.06%     
===========================================
  Files          26       23        -3     
  Lines        1479     1414       -65     
===========================================
+ Hits         1013     1125      +112     
+ Misses        466      289      -177     

Impacted Files	Coverage Δ
src/core/Core.jl	100.00% <ø> (ø)
src/stdlib/RandomMeasures.jl	34.28% <0.00%> (-3.46%)	⬇️
src/variational/VariationalInference.jl	53.84% <37.50%> (-35.52%)	⬇️
src/stdlib/distributions.jl	56.98% <58.13%> (+4.60%)	⬆️
src/core/container.jl	76.19% <76.19%> (-15.40%)	⬇️
src/variational/advi.jl	61.11% <76.92%> (-2.13%)	⬇️
src/inference/Inference.jl	84.55% <80.35%> (-6.79%)	⬇️
src/core/compat/reversediff.jl	95.34% <83.33%> (+8.86%)	⬆️
src/modes/ModeEstimation.jl	84.29% <84.74%> (+15.46%)	⬆️
src/inference/hmc.jl	76.33% <86.90%> (-8.54%)	⬇️
... and 26 more

---

Continue to review full report at Codecov.

Legend - Click here to learn more
Δ = absolute <relative> (impact), ø = not affected, ? = missing data
Powered by Codecov. Last update d029198...604e3e2. Read the comment docs.

[torfjelde]

@yebai @mohamed82008 @devmotion you guys got a clue?

[torfjelde]

I figured out the issue @yebai : deprecations are slow.

With --depwarn=yes:

julia> using Distributions, BenchmarkTools

julia> @benchmark $(MvNormal)($(zeros(1)), $(ones(1)))
┌ Warning: `MvNormal(μ::AbstractVector{<:Real}, σ::AbstractVector{<:Real})` is deprecated, use `MvNormal(μ, Diagonal(map(abs2, σ)))` instead.
│   caller = ip:0x0
└ @ Core :-1
BenchmarkTools.Trial: 
  memory estimate:  27.44 KiB
  allocs estimate:  363
  --------------
  minimum time:     64.617 ms (0.00% GC)
  median time:      67.703 ms (0.00% GC)
  mean time:        68.065 ms (0.00% GC)
  maximum time:     85.660 ms (0.00% GC)
  --------------
  samples:          74
  evals/sample:     1

without --depwarn=yes:

julia> @benchmark $(MvNormal)($(zeros(1)), $(ones(1)))
BenchmarkTools.Trial: 
  memory estimate:  192 bytes
  allocs estimate:  2
  --------------
  minimum time:     81.207 ns (0.00% GC)
  median time:      84.698 ns (0.00% GC)
  mean time:        96.957 ns (10.22% GC)
  maximum time:     3.617 μs (96.73% GC)
  --------------
  samples:          10000
  evals/sample:     962

[yebai]

That's a bit surprising - does disable deprecations messages fix the time outs?

[torfjelde]

Yes, that's what the above is showing.

So endusers won't see any issues when running their models because --depwarn=no by default, i.e. we probably don't need to upper-bound Distributions.jl in Turing.jl (though we need to in the tests until we've updated the tests to not use the deprecated constructors).