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

[FR] warn_on_unsupported_args a significant bottleneck when adding many series #4237

Closed
BioTurboNick opened this issue Jun 12, 2022 · 14 comments · Fixed by #4408
Closed

[FR] warn_on_unsupported_args a significant bottleneck when adding many series #4237

BioTurboNick opened this issue Jun 12, 2022 · 14 comments · Fixed by #4408
Labels
enhancement improving existing functionality performance speedups and slowdowns

Comments

@BioTurboNick
Copy link
Member

BioTurboNick commented Jun 12, 2022

In profiling the creation of a plot with many series, after #4235 and #4236, a significant bottleneck is warn_on_unsupported_args, with two lines taking up a combined 23% of samples: 1614 and 1623, which I believe is just both ends of the loop iterating over plot attributes. That's a lot of work just to inform people about deprecations.

This function is run every time a series is added.

Current (after the two prior PRs): 365.065 ms (2814346 allocations: 124.53 MiB)
Short-circuiting warn_on_unsupported_args: 252.194 ms (1170214 allocations: 69.42 MiB)

For perspective, when I started this profiling work, this plot was taking 8 seconds to generate. Once this (and the other two PRs) bottleneck is resolved, it'll be 250 ms, 32x faster.

There's a switch to turn warnings off, warn_on_unsupported, but this only prevents the warnings from being displayed, not from stopping the work from being done to check the attributes in the first place.

Inspection with Cthulhu shows some potential for type instability. The iteration also allocates an array for the keys each time, rather than performing a lazy iteration.

Potential solutions

  • Check if type stability can be improved
  • Consolidate so it only occurs once per plot call, regardless of how many series are added
  • Lazy iteration over the keys vs. allocating an array each time
