Skip to content
New issue

Have a question about this project? Sign up for a free GitHub account to open an issue and contact its maintainers and the community.

By clicking “Sign up for GitHub”, you agree to our terms of service and privacy statement. We’ll occasionally send you account related emails.

Already on GitHub? Sign in to your account

2-4x performance regression for Plots.plot in Julia 1.6 vs. 1.5.3 #39509

Closed
truedichotomy opened this issue Feb 3, 2021 · 23 comments
Closed
Labels
performance Must go faster

Comments

@truedichotomy
Copy link

truedichotomy commented Feb 3, 2021

I'm experiencing a large performance regression (2-3x) using Plots.plot function when comparing Julia 1.6 beta1 with 1.5.3. Similar results when using plotly backend.

Julia 1.5.3:

julia> @benchmark Plots.plot(1:100)
BenchmarkTools.Trial: 
  memory estimate:  169.02 KiB
  allocs estimate:  2860
  --------------
  minimum time:     359.307 μs (0.00% GC)
  median time:      370.611 μs (0.00% GC)
  mean time:        396.897 μs (3.38% GC)
  maximum time:     4.577 ms (88.68% GC)
  --------------
  samples:          10000
  evals/sample:     1

Julia 1.6b1:

julia> @benchmark Plots.plot(1:100)
BenchmarkTools.Trial: 
  memory estimate:  200.80 KiB
  allocs estimate:  2659
  --------------
  minimum time:     1.115 ms (0.00% GC)
  median time:      1.140 ms (0.00% GC)
  mean time:        1.194 ms (1.02% GC)
  maximum time:     4.507 ms (73.41% GC)
  --------------
  samples:          4183
  evals/sample:     1
@simeonschaub
Copy link
Member

This is likely expected, since a lot of work has gone into reducing compiler latencies for applications like plotting where runtime cost is typically negligible. As a consequence calls to plot might now take a little more time after precompilation, but I think that's a worthwhile compromise since people don't usually plot thousands of plots in a loop.

@truedichotomy
Copy link
Author

truedichotomy commented Feb 3, 2021

Actually I would disagree. I generate a significant number of plots with a lot more data points than this trivial example. The difference in real world situation end up being a factor of 6-8x. It's 30 seconds vs 4 minutes. That's a large impact on productivity.

@KristofferC
Copy link
Member

An analysis of a profile would be helpful in understanding the slowdown.

@DilumAluthge DilumAluthge added the performance Must go faster label Feb 3, 2021
@simeonschaub
Copy link
Member

simeonschaub commented Feb 3, 2021

One thing you could also try is uncommenting these three lines in Plots.jl: https://github.com/JuliaPlots/Plots.jl/blob/a04946e8320df5ad19559d674ef44fa7201dc2c1/src/Plots.jl#L3

@truedichotomy
Copy link
Author

Here is another trivial example where the performance regression is even more dramatic (4-5x):

v1.5.3:

julia> @benchmark begin Plots.plot([1:100 1:100]); Plots.plot!([1:100 1:100]); Plots.plot!([1:100 1:100]) end
BenchmarkTools.Trial: 
  memory estimate:  706.77 KiB
  allocs estimate:  12954
  --------------
  minimum time:     1.637 ms (0.00% GC)
  median time:      1.757 ms (0.00% GC)
  mean time:        1.878 ms (3.58% GC)
  maximum time:     8.147 ms (65.39% GC)
  --------------
  samples:          2662
  evals/sample:     1

v1.6b1:

julia> @benchmark begin Plots.plot([1:100 1:100]); Plots.plot!([1:100 1:100]); Plots.plot!([1:100 1:100]) end
BenchmarkTools.Trial: 
  memory estimate:  940.41 KiB
  allocs estimate:  13607
  --------------
  minimum time:     7.105 ms (0.00% GC)
  median time:      7.950 ms (0.00% GC)
  mean time:        8.179 ms (0.81% GC)
  maximum time:     13.422 ms (27.26% GC)
  --------------
  samples:          612
  evals/sample:     1

@truedichotomy
Copy link
Author

truedichotomy commented Feb 5, 2021

When I generate a profile here is what it looks like for Julia 1.5.3:

julia> myfunc() = Plots.plot([1:100 1:100]); Plots.plot!([1:100 1:100]); Plots.plot!([1:100 1:100]);

julia> @profile myfunc()

julia> Profile.print()
[long output trimmed to make this thread easier to scroll]

julia> @benchmark myfunc()
BenchmarkTools.Trial: 
  memory estimate:  257.34 KiB
  allocs estimate:  4517
  --------------
  minimum time:     556.110 μs (0.00% GC)
  median time:      672.151 μs (0.00% GC)
  mean time:        727.577 μs (3.85% GC)
  maximum time:     8.630 ms (89.21% GC)
  --------------
  samples:          6855
  evals/sample:     1

@truedichotomy
Copy link
Author

truedichotomy commented Feb 5, 2021

And here what the profile look like for Julia 1.6b1:

julia> myfunc() = Plots.plot([1:100 1:100]); Plots.plot!([1:100 1:100]); Plots.plot!([1:100 1:100]);

julia> @profile myfunc()

julia> Profile.print()
[long output trimmed to make this thread easier to scroll]

julia> @benchmark myfunc()
BenchmarkTools.Trial: 
  memory estimate:  335.11 KiB
  allocs estimate:  4732
  --------------
  minimum time:     2.361 ms (0.00% GC)
  median time:      2.849 ms (0.00% GC)
  mean time:        3.027 ms (0.93% GC)
  maximum time:     8.844 ms (51.28% GC)
  --------------
  samples:          1651
  evals/sample:     1

@KristofferC
Copy link
Member

KristofferC commented Feb 5, 2021

That seems to have way too few samples to be a useful profile data. You probably need to run the function more times to get statistically representative data.

