10-fold slowdown in Julia 0.5.0

[krcools]

I have encountered a situation where code with the following structure slowed down a factor of 10 in the new Julia release:

module Mod
export f
function f(x)
    y = g(x)
    for z in y
        ....
    end
end

using Mod
x = ...
f(x)

The weird thing is that running y=g(x) before invoking f(x) results in the code being run at full speed. (this is not a case of JIT overhead; subsequent invocations of f(x) remain slow if y=g(x) was not run). The problem did not appear immediately after installing Julia 0.5.0 so it could be an updated package I pulled in or a cached compiled package.

I haven't been able to isolate the problem. If I manage to get a one-pager I'll post it here.

For completeness:

Julia Version 0.5.0
Commit 3c9d753 (2016-09-19 18:14 UTC)
Platform Info:
  System: NT (x86_64-w64-mingw32)
  CPU: Intel(R) Xeon(R) CPU E5-1620 v3 @ 3.50GHz
  WORD_SIZE: 64
  BLAS: libopenblas (USE64BITINT DYNAMIC_ARCH NO_AFFINITY Haswell)
  LAPACK: libopenblas64_
  LIBM: libopenlibm
  LLVM: libLLVM-3.7.1 (ORCJIT, haswell)

[krcools]

Some more info:

My test code is:

using MyModule
import Colors
x = ....
f(x)

Commenting out import Colors fixes the slowdown. Leaving it there slows the code down, but does not affect the result. Profiling f(x) shows no time spent in Colors.

The circled area corresponds to normal execution. The slowdown is attributed to iterator traversal according to the profiler.

Profiling with --inline=no consistently results in EXCEPTION_ACCESS_VIOLATION.

[simonster]

If you can post any code (even if long) that reproduces the issue, that would be helpful. Otherwise I'm not sure where to start here.

[eschnett]

A wild guess: Importing Colors affects how type-unstable function calls are looked up. If -- without Colors -- there is only a single matching method for one of the function calls, the lookup might be faster than if there are many methods to sort through. Are there any common function names between Color and your module? Does code_llvm show method calls that are resolved at run time? If you change all function names in your module, do the timings change?

[martinholters]

Could this be #18465? Does @code_warntype give different output depending on whether Colors is imported?

[krcools]

The answer to the last question is definitely yes. The Variables section for @code_warntype are:

• without import Colors:

Variables:
  #self#::BoundaryElements.#assemble!
  biop::BoundaryElements.MWSingleLayer3D{Float64}
  tfs::BoundaryElements.RTBasis{Float64,3}
  bfs::BoundaryElements.RTBasis{Float64,3}
  store::#store
  tad::BoundaryElements.AssemblyData2{Float64}
  bad::BoundaryElements.AssemblyData2{Float64}
  tels::Array{CompScienceMeshes.FlatCellNM{3,2,1,3,Float64},1}
  bels::Array{CompScienceMeshes.FlatCellNM{3,2,1,3,Float64},1}
  tshapes::BoundaryElements.RTRefSpace{Float64}
  bshapes::BoundaryElements.RTRefSpace{Float64}
  qd::BoundaryElements.QuadData{BoundaryElements.WeightPointValue{Float64,CompScienceMeshes.MeshPointNM{3,2,1,3,Float64},FixedSizeArrays.Vec{3,Tuple{FixedSizeArrays.Vec{3,Float64},Float64}}},BoundaryElements.WeightPointValue{Float64,CompScienceMeshes.MeshPointNM{3,2,1,3,Float64},FixedSizeArrays.Vec{3,Tuple{FixedSizeArrays.Vec{3,Float64},Float64}}}}
  zlocal::Array{Complex{Float64},2}
  done::Int64
  pctg::Int64
  todo::Int64
  #temp#@_17::Int64
  p::Int64
  tcell::CompScienceMeshes.FlatCellNM{3,2,1,3,Float64}
  new_pctg::Int64
  #temp#@_21::Int64
  q::Int64
  bcell::CompScienceMeshes.FlatCellNM{3,2,1,3,Float64}
  strat::Any
  #temp#@_25::Int64
  i::Int64
  #temp#@_27::Int64
  j::Int64
  z::Complex{Float64}
  #temp#@_30::Int64
  m::Int64
  a::Float64
  #temp#@_33::Int64
  #temp#@_34::Int64
  n::Int64
  b::Float64
  #temp#@_37::Int64
  tqd::Array{Array{BoundaryElements.WeightPointValue{Float64,CompScienceMeshes.MeshPointNM{3,2,1,3,Float64},FixedSizeArrays.Vec{3,Tuple{FixedSizeArrays.Vec{3,Float64},Float64}}},1},2}
  bqd::Array{Array{BoundaryElements.WeightPointValue{Float64,CompScienceMeshes.MeshPointNM{3,2,1,3,Float64},FixedSizeArrays.Vec{3,Tuple{FixedSizeArrays.Vec{3,Float64},Float64}}},1},2}
  #temp#@_40::Bool
  #temp#@_41::Bool

