前回の記事では Rails 実行中のメソッド呼び出しすべてをトレースしてみましたが、今回のターゲットは Garbage Collection に要している CPU 時間です。前と同じく、render :text => "Hello World!" なアプリに対して Apache Bench から 1万リクエストの負荷を与え、その間の GC 時間をトレースしました。

DTrace の結果をみると、計 75 回の GC が確認され、合計で約 5 秒程度 の CPU 時間を消費しているようです。ab の実行されていた約 40 秒間は、(アクティビティモニタで見ていると) ruby プロセスの CPU 使用率がほぼ 100% 近くに張り付いていたので、そのうちの約 1/8 が GC に使われていたということでしょうか。

# メソッド呼び出しのときと違い、トレース対象をひっかける回数も多くはないので、 DTrace をしかけたことによるオーバーヘッドの影響はほとんどありませんでした。(DTrace をしかけたときとそうでないときで、ab の結果はほとんど同じでした)

以下、作業ログです。







環境 MacBook (intel Core 2 Duo 2GHz)

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!%

Ruby の GC 時間をトレースする DTrace スクリプト rb_gc.d ruby$target:::gc-begin { self->start = vtimestamp; } ruby$target:::gc-end /self->start/ { this->elapsed = vtimestamp - self->start; @count["COUNT"] = count(); @sum["SUM[us]"] = sum(this->elapsed); @avg["AVG[us]"] = avg(this->elapsed); self->start = 0; } dtrace:::END { normalize(@sum, 1000); normalize(@avg, 1000); printf("

"); printa("%-15s %10@d

", @count); printa("%-15s %10@d

", @sum); printa("%-15s %10@d

", @avg); }

DTrace をしかけずに ab だけ実行 まぁこんなものでしょう % ab -c 10 -n 10000 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) (snip) Server Software: Mongrel Server Hostname: 127.0.0.1 Server Port: 3000 Document Path: /post Document Length: 12 bytes Concurrency Level: 10 Time taken for tests: 38.598 seconds Complete requests: 10000 Failed requests: 0 Write errors: 0 Total transferred: 4730018 bytes HTML transferred: 120000 bytes Requests per second: 259.08 [#/sec] (mean) Time per request: 38.598 [ms] (mean) Time per request: 3.860 [ms] (mean, across all concurrent requests) Transfer rate: 119.67 [Kbytes/sec] received

今度は、Dtrace をしかけておいて... % sudo dtrace -s rb_gc.d -p 40211 dtrace: script 'rb_gc.d' matched 3 probes

再び ab を実行 DTrace をしかけてないときとほとんど同じ結果です

GC のはじまりと終わりをひっかけているだけなので、ほとんどオーバーヘッドはかかっていないようですね % ab -c 10 -n 10000 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) (snip) Server Software: Mongrel Server Hostname: 127.0.0.1 Server Port: 3000 Document Path: /post Document Length: 12 bytes Concurrency Level: 10 Time taken for tests: 39.412 seconds Complete requests: 10000 Failed requests: 0 Write errors: 0 Total transferred: 4730018 bytes HTML transferred: 120000 bytes Requests per second: 253.73 [#/sec] (mean) Time per request: 39.412 [ms] (mean) Time per request: 3.941 [ms] (mean, across all concurrent requests) Transfer rate: 117.20 [Kbytes/sec] received