初めての負荷試験とパフォーマンスチューニングで得た苦戦・快感・理解

はじめまして。CYBIRD Advent Calendar 2021 20日目担当の@cy-seiyanと申します。
19日目は@koronekoによる「GooglePlayストアのOS対応とAPIレベル対応って何が違うの？説明してみた。」でした。

はじめに

突然ですが恥を偲ぶのと懺悔をさせて下さい。
実は私、曲がりなりにもサーバサイドエンジニアとして活動して来たのですが、CYBIRDに入社するまでデータベースやソースコードのパフォーマンスチューニングや負荷試験と言った事を経験した事が御座いませんでした。
2019年8月20日にCYBIRDからリリースされたイケメン源氏伝 あやかし恋えにしの開発を担当していた時に生まれて初めて挑戦した負荷試験で躓いた点やリリース後に直面した内容を通して苦労した点や学んだ事等についてお話したいと思います。

負荷試験に挑戦

リリースまであと2ヶ月程に迫っている中、私はタイトルをサービスインするに際して本番環境のサーバスペックを決めるのとボトルネックになっている箇所を洗い出す為、負荷試験を担当致しました。

使用した主なツールや環境等

• Apache JMeter(version 3.2)
• Mackerel
• NewRelic
• 負荷試験用のサーバ環境(AWS)

負荷試験用シナリオの作成

実際にゲームをプレイするユーザの動きを想定し、負荷試験に使用するシナリオデータ(jmxファイル)を作成する必要があります。
今回の負荷試験では下記のシナリオを想定し、シナリオデータを作成しました。

• チュートリアル開始から終了後にゲーム内の各ページに遷移しページ毎の機能を実行。
• ゲーム内ミニゲームの周回的実行。
• パネルチャレンジ攻略。(パネルチャレンジの攻略状況を通知する為のAPIを用意しており、あらゆるシーンでAPIを実行するのでボトルネックになる可能性を感じた。)

テストする際に設定する3つの項目

JMeterには「thread_num(スレッド数)」・「ramp_up(テスト時間)」・「loop(ループ回数)」と言う計3つの項目が存在します。

• 「thread_num(スレッド数)」はどれくらいのセッションを起動するか。
• 「ramp_up(テスト時間)」は指定した期間もとい時間にスレッドをスレッド数で設定した数だけ生成。
• 「loop(ループ回数)」は処理を繰り返す回数。

※例を挙げるならスレッド数を30、ramp_upを10、loopを10にした場合、10秒間に30人がログインする処理を計10回行うイメージ。

Request Per Minute

サーバが1分間にどれだけのリクエストを処理出来たかどうかを表すrpmと言うモノがあるのですが、算出する為の式はこちら。

総UUID件数(ユーザ数) * 1ユーザの総リクエスト数 / JMeterの実行時間(分) = rpm

負荷試験を行って躓いた点等

最初、ローカル環境に対して自分が作成したシナリオ通りに負荷試験が実行できるか試したところ各API実行時にエラーが表示され、作成したシナリオ通りに動かない事象が多発しました。

• マスタ系APIを実行時、「404 Not Found」のエラーが吐かれた。
  • ローカル環境の/etc/nginx/html/50x.htmlが存在せず、作成し実行してみると「502 Bad Gateway」が返ってきた。
  • レスポンスデータのサイズが大きく尚且つphp-fpmのタイムアウト設定が短すぎた為、php-fpmのタイムアウト設定を変更したところ正常にレスポンスが返る事を確認できた。
• プレゼントBOXからアイテム受取りのシナリオでアイテム受取り用APIを実行しているにも拘らずプレゼントが1件も受け取れていなかった。
  • リクエストパラメータにプレゼントアイテムのIDを設定しているのだが、IDがシナリオ作成時に設定されていたIDのままになっていた。
    JMeterの「スレッドグループ」という項目からアイテム受取り用API実行前にプレゼントアイテム一覧を取得するAPIを実行しているシナリオに対して「正規表現抽出」と言う設定をする事でプレゼントアイテムのIDを取得する様にした。
• プレゼントBOX同様、その他のAPIを実行する際に必要なパラメータがリクエストパラメータに含まれていなかった・取得出来ていなかったという事実が発覚し「正規表現抽出」を設定して必要なパラメータを取得する様にした。

サービスインして1年後の状態を想定した状態での負荷試験を執り行うべく、負荷試験環境にて約50万件分のユーザデータを作成する為にJMeterを実行していたのですが実行ジョブが一向に終わらないと言う事象が発生しました。

• NewRelicで確認したところ、ユーザ情報取得系のAPI内で実行されるクエリが重いと言う結果が出ました。

• 対象のクエリに対してexplainを使ってINDEXを使用してるかチェックを行ったところ、INDEXが設定されていなかった事が判明しました。
• Alter tableでINDEXを設定し、再度確認したところ対象クエリの処理時間が大きく改善されました。

• データが少ない状態での負荷試験では判明しなかったが、データが増えた事で顕在化した。

サービスイン直後に起きた悲劇

数々のトラブルに見舞われ、予定していたスケジュールをオーバーするなどありましたがリリースの約10日前までに負荷試験を完了させ、2019年8月20日にサービスインする事が出来ました。
しかし、リリースしてから始まった期間限定のイベント施策を実施したところイベント開始直後とイベント内機能の1つである「フィーバータイム」発生時、イベント終了間際にデータベースサーバのCPU使用率が跳ね上がる事象が発生しました。
第1回目のイベント開始前にメンテナンスを挟んでデータベースサーバのスペックを上げたにも拘らず、CPU使用率が高い数値を叩き出していました。

