こんにちは！京都開発拠点でGoエンジニアをしています @ysakura_ です。

最近はマネーフォワードクラウド会計Plusの性能問題解決を担当しています。

Ruby on Railsで書かれたコードのボトルネックを調べる目的でRailsのプロファイラを導入し、速度改善をいくつか行いました。今回はプロファイラの使い方、取得できる情報、それを元にしたボトルネックの調査、実際の改善についてご紹介します。

RubyとRailsにおいてパフォーマンスのボトルネックを調査する際には、今回の記事が参考になると思います。

導入したプロファイラ

Ruby用

性能テストで用いる大量データ生成スクリプトが遅かったので導入しました。行単位の実行時間と呼び出し回数を知りたかったので、tmm1/rblineprofを選びました。

インストール方法

以下をGemfileに追加します。

gem "rblineprof", require: false

実装方法

READMEのUsageにある例で説明します。次の様に、lineprof(/./) doで該当箇所を囲み、その上で結果をプリントします。

require 'rblineprof'

profile = lineprof(/./) do
  sleep 0.001

  100.times do
    sleep 0.001

    1*2*3
    4*5*6
    7*8*9*10*11*12*13*14*15
    2**32
    2**128
  end
end

file = profile.keys.first

File.readlines(file).each_with_index do |line, num|
  wall, cpu, calls, allocations = profile[file][num + 1]

  if wall > 0 || cpu > 0 || calls > 0
    printf(
      "% 5.1fms + % 6.1fms (% 4d) | %s",
      cpu / 1000.0,
      (wall - cpu) / 1000.0,
      calls,
      line
    )
  else
    printf "                          | %s", line
  end
end

上のコードを実行すると、以下のログが表示されます。今回の例では、CPU時間, Idle時間(実際の経過時間(Wall) - CPU時間), 呼び出し回数が表示されます。実装を読むに、allocationsには GC.statのtotal_allocated_objectsが入る様です。

                          | require 'rblineprof'
                          | 
                          | profile = lineprof(/./) do
  0.1ms +    1.4ms (   1) |   sleep 0.001
                          | 
  2.7ms +  132.2ms (   1) |   100.times do
  1.3ms +  131.7ms ( 100) |     sleep 0.001
                          | 
                          |     1*2*3
                          |     4*5*6
                          |     7*8*9*10*11*12*13*14*15
  0.1ms +    0.1ms ( 100) |     2**32
  0.6ms +    0.1ms ( 100) |     2**128
                          |   end
                          | end
                          | 
                          | file = profile.keys.first
                          | 
                          | File.readlines(file).each_with_index do |line, num|
                          |   wall, cpu, calls, allocations = profile[file][num + 1]
                          | 
                          |   if wall > 0 || cpu > 0 || calls > 0
                          |     printf(
                          |       "% 5.1fms + % 6.1fms (% 4d) | %s",
                          |       cpu / 1000.0,
                          |       (wall - cpu) / 1000.0,
                          |       calls,
                          |       line
                          |     )
                          |   else
                          |     printf "                          | %s", line
                          |   end
                          | end

Rails用

Rubyのプロファイラを使ってみて、Railsでもプロファイラを利用したくなったので導入する事にしました。会計Plusはコンテナで動いているので、ファイルに結果を出力するタイプのプロファイラはやめました。 S3などをマウントするのは実装が手間である為、Webで結果が見られる点を重視し、peek/peek-rblineprofを選びました。 rblineprofとpeek/peekを内部的に用いており、rblineprofによるプロファイル結果をpeekにより描画している様です。

基本的な使い方

プロファイルを出したいURLで、クエリパラーメーターにlineprofiler=allを指定します以下の画像のように、通常の画面の上に各ファイル/行ごとのrblineprofの結果が描画されます。

画像では途切れていますが、スクロールすると別のファイルのプロファイル結果も表示されています。デフォルトでは、ファイル単位の合計CPU時間の降順でファイルが一覧表示されます。詳しい表示内容は、ソースコードを参照してみてください。

インストール方法

以下をGemfileに追加します。

gem 'peek-rblineprof'

実装方法

会計Plusで実装したコードを例として紹介します。 RAILS_ENV=developmentの時にのみ有効化しています。

if Rails.env.development?
    Peek.into Peek::Views::Rblineprof
end

//= require peek
//= require peek/views/rblineprof

(略)
-if Rails.env.development?
  = stylesheet_link_tag "rblineprof", media: 'all'
  = javascript_include_tag "peek"
  = javascript_include_tag "peek/views/rblineprof"
(略)

(略)
config.assets.precompile += %w( rblineprof.css )
(略)

オプション

検証の時に指定していたオプションを紹介します。 lineprofiler=all&lineprofiler_min=100で自分はテストしていました。詳しいオプションは、ソースコードを参照してみてください。

・lineprofiler 　　・app 　　　　・appとlib配下をプロファイル　　・views 　　　　・app/view配下をプロファイル　　・all 　　　　・Rails.root配下をプロファイル・lineprofiler_min 　　・この時間を超えたファイルのみ、行単位でプロファイルが表示されます。　　　　・単位はミリ秒でデフォルトは5ms

プロファイラを利用した性能改善

プロファイラが導入できたので、プロファイラを利用した実際の性能改善についてご紹介します。

実際のボトルネック調査と改善

本番と同じ構成/スペックの環境を用意して試しました。別途、大量データによる性能テストで遅い画面は分かっていたので、その画面に関してプロファイラを適用しました。性能テストは以下の記事で紹介していますので、よろしければご覧ください。大量データで性能テストをする際に考えた事 ~ 将来のユーザーを見据えたテスト方針 ~

以下では実際に行った2つの改善について紹介します。

呼び出し回数に着目

プロファイラを適用し重い処理の回数に着目した所、キャッシュがExpireして処理が複数回走っている事が分かりました。そこで、時間がかかる処理向けにキャッシュ期間を少し伸ばす対応を入れる事にしました。

問題となっている実行箇所を特定する

会計PlusではDatadogのAPMを使っているのですが、ある画面で同じSQLが2本発行されている事が分かりました。自分はRailsエンジニアではない為、どこでその処理が実行されているかがあまり分かりませんでした。このクエリは比較的重いクエリだった為、プロファイル結果のIdle Timeが長い処理から実行箇所を特定し、改善を行いました。

改善としては、クエリを1度のみ発行し1回目の結果を使い回す様にしました。プロファイラは処理フローや実際に呼び出されるコードを追う上でも便利になるという学びを得ました。