[gorm] 超絶遅いDBクエリを発見したので修正した

前書き

趣味開発しているとあるゲームAPIで、OpenTelemetryで集めているエラーログを見てみると、SELECT 1つで 23秒かかっている、明らかにやばいクエリを見つけました。なんとか改善できないか、調査してみました。

実行環境

• サーバー
  • Oracle Cloud Infrastructure
    • Go/Gorm/OpenTelemetryを使ったとあるゲームAPI(Docker-compose)
    • MySQL 8.1(Docker-compose)
• ログ基盤
  • 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
  • スクリーンショットにモザイクをかけるのが面倒だったため、スクリプトで文字列を置き換えました