質問をすることでしか得られない、回答やアドバイスがある。

15分調べてもわからないことは、質問しよう!

ただいまの
回答率

90.51%

  • Ruby on Rails

    8857questions

    Ruby on Railsは、オープンソースのWebアプリケーションフレームワークです。「同じことを繰り返さない」というRailsの基本理念のもと、他のフレームワークより少ないコードで簡単に開発できるよう設計されています。

  • PostgreSQL

    1357questions

    PostgreSQLはオープンソースのオブジェクトリレーショナルデータベース管理システムです。 Oracle Databaseで使われるPL/SQLを参考に実装されたビルトイン言語で、Windows、 Mac、Linux、UNIX、MSなどいくつものプラットフォームに対応しています。

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

解決済

回答 2

投稿 編集

  • 評価
  • クリップ 0
  • VIEW 3,524

h_daido

score 799

 困った点

表題のとおりなのですが、何かの条件を期に急激にパフォーマンスが劣化(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側でクエリを作成している箇所のソースをはっておきます。

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

# クエリ
@current_user.chat_groups
  .without_trashed
  .without_archived
  .has_chats
  .preload_for_index
  .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)
  }
  • 気になる質問をクリップする

    クリップした質問は、後からいつでもマイページで確認できます。

    またクリップした質問に回答があった際、通知やメールを受け取ることができます。

    クリップを取り消します

  • 良い質問の評価を上げる

    以下のような質問は評価を上げましょう

    • 質問内容が明確
    • 自分も答えを知りたい
    • 質問者以外のユーザにも役立つ

    評価が高い質問は、TOPページの「注目」タブのフィードに表示されやすくなります。

    質問の評価を上げたことを取り消します

  • 評価を下げられる数の上限に達しました

    評価を下げることができません

    • 1日5回まで評価を下げられます
    • 1日に1ユーザに対して2回まで評価を下げられます

    質問の評価を下げる

    teratailでは下記のような質問を「具体的に困っていることがない質問」、「サイトポリシーに違反する質問」と定義し、推奨していません。

    • プログラミングに関係のない質問
    • やってほしいことだけを記載した丸投げの質問
    • 問題・課題が含まれていない質問
    • 意図的に内容が抹消された質問
    • 広告と受け取られるような投稿

    評価が下がると、TOPページの「アクティブ」「注目」タブのフィードに表示されにくくなります。

    質問の評価を下げたことを取り消します

    この機能は開放されていません

    評価を下げる条件を満たしてません

    評価を下げる理由を選択してください

    詳細な説明はこちら

    上記に当てはまらず、質問内容が明確になっていない質問には「情報の追加・修正依頼」機能からコメントをしてください。

    質問の評価を下げる機能の利用条件

    この機能を利用するためには、以下の事項を行う必要があります。

質問への追記・修正、ベストアンサー選択の依頼

  • sazi

    2018/03/29 16:52 編集

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

    キャンセル

  • h_daido

    2018/03/29 17:10

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

    キャンセル

  • sazi

    2018/03/29 17:15

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

    キャンセル

  • h_daido

    2018/03/29 19:33

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

    キャンセル

回答 2

checkベストアンサー

0

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

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

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

投稿

  • 回答の評価を上げる

    以下のような回答は評価を上げましょう

    • 正しい回答
    • わかりやすい回答
    • ためになる回答

    評価が高い回答ほどページの上位に表示されます。

  • 回答の評価を下げる

    下記のような回答は推奨されていません。

    • 間違っている回答
    • 質問の回答になっていない投稿
    • スパムや攻撃的な表現を用いた投稿

    評価を下げる際はその理由を明確に伝え、適切な回答に修正してもらいましょう。

  • 2018/03/29 19:35

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

    キャンセル

0

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

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

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
    AND ("chat_groups"."id" IS NOT NULL)
ORDER BY updated_at DESC LIMIT 10  [["user_id", 1], ["company_id", 2]]


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

SELECT  "chat_groups".*
FROM "chat_groups"
WHERE "chat_groups"."company_id" = $2
    AND "chat_groups"."trashed_at" IS NULL
    AND "chat_groups"."archived_at" IS NULL
    AND (chats_count > 0)
    AND exists(
       select 0
       from "chat_group_joins"
       where "chat_group_joins"."chat_group_id"="chat_groups"."id"
           and "chat_group_joins"."user_id" = $1
)
ORDER 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 19:37

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

    キャンセル

  • 2018/03/29 20:47

    activeRecordとかはよくわからないんですが、解決しそうでよかったです。

    キャンセル

同じタグがついた質問を見る

  • Ruby on Rails

    8857questions

    Ruby on Railsは、オープンソースのWebアプリケーションフレームワークです。「同じことを繰り返さない」というRailsの基本理念のもと、他のフレームワークより少ないコードで簡単に開発できるよう設計されています。

  • PostgreSQL

    1357questions

    PostgreSQLはオープンソースのオブジェクトリレーショナルデータベース管理システムです。 Oracle Databaseで使われるPL/SQLを参考に実装されたビルトイン言語で、Windows、 Mac、Linux、UNIX、MSなどいくつものプラットフォームに対応しています。