Date: Fri, 23 Jul 2021 13:18:17 -0500
From: Justin Pryzby <pryzby@telsasoft.com>
To: Manoj Kumar <manojkumar@temenos.com>
Cc: pgsql-performance@postgresql.org,
	"A.S. Fazlu Rahman" <fazlur@temenos.com>
Subject: Re: Performance Issue on a table
Message-ID: <20210723181817.GP19620@telsasoft.com>
References: 
 <SJ0PR04MB7662C951C68CC4B0D694A770D9E49@SJ0PR04MB7662.namprd04.prod.outlook.com>
MIME-Version: 1.0
Content-Type: text/plain; charset=us-ascii
Content-Disposition: inline
In-Reply-To: 
 <SJ0PR04MB7662C951C68CC4B0D694A770D9E49@SJ0PR04MB7662.namprd04.prod.outlook.com>
User-Agent: Mutt/1.9.4 (2018-02-28)
Archived-At: 
 <https://www.postgresql.org/message-id/20210723181817.GP19620%40telsasoft.com>
Precedence: bulk

On Thu, Jul 22, 2021 at 01:54:25PM +0000, 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)