Re: Weird behavior of INSERT QUERY

On Mon, 5 Jun 2023 at 04:35, Ranier Vilela <ranier(dot)vf(at)gmail(dot)com> wrote:

> Em dom., 4 de jun. de 2023 às 11:49, Satalabaha Postgres <
> satalabaha(dot)postgres(at)gmail(dot)com> escreveu:
>
>>
>>
>>
>> On Sun, 4 Jun 2023 at 19:46, Ranier Vilela <ranier(dot)vf(at)gmail(dot)com> wrote:
>>
>>> Em dom., 4 de jun. de 2023 às 05:35, Satalabaha Postgres <
>>> satalabaha(dot)postgres(at)gmail(dot)com> 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 | |
>> lastupdatedby | character varying(255) | |
>> | | extended | |
>>
>> \d+ schema1.table_b
>> Table "schema1.table_b"
>> 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 | |
>> version | numeric(10,0) | |
>> not null | | main | |
>> isactive | boolean | |
>> not null | | plain | |
>> name | character varying(255) | |
>> not null | | extended | |
>> displayname | character varying(255) | |
>> not null | | extended | |
>> ispublished | boolean | |
>> not null | | plain | |
>> isretired | boolean | |
>> not null | | plain | |
>> publishdatetime | timestamp(4) without time zone | |
>> | | plain | |
>> createdbyid | numeric(20,0) | |
>> | | main | |
>> updatedbyid | numeric(20,0) | |
>> | | main | |
>> periodid | numeric(20,0) | |
>> not null | | main | |
>> uploadchartyearversionid | numeric(20,0) | |
>> not null | | main | |
>> importchartyearversionid | numeric(20,0) | |
>> | | main | |
>> initialtbadjversionid | numeric(20,0) | |
>> | | main | |
>> latesttbadjversionid | numeric(20,0) | |
>> | | main | |
>> trialbalancesourceid | numeric(20,0) | |
>> not null | | main | |
>> filedefinitionid | numeric(20,0) | |
>> not null | | main | |
>> createdby | character varying(255) | |
>> | | extended | |
>> lastupdatedby | character varying(255) | |
>> | | extended | |
>>
> I think you are in trouble when comparing float8 (double precision) with
> numeric.
> This small example shows problems.
>
> Postgres version 14.2:
> SELECT '8217316934885843456'::float8 =
> '8217316934885843456'::float8::bigint::float8,
> '8217316934885843456'::float8 =
> '8217316934885843456'::float8::numeric::float8;
> ?column? | ?column?
> ----------+----------
> t | f
> (1 row)
>
> I suggest a study to switch to bigint.
>

>
> regards,
> Ranier Vilela
>

Hi Ranier / All,

Any idea if that is the case why as postgres user the query just works
fine? Also I enabled all parameters for auto_explain and couldn't find any
SQL that is taking more time. At last it just showed the insert statement
and its execution plan which I have mentioned in the beginning of the email
stating "trigger for constraints " taking more time.

One thing that was observed is that, when as postgres user I ran the query,
it was not taking rowshare locks on the parent table (table_b) whereas as
when I ran the same SQL as schema1_u user, I saw the Row Share locks
acquired on the parent table and its FK's and indexes etc. Not sure if I am
missing something here.

As postgres user:

clock_timestamp | relname | locktype |
database | relation | page | tuple | virtualtransaction | pid |
mode | granted
-------------------------------+----------------------+----------+----------+----------+------+-------+--------------------+-------+------------------+---------
2023-06-05 08:57:38.596859+00 | table_a_sq | relation | 16400 |
12826203 | | | 11/14697 | 17833 | RowExclusiveLock | t
2023-06-05 08:57:38.596877+00 | idx1_table_a | relation | 16400
| 28894204 | | | 11/14697 | 17833 | RowExclusiveLock |
t
2023-06-05 08:57:38.596884+00 | idx2_table_a | relation | 16400 |
28894201 | | | 11/14697 | 17833 | RowExclusiveLock | t
2023-06-05 08:57:38.59689+00 | idx3_table_a | relation | 16400
| 28894199 | | | 11/14697 | 17833 | RowExclusiveLock |
t
2023-06-05 08:57:38.596896+00 | idx4_table_a | relation | 16400 |
28894197 | | | 11/14697 | 17833 | RowExclusiveLock | t
2023-06-05 08:57:38.596902+00 | idx5_table_a | relation | 16400
| 28894195 | | | 11/14697 | 17833 | RowExclusiveLock |
t
2023-06-05 08:57:38.596909+00 | fk1_table_a | relation | 16400 |
28894193 | | | 11/14697 | 17833 | RowExclusiveLock | t
2023-06-05 08:57:38.596915+00 | fk2_table_a | relation | 16400 |
28894191 | | | 11/14697 | 17833 | RowExclusiveLock | t
2023-06-05 08:57:38.596923+00 | table_a_pkey | relation | 16400 |
12826690 | | | 11/14697 | 17833 | RowExclusiveLock | t
2023-06-05 08:57:38.596932+00 | staging_table_a | relation | 16400 |
12826482 | | | 11/14697 | 17833 | AccessShareLock | t
2023-06-05 08:57:38.596939+00 | table_a | relation | 16400 |
12826497 | | | 11/14697 | 17833 | RowExclusiveLock | t
(11 rows)

As schema1_u user:

===========================

clock_timestamp | relname | locktype |
database | relation | page | tuple | virtualtransaction | pid |
mode | granted
-------------------------------+------------------------+----------+----------+----------+------+-------+--------------------+-------+------------------+---------
2023-06-05 09:16:24.097184+00 | fk1_table_b | relation | 16400 |
28894114 | | | 13/18586 | 21032 | RowShareLock | t
2023-06-05 09:16:24.097203+00 | fk2_table_b | relation | 16400 |
28894112 | | | 13/18586 | 21032 | RowShareLock | t
2023-06-05 09:16:24.09721+00 | fk3_table_b | relation | 16400 |
28894110 | | | 13/18586 | 21032 | RowShareLock | t
2023-06-05 09:16:24.097221+00 | table_b_pkey | relation | 16400 |
12826648 | | | 13/18586 | 21032 | RowShareLock | t
2023-06-05 09:16:24.097229+00 | table_b | relation | 16400 |
12826410 | | | 13/18586 | 21032 | RowShareLock | t
2023-06-05 09:16:24.097238+00 | table_a_sq | relation | 16400 |
12826203 | | | 13/18586 | 21032 | RowExclusiveLock | t
2023-06-05 09:16:24.097246+00 | idx1_table_a | relation |
16400 | 28894204 | | | 13/18586 | 21032 |
RowExclusiveLock | t
2023-06-05 09:16:24.097252+00 | idx2_table_a | relation | 16400
| 28894201 | | | 13/18586 | 21032 | RowExclusiveLock |
t
2023-06-05 09:16:24.097258+00 | idx3_table_a | relation |
16400 | 28894199 | | | 13/18586 | 21032 |
RowExclusiveLock | t
2023-06-05 09:16:24.097264+00 | idx4_table_a | relation | 16400
| 28894197 | | | 13/18586 | 21032 | RowExclusiveLock |
t
2023-06-05 09:16:24.097271+00 | idx5_table_a | relation |
16400 | 28894195 | | | 13/18586 | 21032 |
RowExclusiveLock | t
2023-06-05 09:16:24.097277+00 | fk1_table_a | relation | 16400
| 28894193 | | | 13/18586 | 21032 | RowExclusiveLock |
t
2023-06-05 09:16:24.097283+00 | fk2_table_a | relation | 16400
| 28894191 | | | 13/18586 | 21032 | RowExclusiveLock |
t
2023-06-05 09:16:24.09729+00 | table_a_pkey | relation | 16400 |
12826690 | | | 13/18586 | 21032 | RowExclusiveLock | t
2023-06-05 09:16:24.097298+00 | staging_table_a | relation | 16400 |
12826482 | | | 13/18586 | 21032 | AccessShareLock | t
2023-06-05 09:16:24.097305+00 | table_a | relation | 16400 |
12826497 | | | 13/18586 | 21032 | RowExclusiveLock | t
2023-06-05 09:16:24.097318+00 | fk4_table_b | relation | 16400 |
28894116 | | | 13/18586 | 21032 | RowShareLock | t
2023-06-05 09:16:24.097324+00 | fk5_table_b | relation | 16400 |
28894120 | | | 13/18586 | 21032 | RowShareLock | t
2023-06-05 09:16:24.09733+00 | fk6_table_b | relation | 16400 |
28894122 | | | 13/18586 | 21032 | RowShareLock | t
2023-06-05 09:16:24.097336+00 | fk7_table_b | relation | 16400
| 28894118 | | | 13/18586 | 21032 | RowShareLock |
t
2023-06-05 09:16:24.097344+00 | fk8_table_b | relation | 16400
| 29343754 | | | 13/18586 | 21032 | RowShareLock |
t
(21 rows)

Regards, Satalabaha