Money.round drastic performance regression
Closed this issue · 10 comments
Hi, we've recently upgraded ex_money and noticed a pretty drastic slow-down that I've traced to Money.round.
Going from:
{:ex_cldr, "2.2.0"},
{:ex_cldr_currencies, "2.0.0"},
{:ex_cldr_numbers, "2.1.0"},
{:ex_money, "3.1.0"},...to:
{:ex_cldr, "2.2.4"},
{:ex_cldr_currencies, "2.1.1"},
{:ex_cldr_numbers, "2.1.1"},
{:ex_money, "3.2.3"},...affected the performance of Money.round making it about 20x slower. Here are some benchee benchmarks from BEFORE the upgrade:
Operating System: macOS
CPU Information: Intel(R) Core(TM) i7-8750H CPU @ 2.20GHz
Number of Available Cores: 12
Available memory: 16 GB
Elixir 1.8.0
Erlang 21.2.2
Benchmark suite executing with the following configuration:
warmup: 2 s
time: 5 s
memory time: 0 ns
parallel: 1
inputs: none specified
Estimated total run time: 28 s
Benchmarking add...
Benchmarking mult...
Benchmarking round...
Benchmarking sum...
Name ips average deviation median 99th %
sum 19.14 52.24 ms ±5.87% 51.29 ms 68.89 ms
add 11.87 84.23 ms ±14.23% 80.10 ms 123.34 ms
mult 10.97 91.20 ms ±16.01% 86.69 ms 137.41 ms
round 2.20 455.37 ms ±5.61% 447.31 ms 519.11 ms
Comparison:
sum 19.14
add 11.87 - 1.61x slower
mult 10.97 - 1.75x slower
round 2.20 - 8.72x slower
And here are the same benchmarks AFTER the upgrade:
Operating System: macOS
CPU Information: Intel(R) Core(TM) i7-8750H CPU @ 2.20GHz
Number of Available Cores: 12
Available memory: 16 GB
Elixir 1.8.0
Erlang 21.2.2
Benchmark suite executing with the following configuration:
warmup: 2 s
time: 5 s
memory time: 0 ns
parallel: 1
inputs: none specified
Estimated total run time: 28 s
Benchmarking add...
Benchmarking mult...
Benchmarking round...
Benchmarking sum...
Name ips average deviation median 99th %
sum 19.82 50.44 ms ±4.23% 50.11 ms 67.87 ms
add 11.38 87.87 ms ±13.55% 82.95 ms 129.83 ms
mult 10.88 91.94 ms ±12.81% 86.87 ms 133.62 ms
round 0.107 9385.01 ms ±0.00% 9385.01 ms 9385.01 ms
Comparison:
sum 19.82
add 11.38 - 1.74x slower
mult 10.88 - 1.82x slower
round 0.107 - 186.06x slower
You can see the average time for my round function went from ~455ms to ~9385ms.
I've since also upgraded to the very latest versions at the time of this writing, with similar results.
I'm not exactly sure where in the ecosystem this slow-down is coming from, wether or not it's purely from ex_money or maybe from ex_cldr or ex_cldr_numbers, which is why I've included all the relevant version numbers.
The repo I used to perform the benchmarks is available here: https://github.com/peek-travel/money_bench
The relevant benchmark code is:
monies = 1..100_000 |> Enum.map(fn i -> Money.new(:USD, i) end)
mult = fn monies -> Enum.map(monies, fn money -> Money.mult!(money, 2) end) end
add = fn monies -> Enum.map(monies, fn money -> Money.add!(money, money) end) end
round = fn monies -> Enum.map(monies, fn money -> Money.round(money) end) end
sum = fn monies -> Enum.reduce(monies, Money.zero(:USD), &Money.add!/2) end
Benchee.run(%{
"mult" => fn -> mult.(monies) end,
"add" => fn -> add.(monies) end,
"round" => fn -> round.(monies) end,
"sum" => fn -> sum.(monies) end
})Hoping we can get to the bottom of this, as we use ex_money in a critical code-path that is performance sensitive.
Thanks for your time and your amazing work on this and all related libraries!
@doughsay No doubt, thats not a good thing. Thanks for the detailed analysis. I will review in the next few hours.
Given the examples you show its quite surprising since the math operations and rounding delegate to to the Decimal package.
I did think at first it may have been a regression in Decimal, but the version of that package didn't change, so it pointed me towards ex_money instead. I looked through the diffs of ex_money, ex_cldr, ex_cldr_numbers and ex_cldr_currencies, but I couldn't find anything obvious to me...
Thanks for the clarification. Its very weird indeed and I haven't been able to dedicate enough time to working on this today, but I will get to the bottom of it over the weekend if not before.
Current theory (based upon just changing dependency versions one-by-one) is that its ex_cldr_currencies thats the issue. May I ask you to try to set your dependency for this to:
{:ex_cldr_currencies, "2.1.0"}
Using your benchmarking script, this is the version that delivers the original performance and 2.1.1 has the much slower performance.
As to why? Currently I have no idea but if setting this version gets you some performance back then its a start. I'll keep working on this and will build performance regression into the release process (when I work out how to automate that!)
I think i have it. It's a regression in Cldr.Currency.currency_for_code/2. Now to work out what the regression is and how to fix it. This function should be fast because all of the work is done at compile time. I'm assuming I've screwed that up in a commit between 2.1.0 and 2.1.1.
Hmmm, that's very interesting. I added profiling to my money_bench repo and it doesn't point me towards currency_for_code. The new versions seem to be making a lot of extra calls to Elixir.Cldr.Locale.known_gettext_locale_name/2 and Elixir.Cldr.Currency.currency_filter/2. See my profiling results below to see if they help you:
Before upgrade:
FUNCTION CALLS % TIME [uS / CALLS]
-------- ----- ------- ---- [----------]
erlang:send/2 1 0.00 0 [ 0.00]
code_server:call/1 5 0.00 2 [ 0.40]
code:ensure_loaded/1 5 0.00 3 [ 0.60]
code:call/1 5 0.00 3 [ 0.60]
error_handler:undefined_function/3 5 0.00 4 [ 0.80]
'Elixir.MoneyBench.Profile':'-do_analyze/0-fun-1-'/0 1 0.00 5 [ 5.00]
erlang:function_exported/3 5 0.00 6 [ 1.20]
erlang:module_loaded/1 5 0.00 6 [ 1.20]
erlang:whereis/1 5 0.00 7 [ 1.40]
erlang:demonitor/2 5 0.00 9 [ 1.80]
error_handler:ensure_loaded/1 5 0.00 12 [ 2.40]
erlang:monitor/2 5 0.00 22 [ 4.40]
lists:reverse/2 10000 0.05 1797 [ 0.18]
'Elixir.Money':do_round_to_nearest/4 100000 0.39 13936 [ 0.14]
'Elixir.Money':round/1 100000 0.41 14742 [ 0.15]
'Elixir.Decimal':context/1 100000 0.43 15488 [ 0.15]
'Elixir.Money':round/2 100000 0.44 16093 [ 0.16]
lists:reverse/1 100000 0.48 17441 [ 0.17]
erlang:list_to_integer/1 100000 0.51 18285 [ 0.18]
'Elixir.Money':round_to_nearest/2 100000 0.52 18752 [ 0.19]
erlang:'++'/2 100000 0.52 18826 [ 0.19]
'Elixir.Enum':find/3 200000 0.78 28313 [ 0.14]
'Elixir.Enum':find_list/3 200000 0.81 29173 [ 0.15]
'Elixir.Cldr.Currency':currency_for_code/2 200000 0.81 29235 [ 0.15]
'Elixir.Decimal':context/2 200000 0.81 29419 [ 0.15]
application:get_env/3 200000 0.82 29618 [ 0.15]
'Elixir.Money':increment_from_opts/2 100000 0.83 30041 [ 0.30]
elixir_aliases:concat/1 200000 0.83 30176 [ 0.15]
'Elixir.Enum':'-map/2-lists^map/1-0-'/2 100001 0.85 30630 [ 0.31]
'Elixir.MoneyBench.Profile':'-do_analyze/0-fun-0-'/1 100000 0.86 31217 [ 0.31]
'Elixir.Money':round_to_decimal_digits/2 100000 0.88 32006 [ 0.32]
'Elixir.Process':get/2 200000 0.89 32274 [ 0.16]
'Elixir.Application':get_env/3 200000 0.90 32674 [ 0.16]
'Elixir.Decimal':digits_to_integer/1 100000 0.91 32914 [ 0.33]
'Elixir.Keyword':get/3 100000 0.93 33819 [ 0.34]
application_controller:get_env/2 200000 0.94 34144 [ 0.17]
'Elixir.MoneyBench.Cldr':validate_locale/1 200000 0.95 34402 [ 0.17]
'Elixir.Decimal':round/3 100000 0.96 34669 [ 0.35]
'Elixir.Decimal':do_round/5 100000 0.98 35574 [ 0.36]
'Elixir.Decimal':reduce/1 100000 1.01 36476 [ 0.36]
'Elixir.MoneyBench.Cldr.Currency':currencies_for_locale/1 200000 1.04 37458 [ 0.19]
'Elixir.Enum':map/2 100001 1.05 38057 [ 0.38]
'Elixir.Map':get/3 200000 1.06 38265 [ 0.19]
'Elixir.Cldr.Currency':currency_for_code/3 200000 1.08 38910 [ 0.19]
erlang:put/2 200000 1.08 38917 [ 0.19]
'Elixir.Range':new/2 100000 1.09 39593 [ 0.40]
'Elixir.Enum':'-map/2-fun-0-'/3 211111 1.50 54333 [ 0.26]
'Elixir.Enum':reduce_range_inc/4 211111 1.56 56503 [ 0.27]
'Elixir.Enum':'-reduce/3-lists^foldl/2-0-'/3 400000 1.60 57837 [ 0.14]
'Elixir.Cldr.Currency':get_currency_metadata/2 200000 1.61 58197 [ 0.29]
'Elixir.Decimal':'-do_round/5-fun-0-'/1 211111 1.62 58462 [ 0.28]
application:get_env/2 200000 1.65 59720 [ 0.30]
'Elixir.Map':get/2 200000 1.67 60273 [ 0.30]
erlang:binary_to_atom/2 200000 1.67 60283 [ 0.30]
'Elixir.Process':put/2 200000 1.68 60880 [ 0.30]
'Elixir.Application':get_env/2 200000 1.69 60987 [ 0.30]
'Elixir.Money':default_backend/0 200000 1.70 61449 [ 0.31]
'Elixir.Keyword':merge/2 200000 1.70 61643 [ 0.31]
elixir_aliases:do_concat/2 400000 1.72 62088 [ 0.16]
'Elixir.Enum':find/2 200000 1.72 62335 [ 0.31]
'Elixir.Decimal':handle_error/4 200000 1.74 62962 [ 0.31]
'Elixir.Money':digits_from_opts/2 200000 1.74 63122 [ 0.32]
'Elixir.MoneyBench.Cldr':default_locale/0 200000 1.75 63248 [ 0.32]
'Elixir.Cldr':validate_currency/1 200000 1.82 65994 [ 0.33]
'Elixir.Cldr.Currency':currencies_for_locale/2 200000 1.82 66025 [ 0.33]
erlang:integer_to_list/1 300000 1.87 67548 [ 0.23]
'Elixir.Decimal':get_context/0 200000 1.87 67701 [ 0.34]
'Elixir.Money.Currency':currency_for_code/1 200000 1.88 67964 [ 0.34]
'Elixir.Decimal':set_context/1 200000 1.89 68445 [ 0.34]
'Elixir.Cldr':validate_locale/2 200000 1.90 68748 [ 0.34]
'Elixir.Decimal':put_uniq/2 200000 1.96 71069 [ 0.36]
'Elixir.Decimal':do_reduce/2 111111 2.00 72222 [ 0.65]
'Elixir.Decimal':precision/3 200000 2.01 72821 [ 0.36]
'Elixir.List':wrap/1 200000 2.12 76720 [ 0.38]
erlang:atom_to_binary/2 400000 2.14 77413 [ 0.19]
'Elixir.Module':concat/2 200000 2.18 79061 [ 0.40]
ets:lookup/2 200000 2.44 88273 [ 0.44]
lists:keyfind/3 600000 2.45 88615 [ 0.15]
'Elixir.Enum':reduce/3 400000 2.74 99042 [ 0.25]
elixir_aliases:do_concat/1 400000 2.93 106171 [ 0.27]
elixir_aliases:to_partial/1 200000 4.32 156479 [ 0.78]
'Elixir.Access':get/3 500000 4.44 160543 [ 0.32]
--------------------------------------------------------- -------- ------- ------- [----------]
Total: 13654498 100.00% 3618589 [ 0.27]
After upgrade:
FUNCTION CALLS % TIME [uS / CALLS]
-------- ----- ------- ---- [----------]
erlang:send/2 1 0.00 0 [ 0.00]
'Elixir.MoneyBench.Profile':'-do_analyze/0-fun-1-'/0 1 0.00 6 [ 6.00]
'Elixir.Money':do_round_to_nearest/4 100000 0.02 14784 [ 0.15]
'Elixir.Decimal':context/1 100000 0.02 15885 [ 0.16]
'Elixir.Money':round/1 100000 0.02 16046 [ 0.16]
'Elixir.Money':round/2 100000 0.02 18701 [ 0.19]
'Elixir.Money':round_to_nearest/2 100000 0.02 21083 [ 0.21]
erlang:list_to_integer/1 100000 0.02 21336 [ 0.21]
erlang:'++'/2 100000 0.02 21927 [ 0.22]
'Elixir.Cldr.Currency':currency_for_code/2 200000 0.03 30493 [ 0.15]
'Elixir.Cldr.Config':locale_name_to_posix/1 200000 0.03 30568 [ 0.15]
elixir_aliases:concat/1 200000 0.03 32514 [ 0.16]
application:get_env/3 200000 0.03 32591 [ 0.16]
'Elixir.Decimal':context/2 200000 0.03 33341 [ 0.17]
'Elixir.Money':increment_from_opts/2 100000 0.04 35456 [ 0.35]
'Elixir.Cldr.Locale':locale_name_to_posix/1 200000 0.04 35972 [ 0.18]
'Elixir.Process':get/2 200000 0.04 36038 [ 0.18]
'Elixir.Decimal':digits_to_integer/1 100000 0.04 36384 [ 0.36]
'Elixir.MoneyBench.Profile':'-do_analyze/0-fun-0-'/1 100000 0.04 36731 [ 0.37]
'Elixir.Money':round_to_decimal_digits/2 100000 0.04 36982 [ 0.37]
erlang:put/2 200000 0.04 37672 [ 0.19]
'Elixir.Range':new/2 100000 0.04 39334 [ 0.39]
'Elixir.Cldr.Locale':put_gettext_locale_name/2 200000 0.04 39344 [ 0.20]
'Elixir.Application':get_env/3 200000 0.04 39659 [ 0.20]
'Elixir.Decimal':round/3 100000 0.04 39827 [ 0.40]
'Elixir.Enum':'-map/2-lists^map/1-0-'/2 100001 0.04 40230 [ 0.40]
'Elixir.MoneyBench.Cldr':validate_locale/1 200000 0.04 40279 [ 0.20]
'Elixir.Map':get/3 200000 0.04 40592 [ 0.20]
'Elixir.Decimal':reduce/1 100000 0.04 42354 [ 0.42]
'Elixir.Keyword':get/3 100000 0.04 42735 [ 0.43]
'Elixir.Cldr.Currency':currencies_for_locale/3 200000 0.04 42952 [ 0.21]
application_controller:get_env/2 200000 0.04 43549 [ 0.22]
'Elixir.Decimal':do_round/5 100000 0.05 44309 [ 0.44]
'Elixir.Map':new/1 200000 0.05 45794 [ 0.23]
'Elixir.MoneyBench.Cldr.Currency':currencies_for_locale/2 200000 0.05 46189 [ 0.23]
'Elixir.Enum':map/2 100001 0.05 47510 [ 0.48]
'Elixir.Enum':'-map/2-fun-0-'/3 211111 0.05 53026 [ 0.25]
'Elixir.Enum':reduce_range_inc/4 211111 0.06 55246 [ 0.26]
'Elixir.Cldr.Currency':currency_for_code/3 200000 0.06 56650 [ 0.28]
'Elixir.Application':get_env/2 200000 0.06 57800 [ 0.29]
'Elixir.Cldr.Currency':get_currency_metadata/2 200000 0.06 57965 [ 0.29]
'Elixir.Decimal':do_reduce/2 111111 0.06 59209 [ 0.53]
'Elixir.Decimal':'-do_round/5-fun-0-'/1 211111 0.06 60170 [ 0.29]
'Elixir.Enum':'-reduce/3-lists^foldl/2-0-'/3 400000 0.06 61726 [ 0.15]
maps:iterator/1 200000 0.07 64163 [ 0.32]
lists:reverse/1 300000 0.07 64704 [ 0.22]
'Elixir.Process':put/2 200000 0.07 65752 [ 0.33]
'Elixir.List':wrap/1 200000 0.07 66714 [ 0.33]
application:get_env/2 200000 0.07 66882 [ 0.33]
elixir_aliases:do_concat/2 400000 0.07 68010 [ 0.17]
'Elixir.Keyword':merge/2 200000 0.07 68944 [ 0.34]
'Elixir.Decimal':handle_error/4 200000 0.07 69962 [ 0.35]
'Elixir.Decimal':put_uniq/2 200000 0.07 70513 [ 0.35]
'Elixir.Map':get/2 200000 0.07 71099 [ 0.36]
'Elixir.Money':default_backend/0 200000 0.08 73285 [ 0.37]
'Elixir.Decimal':set_context/1 200000 0.08 73794 [ 0.37]
'Elixir.Money':digits_from_opts/2 200000 0.08 74049 [ 0.37]
erlang:binary_to_atom/2 200000 0.08 74325 [ 0.37]
'Elixir.Cldr.Currency':currencies_for_locale/2 200000 0.08 75463 [ 0.38]
'Elixir.Decimal':get_context/0 200000 0.08 75731 [ 0.38]
'Elixir.Cldr.Locale':first_match/2 200000 0.08 76193 [ 0.38]
erlang:integer_to_list/1 300000 0.08 76277 [ 0.25]
'Elixir.Decimal':precision/3 200000 0.08 78714 [ 0.39]
'Elixir.MoneyBench.Cldr':default_locale/0 200000 0.08 79542 [ 0.40]
maps:fold/3 200000 0.08 80171 [ 0.40]
'Elixir.Cldr':validate_locale/2 200000 0.08 80805 [ 0.40]
'Elixir.Cldr':validate_currency/1 200000 0.08 81006 [ 0.41]
'Elixir.Cldr.Locale':gettext_locale_name/2 200000 0.09 84568 [ 0.42]
'Elixir.Money.Currency':currency_for_code/1 200000 0.09 85348 [ 0.43]
erlang:atom_to_binary/2 400000 0.10 93322 [ 0.23]
'Elixir.Enum':filter/2 200000 0.10 95103 [ 0.48]
'Elixir.Module':concat/2 200000 0.10 98280 [ 0.49]
'Elixir.Enum':reduce/3 400000 0.10 100090 [ 0.25]
lists:keyfind/3 600000 0.11 103100 [ 0.17]
ets:lookup/2 200000 0.11 111306 [ 0.56]
elixir_aliases:do_concat/1 400000 0.13 121291 [ 0.30]
elixir_aliases:to_partial/1 200000 0.16 159003 [ 0.80]
'Elixir.Access':get/3 500000 0.18 176856 [ 0.35]
'Elixir.Enum':find/3 1800000 0.26 254028 [ 0.14]
'Elixir.Enum':find_list/3 1800000 0.27 260656 [ 0.14]
'Elixir.Enum':join/2 1600000 0.27 266012 [ 0.17]
'Elixir.Cldr.Locale':known_gettext_locale_name/2 1600000 0.30 287755 [ 0.18]
lists:reverse/2 210006 0.34 333858 [ 1.59]
erlang:iolist_to_binary/1 1619259 0.37 353435 [ 0.22]
'Elixir.Enum':reject/2 1600000 0.46 445729 [ 0.28]
'Elixir.Cldr.Locale':'-gettext_locale_name/2-fun-0-'/2 1600000 0.48 463148 [ 0.29]
'Elixir.MoneyBench.Cldr':known_gettext_locale_names/0 1600000 0.48 464147 [ 0.29]
'Elixir.Enum':find/2 1800000 0.53 514298 [ 0.29]
erts_internal:map_next/3 457410 0.81 780689 [ 1.71]
'Elixir.Cldr.Locale':locale_name_from/4 3200000 0.83 803288 [ 0.25]
'Elixir.Enum':'-join/2-fun-0-'/3 3200000 0.93 897753 [ 0.28]
'Elixir.Enum':'-join/2-lists^foldl/2-0-'/3 4800000 0.99 962824 [ 0.20]
'Elixir.Enum':reject_list/2 8000000 1.67 1621065 [ 0.20]
'Elixir.Cldr.Locale':'-locale_name_from/4-fun-0-'/1 6400000 1.85 1794245 [ 0.28]
maps:from_list/1 200000 3.38 3275099 [ 16.38]
maps:fold_1/3 60800000 9.20 8907204 [ 0.15]
'Elixir.Enum':'-filter/2-fun-0-'/3 60600000 9.45 9146954 [ 0.15]
'Elixir.Cldr.Currency':currency_filter/2 60800000 9.47 9171169 [ 0.15]
'Elixir.Cldr.Currency':'-currency_filter/2-fun-1-'/2 60600000 17.31 16762081 [ 0.28]
maps:next/1 60800000 17.70 17133889 [ 0.28]
'Elixir.Enum':'-filter/2-anonymous-1-'/4 60600000 17.95 17378499 [ 0.29]
--------------------------------------------------------- --------- ------- -------- [----------]
Total: 420931123 100.00% 96823149 [ 0.23]
The code I ran:
defmodule MoneyBench.Profile do
import ExProf.Macro
@monies 1..100_000 |> Enum.map(fn i -> Money.new(:USD, i) end)
def do_analyze do
profile do
Enum.map(@monies, fn money -> Money.round(money) end)
end
end
@doc "get analysis records and sum them up"
def run do
{records, _block_result} = do_analyze()
total_percent = Enum.reduce(records, 0.0, &(&1.percent + &2))
IO.inspect("total = #{total_percent}")
end
end
MoneyBench.Profile.run()Yes, the root cause is the call to currency_filter which is doing a lot of unnecessary work for the default case of all currencies. I have a fix in and I'm testing now. Cldr.Currency.currencies_for_locale/2 calls currency_filter and currency_filter isn't behaving nicely.
New release pushed and a new version 2.1.4 published. There is a marginal difference in performance from the original version and I'll keep working on that but I believe this release should get your performance back. Please let me know if you see differently.
@doughsay I can confirm that with the following upgrade, our performance is back where we were at previously! Thanks @kipcole9 for the quick fix... and any other performance improvements are always welcome as, like @doughsay said, we have a critical path with many-a-money..
Upgraded:
ex_cldr 2.2.0 => 2.2.5
ex_cldr_currencies 2.0.0 => 2.1.4
ex_cldr_numbers 2.1.0 => 2.1.1
ex_money 3.1.0 => 3.2.4
Very glad to hear its back to where it was. Sorry for the inconvenience. Ive posted a question on the Elixir Forum seeking feedback on good ways to build performance regression testing into a CI and release cycle.
One of the things I noticed in the profiling above is a lot of time spend in resolving locale names (ie en) and transforming them to language tags (ie %Cldr.LanguageTag{...}). Most function in cldr_* work by first resolving the locale name into a language tag. This is done in the call to Cldr.validate_locale/2.
For configured locale names this is quick since the language tag is pre-generated at compile time. But I can't know in advance the gettext configuration so gettext locale name resolution occurs each call to Cldr.validate_locale/2.
Maybe there is a way in your code to resolve the locale name into a %Cldr.LanguageTag{} early in your request cycle and always pass that around instead of the locale name binary.
I don't think it will rock your world, but I suspect i may help.
I'm going to close this issue now, but feel free to open any others regarding areas of performance improvement you can see - or are getting in your way.