More than 1 year has passed since last update.

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

Last updated at 2024-01-06Posted at 2024-01-06

前書き

趣味開発しているとあるゲーム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であれば"追加の順序を指定せず"最初の要素を取る関数とのことでした。