はじめに
こんにちは！検索チームのエンジニアをしている寺田と申します。ここ最近は新機能開発だけでなく、品質改善・内部改善に目を向ける機会が増えました。 今回はその中でもパフォーマンスチューニングに目を向け、情報の可視化から課題抽出、実際に改善していった話をしたいと思います。
実際に取り組んだ結果、検索用データ生成のパフォーマンスを大きく改善すること( 処理時間 50% 以上カット )に繋がりましたので、パフォーマンス改善に興味のある方の参考になれば幸いです。
パフォーマンス改善に至ったモチベーション
パフォーマンスの重要性
パフォーマンスと一言で言っても文脈によって様々な指標があります。例えば Web ブラウザ上でのパフォーマンスであれば「Webサイトのロード時間」を指しますし、 データ生成の文脈であれば「プログラムを実行してから終了する時間」のようなケースも存在します。
Web ブラウザのパフォーマンスが良くなると、ユーザがストレスなく閲覧できるなどUXの向上に貢献ができ、ユーザ離脱率を低下させることができます。 また、SEO への好影響にも繋がり、ユーザの閲覧率向上にも繋がると考えています( ※ もちろんサイトコンテンツが高品質であることが大前提です )。
データ生成の文脈でいえば、パフォーマンス改善を行うことでリソース削減に繋がり月々のコスト(費用)が下がるなどのメリットも挙げられます。
感じていた課題感
検索チームでは元々、GCP の Cloud Monitoring や Sentry の Error Monitoring を使って SLO や検出されたエラーの可視化を行っており、週1回の定例でそれらの情報を確認し、必要に応じて調査・対応を行っていました。
もちろんこれらの指標はサービス品質を保つためには大事な要素ではありますが、パフォーマンスに関する指標が少なく( 一部のレイテンシーの可視化のみ存在 )期待通りの速度で実行されているのか？等を知る術がありませんでした。これでは、すでに存在している潜在的な問題を検知することができませんし、パフォーマンス改善した際の効果測定も難しい状態となっていました。
チームに課題感を共有
検索チームでは半期に一回、チームオフサイトを実施しています。そちらで検索のプロファイリングを提案しました。 チーム内で話し合ってみたところ、既に導入している Sentry で実現可能そうであることがわかったので、Sentry のプロファイリングを導入してみました。
検索チームのオフサイトについては過去のブログがありますのでよかったら一読ください！
Sentry について
概要
ご存知の方も多いとは思いますが一言で言うと、エラー監視やパフォーマンス監視ができる開発者向けツールです。 さまざまなモニタリング機能を有しており、弊社でもエラーや不具合等の早期発見にも貢献しています。
今回はその中でも、パフォーマンス改善で強力なサポートとなるトレーシングとプロファイリング機能について紹介します。
トレーシング
システムのエントリーからエンドポイントまでのパスを追跡して、課題のある関数やAPIを特定することができます。Sentry が対応している フレームワークやライブラリの利用箇所でどの程度の処理時間がかかっているのかを可視化してくれるのでボトルネックの特定がしやすくなります。
また、弊社では Python によるORM を利用していますが、そこで発行される SQL クエリ もログとして取得することが可能です( ユーザID等がロギングされないようにマスク設定できるのもポイントです )。詳細はこちら。
プロファイリング
関数ごとの実行時間の可視化が可能です。サンプリング方式でフレームグラフを作成しているため厳密な実行時間ではありませんが、処理全体に対して各関数がどの程度処理時間がかかっているかが一目でわかるようになります。
プロファイリングによって「どこで」問題が発生しているかが可視化され、パフォーマンス悪化の原因になっている箇所の特定がかなり行いやすくなりました。原因の場所が特定できればあとは、原因調査・対応方針を考えることで改善していきます。一番辛かった「パフォーマンス悪化原因の場所の特定」が情報の可視化により一気に行いやすくなったことで、高速に改善サイクルが回せるようになりました。詳細はこちら。
余談
Sentry は Slack 連携することで、 エラーや不具合を検知した際に自動で通知できるようになります。 実際に本番環境で発生したエラーログはもちろん、トレーシングのログから 時間のかかっているSQLクエリ や N+1 問題を引き起こしているクエリ等、さまざまな Issue をある程度自動で検出して通知してくれる仕組みが存在するのでおすすめです。
こちらの設定をした際には、潜在的に隠れていた Issue が大量に発行され、一つ一つ改善していったのは良い思い出です。。笑
実際に改善活動してみた
上記の機能を活用して、「Sentry が自動で検出した Issue」や「プロファイリング分析による課題」の改善を行いました。 コードの設計上、潜在化してしまっていた N+1問題の解消 や データのコンバート処理の最適化などさまざまな改善ネタを見つけることができました。いくつかを紹介します。
データ増大によってパフォーマンスが悪化したSQLクエリ
トレース結果にはテーブル名や SQL クエリが出力されています( 添付図は黒色でマスクしてますが... )。どの SQL クエリで時間がかかってしまっているか？が一目瞭然です。 今回のケースでは、オレンジ色で囲ってる箇所がボトルネックであることがわかります。
実際に Sentry で出力された SQL クエリを使って実行計画を確認してみると、データ取得と結合の計算量がデータ量にかなり依存する処理を行っていることがわかりました。 このように、サービスが拡大するにつれて扱うデータ量も増えた結果、パフォーマンスが大きく悪化してしまうような SQL クエリは多く存在すると思います。
実行計画を参考にしつつ、データ量になるべく依存しないようなデータ取得と結合を行う SQL クエリに書き換えることで、こちらの課題を解消しました。
プロダクト内部で利用していたデータ変換処理
次はプロファイリングの結果から課題を見つけたケースです。フレームグラフを用いてボトルネックとなっている関数を探して行ったところ、内部でデータ変換を行っている箇所で処理時間が大きくなっていることがわかりました。 上図でオレンジ色で囲っている箇所です。フレームグラフは横軸が処理時間を表しているので、このプロセスの30%強( 5秒程度 )を占めていることがわかります。
辞書(dict)から対象モデルクラスへコンバートする処理になります。該当データは入れ子構造で、レコードによってはかなりの要素を持つデータ構造になっていました。 利用していたモジュールは入れ子かつ大容量のデータ構造の処理には向いておらず調べたところ別のモジュールで代替可能だったため、いくつかのモジュールでベンチマークテストを行い候補を選び、運用負荷等を考えてモジュールの差し替え対応を行いました。
成果まとめ
大きめの課題の多くは検索用データ更新時のクエリやロジックだったので、そこを中心に改善活動を行いました。結果、データ更新に合わせて6時間40分かかっていた処理が3時間10分程度に収まるようになり、50%以上の処理時間カットを実現することができました。
今後は実際にサービスで利用されている 検索API 等にも改善の手を広げていきたいと考えています。
終わりに
いかがだったでしょうか？開発環境の課題からツールの導入、実際に改善活動を行ったストーリーをお話しさせていただきました！ パフォーマンスを可視化することで、普段何気なく触っているコードにも課題が見つかるかもしれませんね。それでは良いパフォーマンス改善ライフを！
ビザスクではエンジニアの仲間を募集しています！ 少しでもビザスク開発組織にご興味を持たれた方は、ぜひ一度カジュアルにお話ししましょう！
