pockestrap

Web Programmer's memo

Rails Best Practices を3~4倍ぐらい速くした話、あるいはStackProf入門

github.com

TL;DR

  • StackProf でボトルネック検出
  • String#present?は遅いから使わない。
  • 何度も呼び出される毎回同じ値を返すメソッドをメモ化
  • 上記により3~4倍のパフォーマンス改善

はじめに

Rails Best PracticesはRailsに特化したコードメトリックツールです。

github.com

仕事柄このようなツールをよく扱うのですが、Rails Best Practicesは実行が遅いと言う問題点がありました。
と言うわけでなんとなくプロファイリングして高速化してみました。

プロファイリング

使用ツール

まずは、ボトルネックを探すためにプロファイリングします。

それでは、プロファイリングのためにRailsプロジェクトを用意しましょう。
ある程度大きめのプロジェクトが必要なため、今回はgitlabhq/gitlabhqを使用します。 適当な場所にgit cloneしておきましょう。

また、プロファイラにはtmm1/stackprofを使用します。
インストールしておきましょう。

$ gem install stackprof

時間計測

最初に、何も手を入れていない状態で実行時間を計測しておきましょう。

$ time rails_best_practices

3回ほど繰り返して平均を取ると、実行時間は100秒程度ということが分かりました。

コードの修正

では、rails_best_practicesのコードにプロファイラを仕込みましょう。
rails_best_practicesの実行全体でプロファイラを有効にするため、実行ファイルとなるbin/rails_best_practicesを編集します。

#!/usr/bin/env ruby

$LOAD_PATH.unshift(File.expand_path(File.dirname(__FILE__) + "/../lib"))

require 'stackprof'
StackProf.run(mode: :cpu, out: 'stackprof-out') do
  begin
    require 'rails_best_practices'
    require 'rails_best_practices/command'
  rescue SystemExit
  end
end

メインの処理部分をStackProf.run do ... endの中に囲んでいます。

また、require 'rails_best_practices/command'は、終了コードを指定するため中で直接exit()しています。 このままではStackProfの出力が行われないため、rescue SystemExitして例外を握りつぶしています。

Rails Best Practices のインストール

上記修正を施したrails_best_practicesをインストールしましょう。

$ pwd     # => /home/pocke/ghq/github.com/railsbp/rails_best_practices
$ bundle install
$ bundle exec rake install:local

上記のコマンドを実行することでインストールすることが出来ます。
このコマンドは一般的なGem(bundle gemコマンドで作成されたGem)で通用するので、覚えておくとGemのデバッグの際に便利です。

実行

では、実際にプロファイリングを実行してみましょう。
先ほどインストールしたrails_best_practicesを、gitlabをcloneしてきたレポジトリで実行することでStackProfも実行されます。

$ pwd     # => /home/pocke/ghq/github.com/gitlabhq/gitlabhq
$ rails_best_practices

尚、手元環境(Core i7 6700k)で実行に100秒ほどかかっています。気長に待ちましょう。

解析

コマンドを実行すると、カレントディレクトリにstackprof-outというファイルが生成されます。

$ ls -l stackprof-out
-rw-r--r-- 1 pocke users 63022 Jul 16 13:17 stackprof-out

このファイルの内容をstackprofコマンドで見ていきます。
まずは、オプションをつけずに実行してみましょう。

$ stackprof stackprof-out
==================================
  Mode: cpu(1000)
  Samples: 28963 (0.03% miss rate)
  GC: 7436 (25.67%)