@truedichotomy truedichotomy changed the title 2-3x performance regression for Plots.plot in Julia 1.6 vs. 1.5.3 2-4x performance regression for Plots.plot in Julia 1.6 vs. 1.5.3 Feb 5, 2021
@truedichotomy
Copy link
Author

truedichotomy commented Feb 5, 2021

Ok, I defined the following function and reran profile.

function myfunc()
    Plots.plot([1:100 1:100]); 
    for i = 1:1000
        Plots.plot!([1:100 1:100]);
    end
end

Julia 1.5.3:

julia> @btime myfunc()
  680.692 ms (4227545 allocations: 219.83 MiB)

julia> @profile myfunc()

julia> Profile.print(;noisefloor=2)
Overhead ╎ [+additional indent] Count File:Line; Function
=========================================================
   1╎1    @Base/array.jl:785; iterate(::Array{Dict{Symbol,Any},1})
    ╎550  @Base/client.jl:506; _start()
    ╎ 550  @Base/client.jl:313; exec_options(::Base.JLOptions)
    ╎  550  @Base/client.jl:383; run_main_repl(::Bool, ::Bool, ::Bool, ::Bool, ::Bool)
    ╎   550  @Base/essentials.jl:709; invokelatest
    ╎    550  @Base/essentials.jl:710; #invokelatest#1
    ╎     550  @Base/client.jl:399; (::Base.var"#807#809"{Bool,Bool,Bool,Bool})(::Module)
    ╎    ╎ 550  .../usr/share/julia/stdlib/v1.5/REPL/src/REPL.jl:288; run_repl(::REPL.AbstractREPL, ::Any)
    ╎    ╎  550  .../usr/share/julia/stdlib/v1.5/REPL/src/REPL.jl:292; run_repl(::REPL.AbstractREPL, ::Any; backend_on_current_task::Bool)
    ╎    ╎   550  .../usr/share/julia/stdlib/v1.5/REPL/src/REPL.jl:180; start_repl_backend(::REPL.REPLBackend, ::Any)
    ╎    ╎    550  ...usr/share/julia/stdlib/v1.5/REPL/src/REPL.jl:195; repl_backend_loop(::REPL.REPLBackend)
    ╎    ╎     550  ...usr/share/julia/stdlib/v1.5/REPL/src/REPL.jl:134; eval_user_input(::Any, ::REPL.REPLBackend)
   2╎    ╎    ╎ 550  @Base/boot.jl:331; eval(::Module, ::Any)
   2╎    ╎    ╎  547  /Users/gong/GitHub/covid19/myfunc.jl:4; myfunc()
    ╎    ╎    ╎   545  @Plots/src/plot.jl:147; plot!(::Any)
    ╎    ╎    ╎    545  @Plots/src/plot.jl:153; plot!(::Any; kw::Any)
    ╎    ╎    ╎     545  @Plots/src/plot.jl:159; plot!(::Plots.Plot, ::Any)
    ╎    ╎    ╎    ╎ 540  @Plots/src/plot.jl:162; #plot!#134
    ╎    ╎    ╎    ╎  540  @Plots/src/plot.jl:172; _plot!(::Plots.Plot, ::Any, ::Any)
    ╎    ╎    ╎    ╎   58   @RecipesPipeline/src/RecipesPipeline.jl:70; recipe_pipeline!(::Any, ::Any, ::Any)
   3╎    ╎    ╎    ╎    31   @RecipesPipeline/src/user_recipe.jl:38; _process_userrecipes!(::Any, ::Any, ::Any)
    ╎    ╎    ╎    ╎     26   @RecipesPipeline/src/utils.jl:233; userrecipe_signature_string(::Any)
    ╎    ╎    ╎    ╎    ╎ 15   @Base/broadcast.jl:837; materialize
    ╎    ╎    ╎    ╎    ╎  15   @Base/broadcast.jl:1046; copy(::Base.Broadcast.Broadcasted{Base.Broadcast.Style{Tuple...
    ╎    ╎    ╎    ╎    ╎   8    @Base/ntuple.jl:45; ntuple
    ╎    ╎    ╎    ╎    ╎    8    @Base/ntuple.jl:50; macro expansion
    ╎    ╎    ╎    ╎    ╎     8    @Base/broadcast.jl:1046; (::Base.Broadcast.var"#19#20"{Base.Broadcast.Broadcasted{B...
    ╎    ╎    ╎    ╎    ╎    ╎ 6    @Base/broadcast.jl:621; _broadcast_getindex
    ╎    ╎    ╎    ╎    ╎    ╎  6    @Base/broadcast.jl:648; _broadcast_getindex_evalf
    ╎    ╎    ╎    ╎    ╎    ╎   6    @Base/strings/io.jl:174; string
    ╎    ╎    ╎    ╎    ╎    ╎    6    @Base/strings/io.jl:135; print_to_string(::Type)
   2╎    ╎    ╎    ╎    ╎    ╎     6    @Base/strings/io.jl:35; print(::Base.GenericIOBuffer{Array{UInt8,1}}, ::Type)
    ╎    ╎    ╎    ╎    ╎    ╎    ╎ 4    @Base/show.jl:497; show(::Base.GenericIOBuffer{Array{UInt8,1}}, ::Type)
    ╎    ╎    ╎    ╎   107  @RecipesPipeline/src/RecipesPipeline.jl:87; recipe_pipeline!(::Any, ::Any, ::Any)
    ╎    ╎    ╎    ╎    94   @Plots/src/pipeline.jl:145; plot_setup!(::Plots.Plot{Plots.GRBackend}, ::Dict{Symbol,Any},...
    ╎    ╎    ╎    ╎     66   @Plots/src/pipeline.jl:261; _subplot_setup(::Plots.Plot{Plots.GRBackend}, ::Dict{Symbol,A...
    ╎    ╎    ╎    ╎    ╎ 56   @Plots/src/args.jl:1572; _update_subplot_args(::Plots.Plot{Plots.GRBackend}, ::Plots....
    ╎    ╎    ╎    ╎    ╎  54   @Plots/src/args.jl:1499; _update_axis(::Plots.Plot{Plots.GRBackend}, ::Plots.Subplot{...
    ╎    ╎    ╎    ╎    ╎   28   @Plots/src/args.jl:1522; _update_axis(::Plots.Axis, ::Dict{Symbol,Any}, ::Symbol, ::...
    ╎    ╎    ╎    ╎    ╎    28   @Base/strings/basic.jl:227; Symbol
  18╎    ╎    ╎    ╎    ╎     18   @Base/boot.jl:438; Symbol
    ╎    ╎    ╎    ╎    ╎     10   @Base/strings/io.jl:174; string
    ╎    ╎    ╎    ╎    ╎    ╎ 6    @Base/strings/io.jl:133; print_to_string(::Symbol, ::Vararg{Symbol,N} where N)
    ╎    ╎    ╎    ╎    ╎    ╎  6    @Base/iobuffer.jl:112; Type##kw
    ╎    ╎    ╎    ╎    ╎    ╎   6    @Base/iobuffer.jl:114; Base.GenericIOBuffer{Array{UInt8,1}}(; read::Bool, write:...
    ╎    ╎    ╎    ╎    ╎    ╎    5    @Base/iobuffer.jl:31; StringVector
    ╎    ╎    ╎    ╎    ╎   22   @Plots/src/args.jl:1529; _update_axis(::Plots.Axis, ::Dict{Symbol,Any}, ::Symbol, ::...
    ╎    ╎    ╎    ╎    ╎    18   @Plots/src/axes.jl:81; attr!
    ╎    ╎    ╎    ╎    ╎     18   @Plots/src/axes.jl:87; attr!(::Plots.Axis; kw::Base.Iterators.Pairs{Union{},Union{...
   1╎    ╎    ╎    ╎   372  @RecipesPipeline/src/RecipesPipeline.jl:97; recipe_pipeline!(::Any, ::Any, ::Any)
   2╎    ╎    ╎    ╎    358  @RecipesPipeline/src/series_recipe.jl:27; _process_seriesrecipes!(::Any, ::Any)
    ╎    ╎    ╎    ╎     354  @RecipesPipeline/src/series_recipe.jl:46; _process_seriesrecipe(::Any, ::Any)
    ╎    ╎    ╎    ╎    ╎ 171  @Plots/src/pipeline.jl:288; add_series!(::Plots.Plot{Plots.GRBackend}, ::RecipesPipeline....
    ╎    ╎    ╎    ╎    ╎  169  @Plots/src/pipeline.jl:300; _prepare_subplot(::Plots.Plot{Plots.GRBackend}, ::RecipesPip...
   1╎    ╎    ╎    ╎    ╎   138  @Plots/src/args.jl:1572; _update_subplot_args(::Plots.Plot{Plots.GRBackend}, ::Plots...
    ╎    ╎    ╎    ╎    ╎    130  @Plots/src/args.jl:1499; _update_axis(::Plots.Plot{Plots.GRBackend}, ::Plots.Subplo...
    ╎    ╎    ╎    ╎    ╎     75   @Plots/src/args.jl:1522; _update_axis(::Plots.Axis, ::RecipesPipeline.DefaultsDict,...
    ╎    ╎    ╎    ╎    ╎    ╎ 75   @Base/strings/basic.jl:227; Symbol
  45╎    ╎    ╎    ╎    ╎    ╎  45   @Base/boot.jl:438; Symbol
    ╎    ╎    ╎    ╎    ╎    ╎  30   @Base/strings/io.jl:174; string
    ╎    ╎    ╎    ╎    ╎    ╎   15   @Base/strings/io.jl:133; print_to_string(::Symbol, ::Vararg{Symbol,N} where N)
    ╎    ╎    ╎    ╎    ╎    ╎    15   @Base/iobuffer.jl:112; Type##kw
    ╎    ╎    ╎    ╎    ╎    ╎     13   @Base/iobuffer.jl:114; Base.GenericIOBuffer{Array{UInt8,1}}(; read::Bool, writ...
    ╎    ╎    ╎    ╎    ╎    ╎    ╎ 12   @Base/iobuffer.jl:31; StringVector
   7╎    ╎    ╎    ╎    ╎    ╎    ╎  7    @Base/strings/string.jl:60; _string_n
    ╎    ╎    ╎    ╎    ╎     36   @Plots/src/args.jl:1529; _update_axis(::Plots.Axis, ::RecipesPipeline.DefaultsDict,...
    ╎    ╎    ╎    ╎    ╎    ╎ 27   @Plots/src/axes.jl:81; attr!
   1╎    ╎    ╎    ╎    ╎    ╎  27   @Plots/src/axes.jl:87; attr!(::Plots.Axis; kw::Base.Iterators.Pairs{Union{},Union...
    ╎    ╎    ╎    ╎    ╎    ╎   11   @Plots/src/args.jl:1079; preprocess_attributes!(::Dict{Symbol,Any})
    ╎    ╎    ╎    ╎    ╎    ╎    10   @Base/strings/basic.jl:227; Symbol
   7╎    ╎    ╎    ╎    ╎    ╎     7    @Base/boot.jl:438; Symbol
    ╎    ╎    ╎    ╎    ╎ 89   @Plots/src/pipeline.jl:290; add_series!(::Plots.Plot{Plots.GRBackend}, ::RecipesPipeline....
   2╎    ╎    ╎    ╎    ╎  68   @Plots/src/args.jl:1649; _update_series_attributes!(::RecipesPipeline.DefaultsDict, :...
   5╎    ╎    ╎    ╎    ╎   63   @Plots/src/args.jl:1723; _series_index(::RecipesPipeline.DefaultsDict, ::Plots.Subpl...
    ╎    ╎    ╎    ╎    ╎    58   @Plots/src/args.jl:1405; getindex
    ╎    ╎    ╎    ╎    ╎     50   @RecipesPipeline/src/utils.jl:18; getindex
    ╎    ╎    ╎    ╎    ╎    ╎ 42   @Base/dict.jl:535; haskey
    ╎    ╎    ╎    ╎    ╎    ╎  16   @Base/dict.jl:281; ht_keyindex(::Dict{Symbol,Any}, ::Symbol)
  16╎    ╎    ╎    ╎    ╎    ╎   16   @Base/Base.jl:33; getproperty
    ╎    ╎    ╎    ╎    ╎    ╎  20   @Base/dict.jl:282; ht_keyindex(::Dict{Symbol,Any}, ::Symbol)
    ╎    ╎    ╎    ╎    ╎    ╎   20   @Base/dict.jl:168; hashindex
    ╎    ╎    ╎    ╎    ╎    ╎    20   @Base/hashing.jl:18; hash
    ╎    ╎    ╎    ╎    ╎    ╎     20   @Base/hashing.jl:23; hash
  19╎    ╎    ╎    ╎    ╎    ╎    ╎ 19   @Base/reflection.jl:312; objectid
    ╎    ╎    ╎    ╎    ╎ 84   @Plots/src/pipeline.jl:291; add_series!(::Plots.Plot{Plots.GRBackend}, ::RecipesPipeline....
   1╎    ╎    ╎    ╎    ╎  80   @Plots/src/pipeline.jl:348; _add_the_series(::Plots.Plot{Plots.GRBackend}, ::Plots.Subpl...
    ╎    ╎    ╎    ╎    ╎   35   @Plots/src/args.jl:1194; warn_on_unsupported_args(::Plots.GRBackend, ::RecipesPipeli...
    ╎    ╎    ╎    ╎    ╎    35   @Base/abstractdict.jl:60; iterate
    ╎    ╎    ╎    ╎    ╎     20   @RecipesPipeline/src/utils.jl:37; iterate
   1╎    ╎    ╎    ╎    ╎    ╎ 20   @Base/abstractset.jl:156; setdiff
    ╎    ╎    ╎    ╎    ╎    ╎  17   @Base/set.jl:72; copymutable
    ╎    ╎    ╎    ╎    ╎    ╎   17   @Base/set.jl:10; Set
    ╎    ╎    ╎    ╎    ╎    ╎    14   @Base/abstractset.jl:91; union!(::Set{Symbol}, ::Base.KeySet{Symbol,Dict{Symbol,An...
    ╎    ╎    ╎    ╎    ╎    ╎     14   @Base/set.jl:57; push!
    ╎    ╎    ╎    ╎    ╎    ╎    ╎ 12   @Base/dict.jl:381; setindex!(::Dict{Symbol,Nothing}, ::Nothing, ::Symbol)
    ╎    ╎    ╎    ╎    ╎    ╎    ╎  6    @Base/dict.jl:348; ht_keyindex2!(::Dict{Symbol,Nothing}, ::Symbol)
    ╎    ╎    ╎    ╎    ╎    ╎    ╎   4    @Base/dict.jl:193; rehash!(::Dict{Symbol,Nothing}, ::Int64)
   4╎    ╎    ╎    ╎    ╎    ╎    ╎    4    @Base/boot.jl:406; Array
    ╎    ╎    ╎    ╎    ╎     15   @RecipesPipeline/src/utils.jl:38; iterate
    ╎    ╎    ╎    ╎    ╎    ╎ 15   @Base/array.jl:624; collect
    ╎    ╎    ╎    ╎    ╎    ╎  15   @Base/array.jl:636; _collect(::UnitRange{Int64}, ::Base.Iterators.Flatten{Tup...
  13╎    ╎    ╎    ╎    ╎    ╎   14   @Base/iterators.jl:1065; iterate
    ╎    ╎    ╎    ╎    ╎   36   @Plots/src/args.jl:1201; warn_on_unsupported_args(::Plots.GRBackend, ::RecipesPipeli...
  10╎    ╎    ╎    ╎    ╎    34   @Base/abstractdict.jl:60; iterate
  18╎    ╎    ╎    ╎    ╎     23   @RecipesPipeline/src/utils.jl:44; iterate(::RecipesPipeline.DefaultsDict, ::Tuple{Array{Symbo...
   1╎1    @Base/dict.jl:303; ht_keyindex2!(::Dict{Symbol,Any}, ::Symbol)
   1╎1    @Base/dict.jl:174; rehash!(::Dict{Symbol,Any}, ::Int64)
   1╎1    @RecipesPipeline/src/utils.jl:52; setindex!(::RecipesPipeline.DefaultsDict, ::Symbol, ::Symbol)
Total snapshots: 2336

@truedichotomy
Copy link
Author

truedichotomy commented Feb 5, 2021

And here is the profile for Julia 1.6 b1:

julia> @btime myfunc()
  2.591 s (4446760 allocations: 296.02 MiB)

julia> @profile myfunc()

julia> Profile.print(;noisefloor=2)
Overhead ╎ [+additional indent] Count File:Line; Function
=========================================================
    ╎1851 @Base/client.jl:485; _start()
    ╎ 1851 @Base/client.jl:302; exec_options(opts::Base.JLOptions)
    ╎  1851 @Base/client.jl:372; run_main_repl(interactive::Bool, quiet::Bool, banner::Bool, history_file...
    ╎   1851 @Base/essentials.jl:706; invokelatest
    ╎    1851 @Base/essentials.jl:707; #invokelatest#2
    ╎     1851 @Base/client.jl:387; (::Base.var"#875#877"{Bool, Bool, Bool})(REPL::Module)
    ╎    ╎ 1851 .../usr/share/julia/stdlib/v1.6/REPL/src/REPL.jl:305; run_repl(repl::REPL.AbstractREPL, consumer::Any)
    ╎    ╎  1851 .../usr/share/julia/stdlib/v1.6/REPL/src/REPL.jl:317; run_repl(repl::REPL.AbstractREPL, consumer::Any; backend_on_current_t...
    ╎    ╎   1851 .../usr/share/julia/stdlib/v1.6/REPL/src/REPL.jl:185; start_repl_backend(backend::REPL.REPLBackend, consumer::Any)
    ╎    ╎    1851 ...usr/share/julia/stdlib/v1.6/REPL/src/REPL.jl:200; repl_backend_loop(backend::REPL.REPLBackend)
    ╎    ╎     1851 ...usr/share/julia/stdlib/v1.6/REPL/src/REPL.jl:139; eval_user_input(ast::Any, backend::REPL.REPLBackend)
   1╎    ╎    ╎ 1851 @Base/boot.jl:360; eval(m::Module, e::Any)
    ╎    ╎    ╎  1849 /Users/gong/GitHub/covid19/myfunc.jl:4; myfunc()
    ╎    ╎    ╎   1849 @Plots/src/plot.jl:147; plot!(args::Any)
    ╎    ╎    ╎    1849 @Plots/src/plot.jl:153; plot!(args::Any; kw::Any)
    ╎    ╎    ╎     1849 @Plots/src/plot.jl:159; plot!(plt::Plots.Plot, args::Any)
    ╎    ╎    ╎    ╎ 1842 @Plots/src/plot.jl:162; #plot!#134
    ╎    ╎    ╎    ╎  1842 @Plots/src/plot.jl:172; _plot!(plt::Plots.Plot, plotattributes::Any, args::Any)
    ╎    ╎    ╎    ╎   1344 @RecipesPipeline/src/RecipesPipeline.jl:70; recipe_pipeline!(plt::Any, plotattributes::Any, args::Any)
   2╎    ╎    ╎    ╎    1295 @RecipesPipeline/src/user_recipe.jl:38; _process_userrecipes!(plt::Any, plotattributes::Any, args::Any)
   1╎    ╎    ╎    ╎     1287 @RecipesPipeline/src/utils.jl:233; userrecipe_signature_string(::Any, ::Vararg{Any, N} where N)
   3╎    ╎    ╎    ╎    ╎ 1272 @Base/broadcast.jl:883; materialize
    ╎    ╎    ╎    ╎    ╎  1269 @Base/broadcast.jl:1096; copy(bc::Base.Broadcast.Broadcasted{Base.Broadcast.Style{Tup...
    ╎    ╎    ╎    ╎    ╎   445  @Base/ntuple.jl:48; ntuple
    ╎    ╎    ╎    ╎    ╎    445  @Base/broadcast.jl:1096; #19
    ╎    ╎    ╎    ╎    ╎     445  @Base/broadcast.jl:621; _broadcast_getindex
    ╎    ╎    ╎    ╎    ╎    ╎ 445  @Base/broadcast.jl:648; _broadcast_getindex_evalf
    ╎    ╎    ╎    ╎    ╎    ╎  445  @Base/strings/io.jl:174; string
    ╎    ╎    ╎    ╎    ╎    ╎   445  @Base/strings/io.jl:135; print_to_string(xs::Type)
   1╎    ╎    ╎    ╎    ╎    ╎    445  @Base/strings/io.jl:35; print(io::IOBuffer, x::Type)
    ╎    ╎    ╎    ╎    ╎    ╎     443  @Base/show.jl:773; show(io::IOBuffer, x::Type)
   1╎    ╎    ╎    ╎    ╎    ╎    ╎ 440  @Base/show.jl:640; show_typealias(io::IOBuffer, x::Type)
    ╎    ╎    ╎    ╎    ╎    ╎    ╎  141  @Base/show.jl:554; make_typealias(x::Type)
    ╎    ╎    ╎    ╎    ╎    ╎    ╎   141  @Base/reflection.jl:98; names
  92╎    ╎    ╎    ╎    ╎    ╎    ╎    141  @Base/reflection.jl:98; #names#10
    ╎    ╎    ╎    ╎    ╎    ╎    ╎     49   @Base/sort.jl:735; sort!
    ╎    ╎    ╎    ╎    ╎    ╎    ╎    ╎ 49   @Base/sort.jl:747; #sort!#8
    ╎    ╎    ╎    ╎    ╎    ╎    ╎    ╎  49   @Base/sort.jl:687; sort!
    ╎    ╎    ╎    ╎    ╎    ╎    ╎    ╎   49   @Base/sort.jl:616; sort!
    ╎    ╎    ╎    ╎    ╎    ╎    ╎    ╎    19   @Base/sort.jl:622; sort!(v::Vector{Symbol}, lo::Int64, hi::Int64, a::...
    ╎    ╎    ╎    ╎    ╎    ╎    ╎    ╎     9    @Base/sort.jl:622; sort!(v::Vector{Symbol}, lo::Int64, hi::Int64, a:...
    ╎    ╎    ╎    ╎    ╎    ╎    ╎    ╎     9    @Base/sort.jl:623; sort!(v::Vector{Symbol}, lo::Int64, hi::Int64, a:...
    ╎    ╎    ╎    ╎    ╎    ╎    ╎    ╎    22   @Base/sort.jl:623; sort!(v::Vector{Symbol}, lo::Int64, hi::Int64, a::...
    ╎    ╎    ╎    ╎    ╎    ╎    ╎    ╎     10   @Base/sort.jl:622; sort!(v::Vector{Symbol}, lo::Int64, hi::Int64, a:...
  33╎    ╎    ╎    ╎    ╎    ╎    ╎  81   @Base/show.jl:555; make_typealias(x::Type)
  19╎    ╎    ╎    ╎    ╎    ╎    ╎   19   @Base/reflection.jl:244; isconst
  29╎    ╎    ╎    ╎    ╎    ╎    ╎   29   @Base/reflection.jl:102; isdeprecated
  45╎    ╎    ╎    ╎    ╎    ╎    ╎  52   @Base/show.jl:557; make_typealias(x::Type)
 120╎    ╎    ╎    ╎    ╎    ╎    ╎  120  @Base/show.jl:574; make_typealias(x::Type)
    ╎    ╎    ╎    ╎    ╎   424  @Base/ntuple.jl:50; ntuple
    ╎    ╎    ╎    ╎    ╎    424  @Base/broadcast.jl:1096; #19
    ╎    ╎    ╎    ╎    ╎     424  @Base/broadcast.jl:621; _broadcast_getindex
    ╎    ╎    ╎    ╎    ╎    ╎ 424  @Base/broadcast.jl:648; _broadcast_getindex_evalf
    ╎    ╎    ╎    ╎    ╎    ╎  424  @Base/strings/io.jl:174; string
    ╎    ╎    ╎    ╎    ╎    ╎   424  @Base/strings/io.jl:135; print_to_string(xs::Type)
   1╎    ╎    ╎    ╎    ╎    ╎    424  @Base/strings/io.jl:35; print(io::IOBuffer, x::Type)
    ╎    ╎    ╎    ╎    ╎    ╎     422  @Base/show.jl:773; show(io::IOBuffer, x::Type)
    ╎    ╎    ╎    ╎    ╎    ╎    ╎ 420  @Base/show.jl:640; show_typealias(io::IOBuffer, x::Type)
    ╎    ╎    ╎    ╎    ╎    ╎    ╎  105  @Base/show.jl:554; make_typealias(x::Type)
    ╎    ╎    ╎    ╎    ╎    ╎    ╎   105  @Base/reflection.jl:98; names
  59╎    ╎    ╎    ╎    ╎    ╎    ╎    105  @Base/reflection.jl:98; #names#10
    ╎    ╎    ╎    ╎    ╎    ╎    ╎     46   @Base/sort.jl:735; sort!
    ╎    ╎    ╎    ╎    ╎    ╎    ╎    ╎ 46   @Base/sort.jl:747; #sort!#8
    ╎    ╎    ╎    ╎    ╎    ╎    ╎    ╎  46   @Base/sort.jl:687; sort!
    ╎    ╎    ╎    ╎    ╎    ╎    ╎    ╎   46   @Base/sort.jl:616; sort!
    ╎    ╎    ╎    ╎    ╎    ╎    ╎    ╎    16   @Base/sort.jl:623; sort!(v::Vector{Symbol}, lo::Int64, hi::Int64, a::...
    ╎    ╎    ╎    ╎    ╎    ╎    ╎    ╎     8    @Base/sort.jl:623; sort!(v::Vector{Symbol}, lo::Int64, hi::Int64, a:...
    ╎    ╎    ╎    ╎    ╎    ╎    ╎    ╎    ╎ 5    @Base/sort.jl:623; sort!(v::Vector{Symbol}, lo::Int64, hi::Int64, a:...
  41╎    ╎    ╎    ╎    ╎    ╎    ╎  89   @Base/show.jl:555; make_typealias(x::Type)
  22╎    ╎    ╎    ╎    ╎    ╎    ╎   22   @Base/reflection.jl:244; isconst
  26╎    ╎    ╎    ╎    ╎    ╎    ╎   26   @Base/reflection.jl:102; isdeprecated
  32╎    ╎    ╎    ╎    ╎    ╎    ╎  43   @Base/show.jl:557; make_typealias(x::Type)
 144╎    ╎    ╎    ╎    ╎    ╎    ╎  144  @Base/show.jl:574; make_typealias(x::Type)
    ╎    ╎    ╎    ╎    ╎   400  @Base/ntuple.jl:69; ntuple
    ╎    ╎    ╎    ╎    ╎    400  @Base/ntuple.jl:74; macro expansion
    ╎    ╎    ╎    ╎    ╎     400  @Base/broadcast.jl:1096; #19
    ╎    ╎    ╎    ╎    ╎    ╎ 400  @Base/broadcast.jl:621; _broadcast_getindex
    ╎    ╎    ╎    ╎    ╎    ╎  400  @Base/broadcast.jl:648; _broadcast_getindex_evalf
    ╎    ╎    ╎    ╎    ╎    ╎   400  @Base/strings/io.jl:174; string
    ╎    ╎    ╎    ╎    ╎    ╎    400  @Base/strings/io.jl:135; print_to_string(xs::Type)
   1╎    ╎    ╎    ╎    ╎    ╎     400  @Base/strings/io.jl:35; print(io::IOBuffer, x::Type)
    ╎    ╎    ╎    ╎    ╎    ╎    ╎ 398  @Base/show.jl:773; show(io::IOBuffer, x::Type)
   2╎    ╎    ╎    ╎    ╎    ╎    ╎  398  @Base/show.jl:640; show_typealias(io::IOBuffer, x::Type)
    ╎    ╎    ╎    ╎    ╎    ╎    ╎   110  @Base/show.jl:554; make_typealias(x::Type)
    ╎    ╎    ╎    ╎    ╎    ╎    ╎    110  @Base/reflection.jl:98; names
  63╎    ╎    ╎    ╎    ╎    ╎    ╎     110  @Base/reflection.jl:98; #names#10
    ╎    ╎    ╎    ╎    ╎    ╎    ╎    ╎ 47   @Base/sort.jl:735; sort!
    ╎    ╎    ╎    ╎    ╎    ╎    ╎    ╎  47   @Base/sort.jl:747; #sort!#8
    ╎    ╎    ╎    ╎    ╎    ╎    ╎    ╎   47   @Base/sort.jl:687; sort!
    ╎    ╎    ╎    ╎    ╎    ╎    ╎    ╎    47   @Base/sort.jl:616; sort!
    ╎    ╎    ╎    ╎    ╎    ╎    ╎    ╎     21   @Base/sort.jl:622; sort!(v::Vector{Symbol}, lo::Int64, hi::Int64, a:...
    ╎    ╎    ╎    ╎    ╎    ╎    ╎    ╎    ╎ 10   @Base/sort.jl:623; sort!(v::Vector{Symbol}, lo::Int64, hi::Int64, a:...
    ╎    ╎    ╎    ╎    ╎    ╎    ╎    ╎    ╎  6    @Base/sort.jl:622; sort!(v::Vector{Symbol}, lo::Int64, hi::Int64, a...
    ╎    ╎    ╎    ╎    ╎    ╎    ╎    ╎     20   @Base/sort.jl:623; sort!(v::Vector{Symbol}, lo::Int64, hi::Int64, a:...
    ╎    ╎    ╎    ╎    ╎    ╎    ╎    ╎    ╎ 10   @Base/sort.jl:623; sort!(v::Vector{Symbol}, lo::Int64, hi::Int64, a:...
  39╎    ╎    ╎    ╎    ╎    ╎    ╎   78   @Base/show.jl:555; make_typealias(x::Type)
  16╎    ╎    ╎    ╎    ╎    ╎    ╎    17   @Base/reflection.jl:244; isconst
  22╎    ╎    ╎    ╎    ╎    ╎    ╎    22   @Base/reflection.jl:102; isdeprecated
  30╎    ╎    ╎    ╎    ╎    ╎    ╎   43   @Base/show.jl:557; make_typealias(x::Type)
 125╎    ╎    ╎    ╎    ╎    ╎    ╎   125  @Base/show.jl:574; make_typealias(x::Type)
    ╎    ╎    ╎    ╎   109  @RecipesPipeline/src/RecipesPipeline.jl:87; recipe_pipeline!(plt::Any, plotattributes::Any, args::Any)
    ╎    ╎    ╎    ╎    98   @Plots/src/pipeline.jl:145; plot_setup!(plt::Plots.Plot{Plots.GRBackend}, plotattributes::...
    ╎    ╎    ╎    ╎     78   @Plots/src/pipeline.jl:261; _subplot_setup(plt::Plots.Plot{Plots.GRBackend}, plotattribut...
    ╎    ╎    ╎    ╎    ╎ 69   @Plots/src/args.jl:1572; _update_subplot_args(plt::Plots.Plot{Plots.GRBackend}, sp::P...
    ╎    ╎    ╎    ╎    ╎  65   @Plots/src/args.jl:1499; _update_axis(plt::Plots.Plot{Plots.GRBackend}, sp::Plots.Sub...
    ╎    ╎    ╎    ╎    ╎   38   @Plots/src/args.jl:1522; _update_axis(axis::Plots.Axis, plotattributes_in::Dict{Symb...
    ╎    ╎    ╎    ╎    ╎    38   @Base/strings/basic.jl:229; Symbol
  29╎    ╎    ╎    ╎    ╎     29   @Base/boot.jl:480; Symbol
    ╎    ╎    ╎    ╎    ╎   20   @Plots/src/args.jl:1529; _update_axis(axis::Plots.Axis, plotattributes_in::Dict{Symb...
    ╎    ╎    ╎    ╎    ╎    12   @Plots/src/axes.jl:81; attr!
    ╎    ╎    ╎    ╎    ╎     11   @Plots/src/axes.jl:87; attr!(::Plots.Axis; kw::Base.Iterators.Pairs{Union{}, Unio...
    ╎    ╎    ╎    ╎   388  @RecipesPipeline/src/RecipesPipeline.jl:97; recipe_pipeline!(plt::Any, plotattributes::Any, args::Any)
    ╎    ╎    ╎    ╎    373  @RecipesPipeline/src/series_recipe.jl:27; _process_seriesrecipes!(plt::Any, kw_list::Any)
    ╎    ╎    ╎    ╎     371  @RecipesPipeline/src/series_recipe.jl:46; _process_seriesrecipe(plt::Any, plotattributes::Any)
    ╎    ╎    ╎    ╎    ╎ 152  @Plots/src/pipeline.jl:288; add_series!(plt::Plots.Plot{Plots.GRBackend}, plotattributes:...
   1╎    ╎    ╎    ╎    ╎  149  @Plots/src/pipeline.jl:300; _prepare_subplot(plt::Plots.Plot{Plots.GRBackend}, plotattri...
    ╎    ╎    ╎    ╎    ╎   124  @Plots/src/args.jl:1572; _update_subplot_args(plt::Plots.Plot{Plots.GRBackend}, sp::...
    ╎    ╎    ╎    ╎    ╎    115  @Plots/src/args.jl:1499; _update_axis(plt::Plots.Plot{Plots.GRBackend}, sp::Plots.S...
    ╎    ╎    ╎    ╎    ╎     66   @Plots/src/args.jl:1522; _update_axis(axis::Plots.Axis, plotattributes_in::RecipesP...
    ╎    ╎    ╎    ╎    ╎    ╎ 66   @Base/strings/basic.jl:229; Symbol
  47╎    ╎    ╎    ╎    ╎    ╎  47   @Base/boot.jl:480; Symbol
    ╎    ╎    ╎    ╎    ╎    ╎  19   @Base/strings/io.jl:174; string
    ╎    ╎    ╎    ╎    ╎    ╎   8    @Base/strings/io.jl:133; print_to_string(::Symbol, ::Vararg{Symbol, N} where N)
    ╎    ╎    ╎    ╎    ╎    ╎    8    @Base/iobuffer.jl:112; Type##kw
    ╎    ╎    ╎    ╎    ╎    ╎     8    @Base/iobuffer.jl:114; IOBuffer(; read::Bool, write::Bool, append::Nothing, tr...
    ╎    ╎    ╎    ╎    ╎    ╎    ╎ 5    @Base/iobuffer.jl:31; StringVector
   4╎    ╎    ╎    ╎    ╎    ╎    ╎  4    @Base/strings/string.jl:85; unsafe_wrap
    ╎    ╎    ╎    ╎    ╎    ╎   8    @Base/strings/io.jl:135; print_to_string(::Symbol, ::Vararg{Symbol, N} where N)
    ╎    ╎    ╎    ╎    ╎    ╎    7    @Base/show.jl:214; print
    ╎    ╎    ╎    ╎    ╎    ╎     7    @Base/io.jl:710; write
    ╎    ╎    ╎    ╎    ╎     25   @Plots/src/args.jl:1529; _update_axis(axis::Plots.Axis, plotattributes_in::RecipesP...
   1╎    ╎    ╎    ╎    ╎    ╎ 21   @Plots/src/axes.jl:81; attr!
    ╎    ╎    ╎    ╎    ╎    ╎  20   @Plots/src/axes.jl:87; attr!(::Plots.Axis; kw::Base.Iterators.Pairs{Union{}, Unio...
    ╎    ╎    ╎    ╎    ╎ 156  @Plots/src/pipeline.jl:290; add_series!(plt::Plots.Plot{Plots.GRBackend}, plotattributes:...
    ╎    ╎    ╎    ╎    ╎  133  @Plots/src/args.jl:1649; _update_series_attributes!(plotattributes::RecipesPipeline.D...
    ╎    ╎    ╎    ╎    ╎   130  @Plots/src/args.jl:1723; _series_index(plotattributes::RecipesPipeline.DefaultsDict,...
   2╎    ╎    ╎    ╎    ╎    130  @Plots/src/args.jl:1405; getindex
  42╎    ╎    ╎    ╎    ╎     42   @Base/Base.jl:33; getproperty
    ╎    ╎    ╎    ╎    ╎     86   @RecipesPipeline/src/utils.jl:18; getindex(dd::RecipesPipeline.DefaultsDict, k::Symbol)
    ╎    ╎    ╎    ╎    ╎    ╎ 74   @Base/dict.jl:550; haskey
    ╎    ╎    ╎    ╎    ╎    ╎  26   @Base/dict.jl:281; ht_keyindex(h::Dict{Symbol, Any}, key::Symbol)
  26╎    ╎    ╎    ╎    ╎    ╎   26   @Base/array.jl:197; length
    ╎    ╎    ╎    ╎    ╎    ╎  33   @Base/dict.jl:283; ht_keyindex(h::Dict{Symbol, Any}, key::Symbol)
  33╎    ╎    ╎    ╎    ╎    ╎   33   @Base/Base.jl:33; getproperty
    ╎    ╎    ╎    ╎    ╎ 53   @Plots/src/pipeline.jl:291; add_series!(plt::Plots.Plot{Plots.GRBackend}, plotattributes:...
    ╎    ╎    ╎    ╎    ╎  52   @Plots/src/pipeline.jl:348; _add_the_series(plt::Plots.Plot{Plots.GRBackend}, sp::Plots....
    ╎    ╎    ╎    ╎    ╎   31   @Plots/src/args.jl:1201; warn_on_unsupported_args(pkg::Plots.GRBackend, plotattribut...
   1╎    ╎    ╎    ╎    ╎    23   @Base/abstractdict.jl:64; iterate
  20╎    ╎    ╎    ╎    ╎     22   @RecipesPipeline/src/utils.jl:44; iterate(dd::RecipesPipeline.DefaultsDict, ::Tuple{Vector{Sy...
   1╎1    @Plots/src/pipeline.jl:52; is_subplot_attribute(plt::Plots.Plot{Plots.GRBackend}, attr::Symbol)
   2╎2    @RecipesPipeline/src/utils.jl:18; getindex(dd::RecipesPipeline.DefaultsDict, k::Symbol)
Total snapshots: 8404

@KristofferC
Copy link
Member

You can use the noisefloor keyword argument to filter out frames with very few traces. A value of 2 is usually pretty OK.

@truedichotomy
Copy link
Author

I restarted with clean Julia environment, ran the plotting code once, then reran the profiles for each version of Julia. The comments above are updated with the the noisefloor keyword set to 2.

@KristofferC
Copy link
Member

Okay, so it seems it is the showing of types that got slower? Maybe #37990?

@truedichotomy
Copy link
Author

truedichotomy commented Feb 5, 2021

Any chance this issue can be addressed before 1.6 release? It would be nice to be able take advantage of all the other advances that 1.6 has to offer, otherwise I'm stuck with 1.5 for my application.

@jebej
Copy link
Contributor

jebej commented Feb 5, 2021

As a fix, it looks as if this string computation in userrecipe_signature_string is only made to potentially display a warning here, in `warn_on_recipe_aliases!':
https://github.com/JuliaPlots/Plots.jl/blob/a955ded5c87fff9265c416da8c3b614f0c624878/src/pipeline.jl#L5-L20

If instead the string is computed only if the warning is determined to appear, this slowdown should go away. Is that correct @daschw?

@timholy
Copy link
Member

timholy commented Feb 5, 2021

In general type display is slow now because we search module namespaces for aliases for nicer printing. (I really like the new printing, but we should speed it up. CC @vtjnash.)

#36263 (comment)
#39366 (comment)

@JeffBezanson
Copy link
Member

You can also set :compact=>false to get the old printing (and its performance).

@truedichotomy
Copy link
Author

You can also set :compact=>false to get the old printing (and its performance).

Where do I set this when using Plots?

@JeffBezanson
Copy link
Member

It looks like it has to be done inside RecipesPipeline. But it also seems the type stringification it's doing is not even necessary (#39509 (comment)).

@jebej
Copy link
Contributor

jebej commented Feb 7, 2021

Where do I set this when using Plots?

This is not something you can do if you are just using the package. I've made an issue to track this in Plots: JuliaPlots/Plots.jl#3276

@PallHaraldsson
Copy link
Contributor

Should the issue be closed, since closed/fixed in Plots.jl? I do not want this to hold up Julia 1.6 release...

@jebej
Copy link
Contributor

jebej commented Feb 8, 2021

The fix for the Plots slowdown was merged. I don't know if there needs to be an issue for the type show method slowdown, though there's already #37990

@oscardssmith
Copy link
Member

I think #37990 is probably the best issue to track this, as it has a nice simple MWE.

Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment
Labels
performance Must go faster
Projects
None yet
Development

No branches or pull requests

9 participants