Closes#15090.
Unfortunately, I could not write a test for this as the error
only happens when using actual I/O devices. When using the mock
device we use in tests, the warning appears as expected.
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.
José Valim
Łukasz Samson
José Valim
Eksperimental
Jonatan Männchen
Jean Klingler
Jonatan Kłosko
Matt Enlow
Wojtek Mach