Overhead ╎ [+additional indent] Count File:Line; Function
=========================================================
   ╎2555 @Base\task.jl:482; (::VSCodeServer.var"#60#61")()
   ╎ 2555 @VSCodeServer\src\eval.jl:34; macro expansion
   ╎  2555 @Base\essentials.jl:726; invokelatest(::Any)
   ╎   2555 @Base\essentials.jl:729; #invokelatest#2
   ╎    2555 @VSCodeServer\src\repl.jl:124; (::VSCodeServer.var"#77#79"{Module, Expr, REP...
   ╎     2555 @Base\logging.jl:623; with_logger
   ╎    ╎ 2555 @Base\logging.jl:511; with_logstate(f::Function, logstate::Any)
   ╎    ╎  2555 @VSCodeServer\src\repl.jl:123; (::VSCodeServer.var"#78#80"{Module, Expr, R...
   ╎    ╎   2555 @VSCodeServer\src\repl.jl:157; repleval(m::Module, code::Expr, #unused#::...
   ╎    ╎    2555 @Base\Base.jl:65; eval
   ╎    ╎     2555 @Base\boot.jl:368; eval
   ╎    ╎    ╎ 2555 ...1.8\Profile\src\Profile.jl:30; top-level scope
  1╎    ╎    ╎  2555 REPL[70]:1; macro expansion
   ╎    ╎    ╎   2554 @Plots\src\plot.jl:82; (::RecipesBase.var"#plot##kw")(::NamedTu...
   ╎    ╎    ╎    2554 @Plots\src\plot.jl:91; #plot#143
   ╎    ╎    ╎     2554 @Plots\src\plot.jl:208; _plot!(plt::Plots.Plot, plotattributes...
   ╎    ╎    ╎    ╎ 496  ...e\src\RecipesPipeline.jl:70; recipe_pipeline!(plt::Any, plotattribu...        
   ╎    ╎    ╎    ╎  232  ...eline\src\user_recipe.jl:34; _process_userrecipes!(plt::Any, plota...        
   ╎    ╎    ╎    ╎   220  ...line\src\user_recipe.jl:102; _finish_userrecipe!(plt::Plots.Plot{...        
   ╎    ╎    ╎    ╎    220  @Plots\src\pipeline.jl:46; preprocess_attributes!(plt::Plots.Pl...
  1╎    ╎    ╎    ╎     51   @Plots\src\args.jl:1447; preprocess_attributes!(plotattribu...
 20╎    ╎    ╎    ╎  159  ...eline\src\user_recipe.jl:36; _process_userrecipes!(plt::Any, plota...        
   ╎    ╎    ╎    ╎   128  ...Base\src\RecipesBase.jl:289; apply_recipe(plotattributes::Abstrac...
  4╎    ╎    ╎    ╎  92   ...eline\src\user_recipe.jl:38; _process_userrecipes!(plt::Any, plota...        
   ╎    ╎    ╎    ╎   86   ...ipesPipeline\src\api.jl:14; warn_on_recipe_aliases!(plt::Plots.Pl...        
  3╎    ╎    ╎    ╎    86   ...ipesPipeline\src\api.jl:18; warn_on_recipe_aliases!(plt::Plots.P...        
   ╎    ╎    ╎    ╎ 130  ...e\src\RecipesPipeline.jl:87; recipe_pipeline!(plt::Any, plotattribu...        
   ╎    ╎    ╎    ╎  112  @Plots\src\pipeline.jl:149; plot_setup!(plt::Plots.Plot{Plots.GRB...
   ╎    ╎    ╎    ╎   61   @Plots\src\pipeline.jl:253; _subplot_setup(plt::Plots.Plot{Plots...
  1╎    ╎    ╎    ╎    55   @Plots\src\args.jl:560; is_axis_attr(k::Symbol)
   ╎    ╎    ╎    ╎ 1915 ...e\src\RecipesPipeline.jl:97; recipe_pipeline!(plt::Any, plotattribu...
   ╎    ╎    ╎    ╎  63   ...ine\src\series_recipe.jl:14; _process_seriesrecipes!(plt::Any, kw_...        
   ╎    ╎    ╎    ╎   61   @Plots\src\pipeline.jl:342; slice_series_attributes!(plt::Plots....
   ╎    ╎    ╎    ╎  1830 ...ine\src\series_recipe.jl:27; _process_seriesrecipes!(plt::Any, kw_...        
 13╎    ╎    ╎    ╎   1806 ...ne\src\series_recipe.jl:46; _process_seriesrecipe(plt::Any, plota...        
   ╎    ╎    ╎    ╎    745  @Plots\src\pipeline.jl:351; add_series!(plt::Plots.Plot{Plots.GR...
   ╎    ╎    ╎    ╎     715  @Plots\src\pipeline.jl:377; _prepare_subplot(plt::Plots.Plot{Pl...
   ╎    ╎    ╎    ╎    ╎ 76   @Plots\src\args.jl:2070; _update_subplot_args(plt::Plots.Pl...
   ╎    ╎    ╎    ╎    ╎ 591  @Plots\src\args.jl:2078; _update_subplot_args(plt::Plots.Pl...
   ╎    ╎    ╎    ╎    ╎  547  @Plots\src\args.jl:1993; _update_axis(plt::Plots.Plot{Plot...
  4╎    ╎    ╎    ╎    ╎   381  @Plots\src\args.jl:2029; _update_axis(axis::Plots.Axis, pl...
 54╎    ╎    ╎    ╎    ╎    54   @Base\namedtuple.jl:313; merge(a::NamedTuple{(), Tuple{}},...
   ╎    ╎    ╎    ╎    ╎    316  @Plots\src\axes.jl:81; attr!
   ╎    ╎    ╎    ╎    ╎     309  @Plots\src\axes.jl:89; attr!(::Plots.Axis; kw::Base.Pai...
   ╎    ╎    ╎    ╎    133  @Plots\src\pipeline.jl:365; add_series!(plt::Plots.Plot{Plots.GR...
   ╎    ╎    ╎    ╎     124  @Plots\src\pipeline.jl:428; _expand_subplot_extrema(sp::Plots.S...
  3╎    ╎    ╎    ╎    ╎ 99   @Plots\src\axes.jl:465; expand_extrema!(sp::Plots.Subplot{...
 73╎    ╎    ╎    ╎    ╎  85   @Plots\src\axes.jl:430; expand_extrema!(axis::Plots.Axis, ...
   ╎    ╎    ╎    ╎    159  @Plots\src\pipeline.jl:367; add_series!(plt::Plots.Plot{Plots.GR...
   ╎    ╎    ╎    ╎    752  @Plots\src\pipeline.jl:368; add_series!(plt::Plots.Plot{Plots.GR...
   ╎    ╎    ╎    ╎     699  @Plots\src\pipeline.jl:438; _add_the_series(plt::Plots.Plot{Plo...
   ╎    ╎    ╎    ╎    ╎ 247  @Plots\src\args.jl:1614; warn_on_unsupported_args(pkg::Plot...
   ╎    ╎    ╎    ╎    ╎  245  @Base\abstractdict.jl:64; iterate
   ╎    ╎    ╎    ╎    ╎   179  ...Pipeline\src\utils.jl:38; iterate(dd::DefaultsDict)
   ╎    ╎    ╎    ╎    ╎    179  @Base\array.jl:712; collect
   ╎    ╎    ╎    ╎    ╎     55   @Base\array.jl:723; _collect(cont::UnitRange{Int64},...
   ╎    ╎    ╎    ╎    ╎    ╎ 55   @Base\iterators.jl:1147; iterate
   ╎    ╎    ╎    ╎    ╎    ╎  55   @Base\iterators.jl:1155; iterate
 55╎    ╎    ╎    ╎    ╎    ╎   55   @Base\tuple.jl:68; iterate
   ╎    ╎    ╎    ╎    ╎     111  @Base\array.jl:725; _collect(cont::UnitRange{Int64},...
 83╎    ╎    ╎    ╎    ╎    ╎ 107  @Base\iterators.jl:1148; iterate
  1╎    ╎    ╎    ╎    ╎ 350  @Plots\src\args.jl:1623; warn_on_unsupported_args(pkg::Plot...
  3╎    ╎    ╎    ╎    ╎  276  @Base\abstractdict.jl:64; iterate
236╎    ╎    ╎    ╎    ╎   266  ...Pipeline\src\utils.jl:44; iterate(dd::DefaultsDict, ::Tuple{...        
   ╎    ╎    ╎    ╎    ╎  71   @Base\abstractdict.jl:66; iterate
 61╎    ╎    ╎    ╎    ╎   61   @Base\tuple.jl:29; getindex
@BeastyBlacksmith BeastyBlacksmith added enhancement improving existing functionality performance speedups and slowdowns labels Jun 14, 2022
@BioTurboNick
Copy link
Member Author

BioTurboNick commented Sep 30, 2022

Revisiting, and hopefully solving. Starting point:

const xxxx = rand(10, 10000) # lots of small series
@profview plot(xxxx)

Time profiler:
image

And the allocation profiler:
image

@BioTurboNick
Copy link
Member Author

BioTurboNick commented Sep 30, 2022

Iterating over the DefaultsDict is very expensive.

The first iteration, which extracts the Plot (the first entry obtained), consumes 359 allocations totaling 21 KiB. (Why so much just to iterate?)

(UPDATE: Ah, I was missing a bit - the issue is the first iteration has a lot of overhead, unrelated to the item.)

Each subsequent member of the dictionary iterated over uses 3 allocations of ~100 bytes each

Every subsequent time the Plot is iterated (on a new series), it consumes 186 allocations totaling 8 KiB each time.

This warn_on_unsupported_arguments function has an O(M * N) impact on processing time, where N is the number of series and M is the number of dictionary entries.

@BioTurboNick
Copy link
Member Author

BioTurboNick commented Oct 1, 2022

Why is this function in RecipesPipeline defined this way, rather than just taking a union?

function Base.iterate(dd::DefaultsDict)
    exp_keys = keys(dd.explicit)
    def_keys = setdiff(keys(dd.defaults), exp_keys)
    key_list = collect(Iterators.flatten((exp_keys, def_keys))) # this line is the biggest memory hog
    iterate(dd, (key_list, 1))
end # (6.93 M allocations: 300.429 MiB)

function Base.iterate(dd::DefaultsDict)
    key_list = union!(collect(keys(dd.explicit)), keys(dd.defaults))
    iterate(dd, (key_list, 1))
end # (5.22 M allocations: 256.865 MiB)

Seems to be equivalent.

@BioTurboNick
Copy link
Member Author

BioTurboNick commented Oct 1, 2022

Is there any reason warn_on_unsupported_args needs to iterate over the default keys? It's just the explicit keys that could be a problem? @BeastyBlacksmith @t-bltg

Because if I restrict iteration to the explicit keys, I can cut the vast majority of the remaining allocations in this method.

(2.19 M allocations: 134.719 MiB)

Time:
image

Allocations:
image

@t-bltg
Copy link
Member

t-bltg commented Oct 1, 2022

Is there any reason warn_on_unsupported_args needs to iterate over the default keys

Where ?

@BioTurboNick
Copy link
Member Author

for k in keys(plotattributes)

@t-bltg
Copy link
Member

t-bltg commented Oct 1, 2022

Those aren't the default ones, but the modified attributes, no ?

@BioTurboNick
Copy link
Member Author

The DefaultsDict contains two dictionaries, and provides a unified view of the default and explicit keys, just with the explicit keys taking precedence.

@t-bltg
Copy link
Member

t-bltg commented Oct 1, 2022

Hi see. I see no valid reason to iterate over default keys which are by definition supported. Honestly, just by the look of the implementation of warn_on_unsupported_args it looks poorly coded. All these allocations just for some warnings are unjustified. So any effort towards removing them is justified. You have all my support for modifying the implementation.

@BioTurboNick
Copy link
Member Author

Thanks! The headache is really all due to the implementation of DefaultsDict iteration, which should probably be revised but that seems to be a bigger challenge.

@t-bltg
Copy link
Member

t-bltg commented Oct 1, 2022

Because if I restrict iteration to the explicit keys, I can cut the vast majority of the remaining allocations in this method.

Just by changing to keys(dd.explicit) ?

@BioTurboNick
Copy link
Member Author

Because if I restrict iteration to the explicit keys,

Just by changing to keys(dd.explicit) ?

Yep! But I'll add a method in RecipesPipeline so it's not accessing an internal directly.

@t-bltg
Copy link
Member

t-bltg commented Oct 1, 2022

Yep! But I'll add a method in RecipesPipeline so it's not accessing an internal directly.

PR, CI, merge & release at will ;)

@t-bltg
Copy link
Member

t-bltg commented Oct 1, 2022

The headache is really all due to the implementation of DefaultsDict iteration

Maybe another justification for #4359, please weigh in there if you concur.

Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment
Labels
enhancement improving existing functionality performance speedups and slowdowns
Projects
None yet
Development

Successfully merging a pull request may close this issue.

3 participants