私はt_time_tracker (woohoo!) と呼ばれる最初の gem を開発しています。開発は順調に進んでいました。実行時間をできるだけ短縮するために、可能な限り最適化しました。
t_time_tracker[master*]% time ruby -Ilib ./bin/t_time_tracker
You're not working on anything
0.07s user 0.03s system 67% cpu 0.141 total
(これは私のアプリの「Hello World」です。パラメーターなしで呼び出すと、「You're not working on anything」と表示されます)
約 10 分の 1 秒で、CPU の 67% を使用します。これで十分です。割とあっさりした感じです。それを構築しましょう:
$ gem build t_time_tracker.gemspec
$ gem install ./t_time_tracker-0.0.0.gem
そして、インストールされたバイナリでまったく同じことを行います:
$ time t_time_tracker
You're not working on anything
t_time_tracker 0.42s user 0.06s system 93% cpu 0.513 total
0.5秒?!それはどこから来ましたか?!デバッグ出力を追加し、開発バイナリのシステム gem を含めて、ボトルネックがどこにあるかを確認してみましょう。
t_time_tracker[master*]% time ruby ./bin/t_time_tracker
(starting binary)
(require 'time' and 'optparse')
0.041432
(before `require 't_time_tracker')
0.497135
(after `require 't_time_tracker')
(Gem.loaded_specs.keys = t_time_tracker)
(initializing TTimeTracker class)
You're not working on anything
ruby ./bin/t_time_tracker 0.44s user 0.07s system 91% cpu 0.551 total
よし、'require 't_time_tracker' 行が原因のようだ。irb でもう一度試して、さらに絞り込みましょう。
$ irb
>> t=Time.now; require 't_time_tracker'; puts Time.now-t
0.046792
=> nil
...何?しかし、それには 0.5 秒しかかかりませんでした。デバッグ出力を使用して gem をビルドしてみましょう。
$ gem build t_time_tracker.gemspec
$ gem install ./t_time_tracker-0.0.0.gem
$ time t_time_tracker
(starting binary) <---noticeable half second delay before this line shows up
(require 'time' and 'optparse')
0.050458
(before `require 't_time_tracker')
0.073789
(after `require 't_time_tracker')
(Gem.loaded_specs.keys = t_time_tracker)
(initializing TTimeTracker class)
You're not working on anything
t_time_tracker 0.42s user 0.06s system 88% cpu 0.546 total
ええ、この 0.5 秒の遅延はどこから来ているのでしょうか? 私は普段は気にしませんが、これは私がやっていることを更新するために 1 日に約 50 回電話をかけていることです。50 * 0.5 秒 * 365 日 * 70 年 = 失われた 15 日。
システムインフォメーション:
Mac OS X 10.7.3。2 GHz インテル Core 2 Duo。4GBのラム。ルビー 1.9.2p290。
% gem -v
1.8.10<---noticeable half second delay before this line shows up
% gem list | wc -l
209