0

I'm trying to figure out what the problem is with my Database. I am running PostgreSQL on Azure - "Azure Database for PostgreSQL single server".

I run PostgreSQL 11.17.

I have integrated Postgraphile, which allows me to translate GraphQL into SQL queries. I also use Row Level Security on two gin indexed varchar array fields access_team_ids and access_territory_ids.

RLS logic is following: user's ID must be in access_team_ids, user has only one ID or one of multiple user's territory ids must be present in access_territory_ids column.

Row count is: 1792332 Row count after applying RLS is: 3067 Table size is: 2670 MB.

I have tried REINDEXing the DB, but without any success.

One of the graphql queries is extremely slow (~6s) even though it does not perform any special operations. The only thing it does is SELECTs the ids, LIMITs then output and applies OFFSET, output is a JSON. The SQL query is as follows:

explain(analyze, buffers)
WITH __local_0__ AS (
        SELECT to_json((json_build_object('@node'::TEXT, (json_build_object('__identifiers'::TEXT, json_build_array(__local_1__."id"), 'id'::TEXT, (__local_1__."id")))))) AS "@edges"
            ,to_json(json_build_array('id_asc', json_build_array(__local_1__."id"))) AS "__cursor"
        FROM (
            SELECT __local_1__.*
            FROM "public"."installed_base" AS __local_1__
            WHERE (TRUE)
                AND (TRUE)
            ORDER BY __local_1__."id" ASC limit 100 offset 0
            ) __local_1__
        )
    ,__local_2__ AS (
        SELECT json_agg(to_json(__local_0__)) AS data
        FROM __local_0__
        )

SELECT coalesce((
            SELECT __local_2__.data
            FROM __local_2__
            ), '[]'::json) AS "data"
    ,(
        SELECT json_build_object('totalCount'::TEXT, count(1))
        FROM "public"."installed_base" AS __local_1__
        WHERE 1 = 1
        ) AS "aggregates";

It produces following EXPLAIN output:

 Result  (cost=29759.86..29759.87 rows=1 width=64) (actual time=5695.451..5695.455 rows=1 loops=1)
   Buffers: shared hit=1092424 dirtied=23
   CTE __local_0__
     ->  Subquery Scan on __local_1__  (cost=0.43..1306.70 rows=100 width=64) (actual time=223.995..5691.564 rows=100 loops=1)
           Buffers: shared hit=1091589 dirtied=23
           ->  Limit  (cost=0.43..1303.95 rows=100 width=2126) (actual time=223.979..5691.187 rows=100 loops=1)
                 Buffers: shared hit=1091589 dirtied=23
                 ->  Index Scan using installed_base_id_uindex on installed_base __local_1___1  (cost=0.43..349278.45 rows=26795 width=2126) (actual time=223.978..5691.181 rows=100 loops=1)
                       Filter: ((access_team_ids @> ARRAY[(NULLIF(current_setting('jwt.claims.user_id'::text, true), ''::text))::character varying]) OR (access_territory_ids && (NULLIF(current_setting('jwt.claims.territory_ids'::text, true), '{}'::text))::character varying[]))
                       Rows Removed by Filter: 1115221
                       Buffers: shared hit=1091589 dirtied=23
   CTE __local_2__
     ->  Aggregate  (cost=2.50..2.51 rows=1 width=32) (actual time=5691.806..5691.807 rows=1 loops=1)
           Buffers: shared hit=1091589 dirtied=23
           ->  CTE Scan on __local_0__  (cost=0.00..2.00 rows=100 width=24) (actual time=224.004..5691.655 rows=100 loops=1)
                 Buffers: shared hit=1091589 dirtied=23
   InitPlan 3 (returns $2)
     ->  CTE Scan on __local_2__  (cost=0.00..0.02 rows=1 width=32) (actual time=5691.814..5691.814 rows=1 loops=1)
           Buffers: shared hit=1091589 dirtied=23
   InitPlan 4 (returns $3)
     ->  Aggregate  (cost=28450.61..28450.63 rows=1 width=32) (actual time=3.624..3.625 rows=1 loops=1)
           Buffers: shared hit=835
           ->  Bitmap Heap Scan on installed_base __local_1___2  (cost=301.95..28383.63 rows=26795 width=0) (actual time=2.479..3.491 rows=3067 loops=1)
                 Recheck Cond: ((access_team_ids @> ARRAY[(NULLIF(current_setting('jwt.claims.user_id'::text, true), ''::text))::character varying]) OR (access_territory_ids && (NULLIF(current_setting('jwt.claims.territory_ids'::text, true), '{}'::text))::character varying[]))
                 Heap Blocks: exact=2837
                 Buffers: shared hit=835
                 ->  BitmapOr  (cost=301.95..301.95 rows=26885 width=0) (actual time=2.169..2.170 rows=0 loops=1)
                       Buffers: shared hit=78
                       ->  Bitmap Index Scan on installed_base_access_team_ids_idx  (cost=0.00..103.52 rows=8962 width=0) (actual time=0.841..0.842 rows=3048 loops=1)
                             Index Cond: (access_team_ids @> ARRAY[(NULLIF(current_setting('jwt.claims.user_id'::text, true), ''::text))::character varying])
                             Buffers: shared hit=31
                       ->  Bitmap Index Scan on installed_base_access_territory_ids_idx  (cost=0.00..185.03 rows=17923 width=0) (actual time=1.327..1.327 rows=2872 loops=1)
                             Index Cond: (access_territory_ids && (NULLIF(current_setting('jwt.claims.territory_ids'::text, true), '{}'::text))::character varying[])
                             Buffers: shared hit=47
 Planning Time: 0.551 ms
 Execution Time: 5695.772 ms
(36 rows)

as you can see, Index Scan using installed_base_id_uindex on installed_base is the slowest operation.

However, if I just change the order by id" ASC to DESC it will execute the query much faster and will produce following output:

 Result  (cost=29759.86..29759.87 rows=1 width=64) (actual time=459.884..459.888 rows=1 loops=1)
   Buffers: shared hit=101140 dirtied=8
   CTE __local_0__
     ->  Subquery Scan on __local_1__  (cost=0.43..1306.70 rows=100 width=64) (actual time=8.464..455.861 rows=100 loops=1)
           Buffers: shared hit=100305 dirtied=8
           ->  Limit  (cost=0.43..1303.95 rows=100 width=2126) (actual time=8.450..455.324 rows=100 loops=1)
                 Buffers: shared hit=100305 dirtied=8
                 ->  Index Scan Backward using installed_base_id_uindex on installed_base __local_1___1  (cost=0.43..349278.45 rows=26795 width=2126) (actual time=8.449..455.312 rows=100 loops=1)
                       Filter: ((access_team_ids @> ARRAY[(NULLIF(current_setting('jwt.claims.user_id'::text, true), ''::text))::character varying]) OR (access_territory_ids && (NULLIF(current_setting('jwt.claims.territory_ids'::text, true), '{}'::text))::character varying[]))
                       Rows Removed by Filter: 106220
                       Buffers: shared hit=100305 dirtied=8
   CTE __local_2__
     ->  Aggregate  (cost=2.50..2.51 rows=1 width=32) (actual time=456.157..456.158 rows=1 loops=1)
           Buffers: shared hit=100305 dirtied=8
           ->  CTE Scan on __local_0__  (cost=0.00..2.00 rows=100 width=24) (actual time=8.470..455.961 rows=100 loops=1)
                 Buffers: shared hit=100305 dirtied=8
   InitPlan 3 (returns $2)
     ->  CTE Scan on __local_2__  (cost=0.00..0.02 rows=1 width=32) (actual time=456.178..456.178 rows=1 loops=1)
           Buffers: shared hit=100305 dirtied=8
   InitPlan 4 (returns $3)
     ->  Aggregate  (cost=28450.61..28450.63 rows=1 width=32) (actual time=3.695..3.696 rows=1 loops=1)
           Buffers: shared hit=835
           ->  Bitmap Heap Scan on installed_base __local_1___2  (cost=301.95..28383.63 rows=26795 width=0) (actual time=2.508..3.542 rows=3067 loops=1)
                 Recheck Cond: ((access_team_ids @> ARRAY[(NULLIF(current_setting('jwt.claims.user_id'::text, true), ''::text))::character varying]) OR (access_territory_ids && (NULLIF(current_setting('jwt.claims.territory_ids'::text, true), '{}'::text))::character varying[]))
                 Heap Blocks: exact=2837
                 Buffers: shared hit=835
                 ->  BitmapOr  (cost=301.95..301.95 rows=26885 width=0) (actual time=2.191..2.191 rows=0 loops=1)
                       Buffers: shared hit=78
                       ->  Bitmap Index Scan on installed_base_access_team_ids_idx  (cost=0.00..103.52 rows=8962 width=0) (actual time=0.813..0.813 rows=3048 loops=1)
                             Index Cond: (access_team_ids @> ARRAY[(NULLIF(current_setting('jwt.claims.user_id'::text, true), ''::text))::character varying])
                             Buffers: shared hit=31
                       ->  Bitmap Index Scan on installed_base_access_territory_ids_idx  (cost=0.00..185.03 rows=17923 width=0) (actual time=1.377..1.377 rows=2872 loops=1)
                             Index Cond: (access_territory_ids && (NULLIF(current_setting('jwt.claims.territory_ids'::text, true), '{}'::text))::character varying[])
                             Buffers: shared hit=47
 Planning Time: 0.338 ms
 Execution Time: 460.322 ms
(36 rows)

I've also found that if I use an offset at ~ 2400 rows, Postgres will start using a different sort method, resulting in a super fast query output:

 Result  (cost=58492.03..58492.04 rows=1 width=64) (actual time=18.588..18.592 rows=1 loops=1)
   Buffers: shared hit=3750
   CTE __local_0__
     ->  Subquery Scan on __local_1__  (cost=30035.87..30038.87 rows=100 width=64) (actual time=14.511..14.824 rows=100 loops=1)
           Buffers: shared hit=2915
           ->  Limit  (cost=30035.87..30036.12 rows=100 width=2126) (actual time=14.494..14.503 rows=100 loops=1)
                 Buffers: shared hit=2915
                 ->  Sort  (cost=30029.87..30096.86 rows=26795 width=2126) (actual time=14.389..14.453 rows=2500 loops=1)
                       Sort Key: __local_1___1.id
                       Sort Method: quicksort  Memory: 336kB
                       Buffers: shared hit=2915
                       ->  Bitmap Heap Scan on installed_base __local_1___1  (cost=301.95..28383.63 rows=26795 width=2126) (actual time=3.245..6.663 rows=3067 loops=1)
                             Recheck Cond: ((access_team_ids @> ARRAY[(NULLIF(current_setting('jwt.claims.user_id'::text, true), ''::text))::character varying]) OR (access_territory_ids && (NULLIF(current_setting('jwt.claims.territory_ids'::text, true), '{}'::text))::character varying[]))
                             Heap Blocks: exact=2837
                             Buffers: shared hit=2915
                             ->  BitmapOr  (cost=301.95..301.95 rows=26885 width=0) (actual time=2.835..2.835 rows=0 loops=1)
                                   Buffers: shared hit=78
                                   ->  Bitmap Index Scan on installed_base_access_team_ids_idx  (cost=0.00..103.52 rows=8962 width=0) (actual time=1.094..1.094 rows=3048 loops=1)
                                         Index Cond: (access_team_ids @> ARRAY[(NULLIF(current_setting('jwt.claims.user_id'::text, true), ''::text))::character varying])
                                         Buffers: shared hit=31
                                   ->  Bitmap Index Scan on installed_base_access_territory_ids_idx  (cost=0.00..185.03 rows=17923 width=0) (actual time=1.740..1.740 rows=2872 loops=1)
                                         Index Cond: (access_territory_ids && (NULLIF(current_setting('jwt.claims.territory_ids'::text, true), '{}'::text))::character varying[])
                                         Buffers: shared hit=47
   CTE __local_2__
     ->  Aggregate  (cost=2.50..2.51 rows=1 width=32) (actual time=14.980..14.981 rows=1 loops=1)
           Buffers: shared hit=2915
           ->  CTE Scan on __local_0__  (cost=0.00..2.00 rows=100 width=24) (actual time=14.517..14.869 rows=100 loops=1)
                 Buffers: shared hit=2915
   InitPlan 3 (returns $2)
     ->  CTE Scan on __local_2__  (cost=0.00..0.02 rows=1 width=32) (actual time=14.986..14.987 rows=1 loops=1)
           Buffers: shared hit=2915
   InitPlan 4 (returns $3)
     ->  Aggregate  (cost=28450.61..28450.63 rows=1 width=32) (actual time=3.595..3.596 rows=1 loops=1)
           Buffers: shared hit=835
           ->  Bitmap Heap Scan on installed_base __local_1___2  (cost=301.95..28383.63 rows=26795 width=0) (actual time=2.465..3.457 rows=3067 loops=1)
                 Recheck Cond: ((access_team_ids @> ARRAY[(NULLIF(current_setting('jwt.claims.user_id'::text, true), ''::text))::character varying]) OR (access_territory_ids && (NULLIF(current_setting('jwt.claims.territory_ids'::text, true), '{}'::text))::character varying[]))
                 Heap Blocks: exact=2837
                 Buffers: shared hit=835
                 ->  BitmapOr  (cost=301.95..301.95 rows=26885 width=0) (actual time=2.156..2.157 rows=0 loops=1)
                       Buffers: shared hit=78
                       ->  Bitmap Index Scan on installed_base_access_team_ids_idx  (cost=0.00..103.52 rows=8962 width=0) (actual time=0.814..0.814 rows=3048 loops=1)
                             Index Cond: (access_team_ids @> ARRAY[(NULLIF(current_setting('jwt.claims.user_id'::text, true), ''::text))::character varying])
                             Buffers: shared hit=31
                       ->  Bitmap Index Scan on installed_base_access_territory_ids_idx  (cost=0.00..185.03 rows=17923 width=0) (actual time=1.341..1.342 rows=2872 loops=1)
                             Index Cond: (access_territory_ids && (NULLIF(current_setting('jwt.claims.territory_ids'::text, true), '{}'::text))::character varying[])
                             Buffers: shared hit=47
 Planning Time: 0.480 ms
 Execution Time: 19.151 ms
