ReconTrace で Erlang VM のトレース機能に親しむ #Elixir

（Elixir 向けの内容ですが、Erlang で書かれた recon_trace を紹介しているので、Erlang タグも付けてます）

トレース機能、使ってますか？

みなさんは Elixir のプログラムをどのようにデバッグしてますか？　IEx.pry？　それとも、IO.inspect を使った、いわゆる printf デバッグでしょうか？

また、もし本番環境で次のような問題が起こったら、どう調査しますか？

特定の条件（ユーザーからの入力）でエラーになるようだが、その条件自体がわからない
どこかが性能上のボトルネックになっているようだ

ログを追加して、アプリケーションをデプロイし直すのもひとつの方法ですよね。

もちろん、どれも有効な手段です。でも、こんな時、まずは Erlang VM のトレース機能を使うことをお勧めします。それだけで原因がわかるかもしれません。

「すごいE本¹」の原著者、Fred Hebert さんは、「Stuff Goes Bad: Erlang in Anger」というフリーの PDF 本も出されています。この本は Erlang/OTP で構築された本番システムをトラブルシューティングする際の tips 集で、すごく勉強になります。そして、その本の「Tracing」という章には、以下のように書かれています。

One of the lesser known and absolutely under-used features of Erlang and the BEAM virtual machine is just about how much tracing you can do on there.

Erlang と BEAM 仮想マシンの機能のなかで、絶対にもっと使われるべきなのに、あまりよく知られていないのは、トレースでどれだけのことができるかということです。

Forget your debuggers, their use is too limited. Tracing makes sense in Erlang at all steps of your system’s life cycle, whether it’s for development or for diagnosing a running production system.

出番がごく限られているデバッガーのことは忘れましょう。Erlang の世界でトレースは、開発作業と本番稼働中のシステムの診断を含めた、システムのライフサイクルの全工程で使えるものなのです。

Fred さんは recon_trace というトレースライブラリーを Erlang で開発し、オープンソースとして公開しています。いま私は、このライブラリーを Elixir から使うためのラッパーモジュールを書いていますので、使い方を紹介します。

Erlang VM のトレース機能

まずは例を見てみましょう。関数型プログラミングの入門書などでお馴染みの、階乗計算プログラムを使います。

my_math.ex

defmodule MyMath do

  @spec factorial(non_neg_integer()) :: non_neg_integer()
  def factorial(0),             do: 1
  def factorial(n) when n > 0,  do: n * factorial(n - 1)

end

iex(1)> c "my_math.ex"
[MyMath]
iex(2)> MyMath.factorial(0)
1
iex(3)> MyMath.factorial(1)
1
iex(4)> MyMath.factorial(5)
120

正しく動いているようです。

このプログラムの実行過程を、Erlang VM のトレース機能で可視化します。(トレース中の余計な改行を削除してます)

iex(5)> ReconTrace.calls({MyMath, :_, fn(_) -> :return end}, 50, [scope: :local])
9
iex(6)> MyMath.factorial(5)
120
23:47:56.917968 <0.57.0> MyMath.__info__(:macros)
23:47:56.925911 <0.57.0> MyMath.__info__/1 --> []
23:47:56.926023 <0.57.0> MyMath.factorial(5)
23:47:56.926101 <0.57.0> MyMath.factorial(4)
23:47:56.926174 <0.57.0> MyMath.factorial(3)
23:47:56.926254 <0.57.0> MyMath.factorial(2)
23:47:56.926318 <0.57.0> MyMath.factorial(1)
23:47:56.926375 <0.57.0> MyMath.factorial(0)
23:47:56.926442 <0.57.0> MyMath.factorial/1 --> 1
23:47:56.926514 <0.57.0> MyMath.factorial/1 --> 1
23:47:56.926590 <0.57.0> MyMath.factorial/1 --> 2
23:47:56.926652 <0.57.0> MyMath.factorial/1 --> 6
23:47:56.926722 <0.57.0> MyMath.factorial/1 --> 24
23:47:56.926786 <0.57.0> MyMath.factorial/1 --> 120

