🔥
isucon14反省記、より速くバグらせない方法を考察した

2024/12/15に公開
 はじめにISUCON14に参加して無事再起動試験で0点になりました😅。

ISUCONは12予選から参加しており、今回で3回目の参加でした。

点数としては自己ワーストを記録してしまいましたが、大会の内容としては暫定結果で61位につけるなど前回よりも明らかに改善していました。
今後の課題として自分は実装が遅く、今回の8時間の競技の間で実装できた改善は3つ程でした。

一方で今回の優勝者は1人チームでの参加で様々な改善を行なっています。
自分としてはさらにISUCON上位に行くためには以下の点を改善する必要があると考えています。
実装にかかる時間を減らし、より多くの改善を競技時間中に行えるようにする。
加点条件やベンチマーカーの動きを理解し、プロファイリングに現れない改善点を見つける。

 この記事の目的前述した2つの改善点のうち、この記事では1の実装にかかる時間をどうやって減らしていくかについてまとめます。

この記事の目的は以下の2点です。
来年のISUCONに向けてバグを作らずに実装しきる方法論をまとめる。
バグを作った場合でもなるべく早くデバッグできるようにする。

 なぜ実装が遅いのかまずなぜ実装が遅いのかをISUCON14での反省も踏まえて振り返ります。
まずはじめに自分の体感として一つの改善を行うのに以下の時間をかけていました。
実装箇所の特定: 大体5min
実装箇所の理解と方針: 大体15min
実装: 大体1h
デバッグ: 大体2h
このことから、自分のISUCONにおける実装のボトルネックは主にデバッグにあるとわかります。

そもそも自分が行った改善の実装が間違えていなければデバッグにかかる時間は0hになるはずなので、このボトルネックを潰すためには以下の2つのアプローチが考えられます。
そもそも実装をバグらせない。
もしバグらせても早くデバッグを行う。

 バグらせない実装の基本普段から業務を行っている中でも実装中にバグらせないためには以下の2つが大事であると考えます。
変更を小さく分解していく。
小さく変更し小さく試す。
なぜなら、小さいタスクは大きなタスクに比べて考えることが少なく、実装のミスが起きにくいからです。

また、もしもバグを埋め込んだとしても変更が小さければバグの箇所の特定が行いやすいです。

 今回行った改善自分が行った改善はownerGetChairsエンドポイントの改善でした。

ISUCON14に参加されていた方はご存知だとは思いますが、今年の問題は最初はDBが重かったです。

その中でも以下のクエリがスロークエリとしてダントツの重さでした。
SELECT id,
       owner_id,
       name,
       access_token,
       model,
       is_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 = '01JEXBPHZJ5DZY7E8CCMD5NV4R'\G
このクエリは全体の約50%近くを占めるクエリでスコアアップを目指すためにはまずこのクエリを処理する必要がありました。

しかし、DBにINDEXを貼るにもこのクエリは複雑で二つのサブクエリと一つのJOINが使われています。
このクエリの行なっていることを簡単に説明すると、以下の通りです。

chair_locationsテーブルにLAG関数を使うことで1行前のlatitude, longitudeとの差を計算している。これはつまりchairの移動距離に相当する。
1で計算してchairの移動距離とchairテーブルをJOIN
2でできたテーブルからowner_idが指定されたものと等しいchairを取得する。
この事から、chair_locationの最新の位置とそれまでの累積距離を事前に求めておくことでこのクエリを処理しようと考えました。

 どうしてバグらせてしまったのか前述の通り、この実装において自分は競技時間の約半分を溶かしてしまいました。

以下ではその原因と対策を考察していきます。

 実装の設計が悪かった実装の方針として集計テーブル(競技当日はキャッシュでしたが)をおくという方針までは良かったのですが、その集計テーブルの実装を間違えました。

具体的には自分は以下のような構造体を集計テーブルとして使ってしまいました。
type chairLocationSummary struct {
 ID                     string       `db:"id"`
 OwnerID                string       `db:"owner_id"`
 Name                   string       `db:"name"`
 AccessToken            string       `db:"access_token"`
 Model                  string       `db:"model"`
 IsActive               bool         `db:"is_active"`
 CreatedAt              time.Time    `db:"created_at"`
 UpdatedAt              time.Time    `db:"updated_at"`
 TotalDistance          int          `db:"total_distance"`
 TotalDistanceUpdatedAt sql.NullTime `db:"total_distance_updated_at"`
  CurrentLongitude sql.NullInt `db:"current_longitude"`
  CurrentLatitude sql.NullInt `db:"current_latitude"`
}
この構造体を使えば先ほどのスロークエリは1行で置き換えられるので安易にこの構造体を使おうと考えてしまいました。
しかし、この構造体のメンバのうち、UpdatedAtまではchairsテーブルの内容、以降はchair_locationsの内容です。

