GORMを使い始めたら…【AdC2020 14日目】

この記事はtraPアドベントカレンダー2020の 14日目(11/27) の記事です。19Bのmazreanです。普段はSysAd班で部内サービスの運用・開発を行っています。

traPにはanke-toというアンケートを行う部内サービスがあります(詳細は↓)。

現在anke-toのリファクタリングと新規機能追加を行っています。自分はそのサーバーサイドのリーダーをしています。この記事ではその中で起きた恐怖(？)の出来事について話したいと思います。

前提

anke-toのサーバーサイドはGolangで書かれており、データベースにはMariaDBが使われています。リファクタリング前はORMを使わずsqlxでSQL直書きによりデータベースを扱っている状態でした。保守性を考えるとORMを使うよう書き換えた方が良い、という判断でリファクタリングに当たってGORMを使い書き換えることになりました。
sqlboilerなどの他のORM(またはORMに類するもの)ではなくGORMを選んだ理由としては、「既に多くのSysAd班のアプリケーションで使われており、新入部員の学習コストを抑えられる」というのが大きかったです。これはサークルという入れ替わりが激しい組織においては長期運用していくに当たって重要なポイントでした。
また、anke-toは運用され始めてから1年半以上が経過するサービスで、アンケート数は750を超え、アンケートの中のそれぞれの質問への回答が格納されるresponseテーブルには5,6万程度のレコードが存在している状態でした。
今回の事件はそのような状況下でGORMを使う中でおきました。

事件の詳細

GORMによる置き換えが終わり、stagingでの挙動確認なども終わったタイミングで一度デプロイを行うことになりました。デプロイが終わったタイミングで恐怖の出来事がおきます。
レスポンスが遅い
回答を追加するエンドポイントの応答が返ってくるのが非常に遅くなっていました。
具体的にはアンケートによってはリクエストからレスポンスが変えるまでに8秒以上かかっているような状態でした^[1]。
当然staging環境などで試しに動かして見る中で回答が正常にできるかは行っており、そのときには体感で何も問題を感じない程度の速度でした。このことからstagingと本番環境での最も大きな差であるレコード数が何らかの影響を与えているのではないかと考えました。

最初に行った対処

GORMへの置き換えと同じデプロイで入っていた変更に回答へのバリデーション機能の実装がありました。この処理でN+1問題が発生しているのがこの問題が発生する前から分かっており、まず最初にこれを疑いました^[2]。
そこまで大変な修正ではなかったためすぐに修正を行ったのですが、応答速度はほとんど改善されませんでした。

原因調査

推測で行った対処が完全に外れたことで、「推測するな、計測せよ」の言葉を思い出ししっかり計測を行って原因を調査した上で対処するべきと考え直しました。当然本番環境に計測機器を仕込むわけにはいかないので、手元でレコード数が多く、かつ、計測をしっかり行える環境を作ることにしました。

作った環境

今後同様の自体が発生した際に容易に計測が行えるよう、普段ISUCONで使う計測機器が仕込まれた環境をdocker-composeで立ち上げられるようにしました。

pprof
pt-query-digest
myprofiler

が入り使える状態になった環境をdocker-composeにより作りました。また、計測時にいちいちコマンドを叩くのも面倒なので元から開発環境を立ち上げるためにあったMakefileにpprofでの計測、コンテナに入りpt-query-digest、myprofilerでのクエリログの解析が行う処理を書いて容易に計測が行えるようにしました。

また、しっかり計測を行うためにレコード数が多く、高負荷の環境を作る必要がありました。このためにアンケートの作成・回答の追加をなどの初期化を行い、並列で回答を追加するエンドポイントを叩くコードをGolangで書きました。初期化についてはSQLを書いても良かったのですが、どの程度のレコード数で速度低下が顕著になるか確認するためにレコードの増える過程でも応答速度を確認したい、というのがあったので、Golangで並列でAPIを叩くことでしています。

これらの計測環境を作ったcommitが https://github.com/traPtitech/anke-to/commit/673075f469f030f314045382f373242482d289b4#diff-2a9472c5018194dbcd60560b00bba564838fb0e6d987cf19aac46bc9daa719ca です^[3]。
Golangのコードに関しては急ごしらえでかなりエラーハンドリングとかが雑ですが見なかったことにしてください…

予想

「推測するな、計測せよ」は言っても計測前にある程度原因を推測してはいました。GORMへの置き換えのデプロイと同時にしたこととして、インデックスを新しく貼る、というのがあり、この中には回答が保存されるresponseテーブルに関わるものがありました。これによって何らかの大幅な速度低下が起きている可能性を考えました^[4]。計測に踏み切った理由としてどのインデックスが速度低下の原因か特定したかった、というのもありました。

