Received: from localhost (maia-1.hub.org [200.46.204.191]) by postgresql.org (Postfix) with ESMTP id ABDB69FBC05 for ; Thu, 26 Jul 2007 12:27:36 -0300 (ADT) Received: from postgresql.org ([200.46.204.71]) by localhost (mx1.hub.org [200.46.204.191]) (amavisd-maia, port 10024) with ESMTP id 27046-09 for ; Thu, 26 Jul 2007 12:27:34 -0300 (ADT) X-Greylist: from auto-whitelisted by SQLgrey-1.7.5 Received: from brmea-mail-2.sun.com (brmea-mail-2.Sun.COM [192.18.98.43]) by postgresql.org (Postfix) with ESMTP id 230AD9FBC62 for ; Thu, 26 Jul 2007 12:27:33 -0300 (ADT) Received: from fe-amer-01.sun.com ([192.18.108.175]) by brmea-mail-2.sun.com (8.13.6+Sun/8.12.9) with ESMTP id l6QFRWVR008139 for ; Thu, 26 Jul 2007 15:27:32 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 <0JLS00501LDIUQ00@mail-amer.sun.com> (original mail from J.K.Shah@Sun.COM) for pgsql-performance@postgresql.org; Thu, 26 Jul 2007 09:27:32 -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 <0JLS00F0GLLUC4H1@mail-amer.sun.com>; Thu, 26 Jul 2007 09:27:31 -0600 (MDT) Date: Thu, 26 Jul 2007 11:27:30 -0400 From: "Jignesh K. Shah" Subject: Re: User concurrency thresholding: where do I look? In-reply-to: <26825.1185460816@sss.pgh.pa.us> To: Tom Lane Cc: Simon Riggs , Josh Berkus , pgsql-performance@postgresql.org, Alvaro Herrera Message-id: <46A8BD62.2080904@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> User-Agent: Thunderbird 1.5.0.8 (X11/20061110) X-Virus-Scanned: Maia Mailguard 1.0.1 X-Archive-Number: 200707/367 X-Sequence-Number: 26051 I will look for runs with longer samples.. Now the script could have mislabeled lock names.. Anyway digging into the one that seems to increase over time... I did stack profiles on how that increases... and here are some numbers.. For 600-850 Users: that potential mislabeled CheckPointStartLock or LockID==12 comes from various sources where the top source (while system is still doing great) comes from: postgres`LWLockAcquire+0x1c8 postgres`SimpleLruReadPage_ReadOnly+0xc postgres`TransactionIdGetStatus+0x14 postgres`TransactionLogFetch+0x58 postgres`TransactionIdDidCommit+0x4 postgres`HeapTupleSatisfiesSnapshot+0x234 postgres`heap_release_fetch+0x1a8 postgres`index_getnext+0xf4 postgres`IndexNext+0x7c postgres`ExecScan+0x8c postgres`ExecProcNode+0xb4 postgres`ExecutePlan+0xdc postgres`ExecutorRun+0xb0 postgres`PortalRunSelect+0x9c postgres`PortalRun+0x244 postgres`exec_execute_message+0x3a0 postgres`PostgresMain+0x1300 postgres`BackendRun+0x278 postgres`ServerLoop+0x63c postgres`PostmasterMain+0xc40 8202100 postgres`LWLockAcquire+0x1c8 postgres`TransactionIdSetStatus+0x1c postgres`RecordTransactionCommit+0x2a8 postgres`CommitTransaction+0xc8 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 30822100 However at 900 Users where the big drop in throughput occurs: It gives a different top "consumer" of time: postgres`LWLockAcquire+0x1c8 postgres`TransactionIdSetStatus+0x1c postgres`RecordTransactionCommit+0x2a8 postgres`CommitTransaction+0xc8 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 406601300 postgres`LWLockAcquire+0x1c8 postgres`SimpleLruReadPage+0x1ac postgres`TransactionIdGetStatus+0x14 postgres`TransactionLogFetch+0x58 postgres`TransactionIdDidCommit+0x4 postgres`HeapTupleSatisfiesUpdate+0x360 postgres`heap_lock_tuple+0x27c postgres`ExecutePlan+0x33c postgres`ExecutorRun+0xb0 postgres`PortalRunSelect+0x9c postgres`PortalRun+0x244 postgres`exec_execute_message+0x3a0 postgres`PostgresMain+0x1300 postgres`BackendRun+0x278 postgres`ServerLoop+0x63c postgres`PostmasterMain+0xc40 postgres`main+0x394 postgres`_start+0x108 444523100 postgres`LWLockAcquire+0x1c8 postgres`SimpleLruReadPage+0x1ac postgres`TransactionIdGetStatus+0x14 postgres`TransactionLogFetch+0x58 postgres`TransactionIdDidCommit+0x4 postgres`HeapTupleSatisfiesSnapshot+0x234 postgres`heap_release_fetch+0x1a8 postgres`index_getnext+0xf4 postgres`IndexNext+0x7c postgres`ExecScan+0x8c postgres`ExecProcNode+0xb4 postgres`ExecutePlan+0xdc postgres`ExecutorRun+0xb0 postgres`PortalRunSelect+0x9c postgres`PortalRun+0x244 postgres`exec_execute_message+0x3a0 postgres`PostgresMain+0x1300 postgres`BackendRun+0x278 postgres`ServerLoop+0x63c postgres`PostmasterMain+0xc40 1661300000 Maybe you all will understand more than I do on what it does here.. Looks like IndexNext has a problem at high number of users to me.. but I could be wrong.. -Jignesh Tom Lane wrote: > "Jignesh K. Shah" writes: > >> The count is only for a 10-second snapshot.. Plus remember there are >> about 1000 users running so the connection being profiled only gets >> 0.01 of the period on CPU.. And the count is for that CONNECTION only. >> > > OK, that explains the low absolute levels of the counts, but if the > counts are for a regular backend then there's still a lot of bogosity > here. Backends won't be taking the CheckpointLock at all, nor do they > take CheckpointStartLock in exclusive mode. The bgwriter would do that > but it'd not be taking most of these other locks. So I think the script > is mislabeling the locks somehow. > > Also, elementary statistics should tell you that a sample taken as above > is going to have enormous amounts of noise. You should be sampling over > a much longer period, say on the order of a minute of runtime, to have > numbers that are trustworthy. > > regards, tom lane >