Sentry

Sentryはエラーやパフォーマンスの監視ができるサービスです。YOUTRUSTでは主にサーバーサイドとフロントエンドで発生したエラーのモニタリングに利用しています。

通知された内容

Sentryからメールが届きました。

Most frequent performance issuesにN+1 Query Sidekiq/ActionMailer::MailDeliveryJobとありました。

N+1 QueryとはRailsで発生するパフォーマンス問題の一つです。ループ内で個別にデータ取得すると、データ件数分のクエリが発行されるため、データ取得に時間がかかります。 preloadなどを利用してまとめてデータ取得することで解消することができます。

Sidekiqとは、非同期ジョブを実行するためのフレームワークです。 YOUTRUSTではユーザーへの通知やメール送信などで利用しています。 ActionMailer::MailDeliveryJobはメール送信のためのジョブです。このジョブでは意欲変更があったユーザーの情報を1日分のサマリーとしてまとめてメール送信しています。

今回はSentryでN+1 Queryが検知できるようになっているので、通知を受け取ることができました。

docs.sentry.io

通知内容をSentryで確認しました。

同じ種類のクエリが複数回発行されていることがわかります。

対応した内容

エンキューするときにActiveRecordオブジェクトの配列を渡していたため、デキューする際に配列の要素数分のクエリが発行されていることがわかりました。このため、ActiveRecordオブジェクトの配列を渡すのではなく、ActiveRecordオブジェクトのIDの配列を渡すように修正しました。実行時に個別に取得することなく、必要な時にまとめて取得するようにしました。

該当部分のコードを抜粋します。job_change_histories、side_job_historiesが意欲変更に関するActiveRecordオブジェクトの配列です。

# 変更前
V2::DailySummaryCareerMotivationHistoriesMailer
  .build(
    to_user,
    time,
    job_change_histories,
    side_job_histories,
  )
  .deliver_later(queue: :very_low)

ローカル環境で再現したSidekiq workerログです。同じようなクエリが複数回発行されていることがわかります。

User Load (2.1ms)  SELECT `users`.* FROM `users` WHERE `users`.`id` = 4 LIMIT 1
UserJobChangeMotivationHistory Load (0.6ms)  SELECT `user_job_change_motivation_histories`.* FROM `user_job_change_motivation_histories` WHERE `user_job_change_motivation_histories`.`id` = 36 LIMIT 1
UserJobChangeMotivationHistory Load (1.2ms)  SELECT `user_job_change_motivation_histories`.* FROM `user_job_change_motivation_histories` WHERE `user_job_change_motivation_histories`.`id` = 38 LIMIT 1
UserJobChangeMotivationHistory Load (17.9ms)  SELECT `user_job_change_motivation_histories`.* FROM `user_job_change_motivation_histories` WHERE `user_job_change_motivation_histories`.`id` = 39 LIMIT 1
UserJobChangeMotivationHistory Load (8.1ms)  SELECT `user_job_change_motivation_histories`.* FROM `user_job_change_motivation_histories` WHERE `user_job_change_motivation_histories`.`id` = 40 LIMIT 1
UserSideJobMotivationHistory Load (2.5ms)  SELECT `user_side_job_motivation_histories`.* FROM `user_side_job_motivation_histories` WHERE `user_side_job_motivation_histories`.`id` = 30 LIMIT 1
UserSideJobMotivationHistory Load (1.7ms)  SELECT `user_side_job_motivation_histories`.* FROM `user_side_job_motivation_histories` WHERE `user_side_job_motivation_histories`.`id` = 31 LIMIT 1
Performing ActionMailer::MailDeliveryJob (Job ID: 6fdd59fe-04e7-4a43-b899-aa84929f9885) from Sidekiq(very_low) enqueued at 2024-03-05T07:33:06Z with arguments: "V2::DailySummaryCareerMotivationHistoriesMailer", "build", "deliver_now", {:args=>[#<GlobalID:0x0000ffff885f3740 @uri=#<URI::GID gid://youtrust-webapp/User/4>>, Tue, 05 Mar 2024, [#<GlobalID:0x0000ffff885f2e08 @uri=#<URI::GID gid://youtrust-webapp/UserJobChangeMotivationHistory/36>>, #<GlobalID:0x0000ffff885f2890 @uri=#<URI::GID gid://youtrust-webapp/UserJobChangeMotivationHistory/38>>, #<GlobalID:0x0000ffff885f2318 @uri=#<URI::GID gid://youtrust-webapp/UserJobChangeMotivationHistory/39>>, #<GlobalID:0x0000ffff885f1dc8 @uri=#<URI::GID gid://youtrust-webapp/UserJobChangeMotivationHistory/40>>], [#<GlobalID:0x0000ffff885f1850 @uri=#<URI::GID gid://youtrust-webapp/UserSideJobMotivationHistory/30>>, #<GlobalID:0x0000ffff885f1198 @uri=#<URI::GID gid://youtrust-webapp/UserSideJobMotivationHistory/31>>]]}
...

変更後のコードです。ActiveRecordオブジェクトの配列ではなく、ActiveRecordオブジェクトのIDの配列を渡すようにしました。

# 変更後
job_change_history_ids = job_change_histories.map(&:id)
side_job_history_ids = side_job_histories.map(&:id)

V2::DailySummaryCareerMotivationHistoriesMailer
  .build(
    to_user,
    time,
    job_change_history_ids,
    side_job_history_ids,
  )
  .deliver_later(queue: :very_low)

# V2::DailySummaryCareerMotivationHistoriesMailer内でidsをまとめて取得します

ローカル環境で確認しました。クエリが1回だけ発行されていることがわかります。

User Load (0.9ms)  SELECT `users`.* FROM `users` WHERE `users`.`id` = 4 LIMIT 1
Performing ActionMailer::MailDeliveryJob (Job ID: 771fa403-1a0e-4ccb-b233-7165c738255c) from Sidekiq(very_low) enqueued at 2024-03-05T11:08:25Z with arguments: "V2::DailySummaryCareerMotivationHistoriesMailer", "build", "deliver_now", {:args=>[#<GlobalID:0x0000ffff7fc6bd60 @uri=#<URI::GID gid://youtrust-webapp/User/4>>, Tue, 05 Mar 2024, [36, 38, 39, 40], [30, 31]]}
UserJobChangeMotivationHistory Exists? (1.8ms)  SELECT 1 AS one FROM `user_job_change_motivation_histories` WHERE `user_job_change_motivation_histories`.`id` IN (36, 38, 39, 40) LIMIT 1
↳ app/mailers/v2/daily_summary_career_motivation_histories_mailer.rb:12:in `build'
UserJobChangeMotivationHistory Load (1.0ms)  SELECT `user_job_change_motivation_histories`.* FROM `user_job_change_motivation_histories` WHERE `user_job_change_motivation_histories`.`id` IN (36, 38, 39, 40)
↳ app/mailers/v2/daily_summary_career_motivation_histories_mailer.rb:15:in `map'
UserSideJobMotivationHistory Load (1.2ms)  SELECT `user_side_job_motivation_histories`.* FROM `user_side_job_motivation_histories` WHERE `user_side_job_motivation_histories`.`id` IN (30, 31)
...