Re: Performance Issue on a table

2021-07-23 Thread Justin Pryzby 
On Thu, Jul 22, 2021 at 01:54:25PM +, Manoj Kumar wrote:
> Recently we have noticed that in one of our DB instances there is a potential 
> delay in querying a table from java code. could you please check the attached 
> log and help understand what is the problem and which direction should be 
> look into solving this delay of 4 odd mins ?

I'm not familiar with the log, but it looks like the delay is in query parsing
(ParseComplete).  Which seems weird.  You might try running wireshark to verify
that.  Or check postgres logs, and make sure the query isn't being blocked by
DDL commands.  Make sure these are enabled:

log_lock_waits = 'on'
deadlock_timeout = '1s'

> 4:25:00 PM ... execute FINEST:   simple execute, 
> handler=org.postgresql.jdbc.PgStatement$StatementResultHandler@13e344d, 
> maxRows=0, fetchSize=0, flags=1
> 4:25:00 PM ... sendSimpleQuery FINEST:  FE=> SimpleQuery(query="SAVEPOINT 
> PGJDBC_AUTOSAVE")
> 4:25:00 PM ... sendParse FINEST:  FE=> Parse(stmt=null,query="SELECT RECID 
> FROM TAFJ_HASHLOCKS WHERE RECID = $1 FOR UPDATE NOWAIT ",oids={1043})
> 4:25:00 PM ... sendBind FINEST:  FE=> 
> Bind(stmt=null,portal=null,$1=<'256292129'>,type=VARCHAR)
> 4:25:00 PM ... sendDescribePortal FINEST:  FE=> Describe(portal=null)
> 4:25:00 PM ... sendExecute FINEST:  FE=> Execute(portal=null,limit=0)
> 4:25:00 PM ... sendSync FINEST:  FE=> Sync
> 4:25:00 PM ... receiveCommandStatus FINEST:  <=BE CommandStatus(RELEASE)
> 4:25:00 PM ... receiveRFQ FINEST:  <=BE ReadyForQuery(T)
> 4:25:00 PM ... receiveCommandStatus FINEST:  <=BE CommandStatus(SAVEPOINT)
> 4:25:00 PM ... receiveRFQ FINEST:  <=BE ReadyForQuery(T)
> 4:29:20 PM ... processResults FINEST:  <=BE ParseComplete [null]
> 4:29:20 PM ... processResults FINEST:  <=BE BindComplete [unnamed]
> 4:29:20 PM ... receiveFields FINEST:  <=BE RowDescription(1)

Performance Issue on a table

2021-07-23 Thread Manoj Kumar 
Dear Team,

Recently we have noticed that in one of our DB instances there is a potential 
delay in querying a table from java code. could you please check the attached 
log and help understand what is the problem and which direction should be look 
into solving this delay of 4 odd mins ?

The table definition is as below, it contains around 2 billion rows.

create table "TAFJ_HASHLOCKS" (recid integer);
alter table "TAFJ_HASHLOCKS" add constraint "TAFJ_HASHLOCKS_PK" PRIMARY KEY  
(recid);



Jul 22, 2021 4:25:00 PM org.postgresql.core.v3.QueryExecutorImpl execute
FINEST:   simple execute, 
handler=org.postgresql.jdbc.PgStatement$StatementResultHandler@13e344d, 
maxRows=0, fetchSize=0, flags=1
Jul 22, 2021 4:25:00 PM org.postgresql.core.v3.QueryExecutorImpl sendSimpleQuery
FINEST:  FE=> SimpleQuery(query="SAVEPOINT PGJDBC_AUTOSAVE")
Jul 22, 2021 4:25:00 PM org.postgresql.core.v3.QueryExecutorImpl sendParse
FINEST:  FE=> Parse(stmt=null,query="SELECT RECID FROM TAFJ_HASHLOCKS WHERE 
RECID = $1 FOR UPDATE NOWAIT ",oids={1043})
Jul 22, 2021 4:25:00 PM org.postgresql.core.v3.QueryExecutorImpl sendBind
FINEST:  FE=> Bind(stmt=null,portal=null,$1=<'256292129'>,type=VARCHAR)
Jul 22, 2021 4:25:00 PM org.postgresql.core.v3.QueryExecutorImpl 
sendDescribePortal
FINEST:  FE=> Describe(portal=null)
Jul 22, 2021 4:25:00 PM org.postgresql.core.v3.QueryExecutorImpl sendExecute
FINEST:  FE=> Execute(portal=null,limit=0)
Jul 22, 2021 4:25:00 PM org.postgresql.core.v3.QueryExecutorImpl sendSync
FINEST:  FE=> Sync
Jul 22, 2021 4:25:00 PM org.postgresql.core.v3.QueryExecutorImpl 
receiveCommandStatus
FINEST:  <=BE CommandStatus(RELEASE)
Jul 22, 2021 4:25:00 PM org.postgresql.core.v3.QueryExecutorImpl receiveRFQ
FINEST:  <=BE ReadyForQuery(T)
Jul 22, 2021 4:25:00 PM org.postgresql.core.v3.QueryExecutorImpl 
receiveCommandStatus
FINEST:  <=BE CommandStatus(SAVEPOINT)
Jul 22, 2021 4:25:00 PM org.postgresql.core.v3.QueryExecutorImpl receiveRFQ
FINEST:  <=BE ReadyForQuery(T)
Jul 22, 2021 4:29:20 PM org.postgresql.core.v3.QueryExecutorImpl processResults
FINEST:  <=BE ParseComplete [null]
Jul 22, 2021 4:29:20 PM org.postgresql.core.v3.QueryExecutorImpl processResults
FINEST:  <=BE BindComplete [unnamed]
Jul 22, 2021 4:29:20 PM org.postgresql.core.v3.QueryExecutorImpl receiveFields
FINEST:  <=BE RowDescription(1)


Thanks

The information in this e-mail and any attachments is confidential and may be 
legally privileged. It is intended solely for the addressee or addressees. Any 
use or disclosure of the contents of this e-mail/attachments by a not intended 
recipient is unauthorized and may be unlawful. If you have received this e-mail 
in error please notify the sender. Please note that any views or opinions 
presented in this e-mail are solely those of the author and do not necessarily 
represent those of TEMENOS. We recommend that you check this e-mail and any 
attachments against viruses. TEMENOS accepts no liability for any damage caused 
by any malicious code or virus transmitted by this e-mail.


pgjdbc.log
Description: pgjdbc.log

RE: Big performance slowdown from 11.2 to 13.3

2021-07-23 Thread l...@laurent-hasson.com 


From: Vijaykumar Jain 
Sent: Friday, July 23, 2021 10:45
To: l...@laurent-hasson.com
Cc: Justin Pryzby ; pgsql-performa...@postgresql.org
Subject: Re: Big performance slowdown from 11.2 to 13.3

On Fri, 23 Jul 2021 at 03:06, 
l...@laurent-hasson.com 
mailto:l...@laurent-hasson.com>> wrote:
I am not sure I understand this parameter well enough but it’s with a default 
value right now of 1000. I have read Robert’s post 
(http://rhaas.blogspot.com/2018/06/using-forceparallelmode-correctly.html) and 
could play with those parameters, but unsure whether what you are describing 
will unlock this 2GB limit.


Yeah, may be i was diverting, and possibly cannot use the windows bottleneck.

although the query is diff, the steps were
1) use system default, work_mem = 4MB, parallel_setup_cost = 1000
-- runs the query in parallel, no disk spill as work_mem suff.for my data

postgres=# explain analyze with cte as (select month_name, day_name, 
year_actual, max(date) date from dimensions.dates  group by year_actual, 
month_name, day_name) select max(date),year_actual  from cte group by 
year_actual;
 QUERY 
PLAN

 GroupAggregate  (cost=931227.78..932398.85 rows=200 width=8) (actual 
time=7850.214..7855.848 rows=51 loops=1)
   Group Key: dates.year_actual
   ->  Finalize GroupAggregate  (cost=931227.78..932333.85 rows=4200 width=28) 
(actual time=7850.075..7855.611 rows=4201 loops=1)
 Group Key: dates.year_actual, dates.month_name, dates.day_name
 ->  Gather Merge  (cost=931227.78..932207.85 rows=8400 width=28) 
(actual time=7850.069..7854.008 rows=11295 loops=1)
   Workers Planned: 2
   Workers Launched: 2
   ->  Sort  (cost=930227.76..930238.26 rows=4200 width=28) (actual 
time=7846.419..7846.551 rows=3765 loops=3)
 Sort Key: dates.year_actual, dates.month_name, 
dates.day_name
 Sort Method: quicksort  Memory: 391kB
 Worker 0:  Sort Method: quicksort  Memory: 392kB
 Worker 1:  Sort Method: quicksort  Memory: 389kB
 ->  Partial HashAggregate  (cost=929933.00..929975.00 
rows=4200 width=28) (actual time=7841.979..7842.531 rows=3765 loops=3)
   Group Key: dates.year_actual, dates.month_name, 
dates.day_name
   Batches: 1  Memory Usage: 721kB
   Worker 0:  Batches: 1  Memory Usage: 721kB
   Worker 1:  Batches: 1  Memory Usage: 721kB
   ->  Parallel Seq Scan on dates  
(cost=0.00..820355.00 rows=10957800 width=28) (actual time=3.347..4779.784 
rows=8766240 loops=3)
 Planning Time: 0.133 ms
 Execution Time: 7855.958 ms
(20 rows)

-- set  work_mem to a very low value, to spill to disk and compare the spill in 
parallel vs serial
postgres=# set work_mem TO 64; --
SET
postgres=# explain analyze with cte as (select month_name, day_name, 
year_actual, max(date) date from dimensions.dates  group by year_actual, 
month_name, day_name) select max(date),year_actual  from cte group by 
year_actual;
 QUERY 
PLAN

 GroupAggregate  (cost=2867778.00..2868949.07 rows=200 width=8) (actual 
time=18116.529..18156.972 rows=51 loops=1)
   Group Key: dates.year_actual
   ->  Finalize GroupAggregate  (cost=2867778.00..2868884.07 rows=4200 
width=28) (actual time=18116.421..18156.729 rows=4201 loops=1)
 Group Key: dates.year_actual, dates.month_name, dates.day_name
 ->  Gather Merge  (cost=2867778.00..2868758.07 rows=8400 width=28) 
(actual time=18116.412..18155.136 rows=11126 loops=1)
   Workers Planned: 2
   Workers Launched: 2
   ->  Sort  (cost=2866777.98..2866788.48 rows=4200 width=28) 
(actual time=17983.836..17984.981 rows=3709 loops=3)
 Sort Key: dates.year_actual, dates.month_name, 
dates.day_name
 Sort Method: external merge  Disk: 160kB
 Worker 0:  Sort Method: external merge  Disk: 168kB
 Worker 1:  Sort Method: external merge  Disk: 160kB
 ->  Partial HashAggregate  (cost=2566754.38..2866423.72 
rows=4200 width=28) (actual time=10957.390..17976.250 rows=3709 loops=3)
   Group Key: dates.year_actual, dates.month_name, 
dates.day_name
   Planned Partitions: 4  Batches: 21  Memory Usage: 
93kB  Disk Usage: 457480kB
   Worker 0:  Batches: 21  Memory Usage: 93kB  Disk

Re: Big performance slowdown from 11.2 to 13.3

2021-07-23 Thread Vijaykumar Jain 
On Fri, 23 Jul 2021 at 03:06, l...@laurent-hasson.com 
wrote:

> I am not sure I understand this parameter well enough but it’s with a
> default value right now of 1000. I have read Robert’s post (
> http://rhaas.blogspot.com/2018/06/using-forceparallelmode-correctly.html)
> and could play with those parameters, but unsure whether what you are
> describing will unlock this 2GB limit.
>
>
>

Yeah, may be i was diverting, and possibly cannot use the windows
bottleneck.

although the query is diff, the steps were
1) use system default, work_mem = 4MB, parallel_setup_cost = 1000
-- runs the query in parallel, no disk spill as work_mem suff.for my data

postgres=# explain analyze with cte as (select month_name, day_name,
year_actual, max(date) date from dimensions.dates  group by year_actual,
month_name, day_name) select max(date),year_actual  from cte group by
year_actual;

 QUERY PLAN

 GroupAggregate  (cost=931227.78..932398.85 rows=200 width=8) (actual
time=7850.214..7855.848 rows=51 loops=1)
   Group Key: dates.year_actual
   ->  Finalize GroupAggregate  (cost=931227.78..932333.85 rows=4200
width=28) (actual time=7850.075..7855.611 rows=4201 loops=1)
 Group Key: dates.year_actual, dates.month_name, dates.day_name
 ->  Gather Merge  (cost=931227.78..932207.85 rows=8400 width=28)