つまり2つのテーブルに依存してしまい、単一責務の原則を違反しており実装が難しくなってしまいました。
本来は以下のような構造体にすべきでした。
type ChairChairLocation struct {
 ChairID          string    `db:"chair_id"`
 LatestLatitude  int       `db:latest_latitude"`
 LatestLongitude int       `db:"latest_longitude"`
 TotalDistance int       `db:"total_distance"`
 TotalDistanceUpdatedAt time.Time `db:"total_distance_updated_at"`
}
この集計テーブルはchair_locationsのみに依存したテーブルになっています。

以下では単一責務の原則を違反することで、具体的にどう実装が難しくなったのかを説明します。

 処理するエンドポイントの数が増えたまず、依存先が2つになることで処理を記載すべきエンドポイントが増大しました。

具体的にはこのテーブルは以下の5つのエンドポイントで処理が必要でした。
postInitialize
chairPostChairs
chairPostActivities
chairPostCoordinate
ownerGetChairs
一方後者の構造体はchair_locationにしか依存しないため、処理が必要なエンドポイントは5つから3つに減少します。
postInitialize
chairPostCoordinate
ownerGetChairs

 状態遷移が複雑になった前者の構造体は、2つのテーブルを持っているため初期化処理や更新処理が複雑になります。

なぜなら以下のような状態を考慮しないといけないからです。

Chairのみが登録されておりis_active=Falseである場合(chair_locationは未登録)。

Chairのみが登録されておりis_active=Trueである場合(chair_locationは未登録)。

Chairとchair_locationが登録されているが、chair_locationは1件のみ登録されており、移動距離は計算できない。

Chairとchair_locationが登録されており、chair_locationは2件以上登録されており、移動距離は計算できる。
一方後者であれば、考えるべき状態の数も以下の2つに減少します。

Chairとchair_locationが登録されているが、chair_locationは1件のみ登録されており、移動距離は計算できない。

Chairとchair_locationが登録されており、chair_locationは2件以上登録されており、移動距離は計算できる。
このように今回の設計では変更する範囲も大きくなってしまったことが、実装に時間がかかってしまった一番の原因でした。
ISUCONでは8時間という限られた時間の制約の中でコードの綺麗さや設計に対して雑に考えがちでした。
次回からは、欲張って複数テーブルに依存する集計テーブルの設計は控えようと思います。

 細かいミスが多かった根本原因は前述した設計が悪かったのですが、実装面においても細かいミスを誘発する罠がありました。

 DBとアプリケーションの型は合わせようDBではint32なのにアプリケーションでint64を使ってしまっていました。
すると、初期値でmath.MaxInt64を使いDBに格納できない数字だよみたいなエラーになりました。
SQL周りのエラーはgoのコンパイルでは見つけられないのが辛いところですね。

 なるべくNamedExecを使おうgoのsqlxでは以下のような書き方でinsert文を発行できます。
_, err := db.ExecContext(
  ctx,
  "INSERT INTO owners (id, name, access_token, chair_register_token) VALUES (?, ?, ?, ?)",
  ownerID, req.Name, accessToken, chairRegisterToken,
 )
しかし、この場合、id, name, access_token, chair_register_tokenとownerID, req.Name, accessToken, chairRegisterTokenの順序は一致しないと期待通りの動作にはなりません。
これは?の数が増えるごとにミスの確率が上がってしまいます。
しかも、最悪の場合、実行時にもエラーにならないかもしれません。

例えば、今年の問題のようにlatitude, longitude, total_distanceといった同じ型のデータが多い場合、順序を常に合わせてコーディングすることは難しいです。
そのためNamedExecで:変数名とすることで少しではありますが、つまらないエラーを減らせると考えられます。

 SQLで使うstructはクエリのあるファイルとは別ファイルに集めようJOINを行うSQLをsqlxで扱う場合、カラムをリネームしないといけません。
これはとてもつまらない作業ですが、同時にタイポしやすい場所でもあります。

github copilotを使っているかたはcopilotが気を効かせてうまく書いてくれますが、ちゃんと確認する必要があります。
その時にクエリの上にクエリで使う構造体を書いておくと上下にエディタをスクロールしながら確認する必要があり、非常にストレスでミスしやすいです。

