Understand time taken by individual SQL statements in a procedure
Hi Listers, We would like to determine how long it takes for each SQL statement to execute within a long-running procedure. I tried to see if pg_stat_statements could offer any insight into the matter. But I was unable to locate any. Is this even possible? How can we also determine the precise SQL execution plan used when a SQL is run from an application? The query runs without issue when we try to execute it directly, but it takes longer to run when an application is used. Regards, Satalabha
Re: Understand time taken by individual SQL statements in a procedure
Thanks Julien. Regards, Satalabha On Sat, 3 Jun 2023 at 13:06, Julien Rouhaud wrote: > Hi, > > On Sat, Jun 03, 2023 at 12:48:37PM +0530, Satalabaha Postgres wrote: > > Hi Listers, > > > > We would like to determine how long it takes for each SQL statement to > > execute within a long-running procedure. I tried to see if > > pg_stat_statements could offer any insight into the matter. But I was > > unable to locate any. Is this even possible? > > pg_stat_statements can tell you about queries executed inside a procedure, > as > long as you set pg_stat_statements.track = 'all': > > rjuju=# select pg_stat_statements_reset(); > pg_stat_statements_reset > -- > > (1 row) > > rjuju=# set pg_stat_statements.track = 'all'; > SET > > rjuju=# do > $$ > begin > perform count(*) from pg_class; > perform pg_sleep(2); > end; > $$ language plpgsql; > DO > > rjuju=# select query, total_exec_time from pg_stat_statements; > query | total_exec_time > --+- > SELECT count(*) from pg_class| 0.139416999 > do +| 2001.903792 > $$ +| > begin +| > perform count(*) from pg_class; +| > perform pg_sleep(2);+| > end;+| > $$ language plpgsql | > SELECT pg_sleep($1) | 2000.227249 > [...] > > If that's not enough, and if your procedures are written in plpgsql you > could > also look at plpgsql_check: https://github.com/okbob/plpgsql_check. It > has an > integrated profiler (see https://github.com/okbob/plpgsql_check#profiler) > that > works very well. > > > unable to locate any. Is this even possible? How can we also determine > the > > precise SQL execution plan used when a SQL is run from an application? > The > > query runs without issue when we try to execute it directly, but it takes > > longer to run when an application is used. > > You could look at auto_explain for that: > https://www.postgresql.org/docs/current/auto-explain.html. >
Weird behavior of INSERT QUERY
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
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 < [email protected]> 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 T
Re: Weird behavior of INSERT QUERY
Hi Julien, Yes both in both the cases the same tables are accessed. Yes we tried indexing as well, but we have the same behaviour. Regards, Satalabha On Sun, 4 Jun 2023 at 16:51, Julien Rouhaud wrote: > Hi, > > On Sun, Jun 04, 2023 at 02:04:52PM +0530, Satalabaha Postgres wrote: > > > > 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? > > Are you sure that in both case the exact same tables are accessed? It > looks > like schema1_u is checking the rows for a way bigger table. The usual > answer > is to create a proper index for the table referenced by the FK. >
Re: Weird behavior of INSERT QUERY
On Sun, 4 Jun 2023 at 19:46, Ranier Vilela wrote: > Em dom., 4 de jun. de 2023 às 05:35, Satalabaha Postgres < > [email protected]> escreveu: > >> 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$ >> ; >> > Can you show what type is FILEID? > > Can there be type mismatch? > > regards, > Ranier Vilela > Thanks Ranier. Please find the below. \d+ schema1.table_a Table "schema1.table_a" Column| Type | Collation | Nullable | Default | Storage | Stats target | Description -++---+--+-+--+--+- id | numeric(20,0) | | not null | | main | | rowversion | timestamp(4) without time zone | | not null | | plain| | created | timestamp(4) without time zone | | not null | | plain| | isdeleted | boolean| | not null | | plain| | lastupdated | timestamp(4) without time zone | | | | plain| | isignored | boolean| | not null | | plain| | importedaccountcode | character varying(255) | | | | extended | | importedunitcode| character varying(255) | | | | extended | | beginningbalance| numeric(19,5) | | | | main | | endingbalance | numeric(19,5) | | | | main | | createdbyid | numeric(20,0) | | | | main | | updatedbyid | numeric(20,0) | | | | main | | fileid | numeric(20,0) | | not null | | main | | previousid | numeric(20,0) | | | | main | | createdby | character varying(255) | | | | extended |
Re: Weird behavior of INSERT QUERY
Regards, Satalabha On Sun, 4 Jun 2023 at 18:56, Tom Lane wrote: > Satalabaha Postgres writes: > > 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. > > So you need to find out what's happening in the trigger. Perhaps > auto_explain with auto_explain.log_nested_statements enabled > would give some insight. > > I suspect there might be a permissions problem causing schema1_u > to not be allowed to "see" the statistics for table_b, resulting > in a bad plan choice for the FK enforcement query; but that's > just a guess. > > regards, tom lane > Hi Tom, We did enable auto_explain and auto_explain.log_nested_statements and apart from the insert statement we couldn't find any other SQL's causing that was taking more time. Regards, Satalabaha.
Re: Weird behavior of INSERT QUERY
On Mon, 5 Jun 2023 at 04:35, Ranier Vilela wrote: > Em dom., 4 de jun. de 2023 às 11:49, Satalabaha Postgres < > [email protected]> escreveu: > >> >> >> >> On Sun, 4 Jun 2023 at 19:46, Ranier Vilela wrote: >> >>> Em dom., 4 de jun. de 2023 às 05:35, Satalabaha Postgres < >>> [email protected]> escreveu: >>> >>>> 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$ >>>> ; >>>> >>> Can you show what type is FILEID? >>> >>> Can there be type mismatch? >>> >>> >> regards, >>> Ranier Vilela >>> >> >> Thanks Ranier. Please find the below. >> >> \d+ schema1.table_a >> Table "schema1.table_a" >>Column| Type | Collation | >> Nullable | Default | Storage | Stats target | Description >> >> -++---+--+-+--+--+- >> id | numeric(20,0) | | not >> null | | main | | >> rowversion | timestamp(4) without time zone | | not >> null | | plain| | >> created | timestamp(4) without time zone | | not >> null | | plain| | >> isdeleted | boolean| | not >> null | | plain| | >> lastupdated | timestamp(4) without time zone | | >>| | plain| | >> isignored | boolean| | not >> null | | plain
query column in pg_stat_statements and pg_stat_activity
I've written the below SQL query that joins pg_stat_statements with pg_stat_activity using "queryid" as the join condition. Yet, the results show that pg_stat_statements and pg_stat_activity are reporting two distinct queries for the identical queryid. Can this occur? select pgss.queryid as "PGSS_QUERYID", pgss.query as "PGSS_QUERY", pgsa.query_id as "PGSA_QUERYID", substring(pgsa.query, 1, 45) as "PGSA_QUERY" from pg_stat_statements pgss join pg_stat_activity pgsa on pgss.queryid = pgsa.query_id and pgss.queryid = '2397681704071010949'; PGSS_QUERYID | PGSS_QUERY |PGSA_QUERYID | PGSA_QUERY -++-+--- 2397681704071010949 | BEGIN | 2397681704071010949 | select projectper0_.ENTITY_PERMISSION_SID as 2397681704071010949 | BEGIN | 2397681704071010949 | select projectper0_.ENTITY_PERMISSION_SID as 2397681704071010949 | BEGIN | 2397681704071010949 | select folderperm0_.ENTITY_PERMISSION_SID as 2397681704071010949 | BEGIN | 2397681704071010949 | select folderperm0_.ENTITY_PERMISSION_SID as 2397681704071010949 | BEGIN | 2397681704071010949 | SELECT item_guid, count(item_guid) count FR 2397681704071010949 | BEGIN | 2397681704071010949 | SELECT item_guid, count(item_guid) count FR 2397681704071010949 | BEGIN | 2397681704071010949 | select folderperm0_.ENTITY_PERMISSION_SID as 2397681704071010949 | BEGIN | 2397681704071010949 | select folderperm0_.ENTITY_PERMISSION_SID as 2397681704071010949 | BEGIN | 2397681704071010949 | SELECT distinct ep.role FROM v_project_permis 2397681704071010949 | BEGIN | 2397681704071010949 | SELECT distinct ep.role FROM v_project_permis 2397681704071010949 | BEGIN | 2397681704071010949 | select this_.CONTACT_SID as CONTACT1_362_1_, 2397681704071010949 | BEGIN | 2397681704071010949 | select this_.CONTACT_SID as CONTACT1_362_1_, 2397681704071010949 | BEGIN | 2397681704071010949 | SELECT item_guid,category,root_guid, count(i 2397681704071010949 | BEGIN | 2397681704071010949 | SELECT item_guid,category,root_guid, count(i 2397681704071010949 | BEGIN | 2397681704071010949 | select folderperm0_.ENTITY_PERMISSION_SID as 2397681704071010949 | BEGIN | 2397681704071010949 | select folderperm0_.ENTITY_PERMISSION_SID as 2397681704071010949 | BEGIN | 2397681704071010949 | select folderperm0_.ENTITY_PERMISSION_SID as 2397681704071010949 | BEGIN | 2397681704071010949 | select folderperm0_.ENTITY_PERMISSION_SID as 2397681704071010949 | BEGIN | 2397681704071010949 | select folderperm0_.ENTITY_PERMISSION_SID as Regards, Satalabha
