Re: Why are we waiting? - Mailing list pgsql-hackers
| From | Staale Smedseng |
|---|---|
| Subject | Re: Why are we waiting? |
| Date | |
| Msg-id | 1202319897.809.269.camel@khepri29 Whole thread Raw |
| In response to | Re: Why are we waiting? (Simon Riggs <simon@2ndquadrant.com>) |
| Responses |
Re: Why are we waiting?
|
| List | pgsql-hackers |
> 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();
}
pgsql-hackers by date: