Date: Fri, 27 Jul 2007 08:49:57 -0400
From: "Jignesh K. Shah" <J.K.Shah@Sun.COM>
Subject: Re: User concurrency thresholding: where do I look?
In-reply-to: <1185527727.4191.22.camel@ebony.site>
To: Simon Riggs <simon@2ndquadrant.com>
Cc: Tom Lane <tgl@sss.pgh.pa.us>, Josh Berkus <josh@agliodbs.com>,
	pgsql-performance@postgresql.org,
	Alvaro Herrera <alvherre@commandprompt.com>
Message-id: <46A9E9F5.3020901@sun.com>
MIME-version: 1.0
Content-type: text/plain; format=flowed; charset=UTF-8
Content-transfer-encoding: 7BIT
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> <1185527727.4191.22.camel@ebony.site>
User-Agent: Thunderbird 2.0.0.5 (Windows/20070716)

Yes I can try to breakup the Shared and exclusive time..

Also yes I use commit delays =10, it helps out a lot in reducing IO load..

I will try out the patch soon.

-Jignesh


Simon Riggs wrote:
> 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.
>
>