2年目のErlangプログラマが身につけておきたい12のデバッグ術

1年目のErlangプログラマが嵌まる20のポイント の続編です（？）
プログラム的なことを知りたい場合はこちらの記事をご参照ください.

Erlang VMにアタッチする

Erlangは稼働中のVMにシステムに大した負荷なくアタッチすることができます. relxなどを使っている場合は, attach用のコマンドを使うこともできますが, より安全な方法があります.

erl -sname ${NAME} -setcookie XXXX -remsh ${NODE_NAME}

リモートシェルを使うことで, システムが動いているVM上に立ち上げたシェルを使うことができます.
escriptからはremshは使えなかったように思うので (方法があれば教えてください), rpc:callするしかないと思います.

いつでもVM再起動できるように, CrashDumpの設定を忘れずに

最終手段のOS再起動の前にErlangVMの再起動で済ませられるのであれば済ませましょう.

CrashDumpを吐かせる準備を整える

http://erlang.org/doc/apps/erts/crash_dump.html
http://erlang.org/doc/man/erl.html

CoreDumpとは別に, ErlangVM上のdumpを吐かせることができます. relxはデフォルトでcrash dumpを吐く設定になっています.

vm.args

## これを書くとcrash dumpが吐かれなくなります
+d

## これでパスを指定することができます
-env ERL_CRASH_DUMP /tmp/erl_crash.dump

吐かせる方法には以下の方法があります.

• VM上でerlang:halt("slogan")を実行する
• kill -SIGUSR1 ${PID} でVMを殺す

CrashDumpは読める

Erlangのcrash dumpは人間が割と読めますが, 問題発見を早める為に以下のツールが有用です.

• CrashDumpViewer
• erl_crashdump_analyzer

自分がよく使うのは後者です. 前者はGUI環境が必要なので運用している環境だと辛いかもしれません.
また, 後者は最初に知りたいであろうことしか出力しないので迷うことがないと思います.

細かい部分は直接dumpを読むので私は困りませんでした.
binary部分を読む必要がある場合は, binppのfrom_str/1を使っても良いかもしれません.

8割方メッセージキューが詰まる時が問題が起きる時

私の経験上の話です. ログは一回詰まると詰まり続けるので気をつけましょう.
愛してやまないreconを使うと,

1> recon:proc_count(message_queue_len, 5).
[{<0.309.0>,7,
  [{current_function,{timer,sleep,1}},
   {initial_call,{erlang,apply,2}}]},
 {<0.308.0>,0,
  [{current_function,{gen_fsm,loop,7}},
   {initial_call,{proc_lib,init_p,5}}]},
 {<0.307.0>,0,
  [{current_function,{websocket_client,websocket_loop,3}},
   {initial_call,{proc_lib,init_p,5}}]},
 {<0.303.0>,0,
  [inet_gethost_native,
   {current_function,{inet_gethost_native,main_loop,1}},
   {initial_call,{inet_gethost_native,server_init,2}}]},
 {<0.302.0>,0,
  [inet_gethost_native_sup,
   {current_function,{gen_server,loop,6}},
   {initial_call,{proc_lib,init_p,5}}]}]

若干分かり辛いですが, tupleの2要素目がメッセージキューに溜まっているメッセージの数です.
多い順に第二引数分 (この例では5件) リストアップしてくれます.

殺して良いプロセスであれば, shell上から殺してsupervisorに再起動させるという方法もあります.

binaryのリークには要注意

Erlangでメモリが右肩上がりになる場合は, プロセスリークとバイナリリークが大体の原因ではないかと思います.
(バイナリリークもプロセスリークによって発生するんですが……)

プロセスのリークには気をつけるとして, プロセスのGC間隔によってバイナリの解放が遅れてしまい, メモリを食い潰すという現象があります.
詳しく書くと1つの記事が書けてしまうので簡単にバイナリのGCについて, 誤解を恐れずにざっくり概要を書くと,

