全く同じデータ、クエリなのにパフォーマンスが急激に遅くなることがある

困った点

表題のとおりなのですが、何かの条件を期に急激にパフォーマンスが劣化（100倍ほど遅くなる）ことがあります。前後でデータ数には変化がなく、関連レコードにupdateを走らせたあとに発生しやすい（気がする）といったくらいです。

環境

以下環境でAPIサーバーを作成しています
Rails 4.2.4
psql (PostgreSQL) 9.5.1

A. 速い状態

ChatGroup Load (16.9ms) SELECT "chat_groups".* FROM "chat_groups" INNER JOIN "chat_group_joins" ON "chat_groups"."id" = "chat_group_joins"."chat_group_id" WHERE "chat_group_joins"."user_id" = $1 AND "chat_groups"."trashed_at" IS NULL AND "chat_groups"."archived_at" IS NULL AND (chats_count > 0) AND "chat_groups"."company_id" = $2 ORDER BY updated_at DESC [["user_id", 1], ["company_id", 2]]
EXPLAIN for: SELECT "chat_groups".* FROM "chat_groups" INNER JOIN "chat_group_joins" ON "chat_groups"."id" = "chat_group_joins"."chat_group_id" WHERE "chat_group_joins"."user_id" = $1 AND "chat_groups"."trashed_at" IS NULL AND "chat_groups"."archived_at" IS NULL AND (chats_count > 0) AND "chat_groups"."company_id" = $2 ORDER BY updated_at DESC [["user_id", 1], ["company_id", 2]]

                                                                            QUERY PLAN
------------------------------------------------------------------------------------------------------------------------------------------------------------------
 Sort  (cost=1504.48..1505.11 rows=251 width=100) (actual time=4.832..4.946 rows=1593 loops=1)
   Sort Key: chat_groups.updated_at DESC
   Sort Method: quicksort  Memory: 260kB
   ->  Hash Join  (cost=582.30..1494.48 rows=251 width=100) (actual time=2.213..4.276 rows=1593 loops=1)
         Hash Cond: (chat_group_joins.chat_group_id = chat_groups.id)
         ->  Bitmap Heap Scan on chat_group_joins  (cost=101.28..991.18 rows=5272 width=4) (actual time=0.431..1.499 rows=4743 loops=1)
               Recheck Cond: (user_id = 1)
               Heap Blocks: exact=661
               ->  Bitmap Index Scan on index_chat_group_joins_on_user_id  (cost=0.00..99.96 rows=5272 width=0) (actual time=0.360..0.360 rows=4743 loops=1)
                     Index Cond: (user_id = 1)
         ->  Hash  (cost=462.81..462.81 rows=1457 width=100) (actual time=1.741..1.741 rows=1850 loops=1)
               Buckets: 2048  Batches: 1  Memory Usage: 167kB
               ->  Bitmap Heap Scan on chat_groups  (cost=106.70..462.81 rows=1457 width=100) (actual time=0.386..1.419 rows=1850 loops=1)
                     Recheck Cond: (company_id = 2)
                     Filter: ((trashed_at IS NULL) AND (archived_at IS NULL) AND (chats_count > 0))
                     Rows Removed by Filter: 3758
                     Heap Blocks: exact=271
                     ->  Bitmap Index Scan on index_chat_groups_on_company_id  (cost=0.00..106.34 rows=5607 width=0) (actual time=0.341..0.341 rows=5608 loops=1)
                           Index Cond: (company_id = 2)
 Planning time: 0.226 ms
 Execution time: 5.048 ms

A. 遅い状態

ChatGroup Load (673.4ms) SELECT "chat_groups".* FROM "chat_groups" INNER JOIN "chat_group_joins" ON "chat_groups"."id" = "chat_group_joins"."chat_group_id" WHERE "chat_group_joins"."user_id" = $1 AND "chat_groups"."trashed_at" IS NULL AND "chat_groups"."archived_at" IS NULL AND (chats_count > 0) AND "chat_groups"."company_id" = $2 ORDER BY updated_at DESC [["user_id", 1], ["company_id", 2]]
EXPLAIN for: SELECT "chat_groups".* FROM "chat_groups" INNER JOIN "chat_group_joins" ON "chat_groups"."id" = "chat_group_joins"."chat_group_id" WHERE "chat_group_joins"."user_id" = $1 AND "chat_groups"."trashed_at" IS NULL AND "chat_groups"."archived_at" IS NULL AND (chats_count > 0) AND "chat_groups"."company_id" = $2 ORDER BY updated_at DESC [["user_id", 1], ["company_id", 2]]

                                                                                                                                                        QUERY PLAN
