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

Commit39b0369

Browse files
committed
Log long wait time on recovery conflict when it's resolved.
This is a follow-up of the work done in commit0650ff2. This commitextends log_recovery_conflict_waits so that a log message is producedalso when recovery conflict has already been resolved after deadlock_timeoutpasses, i.e., when the startup process finishes waiting for recoveryconflict after deadlock_timeout. This is useful in investigating how longrecovery conflicts prevented the recovery from applying WAL.Author: Fujii MasaoReviewed-by: Kyotaro Horiguchi, Bertrand DrouvotDiscussion:https://postgr.es/m/9a60178c-a853-1440-2cdc-c3af916cff59@amazon.com
1 parent6ecaaf8 commit39b0369

File tree

5 files changed

+61
-15
lines changed

5 files changed

+61
-15
lines changed

‎doc/src/sgml/config.sgml

Lines changed: 1 addition & 1 deletion
Original file line numberDiff line numberDiff line change
@@ -6961,7 +6961,7 @@ log_line_prefix = '%m [%p] %q%u@%d/%a '
69616961
<listitem>
69626962
<para>
69636963
Controls whether a log message is produced when the startup process
6964-
is waiting longer than <varname>deadlock_timeout</varname>
6964+
waits longer than <varname>deadlock_timeout</varname>
69656965
for recovery conflicts. This is useful in determining if recovery
69666966
conflicts prevent the recovery from applying WAL.
69676967
</para>

‎src/backend/storage/buffer/bufmgr.c

Lines changed: 11 additions & 1 deletion
Original file line numberDiff line numberDiff line change
@@ -4034,6 +4034,16 @@ LockBufferForCleanup(Buffer buffer)
40344034
/* Successfully acquired exclusive lock with pincount 1 */
40354035
UnlockBufHdr(bufHdr,buf_state);
40364036

4037+
/*
4038+
* Emit the log message if recovery conflict on buffer pin was
4039+
* resolved but the startup process waited longer than
4040+
* deadlock_timeout for it.
4041+
*/
4042+
if (logged_recovery_conflict)
4043+
LogRecoveryConflict(PROCSIG_RECOVERY_CONFLICT_BUFFERPIN,
4044+
waitStart,GetCurrentTimestamp(),
4045+
NULL, false);
4046+
40374047
/* Report change to non-waiting status */
40384048
if (new_status)
40394049
{
@@ -4088,7 +4098,7 @@ LockBufferForCleanup(Buffer buffer)
40884098
DeadlockTimeout))
40894099
{
40904100
LogRecoveryConflict(PROCSIG_RECOVERY_CONFLICT_BUFFERPIN,
4091-
waitStart,now,NULL);
4101+
waitStart,now,NULL, true);
40924102
logged_recovery_conflict= true;
40934103
}
40944104
}

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

