On 2021-01-02 06:49, Justin Pryzby wrote:
On Tue, Dec 15, 2020 at 11:47:23AM +0900, torikoshia wrote:
So I'm now thinking about adding a new column in pg_locks which
keeps the time at which locks started waiting.
Attached a patch.
This is failing make check-world, would you send an updated patch ?
I added you as an author so it shows up here.
http://cfbot.cputube.org/atsushi-torikoshi.html
Thanks!
Attached an updated patch.
Regards,
From 608bba31da1bc5d15db991662fa858cd4632d849 Mon Sep 17 00:00:00 2001
From: Atsushi Torikoshi <torikos...@oss.nttdata.com>
Date: Mon, 4 Jan 2021 09:53:17 +0900
Subject: [PATCH v2] To examine the duration of locks, we did join on pg_locks
and pg_stat_activity and used columns such as query_start or state_change.
However, since they are the moment when queries have started or their state
has changed, we could not get the exact lock duration in this way.
This patch adds a new field preserving the time at which locks
started waiting.
---
contrib/amcheck/expected/check_btree.out | 4 ++--
doc/src/sgml/catalogs.sgml | 9 +++++++++
src/backend/storage/lmgr/lock.c | 10 ++++++++++
src/backend/storage/lmgr/proc.c | 2 ++
src/backend/utils/adt/lockfuncs.c | 9 ++++++++-
src/include/catalog/pg_proc.dat | 6 +++---
src/include/storage/lock.h | 3 +++
src/test/regress/expected/rules.out | 5 +++--
8 files changed, 40 insertions(+), 8 deletions(-)
diff --git a/contrib/amcheck/expected/check_btree.out b/contrib/amcheck/expected/check_btree.out
index 13848b7449..c0aecb0288 100644
--- a/contrib/amcheck/expected/check_btree.out
+++ b/contrib/amcheck/expected/check_btree.out
@@ -97,8 +97,8 @@ SELECT bt_index_parent_check('bttest_b_idx');
SELECT * FROM pg_locks
WHERE relation = ANY(ARRAY['bttest_a', 'bttest_a_idx', 'bttest_b', 'bttest_b_idx']::regclass[])
AND pid = pg_backend_pid();
- locktype | database | relation | page | tuple | virtualxid | transactionid | classid | objid | objsubid | virtualtransaction | pid | mode | granted | fastpath
-----------+----------+----------+------+-------+------------+---------------+---------+-------+----------+--------------------+-----+------+---------+----------
+ locktype | database | relation | page | tuple | virtualxid | transactionid | classid | objid | objsubid | virtualtransaction | pid | mode | granted | fastpath | wait_start
+----------+----------+----------+------+-------+------------+---------------+---------+-------+----------+--------------------+-----+------+---------+----------+------------
(0 rows)
COMMIT;
diff --git a/doc/src/sgml/catalogs.sgml b/doc/src/sgml/catalogs.sgml
index 3a2266526c..626e5672bd 100644
--- a/doc/src/sgml/catalogs.sgml
+++ b/doc/src/sgml/catalogs.sgml
@@ -10578,6 +10578,15 @@ SCRAM-SHA-256$<replaceable><iteration count></replaceable>:<replaceable>&l
lock table
</para></entry>
</row>
+
+ <row>
+ <entry role="catalog_table_entry"><para role="column_definition">
+ <structfield>wait_start</structfield> <type>timestamptz</type>
+ </para>
+ <para>
+ The time at which lock started waiting
+ </para></entry>
+ </row>
</tbody>
</tgroup>
</table>
diff --git a/src/backend/storage/lmgr/lock.c b/src/backend/storage/lmgr/lock.c
index 20e50247ea..27969d3772 100644
--- a/src/backend/storage/lmgr/lock.c
+++ b/src/backend/storage/lmgr/lock.c
@@ -1195,6 +1195,7 @@ SetupLockInTable(LockMethod lockMethodTable, PGPROC *proc,
lock->waitMask = 0;
SHMQueueInit(&(lock->procLocks));
ProcQueueInit(&(lock->waitProcs));
+ lock->wait_start = 0;
lock->nRequested = 0;
lock->nGranted = 0;
MemSet(lock->requested, 0, sizeof(int) * MAX_LOCKMODES);
@@ -3627,6 +3628,12 @@ GetLockStatusData(void)
instance->leaderPid = proc->pid;
instance->fastpath = true;
+ /*
+ * Successfully taking fast path lock means there was no
+ * conflicting locks.
+ */
+ instance->wait_start = 0;
+
el++;
}
@@ -3654,6 +3661,7 @@ GetLockStatusData(void)
instance->pid = proc->pid;
instance->leaderPid = proc->pid;
instance->fastpath = true;
+ instance->wait_start = 0;
el++;
}
@@ -3706,6 +3714,7 @@ GetLockStatusData(void)
instance->pid = proc->pid;
instance->leaderPid = proclock->groupLeader->pid;
instance->fastpath = false;
+ instance->wait_start = lock->wait_start;
el++;
}
@@ -4183,6 +4192,7 @@ lock_twophase_recover(TransactionId xid, uint16 info,
lock->waitMask = 0;
SHMQueueInit(&(lock->procLocks));
ProcQueueInit(&(lock->waitProcs));
+ lock->wait_start = 0;
lock->nRequested = 0;
lock->nGranted = 0;
MemSet(lock->requested, 0, sizeof(int) * MAX_LOCKMODES);
diff --git a/src/backend/storage/lmgr/proc.c b/src/backend/storage/lmgr/proc.c
index 57717f666d..56aa8b7f6b 100644
--- a/src/backend/storage/lmgr/proc.c
+++ b/src/backend/storage/lmgr/proc.c
@@ -1259,6 +1259,8 @@ ProcSleep(LOCALLOCK *locallock, LockMethod lockMethodTable)
}
else
enable_timeout_after(DEADLOCK_TIMEOUT, DeadlockTimeout);
+
+ lock->wait_start = get_timeout_start_time(DEADLOCK_TIMEOUT);
}
/*
diff --git a/src/backend/utils/adt/lockfuncs.c b/src/backend/utils/adt/lockfuncs.c
index 9f2c4946c9..85b216a1d6 100644
--- a/src/backend/utils/adt/lockfuncs.c
+++ b/src/backend/utils/adt/lockfuncs.c
@@ -63,7 +63,7 @@ typedef struct
} PG_Lock_Status;
/* Number of columns in pg_locks output */
-#define NUM_LOCK_STATUS_COLUMNS 15
+#define NUM_LOCK_STATUS_COLUMNS 16
/*
* VXIDGetDatum - Construct a text representation of a VXID
@@ -142,6 +142,8 @@ pg_lock_status(PG_FUNCTION_ARGS)
BOOLOID, -1, 0);
TupleDescInitEntry(tupdesc, (AttrNumber) 15, "fastpath",
BOOLOID, -1, 0);
+ TupleDescInitEntry(tupdesc, (AttrNumber) 16, "wait_start",
+ TIMESTAMPTZOID, -1, 0);
funcctx->tuple_desc = BlessTupleDesc(tupdesc);
@@ -336,6 +338,10 @@ pg_lock_status(PG_FUNCTION_ARGS)
values[12] = CStringGetTextDatum(GetLockmodeName(instance->locktag.locktag_lockmethodid, mode));
values[13] = BoolGetDatum(granted);
values[14] = BoolGetDatum(instance->fastpath);
+ if (instance->wait_start != 0)
+ values[15] = TimestampTzGetDatum(instance->wait_start);
+ else
+ nulls[15] = true;
tuple = heap_form_tuple(funcctx->tuple_desc, values, nulls);
result = HeapTupleGetDatum(tuple);
@@ -406,6 +412,7 @@ pg_lock_status(PG_FUNCTION_ARGS)
values[12] = CStringGetTextDatum("SIReadLock");
values[13] = BoolGetDatum(true);
values[14] = BoolGetDatum(false);
+ nulls[15] = true;
tuple = heap_form_tuple(funcctx->tuple_desc, values, nulls);
result = HeapTupleGetDatum(tuple);
diff --git a/src/include/catalog/pg_proc.dat b/src/include/catalog/pg_proc.dat
index d7b55f57ea..c453cd5875 100644
--- a/src/include/catalog/pg_proc.dat
+++ b/src/include/catalog/pg_proc.dat
@@ -5946,9 +5946,9 @@
{ oid => '1371', descr => 'view system lock information',
proname => 'pg_lock_status', prorows => '1000', proretset => 't',
provolatile => 'v', prorettype => 'record', proargtypes => '',
- proallargtypes => '{text,oid,oid,int4,int2,text,xid,oid,oid,int2,text,int4,text,bool,bool}',
- proargmodes => '{o,o,o,o,o,o,o,o,o,o,o,o,o,o,o}',
- proargnames => '{locktype,database,relation,page,tuple,virtualxid,transactionid,classid,objid,objsubid,virtualtransaction,pid,mode,granted,fastpath}',
+ proallargtypes => '{text,oid,oid,int4,int2,text,xid,oid,oid,int2,text,int4,text,bool,bool,timestamptz}',
+ proargmodes => '{o,o,o,o,o,o,o,o,o,o,o,o,o,o,o,o}',
+ proargnames => '{locktype,database,relation,page,tuple,virtualxid,transactionid,classid,objid,objsubid,virtualtransaction,pid,mode,granted,fastpath,wait_start}',
prosrc => 'pg_lock_status' },
{ oid => '2561',
descr => 'get array of PIDs of sessions blocking specified backend PID from acquiring a heavyweight lock',
diff --git a/src/include/storage/lock.h b/src/include/storage/lock.h
index 2e6ef174e9..a944c93774 100644
--- a/src/include/storage/lock.h
+++ b/src/include/storage/lock.h
@@ -22,6 +22,7 @@
#include "storage/lockdefs.h"
#include "storage/lwlock.h"
#include "storage/shmem.h"
+#include "utils/timestamp.h"
/* struct PGPROC is declared in proc.h, but must forward-reference it */
typedef struct PGPROC PGPROC;
@@ -304,6 +305,7 @@ typedef struct LOCK
LOCKMASK waitMask; /* bitmask for lock types awaited */
SHM_QUEUE procLocks; /* list of PROCLOCK objects assoc. with lock */
PROC_QUEUE waitProcs; /* list of PGPROC objects waiting on lock */
+ TimestampTz wait_start; /* time at which lock started waiting */
int requested[MAX_LOCKMODES]; /* counts of requested locks */
int nRequested; /* total of requested[] array */
int granted[MAX_LOCKMODES]; /* counts of granted locks */
@@ -445,6 +447,7 @@ typedef struct LockInstanceData
LOCKMODE waitLockMode; /* lock awaited by this PGPROC, if any */
BackendId backend; /* backend ID of this PGPROC */
LocalTransactionId lxid; /* local transaction ID of this PGPROC */
+ TimestampTz wait_start; /* time at which lock started waiting */
int pid; /* pid of this PGPROC */
int leaderPid; /* pid of group leader; = pid if no group */
bool fastpath; /* taken via fastpath? */
diff --git a/src/test/regress/expected/rules.out b/src/test/regress/expected/rules.out
index 6293ab57bc..d8f0600a4b 100644
--- a/src/test/regress/expected/rules.out
+++ b/src/test/regress/expected/rules.out
@@ -1394,8 +1394,9 @@ pg_locks| SELECT l.locktype,
l.pid,
l.mode,
l.granted,
- l.fastpath
- FROM pg_lock_status() l(locktype, database, relation, page, tuple, virtualxid, transactionid, classid, objid, objsubid, virtualtransaction, pid, mode, granted, fastpath);
+ l.fastpath,
+ l.wait_start
+ FROM pg_lock_status() l(locktype, database, relation, page, tuple, virtualxid, transactionid, classid, objid, objsubid, virtualtransaction, pid, mode, granted, fastpath, wait_start);
pg_matviews| SELECT n.nspname AS schemaname,
c.relname AS matviewname,
pg_get_userbyid(c.relowner) AS matviewowner,
--
2.18.1
