Base.exp(::Complex) is 100x slower when Plots is loaded

[adambrewster]

I don't know if this is a julia problem or a plots problem, but loading the Plots module makes computing complex exponentials slow.

Here's a small test program:

if length(ARGS) == 0
  ;
elseif ARGS[1] == "plots"
  using Plots
elseif ARGS[1] == "deps"
  using PlotUtils, RecipesBase, Reexport, Compat, FixedSizeArrays, Measures, Showoff
else
  println("Usage: julia slow_exp.jl [plots | deps]")
  exit(1)
end

a = randn(10^6)*im
@time exp(a)
@time exp(a)

@profile exp(a)
Profile.print()

Baseline (no modules loaded):

julia slow_exp.jl
  0.121778 seconds (27.08 k allocations: 16.512 MB)
  0.148157 seconds (8 allocations: 15.259 MB, 54.76% gc time)

With plots, it's almost 100x slower:

julia slow_exp.jl plots
 11.667060 seconds (7.27 M allocations: 149.621 MB, 2.32% gc time)
 11.129141 seconds (7.00 M allocations: 137.330 MB, 0.13% gc time)

FixedSizeArrays is a dependency of Plots and adds a method to Base.exp. I thought that it might be at fault. With FixedSizeArrays (and all of the other dependencies of Plots) loaded, it's not slow.

julia slow_exp.jl deps
  0.120671 seconds (27.50 k allocations: 16.528 MB)
  0.148993 seconds (8 allocations: 15.259 MB, 59.42% gc time)

I profiled both versions. Here's the baseline:

julia slow_exp.jl
  0.121864 seconds (27.08 k allocations: 16.512 MB)
  0.148311 seconds (8 allocations: 15.259 MB, 54.78% gc time)
