Why are we waiting?

Simon Riggs <simon@2ndquadrant.com> writes:

I'm thinking of adding an extra parameter onto every call to
LockBuffer() and LWLockAcquire() to explain the reason for the lock
request.

Maybe I'm missing something, but I don't see what this would buy us,
except for being able to track which call site resulted in a wait;
which can already be measured with dtrace, no?

I'm hesitant to decorate such widely-used functions with extra tracing
information. You'd be breaking every third-party module and pending
patch that uses either function, and imposing some performance penalty
(probably not much, but it's hard to be sure) into the indefinite
future, for a performance measurement need that might be fleeting.

Basically I'd rather try to attack the problem with dtrace ...

regards, tom lane

On Mon, 2008-02-04 at 17:06 -0500, Tom Lane wrote:

Basically I'd rather try to attack the problem with dtrace ...

OK. I'll switch to Solaris. Or do you something I don't about dtrace on
linux?

--
Simon Riggs
2ndQuadrant http://www.2ndQuadrant.com

Simon Riggs wrote:

On Mon, 2008-02-04 at 17:06 -0500, Tom Lane wrote:

Basically I'd rather try to attack the problem with dtrace ...

OK. I'll switch to Solaris. Or do you something I don't about dtrace on
linux?

One idea would be to add new arguments to LWLockAcquire as you suggest,
but instead of modifying all call sites, decorate it with a macro that
passes __FILE__ and __LINE__ as the extra arguments. The good thing
about that is that it's a relatively small patch and you can easily
switch it on/off with a #ifdef. And there's no need to push for
inclusion of that into CVS, because it would be an easy patch to
maintain yourself.

--
Heikki Linnakangas
EnterpriseDB http://www.enterprisedb.com

On Tue, 2008-02-05 at 14:14 +0000, Heikki Linnakangas wrote:

Simon Riggs wrote:

On Mon, 2008-02-04 at 17:06 -0500, Tom Lane wrote:

Basically I'd rather try to attack the problem with dtrace ...

OK. I'll switch to Solaris. Or do you something I don't about dtrace on
linux?

One idea would be to add new arguments to LWLockAcquire as you suggest,
but instead of modifying all call sites, decorate it with a macro that
passes __FILE__ and __LINE__ as the extra arguments. The good thing
about that is that it's a relatively small patch and you can easily
switch it on/off with a #ifdef. And there's no need to push for
inclusion of that into CVS, because it would be an easy patch to
maintain yourself.

Thanks for the idea. It had occurred to me to make a private patch, but
I prefer my patches to be open, so they're easier to discuss results
arising from them.

--
Simon Riggs
2ndQuadrant http://www.2ndQuadrant.com

Simon Riggs <simon@2ndquadrant.com> writes:

On Mon, 2008-02-04 at 17:06 -0500, Tom Lane wrote:

Basically I'd rather try to attack the problem with dtrace ...

OK. I'll switch to Solaris. Or do you something I don't about dtrace on
linux?

Nope :-(. The SystemTap guys keep promising support for userspace
probes but it's not there yet.

regards, tom lane

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

On Wed, 2008-02-06 at 15:30 +0100, Staale Smedseng wrote:

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.

Thanks for this Staale.

Lock Id Mode Count
ProcArrayLock Shared 1821
ProcArrayLock Exclusive 49762

Lock Id Mode Combined Time (ns)
ProcArrayLock Shared 31114676303
ProcArrayLock Exclusive 888356047549

Which looks like a mean service time of 17ms for X lock waiters.

What is the frequency distribution of lock wait time on ProcArrayLock?
Does the distribution vary over time?

--
Simon Riggs
2ndQuadrant http://www.2ndQuadrant.com

"Staale Smedseng" <Staale.Smedseng@Sun.COM> writes:

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

I'm not sure but I think that's only true in 8.3. As I understood it in 8.2
transaction start also needed the exclusive lock.

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):
...
PostgreSQL 8.3 (64-bit):
...

I'm not sure 32-bit and 64-bit cases are going to be directly comparable. We
could have a problem with cache line aliasing on only one or the other for
example.

But that is a pretty striking difference. Does the 8.3 run complete more
transactions in that time?

--
Gregory Stark
EnterpriseDB http://www.enterprisedb.com
Ask me about EnterpriseDB's 24x7 Postgres support!

What is the frequency distribution of lock wait time on ProcArrayLock?

See below for wait time distributions for ProcArrayLock (both shared and
exclusive). The time measured is from entry into LWLockAcquire() until
return. I've recorded the same data in two different resolutions (ms,
and us for the lower part of the distribution). The DTrace script is at
the bottom.