どうですか？　データが加工されていく過程が、一目瞭然ですよね。

このプログラムは再帰呼出しのたびにコールスタックを消費しますので、もし大きな数に適用するとスタックがオーバーフローしてしまいます。そこで、同じプログラムを末尾再帰によるイテレーション形式で書き直してみます。これによりコンパイラーが、コールスタックを消費しない呼び出し法に最適化してくれます。

my_math.ex

defmodule MyMath do

  @spec factorial_iter(non_neg_integer()) :: non_neg_integer()
  def factorial_iter(n) when n >= 0, do: factorial_iter1(n, 1)

  defp factorial_iter1(0, acc), do: 1
  defp factorial_iter1(n, acc), do: factorial_iter1(n - 1, acc * n)

end

実行してみましょう。

iex(7)> c "my_math.ex"
my_math.ex:1: warning: redefining module MyMath
my_math.ex:10: warning: variable acc is unused
[MyMath]
iex(8)> MyMath.factorial_iter(0)
1
iex(9)> MyMath.factorial_iter(1)
1
iex(10)> MyMath.factorial_iter(5)
1    # <-- あれれ？

５に適用すると答えがおかしい。これはバグですねー（棒読み）。もう一度、トレースしてみましょう。

iex(11)> ReconTrace.calls({MyMath, :_, fn(_) -> :return end}, 50, [scope: :local])
9
iex(12)> MyMath.factorial_iter(5)
1
23:49:41.802883 <0.57.0> MyMath.__info__/1 --> []
23:49:41.803050 <0.57.0> MyMath.factorial_iter(5)
23:49:41.803127 <0.57.0> MyMath.factorial_iter1(5, 1)
23:49:41.803202 <0.57.0> MyMath.factorial_iter1(4, 5)
23:49:41.803280 <0.57.0> MyMath.factorial_iter1(3, 20)
23:49:41.803352 <0.57.0> MyMath.factorial_iter1(2, 60)
23:49:41.803432 <0.57.0> MyMath.factorial_iter1(1, 120)
23:49:41.803510 <0.57.0> MyMath.factorial_iter1(0, 120) 　# <-- ここまではOK
23:49:41.803584 <0.57.0> MyMath.factorial_iter1/2 --> 1   # <-- 120の代わりに1が
23:49:41.803657 <0.57.0> MyMath.factorial_iter1/2 --> 1
23:49:41.803737 <0.57.0> MyMath.factorial_iter1/2 --> 1
23:49:41.803811 <0.57.0> MyMath.factorial_iter1/2 --> 1
23:49:41.803880 <0.57.0> MyMath.factorial_iter1/2 --> 1
23:49:41.803948 <0.57.0> MyMath.factorial_iter1/2 --> 1
23:49:41.804017 <0.57.0> MyMath.factorial_iter/1 --> 1

引数が０の時の factorial_iter1/2 の戻り値がおかしいようです。120を返すべきところが、1を返しています。

ソースコードを見なおすと、acc とするべきところが、1 になっていたことがわかりました。

my_math.ex

  defp factorial_iter1(0, acc), do: 1   # <- 正しくは acc

プログラムを修正して実行すると、今度は正しい答えが得られました。

