Re: Why are we waiting? - Mailing list pgsql-hackers

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 %@15d\n",@count);
     printf("\n%20s %15s %20s\n", "Lock Id","Mode", "Combined Time (ns)");     printa("%20d %15s %@20d\n",@time);
}

tick-10sec
{     exit(0);
}