トレーシング

この記事は英語の原文を日本語に翻訳したものです。原文: https://blog.stenmans.org/theBeamBook/#CH-Tracing

翻訳元: happi/theBeamBook 7998e22e78417dbe20e5136b9aee862a1ecaa404（コミット 7998e22）

並行システムや分散システムには独特の難しさや複雑さがあり、とりわけデバッグと監視の面でそれが顕著です。トレーシングはこうした場面で役立ち、稼働中のシステムの挙動をのぞく窓を開発者に与えてくれます。本章では、まずBEAMにおけるトレーシングの役割を見ていきます。

トレーシングは、プロセスの実行、プロセス間のやり取り、システム全体の挙動を可視化します。Erlangのシステムは堅牢性とフォールトトレランスで知られており、それはまさに私たちが実現したい特性です。しかしこの特性ゆえに、エラーや予期しない挙動の原因を突き止めるのが難しくなることがあります。トレーシングを使えば、開発者は実行の流れをリアルタイムで、あるいは記録されたログを通して追跡でき、バグの特定と修正がしやすくなります。トレーシングは、Erlangアプリケーションの性能を監視するうえでも重要な役割を果たします。関数呼び出しやメッセージのやり取り、その他のシステムの活動をトレースすることで、開発者は性能上のボトルネックや非効率なコードパス、予期しないシステムの挙動についてのデータを集められます。Erlangのトレーシング機能は、システムの挙動そのものへの洞察を与えるところにまで及びます。トレーシングは、システムの各部分がどう相互作用し、どうスケールし、障害からどう回復するかを理解する助けになります。こうしてトレーシングは、開発者がシステムの挙動をより正確にモデル化し予測できるようにする、学びの道具にもなります。

ここでは、ERTSが提供するトレーシングツールと、その組み込みのサポートの上に構築されたいくつかのツールを見ていきます。

組み込みのErlangトレーシング機構

`io:format`によるトレーシング

従来の意味でのトレーシングツールではありませんが、io:formatは、他のプログラミング言語におけるprintfデバッグに相当する、Erlangならではのデバッグ手法です。コードの中にprint文を挿入でき、変数の状態や関数呼び出しの結果、プロセスの状態をすぐに簡単な形で出力できます。この手法は非常に手軽で、準備もほとんど要らないため、より高度なトレーシングツールを使う前に問題を特定する最初の一歩として最適です。

Erlangトレース（`erl_tracer`）

このトレーシング機構は、Erlangの関数、メッセージ、プロセスをトレースするための低レベルなインタフェースを提供します。より高レベルなトレーシングツールが構築される土台となる中核的な機能を提供し、Erlangランタイムが直接サポートする基本的なトレーシングのプリミティブを提供します。

シーケンシャルトレーシング（`seq_trace`）

seq_traceは、分散Erlangシステム内でのメッセージの流れをトレースすることに特化しており、プロセス間でやり取りされるメッセージの連なりを追跡できます。

サードパーティ製ツール

Redbug

Redbugは、eperというパフォーマンス・デバッグ用スイートの一部で、使いやすいインタフェースと性能への影響の少なさで知られています。トレース出力があふれたりシステムが過負荷になったりといった、よくある落とし穴を避けながら、安全で効率的なトレーシングに重点を置いており、稼働中のシステムを分析するのに理想的な選択肢です。外部ライブラリであるため、別途インストールする必要があります。Redbugの優れた特徴の一つは、過負荷になった場合に自ら停止できることです。

Redbugのインストール

次のようにしてredbugをクローンできます。

$ git clone https://github.com/massemanet/redbug

続いて次のようにコンパイルできます。

$ cd redbug
$ make

Erlangシェルを起動する際にredbugがパスに含まれるようにしておけば準備は完了です。これは、erlを呼び出すときにredbugのBEAMファイルへのパスを明示的に追加することで行えます。

$ erl -pa /path/to/redbug/ebin

あるいは、次の行を~/.erlangファイルに追加することもできます。これにより、起動のたびにredbugへのパスが自動的に含まれるようになります。

code:add_patha("/path/to/redbug/ebin").

Redbugの使い方

Redbugは、過負荷に対する自己防御の仕組みのおかげで、本番環境でも安全に使えます。トレースメッセージが送られすぎた場合にツール自体を終了させることで、Erlangノードが過負荷になるのを防ぎます。実際に動かしてみましょう。

$ erl
Erlang/OTP 19 [erts-8.2] [...]

Eshell V8.2 (abort with ^G)
1> l(redbug). 
{module,redbug}
2> redbug:start("lists:sort/1"). 
{30,1}
3> lists:sort([3,2,1]).
[1,2,3]

% 15:20:20 <0.31.0>({erlang,apply,2}) 
% lists:sort([3,2,1])
redbug done, timeout - 1

まず、redbugモジュールが利用可能でロード済みであることを確認します。
続いてredbugを起動します。ここでは、モジュールlistsがエクスポートしているアリティ1のsortという関数に注目します。Erlangの用語では、アリティとは、ある関数が取る入力引数の数を表すことを覚えておいてください。
最後にlists:sort/1関数を呼び出し、redbugによってメッセージが出力されることを確認します。
デフォルトのタイムアウト（15秒）に達すると、redbugは停止し、「redbug done」というメッセージを表示します。Redbugは、停止した理由（timeout）と、それまでに収集したメッセージの数（1）も親切に教えてくれます。

では、redbugが実際に出力するメッセージを見てみましょう。デフォルトでは標準出力に表示されますが、ファイルに書き出すこともできます。

% 15:20:20 <0.31.0>({erlang,apply,2})
% lists:sort([3,2,1])

使っているredbugのバージョンによっては、少し違うメッセージになることがあります。この例では、メッセージが二行に分かれています。最初の行にはタイムスタンプ、その関数を呼び出したErlangプロセスのプロセス識別子（PID）、そして呼び出し元の関数が含まれています。二行目には、入力引数を含む、呼び出された関数が示されます。どちらの行も%で始まっており、これはErlangのコメントの構文を思い出させます。

戻り値についても追加のメッセージを出すようredbugに指示できます。これは次のような構文で実現します。

4> redbug:start("lists:sort/1->return").
{30,1}

もう一度lists:sort/1関数を呼び出してみましょう。今度はredbugの出力が少し変わります。

5> lists:sort([3,2,1]).
[1,2,3]

% 15:35:52 <0.31.0>({erlang,apply,2})
% lists:sort([3,2,1])

% 15:35:52 <0.31.0>({erlang,apply,2})
% lists:sort/1 -> [1,2,3]
redbug done, timeout - 1

この場合、関数に入るときと出るときとで、二つのメッセージが出力されます。

実際のコードを扱う場合、トレースメッセージは複雑になり、読みづらくなることがあります。10,000要素を含むリストのソートをトレースしようとするとどうなるか見てみましょう。

6> lists:sort(lists:seq(10000, 1, -1)).
[1,2,3,4,5,6,7,8,9,10,11,12,13,14,15,16,17,18,19,20,21,22,
23,24,25,26,27,28,29|...]

% 15:48:42.208 <0.77.0>({erlang,apply,2})
% lists:sort([10000,9999,9998,9997,9996,9995,9994,9993,9992,9991,9990,9989,9988,9987,9986,
% 9985,9984,9983,9982,9981,9980,9979,9978,9977,9976,9975,9974,9973,9972,9971,
% 9970,9969,9968,9967,9966,9965,9964,9963,9962,9961,9960,9959,9958,9957,9956,
% 9955,9954,9953,9952,9951,9950,9949,9948,9947,9946,9945,9944,9943,9942,9941,
% 9940,9939,9938,9937,9936,9935,9934,9933,9932,9931,9930,9929,9928,9927,9926,
% 9925,9924,9923,9922,9921,9920,9919,9918,9917,9916,9915,9914,9913,9912,9911,
% [...]
% 84,83,82,81,80,79,78,77,76,75,74,73,72,71,70,69,68,67,66,65,64,63,62,61,60,
% 59,58,57,56,55,54,53,52,51,50,49,48,47,46,45,44,43,42,41,40,39,38,37,36,35,
% 34,33,32,31,30,29,28,27,26,25,24,23,22,21,20,19,18,17,16,15,14,13,12,11,10,9,
% 8,7,6,5,4,3,2,1])

% 15:48:42.210 <0.77.0>({erlang,apply,2}) lists:sort/1 ->
% [1,2,3,4,5,6,7,8,9,10,11,12,13,14,15,16,17,18,19,20,21,22,
% 23,24,25,26,27,28,29,30,31,32,33,34,35,36,37,38,39,40,41,
% 42,43,44,45,46,47,48,49,50,51,52,53,54,55,56,57,58,59,60,
% 61,62,63,64,65,66,67,68,69,70,71,72,73,74,75,76,77,78,79,
% 80,81,82,83,84,85,86,87,88,89,90,91,92,93,94,95,96,97,98,
% 99,100,101,102,103,104,105,106,107,108,109,110,111,112,113,
% [...]
% 9951,9952,9953,9954,9955,9956,9957,9958,9959,9960,9961,
% 9962,9963,9964,9965,9966,9967,9968,9969,9970,9971,9972,
% 9973,9974,9975,9976,9977,9978,9979,9980,9981,9982,9983,
% 9984,9985,9986,9987,9988,9989,9990,9991,9992,9993,9994,
% 9995,9996,9997,9998,9999,10000]
redbug done, timeout - 1

ここでは出力のほとんどを省略していますが、雰囲気はつかめるはずです。これを改善するために、いくつかのredbugのオプションを使えます。{arity, true}オプションは、引数の実際の値ではなく、対象の関数の入力引数の数だけを表示するようredbugに指示します。{print_return, false}オプションは、関数呼び出しの戻り値を表示せず、代わりに…という記号を表示するようredbugに指示します。これらのオプションを実際に使ってみましょう。

7> redbug:start("lists:sort/1->return", [{arity, true}, {print_return, false}]).
{30,1}

8> lists:sort(lists:seq(10000, 1, -1)).
[1,2,3,4,5,6,7,8,9,10,11,12,13,14,15,16,17,18,19,20,21,22,
23,24,25,26,27,28,29|...]

% 15:55:32 <0.77.0>({erlang,apply,2})
% lists:sort/1

% 15:55:32 <0.77.0>({erlang,apply,2})
% lists:sort/1 -> '...'
redbug done, timeout - 1

デフォルトでは、redbugは15秒経過するか10件のメッセージを受け取ると停止します。これらの値は安全側に振ったデフォルトですが、十分な場合はあまりありません。timeとmsgsオプションを使えば、これらの上限を引き上げられます。timeはミリ秒単位で指定します。

9> redbug:start("lists:sort/1->return", [{arity, true}, {print_return, false}, {time, 60 * 1000}, {msgs, 100}]).
{30,1}

複数の関数呼び出しに対して同時にredbugを有効化することもできます。lists:sort/1と、その内部で使われる関数lists:sort_1/3の両方に対してトレーシングを有効にしてみましょう。

10> redbug:start(["lists:sort/1->return", "lists:sort_1/3->return"]).
{30,2}

11> lists:sort([4,4,2,1]).
[1,2,4,4]

% 18:39:26 <0.32.0>({erlang,apply,2})
% lists:sort([4,4,2,1])

% 18:39:26 <0.32.0>({erlang,apply,2})
% lists:sort_1(4, [2,1], [4])

% 18:39:26 <0.32.0>({erlang,apply,2})
% lists:sort_1/3 -> [1,2,4,4]

% 18:39:26 <0.32.0>({erlang,apply,2})
% lists:sort/1 -> [1,2,4,4]
redbug done, timeout - 2

最後に、redbugには、一致する入力引数のときだけ結果を表示する機能もあります。ここからは構文が少し魔法のように見えてきます。

12> redbug:start(["lists:sort([1,2,5])->return"]).
{30,1}

13> lists:sort([4,4,2,1]).
[1,2,4,4]

14> lists:sort([1,2,5]).
[1,2,5]

% 18:45:27 <0.32.0>({erlang,apply,2})
% lists:sort([1,2,5])

% 18:45:27 <0.32.0>({erlang,apply,2})
% lists:sort/1 -> [1,2,5]
redbug done, timeout - 1

上の例では、入力引数がリスト[1,2,5]のときのlists:sort/1関数への呼び出しにだけ関心があることをredbugに伝えています。これにより、対象の関数が多数のプロセスから同時に使われている状況で、特定のユースケースにだけ関心がある場合に、大量のノイズを取り除けます。そして、アンダースコアをワイルドカードとして使えることも忘れないでください。

15> redbug:start(["lists:sort([1,_,5])->return"]).  {30,1}

16> lists:sort([1,2,5]).  [1,2,5]

% 18:49:07 <0.32.0>({erlang,apply,2}) lists:sort([1,2,5])

% 18:49:07 <0.32.0>({erlang,apply,2}) lists:sort/1 -> [1,2,5]

17> lists:sort([1,4,5]).  [1,4,5]

% 18:49:09 <0.32.0>({erlang,apply,2}) lists:sort([1,4,5])

% 18:49:09 <0.32.0>({erlang,apply,2}) lists:sort/1 -> [1,4,5] redbug
% done, timeout - 2

本節はredbugの網羅的なガイドを目指すものではありませんが、使い始めるには十分でしょう。redbugで使えるオプションの完全な一覧を得るには、ツール自身に尋ねられます。

18> redbug:help().

Recon Trace（`recon_trace`）

本番システムの診断向けライブラリreconの一部であるrecon_traceは、安全性と性能への影響の少なさを重視して設計された、強力なトレーシング機能で際立っています。

比較とユースケース

組み込みのツールとサードパーティ製ツールのどちらを選ぶかは、主に具体的なデバッグのニーズによって決まります。io:formatは手軽で素早いデバッグ手法を提供する一方、erl_tracerやrecon_traceのようなツールは、より包括的なトレーシング機能によって深い洞察を提供します。

redbugやrecon_traceのように、運用への影響を最小限に抑えるよう設計されたツールは、本番環境において特に価値があります。これらは、性能面での大きな欠点なしに、リアルタイムでの問題診断を可能にします。

seq_traceは、分散Erlangノード間でのメッセージのやり取りとプロセスの相互作用の力学について、欠かせない洞察を与えてくれます。