iex(13)> c "my_math.ex"
my_math.ex:1: warning: redefining module MyMath
[MyMath]
iex(14)> ReconTrace.calls({MyMath, :_, fn(_) -> :return end}, 50, [scope: :local])
9
iex(15)> MyMath.factorial_iter(5)
23:51:32.439220 <0.57.0> MyMath.__info__(:macros)
120
23:51:32.439409 <0.57.0> MyMath.__info__/1 --> []
23:51:32.439564 <0.57.0> MyMath.factorial_iter(5)
23:51:32.439644 <0.57.0> MyMath.factorial_iter1(5, 1)
23:51:32.439737 <0.57.0> MyMath.factorial_iter1(4, 5)
23:51:32.439825 <0.57.0> MyMath.factorial_iter1(3, 20)
23:51:32.439902 <0.57.0> MyMath.factorial_iter1(2, 60)
23:51:32.439987 <0.57.0> MyMath.factorial_iter1(1, 120)
23:51:32.440066 <0.57.0> MyMath.factorial_iter1(0, 120)
23:51:32.440148 <0.57.0> MyMath.factorial_iter1/2 --> 120
23:51:32.440221 <0.57.0> MyMath.factorial_iter1/2 --> 120
23:51:32.440297 <0.57.0> MyMath.factorial_iter1/2 --> 120
23:51:32.440374 <0.57.0> MyMath.factorial_iter1/2 --> 120
23:51:32.440446 <0.57.0> MyMath.factorial_iter1/2 --> 120
23:51:32.440517 <0.57.0> MyMath.factorial_iter1/2 --> 120
23:51:32.440590 <0.57.0> MyMath.factorial_iter/1 --> 120

わざとらしい例でしたが、このように、トレースを使うと、プログラムのどのあたりにバグが潜んでいるのかが、見つけやすくなります。これはソースコードに IO.inspect を追加してデバッグするのと似ています。しかし、決定的に違うのは、ソースコードを何も修正してないで、それが可能になっていることです。

またトレースは、自分の開発しているプログラムが依存している他のライブラリーの中をデバッグしたい時、（というか、動作を理解したい時）にも役立ちます。トレースを手がかりにソースコードを読み進めていくと、結構はかどりますよ。

トレース自体は Erlang VM にとって軽い処理ですので、対象範囲を広げすぎなければ、高負荷がかかっている本番環境での利用も可能です。そのため、Erlang コミュニティーでは、開発時だけでなく、本番環境のトラブルシューティングにも、トレースが積極的に使われています。

実際、私がいまの会社の入社初日に与えられた任務は、お客さんが本番環境で取得したトレースを解析することでした。Erlang 未経験で入社したので、焦ったのはもちろんですが（特に入れ子になった大量のカッコ、つまり、タプルとリストとバイナリーに目がチカチカした）、それと同時に、こういうやり方もあるのか！　と、目からウロコが落ちたのでした。

OTP 標準のトレース API は、使い勝手と本番環境での安全性に難あり

Erlang/OTP には、Erlang VM のトレース機能を使うための API が用意されています。:sys モジュール、:dbg モジュール、:erlang モジュールのトレース BIF などです。しかし、これらは、あまり使い勝手がいいとはいえず、シェル（iex）から直接入力するのは、かなりの苦痛が伴います。

また、本番環境で使うには安全性の問題があります。トレース時にその対象を決めるためにトレース・スペックを与えるのですが、うっかり広範囲にマッチするものを与えてしまうと、トレース結果の出力が追いつかず、プロセス・メッセージキューが溢れて VM がクラッシュすることもあります²。

Elixir にも、OTP の :dbg モジュールをラップした Dbg というオープンソースライブラリーがあります。しかし、恐らく安全性に関しては考慮されていない（使う側が考慮すべきもの）と思われます。

使いやすく、しかも、安全な recon_trace

こういった問題を解決するために、古くからいくつかの試みがありました。本番環境での長い実績があり、Erlang コミュニティーで最もよく使われているのは、redbug でしょう。eper という、性能関連の調査をする時に役立つツールボックスの一機能として提供されています。使いやすく、また、本番環境でも使える安全なツールとなっています。

Fred さんの recon_trace は、recon の一部で、redbug と同様の使い勝手と安全性を備えています。Erlang コミュニティーでどの程度使われているかはわからないのですが、Fred さんによると、本番環境での実績も豊富だそうです。redbug との違いは、OTP 標準のモジュールだけに依存しているので、recon_trace.beam ファイル１つをサーバーにコピーするだけで使用できることです。redbug では、eper アプリケーション全体をコピーしなければなりません。

