急なレスポンスタイム悪化から、オープンソースプロジェクトにPull Requestを送るまで

こんにちは、Misoca開発チームの黒曜(@kokuyouwind)です。

最近はシャニマスのイベントシナリオ感想記事をnoteにまとめたりしています。

😨 急に本番のレスポンスタイムが悪化した話

Webエンジニアにとって、「本番障害」という4文字ほど見たくないものはないでしょう。

本番障害ほどではないにしても、「急なレスポンスタイム悪化」もあまり見たくない文字列ですね。まぁ、見たくなくても向こうからやってくるんですが…

というわけで、今回は本番レスポンスが急に悪化したときの話です。いろいろ調べた結果、利用しているオープンソースプロジェクトが原因だったことがわかりPull Requestを送ったので、その流れをまとめてみたいと思います。

❗️ レスポンスタイム悪化の検知

Misocaでは監視ツールとしてMackerelを、APMツールとしてSkylightを利用しています。

本番レスポンスタイムはMackerelでアラートを設定しており、平常値から大きく悪化した場合はSlackに通知されるようになっています。

その日はリリース作業を行った直後、レスポンスタイム悪化のアラートが飛んできました。気になってSkylightを確認したところ、驚きの事態が。*1

リリース以降、95パーセンタイルがめちゃくちゃ悪化しとるやん！*2*3

🩹 応急処置

幸いアプリケーションが使えなくなるほどの悪化ではなかったため、落ち着いて応急処置に臨みます。

Skylightで表示する期間をリリース前とリリース後で切り替えて比べた結果、どうやらPDF生成処理にかかる時間が伸びているらしいとわかりました。

リリース内容を精査したところ、ちょうどそのタイミングでPDF生成処理に関係しそうなTTFunk gemの更新が入っていることが判明。*4

おそらくこれだろうとアタリをつけ、該当コミットを巻き戻してリリース。結果、見事にレスポンスタイムが回復しました。

🕵️‍♀️ 原因調査

ひとまず本番の問題は落ち着いたため、なにが原因だったのかを調査していきます。

まずはローカル環境での再現確認。以下のようなコードでベンチマークを取り、gem更新前と更新後とでPDF生成にかかる時間が増えるかを確認します。

10回繰り返しているのはActiveRecordアクセスなどPDF生成以外の要因を相対的に小さくするためです。

require 'benchmark'

Benchmark.bmbm do |x|
  x.report('generate') {
    10.times { Misoca::PDF.generate(Invoice.first) }
  }
end

結果、ttfunk 1.5.1のときと比べて、ttfunk 1.6.2.1では概ね4倍ほど遅くなることが確認できました。

本番でしか起きない問題だと調査が難しいのですが、ローカルでも再現することがわかったため調査がしやすくなりましたね。

続けてStackprofを使ってプロファイルを取り、どのような処理に時間がかかっているかを調べていきます。

require 'stackprof'

StackProf.run(mode: :cpu, out: 'tmp/stackprof-cpu-myapp.dump', raw: true) do
  10.times { Misoca::PDF.generate(Invoice.first) }
end

stackprof tmp/stackprof-cpu-myapp.dump で確認した結果、以下のようにActiveSupport::CompareWithRange#cover?が50%以上の時間を使っていることがわかりました。

==================================
  Mode: cpu(1000)
  Samples: 13617 (0.71% miss rate)
  GC: 1461 (10.73%)
==================================
     TOTAL    (pct)     SAMPLES    (pct)     FRAME
      7765  (57.0%)        7765  (57.0%)     ActiveSupport::CompareWithRange#cover?
      1138   (8.4%)        1138   (8.4%)     (marking)
      8609  (63.2%)         844   (6.2%)     TTFunk::Table::OS2.group_original_code_points_by_bit
       322   (2.4%)         322   (2.4%)     String#unpack
       322   (2.4%)         322   (2.4%)     (sweeping)
...

TTFunk::Table::OS2.group_original_code_points_by_bitã‚‚TOTALでは多くの時間を使っており、SAMPLESは少なくなっています。 このことから、TTFunk::Table::OS2.group_original_code_points_by_bitからActiveSupport::CompareWithRange#cover?を呼び出している箇所が重いのだろうと推測することができました。

実際にTTFunk::Table::OS2.group_original_code_points_by_bitのコードを確認すると、以下のようにr.cover?を繰り返し呼び出しています。

os2.file.cmap.unicode.first.code_map.each_key do |code_point|
  # find corresponding bit
  range = UNICODE_RANGES.find { |r| r.cover?(code_point) }

この処理は1.6.0で追加されたものでした。ここにパフォーマンス上の問題があるようですね。

📝 Issueを立てる

問題が把握できたため既存のIssueやPull Requestを確認しましたが、どうやらまだ報告されていないようでした。

