Skip to content

Commit 46d6e5f

Browse files
MasaoFujiiMasaoFujii
committed
Display the time when the process started waiting for the lock, in pg_locks, take 2
This commit adds new column "waitstart" into pg_locks view. This column reports the time when the server process started waiting for the lock if the lock is not held. This information is useful, for example, when examining the amount of time to wait on a lock by subtracting "waitstart" in pg_locks from the current time, and identify the lock that the processes are waiting for very long. This feature uses the current time obtained for the deadlock timeout timer as "waitstart" (i.e., the time when this process started waiting for the lock). Since getting the current time newly can cause overhead, we reuse the already-obtained time to avoid that overhead. Note that "waitstart" is updated without holding the lock table's partition lock, to avoid the overhead by additional lock acquisition. This can cause "waitstart" in pg_locks to become NULL for a very short period of time after the wait started even though "granted" is false. This is OK in practice because we can assume that users are likely to look at "waitstart" when waiting for the lock for a long time. The first attempt of this patch (commit 3b733fc) caused the buildfarm member "rorqual" (built with --disable-atomics --disable-spinlocks) to report the failure of the regression test. It was reverted by commit 890d218. The cause of this failure was that the atomic variable for "waitstart" in the dummy process entry created at the end of prepare transaction was not initialized. This second attempt fixes that issue. Bump catalog version. Author: Atsushi Torikoshi Reviewed-by: Ian Lawrence Barwick, Robert Haas, Justin Pryzby, Fujii Masao Discussion: https://postgr.es/m/a96013dc51cdc56b2a2b84fa8a16a993@oss.nttdata.com
1 parent 9e596b6 commit 46d6e5f

File tree

12 files changed

+94
-11
lines changed

12 files changed

+94
-11
lines changed

‎contrib/amcheck/expected/check_btree.out

Lines changed: 2 additions & 2 deletions
Original file line numberDiff line numberDiff line change
@@ -97,8 +97,8 @@ SELECT bt_index_parent_check('bttest_b_idx');
9797
SELECT * FROM pg_locks
9898
WHERE relation = ANY(ARRAY['bttest_a', 'bttest_a_idx', 'bttest_b', 'bttest_b_idx']::regclass[])
9999
AND pid = pg_backend_pid();
100-
locktype | database | relation | page | tuple | virtualxid | transactionid | classid | objid | objsubid | virtualtransaction | pid | mode | granted | fastpath
101-
----------+----------+----------+------+-------+------------+---------------+---------+-------+----------+--------------------+-----+------+---------+----------
100+
locktype | database | relation | page | tuple | virtualxid | transactionid | classid | objid | objsubid | virtualtransaction | pid | mode | granted | fastpath | waitstart
101+
----------+----------+----------+------+-------+------------+---------------+---------+-------+----------+--------------------+-----+------+---------+----------+-----------
102102
(0 rows)
103103

104104
COMMIT;

‎doc/src/sgml/catalogs.sgml

Lines changed: 13 additions & 0 deletions
Original file line numberDiff line numberDiff line change
@@ -10605,6 +10605,19 @@ SCRAM-SHA-256$<replaceable>&lt;iteration count&gt;</replaceable>:<replaceable>&l
1060510605
lock table
1060610606
</para></entry>
1060710607
</row>
10608+
10609+
<row>
10610+
<entry role="catalog_table_entry"><para role="column_definition">
10611+
<structfield>waitstart</structfield> <type>timestamptz</type>
10612+
</para>
10613+
<para>
10614+
Time when the server process started waiting for this lock,
10615+
or null if the lock is held.
10616+
Note that this can be null for a very short period of time after
10617+
the wait started even though <structfield>granted</structfield>
10618+
is <literal>false</literal>.
10619+
</para></entry>
10620+
</row>
1060810621
</tbody>
1060910622
</tgroup>
1061010623
</table>

‎src/backend/access/transam/twophase.c

