Feedforce Developer Blog

フィードフォース開発者ブログ

rblineprofでRubyアプリケーションの速度を計測する、あるいはevalで評価するDSLを無理矢理requireする

Ruby メタプログラミング

こんにちは、id:azminです。好きなフィルムはKodakのULTRA MAX 400です。ずっとパッケージの表記から「ULTRAMAX」だと思っていたのですが、この記事を書きながら公式サイトを見て初めて間にスペースが入ることを知りました。

今回は、プロダクトのアプリケーションの実行速度を測って、ボトルネックを見つけて改善した話をご紹介します。

はじめに

プログラムの実行速度の向上は、開発や運用を続けていると、ときに重要な課題となる。バッチアプリケーションであるDFMakerにおいても、バッチの高速化はチームメンバーの作業効率向上や、AWSリソースの利用効率の改善に結びつくので、継続して取り組んでいる。

速度改善のためのチューニングには、プログラムの実行速度の測定が不可欠である。計算量の見積もりに基づいて改善施策を立てることもできるが、その施策にどれほどの効果があるか明らかにするには、実際に実行にかかる時間を計測するほかない。また、効果的な改善ポイント、つまり処理のボトルネックを見つけるのにも実行時間の計測は役立つ。

プログラムの実行状況を計測するツールは、それぞれのプログラミング言語においてさまざまな目的のために存在する。今回、DFMakerでは rblineprof というライブラリを用いてバッチ実行時間の計測を行った。通常、rblineprofは Kernel#require や Kernel#load で読み込まれたスクリプトの1行ごとの実行時間を計測できる。 DFMakerの変換設定は、 instance_eval でロードされるため、そのままではrblineprofによる計測ができなかったが、一時的に別ファイルに保存して require する、という手法で行ごとのプロファイリングを可能にした。

これにより、DFMakerの汎用処理だけでなく、フィードごとの変換設定も含めたパフォーマンスチューニングが可能になり、バッチ処理の速度改善に取れる施策の幅が広がった。

サービスの紹介

この記事で取り上げるDF PLUSは、広告主に代わってデータフィードの作成と配信を行い、データフィード広告の運用をサポートするサービスである。データフィードの作成とは、広告主の持つ商材データから、広告プラットフォームのデータ形式への変換と言うことができる。DF PLUSは、クライアントと合意した変換仕様に基づいて、フィードフォースが変換ロジックを作成するアウトソーシング型のサービスである。

フィードフォースが提供するデータフィード構築サービスには、他にdfplus.ioがある。dfplus.ioは、ユーザーが管理画面を通じて変換ルールを設定するセルフサーブ型のSaaS、という異なる性格が与えられている。これにより、データフィード広告への取り組み方に応じて適したサービスを選べるラインナップを構成している。

データフィード広告が一体どのようなものかについては、以下のdfplus.ioのブログ記事に簡潔にまとめられているので、気になる方は参照されたい。

blog.dfplus.io

rblineprof とは

rblineprof とは、Rubyコードの実行時間を一行ごとに計測するためのgemである。

READMEに従ってRubyスクリプトを実行すると、以下のようにその行のコードを実行するのに要したCPU時間および待ち時間と、スクリプト終了までに呼び出された回数が得られる。

                          | 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
                          | 
# 後略

ここでの待ち時間とは、1行の処理にかかった時間からCPUの処理時間を引いたものである。メモリ、ディスク、ネットワーク等CPUの外にあるデバイスの処理にかかる時間なので、「待ち時間」と称する。

このように、行ごとの処理時間の内訳を知ることで、単純にCPUの性能に縛られる処理、CPUから見た外部デバイスが足を引っ張る処理、呼び出し回数が見立てより多い処理、という具合にアタリをつけることができ、スクリプト実行効率の改善に役立つ。

DFMakerにおける変換設定のロード方法

DF PLUSは、データフィード生成に必要な機能を備えたRubyアプリケーション「DFMaker」と、広告主の商材データを広告媒体のデータ形式に変換するために必要なロジックを記述した「変換設定」と呼ばれる、2つのコードベースによって機能する。DFMakerは主にDF PLUSの開発者がメンテナンスを行う一方、変換設定はデータフィードの作成・配信を担うディレクターがメンテナンスする。