新しいIssueを立てたいところですが、このためには最小限の再現コードを作り、ttfunk自体の問題である確証を得ておきたいところです。

PDF生成の内部処理からどのようにttfunkが呼び出されているかわからなかったため、stackprof --graphviz tmp/stackprof-cpu-myapp.dump > tmp/stackprof.dotでdotファイルを作成し、dot -T pdf -o tmp/stackprof.pdf tmp/stackprof.dotでPDF化して呼び出しグラフを見てみました。*5

どうやら、TTFunk::Subset::Base#encodeが外部とのインターフェイスのようです。

specファイルを参考にしつつ、この処理を呼び出す再現コードを書いてみます。

require 'ttfunk'
require 'benchmark'

# English Font
file = TTFunk::File.open("DejaVuSans.ttf")
# Japanese Font
# file = TTFunk::File.open("GenShinGothic-Normal.ttf")

subset = TTFunk::Subset.for(file, :unicode)
Benchmark.bmbm { |x| x.report('encode') { 10.times { subset.encode } } }

日本語などのマルチバイト文字でしか再現しない問題かもしれないので、フォントを英字フォントと日本語フォントの2種類で確認できるようにしています。

このコードを用いて1.5.1と1.6.2.1でベンチマークを取ったところ、英字フォント・日本語フォントを問わず実に30倍程度遅くなっていることがわかりました。やはり日本語フォントのほうが長時間かかるため、英字フォントを扱う海外ではパフォーマンスの問題に気づかなかったのかもしれません。

無事ttfunkのみで再現コードを作り計測もできたため、Issueとして報告することができました。

🛠 修正Pull requestを送る

あまりに難しそうな問題であれば手出しできませんが、今回は比較的読めそうなコードだったため、自分で直せないか検討してみることにします。

問題の箇所ではos2.file.cmap.unicode.first.code_mapの各キーについてeachを呼び出し、UNICODE_RANGESの中からr.cover?(code_point)を満たすものを探し出しています。

それぞれの要素数をN,M とすると、この処理は Ο(N * M)の計算量になります。Mは200弱の固定値ですが、それでも効率の悪い計算に見えますね。

素直に思いつくのはUNICODE_RANGESを探索木にすることです。ただしUNICODE_RANGESはRangeの配列のため通常の探索木ではなく区間木を使うことになります。Ruby標準でサポートされないデータ構造のため依存gemを増やすか自力で実装するかになりますが、いずれも少々大きな変更になります。オープンソースプロジェクトへのPull Requestとしては、できれば避けたいところです。

ここで発想を変えて、「UNICODE_RANGESごとに、その範囲に含まれるcode_mapキーをまとめて見つけ出す」としたらどうでしょうか。code_mapが整列していた場合、同じUNICODE_RANGESに含まれるキーは必ず固まって並ぶため、効率良く処理できそうです。またUNICODE_RANGESは互いに重複しない範囲であるため、他のUNICODE_RANGESに含まれていたものを以降の判定から除外することができます。

この方針で実装してみたところうまく動いたため、Pull Requestを出すことにしました。計算量はΟ(max(N, M))まで改善しており、ベンチマークも8倍ほど早くなっています。

💬 感想

今回は本番でパフォーマンス悪化に気づいてから原因を調査し、オープンソースプロジェクトにIssueを立ててPull Requestを送るまでの流れをまとめてみました。

定番ですがStackprofを用いたプロファイル分析は大切ですね。またみんなのコンピュータサイエンス読書会で読んだばかりの計算量やアルゴリズムの話がさっそく活かせたのも良かったです。

tech.misoca.jp

今後も利用しているオープンソースプロジェクトの問題を見つけたときは、Issueで報告して直せるものはPull Requestを出していきたいと思います。

📢 宣伝

Misocaではパフォーマンスの問題を改善したいエンジニアを募集しています。

*1:話を簡単にするために省略しましたが、実は月初の負荷にまぎれてしまい、当日はアクセス量の問題だと思っていました。翌日も数値が回復しなかったため怪しんで調査し、コード起因の問題であったことがわかりました。

*2:95パーセンタイルは、レスポンスタイムすべてを短い順に並べて95%目の値を取り出したものです。SkylightのTypical responseは中央値(50パーセンタイル)を、Problem Responseは95パーセンタイルを表示しています。

*3:グラフの縦軸は具体的なパフォーマンスの情報になってしまうため、意図的に伏せています。

*4:話を簡単にするために省略しましたが、実際には別のgemの更新に伴い、依存していたttfunkも更新されていました。原因調査の際はここの切り分けでかなり苦労しました。

*5:flamegraphでも同じようなコールスタックが見えますが、スクリーンショットで貼ったときに細かすぎて見づらいため、今回はgraphvizを使っています。