はじめに
この記事は 食べログアドベントカレンダー2024 の16日目の記事です🎄
こんにちは。食べログ開発本部ウェブ開発1部 システム運用改善チーム所属の @4palaceです。
今回は、私の所属するシステム運用改善チームで、とある社内業務の処理パフォーマンスを改善した事例を紹介します。
この事例では、10日間かかっていた処理を、少しの改修で10分未満に短縮しました。
改修量としては小さくとも、大きなパフォーマンス改善を実現でき、運用業務の効率化につながりました。
個人的に興味深い例でしたので、ここで共有させていただきます。
問題の発見
月次処理が月内に終わらない！
きっかけはカスタマーサポートチームからの相談でした。
「月次の新店舗の登録チェック業務で行われているマッチング処理が遅すぎて、後続の業務も含めて月内に終わらなくなってきている。どうにかできませんか？」
そもそもこの業務とは何か？を以下で説明します。
新店舗の登録チェック業務とは？
カスタマーサポートチームでは、レストラン情報の正確性のチェックから、口コミや投稿内容の確認など、さまざまな業務を行なっています。
今回の「新店舗の登録チェック業務」とは、新規開店したレストラン情報のデータを入手・チェックする業務のことです。
すでに食べログに登録されているか、登録されている場合はどのデータと紐づいているか、などを月次で一斉に確認しています。
食べログの充実した店舗情報の背景には、このような地道な努力が隠れています。
これが「新店舗の登録チェック業務」ということです。さて、この業務はざっくり以下のように分解できます。
- (1) 新店舗候補の一覧を入手/出力する
- 新規開店レストラン情報をデータで入手する
- データの電話番号や店名、住所などから食べログのデータベースとマッチング処理を実施し、食べログのデータと紐付けを確認する
- (2) 出力された候補一覧から、食べログの店舗情報の登録/修正する
- 食べログに登録されている店舗/紐付けされていない店舗のリストを元に、食べログへの店舗情報登録やデータの修正する
という流れで、プログラムの処理(1) の後に、人間による後続処理(2) が行われる、というフローになっています。
食べログ側で店舗データを登録する前には、人間による確認作業が含まれます。
リストの住所や店名が本当に正しいか、電話番号に本当につながるかなど、データの正確性の確認が必要なためです。
ここで問題となっていたのは(1)の処理で、数ヶ月前の実行までは4~5日程度で終わっていたようです。 しかし、先月の実行時には急激に遅くなり、10日間かかっていました。 10日間もかかってしまうと、(2)の処理を始める前に月をまたいでしまいます。
(2)の確認作業は時間・工数ともにかかる業務のため、可能であれば早めに取り掛かりたいのですが、
(1)の開始を早めすぎるとデータ取得が早くなりすぎて、今度は確認完了時にはすでにデータが古くなってしまいます。
このため、(1)はある程度待ってから開始したいが、(2)まで含めて月次処理で終わらせたい、という狙いがあります。
そこで、(1)の処理を調査し、結果を変えずに早く処理完了できないか検討を始めました。
具体的な高速化の流れ
開発環境でのプロファイラログ計測
高速化の1歩目はまず計測です。
開発環境で同様に遅くなるかどうかを調査しました。 とはいっても、単純に実行前後でストップウォッチを持って計測するわけではなく、ラインプロファイラを用いて計測しました。
ラインプロファイラとは、プログラムの行ごとに処理時間を計測してくれるツールのことです。 これまで食べログでは、Webアプリの画面やAPI実行時に、行ごとの計測時間を閲覧できるように rblineprof を適用して計測できるような仕組みが用意されていました。
今回計測したい部分は、resque による非同期処理を行っていた部分であり、rblineprof を適用する仕組みが用意されていませんでした。
そこで、まずrblineprofをresque処理にも適用できるような簡単なラッパークラスを作り、開発環境で計測できるように改修しました。 そのラッパークラスを介して非同期処理を呼ぶことで、プログラムの行ごとの処理時間を計測できます。
開発環境で実行させたときのプロファイラログの一部を示します。(コードは抜粋・一部変更しています)
| #登録済みかどうか調べる 67.4ms + 0.4ms (15540cl/ 22490) | restaurant_masters = get_restaurant_master(line["site_restaurant_cd"]) | case restaurant_masters.size | when 0 #なかったらマッチングしてログ出力 3537886.6ms + 239351.1ms (11245cl/1017358023) | match_new_rst_with_restaurant(line, @restaurants_from_csv[site_rst_id]) | when 1 | #何もしない | else | @logger.error("Error:#{line["line_no"]}行目:同じ#{site_rst_id}のレストランが複数登録されています。データ不整合の可能性が高いです。") | end | end 0.1ms + 0.0ms ( 1cl/ 12) | @logger.info("マッチングを終了します。") | end
上記の match_new_rst_with_restaurant の行の処理時間が大きくなっています。
さらに内部を見てみると、電話番号が同じレストラン情報をDBから抽出する処理である find_restaurants_by_tel の処理時間が大きな割合を占めていると判明しました。
ただ、ここ1ヶ月で急激に遅くなった理由がわかりません。その謎を解くため、もう少し条件を明確にしたいと考えました。
find_restaurants_by_tel メソッドは、電話番号の文字列を入力とし、DBから検索する処理のため、入力は電話番号を表す文字列しか受け取りません。
そこで、遅くなる電話番号に規則性があるか、という観点で調査しました。
遅くなる条件を突き止める
ここで、処理進行中の実行ログから、前半は高速な一方で、後半にかけて急激に処理が遅くなるとわかっていました。
マッチング元のデータの電話番号に着目すると、後半にかけて電話番号なしのデータの比率が増えていました。
- 冒頭の2万件 : 電話番号が不明な店舗16件(2万件に対し 0.08%)
- 最後の2万件 : 電話番号が不明な店舗4247件(2万件に対し 21.2%)
最後の2万件はオープンしてまもない店舗がほとんどです。オープン直後は電話番号不明の店舗が増えることは多いため、データ自体に問題があるわけではありません。
問題はこの時の内部処理にありました。電話番号不明のケースの場合、すべての電話番号不明の店舗を返却しActiveModelのインスタンスにしていました。その数は約10.7万件。
約10.7万件の店舗データをすべてDBから取得して、ActiveModelのインスタンスに格納するという処理を電話番号不明のデータ全てに対して繰り返し行っていたことがわかりました。これが遅い原因ではないか、と考えました。
ちなみに、食べログのデータはどんどん成長するので、電話番号不明の店舗数もこれまでと比べて増加しています。
(つまり、去年より先月、先月より今月の方が重いクエリになることが想定されます)
そこで、その仮説を裏付けるため、本番環境で1件あたりどの程度の時間がかかるかを計測しました。 1件のデータを電話番号で比較する場合に、電話番号のデータの違いで以下のような違いが見られました。
- 電話番号があるデータの場合 : 0.002秒
- 電話番号が不明のデータの場合 : 41.528秒
その速度差なんと20764倍！これが一番の原因であることが確定しました。
原因を踏まえてどう直すか
前章で述べた通り、電話番号が不明のデータの全量が多く、その全てをActiveModelクラスのインスタンスにしたことが原因でした。
処理内容を見ると、実は find_restaurants_by_tel で2件以上の店舗数がヒットした場合はIDしか見ておらず、ほとんどの要素はそのまま読み捨てられていることがわかりました。
食べログにおいて電話番号不明の店舗が1件になることはなく、そのため電話番号不明の店舗のIDだけを格納した集合があれば事足りることがわかりました。
以上を踏まえて、不要なデータをとらない・保持しないことで処理を見直した結果、 電話番号不明データのマッチング処理を電話番号ありのデータの比較速度と同等にできました。 また、副次効果として、余分なオブジェクトを生成しなくなったため、プログラム実行中のメモリ消費量も抑えることができました。
修正内容としては小さくでき、コード修正行はコメントを除くと20行程度でした。
リリースする前に確認すること
パフォーマンスチューニングは重要ですが、結果が変わってしまっては意味がありません。 そのため、改修前後で同じデータを使用して処理を行い、全く同じ結果が出力されることを確認しました。
また、この機能はカスタマーサポートチームが使用するもので、実行後には後続処理が行われます。 そのため、リリース日時やリリース後の初回実行に関しては、カスタマーサポートのメンバーと確認・連携を取りながら進めました。 もし不具合が発生した場合、迅速にロールバックして業務に支障が出ないようにする必要があります。
高速化の結果
リリース後、最初の本番実行はカスタマーサポートチームのメンバーと連携しながら行いました。ドキドキです。
高速化リリース後、実行時間は以下の結果のように変化しました。
- 全体の処理時間
- 改善前 : 9日23時間7分59秒
- 改善後 : 8分16秒
- マッチング部分の処理時間
- 改善前 : 9日23時間3分59秒
- 改善後 : 4分24秒
なんと、約10日かかっていた処理が8分16秒で終わってしまいました。流石に自分でも驚きました🎉
処理時間の中心となっていたマッチング部分の処理時間だけを見ると、実に3260倍速くなったことになります。
高速化による副次的な効果
今回の対応によって、10日かかっていた処理が10分未満で完了するようになりました。 これにより、カスタマーサポートチームでは、後続の業務をすぐ実施できるようになり、期日に余裕を持って対応できるようになりました。
また、エンジニア観点でも収穫がありました。 これまで、Resqueによる非同期処理の計測ツールがあまりなく、パフォーマンス改善が少し厄介でした。 しかし、今回Resque処理のパフォーマンス計測の仕組みをあらたに手に入れたため、これまで手を焼いていたResque処理のチューニングにも役立てることができるようになりました。
開発を高速化するには、問題・真因のいち早い特定が不可欠です。その観点でも、今回有用なツールを手に入れられたことは大きな成果でした。
学んだ教訓と今後の展望
今回の実例から、わずかな改善が大きな効果をもたらす可能性を具体的に肌で感じることができました。 単純に「プログラムが高速化した」だけではなく、プログラムの高速化によって業務の無駄や待ちがなくなり、 それによって業務の効率化・生産性の向上がみられました。
今後の展望としては、パフォーマンス改善の他の画面への展開を考えています。 プログラムが遅いことはそれだけでユーザー離脱の原因となり得ますし、それを使っている人たちの業務効率にも影響を与えます。 今回の調査で見つけた観点や、調査の流れは他の画面や処理にも流用できるので、低速な画面/機能に対しても計測・改善を続けていきます。
おわりに
本記事では、食べログの社内向け機能のパフォーマンス改善事例を紹介しました。 今回は社内向け機能でしたが、現在はユーザー向けの画面/APIに対しても積極的にチューニングを進めています。
なお、ユーザー向けの画面/APIに関しては過去にTabelog Tech Blogで取り上げた分散トレーシングの技術で解析することも可能です。 分散トレーシングによる解析では本番環境でのログを元にした解析が可能なため、新たな視点での解析が可能となります。
分散トレーシングについて興味のある方は、過去に投稿した以下の記事をご覧ください。
分散トレーシングを使ってパフォーマンス改善をやってみたら、レスポンスタイムを2割近く改善できたお話
パフォーマンス改善は終わりのないテーマであり、何から取り掛かれば良いのか迷ってしまうことも多いかと思います。 少し手をつけても効果があるのか不安になることもありますが、心配はいりません。 事実を整理し、事実と丁寧に向き合いましょう。
また、パフォーマンス改善は、単に「速度が速くなる」「動作が軽くなる」だけではありません。 業務の無駄を省くことができたり、ユーザーの使い勝手を大いに向上させる可能性を持っています。
今回の改修のようにわずか20行程度の修正で爆速になることもありますので、チャンスがあれば気軽にチャレンジしてみてはいかがでしょうか？
明日は @itaya さんの「音声入力×AIチャットボットで広がる新たなAI活用の可能性」です。お楽しみに!