These results are for 1000 TPC-C like clients, and measured over the
1000 PostgreSQL processes over a period of 10 seconds.

Does the distribution vary over time?

Hmm... I will have to get back to you on that one.

Staale

CPU ID FUNCTION:NAME
6 71245 :tick-10sec

Total LW_EXCLUSIVE 25178
Total Transaction Starts 25679
Total LW_SHARED 107211
LW_SHARED [ms]
value ------------- Distribution ------------- count
< 0 | 0
0 |@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@ 100565
10 | 1
20 | 0
30 | 0
40 | 0
50 | 0
60 | 0
70 | 6
80 | 304
90 |@ 1370
100 |@ 2685
110 |@ 1731
120 | 307
130 | 13
140 | 0
150 | 0
160 | 5
170 | 4
180 | 26
190 | 36
200 | 24
210 | 61
220 | 49
230 | 15
240 | 0
250 | 0
260 | 0
270 | 0
280 | 2
290 | 2
300 | 0
310 | 2
320 | 1
330 | 1
340 | 0
350 | 0
360 | 0
370 | 0
380 | 0
390 | 0
400 | 1
410 | 0

LW_EXCLUSIVE [ms]
value ------------- Distribution ------------- count
< 0 | 0
0 |@@ 1565
10 | 0
20 | 0
30 | 0
40 | 0
50 | 0
60 | 0
70 | 16
80 |@ 894
90 |@@@@@@@ 4108
100 |@@@@@@@@@@@@@ 8090
110 |@@@@@@@@ 4863
120 |@ 595
130 | 64
140 | 14
150 | 0
160 | 4
170 | 93
180 | 262
190 |@ 549
200 |@ 854
210 |@@ 976
220 |@ 770
230 | 268
240 | 40
250 | 2
260 | 9
270 | 29
280 | 46
290 | 94
300 | 134
310 | 169
320 | 164
330 | 146
340 | 94
350 | 13
360 | 2
370 | 8
380 | 15
390 | 17
400 | 20
410 | 37
420 | 27
430 | 32
440 | 29
450 | 8
460 | 4
470 | 2
480 | 1
490 | 3

= 500 | 48

LW_SHARED [us]
value ------------- Distribution ------------- count
0 | 0
10 | 39
20 |@@@@@@@@@@@@ 31038
30 |@@@@@@@@@@@@@@@@@@@@@@@@@ 66010
40 |@ 2409
50 | 103
60 | 145
70 | 85
80 | 68
90 | 57
100 | 40
110 | 33
120 | 37
130 | 24
140 | 15
150 | 35
160 | 26
170 | 35
180 | 24
190 | 16
200 | 12
210 | 13
220 | 13
230 | 8
240 | 9
250 | 3
260 | 4
270 | 3
280 | 2
290 | 4
300 | 3
310 | 3
320 | 3
330 | 2
340 | 0
350 | 1
360 | 2
370 | 0
380 | 0
390 | 2
400 | 1
410 | 2
420 | 0
430 | 0
440 | 1
450 | 0
460 | 5
470 | 1
480 | 1
490 | 4
500 | 6
510 | 1
520 | 1
530 | 0
540 | 1
550 | 1
560 | 2
570 | 0
580 | 0
590 | 0
600 | 0
610 | 1
620 | 0
630 | 0
640 | 0
650 | 0
660 | 0
670 | 1
680 | 0
690 | 2
700 | 1
710 | 1
720 | 3
730 | 0
740 | 1
750 | 0
760 | 0
770 | 0
780 | 0
790 | 0
800 | 0
810 | 0
820 | 0
830 | 0
840 | 0
850 | 0
860 | 1
870 | 0
880 | 0
890 | 0
900 | 0
910 | 0
920 | 1
930 | 0
940 | 0
950 | 2
960 | 0
970 | 0
980 | 1
990 | 0

