teratail
回答率
85.49%
質問するログイン新規登録
トップに関する質問全く同じデータ、クエリなのにパフォーマンスが急激に遅くなることがある

編集履歴

質問編集履歴

3

explani analyzeの結果を追記

2018/03/29 10:31

投稿

h_daido
h_daido

スコア824

test CHANGED
File without changes
test CHANGED
@@ -14,82 +14,126 @@
14
14
 
15
15
 
16
16
 
17
- #### A. 早い状態（サーバー起動直後）
18
-
19
- ChatGroup Load (**8.3ms**) 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]]
20
-
21
-
22
-
23
- ```
24
-
25
- Sort (cost=1504.48..1505.11 rows=251 width=100)
17
+ #### A. 速い状態
18
+
19
+ 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]]
20
+
21
+ 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]]
22
+
23
+
24
+
25
+ ```
26
+
27
+ QUERY PLAN
28
+
29
+ ------------------------------------------------------------------------------------------------------------------------------------------------------------------
30
+
31
+ Sort (cost=1504.48..1505.11 rows=251 width=100) (actual time=4.832..4.946 rows=1593 loops=1)
26
32
 
27
33
  Sort Key: chat_groups.updated_at DESC
28
34
 
35
+ Sort Method: quicksort Memory: 260kB
36
+
29
- -> Hash Join (cost=582.30..1494.48 rows=251 width=100)
37
+ -> Hash Join (cost=582.30..1494.48 rows=251 width=100) (actual time=2.213..4.276 rows=1593 loops=1)
30
38
 
31
39
  Hash Cond: (chat_group_joins.chat_group_id = chat_groups.id)
32
40
 
33
- -> Bitmap Heap Scan on chat_group_joins (cost=101.28..991.18 rows=5272 width=4)
41
+ -> 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)
34
42
 
35
43
  Recheck Cond: (user_id = 1)
36
44
 
45
+ Heap Blocks: exact=661
46
+
37
- -> Bitmap Index Scan on index_chat_group_joins_on_user_id (cost=0.00..99.96 rows=5272 width=0)
47
+ -> 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)
38
48
 
39
49
  Index Cond: (user_id = 1)
40
50
 
41
- -> Hash (cost=462.81..462.81 rows=1457 width=100)
51
+ -> Hash (cost=462.81..462.81 rows=1457 width=100) (actual time=1.741..1.741 rows=1850 loops=1)
52
+
42
-
53
+ Buckets: 2048 Batches: 1 Memory Usage: 167kB
54
+
43
- -> Bitmap Heap Scan on chat_groups (cost=106.70..462.81 rows=1457 width=100)
55
+ -> 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)
44
56
 
45
57
  Recheck Cond: (company_id = 2)
46
58
 
47
59
  Filter: ((trashed_at IS NULL) AND (archived_at IS NULL) AND (chats_count > 0))
48
60
 
61
+ Rows Removed by Filter: 3758
62
+
63
+ Heap Blocks: exact=271
64
+
49
- -> Bitmap Index Scan on index_chat_groups_on_company_id (cost=0.00..106.34 rows=5607 width=0)
65
+ -> 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)
50
66
 
51
67
  Index Cond: (company_id = 2)
52
68
 
53
- ```
54
-
55
-
56
-
57
- #### B. 遅くなったあと
58
-
59
- ChatGroup Load (**878.6ms**) 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]]
60
-
61
-
62
-
63
- ```
64
-
65
- Sort (cost=1504.48..1505.11 rows=251 width=100)
69
+ Planning time: 0.226 ms
70
+
71
+ Execution time: 5.048 ms
72
+
73
+ ```
74
+
75
+
76
+
77
+
78
+
79
+ #### A. 遅い状態
80
+
81
+ 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]]
82
+
83
+ 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]]
84
+
85
+
86
+
87
+ ```
88
+
89
+ QUERY PLAN
90
+
91
+ ------------------------------------------------------------------------------------------------------------------------------------------------------------------
92
+
93
+ Sort (cost=1504.48..1505.11 rows=251 width=100) (actual time=9.713..9.859 rows=1593 loops=1)
66
94
 
67
95
  Sort Key: chat_groups.updated_at DESC
68
96
 
97
+ Sort Method: quicksort Memory: 260kB
98
+
69
- -> Hash Join (cost=582.30..1494.48 rows=251 width=100)
99
+ -> Hash Join (cost=582.30..1494.48 rows=251 width=100) (actual time=3.825..9.063 rows=1593 loops=1)
70
100
 
71
101
  Hash Cond: (chat_group_joins.chat_group_id = chat_groups.id)
72
102
 
73
- -> Bitmap Heap Scan on chat_group_joins (cost=101.28..991.18 rows=5272 width=4)
103
+ -> 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)
74
104
 
75
105
  Recheck Cond: (user_id = 1)
76
106
 
107
+ Heap Blocks: exact=661
108
+
77
- -> Bitmap Index Scan on index_chat_group_joins_on_user_id (cost=0.00..99.96 rows=5272 width=0)
109
+ -> 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)
78
110
 
79
111
  Index Cond: (user_id = 1)
80
112
 
81
- -> Hash (cost=462.81..462.81 rows=1457 width=100)
113
+ -> Hash (cost=462.81..462.81 rows=1457 width=100) (actual time=3.114..3.114 rows=1850 loops=1)
114
+
82
-
115
+ Buckets: 2048 Batches: 1 Memory Usage: 167kB
116
+
83
- -> Bitmap Heap Scan on chat_groups (cost=106.70..462.81 rows=1457 width=100)
117
+ -> 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)
84
118
 
85
119
  Recheck Cond: (company_id = 2)
86
120
 
87
121
  Filter: ((trashed_at IS NULL) AND (archived_at IS NULL) AND (chats_count > 0))
88
122
 
123
+ Rows Removed by Filter: 3758
124
+
125
+ Heap Blocks: exact=271
126
+
89
- -> Bitmap Index Scan on index_chat_groups_on_company_id (cost=0.00..106.34 rows=5607 width=0)
127
+ -> 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)
90
128
 
91
129
  Index Cond: (company_id = 2)
92
130
 
131
+ Planning time: 0.380 ms
132
+
133
+ Execution time: 9.993 ms
134
+
135
+ (21 rows)
136
+
93
137
  ```
94
138
 
95
139
 
@@ -117,3 +161,89 @@
117
161
 
118
162
 
119
163
  不足情報などありましたら、できるだけすぐに対応しますので、追記依頼をおねがいします。
164
+
165
+
166
+
167
+ ### 追記
168
+
169
+ いただいた情報をもとに execution timeも出力してみたところ、遅い状態では
170
+
171
+ - Execution time自体は速い数値を出している(9.993 ms)
172
+
173
+ - activerecordのLoggerで出力される値が遅い数値（673.4ms）
174
+
175
+
176
+
177
+ ということがわかりました。
178
+
179
+ よってActiveRecord側の問題なきがしてきました...。
180
+
181
+ 少しActiveRecord側の挙動を調べてみようかと思います。
182
+
183
+
184
+
185
+ もし、知見をお持ちの方がいらっしゃいましたら助けていただけるとうれしいです。
186
+
187
+ 念のため、rails側でクエリを作成している箇所のソースをはっておきます。
188
+
189
+
190
+
191
+ コントローラーでのデータ取得箇所は
192
+
193
+ ```ruby
194
+
195
+ # クエリ
196
+
197
+ @current_user.chat_groups
198
+
199
+ .without_trashed
200
+
201
+ .without_archived
202
+
203
+ .has_chats
204
+
205
+ .preload_for_index
206
+
207
+ .where(company_id: @company.id)
208
+
209
+ ```
210
+
211
+
212
+
213
+ 定義しているスコープは
214
+
215
+ ```
216
+
217
+ 　# chats_countはcounter_cacheによる更新です
218
+
219
+ scope :has_chats, -> {
220
+
221
+ where("chats_count > 0")
222
+
223
+ }
224
+
225
+
226
+
227
+ scope :without_archived, -> {
228
+
229
+ where(archived_at: nil)
230
+
231
+ }
232
+
233
+
234
+
235
+ scope :preload_for_index, -> {
236
+
237
+ preload({:last_chat => [:user]}, {:stock => [:group]})
238
+
239
+ }
240
+
241
+
242
+
243
+ scope :without_trashed, -> {
244
+
245
+ where(trashed_at: nil)
246
+
247
+ }
248
+
249
+ ```

2

explainを修正

2018/03/29 10:31

投稿

h_daido
h_daido

スコア824

test CHANGED
File without changes
test CHANGED
@@ -14,9 +14,43 @@
14
14
 
15
15
 
16
16
 
17
- #### A. サーバー起動直後
17
+ #### A. 早い状態（サーバー起動直後）
18
18
 
19
19
  ChatGroup Load (**8.3ms**) 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]]
20
+
21
+
22
+
23
+ ```
24
+
25
+ Sort (cost=1504.48..1505.11 rows=251 width=100)
26
+
27
+ Sort Key: chat_groups.updated_at DESC
28
+
29
+ -> Hash Join (cost=582.30..1494.48 rows=251 width=100)
30
+
31
+ Hash Cond: (chat_group_joins.chat_group_id = chat_groups.id)
32
+
33
+ -> Bitmap Heap Scan on chat_group_joins (cost=101.28..991.18 rows=5272 width=4)
34
+
35
+ Recheck Cond: (user_id = 1)
36
+
37
+ -> Bitmap Index Scan on index_chat_group_joins_on_user_id (cost=0.00..99.96 rows=5272 width=0)
38
+
39
+ Index Cond: (user_id = 1)
40
+
41
+ -> Hash (cost=462.81..462.81 rows=1457 width=100)
42
+
43
+ -> Bitmap Heap Scan on chat_groups (cost=106.70..462.81 rows=1457 width=100)
44
+
45
+ Recheck Cond: (company_id = 2)
46
+
47
+ Filter: ((trashed_at IS NULL) AND (archived_at IS NULL) AND (chats_count > 0))
48
+
49
+ -> Bitmap Index Scan on index_chat_groups_on_company_id (cost=0.00..106.34 rows=5607 width=0)
50
+
51
+ Index Cond: (company_id = 2)
52
+
53
+ ```
20
54
 
21
55
 
22
56
 
@@ -26,39 +60,39 @@
26
60
 
27
61
 
28
62
 
63
+ ```
29
64
 