(actual time=7850.069..7854.008 rows=11295 loops=1)
   Workers Planned: 2
   Workers Launched: 2
   ->  Sort  (cost=930227.76..930238.26 rows=4200 width=28)
(actual time=7846.419..7846.551 rows=3765 loops=3)
 Sort Key: dates.year_actual, dates.month_name,
dates.day_name
 Sort Method: quicksort  Memory: 391kB
 Worker 0:  Sort Method: quicksort  Memory: 392kB
 Worker 1:  Sort Method: quicksort  Memory: 389kB
 ->  Partial HashAggregate  (cost=929933.00..929975.00
rows=4200 width=28) (actual time=7841.979..7842.531 rows=3765 loops=3)
   Group Key: dates.year_actual, dates.month_name,
dates.day_name
   Batches: 1  Memory Usage: 721kB
   Worker 0:  Batches: 1  Memory Usage: 721kB
   Worker 1:  Batches: 1  Memory Usage: 721kB
   ->  Parallel Seq Scan on dates
(cost=0.00..820355.00 rows=10957800 width=28) (actual time=3.347..4779.784
rows=8766240 loops=3)
 Planning Time: 0.133 ms
 Execution Time: 7855.958 ms
(20 rows)

-- set  work_mem to a very low value, to spill to disk and compare the
spill in parallel vs serial
postgres=# set work_mem TO 64; --
SET
postgres=# explain analyze with cte as (select month_name, day_name,
year_actual, max(date) date from dimensions.dates  group by year_actual,
month_name, day_name) select max(date),year_actual  from cte group by
year_actual;

 QUERY PLAN

 GroupAggregate  (cost=2867778.00..2868949.07 rows=200 width=8) (actual
time=18116.529..18156.972 rows=51 loops=1)
   Group Key: dates.year_actual
   ->  Finalize GroupAggregate  (cost=2867778.00..2868884.07 rows=4200
width=28) (actual time=18116.421..18156.729 rows=4201 loops=1)
 Group Key: dates.year_actual, dates.month_name, dates.day_name
 ->  Gather Merge  (cost=2867778.00..2868758.07 rows=8400 width=28)