= 1000 |@@@ 6843

LW_EXCLUSIVE [us]
value ------------- Distribution ------------- count
10 | 0
20 |@ 357
30 |@@ 1166
40 | 35
50 | 1
60 | 1
70 | 1
80 | 1
90 | 0
100 | 0
110 | 0
120 | 0
130 | 1
140 | 0
150 | 0
160 | 0
170 | 0
180 | 0
190 | 0
200 | 0
210 | 0
220 | 0
230 | 0
240 | 0
250 | 0
260 | 0
270 | 0
280 | 0
290 | 0
300 | 0
310 | 0
320 | 0
330 | 0
340 | 0
350 | 0
360 | 0
370 | 0
380 | 0
390 | 0
400 | 0
410 | 0
420 | 0
430 | 0
440 | 0
450 | 0
460 | 0
470 | 0
480 | 0
490 | 0
500 | 0
510 | 0
520 | 0
530 | 0
540 | 0
550 | 0
560 | 0
570 | 0
580 | 0
590 | 0
600 | 0
610 | 0
620 | 0
630 | 0
640 | 0
650 | 0
660 | 0
670 | 0
680 | 0
690 | 0
700 | 0
710 | 0
720 | 0
730 | 0
740 | 0
750 | 0
760 | 0
770 | 0
780 | 0
790 | 0
800 | 0
810 | 0
820 | 0
830 | 0
840 | 0
850 | 0
860 | 0
870 | 0
880 | 0
890 | 0
900 | 0
910 | 0
920 | 0
930 | 0
940 | 0
950 | 0
960 | 0
970 | 0
980 | 0
990 | 0

= 1000 |@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@ 23615

--------------------------------------------------------------

#!/usr/sbin/dtrace -s

/*
* Show ProcArrayLock wait time
*
* $Id$
*/

BEGIN
{
self->ts = 0;
}

tick-10sec
{
exit(0);
}

/*
* Accumulate average time spent from start of LWLockAcquire()
* until return from LWLockAcquire().
*/
postgresql$1:::lwlock-acquire-begin
/ arg0 == 4 /
{
self->ts = timestamp;
self->mode = arg1;
}

postgresql$1:::lwlock-acquire-end
/ self->ts /
{
@acqcount[self->mode==0?"Total LW_EXCLUSIVE":"Total LW_SHARED"]
= count();

/* whole frequency distribution 0-500ms */
@wholedist[self->mode==0?"LW_EXCLUSIVE [ms]":"LW_SHARED [ms]"]
= lquantize((timestamp - self->ts)/1000000, 0, 500, 10);

/* the lower part of the distribution in detail 0-1000us */
@lowdist[self->mode==0?"LW_EXCLUSIVE [us]":"LW_SHARED [us]"]
= lquantize((timestamp - self->ts)/1000, 0, 1000, 10);

self->ts = 0;
}

postgresql$1:::transaction-start
{
@acqcount["Total Transaction Starts"] = count();
}

On Wed, 2008-02-06 at 18:44 +0100, Staale Smedseng wrote:

What is the frequency distribution of lock wait time on ProcArrayLock?

See below for wait time distributions for ProcArrayLock (both shared and
exclusive). The time measured is from entry into LWLockAcquire() until
return. I've recorded the same data in two different resolutions (ms,
and us for the lower part of the distribution). The DTrace script is at
the bottom.