65
+ Sort (cost=1504.48..1505.11 rows=251 width=100)
30
66
 
67
+ Sort Key: chat_groups.updated_at DESC
68
+
69
+ -> Hash Join (cost=582.30..1494.48 rows=251 width=100)
70
+
71
+ Hash Cond: (chat_group_joins.chat_group_id = chat_groups.id)
72
+
73
+ -> Bitmap Heap Scan on chat_group_joins (cost=101.28..991.18 rows=5272 width=4)
74
+
75
+ Recheck Cond: (user_id = 1)
76
+
77
+ -> Bitmap Index Scan on index_chat_group_joins_on_user_id (cost=0.00..99.96 rows=5272 width=0)
78
+
31
- なお、explainの結果は下記になります
79
+ Index Cond: (user_id = 1)
80
+
81
+ -> Hash (cost=462.81..462.81 rows=1457 width=100)
82
+
83
+ -> Bitmap Heap Scan on chat_groups (cost=106.70..462.81 rows=1457 width=100)
84
+
85
+ Recheck Cond: (company_id = 2)
86
+
87
+ Filter: ((trashed_at IS NULL) AND (archived_at IS NULL) AND (chats_count > 0))
88
+
89
+ -> Bitmap Index Scan on index_chat_groups_on_company_id (cost=0.00..106.34 rows=5607 width=0)
90
+
91
+ Index Cond: (company_id = 2)
32
92
 
33
93
  ```
34
94
 
35
- Limit (cost=2831.72..2831.75 rows=10 width=100)
36
95
 
37
- -> Sort (cost=2831.72..2844.28 rows=5022 width=100)
38
-
39
- Sort Key: chat_groups.updated_at DESC
40
-
41
- -> Merge Join (cost=1317.38..2723.20 rows=5022 width=100)
42
-
43
- Merge Cond: (chat_groups.id = chat_group_joins.chat_group_id)
44
-
45
- -> Index Scan using chat_groups_pkey on chat_groups (cost=0.29..1256.93 rows=29111 width=100)
46
-
47
- Filter: ((trashed_at IS NULL) AND (archived_at IS NULL))
48
-
49
- -> Sort (cost=1317.09..1330.27 rows=5272 width=4)
50
-
51
- Sort Key: chat_group_joins.chat_group_id
52
-
53
- -> Bitmap Heap Scan on chat_group_joins (cost=101.28..991.18 rows=5272 width=4)
54
-
55
- Recheck Cond: (user_id = 1)
56
-
57
- -> Bitmap Index Scan on index_chat_group_joins_on_user_id (cost=0.00..99.96 rows=5272 width=0)
58
-
59
- Index Cond: (user_id = 1)
60
-
61
- ```
62
96
 
63
97
 
64
98
 

1

explainを追記

2018/03/29 08:08

投稿

h_daido
h_daido

スコア824

test CHANGED
File without changes
test CHANGED
@@ -28,6 +28,40 @@
28
28
 
29
29
 
30
30
 
31
+ なお、explainの結果は下記になります
32
+
33
+ ```
34
+
35
+ Limit (cost=2831.72..2831.75 rows=10 width=100)
36
+
37
+ -> Sort (cost=2831.72..2844.28 rows=5022 width=100)
38
+
39
+ Sort Key: chat_groups.updated_at DESC
40
+
41
+ -> Merge Join (cost=1317.38..2723.20 rows=5022 width=100)
42
+
43
+ Merge Cond: (chat_groups.id = chat_group_joins.chat_group_id)
44
+
45
+ -> Index Scan using chat_groups_pkey on chat_groups (cost=0.29..1256.93 rows=29111 width=100)
46
+
47
+ Filter: ((trashed_at IS NULL) AND (archived_at IS NULL))
48
+
49
+ -> Sort (cost=1317.09..1330.27 rows=5272 width=4)
50
+
51
+ Sort Key: chat_group_joins.chat_group_id
52
+
53
+ -> Bitmap Heap Scan on chat_group_joins (cost=101.28..991.18 rows=5272 width=4)
54
+
55
+ Recheck Cond: (user_id = 1)
56
+
57
+ -> Bitmap Index Scan on index_chat_group_joins_on_user_id (cost=0.00..99.96 rows=5272 width=0)
58
+
59
+ Index Cond: (user_id = 1)
60
+
61
+ ```
62
+
63
+
64
+
31
65
  おそらく遅くなる条件としては、
32
66
 
33
67
  - 関連モデルの更新が走った