子供のころからできるだけ手抜きして成果を挙げることだけは長けている山本です。

今回は、C/C++ で作ったプログラムが運用中にクラッシュするときのデバッグ方法のお話しです。開発中のデバッグはgdb などでソース追いながらデバッグできますが、運用中ですとstrip していたり最適化していたりしてデバッグが難しくなります。そもそも、いきなりクラッシュすると情報が残らずに困ってしまいます。そんなときどうするか。

Step1.スタックトレースを出力する

こんな関数を用意しましょう。Linux 以外の人はそれなりに実装してください。

#include<execinfo.h>#include<unistd.h>void dump_stack() {void* bt[100];int n = backtrace(bt,100);    backtrace_symbols_fd(bt, n, STDERR_FILENO);}

dump_stack() は標準エラー出力に以下のようなスタックトレースを出力する関数です。

/usr/local/sbin/yrmcdsd[0x420564]/usr/local/sbin/yrmcdsd[0x41b665]/usr/local/sbin/yrmcdsd[0x41be9f]/usr/local/sbin/yrmcdsd[0x41c0ee]/usr/local/sbin/yrmcdsd[0x40bf23]/usr/local/sbin/yrmcdsd[0x40c965]/usr/local/sbin/yrmcdsd[0x404fa2]/lib/x86_64-linux-gnu/libc.so.6(__libc_start_main+0xed)[0x7fe98bad376d]/usr/local/sbin/yrmcdsd[0x4039c9]

読み方はあとで解説します。

Step2. 落ちる箇所に dump を仕込む

事前に落ちる箇所でスタックトレースを出力するようにしないと、情報がとれません。そこで落ちそうなポイントにdump_stack() を仕込んでいきます。

自分で例外を投げるところ

当然ですね。throw をマクロにしてソースコードのファイル名・行番号を出力するようにするのもいいかもしれません。

#define THROW(e) { \    fprintf(stderr,"%s:%d%s\n",__FILE__,__LINE__, #e); \    dump_stack(); \throw (e); }void foo() {    THROW( std::runtime_error("hoge") );}

実行結果はこんな感じになります。

aaa.cpp:19 std::runtime_error("hoge")./aaa[0x400f8f]./aaa[0x400ff7]/lib/x86_64-linux-gnu/libc.so.6(__libc_start_main+0xed)[0x7fd0bbce776d]./aaa[0x400e89]

シグナル

メモリアクセス違反で飛んでくるSIGSEGV や、C++ で飛ばしがちなSIGABRT あたりをハンドルしてやりましょう。

2013/07/06 編集:SIGABRT を受けたらコアファイルを残せるように修正。

#include<signal.h>#include<stdlib.h>#include<string.h>#include<unistd.h>constchar ABORT_MESSAGE[] ="got a signal.\n";void dump_and_abort(int) {    write(STDERR_FILENO, ABORT_MESSAGE,sizeof(ABORT_MESSAGE) -1);    dump_stack();    abort();// will generate a core file.}...struct sigaction act;    memset(&act,0,sizeof(act));    act.sa_handler = dump_and_abort;    act.sa_flags = SA_RESETHAND;// one-shot handler.    sigaction(SIGABRT, &act,NULL);// for SIGABRT...

Step3. シンボルテーブルを作成する

strip は好きですか？　私は好きです。最適化しちゃうとソースコードとは対比とれなくなるので、デバッグ情報を残していても仕方ないと思うんです。C++ でSTL を多用しているようなプログラムでしたら、strip 前は 11 MiB のバイナリが、strip 後は 700 KiB になるなんてざらです。やけに具体的な数字なのは突っ込まないでください。

とはいえ、strip はデバッグ情報だけでなく、シンボル情報も取り除いてしまいます。対策は二つあります。

デバッグ情報だけ取り除く

--strip-debug オプションを指定すれば、デバッグ情報だけ取り除いてくれます。シンボル情報は残るので、いつでもnm で参照できます。

$ strip --strip-debug EXE

あらかじめシンボルテーブルを作成しておく

シンボルテーブルとは、実行ファイルに含まれる関数のアドレスをソートして一覧できるようにしたものです。nm で以下のように作成します。

$ nm -n EXE > EXE.map

中身はこんな感じになります。

000000000040ab30 t _ZNSt17_Function_handlerIFvRN6cybozu7reactorEEZN6yrmcds6server12serve_masterEvEUlS2_E_E9_M_invokeERKSt9_Any_dataS2_000000000040b8c0 T _ZN6yrmcds6server16make_repl_socketEi000000000040bc40 t _ZNSt17_Function_handlerIFSt10unique_ptrIN6cybozu10tcp_socketESt14default_deleteIS2_EEiRKNS1_10ip_addressEEZN6yrmcds6server5serveEvEUliS8_E1_E9_M_invokeERKSt9_Any_dataiS8_000000000040bc60 T _ZN6yrmcds6server12serve_masterEv000000000040c600 T _ZN6yrmcds6server5serveEv000000000040ce30 W _ZN6cybozu8resource13on_invalidateEv000000000040ce40 W _ZNSt16_Sp_counted_baseILN9__gnu_cxx12_Lock_policyE2EE10_M_destroyEv

C++ のシンボルは mangling されているので読めませんね。以下のようにすれば読みやすくなります。

