disassembleによるデバッグの方法
開発環境でのバイナリやデバッグバイナリではないもの、すなわち、
- 障害解析対象のプログラムは-gが付いていない(プロダクション用なら当然)
というようなバイナリからとれたstacktraceを手がかりにsignal 11の位置を特定する方法について書きます。
(以前よりも少しやりかたを改善できたのでメモしておきます。もっと簡単にできる方法があればコメント下さい)
16進数のstacktraceを確認
まずエラーログを見る。mysqldの場合はエラーログにstacktraceを吐いてくれるので別にcoreファイルがなくても大丈夫。吐いてくれないプログラムの場合は"ulimit -c unlimited"でcoreを出すようにしておいてbtする。
こんな感じの16進数のstacktraceが取れる。
0x5c4ceb 0x6267de 0x626e63 ...
hoge.logとでもしておく。
バイナリからシンボルを入手
strip済みのバイナリだと取れないので注意。stripしない、あるいは事前に入手しておくことが必要。
GNU binutilsのnmコマンドで採取する。
nm --numeric-sort --demangle=auto mysqld > fuga.sym
オプションの"--numeric-sort"はアドレス順にソートして出力してくれるようにするためのもの。
シンボルとstacktraceを突き合わせる
MySQLには、resolve_stack_dumpという便利なコマンドが付いています。これはシンボル情報とstacktraceをつき合わせて、stacktraceに書かれているアドレスがどの関数のもので、その関数の先頭アドレスから何バイト目のインストラクションのものなのかを判別してくれるものです。
./resolve_stack_dump fuga.sym hoge.log
このコマンドのやっていることは単純な突き合わせなので、使えない場合には人間の目による手動突き合わせでも代用可能です。(面倒くさいけど)
するとこんな感じになります。
0x5c4ceb handle_segfault + 593 0x6267de join_read_next(st_read_record*) + 60 0x626e63 sub_select(JOIN*, st_join_table*, bool) + 499 ...
ここではjoin_read_next(st_read_record*)の開始アドレスから60bytesのところでsignal 11が起きたのではということが分かります。
対象の関数をdisassembleする
join_read_next関数が書かれたソースファイルを見ても、まだどの行が何バイト目なのかが分からないため、ソースの行の特定ができません。
そこでdisassembleしてまずはどのインストラクションを実行する際に問題が起きたのかを調べます。
disassembleはgdbなどで行えます。この時に使うバイナリは障害が起きたものと同じ-g無しのバイナリです。
(gdb) disass join_read_next Dump of assembler code for function _Z14join_read_nextP14st_read_record: 0x00000000006267a2 <_Z14join_read_nextP14st_read_record+0>: push %rbp 0x00000000006267a3 <_Z14join_read_nextP14st_read_record+1>: mov %rsp,%rbp 0x00000000006267a6 <_Z14join_read_nextP14st_read_record+4>: sub $0x20,%rsp 0x00000000006267aa <_Z14join_read_nextP14st_read_record+8>: mov %rdi,0xffffffffffffffe8(%rbp) 0x00000000006267ae <_Z14join_read_nextP14st_read_record+12>: callq 0x88dbe4 <_my_thread_var> 0x00000000006267b3 <_Z14join_read_nextP14st_read_record+17>: mov 0xa8(%rax),%eax 0x00000000006267b9 <_Z14join_read_nextP14st_read_record+23>: and $0x1,%eax 0x00000000006267bc <_Z14join_read_nextP14st_read_record+26>: xor $0x1,%eax 0x00000000006267bf <_Z14join_read_nextP14st_read_record+29>: test %al,%al 0x00000000006267c1 <_Z14join_read_nextP14st_read_record+31>: jne 0x6267f9 <_Z14join_read_nextP14st_read_record+87> 0x00000000006267c3 <_Z14join_read_nextP14st_read_record+33>: callq 0x88dbe4 <_my_thread_var> 0x00000000006267c8 <_Z14join_read_nextP14st_read_record+38>: mov 0xa8(%rax),%eax 0x00000000006267ce <_Z14join_read_nextP14st_read_record+44>: and $0x1a,%eax 0x00000000006267d1 <_Z14join_read_nextP14st_read_record+47>: cmp $0xa,%eax 0x00000000006267d4 <_Z14join_read_nextP14st_read_record+50>: jne 0x6267f9 <_Z14join_read_nextP14st_read_record+87> 0x00000000006267d6 <_Z14join_read_nextP14st_read_record+52>: mov 0xffffffffffffffe8(%rbp),%rax 0x00000000006267da <_Z14join_read_nextP14st_read_record+56>: mov 0x20(%rax),%rdx 0x00000000006267de <_Z14join_read_nextP14st_read_record+60>: mov 0xbe0(%rdx),%rax 0x00000000006267e5 <_Z14join_read_nextP14st_read_record+67>: add $0x1,%rax 0x00000000006267e9 <_Z14join_read_nextP14st_read_record+71>: mov %rax,0xbe0(%rdx) 0x00000000006267f0 <_Z14join_read_nextP14st_read_record+78>: movl $0x0,0xffffffffffffffe4(%rbp) 0x00000000006267f7 <_Z14join_read_nextP14st_read_record+85>: jmp 0x626843 <_Z14join_read_nextP14st_read_record+161> 0x00000000006267f9 <_Z14join_read_nextP14st_read_record+87>: mov 0xffffffffffffffe8(%rbp),%rax 0x00000000006267fd <_Z14join_read_nextP14st_read_record+91>: mov 0x8(%rax),%rax 0x0000000000626801 <_Z14join_read_nextP14st_read_record+95>: mov (%rax),%rax 0x0000000000626804 <_Z14join_read_nextP14st_read_record+98>: add $0xc0,%rax 0x000000000062680a <_Z14join_read_nextP14st_read_record+104>: mov (%rax),%rdx ...
この行で落ちたということになります。
0x00000000006267de <_Z14join_read_nextP14st_read_record+60>: mov 0xbe0(%rdx),%rax
ソースコードをデバッグ情報付きでアセンブラにする
これだけだとまだソースコードの行とアセンブラのインストラクションの対応の裏付けができません。
そこでgccでデバッグ情報付きのアセンブラコードを作成します。
make実行時のログなどから、対象のソースファイルのコンパイル実行コマンドを抜き出してきます。join_read_next関数はsql/sql_select.ccというファイルに書かれていまして、以下のようにコンパイルされていました。
gcc -DMYSQL_SERVER -DDEFAULT_MYSQL_HOME="\"/usr/local/mysql\"" -DDATADIR="\"/usr/local/mysql/data\"" -DSHAREDIR="\"/usr/local/mysql/share/mysql\"" -DHAVE_CONFIG_H -I. -I. -I.. -I../zlib -I../innobase/include -I../innobase/include -I../include -I../include -I../regex -I. -I/usr/include/senna -DDBUG_OFF -g -fno-implicit-templates -fno-exceptions -fno-rtti -c -o sql_select.o sql_select.cc
ここに、--save-tempsオプションを付与することでgccが作る中間ファイル(プリプロセッサ実行後のファイル、アセンブラソースファイル)が残るようになり、さらに-dAオプションを付与することでアセンブラソースファイルにデバッグ情報が付与されるようになります。
gcc -DMYSQL_SERVER -DDEFAULT_MYSQL_HOME="\"/usr/local/mysql\"" -DDATADIR="\"/usr/local/mysql/data\"" -DSHAREDIR="\"/usr/local/mysql/share/mysql\"" -DHAVE_CONFIG_H -I. -I. -I.. -I../zlib -I../innobase/include -I../innobase/include -I../include -I../include -I../regex -I. -I/usr/include/senna -DDBUG_OFF -g -fno-implicit-templates -fno-exceptions -fno-rtti -c -o sql_select.o sql_select.cc --save-temps -dA
disassemble結果、アセンブラソース、C++ソースファイルを比較する
では必要なものがそろったのでそれぞれ比較してみましょう。
sql_select.sでの該当箇所を調べてみます。join_read_nextで検索します。
_Z14join_read_nextP14st_read_record:
.LFB5275:
# sql_select.cc:11295
.loc 16 11295 0
# basic block 0
pushq %rbp
.LCFI1430:
movq %rsp, %rbp
.LCFI1431:
subq $32, %rsp
.LCFI1432:
movq %rdi, -24(%rbp)
.LBB285:
# sql_select.cc:11299
.loc 16 11299 0
call _my_thread_var
movl 168(%rax), %eax
andl $1, %eax
xorl $1, %eax
testb %al, %al
jne .L2870
# basic block 2
call _my_thread_var
movl 168(%rax), %eax
andl $26, %eax
cmpl $10, %eax
jne .L2870
# basic block 3
# sql_select.cc:11304
.loc 16 11304 0
movq -24(%rbp), %rax
movq 32(%rax), %rdx
movq 3040(%rdx), %rax
addq $1, %rax
movq %rax, 3040(%rdx)
# sql_select.cc:11305
.loc 16 11305 0
movl $0, -28(%rbp)
jmp .L2873このうち、以下の行と同じものは、、
0x00000000006267de <_Z14join_read_nextP14st_read_record+60>: mov 0xbe0(%rdx),%rax
10進数表記と16進数表記の違いによりちょっと分かりにくくなっていましたが、sql_select.cc:11304行目に相当するこの部分ですね。
.loc 16 11304 0
movq -24(%rbp), %rax
movq 32(%rax), %rdx
movq 3040(%rdx), %rax
addq $1, %rax
movq %rax, 3040(%rdx)
# sql_select.cc:11305ここの"movq 3040(%rdx), %rax"がこれに該当します。
sql_select.ccの11304行目を見てみると、、
static int join_read_next(READ_RECORD *info) { int error; #ifdef ENABLE_SENNA if ((my_thread_var->sen_flags & SENNA_USE_2IND) && (my_thread_var->sen_flags & (SENNA_MATCH | SENNA_DO_READ_RECORD | SENNA_IF_READ_RECORD)) == (SENNA_MATCH | SENNA_DO_READ_RECORD)) { //error=info->file->index_next(NULL); statistic_increment(info->thd->status_var.senna_2ind_count, &LOCK_status); ←ここが該当 return 0; } else
このstatistic_incrementしている部分で落ちていたようです。
ちなみにstatistic_incrementはマクロなのですが、sql_select.ii(プリプロセッサ後)で見ると、以下のようになっています。
join_read_next(READ_RECORD *info)
{
int error;
if (((_my_thread_var())->sen_flags & (1 << 0)) &&
((_my_thread_var())->sen_flags &
((1 << 1) | (1 << 3) | (1 << 4)))
== ((1 << 1) | (1 << 3))) {
(info->thd->status_var.senna_2ind_count)++;
return 0;
} else
といことで以下の最初の3つのmovqはinfo->thd->status_var.senna_2ind_countをaddqするためにレジスタに入れるための作業だったようです。
.loc 16 11304 0
movq -24(%rbp), %rax
movq 32(%rax), %rdx
movq 3040(%rdx), %rax
addq $1, %rax
movq %rax, 3040(%rdx)
# sql_select.cc:11305ということでstatus_varが0x0だったか、あるいは不正なアドレスを指していたか、ということが分かりました。
最初に得られたのは16進数のstacktraceだけだったのですが、ここまでくると多少はデバッグも進められそうと思います。
おしまい。