そのため、今回のようにmodels.goといった構造体定義ようのファイルに構造体定義を集めておき、それらを別タブで開くことで効率的に確認することができます。
余談ですが、このようなミスを防ぐために以下のVSCode拡張機能が感想戦中便利でした。次回からは本番で入れられるようにextensions.jsonを整備していきたいところです。
MYSQLクライアント https://marketplace.visualstudio.com/items?itemName=cweijan.vscode-mysql-client2
Code Spell Checker https://marketplace.visualstudio.com/items?itemName=streetsidesoftware.code-spell-checker
そして以下のようにタブを分割することで右側でDBの内容やmodelsの内容を確認しながら左側でコーディングに集中できます。

 SQL文はバッククオート(`)で頻繁に改行しながら書こうこれも前述した内容に近いです。

シングルクオーテーションやダブルクオーテーションでは改行ができず、横に長いSQLになりがちです。

もう最初から(`)で書きましょう。
頻繁に改行することでcopilotが提案してくるコードの分量も短くなるため少しずつ内容を確認しながらコードを書くことができます。

 デバッグについて以上の内容を試してもバグからは完璧には逃れられないでしょう。

その場合にはデバッグをしていく必要があるのですが、今回はそこにも時間がかかりました。

 バグの原因箇所の特定に時間がかかったISUCON本番では、実装自体はエラーを吐かない(レスポンスのステータスコードが500にならないの意味)が整合性チェックや負荷走行試験中に結果が期待値と合わないエラーが頻発しました。

自分の設計が複雑であったことに加え以下の原因から、このバグの原因特定は難しかったです。
変更すべき箇所が理解できておらず実装の抜け漏れがあった
ログが見にくかった。

 実装の抜けもれ集計テーブルを扱うための以下の4つの処理からなる全体像が頭に入っていませんでした。
初期化(最初にDBに入っているデータを処理する)
新規作成(Chairやchair_locationが追加された時の処理)
更新(Chairが更新された時の処理)
参照(集計テーブルを使って実際にスロークエリを改善する部分)
なので初期化を一部忘れており、集計結果が合わないことがありました。
次回以降これらの項目に分解して実装やデバッグを進めていくことでより正しい実装を行えるようになります。

 ログが見にくかったアプリケーションのログを確認するときにはjournalctlコマンドを使っているのですが、特に今回はログが見にくかったです。
というのも、別サービスでmatcherという別プロセスが動いており、これがアプリケーションの動作に関わらず/api/internal/matchに0.5秒間隔でリクエストを飛ばしてくるためjournalctlが/api/internal/matchまみれになっていたのです。
そもそもjournalctl自体、見たいログ以外の情報も入ってきていたのでPrintデバッグが行いにくかったのです。
そこで振り返り時には以下のようにfileにログを吐き出すdebugLoggerを定義しました。log/slogは雑にobjectを投げてもいい感じにログをしてくれるのでそこは良かったです。
file, err := os.OpenFile("app.log", os.O_APPEND|os.O_WRONLY|os.O_CREATE, 0644)
if err != nil {
  panic(err)
}
defer file.Close()
handler := slog.NewTextHandler(file, nil)
debugLogger = slog.New(handler)
debugLogger.Info("Application started", "version", "1.0.0")
また別の方法としてjournalctlのlogをリセットする方法もありました。
logを全削除する場合は以下のコマンド
sudo rm -rf /var/log/journal/*
sudo rm -rf /run/log/journal/*
sudo systemctl restart systemd-journald
または、ある量や時間を基準にログを切り捨てる方法もあります。
sudo journalctl --vacuum-time=60s # 60s移行全消し
sudo journalctl --vacuum-size=10M # 10Mを超えるログを全消し
ここら辺のコマンドは次回、ベンチ実行前コマンドに追加して自動で回るようにしたいところですね。

 最後に今回は結果としては残念ながら再起動試験で失格しスコア0に終わってしまいました。

しかし、内容的にはISUCONで戦えている！という実感を競技時間中に得られて、ISUCON3年目の成長を感じられたことが嬉しかったです。
またメンバーとは一緒に感想戦を企画しているのでそこでも色々と発見した時には追記していこうと思います。
最後にISUCON14の運営の皆様、本当に楽しいISUCON14をありがとうございました。また来年も参加できることを願って努力を続けていこうと思います！
はじめに

この記事の目的

なぜ実装が遅いのか

バグらせない実装の基本

今回行った改善

どうしてバグらせてしまったのか

実装の設計が悪かった

処理するエンドポイントの数が増えた

状態遷移が複雑になった

細かいミスが多かった

DBとアプリケーションの型は合わせよう

なるべくNamedExecを使おう

SQLで使うstructはクエリのあるファイルとは別ファイルに集めよう

SQL文はバッククオート(`)で頻繁に改行しながら書こう

デバッグについて

バグの原因箇所の特定に時間がかかった

実装の抜けもれ

ログが見にくかった

最後に

Discussion