計測結果

計測してみたところ、全く違うことが原因であることが発覚しました。以下はpt-query-digestの結果です。

# 50.8s user time, 170ms system time, 30.67M rss, 82.85M vsz
# Current date: Thu Nov 26 14:49:18 2020
# Hostname: c4daaf499e68
# Files: /tmp/mysql-slow.sql
# Overall: 141.31k total, 74 unique, 182.57 QPS, 0.37x concurrency _______
# Time range: 2020-11-26 14:36:23 to 14:49:17
# Attribute          total     min     max     avg     95%  stddev  median
# ============     ======= ======= ======= ======= ======= ======= =======
# Exec time           283s       0   338ms     2ms    11ms     6ms    98us
# Lock time             2s       0    10ms    13us    49us    69us       0
# Rows sent         74.13M       0  12.13k  550.09   5.20k   1.96k       0
# Rows examine      74.13M       0  12.13k  550.07   5.20k   1.96k       0
# Rows affecte     285.12k       0 121.39k    2.07    0.99  322.48       0
# Bytes sent         1.81G       0 303.38k  13.41k 130.04k  49.00k   10.84
# Query size        10.07M       6   7.66k   74.71  124.25  348.01   31.70
# Boolean:
# QC hit         1% yes,  98% no

# Profile
# Rank Query ID           Response time  Calls  R/Call V/M   Item
# ==== ================== ============== ====== ====== ===== =============
#    1 0xE9CE2FA94DFD6FF4 181.7717 64.3%  12422 0.0146  0.01 SELECT response
#    2 0x813031B8BBC3B329  88.4067 31.3%  20490 0.0043  0.00 COMMIT
# MISC 0xMISC              12.4374  4.4% 108398 0.0001   0.0 <72 ITEMS>

# Query 1: 18.65 QPS, 0.27x concurrency, ID 0xE9CE2FA94DFD6FF4 at byte 39514193
# This item is included in the report because it matches --limit.
# Scores: V/M = 0.01
# Time range: 2020-11-26 14:38:11 to 14:49:17
# Attribute    pct   total     min     max     avg     95%  stddev  median
# ============ === ======= ======= ======= ======= ======= ======= =======
# Count          8   12422
# Exec time     64    182s    95us   157ms    15ms    36ms    12ms    12ms
# Lock time     33   654ms    14us    10ms    52us    76us   145us    38us
# Rows sent     99  73.56M       1  12.13k   6.06k  11.34k   3.42k   6.01k
# Rows examine  99  73.56M       1  12.13k   6.06k  11.34k   3.42k   6.01k
# Rows affecte   0       0       0       0       0       0       0       0
# Bytes sent    99   1.80G     188 303.38k 151.77k 283.86k  85.52k 150.54k
# Query size     5 606.54k      50      50      50      50       0      50
# String:
# Databases    anke-to
# Hosts        172.26.0.1
# Users        root
# Query_time distribution
#   1us
#  10us  #
# 100us  #####
#   1ms  #######################################
#  10ms  ################################################################
# 100ms  #
#    1s
#  10s+
# Tables
#    SHOW TABLE STATUS FROM `anke-to` LIKE 'response'\G
#    SHOW CREATE TABLE `anke-to`.`response`\G
# EXPLAIN /*!50100 PARTITIONS*/
SELECT `modified_at`, `deleted_at` FROM `response`\G

# Query 2: 30.77 QPS, 0.13x concurrency, ID 0x813031B8BBC3B329 at byte 29418104
# This item is included in the report because it matches --limit.
# Scores: V/M = 0.00
# Time range: 2020-11-26 14:38:11 to 14:49:17
# Attribute    pct   total     min     max     avg     95%  stddev  median
# ============ === ======= ======= ======= ======= ======= ======= =======
# Count         14   20490
# Exec time     31     88s     3ms    28ms     4ms     7ms     2ms     4ms
# Lock time      0       0       0       0       0       0       0       0
# Rows sent      0       0       0       0       0       0       0       0
# Rows examine   0       0       0       0       0       0       0       0
# Rows affecte   0       0       0       0       0       0       0       0
# Bytes sent     0 220.11k      11      11      11      11       0      11
# Query size     1 120.06k       6       6       6       6       0       6
# String:
# Databases    anke-to
# Hosts        172.26.0.1
# Users        root
# Query_time distribution
#   1us
#  10us
# 100us
#   1ms  ################################################################
#  10ms  #
# 100ms
#    1s
#  10s+
COMMIT\G

SELECT modified_at, deleted_at FROM responseというresponseテーブルの全てのレコードを見るSQLが実行されており、これにかなりの時間がかかっていることが分かります。responseテーブルは本番環境で6万レコード近くあるテーブルで、これを全て見るSQLが実行されていたならこれだけ遅くなるのも理解出来ます。しかし、このようなクエリが叩かれる箇所に心当たりはありませんでした。そこで今度はGolangのコードのどこでこのSQLが叩かれているのか見つけるためにGORMのログを見てみました。すると、

anke-to_1  | (/go/src/github.com/traPtitech/anke-to/model/responses.go:43) 
anke-to_1  | [2020-11-27 14:34:35]  [824.34ms]  SELECT `modified_at`, `deleted_at` FROM `response`    
anke-to_1  | [114970 rows affected or returned ]

というのがありました。/model/responses.goの43行目が原因のようです。見てみると、

	err := db.Create(&Response{
		ResponseID: responseID,
		QuestionID: questionID,
		Body:       null.NewString(data, true),
	}).Error

GORMのCreateです。なんとレコードを作成するはずのCreate関数の内部でテーブルの全件取得がはしっていたことが分かりました。
リファクタリング前のanke-toではinsertが全てN+1となっており、この800msかかるSQLがresponseテーブルに挿入されるレコード数分叩かれていたことになります。
恐怖ですね…

対処

かなりの速度低下が引き起こされていたので、根本的な原因究明の前に速度低下の原因を排除しました。そのcommitが https://github.com/traPtitech/anke-to/commit/641d1635e3e9f17e0d8dc13d1a2bcccab52a1150 です(急いで作業していたので今見ると余計なものが含まれていますね…)。
全取得の停止のついでにINSERTがN+1になっている問題も直してしまいたかったのでgorm-bulk-insert^[5]というパッケージを使ってバルクインサートするようにしています。このライブラリのINSERTでは全件取得が走らないことが確認できたので、これで速度が大幅に向上しました^[6]。

根本原因

GORMのCreateではINSERTを行わないカラムに何か実際に入ったのか自動でSQLを叩き確認する処理が走ります^[7]。本来はWhereにより1レコードのみの取得となり、そこまで時間がかかることはありません。しかし、このWhereの条件は構造体のprimary_keyタグで指定されたカラムの値になります。
たとえば、

type User struct {
  Id int `gorm:"type:int;primary_key"`
  Name string `gorm:"type:text"`
}

のような構造体であれば、idというカラムの値でWhereの条件が決まります。
しかし、anke-toではGORMのマイグレーションを利用しており、GORMのマイグレーションでは構造体のタグでtypeがintのような単純な型でなくint(11)のようになるとprimary_keyの指定が無視され、Primary Keyが設定されないため、type:int(11) Primary Keyのように書くことでprimary_keyの指定をしていました。このため、Whereの条件のないSELECT、つまり全件取得が行われ、大幅な速度低下が起きたというのが今回の事件の真相でした。

まとめ

今回の問題はGORMの使い方が原因で起きた問題でした。今回のようにGORMを使っているアプリケーションで

レコード数が多い環境でのみ
INSERTを行うエンドポイント

という条件下で速度低下が起きた際にはGORMのCreateの際に走るSELECTが原因の可能性が考えられます。参考になれば幸いです。

明日の担当者は@potato167です。お楽しみに！

余談

現在、個人でGolangのORM(厳密にはORMジェネレーター)の開発を行っています。完成したときにまた記事を書くと思うのでお楽しみに。

手元で当時の状況を再現して計測したところ応答まで8.87秒かかるアンケートがありました ↩︎
このNはresponseテーブルに挿入するレコードの数であり、ここまでの処理時間がかかるとは思えない、という違和感はこのタイミングでありました ↩︎
ベンチマーカーは https://github.com/traPtitech/anke-to/blob/2cdde5aa3671e395153fe26be0fe7a227645fa74/tuning/main.go のようにその後修正しました ↩︎
これだけで秒単位の速度低下になるのか？、という違和感はやはりありました ↩︎
anke-toではGORM v1が使われているのですが、今後移行する予定のGORM v2でBatch Insertが入ったので今ならそちらを使ったほうが良いと思います ↩︎
修正前8.87秒応答までかかっていたリクエストの応答速度が65msになりました ↩︎
http://v1.gorm.io/docs/create.html#Default-Values より ↩︎