Lines changed: 8 additions & 1 deletion
Original file line numberDiff line numberDiff line change
@@ -873,8 +873,15 @@ PGPROC *
873873
TwoPhaseGetDummyProc(TransactionId xid, bool lock_held)
874874
{
875875
GlobalTransaction gxact = TwoPhaseGetGXact(xid, lock_held);
876+
PGPROC *dummy = &ProcGlobal->allProcs[gxact->pgprocno];
876877

877-
return &ProcGlobal->allProcs[gxact->pgprocno];
878+
/*
879+
* Initialize atomic variable in dummy proc so that GetLockStatusData()
880+
* can read it later.
881+
*/
882+
pg_atomic_init_u64(&dummy->waitStart, 0);
883+
884+
return dummy;
878885
}
879886

880887
/************************************************************************/

‎src/backend/storage/ipc/standby.c

Lines changed: 23 additions & 1 deletion
Original file line numberDiff line numberDiff line change
@@ -540,12 +540,34 @@ void
540540
ResolveRecoveryConflictWithLock(LOCKTAG locktag, bool logging_conflict)
541541
{
542542
TimestampTz ltime;
543+
TimestampTz now;
543544

544545
Assert(InHotStandby);
545546

546547
ltime = GetStandbyLimitTime();
548+
now = GetCurrentTimestamp();
547549

548-
if (GetCurrentTimestamp() >= ltime && ltime != 0)
550+
/*
551+
* Update waitStart if first time through after the startup process
552+
* started waiting for the lock. It should not be updated every time
553+
* ResolveRecoveryConflictWithLock() is called during the wait.
554+
*
555+
* Use the current time obtained for comparison with ltime as waitStart
556+
* (i.e., the time when this process started waiting for the lock). Since
557+
* getting the current time newly can cause overhead, we reuse the
558+
* already-obtained time to avoid that overhead.
559+
*
560+
* Note that waitStart is updated without holding the lock table's
561+
* partition lock, to avoid the overhead by additional lock acquisition.
562+
* This can cause "waitstart" in pg_locks to become NULL for a very short
563+
* period of time after the wait started even though "granted" is false.
564+
* This is OK in practice because we can assume that users are likely to
565+
* look at "waitstart" when waiting for the lock for a long time.
566+
*/
567+
if (pg_atomic_read_u64(&MyProc->waitStart) == 0)
568+
pg_atomic_write_u64(&MyProc->waitStart, now);
569+
570+
if (now >= ltime && ltime != 0)
549571
{
550572
/*
551573
* We're already behind, so clear a path as quickly as possible.

‎src/backend/storage/lmgr/lock.c

Lines changed: 8 additions & 0 deletions
Original file line numberDiff line numberDiff line change
@@ -3619,6 +3619,12 @@ GetLockStatusData(void)
36193619
instance->leaderPid = proc->pid;
36203620
instance->fastpath = true;
36213621

3622+
/*
3623+
* Successfully taking fast path lock means there were no
3624+
* conflicting locks.
3625+
*/
3626+
instance->waitStart = 0;
3627+
36223628
el++;
36233629
}
36243630

@@ -3646,6 +3652,7 @@ GetLockStatusData(void)
36463652
instance->pid = proc->pid;
36473653
instance->leaderPid = proc->pid;
36483654
instance->fastpath = true;
3655+
instance->waitStart = 0;
36493656

36503657
el++;
36513658
}
@@ -3698,6 +3705,7 @@ GetLockStatusData(void)
36983705
instance->pid = proc->pid;
36993706
instance->leaderPid = proclock->groupLeader->pid;
37003707
instance->fastpath = false;
3708+
instance->waitStart = (TimestampTz) pg_atomic_read_u64(&proc->waitStart);
37013709

37023710
el++;
37033711
}

‎src/backend/storage/lmgr/proc.c