• バイナリはShared Heapに保存され, 各プロセスが参照する際に参照カウントを+1する
• 各プロセスのGCが走るタイミングで不要であれば-1される
• プロセスが終了する場合は, そのプロセスの参照を解放する

より詳しい内容は以下の記事が参考になります.

• Erlang Garbage Collection Details and Why It Matters
• Erlang 19.0 Garbage Collector

このGCには1つ(?)問題点があり, プロセスのGCはプロセススタック/ヒープを消費しないと実行されません.
その為, バイナリ以外を扱わない生存期間が長いプロセスがいると非常に危険です.
その場合はコード上で明示的にGCを呼ぶことで改善されることがあります.

ちなみに, reconには不要なバイナリを解放するコマンドがあり, この結果から推測することができます.

1> recon:bin_leak(3). 
[{<0.308.0>,-2,
  [{current_function,{gen_fsm,loop,7}},
   {initial_call,{proc_lib,init_p,5}}]},
 {<0.268.0>,-2,
  [user_drv,
   {current_function,{user_drv,server_loop,6}},
   {initial_call,{user_drv,server,2}}]},
 {<0.307.0>,-1,
  [{current_function,{websocket_client,websocket_loop,3}},
   {initial_call,{proc_lib,init_p,5}}]}]

不要な参照を解放すると同時に, leakの多かったプロセスを引数で指定した数表示してくれます.

実行中のpidが分かれば, 何をしているかは一目瞭然

プロセスの起動引数を知る

http://erlang.org/doc/man/proc_lib.html#initial_call-1
http://erlang.org/doc/man/erlang.html#process_info-2

%% proc_lib, gen_XXXの場合
1> proc_lib:initial_call(pid(0,308,0)).
{tls_connection,init,['Argument__1']}

%% spawnの場合
2> Pid = spawn(timer, sleep, [infinity]).
<0.364.0>
3> proc_lib:initial_call(Pid).
false
4> process_info(Pid, initial_call).
{initial_call,{timer,sleep,1}}

supervisorも使えば, 引数の正確な値まで知ることができます.
ここでは割愛しますが, 作っていた調査用ライブラリに書いた部分があったので, 興味がある方がいたら参考にしてください ¹

プロセスの現在の状態を知る

%% proc_lib, gen_XXXの場合
1> sys:get_state(pid(0,171,0), 5000). 
{state,{local,preminder_sup},
       one_for_one,
       [{child,<0.187.0>,preminder_ws,
               {preminder_ws,start_link,[]},
               permanent,5000,worker,
               [preminder_ws]},
        {child,<0.178.0>,preminder_pr,
               {preminder_pr,start_link,[]},
               permanent,5000,worker,
               [preminder_pr]},
        {child,<0.173.0>,preminder_user,
               {preminder_user,start_link,[]},
               permanent,5000,worker,
               [preminder_user]},
        {child,<0.172.0>,preminder_cache,
               {preminder_cache,start_link,[]},
               permanent,5000,worker,
               [preminder_cache]}],
       undefined,5,10,[],preminder_sup,[]}

なお, /1はtimeoutがinfinityになっているので使うのはやめましょう.
reconを使っているのであれば, recon:get_state/1を使うようにしておくのが良いです.

また, 似たような関数にsys:get_status/1がありますが, こちらの結果は以下のようになります.

%% proc_lib, gen_XXXの場合
1> sys:get_status(pid(0,171,0)).
{status,<0.171.0>,
        {module,gen_server},
        [[{'$ancestors',[<0.170.0>]},
          {'$initial_call',{supervisor,preminder_sup,1}}],
         running,<0.170.0>,[],
         [{header,"Status for generic server preminder_sup"},
          {data,[{"Status",running},
                 {"Parent",<0.170.0>},
                 {"Logged events",[]}]},
          {data,[{"State",
                  {state,{local,preminder_sup},
                         one_for_one,
                         [{child,<0.187.0>,preminder_ws,
                                 {preminder_ws,start_link,[]},
                                 permanent,5000,worker,...},
                          {child,<0.178.0>,preminder_pr,
                                 {preminder_pr,start_link,...},
                                 permanent,5000,...},
                          {child,<0.173.0>,preminder_user,
                                 {preminder_user,...},
                                 permanent,...},
                          {child,<0.172.0>,preminder_cache,{...},...}],
                         undefined,5,10,[],preminder_sup,[]}}]}]]}

