thread-index: AcfQLphID0E9iHq6Qju1APAIabCc4g==
Content-Transfer-Encoding: 7bit
Content-Class: urn:content-classes:message
Importance: normal
Subject: Re: User concurrency thresholding: where do I look?
From: "Simon Riggs" <simon@2ndquadrant.com>
To: "Jignesh K. Shah" <J.K.Shah@Sun.COM>
Cc: "Tom Lane" <tgl@sss.pgh.pa.us>, "Josh Berkus" <josh@agliodbs.com>,
	<pgsql-performance@postgresql.org>,
	"Alvaro Herrera" <alvherre@commandprompt.com>
In-Reply-To: <46A90F83.8050401@sun.com>
References: <200707190828.59088.josh@agliodbs.com>
	<200707191819.13899.josh@agliodbs.com>
	<15685.1184895926@sss.pgh.pa.us>
	<200707192138.39679.josh@agliodbs.com>
	<46A0FA31.2080208@sun.com> <12002.1184955831@sss.pgh.pa.us>
	<46A1055F.9010304@sun.com> <12445.1184958793@sss.pgh.pa.us>
	<46A11116.5030905@sun.com> <14909.1184962561@sss.pgh.pa.us>
	<46A1205B.8010205@sun.com> <15343.1184965054@sss.pgh.pa.us>
	<1185180668.4284.149.camel@ebony.site>
	<23848.1185199901@sss.pgh.pa.us>
	<1185201556.4284.243.camel@ebony.site>
	<25095.1185202498@sss.pgh.pa.us>
	<1185205663.4284.249.camel@ebony.site>
	<1185212261.4284.270.camel@ebony.site>
	<1545.1185214760@sss.pgh.pa.us> <46A7D5AD.9000706@sun.com>
	<13162.1185405865@sss.pgh.pa.us> <46A8AFDF.3050804@sun.com>
	<26825.1185460816@sss.pgh.pa.us> <46A8BD62.2080904@sun.com>
	<1185465076.4190.87.camel@ebony.site> <46A8F9AA.4040507@sun.com>
	<1185480291.5510.22.camel@ebony.site> <46A90F83.8050401@sun.com>
Content-Type: multipart/mixed;
	boundary="=-CvYgak8bPHkJ7a/Z4zki"
Date: Fri, 27 Jul 2007 10:15:27 +0100
Message-ID: <1185527727.4191.22.camel@ebony.site>
MIME-Version: 1.0

This is a multi-part message in MIME format.

--=-CvYgak8bPHkJ7a/Z4zki
Content-Type: text/plain;
	charset="utf-8"
Content-Transfer-Encoding: 7bit

On Thu, 2007-07-26 at 17:17 -0400, Jignesh K. Shah wrote:
>              Lock Id   Combined Time (ns)
>           XidGenLock            194966200
>        WALInsertLock            517955000
>      CLogControlLock            679665100
>         WALWriteLock           2838716200
>        ProcArrayLock          44181002600

Is this the time the lock is held for or the time that we wait for that
lock? It would be good to see the break down of time separately for
shared and exclusive.

Can we have a table like this:
	LockId,LockMode,SumTimeLockHeld,SumTimeLockWait

> Top Wait time   seems to come from the following code path for 
> ProcArrayLock:
> 
>              Lock Id            Mode           Count
>        ProcArrayLock       Exclusive              21
> 
>              Lock Id   Combined Time (ns)
>        ProcArrayLock           5255937500
> 
>              Lock Id   Combined Time (ns)
> 
> 
>               postgres`LWLockAcquire+0x1f0
>               postgres`CommitTransaction+0x104
>               postgres`CommitTransactionCommand+0xbc
>               postgres`finish_xact_command+0x78

Well thats pretty weird. That code path clearly only happens once per
transaction and ought to be fast. The other code paths that take
ProcArrayLock like TransactionIdIsInProgress() and GetSnapshotData()
ought to spend more time holding the lock. Presumably you are running
with a fair number of SERIALIZABLE transactions? 

Are you running with commit_delay > 0? Its possible that the call to
CountActiveBackends() is causing pinging of the procarray by other
backends while we're trying to read it during CommitTransaction(). If
so, try the attached patch.

-- 
  Simon Riggs
  EnterpriseDB  http://www.enterprisedb.com

--=-CvYgak8bPHkJ7a/Z4zki
Content-Disposition: attachment; filename="remove_commit_delay.v1.test.patch"
Content-Type: text/x-patch; charset="utf-8";
	name="remove_commit_delay.v1.test.patch"
Content-Transfer-Encoding: 7bit

Index: src/backend/access/transam/xact.c
===================================================================
RCS file: /projects/cvsroot/pgsql/src/backend/access/transam/xact.c,v
retrieving revision 1.245
diff -c -r1.245 xact.c
*** src/backend/access/transam/xact.c	7 Jun 2007 21:45:58 -0000	1.245
--- src/backend/access/transam/xact.c	27 Jul 2007 09:09:08 -0000
***************
*** 820,827 ****
  			 * are fewer than CommitSiblings other backends with active
  			 * transactions.
  			 */
! 			if (CommitDelay > 0 && enableFsync &&
! 				CountActiveBackends() >= CommitSiblings)
  				pg_usleep(CommitDelay);
  
  			XLogFlush(recptr);
--- 820,826 ----
  			 * are fewer than CommitSiblings other backends with active
  			 * transactions.
  			 */
! 			if (CommitDelay > 0 && enableFsync)
  				pg_usleep(CommitDelay);
  
  			XLogFlush(recptr);

--=-CvYgak8bPHkJ7a/Z4zki--