------------------------------------------------------------------------------------------------------------------------------------------------------------------
 Sort  (cost=1504.48..1505.11 rows=251 width=100) (actual time=9.713..9.859 rows=1593 loops=1)
   Sort Key: chat_groups.updated_at DESC
   Sort Method: quicksort  Memory: 260kB
   ->  Hash Join  (cost=582.30..1494.48 rows=251 width=100) (actual time=3.825..9.063 rows=1593 loops=1)
         Hash Cond: (chat_group_joins.chat_group_id = chat_groups.id)
         ->  Bitmap Heap Scan on chat_group_joins  (cost=101.28..991.18 rows=5272 width=4) (actual time=0.634..4.163 rows=4743 loops=1)
               Recheck Cond: (user_id = 1)
               Heap Blocks: exact=661
               ->  Bitmap Index Scan on index_chat_group_joins_on_user_id  (cost=0.00..99.96 rows=5272 width=0) (actual time=0.552..0.552 rows=4743 loops=1)
                     Index Cond: (user_id = 1)
         ->  Hash  (cost=462.81..462.81 rows=1457 width=100) (actual time=3.114..3.114 rows=1850 loops=1)
               Buckets: 2048  Batches: 1  Memory Usage: 167kB
               ->  Bitmap Heap Scan on chat_groups  (cost=106.70..462.81 rows=1457 width=100) (actual time=0.626..2.711 rows=1850 loops=1)
                     Recheck Cond: (company_id = 2)
                     Filter: ((trashed_at IS NULL) AND (archived_at IS NULL) AND (chats_count > 0))
                     Rows Removed by Filter: 3758
                     Heap Blocks: exact=271
                     ->  Bitmap Index Scan on index_chat_groups_on_company_id  (cost=0.00..106.34 rows=5607 width=0) (actual time=0.563..0.563 rows=5608 loops=1)
                           Index Cond: (company_id = 2)
 Planning time: 0.380 ms
 Execution time: 9.993 ms
(21 rows)

おそらく遅くなる条件としては、

関連モデルの更新が走った
counter_cacheが走った

などがあるような気がするのですが、定かにはできていない状況です。

コンソールに出力される情報を見る分にはキャッシュもされていないようではあります...。

何から調べればいいのか？どのような可能性があるのかもわからず、行き詰まってしまっております。
どのようなアドバイスでも良いので、いただけませんでしょうか？

不足情報などありましたら、できるだけすぐに対応しますので、追記依頼をおねがいします。

追記

いただいた情報をもとに execution timeも出力してみたところ、遅い状態では

Execution time自体は速い数値を出している(9.993 ms)
activerecordのLoggerで出力される値が遅い数値（673.4ms）

ということがわかりました。
よってActiveRecord側の問題なきがしてきました...。
少しActiveRecord側の挙動を調べてみようかと思います。

もし、知見をお持ちの方がいらっしゃいましたら助けていただけるとうれしいです。
念のため、rails側でクエリを作成している箇所のソースをはっておきます。

コントローラーでのデータ取得箇所は

ruby
1# クエリ
2@current_user.chat_groups
3  .without_trashed
4  .without_archived
5  .has_chats
6  .preload_for_index
7  .where(company_id: @company.id)

定義しているスコープは

　# chats_countはcounter_cacheによる更新です
  scope :has_chats, -> {
    where("chats_count > 0")
  }

  scope :without_archived, -> {
    where(archived_at: nil)
  }

  scope :preload_for_index, -> {
    preload({:last_chat => [:user]}, {:stock => [:group]})
  }

  scope :without_trashed, -> {
    where(trashed_at: nil)
  }

sazi

2018/03/29 07:53 編集