(actual time=18116.412..18155.136 rows=11126 loops=1)
   Workers Planned: 2
   Workers Launched: 2
   ->  Sort  (cost=2866777.98..2866788.48 rows=4200 width=28)
(actual time=17983.836..17984.981 rows=3709 loops=3)
 Sort Key: dates.year_actual, dates.month_name,
dates.day_name
 Sort Method: external merge  Disk: 160kB
 Worker 0:  Sort Method: external merge  Disk: 168kB
 Worker 1:  Sort Method: external merge  Disk: 160kB
 ->  Partial HashAggregate
(cost=2566754.38..2866423.72 rows=4200 width=28) (actual
time=10957.390..17976.250 rows=3709 loops=3)
   Group Key: dates.year_actual, dates.month_name,
dates.day_name
   Planned Partitions: 4  Batches: 21  Memory
Usage: 93kB  Disk Usage: 457480kB
   Worker 0:  Batches: 21  Memory Usage: 93kB  Disk
Usage: *473056kB*
   Worker 1:  Batches: 21  Memory Usage: 93kB  Disk
Usage: *456792kB*
   ->  Parallel Seq Scan on dates
(cost=0.00..820355.00 rows=10957800 width=28) (actual time=1.042..5893.803
rows=8766240 loops=3)
 Planning Time: 0.142 ms
 Execution Time: 18195.973 ms
(20 rows)

postgres=# set parallel_setup_cost TO 10; -- make sure it never
uses parallel, check