Rails Best Practices を3~4倍ぐらい速くした話、あるいはStackProf入門
TL;DR
- StackProf でボトルネック検出
String#present?は遅いから使わない。- 何度も呼び出される毎回同じ値を返すメソッドをメモ化
- 上記により3~4倍のパフォーマンス改善
はじめに
Rails Best PracticesはRailsに特化したコードメトリックツールです。
仕事柄このようなツールをよく扱うのですが、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/command.rb · railsbp/rails_best_practices
- module function Kernel.#exit (Ruby 2.3.0)
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_nameがCodeAnalyzer::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_nameとextend_class_nameの呼び出し元を見てみると、以下が該当しました。
ここで、Klass#to_sはKlass#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の高速化にチャレンジしてみて下さい。
