varnishd: add lock duration

[asadsa92]

Our instrumented locks lacks a way to tell how long a lock was held before released. Just looking at the number of time the lock was taken is not enough. Some locks are more expensive than others (held for longer).

This PR adds duration to each instrumented lock given in microsecond resolution.

Example output:

LCK.ban.creat                                 1         0.01 Created locks
LCK.ban.destroy                               0         0.00 Destroyed locks
LCK.ban.locks                                12         0.12 Lock Operations
LCK.ban.dur_us                               14         0.14 Lock duration
LCK.ban.dbg_busy                              0         0.00 Contended lock operations
LCK.ban.dbg_try_fail                          0         0.00 Contended trylock operations
LCK.busyobj.creat                             0         0.00 Created locks
LCK.busyobj.destroy                           0         0.00 Destroyed locks
LCK.busyobj.locks                             0         0.00 Lock Operations
LCK.busyobj.dur_us                            0         0.00 Lock duration
LCK.busyobj.dbg_busy                          0         0.00 Contended lock operations
LCK.busyobj.dbg_try_fail                      0         0.00 Contended trylock operations
LCK.cli.creat                                 1         0.01 Created locks
LCK.cli.destroy                               0         0.00 Destroyed locks
LCK.cli.locks                                46         0.46 Lock Operations
LCK.cli.dur_us                             1393        13.79 Lock duration
LCK.cli.dbg_busy                              0         0.00 Contended lock operations
LCK.cli.dbg_try_fail                          0         0.00 Contended trylock operations
LCK.director.creat                            1         0.01 Created locks
LCK.director.destroy                          0         0.00 Destroyed locks
LCK.director.locks                            0         0.00 Lock Operations
LCK.director.dur_us                           0         0.00 Lock duration
LCK.director.dbg_busy                         0         0.00 Contended lock operations
LCK.director.dbg_try_fail                     0         0.00 Contended trylock operations
LCK.exp.creat                                 1         0.01 Created locks
LCK.exp.destroy                               0         0.00 Destroyed locks
LCK.exp.locks                                34         0.34 Lock Operations
LCK.exp.dur_us                              282         2.79 Lock duration
LCK.exp.dbg_busy                              0         0.00 Contended lock operations
LCK.exp.dbg_try_fail                          0         0.00 Contended trylock operations
LCK.hcb.creat                                 1         0.01 Created locks
LCK.hcb.destroy                               0         0.00 Destroyed locks
LCK.hcb.locks                                 1         0.01 Lock Operations
LCK.hcb.dur_us                                0         0.00 Lock duration
LCK.hcb.dbg_busy                              0         0.00 Contended lock operations
LCK.hcb.dbg_try_fail                          0         0.00 Contended trylock operations
LCK.lru.creat                                 2         0.02 Created locks
LCK.lru.destroy                               0         0.00 Destroyed locks
LCK.lru.locks                                 0         0.00 Lock Operations
LCK.lru.dur_us                                0         0.00 Lock duration
LCK.lru.dbg_busy                              0         0.00 Contended lock operations
LCK.lru.dbg_try_fail                          0         0.00 Contended trylock operations
LCK.mempool.creat                             5         0.05 Created locks
LCK.mempool.destroy                           0         0.00 Destroyed locks
LCK.mempool.locks                           477         4.72 Lock Operations
LCK.mempool.dur_us                          377         3.73 Lock duration
LCK.mempool.dbg_busy                          0         0.00 Contended lock operations
LCK.mempool.dbg_try_fail                      0         0.00 Contended trylock operations
LCK.objhdr.creat                              1         0.01 Created locks
LCK.objhdr.destroy                            0         0.00 Destroyed locks
LCK.objhdr.locks                              0         0.00 Lock Operations
LCK.objhdr.dur_us                             0         0.00 Lock duration
LCK.objhdr.dbg_busy                           0         0.00 Contended lock operations
LCK.objhdr.dbg_try_fail                       0         0.00 Contended trylock operations
LCK.perpool.creat                             2         0.02 Created locks
LCK.perpool.destroy                           0         0.00 Destroyed locks
LCK.perpool.locks                           250         2.48 Lock Operations
LCK.perpool.dur_us                           73         0.72 Lock duration
LCK.perpool.dbg_busy                          0         0.00 Contended lock operations
LCK.perpool.dbg_try_fail                      0         0.00 Contended trylock operations
LCK.pipestat.creat                            1         0.01 Created locks
LCK.pipestat.destroy                          0         0.00 Destroyed locks
LCK.pipestat.locks                            0         0.00 Lock Operations
LCK.pipestat.dur_us                           0         0.00 Lock duration
LCK.pipestat.dbg_busy                         0         0.00 Contended lock operations
LCK.pipestat.dbg_try_fail                     0         0.00 Contended trylock operations
LCK.probe.creat                               1         0.01 Created locks
LCK.probe.destroy                             0         0.00 Destroyed locks
LCK.probe.locks                              48         0.48 Lock Operations
LCK.probe.dur_us                            623         6.17 Lock duration
LCK.probe.dbg_busy                            0         0.00 Contended lock operations
LCK.probe.dbg_try_fail                        0         0.00 Contended trylock operations
LCK.sess.creat                                0         0.00 Created locks
LCK.sess.destroy                              0         0.00 Destroyed locks
LCK.sess.locks                                0         0.00 Lock Operations
LCK.sess.dur_us                               0         0.00 Lock duration
LCK.sess.dbg_busy                             0         0.00 Contended lock operations
LCK.sess.dbg_try_fail                         0         0.00 Contended trylock operations
LCK.conn_pool.creat                           2         0.02 Created locks
LCK.conn_pool.destroy                         0         0.00 Destroyed locks
LCK.conn_pool.locks                           2         0.02 Lock Operations
LCK.conn_pool.dur_us                          0         0.00 Lock duration
LCK.conn_pool.dbg_busy                        0         0.00 Contended lock operations
LCK.conn_pool.dbg_try_fail                    0         0.00 Contended trylock operations
LCK.vbe.creat                                 1         0.01 Created locks
LCK.vbe.destroy                               0         0.00 Destroyed locks
LCK.vbe.locks                                 1         0.01 Lock Operations
LCK.vbe.dur_us                                0         0.00 Lock duration
LCK.vbe.dbg_busy                              0         0.00 Contended lock operations
LCK.vbe.dbg_try_fail                          0         0.00 Contended trylock operations
LCK.vcapace.creat                             1         0.01 Created locks
LCK.vcapace.destroy                           0         0.00 Destroyed locks
LCK.vcapace.locks                             0         0.00 Lock Operations
LCK.vcapace.dur_us                            0         0.00 Lock duration
LCK.vcapace.dbg_busy                          0         0.00 Contended lock operations
LCK.vcapace.dbg_try_fail                      0         0.00 Contended trylock operations
LCK.vcl.creat                                 1         0.01 Created locks
LCK.vcl.destroy                               0         0.00 Destroyed locks
LCK.vcl.locks                                 3         0.03 Lock Operations
LCK.vcl.dur_us                                9         0.09 Lock duration
LCK.vcl.dbg_busy                              0         0.00 Contended lock operations
LCK.vcl.dbg_try_fail                          0         0.00 Contended trylock operations
LCK.vxid.creat                                1         0.01 Created locks
LCK.vxid.destroy                              0         0.00 Destroyed locks
LCK.vxid.locks                                0         0.00 Lock Operations
LCK.vxid.dur_us                               0         0.00 Lock duration
LCK.vxid.dbg_busy                             0         0.00 Contended lock operations
LCK.vxid.dbg_try_fail                         0         0.00 Contended trylock operations
LCK.waiter.creat                              2         0.02 Created locks
LCK.waiter.destroy                            0         0.00 Destroyed locks
LCK.waiter.locks                              4         0.04 Lock Operations
LCK.waiter.dur_us                             8         0.08 Lock duration
LCK.waiter.dbg_busy                           0         0.00 Contended lock operations
LCK.waiter.dbg_try_fail                       0         0.00 Contended trylock operations
LCK.wq.creat                                  1         0.01 Created locks
LCK.wq.destroy                                0         0.00 Destroyed locks
LCK.wq.locks                                314         3.11 Lock Operations
LCK.wq.dur_us                               108         1.07 Lock duration
LCK.wq.dbg_busy                               0         0.00 Contended lock operations
LCK.wq.dbg_try_fail                           0         0.00 Contended trylock operations
LCK.wstat.creat                               1         0.01 Created locks
LCK.wstat.destroy                             0         0.00 Destroyed locks
LCK.wstat.locks                              48         0.48 Lock Operations
LCK.wstat.dur_us                             55         0.54 Lock duration
LCK.wstat.dbg_busy                            0         0.00 Contended lock operations
LCK.wstat.dbg_try_fail                        0         0.00 Contended trylock operations
LCK.sma.creat                                 2         0.02 Created locks
LCK.sma.destroy                               0         0.00 Destroyed locks
LCK.sma.locks                                 0         0.00 Lock Operations
LCK.sma.dur_us                                0         0.00 Lock duration
LCK.sma.dbg_busy                              0         0.00 Contended lock operations
LCK.sma.dbg_try_fail                          0         0.00 Contended trylock operations

[nigoroll]

bugwash: DBG_LCK should already give clues on hot locks, and the impact of this patch is considered too relevant.