$ c++filt < EXE.map | less000000000040ab30 t std::_Function_handler<void (cybozu::reactor&), yrmcds::server::serve_master()::{lambda(cybozu::reactor&)#1}>::_M_invoke(std::_Any_data const&, cybozu::reactor&)000000000040b8c0 T yrmcds::server::make_repl_socket(int)000000000040bc40 t std::_Function_handler<std::unique_ptr<cybozu::tcp_socket, std::default_delete<cybozu::tcp_socket> > (int, cybozu::ip_address const&), yrmcds::server::serve()::{lambda(int, cybozu::ip_address const&)#3}>::_M_invoke(std::_Any_data const&, int, cybozu::ip_address const&)000000000040bc60 T yrmcds::server::serve_master()000000000040c600 T yrmcds::server::serve()000000000040ce30 W cybozu::resource::on_invalidate()000000000040ce40 W std::_Sp_counted_base<(__gnu_cxx::_Lock_policy)2>::_M_destroy()

Step4. シンボルテーブルからスタックトレースで落ちている箇所を探す

先ほどのスタックトレースを再掲します。

/usr/local/sbin/yrmcdsd[0x420564]/usr/local/sbin/yrmcdsd[0x41b665]/usr/local/sbin/yrmcdsd[0x41bfdf]/usr/local/sbin/yrmcdsd[0x41c0ee]/usr/local/sbin/yrmcdsd[0x40bf23]/usr/local/sbin/yrmcdsd[0x40c965]/usr/local/sbin/yrmcdsd[0x404fa2]/lib/x86_64-linux-gnu/libc.so.6(__libc_start_main+0xed)[0x7fe98bad376d]/usr/local/sbin/yrmcdsd[0x4039c9]

[] 内に表示されているアドレス情報をシンボルテーブルで探します。ぴったり一致する番地はないので、その一つ前のシンボルを。例えば 0x41bfdf の場合、シンボルテーブルに以下の情報があるとすると、cybozu::reactor::poll() で落ちているのが分かります。

000000000041be20 T cybozu::reactor::poll()000000000041c1e0 T cybozu::reactor::run(std::function<void (cybozu::reactor&)>, int)

Final Step. 実行ファイルを disassemble して解析する

ここまで読んでくれる人は何人いるでしょうか。多分大半の人が脱落していると思いますが、一番書きたかったのはここだったりします。さて、cybozu::reactor::poll() のどこかで落ちていることが分かったので、アセンブリを見てみましょう。大丈夫、怖くない。

gdb を立ち上げて、シンボルテーブルから該当する関数を disassemble します。

$ gdb EXE(gdb) disass 0x41be20, 0x41c1e0Dump of assembler code from 0x41be20 to 0x41c1e0:...   0x000000000041be67:  sub    %rax,%rdx   0x000000000041be6a:  add    %rdx,%rdx   0x000000000041be6d:  callq  0x41ca40   0x000000000041be72:  cmp    $0x43,%r12...   0x000000000041bf36:  callq  0x41c7d0   0x000000000041bf3b:  mov    (%rax),%rdi   0x000000000041bf3e:  mov    (%rdi),%rax   0x000000000041bf41:  callq  *0x18(%rax)   0x000000000041bf44:  test   %al,%al...   0x000000000041bf4f:  add    $0x4,%rbp   0x000000000041bf53:  callq  0x41b5b0   0x000000000041bf58:  cmp    %rbp,%r13...   0x000000000041bfd6:  add    $0x4,%rbp   0x000000000041bfda:  callq  0x41b5b0   0x000000000041bfdf:  cmp    %rbp,%r13...

うにゃっと出てきます。ここで assembly を読もうと努力する真面目なあなた、働いたら負けですよ！

ここで注目するべきはcallq です。抜粋してみます。

   0x000000000041be6d:  callq  0x41ca40   0x000000000041be82:  callq  0x41c560   0x000000000041bf36:  callq  0x41c7d0   0x000000000041bf41:  callq  *0x18(%rax)   0x000000000041bf53:  callq  0x41b5b0   0x000000000041bfda:  callq  0x41b5b0

callq の引数はシンボルテーブルにあるはずなので、探してみます。

000000000041ca40 W void std::__introsort_loop<__gnu_cxx::__normal_iterator<int*, std::vector<int, std::allocator<int> > >, long>(__gnu_cxx::__normal_iterator<int*, std::vector<int, std::allocator<int> > >, __gnu_cxx::__normal_iterator<int*, std::vector<int, std::allocator<int> > >, long)000000000041c560 W void std::__insertion_sort<__gnu_cxx::__normal_iterator<int*, std::vector<int, std::allocator<int> > > >(__gnu_cxx::__normal_iterator<int*, std::vector<int, std::allocator<int> > >, __gnu_cxx::__normal_iterator<int*, std::vector<int, std::allocator<int> > >)000000000041c7d0 W std::__detail::_Map_base<int, std::pair<int const, std::unique_ptr<cybozu::resource, std::default_delete<cybozu::resource> > >, std::allocator<std::pair<int const, std::unique_ptr<cybozu::resource, std::default_delete<cybozu::resource> > > >, std::__detail::_Select1st, std::equal_to<int>, std::hash<int>, std::__detail::_Mod_range_hashing, std::__detail::_Default_ranged_hash, std::__detail::_Prime_rehash_policy, std::__detail::_Hashtable_traits<false, false, true>, true>::operator[](int const&)000000000041b5b0 T cybozu::reactor::remove_resource(int)

STL でうにゃっとソートした後に、cybozu::reactor::remove_resource(int) の２回目の呼び出しで落ちていそうということが分かりますね。ほら、怖くない。

以上です。C/C++ でまじめに運用するのってここら辺ができないと辛いですよね、ご同業のみなさん。