DFMakerと変換設定は別のGitリポジトリとし、それぞれのCIでDockerイメージのビルドを行う。これにより、開発者とディレクターそれぞれのタイミングでリリースできるようになっている。本番環境でアプリケーションが起動するときには、DFMakerコンテナが変換設定コンテナのボリュームをマウントする。

変換設定がDFMakerコンテナ上のファイルとして参照できるようになった後は、DFMaker上でいったん文字列として展開され、その文字列をRubyコードとして実行することでロードされる（ ConfigLoader インスタンスをselfに instance_eval する）。変換設定に必要な機能はあらかじめDFMakerの ConfigLoader や Column といったクラスに用意されており、ディレクターが記述した変換設定は、それらのクラスのコンテキストで実行される。

DFMakerのコードから変換設定をロードする部分を抜き出したのが以下のコードである。

class Converter
  class ConfigLoader
    # Convert 設定ファイルを評価して、結果を @config に格納する
    def load!
      contents = load_path.read
      # 中略
      instance_eval(contents, load_path.to_s)
    end
  end
end

eval 類のメソッドを利用するとすぐ「黒魔術」などと言われる向きもあるが、変換設定を記述するディレクターは「これは何々モジュールの拡張である」といったことを意識せず、案件ごとの関心事に集中できるという点でこの方式は優れている。

rblineprofが行ごと・ファイルごとに結果を集計するメカニズム

rblineprofのプロファイリングは、Ruby VMのメソッド呼び出しと、メソッド呼び出しからのリターンイベントをフックして行われる。

呼び出しとリターンの間で経過時間や配置されたオブジェクトの増分を記録し、Rubyスクリプトのファイル単位で集計される。このとき、これから呼び出す/リターンしたメソッドがどのファイルに由来するのかを特定するために、Ruby VMのInstructionSequence（以下isecと呼ぶ）の absolute_path という属性を利用する。

iseqは、コンパイル済のRubyコードとそのメタデータ等を含む、Ruby VM上の中間表現である。Rubyからも一部の機能を利用でき、Rubyのリファレンスマニュアルが存在する。それによると、「命令シーケンスの絶対パス」を返す #absolute_path というメソッドは、

self が表す命令シーケンスの絶対パスを返します。

self を文字列から作成していた場合は nil を返します。

という動作をする。「self を文字列から作成していた場合は nil」ということは、eval によってロードされたコードは元ファイルを探そうとしても nil を返す、ということである。これはRubyオブジェクトとしてのiseqの振る舞いに関するドキュメントだが、rblineprofが扱うネイティブのiseqも同じように振る舞うと考えてよいだろう。

そして、元ファイルが特定できないとき、rblineprofは計測を行わない。

動的に変換設定ファイルを生成してrequireする

eval でロードしたコードは計測されないのなら、 eval を使わずに require でロードすればよい。そのように考えて、以下のようなモジュールのテンプレートを用意した。

module ConfigPlaceHolder
  def self.load(config_loader)
    instance_method(:convert_rb).bind(config_loader).call
  end

  def convert_rb
    <%= contents %>
  end
end

convert_rb というメソッドは、変換設定（DFMakerでは convert.rb というファイル名で統一している）の中身をそのまま保持するメソッドである。

変換設定は、先に少し触れたように、DFMaker本体の機能を利用するためのDSLとしての性質がある。DSLとして機能させるために、然るべきクラスのコンテキストで eval していたのだが、その代わりにモジュールのインスタンスメソッドとして扱い、然るべきクラスを実行時にバインドすることで、変換設定が同等に機能するようにした。

このモジュールの <%= contents %> の部分を変換設定の中身で埋めて一時ファイルに書き出して require することで、変換設定のコードもIseqのabsolute_path が取れるようになり、rblineprofのプロファイル結果に含めることができる。

module ProfilableConfigLoader
  def load!
    # 変換設定をファイルから読み込む
    contents = load_path.read

    tmp_convert_rb_path = Pathname.new(Dir.tmpdir).join(load_path.basename)

    # ERBを使ってconvert_rbメソッドの中身をファイルから読み込んだ変換設定で埋める
    erb = ERB.new(Rails.root.join('lib', 'tasks', 'line_profiler', 'config_place_holder.erb').read)
    File.open(tmp_convert_rb_path, 'w') do |file|
      file.write(erb.result(binding))
    end
    require tmp_convert_rb_path.to_s
    ::ConfigPlaceHolder.load(self)
  end
