子供のころからできるだけ手抜きして成果を挙げることだけは長けている山本です。
今回は、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> const char 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_socketEi 000000000040bc40 t _ZNSt17_Function_handlerIFSt10unique_ptrIN6cybozu10tcp_socketESt14default_deleteIS2_EEiRKNS1_10ip_addressEEZN6yrmcds6server5serveEvEUliS8_E1_E9_M_invokeERKSt9_Any_dataiS8_ 000000000040bc60 T _ZN6yrmcds6server12serve_masterEv 000000000040c600 T _ZN6yrmcds6server5serveEv 000000000040ce30 W _ZN6cybozu8resource13on_invalidateEv 000000000040ce40 W _ZNSt16_Sp_counted_baseILN9__gnu_cxx12_Lock_policyE2EE10_M_destroyEv
C++ のシンボルは mangling されているので読めませんね。以下のようにすれば読みやすくなります。
$ c++filt < EXE.map | less 000000000040ab30 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, 0x41c1e0 Dump 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)
の2回目の呼び出しで落ちていそうということが分かりますね。
ほら、怖くない。
以上です。C/C++ でまじめに運用するのってここら辺ができないと辛いですよね、ご同業のみなさん。