第2回 197X オフパーティーでDTraceについて話しました

LT申し込んだはいいけどぜんぜん準備してなくて、比較的すぐに書ける内容ってことでDTraceの話をしてきました。LT中にも言ったんだけど、ほんとはplan9上のinfernoでlimboプログラミングとかやってみたかったけどまだムリポ。あと当日いろいろ不手際でごめんなさい > ymsr先生

資料張ってもいいんだけど、あまりに適当すぎたのでもうちょいまとめて書きます。

DTraceってなに?

詳しくは http://ja.wikipedia.org/wiki/DTrace とか http://www.opensolaris.org/os/community/dtrace/ を参照していただくとして、パフォーマンスチューニングのためのプロファイリングツールと思っていただければいいかと。

Solarisカーネルのデフォルト機能だし、Sunが配ってるJVMApache, PHP, MySQLではデフォルトで対応しています。Linuxのoprofileみたいなもんだと思うけど、最初からうごくのでらくちん。

probe

各アプリケーションもしくはカーネルにprobeというのが用意されていて、たとえば関数やシステムコールのタイミングでinterceptして、引数を調べたりcall graphを見たり実行時間を調べたり、なんてことができます。

たとえばMySQL本家が配っているMySQL-5.4.1-betaのSolaris amd64版では、次のようなかんじでprobeを調べることができます。それぞれがどういう意味なのかは、文字列をググるなりソースからgrepするなりして調べてください。

ichii386@count% pfexec dtrace -l -n '*:mysqld:*myisam*:*index*start*'
   ID   PROVIDER            MODULE                          FUNCTION NAME
56961  mysql3468            mysqld __1cMha_myisammrgPindex_next_same6MpCpkCI_i_ index-read-row-start
56962  mysql3468            mysqld __1cMha_myisammrgKindex_last6MpC_i_ index-read-row-start
56963  mysql3468            mysqld __1cMha_myisammrgLindex_first6MpC_i_ index-read-row-start
...

DTraceToolKit

DTraceでググると「DTrace用のD言語があって云々」という例がたくさん見つかると思います。またわけわかんない言語覚えなきゃいけないのかよ、と面倒に思うわけですが、サンプル的によくある使い方をあらかじめ用意してあるのが DTraceToolKit です。

2009.06リリースのOpenSolarisでは、「DTraceToolKit」という名前のパッケージがデフォルトで入っていて、/opt/DTT/ 以下にいろいろスクリプトが転がっていると思います。中身はそのまま読めるスクリプトなので、それを参考にしつつ自分でいろいろアレンジすればよさそう。

hotuser, hotkernel

DTTのなかでも、とりあえず実行してみるとなんとなくありがたいのがhotkernelとhotuser。実は中身はDスクリプトを吐き出して実行するperlスクリプトになっててちょっと気持ち悪いです。

中身はprofile-1001hzとうprobeを使っていて、1001hzで実行ポイントをサンプリングして、サンプリング中の実行時間の割合を表示してくれます。id:a2cが聞いてくれた通り、あまり細かくやりすぎるとカーネルに負荷がかかっちゃうので、これくらいで。

ichii386@count% pfexec /opt/DTT/hotuser -c 'bzip2 ./aho.txt'
Sampling... Hit Ctrl-C to end.

FUNCTION                                                COUNT   PCNT
libbz2.so.1`generateMTFValues                               2   8.3%
libbz2.so.1`bsW                                             2   8.3%
libbz2.so.1`copy_input_until_stop                           2   8.3%
libbz2.so.1`sendMTFValues                                   3  12.5%
libbz2.so.1`mainSimpleSort                                  3  12.5%
libbz2.so.1`mainQSort3                                      4  16.7%
libbz2.so.1`mainSort                                        8  33.3%

mainSortってのがけっこう時間食ってるなー、なんてことが分かります。具体的に何なの? というのは、libbz2のソース読んでね。

ichii386@count% pfexec /opt/DTT/hotkernel
Sampling... Hit Ctrl-C to end.
^C
FUNCTION                                                COUNT   PCNT
...
genunix`kmem_cache_free                                    56   0.2%
unix`ddi_get16                                             87   0.2%
zfs`lzjb_decompress                                       137   0.4%
unix`mutex_enter                                          143   0.4%
unix`ddi_get8                                             169   0.5%
zfs`fletcher_2_native                                     236   0.6%
unix`ddi_io_put8                                          300   0.8%
unix`0xfffffffffb84                                       383   1.0%
unix`i86_mwait                                          32939  88.6%

