4
0

Delete article

Deleted articles cannot be recovered.

Draft of this article would be also deleted.

Are you sure you want to delete this article?

More than 1 year has passed since last update.

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

Last updated at Posted at 2024-01-06

前書き

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

実行環境

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

今回のトラブル

image.png

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

image.png

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

修正方法を調べる

INDEXを貼ってみる (失敗)

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

image.png

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

上記記事によると Using Filesortは指定したソート+検索条件がINDEXされていないということを意味します。もう聞くからに時間がかかりそうです。INDEXを設定すると改善できそうなので、探してみます。

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

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

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

image.png

image.png

実際にローカルで、Firstの代わりにTakeを指定した後、Jaegerでログを見てみると余計な quest_logs.quest_log_id が消えました。

image.png

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

まとめと感想

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

参考

4
0
0

Register as a new user and use Qiita more conveniently

  1. You get articles that match your needs
  2. You can efficiently read back useful information
  3. You can use dark theme
What you can do with signing up
4
0

Delete article

Deleted articles cannot be recovered.

Draft of this article would be also deleted.

Are you sure you want to delete this article?