Add Information during standby recovery conflicts
Drouvot, Bertrand <bdrouvot@amazon.com>
From: "Drouvot, Bertrand" <bdrouvot@amazon.com>
To: <pgsql-hackers@postgresql.org>
Date: 2020-06-18T07:28:13Z
Lists: pgsql-hackers
Attachments
- v1-0001-Add-Standby-Recovery-Conflicts-Info.patch (text/plain) patch v1-0001
Hi hackers,
I've attached a patch to add information during standby recovery conflicts.
The motive behind is to be able to get some information:
* On the apply side
* On the blocker(s) side
_Motivation:_
When a standby recovery conflict occurs it could be useful to get more
information to be able to dive deep on the root cause and find a way to
avoid/mitigate new occurrences.
Adding this information would make the investigations easier, it could
help answering questions like:
* On which LSN was the WAL apply blocked?
* What was the purpose of the bocked WAL record?
* On which relation (if any) was the blocked WAL record related to?
* What was the blocker(s) doing?
* When did the blocker(s) started their queries (if any)?
* What was the blocker(s) waiting for? on which wait event?
_Technical context and proposal:_
There is 2 points in this patch:
* Add the information about the blocked WAL record. This is done in
standby.c (ResolveRecoveryConflictWithVirtualXIDs,
ResolveRecoveryConflictWithDatabase, StandbyTimeoutHandler)
* Add the information about the blocker(s). This is done in postgres.c
(RecoveryConflictInterrupt)
_Outcome Example:_
2020-06-15 06:48:23.774 UTC [6971] LOG: wal record apply is blocked by 2 connection(s), reason: User query might have needed to see row versions that must be removed.
2020-06-15 06:48:23.774 UTC [6971] LOG: blocked wal record rmgr: Heap2, lsn: 0/038E2678, received at: 2020-06-15 06:48:23.774098+00, desc: CLEAN, relation: rel 1663/13586/16652 fork main blk 0
2020-06-15 06:48:54.773 UTC [7088] LOG: about to interrupt pid: 7088, backend_type: client backend, state: active, wait_event_type: Timeout, wait_event: PgSleep, query_start: 2020-06-15 06:48:14.87672+00
2020-06-15 06:48:54.773 UTC [7088] DETAIL: statement: select *, pg_sleep(120) from bdt;
2020-06-15 06:48:54.773 UTC [7088] STATEMENT: select *, pg_sleep(120) from bdt;
2020-06-15 06:48:54.773 UTC [7088] ERROR: canceling statement due to conflict with recovery
2020-06-15 06:48:54.773 UTC [7088] DETAIL: User query might have needed to see row versions that must be removed.
2020-06-15 06:48:54.773 UTC [7088] STATEMENT: select *, pg_sleep(120) from bdt;
2020-06-15 06:48:54.778 UTC [7037] LOG: about to interrupt pid: 7037, backend_type: client backend, state: active, wait_event_type: Timeout, wait_event: PgSleep, query_start: 2020-06-15 06:48:13.008427+00
2020-06-15 06:48:54.778 UTC [7037] DETAIL: statement: select *, pg_sleep(300) from bdt;
2020-06-15 06:48:54.778 UTC [7037] STATEMENT: select *, pg_sleep(300) from bdt;
2020-06-15 06:48:54.778 UTC [7037] ERROR: canceling statement due to conflict with recovery
2020-06-15 06:48:54.778 UTC [7037] DETAIL: User query might have needed to see row versions that must be removed.
2020-06-15 06:48:54.778 UTC [7037] STATEMENT: select *, pg_sleep(300) from bdt;
It takes care of the other conflicts reason too.
So, should a standby recovery conflict occurs, we could see:
* information about the blocked WAL record apply
* information about the blocker(s)
I will add this patch to the next commitfest. I look forward to your
feedback about the idea and/or implementation.
Regards,
Bertrand
Commits
-
Log long wait time on recovery conflict when it's resolved.
- 39b03690b529 14.0 landed
-
Add GUC to log long wait times on recovery conflicts.
- 0650ff23038b 14.0 landed
-
Detect the deadlocks between backends and the startup process.
- 8900b5a9d59a 14.0 cited
-
Get rid of the dedicated latch for signaling the startup process.
- ac22929a2613 14.0 cited
-
Add block information in error context of WAL REDO apply loop
- 9d0bd95fa90a 14.0 cited