PostgREST: Requests to volatile RPC with a single json parameter and which fires multiple triggers taking a very long time to complete - Solved

Question

I am experiencing major performance issues when calling a stored procedure via PostgREST compared when calling it via psql. Both methods complete successfully, but the PostgREST takes ~1 min compared to 2 seconds with psql. There are many statement levels and a few row-level triggers fired as a result of this procedure.

This procedure updates the database, another update procedure has the same issues,

Calling from psql:

set role myrole;
start transaction;

WITH pgrst_source AS (WITH pgrst_args AS (SELECT NULL) SELECT "api"."docket_creation"('{"dockets":[{"docket":{},"transactions":[{"transaction":{"batch_id":null,"best_before_date":null,"docket_id":1417,"minimum_price":1.5,"note":"","price":3,"product_code":"TL12","product_cost":1,"product_description":"","product_group_id":null,"product_id":217,"product_name":"12 Tray Large","quantity":1,"vat_rate_id":4,"vat_rate_percentage":0,"return_reason_id":null,"transaction_type_id":2},"transaction_discounts":[{"discount_percentage":5,"discount_type_id":10,"discount_value_per_unit":null,"minimum_quantity":null,"note":""}],"transaction_returns":[],"transaction_commissions":[{"commission_id":null,"commission_percentage":0,"commission_type_id":2,"customer_id":1,"delivery_agent_id":0,"effective_from":null,"effective_to":null,"is_cumulative":true,"owner":2,"product_id":217}]}],"docket_buy_x_get_y_discounts":[]}]}'::json) AS pgrst_scalar)
  
  SELECT
    null::bigint AS total_result_set,
    pg_catalog.count(_postgrest_t) AS page_total,
    (json_agg(_postgrest_t.pgrst_scalar)->0)::character varying AS body,
    coalesce(nullif(current_setting('response.headers', true), ''), '[]') AS response_headers
  FROM (SELECT "pgrst_source".* FROM "pgrst_source"    ) _postgrest_t;

Or simply:

 SELECT "api"."docket_creation"('{"dockets":[{"docket":{},"transactions":[{"transaction":{"batch_id":null,"best_before_date":null,"docket_id":1417,"minimum_price":1.5,"note":"","price":3,"product_code":"TL12","product_cost":1,"product_description":"","product_group_id":null,"product_id":217,"product_name":"12 Tray Large","quantity":1,"vat_rate_id":4,"vat_rate_percentage":0,"return_reason_id":null,"transaction_type_id":2},"transaction_discounts":[{"discount_percentage":5,"discount_type_id":10,"discount_value_per_unit":null,"minimum_quantity":null,"note":""}],"transaction_returns":[],"transaction_commissions":[{"commission_id":null,"commission_percentage":0,"commission_type_id":2,"customer_id":1,"delivery_agent_id":0,"effective_from":null,"effective_to":null,"is_cumulative":true,"owner":2,"product_id":217}]}],"docket_buy_x_get_y_discounts":[]}]}')

This takes about 2 secs.

When calling from a webapp or via curl with the call

curl 'https://<server>/hhdb_api/rpc/docket_creation' \
   -X 'POST' \
   -H 'Connection: keep-alive' \
   -H 'sec-ch-ua: " Not A;Brand";v="99", "Chromium";v="90", "Google Chrome";v="90"' \
   -H 'Prefer: params=single-object' \
   -H 'sec-ch-ua-mobile: ?0' \
   -H 'Authorization: Bearer $bearer_token' \
   -H 'Content-Type: application/json' \
   -H 'Accept: application/json, text/plain, */*' \
   -H 'User-Agent: Mozilla/5.0 (Windows NT 10.0; Win64; x64) AppleWebKit/537.36 (KHTML, like Gecko) Chrome/90.0.4430.85 Safari/537.36' \
   -H 'DNT: 1' \
   -H 'Origin: https://hh-tincan-dev.srv.handheld.ie' \
   -H 'Sec-Fetch-Site: same-site' \
   -H 'Sec-Fetch-Mode: cors' \
   -H 'Sec-Fetch-Dest: empty' \
   -H 'Referer: https://hh-tincan-dev.srv.handheld.ie/' \
   -H 'Accept-Language: en-GB,en-US;q=0.9,en;q=0.8' \
   --data-raw '{"dockets":[{"docket":{},"transactions":[{"transaction":{"batch_id":null,"best_before_date":null,"docket_id":1428,"minimum_price":1.5,"note":"","price":3,"product_code":"TL12","product_cost":1,"product_description":"","product_group_id":null,"product_id":217,"product_name":"12 Tray Large","quantity":1,"vat_rate_id":4,"vat_rate_percentage":0,"return_reason_id":null,"transaction_type_id":2},"transaction_discounts":[{"discount_percentage":5,"discount_type_id":10,"discount_value_per_unit":null,"minimum_quantity":null,"note":""}],"transaction_returns":[],"transaction_commissions":[{"commission_id":null,"commission_percentage":0,"commission_type_id":2,"customer_id":1,"delivery_agent_id":0,"effective_from":null,"effective_to":null,"is_cumulative":true,"owner":2,"product_id":217}]}],"docket_buy_x_get_y_discounts":[]}]}' \
   --compressed

This will take over a minute.

I would expect both of these invocations to take a similar time.

I have enabled extensive logging to try to track this down the difference between the two methods seems to be the delays when entering a nested trigger ~

I have raised this as an issue on the PostgREST's GitHub with some configuration details:

https://github.com/PostgREST/postgrest/issues/1836

This issue is now solved please refer to the PostgREST github issue for details