redbug も recon_trace も :dbg モジュール上に構築されたツールです。安全性を確保するために、トレースメッセージ数の上限、メッセージレート制限といった各種のリミッターを搭載しています。また、トレース結果を受信する軽量プロセスはフィルタリングに専念し、画面やファイルへの出力といった重い処理は、他の軽量プロセスに行わせる設計になっています。これによりトレース結果を受け取るプロセスのレスポンスを良くし、メッセージキューにメッセージが溜まらないようにしています。

これらの仕組みにより、たとえトレース・スペックが広範囲にマッチしてしまっても、大事に至らない（至りにくい）ようになっています。

実は今回、私は、redbug と recon_trace を素のまま Elixir から使う、といった趣旨の記事を書く予定でした。が、使ってみて、色々とうまく行かないところがあったので、急きょラッパーモジュールを書くことにしたのです。redbug でなく recon_trace を使った理由は、こちらのほうが実装がシンプルで、ラッパーモジュールを書きやすかったためです。昨晩書き始めたので、まだ mix プロジェクトの体裁にはなってなくて、単体のソースファイルを Gist に置いているだけですが。（Elixir は２週間前に初めて触ったので、おかしなところがあれば教えてください）

recon_trace のセットアップ

recon_trace と、そのラッパーモジュール（とりあえず、ReconTrace という名前にしています）を、ローカルマシンに設定してみましょう。iex が起動時に読み込む .iex.exs にパスを登録して、iex から常に使えるようにします。

今回は FreeBSD 10.2-RELEASE 上で、Elixir 1.1.1 と Erlang/OTP 18.2.1 を使用しました。Linux や Mac OS X でも同じ手順でセットアップできると思います³。

ダウンロードとビルド

ローカルマシンの適当なディレクトリーに recon をダウンロードして、ビルドします。私は $HOME/opt/erlang/recon に置いているので、その前提で進めます。

$ mkdir -p ~/opt/erlang
$ cd ~/opt/relang
$ git clone git@github.com:ferd/recon.git
$ cd recon
$ ./rebar compile

また、ラッパーモジュールをダウンロードして、ビルドします。こちらは、$HOME/opt/elixir/ に置きました。URL が長くてすいません。

$ mkdir ~/opt/elixir
$ cd ~/opt/elixir
$ curl -O https://gist.githubusercontent.com/tatsuya6502/279aa8b448b9881c3ebe/raw/8ca1ab997e96e8d83cbf9fa376a6c6b0df9328a9/recon_trace.ex
$ elixirc -pz ~/opt/erlang/recon/ebin recon_trace.ex

階乗のプログラムはここからダウンロードできます。どこに置いてもいいです。（以下 $MY_PROG_DIRとします）

$ export MY_PROG_DIR=$HOME/（任意のディレクトリー）
$ cd $MY_PROG_DIR
$ curl -O https://gist.githubusercontent.com/tatsuya6502/12ae8f298b448d648a51/raw/4ab6aebfcd92a05ef9ee047d9f62e539d39d0e65/my_math.ex

.iex.exs でパスを通す

ホームディレクトリーに .iex.exs ファイルを作り、以下の内容を追加します。

home_dir = :os.getenv("HOME")

libs = [:filename.join(home_dir, "opt/erlang/recon/ebin"),
        :filename.join(home_dir, "opt/elixir/")
       ]

add_pathz = fn(path) ->
  case String.to_char_list(path) |> :code.add_pathz do
    true ->
      IO.puts "Added #{path} to pathz."
    other ->
      IO.puts "ERROR: Could not add #{path} to pathz: #{inspect other}"
  end
end

IO.puts ""
Enum.each(libs, &(add_pathz.(&1)))
IO.puts ""

これで iex の起動時に、recon と ReconTrace へのパスが通るようになりました。

iex を起動する

