Slow queries on ListElementChildren in demo

Erwan Rouchet
2023-07-10T14:43:06Z

`ListElementChildren` without `recursive` set seems to be awfully slow in demo after a `VACUUM ANALYZE` ran on the database over the weekend.

## Current query

```sql
EXPLAIN (ANALYZE, VERBOSE, COSTS, SETTINGS, BUFFERS, WAL, TIMING, SUM...

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" ASC

Unique  (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 ms

The 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" ASC

Unique  (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 ms

Instead 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.