Slow queries on ListElementChildren in demo
ListElementChildren without recursive set seems to be awfully slow in demo after a VACUUM ANALYZE ran on the database over the weekend.
Current query
EXPLAIN (ANALYZE, VERBOSE, COSTS, SETTINGS, BUFFERS, WAL, TIMING, SUMMARY) SELECT DISTINCT
ON ("documents_element"."id", "documents_elementpath"."ordering") "documents_element"."id",
"documents_element"."created",
"documents_element"."updated",
"documents_element"."corpus_id",
"documents_element"."type_id",
"documents_element"."name",
"documents_element"."creator_id",
"documents_element"."worker_version_id",
"documents_element"."worker_run_id",
"documents_element"."image_id",
"documents_element"."polygon"::bytea,
"documents_element"."rotation_angle",
"documents_element"."mirrored",
"documents_element"."confidence"
FROM "documents_element"
INNER JOIN "documents_elementpath"
ON ("documents_element"."id" = "documents_elementpath"."element_id")
WHERE ("documents_element"."corpus_id" = '9939cde8-2c3b-41c2-9c66-0ca1e6eec881'::uuid AND "documents_elementpath"."path"[array_length("documents_elementpath"."path", 1)] = '40b4890d-b40a-4fc1-a3cf-0ac63fd47e5d'::uuid)
ORDER BY "documents_elementpath"."ordering" ASC,
"documents_element"."id" ASCUnique (cost=2345.07..2345.08 rows=1 width=166) (actual time=12530.333..12530.338 rows=3 loops=1)
Output: documents_element.id, documents_element.created, documents_element.updated, documents_element.corpus_id, documents_element.type_id, documents_element.name, documents_element.creator_id, documents_element.worker_version_id, documents_element.worker_run_id, documents_element.image_id, ((documents_element.polygon)::bytea), documents_element.rotation_angle, documents_element.mirrored, documents_element.confidence, documents_elementpath.ordering
Buffers: shared hit=152493 read=2390918
-> Sort (cost=2345.07..2345.08 rows=1 width=166) (actual time=12530.332..12530.333 rows=3 loops=1)
Output: documents_element.id, documents_element.created, documents_element.updated, documents_element.corpus_id, documents_element.type_id, documents_element.name, documents_element.creator_id, documents_element.worker_version_id, documents_element.worker_run_id, documents_element.image_id, ((documents_element.polygon)::bytea), documents_element.rotation_angle, documents_element.mirrored, documents_element.confidence, documents_elementpath.ordering
Sort Key: documents_elementpath.ordering, documents_element.id
Sort Method: quicksort Memory: 25kB
Buffers: shared hit=152493 read=2390918
-> Nested Loop (cost=1.12..2345.06 rows=1 width=166) (actual time=103.223..12530.226 rows=3 loops=1)
Output: documents_element.id, documents_element.created, documents_element.updated, documents_element.corpus_id, documents_element.type_id, documents_element.name, documents_element.creator_id, documents_element.worker_version_id, documents_element.worker_run_id, documents_element.image_id, (documents_element.polygon)::bytea, documents_element.rotation_angle, documents_element.mirrored, documents_element.confidence, documents_elementpath.ordering
Inner Unique: true
Buffers: shared hit=152487 read=2390918
-> Index Scan using unique_element_orderings on public.documents_elementpath (cost=0.55..755.79 rows=185 width=20) (actual time=103.180..12530.124 rows=3 loops=1)
Output: documents_elementpath.id, documents_elementpath.path, documents_elementpath.ordering, documents_elementpath.element_id
Index Cond: (documents_elementpath.path[array_length(documents_elementpath.path, 1)] = '40b4890d-b40a-4fc1-a3cf-0ac63fd47e5d'::uuid)
Buffers: shared hit=152481 read=2390909
-> Index Scan using documents_element_pkey on public.documents_element (cost=0.57..8.59 rows=1 width=268) (actual time=0.028..0.028 rows=1 loops=3)
Output: documents_element.id, documents_element.created, documents_element.updated, documents_element.name, documents_element.corpus_id, documents_element.type_id, documents_element.worker_version_id, documents_element.image_id, documents_element.polygon, documents_element.mirrored, documents_element.rotation_angle, documents_element.creator_id, documents_element.confidence, documents_element.worker_run_id
Index Cond: (documents_element.id = documents_elementpath.element_id)
Filter: (documents_element.corpus_id = '9939cde8-2c3b-41c2-9c66-0ca1e6eec881'::uuid)
Buffers: shared hit=6 read=9
Settings: effective_cache_size = '32094MB', work_mem = '50MB'
Planning:
Buffers: shared hit=20
Planning Time: 0.893 ms
Execution Time: 12530.653 msThe query appears to be very slow because it uses the unique_element_orderings index, which is an exclusion constraint and is definitely not meant to be used to filter on paths.
With &&
My recent testing when messing around with add_parent shows that using path__overlap is always faster than using path__last alone, since the GIN index is super fast but does not support direct index access, only array operators like && and @>. So I tried to add it on a whim.
EXPLAIN (ANALYZE, VERBOSE, COSTS, SETTINGS, BUFFERS, WAL, TIMING, SUMMARY) SELECT DISTINCT
ON ("documents_element"."id", "documents_elementpath"."ordering") "documents_element"."id",
"documents_element"."created",
"documents_element"."updated",
"documents_element"."corpus_id",
"documents_element"."type_id",
"documents_element"."name",
"documents_element"."creator_id",
"documents_element"."worker_version_id",
"documents_element"."worker_run_id",
"documents_element"."image_id",
"documents_element"."polygon"::bytea,
"documents_element"."rotation_angle",
"documents_element"."mirrored",
"documents_element"."confidence"
FROM "documents_element"
INNER JOIN "documents_elementpath"
ON ("documents_element"."id" = "documents_elementpath"."element_id")
WHERE ("documents_element"."corpus_id" = '9939cde8-2c3b-41c2-9c66-0ca1e6eec881'::uuid AND "documents_elementpath"."path" && ARRAY['40b4890d-b40a-4fc1-a3cf-0ac63fd47e5d'::uuid] AND "documents_elementpath"."path"[array_length("documents_elementpath"."path", 1)] = '40b4890d-b40a-4fc1-a3cf-0ac63fd47e5d'::uuid)
ORDER BY "documents_elementpath"."ordering" ASC,
"documents_element"."id" ASCUnique (cost=250.76..250.77 rows=1 width=166) (actual time=9.746..9.757 rows=3 loops=1)
Output: documents_element.id, documents_element.created, documents_element.updated, documents_element.corpus_id, documents_element.type_id, documents_element.name, documents_element.creator_id, documents_element.worker_version_id, documents_element.worker_run_id, documents_element.image_id, ((documents_element.polygon)::bytea), documents_element.rotation_angle, documents_element.mirrored, documents_element.confidence, documents_elementpath.ordering
Buffers: shared hit=5 read=23
-> Sort (cost=250.76..250.76 rows=1 width=166) (actual time=9.744..9.749 rows=3 loops=1)
Output: documents_element.id, documents_element.created, documents_element.updated, documents_element.corpus_id, documents_element.type_id, documents_element.name, documents_element.creator_id, documents_element.worker_version_id, documents_element.worker_run_id, documents_element.image_id, ((documents_element.polygon)::bytea), documents_element.rotation_angle, documents_element.mirrored, documents_element.confidence, documents_elementpath.ordering
Sort Key: documents_elementpath.ordering, documents_element.id
Sort Method: quicksort Memory: 25kB
Buffers: shared hit=5 read=23
-> Nested Loop (cost=238.59..250.75 rows=1 width=166) (actual time=9.614..9.725 rows=3 loops=1)
Output: documents_element.id, documents_element.created, documents_element.updated, documents_element.corpus_id, documents_element.type_id, documents_element.name, documents_element.creator_id, documents_element.worker_version_id, documents_element.worker_run_id, documents_element.image_id, (documents_element.polygon)::bytea, documents_element.rotation_angle, documents_element.mirrored, documents_element.confidence, documents_elementpath.ordering
Inner Unique: true
Buffers: shared hit=5 read=23
-> Bitmap Heap Scan on public.documents_elementpath (cost=238.02..242.03 rows=1 width=20) (actual time=9.536..9.541 rows=3 loops=1)
Output: documents_elementpath.id, documents_elementpath.path, documents_elementpath.ordering, documents_elementpath.element_id
Recheck Cond: ((documents_elementpath.path[array_length(documents_elementpath.path, 1)] = '40b4890d-b40a-4fc1-a3cf-0ac63fd47e5d'::uuid) AND (documents_elementpath.path && '{40b4890d-b40a-4fc1-a3cf-0ac63fd47e5d}'::uuid[]))
Heap Blocks: exact=1
Buffers: shared hit=2 read=11
-> BitmapAnd (cost=238.02..238.02 rows=1 width=0) (actual time=9.513..9.515 rows=0 loops=1)
Buffers: shared hit=2 read=10
-> Bitmap Index Scan on element_path_last (cost=0.00..9.96 rows=185 width=0) (actual time=7.770..7.770 rows=3 loops=1)
Index Cond: (documents_elementpath.path[array_length(documents_elementpath.path, 1)] = '40b4890d-b40a-4fc1-a3cf-0ac63fd47e5d'::uuid)
Buffers: shared read=4
-> Bitmap Index Scan on documents_e_path_15a4b8_gin (cost=0.00..227.81 rows=21841 width=0) (actual time=1.738..1.739 rows=4078 loops=1)
Index Cond: (documents_elementpath.path && '{40b4890d-b40a-4fc1-a3cf-0ac63fd47e5d}'::uuid[])
Buffers: shared hit=2 read=6
-> Index Scan using documents_element_pkey on public.documents_element (cost=0.57..8.59 rows=1 width=268) (actual time=0.055..0.055 rows=1 loops=3)
Output: documents_element.id, documents_element.created, documents_element.updated, documents_element.name, documents_element.corpus_id, documents_element.type_id, documents_element.worker_version_id, documents_element.image_id, documents_element.polygon, documents_element.mirrored, documents_element.rotation_angle, documents_element.creator_id, documents_element.confidence, documents_element.worker_run_id
Index Cond: (documents_element.id = documents_elementpath.element_id)
Filter: (documents_element.corpus_id = '9939cde8-2c3b-41c2-9c66-0ca1e6eec881'::uuid)
Buffers: shared hit=3 read=12
Settings: effective_cache_size = '32094MB', work_mem = '50MB'
Planning:
Buffers: shared hit=13 read=8
Planning Time: 1.107 ms
Execution Time: 9.888 msInstead of taking 12.5 seconds, the same query now takes 10 milliseconds, and goes through the GIN index then the index meant solely for path__last, which is the ideal path.
Edited by Erwan Rouchet