Lines changed: 36 additions & 11 deletions
Original file line numberDiff line numberDiff line change
@@ -226,18 +226,27 @@ WaitExceedsMaxStandbyDelay(uint32 wait_event_info)
226226
* wait_start is the timestamp when the caller started to wait.
227227
* now is the timestamp when this function has been called.
228228
* wait_list is the list of virtual transaction ids assigned to
229-
* conflicting processes.
229+
* conflicting processes. still_waiting indicates whether
230+
* the startup process is still waiting for the recovery conflict
231+
* to be resolved or not.
230232
*/
231233
void
232234
LogRecoveryConflict(ProcSignalReasonreason,TimestampTzwait_start,
233-
TimestampTznow,VirtualTransactionId*wait_list)
235+
TimestampTznow,VirtualTransactionId*wait_list,
236+
boolstill_waiting)
234237
{
235238
longsecs;
236239
intusecs;
237240
longmsecs;
238241
StringInfoDatabuf;
239242
intnprocs=0;
240243

244+
/*
245+
* There must be no conflicting processes when the recovery conflict has
246+
* already been resolved.
247+
*/
248+
Assert(still_waiting||wait_list==NULL);
249+
241250
TimestampDifference(wait_start,now,&secs,&usecs);
242251
msecs=secs*1000+usecs /1000;
243252
usecs=usecs %1000;
@@ -275,12 +284,21 @@ LogRecoveryConflict(ProcSignalReason reason, TimestampTz wait_start,
275284
* conflicting backends in a detail message. Note that if all the backends
276285
* in the list are not active, no detail message is logged.
277286
*/
278-
ereport(LOG,
279-
errmsg("recovery still waiting after %ld.%03d ms: %s",
280-
msecs,usecs,_(get_recovery_conflict_desc(reason))),
281-
nprocs>0 ?errdetail_log_plural("Conflicting process: %s.",
282-
"Conflicting processes: %s.",
283-
nprocs,buf.data) :0);
287+
if (still_waiting)
288+
{
289+
ereport(LOG,
290+
errmsg("recovery still waiting after %ld.%03d ms: %s",
291+
msecs,usecs,_(get_recovery_conflict_desc(reason))),
292+
nprocs>0 ?errdetail_log_plural("Conflicting process: %s.",
293+
"Conflicting processes: %s.",
294+
nprocs,buf.data) :0);
295+
}
296+
else
297+
{
298+
ereport(LOG,
299+
errmsg("recovery finished waiting after %ld.%03d ms: %s",
300+
msecs,usecs,_(get_recovery_conflict_desc(reason))));
301+
}
284302

285303
if (nprocs>0)
286304
pfree(buf.data);
@@ -375,13 +393,12 @@ ResolveRecoveryConflictWithVirtualXIDs(VirtualTransactionId *waitlist,
375393

376394
/*
377395
* Emit the log message if the startup process is waiting
378-
* longer than deadlock_timeout for recovery conflict on
379-
* buffer pin.
396+
* longer than deadlock_timeout for recovery conflict.
380397
*/
381398
if (maybe_log_conflict&&
382399
TimestampDifferenceExceeds(waitStart,now,DeadlockTimeout))
383400
{
384-
LogRecoveryConflict(reason,waitStart,now,waitlist);
401+
LogRecoveryConflict(reason,waitStart,now,waitlist, true);
385402
logged_recovery_conflict= true;
386403
}
387404
}
@@ -391,6 +408,14 @@ ResolveRecoveryConflictWithVirtualXIDs(VirtualTransactionId *waitlist,
391408
waitlist++;
392409
}
393410

411+
/*
412+
* Emit the log message if recovery conflict was resolved but the startup
413+
* process waited longer than deadlock_timeout for it.
414+
*/
415+
if (logged_recovery_conflict)
416+
LogRecoveryConflict(reason,waitStart,GetCurrentTimestamp(),
417+
NULL, false);
418+
394419
/* Reset ps display if we changed it */
395420
if (new_status)
396421
{

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

Lines changed: 11 additions & 1 deletion
Original file line numberDiff line numberDiff line change
@@ -1322,7 +1322,8 @@ ProcSleep(LOCALLOCK *locallock, LockMethod lockMethodTable)
13221322
* longer than deadlock_timeout.
13231323
*/
13241324
LogRecoveryConflict(PROCSIG_RECOVERY_CONFLICT_LOCK,
1325-
standbyWaitStart,now,cnt>0 ?vxids :NULL);
1325+
standbyWaitStart,now,
1326+
cnt>0 ?vxids :NULL, true);
13261327
logged_recovery_conflict= true;
13271328
}
13281329
}
@@ -1607,6 +1608,15 @@ ProcSleep(LOCALLOCK *locallock, LockMethod lockMethodTable)
16071608
disable_timeout(DEADLOCK_TIMEOUT, false);
16081609
}
16091610

1611+
/*
1612+
* Emit the log message if recovery conflict on lock was resolved but the
1613+
* startup process waited longer than deadlock_timeout for it.
1614+
*/
1615+
if (InHotStandby&&logged_recovery_conflict)
1616+
LogRecoveryConflict(PROCSIG_RECOVERY_CONFLICT_LOCK,
1617+
standbyWaitStart,GetCurrentTimestamp(),
1618+
NULL, false);
1619+
16101620
/*
16111621
* Re-acquire the lock table's partition lock. We have to do this to hold
16121622
* off cancel/die interrupts before we can mess with lockAwaited (else we

‎src/include/storage/standby.h

Lines changed: 2 additions & 1 deletion
Original file line numberDiff line numberDiff line change
@@ -40,7 +40,8 @@ extern void StandbyDeadLockHandler(void);
4040
externvoidStandbyTimeoutHandler(void);
4141
externvoidStandbyLockTimeoutHandler(void);
4242
externvoidLogRecoveryConflict(ProcSignalReasonreason,TimestampTzwait_start,
43-
TimestampTzcur_ts,VirtualTransactionId*wait_list);
43+
TimestampTzcur_ts,VirtualTransactionId*wait_list,
44+
boolstill_waiting);
4445

4546
/*
4647
* Standby Rmgr (RM_STANDBY_ID)

0 commit comments

Comments
 (0)
[8]ページ先頭
©2009-2025 Movatter.jp