libdw で遊ぶ #Haskell

はじめに

Haskell を実用していると、ネットワーク通信をしてり、FFI で外部ライブラリを呼び出すことが増えるかと思います。
そういったレイヤで出たバグを解析するために、コンパイル時に生成されるデバッグ情報を元にバグの原因を調査する必要があるかもしれません。

この記事では、主に Linux などで利用されている ELF 形式の実行バイナリに対応するデバッグ情報である DWARF を使って、Haskell でもスタックトレースを吐かせて遊んでみることにします。

Haskell での DWARF

GHC 8.2.1 のリリースノートを見ると、

More reliable DWARF debug information

という記述があるので DWARF を使って、Haskell のスタックトレースを出して遊んでみることにします。

GHC のランタイムシステムにスタックトレースを吐かせる方法としては次の 2 種類の方法があります。

GHC.ExecutionStack モジュールを使って、プログラム内部からアクセスする方法
実行中のプロセスに SIGQUIT を送る方法

どちらの方法も、GHC 自体が libdw サポートを有効にした状態でコンパイルされている必要があります。
お使いの GHC が libdw をサポートしているかは ghc --info で確認することができます。

$ ghc --info | grep libdw
 ,("RTS expects libdw","NO")

# stack を使う場合
$ stack ghc -- --info | grep libdw
 ,("RTS expects libdw","NO")

普通に stack 等でインストールされた GHC では libdw サポートは有効になっていないと思われるので、libdw で遊びたい場合は自前で GHC をコンパイルする必要があります。

GHC のコンパイル手順

1. GHC ビルド用の環境を整える

まずはじめに GHC ビルド用の環境を整えます。

などを参考にしてください。GHC ソースコードを Git 取得したい場合は、ghc.haskell.org より githab.com のミラーの方が早いので、Building/GettingTheSources – GHC を参考にして GitHub を使うように設定すると良いです。

2. libdw 開発用ライブラリのインストール

libdw のヘッダファイルを取得します。Debian GNU/Linux では libdw-dev パッケージを、RedHat 系では elfutils-devel あたりをインストールします。

3. GHC のコンパイル

DWARF/Status – GHC を参考にして、GHC をコンパイルします。

まずは、ビルド設定ファイル mk/build.mk に下記の内容を追記します。

GhcLibHcOpts += -g3
GhcRtsHcOpts += -g3

このオプションを有効にすることで、RTS や base, bytestring など、GHC 組み込みのライブラリのコンパイルでも DWARF 情報の生成が有効になります。

次に、configure スクリプトを使って Makefile を作成します。この際、--enable-dwarf-unwind を configure スクリプトの引数に指定することで、GHC の libdw サポートが有効になります。
ソースコードを tarball ではなく Git などから取得した場合は boot コマンドも実行しておくようにしてください。

$ ./boot
$ ./configure --enable-dwarf-unwind

configure スクリプトが成功したら libdw が有効になっているか確認しておきましょう。

$ grep UseLibdw config.status
S["UseLibdw"]="YES"

ちゃんと有効になっていますね。

後は make するだけです。並列数 (-j) を環境に合わせて適宜指定してください。
それなりに時間が掛かるのでコーヒーなどを飲んで気長に待ちましょう。

$ make -j XXX

stage2 までやる設定になっていれば、出来上がった ghc バイナリはビルドしたディレクトリの inplace/bin/ghc-stage2 に配置されています。

ちゃんと libdw が有効になっているか確認してみます。

$ inplace/bin/ghc-stage2 --info | grep libdw
 ,("RTS expects libdw","YES")

DWARF で stack trace を吐いて遊んでみる

お試し

試しに、単純な入力待ちをするコードを書き、SIGQUIT を送ってスタックトレースを吐かせてみます。

sample.hs:

module Main where

main :: IO ()
main = getLine >>= putStrLn

