JanGaJan.com

Is fun? JOY!

Rubyでのパフォーマンス改善

Rubyでのパフォーマンス改善に挑戦してみます。 やることとしては以下に絞って確認してみます。

  • benchmarkを使って実行時間を計測
  • stackprofを使ってメソッドの呼び出し状況を確認

例えば、Railsアプリで、PostsController#indexでDBからPostをランダムに10件取得する処理があるとします。 ちなみに、postsテーブルには10万件のレコードがあります。

1
2
3
4
5
class PostsController < ApplicationController
  def index
    @posts = Post.all.sample(10)
  end
end

計測用モジュールを作成する

Ruby2.2にはprependという計測時に便利なメソッドが追加されました。

#{app.root}/libに、app_performance.rbという計測用のモジュールを追加してみます。

1
2
3
4
5
6
7
module AppPerformance
  def index
    p '始まるよ'
    super
    p '終わるよ'
  end
end

ついでに、autoload_paths#{Rails.root}/libを追加するのを忘れないでください。 そして、PostsController側でこのAppPerfonceモジュールをprependしてみます。

1
2
3
4
5
6
7
class PostsController < ApplicationController
  prepend AppPerformance

  def index
    @posts = Post.all.sample(10)
  end
end

これでindexページにアクセスしてみましょう。ログがSQLの前後に表示されていることが確認できますね。

1
2
3
4
5
6
7
Started GET "/posts" for 127.0.0.1 at 2015-11-22 14:30:54 +0900
Processing by PostsController#index as HTML
"始まるよ"
  Post Load (773.0ms)  SELECT "posts".* FROM "posts"  ORDER BY "posts"."published_at" DESC
"終わるよ"
  Rendered posts/index.html.erb within layouts/application (3.0ms)
Completed 200 OK in 1943ms (Views: 45.3ms | ActiveRecord: 773.5ms)

準備が整ったのでindexの処理時間を確認してみましょう。

処理時間を計測する

benchmarkライブラリを使用してみます。

1
2
3
4
5
6
7
8
module AppPerformance
  def index
    result = Benchmark.measure do
      super
    end
    File.open('tmp/benchmark_before.txt', 'w') {|f| f.write(result) }
  end
end

実行結果を確認してみます。

1
2
$ cat tmp/benchmark_before.txt
1.710000   0.110000   1.820000 (  2.208176) )

カッコ内が呼び出しから実行までにかかった時間です。 2.20はだいぶかかっていますねー。

関数の呼び出し状況を計測する

次に、stackprofを利用して関数の呼び出し状況を確認してみましょう。

stackprofをインストールします。

1
2
echo "gem 'stackprof' >> Gemfile"
bundle install

次にapp_performance.rbを修正します。

1
2
3
4
5
6
7
8
9
10
module AppPerformance
  def index
    result = Benchmark.measure do
      StackProf.run(mode: :cpu, raw: true, out: "tmp/stackprof-cpu_before.dump") do
        super
      end
    end
    File.open('tmp/benchmark_before.txt', 'w') {|f| f.write(result) }
  end
end

stackprofコマンドで実行結果を確認します。

1
2
3
4
5
6
7
8
9
10
11
12
$ bundle exec stackprof --text tmp/stackprof-cpu_before.dump --limit 5
==================================
  Mode: cpu(1000)
  Samples: 1236 (0.00% miss rate)
  GC: 440 (35.60%)
==================================
     TOTAL    (pct)     SAMPLES    (pct)     FRAME
       319  (25.8%)         319  (25.8%)     block in SQLite3::Statement#each
       151  (12.2%)         151  (12.2%)     block in ActiveRecord::Result#hash_rows
       325  (26.3%)          85   (6.9%)     block in ActiveRecord::Result#each
        67   (5.4%)          67   (5.4%)     ActiveRecord::Core#init_internals
        62   (5.0%)          31   (2.5%)     ActiveRecord::ModelSchema::ClassMethods#inheritance_column==================================

使用率の高い上位5つのメソッドを表示しました。当然ですが、ARやDB周りのメソッド呼び出しが多いですね。

改善

sampleの利用をやめて、DBで事前にソートするようにしました。 DB依存のコードになってしまいますが、余計な処理を省くためにsqlite3のRANDOM()関数を使用します。

1
2
3
4
5
6
7
class PostsController < ApplicationController
  prepend AppPerformance

  def index
    @posts = Post.order('RANDOM()').take(10)
  end
end

結果はこちら。

1
2
3
4
5
6
7
8
9
10
11
12
13
14
15
$ cat tmp/benchmark_after.txt
  0.090000   0.060000   0.150000 (  0.252615)

$ bundle exec stackprof --text tmp/stackprof-cpu_after.dump --limit 5
==================================
  Mode: cpu(1000)
  Samples: 18 (86.47% miss rate)
  GC: 0 (0.00%)
==================================
     TOTAL    (pct)     SAMPLES    (pct)     FRAME
         3  (16.7%)           3  (16.7%)     ActiveRecord::Core::ClassMethods#arel_table
         2  (11.1%)           2  (11.1%)     ActiveRecord::Base.logger
         2  (11.1%)           2  (11.1%)     block in SQLite3::Statement#each
         1   (5.6%)           1   (5.6%)     Arel::Collectors::PlainString#<<
         1   (5.6%)           1   (5.6%)     block in SQLite3::Statement#get_metadata

ちなみにtakeではなくlimitを利用すると、計測数値はさらに向上します。(render処理での実行時間は遅くなりますが)

だいぶ極端な例になりましたが、benchmarkstackprofを利用することで、改善のポイントや勘所が絞り込みやすくなります。 今回試してみて思ったのはテストしやすいコードは計測しもしやすいコードになりやすそう。 また、prependメソッドは必要以上の変更をせずにメソッドをフックしたいケースで非常に使いやすいです。

Comments