前書き
趣味開発しているとあるゲームAPIで、OpenTelemetryで集めているエラーログを見てみると、SELECT 1つで 23秒かかっている、明らかにやばいクエリを見つけました。なんとか改善できないか、調査してみました。
実行環境
- サーバー
- Oracle Cloud Infrastructure
- Go/Gorm/OpenTelemetryを使ったとあるゲームAPI(Docker-compose)
- MySQL 8.1(Docker-compose)
- Oracle Cloud Infrastructure
- ログ基盤
- Uptrace (後述)
今回のトラブル
これはOpenTelemetryのTraceログを収集できるobservability platformの1つ、Uptraceで見た1リクエストです。別件でエラーが発生し、Discord/メールに通知が送られてきたので調査しようと思い確認したのですが、エラーどうこう以前に23.5秒
という尋常じゃない時間がかかっているSpanを見つけました。
今回のAPIではotelgormを利用しているので、実行されたSQLも自動的に収集しています。どうも、SELECT * FROM quest_logs WHERE user_id = (ID) ORDER BY created_at DESC, quest_logs.quest_log_id LIMIT 1
が尋常じゃない時間かかっているようです。
修正方法を調べる
INDEXを貼ってみる (失敗)
上記記事とほぼ同一(に見える)クエリを打っていたので、これをものすごく参考にします。
とりあえず、まずはEXPLAINをしてみました。どうやら187179行をFilesortを使い並び替えているようです。
上記記事によると Using Filesortは指定したソート+検索条件がINDEXされていないということを意味します。もう聞くからに時間がかかりそうです。INDEXを設定すると改善できそうなので、探してみます。
上記記事を参考にインデックスを貼るSQLを書いてみます。
WHEREにuser_id
、ORDER BYにcreated_at
を使っているのでuser_id
とcreated_at
の複合インデックスを貼るのが良さそうな気がします。
ALTER TABLE quest_logs add index idx_quest_logs_user_id_created_at (user_id, created_at);
というクエリを打って、その後改めてEXPLAINしてみました。が、未だUsing Filesortが出力されており全く影響がでていません。そこでクエリをよ~く見るとSELECT * FROM quest_logs WHERE user_id = (ID) ORDER BY created_at DESC quest_logs.quest_log_id
LIMIT 1 なので、 ORDER BY が なぜか2種かかっていることがわかります。quest_logs.quest_log_id
を外してみるとヒットするrowsが大幅に減ったので元凶はこれのようでした。
gormのクエリ方法を変えてみる (成功)
意図的にこのクエリにquest_logs.quest_log_idを入れた覚えがないので友人に相談したところ、gormのFirstとTakeに動作の違いがあることがわかりました。Firstは "プライマリキーの昇順で"最初の要素を取る関数
で Takeであれば"追加の順序を指定せず"最初の要素を取る関数
とのことでした。
実際にローカルで、Firstの代わりにTakeを指定した後、Jaegerでログを見てみると余計な quest_logs.quest_log_id
が消えました。
変更後のクエリでもう一度EXPLAINをしてみるとヒットするrowsが減って、大幅に早くなっていることが確認できました。これで一瞬にレスポンスが帰ってくるようになりました🎉
まとめと感想
- あってよかったOpenTelemetryのトレーシング
- gormのFirstとTakeは挙動が違うので注意
- Firstを指定すると PKを元に並び替える処理がおまけで付いてくる
- 直したけれど、gormの罠が怖すぎる。gorm、難しすぎる。ent等の方が良さそう...
- パフォーマンスは良くなりましたが、そもそも調査してたエラーの方を何1つ解決していないため この後要調査
参考
-
https://chat.openai.com/share/f28b2f0b-c04e-4c74-af10-b412a745c482
- スクリーンショットにモザイクをかけるのが面倒だったため、スクリプトで文字列を置き換えました