Haskell で I/Oを伴うマルチスレッドプログラムを開発していると、タイミングに依存するバグや意図しない停止など、デバッグが非常に難しい問題に直面することがよくあります。

GHCのeventlog*1 と聞くと、ThreadScope*2 のようなツールに読み込ませてパフォーマンスのプロファイリングや並行性の可視化を行うための入力データ、という印象を持っている方も多いかもしれません*3。

しかし、eventlogにはRTS（ランタイムシステム）レベルの微細な挙動が記録されるため、その出力内容自体がマルチスレッドプログラムのデバッグにおいて非常に有用です。この記事では、デバッグ目的でのeventlogの活用方法を紹介します。

デバッグの役に立つ軽量スレッドのイベント

eventlogには、Haskellの軽量スレッドのライフサイクルに関する様々な情報が出力されます。特にデバッグで役立つのは以下のようなイベントです。

I/O 待ち等によるスレッドの停止（ブロック状態の確認）
スレッドの実行の開始
アプリケーションのロジックから任意のタイミングで出力するログ情報

これらのイベントを時系列で追跡することで、各スレッドのブロック理由や、アプリケーションの状態との関連を観測できます。

GHC の RTS の機能で eventlog を記録する

eventlogを記録するための手順は非常に簡単です。

まず、アプリケーションの実行時に RTS オプションとして -l（例: ユーザーイベントを記録する -lu など）を渡します。例えば +RTS -lu -RTS のように起動します*4。

嬉しいことに、最近の GHC RTS では、事前にコンパイラ（GHC）に -eventlog オプションを渡してビルドし直す必要がありません*5。標準でeventlogの記録が可能な状態になっています。

プログラムを実行すると <プログラム名>.eventlog というバイナリファイルが生成されるので、これを ghc-events コマンド*6 の inc サブコマンドなどを使って、人間が読めるテキスト形式で確認します。

% ghc-events --help
ghc-events --help:                        Display this help.
ghc-events inc <file>:                    Pretty print an event log incrementally
ghc-events inc force <file>:              Pretty print an event log incrementally. Retry on incomplete input (aka 'tail -f').
ghc-events show <file>:                   Pretty print an event log.
...

軽量スレッドの停止イベントの例

ghc-events で出力されたログを見ると、スレッドがどのような理由で停止したのかが記録されています。よく見かける例をいくつか紹介します。

FFI 呼び出しによる停止: cap 0: stopping thread 2 (making a foreign call)
FFIを呼び出したため、スレッドが一時的にブロックされている
STM 待ちによる停止: cap 0: stopping thread 12 (blocked in STM retry)
Software Transactional Memory (STM) のトランザクション内で retry が呼ばれ、STM 変数の更新を待つ
別スレッドへスケジュールを譲るための停止: cap 0: stopping thread 26 (thread yielding)
軽量スレッドの実行を一時的に停止し、RTSのスケジューラに別のスレッドの実行を促す

アプリケーション側からの情報の埋め込み

デフォルトのログだけでは thread 12 や thread 26 といったIDしか分からず、それがアプリケーション上のどの処理を担っているスレッドなのかが判別しづらいです。これを解決するための機能も用意されています。

スレッドに名前をつける

GHC.Conc.Sync モジュールが提供する labelThread :: ThreadId -> String -> IO () 関数を使うと、特定のスレッドに任意のラベルを割り当てることができます。この名前は eventlog にも記録されます。

出力例:

cap 3: thread 7 has label "bw.main"

アプリケーションのログを eventlog に流す

標準出力などに出す通常のログとは別に、 Debug.Trace モジュールの traceEventIO :: String -> IO () 関数を利用すると、RTSのイベントと完全に同期した形でアプリケーション側からのログを記録できます。

コード例:

eventLog s = do
    tid <- showTid <$> myThreadId
    traceEventIO ("uevent: thread " ++ tid ++ " (" ++ s ++ ")")

出力例:

cap 0: uevent: thread 208 ...

これにより、RTSが記録する「スレッドの停止・再開」のタイミングと、自作アプリケーションの内部ステートの変化を、一つの時系列上で突き合わせることが可能になります。

実例: DNSフルリゾルバ bowline での活用

私は現在、DNSフルリゾルバ bowline *7の開発を行っていますが、このプロジェクトでも eventlog をマルチスレッドのデバッグに活用しています。

具体的には、多数立ち上がる worker スレッドの状態変化を eventlog に記録する*8 ことで、問題が起きた状況の特定に役立てています。

実際のコードの一部は以下のような形です。worker スレッドの状態を書きかえる際に、eventlog にも出力しています。

setWorkerStatEV :: WorkerStatOP -> WorkerStat -> IO ()
setWorkerStatEV wstat st = do
    WStat.setWorkerStat wstat st
    eventLog $ "iter.st " ++ show st

RTSの状況を伴った形でアプリのログを記録できるeventlogは、デバッグの効率を大きく引き上げてくれます。スレッドの停止理由などが可視化されるため、問題の解析の際に役立つ手段としておすすめです。