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.