その遅い状況は何かの手当てで、復旧していますか？若しくは遅いままなのでしょうか？また、遅い状況での実行計画は確認されていますか？

h_daido

2018/03/29 08:10

回答ありがとうございます。とりあえずサーバーをリスタートさせると100%復旧することはわかっているのですが、それ以外の条件はわかっていないです。。実行計画を追記したのですが、こういった形であっているのでしょうか？

sazi

2018/03/29 08:15

実行計画はアナライズオプション付きのもの（actual time付き)の方が良いです

h_daido

2018/03/29 10:33

ご指摘ありがとうございます！アナライズオプション付きで実行してみたところ、postgresからの取得は早く完了しているようでした。rails の activerecord側の問題な気がしています。再度しらべてみます！

行動規範の内容に同意します

回答2件

ベストアンサー

実行計画見た感じですと、
各テーブルで対象って5000件くらいであってますか？
そのくらいのテーブルだとindexなんかは関係なく性能出る気がします。

counter_cache（chats_countかな？）がなんか悪いことしてそうな気がします。
chatsテーブル？に更新が入って、chats_countを更新に来ていると推測しますが、
rails触ったことないので詳しいところは分かりません。
？ばかりで、すいません。

提供できるレベルでテーブル定義やfunctionを提供してもらえると、
もう少し分かるかもしれません。

投稿2018/03/29 09:00

szk.

総合スコア1400

h_daido

2018/03/29 10:35

ご指摘ありがとうございます！確かにcounter_cache周りの条件をはずしたところ、発生しなくなりました。。。追記内容にも記載したのですが、railsのactiveRecordまわりの問題な気がしています。テーブル定義やfunctionはそのまま貼ることができなくて...すこし時間かかってしまうかもしれません。いただいた情報をもとに、もう少し調査してみます！

行動規範の内容に同意します

遅くなる原因は不明ですがあまり効率がいいクエリでもない気がします。

・個人的に『selectしていないテーブルがfrom句にある』のは許せないです（笑）
・"chat_groups"."id"は主キーっぽそうなのにis not nullがある。
主キーでなくてもINNER JOINに引っかからないためis nullはあり得ない気がする。
・chats_countはどっちのものか不明なのでなんとも言えません。

sql
1SELECT  "chat_groups".*
2FROM "chat_groups"
3    INNER JOIN "chat_group_joins" ON "chat_groups"."id" = "chat_group_joins"."chat_group_id"
4WHERE "chat_group_joins"."user_id" = $1
5    AND "chat_groups"."trashed_at" IS NULL
6    AND "chat_groups"."archived_at" IS NULL
7    AND (chats_count > 0)
8    AND "chat_groups"."company_id" = $2
9    AND ("chat_groups"."id" IS NOT NULL)
10ORDER BY updated_at DESC LIMIT 10  [["user_id", 1], ["company_id", 2]]

修正したらこうなるのかな？postgresはよく存じ上げないので適当に書いてます。

sql
1SELECT  "chat_groups".*
2FROM "chat_groups"
3WHERE "chat_groups"."company_id" = $2
4    AND "chat_groups"."trashed_at" IS NULL
5    AND "chat_groups"."archived_at" IS NULL
6    AND (chats_count > 0)
7    AND exists(
8       select 0
9       from "chat_group_joins"
10       where "chat_group_joins"."chat_group_id"="chat_groups"."id"
11           and "chat_group_joins"."user_id" = $1
12)
13ORDER BY updated_at DESC LIMIT 10  [["user_id", 1], ["company_id", 2]]

(chats_count > 0)のテーブルが違えばexistsに入れることになるかな。

あとインデックスによっては"chat_group_joins"."user_id" = $1は
"chat_group_joins"."chat_group_id"="chat_groups"."id"よりも先に書いたほうが早いかもです。

投稿2018/03/29 08:47

sousuke

総合スコア3828

h_daido

2018/03/29 10:37

ご指摘ありがとうございます！確かにクエリはきたないんですよね...。運用の簡易化のためrailsのactiveRecordによるsql自動生成をつかっていまして（後出しですいません）。追記コーナーにも記載したのですが、postgres側でなく、まさにこのactiveRecordまわりによる操作があやしいのでは？と踏んでいます。