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

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

## 実行環境
- サーバー
  - Oracle Cloud Infrastructure
    - Go/Gorm/OpenTelemetryを使ったとあるゲームAPI(Docker-compose)
    - MySQL 8.1(Docker-compose)
- ログ基盤
  - Uptrace (後述)

## 今回のトラブル
![image.png](https://qiita-image-store.s3.ap-northeast-1.amazonaws.com/0/254984/be7e85bf-1d00-1757-c8a3-8397d3374f87.png)

これは[OpenTelemetryのTraceログ](https://christina04.hatenablog.com/entry/opentelemetry-in-go)を収集できるobservability platformの1つ、[Uptrace](https://uptrace.dev)で見た1リクエストです。別件でエラーが発生し、Discord/メールに通知が送られてきたので調査しようと思い確認したのですが、エラーどうこう以前に`23.5秒`という尋常じゃない時間がかかっているSpanを見つけました。

![image.png](https://qiita-image-store.s3.ap-northeast-1.amazonaws.com/0/254984/6c8eaaef-b87b-790c-366d-202541393367.png)

今回のAPIでは[otelgorm](https://uptrace.dev/get/instrument/opentelemetry-gorm.html)を利用しているので、実行されたSQLも自動的に収集しています。どうも、`SELECT *
FROM quest_logs WHERE user_id = (ID) ORDER BY created_at DESC, quest_logs.quest_log_id LIMIT 1` が尋常じゃない時間かかっているようです。

## 修正方法を調べる

### INDEXを貼ってみる (失敗)

https://qiita.com/udonn/items/ca4002aa242c857d4916

上記記事とほぼ同一(に見える)クエリを打っていたので、これをものすごく参考にします。


![image.png](https://qiita-image-store.s3.ap-northeast-1.amazonaws.com/0/254984/33ed00e8-6998-1706-2f02-75c8f4261dec.png)

とりあえず、まずはEXPLAINをしてみました。どうやら187179行をFilesortを使い並び替えているようです。

https://qiita.com/nikadon/items/2f66b447ed6d3b26d78e

上記記事によると [Using Filesortは指定したソート+検索条件がINDEXされていないということを意味します。](#using-temporary-%E3%81%BE%E3%81%9F%E3%81%AF-using-filesort-%E3%82%92%E8%A1%A8%E7%A4%BA%E3%81%95%E3%81%9B%E3%81%AA%E3%81%84)もう聞くからに時間がかかりそうです。INDEXを設定すると改善できそうなので、探してみます。

https://qiita.com/C058/items/1c9c57f634ebf54d99bb

https://polidog.jp/2013/11/24/mysql/

https://yk5656.hatenadiary.org/entry/20140206/1392097362

上記記事を参考にインデックスを貼るSQLを書いてみます。
WHEREに`user_id`、ORDER BYに`created_at`を使っているので`user_id`と`created_at`の複合インデックスを貼るのが良さそうな気がします。

![image.png](https://qiita-image-store.s3.ap-northeast-1.amazonaws.com/0/254984/0eee1327-236e-75c1-c6d6-c9fd52824b2b.png)

`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のクエリ方法を変えてみる (成功)

https://gorm.io/ja_JP/docs/query.html#%E5%8D%98%E4%B8%80%E3%81%AE%E3%82%AA%E3%83%96%E3%82%B8%E3%82%A7%E3%82%AF%E3%83%88%E3%82%92%E5%8F%96%E5%BE%97%E3%81%99%E3%82%8B

意図的にこのクエリに**quest_logs.quest_log_id**を入れた覚えがないので友人に相談したところ、gormのFirstとTakeに動作の違いがあることがわかりました。Firstは `"プライマリキーの昇順で"最初の要素を取る関数`で Takeであれば`"追加の順序を指定せず"最初の要素を取る関数`とのことでした。

![image.png](https://qiita-image-store.s3.ap-northeast-1.amazonaws.com/0/254984/e181a6ae-1e6f-592e-3c96-4cfbfdffe326.png)

![image.png](https://qiita-image-store.s3.ap-northeast-1.amazonaws.com/0/254984/9153e4ef-e3f1-4e2d-d77d-0218236bf745.png)

実際にローカルで、Firstの代わりにTakeを指定した後、[Jaeger](https://www.jaegertracing.io/)でログを見てみると余計な `quest_logs.quest_log_id` が消えました。

![image.png](https://qiita-image-store.s3.ap-northeast-1.amazonaws.com/0/254984/9f1b966e-b7c6-1ae0-c7f6-ed33d80ec727.png)

変更後のクエリでもう一度EXPLAINをしてみるとヒットするrowsが減って、大幅に早くなっていることが確認できました。これで一瞬にレスポンスが帰ってくるようになりました🎉


## まとめと感想
- あってよかったOpenTelemetryのトレーシング
- gormのFirstとTakeは挙動が違うので注意
  - Firstを指定すると PKを元に並び替える処理がおまけで付いてくる
- 直したけれど、gormの罠が怖すぎる。gorm、難しすぎる。ent等の方が良さそう...
- パフォーマンスは良くなりましたが、そもそも調査してたエラーの方を何1つ解決していないため この後要調査

## 参考
- https://chat.openai.com/share/f28b2f0b-c04e-4c74-af10-b412a745c482
  - スクリーンショットにモザイクをかけるのが面倒だったため、スクリプトで文字列を置き換えました