LT申し込んだはいいけどぜんぜん準備してなくて、比較的すぐに書ける内容ってことでDTraceの話をしてきました。LT中にも言ったんだけど、ほんとはplan9上のinfernoでlimboプログラミングとかやってみたかったけどまだムリポ。あと当日いろいろ不手際でごめんなさい > ymsr先生
資料張ってもいいんだけど、あまりに適当すぎたのでもうちょいまとめて書きます。
DTraceってなに?
詳しくは http://ja.wikipedia.org/wiki/DTrace とか http://www.opensolaris.org/os/community/dtrace/ を参照していただくとして、パフォーマンスチューニングのためのプロファイリングツールと思っていただければいいかと。
Solarisカーネルのデフォルト機能だし、Sunが配ってるJVMやApache, 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を!