You signed in with another tab or window. Reload to refresh your session.You signed out in another tab or window. Reload to refresh your session.You switched accounts on another tab or window. Reload to refresh your session.Dismiss alert
We have used this code:
data = Base.encode64(:crypto.strong_rand_bytes(2_000_000))
Mix.Tasks.Profile.Tprof.profile(
fn -> inspect(data, printable_limit: :infinity) end,
type: :memory
)
The first result reported this:
Profile results of #PID<0.106.0>
# CALLS % WORDS PER CALL
Total 10666685 100.00 9268308211 868.90
:code.ensure_loaded/1 1 0.00 3 3.00
Inspect.BitString.inspect/2 1 0.00 4 4.00
Inspect.Algebra.group/2 1 0.00 4 4.00
Inspect.Algebra.format/2 1 0.00 6 6.00
Inspect.Algebra.format/3 3 0.00 8 2.67
:erlang.iolist_to_binary/1 2 0.00 11 5.50
anonymous fn/2 in Kernel.struct/2 1 0.00 17 17.00
Inspect.Opts.new/1 1 0.00 17 17.00
Code.Identifier.escape/5 2666669 0.06 5333344 2.00
String.recur_printable?/2 2666669 0.29 26666778 10.00
Code.Identifier.escape_map/1 2666668 28.72 2662035405 998.26
Code.Identifier.escape_char/1 2666668 70.93 6574272614 2465.35
As you can see, most of the allocations were in escape_char,
which makes sense: it will be invoked a lot for raw binaries
and it allocated lists, instead of relying on binary optimizations.
We reimplemented Code.Identifier.escape/5 to rely on binary
optimizations which then yielded this:
Profile results of #PID<0.112.0>
# CALLS % WORDS PER CALL
Total 5333350 100.00 26666864 5.00
:code.ensure_loaded/1 1 0.00 3 3.00
Inspect.BitString.inspect/2 1 0.00 4 4.00
Inspect.Algebra.group/2 1 0.00 4 4.00
Inspect.Algebra.format/2 1 0.00 6 6.00
Code.Identifier.escape/4 1 0.00 8 8.00
Code.Identifier.escape/5 2666669 0.00 8 0.00
Inspect.Algebra.format/3 3 0.00 8 2.67
:erlang.iolist_to_binary/1 2 0.00 11 5.50
anonymous fn/2 in Kernel.struct/2 1 0.00 17 17.00
Inspect.Opts.new/1 1 0.00 17 17.00
String.recur_printable?/2 2666669 100.00 26666778 10.00
Now the allocations are all on `recur_printable?/2`. By running this
command, we can find out why it is allocating so much:
ERL_COMPILER_OPTIONS=bin_opt_info elixir lib/elixir/lib/string.ex
It happens that, due to a catch all, new binary contexts had to be
allocated. By addressing that, we now get:
Profile results of #PID<0.119.0>
# CALLS % WORDS PER CALL
Total 5333350 100.00 91 0.00
:code.ensure_loaded/1 1 3.30 3 3.00
Inspect.BitString.inspect/2 1 4.40 4 4.00
Inspect.Algebra.group/2 1 4.40 4 4.00
String.recur_printable?/2 2666669 5.49 5 0.00
Inspect.Algebra.format/2 1 6.59 6 6.00
Code.Identifier.escape/4 1 8.79 8 8.00
Code.Identifier.escape/5 2666669 8.79 8 0.00
Inspect.Algebra.format/3 3 8.79 8 2.67
:erlang.iolist_to_binary/1 2 12.09 11 5.50
anonymous fn/2 in Kernel.struct/2 1 18.68 17 17.00
Inspect.Opts.new/1 1 18.68 17 17.00
Which is several orders of magnitude fewer words. We basically
allocate the new escaped binary and a few extra bytes.
Closes#14029.
0 commit comments