プロセスの状態を観察する

プロセスの現在の状態ではなく, どういう遷移をしているかを見たいときもあります. そういう時は以下のコマンドが役に立ちます.

%% proc_lib, gen_XXXの場合
1> sys:trace(pid(0,188,0), true).    
ok
*DBG* <0.188.0> got {'$gen_sync_all_state_event',
                        {<0.187.0>,#Ref<0.0.2.2359>},
                        {application_data,<<....>>}} in state connection
*DBG* <0.188.0> sent ok to <0.187.0>
      and switched to state connection
*DBG* <0.188.0> got {tcp,#Port<0.37051>,
                         <......>>} in state connection
*DBG* <0.188.0> switched to state connection
*DBG* <0.188.0> got {tcp,#Port<0.37051>,
                         <<......>>} in state connection
*DBG* <0.188.0> switched to state connection

2> sys:trace(pid(0,188,0), false).

attachができなくなった. gdbの出番だ.

スケジューラーがロックされるとattachできなくなったり, connectできなくなったりします.
例えば, NIFに無限ループのバグがあるとスケジューラーが１つ死にます. こうしてスケジューラーが死んでいくと最終的には外部から何もできない状況ができます.

こういう時はgdbを使いましょう.

$ gdb -p ${PID}

coreを吐くように設定していれば (ulimitとかです), kill -SIGSEGV ${PID}でcoreを吐くので, それを見ても良いでしょう.

関数呼び出しをリアルタイムで確認する

今まで運用で役に立ちそうなTipsの紹介でしたが, 開発中に役に立つこともあります.
その最たる例は関数の呼び出し引数/返り値の確認でしょう.

breakpointを使う方法もありますが, 2年ほど仕事で書いて結局一度も使いませんでした.

1> recon_trace:calls({preminder_slack, '_', fun(_) -> return_trace() end}, 10).
8
2:21:16.248402 <0.215.0> preminder_slack:slack_id()
2:21:16.248907 <0.215.0> preminder_slack:slack_id/0 --> <<"UXXXXX">>

reconを使わずにstdlibだけでできますが, 割愛します.
また, recon_traceの使い方は, 以下が詳しいです.

• ReconTrace で Erlang VM のトレース機能に親しむ
• 公式ドキュメント

shellの機能を使い倒す

まず, help().を覚えましょう.

1> help().
** shell internal commands **
b()        -- display all variable bindings
e(N)       -- repeat the expression in query <N>
f()        -- forget all variable bindings
f(X)       -- forget the binding of variable X
...

面倒だと思いながら書いていたメソッドのショートシンタックスが多数用意されています.
特に有用な物をピックアップすると以下のようなものがあります.

f()        -- forget all variable bindings
i(X,Y,Z)   -- information about pid <X,Y,Z>
m(Mod)     -- information about module <Mod>
memory()   -- memory allocation information
pid(X,Y,Z) -- convert X,Y,Z to a Pid
v(N)       -- use the value of query <N>

ちなみに, v/1はv(-1).のような使い方もできます.

testでもprintfしたい

printfではなく, io:format/2ですが.

%% eunit
-include_lib("eunit/include/eunit.hrl").

case ?debugVal(hoge(args)) of
   ....

%% ct
ct:log("debug: ~p", [Val]).

OTP19からは @mururu さん製の?debugVal/2も使えます.

---

昨年よりも項目が少なくなってしまいましたが, (そして最後の方が大分テキトウでしたが), 参考になれば幸いですm(_ _)m
なお, 「3年目のErlangプログラマ～」は出ません.

---

1. ライブラリ自体は途中で飽きてしまったので, 使わない方が良いです ↩