These results are for 1000 TPC-C like clients, and measured over the
1000 PostgreSQL processes over a period of 10 seconds.

Thanks! Interesting resonance pattern.

--
Simon Riggs
2ndQuadrant http://www.2ndQuadrant.com

I'm not sure 32-bit and 64-bit cases are going to be directly
comparable. We
could have a problem with cache line aliasing on only one or the
other for
example.

Agreed, this is likely comparing apples and oranges. I'll see if I can
get a one-to-one comparison done (these were the numbers I had close
by when writing the email).

But that is a pretty striking difference. Does the 8.3 run complete
more
transactions in that time?

I'll make sure to include those numbers as well. :)

Staale

Gregory Stark <stark@enterprisedb.com> writes:

"Staale Smedseng" <Staale.Smedseng@Sun.COM> writes:

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):
...
PostgreSQL 8.3 (64-bit):
...

I'm not sure 32-bit and 64-bit cases are going to be directly comparable. We
could have a problem with cache line aliasing on only one or the other for
example.

Yeah, I find these numbers highly dubious. AFAIR we didn't do anything
that would have reduced CLogControlLock contention, and we definitely
did work to reduce ProcArrayLock contention, so the claimed results seem
directly opposite to expectation. I am wondering if the waits are being
attributed to the right locks --- I remember such an error in a previous
set of dtrace results, and some of the other details such as claiming
shared lock delays but no exclusive lock delays for FirstLockMgrLock
seem less than credible as well.

regards, tom lane

On Wed, 2008-02-06 at 13:55 -0500, Tom Lane wrote:

Gregory Stark <stark@enterprisedb.com> writes:

"Staale Smedseng" <Staale.Smedseng@Sun.COM> writes:

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):
...
PostgreSQL 8.3 (64-bit):
...

I'm not sure 32-bit and 64-bit cases are going to be directly comparable. We
could have a problem with cache line aliasing on only one or the other for
example.

Yeah, I find these numbers highly dubious. AFAIR we didn't do anything
that would have reduced CLogControlLock contention, and we definitely
did work to reduce ProcArrayLock contention, so the claimed results seem
directly opposite to expectation. I am wondering if the waits are being
attributed to the right locks --- I remember such an error in a previous
set of dtrace results, and some of the other details such as claiming
shared lock delays but no exclusive lock delays for FirstLockMgrLock
seem less than credible as well.

There were only 2 lock delays for FirstLockMgrLock in SHARED mode, so it
seems believable that there were 0 lock delays in EXCLUSIVE mode.

I assumed that Staale is running with clog buffers tweaked? Can you
confirm Staale?

--
Simon Riggs
2ndQuadrant http://www.2ndQuadrant.com

Simon Riggs <simon@2ndquadrant.com> writes:

There were only 2 lock delays for FirstLockMgrLock in SHARED mode, so it
seems believable that there were 0 lock delays in EXCLUSIVE mode.

Not really, considering the extremely limited use of LW_SHARED in lock.c
(GetLockConflicts is used only by CREATE INDEX CONCURRENTLY, and
GetLockStatusData only by the pg_locks view). For the type of benchmark
that I gather this is, there should be *zero* LW_SHARED acquisitions at
all. And even if there are some, they could only be blocking against
the (undoubtedly much more frequent) LW_EXCLUSIVE acquisitions; it's not
very credible that there is zero contention among the LW_EXCLUSIVE locks
yet a few shared acquirers manage to get burnt.

regards, tom lane

On Wed, 2008-02-06 at 14:42 -0500, Tom Lane wrote:

Simon Riggs <simon@2ndquadrant.com> writes:

There were only 2 lock delays for FirstLockMgrLock in SHARED mode, so it
seems believable that there were 0 lock delays in EXCLUSIVE mode.

