On 2021-01-25 23:44, Fujii Masao wrote:
Another comment is; Doesn't the change of MyProc->waitStart need the
lock table's partition lock? If yes, we can do that by moving
LWLockRelease(partitionLock) just after the change of
MyProc->waitStart, but which causes the time that lwlock is being held
to be long. So maybe we need another way to do that.
Thanks for your comments!
It would be ideal for the consistency of the view to record "waitstart"
during holding the table partition lock.
However, as you pointed out, it would give non-negligible performance
impacts.
I may miss something, but as far as I can see, the influence of not
holding the lock is that "waitstart" can be NULL even though "granted"
is false.
I think people want to know the start time of the lock when locks are
held for a long time.
In that case, "waitstart" should have already been recorded.
If this is true, I think the current implementation may be enough on the
condition that users understand it can happen that "waitStart" is NULL
and "granted" is false.
Attached a patch describing this in the doc and comments.
Any Thoughts?
Regards,
--
Atsushi Torikoshi
From 03c6e1ed6ffa215ee898b5a6a75d77277fb8e672 Mon Sep 17 00:00:00 2001
From: Atsushi Torikoshi <torikos...@oss.nttdata.com>
Date: Tue, 2 Feb 2021 21:32:36 +0900
Subject: [PATCH v6] 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 lock duration in this way. This patch adds
a new field "waitstart" preserving lock acquisition wait start time.
Note that updating this field and lock acquisition are not performed
synchronously for performance reasons. Therefore, depending on the
timing, it can happen that waitstart is NULL even though granted is
false.
Author: Atsushi Torikoshi
Reviewed-by: Ian Lawrence Barwick, Robert Haas, Fujii Masao
Discussion: https://postgr.es/m/a96013dc51cdc56b2a2b84fa8a16a...@oss.nttdata.com
---
contrib/amcheck/expected/check_btree.out | 4 ++--
doc/src/sgml/catalogs.sgml | 14 ++++++++++++++
src/backend/storage/ipc/standby.c | 16 ++++++++++++++--
src/backend/storage/lmgr/lock.c | 8 ++++++++
src/backend/storage/lmgr/proc.c | 10 ++++++++++
src/backend/utils/adt/lockfuncs.c | 9 ++++++++-
src/include/catalog/pg_proc.dat | 6 +++---
src/include/storage/lock.h | 2 ++
src/include/storage/proc.h | 1 +
src/test/regress/expected/rules.out | 5 +++--
10 files changed, 65 insertions(+), 10 deletions(-)
diff --git a/contrib/amcheck/expected/check_btree.out b/contrib/amcheck/expected/check_btree.out
index 13848b7449..5a3f1ef737 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 | waitstart
+----------+----------+----------+------+-------+------------+---------------+---------+-------+----------+--------------------+-----+------+---------+----------+-----------
(0 rows)
COMMIT;
diff --git a/doc/src/sgml/catalogs.sgml b/doc/src/sgml/catalogs.sgml
index 865e826fb0..d81d6e1c52 100644
--- a/doc/src/sgml/catalogs.sgml
+++ b/doc/src/sgml/catalogs.sgml
@@ -10592,6 +10592,20 @@ 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>waitstart</structfield> <type>timestamptz</type>
+ </para>
+ <para>
+ Lock acquisition wait start time.
+ Note that updating this field and lock acquisition are not performed
+ synchronously for performance reasons. Therefore, depending on the
+ timing, it can happen that <structfield>waitstart</structfield> is
+ <literal>NULL</literal> even though
+ <structfield>granted</structfield> is false.
+ </para></entry>
+ </row>
</tbody>
</tgroup>
</table>
diff --git a/src/backend/storage/ipc/standby.c b/src/backend/storage/ipc/standby.c
index 39a30c00f7..2282229568 100644
--- a/src/backend/storage/ipc/standby.c
+++ b/src/backend/storage/ipc/standby.c
@@ -539,13 +539,25 @@ ResolveRecoveryConflictWithDatabase(Oid dbid)
void
ResolveRecoveryConflictWithLock(LOCKTAG locktag, bool logging_conflict)
{
- TimestampTz ltime;
+ TimestampTz ltime, now;
Assert(InHotStandby);
ltime = GetStandbyLimitTime();
+ now = GetCurrentTimestamp();
- if (GetCurrentTimestamp() >= ltime && ltime != 0)
+ /*
+ * Record waitStart using the current time obtained for comparison
+ * with ltime.
+ *
+ * It would be ideal this can be synchronously done with updating
+ * lock information. Howerver, since it gives performance impacts
+ * to hold partitionLock longer time, we do it here asynchronously.
+ */
+ if (MyProc->waitStart == 0)
+ MyProc->waitStart = now;
+
+ if (now >= ltime && ltime != 0)
{
/*
* We're already behind, so clear a path as quickly as possible.
diff --git a/src/backend/storage/lmgr/lock.c b/src/backend/storage/lmgr/lock.c
index 79c1cf9b8b..295c3220e0 100644
--- a/src/backend/storage/lmgr/lock.c
+++ b/src/backend/storage/lmgr/lock.c
@@ -3619,6 +3619,12 @@ GetLockStatusData(void)
instance->leaderPid = proc->pid;
instance->fastpath = true;
+ /*
+ * Successfully taking fast path lock means there were no
+ * conflicting locks.
+ */
+ instance->waitStart = 0;
+
el++;
}
@@ -3646,6 +3652,7 @@ GetLockStatusData(void)
instance->pid = proc->pid;
instance->leaderPid = proc->pid;
instance->fastpath = true;
+ instance->waitStart = 0;
el++;
}
@@ -3698,6 +3705,7 @@ GetLockStatusData(void)
instance->pid = proc->pid;
instance->leaderPid = proclock->groupLeader->pid;
instance->fastpath = false;
+ instance->waitStart = proc->waitStart;
el++;
}
diff --git a/src/backend/storage/lmgr/proc.c b/src/backend/storage/lmgr/proc.c
index c87ffc6549..84401e8430 100644
--- a/src/backend/storage/lmgr/proc.c
+++ b/src/backend/storage/lmgr/proc.c
@@ -402,6 +402,7 @@ InitProcess(void)
MyProc->lwWaitMode = 0;
MyProc->waitLock = NULL;
MyProc->waitProcLock = NULL;
+ MyProc->waitStart = 0;
#ifdef USE_ASSERT_CHECKING
{
int i;
@@ -1262,6 +1263,14 @@ ProcSleep(LOCALLOCK *locallock, LockMethod lockMethodTable)
}
else
enable_timeout_after(DEADLOCK_TIMEOUT, DeadlockTimeout);
+ /*
+ * Record waitStart reusing the deadlock timeout timer.
+ *
+ * It would be ideal this can be synchronously done with updating
+ * lock information. Howerver, since it gives performance impacts
+ * to hold partitionLock longer time, we do it here asynchronously.
+ */
+ MyProc->waitStart = get_timeout_start_time(DEADLOCK_TIMEOUT);
}
else if (log_recovery_conflict_waits)
{
@@ -1678,6 +1687,7 @@ ProcWakeup(PGPROC *proc, ProcWaitStatus waitStatus)
proc->waitLock = NULL;
proc->waitProcLock = NULL;
proc->waitStatus = waitStatus;
+ proc->waitStart = 0;
/* And awaken it */
SetLatch(&proc->procLatch);
diff --git a/src/backend/utils/adt/lockfuncs.c b/src/backend/utils/adt/lockfuncs.c
index b1cf5b79a7..97f0265c12 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, "waitstart",
+ 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 (!granted && instance->waitStart != 0)
+ values[15] = TimestampTzGetDatum(instance->waitStart);
+ 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 f8174061ef..a1a99c9ef4 100644
--- a/src/include/catalog/pg_proc.dat
+++ b/src/include/catalog/pg_proc.dat
@@ -5986,9 +5986,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,waitstart}',
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 68a3487d49..846487f94b 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;
@@ -446,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 waitStart; /* time at which this PGPROC started waiting for lock */
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/include/storage/proc.h b/src/include/storage/proc.h
index 683ab64f76..83b5ec3bab 100644
--- a/src/include/storage/proc.h
+++ b/src/include/storage/proc.h
@@ -181,6 +181,7 @@ struct PGPROC
LOCKMODE waitLockMode; /* type of lock we're waiting for */
LOCKMASK heldLocks; /* bitmask for lock types already held on this
* lock object by this backend */
+ TimestampTz waitStart; /* time at which wait for lock acquisition started */
bool delayChkpt; /* true if this proc delays checkpoint start */
diff --git a/src/test/regress/expected/rules.out b/src/test/regress/expected/rules.out
index 6173473de9..5b86c7d5f2 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.waitstart
+ FROM pg_lock_status() l(locktype, database, relation, page, tuple, virtualxid, transactionid, classid, objid, objsubid, virtualtransaction, pid, mode, granted, fastpath, waitstart);
pg_matviews| SELECT n.nspname AS schemaname,
c.relname AS matviewname,
pg_get_userbyid(c.relowner) AS matviewowner,
--
2.18.1
