Received: from localhost (maia-4.hub.org [200.46.204.183]) by postgresql.org (Postfix) with ESMTP id EB2929FB3FC for ; Thu, 26 Jul 2007 16:44:55 -0300 (ADT) Received: from postgresql.org ([200.46.204.71]) by localhost (mx1.hub.org [200.46.204.183]) (amavisd-maia, port 10024) with ESMTP id 47420-07 for ; Thu, 26 Jul 2007 16:44:48 -0300 (ADT) X-Greylist: from auto-whitelisted by SQLgrey-1.7.5 Received: from brmea-mail-3.sun.com (brmea-mail-3.Sun.COM [192.18.98.34]) by postgresql.org (Postfix) with ESMTP id C68A29FA206 for ; Thu, 26 Jul 2007 16:44:46 -0300 (ADT) Received: from fe-amer-04.sun.com ([192.18.108.178]) by brmea-mail-3.sun.com (8.13.6+Sun/8.12.9) with ESMTP id l6QJijkV029913 for ; Thu, 26 Jul 2007 19:44:45 GMT Received: from conversion-daemon.mail-amer.sun.com by mail-amer.sun.com (Sun Java System Messaging Server 6.2-6.01 (built Apr 3 2006)) id <0JLS00J01XDWSX00@mail-amer.sun.com> (original mail from J.K.Shah@Sun.COM) for pgsql-performance@postgresql.org; Thu, 26 Jul 2007 13:44:45 -0600 (MDT) Received: from [129.148.9.17] by mail-amer.sun.com (Sun Java System Messaging Server 6.2-6.01 (built Apr 3 2006)) with ESMTPSA id <0JLS00CZFXIJGSH8@mail-amer.sun.com>; Thu, 26 Jul 2007 13:44:44 -0600 (MDT) Date: Thu, 26 Jul 2007 15:44:42 -0400 From: "Jignesh K. Shah" Subject: Re: User concurrency thresholding: where do I look? In-reply-to: <1185465076.4190.87.camel@ebony.site> To: Simon Riggs Cc: Tom Lane , Josh Berkus , pgsql-performance@postgresql.org, Alvaro Herrera Message-id: <46A8F9AA.4040507@sun.com> Organization: Sun Microsystems MIME-version: 1.0 Content-type: text/plain; format=flowed; charset=ISO-8859-1 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> User-Agent: Thunderbird 1.5.0.8 (X11/20061110) X-Virus-Scanned: Maia Mailguard 1.0.1 X-Archive-Number: 200707/372 X-Sequence-Number: 26056 BEAUTIFUL!!! Using the Patch I can now go upto 1300 users without dropping.. But now it still repeats at 1300-1350 users.. I corrected the Lock Descriptions based on what I got from lwlock.h and retried the whole scalability again with profiling again.. This time it looks like the ProcArrayLock bash-3.00# echo 600 users 600 users bash-3.00# ./4_lwlock_waits.d 7056 Lock Id Mode Count XidGenLock Exclusive 1 CLogControlLock Shared 2 XidGenLock Shared 2 WALWriteLock Exclusive 4 WALInsertLock Exclusive 8 CLogControlLock Exclusive 9 ProcArrayLock Exclusive 9 Lock Id Combined Time (ns) WALWriteLock 2842300 XidGenLock 4951000 CLogControlLock 11151800 WALInsertLock 13035600 ProcArrayLock 20040000 bash-3.00# echo 700 users 700 users bash-3.00# ./4_lwlock_waits.d 7056 Lock Id Mode Count XidGenLock Exclusive 1 WALWriteLock Exclusive 2 XidGenLock Shared 2 CLogControlLock Shared 3 CLogControlLock Exclusive 8 WALInsertLock Exclusive 9 ProcArrayLock Exclusive 22 Lock Id Combined Time (ns) XidGenLock 4093300 WALWriteLock 4914800 WALInsertLock 7389100 ProcArrayLock 10248200 CLogControlLock 11989400 bash-3.00# echo 800 users 800 users bash-3.00# ./4_lwlock_waits.d 7056 Lock Id Mode Count WALWriteLock Exclusive 1 XidGenLock Shared 2 CLogControlLock Shared 3 CLogControlLock Exclusive 7 WALInsertLock Exclusive 7 ProcArrayLock Exclusive 31 Lock Id Combined Time (ns) WALWriteLock 319100 XidGenLock 5388700 WALInsertLock 9901400 CLogControlLock 13465000 ProcArrayLock 42979700 bash-3.00# echo 900 users 900 users bash-3.00# ./4_lwlock_waits.d 7056 Lock Id Mode Count CLogControlLock Shared 1 XidGenLock Exclusive 1 WALWriteLock Exclusive 2 CLogControlLock Exclusive 6 WALInsertLock Exclusive 9 ProcArrayLock Exclusive 25 Lock Id Combined Time (ns) XidGenLock 3197700 WALWriteLock 3887100 CLogControlLock 15774500 WALInsertLock 38268700 ProcArrayLock 162073100 bash-3.00# ./6_lwlock_stack.d 4 7056 Lock Id Mode Count ProcArrayLock Shared 1 ProcArrayLock Exclusive 67 Lock Id Combined Time (ns) ProcArrayLock 216773800 Lock Id Combined Time (ns) postgres`LWLockAcquire+0x1c8 postgres`GetSnapshotData+0x118 postgres`GetTransactionSnapshot+0x5c postgres`PortalStart+0x150 postgres`exec_bind_message+0x81c postgres`PostgresMain+0x12b8 postgres`BackendRun+0x278 postgres`ServerLoop+0x63c postgres`PostmasterMain+0xc40 postgres`main+0x394 postgres`_start+0x108 2779000 postgres`LWLockAcquire+0x1c8 postgres`CommitTransaction+0xe0 postgres`CommitTransactionCommand+0x90 postgres`finish_xact_command+0x60 postgres`exec_execute_message+0x3d8 postgres`PostgresMain+0x1300 postgres`BackendRun+0x278 postgres`ServerLoop+0x63c postgres`PostmasterMain+0xc40 postgres`main+0x394 postgres`_start+0x108 213994800 bash-3.00# echo 1000 users - SLIGHT DROP 1000 users bash-3.00# ./4_lwlock_waits.d 7056 Lock Id Mode Count WALWriteLock Exclusive 1 CLogControlLock Exclusive 2 XidGenLock Shared 2 CLogControlLock Shared 3 WALInsertLock Exclusive 4 ProcArrayLock Exclusive 26 Lock Id Combined Time (ns) WALWriteLock 1807400 XidGenLock 2024000 WALInsertLock 2177500 CLogControlLock 9064700 ProcArrayLock 199216000 bash-3.00# ./6_lwlock_stack.d 4 7056 Lock Id Mode Count ProcArrayLock Shared 3 ProcArrayLock Exclusive 38 Lock Id Combined Time (ns) ProcArrayLock 858238600 Lock Id Combined Time (ns) postgres`LWLockAcquire+0x1c8 postgres`TransactionIdIsInProgress+0x50 postgres`HeapTupleSatisfiesVacuum+0x2ec postgres`_bt_check_unique+0x2a0 postgres`_bt_doinsert+0x98 postgres`btinsert+0x54 postgres`FunctionCall6+0x44 postgres`index_insert+0x90 postgres`ExecInsertIndexTuples+0x1bc postgres`ExecUpdate+0x500 postgres`ExecutePlan+0x704 postgres`ExecutorRun+0x60 postgres`PortalRunMulti+0x2a0 postgres`PortalRun+0x310 postgres`exec_execute_message+0x3a0 postgres`PostgresMain+0x1300 postgres`BackendRun+0x278 postgres`ServerLoop+0x63c postgres`PostmasterMain+0xc40 postgres`main+0x394 167100 postgres`LWLockAcquire+0x1c8 postgres`GetSnapshotData+0x118 postgres`GetTransactionSnapshot+0x5c postgres`PortalRunMulti+0x22c postgres`PortalRun+0x310 postgres`exec_execute_message+0x3a0 postgres`PostgresMain+0x1300 postgres`BackendRun+0x278 postgres`ServerLoop+0x63c postgres`PostmasterMain+0xc40 postgres`main+0x394 postgres`_start+0x108 7125900 postgres`LWLockAcquire+0x1c8 postgres`CommitTransaction+0xe0 postgres`CommitTransactionCommand+0x90 postgres`finish_xact_command+0x60 postgres`exec_execute_message+0x3d8 postgres`PostgresMain+0x1300 postgres`BackendRun+0x278 postgres`ServerLoop+0x63c postgres`PostmasterMain+0xc40 postgres`main+0x394 postgres`_start+0x108 850945600 bash-3.00# echo 1100 users - DROP .... 1100 users bash-3.00# ./4_lwlock_waits.d 7056 Lock Id Mode Count CLogControlLock Shared 1 WALWriteLock Exclusive 1 XidGenLock Exclusive 1 ProcArrayLock Shared 2 WALInsertLock Exclusive 2 XidGenLock Shared 2 CLogControlLock Exclusive 4 ProcArrayLock Exclusive 20 Lock Id Combined Time (ns) WALWriteLock 4179500 XidGenLock 6249400 CLogControlLock 20411100 WALInsertLock 29707600 ProcArrayLock 207923700 bash-3.00# ./6_lwlock_stack.d 4 7056 Lock Id Mode Count ProcArrayLock Exclusive 40 Lock Id Combined Time (ns) ProcArrayLock 692242100 Lock Id Combined Time (ns) postgres`LWLockAcquire+0x1c8 postgres`CommitTransaction+0xe0 postgres`CommitTransactionCommand+0x90 postgres`finish_xact_command+0x60 postgres`exec_execute_message+0x3d8 postgres`PostgresMain+0x1300 postgres`BackendRun+0x278 postgres`ServerLoop+0x63c postgres`PostmasterMain+0xc40 postgres`main+0x394 postgres`_start+0x108 692242100 bash-3.00# LockID for ProcArrayLock is 4 or the 5 entry in lwlock.h which seems to indicate it is lwlock.h Any tweaks for that? -Jignesh Simon Riggs wrote: > On Thu, 2007-07-26 at 11:27 -0400, Jignesh K. Shah wrote: > > >> However at 900 Users where the big drop in throughput occurs: >> It gives a different top "consumer" of time: >> > > > postgres`LWLockAcquire+0x1c8 > >> postgres`SimpleLruReadPage+0x1ac >> postgres`TransactionIdGetStatus+0x14 >> postgres`TransactionLogFetch+0x58 >> > > TransactionIdGetStatus doesn't directly call SimpleLruReadPage(). > Presumably the compiler has been rearranging things?? > > Looks like you're out of clog buffers. It seems like the clog buffers > aren't big enough to hold clog pages for long enough and the SELECT FOR > SHARE processing is leaving lots of additional read locks that are > increasing the number of clog requests for older xids. > > Try the enclosed patch. > > > ------------------------------------------------------------------------ > > Index: src/include/access/clog.h > =================================================================== > RCS file: /projects/cvsroot/pgsql/src/include/access/clog.h,v > retrieving revision 1.19 > diff -c -r1.19 clog.h > *** src/include/access/clog.h 5 Jan 2007 22:19:50 -0000 1.19 > --- src/include/access/clog.h 26 Jul 2007 15:44:58 -0000 > *************** > *** 29,35 **** > > > /* Number of SLRU buffers to use for clog */ > ! #define NUM_CLOG_BUFFERS 8 > > > extern void TransactionIdSetStatus(TransactionId xid, XidStatus status); > --- 29,35 ---- > > > /* Number of SLRU buffers to use for clog */ > ! #define NUM_CLOG_BUFFERS 64 > > > extern void TransactionIdSetStatus(TransactionId xid, XidStatus status); > > ------------------------------------------------------------------------ > > > ---------------------------(end of broadcast)--------------------------- > TIP 5: don't forget to increase your free space map settings >