-g3 を付けてコンパイルします。何回かコンパイルして確認したい場合は -fforce-recomp を付けて強制的に再コンパイルが走るようにすると良いと思います。

$ inplace/bin/ghc-stage2 -g3 -fforce-recomp ./sample.hs
[1 of 1] Compiling Main             ( sample.hs, sample.o )
Linking sample ...

端末からフォアグラウンドのプロセスに SIGQUIT を送るには Ctrl-\ を押します。

$ ./sample
^\
Caught SIGQUIT; Backtrace:
                  0x48850f    set_initial_registers (rts/Libdw.c:288.0)
            0x7faecd3a88b8    dwfl_thread_getframes (/usr/lib/x86_64-linux-gnu/libdw-0.168.so)
            0x7faecd3a8347    (null) (/usr/lib/x86_64-linux-gnu/libdw-0.168.so)
            0x7faecd3a8673    dwfl_getthreads (/usr/lib/x86_64-linux-gnu/libdw-0.168.so)
            0x7faecd3a8c30    dwfl_getthread_frames (/usr/lib/x86_64-linux-gnu/libdw-0.168.so)
                  0x488af7    libdwGetBacktrace (rts/Libdw.c:259.0)
                  0x478f66    backtrace_handler (rts/posix/Signals.c:534.0)
            0x7faecd7e70bf    (null) (/lib/x86_64-linux-gnu/libpthread-2.24.so)
            0x7faecd0b83a2    __select (../sysdeps/unix/syscall-template.S:84.0)
                  0x479c8b    awaitEvent (rts/posix/Select.c:335.0)
                  0x46bff2    scheduleWaitThread (rts/Schedule.c:898.0)
                  0x471dfc    hs_main (rts/RtsMain.c:73.0)
                  0x406f6e    (null) (/home/taka/sample)
            0x7faeccff72e1    __libc_start_main (../csu/libc-start.c:325.0)
                  0x406cca    _start (/home/taka/sample)

ちゃんと select で止まっている様子が確認できました。

GHC.ExecutionStack を使ってみる

libdw サポートを有効にすると、SIGQUIT を送る以外にも、GHC.ExecutionStack モジュールにより、アプリ内部からスタックトレースにアクセスする方法が提供されるようになります。

sample2.hs:

import GHC.ExecutionStack

myFunction :: IO ()
myFunction = mapM_ putStrLn =<< showStackTrace

$ inplace/bin/ghc-stage2 -g3 -fforce-recomp ./sample2.hs
[1 of 1] Compiling Main             ( sample2.hs, sample2.o )
Linking nya ...

$ ./sample2.hs
sample2: Failed to get stack frames of current process: no matching address range: Success
Stack trace:
    set_initial_registers (rts/Libdw.c:288.0) in /home/taka/sample2
    dwfl_thread_getframes in 
     in /usr/lib/x86_64-linux-gnu/libdw-0.168.so
    dwfl_getthreads in /usr/lib/x86_64-linux-gnu/libdw-0.168.so
    dwfl_getthread_frames in /usr/lib/x86_64-linux-gnu/libdw-0.168.so
    libdwGetBacktrace (rts/Libdw.c:259.0) in /home/taka/sample2
    base_GHCziExecutionStackziInternal_collectStackTrace1_info (libraries/base/GHC/ExecutionStack/Internal.hsc:74.10) in /home/taka/sample2

それっぽいスタックトレースが出ていますが、なにやら不穏なメッセージ (Failed to get stack frames of current process: no matching address range: Success) が出てしまいました。どうやら、きちんとスタックトレースが遡れていない様子です。
GHC 8.2.1 リリース後も、#14510 (GHC.ExecutionStack.showStackTrace broken) – GHC みたいな issue が上がっているようなので、まだまだ実験的な機能なのかもしれません。

実際のアプリで使ってみる

サンプルコードでの動作確認ができたので、実際のアプリで使ってみましょう。

