この記事は every Tech Blog Advent Calendar 2024の18日目の記事です。
はじめに
こんにちは、TIMELINE 開発部 Service Development をしているhondです！
今回は12/8に行われ、弊社がISUポンサーとして協賛したISUCON 14に会社の同期と友人と共に参加した際に行った事前準備と当日の流れ、反省をまとめていこうと思います。
本ブログ以外にもISUCONに向けて勉強したことやISUCON14 に ISUポンサーの枠で出場しましたもアドベントカレンダーとして投稿されているのでぜひ読んでみてください！
事前準備
前提
今回はチームメンバー全員がGoの経験があることから言語はGo、ISUCON 12予選より他のDBだとしても使い慣れているMySQLに移行することが良いことを知っていたのでMySQLを使うことを前提に準備を行いました。
概要
事前準備としては主に下記の三つを行いました。
- 達人が教えるWebパフォーマンスチューニング 〜ISUCONから学ぶ高速化の実践の読解
- 過去問
- 競技に使うツール導入スクリプトの作成
達人が教えるWebパフォーマンスチューニング 〜ISUCONから学ぶ高速化の実践の読解
こちらの本はモニタリングや負荷試験、ログの集計をはじめとしたWebサービスのパフォーマンス改善を行う際に必要なメソッドがまとまったものになっています。
また、本番同様の環境が準備されたprivate-isuに対し、どのような改善を行えばスコアが上がるか丁寧に順序立てて説明されているのでISUCONに参加したことない人やWebサービスのパフォーマンス改善の概要を知りたい人にはおすすめの一冊です！
過去問
AWS環境で構築するものであればISUCON 5以降の一部予選、本戦の問題が公式にてAMIでの実行方法が公開されています。(ISUCON過去問)本番では例年EC2サーバーが三台用意されるので先ほどのAMIを元に三台起動すると本番同様の環境で過去問に着手することができます。
過去問を解いた後は一部の予選・本戦問題では公式から解説と講評ISUCON13 問題の解説と講評が出ているのでそちらを参考に答え合わせを行うとより理解が深まります。
ISUCON 13ではDNSが初登場するなどまだまだ進化し続けるISUCONなので過去問を解いて引き出しを増やしておくと良さそうです。
競技に使うツール導入スクリプトの作成
競技ではMySQLスロークエリーの解析やアクセスログの集計、APIサーバーのプロファイリングが必要になるので、それらを円滑に行うためのツールやcnfを事前にまとめておきました。
MySQLスロークエリーの解析
初期状態ではスロークエリーログの有効化や出力先が設定されていないのでmy.cnfに以下を記述します。
[mysqld] slow_query_log = 1 slow_query_log_file = /var/log/mysql/mysql-slow.log long_query_time = 0
上記によって/var/log/mysql/mysql-slow.logにスロークエリーログ(0秒を閾値にしているので全てのクエリー)が出力されるようになっているので、それらを解析するためのツールとしてpt-query-digestを導入します。
pt-query-digestを用いることでそれぞれのクエリーが全体のリクエストタイムに締める割合やRow sentやRow examineを可視化することができます。
最後にこの状態ではスロークエリーログが同一ファイルに出力されベンチマークごとの結果を確認できないので、一時的に出力先を変更するためにpt-query-digestのラッパーのquery-digestを導入します。
下記のコマンドを実行することでquery-digestを実行することができます。
perl ./query-digester -duration 10
アクセスログの集計
基本的にISUCONではnginxを経由してAPIサーバーに到達するかたちになっているので、nginxのcnfを修正しJSON形式でログが出力されるようにします。
http {
// 省略
log_format json escape=json '{"time":"$time_iso8601",'
'"host":"$remote_addr",'
'"port":$remote_port,'
'"method":"$request_method",'
'"uri":"$request_uri",'
'"status":"$status",'
'"body_bytes":$body_bytes_sent,'
'"referer":"$http_referer",'
'"ua":"$http_user_agent",'
'"request_time":"$request_time",'
'"response_time":"$upstream_response_time"}';
access_log /var/log/nginx/access.log json;
//省略
}
次にアクセスログを集計するツールとしてalpを導入します。 alpはステータスコードやカウント数をはじめレスポンスタイムの最大・平均・最小値などのメトリクスでアクセスログを集計できるツールとなっています。
最後にMySQLのスロークエリーログ同様にベンチマークごとに結果を確認するために、アクセスログファイルをローテートするスクリプトを作成します。
#!/bin/sh new_file_name=/var/log/nginx/access.log.`date +%Y%m%d-%H%M%S` mv /var/log/nginx/access.log $new_file_name nginx -s reopen
APIサーバーのプロファイリング
今回APIサーバーの言語はGoを選択しているので、プロファイリングツールとしてpprofを用います。
pprofの導入はとても簡単で、下記のようにmain.goに数行追加するだけでプロファイリングできるようになります！
func main() { // ここから runtime.SetBlockProfileRate(1) runtime.SetMutexProfileFraction(1) go func() { log.Fatal(http.ListenAndServe("localhost:6060", nil)) }() // ここまでを追加する log.Fatal(http.ListenAndServe("localhost:8080", nil)) }
当日
ここからは当日の流れになります。
ツール導入スクリプトの実行 10:00 ~ 10:30
競技に使うツール導入スクリプトの作成にて作成したスクリプトを実行し計測可能な状態に、一部のコードをGithubに連携しdevelop branchにmergeしたらEC2にデプロイされる状態にしました。
その後初めてのベンチマークの実行を行いスコアの計測を行いました。
この時点でのスコアは700点程度。
10:30 ~ 13:00
計測の準備が完了したので実際にベンチマークを実行してその結果を確認していきました。
初期の実装ではMySQLのCPU使用率が175%付近になりAPIサーバーやnginxがうまく使えていない状態だったのでquery-digestを用いてスロークエリーログの確認を行いました。
スロークエリーの改善では主にquery-digestを用いてトータルレスポンスの割合が上位になっているクエリーの特定、EXPLAINを用いて実行計画の確認を行いクエリーの改善を行いました。
query-digestと実行計画の結果から上位のスロークエリーはテーブルにインデックスが不足していることでフィルタ処理される行の割合、調査される行の見積もりが悪化していることがわかったのでそれぞれのテーブルに対してインデックスの追加を行い改善を行いました。
オーナーに紐づく椅子を取得するクエリーに関してはサブクエリーを実行するなどクエリー自体の改善が必要そうだったので僕がインデックスの追加を行っている間にチームメイトに改善をお願いしました。
インデックスの追加とクエリーの改善によりスロークエリーは改善されお昼時点で3000点を超え一時80位台に到達しました！
14:00 ~ 16:00
スロークエリーの改善は完了していたので、マニュアルのスコアの計算とアクセスログの結果から配車と通知の改善が必要そうなことを確認し対象の箇所の改善に挑みました。
スコアの計算は下記のように示されていました。
以下に示す要素の合計がスコアとなります。 - 椅子がライドとマッチした位置から乗車位置までの移動距離の合計 * 0.1 - 椅子の乗車位置から目的地までの移動距離の合計 - ライド完了数 * 5
結果としては二時間ほどかけて改善に挑んだのですが、アプリケーションの理解不足でめぼしい改善ができずスコアとしては横ばいでした。
16:00 ~ 18:00
16:00以降は当初より予定していたAPIサーバーとDBのインスタンスを分離する作業に着手しました。
初期実装ではnginx, APIサーバー、DBは全て一つのインスタンスで完結していてスロークエリー改善後もMySQLがCPU使用率の大半を占めていたのでnginxとAPIサーバーのインスタンス、DBのインスタンスと二台構成にする対応を開始しました。
作業としてはAPIサーバーの向き先DBのホストの修正とMySQLでbind-addressを追加するのみだったので練習で行った通りに作業を完了しベンチマークでスコアを測定しました。
CPU負荷の大半を占めていたMySQLが分離したことでAPIサーバーで使えるCPUが増えベンチマークのログを見るとスコアが8000点を超えるなど順調に思われましたが下記のクリティカルエラーが発生ベンチマークが失敗する状態になってしまいました。
msg=クリティカルエラーが発生しました error="椅子に想定していないライドの状態遷移の通知がありました (CODE=12): ride_id: 01JEJMQWN1HEGJM5NZQ40A6KG2, expect: MATCHING, got: COMPLETED"
クリティカルエラーの内容によると15:00まで改善に着手していた通知の不整合とのことだったのでチームメイトとペアプロで改善を試みましたが、対象のクリティカルエラーは改善することはできず複数台構成を諦めることになりました。
後日同僚にクリティカルエラーについて話したところそのチームでも同様の現象が見られ、初期実装では通知間隔が短く複数台構成にしてパフォーマンスが向上することで不整合が発生するので通知間隔を延ばせば改善できたとのことでした。
通知間隔をどこまで延ばして良いかなどは当日マニュアルの猶予時間に記述されていました。
結果
結果スコアの推移は下記画像のようになりました。
インデックスやクエリーの修正によるスロークエリーの改善を行った14:00付近以降はめぼしい改善ができていないので約四時間スコアが横ばいのまま競技終了を迎えました。
しかし、5.環境チェックNGで失格になりました😭
おそらく原因としては僕が複数台構成にするときにAPIサーバーをdisableにしたような気が。
まとめ
僕自身3回目のISUCON参加となるのですが、今まではろくに準備を行わず参加していたのでそれまでに比べれば入念に準備を行えたため当日は納得のいく動きをできたと感じました(結果としては失格ですが笑)。
複数台構成にした時にベンチマークでクリティカルエラーが発生した通知機能に関してはヒントとなる猶予時間が、当日のマニュアルに記述されていたので改めてマニュアルを確認することは大事だと感じました。
また、ペアプロを行うときにアプリの仕様について確認し合う場面が多くあったので、チームで時間を取りマニュアルの読み合わせを行う時間を取ることでその後の実装で共通認識を持って作業できるのではないかと思いました。
失敗の原因になった環境チェックに関して、当日マニュアルの競技環境の確認に環境チェックを行うコマンドが明記されています。
今回はこのチェックを行うことを怠り終了間際までGoのコードと向き合っていたので、普段の過去問を行う際や次回本番では環境確認時にエラーが発生することがあることも踏まえ終了時間の30分以上前には環境確認を含めた締め作業を行おうと思います。
来年はより高スコアを狙えるように普段の業務からパフォーマンスの改善を行えるところがないかなど意識していきます。