開催される各イベント施策でのCPU使用率

イケメン源氏伝にて開催されるキャラクターのメインストーリーを読み進めて特典等を獲得する事が出来るイベント(通称：本編応援キャンペーン)では瞬間的に100％になる事象が発生し、2019年10月上旬から始まった期間限定キャラクターストーリーを読み進めて特典を獲得する事が出来るイベント（通称：ストーリーイベント）では開始直後にCPU使用率が97％を叩き出すと言う事象を目の当たりにし、気を失いそうになりました。
イベント中、平常時がおおよそ20～30％を推移していました。

本編応援キャンペーン終了間際のCPU使用率

ストーリーイベント開始直後のCPU使用率

泥沼化する負荷試験＆パフォーマンスチューニング

ストーリーイベントと本編応援キャンペーンの負荷試験を行いボトルネックになっている箇所を必死に洗い出そうとするが、イベント系のAPIでデータベースに対してボトルネックになっているクエリはこれと言って存在せず、APIでループ処理の中でマスタデータのSelectしている箇所を改修する等を行っても大改善に繋がらず頭を抱え、某ゲームキャラクターの様に「悪い、やっぱ辛えわ」と言ってしまう程ブルーな気持ちになりました。
これ以上やっても埒が明かず途方に暮れていた時に、インフラチームに所属している先輩エンジニアの方達から「本番環境にNewRelicを仕込んで各APIの負荷状況等を可視化してみましょうか。」と言うお言葉を頂き、可視化して再度調査する方向にしました。

可視化した事によって明かされる驚愕の事実

NewRelicで負荷状況を見れるようになったとの通達が来て、早速本番環境の各APIの負荷状況を確認しました。
イベントとは全く関係無いユーザ情報を取得するAPI(ユーザのログインボーナス情報を取得するAPI)が一番負荷が高いと結果が出ました。

該当のAPIで実行しているクエリとテーブルを確認するとカエルの如く口から胃袋が出そうな原因が発覚しました。そう…それは至極単純な事でした…。
INDEXが設定されていない！！

※後から分かったことですが、ストーリーイベントと本編応援キャンペーンの負荷試験を実施する際にシナリオデータの作成段階でサービスイン後にある程度ユーザデータが溜まっている状態尚且つイベント開始によるユーザの駆け込みを想定から漏れていたのが原因で、負荷試験を何度も行えど上記の原因を発見する事が出来ませんでした。

原因対応後の結果

INDEXが設定されていないと言う事実を知り、急いでテーブルにINDEXを設定する為のALTER文を作成し、本番環境に反映しました。
反映後、NewRelicで確認してみると負荷が高いAPI上位に来ていた該当のAPIが項目から消え去り、MackerelでデータベースサーバのCPU使用率を見てみると半分以下にまで下がり改善しました。

負荷試験・パフォーマンスチューニングの所感等

• 負荷試験は他のタスクをこなしながらやってはいけない、むしろ出来ない。
• 負荷試験が全くの初めてで尚且つ1人でやる場合、2～3ヶ月ぐらい時間とってじっくりやった方が良い。
  • 私は今回、負荷試験のシナリオデータ作成やJMeterを実行して発生したエラーで躓き、その対処等で結構大きな遅れを取った。
  • ボトルネックになっているクエリが出てきたらexplainを使ってINDEXが効いているか確認する事。
  • INDEX貼っているから大丈夫だ！っと思っていたら実はINDEXが効いていなかったという事実が判明した時にはかなりビビりました。
  • 何かの処理作ったり、改修する時にはちゃんとINDEXが効いてるか確認すること。
• ループ処理の中でクエリを発行するのは止めよう。
  • ループの前でin句などを利用して欲しいデータ取得してから取得した件数分を処理するようにしよう。
• ボトルネックになっていた部分を改修してその成果が出た時の快感がヤバいです。
  • 詰まった排水溝が一気に流れるような感じでした。

最後に

• CYBIRDに入社するまで「テーブルにINDEXを設定しないとデータ増えた時に検索するとパフォーマンス落ちるぞ。クエリ実行する際にちゃんとINDEXを使用するクエリにしないとダメだぞ。」っと座学でしか理解しなかったのですが、負荷試験とリリース後の高負荷問題を通して、改めて学ぶことが出来ました。
  • とある漫画のキャラクターの台詞で「百聞は一見にしかず、百見は一触にしかず」と言うのがあるのですが、見聞きするだけでなく実際に触れる事で理解が広まる・深まると言うのを身をもって知りました。
• 期間限定イベントで発生した高負荷問題は負荷試験では顕在化しなかったのは負荷試験用のシナリオの作り方が甘かった・負荷の掛け方が宜しくなかったと身に沁みました。
• 何故もっと早く本番環境の各APIの負荷状況をNewRelicで可視化しなかったのかと後悔しました。原因解決に行き詰った時は実稼動しているサービスの負荷状況等を便利なツールで可視化し原因を特定する事の大切さを実感しました。

ここまで読んで頂き誠にありがとうございました。若干、ただの感想文になっているかもしれませんが本記事を通して負荷試験とパフォーマンスチューニングの大切さを知って頂ければと思います。

「CYBIRDエンジニア Advent Calendar 2021」21日目は@R_araiさんの「研修中勉強したObserverパターンについて」です。デザインパターンの一種であるObserverパターンについて語られるみたいなので気になりますね！