==================================
     TOTAL    (pct)     SAMPLES    (pct)     FRAME
      6242  (21.6%)        6242  (21.6%)     String#blank?
      5757  (19.9%)        5460  (18.9%)     RailsBestPractices::Core::Klass#class_name
     11042  (38.1%)        4200  (14.5%)     RailsBestPractices::Core::Klass#extend_class_name
      2149   (7.4%)         875   (3.0%)     RailsBestPractices::Core::Check#is_interesting_file?
       519   (1.8%)         519   (1.8%)     Sexp#sexp_type
       407   (1.4%)         407   (1.4%)     CodeAnalyzer::Checker.interesting_files
     35975 (124.2%)         371   (1.3%)     RailsBestPractices::Core::Methods#mark_subclasses_method_used
     15696  (54.2%)         340   (1.2%)     RailsBestPractices::Core::Methods#mark_parent_class_method_used
      6466  (22.3%)         224   (0.8%)     Object#present?
       433   (1.5%)         223   (0.8%)     Sexp#children
       207   (0.7%)         207   (0.7%)     CodeAnalyzer::Nil#present?
     17732  (61.2%)         200   (0.7%)     Sexp.from_array
       348   (1.2%)         192   (0.7%)     #<Module:0x00000002ec1fb0>.klasses
       266   (0.9%)         129   (0.4%)     RailsBestPractices::Core::Methods#get_method
       120   (0.4%)         120   (0.4%)     CodeAnalyzer::Checker.callbacks
   1084726 (3745.2%)          88   (0.3%)     CodeAnalyzer::CheckingVisitor::Default#check_node
      5539  (19.1%)          80   (0.3%)     RailsBestPractices::Core::Klass#to_s
        76   (0.3%)          76   (0.3%)     Sexp#initialize
       152   (0.5%)          69   (0.2%)     ActiveSupport::Inflector#apply_inflections
        68   (0.2%)          68   (0.2%)     #<Module:0x00000002ec1fb0>.controllers
        64   (0.2%)          64   (0.2%)     #<Module:0x00000002ec1fb0>.models
        59   (0.2%)          59   (0.2%)     Ripper::SexpBuilder#on_ident
       107   (0.4%)          54   (0.2%)     RailsBestPractices::Core::Methods#has_method?
        53   (0.2%)          53   (0.2%)     RailsBestPractices::Core::Check#regex_ignored_files
       570   (2.0%)          51   (0.2%)     Sexp#sexp_type
       157   (0.5%)          43   (0.1%)     Sexp#to_s
        43   (0.1%)          43   (0.1%)     RailsBestPractices::Core::Methods#methods
        45   (0.2%)          43   (0.1%)     Sexp#==
        39   (0.1%)          39   (0.1%)     RailsBestPractices::Core::Methods#possible_public_used
     42801 (147.8%)          36   (0.1%)     RailsBestPractices::Analyzer#process

どうやら、String#blank?が時間を食っているようです。
ですので、このメソッドを解析していきましょう。 --methodオプションにメソッド名を指定して実行することで、指定したメソッドに対して詳しく解析結果を見ることが可能です。

$ stackprof stackprof-out --method 'String#blank?'
String#blank? (/home/pocke/.gem/ruby/2.3.0/gems/activesupport-5.0.0/lib/active_support/core_ext/object/blank.rb:114)
  samples:  6242 self (21.6%)  /   6242 total (21.6%)
  callers:
    6242  (  100.0%)  Object#present?
  code:
                                  |   114  |   def blank?
                                  |   115  |     # The regexp that matches blank strings is expensive. For the case of empty
                                  |   116  |     # strings we can speed up this method (~3.5x) with an empty? call. The
                                  |   117  |     # penalty for the rest of strings is marginal.
 6242   (21.6%) /  6242  (21.6%)  |   118  |     empty? || BLANK_RE === self
                                  |   119  |   end

さて、これを見ると118行目に時間がかかっていることがわかりますが、これだけではどうしようもありません。
そこで、callersに注目します。 callersでは、このメソッドの呼び出し元一覧が表示されています。 今回は、全てObject#present?からの呼び出しなので、次はこのメソッドを見てみましょう。

ちなみに、--methodオプションは-mと省略することが可能です。

