0

I have recently been finding my production application's database instance hitting around 100% cpu, and when I look at stuck queries, I was seeing a lot of stuck queries that were involving a table which has a column containing a list of ancestor is, and basically doing a regular expression substring to find the parent ID from that column and then performing a NOT IN to exclude rows that are parents...

SELECT fp.*, admin_folders.id AS folder_id FROM folder_permissions fp RIGHT OUTER JOIN (
          SELECT f.* FROM folders f WHERE f.deleted = FALSE AND ((SUBSTRING(f.ancestry FROM '([^/]*)$')::integer NOT IN (SELECT f2.id FROM folders f2 WHERE deleted = FALSE)) OR (f.ancestry IS NULL))
        ) admin_folders
          ON admin_folders.id = fp.folder_id
            AND fp.user_id = 12345 ORDER BY lower(admin_folders.name);

Initially I thought maybe the substring with the regex was causing the problem, so I tried adding a ltree column and changing that to ((ltree2text(subpath(f.path, -2, 1))::integer ... That seemed to make it slightly faster in lower environments, but again the production database hangs indefinitely when this query is done.

The thing that is interesting to me is, in the lower environments, if I do this query with a user id that has >100,000 folder permission records, it is instantaneous..

----------------------------------------------------------------------------------------------------------------------------------
 Sort  (cost=24.49..24.50 rows=5 width=73) (actual time=4.286..4.289 rows=8 loops=1)
   Sort Key: (lower((f.name)::text))
   Sort Method: quicksort  Memory: 25kB
   ->  Nested Loop Left Join  (cost=10.22..24.43 rows=5 width=73) (actual time=3.810..3.997 rows=8 loops=1)
         Join Filter: (f.id = fp.folder_id)
         ->  Seq Scan on folders f  (cost=10.22..20.62 rows=5 width=520) (actual time=3.448..3.624 rows=8 loops=1)
               Filter: ((NOT deleted) AND ((NOT (hashed SubPlan 1)) OR (ancestry IS NULL)))
               Rows Removed by Filter: 14
               SubPlan 1
                 ->  Seq Scan on folders f2  (cost=0.00..10.20 rows=10 width=4) (actual time=0.008..0.018 rows=22 loops=1)
                       Filter: (NOT deleted)
         ->  Materialize  (cost=0.00..3.72 rows=1 width=37) (actual time=0.015..0.015 rows=0 loops=8)
               ->  Seq Scan on folder_permissions fp  (cost=0.00..3.71 rows=1 width=37) (actual time=0.120..0.120 rows=0 loops=1)
                     Filter: (user_id = 12345)
                     Rows Removed by Filter: 175
 Planning Time: 2.346 ms
 Execution Time: 5.266 ms
(17 rows)

In the production environment, trying it with a user who has only 8,000 folder permission records, it hangs indefinitely... I've left explain analyze running for 8+ hours and I never see the output...

Both lower and higher environments have the same indices, and I have tried rebuilding them.

*** UPDATE ***

As requested, here is the explain on the hanging machine:

=> explain SELECT fp.*, admin_folders.id AS folder_id FROM folder_permissions fp RIGHT OUTER JOIN (SELECT f.* FROM folders f WHERE f.deleted = FALSE AND ((SUBSTRING(f.ancestry FROM '([^/]*)$')::integer NOT IN (SELECT f2.id FROM folders f2 WHERE deleted = FALSE)) OR (f.ancestry IS NULL))) admin_folders ON admin_folders.id = fp.folder_id AND fp.user_id = 12345 ORDER BY lower(admin_folders.name);
                                                               QUERY PLAN
-----------------------------------------------------------------------------------------------------------------------------------------
 Gather Merge  (cost=332160509.79..332167328.27 rows=58440 width=73)
   Workers Planned: 2
   ->  Sort  (cost=332159509.77..332159582.82 rows=29220 width=73)
         Sort Key: (lower((f.name)::text))
         ->  Merge Left Join  (cost=17496.11..332157342.42 rows=29220 width=73)
               Merge Cond: (f.id = fp.folder_id)
               ->  Parallel Index Scan using index_folder_id_on_undeleted_v2 on folders f  (cost=0.42..332139670.56 rows=29220 width=20)
                     Filter: ((NOT (SubPlan 1)) OR (ancestry IS NULL))
                     SubPlan 1
                       ->  Materialize  (cost=0.00..11018.00 rows=140223 width=4)
                             ->  Seq Scan on folders f2  (cost=0.00..9768.88 rows=140223 width=4)
                                   Filter: (NOT deleted)
               ->  Sort  (cost=17495.69..17507.71 rows=4807 width=37)
                     Sort Key: fp.folder_id
                     ->  Bitmap Heap Scan on folder_permissions fp  (cost=93.82..17201.72 rows=4807 width=37)
                           Recheck Cond: (user_id = 12345)
                           ->  Bitmap Index Scan on index_folder_permissions_on_user_id  (cost=0.00..92.62 rows=4807 width=0)
                                 Index Cond: (user_id = 12345)
(18 rows)

And explain analyze on the query WITHOUT the NOT IN part:

                                                                                      QUERY PLAN
---------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------
 Sort  (cost=410.76..410.84 rows=33 width=73) (actual time=12.446..12.483 rows=43 loops=1)
   Sort Key: (lower((f.name)::text))
   Sort Method: quicksort  Memory: 28kB
   ->  Nested Loop Left Join  (cost=5.11..409.92 rows=33 width=73) (actual time=0.417..12.314 rows=43 loops=1)
         ->  Bitmap Heap Scan on folders f  (cost=4.68..130.41 rows=33 width=20) (actual time=0.392..1.518 rows=43 loops=1)
               Recheck Cond: ((ancestry IS NULL) AND (NOT deleted))
               Heap Blocks: exact=43
               ->  Bitmap Index Scan on index_folders_on_ancestry_and_not_deleted  (cost=0.00..4.67 rows=33 width=0) (actual time=0.220..0.221 rows=1620 loops=1)
                     Index Cond: (ancestry IS NULL)
         ->  Index Scan using index_folder_permissions_on_folder_id_and_user_id on folder_permissions fp  (cost=0.44..8.46 rows=1 width=37) (actual time=0.246..0.246 rows=0 loops=43)
               Index Cond: ((folder_id = f.id) AND (user_id = 12345))
 Planning Time: 0.464 ms
 Execution Time: 12.581 ms
(13 rows)

And the same thing on the non-hanging machine:

                                                                                      QUERY PLAN
---------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------
 Sort  (cost=556.42..556.53 rows=45 width=73) (actual time=0.685..0.726 rows=49 loops=1)
   Sort Key: (lower((f.name)::text))
   Sort Method: quicksort  Memory: 29kB
   ->  Nested Loop Left Join  (cost=5.20..555.19 rows=45 width=73) (actual time=0.045..0.589 rows=49 loops=1)
         ->  Bitmap Heap Scan on folders f  (cost=4.77..174.15 rows=45 width=17) (actual time=0.025..0.178 rows=49 loops=1)
               Recheck Cond: ((ancestry IS NULL) AND (NOT deleted))
               Heap Blocks: exact=45
               ->  Bitmap Index Scan on index_folders_on_ancestry_and_not_deleted  (cost=0.00..4.76 rows=45 width=0) (actual time=0.014..0.015 rows=51 loops=1)
                     Index Cond: (ancestry IS NULL)
         ->  Index Scan using index_folder_permissions_on_folder_id_and_user_id on folder_permissions fp  (cost=0.43..8.46 rows=1 width=37) (actual time=0.004..0.005 rows=0 loops=49)
               Index Cond: ((folder_id = f.id) AND (user_id = 12345))
 Planning Time: 0.404 ms
 Execution Time: 0.845 ms
(13 rows)

and lastly, explain on the part of the query that causes the hanging:

compass=> explain SELECT f.* FROM folders f WHERE f.deleted = FALSE AND ((SUBSTRING(f.ancestry FROM '([^/]*)$')::integer NOT IN (SELECT f2.id FROM folders f2 WHERE deleted = FALSE)) OR (f.ancestry IS NULL));
                                                 QUERY PLAN
------------------------------------------------------------------------------------------------------------
 Gather  (cost=3547.07..332130118.64 rows=70128 width=486)
   Workers Planned: 2
   ->  Parallel Bitmap Heap Scan on folders f  (cost=2547.07..332122105.84 rows=29220 width=486)
         Recheck Cond: (NOT deleted)
         Filter: ((NOT (SubPlan 1)) OR (ancestry IS NULL))
         ->  Bitmap Index Scan on index_folder_id_on_undeleted_v2  (cost=0.00..2529.53 rows=140223 width=0)
         SubPlan 1
           ->  Materialize  (cost=0.00..11018.00 rows=140223 width=4)
                 ->  Seq Scan on folders f2  (cost=0.00..9768.88 rows=140223 width=4)
                       Filter: (NOT deleted)
(10 rows)
8
  • What is a "lower" and "higher" environment? It seems like this doesn't pertain to the row counts, so what does it describe?
    – jjanes
    Oct 7, 2023 at 3:12
  • 1
    lower means non-production.. a snapshot of the production database from a while back. higher = production.
    – patrick
    Oct 7, 2023 at 23:05
  • If you have lots of NOT deleted folders, that query is likely to take forever. Oct 8, 2023 at 4:35
  • 1
    Show a simple EXPLAIN for the one where the EXPLAIN ANALYZE hangs. Also show EXPLAIN ANALYZE for each of those subqueries run without it's containing query, on the hanging machine.
    – jjanes
    Oct 8, 2023 at 12:44
  • @jjanes I have updated my question with what you asked for.
    – patrick
    Oct 9, 2023 at 2:15

2 Answers 2

1

The devastating difference is between NOT (hashed SubPlan 1) and NOT (SubPlan 1) which is driven by the difference in estimation between 10 rows (actual: 22) and 140223 row (actual: unknown). It makes the switch because your work_mem is not large enough to accommodate a hash table of the expected count of 140223 values.

This suggests your work_mem is quite low, as it doesn't take very much memory to accommodate a hash table of that size. So while there may be other ways to address this, a simple thing would be to increase work_mem, which should probably be done anyway if you are running queries like this.

Also, you should probably recreate your test environment, as 22 vs 140223 is a massive difference in row count estimation. There are likely to be all kinds of plan differences between the systems.

2
  • wow, you are right.. the prod db had that set to 8MB, and it was 64mb in non-prod. I changed 8 to 64 and that no longer hangs. thanks!!
    – patrick
    Oct 9, 2023 at 20:50
  • Great! I keep learning. Oct 19, 2023 at 6:14
0

The subquery in the right join:

SELECT f.*
FROM folders f
WHERE f.deleted = FALSE
  AND ((SUBSTRING(f.ancestry FROM '([^/]*)$')::integer
        NOT IN (SELECT f2.id FROM folders f2 WHERE deleted = FALSE)
       )
       OR (f.ancestry IS NULL)
      )

had better be written as

SELECT f.id, f.name
FROM folders f
WHERE NOT f.deleted
  AND NOT EXISTS (SELECT 1 FROM folders f2 
                  WHERE NOT deleted
                    AND SUBSTRING(f.ancestry FROM '([^/]*)$')::integer = f2.id)
UNION ALL
SELECT f.id, f.name
FROM folders f
WHERE NOT f.deleted
  AND f.ancestry IS NULL

I find it difficult to recommend indexes; perhaps if I see EXPLAIN (ANALYZE, BUFFERS) for the improved subquery.

5
  • The 2nd version of that queries returns different results...
    – patrick
    Oct 9, 2023 at 18:20
  • It returns only the required columns. Other than that, it should return the same rows if id is the primary key of folders. Care to elaborate on the differences? Oct 9, 2023 at 19:08
  • no, in my tests, one query returns 50 results, your modified version returns 99 results.
    – patrick
    Oct 9, 2023 at 20:42
  • Then I either made a mistake, or folders.id is not the primary key. Well, looks like we will never figure it out, since there are no test data. A pity, since my version would probably be faster. Oct 10, 2023 at 5:34
  • just was looking at this query again.. It appears the problem is your version contains duplicates, according to postgres docs regarding UNION: "Furthermore, it eliminates duplicate rows from its result, in the same way as DISTINCT, unless UNION ALL is used." .. and this query has UNION ALL ... I changed that to UNION and it seems to have the same result set now.
    – patrick
    Oct 18, 2023 at 21:38

Your Answer

By clicking “Post Your Answer”, you agree to our terms of service and acknowledge you have read our privacy policy.

Not the answer you're looking for? Browse other questions tagged or ask your own question.