I'm using Hasura v1.3.1 to query and populate a grid on my website. I'm experience an issue where the same query executed on Hasura Production (Heroku Standard 2x dyno) times out after 30 seconds but the same query executed on Hasura Staging (Heroku Standard dyno) is lightning fast. Both Heroku instances of Hasura are connecting to different Heroku Postgres 13.4 instances both on a Standard dyno.
Here is the query itself:
query collections($submissionRecordId: bigint!) {
collections_submissions_by_pk(id: $submissionRecordId) {
collections(where: {status: {_neq: "deleted"}}) {
id
debtor_number
invoice_number
invoice_date
invoice_amount
verification_alerts(where: {verifiable_record_type: {_eq: "Collection"}}) {
verification_types {
name
message
}
}
}
}
}
On first pass the slowness seemed to be related to table/role permissions since the verification_alerts and verification_types tables have some deeply nested permission filters. If I remove the most deeply nested part of the query and replace it with just the id the query becomes fast again on production. e.g.
query collections($submissionRecordId: bigint!) {
collections_submissions_by_pk(id: $submissionRecordId) {
collections(where: {status: {_neq: "deleted"}}) {
id
debtor_number
invoice_number
invoice_date
invoice_amount
verification_alerts(where: {verifiable_record_type: {_eq: "Collection"}}) {
verification_type_id
}
}
}
}
This led me to believe that it was a table role permissions issue. I thought perhaps permission checks were growing exponentially because of the nested queries and thus slowing things down. To check this I turn off permission filtering on the table and the query was lightning fast on production the way I expected it to be. So I must have found the problem... I thought.
To double check I did a full backup and restore from production to my staging postgres database on heroku (standard dyno) and ran the same query with identical permission filters enabled as are on production. The query should have timed out if I had indeed found the problem. Nope, it was lightning fast and running on a less powerful hasura dyno (standard vs standard 2x).
The next thing I thought was that my production database must have a lot more bloat than my staging database. This was indeed the case so I went and performed a VACUUM FULL on production bringing the bloat down to levels that compared closely with staging. However, the query still timed out on Production when I turned the table permission filters back on.
I just cannot explain what could possibly be different on my production environment that would make the query take longer than 30 seconds when the same DB and same hasura table metadata on staging is lightning fast. I'm desperate for someone smarter than me to take a crack at this problem.
Even though I have a temporary solution, disable permission filtering in prod, that does not satisfy my need to know why this is happening.
Some further information for those willing to help me can be found below.
Here is the SQL that the query generates in production:
SELECT
coalesce((json_agg("root") -> 0), 'null') AS "root"
FROM
(
SELECT
row_to_json(
(
SELECT
"_12_e"
FROM
(
SELECT
"_11_root.ar.root.collections"."collections" AS "collections"
) AS "_12_e"
)
) AS "root"
FROM
(
SELECT
*
FROM
"public"."collections_submissions"
WHERE
(
("public"."collections_submissions"."id") = (('23453') :: bigint)
)
) AS "_0_root.base"
LEFT OUTER JOIN LATERAL (
SELECT
coalesce(json_agg("collections"), '[]') AS "collections"
FROM
(
SELECT
row_to_json(
(
SELECT
"_9_e"
FROM
(
SELECT
"_1_root.ar.root.collections.base"."id" AS "id",
"_1_root.ar.root.collections.base"."debtor_number" AS "debtor_number",
"_1_root.ar.root.collections.base"."invoice_number" AS "invoice_number",
"_1_root.ar.root.collections.base"."invoice_date" AS "invoice_date",
"_1_root.ar.root.collections.base"."invoice_amount" AS "invoice_amount",
"_8_root.ar.root.collections.ar.collections.verification_alerts"."verification_alerts" AS "verification_alerts"
) AS "_9_e"
)
) AS "collections"
FROM
(
SELECT
*
FROM
"public"."collections"
WHERE
(
(
("_0_root.base"."id") = ("collections_submission_id")
)
AND (
("public"."collections"."status") <> (('deleted') :: text)
)
)
) AS "_1_root.ar.root.collections.base"
LEFT OUTER JOIN LATERAL (
SELECT
coalesce(json_agg("verification_alerts"), '[]') AS "verification_alerts"
FROM
(
SELECT
row_to_json(
(
SELECT
"_6_e"
FROM
(
SELECT
"_5_root.ar.root.collections.ar.collections.verification_alerts.or.verification_types"."verification_types" AS "verification_types"
) AS "_6_e"
)
) AS "verification_alerts"
FROM
(
SELECT
*
FROM
"public"."verification_alerts"
WHERE
(
(
("_1_root.ar.root.collections.base"."id") = ("verifiable_record_id")
)
AND (
(
"public"."verification_alerts"."verifiable_record_type"
) = (('Collection') :: text)
)
)
) AS "_2_root.ar.root.collections.ar.collections.verification_alerts.base"
LEFT OUTER JOIN LATERAL (
SELECT
row_to_json(
(
SELECT
"_4_e"
FROM
(
SELECT
"_3_root.ar.root.collections.ar.collections.verification_alerts.or.verification_types.base"."name" AS "name",
"_3_root.ar.root.collections.ar.collections.verification_alerts.or.verification_types.base"."message" AS "message"
) AS "_4_e"
)
) AS "verification_types"
FROM
(
SELECT
*
FROM
"public"."verification_types"
WHERE
(
(
"_2_root.ar.root.collections.ar.collections.verification_alerts.base"."verification_type_id"
) = ("id")
)
) AS "_3_root.ar.root.collections.ar.collections.verification_alerts.or.verification_types.base"
) AS "_5_root.ar.root.collections.ar.collections.verification_alerts.or.verification_types" ON ('true')
) AS "_7_root.ar.root.collections.ar.collections.verification_alerts"
) AS "_8_root.ar.root.collections.ar.collections.verification_alerts" ON ('true')
) AS "_10_root.ar.root.collections"
) AS "_11_root.ar.root.collections" ON ('true')
) AS "_13_root"
Here is the execution plan for the query on production:
Aggregate (cost=504.36..504.36 rows=1 width=32)
-> Nested Loop Left Join (cost=500.34..504.35 rows=1 width=32)
-> Index Only Scan using collections_submissions_pkey on collections_submissions (cost=0.06..4.06 rows=1 width=8)
Index Cond: (id = '23453'::bigint)
-> Aggregate (cost=500.28..500.29 rows=1 width=32)
-> Nested Loop Left Join (cost=5.23..499.97 rows=78 width=64)
-> Index Scan using index_collections_on_collections_submission_id on collections (cost=0.08..98.15 rows=78 width=32)
Index Cond: (collections_submissions.id = collections_submission_id)
Filter: ((status)::text <> 'deleted'::text)
-> Aggregate (cost=5.14..5.15 rows=1 width=32)
-> Nested Loop Left Join (cost=0.08..5.14 rows=1 width=32)
Join Filter: (verification_alerts.verification_type_id = verification_types.id)
-> Index Only Scan using index_all_verification_alerts_fields_unique on verification_alerts (cost=0.08..4.09 rows=1 width=8)
Index Cond: ((verifiable_record_id = collections.id) AND (verifiable_record_type = 'Collection'::text))
-> Seq Scan on verification_types (cost=0.00..1.03 rows=5 width=40)
SubPlan 3
-> Result (cost=0.00..0.00 rows=1 width=32)
SubPlan 4
-> Result (cost=0.00..0.00 rows=1 width=32)
SubPlan 2
-> Result (cost=0.00..0.00 rows=1 width=32)
SubPlan 1
-> Result (cost=0.00..0.00 rows=1 width=32)
Here is the SQL query generated on staging:
SELECT
coalesce((json_agg("root") -> 0), 'null') AS "root"
FROM
(
SELECT
row_to_json(
(
SELECT
"_12_e"
FROM
(
SELECT
"_11_root.ar.root.collections"."collections" AS "collections"
) AS "_12_e"
)
) AS "root"
FROM
(
SELECT
*
FROM
"public"."collections_submissions"
WHERE
(
("public"."collections_submissions"."id") = (('23453') :: bigint)
)
) AS "_0_root.base"
LEFT OUTER JOIN LATERAL (
SELECT
coalesce(json_agg("collections"), '[]') AS "collections"
FROM
(
SELECT
row_to_json(
(
SELECT
"_9_e"
FROM
(
SELECT
"_1_root.ar.root.collections.base"."id" AS "id",
"_1_root.ar.root.collections.base"."debtor_number" AS "debtor_number",
"_1_root.ar.root.collections.base"."invoice_number" AS "invoice_number",
"_1_root.ar.root.collections.base"."invoice_date" AS "invoice_date",
"_1_root.ar.root.collections.base"."invoice_amount" AS "invoice_amount",
"_8_root.ar.root.collections.ar.collections.verification_alerts"."verification_alerts" AS "verification_alerts"
) AS "_9_e"
)
) AS "collections"
FROM
(
SELECT
*
FROM
"public"."collections"
WHERE
(
(
("_0_root.base"."id") = ("collections_submission_id")
)
AND (
("public"."collections"."status") <> (('deleted') :: text)
)
)
) AS "_1_root.ar.root.collections.base"
LEFT OUTER JOIN LATERAL (
SELECT
coalesce(json_agg("verification_alerts"), '[]') AS "verification_alerts"
FROM
(
SELECT
row_to_json(
(
SELECT
"_6_e"
FROM
(
SELECT
"_5_root.ar.root.collections.ar.collections.verification_alerts.or.verification_types"."verification_types" AS "verification_types"
) AS "_6_e"
)
) AS "verification_alerts"
FROM
(
SELECT
*
FROM
"public"."verification_alerts"
WHERE
(
(
("_1_root.ar.root.collections.base"."id") = ("verifiable_record_id")
)
AND (
(
"public"."verification_alerts"."verifiable_record_type"
) = (('Collection') :: text)
)
)
) AS "_2_root.ar.root.collections.ar.collections.verification_alerts.base"
LEFT OUTER JOIN LATERAL (
SELECT
row_to_json(
(
SELECT
"_4_e"
FROM
(
SELECT
"_3_root.ar.root.collections.ar.collections.verification_alerts.or.verification_types.base"."name" AS "name",
"_3_root.ar.root.collections.ar.collections.verification_alerts.or.verification_types.base"."message" AS "message"
) AS "_4_e"
)
) AS "verification_types"
FROM
(
SELECT
*
FROM
"public"."verification_types"
WHERE
(
(
"_2_root.ar.root.collections.ar.collections.verification_alerts.base"."verification_type_id"
) = ("id")
)
) AS "_3_root.ar.root.collections.ar.collections.verification_alerts.or.verification_types.base"
) AS "_5_root.ar.root.collections.ar.collections.verification_alerts.or.verification_types" ON ('true')
) AS "_7_root.ar.root.collections.ar.collections.verification_alerts"
) AS "_8_root.ar.root.collections.ar.collections.verification_alerts" ON ('true')
) AS "_10_root.ar.root.collections"
) AS "_11_root.ar.root.collections" ON ('true')
) AS "_13_root"
Here is the execution plan from staging:
Aggregate (cost=450.33..450.34 rows=1 width=32)
-> Nested Loop Left Join (cost=448.32..450.33 rows=1 width=32)
-> Index Only Scan using collections_submissions_pkey on collections_submissions (cost=0.06..2.06 rows=1 width=8)
Index Cond: (id = '23453'::bigint)
-> Aggregate (cost=448.26..448.26 rows=1 width=32)
-> Nested Loop Left Join (cost=5.20..447.98 rows=70 width=64)
-> Index Scan using index_collections_on_collections_submission_id on collections (cost=0.08..89.12 rows=70 width=32)
Index Cond: (collections_submission_id = collections_submissions.id)
Filter: ((status)::text <> 'deleted'::text)
-> Aggregate (cost=5.12..5.12 rows=1 width=32)
-> Nested Loop Left Join (cost=0.06..5.11 rows=1 width=32)
Join Filter: (verification_alerts.verification_type_id = verification_types.id)
-> Index Only Scan using index_all_verification_alerts_fields_unique on verification_alerts (cost=0.06..4.06 rows=1 width=8)
Index Cond: ((verifiable_record_id = collections.id) AND (verifiable_record_type = 'Collection'::text))
-> Seq Scan on verification_types (cost=0.00..1.03 rows=5 width=40)
SubPlan 3
-> Result (cost=0.00..0.00 rows=1 width=32)
SubPlan 4
-> Result (cost=0.00..0.00 rows=1 width=32)
SubPlan 2
-> Result (cost=0.00..0.00 rows=1 width=32)
SubPlan 1
-> Result (cost=0.00..0.00 rows=1 width=32)
The execution plan only differs by the values of 'cost' but not enough to be more than a 30 sec difference in run times I would think.
The SQL generated by the Hasura query is unsurprisingly identical.