Movatterモバイル変換

[0]ホーム
URL:

Skip to content

Navigation Menu

Sign in
Appearance settings

Search code, repositories, users, issues, pull requests...

Provide feedback

We read every piece of feedback, and take your input very seriously.

Saved searches

Use saved searches to filter your results more quickly

 Sign up
Appearance settings

Commit46d6e5f

Browse files
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 columnreports the time when the server process started waiting for the lockif the lock is not held. This information is useful, for example, whenexamining the amount of time to wait on a lock by subtracting"waitstart" in pg_locks from the current time, and identify the lockthat the processes are waiting for very long.This feature uses the current time obtained for the deadlock timeouttimer as "waitstart" (i.e., the time when this process started waitingfor 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'spartition lock, to avoid the overhead by additional lock acquisition.This can cause "waitstart" in pg_locks to become NULL for a very shortperiod of time after the wait started even though "granted" is false.This is OK in practice because we can assume that users are likely tolook at "waitstart" when waiting for the lock for a long time.The first attempt of this patch (commit3b733fc) caused the buildfarmmember "rorqual" (built with --disable-atomics --disable-spinlocks) to reportthe failure of the regression test. It was reverted by commit890d218.The cause of this failure was that the atomic variable for "waitstart"in the dummy process entry created at the end of prepare transaction wasnot initialized. This second attempt fixes that issue.Bump catalog version.Author: Atsushi TorikoshiReviewed-by: Ian Lawrence Barwick, Robert Haas, Justin Pryzby, Fujii MasaoDiscussion:https://postgr.es/m/a96013dc51cdc56b2a2b84fa8a16a993@oss.nttdata.com
1 parent9e596b6 commit46d6e5f

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(TransactionIdxid,boollock_held)
874874
{
875875
GlobalTransactiongxact=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+
returndummy;
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(LOCKTAGlocktag,boollogging_conflict)
541541
{
542542
TimestampTzltime;
543+
TimestampTznow;
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
#ifdefUSE_ASSERT_CHECKING
406407
{
407408
inti;
@@ -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
#ifdefUSE_ASSERT_CHECKING
584586
{
585587
inti;
@@ -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
elseif (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-
#defineNUM_LOCK_STATUS_COLUMNS15
66+
#defineNUM_LOCK_STATUS_COLUMNS16
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-
#defineCATALOG_VERSION_NO202102121
56+
#defineCATALOG_VERSION_NO202102151
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
typedefstructPGPROCPGPROC;
@@ -446,6 +447,8 @@ typedef struct LockInstanceData
446447
LOCKMODEwaitLockMode;/* lock awaited by this PGPROC, if any */
447448
BackendIdbackend;/* backend ID of this PGPROC */
448449
LocalTransactionIdlxid;/* local transaction ID of this PGPROC */
450+
TimestampTzwaitStart;/* time at which this PGPROC started waiting
451+
* for lock */
449452
intpid;/* pid of this PGPROC */
450453
intleaderPid;/* pid of group leader; = pid if no group */
451454
boolfastpath;/* 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
LOCKMODEwaitLockMode;/* type of lock we're waiting for */
182182
LOCKMASKheldLocks;/* bitmask for lock types already held on this
183183
* lock object by this backend */
184+
pg_atomic_uint64waitStart;/* time at which wait for lock acquisition
185+
* started */
184186

185187
booldelayChkpt;/* 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)
[8]ページ先頭
©2009-2025 Movatter.jp