DTrace をためしてみました
Rails 実行時の CPU 使用率がけっこう高いので、DTrace でなにかわからないものかと使ってみました。
以下のような環境のもとで、ここのサンプルをちょっと改良して、Apache Bench (以下、ab) で負荷をかけている Rails アプリをトレースしてみました。関数呼び出しごとの回数、平均処理時間、合計処理時間なんかをみています。GC にかかった CPU 時間なんかもトレースできるので、DTrace、面白いですね。
DTrace は軽いはずなんですが、関数呼び出しをすべてひろって集計とかをゴリゴリしているので、さすがにトレースの負荷が高かったです。 (^^;
# アプリの監視という意味では、もっと粗粒度のもの、リクエストごととか、データベース問い合わせごとでみるはずなので、そのくらいであればオーバヘッドはほとんど無視できるのでしょう。
ちなみに、DTrace のスレッドローカル変数の領域はデフォルトではけっこう小さいので、オプションをつけずに実行すると取りこぼしがわらわらとでてしまいました。ここらへんは注意が必要ですね。
(追記: 2009-2-12)
timestamp/vtimestamp で取得したメソッド呼び出し時間の合計値が明らかに実際の経過時間より大きくなっていましたが、DTrace の副作用である旨が資料に書かれていました。詳細は最後のほうに載せています。
環境
- iMac (intel Core 2 Duo 2.33GHz)
- Mac OS X 10.5.6
- 処理系、ライブラリのバージョンは以下のとおり
% /usr/bin/ruby -v ruby 1.8.6 (2008-03-03 patchlevel 114) [universal-darwin9.0] % dtrace -V dtrace: Sun D 1.2.2 % rails -v Rails 2.2.2 # 単純に render :text => "Hello World!" するだけのアプリを用意 % curl http://127.0.0.1:3000/posts Hello World!%
DTrace のスクリプト
- rb_functime_ext.d
- ほとんど、ここのパクリで、CPU時間と全関数呼び出しのサマリを出すようにしています
this string class;
this string method;
dtrace:::BEGIN
{
printf("Tracing... Hit Ctrl-C to end.\n");
depth = 0;
}
ruby$target:::function-entry
{
self->depth++;
self->start[copyinstr(arg0), copyinstr(arg1), self->depth] = vtimestamp;
@num["Total", "in"] = count();
}
ruby$target:::function-return
/(this->class = copyinstr(arg0)) != NULL && (this->method = copyinstr(arg1)) != NULL && self->start[this->class, this->method, self->depth]/
{
this->elapsed = vtimestamp - self->start[this->class, this->method, self->depth];
@num[this->class, this->method] = count();
@eavg[this->class, this->method] = avg(this->elapsed);
@esum[this->class, this->method] = sum(this->elapsed);
@edist[this->class, this->method] = quantize(this->elapsed);
@num["Total", "out"] = count();
@eavg["Total", "out"] = avg(this->elapsed);
@esum["Total", "in"] = sum(this->elapsed);
@esum["Total", "out"] = sum(this->elapsed);
self->start[this->class, this->method, self->depth] = 0;
self->depth--;
}
dtrace:::END
{
normalize(@eavg, 1000);
normalize(@esum, 1000);
printf("ELAPSED TIME DISTRIBUTION,\n");
printa(@edist);
setopt("aggsortpos", "2");
printf("%-33s %45s\n", "___ OVERLAP TIMES: ___", "______ ELAPSED ______");
printf("%-24s %-23s %6s %10s %12s\n", "CLASS", "METHOD", "COUNT", "AVG(us)", "SUM(us)");
printa("%-24.24s %-23.23s %@6d %@10d %@12d\n", @num, @eavg, @esum);
}
DTrace をしかけずに ab だけ実行
- たった、100回の実行なので、あっという間です!
% ab -c 10 -n 100 http://127.0.0.1:3000/posts This is ApacheBench, Version 2.3 <$Revision: 655654 $> Copyright 1996 Adam Twiss, Zeus Technology Ltd, http://www.zeustech.net/ Licensed to The Apache Software Foundation, http://www.apache.org/ Benchmarking 127.0.0.1 (be patient).....done Server Software: Mongrel Server Hostname: 127.0.0.1 Server Port: 3000 Document Path: /posts Document Length: 12 bytes Concurrency Level: 10 Time taken for tests: 0.460 seconds Complete requests: 100 Failed requests: 0 Write errors: 0 Total transferred: 47201 bytes HTML transferred: 1200 bytes Requests per second: 217.20 [#/sec] (mean) Time per request: 46.040 [ms] (mean) Time per request: 4.604 [ms] (mean, across all concurrent requests) Transfer rate: 100.12 [Kbytes/sec] received
DTrace をしかけたときの ab の結果
- かなーり時間がかかっています... ざっと 20 倍くらい
% ab -c 10 -n 100 http://127.0.0.1:3000/posts This is ApacheBench, Version 2.3 <$Revision: 655654 $> Copyright 1996 Adam Twiss, Zeus Technology Ltd, http://www.zeustech.net/ Licensed to The Apache Software Foundation, http://www.apache.org/ Benchmarking 127.0.0.1 (be patient).....done Server Software: Mongrel Server Hostname: 127.0.0.1 Server Port: 3000 Document Path: /posts Document Length: 12 bytes Concurrency Level: 10 Time taken for tests: 10.095 seconds Complete requests: 100 Failed requests: 0 Write errors: 0 Total transferred: 47300 bytes HTML transferred: 1200 bytes Requests per second: 9.91 [#/sec] (mean) Time per request: 1009.509 [ms] (mean) Time per request: 100.951 [ms] (mean, across all concurrent requests) Transfer rate: 4.58 [Kbytes/sec] received
そのときの DTrace の結果
- 妙なログ "xxx dynamic variable drops" がたくさんでています、うまく測れてなさそう?
- 3万近い関数呼び出しをトレースしてるので、オーバヘッドも馬鹿にならないのかな...
- でも、合計 CPU 時間は 2秒くらいしかなくてなんか変!?
% sudo dtrace -s rb_functime_ext.d -p 74473 dtrace: script 'rb_functime_ext.d' matched 4 probes CPU ID FUNCTION:NAME 1 1 :BEGIN Tracing... Hit Ctrl-C to end. dtrace: 538 dynamic variable drops with non-empty dirty list dtrace: 28791 dynamic variable drops dtrace: 4624 dynamic variable drops with non-empty dirty list dtrace: 35199 dynamic variable drops dtrace: 35204 dynamic variable drops dtrace: 21923 dynamic variable drops dtrace: 17 dynamic variable drops dtrace: 11 dynamic variable drops dtrace: 11 dynamic variable drops dtrace: 11 dynamic variable drops ... (snip) ... ___ OVERLAP TIMES: ___ ______ ELAPSED ______ CLASS METHOD COUNT AVG(us) SUM(us) Time compare_without_coercio 8 5 46 Module included 18 4 87 Array blank? 18 4 88 ... (snip) ... ActionController::Base close_session 17 2251 38279 ActionController::Base process_cleanup_without 17 2264 38503 Object process_cleanup_without 17 2350 39951 Object process_cleanup 17 2364 40192 Object run_callbacks 70 578 40514 Object send 239 266 63719 Class new 702 158 110978 Mutex synchronize 33 3560 117487 Total out 29161 65 1922062 Total in 30683 0 1922062
"xxx dynamic variable drops" ってなに?
- Sun に DTrace - dynamic variable drop なページがあり、ここで紹介されている PDF の P22
- 変数用の領域がデフォルトでは小さいので、正しい結果が得られないことがあるみたい
- オプションを設定するべし、と...ふむふむ
Gotcha: Dynamic variable drops
- DTrace has a finite dynamic variable space for use by thread-local variables and associative array variables
- When exhausted, subsequent allocation will induce a dynamic variable drop, e.g.:
- dtrace: 103 dynamic variable drops
- These drops are often caused by failureto zero dead dynamic variables
- Must be eliminated for correct results!
Tip: Tuning away dynamic drops
- If a program correctly zeroes dead dynamic variables, drops must be eliminated by tuning
- Size tuned via the dynvarsize option
- In some cases, “dirty” "r “rin" dynamic variable drops may be seen:
- dtrace: 73 dynamic variable drops with non-empty dirty list
- These drops can be eliminated byincreasing cleanrate
というわけで、オプションをつけて DTrace を実行
- 今度は妙なログはでなかった
- CPU 時間も10秒で妥当そう?
- でも、関数の入口と出口でカウントをとってるはずなのに、なぜか差が生じてる... orz
% sudo dtrace -s rb_functime_ext.d -p 74473 -x dynvarsize=20000000 dtrace: script 'rb_functime_ext.d' matched 4 probes CPU ID FUNCTION:NAME 1 1 :BEGIN Tracing... Hit Ctrl-C to end. ... (snip) ... ___ OVERLAP TIMES: ___ ______ ELAPSED ______ CLASS METHOD COUNT AVG(us) SUM(us) IO read 1 56 56 Mongrel::HttpResponse send_body 1 78 78 Mongrel::HttpResponse send_header 1 93 93 TCPServer accept 3 35 105 Mongrel::HttpResponse send_status 1 144 144 Mongrel::HttpResponse write 3 49 147 Time compare_without_coercio 29 5 162 IO readpartial 2 120 241 Mongrel::HttpResponse finished 1 353 353 Fixnum * 100 4 480 Module included 100 4 481 ... (snip) ... ActiveSupport::Callbacks run 386 392 151470 Hash [] 13998 10 152694 ActionController::Base log_processing 88 1811 159408 CGI::Cookie initialize 100 1759 175919 ActiveSupport::Callbacks call 291 608 177066 CGI::Session::CookieStor write_cookie 100 1858 185827 CGI::Session::CookieStor close 100 2125 212568 CGI::Session close 100 2151 215142 ActionController::Base close_session 100 2175 217563 Object run_callbacks 378 578 218638 ActionController::Base process_cleanup_without 100 2188 218808 Object process_cleanup_without 100 2270 227099 Object process_cleanup 100 2284 228412 Object send 1286 278 357680 Class new 3300 156 516029 Mutex synchronize 177 3549 628291 Total out 150258 72 10859498 Total in 157439 0 10859498
今回のスクリプトでは、時間をとるのに timestamp ではなく、vtimestamp を使用しました。
D 言語を使ったスクリプトの作成 (DTrace ユーザーガイド) - Sun Microsystems によると、それぞれの意味は次のとおりです。
- uint64_t timestamp
ナノ秒タイムスタンプカウンタの現在の値です。このカウンタの値は、過去の任意の時点から増分しています。そのため、このカウンタは、相対計算専用です。
- uint64_t vtimestamp
ナノ秒タイムスタンプカウンタの現在の値です。このカウンタは、現在のスレッドの CPU 上での実行時間を示します。これには、DTrace の述語やアクションの実行にかかる時間は含まれません。このカウンタの値は、過去の任意の時点から増分しています。そのため、このカウンタは、相対時間計算専用です。
vtimestamp での関数呼び出しの合計値は 10859498 マイクロ秒、すなわち 約 11秒でしたが、timestamp を使って同様に合計値を求めてみると、40秒近くになってしまいました。
ab で 10秒程度負荷をかけていたのにその結果って...? 誤差の詰み重ねにしては微妙なような...?
# 相対的な時間の配分はわかるので、その用途でなら今の結果で十分なのですが。うーん。
(追記: 2009-2-12)
"xxx dynamic variable drops" について書かれていた PDF をよくよく見ていたら、理由と思われる記述がありました。やはり避けられない副作用があるみたいですね。
なので、とくに今回のようなオーバーヘッドの大きくなるようなトレースでは、絶対値はほとんど意味がないものと思ったほうがよいでしょう。
Gotcha: vtimestamp
- vtimestamp represents the number of nanoseconds that the current thread has spent on CPU since some arbitrary time in the past
- vtimestamp factors out time spent in DTrace – the explicit probe effect
- There is no way to factor out the implicit probe effect: cache effects, TLB effects, etc. due to DTrace
- Use the absolute numbers carefully!
今回は、Mongrel で Rails を動かしてますが、近いうちに Thin とかでもトレースをとってみようと思います。あとは、もう少し複雑なアプリでも結果をみてみたいと思います。