Lines changed: 20 additions & 0 deletions
Original file line numberDiff line numberDiff line change
@@ -402,6 +402,7 @@ InitProcess(void)
402402
MyProc->lwWaitMode = 0;
403403
MyProc->waitLock = NULL;
404404
MyProc->waitProcLock = NULL;
405+
pg_atomic_init_u64(&MyProc->waitStart, 0);
405406
#ifdef USE_ASSERT_CHECKING
406407
{
407408
int i;
@@ -580,6 +581,7 @@ InitAuxiliaryProcess(void)
580581
MyProc->lwWaitMode = 0;
581582
MyProc->waitLock = NULL;
582583
MyProc->waitProcLock = NULL;
584+
pg_atomic_init_u64(&MyProc->waitStart, 0);
583585
#ifdef USE_ASSERT_CHECKING
584586
{
585587
int i;
@@ -1262,6 +1264,23 @@ ProcSleep(LOCALLOCK *locallock, LockMethod lockMethodTable)
12621264
}
12631265
else
12641266
enable_timeout_after(DEADLOCK_TIMEOUT, DeadlockTimeout);
1267+
1268+
/*
1269+
* Use the current time obtained for the deadlock timeout timer as
1270+
* waitStart (i.e., the time when this process started waiting for the
1271+
* lock). Since getting the current time newly can cause overhead, we
1272+
* reuse the already-obtained time to avoid that overhead.
1273+
*
1274+
* Note that waitStart is updated without holding the lock table's
1275+
* partition lock, to avoid the overhead by additional lock
1276+
* acquisition. This can cause "waitstart" in pg_locks to become NULL
1277+
* for a very short period of time after the wait started even though
1278+
* "granted" is false. This is OK in practice because we can assume
1279+
* that users are likely to look at "waitstart" when waiting for the
1280+
* lock for a long time.
1281+
*/
1282+
pg_atomic_write_u64(&MyProc->waitStart,
1283+
get_timeout_start_time(DEADLOCK_TIMEOUT));
12651284
}
12661285
else if (log_recovery_conflict_waits)
12671286
{
@@ -1678,6 +1697,7 @@ ProcWakeup(PGPROC *proc, ProcWaitStatus waitStatus)
16781697
proc->waitLock = NULL;
16791698
proc->waitProcLock = NULL;
16801699
proc->waitStatus = waitStatus;
1700+
pg_atomic_write_u64(&MyProc->waitStart, 0);
16811701

16821702
/* And awaken it */
16831703
SetLatch(&proc->procLatch);

‎src/backend/utils/adt/lockfuncs.c

Lines changed: 8 additions & 1 deletion
Original file line numberDiff line numberDiff line change
@@ -63,7 +63,7 @@ typedef struct
6363
} PG_Lock_Status;
6464

6565
/* Number of columns in pg_locks output */
66-
#define NUM_LOCK_STATUS_COLUMNS 15
66+
#define NUM_LOCK_STATUS_COLUMNS 16
6767

6868
/*
6969
* VXIDGetDatum - Construct a text representation of a VXID
@@ -142,6 +142,8 @@ pg_lock_status(PG_FUNCTION_ARGS)
142142
BOOLOID, -1, 0);
143143
TupleDescInitEntry(tupdesc, (AttrNumber) 15, "fastpath",
144144
BOOLOID, -1, 0);
145+
TupleDescInitEntry(tupdesc, (AttrNumber) 16, "waitstart",
146+
TIMESTAMPTZOID, -1, 0);
145147

146148
funcctx->tuple_desc = BlessTupleDesc(tupdesc);
147149

@@ -336,6 +338,10 @@ pg_lock_status(PG_FUNCTION_ARGS)
336338
values[12] = CStringGetTextDatum(GetLockmodeName(instance->locktag.locktag_lockmethodid, mode));
337339
values[13] = BoolGetDatum(granted);
338340
values[14] = BoolGetDatum(instance->fastpath);
341+
if (!granted && instance->waitStart != 0)
342+
values[15] = TimestampTzGetDatum(instance->waitStart);
343+
else
344+
nulls[15] = true;
339345

340346
tuple = heap_form_tuple(funcctx->tuple_desc, values, nulls);
341347
result = HeapTupleGetDatum(tuple);
@@ -406,6 +412,7 @@ pg_lock_status(PG_FUNCTION_ARGS)
406412
values[12] = CStringGetTextDatum("SIReadLock");
407413
values[13] = BoolGetDatum(true);
408414
values[14] = BoolGetDatum(false);
415+
nulls[15] = true;
409416

410417
tuple = heap_form_tuple(funcctx->tuple_desc, values, nulls);
411418
result = HeapTupleGetDatum(tuple);

‎src/include/catalog/catversion.h

Lines changed: 1 addition & 1 deletion
Original file line numberDiff line numberDiff line change
@@ -53,6 +53,6 @@
5353
*/
5454

5555
/* yyyymmddN */
56-
#define CATALOG_VERSION_NO 202102121
56+
#define CATALOG_VERSION_NO 202102151
5757