最近は Haskell アプリの開発には Stack を使う場合が多いですが、Stack は最新のコンパイラや、独自ビルドのコンパイラを使う目的には使い辛いので、cabal new-build を使います。
Cabal new-build は Cabal User's Guide の Chapter 5. Nix-style Local Builds に詳細な説明があります。

既に cabal new-build の環境が整っているのであれば、new-build に、今回ビルドした GHC を使うようにオプションを指定してあげれば OK です。

cabal new-build \
    -g3 \
    --with-compiler=/path/to/ghc/inplace/bin/ghc-stage2 \
    --package-db=/path/to/ghc/inplace/lib/package.conf.d \
    all

出来上がったプログラムを実行しつつ、SIGQUIT を送ってみます。

$ dist-newstyle/build/x86_64-linux/ghc-8.6.3/cgrepos-0.6.4/x/cgrepos/build/cgrepos/cgrepos

Caught SIGQUIT; Backtrace:
                 0x343704f    set_initial_registers (rts/Libdw.c:288.0)
            0x7f52b453b8b8    dwfl_thread_getframes (/usr/lib/x86_64-linux-gnu/libdw-0.168.so)
            0x7f52b453b347    (null) (/usr/lib/x86_64-linux-gnu/libdw-0.168.so)
            0x7f52b453b673    dwfl_getthreads (/usr/lib/x86_64-linux-gnu/libdw-0.168.so)
            0x7f52b453bc30    dwfl_getthread_frames (/usr/lib/x86_64-linux-gnu/libdw-0.168.so)
                 0x3437637    libdwGetBacktrace (rts/Libdw.c:259.0)
                 0x34279a6    backtrace_handler (rts/posix/Signals.c:535.0)
            0x7f52b54260bf    (null) (/lib/x86_64-linux-gnu/libpthread-2.24.so)
            0x7f52b424967c    poll (../sysdeps/unix/syscall-template.S:84.0)
            0x7f52b564e16f    (null) (/usr/lib/x86_64-linux-gnu/libmariadb.so.2)
            0x7f52b564e2bc    (null) (/usr/lib/x86_64-linux-gnu/libmariadb.so.2)
            0x7f52b564e448    (null) (/usr/lib/x86_64-linux-gnu/libmariadb.so.2)
            0x7f52b564ee93    (null) (/usr/lib/x86_64-linux-gnu/libmariadb.so.2)
            0x7f52b564feed    (null) (/usr/lib/x86_64-linux-gnu/libmariadb.so.2)
            0x7f52b5656262    (null) (/usr/lib/x86_64-linux-gnu/libmariadb.so.2)
            0x7f52b5656c58    (null) (/usr/lib/x86_64-linux-gnu/libmariadb.so.2)
            0x7f52b5657167    mysql_real_query (/usr/lib/x86_64-linux-gnu/libmariadb.so.2)
                 0x23c373a    _hs_mysql_real_query (/home/taka/work/cgrepos/dist-newstyle/build/x86_64-linux/ghc-8.6.3/cgrepos-0.6.4/x/cgrepos/build/cgrepos/cgrepos)
                 0x234e426    sUOn_info (/home/taka/work/cgrepos/dist-newstyle/build/x86_64-linux/ghc-8.6.3/cgrepos-0.6.4/x/cgrepos/build/cgrepos/cgrepos)
cgrepos: Failed to get stack frames of current process: アドレス範囲に対応しません: 成功です

あいかわらず不穏なメッセージが出ていますが、なにやら mysql で query している途中っぽいことが分かりました。
実際のアプリで何かしら詰まって反応が無くなった場合などに雑に SIGQUIT 送るだけで情報が出てくれるのは便利そうですね。

まとめ

まだまだ実験中の機能のような気がしますが、DWARF を元にスタックトレースを吐かせて遊んでみました。
まだ GHC を自分でビルドしないといけないので面倒ですが、デフォルトで有効になって (& 安定して) くれると、いろいろと捗ると思います。