2012年7月14日土曜日

アプリケーションのエラー原因解析方法(debug)


アプリケーションにトラブルが発生した場合の解析手段をまとめておく。

目次
- 前提

- 何を調査するか

- ソースコード解析
  静的解析
  動的解析

- コアファイルからの解析

- クラッシュはしないけれど性能が劣化している場合の解析
  スタックトレースを利用して原因分析
  プログラムが利用するシステムコールを監視して原因分析


別の目的でWebエンジニアのためのデータベース技術[実践]入門という書籍を購入したのだが、その中でソースハッキングする手法が説明されており、分かりやすかった。こちらを参考にさせてもらっている。



前提
解析にmysqlを利用するためソースからインストールしておく。
バージョン:mysql-5系
インストールパス:/usr/local/mysql-5.X.XX/

# cd /usr/local/src

# wget http://~/mysql-5.X.XX.tar.gz

# tar zxvf mysql-5.X.XX.tar.gz

$ cd mysql-5.X.XX

$ ./configure --prefix=/usr/local/mysql-5.X.XX --with-debug=full
cmakeが使えるなら、
$ cmake ./ -DCMAKE_INSTALL_PREFIX=/usr/local/mysql-5.X.XX -DCMAKE_BUILD_TYPE=Debug
当然だが、本番系ではdebugモードをつけない。

$ make -j12

$ sudo make install



何を調査するか
mysqlサーバに接続しようとして失敗した回数を記録するステータス変数である、Aborted_connects がいつ加算されていくのかを調査する。



ソースコード解析
● 静的解析
静的解析とは目的のソースファイルと行数を調べてリーディングして解析する方法である。

$ cd /usr/local/src/mysql-5.X.XX/

$ grep -r Aborted_connects ./
./sql/mysqld.cc:  {"Aborted_connects", (char*) &aborted_connects, SHOW_LONG},

もしくは
$ find ./ -type f -name '*cc' -exec grep -l Aborted_connects {} \;

aborted_connectsという変数があやしい。
このがどこで利用されているかを確認する。
$ grep -r aborted_connects ./
./sql/mysqld.cc:ulong aborted_threads, aborted_connects;
./sql/mysqld.cc:      statistic_increment(aborted_connects,&LOCK_status);
./sql/mysqld.cc:  {"Aborted_connects", (char*) &aborted_connects,  SHOW_LONG},
./sql/mysqld.cc:  aborted_threads= aborted_connects= 0;
./sql/sql_connect.cc:    statistic_increment(aborted_connects,&LOCK_status);
./sql/sql_connect.cc:    statistic_increment(aborted_connects,&LOCK_status);
./sql/sql_connect.cc:    statistic_increment(aborted_connects,&LOCK_status);
./sql/mysqld.h:extern ulong aborted_threads,aborted_connects;

もしくは
$ find ./ -type f -name '*cc' -exec grep -l aborted_connects {} \;

各ファイル内で該当の変数が現れる行数を調べておく。

./sql/mysqld.cc
4991行 : statistic_increment(aborted_connects,&LOCK_status);

./sql/sql_connect.cc
546行 : statistic_increment(aborted_connects,&LOCK_status);

591行 : statistic_increment(aborted_connects,&LOCK_status);

772行 : statistic_increment(aborted_connects,&LOCK_status);

あとは力づくでソースコードを読んでいけばよい。
次に紹介する動的解析でこの行番号を利用するため覚えておく。


● 動的解析
ブレークポイントを利用して解析する。

【端末A】
gdbからmysqldを実行する・・・★① ※数字は以下【端末A】と【端末B】での操作順番である
# gdb /usr/local/mysql-5.5.25/bin/mysqld


ブレークポイントを設定する・・・★②
(gdb) br mysqld.cc:4991
(gdb) br sql_connect.cc:546
(gdb) br sql_connect.cc:591
(gdb) br sql_connect.cc:772


mysqldを起動・・・★③
(gdb) run --defaults-file=/etc/my.cnf


ブレークポイントで停止する・・・★⑤
Breakpoint 3, login_connection (thd=0x16d5ba0) at /var/tmp/src/mysql-5.X.XX/sql/sql_connect.cc:591


継続させる・・・★⑥
(gdb) continue


ブレークポイントで停止する・・・★⑧
Breakpoint 3, login_connection (thd=0x16d5ba0) at /var/tmp/src/mysql-5.X.XX/sql/sql_connect.cc:591
591     in /var/tmp/src/mysql-5.5.25/sql/sql_connect.cc
※continueさせているので上記エラーが出るだけで停止はしない


【端末B】
誤ったパスワードでログインする・・・★④
$ /usr/local/mysql-5.5.25/bin/mysql -u root -pbadpassword


3306ポートへ接続する・・・★⑦
$ telnet localhost 3306
その後
ctrl + ] で抜ける。



コアファイルからの解析
クラッシュするような自体になった場合コアから原因を解析する。

# gdb 実行ファイル コアファイル
(gdb) backtrace



クラッシュはしないけれど性能が劣化している場合の解析
● スタックトレースを利用して原因分析
プロセスにstackの情報を取得(アタッチ)する間は該当処理が停まる。
pstack実行以降もずっと停止することはない。しかし、取得するstackの量にもよるが、長い場合は数秒間程度でかかることもあるため、商用系で実施するならよくよく検討した方がいい。

# pstack プロセスID

デバッグモードでビルドしていれば、gdbを使い、ソースコードの行番号も表示させることができる。pstackよりも若干遅くなるが解析には有利であろう。
# gdb --batch --pid=プロセスID


● プログラムが利用するシステムコールを監視して原因分析
-fオプションを付与すればforkした子プロセスもトレースできる。

# strace -p プロセスID 
または
# strace 実行ファイル 
※デーモン化しない例えばlsコマンドの結果などもトレースできる。




(興味深い記事があったので参考までに)
パーフェクトなCRubyを目指して - 1行のバグ修正に潜む苦労