[Elixir] 指定文字数以下かどうかを判定するために String.length/1 を使うのはやめたほうがいいかもしれない

## はじめに

- タイトルの話 => [Benchee でベンチマークしてみた](#benchee-でベンチマークしてみた)
    - N 番煎じな気もしますが、一番キャッチーかなと思ったのでタイトルにしてみました。
- 気になるところをもう少し詳しく調べてみた => [メモリ使用量が多いのはどうして](#メモリ使用量が多いのはどうして)
    - tail-recursive だからといってメモリ的に安心という訳ではなさそうという話です。
- この記事を書いたきっかけ => [OTP 22 になってから `String.length/1` のメモリ使用量が増えた気がする](#otp-22-になってから-stringlength1-のメモリ使用量が増えた気がする)
    - OTP 22 のリリースは 2 年以上前ですが、せっかくなので記事に入れてみました。

## Benchee でベンチマークしてみた

引数で渡した string の長さが指定した文字数よりも小さければ true そうでなければ false を返す関数を考えてみます。

```elixir
defmodule MyString do
  def less_than1(string, n) do
    String.length(string) < n
  end

  def less_than2(string, n) do
    String.at(string, n - 1) == nil
  end

  def less_than3(string, n) do
    case String.split_at(string, n - 1) do
      {_, ""} -> true
      _ -> false
    end
  end
end
```

`String.length/1` を使った実装では、末尾まで走査するため、渡した string が長い分だけパフォーマンスが悪化するようです。
このあたりの話は [公式ドキュメント](https://hexdocs.pm/elixir/1.12/String.html#module-string-and-binary-operations) にも書いてあります。
一方、`String.at/2` と `String.split_at/2` を使った実装では、指定した文字数までしか走査しないため、渡した string が長くてもパフォーマンスはほぼ変わらないようです。
この 2 つの関数を使った結果は似たようなものだったので、どちらを使うかは用途を踏まえて考えればよさそうです。

[Benchee](https://github.com/bencheeorg/benchee) でのベンチマークには、下記のようなコードを使いました。

```elixir
s500 = String.duplicate("ありがとう", 100)
s50k = String.duplicate("ありがとう", 10_000)
s5M = String.duplicate("ありがとう", 1_000_000)

Benchee.run([
  {"String.length/1",   fn {input, n} -> MyString.less_than1(input, n) end},
  {"String.at/2",       fn {input, n} -> MyString.less_than2(input, n) end},
  {"String.split_at/2", fn {input, n} -> MyString.less_than3(input, n) end},
], [
  inputs: [
    {"s500,500", {s500, 500}},
    {"s50k,500", {s50k, 500}},
    {"s5M,500", {s5M, 500}},
    {"s500,50k", {s500, 50_000}},
    {"s50k,50k", {s50k, 50_000}},
    {"s5M,50k", {s5M, 50_000}},
  ],
  time: 5,
  memory_time: 1,
])
```

出力は以下でした。
（記事には簡潔にまとめたものを載せたほうが良いかもと思いつつ、そのまま。。。）

```
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.9.4
Erlang 22.3.4.20

Benchmark suite executing with the following configuration:
warmup: 2 s
time: 5 s
memory time: 1 s
parallel: 1
inputs: s500,500, s50k,500, s5M,500, s500,50k, s50k,50k, s5M,50k
Estimated total run time: 2.40 min

Benchmarking String.length/1 with input s500,500...
Benchmarking String.length/1 with input s50k,500...
Benchmarking String.length/1 with input s5M,500...
Benchmarking String.length/1 with input s500,50k...
Benchmarking String.length/1 with input s50k,50k...
Benchmarking String.length/1 with input s5M,50k...
Benchmarking String.at/2 with input s500,500...
Benchmarking String.at/2 with input s50k,500...
Benchmarking String.at/2 with input s5M,500...
Benchmarking String.at/2 with input s500,50k...
Benchmarking String.at/2 with input s50k,50k...
Benchmarking String.at/2 with input s5M,50k...
Benchmarking String.split_at/2 with input s500,500...
Benchmarking String.split_at/2 with input s50k,500...
Benchmarking String.split_at/2 with input s5M,500...
Benchmarking String.split_at/2 with input s500,50k...
Benchmarking String.split_at/2 with input s50k,50k...
Benchmarking String.split_at/2 with input s5M,50k...

##### With input s500,500 #####
Name                        ips        average  deviation         median         99th %
String.length/1         10.59 K       94.47 μs    ±47.67%          80 μs         271 μs
String.split_at/2        9.88 K      101.21 μs    ±39.89%          88 μs         237 μs
String.at/2              9.75 K      102.51 μs    ±39.29%          88 μs         235 μs

Comparison:
String.length/1         10.59 K
String.split_at/2        9.88 K - 1.07x slower +6.74 μs
String.at/2              9.75 K - 1.09x slower +8.04 μs

Memory usage statistics:

Name                 Memory usage
String.length/1          50.82 KB
String.split_at/2        50.73 KB - 1.00x memory usage -0.09375 KB
String.at/2              50.83 KB - 1.00x memory usage +0.00781 KB

**All measurements for memory usage were the same**

##### With input s50k,500 #####
Name                        ips        average  deviation         median         99th %
String.at/2              9.59 K      104.30 μs    ±38.83%          91 μs         239 μs
String.split_at/2        9.24 K      108.28 μs    ±45.60%          92 μs         284 μs
String.length/1         0.135 K     7382.42 μs     ±4.02%        7298 μs     8219.26 μs

Comparison:
String.at/2              9.59 K
String.split_at/2        9.24 K - 1.04x slower +3.97 μs
String.length/1         0.135 K - 70.78x slower +7278.12 μs

Memory usage statistics:

Name                 Memory usage
String.at/2              50.83 KB
String.split_at/2        50.73 KB - 1.00x memory usage -0.10156 KB
String.length/1        5078.16 KB - 99.91x memory usage +5027.34 KB

**All measurements for memory usage were the same**

##### With input s5M,500 #####
Name                        ips        average  deviation         median         99th %
String.split_at/2        9.59 K      104.24 μs    ±38.89%          89 μs         230 μs
String.at/2              9.30 K      107.53 μs    ±56.76%          92 μs         255 μs
String.length/1       0.00134 K   748814.86 μs     ±2.73%      737895 μs      782073 μs

Comparison:
String.split_at/2        9.59 K
String.at/2              9.30 K - 1.03x slower +3.29 μs
String.length/1       0.00134 K - 7183.54x slower +748710.62 μs

Memory usage statistics:

Name                 Memory usage
String.split_at/2        50.73 KB
String.at/2              50.83 KB - 1.00x memory usage +0.102 KB
String.length/1      507812.54 KB - 10010.78x memory usage +507761.81 KB

**All measurements for memory usage were the same**

##### With input s500,50k #####
Name                        ips        average  deviation         median         99th %
String.length/1         10.39 K       96.25 μs    ±45.01%          82 μs         244 μs
String.at/2             10.04 K       99.64 μs    ±40.19%          86 μs         236 μs
String.split_at/2        9.87 K      101.35 μs    ±40.96%          87 μs         239 μs

Comparison:
String.length/1         10.39 K
String.at/2             10.04 K - 1.04x slower +3.39 μs
String.split_at/2        9.87 K - 1.05x slower +5.09 μs

Memory usage statistics:

Name                 Memory usage
String.length/1          50.82 KB
String.at/2              50.84 KB - 1.00x memory usage +0.0234 KB
String.split_at/2        50.87 KB - 1.00x memory usage +0.0469 KB

**All measurements for memory usage were the same**

##### With input s50k,50k #####
Name                        ips        average  deviation         median         99th %
String.length/1          133.89        7.47 ms     ±6.73%        7.33 ms        9.39 ms
String.at/2              124.53        8.03 ms     ±3.53%        7.98 ms        8.81 ms
String.split_at/2        116.00        8.62 ms    ±24.43%        8.15 ms       21.07 ms

Comparison:
String.length/1          133.89
String.at/2              124.53 - 1.08x slower +0.56 ms
String.split_at/2        116.00 - 1.15x slower +1.15 ms

Memory usage statistics:

Name                 Memory usage
String.length/1           4.96 MB
String.at/2               4.96 MB - 1.00x memory usage +0.00001 MB
String.split_at/2         4.96 MB - 1.00x memory usage -0.00009 MB

**All measurements for memory usage were the same**

##### With input s5M,50k #####
Name                        ips        average  deviation         median         99th %
String.split_at/2        124.68        8.02 ms     ±4.57%        7.94 ms        9.04 ms
String.at/2              119.93        8.34 ms     ±4.45%        8.32 ms        9.89 ms
String.length/1            1.29      775.97 ms     ±1.77%      776.32 ms      794.00 ms

Comparison:
String.split_at/2        124.68
String.at/2              119.93 - 1.04x slower +0.32 ms
String.length/1            1.29 - 96.74x slower +767.95 ms

Memory usage statistics:

Name                 Memory usage
String.split_at/2         4.96 MB
String.at/2               4.96 MB - 1.00x memory usage +0.00010 MB
String.length/1         495.91 MB - 100.00x memory usage +490.95 MB

**All measurements for memory usage were the same**
```

## メモリ使用量が多いのはどうして

前述のベンチマーク結果について、走査する量が増えるので結果を返すまでの時間が長くなるのは分かるのですが、メモリ使用量もやたら多い気がします。
[実装](https://github.com/elixir-lang/elixir/blob/v1.9.4/lib/elixir/unicode/unicode.ex#L264) を見ると tail-recursive になっているので、stack が膨れ上がっているわけではなさそうです。
自分なりの結論から書くと、再帰関数の引数がシンプルな形（list の tail そのままとか）になっていないと heap の使用量が大きくなってしまうみたいです。

シンプルな実装を使ってもう少し詳しく調べてみました。
`len_by_tail_recursion2/2` では、所謂 ok tuple に包んで残りの部分を次の関数に渡しています。

```elixir
defmodule MyRecursion do
  def len_by_body_recursion(<<>>), do: 0
  def len_by_body_recursion(<<_::utf8, rest::binary>>) do
    len_by_body_recursion(rest) + 1
  end

  def len_by_tail_recursion(str), do: len_by_tail_recursion(str, 0)

  def len_by_tail_recursion(<<>>, acc), do: acc
  def len_by_tail_recursion(<<_::utf8, rest::binary>>, acc) do
    len_by_tail_recursion(rest, acc + 1)
  end

  def len_by_tail_recursion2(str), do: len_by_tail_recursion2({:ok, str}, 0)

  def len_by_tail_recursion2({:ok, <<>>}, acc), do: acc
  def len_by_tail_recursion2({:ok, <<_::utf8, rest::binary>>}, acc) do
    len_by_tail_recursion2({:ok, rest}, acc + 1)
  end
end
```

先ほどと同様に Benchee を使ってベンチマークしてみます。

```elixir
Benchee.run([
  {"len_by_body_recursion/1", &MyRecursion.len_by_body_recursion(&1)},
  {"len_by_tail_recursion/1", &MyRecursion.len_by_tail_recursion(&1)},
  {"len_by_tail_recursion2/1", &MyRecursion.len_by_tail_recursion2(&1)},
], [
  inputs: [
    {"s5M", s5M},
  ],
  time: 5,
  memory_time: 1,
])
```

下記が出力の要約です。

```
// IPS
len_by_tail_recursion/1           6.61
len_by_body_recursion/1           6.08 - 1.09x slower +13.04 ms
len_by_tail_recursion2/1          2.80 - 2.36x slower +206.14 ms
// Memory
len_by_tail_recursion/1             40 B
len_by_body_recursion/1             40 B - 1.00x memory usage +0 B
len_by_tail_recursion2/1     520000304 B - 13000007.60x memory usage +520000264 B
```

- シンプルな tail-recursive が一番速い
- tail-recursive と body-recursive のメモリ使用量が同じ。。。？
    - これは Benchee が stack を [計算に入れていない](https://github.com/bencheeorg/benchee/blob/1.0.1/lib/benchee/benchmark/collect/memory.ex#L143-L148) からで、実際のところ stack size は body-recursive のほうが大きくなります。
- ok tuple に包んだだけでメモリ使用量がすごく大きくなっている！
- ちなみに、ここでは binary を使った再帰ですが、list を使った再帰でも同様の傾向になりました。

どうしてこうなるのかは結局よく分からなかったのですが、実際の heap と disassemble した beam ファイルを見てみると、メモリをたくさん使っていそうな雰囲気だけは確認できました。

### heap を見てみる

`len_by_tail_recursion/1` では、コードのデータが大部分を占めていて、再帰に起因するデータはほとんどないようでした。
使用領域自体も小さいです。

```elixir
iex> a2n = Enum.map_join(?あ..?ん, &(<<&1::utf8>>))
iex> Process.spawn(fn ->
...>   MyRecursion.len_by_tail_recursion(a2n)
...>   :hipe_bifs.show_heap(self())
...> end, min_heap_size: 1_000) # GC を抑制
From: 0x0000000021315850 to 0x0000000021315dd8
 |                 H E A P                 |
 |            Address |           Contents |
 |--------------------|--------------------|
 # 略
 | 0x0000000021315b80 | 0x00000000000000c0 | Arity(3)
 | 0x0000000021315b88 | 0x000000000000a10b | value
 | 0x0000000021315b90 | 0x00000000000acb0b | 'Elixir.MyRecursion'
 | 0x0000000021315b98 | 0x00000000213158c1 | [{'_@0',<<227,129,130,227,129,131,227,129,132,227,129,133,227,129,134,227,129,135,227,129,136,227,129,137...
 | 0x0000000021315ba0 | 0x00000000000000c0 | Arity(3)
 | 0x0000000021315ba8 | 0x000000000000a10b | value
 | 0x0000000021315bb0 | 0x00000000000aaf8b | len_by_tail_recursion
 | 0x0000000021315bb8 | 0x00000000213158c1 | [{'_@0',<<227,129,130,227,129,131,227,129,132,227,129,133,227,129,134,227,129,135,227,129,136,227,129,137...
 | 0x0000000021315bc0 | 0x0000000000000080 | Arity(2)
 | 0x0000000021315bc8 | 0x0000000000006f0b | ok
 | 0x0000000021315bd0 | 0x0000000021315b3a | <<227,129,130,227,129,131,227,129,132,227,129,133,227,129,134,227,129,135,227,129,136,227,129,137,227,129,138,227,129,139...
 | 0x0000000021315bd8 | 0x0000000000000080 | Arity(2)
 | 0x0000000021315be0 | 0x0000000000006f0b | ok
 | 0x0000000021315be8 | 0x0000000021315b3a | <<227,129,130,227,129,131,227,129,132,227,129,133,227,129,134,227,129,135,227,129,136,227,129,137,227,129,138,227,129,139...
 | 0x0000000021315bf0 | 0x0000000000000080 | Arity(2)
 | 0x0000000021315bf8 | 0x000000000000a10b | value
 | 0x0000000021315c00 | 0x0000000021315b3a | <<227,129,130,227,129,131,227,129,132,227,129,133,227,129,134,227,129,135,227,129,136,227,129,137,227,129,138,227,129,139...
 | 0x0000000021315c08 | 0x00000000000000c0 | Arity(3)
 | 0x0000000021315c10 | 0x000000000000a10b | value
 | 0x0000000021315c18 | 0x0000000021315b3a | <<227,129,130,227,129,131,227,129,132,227,129,133,227,129,134,227,129,135,227,129,136,227,129,137,227,129,138,227,129,139...
 | 0x0000000021315c20 | 0x00000000213158c1 | [{'_@0',<<227,129,130,227,129,131,227,129,132,227,129,133,227,129,134,227,129,135,227,129,136,227,129,137...
 | 0x0000000021315c28 | 0x0000000000000080 | Arity(2)
 | 0x0000000021315c30 | 0x0000000000006f0b | ok
 | 0x0000000021315c38 | 0x0000000021315b3a | <<227,129,130,227,129,131,227,129,132,227,129,133,227,129,134,227,129,135,227,129,136,227,129,137,227,129,138,227,129,139...
 | 0x0000000021315c40 | 0x0000000021315b3a | <<227,129,130,227,129,131,227,129,132,227,129,133,227,129,134,227,129,135,227,129,136,227,129,137,227,129,138,227,129,139...
 | 0x0000000021315c48 | 0xfffffffffffffffb | []
 | 0x0000000021315c50 | 0x0000000000000080 | Arity(2)
 | 0x0000000021315c58 | 0x0000000021315c41 | [<<227,129,130,227,129,131,227,129,132,227,129,133,227,129,134,227,129,135,227,129,136,227,129,137,227,129,138,227,129...
 | 0x0000000021315c60 | 0x00000000213158c1 | [{'_@0',<<227,129,130,227,129,131,227,129,132,227,129,133,227,129,134,227,129,135,227,129,136,227,129,137...
 | 0x0000000021315c68 | 0x0000000000000104 | Thing Arity(4) Tag(4) # tag が 0100 なので reference と思われる
 | 0x0000000021315c70 | 0x0000000021315b3a | THING                 # これが所謂 match context なのだろうか。。。？
 | 0x0000000021315c78 | 0x00007fed99e01648 | THING
 | 0x0000000021315c80 | 0x00000000000007b0 | THING
 | 0x0000000021315c88 | 0x00000000000007b0 | THING
 | 0x0000000021315c90 | 0x00000000000000c0 | Arity(3)
 | 0x0000000021315c98 | 0x000000000000a10b | value
 | 0x0000000021315ca0 | 0x000000000000052f | 82
 | 0x0000000021315ca8 | 0x00000000213158c1 | [{'_@0',<<227,129,130,227,129,131,227,129,132,227,129,133,227,129,134,227,129,135,227,129,136,227,129,137...
 # 略
```

（`:hipe_bifs.show_heap/1` の出力は Elixir のコードではないですが、Elixir の syntax highlight を使うと見やすい。。。）

一方、`len_by_tail_recursion2/1` では、`{:ok, rest}` に相当するデータが再帰に伴って heap 上につくられているようでした。
それに加えて、（タグを含めて）5 words の reference (`Thing Arity(4) Tag(4)`) とそれに続く数 words の boxed term が繰り返しつくられています。
正しく解釈できているか分かりませんが、`len_by_tail_recursion/1` では元の `a2n` に対する reference を使い回しているのに対し、`len_by_tail_recursion2/1` では再帰の度に `rest` に対する reference をつくり直しているように見えます。

```elixir
iex> Process.spawn(fn ->
...>   MyRecursion.len_by_tail_recursion2(a2n)
...>   :hipe_bifs.show_heap(self())
...> end, min_heap_size: 1_000) # GC を抑制
From: 0x0000000021318a48 to 0x000000002131b228
 # 略 (len_by_tail_recursion/1 と似たような感じ)
 | 0x0000000021318e60 | 0x0000000000000080 | Arity(2)
 | 0x0000000021318e68 | 0x0000000000006f0b | ok
 | 0x0000000021318e70 | 0x0000000021318d32 | <<227,129,130,227,129,131,227,129,132,227,129,133,227,129,134,227,129,135,227,129,136,227,129,137,227,129,138,227,129,139...
 | 0x0000000021318e78 | 0x0000000000000104 | Thing Arity(4) Tag(4) # len_by_tail_recursion/1 にも同様の reference はある
 | 0x0000000021318e80 | 0x0000000021318d32 | THING                 # ただ、こちらでは再帰の度につくられているようだ
 | 0x0000000021318e88 | 0x00007fed99e01648 | THING
 | 0x0000000021318e90 | 0x00000000000007b0 | THING
 | 0x0000000021318e98 | 0x00000000000007b0 | THING
 | 0x0000000021318ea0 | 0x00000000000000e8 | Thing Arity(3) Tag(40) # tag が 1000 なので refc binary と思われる
 | 0x0000000021318ea8 | 0x00000000000000f3 | THING                  # なんなんだろう。。。？
 | 0x0000000021318eb0 | 0x0000000000000003 | THING
 | 0x0000000021318eb8 | 0x0000000000000000 | THING
 | 0x0000000021318ec0 | 0x0000000021318d32 | <<227,129,130,227,129,131,227,129,132,227,129,133,227,129,134,227,129,135,227,129,136,227,129,137,227,129,138,227,129,139...
 | 0x0000000021318ec8 | 0x0000000000000080 | Arity(2)
 | 0x0000000021318ed0 | 0x0000000000006f0b | ok
 | 0x0000000021318ed8 | 0x0000000021318ea2 | <<227,129,131,227,129,132,227,129,133,227,129,134,227,129,135,227,129,136,227,129,137,227,129,138,227,129,139,227,129,140...
 | 0x0000000021318ee0 | 0x0000000000000104 | Thing Arity(4) Tag(4)
 | 0x0000000021318ee8 | 0x0000000021318d32 | THING
 | 0x0000000021318ef0 | 0x00007fed99e01648 | THING
 | 0x0000000021318ef8 | 0x00000000000007b0 | THING
 | 0x0000000021318f00 | 0x00000000000007b0 | THING
 | 0x0000000021318f08 | 0x00000000000000e8 | Thing Arity(3) Tag(40)
 | 0x0000000021318f10 | 0x00000000000000f0 | THING
 | 0x0000000021318f18 | 0x0000000000000006 | THING
 | 0x0000000021318f20 | 0x0000000021000000 | THING
 | 0x0000000021318f28 | 0x0000000021318d32 | <<227,129,130,227,129,131,227,129,132,227,129,133,227,129,134,227,129,135,227,129,136,227,129,137,227,129,138,227,129,139...
 # 略
 | 0x000000002131aff8 | 0x0000000000000080 | Arity(2)
 | 0x000000002131b000 | 0x0000000000006f0b | ok
 | 0x000000002131b008 | 0x000000002131afe2 | <<227,130,146,227,130,147>>
 | 0x000000002131b010 | 0x0000000000000104 | Thing Arity(4) Tag(4)
 | 0x000000002131b018 | 0x000000002131afe2 | THING
 | 0x000000002131b020 | 0x000000002131aff0 | THING
 | 0x000000002131b028 | 0x0000000000000030 | THING
 | 0x000000002131b030 | 0x0000000000000030 | THING
 | 0x000000002131b038 | 0x00000000000000a4 | Thing Arity(2) Tag(36) # 途中から refc binary から reference に変わっている
 | 0x000000002131b040 | 0x0000000000000003 | THING                  # サイズが小さくなったから。。。？
 | 0x000000002131b048 | 0x00000000219382e3 | THING
 | 0x000000002131b050 | 0x0000000000000080 | Arity(2)
 | 0x000000002131b058 | 0x0000000000006f0b | ok
 | 0x000000002131b060 | 0x000000002131b03a | <<227,130,147>>
 | 0x000000002131b068 | 0x0000000000000104 | Thing Arity(4) Tag(4)
 | 0x000000002131b070 | 0x000000002131b03a | THING
 | 0x000000002131b078 | 0x000000002131b048 | THING
 | 0x000000002131b080 | 0x0000000000000018 | THING
 | 0x000000002131b088 | 0x0000000000000018 | THING
 | 0x000000002131b090 | 0x0000000000000064 | Thing Arity(1) Tag(36)
 | 0x000000002131b098 | 0x0000000000000000 | THING
 | 0x000000002131b0a0 | 0x0000000000000080 | Arity(2)
 | 0x000000002131b0a8 | 0x0000000000006f0b | ok
 | 0x000000002131b0b0 | 0x000000002131b092 | <<>>
 | 0x000000002131b0b8 | 0x0000000000000104 | Thing Arity(4) Tag(4)
 | 0x000000002131b0c0 | 0x000000002131b092 | THING
 | 0x000000002131b0c8 | 0x000000002131b0a0 | THING
 | 0x000000002131b0d0 | 0x0000000000000000 | THING
 | 0x000000002131b0d8 | 0x0000000000000000 | THING
 | 0x000000002131b0e0 | 0x00000000000000c0 | Arity(3)
 | 0x000000002131b0e8 | 0x000000000000a10b | value
 | 0x000000002131b0f0 | 0x000000000000052f | 82
 | 0x000000002131b0f8 | 0x0000000021318ab9 | [{'_@0',<<227,129,130,227,129,131,227,129,132,227,129,133,227,129,134,227,129,135,227,129,136,227,129,137...
 # 略
```

### `Elixir.MyRecursion.beam` を見てみる

beam を見るとき、VS Code を使用しているのであれば、[BEAMdasm](https://marketplace.visualstudio.com/items?itemName=Valentin.beamdasm) という extension が便利です。

```
//Function  Elixir.MyRecursion:len_by_tail_recursion/1
label11:  func_info            Elixir.MyRecursion len_by_tail_recursion 1 //line my_recursion.ex, 7
label12:  move                 0 X[1]
          call_only            2 label14

//Function  Elixir.MyRecursion:len_by_tail_recursion/2
label13:  func_info            Elixir.MyRecursion len_by_tail_recursion 2 //line my_recursion.ex, 9
label14:  bs_start_match3      label13 X[0] 2 X[2]
          bs_get_position      X[2] X[0] 3
          bs_test_tail2        label15 X[2] 0
          move                 X[1] X[0]
          return
label15:  bs_skip_utf8         label16 X[2] 3 0
          bs_test_unit         label16 X[2] 8
          gc_bif2              label00 3 erlang:+/2 X[1] 1 X[1] //line my_recursion.ex, 11
          move                 X[2] X[0]
          call_only            2 label14
label16:  bs_set_position      X[2] X[0]
          bs_get_tail          X[2] X[0] 3
          jump                 label13

//Function  Elixir.MyRecursion:len_by_tail_recursion2/1
label17:  func_info            Elixir.MyRecursion len_by_tail_recursion2 1 //line my_recursion.ex, 14
label18:  test_heap            3 1
          put_tuple2           X[0] [ok, X[0]]
          move                 0 X[1]
          call_only            2 label20

//Function  Elixir.MyRecursion:len_by_tail_recursion2/2
label19:  func_info            Elixir.MyRecursion len_by_tail_recursion2 2 //line my_recursion.ex, 16
label20:  is_tagged_tuple      label19 X[0] 2 ok
          get_tuple_element    X[0] 1 X[2]
          bs_start_match3      label19 X[2] 3 X[2]
          bs_test_tail2        label21 X[2] 0
          move                 X[1] X[0]
          return
label21:  bs_skip_utf8         label19 X[2] 3 0
          bs_get_binary2       label19 X[2] 3 all 8 0 X[2]
          gc_bif2              label00 3 erlang:+/2 X[1] 1 X[1] //line my_recursion.ex, 18
          test_heap            3 3
          put_tuple2           X[0] [ok, X[2]]
          call_only            2 label20
```

2 つ目の関数について気になった点は以下です。

- `get_tuple_element` してから `bs_start_match3` している
    - match context を使い回すのではなく、新しくつくられる？
- `bs_get_binary2` で match context から sub binary を取り出している
    - 次の関数は match context ではなく sub binary を渡している？

（match context や sub binary を繰り返しつくっているとすれば、確かに heap をたくさん使いそう。。。）

## OTP 22 になってから `String.length/1` のメモリ使用量が増えた気がする

`String.length/1` は `String.Unicode.length/1` に delegate されています。
OTP の 21 と 22 のそれぞれでコンパイルされた `String.Unicode` を使ってベンチマークをとってみます。

まず、[asdf](https://github.com/asdf-vm/asdf) を使って `.tool-versions` を以下のようにしておきます。

```
erlang 22.3.4.21
elixir 1.9.4-otp-21
```

この設定では、通常の `String.Unicode` は OTP 21 でコンパイルされたものになります。
次に、[elixir の `lib/elixir/unicode/`](https://github.com/elixir-lang/elixir/tree/v1.9.4/lib/elixir/unicode) をコピーし、モジュール名を変えて `unicode.ex` をコンパイルします。
このモジュールを OTP 22 でコンパイルした `String.Unicode` として考えることにします。
（`String.Unicode` は Elixir の他モジュールに依存していないため、このように考えることができると思います。）

```elixir
Benchee.run([
  {"OTP 21", &String.Unicode.length(&1)},
  {"OTP 22", &MyUnicodeOtp22.length(&1)}, # OTP 22 でコンパイルしたもの
], [
  inputs: [
    {"s5M", s5M},
  ],
  time: 5,
  memory_time: 1,
])
```

下記がベンチマーク結果の要約です。

```
// IPS
OTP 21          1.23
OTP 22          1.14 - 1.08x slower +62.35 ms
// Memory
OTP 21       381.47 MB
OTP 22       495.91 MB - 1.30x memory usage +114.44 MB
```

同じ Erlang で動かした結果なので、この違いは Erlang の compiler に起因するものと考えることができます。

実は、OTP 22 では [compiler に結構大きな変更](https://blog.erlang.org/OTP-22-Highlights/#compiler) が入っています。
この変更によって、全体としては match context が再利用されやすくなったのですが、`String.Unicode` はその恩恵を受けられなかったようです。

実際に heap を見てみると、OTP 21（`String.Unicode.length/1`） のときに再帰毎に現れるパターンは 10 words ですが、OTP 22（`MyUnicodeOtp22.length/1`）では 13 words になっています。
この 10 : 13 の比率は、ベンチマークしたメモリ使用量の比率と一致しています。

```elixir
iex> a2n = Enum.map_join(?あ..?ん, &(<<&1::utf8>>))
iex> spawn(fn ->
...>   String.Unicode.length(a2n)
...>   :hipe_bifs.show_heap(self())
...> end)
From: 0x0000000019bc5cd8 to 0x0000000019bc62a8
 # 略
 | 0x0000000019bc6038 | 0x00000000000000e8 | Thing Arity(3) Tag(40)
 | 0x0000000019bc6040 | 0x0000000000000006 | THING
 | 0x0000000019bc6048 | 0x00000000000000f0 | THING
 | 0x0000000019bc6050 | 0x0000000000000000 | THING
 | 0x0000000019bc6058 | 0x0000000019bcbaca | <<227,129,130,227,129,131,227,129,132,227,129,133,227,129,134,227,129,135,227,129,136,227,129,137,227,129,138,227,129,139...
 | 0x0000000019bc6060 | 0x0000000000000048 | Thing Arity(1) Tag(8)
 | 0x0000000019bc6068 | 0x0000000000000770 | THING
 | 0x0000000019bc6070 | 0x0000000000000080 | Arity(2)
 | 0x0000000019bc6078 | 0x000000000000003f | 3
 | 0x0000000019bc6080 | 0x0000000019bc603a | <<227,130,146,227,130,147>>
 | 0x0000000019bc6088 | 0x00000000000000e8 | Thing Arity(3) Tag(40)
 | 0x0000000019bc6090 | 0x0000000000000003 | THING
 | 0x0000000019bc6098 | 0x00000000000000f3 | THING
 | 0x0000000019bc60a0 | 0x0000000000000000 | THING
 | 0x0000000019bc60a8 | 0x0000000019bcbaca | <<227,129,130,227,129,131,227,129,132,227,129,133,227,129,134,227,129,135,227,129,136,227,129,137,227,129,138,227,129,139...
 | 0x0000000019bc60b0 | 0x0000000000000048 | Thing Arity(1) Tag(8)
 | 0x0000000019bc60b8 | 0x0000000000000788 | THING
 | 0x0000000019bc60c0 | 0x0000000000000080 | Arity(2)
 | 0x0000000019bc60c8 | 0x000000000000003f | 3
 | 0x0000000019bc60d0 | 0x0000000019bc608a | <<227,130,147>>
 | 0x0000000019bc60d8 | 0x00000000000000e8 | Thing Arity(3) Tag(40)
 | 0x0000000019bc60e0 | 0x0000000000000000 | THING
 | 0x0000000019bc60e8 | 0x00000000000000f6 | THING
 | 0x0000000019bc60f0 | 0x0000000000000000 | THING
 | 0x0000000019bc60f8 | 0x0000000019bcbaca | <<227,129,130,227,129,131,227,129,132,227,129,133,227,129,134,227,129,135,227,129,136,227,129,137,227,129,138,227,129,139...
 | 0x0000000019bc6100 | 0x0000000000000048 | Thing Arity(1) Tag(8)
 | 0x0000000019bc6108 | 0x00000000000007a0 | THING
 | 0x0000000019bc6110 | 0x0000000000000080 | Arity(2)
 | 0x0000000019bc6118 | 0x000000000000003f | 3
 | 0x0000000019bc6120 | 0x0000000019bc60da | <<>>
 | 0x0000000019bc6128 | 0x0000000000000184 | Thing Arity(6) Tag(4)
 | 0x0000000019bc6130 | 0x0000000019bcbaca | THING
 | 0x0000000019bc6138 | 0x00007fd028484098 | THING
 | 0x0000000019bc6140 | 0x00000000000007b0 | THING
 | 0x0000000019bc6148 | 0x00000000000007b0 | THING
 | 0x0000000019bc6150 | 0x00000000000007b0 | THING
 | 0x0000000019bc6158 | 0x00000000000003b0 | THING
 | 0x0000000019bc6160 | 0x00000000000000c0 | Arity(3)
 | 0x0000000019bc6168 | 0x000000000000a10b | value
 | 0x0000000019bc6170 | 0x000000000000052f | 82
 | 0x0000000019bc6178 | 0x0000000019bcbaa9 | [{'_@0',<<227,129,130,227,129,131,227,129,132,227,129,133,227,129,134,227,129,135,227,129,136,227,129,137...
```

```elixir
iex> spawn(fn ->
...>   MyUnicodeOtp22.length(a2n)
...>   :hipe_bifs.show_heap(self())
...> end)
From: 0x0000000019bf4c30 to 0x0000000019bf52c0
 # 略
 | 0x0000000019bf5018 | 0x0000000000000104 | Thing Arity(4) Tag(4)
 | 0x0000000019bf5020 | 0x0000000019bcbaca | THING
 | 0x0000000019bf5028 | 0x00007fd028484098 | THING
 | 0x0000000019bf5030 | 0x0000000000000780 | THING
 | 0x0000000019bf5038 | 0x00000000000007b0 | THING
 | 0x0000000019bf5040 | 0x00000000000000e8 | Thing Arity(3) Tag(40)
 | 0x0000000019bf5048 | 0x0000000000000006 | THING
 | 0x0000000019bf5050 | 0x00000000000000f0 | THING
 | 0x0000000019bf5058 | 0x0000000019000000 | THING
 | 0x0000000019bf5060 | 0x0000000019bcbaca | <<227,129,130,227,129,131,227,129,132,227,129,133,227,129,134,227,129,135,227,129,136,227,129,137,227,129,138,227,129,139...
 | 0x0000000019bf5068 | 0x0000000000000080 | Arity(2)
 | 0x0000000019bf5070 | 0x000000000000003f | 3
 | 0x0000000019bf5078 | 0x0000000019bf5042 | <<227,130,146,227,130,147>>
 | 0x0000000019bf5080 | 0x0000000000000104 | Thing Arity(4) Tag(4)
 | 0x0000000019bf5088 | 0x0000000019bcbaca | THING
 | 0x0000000019bf5090 | 0x00007fd028484098 | THING
 | 0x0000000019bf5098 | 0x0000000000000798 | THING
 | 0x0000000019bf50a0 | 0x00000000000007b0 | THING
 | 0x0000000019bf50a8 | 0x00000000000000e8 | Thing Arity(3) Tag(40)
 | 0x0000000019bf50b0 | 0x0000000000000003 | THING
 | 0x0000000019bf50b8 | 0x00000000000000f3 | THING
 | 0x0000000019bf50c0 | 0x0000000019000000 | THING
 | 0x0000000019bf50c8 | 0x0000000019bcbaca | <<227,129,130,227,129,131,227,129,132,227,129,133,227,129,134,227,129,135,227,129,136,227,129,137,227,129,138,227,129,139...
 | 0x0000000019bf50d0 | 0x0000000000000080 | Arity(2)
 | 0x0000000019bf50d8 | 0x000000000000003f | 3
 | 0x0000000019bf50e0 | 0x0000000019bf50aa | <<227,130,147>>
 | 0x0000000019bf50e8 | 0x0000000000000104 | Thing Arity(4) Tag(4)
 | 0x0000000019bf50f0 | 0x0000000019bcbaca | THING
 | 0x0000000019bf50f8 | 0x00007fd028484098 | THING
 | 0x0000000019bf5100 | 0x00000000000007b0 | THING
 | 0x0000000019bf5108 | 0x00000000000007b0 | THING
 | 0x0000000019bf5110 | 0x00000000000000e8 | Thing Arity(3) Tag(40)
 | 0x0000000019bf5118 | 0x0000000000000000 | THING
 | 0x0000000019bf5120 | 0x00000000000000f6 | THING
 | 0x0000000019bf5128 | 0x0000000019000000 | THING
 | 0x0000000019bf5130 | 0x0000000019bcbaca | <<227,129,130,227,129,131,227,129,132,227,129,133,227,129,134,227,129,135,227,129,136,227,129,137,227,129,138,227,129,139...
 | 0x0000000019bf5138 | 0x0000000000000080 | Arity(2)
 | 0x0000000019bf5140 | 0x000000000000003f | 3
 | 0x0000000019bf5148 | 0x0000000019bf5112 | <<>>
 | 0x0000000019bf5150 | 0x0000000000000104 | Thing Arity(4) Tag(4)
 | 0x0000000019bf5158 | 0x0000000019bcbaca | THING
 | 0x0000000019bf5160 | 0x00007fd028484098 | THING
 | 0x0000000019bf5168 | 0x00000000000007b0 | THING
 | 0x0000000019bf5170 | 0x00000000000007b0 | THING
 | 0x0000000019bf5178 | 0x00000000000000c0 | Arity(3)
 | 0x0000000019bf5180 | 0x000000000000a10b | value
 | 0x0000000019bf5188 | 0x000000000000052f | 82
 | 0x0000000019bf5190 | 0x0000000019bcbaa9 | [{'_@0',<<227,129,130,227,129,131,227,129,132,227,129,133,227,129,134,227,129,135,227,129,136,227,129,137...
 | 0x0000000019bf5198 | 0x00000000000000c0 | Arity(3)
```

（match context を再利用しやすくするために [追加の情報を保存するようにした](https://github.com/erlang/otp/pull/1958) ようなので、それが増えた 3 words に対応しているのでしょうか。。。？）

その他にも OTP 22 での compiler の改良が `String.Unicode` に与えた影響が 2 つほどあります。

### `Elixir.String.Unicode.beam` のファイルサイズが小さくなった

344kB から 208kB になりました。

### OTP 21 以前の `String.Unicode` を OTP 22 でロードすると時間がかかる

環境依存だと思いますが、手元の環境では、以前のバージョンでロードする場合に数 ms 程度だったのが数十 ms 程度になりました。

`fprof` でプロファイルしてみると、code server がロードの準備をする部分で時間がかかっていそうなことが分かりました。
Compiler の変更に伴ってロードに関連するコードにもいくつも変更が入ったようなので、その影響なのかなと（ふんわりと）理解しています。

```elixir
iex> spawn(fn ->
...>   :fprof.apply(Code, :ensure_loaded, [String.Unicode])
...>   :fprof.profile()
...>   :fprof.analyse()
...> end
```

code server からの応答待ちに時間がかかっているようです。

```
%% Analysis results:
{  analysis_options,
 [{callers, true},
  {sort, acc},
  {totals, false},
  {details, true}]}.

%                                               CNT       ACC       OWN
[{ totals,                                       12,   56.258,    0.069}].  %%%


%                                               CNT       ACC       OWN
[{ "<0.112.0>",                                  12,undefined,    0.069}].   %%

{[{undefined,                                     0,   56.258,    0.023}],
 { {fprof,apply_start_stop,4},                    0,   56.258,    0.023},     %
 [{{'Elixir.Code',ensure_loaded,1},               1,   56.220,    0.003},
  {garbage_collect,                               2,    0.012,    0.012},
  {{fprof,'-apply_start_stop/4-after$^1/0-0-',3},   1,    0.003,    0.003}]}.

{[{{fprof,apply_start_stop,4},                    1,   56.220,    0.003}],
 { {'Elixir.Code',ensure_loaded,1},               1,   56.220,    0.003},     %
 [{{code,ensure_loaded,1},                        1,   56.217,    0.004}]}.

{[{{'Elixir.Code',ensure_loaded,1},               1,   56.217,    0.004}],
 { {code,ensure_loaded,1},                        1,   56.217,    0.004},     %
 [{{code,call,1},                                 1,   56.212,    0.002},
  {{erlang,module_loaded,1},                      1,    0.001,    0.001}]}.

{[{{code,ensure_loaded,1},                        1,   56.212,    0.002}],
 { {code,call,1},                                 1,   56.212,    0.002},     %
 [{{code_server,call,1},                          1,   56.210,    0.015}]}.

{[{{code,call,1},                                 1,   56.210,    0.015}],
 { {code_server,call,1},                          1,   56.210,    0.015},     %
 [{suspend,                                       1,   56.189,    0.000},       // ここ
  {{erlang,monitor,2},                            1,    0.003,    0.003},
  {{erlang,demonitor,2},                          1,    0.003,    0.003}]}.

{[{{code_server,call,1},                          1,   56.189,    0.000},
  {{fprof,'-apply_start_stop/4-after$^1/0-0-',3},   1,    0.000,    0.000}],
 { suspend,                                       2,   56.189,    0.000},     %
 [ ]}.

...
```

iex を立ち上げ直して、今度は code server のプロセスを見てみます。

```elixir
iex> code_server = Process.whereis(:code_server)
iex> spawn(fn ->
...>   :fprof.apply(Code, :ensure_loaded, [String.Unicode], [:start, procs: [code_server]])
...>   :fprof.profile()
...>   :fprof.analyse()
...> end
```

`:erlang.prepare_loading/2` で時間がかかっているようです。
（これより先は BIF になってしまうため、諦めました。。。）

```
%% Analysis results:
{  analysis_options,
 [{callers, true},
  {sort, acc},
  {totals, false},
  {details, true}]}.

%                                               CNT       ACC       OWN
[{ totals,                                      111,   61.212,   60.050}].  %%%


%                                               CNT       ACC       OWN
[{ "<0.50.0>",                                  101,undefined,   60.006}].   %%

{[{undefined,                                     0,   61.174,    0.005},
  {{code_server,loop,1},                          1,    0.000,    0.004}],
 { {code_server,loop,1},                          1,   61.174,    0.009},     %
 [{{code_server,handle_call,3},                   1,   61.096,    0.005},
  {suspend,                                       2,    0.065,    0.000},
  {{code_server,reply,2},                         1,    0.004,    0.004},
  {{code_server,loop,1},                          1,    0.000,    0.004}]}.

{[{{code_server,loop,1},                          1,   61.096,    0.005}],
 { {code_server,handle_call,3},                   1,   61.096,    0.005},     %
 [{{code_server,ensure_loaded,3},                 1,   61.090,    0.002},
  {{erlang,module_loaded,1},                      1,    0.001,    0.001}]}.

{[{{code_server,handle_call,3},                   1,   61.090,    0.002}],
 { {code_server,ensure_loaded,3},                 1,   61.090,    0.002},     %
 [{{code_server,handle_pending_on_load,4},        1,   61.088,    0.005}]}.

{[{{code_server,ensure_loaded,3},                 1,   61.088,    0.005}],
 { {code_server,handle_pending_on_load,4},        1,   61.088,    0.005},     %
 [{{code_server,'-ensure_loaded/3-fun-0-',4},     1,   61.082,    0.004},
  {{lists,keyfind,3},                             1,    0.001,    0.001}]}.

{[{{code_server,handle_pending_on_load,4},        1,   61.082,    0.004}],
 { {code_server,'-ensure_loaded/3-fun-0-',4},     1,   61.082,    0.004},     %
 [{{code_server,load_file_1,3},                   1,   61.077,    0.004},
  {{erlang,module_loaded,1},                      1,    0.001,    0.001}]}.

{[{{code_server,'-ensure_loaded/3-fun-0-',4},     1,   61.077,    0.004}],
 { {code_server,load_file_1,3},                   1,   61.077,    0.004},     %
 [{{code_server,try_load_module_1,5},             1,   59.741,    0.005},
  {{code_server,get_object_code,2},               1,    1.332,    0.008}]}.

{[{{code_server,load_file_1,3},                   1,   59.741,    0.005}],
 { {code_server,try_load_module_1,5},             1,   59.741,    0.005},     %
 [{{code_server,try_load_module_2,6},             1,   59.729,    0.004},
  {{code_server,is_sticky,2},                     1,    0.005,    0.004},
  {{erlang,system_info,1},                        1,    0.002,    0.002}]}.

{[{{code_server,try_load_module_1,5},             1,   59.729,    0.004}],
 { {code_server,try_load_module_2,6},             1,   59.729,    0.004},     %
 [{{code_server,try_load_module_3,6},             1,   59.715,    0.006},
  {{hipe_unified_loader,load_native_code,3},      1,    0.010,    0.006}]}.

{[{{code_server,try_load_module_2,6},             1,   59.715,    0.006}],
 { {code_server,try_load_module_3,6},             1,   59.715,    0.006},     %
 [{{erlang,load_module,2},                        1,   59.697,    0.015},
  {{code_server,handle_on_load,5},                1,    0.012,    0.003}]}.

{[{{code_server,try_load_module_3,6},             1,   59.697,    0.015}],
 { {erlang,load_module,2},                        1,   59.697,    0.015},     %
 [{{erlang,prepare_loading,2},                    1,   59.151,   59.151},
  {{erlang,finish_loading,1},                     1,    0.531,    0.531}]}.

{[{{erlang,load_module,2},                        1,   59.151,   59.151}],
 { {erlang,prepare_loading,2},                    1,   59.151,   59.151},     % // ここ
 [ ]}.

{[{{code_server,load_file_1,3},                   1,    1.332,    0.008}],
 { {code_server,get_object_code,2},               1,    1.332,    0.008},     %
 [{{code_server,mod_to_bin,3},                    1,    1.248,    0.006},
  {{erl_prim_loader,is_basename,1},               1,    0.068,    0.012},
  {{code_server,objfile_extension,0},             1,    0.004,    0.002},
  {{erlang,atom_to_list,1},                       1,    0.002,    0.002},
  {{erlang,'++',2},                               1,    0.002,    0.002}]}.

...
```

## おわりに

Elixir の `String` や `String.Unicode` ですが、現在の `master` では Erlang の実装を利用した形に [変更](https://github.com/elixir-lang/elixir/pull/11024) されています。
`String.Unicode.length/1` がなくなっているなど、かなり大きな変更になっています。
Elixir で unicode を扱うときのパフォーマンスにも影響がありそうなので、気になりますね。

## 参考リンク

- https://blog.stenmans.org/theBeamBook/
- http://beam-wisdoms.clau.se/en/latest/index.html
- https://erlang.org/doc/efficiency_guide/binaryhandling.html