Tracing on Erlang/OTP 19

OTP19-rc1が来ましたね.
いくつかの大きな変更の中に, traceに関する変更があります. Erlang Factory 2016でそれに関する発表がされているので, 発表 + ドキュメント + 他から纏めてみました.
誤りがあればご指摘ください m(_ _)m

traceとは...?

C/C++だとgdbでbreak pointを仕込んだり、ポインタの中身を見たりすることがあるかと思います.
こういった実行中のプログラムの状態を知る為の仕組みをErlangはVM上で提供しています.

そもそも使ったことないという人は, 以下のうち一つは抑えておくと世界が変わるのでオススメです.

• Erlang/OTP
  • erlang:trace/3
  • dbg
• その他のライブラリ
  • recon
  • eper (redbug)

traceの種類/概要

• trraced processes
  • receive / send (message)
  • in / out (schedule)
• traced modules
  • call / return

上記のような2種類に分類されるイベント(erlang:trace/3参照) を指定することができ, 指定されたイベントが発生した時, tracerプロセスに対してメッセージが送信されます.

また, meta traceを使うことで他のプロセスに対してそのメッセージを送ることもできます. (erlang:trace_pattern/3 のmetaを参照)

Match specification

関数呼び出しに関するイベントは, 特定のパターンにマッチする関数の呼び出しを指定することができます.
なので, Mod:Function(a, _)の場合のみトレースするといったこともできます.

Sequence Trace

メッセージのやりとりを追うことができるtrace.

(<0.227.0>) call dbg:get_tracer()
SeqTrace [0]: (<0.227.0>) <0.217.0> ! {<0.227.0>,{get_tracer,nonode@nohost}} [Serial: {0,1}]
SeqTrace [0]: (<0.217.0>) <0.227.0> ! {dbg,{ok,<0.218.0>}} [Serial: {1,3}]
SeqTrace [0]: (<0.227.0>) <0.167.0> ! {io_request,<0.227.0>,#Ref<0.0.0.3303>,getopts} [Serial: {3,
                                                                                  4}]
SeqTrace [0]: (<0.167.0>) <0.165.0> ! {<0.167.0>,get_unicode_state} [Serial: {4,63}]
SeqTrace [0]: (<0.165.0>) <0.167.0> ! {<0.165.0>,get_unicode_state,true} [Serial: {63,64}]

DTrace / SystemTap

gdbでattachするとErlangVMがとまってしまいます. ErlangVMを止めずに低オーバーヘッドで調査する為のツールとしてDTrace (Mac / BSD), SystemTap (Linux) をサポートしています.

例えば, NIF/Port driverがスケジューラーをロックしてしまった場合 (よくありますね！) なんかに活躍できるっぽいです.

• http://erlang.org/doc/apps/runtime_tools/DTRACE.html
• http://erlang.org/doc/apps/runtime_tools/SYSTEMTAP.html
• http://voluntas.hatenablog.com/entry/20120330/1333110554
• http://www.erlang-factory.com/static/upload/media/1399288388410589dtrace.pdf

trace on OTP19

scalabirity

OTP19以前は一度globalなsystem message dispatcher threadを経由していた為, trace messageはシーケンシャルに処理されていた.
これは, traceの一部はproc msg / proc statusをtrace messageの順にlockする必要があった為であり, 拡張性を阻害する原因となっていた.

OTP19では, traceeからtracerに直接メッセージが送信されるようになりました.
より具体的には,

• proc statusのlockをなくした
• proc msgのlockをtry lock (timeout可能なlock) にした.
• process毎に存在するtrace message queueのlockを取るようになった.

performance

詳しくは, スライドのグラフ / 動画を参照して欲しい.

• call trace to process
  • traceなしと比べると100倍程度遅いものの, 従来よりも2～3倍速い.
• call trace to port
  • 従来見られたscheduler数が増えると悪化する問題が改善された
• Max mem usage during trace to process
  • 従来の半分程度まで削減
• Max mem usage during trace to port
  • 従来よりも悪化するが, 従来は遅すぎて使い物にならなかったようです.
  • to processの場合と比べると同程度もしくは, 少ない程度.

new behaviour

OTP19からerl_tracer behvaiour が追加された.

特徴

• Erlang codeで全てのtrace eventに対するフィルタを記述することができる
  • 但し, ドキュメントには(将来的にはこの制限はなくなるが) NIFで全部実装しろという記述がある為, 真偽のほどは不明
  • 従来の方法では, receiveしてからのハンドリングかmatch specificationsによるマッチしかできなかった (はず)
• backendをplugginの形で選ぶことができる
  • erl_tracer behaviourで実装されていれば何でもOK
• NIFで実装されているので, trace termのcopyは発生しない

callback function

callback functionは以下の大きく以下の二種類に分類される

• enabled ...... traceするか/しないか
  • enabled_procs
  • enabled_ports
  • eabled_running_ports
  • (以下略)
• trace ...... trace時の挙動
  • trace_procs
  • trace_ports
  • trace_running_ports
  • (以下略)

どちらとも(enabled/trace)_XXXXが定義されていればそちらを, 定義されていない場合はenabled/traceをtrace event毎に実行する.
(trace系の関数はenabled系の関数でtraceを返した場合のみ実行される)

Usage

1> erlang:trace(new, true, [send, {tracer, ErlTracerModule, Tracer}]).

• Example tracer module nif