バッチ処理の仕様そのものを見直したら200倍超えの爆速化を果たした話

5月のとある昼下がり、社内で運用されている請求管理系のバッチ処理においてメモリ使用率の上昇にともない途中で異常終了してしまう問題が発生しました。

最初はコードそのものを改善できないか考えていたのですが、だんだんと仕様自体を見直したほうがいいのでは？と思うようになり、結果的に2時間超かかって異常終了していたバッチを30秒程度へ爆速化できたので、その内容を共有したいと思います。

アラートはいつも突然に

スペースマーケットではバックエンドに Ruby on Rails を採用しており、バッチ処理も Rakeタスク で実行しているものが多くあります。
今回のバッチも Rakeタスク で実行されていましたが、バッチサーバの負荷上昇にともなうアラートが発生し、普段であれば終わっているはずの時間になってもプロセスが残っている状態が続いていました。

一旦手動でkillし、再実行を試みるも同様の問題が発生して異常終了するため、一旦バッチサーバのスペックを向上してリトライを行うという対応をとりました。
（このときはわたしが育休中だったこともあり、他のエンジニアが対応してくれました。ありがとうございます！）

原因の特定

基本的にはメモリ使用率の上昇による異常終了になるのですが、これ以外にも問題が潜んでいました。

1. メモリ増加の問題

まずはメモリ増加の問題についてですが、これは大量レコードを取得する際に、関連テーブルを含めた情報で結果ファイルに書き出していたことに起因しています。
この請求管理系バッチは月次処理であるため件数が多くなることは避けられませんが、主な理由はこの3コンボによるものでした。

1. 1つのレコードにつき4〜6の関連テーブルを取得したうえで約140項目のデータを吐き出そうとしていること
2. レコード数が数万件〜十数万件となることで数百MBのファイルを出力してたこと
3. ファイル数も1つではなく複数作成していたこと

なお、レコード取得のループ処理は find_each が利用されていたため、予め全件メモリに読み込むという処理ではありません。 ^[1]

これらは潜在していた問題で、これまで徐々に増えつつギリギリで耐えていたところ、今回顕在化したことになります。
トランザクションが増え事業が成長しているということですね！

2. 処理速度・DB負荷の問題

もう一つ、データ取得に付随して発生しているN+1問題があります。
関連テーブルのレコードを取得する際に都度クエリが発行されることで、数十万単位でのクエリをDBに対して投げることになります。
また、インデックスが適切に設定されていないことでフルスキャンが発生していることも時間がかかっていた要因の1つでした。

改善策を考えてたうえでそもそもに立ち戻る

ファイルサイズ問題については、プログラム内ですべてのデータを保持してから書き出すのではなく、順次ファイルに追記することでメモリ増加を抑えられそうです。
N+1の問題については preload や eager_load で取得する、クエリの遅さにつてはインデックスを適切に設定することで解決できると考えられます。

・・・が、ここで1つの疑問が浮かび上がります。

この巨大なファイルに出力されている項目は全て使う必要があるのだろうか？

ファイルサイズが数百MBにもなるという時点で疑問を持たれる方も当然いらっしゃるでしょう。
ということで、このファイルを使っているシステム or 人がだれなのかを確認しにいきましょう！

GitHubのorganizationに対して検索をかけることで、このファイルを使っているをgrepすると以下のケースに絞られました。

• ケース1: 出力ファイルをもとに社内管理ツールから明細として表示する機能がある
• ケース2: 出力ファイルをもとにサマリを作り、経理担当者にメールで送信しているバッチがある

なんとケース2においてはサマリファイルの容量はせいぜい数百KB程度であり、このファイルさえあればよしということであればメモリ問題は一気に解消されるかもしれません。

というこで、経理に聞いてみましょう！

わたし「社内管理ツールのこの機能使われているでしょうか？メールで飛んでるファイルもあると思います。」
経理さん「使ってません！メールで飛んでくるファイルを見ています！」
わたし「ありがとうございます！この機能は社内管理ツールのメニューから消してしまいますね。（やったぜ）」

なんということでしょう。この巨大なファイルを出力する必要がないということが判明しました。

ここまでくれば、道筋は明確です。
最初からサマリファイルさえ作れば問題ないことになるため、必要な計算は MySQL の GROUP BY で集計し、その結果をファイルに書き出すだけで十分となりました。

あわせてMySQLのINDEXを設定することで、バッチ処理の実行時間は2時間超から30秒と240倍もの爆速化を果たすことができ、メモリ問題も解消されました。
もちろん、不要となった社内管理ツールで明細を見る機能も削除し、これにて一件落着となりました。

大事なこと

時間の流れの中で運用は変わっていくものであり、勝手に使っているだろうと決めつけずコミュニケーションをとるという当たり前の行動の大切さを実感しました。

この手のパフォーマンス改善はコードそのものを改善するだけで解決できることが多いかと思います。
しかし、今回のように「なぜその処理が必要なのか？」という問いに立ち返った際に、仕様そのものを見直すことで大幅な改善につながる場合もあります。

スタートアップでは過去の仕様でそのまま動いているケースも多く、紆余曲折を経て現在では役割が変わっていたり、もう使われていなかったりすることも多々あります。
これまでこう動いているからといって、それが現在でも正しいとは限りません。
一度立ち止まって「なぜ？」と問い直すことを忘れずに、コミュニケーションを大事にしていきたいと思います。

おまけ

実は今回のケースでN+1問題を実直に解消するには少々厄介な問題がありました。
単純に preload や eager_load を使えればよいのですが、既存コードにおけるデフォルトスコープと関連付けの方法が干渉しており、そのままでは解消できないという具合です。

例えば comments belongs to user となるような以下のようなモデルが存在するとします。

class  Comment < ApplicationRecord
  acts_as_paranoid

  belongs_to :user

  # 削除されていても取得する
  def user
    User.unscoped { super }
  end
end

acts_as_paranoid は論理削除を扱うための gem で、スペースマーケットでは多くのモデルで利用しています。
この gem を利用すると、クエリを発行した際に deleted_at IS NULL の条件を追加してくれるようになります。

さらに、コメントが残っているならユーザーは消えていても取得する、という制約（実際には請求レコードがあればユーザーが削除されていても対象とする）があるため、def user のメソッドで削除フラグを無視して取得するように組まれています。

この場合は残念ながら preload あるいは eager_load をしても、user を引いた時点で unscoped が効くためN+1問題は依然として残ります。

Comment.preload(:user).each do |comment|
  # ここでの user は unscoped が効くためN+1問題が残る
  comment.user
end

この問題を解決するためには、別名で関連付けを行う必要があります。

  class  Comment < ApplicationRecord
    acts_as_paranoid

    belongs_to :user
    # 新しく追加. with_deleted は acts_as_paranoid で提供されており、削除されたレコードも取得することができる
+   belongs_to :user_with_deleted, -> { with_deleted }, class_name: 'User', foreign_key: 'user_id'

    def user
      User.unscoped { super }
    end
  end

取得処理は以下のようになります。

Comment.preload(:user_with_deleted).each do |comment|
  # N+1は解消される
  comment.user_with_deleted
end

脚注

1. find_each はデフォルトで1000件ずつ取得処理を行うため、メモリ使用量を抑えることができます。