Re: Why are we waiting? - Mailing list pgsql-hackers

From Staale Smedseng
Subject Re: Why are we waiting?
Date
Msg-id 1202308255.809.250.camel@khepri29
Whole thread Raw
In response to Why are we waiting?  (Simon Riggs <simon@2ndquadrant.com>)
Responses Re: Why are we waiting?  (Simon Riggs <simon@2ndquadrant.com>)
Re: Why are we waiting?  (Gregory Stark <stark@enterprisedb.com>)
List pgsql-hackers
On Mon, 2008-02-04 at 19:46, Simon Riggs wrote:
> We've got various facilities now for looking at LWLock waits, but I'd
> like to have more information about the *reasons* for lock waits.
> 
> I know its possible to get backtraces in Dtrace at various tracepoints
> but that can be fairly hard to interpret.

Simon,

A couple of guys here at Sun have started looking at trying to improve
the scaling on Sun's T2000 Niagara servers (single core, 32 HW-threads).

We mostly use various DTrace scripts to monitor locking usage. We'd be
happy to share results, probes and DTrace scripts for monitoring if you
like.

So far we've found lock contention (especially for the ProcArrayLock) to
be the likely source for our inability to saturate the CPU with a TPC-C
like OLTP load with >1000 users.

The following shows average time spent in and waiting for exclusive
ProcArrayLock vs the time used in the transaction through commit, (i.e.,
up until the exclusive ProcArrayLock acquire to update the PGPROC
setting transaction no longer running):
 # ./pg-lwlock-procarray.d $(pgrep -n postgres)
             postgres`LWLockAcquire             postgres`ProcArrayEndTransaction+0x10
postgres`CommitTransaction+0xf0            postgres`CommitTransactionCommand+0x90
postgres`finish_xact_command+0x60            postgres`exec_execute_message+0x3b4
postgres`PostgresMain+0x13a0            postgres`BackendRun+0x27c             postgres`BackendStartup+0xe0
postgres`ServerLoop+0x1a0            postgres`PostmasterMain+0xcbc             postgres`main+0x1d8
postgres`_start+0x108             23 avg lwlock acquire service time [ns]                 193051989 transaction-commit
[count]                                 23 transaction-start [count]                                   23 avg
transactiontime [ns]                             12763079
 

The stack trace shows that the only time the lock is acquired
exclusively is from the call to ProcArrayEndTransaction() in
CommitTransaction().

Also, an interesting observation is that the hot locks seem to have
changed from v8.2 to v8.3, making the ProcArrayLock more contended. See
the following outputs:

PostgreSQL 8.2 (32-bit):
 -bash-3.00# ./825_lwlock_wait.d
            Lock Id            Mode           Count   FirstLockMgrLock          Shared               2
ProcArrayLock         Shared             209         XidGenLock       Exclusive            1030         XidGenLock
   Shared            1215      WALInsertLock       Exclusive            3942    CLogControlLock          Shared
  4113      ProcArrayLock       Exclusive            6929       WALWriteLock       Exclusive           17155
CLogControlLock      Exclusive          128182
 
            Lock Id   Combined Time (ns)   FirstLockMgrLock                24705      WALInsertLock
79644210        XidGenLock            179886846      ProcArrayLock           1486950738       WALWriteLock
18425400504   CLogControlLock        1507388036453
 



PostgreSQL 8.3 (64-bit):
 -bash-3.00# ./83_lwlock_wait.d
            Lock Id            Mode           Count         SInvalLock       Exclusive               1
WALWriteLock      Exclusive               1         SInvalLock          Shared              20    CLogControlLock
  Shared             534    CLogControlLock       Exclusive             845         XidGenLock       Exclusive
 1140      ProcArrayLock          Shared            1821      WALInsertLock       Exclusive           17043
ProcArrayLock      Exclusive           49762
 
            Lock Id            Mode   Combined Time (ns)         SInvalLock       Exclusive                17216
SInvalLock          Shared               531129       WALWriteLock       Exclusive              2003064
CLogControlLock         Shared             61325819    CLogControlLock       Exclusive             73509195
XidGenLock      Exclusive            929477929      WALInsertLock       Exclusive          17941476941
ProcArrayLock         Shared          31114676303      ProcArrayLock       Exclusive         888356047549
 



Regards,
Staale Smedseng
Database Technology Group, Sun Microsystems




pgsql-hackers by date:

Previous
From: Simon Riggs
Date:
Subject: HeapTupleSatisfies micro tuning
Next
From: "Dave Page"
Date:
Subject: Re: PostgreSQL 8.4 development plan