Re: Why are we waiting?

> 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();
}