Not really, considering the extremely limited use of LW_SHARED in lock.c
(GetLockConflicts is used only by CREATE INDEX CONCURRENTLY, and
GetLockStatusData only by the pg_locks view). For the type of benchmark
that I gather this is, there should be *zero* LW_SHARED acquisitions at
all. And even if there are some, they could only be blocking against
the (undoubtedly much more frequent) LW_EXCLUSIVE acquisitions; it's not
very credible that there is zero contention among the LW_EXCLUSIVE locks
yet a few shared acquirers manage to get burnt.

...but the total wait time on those lock waits was 24 microseconds. I
hardly call that burnt.

--
Simon Riggs
2ndQuadrant http://www.2ndQuadrant.com

Simon Riggs <simon@2ndquadrant.com> writes:

On Wed, 2008-02-06 at 14:42 -0500, Tom Lane wrote:

Not really, considering the extremely limited use of LW_SHARED in lock.c
(GetLockConflicts is used only by CREATE INDEX CONCURRENTLY, and
GetLockStatusData only by the pg_locks view). For the type of benchmark
that I gather this is, there should be *zero* LW_SHARED acquisitions at
all. And even if there are some, they could only be blocking against
the (undoubtedly much more frequent) LW_EXCLUSIVE acquisitions; it's not
very credible that there is zero contention among the LW_EXCLUSIVE locks
yet a few shared acquirers manage to get burnt.

...but the total wait time on those lock waits was 24 microseconds. I
hardly call that burnt.

What you are failing to grasp is that the data is simply not credible
(unless perhaps Staale fesses up that his benchmark includes a whole lot
of pg_locks monitoring, in which case I'd want to see it redone without
anyway).

regards, tom lane

On Wed, 2008-02-06 at 19:55, Tom Lane wrote:

I am wondering if the waits are being
attributed to the right locks --- I remember such an error in a previous
set of dtrace results, and some of the other details such as claiming
shared lock delays but no exclusive lock delays for FirstLockMgrLock
seem less than credible as well.

Good catch. We've checked the DTrace scripts against the respective
versions of lwlock.h, and the FirstLockMgrLock is off (this is actually
the results for FirstBufMappingLock).

However, this is the last lock in the enum that we trace, the other
lower-numbered lock enums were correctly mapped. (In particular the
ProcArrayLock which we've been puzzled by.)

And also, there was no clog buffer twaking or pg_lock monitoring done
when this benchmark was run, AFAIK.

We'll redo the benchmarks and post new scripts and results.

Staale

Staale Smedseng <Staale.Smedseng@Sun.COM> writes:

Good catch. We've checked the DTrace scripts against the respective
versions of lwlock.h, and the FirstLockMgrLock is off (this is actually
the results for FirstBufMappingLock).

However, this is the last lock in the enum that we trace, the other
lower-numbered lock enums were correctly mapped. (In particular the
ProcArrayLock which we've been puzzled by.)

Hmm, do you mean that you're just neglecting to collect any stats about
all the dynamically assigned locks? That doesn't seem like it's going
to offer a very good view of what's going on. I think the most useful
stats would include aggregate wait data for all the lockmgr locks,
all the bufmapping locks, all the buffer content locks, and all the
buffer I/O locks. We'd like to think that contention for those would
be low because of the partitioning ... but the point of measuring is
to find out, not just hope.

regards, tom lane

On Thu, 2008-02-07 at 16:29 +0100, Staale Smedseng wrote:

On Wed, 2008-02-06 at 19:55, Tom Lane wrote:

I am wondering if the waits are being
attributed to the right locks --- I remember such an error in a previous
set of dtrace results, and some of the other details such as claiming
shared lock delays but no exclusive lock delays for FirstLockMgrLock
seem less than credible as well.

Good catch. We've checked the DTrace scripts against the respective
versions of lwlock.h, and the FirstLockMgrLock is off (this is actually
the results for FirstBufMappingLock).

I just realised you are using a lookup to get the text for the name of
the lock. You used the same lookup table for both releases?

--
Simon Riggs
2ndQuadrant http://www.2ndQuadrant.com