73 ./client.jl:318; _start()
 73 ./client.jl:262; process_options(::Base.JLOptions)
  73 ./loading.jl:488; include_from_node1(::String)
   73 ./<missing>:?; anonymous
    73 ./profile.jl:16; macro expansion;
     73 ./operators.jl:555; exp(::Array{Complex{Float64},1})
      73 ./array.jl:308; collect(::Base.Generator{Array{Complex{Float6...
       2  ./array.jl:339; collect_to!(::Array{Complex{Float64},1}, ::Ba...
       57 ./array.jl:340; collect_to!(::Array{Complex{Float64},1}, ::Ba...
        1  ./complex.jl:0; exp(::Complex{Float64})
        1  ./complex.jl:397; exp(::Complex{Float64})
        1  ./complex.jl:399; exp(::Complex{Float64})
        1  ./complex.jl:408; exp(::Complex{Float64})
        1  ./complex.jl:409; exp(::Complex{Float64})
        50 ./complex.jl:412; exp(::Complex{Float64})
         31 ./math.jl:202; cos(::Float64)
         1  ./math.jl:0; sin(::Float64)
         1  ./math.jl:196; sin(::Float64)
         13 ./math.jl:202; sin(::Float64)
        1  ./generator.jl:25; next
       12 ./array.jl:343; collect_to!(::Array{Complex{Float64},1}, ::Ba...
       1  ./complex.jl:412; exp(::Complex{Float64})

And here's the slow version:

julia slow_exp.jl plots
 11.667060 seconds (7.27 M allocations: 149.621 MB, 2.32% gc time)
 11.129141 seconds (7.00 M allocations: 137.330 MB, 0.13% gc time)
12765 ./client.jl:318; _start()
 12765 ./client.jl:262; process_options(::Base.JLOptions)
  12765 ./loading.jl:488; include_from_node1(::String)
   12765 ./<missing>:?; anonymous
    12765 ./profile.jl:16; macro expansion;
     12765 ./operators.jl:555; exp(::Array{Complex{Float64},1})
      12765 ./array.jl:308; collect(::Base.Generator{Array{Complex{Float...
       2     ./array.jl:295; _array_for(::Type{Complex{Float64}}, ::Arra...
       12763 ./array.jl:327; collect_to_with_first!(::Array{Complex{Floa...
        1     ./array.jl:339; collect_to!(::Array{Complex{Float64},1}, :...
        12733 ./array.jl:340; collect_to!(::Array{Complex{Float64},1}, :...
         3     ./complex.jl:0; exp(::Complex{Float64})
         4     ./complex.jl:399; exp(::Complex{Float64})
         14    ./complex.jl:408; exp(::Complex{Float64})
         1     ./complex.jl:409; exp(::Complex{Float64})
         12680 ./complex.jl:412; exp(::Complex{Float64})  <=== ???
          1  ./math.jl:196; cos(::Float64)
          33 ./math.jl:202; cos(::Float64)
          27 ./math.jl:202; sin(::Float64)
         26    ./generator.jl:25; next
        29    ./array.jl:343; collect_to!(::Array{Complex{Float64},1}, :...

For reference, here's line 412 of julia/base/complex.jl:

        if zi == zero(zi)
            Complex(er, zi)
        else
            Complex(er*cos(zi), er*sin(zi))  #   Line 412
        end

I can't see any reason why Plots should affect this, but I thought I'd ask if there's something I'm missing before posting this as a julia bug.

Any ideas?

[KristofferC]

This is an unfortunate bug in julia 0.5.There is a PR to fix it JuliaLang/julia#18869 and will thus be fixed when 0.5.1 comes out. It is not directly related to Plots.jl

[tbreloff]

I think this is a known Julia bug. We found the root cause a month ago, but
I can't remember where we had that discussion (can't search for it right
now). If anyone remembers please post a link.

On Saturday, October 22, 2016, adambrewster notifications@github.com
wrote:

I don't know if this is a julia problem or a plots problem, but loading
the Plots module makes computing complex exponentials slow.

Here's a small test program:

if length(ARGS) == 0
;elseif ARGS[1] == "plots"
using Plotselseif ARGS[1] == "deps"
using PlotUtils, RecipesBase, Reexport, Compat, FixedSizeArrays, Measures, Showoffelse
println("Usage: julia slow_exp.jl [plots | deps]")
exit(1)end

a = randn(10^6)*im@time exp(a)@time exp(a)
@Profile exp(a)
Profile.print()

Baseline (no modules loaded):

julia slow_exp.jl
0.121778 seconds (27.08 k allocations: 16.512 MB)
0.148157 seconds (8 allocations: 15.259 MB, 54.76% gc time)

With plots, it's almost 100x slower:

julia slow_exp.jl plots
11.667060 seconds (7.27 M allocations: 149.621 MB, 2.32% gc time)
11.129141 seconds (7.00 M allocations: 137.330 MB, 0.13% gc time)

FixedSizeArrays is a dependency of Plots and adds a method to Base.exp. I
thought that it might be at fault. With FixedSizeArrays (and all of the
other dependencies of Plots) loaded, it's not slow.

julia slow_exp.jl deps
0.120671 seconds (27.50 k allocations: 16.528 MB)
0.148993 seconds (8 allocations: 15.259 MB, 59.42% gc time)

I profiled both versions. Here's the baseline:

julia slow_exp.jl
0.121864 seconds (27.08 k allocations: 16.512 MB)
0.148311 seconds (8 allocations: 15.259 MB, 54.78% gc time)
73 ./client.jl:318; _start()
73 ./client.jl:262; process_options(::Base.JLOptions)
73 ./loading.jl:488; include_from_node1(::String)
73 ./:?; anonymous
73 ./profile.jl:16; macro expansion;
73 ./operators.jl:555; exp(::Array{Complex{Float64},1})
73 ./array.jl:308; collect(::Base.Generator{Array{Complex{Float6...
2 ./array.jl:339; collect_to!(::Array{Complex{Float64},1}, ::Ba...
57 ./array.jl:340; collect_to!(::Array{Complex{Float64},1}, ::Ba...
1 ./complex.jl:0; exp(::Complex{Float64})
1 ./complex.jl:397; exp(::Complex{Float64})
1 ./complex.jl:399; exp(::Complex{Float64})
1 ./complex.jl:408; exp(::Complex{Float64})
1 ./complex.jl:409; exp(::Complex{Float64})
50 ./complex.jl:412; exp(::Complex{Float64})
31 ./math.jl:202; cos(::Float64)
1 ./math.jl:0; sin(::Float64)
1 ./math.jl:196; sin(::Float64)
13 ./math.jl:202; sin(::Float64)
1 ./generator.jl:25; next
12 ./array.jl:343; collect_to!(::Array{Complex{Float64},1}, ::Ba...
1 ./complex.jl:412; exp(::Complex{Float64})

And here's the slow version:

julia slow_exp.jl plots
11.667060 seconds (7.27 M allocations: 149.621 MB, 2.32% gc time)
11.129141 seconds (7.00 M allocations: 137.330 MB, 0.13% gc time)
12765 ./client.jl:318; _start()
12765 ./client.jl:262; process_options(::Base.JLOptions)
12765 ./loading.jl:488; include_from_node1(::String)
12765 ./:?; anonymous
12765 ./profile.jl:16; macro expansion;
12765 ./operators.jl:555; exp(::Array{Complex{Float64},1})
12765 ./array.jl:308; collect(::Base.Generator{Array{Complex{Float...
2 ./array.jl:295; _array_for(::Type{Complex{Float64}}, ::Arra...
12763 ./array.jl:327; collect_to_with_first!(::Array{Complex{Floa...
1 ./array.jl:339; collect_to!(::Array{Complex{Float64},1}, :...
12733 ./array.jl:340; collect_to!(::Array{Complex{Float64},1}, :...
3 ./complex.jl:0; exp(::Complex{Float64})
4 ./complex.jl:399; exp(::Complex{Float64})
14 ./complex.jl:408; exp(::Complex{Float64})
1 ./complex.jl:409; exp(::Complex{Float64})
12680 ./complex.jl:412; exp(::Complex{Float64}) <=== ???
1 ./math.jl:196; cos(::Float64)
33 ./math.jl:202; cos(::Float64)
27 ./math.jl:202; sin(::Float64)
26 ./generator.jl:25; next
29 ./array.jl:343; collect_to!(::Array{Complex{Float64},1}, :...

For reference, here's line 412 of julia/base/complex.jl:

    if zi == zero(zi)
        Complex(er, zi)
    else
        Complex(er*cos(zi), er*sin(zi))  #   Line 412
    end

I can't see any reason why Plots should affect this, but I thought I'd ask
if there's something I'm missing before posting this as a julia bug.

Any ideas?

—
You are receiving this because you are subscribed to this thread.
Reply to this email directly, view it on GitHub
#548, or mute the thread
https://github.com/notifications/unsubscribe-auth/AA492pfrFnC7gQe6p2gG1DPx4zJ3fr-iks5q2mfigaJpZM4Kd879
.

[adambrewster]

Thank you.