From: Jignesh K. Shah <J.K.Shah@Sun.COM>
To: Tom Lane <tgl@sss.pgh.pa.us>
Cc: Simon Riggs <simon@2ndquadrant.com>
Cc: Josh Berkus <josh@agliodbs.com>
Cc: pgsql-performance@postgresql.org, Alvaro Herrera <alvherre@commandprompt.com>
Subject: Re: User concurrency thresholding: where do I look?
Date: Thu, 26 Jul 2007 11:27:30 -0400
Message-ID: <46A8BD62.2080904@sun.com> (raw)
In-Reply-To: <26825.1185460816@sss.pgh.pa.us>
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>
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" <J.K.Shah@Sun.COM> 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
>
Reply instructions:
You may reply publicly to this message via plain-text email
using any one of the following methods:
* Reply to all the recipients using the --to and --cc options:
reply via email
To: pgsql-performance@postgresql.org
Cc: J.K.Shah@Sun.COM, tgl@sss.pgh.pa.us, simon@2ndquadrant.com, josh@agliodbs.com, alvherre@commandprompt.com
Subject: Re: User concurrency thresholding: where do I look?
In-Reply-To: <46A8BD62.2080904@sun.com>
* Save the following mbox file, import it into your mail client,
and reply-to-all from there: mbox
This inbox is served by DDX for PostgreSQL; see mirroring instructions
for how to clone and mirror all data and code used for this inbox