$ stackprof stackprof-out -m 'Object#present?'
Object#present? (/home/pocke/.gem/ruby/2.3.0/gems/activesupport-5.0.0/lib/active_support/core_ext/object/blank.rb:21)
  samples:   224 self (0.8%)  /   6466 total (22.3%)
  callers:
    6466  (  100.0%)  RailsBestPractices::Core::Klass#extend_class_name
  callees (6242 total):
    6242  (  100.0%)  String#blank?
  code:
                                  |    21  |   def present?
 6466   (22.3%) /   224   (0.8%)  |    22  |     !blank?
                                  |    23  |   end

今度もcallersに注目します。
今回はRailsBestPractices::Core::Klass#extend_class_nameからの呼び出しになっていますね。 やっとRails Best Practicesのコードにたどり着きました。 次はこのメソッドについての情報を見てみましょう。

$ stackprof stackprof-out -m 'RailsBestPractices::Core::Klass#extend_class_name'
RailsBestPractices::Core::Klass#extend_class_name (/home/pocke/.gem/ruby/2.3.0/gems/rails_best_practices-1.16.0/lib/rails_best_practices/core/klasses.rb:27)
  samples:  4200 self (14.5%)  /   11042 total (38.1%)
  callers:
    10762  (   97.5%)  RailsBestPractices::Core::Methods#mark_subclasses_method_used
     169  (    1.5%)  RailsBestPractices::Core::Klass#extend_class_name
     110  (    1.0%)  RailsBestPractices::Core::Methods#mark_parent_class_method_used
       1  (    0.0%)  RailsBestPractices::Core::Check::Classable#current_extend_class_name
  callees (6842 total):
    6466  (   94.5%)  Object#present?
     207  (    3.0%)  CodeAnalyzer::Nil#present?
     169  (    2.5%)  RailsBestPractices::Core::Klass#extend_class_name
  code:
                                  |    27  |       def extend_class_name
 10631   (36.7%) /  3958  (13.7%)  |    28  |         if @extend_class_name.present?
  411    (1.4%) /   242   (0.8%)  |    29  |           @modules.map { |modu| "#{modu}::" }.join("") + @extend_class_name
                                  |    30  |         end

ようやく問題のコードが見つかりました。これを最適化していきます。

最適化

該当のメソッドはここで定義されています。
https://github.com/railsbp/rails_best_practices/blob/9c918f09539de60575339e6224e4e7a78f9690d0/lib/rails_best_practices/core/klasses.rb#L27-L31

最適化その1 present?を呼び出さない

present?メソッドが遅いので、メソッド呼び出しをなくせないか検討してみましょう。

適当なコードを仕込んで何回か走らせてみると、このpresent?メソッドがfalseを返す場合は全て@xtended_class_nameCodeAnalyzer::Nilというクラスのインスタンスである場合に限られることが分かりました。
そこで、コードを以下のように修正してみます。

diff --git a/lib/rails_best_practices/core/check.rb b/lib/rails_best_practices/core/check.rb
index 20d186c..d8a158d 100644
--- a/lib/rails_best_practices/core/check.rb
+++ b/lib/rails_best_practices/core/check.rb
@@ -130,7 +130,8 @@ module RailsBestPractices
 
             # remember the class name
             add_callback :start_class do |node|
-              @klass = Core::Klass.new(node.class_name.to_s, node.base_class.to_s, classable_modules)
+              base_class_name = node.base_class.is_a?(CodeAnalyzer::Nil) ? nil : node.base_class.to_s
+              @klass = Core::Klass.new(node.class_name.to_s, base_class_name, classable_modules)
               klasses << @klass
             end
 
diff --git a/lib/rails_best_practices/core/klasses.rb b/lib/rails_best_practices/core/klasses.rb
index 8fde9d2..26d7c90 100644
--- a/lib/rails_best_practices/core/klasses.rb
+++ b/lib/rails_best_practices/core/klasses.rb
@@ -25,7 +25,7 @@ module RailsBestPractices
       end
 
       def extend_class_name
