LoginSignup
8
1

Delete article

Deleted articles cannot be recovered.

Draft of this article would be also deleted.

Are you sure you want to delete this article?

More than 3 years have passed since last update.

@irisTa56in株式会社ACCESS

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

Posted at

はじめに

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

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

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 が長い分だけパフォーマンスが悪化するようです。
このあたりの話は 公式ドキュメント にも書いてあります。
一方、String.at/2 と String.split_at/2 を使った実装では、指定した文字数までしか走査しないため、渡した string が長くてもパフォーマンスはほぼ変わらないようです。
この 2 つの関数を使った結果は似たようなものだったので、どちらを使うかは用途を踏まえて考えればよさそうです。

Benchee でのベンチマークには、下記のようなコードを使いました。

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**

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

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

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

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 を使ってベンチマークしてみます。

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 を 計算に入れていない からで、実際のところ stack size は body-recursive のほうが大きくなります。
  • ok tuple に包んだだけでメモリ使用量がすごく大きくなっている！
  • ちなみに、ここでは binary を使った再帰ですが、list を使った再帰でも同様の傾向になりました。

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

heap を見てみる

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

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 をつくり直しているように見えます。

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 という 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 を使って .tool-versions を以下のようにしておきます。

erlang 22.3.4.21
elixir 1.9.4-otp-21

この設定では、通常の String.Unicode は OTP 21 でコンパイルされたものになります。
次に、elixir の lib/elixir/unicode/ をコピーし、モジュール名を変えて unicode.ex をコンパイルします。
このモジュールを OTP 22 でコンパイルした String.Unicode として考えることにします。
（String.Unicode は 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 に結構大きな変更 が入っています。
この変更によって、全体としては match context が再利用されやすくなったのですが、String.Unicode はその恩恵を受けられなかったようです。

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

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...

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 を再利用しやすくするために 追加の情報を保存するようにした ようなので、それが増えた 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 の変更に伴ってロードに関連するコードにもいくつも変更が入ったようなので、その影響なのかなと（ふんわりと）理解しています。

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 のプロセスを見てみます。

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 の実装を利用した形に 変更 されています。
String.Unicode.length/1 がなくなっているなど、かなり大きな変更になっています。
Elixir で unicode を扱うときのパフォーマンスにも影響がありそうなので、気になりますね。

参考リンク

8
1
0

Register as a new user and use Qiita more conveniently

  1. You get articles that match your needs
  2. You can efficiently read back useful information
  3. You can use dark theme
What you can do with signing up
Sign upLogin
8
1

Delete article

Deleted articles cannot be recovered.

Draft of this article would be also deleted.

Are you sure you want to delete this article?