ほとんどwaitなので面白くないですが、うらで zpool scrub rpool 中です。まあなんとなくzfsがsys time食ってそうだな、てことは分かるかな??

もうちょい実用的な例

あらかじめアプリに用意されたprobeで調べたいことがわかればハッピーですが、そうでない場合もあります。一方でhotuser, hotkernelみたく網羅的すぎるのもまた違ったりで、じゃあ自分でDスクリプト書いてみよう! となるわけですね。

例えばMySQLで、テーブルにindexをたくさん張ってるけど、こいつらがどれくらい使われているのかを調べたい場合。MySQL標準のprobeではindex readのタイミングでテーブル名は分かるんだけど、具体的にどのindexなのかまでは分かりません。もちろんMySQLにパッチ当てるんでもいいけど、そこは極力DTrace側だけでなんとかしたいところ。

MySQLでindexを使うときに必ず呼ばれるのは ha_index_init() ってやつ (斯波さん@ST Global、木下さん@PERCONA、どもでした!!)。

1164   int ha_index_init(uint idx, bool sorted)
1165   {
1166     int result;
1167     DBUG_ENTER("ha_index_init");
1168     DBUG_ASSERT(inited==NONE);
1169     if (!(result= index_init(idx, sorted)))
1170       inited=INDEX;
1171     DBUG_RETURN(result);
1172   }

これをPID Providerで見てみることにします。

#!/usr/sbin/dtrace -s
#pragma D option quiet

pid$target::*ha_index_init*:entry
{
    printf("ha_index_init[%d]: %s,%d,%d,%d\n", timestamp, probefunc, arg0, arg1, arg2);
}

とりあえず冗長めでいろいろ出力版。

サンプルデータ

次のようなテーブルを考えます。

mysql> show create table hoge\G
*************************** 1. row ***************************
       Table: hoge
Create Table: CREATE TABLE `hoge` (
  `id` int(10) unsigned NOT NULL AUTO_INCREMENT,
  `col1` int(10) unsigned NOT NULL DEFAULT '0',
  `col2` char(32) NOT NULL DEFAULT '',
  PRIMARY KEY (`id`),
  KEY `col1` (`col1`),
  KEY `col2` (`col2`)
) ENGINE=MyISAM DEFAULT CHARSET=latin1
1 row in set (0.00 sec)

そして id:sotarok の指示に従い id:moriyoshi の指導を受けつつ、以下のように 100,000 件のサンプルデータを作ります。

-module(aho).
-export([start/0]).
md5_hex(Str) ->
    lists:flatten([ io_lib:format("~2.16.0b", [X]) || X <- binary_to_list(erlang:md5(<<Str>>)) ]).

print_int_char(Num) ->
    lists:foreach(fun (X) -> io:format("~b ~s~n", X) end, [[X, md5_hex(X)] || X <- lists:seq(1, Num)] ).

start() ->
    {_, [[N]]} = init:get_argument(n),
    print_int_char(list_to_integer(N)).
ichii386@count% erl -compile aho
ichii386@count% erl -s aho -n 10 -s erlang halt -noshell -noinput > aho.dat

これを load data で突っ込むと。

mysql> load data local infile '/home/ichii386/work/aho.dat' into table hoge (col1, col2);
Query OK, 100000 rows affected (2.91 sec)
Records: 100000  Deleted: 0  Skipped: 0  Warnings: 0

Dynamic Trace!

ichii386@count% pfexec dtrace -s ./keyname.d -p `pgrep -nx mysqld`

screen起動してどっかで上を実行しつつ、いろいろクエリを投げてみる。

mysql> explain select sql_no_cache col1 from hoge where col1 = 10;
+----+-------------+-------+------+---------------+------+---------+-------+------+-------------+
| id | select_type | table | type | possible_keys | key  | key_len | ref   | rows | Extra       |
+----+-------------+-------+------+---------------+------+---------+-------+------+-------------+
|  1 | SIMPLE      | hoge  | ref  | col1          | col1 | 4       | const |    1 | Using index | 
+----+-------------+-------+------+---------------+------+---------+-------+------+-------------+
1 row in set (0.04 sec)

mysql> select sql_no_cache col1 from hoge where col1 = 10;
+------+
| col1 |
+------+
|   10 | 
+------+
1 row in set (0.00 sec)

そうすると、dtraceしてたほうに

ha_index_init[536298870765270]: __1cHhandlerNha_index_init6MIb_i_,1275437192,1,1