-        if @extend_class_name.present?
+        if @extend_class_name
           @modules.map { |modu| "#{modu}::" }.join("") + @extend_class_name
         end
       end

このDiffから、present?の呼び出しがなくなっていることがわかると思います。
またpresent?の呼び出しを削るために、Klassのコンストラクタを呼び出している箇所でCodeAnalyzer::Nilかどうかを判定しています。

この変更を適用して再度実行時間を計測したところ、77秒程度まで実行時間が改善しました(念の為stackprofのコードは削除しての計測です)。 23秒程度の改善ですね。

最適化その2 呼び出し回数をへらす

なんだかまだ高速化出来る気がします。

ここまでの修正を行った上で、もう一度StackProfを実行してみましょう。

$ stackprof stackprof-out
==================================
  Mode: cpu(1000)
  Samples: 23118 (0.05% miss rate)
  GC: 7190 (31.10%)
==================================
     TOTAL    (pct)     SAMPLES    (pct)     FRAME
      5955  (25.8%)        5660  (24.5%)     RailsBestPractices::Core::Klass#class_name
      5472  (23.7%)        5241  (22.7%)     RailsBestPractices::Core::Klass#extend_class_name
      2273   (9.8%)         942   (4.1%)     RailsBestPractices::Core::Check#is_interesting_file?
       526   (2.3%)         526   (2.3%)     Sexp#sexp_type
       396   (1.7%)         396   (1.7%)     CodeAnalyzer::Checker.interesting_files
     18140  (78.5%)         323   (1.4%)     RailsBestPractices::Core::Methods#mark_subclasses_method_used
     16082  (69.6%)         311   (1.3%)     RailsBestPractices::Core::Methods#mark_parent_class_method_used
       329   (1.4%)         199   (0.9%)     #<Module:0x00000000c34f60>.klasses
     16715  (72.3%)         197   (0.9%)     Sexp.from_array
       368   (1.6%)         190   (0.8%)     Sexp#children
       274   (1.2%)         137   (0.6%)     RailsBestPractices::Core::Methods#get_method
        86   (0.4%)          86   (0.4%)     CodeAnalyzer::Checker.callbacks
    760648 (3290.3%)          73   (0.3%)     CodeAnalyzer::CheckingVisitor::Default#check_node
      5732  (24.8%)          72   (0.3%)     RailsBestPractices::Core::Klass#to_s
        66   (0.3%)          66   (0.3%)     Sexp#initialize
       131   (0.6%)          60   (0.3%)     ActiveSupport::Inflector#apply_inflections
        60   (0.3%)          60   (0.3%)     #<Module:0x00000000c34f60>.controllers
        97   (0.4%)          53   (0.2%)     RailsBestPractices::Core::Methods#has_method?
        51   (0.2%)          51   (0.2%)     Ripper::SexpBuilder#on_ident
        49   (0.2%)          49   (0.2%)     RailsBestPractices::Core::Check#regex_ignored_files
        49   (0.2%)          49   (0.2%)     RailsBestPractices::Core::Methods#possible_public_used
        46   (0.2%)          46   (0.2%)     #<Module:0x00000000c34f60>.models
       570   (2.5%)          44   (0.2%)     Sexp#sexp_type
        43   (0.2%)          43   (0.2%)     Sexp#==
       151   (0.7%)          41   (0.2%)     Sexp#to_s
        84   (0.4%)          35   (0.2%)     RailsBestPractices::Core::Check#is_ignored?
        34   (0.1%)          32   (0.1%)     ActiveSupport::Inflector#underscore
        30   (0.1%)          30   (0.1%)     Ripper::SexpBuilder#on_sp
     25499 (110.3%)          28   (0.1%)     CodeAnalyzer::Checker#node_start
        28   (0.1%)          28   (0.1%)     RailsBestPractices::Core::Methods#methods