end

# 本来の変換設定のロード処理を上書き
Converter::ConfigLoader.prepend(ProfilableConfigLoader)

本来の変換設定をロードする処理を上書きするようにしたが、既存の動作を変えないよう、 ProfilableConfigLoader はrblineprof使用時（Rakeタスクから利用する）にのみrequireするようにした。

プロファイリングの活用事例

rblineprofで変換設定もプロファイリングできるようになったことで、実行時間が長い案件（広告主-広告媒体の組み合わせ）に的を絞って速度改善を検討することができるようになった。フィード生成処理にかかる時間は、商品データのレコード数よりも、変換処理の内容に左右されることが分かっていたが、これまであまり検討されずにいた。

一つ事例を挙げると、ある案件のフィード生成に1時間以上かかっていたのでプロファイリングを行ったところ、「商品名に含まれる、ブランド名リストの中で順番が最も早い文字列をブランド名とする」という要件で、1レコードごとにブランド名リストの先頭から1要素ずつ正規表現マッチを行う、という処理に時間がかかっていることが分かった。変換設定の該当箇所とほぼ同等の擬似コードを以下に示す。

# 商品データ1レコードごとにブロックを実行し、その戻り値が'brand'という出力先カラムの値になる
column 'brand' do
  brand = ""
  brand_candidate_list.each do |candidate|
    # ブランド名リストを先頭からループして、正規表現でマッチすれば抜ける
    brand = candidate if data['product_name'] =~ /#{Regexp.escape(candidate)}/
    break if brand.present?
  end
  brand
end

商品データがおよそ10万、ブランド名リストが1万件なので、each のブロックは最大10億回近く呼び出される可能性がある。出力結果には実際にブランド名が見つからないレコードが相当数含まれるので、それに近い回数の呼び出しが行われていたと思われる。この見立てを裏付けるものとして、商品データのレコード数を1000件絞ってプロファイリングを行ったところ、 brand.present? の呼び出し回数は約900万回に上っていることが分かった。

この課題に対して、Rubyの配列をループするよりも正規表現エンジンにループさせたほうがより速い（ブランド名リストを /(brand1)|(brand2)|(brand3).../ のように長いパターンにしてしまう）、というアプローチを提案した。

# 商品データ1レコードごとにブロックを実行し、その戻り値が'brand'という出力先カラムの値になる
column 'brand' do
  # マッチング用の正規表現パターンを作る（1レコード目のみ）
  @brand_matcher ||= /(#{brand_candidate_list.map { |b| Regexp.escape(b) }.join(')|(')})/

  # 商品名のテキストに含まれるブランド名を探す。見つからなければ空文字を返す
  scanned = data['product_name'].scan(@brand_matcher)
  next "" if scanned.size.zero?

  # ブランド名がヒットしていれば、ブランド名リストの順位が早い方を返す
  found_brands = scanned.map { |match_result| match_result.compact.first }
  brand_candidate_list.find { |brand| found_brands.include?(brand) }
end

マッチする文字列が見つかったあと、順位を決めるところでRubyでのループ（ Array#find ）が残る形にはなったが、正規表現エンジンであるOnigmoは十分に高速で、結果として1時間以上かかっていたフィード変換の所要時間を3分強に短縮することができた。

おわりに

Rubyアプリケーションの実行速度をrblineprofで計測し、実際にプロダクトの改善に適用した事例を紹介した。また、計測に際して、そのままではプロファイリングできない eval 類でロードされるコードを計測できるようにする方法も示した。 DF PLUSでは、同じRubyコードでも開発者が触る領域とディレクターが触る領域とに別れているが、測定結果という裏付けがあることで、領域の境界を超えて、プロダクト改善のために実のある議論ができたように感じられた。ディレクターの皆さんには、別の業務もある中で今回の改善提案のレビューに参加していただいた。この場を借りて感謝申し上げたい。

▲