5858
#endif

‎src/include/catalog/pg_proc.dat

Lines changed: 3 additions & 3 deletions
Original file line numberDiff line numberDiff line change
@@ -5994,9 +5994,9 @@
59945994
{ oid => '1371', descr => 'view system lock information',
59955995
proname => 'pg_lock_status', prorows => '1000', proretset => 't',
59965996
provolatile => 'v', prorettype => 'record', proargtypes => '',
5997-
proallargtypes => '{text,oid,oid,int4,int2,text,xid,oid,oid,int2,text,int4,text,bool,bool}',
5998-
proargmodes => '{o,o,o,o,o,o,o,o,o,o,o,o,o,o,o}',
5999-
proargnames => '{locktype,database,relation,page,tuple,virtualxid,transactionid,classid,objid,objsubid,virtualtransaction,pid,mode,granted,fastpath}',
5997+
proallargtypes => '{text,oid,oid,int4,int2,text,xid,oid,oid,int2,text,int4,text,bool,bool,timestamptz}',
5998+
proargmodes => '{o,o,o,o,o,o,o,o,o,o,o,o,o,o,o,o}',
5999+
proargnames => '{locktype,database,relation,page,tuple,virtualxid,transactionid,classid,objid,objsubid,virtualtransaction,pid,mode,granted,fastpath,waitstart}',
60006000
prosrc => 'pg_lock_status' },
60016001
{ oid => '2561',
60026002
descr => 'get array of PIDs of sessions blocking specified backend PID from acquiring a heavyweight lock',

‎src/include/storage/lock.h

Lines changed: 3 additions & 0 deletions
Original file line numberDiff line numberDiff line change
@@ -22,6 +22,7 @@
2222
#include "storage/lockdefs.h"
2323
#include "storage/lwlock.h"
2424
#include "storage/shmem.h"
25+
#include "utils/timestamp.h"
2526

2627
/* struct PGPROC is declared in proc.h, but must forward-reference it */
2728
typedef struct PGPROC PGPROC;
@@ -446,6 +447,8 @@ typedef struct LockInstanceData
446447
LOCKMODE waitLockMode; /* lock awaited by this PGPROC, if any */
447448
BackendId backend; /* backend ID of this PGPROC */
448449
LocalTransactionId lxid; /* local transaction ID of this PGPROC */
450+
TimestampTz waitStart; /* time at which this PGPROC started waiting
451+
* for lock */
449452
int pid; /* pid of this PGPROC */
450453
int leaderPid; /* pid of group leader; = pid if no group */
451454
bool fastpath; /* taken via fastpath? */

‎src/include/storage/proc.h

Lines changed: 2 additions & 0 deletions
Original file line numberDiff line numberDiff line change
@@ -181,6 +181,8 @@ struct PGPROC
181181
LOCKMODE waitLockMode; /* type of lock we're waiting for */
182182
LOCKMASK heldLocks; /* bitmask for lock types already held on this
183183
* lock object by this backend */
184+
pg_atomic_uint64 waitStart; /* time at which wait for lock acquisition
185+
* started */
184186

185187
bool delayChkpt; /* true if this proc delays checkpoint start */
186188

‎src/test/regress/expected/rules.out

Lines changed: 3 additions & 2 deletions
Original file line numberDiff line numberDiff line change
@@ -1394,8 +1394,9 @@ pg_locks| SELECT l.locktype,
13941394
l.pid,
13951395
l.mode,
13961396
l.granted,
1397-
l.fastpath
1398-
FROM pg_lock_status() l(locktype, database, relation, page, tuple, virtualxid, transactionid, classid, objid, objsubid, virtualtransaction, pid, mode, granted, fastpath);
1397+
l.fastpath,
1398+
l.waitstart
1399+
FROM pg_lock_status() l(locktype, database, relation, page, tuple, virtualxid, transactionid, classid, objid, objsubid, virtualtransaction, pid, mode, granted, fastpath, waitstart);
13991400
pg_matviews| SELECT n.nspname AS schemaname,
14001401
c.relname AS matviewname,
14011402
pg_get_userbyid(c.relowner) AS matviewowner,

0 commit comments

Comments
 (0)