どうやら先ほど最適化を行ったKlass周辺が依然として遅いようです。

class_nameextend_class_nameの呼び出し元を見てみると、以下が該当しました。 ここで、Klass#to_sKlass#class_nameエイリアスとなっています

# https://github.com/railsbp/rails_best_practices/blob/9c918f09539de60575339e6224e4e7a78f9690d0/lib/rails_best_practices/core/methods.rb#L58
klass = Prepares.klasses.find { |klass| klass.to_s == class_name }

# https://github.com/railsbp/rails_best_practices/blob/9c918f09539de60575339e6224e4e7a78f9690d0/lib/rails_best_practices/core/methods.rb#L71
Prepares.klasses.select { |klass| klass.extend_class_name == class_name }.each do |klass|

# https://github.com/railsbp/rails_best_practices/blob/9c918f09539de60575339e6224e4e7a78f9690d0/lib/rails_best_practices/core/methods.rb#L92
klass = Prepares.klasses.find { |klass| klass.to_s == class_name }

これを見ると、Klass#to_s及びKlass#extend_class_nameは何回も呼び出されるメソッドであることが分かります。 また、動きを追っていくと両者のメソッド共に途中で値が変化しないことがわかります。

そこで、この二つのメソッドの値をinitalizeの時にインスタンス変数に保存してしまい、attr_readerでそれを参照する用に修正します。

diff --git a/lib/rails_best_practices/core/check.rb b/lib/rails_best_practices/core/check.rb
index 20d186c..d8a158d 100644
--- a/lib/rails_best_practices/core/check.rb
+++ b/lib/rails_best_practices/core/check.rb
@@ -130,7 +130,8 @@ def self.included(base)
 
             # remember the class name
             add_callback :start_class do |node|
-              @klass = Core::Klass.new(node.class_name.to_s, node.base_class.to_s, classable_modules)
+              base_class_name = node.base_class.is_a?(CodeAnalyzer::Nil) ? nil : node.base_class.to_s
+              @klass = Core::Klass.new(node.class_name.to_s, base_class_name, classable_modules)
               klasses << @klass
             end
 
diff --git a/lib/rails_best_practices/core/klasses.rb b/lib/rails_best_practices/core/klasses.rb
index 8fde9d2..b6f1dc4 100644
--- a/lib/rails_best_practices/core/klasses.rb
+++ b/lib/rails_best_practices/core/klasses.rb
@@ -14,19 +14,14 @@ def include?(class_name)
 
     # Class info includes class name, extend class name and module names.
     class Klass
+      attr_reader :extend_class_name, :class_name
+
       def initialize(class_name, extend_class_name, modules)
-        @class_name = class_name
-        @extend_class_name = extend_class_name
         @modules = modules.dup
-      end
-
-      def class_name
-        @modules.map { |modu| "#{modu}::" }.join("") + @class_name
-      end
-
-      def extend_class_name
-        if @extend_class_name.present?
-          @modules.map { |modu| "#{modu}::" }.join("") + @extend_class_name
+        base = @modules.map { |modu| "#{modu}::" }.join("")
+        @class_name =  base + class_name
+        if extend_class_name
+          @extend_class_name = base + extend_class_name
         end
       end

この修正を適用して再度実行速度を計測すると、25~6秒程度まで改善が確認できました。 75秒程実行時間を短縮できています。実行時間が4分の1になっていますね!

まとめ

このようにStackProfを使用すると簡単にプロファイリングが取れるため、Gemの高速化には欠かせないツールと言えるでしょう。
また記事中では省略していますが、途中デバッグpryを仕込んだり、動作確認にテストをこまめに実行することも行っています。

私はRails Best Practicesの他にもRuboCopやNattoなどの高速化を行っています。
この記事を読んで興味がわきましたら、是非Gemの高速化にチャレンジしてみて下さい。