Re: Why are we waiting?

Last try for the script/results (truncating less significant portions of
output which are too big)

Staale Smedseng wrote:
>
> her locks should have been output correctly, however.
>
> But as Tom pointed out, the dynamic locks were not in the equation. So
> now we're measuring all lock waits instead of assuming. :-)
>
> Staale
>
>
>

Here are some recent runs on 4-quadcore xeons using PostgreSQL 8.3.0
with 10-second runs

Hope it gets through this time

-Jignesh

for about 500users :
Lock Id Mode Count
64 Shared 754
53 Exclusive 846
43 Exclusive 1379
11 Shared 2038
3 Exclusive 2376
47 Exclusive 2900
4 Shared 3194
42 Exclusive 3389
50 Exclusive 3689
41 Exclusive 5280
11 Exclusive 6560
48 Exclusive 10837
7 Exclusive 20599
44 Exclusive 29193
46 Exclusive 30299
4 Exclusive 66303

Lock Id Mode Combined Time (ns)
43 Exclusive 3440644758
47 Exclusive 6392480847
50 Exclusive 7199215298
42 Exclusive 7865126413
11 Exclusive 8503940437
4 Shared 9142071412
61 Shared 10613733376
41 Exclusive 14380504651
48 Exclusive 16631996177
7 Exclusive 17485716438
46 Exclusive 61584135053
44 Exclusive 68889040292
4 Exclusive 177458486936

For about 700 Users:

Lock Id Mode Count
3 Exclusive 2873
4 Shared 3436
47 Exclusive 3555
11 Shared 4098
50 Exclusive 4392
42 Exclusive 4573
11 Exclusive 6209
41 Exclusive 7552
48 Exclusive 12335
7 Exclusive 22469
44 Exclusive 36987
46 Exclusive 38467
4 Exclusive 81453

Lock Id Mode Combined Time (ns)
7 Exclusive 12033761450
43 Exclusive 12217953092
50 Exclusive 15454797539
47 Exclusive 15684068953
42 Exclusive 19365161311
4 Shared 27038955376
48 Exclusive 32990318986
41 Exclusive 48350689916
46 Exclusive 193727946721
44 Exclusive 212025745038
4 Exclusive 713263386624

At 1000 users

Lock Id Mode Count
59 Shared 10475
58 Shared 11062
57 Shared 13726
7 Exclusive 18548
44 Exclusive 29714
46 Exclusive 33886
4 Exclusive 74773
11 Exclusive 79596

Lock Id Mode Combined Time (ns)
43 Exclusive 9067359926
47 Exclusive 12259067669
50 Exclusive 13239372833
42 Exclusive 16534292830
7 Exclusive 23505490039
48 Exclusive 24991948402
41 Exclusive 33874749560
11 Shared 43963854482
4 Shared 64098606143
63 Shared 130988696365
64 Shared 137865936811
61 Shared 140978086498
59 Shared 161661023016
62 Shared 163857754020
58 Shared 167946299990
44 Exclusive 220719773416
57 Shared 245170386594
46 Exclusive 326272389569
11 Exclusive 1312009781095
4 Exclusive 2403450038504

4 is ProcArray..
ClogControlLock is not completely out but I dont see it consistently
like ProcArrayLock. It would show up in few cases if I continue taking
different snapshots of the output (maybe when Checkpoint kicks in or
something , I dont know..)

Lock Id Mode Count
3 Exclusive 160
7 Exclusive 396
11 Shared 828
44 Exclusive 991
46 Exclusive 1093
4 Exclusive 1550
62 Shared 20332
57 Shared 21244
64 Shared 21492
63 Shared 21791
61 Shared 22132
58 Shared 23747
60 Shared 26230
11 Exclusive 158168

Lock Id Mode Combined Time (ns)
64864 Shared 3743818402
10830 Shared 3835685469
89688 Shared 4164484448
84354 Shared 4268747714
870 Shared 4376161411
17078 Shared 4712788740
11 Shared 17718901870
62 Shared 331016914134
57 Shared 340929880655
64 Shared 355793689545
63 Shared 362464073193
61 Shared 362561852786
58 Shared 388597307969
60 Shared 430378269549
11 Exclusive 2641836280591

Now the script

# cat 83_all_wait.d
#!/usr/sbin/dtrace -qs

/*
* Usage : 83_all_wait.d
* Description: Show number and total time of LWLock waits by lock id and
mode
* Author : Jignesh Shah
*/

dtrace:::BEGIN
{
lckmode[0] = "Exclusive";
lckmode[1] = "Shared";
/* Only for reference not used... Refer to src/include/storage/lwlock.h */
lckid[0] = "BufFreelistLock";
lckid[1] = "ShmemIndexLock";
lckid[2] = "OidGenLock";
lckid[3] = "XidGenLock";
lckid[4] = "ProcArrayLock";
lckid[5] = "SInvalLock";
lckid[6] = "FreeSpaceLock";
lckid[7] = "WALInsertLock";
lckid[8] = "WALWriteLock";
lckid[9] = "ControlFileLock";
lckid[10] = "CheckpointLock";
lckid[11] = "CLogControlLock";
lckid[12] = "SubtransControlLock";
lckid[13] = "MultiXactGenLock";
lckid[14] = "MultiXactOffsetControlLock";
lckid[15] = "MultiXactMemberControlLock";
lckid[16] = "RelCacheInitLock";
lckid[17] = "BgWriterCommLock";
lckid[18] = "TwoPhaseStateLock";
lckid[19] = "TablespaceCreateLock";
lckid[20] = "BtreeVacuumLock";
lckid[21] = "AddinShmemInitLock";
lckid[22] = "AutovacuumLock";
lckid[23] = "AutovacuumScheduleLock";
lckid[24] = "SyncScanLock";
lckid[25] = "FirstBufMappingLock";
lckid[26] = "FirstLockMgrLock";

}

postgresql*:::lwlock-startwait
{
self->ts[arg0]=timestamp;
@count[arg0, lckmode[arg1]] = count();
}

postgresql*:::lwlock-endwait
/self->ts[arg0]/
{
@time[arg0 ,lckmode[arg1]] = sum (timestamp - self->ts[arg0]);
self->ts[arg0]=0;
}

dtrace:::END {
printf("\n%20s %15s %15s\n", "Lock Id", "Mode", "Count");
printa("%20d %15s %(at)15d\n",@count);

printf("\n%20s %15s %20s\n", "Lock Id","Mode", "Combined Time (ns)");
printa("%20d %15s %(at)20d\n",@time);
}

tick-10sec
{
exit(0);
}