2024年12月8日に開催されたISUCON14に参加しました。この記事はその参加記です。
「去年の振り返り」「準備」「当日」「今年の開催の振り返り」の内容でまとめていきます。
はじめに参加結果
結果としては、1人チームとして参加して、最終スコア6,821点、MAXスコア7,188点でした。順位としては、自分の見た限りでは全体270位、学生28位でした。（下のツイートの学生順位はミスです）
当日の最終的なプログラムは以下に残しています。今後、感想戦で変更を加えるかも知れませんが、当日の最終時点でのソースはv1のタグです。
昨年の振り返り
ISUCONは2022年のISUCON12から参加していて、去年のISUCON13は2年目で初めての1人参加でした。スコアは3,500点程度で、あまり覚えてはいないですがほとんど初期スコアと変わらなかった記憶があります。
去年の自分はろくに計測もせず、取り敢えずN+1解消ゲーかなとか思って、ひたすらにプログラムの中のN+1になっているクエリを消していました。今思い返せば、きっとそこよりも先にDBのスロークエリなどがボトルネックになっていただろうことにも一切気付けずに…。
終了後に他の人の関連エントリを見て、INDEXを設定しただけで5,000点いきました、とかを見て、マジかよ…となっていた記憶があります。
準備
昨年の振り返りから、今年は「推測するな、計測せよ」という有名な言葉をしっかりと肝に銘じて挑むことは考えていました。そのためには、APIにおけるレスポンス時間などの分析ツールであるalp、SQLのボトルネックを見つけるslow_query_log、Goの色々見られるすごいプロファイラ（雑な認識ですみません）pprofあたりは使いこなせないとなという認識でした。
ISUCON13の時点でもこれらのツールは知っていましたが上手く導入ができず、なんとか導入できたalpだけを使ってN+1を消していったというのが去年のハイライトです。導入含めたこれらを扱う練習ができたらなーと言うのが元々思っていた準備の予定です。
と、思ってはいましたが、ちょうど忙しい時期にあたってしまい、気付いたらISUCONの直前で対策の時間はほとんど取れませんでした。
流石に何もしないのはマズいと思って、ISUCONの過去エントリを1つ読んだのが前日寝る前の深夜4時（当日朝4時）です。「ISUCON 定石」で調べてトップにヒットした「ISUCON11 予選問題実践攻略法」を読むだけにとどまりましたが、この記事の内容が非常に助かった…。当日の競技中含め何度も読み返しました。
この記事を軽く目を通して、1年以上ぶりに触れるISUCONの雰囲気を少しばかり思い出し、明日寝坊してはマズいので急いで寝ました。
当日
起きたのは朝9時半、急いでご飯を食べていたらライブ中継の出題動画は見逃し、バタバタしながら10時に競技開始です。
競技開始～11時半頃 計測環境の用意
競技開始からは計測環境の前にまず以下の準備を行いました。
- 配布されたCloudformationによるサーバの構築
- Gitの設定
次に、alp, slow-query-log, pprofの設定を行いました。基本は先ほども挙げた「ISUCON11 予選問題実践攻略法」の記事に倣って設定しました。
alpの設定
alpのインストールは以下の記事なども参考にして、次のコマンドで行いました。GitHubのリポジトリから対応するバージョンとOSのバイナリをダウンロードして解凍、実行ファイルのフォルダに移動します。
curl -L -O https://github.com/tkuchiki/alp/releases/download/v1.0.21/alp_linux_amd64.zip
unzip alp_linux_amd64.zip
sudo mv alp /usr/local/bin/
alp --versionとしてバージョンが表示されればインストール完了です。
それから、APIの前段に置かれているnginxのログ出力の設定も変更しておきます。/etc/nginx/nginx.confのパスの設定ファイルを編集して、以下のように変えました。（ここはGit管理していません🙇）
〜〜（省略）〜〜
+ log_format ltsv "time:$time_local"
+ "\thost:$remote_addr"
+ "\tforwardedfor:$http_x_forwarded_for"
+ "\treq:$request"
+ "\tstatus:$status"
+ "\tmethod:$request_method"
+ "\turi:$request_uri"
+ "\tsize:$body_bytes_sent"
+ "\treferer:$http_referer"
+ "\tua:$http_user_agent"
+ "\treqtime:$request_time"
+ "\tcache:$upstream_http_x_cache"
+ "\truntime:$upstream_http_x_runtime"
+ "\tapptime:$upstream_response_time"
+ "\tvhost:$host";
+ access_log /var/log/nginx/access.log ltsv;
- access_log /var/log/nginx/access.log main;
〜〜（省略）〜〜
インストールができたら、結果集計用のコマンドをMakefileで作成しておきます。こちらも予選問題実践攻略法の記事を参照していますが、以下のようにしました。
ALPSORT=sum
ALPM="/assets/.+,/images/.+,/api/app/rides/[-A-Z0-9]+/evaluation,/api/chair/rides/[-A-Z0-9]+/status,/api/app/nearby-chairs\?,/api/owner/sales\?"
OUTFORMAT=count,method,uri,min,max,sum,avg,p99
.PHONY: alp alpsave alpload
alp:
sudo alp ltsv --file=/var/log/nginx/access.log --nosave-pos --pos /tmp/alp.pos --sort $(ALPSORT) --reverse -o $(OUTFORMAT) -m $(ALPM) -q
alpsave:
sudo alp ltsv --file=/var/log/nginx/access.log --pos /tmp/alp.pos --dump /tmp/alp.dump --sort $(ALPSORT) --reverse -o $(OUTFORMAT) -m $(ALPM) -q
alpload:
sudo alp ltsv --load /tmp/alp.dump --sort $(ALPSORT) --reverse -o count,method,uri,min,max,sum,avg,p99 -q
ALPM=~~~~で指定しているのは、リクエストが来るパスのパターンです。こちらを設定せずにalpの結果を見て見ると、今回の問題だと例えば/api/chair/rides/{ride_id}/statusのような形式のリクエストが、ride_idの数だけ別のパスとして沢山表示されます。
取り敢えず初期段階では、個々のride_idに対するレスポンス速度などを見る必要は無く、総じてrideのステータスを更新するAPIのレスポンス速度の傾向を見たいです。なので、ride_idに関わらずこれらをまとめて1つのパターンとして指定しています。
正規表現もあまりしっかり理解しているわけでもなく、上記見ていただくと.+と書いている所と、[-A-Z0-9]+と書いているところがありますが、正直適当です。[-A-Z0-9]+の書き方はアンダースコアなどの記号が入ると効かないですかね。
それから、クエリパラメータ(/api/app/hoge?fuga=aaaa)の形式でリクエストが来る場合もパターンを設定する必要があり、/api/owner/sales\?などがその指定にあたります。?の記号は正規表現としても意味を持ってしまうのでエスケープしています。
後から見返して思いましたが、実行コマンドで-qのオプションを外せばクエリパラメータは無視されるかもしれません。
--pos /tmp/alp.posのオプションでは、ログをどこまで読んだかを記録しておくファイルを指定しています。このファイルがあるおかげで、例えばベンチマーク1回目を回してalpの解析結果を見て、改めてベンチマーク2回目を回す時に、前のログを削除するなどの手間が省けます。
--nosave-posのオプションを指定すれば↑のログをどこまで読み込んだかの記録をしないようになります。
--dump /tmp/alp.dumpのオプションでは解析結果の出力を記録しておくファイルをしてします。
これらのオプションを使用して、上のMakefileで指定している各コマンドは次のような意味を持ちます。
-
alp：まだ解析していない分のログを解析する。（解析済みの位置を変えない） -
alpsave：まだ解析していない分のログを解析する。（最新のログまでが解析済みになる） -
alpload：直近の解析結果を再度確認する。前々回の解析結果は見られない
より具体的なシチュエーションで例をあげると次の意味になります。
- ベンチマーク1回目
-
alp：1回目のベンチマークの結果を解析する -
alpsave：1回目のベンチマークの結果を解析し保存する -
alpload：まだ解析していないので読み込めない
-
- 1回以上
alpsaveを実行済み-
alp：いずれのログも解析されない（既に解析済みのため） -
alpsave：いずれのログも解析されないが、解析対象なしの結果が保存されてしまう -
alpload：alpsaveの実行が1回だけなら1回目のベンチマークの結果が見られる
-
- ベンチマーク2回目
-
alp：2回目のベンチマークの結果を解析する -
alpsave：2回目のベンチマークの結果を解析し保存する -
alpload：alpsaveの実行が1回目のベンチマークの後1回だけで、2回目のベンチマークの後にまだ実行していないなら、1回目のベンチマークの結果が見られる
-
ここまでの設定で、ベンチマークごとに結果を解析すると、次のような結果が確認できます。
+-------+--------+--------------------------------------+-------+-------+---------+-------+-------+
| COUNT | METHOD | URI | MIN | MAX | SUM | AVG | P99 |
+-------+--------+--------------------------------------+-------+-------+---------+-------+-------+
| 10011 | GET | /api/chair/notification | 0.004 | 0.578 | 965.907 | 0.096 | 0.350 |
| 1828 | GET | /api/app/notification | 0.009 | 0.877 | 511.470 | 0.280 | 0.605 |
| | | ～～省略～～ | 0.000 | 0.000 | 0.000 | 0.000 | 0.000 |
| 32 | GET | /client | 0.000 | 0.000 | 0.000 | 0.000 | 0.000 |
| 108 | GET | /favicon.ico | 0.000 | 0.000 | 0.000 | 0.000 | 0.000 |
| 7 | GET | /debug/pprof/profile | 0.000 | 0.000 | 0.000 | 0.000 | 0.000 |
+-------+--------+--------------------------------------+-------+-------+---------+-------+-------+
slow-query-logの設定
スロークエリログの解析はmysqldumpslowというコマンドを利用します。スロークエリログを収集する設定をONにするコマンドと、解析のコマンドをこれもまたMakefileに記述しておきます。ついでに、DBに接続して直接クエリを実行したいと思ったので、そのためのコマンドも定義しておきます。
# mydql関連
MYSQL_HOST="127.0.0.1"
MYSQL_PORT=3306
MYSQL_USER=isucon
MYSQL_DBNAME=isuride
MYSQL_PASS=isucon
MYSQL=mysql -h$(MYSQL_HOST) -P$(MYSQL_PORT) -u$(MYSQL_USER) -p$(MYSQL_PASS) $(MYSQL_DBNAME)
SLOW_LOG=/tmp/slow-query.log
# slow-wuery-logを取る設定にする
# DBを再起動すると設定はリセットされる
.PHONY: slow-on slow-off slow-show db-conn
slow-on:
sudo rm $(SLOW_LOG)
sudo systemctl restart mysql
$(MYSQL) -e "set global slow_query_log_file = '$(SLOW_LOG)'; set global long_query_time = 0.001; set global slow_query_log = ON;"
slow-off:
$(MYSQL) -e "set global slow_query_log = OFF;"
# mysqldumpslowを使ってslow wuery logを出力
# オプションは合計時間ソート
slow-show:
sudo mysqldumpslow -s t $(SLOW_LOG) | head -n 20
db-conn:
$(MYSQL)
make db-connを実行すれば、DBに入って直接操作することができます。
スロークエリログの収集は、make slow-onで設定をONにし、make slow-showでログの解析を行います。make slow-showは、headで出力行数を絞っていますのでご注意ください。(自戒含む)
1つ注意点をあげておくと、スロークエリログは解析後も残っているため、ベンチマークごとに既存のログを削除しないと、前のベンチマークのスロークエリが次以降ものにも混ざりこみます。そのため、slow-onのコマンドの中には既存のログファイルを削除するコマンドsudo rm $(SLOW_LOG)が書かれています。
毎回のベンチマーク実施後に、あらためて再度make slow-onを実行することを想定しています。
一番最初にmake slow-onを実行するときは、まだスロークエリログのファイルが無いためこのrmコマンドでエラーが出ます。一時的にコメントアウトするなどで対応してください。
pprofの設定
Goのソースコードに以下の記述を追記します。
import (
// ～～省略～～
+ _ "net/http/pprof"
"github.com/go-chi/chi/v5"
"github.com/go-chi/chi/v5/middleware"
"github.com/go-sql-driver/mysql"
"github.com/jmoiron/sqlx"
)
var db *sqlx.DB
func main() {
+ go func() {
+ log.Fatal(http.ListenAndServe(":6060", nil))
+ }()
mux := setup()
slog.Info("Listening on :8080")
http.ListenAndServe(":8080", mux)
// ～～省略～～
}
また、Makeコマンドで以下を用意しておきます。Goのソースコードを変更したら、ビルドとサービスのリスタートが必要ですのでお忘れなく。
# ビルドして、サービスのリスタートを行う
# リスタートを行わないと反映されないので注意
.PHONY: build pprof
build:
cd /home/isucon/webapp/go; \
go build -o isuride; \
sudo systemctl restart isuride-go.service;
# pprofのデータをwebビューで見る
# サーバー上で sudo apt install graphvizが必要
pprof:
go tool pprof -http=0.0.0.0:6070 -seconds 90 /home/isucon/webapp/go/isuride http://localhost:6060/debug/pprof/profile
このpprofの使い方で少し詰まってしまいましたが、make pprofと実行するとpprofが計測を開始し、-seconds 90で指定の秒数だけ計測を行います。そのまま待っていると、計測終了後に-http=0.0.0.0:6070で指定したオリジンにアクセスして結果が見られるようになります。
結果の確認について、本来であれば計測終了後に(サーバのアドレス):6070を閲覧しないといけないのかと思いますが、今回私はVSCodeのリモートSSHを利用してサーバにアクセスしており、自動的にポートフォワーディングのようなことをしてくれたのか、手元のPCのlocalhost:6070で結果が確認できました。
11時半～16時半頃 slow-query-logの結果からイスの移動距離の計算を改善する （スコア：1,239）
この5時間がほんとに長かった…。
初期実装ではベンチマークが大体1,000点前後。一度ベンチマークを回してみて、上記のalpとスロークエリログ、pprofを確認しました。あとはtopコマンドを常時付けておいてその動きを見ました。
topを見ていると、明らかにDBのCPU使用率がAPPサーバのCPU使用率よりも高かったです。9割DBの負荷くらいのイメージでした。なので、alpの結果は一旦気にせず、スロークエリログの結果をまず見ました。解析結果は以下の通り。
この記事を書いていてこのタイミングでSELECT status FROM ride_statuses WHERE ride_id = 'S' ORDER BY created_at DESC LIMIT Nのクエリが遅いことに気付きましたが、これは後ほどのタイミングで修正しました。競技中は明らかに速度の遅い SELECT id, owner_id, name,から始まる長いクエリが目につき、まずこちらを修正することにしました。
初期実装のスロークエリログの結果
Reading mysql slow query log from /tmp/slow-query.log
Count: 15797 Time=0.03s (540s) Lock=0.00s (0s) Rows=1.0 (15797), isucon[isucon]@localhost
SELECT status FROM ride_statuses WHERE ride_id = 'S' ORDER BY created_at DESC LIMIT N
Count: 124 Time=3.94s (488s) Lock=0.00s (0s) Rows=5.7 (712), isucon[isucon]@localhost
SELECT id,
owner_id,
name,
access_token,
model,
is_active,
created_at,
updated_at,
IFNULL(total_distance, N) AS total_distance,
total_distance_updated_at
FROM chairs
LEFT JOIN (SELECT chair_id,
SUM(IFNULL(distance, N)) AS total_distance,
MAX(created_at) AS total_distance_updated_at
FROM (SELECT chair_id,
created_at,
該当箇所の確認
該当箇所はGET /api/owner/chairsのAPIで、「椅子のオーナーが管理している椅子の一覧を取得する」という機能です。このうち該当のSQLが以下に示すものでした（私の方で少し整形しています）。
SELECT
id, owner_id, name, access_token,
model, s_active, created_at, updated_at,
IFNULL(total_distance, 0) AS total_distance,
total_distance_updated_at
FROM chairs
LEFT JOIN (
SELECT
chair_id, SUM(IFNULL(distance, 0)) AS total_distance,
MAX(created_at) AS total_distance_updated_at
FROM (
SELECT
chair_id, created_at,
ABS(latitude - LAG(latitude) OVER (PARTITION BY chair_id ORDER BY created_at)) +
ABS(longitude - LAG(longitude) OVER (PARTITION BY chair_id ORDER BY created_at)) AS distance
FROM chair_locations
) tmp GROUP BY chair_id
) distance_table ON distance_table.chair_id = chairs.id
WHERE owner_id = ?
SQLの内容を簡単に見ると、基本はchairsテーブルから椅子の情報を取得するのですが、椅子の 総移動距離total_distance と 総移動距離の更新日時total_distance_updated_at は過去の椅子の位置情報のログchair_locationsから計算しています。
これを見ると移動距離の計算の部分が、毎回chair_locationsのログを全部遡って計算しており、明らかに重そうだなーと見て取れます。
まずはINDEXの追加を検討
初めは去年の振り返りも踏まえてINDEXを追加すれば多少は早くなるのだろうかと思い、それを確かめるためにDB内へ入ってEXPLAIN {該当のSQL}のクエリを実行してみました。出力をみると確かにサブクエリの部分でINDEXを使っておらず処理が重いことがわかります。
じゃあということでINDEXを追加してみることにしました。先述の記事を参考に、今年も初期実行SQLは~/webapp/sql/init.shから呼び出されていましたので、そこで呼ばれる~/webapp/sql/1-schema.sqlのファイルを編集しました。
ですが、色々INDEXの候補になりそうなものを追加してみましたが、何度やってもEXPLAINの結果が良くなりません。chair_idとcreated_atの組みを入れてみたり、それらにlatitudeとlongitudeも追加してみたり…。ほんとに色々試しましたが、EXPLAINは良くならないし、もちろんベンチの結果も良くなりません。
あまり時間は気にしていませんでしたが、ここまででなんだかんだ3時間くらい使った気がしています。本当に分からなかった…。終了後のサブクエリのINDEXどうやんねん、が僕の心からの叫びです。
結果的に移動距離の計算のロジックを変更
そもそもINDEXを貼るという行為を普段ほとんど経験していなかったこともありますし、ここはもう諦め、INDEXに頼らず別の方法でこの「総移動距離」の計算を軽くすることを考えました。
毎回のAPIの呼び出しのたびに「総移動距離」を計算するから大変なわけで、元データにあたる位置情報の履歴データchair_locationsが更新（新規追加）されるたびに総移動距離を計算することにしました。
また、総移動距離total_distanceの情報を持つカラムをchairsテーブルに追加し、これの参照だけで済むようにもしました。なんでか競技中はしませんでしたが、今思えばtotal_distance_updated_atのデータもchairsデーブルのカラムにしても良かったかもしれません。
事前計算に向けての変更で必要だと考えたのは以下の内容です。
- カラムの追加と初期データへの対応
-
chair_locationsの新規追加時に、総移動距離を計算しchairsテーブルを更新する処理 -
GET /api/owner/chairsの呼び出し時の総移動距離の参照を、chairsテーブルから行う
カラムの追加に関しては、先述の1-schema.sqlで追加してしまうと、3-initial-data.sqlの初期データの流し込みでエラーになってしまいます。なので新しく4-migrate.sqlを作成して、その中でchairsテーブルにカラムを追加し、既存データ（初期データ）での移動距離を計算するようにしました。
以下が変更箇所です。
+ mysql -u"$ISUCON_DB_USER" \
+ -p"$ISUCON_DB_PASSWORD" \
+ --host "$ISUCON_DB_HOST" \
+ --port "$ISUCON_DB_PORT" \
+ "$ISUCON_DB_NAME" < 4-migrate.sql
-- 移動記録の事前計算
ALTER TABLE chairs
ADD COLUMN total_distance INTEGER NOT NULL DEFAULT 0 COMMENT '移動距離';
UPDATE chairs c
JOIN (
SELECT
chair_id,
SUM(IFNULL(distance, 0)) AS total_distance,
MAX(created_at) AS total_distance_updated_at
FROM (
SELECT
chair_id, created_at,
ABS(latitude - LAG(latitude) OVER (PARTITION BY chair_id ORDER BY created_at)) +
ABS(longitude - LAG(longitude) OVER (PARTITION BY chair_id ORDER BY created_at)) AS distance
FROM chair_locations
) tmp
GROUP BY chair_id
) tmp_result ON c.id = tmp_result.chair_id
SET c.total_distance = tmp_result.total_distance;
chair_locationsの新規追加時、すなわちchairPostCoordinateの関数の中では次のクエリを実行するようにしました。
UPDATE chairs
JOIN (
SELECT
t1.chair_id,
ABS(t1.latitude - t2.latitude) + ABS(t1.longitude - t2.longitude) AS distance
FROM
chair_locations t1
JOIN
chair_locations t2
ON t1.chair_id = t2.chair_id
AND t1.created_at > t2.created_at
WHERE
t1.chair_id = ?
ORDER BY
t1.created_at DESC
LIMIT 1
) AS distance_data
ON chairs.id = distance_data.chair_id
SET chairs.total_distance = chairs.total_distance + distance_data.distance
また、chair_locationsテーブルにはchair_idとcreated_atの組み合わせのINDEXを追加しました。
最後にGET /api/owner/chairsの呼び出し時のクエリは以下のようになりました。だいぶシンプルになりましたし、これでならEXPLAINの結果もわかりやすくなりました。
SELECT
id, owner_id, name, access_token, model, is_active,
created_at, updated_at, total_distance,
total_distance_updated_at
FROM chairs
LEFT JOIN (
SELECT
chair_id,
MAX(created_at) AS total_distance_updated_at
FROM chair_locations
GROUP BY chair_id
) distance_table ON distance_table.chair_id = chairs.id
WHERE owner_id = ?
この前後でchairsテーブルにowner_idのカラムのINDEXを追加するということもやっています。
ALTER TABLE chairs
ADD INDEX owner_id_index (owner_id);
修正の結果
一連の修正はだいたいこのコミットにあります。
これら一連の修正を実施してベンチマークを回した結果、スコアは1,239になりました。あれ、あんま変わらん…。
今この記事を冷静に書いているときに思えば、より上に来ているSELECT status FROM ride_statuses WHERE ride_id = 'S' ORDER BY created_at DESC LIMIT NのINDEXの不足とかがもっとボトルネックだったのかもしれません。
16時半頃〜17時頃 不足しているINDEXの追加（スコア：4,057）
前の修正にめっちゃ時間をかけた割に、全然スコアが上がらなかったので悲しくなっていましたが、やるしかないので次の修正を進めます。
topコマンドはまだDBのCPU使用率が支配的でしたので、スロークエリログを見ます。先ほどの1,200点台の段階では以下のようなログでした。
Count: 9126 Time=0.03s (275s) Lock=0.00s (0s) Rows=1.0 (9126), isucon[isucon]@localhost
SELECT status FROM ride_statuses WHERE ride_id = 'S' ORDER BY created_at DESC LIMIT N
Count: 3538 Time=0.04s (138s) Lock=0.00s (0s) Rows=0.0 (118), isucon[isucon]@localhost
SELECT * FROM ride_statuses WHERE ride_id = 'S' AND chair_sent_at IS NULL ORDER BY created_at ASC LIMIT N
Count: 2523 Time=0.04s (93s) Lock=0.00s (0s) Rows=0.0 (117), isucon[isucon]@localhost
SELECT * FROM ride_statuses WHERE ride_id = 'S' AND app_sent_at IS NULL ORDER BY created_at ASC LIMIT N
Count: 2265 Time=0.04s (84s) Lock=0.00s (0s) Rows=3.0 (6687), isucon[isucon]@localhost
SELECT * FROM ride_statuses WHERE ride_id = 'S' ORDER BY created_at
Count: 3221 Time=0.01s (37s) Lock=0.00s (0s) Rows=0.0 (0), isucon[isucon]@localhost
COMMIT
Count: 5738 Time=0.01s (28s) Lock=0.00s (0s) Rows=0.6 (3284), isucon[isucon]@localhost
SELECT * FROM rides WHERE chair_id = 'S' ORDER BY updated_at DESC LIMIT N
Count: 457 Time=0.06s (25s) Lock=0.00s (0s) Rows=0.5 (236), isucon[isucon]@localhost
SELECT rides.* FROM rides JOIN ride_statuses ON rides.id = ride_statuses.ride_id WHERE chair_id = 'S' AND status = 'S' AND updated_at BETWEEN 'S' AND 'S' + INTERVAL N MICROSECOND
1つCOMMITが混じっていますが、それ以外は各SELECTが遅いことがわかります。それらをEXPLAINで確認しながら必要な箇所にINDEXを追加していきました。どこに追加したかなどは、Gitのログや最終的な1-schema.sqlを確認していただければと思います。
都度ベンチマークを回しながらSELECTに対するINDEXを追加していくと、結果的に4,000点台のスコアに届きました。やっぱり最初大事なのはINDEXなのか…。
17時頃〜17時半頃 2台構成への変更（スコア：6949）
いちおうDBのINDEXで直せそうなスロークエリは治したし、次の手として昨年からやってみたかったAPPサーバとDBサーバの分離をやってみることにしました。
この部分も先述の記事にあらかたの手順が書かれていて、以外とすぐに実施できました。ざっと、対応したのは以下のような内容です。
- DB用サーバーでMySQLの設定を編集し、外部からのアクセスも可能にする
- ※ 上記の記事の回では
MariaDBが使われていたようで、今回はMySQLのため設定ファイルのパスが異なります
- ※ 上記の記事の回では
- appサーバ用のMySQLのユーザ作成と権限付与
CREATE USER `isucon`@`192.168.%` IDENTIFIED BY 'isucon';
GRANT ALL PRIVILEGES ON `isuride`.* TO `isucon`@`192.168.%`;
- appサーバ側の環境変数の変更
- 環境変数は記事と同様に
~/env.shを参照していましたので、この中のISUCON_DB_HOST="127.0.0.1"をDBサーバのIPアドレスに変えます
- 環境変数は記事と同様に
この変更ののち再度ベンチマークを回すと、スコアは7,000点近くになりました！上ブレの時には7,000点を超えることもありました。1.7倍、強いっ！！
この頃からベンチマークが不安定に
ただ、スコアは上がっていきましたが、この頃からベンチマークがたびたびfailするようになります。エラーはmsg=クリティカルエラーが発生しました error="ライドが長時間マッチングされませんでした (CODE=32)"
しっかりとした原因も分からず、ひとまずドキュメントなどを再度読み込むとアプリケーションマニュアルでマッチング間隔を狭めることができると分かり、それを300msに設定したりもしました。ただ安定せず…。
一旦他の修正に移りましたが、競技の一番最後にもしかしてDBサービスの方でも起動しているGoのアプリケーションがisuride-matcherでトリガーされて不整合が起きている？？と気付き、最後5分くらいでDBサーバ側でsudo systemctl disable isuride-go.serviceを実行し、追試でfailにならないようにとお祈りをしていました。
はたして本当にこれが原因だったのかは、確証はもてないです。
17時半頃〜 通知周りが次のボトルネックぽいが…
DB分割後のスロークエリログを見ると、以下のCOMMITがトップに来ています。
Count: 13815 Time=0.01s (187s) Lock=0.00s (0s) Rows=0.0 (0), isucon[isucon]@ip-192-168-0-11.ap-northeast-1.compute.internal
COMMIT
参考にしている記事曰く、どこかのトランザクションがボトルネックのようだということで、alpの結果をみてみると、/api/app/notificationと/api/chair/notificationのあたりがボトルネックになっていそうです。
+-------+--------+--------------------------------------+-------+-------+---------+-------+-------+
| COUNT | METHOD | URI | MIN | MAX | SUM | AVG | P99 |
+-------+--------+--------------------------------------+-------+-------+---------+-------+-------+
| 20201 | GET | /api/app/notification | 0.002 | 0.284 | 905.268 | 0.045 | 0.121 |
| 34555 | GET | /api/chair/notification | 0.001 | 0.232 | 858.546 | 0.025 | 0.070 |
| 12449 | POST | /api/chair/coordinate | 0.008 | 0.299 | 748.320 | 0.060 | 0.125 |
| 122 | GET | /api/app/nearby-chairs\? | 0.024 | 0.918 | 40.396 | 0.331 | 0.843 |
| 166 | GET | /api/owner/chairs | 0.007 | 0.233 | 20.480 | 0.123 | 0.208 |
〜〜（省略）〜〜
これはN+1のクエリがあるのかなと見てみるも、以外となさそう。マニュアルを見たら「SSEでも良いよ」とか書いてある。え、これからSSEに移植するの？30分で？？無理じゃん。となって正直諦め気味。他に何か改善できることは無いかと探しましたが、結局何もできずここまででタイムアップでした。
総移動距離の計算部分の改善に時間かけすぎたなぁ。
今年の振り返り
全体を振り返ってみると、まず昨年よりもスコアが大きく上がったのが嬉しかったです。結局やったことはINDEXの追加と移動距離計算の改善、DBサーバの分離だけですが、それだけでもまあまあ上がってくれました。あとは、はじめのツール類の設定やINDEXの追加などのような基本的なフェーズがもっとスムーズにできるようになれば、よりコアな変更に取り掛かることができ、さらに高いスコアを狙えるのかなといった振り返りです。
もっとできたことで言えば、他の人の記事を軽く見ていた感じ、DBに頼るのではなくインメモリでデータを持つことで処理を速度を上げたと言う話をちらほら見かけました。私は競技中は、DBをINDEXでより良くする、N+1をロジックでどうにかする、ということばかり考えていたので、メモリで持つことを考えられていなかったです。そこら辺も、今年の問題の感想戦をしながら、他の方の記事を見ながら、どうスコアを上げていくのか考えられたら良いなと思っています。