と出力されました! ha_index_init() 読めば分かる通り、うしろから2つ目の 1 が "KEY `col1` (`col1`)" に対応してるんですね!

ちなみに PRIMARY KEY が 0 でそこから連番、 sql_no_cache 外す (クエリキャッシュ使う) とちゃんとtraceに出なくなります。

もうちょい

  • index_usage.d
#!/usr/sbin/dtrace -s
#pragma D option quiet

pid$target::*ha_index_init*:entry
{
    /*
    @[probefunc, arg1, arg2] = count();
    */
    printf("ha_index_init[%d]: %s,%d\n", timestamp, probefunc, arg1);
}

:mysqld::index-read-row-start
{
    printf("index-read-row-start[%d]: %s,%s,%s\n", timestamp, probefunc, copyinstr(arg0), copyinstr(arg1));
}
  • explainする
mysql> explain select sql_no_cache * from hoge as h1, hoge as h2 where h1.id = h2.col1 and h1.col2 like 'a%' order by h1.id asc limit 1;
+----+-------------+-------+-------+---------------+---------+---------+-----------+------+-------------+
| id | select_type | table | type  | possible_keys | key     | key_len | ref       | rows | Extra       |
+----+-------------+-------+-------+---------------+---------+---------+-----------+------+-------------+
|  1 | SIMPLE      | h1    | index | PRIMARY,col2  | PRIMARY | 4       | NULL      |   16 | Using where | 
|  1 | SIMPLE      | h2    | ref   | col1          | col1    | 4       | aho.h1.id |    1 |             | 
+----+-------------+-------+-------+---------------+---------+---------+-----------+------+-------------+
2 rows in set (0.00 sec)
  • selectすると
ha_index_init[536856224757983]: __1cHhandlerNha_index_init6MIb_i_,0
index-read-row-start[536856224773502]: __1cJha_myisamLindex_first6MpC_i_,aho,hoge
index-read-row-start[536856224878251]: __1cJha_myisamKindex_next6MpC_i_,aho,hoge
index-read-row-start[536856224924024]: __1cJha_myisamKindex_next6MpC_i_,aho,hoge
index-read-row-start[536856224966714]: __1cJha_myisamKindex_next6MpC_i_,aho,hoge
index-read-row-start[536856225009096]: __1cJha_myisamKindex_next6MpC_i_,aho,hoge
index-read-row-start[536856225109642]: __1cJha_myisamKindex_next6MpC_i_,aho,hoge
index-read-row-start[536856225152829]: __1cJha_myisamKindex_next6MpC_i_,aho,hoge
index-read-row-start[536856225195580]: __1cJha_myisamKindex_next6MpC_i_,aho,hoge
index-read-row-start[536856225238180]: __1cJha_myisamKindex_next6MpC_i_,aho,hoge
index-read-row-start[536856225280532]: __1cJha_myisamKindex_next6MpC_i_,aho,hoge
index-read-row-start[536856225323117]: __1cJha_myisamKindex_next6MpC_i_,aho,hoge
index-read-row-start[536856225365853]: __1cJha_myisamKindex_next6MpC_i_,aho,hoge
index-read-row-start[536856225408273]: __1cJha_myisamKindex_next6MpC_i_,aho,hoge
index-read-row-start[536856225450670]: __1cJha_myisamKindex_next6MpC_i_,aho,hoge
index-read-row-start[536856225493007]: __1cJha_myisamKindex_next6MpC_i_,aho,hoge
index-read-row-start[536856225535615]: __1cJha_myisamKindex_next6MpC_i_,aho,hoge
index-read-row-start[536856225577914]: __1cJha_myisamKindex_next6MpC_i_,aho,hoge
index-read-row-start[536856225620259]: __1cJha_myisamKindex_next6MpC_i_,aho,hoge
ha_index_init[536856225663295]: __1cHhandlerNha_index_init6MIb_i_,1
index-read-row-start[536856225674197]: __1cJha_myisamOindex_read_map6MpCpkCLnQha_rkey_function__i_,aho,hoge

ちょっとここまで細かいと負荷もひどいので微妙ですが、explainよりももうちょい細かい実行計画の流れ調べたいときにも使えそうですね!

まとめ

Solaris使ってる人ってやっぱり少ないんですね。自分も1年前は「Debianしかありえねーだろ」と思っていたけど、OpenSolarisならユーザランドもけっこう整備されていていいかんじです。

デスクトップ環境ならやっぱDebian自宅サーバにはぜひOpenSolarisを!