💭

dependent: :destroy_async で大量のレコードを削除したら MySQL の Read IOPS が爆増した

2024/04/09に公開

はじめに

こんにちは、terandard です。
以前 MySQL の Read IOPS が増加しており、その原因が dependent: :destroy_async にあったのでそのことについて話します。

弊社のバックエンドでは Ruby on Rails、DB は Amazon Aurora (MySQL) を使用しています。
当時のバージョンは Rails 7.0, MySQL 5.7 です。

dependent: :destroy_async とは

Rails 6.1 から追加された機能で、モデルの関連先の削除をその場で行うのではなく、ActiveRecord::DestroyAssociationAsyncJob という Job をキューイングすることで非同期に削除を行うようになります。
非同期で削除してくれるため、削除処理に時間がかかるような API のレスポンスを改善することができます。

ただし「削除に時間がかかる原因」については注意が必要です。

OK: 関連先で更に削除する必要がある関連が連なっている
NG: 関連先のレコードが大量にある

この辺は以下の記事で詳しく紹介しているので、合わせて読んでみてください。
https://zenn.dev/socialplus/articles/177b56a034e5f1

今回は dependent: :destroy_async を指定している関連先のレコードが大量にあった 際に発生した問題について話します。

何が起きたか?

AWS の料金 (RDS) が増加していた

弊社では毎月インフラチームが AWS の料金チェックを行っています。
月によってリクエスト数が変動したりするので、料金が増減することはよくあると思います。

問題があった月は RDS の料金が先月と比較して増加しており、特に I/O request 数が先月の数倍に増加していたので、何があったのか確認して欲しいという依頼がありました。

複数のサービスが稼働しているためそれぞれのメトリクスを確認したところ、特定のサービスの Read IOPS が先月と比較して 8倍 近く増加していることがわかりました。

そこで Read IOPS が高い原因の調査を行いました。

Read IOPS が高い時刻に ActiveRecord::DestroyAssociationAsyncJob が実行されていた

まずは Read IOPS が高い時刻のアクセス状況を確認しました。
こちらに関しては前日や先週分などと比較しても特に異常なアクセスはありませんでした。

次に Read IOPS が高い時刻に実行されていたジョブを確認しました。
すると ActiveRecord::DestroyAssociationAsyncJob が長時間実行されていることがわかりました。

当時 ActiveRecord::DestroyAssociationAsyncJob が削除しようとしていたのは以下の UserLoginHistory モデルでした。

class Site < ApplicationRecord
  has_many :user_login_histories, dependent: :destroy_async
end

class UserLoginHistory < ApplicationRecord
end

UserLoginHistory モデルは記録用のテーブルで、ユーザのログイン毎に作成されるためレコード数が非常に多くなります。
調査時は既に削除済みだったため正確なレコード数はわかりませんでしたが、数百万レコード はあったと思われます。

ここまでの調査で Read IOPS が高い原因が ActiveRecord::DestroyAssociationAsyncJob にありそうだと分かりました。
しかし Read IOPS の増加量は削除されたレコード数の数倍はあったため、まだ他に原因がありそうです。

そこで ActiveRecord::DestroyAssociationAsyncJob の詳細を確認しました。

#find_each で発行される SELECT クエリが遅い

MySQL の Read IOPS が高くなっているということは、DB サーバーのディスクからの読み込みが増えているということになります。
つまりディスクから読み込まれるため、クエリの実行時間が長くなっているはずです。

Datadog で発行されているクエリを確認したところ、以下のクエリに5分以上時間がかかっていることが分かりました。

SELECT user_login_histories . * 
FROM user_login_histories 
WHERE user_login_histories . id IN ( ? ) AND user_login_histories . id > ? 
ORDER BY user_login_histories . id ASC 
LIMIT ?

これは以下の find_each で発行される SELECT クエリです。
https://github.com/rails/rails/blob/7-0-stable/activerecord/lib/active_record/destroy_association_async_job.rb#L26-L28

find_each はデフォルトで 1000 レコードずつ取得するようになっています。
したがって LIMIT 1000 が指定されているので、レコード数が多い場合でもそこまで時間がかかることはないはずです。

ここで WHERE 句の条件について確認してみます。
実装を確認すると ActiveRecord::DestroyAssociationAsyncJob の引数に受け取った association_ids がそのまま使用されています。
https://github.com/rails/rails/blob/5bf5344521a6f305ca17e0004273322a0a26f50a/activerecord/lib/active_record/destroy_association_async_job.rb#L13-L17
https://github.com/rails/rails/blob/7-0-stable/activerecord/lib/active_record/destroy_association_async_job.rb#L26-L28

今回の場合、association_ids には削除対象の UserLoginHistory の ID が入っているため、IN 句には数百万レコードの ID が指定されていました
IN 句に大量の値を入れるとフルスキャンを行うため、クエリの実行時間が長くなっていたと考えられます。

To control the memory available to the range optimizer, use the range_optimizer_max_mem_size system variable:
If the specified limit is about to be exceeded, the range access method is abandoned and other methods, including a full table scan, are considered instead. This could be less optimal.

range optimizer で使用可能なメモリを制御するには、range_optimizer_max_mem_size システム変数を使用する
指定された制限を超えそうになると、範囲アクセス法は放棄され、代わりにフルテーブルスキャンを含む他の方法が検討される。これはあまり最適ではないかもしれない。
https://dev.mysql.com/doc/refman/5.7/en/range-optimization.html#range-optimization-memory-use

https://developers.freee.co.jp/entry/large-in-clouse-length-cause-full-scan

また user_login_histories テーブルは記録用のテーブルであるため、参照する頻度は低く、レコード数も数十億件あります。
したがってバッファプールにキャッシュされておらず、ディスクから読み込む必要があるため Read IOPS が増加していたと考えられます。

さらに不幸なことに、バックエンドのデプロイによって ActiveRecord::DestroyAssociationAsyncJob が中断/リトライされていたので、同じクエリが何度も発行されていました。

結果として Read IOPS が爆増していたと考えられます。

対策方法

冒頭で説明したように、dependent: :destroy_async は関連先で更に削除する必要がある関連が連なっていて、削除に時間がかかるケースで使用する機能です。

今回問題になった UserLoginHistory は他に関連先を持っていなかったので dependent: :destroy_async を使用する必要はありませんでした。
また Site の削除自体が Job 化されて非同期で行われているため、削除に時間がかかっても問題ない状況でした。

したがって dependent: :delete_all を使用するように変更することで解決しました。

class Site < ApplicationRecord
-  has_many :user_login_histories, dependent: :destroy_async
+  has_many :user_login_histories, dependent: :delete_all
end

class UserLoginHistory < ApplicationRecord
end

まとめ

dependent: :destroy_async を指定している関連先のレコードが大量にあった際に発生した問題について話しました。
ActiveRecord::DestroyAssociationAsyncJob で発行される SELECT クエリの IN 句に大量の ID が含まれてしまい、フルスキャンが行われて Read IOPS が増加していました。

dependent: :destroy_async関連先で更に削除する必要がある関連が連なっていて、削除に時間がかかるケース で使用しましょう。

参考

GitHubで編集を提案
SocialPLUS Tech Blog

Discussion