Re: Weird behavior of INSERT QUERY

Forgot to mention. If I cancel the long running insert statement from
schema1_u user query before completion, I see the below. Not sure if this
will help but just thought to mention it.

CONTEXT: SQL statement "SELECT 1 FROM ONLY "schema1"."table_b" x WHERE
"id" OPERATOR(pg_catalog.=) $1 FOR KEY SHARE OF x"
Regards,

Satalabha

On Sun, 4 Jun 2023 at 14:04, Satalabaha Postgres <
satalabaha(dot)postgres(at)gmail(dot)com> wrote:

> Hi Listers,
>
> DB : postgres 14.
>
> We are experiencing weird performance issue of one simple insert statement
> taking several minutes to insert data. The application calls insert
> statement via stored procedure show mentioned below.
>
> The select query in the insert returns about 499 rows. However, this
> insert statement when executed from application user i.e. schema1_u takes
> close to 8 minutes. When the same insert statement gets executed as
> postgres user it takes less than 280 ms. Both the executions use the same
> execution plan with only difference that when schema1_u executes the SQL,
> we observe "Trigger for constraint fk_con_tablea: time=426499.314
> calls=499" taking more time. Both the parent and child tables are not big
> in size. There is no table bloat etc for both of these tables. Below are
> the details.
> Is there any way we can identify why as postgres user the insert statement
> works fine and why not with application user schema1_u?
>
> Stored Procedure:
> ====================
>
> CREATE OR REPLACE FUNCTION schema1.ins_staging_fn(parfileid double
> precision, parcreatedby text)
> RETURNS void
> LANGUAGE plpgsql
> AS $function$
> BEGIN
> insert into table_a
> (
> ROWVERSION,
> CREATED,
> ISDELETED,
> ISIGNORED,
> IMPORTEDACCOUNTCODE,
> IMPORTEDUNITCODE,
> BEGINNINGBALANCE,
> ENDINGBALANCE,
> CREATEDBY,
> FILEID
> )
> select to_timestamp(To_char(clock_timestamp(),'DD-MON-YY
> HH.MI.SS.FF4 AM'),'DD-MON-YY HH.MI.SS.FF4 AM'),
> to_timestamp(To_char(clock_timestamp() at time zone
> 'utc', 'DD-MON-YY HH.MI.SS.MS AM'),'DD-MON-YY HH.MI.SS.FF4 AM'),
> false,
> false,
> IMPORTEDACCOUNTCODE,
> IMPORTEDUNITCODE,
> BEGINNINGBALANCE,
> ENDINGBALANCE,
> parCreatedBy,
> FILEID
> from STAGING_table_a
> where FILEID = parFileId;
>
> END;
> $function$
> ;
>
>
>
> Count of tables:
> =================
>
> select count(*) from schema1.table_a;
> count
> -------
> 67019
>
> select count(*) from schema1.table_b;
> count
> -------
> 20
>
>
>
> create trigger table_a_trigger before
> insert
> on
> schema1.table_a for each row execute function
> schema1."table_a_trigger$table_a"();
>
>
>
> CREATE OR REPLACE FUNCTION schema1."table_a_trigger$table_a"()
> RETURNS trigger
> LANGUAGE plpgsql
> AS $function$
> BEGIN
> IF COALESCE(new.id, - 1) = - 1 THEN
> SELECT
> nextval('table_a_sq')
> INTO STRICT new.id;
> END IF;
> RETURN NEW;
> END;
> $function$;
>
> ALTER TABLE schema1.table_a ADD CONSTRAINT fk_con_tablea FOREIGN KEY
> (fileid) REFERENCES schema1.table_b(id);
>
>
>
> POSTGRES QUERY PLAN
>
> --------------------------------------------------------------------------------------------------------------------------------------------------
> Insert on table_a (cost=0.00..431.80 rows=0 width=0) (actual
> time=35.806..35.807 rows=0 loops=1)
> Buffers: shared hit=9266 written=19
> -> Subquery Scan on "*SELECT*" (cost=0.00..431.80 rows=499 width=771)
> (actual time=0.427..5.654 rows=499 loops=1)
> Buffers: shared hit=162
> -> Seq Scan on staging_table_a (cost=0.00..414.33 rows=499
> width=83) (actual time=0.416..4.286 rows=499 loops=1)
> Filter: (fileid = 37)
> Rows Removed by Filter: 18989
> Buffers: shared hit=162
> Settings: effective_cache_size = '266500832kB',
> maintenance_io_concurrency = '1', max_parallel_workers = '24', search_path
> = 'schema1, public'
> Planning Time: 0.092 ms
> Trigger for constraint fk_con_tablea: time=6.304 calls=499
> Trigger table_a_trigger: time=5.658 calls=499
> Execution Time: 42.206 ms
> (13 rows)
>
>
>
> schema1_U QUERY PLAN
>
> --------------------------------------------------------------------------------------------------------------------------------------------------
> Insert on table_a (cost=0.00..431.80 rows=0 width=0) (actual
> time=34.806..34.806 rows=0 loops=1)
> Buffers: shared hit=9247 written=9
> -> Subquery Scan on "*SELECT*" (cost=0.00..431.80 rows=499 width=771)
> (actual time=0.427..5.372 rows=499 loops=1)
> Buffers: shared hit=162
> -> Seq Scan on staging_table_a (cost=0.00..414.33 rows=499
> width=83) (actual time=0.416..4.159 rows=499 loops=1)
> Filter: (fileid = 37)
> Rows Removed by Filter: 18989
> Buffers: shared hit=162
> Settings: effective_cache_size = '266500832kB',
> maintenance_io_concurrency = '1', max_parallel_workers = '24', search_path
> = 'schema1, public'
> Planning Time: 0.092 ms
> Trigger for constraint fk_con_tablea: time=426499.314 calls=499
> <<<<<<<<<<<<<<<<<<<<<<<<<<<<<< Issue
> Trigger table_a_trigger: time=5.712 calls=499
> Execution Time: 426534.633 ms
> (13 rows)
>
> Regards,
>
> Satalabha
>