DTraceでMySQLを斬る！

オトコたるもの、30を過ぎれば健康に気をつけなければならぬ。健康と言えば医療であり、ハイテク医療と言えばCTスキャンに代表される非破壊検査である。そしてコンピュータの世界で非破壊検査といえば、現時点ではDTraceをおいて他にない。

DTraceについては以前の投稿（その１賢いdtraceの使い方、その２Dtrace on Leopard）でも紹介したが、今回はユーザー空間のプログラムを、DTraceを使って追跡する方法について紹介する。

DTraceは元々Solaris 10に組み込まれたモジュールであり、動作中のプログラム（カーネルおよびユーザー空間のプログラムの両方）の動作を追跡することができる。今ではオープンソース化され、MacOS X 10.5.xやOpenSolarisなどでも利用可能となった。優れた技術が広まるのは非常に歓迎すべきことである。

DTraceはD言語という特別なプログラム言語を使って操作するのだが、Probeと呼ばれる観測点を以下のような場所に設置することが出来る。

• 関数の呼び出しとリターン
• システムコールの呼び出しとリターン
• コンパイル時に埋め込まれた特定の場所
• 一定時間間隔で
• トレースの開始時と終了時
  

などである。

Probeという観測点でDTraceは情報収集活動をするのだが、どの観測点でどのような情報収集をするかについては、D言語プログラムで調整できるのである。カーネルを含む全てのプログラムにおける全ての関数呼び出し時に情報を出力するというようなことも出来るが、それでは出力される情報が多すぎてまったく役に立たない。如何にして必要な情報を絞り込むかが重要である。

DTraceを使って普段仕事で使っているMySQLをうまく解析する方法はないだろうかと色々考えていたのだが、ひとつアイデアがまとまったので紹介する。サンプルコードを以下のページに置いたので参考にされたい。
http://www.mysqlpracticewiki.com/index.php/Media:My_error.d
※ファイル名は適当に変更するべし。

このプログラムの使い方を紹介する。

1. MySQLサーバー（mysqld）を起動する。
   
2. rootユーザになる。
   
3. プログラムを実行する。 shell> ./my_error.d -p `pgrep -x mysqld`
4. MySQLに接続してエラーを発生させる。 mysql> SELECT * FROM mysql.no_such_table;
   

※本来は、運用中にエラーが間欠的に発生するような場合にこのプログラムを使用する。

以下、プログラムからの抜粋である。プログラムの内容をコメント形式で解説する。

syscall:::return
/errno && execname == "mysqld"/
{
  self->syscall = probefunc;
  self->errno = errno;
}

システムコールがエラーを返した場合にその内容を記録する。2行目ではerrnoがゼロではない場合、つまりシステムコールの結果がエラーだった場合に、なおかつプログラム名がmysqldだった場合に情報をself->syscallとself->errnoに保存している。self->がついた変数はスレッド固有の変数である。D言語はスクリプト言語なので、事前に宣言は必要ない。

pid$target::*mysql_parse*:entry
{
  self->parsed = 1;
  self->query = copyinstr(arg1);
}

mysql_parseという関数は、MySQLのソースコードでいうとsql/sql_parse.ccに含まれる関数である。2番目の引数はSQL文がそのまま格納されているので、MySQLがどのようなSQL文を実行していたかという情報を、self->queryに保存している。self->queryもスレッド固有の変数であるが、スレッド固有の変数は同じスレッドでなら後で好きなときにいつでも参照することができる。

pid$target::*my_error:entry
/self->parsed/
{
        printf("Erroneous Query: %s\n", self->query);
}

このプローブは関数my_error()が呼び出された時に、self->queryの内容を出力する。ただし実行中のSQL文があるかどうかをself->parsedで判定している。

pid$target::*my_error:entry
{
  printf("MySQL Error No: %d\n", arg0);
}

前のProbeと同じ名前のProbeであるが、DTraceでは同じProbeがあった場合には順番にそれらを実行する。my_error()の一番目の引数（arg0）はエラー番号である。エラー番号については以下のページを参照のこと。
http://dev.mysql.com/doc/refman/5.1/ja/errors-handling.html

pid$target::*my_error:entry
{
  printf("MySQL Process Stack:\n");
  ustack();
}

ユーザー空間のプログラムのスタックを出力する箇所である。これにより、my_error()が呼び出されたときにmysqld内の該当スレッドがどのような状態であったかを知ることができる。

以上である。今回はmy_error()というMySQL固有の関数が実行された際にスタックトレースを出力するプログラムの例を示した。このように、DTraceでは情報採取の条件を見極めることにより、必要な情報を如何にして引き出すかが重要となる。