階乗のプログラムを置いたディレクトリー（$MY_PROG_DIR）で iex を起動します。

$ cd $MY_RPOG_DIR
$ iex
Erlang/OTP 18 [erts-7.2.1] [source] [64-bit] [smp:8:8] [async-threads:10] [hipe] [kernel-poll:false]

Interactive Elixir (1.1.1) - press Ctrl+C to exit (type h() ENTER for help)

Added /home/tatsuya/opt/erlang/recon/ebin to pathz.
Added /home/tatsuya/opt/elixir to pathz.

iex(1)>

トレースの実行

トレース対象のモジュール（MyMath）は事前にロードしておく必要があります。c コマンドでコンパイルすると、すぐにロードされます。（コンパイル済の時は l MyMath でロードできます）

iex(1)> c "my_math.ex"
[MyMath]
iex(2)> MyMath.module_info
[module: MyMath,
[module: MyMath,
 exports: [__info__: 1, factorial_iter: 1, permutations: 1, factorial: 1,
  module_info: 0, module_info: 1],
...

では、トレースしてみましょう。

iex(3)> ReconTrace.calls({MyMath, :_, :_}, 50)
6
iex(4)> MyMath.factorial(5)
120

23:53:44.243104 <0.57.0> MyMath.__info__(:macros)

23:53:44.250695 <0.57.0> MyMath.factorial(5)

{MyMath, :_, :_} の部分をトレース・スペック（trace spec）と呼びます。この例では、モジュール名 MyMath にある、全ての関数（関数名が任意 :_ で arity⁴ も任意 :_）がトレースの対象となります。

ReconTrace.clear とすると、いま設定されているトレース・スペックを消去されます。

iex(5)> ReconTrace.clear
:ok

ReconTrace のオプション

上の例で再帰呼出しの部分が表示されなかったことに気づきましたか？。実は、デフォルトの設定では、関数がグローバルスコープ、つまり、「モジュール.関数名」の形式で呼ばれた時だけトレースするようになっています。関数がその「関数名」だけで呼ばれた時も対象にするには [scope: :local] オプションを追加します。

iex(6)> ReconTrace.calls({MyMath, :_, :_}, 50, [scope: :local])
9
iex(7)> MyMath.factorial(5)

23:54:51.648861 <0.57.0> MyMath.__info__(:macros)
120

23:54:51.649036 <0.57.0> MyMath.factorial(5)

23:54:51.649185 <0.57.0> MyMath.factorial(4)

23:54:51.649261 <0.57.0> MyMath.factorial(3)

23:54:51.649329 <0.57.0> MyMath.factorial(2)

23:54:51.649400 <0.57.0> MyMath.factorial(1)

23:54:51.649469 <0.57.0> MyMath.factorial(0)

また、[args: :arity] とすると、引数の値ではなく、arity を表示します。

３番目の引数は、リミッターです。50 のように書くと、50メッセージ表示した時点でトレースが終了します。{50, 1000} と書くと、50メッセージ/1000ms のレートに到達するとトレースが終了します。

マッチ・スペック

トレース・スペック・タプルの３番目の項目は、関数の arity、または、マッチ・スペック（match spec）と呼ばれる特別な無名関数を与えるようになってます。これは、引数のリストを１つ受け取る関数で、普通の関数のようにパターンマッチとガードが使えます。しかし、その本体部分には atom 以外、何も書けません。:ok を返すようにすると、戻り値は表示しないままトレース対象にさせられます。

たとえば、第１引数が１以下の時のみトレース対象にするには、以下のように書きます。

iex(8)> ReconTrace.calls({MyMath, :factorial_iter1, fn([n, _]) when n <= 1 -> :ok end},
...(8)>                  50, [scope: :local])
1
iex(9)> MyMath.factorial_iter(5)

23:55:33.171322 <0.57.0> MyMath.factorial_iter1(1, 120)

23:55:33.171469 <0.57.0> MyMath.factorial_iter1(0, 120)

:ok の代わりに :return を返すと、戻り値が表示されます。

iex(10)> ReconTrace.calls({MyMath, :factorial_iter1, fn([n, _]) when n <= 1 -> :return end},
...(10)>                  50, [scope: :local])
1
iex(11)> MyMath.factorial_iter(5)
120

23:56:06.562258 <0.57.0> MyMath.factorial_iter1(1, 120)

23:56:06.562491 <0.57.0> MyMath.factorial_iter1(0, 120)

23:56:06.562618 <0.57.0> MyMath.factorial_iter1/2 --> 120

23:56:06.562707 <0.57.0> MyMath.factorial_iter1/2 --> 120

注意：2015年12月29日追記：　OTP のマニュアルによると、:return 指定でトレースされた関数は、トレースの間、末尾呼び出し最適化が解除されてしまうそうです。末尾再帰で寿命の長い関数（例えば、gen_serverのイベントループ）に、このオプションを使うのはできるだ避けて、もし使う場合でもごく短期に抑えるようにしてください。

なお、:return（マニュアル上では return_trace()）以外のトレースオプションにはこのような副作用はありません。以下、マニュアルから引用。

NOTE! If the traced function is tail recursive, this match spec function destroys that property. Hence, if a match spec executing this function is used on a perpetual server process, it may only be active for a limited time, or the emulator will eventually use all memory in the host machine and crash.

NOTE!　トレース対象の関数が末尾再帰の場合、この（return_trace()）マッチスペック関数を用いると、その属性が解除されてしまいます。従って、このオプションを含むマッチスペックを、永続的なサーバープロセスに対して実行する際は、ごく限られた時間だけトレースをアクティブにしてください。さもなければ、エミュレータ（VM）は、いずれ、ホストマシンのメモリーを使い果たし、クラッシュしてしまいます。

追記終わり。

なお、これは :dbg モジュールの約束事なのですが、本当はマッチ・スペックでは、:return ではなくて、架空の関数 return_trace() を書くことになっています⁵。Erlang のシェルはこの「無名関数の中の架空の関数」を受け付けてくれるのですが、iex だと、事前チェックがしっかりしているようで、コンパイルエラーになってしまいます。そこで、コンパイルエラーにならない :return を書くようにして、ReconTrace ラッパーモジュールの中で、正しいマッチ・スペックへ変換しています。

Erlang/OTP 18.2.1 の場合（架空の関数がエラーにならない）

1> ShellFun = fun(_) -> return_trace() end.
#Fun<erl_eval.6.54118792>
2> {fun_data, ImportList, Clauses} = erl_eval:fun_data(ShellFun).
{fun_data,[],
          [{clause,1,
                   [{var,1,'_'}],
                   [],
                   [{call,1,{atom,1,return_trace},[]}]}]}
3> MatchSpec = ms_transform:transform_from_shell(dbg, Clauses, ImportList).
[{'_',[],[{return_trace}]}]

Elixir 1.1.1 の場合（架空の関数がエラーになる）

iex(1)> shell_fun = fn(_) -> return_trace() end
** (CompileError) iex:1: undefined function return_trace/0
    (elixir) src/elixir_fn.erl:33: anonymous fn/3 in :elixir_fn.expand/3
    (elixir) src/elixir_fn.erl:36: :elixir_fn.expand/3

リストを使って、複数のトレース・スペックを与えることもできます。また引数部分は、以下のように arity で指定できます。

iex(12)> ReconTrace.calls([{MyMath, :factorial_iter, 1},
...(12)>                   {MyMath, :factorial_iter1, 2}],
...(12)>                  50, [scope: :local])
2
iex(13)> MyMath.factorial_iter(5)

23:58:10.958364 <0.57.0> MyMath.factorial_iter(5)
120

23:58:10.958545 <0.57.0> MyMath.factorial_iter1(5, 1)

23:58:10.958711 <0.57.0> MyMath.factorial_iter1(4, 5)

23:58:10.958799 <0.57.0> MyMath.factorial_iter1(3, 20)

23:58:10.958889 <0.57.0> MyMath.factorial_iter1(2, 60)

23:58:10.958965 <0.57.0> MyMath.factorial_iter1(1, 120)

23:58:10.959049 <0.57.0> MyMath.factorial_iter1(0, 120)

permutations

別の関数 permutations もトレースしてみましょう。これは、与えられたアイテムのリストから、順列組み合わせを作ります。

my_math.ex

  @spec permutations([term()]) :: [[term()]]
  def permutations([]) do
    [[]]
  end

  def permutations(items) when is_list(items) do
    for head <- items, tail <- permutations(items -- [head]) do
      [head | tail]
    end
  end

iex(14)> MyMath.permutations([1, 2, 3])
[[1, 2, 3], [1, 3, 2], [2, 1, 3], [2, 3, 1], [3, 1, 2], [3, 2, 1]]
iex(15)> MyMath.permutations([:a, :"A"])
[[:a, :A], [:A, :a]]
iex(16)> ReconTrace.calls({MyMath, :_, fn(_) -> :return end},
...(16)>                  100, [scope: :local])
9
iex(17)> MyMath.permutations([:a, :"A"])
00:00:49.369881 <0.57.0> MyMath.__info__(:macros)
[[:a, :A], [:A, :a]]
00:00:49.370049 <0.57.0> MyMath.__info__/1 --> []
00:00:49.370205 <0.57.0> MyMath.permutations([:a, :A])
00:00:49.370341 <0.57.0> MyMath.-permutations/1-fun-1-(:a, [], [:a, :A])
00:00:49.370435 <0.57.0> MyMath.permutations([:A])
00:00:49.370519 <0.57.0> MyMath.-permutations/1-fun-1-(:A, [], [:A])
00:00:49.370624 <0.57.0> MyMath.permutations([])
00:00:49.370700 <0.57.0> MyMath.permutations/1 --> [[]]
00:00:49.370781 <0.57.0> MyMath.-permutations/1-fun-0-([], [], :A)
00:00:49.370857 <0.57.0> MyMath.-permutations/1-fun-0-/3 --> [[:A]]
00:00:49.370937 <0.57.0> MyMath.-permutations/1-fun-1-/3 --> [[:A]]
00:00:49.371027 <0.57.0> MyMath.permutations/1 --> [[:A]]
00:00:49.371109 <0.57.0> MyMath.-permutations/1-fun-0-([:A], [], :a)
00:00:49.371200 <0.57.0> MyMath.-permutations/1-fun-0-/3 --> [[:a, :A]]
00:00:49.371282 <0.57.0> MyMath.-permutations/1-fun-1-/3 --> [[:a, :A]]
00:00:49.371371 <0.57.0> MyMath.-permutations/1-fun-1-(:A, [[:a, :A]], [:a, :A])
00:00:49.371486 <0.57.0> MyMath.permutations([:a])
00:00:49.371564 <0.57.0> MyMath.-permutations/1-fun-1-(:a, [], [:a])
00:00:49.371645 <0.57.0> MyMath.permutations([])
00:00:49.371709 <0.57.0> MyMath.permutations/1 --> [[]]
00:00:49.371789 <0.57.0> MyMath.-permutations/1-fun-0-([], [], :a)
00:00:49.371874 <0.57.0> MyMath.-permutations/1-fun-0-/3 --> [[:a]]
00:00:49.371955 <0.57.0> MyMath.-permutations/1-fun-1-/3 --> [[:a]]
00:00:49.372034 <0.57.0> MyMath.permutations/1 --> [[:a]]
00:00:49.372113 <0.57.0> MyMath.-permutations/1-fun-0-([:a], [[:a, :A]], :A)
00:00:49.372216 <0.57.0> MyMath.-permutations/1-fun-0-/3 --> [[:A, :a], [:a, :A]]
00:00:49.372313 <0.57.0> MyMath.-permutations/1-fun-1-/3 --> [[:A, :a], [:a, :A]]
00:00:49.372412 <0.57.0> MyMath.permutations/1 --> [[:a, :A], [:A, :a]]
iex(20)>

トレースで見ると、for で書かれた２重ループ（入れ子になったリスト内包表記）の部分で、２つの無名関数 -permutations/1-fun-0-/3 と -permutations/1-fun-1-/3 が作られていることがわかります。for はシンタックスシュガーに過ぎず、内部では map 関数から繰り返し呼ばれる無名関数で置き換えられているのです。

なお、引数として与えた atom :a と :"A" は、もし素の recon_trace を使うと、Erlang の文法に則った形式 a と 'A' で表示されてしまいます。ラッパーモジュールを通すと、Elixir の文法に則った形式で表示されるようになります。

トレース対象のプロセスを指定する

トレースの対象となるプロセスを絞り込むこともできます。４番目の引数（オプションのリスト）で以下のような指定ができます。

# プロセスID指定
ReconTrace.calls({MyMath, :_, _}, 100, [pid: {a, b, c}])
ReconTrace.calls({MyMath, :_, _}, 100, [pid: pid(a, b, c)])

# 新規プロセスだけ
ReconTrace.calls({MyMath, :_, _}, 100, [pid: :new])

# 既存プロセスだけ
ReconTrace.calls({MyMath, :_, _}, 100, [pid: :existing])

# gproc に :name で登録されているプロセス
ReconTrace.calls({MyMath, :_, _}, 100, [pid: {:via, :gproc, :name}])

# 複数指定も可能
ReconTrace.calls({MyMath, :_, _}, 100, [pid: [{a, b, c}, {a, d, e}]])

トレース結果をファイルへ出力する

トレース結果をファイルに出力するには、以下のようにします。

iex(1)> {:ok, trace_file} = File.open("/tmp/trace", [:write])
iex(2)> ReconTrace.calls({MyMath, :_, fn(_) -> :return end},
...(2)>                  100,
...(2)>                  [io_server: trace_file,
...(2)>                   scope: :local])
6
iex(3)> MyMath.factorial(100)
Recon tracer rate limit tripped.
iex(4)> File.close(trace_file)

その場合でも、エラーメッセージや、リミットに達した旨を伝えるメッセージは、画面に表示されます。

まとめ

Erlang VM のトレース機能を簡単に使える Erlang モジュール recon_trace と、Elixir 用のラッパーモジュールを紹介しました。recon_trace は本番運用で培った経験が活かされており、開発時だけでなく、本番システムのトラブルシューティングにも活用できるものとなっています。

トレースをデバッグに活かすためには、ひとつひとつの関数を十分に小さくして、入力と出力から動作が把握できるように書く必要があります。関数型プログラミングでは、小さくて汎用的な関数を組み合わせることが推奨されますので、トレースとの相性はいいといえます。また、こう書くことを習慣づければ、自然と単体テストもしやすくなるでしょう。

さらに、オブジェクトの内部ステートを隠すことが推奨されるオブジェクト指向プログラミングと異なり、関数型プログラミングでは、データの中身を隠さないことが推奨されます（Elixir や Erlang では隠しようもないですが）。トレースで取得したデータは、そのまま iex でコピー＆ペーストして関数の入力として使えるので、とても便利です。

すごい Erlang ゆかいに学ぼう！ Fred Hebert著山口能迪訳　オーム社　https://estore.ohmsha.co.jp/titles/978427406912P ↩
Erlang in Anger によると、トレースを始めて数秒で VM をふっ飛ばすこともあるようです。 ↩
Windows はわからないのです。すみません。 ↩
引数の個数のことです。たとえば、MyFact.factorial_iter(n) は arity が 1、MyFact.factorial_iter1(n, acc) なら 2 になります。 ↩
http://www.erlang.org/doc/man/dbg.html#fun2ms-1 ↩