- ID
- 422a9921-0805-4584-b9e1-48dc9b181596
2020-09-10 - Thursday
DONE [[id:ac376401-a8b9-45c5-ab1a-4a77837bd03c][Partnership Squad Engineering Stand-up]]
CLOSED: SCHEDULED: <2020-09-10 Thu 9:00-9:20>
DONE Review Dynatrace for [[id:2d69ab28-c16e-4736-b59f-ef6e1cc89aa2][ENG-12262]]
CLOSED: SCHEDULED:
- ID
- 6094bc67-f1e2-11ea-9a59-e86a64ecc701
- Note taken on
Looking at the PurePath for the view shows that this query is the culprit running in > 240ms:
#+BEGIN_SRC sql
SELECT "ff_question"."id", "ff_question"."delete_ts", "ff_question"."question_frequency", "ff_question"."frequency_params", "ff_question"."is_active", "ff_question"."company_id", "ff_question"."group_id", "ff_question"."user_id", "ff_question"."display_order", "ff_question"."create_ts", "ff_question"."update_ts", "ff_question"."creator_id", "ff_question"."updater_id", "ff_question"."question_text", "ff_question"."permanent_id", "ff_question"."question_type", "ff_question"."extra_json", "ff_question"."question_queue_id", "ff_question"."is_optional", "ff_question"."is_example", "ff_question"."context_text"
FROM "ff_question" WHERE ("ff_question"."delete_ts" IS NULL
AND NOT ("ff_question"."is_example" = true)
AND "ff_question"."company_id" = 14526
AND "ff_question"."group_id" IS NOT NULL
AND "ff_question"."is_active" = true
AND "ff_question"."question_queue_id" IS NULL)
#+END_SRC
# RESULT
488 questions
576 groups
#+BEGIN_SRC sql explain
QUERY PLAN
Bitmap Heap Scan on ff_question (cost=4736.47..6695.85 rows=171 width=264) (actual time=161.955..163.103 rows=488 loops=1)
Recheck Cond: ((company_id = 14526) AND (group_id IS NOT NULL))
Filter: ((delete_ts IS NULL) AND (NOT is_example) AND is_active AND (question_queue_id IS NULL))
Rows Removed by Filter: 519
Heap Blocks: exact=727
-> BitmapAnd (cost=4736.47..4736.47 rows=539 width=0) (actual time=161.573..161.573 rows=0 loops=1)
-> Bitmap Index Scan on ff_question_company_id (cost=0.00..99.00 rows=4077 width=0) (actual time=17.127..17.127 rows=4111 loops=1)
Index Cond: (company_id = 14526)
-> Bitmap Index Scan on ff_question_group_id (cost=0.00..4637.12 rows=139293 width=0) (actual time=144.239..144.239 rows=143642 loops=1)
Index Cond: (group_id IS NOT NULL)
Planning Time: 8.170 ms
Execution Time: 167.536 ms
#+END_SRC
The longest queries in the [[https://yik83377.live.dynatrace.com/#servicecalls;sci=SERVICE-51F39F057B70619A;timeframe=custom1599501600000to1599741368520;servicefilter=0%1E10%11SERVICE_METHOD_GROUP-D3047D1D4B69B003%14Default%20requests%109%11ff.mods.question.api.list.views.GroupQuestionsSumm;gf=all][PurePath list view]] often only have a few queries. The ones with high query counts have a loop over the User table, but those don't account for the longest time.
The problem with the longest views seems to be in python, not the database.
There may be a small opportunity to optimize the way we look up quesitons. The query [[file:/usr/home/powellc/src/ff/fifteen5/ff/mods/group/utils.py::question_qs = Question.existing_objects.filter(][here]] seems to be taking more than 100 miliseconds with the company in question m
#+BEGIN_SRC sql
[ENG-12262] Fix slow query in group utils
This view is only slow sporadically. Looking at dynatrace, the times
it's slowest also happen to involve one particular company. I was
immediately clear what about their data made them susceptible to the
slow down, but running EXPLAIN against the query that was looking up the
list of questions revealed something interesting:
QUERY PLAN
Bitmap Heap Scan on ff_question (cost=4736.47..6695.85 rows=171 width=264) (actual time=161.955..163.103 rows=488 loops=1)
Recheck Cond: ((company_id = 14526) AND (group_id IS NOT NULL))
Filter: ((delete_ts IS NULL) AND (NOT is_example) AND is_active AND (question_queue_id IS NULL))
Rows Removed by Filter: 519
Heap Blocks: exact=727
-> BitmapAnd (cost=4736.47..4736.47 rows=539 width=0) (actual time=161.573..161.573 rows=0 loops=1)
-> Bitmap Index Scan on ff_question_company_id (cost=0.00..99.00 rows=4077 width=0) (actual time=17.127..17.127 rows=4111 loops=1)
Index Cond: (company_id = 14526)
-> Bitmap Index Scan on ff_question_group_id (cost=0.00..4637.12 rows=139293 width=0) (actual time=144.239..144.239 rows=143642 loops=1)
Index Cond: (group_id IS NOT NULL)
Planning Time: 8.170 ms
Execution Time: 167.536 ms
That last index scan over the ff_question_group_id table takes a
whopping 144ms of the total execution time of 167ms. Turns out, checking
for group being null is expensive if you don't prefetch
#+END_SRC
DONE [[id:9a41e0e4-e656-4238-9c9b-2a62d9c7d465][15Five Report]]
CLOSED: SCHEDULED: