Patch LWlocks instrumentation

Pierre Frédéric Caillaud <lists@peufeu.com>

From: Pierre Frédéric Caillaud <lists@peufeu.com>
To: "Jeff Janes" <jeff.janes@gmail.com>, "Tom Lane" <tgl@sss.pgh.pa.us>
Cc: pgsql-hackers@postgresql.org
Date: 2009-09-14T10:22:22Z
Lists: pgsql-hackers

Attachments

A little bit of a reply to Jeff's email about WALInsertLock.

This patch instruments LWLocks, it is controlled with the following  
#define's in lwlock.c :

LWLOCK_STATS
LWLOCK_TIMING_STATS

It is an upgrade of current lwlocks stats.

When active, at backend exit, it will display stats as shown below (here,  
we have a parallel COPY with 4 concurrent processes into the same table,  
on a 4 core machine).
If the (rather wide) sample output is mangled in your mail client, I've  
attached it as a separate text file.

-------- Lock stats for PID 22403
     PID    Lock      ShAcq     ShWait     ShWaitT     ShHeldT       
ExAcq     ExWait             ExWaitT                ExHeldT     Name
   22403       7          0          0        0.00        0.00     
2500002     730338       24.02 ( 53.49 %)        7.25 ( 16.14 %)  WALInsert
   22403       8          0          0        0.00        0.00       
19501         73        3.48 (  7.75 %)        0.40 (  0.88 %)  WALWrite

-------- Lock stats for PID 22404
     PID    Lock      ShAcq     ShWait     ShWaitT     ShHeldT       
ExAcq     ExWait             ExWaitT                ExHeldT     Name
   22404       7          0          0        0.00        0.00     
2500002     724683       23.34 ( 51.59 %)        8.24 ( 18.20 %)  WALInsert
   22404       8          0          0        0.00        0.00       
19418         90        4.37 (  9.67 %)        0.44 (  0.97 %)  WALWrite

-------- Lock stats for PID 22402
     PID    Lock      ShAcq     ShWait     ShWaitT     ShHeldT       
ExAcq     ExWait             ExWaitT                ExHeldT     Name
   22402       7          0          0        0.00        0.00     
2500002     735958       24.06 ( 52.73 %)        8.05 ( 17.63 %)  WALInsert
   22402       8          0          0        0.00        0.00       
19154         97        4.21 (  9.22 %)        0.39 (  0.85 %)  WALWrite

-------- Lock stats for PID 22400
     PID    Lock      ShAcq     ShWait     ShWaitT     ShHeldT       
ExAcq     ExWait             ExWaitT                ExHeldT     Name
   22400       7          0          0        0.00        0.00     
2500002     736265       25.50 ( 55.59 %)        6.74 ( 14.70 %)  WALInsert
   22400       8          0          0        0.00        0.00       
19391         66        2.95 (  6.42 %)        0.39 (  0.85 %)  WALWrite


Here we see that PID 22400 spent :

25.50 s waiting to get exclusive on WALInsert
6.74  s while holding exclusive on WALInsert

The percentages represent the fraction of time relative to the backend  
process' lifetime.
Here, I've exited the processes right after committing the transactions,  
but if you use psql and want accurate %, you'll need to exit quickly after  
the query to benchmark.

Here, for example, backends spend more than 50% of their time waiting on  
WALInsert...