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.
Today the formatter still uses some private APIs
and this commit aims to expose some of them.
In particular, Macro.classify_atom/1 was added to
expose if an atom is an alias, an identifier, quoted,
or unquoted.
Note that the API does not say anything about
operators, since they can fall within three distinct
categories:
* unquoted and callable, such as, `+`, `-`, and
most operators
* unquoted and not callable, such as, `.`, `..`,
and `..//`, which would be ambiguous when used
as `Module.OP()`
* quoted but callable, such as `::`, which is
ambiguous in the atom syntax but not as calls
This information still remains private, especially
because most times operators are used, we often still
want to learn about their precedence too.
We also exposed `inspect_atom/2` with three
distinct clauses to cover the different scenarios
atoms can be inspected at runtime and in source
code.
Jonatan Männchen
José Valim
Jean Klingler
Eksperimental
Ivan Rublev
José Valim
José Valim
Andrea Leopardi
Donald Little
Eric Meadows-Jönsson