(48 rows)

What do I need to do to improve the speed of ASC ordering? I have set hard limit to 3.5 seconds for GraphQL query, 6 seconds is way too slow having in mind that DESC sorting is 0.5 second only.

--EDIT--

Table info is following:

Indexes:
    "PK_823e74f47715375057165d68471" PRIMARY KEY, btree (id)
    "installed_base_id_uidx" UNIQUE, btree (id)
    "installed_base_access_team_ids_idx" gin (access_team_ids)
    "installed_base_access_territory_ids_idx" gin (access_territory_ids)
Policies:
    POLICY "gql_access_policy"
      TO graphql
      USING (((access_team_ids @> current_team_ids()) OR (access_territory_ids && current_territory_ids())))

PS. I know that the installed_base_id_uidx index is redundant, but the execution time does not change without it. It was my first idea to add this index, but it didn't change anything.

Improve this question

1 Answer 1

Reset to default
1

Few of the old records (low id) satisfy the RLS conditions, so walking up the id index turns out to be slow as it needs to walk up it much farther than anticipated before finding 100 meeting the RLS. There is really nothing you can do about that bad estimate: there are no stats which will cause it to stop assuming that the rows meeting the RLS condition are not evenly distributed over id.

Since you probably can't drop the indexes over id, one thing you can do is rewrite the query so that it can't use that index for ordering. Assuming "id" is an int, that would be like this:

ORDER BY __local_1__."id" + 0 ASC limit 100 offset 0

The estimated number of rows which will meet the RLS condition is off by quite a bit (26795 vs 3067). It would be nice if that were better, but just making it better is unlikely to offer a robust solution to this problem. I can't tell if you have a stats problem with that, or if it is off just because the results of current_team_ids() and current_territory_ids() are unknown at planning time, so it has to use generic assumptions to do the estimation.

Improve this answer
6
  • I understand, the values returned from the current_team_ids() and current_territory_ids() functions are set prior to execution using SET LOCAL for the transaction. Both of these values are known before the query is executed. The body of the function is quite simple: create function current_team_ids() returns varchar[] as. $$ select ARRAY [nullif(current_setting('jwt.claims.user_id', true), '')::varchar]; $$ sql language stable;. For the case I posted, there is one user ID and 4 territories. Thank you for the explanation.
    – Lucassith
    Dec 28, 2022 at 18:15
  • Do I also understand correctly that the simplest and most result-oriented solution would be to increase the resources for the Postgres database? Unfortunatelly, ID field is an UUID.
    – Lucassith
    Dec 28, 2022 at 18:23
  • With an UUID, it should be as simple as ORDER BY id::text to defeat the unfortunate index usage.
    – jjanes
    Dec 28, 2022 at 19:52
  • Even though the param may be set at the time of the planning, the planner does not rely on that and can't use it. That the plan shows the expression, rather than the folded constant, signifies this. Which does explain why the estimates are off, as it doesn't plan with the knowledge of what specific values those are. If you were to change the function from stable to immutable, then it could use it for planning (in my testing) but this is a sketchy thing to do, as it is not really immutable.
    – jjanes
    Dec 28, 2022 at 20:09
  • I will try to go with IMMUTABLE. I tried increasing the cost of the function, but that didn't change anything and making the function IMMUTABLE actually improved a lot. I'm not sure how Postgres interprets immutable though - the values set in SET LOCAL are always set at the beggining of the DB connection, it never changes unless we do another request. I guess that this may be problematic but it actually produces very promising results. Thank you!
    – Lucassith
    Dec 29, 2022 at 8:58

Your Answer

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

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