• with import Colors:

Variables:
  #self#::BoundaryElements.#assemble!
  biop::BoundaryElements.MWSingleLayer3D{Float64}
  tfs::BoundaryElements.RTBasis{Float64,3}
  bfs::BoundaryElements.RTBasis{Float64,3}
  store::#store
  tad::BoundaryElements.AssemblyData2{Float64}
  bad::BoundaryElements.AssemblyData2{Float64}
  tels::AbstractArray{T,N}
  bels::AbstractArray{T,N}
  tshapes::BoundaryElements.RTRefSpace{Float64}
  bshapes::BoundaryElements.RTRefSpace{Float64}
  qd::BoundaryElements.QuadData{BoundaryElements.WeightPointValue{Float64,CompScienceMeshes.MeshPointNM{3,2,1,3,Float64},FixedSizeArrays.Vec{3,Tuple{FixedSizeArrays.Vec{3,Float64},Float64}}},BoundaryElements.WeightPointValue{Float64,CompScienceMeshes.MeshPointNM{3,2,1,3,Float64},FixedSizeArrays.Vec{3,Tuple{FixedSizeArrays.Vec{3,Float64},Float64}}}}
  zlocal::Array{Complex{Float64},2}
  done::Int64
  pctg::Int64
  todo::Int64
  #temp#@_17::Any
  p::Any
  tcell::Any
  new_pctg::Int64
  #temp#@_21::Any
  q::Any
  bcell::Any
  strat::Any
  #temp#@_25::Int64
  i::Int64
  #temp#@_27::Int64
  j::Int64
  z::Complex{Float64}
  #temp#@_30::Int64
  m::Int64
  a::Float64
  #temp#@_33::Int64
  #temp#@_34::Int64
  n::Int64
  b::Float64
  #temp#@_37::Int64
  tqd::Array{Array{BoundaryElements.WeightPointValue{Float64,CompScienceMeshes.MeshPointNM{3,2,1,3,Float64},FixedSizeArrays.Vec{3,Tuple{FixedSizeArrays.Vec{3,Float64},Float64}}},1},N}
  bqd::Array{Array{BoundaryElements.WeightPointValue{Float64,CompScienceMeshes.MeshPointNM{3,2,1,3,Float64},FixedSizeArrays.Vec{3,Tuple{FixedSizeArrays.Vec{3,Float64},Float64}}},1},N}
  #temp#@_40::Bool
  #temp#@_41::Bool

In particular, complete type inference fails for tels, bels, tqd, and bqd. This is confirmed (for e.g. tels) by running:

Test.@inferred tels = elements([Γ])

which passes in the absence of Colors but fails otherwise.

[krcools]

Managed to distill a minimal reproducing example:

import Colors

using FixedSizeArrays

t = Vec((Vec(1.0,0.0,0.0),Vec(0.0,1.0,0.0)))


function _normals(tangents)
    PT = eltype(tangents)
    D  = length(tangents)
    T  = eltype(PT)

    n = zeros(T,D+1)
    n *= (-1)^D / norm(n)

end

@code_warntype _normals(t)
Test.@inferred _normals(t)

[martinholters]

@vtjnash Should we close this as dup?

[vtjnash]

sgtm