Re: Why are we waiting?

From: Staale Smedseng <Staale(dot)Smedseng(at)Sun(dot)COM>
To: Simon Riggs <simon(at)2ndquadrant(dot)com>
Cc: pgsql-hackers(at)postgresql(dot)org
Subject: Re: Why are we waiting?
Date: 2008-02-06 14:30:56
Message-ID: 1202308255.809.250.camel@khepri29
Views: Raw Message | Whole Thread | Download mbox | Resend email
Thread:
Lists: 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 transaction time [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

In response to

Responses

Browse pgsql-hackers by date

  From Date Subject
Next Message Dave Page 2008-02-06 14:42:35 Re: PostgreSQL 8.4 development plan
Previous Message Simon Riggs 2008-02-06 14:24:45 HeapTupleSatisfies micro tuning