Re: add recovery, backup, archive, streaming etc. activity messages to server logs along with ps display
On Thu, Dec 9, 2021 at 9:28 PM Alvaro Herrera wrote:
>
> Maybe some tunable like
> log_wal_traffic = { none, medium, high }
> where "none" is current behavior of no noise, "medium" gets (say) once
> every 256 segments (e.g., when going from XFF to (X+1)00), "high" gets
> you one message per segment.
On Fri, Dec 24, 2021 at 7:19 PM Justin Pryzby wrote:
>
> If you're talking about a new feature that uses the infrastructre from 9ce3,
> but is controlled by a separate GUC like log_wal_traffic, that could be okay.
Thanks for the suggestion. I've added a new GUC log_wal_traffic as
suggested above. PSA v7 patch.
Regards,
Bharath Rupireddy.
v7-0001-Add-WAL-recovery-messages-with-log_wal_traffic-GU.patch
Description: Binary data
Re: add recovery, backup, archive, streaming etc. activity messages to server logs along with ps display
On Fri, Dec 24, 2021 at 08:04:08PM +0530, Bharath Rupireddy wrote: > On Fri, Dec 24, 2021 at 7:19 PM Justin Pryzby wrote: > > On Sun, Dec 12, 2021 at 06:08:05PM +0530, Bharath Rupireddy wrote: > > > Another idea could be to use the infrastructure laid out by the commit > > > 9ce346e [1]. With ereport_startup_progress, we can emit the LOGs(of > > > current recovering WAL file) for every log_startup_progress_interval > > > seconds/milliseconds. > > > > > > One problem is that ereport_startup_progress doesn't work on > > > StandbyMode, maybe we can remove this restriction unless we have a > > > major reason for not allowing it on the standby. > > > /* Prepare to report progress of the redo phase. */ > > > if (!StandbyMode) > > > begin_startup_progress_phase(); > > > > The relevant conversation starts here. > > https://www.postgresql.org/message-id/20210814214700.GO10479%40telsasoft.com > > > > There was a lot of confusion in that thread, though. > > > > The understanding was that it didn't make sense for that feature to > > continuously log messages on a standby (every 10sec by default). That seems > > like too much - the issue of a checkpointed logged every 5min was enough of > > a > > hurdle. > > > > If you're talking about a new feature that uses the infrastructre from 9ce3, > > but is controlled by a separate GUC like log_wal_traffic, that could be > > okay. > > Do you see any problems using the same GUC > log_startup_progress_interval and ereport_startup_progress API > introduced by 9ce346e? I prefer this instead of a new GUC. Thoughts? I referenced the thread where we avoided writing progress logs during normal operation of a standby, since the logs would be both useless and excessive. If your patch were to use the same infrastructure, you'd still want to avoid disturbing that behavior and writing useless logs. -- Justin
Re: add recovery, backup, archive, streaming etc. activity messages to server logs along with ps display
On Fri, Dec 24, 2021 at 7:19 PM Justin Pryzby wrote: > > On Sun, Dec 12, 2021 at 06:08:05PM +0530, Bharath Rupireddy wrote: > > Another idea could be to use the infrastructure laid out by the commit > > 9ce346e [1]. With ereport_startup_progress, we can emit the LOGs(of > > current recovering WAL file) for every log_startup_progress_interval > > seconds/milliseconds. > > > > One problem is that ereport_startup_progress doesn't work on > > StandbyMode, maybe we can remove this restriction unless we have a > > major reason for not allowing it on the standby. > > /* Prepare to report progress of the redo phase. */ > > if (!StandbyMode) > > begin_startup_progress_phase(); > > The relevant conversation starts here. > https://www.postgresql.org/message-id/20210814214700.GO10479%40telsasoft.com > > There was a lot of confusion in that thread, though. > > The understanding was that it didn't make sense for that feature to > continuously log messages on a standby (every 10sec by default). That seems > like too much - the issue of a checkpointed logged every 5min was enough of a > hurdle. > > If you're talking about a new feature that uses the infrastructre from 9ce3, > but is controlled by a separate GUC like log_wal_traffic, that could be okay. Do you see any problems using the same GUC log_startup_progress_interval and ereport_startup_progress API introduced by 9ce346e? I prefer this instead of a new GUC. Thoughts? Regards, Bharath Rupireddy.
Re: add recovery, backup, archive, streaming etc. activity messages to server logs along with ps display
On Sun, Dec 12, 2021 at 06:08:05PM +0530, Bharath Rupireddy wrote: > Another idea could be to use the infrastructure laid out by the commit > 9ce346e [1]. With ereport_startup_progress, we can emit the LOGs(of > current recovering WAL file) for every log_startup_progress_interval > seconds/milliseconds. > > One problem is that ereport_startup_progress doesn't work on > StandbyMode, maybe we can remove this restriction unless we have a > major reason for not allowing it on the standby. > /* Prepare to report progress of the redo phase. */ > if (!StandbyMode) > begin_startup_progress_phase(); The relevant conversation starts here. https://www.postgresql.org/message-id/20210814214700.GO10479%40telsasoft.com There was a lot of confusion in that thread, though. The understanding was that it didn't make sense for that feature to continuously log messages on a standby (every 10sec by default). That seems like too much - the issue of a checkpointed logged every 5min was enough of a hurdle. If you're talking about a new feature that uses the infrastructre from 9ce3, but is controlled by a separate GUC like log_wal_traffic, that could be okay. -- Justin
Re: add recovery, backup, archive, streaming etc. activity messages to server logs along with ps display
On Thu, Dec 9, 2021 at 9:28 PM Alvaro Herrera wrote:
>
> On 2021-Dec-09, Bharath Rupireddy wrote:
>
> > On Thu, Dec 9, 2021 at 6:00 PM Alvaro Herrera
> > wrote:
> > >
> > > On 2021-Dec-09, Bharath Rupireddy wrote:
> > >
> > > > I just want to call this out: an insertion of 10 million rows in the
> > > > primary generates a bunch of messages in the standby [1] within 40 sec
> > > > (size of the standby server log grows by 5K).
> > >
> > > Hmm, that does sound excessive to me in terms of log bloat increase.
> > > Remember the discussion about turning log_checkpoints on by default?
> >
> > The amount of LOG messages generated when the log_checkpoints GUC is
> > set to on, are quite less, hardly 4 messages per-checkpoint (5min). I
> > think enabling log_checkpoints is still acceptable as most of the
> > hackers agreed in another thread [1] that the advantages with it are
> > more and it doesn't seem to be bloating the server logs (in a day at
> > max 1152 messages).
>
> My point is that it was argued, in that thread, that setting
> log_checkpoints to on by default would cause too much additional log
> volume. That argument was shot down, but in this thread we're arguing
> that we want five kilobytes of messages in forty seconds. That sounds
> much less acceptable to me, so making it default behavior or
> unconditional behavior is not going to fly very high.
>
> > I'm not sure if it is worth having a GUC log_recovery if enabled the
> > recovery messages can be emitted at LOG level otherwise DEBUG1 level.
>
> Maybe some tunable like
> log_wal_traffic = { none, medium, high }
> where "none" is current behavior of no noise, "medium" gets (say) once
> every 256 segments (e.g., when going from XFF to (X+1)00), "high" gets
> you one message per segment.
Yeah, that can be an option.
Another idea could be to use the infrastructure laid out by the commit
9ce346e [1]. With ereport_startup_progress, we can emit the LOGs(of
current recovering WAL file) for every log_startup_progress_interval
seconds/milliseconds.
One problem is that ereport_startup_progress doesn't work on
StandbyMode, maybe we can remove this restriction unless we have a
major reason for not allowing it on the standby.
/* Prepare to report progress of the redo phase. */
if (!StandbyMode)
begin_startup_progress_phase();
Thoughts?
[1]
commit 9ce346eabf350a130bba46be3f8c50ba28506969
Author: Robert Haas
Date: Mon Oct 25 11:51:57 2021 -0400
Report progress of startup operations that take a long time.
Discussion:
https://postgr.es/m/ca+tgmoahqrgdfobwgy16xcomtxxsrvgfb2jncvb7-ubuee1...@mail.gmail.com
Discussion:
https://postgr.es/m/camm1awahf7ve69572_olq+mgpt5ruiudgf1x5rrtkjbldpr...@mail.gmail.com
Regards,
Bharath Rupireddy.
Re: add recovery, backup, archive, streaming etc. activity messages to server logs along with ps display
On 2021-Dec-09, Bharath Rupireddy wrote:
> On Thu, Dec 9, 2021 at 6:00 PM Alvaro Herrera wrote:
> >
> > On 2021-Dec-09, Bharath Rupireddy wrote:
> >
> > > I just want to call this out: an insertion of 10 million rows in the
> > > primary generates a bunch of messages in the standby [1] within 40 sec
> > > (size of the standby server log grows by 5K).
> >
> > Hmm, that does sound excessive to me in terms of log bloat increase.
> > Remember the discussion about turning log_checkpoints on by default?
>
> The amount of LOG messages generated when the log_checkpoints GUC is
> set to on, are quite less, hardly 4 messages per-checkpoint (5min). I
> think enabling log_checkpoints is still acceptable as most of the
> hackers agreed in another thread [1] that the advantages with it are
> more and it doesn't seem to be bloating the server logs (in a day at
> max 1152 messages).
My point is that it was argued, in that thread, that setting
log_checkpoints to on by default would cause too much additional log
volume. That argument was shot down, but in this thread we're arguing
that we want five kilobytes of messages in forty seconds. That sounds
much less acceptable to me, so making it default behavior or
unconditional behavior is not going to fly very high.
> I'm not sure if it is worth having a GUC log_recovery if enabled the
> recovery messages can be emitted at LOG level otherwise DEBUG1 level.
Maybe some tunable like
log_wal_traffic = { none, medium, high }
where "none" is current behavior of no noise, "medium" gets (say) once
every 256 segments (e.g., when going from XFF to (X+1)00), "high" gets
you one message per segment.
--
Álvaro Herrera PostgreSQL Developer — https://www.EnterpriseDB.com/
Re: add recovery, backup, archive, streaming etc. activity messages to server logs along with ps display
On Thu, Dec 9, 2021 at 6:00 PM Alvaro Herrera wrote: > > On 2021-Dec-09, Bharath Rupireddy wrote: > > > I just want to call this out: an insertion of 10 million rows in the > > primary generates a bunch of messages in the standby [1] within 40 sec > > (size of the standby server log grows by 5K). > > Hmm, that does sound excessive to me in terms of log bloat increase. > Remember the discussion about turning log_checkpoints on by default? The amount of LOG messages generated when the log_checkpoints GUC is set to on, are quite less, hardly 4 messages per-checkpoint (5min). I think enabling log_checkpoints is still acceptable as most of the hackers agreed in another thread [1] that the advantages with it are more and it doesn't seem to be bloating the server logs (in a day at max 1152 messages). I'm not sure if it is worth having a GUC log_recovery if enabled the recovery messages can be emitted at LOG level otherwise DEBUG1 level. log_recovery GUC can also be used to collect and emit some recovery stats like log_checkpoints. [1] - https://www.postgresql.org/message-id/CA%2BTgmoaDFpFmNQuaWj6%2B78CPVBrF_WPT1wFHBTvio%3DtRmxzUcQ%40mail.gmail.com Regards, Bharath Rupireddy.
Re: add recovery, backup, archive, streaming etc. activity messages to server logs along with ps display
On 2021-Dec-09, Bharath Rupireddy wrote: > I just want to call this out: an insertion of 10 million rows in the > primary generates a bunch of messages in the standby [1] within 40 sec > (size of the standby server log grows by 5K). Hmm, that does sound excessive to me in terms of log bloat increase. Remember the discussion about turning log_checkpoints on by default? -- Álvaro Herrera PostgreSQL Developer — https://www.EnterpriseDB.com/ "Las mujeres son como hondas: mientras más resistencia tienen, más lejos puedes llegar con ellas" (Jonas Nightingale, Leap of Faith)
Re: add recovery, backup, archive, streaming etc. activity messages to server logs along with ps display
On Thu, Dec 9, 2021 at 11:28 AM Bharath Rupireddy wrote: > > On Thu, Dec 9, 2021 at 7:56 AM Michael Paquier wrote: > > > > On Wed, Dec 08, 2021 at 04:57:49PM +0530, Bharath Rupireddy wrote: > > > Done in the attached v5 patch. > > > > Thanks for the new version. FWIW, as the information logged when > > recovering a WAL segment from the local pg_wal could be rather > > confusing at bootstrap phase, I would suggest to simplify things as of > > the attached and call it a day. > > Thanks for the patch. It looks good to me. I have a suggestion: It's > better if we specify why we are not emitting any message if the WAL > segment is found in pg_wal directory, something like "we are > intentionally not emitting any messages in case if the required WAL > segment is found in the pg_wal directory to avoid noise in the server > logs". > > + case XLOG_FROM_PG_WAL: > + case XLOG_FROM_ANY: > + break; I just want to call this out: an insertion of 10 million rows in the primary generates a bunch of messages in the standby [1] within 40 sec (size of the standby server log grows by 5K). [1] 2021-12-08 08:11:53.906 UTC [1219898] LOG: recovering WAL segment "00010004" from stream 2021-12-08 08:11:55.864 UTC [1219898] LOG: recovering WAL segment "00010005" from stream 2021-12-08 08:11:56.713 UTC [1219898] LOG: recovering WAL segment "00010006" from stream 2021-12-08 08:11:57.495 UTC [1219898] LOG: recovering WAL segment "00010007" from stream 2021-12-08 08:11:58.301 UTC [1219898] LOG: recovering WAL segment "00010008" from stream 2021-12-08 08:11:59.062 UTC [1219898] LOG: recovering WAL segment "00010009" from stream 2021-12-08 08:11:59.853 UTC [1219898] LOG: recovering WAL segment "0001000A" from stream 2021-12-08 08:12:00.573 UTC [1219898] LOG: recovering WAL segment "0001000B" from stream 2021-12-08 08:12:01.346 UTC [1219898] LOG: recovering WAL segment "0001000C" from stream 2021-12-08 08:12:02.048 UTC [1219898] LOG: recovering WAL segment "0001000D" from stream 2021-12-08 08:12:02.798 UTC [1219898] LOG: recovering WAL segment "0001000E" from stream 2021-12-08 08:12:03.544 UTC [1219898] LOG: recovering WAL segment "0001000F" from stream 2021-12-08 08:12:04.310 UTC [1219898] LOG: recovering WAL segment "00010010" from stream 2021-12-08 08:12:05.096 UTC [1219898] LOG: recovering WAL segment "00010011" from stream 2021-12-08 08:12:06.003 UTC [1219898] LOG: recovering WAL segment "00010012" from stream 2021-12-08 08:12:06.762 UTC [1219898] LOG: recovering WAL segment "00010013" from stream 2021-12-08 08:12:07.595 UTC [1219898] LOG: recovering WAL segment "00010014" from stream 2021-12-08 08:12:08.431 UTC [1219898] LOG: recovering WAL segment "00010015" from stream 2021-12-08 08:12:09.246 UTC [1219898] LOG: recovering WAL segment "00010016" from stream 2021-12-08 08:12:10.144 UTC [1219898] LOG: recovering WAL segment "00010017" from stream 2021-12-08 08:12:14.944 UTC [1219898] LOG: recovering WAL segment "00010018" from stream 2021-12-08 08:12:15.784 UTC [1219898] LOG: recovering WAL segment "00010019" from stream 2021-12-08 08:12:16.757 UTC [1219898] LOG: recovering WAL segment "0001001A" from stream 2021-12-08 08:12:17.571 UTC [1219898] LOG: recovering WAL segment "0001001B" from stream 2021-12-08 08:12:18.375 UTC [1219898] LOG: recovering WAL segment "0001001C" from stream 2021-12-08 08:12:19.179 UTC [1219898] LOG: recovering WAL segment "0001001D" from stream 2021-12-08 08:12:19.964 UTC [1219898] LOG: recovering WAL segment "0001001E" from stream 2021-12-08 08:12:20.839 UTC [1219898] LOG: recovering WAL segment "0001001F" from stream 2021-12-08 08:12:21.782 UTC [1219898] LOG: recovering WAL segment "00010020" from stream 2021-12-08 08:12:24.422 UTC [1219898] LOG: recovering WAL segment "00010021" from stream 2021-12-08 08:12:25.164 UTC [1219898] LOG: recovering WAL segment "00010022" from stream 2021-12-08 08:12:25.989 UTC [1219898] LOG: recovering WAL segment "00010023" from stream 2021-12-08 08:12:26.874 UTC [1219898] LOG: recovering WAL segment "00010024" from stream 2021-12-08 08:12:27.592 UTC [1219898] LOG: recovering WAL segment "00010025" from stream 2021-12-08 08:12:28.471 UTC [1219898] LOG: recovering WAL segment "00010026" from stream 2021-12-08 08:12:29.158 UTC [1219898] LOG: recovering WAL segment "00010027" from stream 2021-12-08 08:12:30.017 UTC [1219898] LOG: recovering WAL segment
Re: add recovery, backup, archive, streaming etc. activity messages to server logs along with ps display
On Thu, Dec 9, 2021 at 7:56 AM Michael Paquier wrote: > > On Wed, Dec 08, 2021 at 04:57:49PM +0530, Bharath Rupireddy wrote: > > Done in the attached v5 patch. > > Thanks for the new version. FWIW, as the information logged when > recovering a WAL segment from the local pg_wal could be rather > confusing at bootstrap phase, I would suggest to simplify things as of > the attached and call it a day. Thanks for the patch. It looks good to me. I have a suggestion: It's better if we specify why we are not emitting any message if the WAL segment is found in pg_wal directory, something like "we are intentionally not emitting any messages in case if the required WAL segment is found in the pg_wal directory to avoid noise in the server logs". + case XLOG_FROM_PG_WAL: + case XLOG_FROM_ANY: + break; Regards, Bharath Rupireddy.
Re: add recovery, backup, archive, streaming etc. activity messages to server logs along with ps display
On Wed, Dec 08, 2021 at 04:57:49PM +0530, Bharath Rupireddy wrote:
> Done in the attached v5 patch.
Thanks for the new version. FWIW, as the information logged when
recovering a WAL segment from the local pg_wal could be rather
confusing at bootstrap phase, I would suggest to simplify things as of
the attached and call it a day.
--
Michael
From 0ab1a0ecdc54272942afbaf523abeff249071e8c Mon Sep 17 00:00:00 2001
From: Michael Paquier
Date: Thu, 9 Dec 2021 11:23:42 +0900
Subject: [PATCH v6] add log messages for recovery
---
src/backend/access/transam/xlog.c| 22 +-
src/backend/access/transam/xlogarchive.c | 2 +-
2 files changed, 22 insertions(+), 2 deletions(-)
diff --git a/src/backend/access/transam/xlog.c b/src/backend/access/transam/xlog.c
index d894af310a..3a98ee6c3b 100644
--- a/src/backend/access/transam/xlog.c
+++ b/src/backend/access/transam/xlog.c
@@ -3787,6 +3787,10 @@ XLogFileRead(XLogSegNo segno, int emode, TimeLineID tli,
xlogfname);
set_ps_display(activitymsg);
+ ereport(LOG,
+ (errmsg("waiting for WAL segment \"%s\" from archive",
+ xlogfname)));
+
if (!RestoreArchivedFile(path, xlogfname,
"RECOVERYXLOG",
wal_segment_size,
@@ -3829,6 +3833,23 @@ XLogFileRead(XLogSegNo segno, int emode, TimeLineID tli,
xlogfname);
set_ps_display(activitymsg);
+ switch (source)
+ {
+ case XLOG_FROM_ARCHIVE:
+ereport(LOG,
+ (errmsg("recovering WAL segment \"%s\" from archive",
+xlogfname)));
+break;
+ case XLOG_FROM_STREAM:
+ereport(LOG,
+ (errmsg("recovering WAL segment \"%s\" from stream",
+xlogfname)));
+break;
+ case XLOG_FROM_PG_WAL:
+ case XLOG_FROM_ANY:
+break;
+ }
+
/* Track source of data in assorted state variables */
readSource = source;
XLogReceiptSource = source;
@@ -3919,7 +3940,6 @@ XLogFileReadAnyTLI(XLogSegNo segno, int emode, XLogSource source)
XLOG_FROM_ARCHIVE, true);
if (fd != -1)
{
-elog(DEBUG1, "got WAL segment from archive");
if (!expectedTLEs)
expectedTLEs = tles;
return fd;
diff --git a/src/backend/access/transam/xlogarchive.c b/src/backend/access/transam/xlogarchive.c
index 4ddeac1fb9..1f724f4acf 100644
--- a/src/backend/access/transam/xlogarchive.c
+++ b/src/backend/access/transam/xlogarchive.c
@@ -214,7 +214,7 @@ RestoreArchivedFile(char *path, const char *xlogfname,
else
{
ereport(LOG,
- (errmsg("restored log file \"%s\" from archive",
+ (errmsg("restored WAL segment \"%s\" from archive",
xlogfname)));
strcpy(path, xlogpath);
return true;
--
2.34.1
signature.asc
Description: PGP signature
Re: add recovery, backup, archive, streaming etc. activity messages to server logs along with ps display
On Wed, Dec 8, 2021 at 2:08 PM Michael Paquier wrote:
> > Do you want me to add "received from stream" in general?
>
> "from stream" would be fine, IMHO.
Done in the attached v5 patch.
> > How about we invent a new GUC log_recovery, with default set to false,
> > similar to log_checkpoints? And, these messages can be like:
> > ereport(log_recovery ? LOG : DEBUG1, .)? This GUC can be useful to
> > add some recovery stats in future as well. Thoughts?
>
> This discussion does not justify a new GUC at this stage IMO.
Having "log_recovery" GUC gives the flexibility to the users to enable
the recovery logs added by this patch if they are concerned otherwise
the logs just be at DEBUG1 level. Setting log_min_messages level to
DEBUG1 would definitely flood the server logs.
> While quickly testing, I got reminded that the LOG for a segment
> retrieved from the local pg_wal would generate some noise when running
> for example the bootstrap process. Is this one really interesting
> compared to the two others?
If we just have the archive related message at LOG level and others at
DEBUG1 level, it is a kind of partial recovery log information that
one has in the log files, missing recovery messages from the pg_wal
directory in the logs.
Another option is to just have all the messages (added in the patch)
at DEBUG1 level, let's users deal with it.
IMO, the new GUC "log_recovery" is way better as it can be extended to
include some recovery stats info as well.
Thoughts?
Regards,
Bharath Rupireddy.
From a486f3643cc7b84bae3cd6a72cd4d3323c224043 Mon Sep 17 00:00:00 2001
From: Bharath Rupireddy
Date: Wed, 8 Dec 2021 09:01:49 +
Subject: [PATCH v5] add log messages for recovery
The messages at LOG level would be helpful to know what's happening
with the system while in recovery. Although these messages seem to
be filling up the server logs, but the advantages we gain with them
are plenty. Of course, having a good log consumption and rotation
mechanism will help the server logs not fill up the disk.
These LOG messages will help us know how much time a restore command
takes to fetch the WAL file, what is the current WAL file the server
is recovering and where is it recovering from.
As a developer or admin, one can monitor these logs and do bunch of
things:
1) see how many WAL files left to be recovered by looking at the WAL
files in the archive location or pg_wal directory or from primary
2) provide an approximate estimation of when the server will come up
or how much more the recovery takes by looking at these previous LOG
messages, one can know the number of WAL files that server recovered
over a minute and with the help of left-over WAL files calculated.
---
src/backend/access/transam/xlog.c| 30 +++-
src/backend/access/transam/xlogarchive.c | 2 +-
2 files changed, 30 insertions(+), 2 deletions(-)
diff --git a/src/backend/access/transam/xlog.c b/src/backend/access/transam/xlog.c
index d894af310a..d799e12a3a 100644
--- a/src/backend/access/transam/xlog.c
+++ b/src/backend/access/transam/xlog.c
@@ -3787,6 +3787,10 @@ XLogFileRead(XLogSegNo segno, int emode, TimeLineID tli,
xlogfname);
set_ps_display(activitymsg);
+ ereport(LOG,
+ (errmsg("waiting for WAL segment \"%s\" from archive",
+ xlogfname)));
+
if (!RestoreArchivedFile(path, xlogfname,
"RECOVERYXLOG",
wal_segment_size,
@@ -3829,6 +3833,31 @@ XLogFileRead(XLogSegNo segno, int emode, TimeLineID tli,
xlogfname);
set_ps_display(activitymsg);
+ switch (source)
+ {
+ case XLOG_FROM_ARCHIVE:
+ereport(LOG,
+ (errmsg("recovering WAL segment \"%s\" received from archive",
+xlogfname)));
+break;
+ case XLOG_FROM_PG_WAL:
+ereport(LOG,
+ (errmsg("recovering WAL segment \"%s\" received from pg_wal",
+xlogfname)));
+break;
+ case XLOG_FROM_STREAM:
+ereport(LOG,
+ (errmsg("recovering WAL segment \"%s\" received from stream",
+xlogfname)));
+break;
+ default:
+/*
+ * Intentionally doing nothing here as invalid source check has
+ * already been perofrmed at the beginning of this function.
+ */
+break;
+ }
+
/* Track source of data in assorted state variables */
readSource = source;
XLogReceiptSource = source;
@@ -3919,7 +3948,6 @@ XLogFileReadAnyTLI(XLogSegNo segno, int emode, XLogSource source)
XLOG_FROM_ARCHIVE, true);
if (fd != -1)
{
-elog(DEBUG1, "got WAL segment from archive");
if (!expectedTLEs)
expectedTLEs = tles;
return fd;
diff --git a/src/backend/access/transam/xlogarchive.c b/src/backend/access/transam/xlogarchive.c
index 4ddeac1fb9..1f724f4acf 100644
--- a/src/backend/access/transam/xlogarchive.c
+++ b/src/backend/access/transam/xlogarchive.c
@@ -214,7 +214,7 @@ RestoreArchivedFile(char *path, const char *xlogfname,
else
{
ereport(LOG,
- (errmsg("restored log file \"%s\" from archive",
+
Re: add recovery, backup, archive, streaming etc. activity messages to server logs along with ps display
On Wed, Dec 08, 2021 at 02:00:12PM +0530, Bharath Rupireddy wrote: > For standby, "received from primary" makes sense. For cascading > standby too it makes sense because the standby still acts as primary > for cascading standby, no? And we don't distinguish any other existing > messages for a standby acting as a cascading standby right? The > comments around the enum XLOG_FROM_STREAM and usage of it still says > from "primary". Quoting the docs: https://www.postgresql.org/docs/devel/glossary.html#GLOSSARY-PRIMARY-SERVER And a standby is no such thing. > Do you want me to add "received from stream" in general? "from stream" would be fine, IMHO. > How about we invent a new GUC log_recovery, with default set to false, > similar to log_checkpoints? And, these messages can be like: > ereport(log_recovery ? LOG : DEBUG1, .)? This GUC can be useful to > add some recovery stats in future as well. Thoughts? This discussion does not justify a new GUC at this stage IMO. -- Michael signature.asc Description: PGP signature
Re: add recovery, backup, archive, streaming etc. activity messages to server logs along with ps display
On Wed, Dec 8, 2021 at 12:52 PM Michael Paquier wrote:
>
> On Wed, Dec 08, 2021 at 10:47:57AM +0530, Bharath Rupireddy wrote:
> > Thanks for taking a look at the patch. How about the attached v4?
> >
> > I added a CF entry - https://commitfest.postgresql.org/36/3443/
>
> + else if (source == XLOG_FROM_STREAM)
> + ereport(LOG,
> + (errmsg("recovering WAL segment \"%s\" received from
> primary",
> + xlogfname)));
> This is incorrect when using a cascading standby.
I visualize the setup like this: primary -> standby -> cascading standby
For standby, "received from primary" makes sense. For cascading
standby too it makes sense because the standby still acts as primary
for cascading standby, no? And we don't distinguish any other existing
messages for a standby acting as a cascading standby right? The
comments around the enum XLOG_FROM_STREAM and usage of it still says
from "primary".
Do you want me to add "received from stream" in general?
> And perhaps this could use a switch/case?
Yes, I will change it to switch-case in the next version.
> While quickly testing, I got reminded that the LOG for a segment
> retrieved from the local pg_wal would generate some noise when running
> for example the bootstrap process. Is this one really interesting
> compared to the two others?
Yes. I observed that for a simple primary-standby setup, inserting
10million rows generated around 40 WAL files and so 40 LOG messages in
the standby server logs, in a typical production environment with
heavy-write workload, the amount of LOG generation is going to be much
more. And we don't want to have them as DEBUG1 messages and enable
DEBUG1 just for recovery messages that one is interested in.
How about we invent a new GUC log_recovery, with default set to false,
similar to log_checkpoints? And, these messages can be like:
ereport(log_recovery ? LOG : DEBUG1, .)? This GUC can be useful to
add some recovery stats in future as well. Thoughts?
Regards,
Bharath Rupireddy.
Re: add recovery, backup, archive, streaming etc. activity messages to server logs along with ps display
On Wed, Dec 08, 2021 at 10:47:57AM +0530, Bharath Rupireddy wrote:
> Thanks for taking a look at the patch. How about the attached v4?
>
> I added a CF entry - https://commitfest.postgresql.org/36/3443/
+ else if (source == XLOG_FROM_STREAM)
+ ereport(LOG,
+ (errmsg("recovering WAL segment \"%s\" received from
primary",
+ xlogfname)));
This is incorrect when using a cascading standby. And perhaps this
could use a switch/case?
While quickly testing, I got reminded that the LOG for a segment
retrieved from the local pg_wal would generate some noise when running
for example the bootstrap process. Is this one really interesting
compared to the two others?
--
Michael
signature.asc
Description: PGP signature
Re: add recovery, backup, archive, streaming etc. activity messages to server logs along with ps display
On Wed, Dec 8, 2021 at 10:05 AM Michael Paquier wrote:
>
> On Tue, Dec 07, 2021 at 06:28:24PM +0530, Bharath Rupireddy wrote:
> > Upon thinking further, having at least the messages at LOG level [1]
> > would be helpful to know what's happening with the system while in
> > recovery. Although these messages at LOG level seem to be filling up
> > the server logs, having a good log consumption and rotation mechanism
> > (I'm sure every major postgres vendor would have one) would be
> > sufficient to allay that concern.
>
> + ereport(LOG,
> + (errmsg("recovering WAL segment \"%s\" from source \"%s\"",
> + xlogfname, srcname)));
> Isn't this approach an issue for translations? It seems to me that
> terms like "stream" or "archive" had better be translated properly,
> meaning that this needs a fully-constructed sentence.
Thanks for taking a look at the patch. How about the attached v4?
I added a CF entry - https://commitfest.postgresql.org/36/3443/
Regards,
Bharath Rupireddy.
v4-0001-add-log-messages-for-recovery.patch
Description: Binary data
Re: add recovery, backup, archive, streaming etc. activity messages to server logs along with ps display
On Tue, Dec 07, 2021 at 06:28:24PM +0530, Bharath Rupireddy wrote:
> Upon thinking further, having at least the messages at LOG level [1]
> would be helpful to know what's happening with the system while in
> recovery. Although these messages at LOG level seem to be filling up
> the server logs, having a good log consumption and rotation mechanism
> (I'm sure every major postgres vendor would have one) would be
> sufficient to allay that concern.
+ ereport(LOG,
+ (errmsg("recovering WAL segment \"%s\" from source \"%s\"",
+ xlogfname, srcname)));
Isn't this approach an issue for translations? It seems to me that
terms like "stream" or "archive" had better be translated properly,
meaning that this needs a fully-constructed sentence.
--
Michael
signature.asc
Description: PGP signature
Re: add recovery, backup, archive, streaming etc. activity messages to server logs along with ps display
On Wed, Nov 17, 2021 at 8:01 AM Michael Paquier wrote:
>
> On Tue, Nov 16, 2021 at 01:26:49PM -0300, Alvaro Herrera wrote:
> > My opinion is that adding these things willy-nilly is not a solution to
> > any actual problem. Adding a few additional log lines that are
> > low-volume at DEBUG1 might be useful, but below that (DEBUG2 etc) it's
> > not good for anything other than specific development, IMO. At least
> > this particular one for streaming replication I think we should not
> > include.
>
> Looking at v2, I think that this leaves the additions of the DEBUG1
> entries in SendBaseBackup() and WalRcvWaitForStartPosition(), then.
> The one in pgarch.c does not provide any additional information as the
> segment to-be-archived should be part of the command.
Thank you all for the inputs. Here's the patch that I've come up with.
Upon thinking further, having at least the messages at LOG level [1]
would be helpful to know what's happening with the system while in
recovery. Although these messages at LOG level seem to be filling up
the server logs, having a good log consumption and rotation mechanism
(I'm sure every major postgres vendor would have one) would be
sufficient to allay that concern.
These LOG messages would help us know how much time a restore command
takes to fetch the WAL file and what is the current WAL file the
server is recovering and where is it recovering from. The customer
often asks questions like: when will my server come up? how much time
does the recovery of my server take?
As a developer or admin, one can monitor these logs and do bunch of things:
1) see how many WAL files left to be recovered by looking at the WAL
files in the archive location or pg_wal directory or from primary
2) provide an approximate estimation of when the server will come up
or how much more the recovery takes by looking at these previous LOG
messages, one can know the number of WAL files that server recovered
over a minute and with the help of left-over WAL files calculated from
(1).
[1]
ereport(LOG,
(errmsg("waiting for WAL segment \"%s\" from archive",
xlogfname)));
ereport(LOG,
(errmsg("restored WAL segment \"%s\" from archive",
xlogfname)));
ereport(LOG,
(errmsg("recovering WAL segment \"%s\" from source \"%s\"",
xlogfname, srcname)));
Regards,
Bharath Rupireddy.
v3-0001-add-log-messages-for-recovery.patch
Description: Binary data
Re: add recovery, backup, archive, streaming etc. activity messages to server logs along with ps display
On Tue, Nov 16, 2021 at 01:26:49PM -0300, Alvaro Herrera wrote: > My opinion is that adding these things willy-nilly is not a solution to > any actual problem. Adding a few additional log lines that are > low-volume at DEBUG1 might be useful, but below that (DEBUG2 etc) it's > not good for anything other than specific development, IMO. At least > this particular one for streaming replication I think we should not > include. Looking at v2, I think that this leaves the additions of the DEBUG1 entries in SendBaseBackup() and WalRcvWaitForStartPosition(), then. The one in pgarch.c does not provide any additional information as the segment to-be-archived should be part of the command. -- Michael signature.asc Description: PGP signature
Re: add recovery, backup, archive, streaming etc. activity messages to server logs along with ps display
On 2021-Nov-16, Bossart, Nathan wrote:
> On 11/15/21, 7:14 PM, "Michael Paquier" wrote:
> > + ereport(DEBUG1,
> > + (errmsg_internal("streaming %X/%X",
> > +
> > LSN_FORMAT_ARGS(sentPtr;
> > Anyway, those two ones are going to make the logs much more noisy, no?
> > The same could be said about XLogFileRead(), joining the point of
> > Nathan's upthread. So I cannot get excited by this change.
>
> Yeah, this might even be too noisy for DEBUG5.
Nod. And if you're at DEBUG5, the log contains so much other crap that
it is unusable for any purposes anyway.
My opinion is that adding these things willy-nilly is not a solution to
any actual problem. Adding a few additional log lines that are
low-volume at DEBUG1 might be useful, but below that (DEBUG2 etc) it's
not good for anything other than specific development, IMO. At least
this particular one for streaming replication I think we should not
include.
--
Álvaro Herrera PostgreSQL Developer — https://www.EnterpriseDB.com/
Re: add recovery, backup, archive, streaming etc. activity messages to server logs along with ps display
On 11/15/21, 7:14 PM, "Michael Paquier" wrote:
> + ereport(DEBUG1,
> + (errmsg_internal("streaming %X/%X",
> +
> LSN_FORMAT_ARGS(sentPtr;
> Anyway, those two ones are going to make the logs much more noisy, no?
> The same could be said about XLogFileRead(), joining the point of
> Nathan's upthread. So I cannot get excited by this change.
Yeah, this might even be too noisy for DEBUG5.
Nathan
Re: add recovery, backup, archive, streaming etc. activity messages to server logs along with ps display
On Mon, Nov 15, 2021 at 10:36:09PM +, Bossart, Nathan wrote:
> +ereport(DEBUG1,
> +(errmsg_internal("executing archive command \"%s\" for archving
> %s",
> + xlogarchcmd, xlog)));
>
> I wonder if it's necessary to include the "for archiving" part in this
> one. Typically, the xlogarchcmd will include it somewhere.
Don't see any need to add that either (s/archving/archiving/, btw).
@@ -1000,6 +1004,10 @@ XLogWalRcvFlush(bool dying, TimeLineID tli)
+ ereport(DEBUG1,
+ (errmsg_internal("streaming %X/%X",
+ LSN_FORMAT_ARGS(LogstreamResult.Write;
Having the same wording for the WAL receiver and the WAL sender could
be confusing when it comes to a cascading standby node, particularly
if log_line_prefix does not include the process PID.
+ ereport(DEBUG1,
+ (errmsg_internal("streaming %X/%X",
+
LSN_FORMAT_ARGS(sentPtr;
Anyway, those two ones are going to make the logs much more noisy, no?
The same could be said about XLogFileRead(), joining the point of
Nathan's upthread. So I cannot get excited by this change.
--
Michael
signature.asc
Description: PGP signature
Re: add recovery, backup, archive, streaming etc. activity messages to server logs along with ps display
On 11/14/21, 4:18 AM, "Bharath Rupireddy"
wrote:
> Thanks. Attaching the v2 to avoid that by directly using the message
> in ereport instead of activitymsg.
+ereport(DEBUG1,
+(errmsg_internal("waiting for %s", xlogfname)));
As a general comment, I think we should include more detail than what
goes in the ps title. While we probably want to keep the ps title,
brief, I don't see any issue with including a bit more context in
debug statements.
+ereport(DEBUG1,
+(errmsg_internal("executing archive command \"%s\" for archving
%s",
+ xlogarchcmd, xlog)));
I wonder if it's necessary to include the "for archiving" part in this
one. Typically, the xlogarchcmd will include it somewhere.
Nathan
Re: add recovery, backup, archive, streaming etc. activity messages to server logs along with ps display
On Sat, Nov 13, 2021 at 9:04 PM Alvaro Herrera
wrote:
>
> A bunch of these now execute snprintf()s unnecessarily. I think these
> should be made conditional on message_level_is_interesting(DEBUG1) to
> avoid that overhead.
Thanks. Attaching the v2 to avoid that by directly using the message in
ereport instead of activitymsg.
Regards,
Bharath Rupireddy.
From 6eea044a734fc53353deaa973df6f70096160435 Mon Sep 17 00:00:00 2001
From: Bharath Rupireddy
Date: Sun, 14 Nov 2021 02:29:04 +
Subject: [PATCH v2] add log messages equivalents of ps display activitymsgs
---
src/backend/access/transam/xlog.c | 6 ++
src/backend/postmaster/pgarch.c | 8
src/backend/replication/basebackup.c | 3 +++
src/backend/replication/walreceiver.c | 8
src/backend/replication/walsender.c | 4
5 files changed, 25 insertions(+), 4 deletions(-)
diff --git a/src/backend/access/transam/xlog.c b/src/backend/access/transam/xlog.c
index e073121a7e..3a62b4c745 100644
--- a/src/backend/access/transam/xlog.c
+++ b/src/backend/access/transam/xlog.c
@@ -3791,6 +3791,9 @@ XLogFileRead(XLogSegNo segno, int emode, TimeLineID tli,
xlogfname);
set_ps_display(activitymsg);
+ ereport(DEBUG1,
+ (errmsg_internal("waiting for %s", xlogfname)));
+
if (!RestoreArchivedFile(path, xlogfname,
"RECOVERYXLOG",
wal_segment_size,
@@ -3833,6 +3836,9 @@ XLogFileRead(XLogSegNo segno, int emode, TimeLineID tli,
xlogfname);
set_ps_display(activitymsg);
+ ereport(DEBUG1,
+(errmsg_internal("recovering %s", xlogfname)));
+
/* Track source of data in assorted state variables */
readSource = source;
XLogReceiptSource = source;
diff --git a/src/backend/postmaster/pgarch.c b/src/backend/postmaster/pgarch.c
index 3b33e01d95..abfe451dbe 100644
--- a/src/backend/postmaster/pgarch.c
+++ b/src/backend/postmaster/pgarch.c
@@ -547,14 +547,14 @@ pgarch_archiveXlog(char *xlog)
}
*dp = '\0';
- ereport(DEBUG3,
- (errmsg_internal("executing archive command \"%s\"",
- xlogarchcmd)));
-
/* Report archive activity in PS display */
snprintf(activitymsg, sizeof(activitymsg), "archiving %s", xlog);
set_ps_display(activitymsg);
+ ereport(DEBUG1,
+ (errmsg_internal("executing archive command \"%s\" for archving %s",
+ xlogarchcmd, xlog)));
+
rc = system(xlogarchcmd);
if (rc != 0)
{
diff --git a/src/backend/replication/basebackup.c b/src/backend/replication/basebackup.c
index ec0485705d..bc173bfe8e 100644
--- a/src/backend/replication/basebackup.c
+++ b/src/backend/replication/basebackup.c
@@ -881,6 +881,9 @@ SendBaseBackup(BaseBackupCmd *cmd)
set_ps_display(activitymsg);
}
+ ereport(DEBUG1,
+ (errmsg_internal("sending backup \"%s\"", opt.label)));
+
/* Create a basic basebackup sink. */
sink = bbsink_copytblspc_new();
diff --git a/src/backend/replication/walreceiver.c b/src/backend/replication/walreceiver.c
index 7a7eb3784e..f0062aa615 100644
--- a/src/backend/replication/walreceiver.c
+++ b/src/backend/replication/walreceiver.c
@@ -712,6 +712,10 @@ WalRcvWaitForStartPosition(XLogRecPtr *startpoint, TimeLineID *startpointTLI)
LSN_FORMAT_ARGS(*startpoint));
set_ps_display(activitymsg);
}
+
+ ereport(DEBUG1,
+ (errmsg_internal("restarting at %X/%X",
+ LSN_FORMAT_ARGS(*startpoint;
}
/*
@@ -1000,6 +1004,10 @@ XLogWalRcvFlush(bool dying, TimeLineID tli)
set_ps_display(activitymsg);
}
+ ereport(DEBUG1,
+(errmsg_internal("streaming %X/%X",
+ LSN_FORMAT_ARGS(LogstreamResult.Write;
+
/* Also let the primary know that we made some progress */
if (!dying)
{
diff --git a/src/backend/replication/walsender.c b/src/backend/replication/walsender.c
index 7950afb173..e04bab54c9 100644
--- a/src/backend/replication/walsender.c
+++ b/src/backend/replication/walsender.c
@@ -2948,6 +2948,10 @@ retry:
LSN_FORMAT_ARGS(sentPtr));
set_ps_display(activitymsg);
}
+
+ ereport(DEBUG1,
+ (errmsg_internal("streaming %X/%X",
+ LSN_FORMAT_ARGS(sentPtr;
}
/*
--
2.25.1
Re: add recovery, backup, archive, streaming etc. activity messages to server logs along with ps display
A bunch of these now execute snprintf()s unnecessarily. I think these should be made conditional on message_level_is_interesting(DEBUG1) to avoid that overhead. -- Álvaro Herrera PostgreSQL Developer — https://www.EnterpriseDB.com/ "You're _really_ hosed if the person doing the hiring doesn't understand relational systems: you end up with a whole raft of programmers, none of whom has had a Date with the clue stick." (Andrew Sullivan)
Re: add recovery, backup, archive, streaming etc. activity messages to server logs along with ps display
On Thu, Nov 11, 2021 at 8:41 PM Bossart, Nathan wrote: > > I'm not sure whether it is okay to do the following, for every of the > > activitymsg, before the command execution, we have an elog(DEBUG1 > > message and after the command execution another elog(DEBUG1 message. > > The general idea seems reasonable to me. Here's a simple patch that I could come up with. Please have a look. Regards, Bharath Rupireddy. v1-0001-add-log-messages-that-are-equivalent-of-ps-displa.patch Description: Binary data
Re: add recovery, backup, archive, streaming etc. activity messages to server logs along with ps display
On Thu, Nov 11, 2021 at 6:07 PM Alvaro Herrera wrote: > On 2021-Nov-10, Bossart, Nathan wrote: > > > On 11/10/21, 9:43 AM, "Bharath Rupireddy" < > bharath.rupireddyforpostg...@gmail.com> wrote: > > > As discussed in [1], isn't it a better idea to add some of activity > > > messages [2] such as recovery, archive, backup, streaming etc. to > > > server logs at LOG level? > > > I think this would make the logs far too noisy for many servers. For > > archiving alone, this could cause tens of thousands more log messages > > per hour on a busy system. I think you can already see such > > information at a debug level, anyway. > > Yeah. If we had some sort of ring buffer in which to store these > messages, the user could examine them through a view; they would still > be accessible in a running server, but they would not be written to the > server log. > That's a good idea. How about also adding some GUC(s) to the log archive, recovery related log messages just like we have for checkpoints, autovacuum etc? Maybe something like log_archive, log_recovery etc. -- With Regards, Ashutosh Sharma.
Re: add recovery, backup, archive, streaming etc. activity messages to server logs along with ps display
On Thu, Nov 11, 2021 at 03:18:16PM +, Bossart, Nathan wrote: > On 11/11/21, 4:38 AM, "Alvaro Herrera" wrote: > > Yeah. If we had some sort of ring buffer in which to store these > > messages, the user could examine them through a view; they would still > > be accessible in a running server, but they would not be written to the > > server log. > > That's an interesting idea. It'd be nice to have a way to see more > debugging information without exploding the server log. Uh, that's what dmesg does, which I mentioned earlier. -- Bruce Momjian https://momjian.us EDB https://enterprisedb.com If only the physical world exists, free will is an illusion.
Re: add recovery, backup, archive, streaming etc. activity messages to server logs along with ps display
On Thu, Nov 11, 2021, at 2:50 AM, Bharath Rupireddy wrote: > But for the snprintf(activitymsg, sizeof(activitymsg), "archiving %s", > xlog); we have elog(DEBUG1, "archived write-ahead log file \"%s\"", > xlog); after the archiving command. It is also good to have a similar > debug message before archive command execution, we can get to know > whether archive command is executed or not, if yes how much time did > it take etc.? If you are only interested in how much time it took to archive a WAL file, you don't need 2 messages (before and after); one message is sufficient. If you calculate the difference and then print it as part of the existent message. Calculate the difference iif the log level is at least DEBUG1 (same as the log message). Messages related to system() e.g. archive and recovery, you could measure the execution time in your own script/program. I like Alvaro's idea of implementing a ring buffer for this kind of activity. This implementation could be applied to checkpoints, archiving, recovery, replication, base backup, WAL usage, connections and others. -- Euler Taveira EDB https://www.enterprisedb.com/
Re: add recovery, backup, archive, streaming etc. activity messages to server logs along with ps display
On 11/11/21, 4:38 AM, "Alvaro Herrera" wrote: > Yeah. If we had some sort of ring buffer in which to store these > messages, the user could examine them through a view; they would still > be accessible in a running server, but they would not be written to the > server log. That's an interesting idea. It'd be nice to have a way to see more debugging information without exploding the server log. Nathan
Re: add recovery, backup, archive, streaming etc. activity messages to server logs along with ps display
On 11/10/21, 9:51 PM, "Bharath Rupireddy" wrote: > But for the snprintf(activitymsg, sizeof(activitymsg), "archiving %s", > xlog); we have elog(DEBUG1, "archived write-ahead log file \"%s\"", > xlog); after the archiving command. It is also good to have a similar > debug message before archive command execution, we can get to know > whether archive command is executed or not, if yes how much time did > it take etc.? There is a DEBUG3 that emits "executing archive command..." prior to executing the archive command. > I'm not sure whether it is okay to do the following, for every of the > activitymsg, before the command execution, we have an elog(DEBUG1 > message and after the command execution another elog(DEBUG1 message. The general idea seems reasonable to me. Nathan
Re: add recovery, backup, archive, streaming etc. activity messages to server logs along with ps display
On 2021-Nov-10, Bossart, Nathan wrote: > On 11/10/21, 9:43 AM, "Bharath Rupireddy" > wrote: > > As discussed in [1], isn't it a better idea to add some of activity > > messages [2] such as recovery, archive, backup, streaming etc. to > > server logs at LOG level? > I think this would make the logs far too noisy for many servers. For > archiving alone, this could cause tens of thousands more log messages > per hour on a busy system. I think you can already see such > information at a debug level, anyway. Yeah. If we had some sort of ring buffer in which to store these messages, the user could examine them through a view; they would still be accessible in a running server, but they would not be written to the server log. -- Álvaro Herrera PostgreSQL Developer — https://www.EnterpriseDB.com/
Re: add recovery, backup, archive, streaming etc. activity messages to server logs along with ps display
On Thu, Nov 11, 2021 at 1:40 AM Euler Taveira wrote: > > On Wed, Nov 10, 2021, at 2:38 PM, Bharath Rupireddy wrote: > > As discussed in [1], isn't it a better idea to add some of activity > messages [2] such as recovery, archive, backup, streaming etc. to > server logs at LOG level? They are currently being set into ps display > which is good if the postgres is being run on a standalone box/VM > where users can see the ps display, but it doesn't help much in case > the postgres is being run on a cloud environment where users don't > have access to ps display output. Moreover, the ps display is > transient and will not help to analyze after an issue occurs. > > Besides recovery, the other activities already provide information through > views. I might be missing something but it seems the current views already > provide the information that ps displays. > > Having the above messages in the server logs will be useful to > understand how the system is/was doing/progressing with these > (sometimes time-intensive) operations. > > It could be useful for a root cause analysis, however, you are also increasing > the number of LOG messages in a system that doesn't/won't require such > information. It is fine to add additional DEBUG messages if there isn't a > similar one yet. If at least the message level were module-controlled, you > could modify a setting to gather more messages from a specific module. > Unfortunately, that's not possible so we should avoid superfluous messages. Yes, at least having the messages at DEBUG1 level would help do the RCA after an issue occurs. Please see my response upthread at [1]. [1] - https://www.postgresql.org/message-id/CALj2ACXVwnHhek9bo9wgamtW9SBinj4ohF1f1Yf3Su2o5WarWg%40mail.gmail.com Regards, Bharath Rupireddy.
Re: add recovery, backup, archive, streaming etc. activity messages to server logs along with ps display
On Thu, Nov 11, 2021 at 12:01 AM Bossart, Nathan wrote: > > On 11/10/21, 9:43 AM, "Bharath Rupireddy" > wrote: > > As discussed in [1], isn't it a better idea to add some of activity > > messages [2] such as recovery, archive, backup, streaming etc. to > > server logs at LOG level? They are currently being set into ps display > > which is good if the postgres is being run on a standalone box/VM > > where users can see the ps display, but it doesn't help much in case > > the postgres is being run on a cloud environment where users don't > > have access to ps display output. Moreover, the ps display is > > transient and will not help to analyze after an issue occurs. > > > > Having the above messages in the server logs will be useful to > > understand how the system is/was doing/progressing with these > > (sometimes time-intensive) operations. > > I think this would make the logs far too noisy for many servers. For > archiving alone, this could cause tens of thousands more log messages > per hour on a busy system. I think you can already see such > information at a debug level, anyway. You are right, having them at LOG level may blow up the log files and disk storage, having them at DEBUG1 like other messages would at least help than having them as activitymsg in ps display. And not all of the activitymsgs are logged at DEBUGX level, at least I don't see them(on a quick search). snprintf(activitymsg, sizeof(activitymsg), "waiting for %s", snprintf(activitymsg, sizeof(activitymsg), "recovering %s", snprintf(activitymsg, sizeof(activitymsg), "performing %s%s%s", snprintf(activitymsg, sizeof(activitymsg), "sending backup \"%s\"", snprintf(activitymsg, sizeof(activitymsg), "restarting at %X/%X", snprintf(activitymsg, sizeof(activitymsg), "streaming %X/%X", But for the snprintf(activitymsg, sizeof(activitymsg), "archiving %s", xlog); we have elog(DEBUG1, "archived write-ahead log file \"%s\"", xlog); after the archiving command. It is also good to have a similar debug message before archive command execution, we can get to know whether archive command is executed or not, if yes how much time did it take etc.? I'm not sure whether it is okay to do the following, for every of the activitymsg, before the command execution, we have an elog(DEBUG1 message and after the command execution another elog(DEBUG1 message. Thoughts? Regards, Bharath Rupireddy.
Re: add recovery, backup, archive, streaming etc. activity messages to server logs along with ps display
On Wed, Nov 10, 2021, at 2:38 PM, Bharath Rupireddy wrote: > As discussed in [1], isn't it a better idea to add some of activity > messages [2] such as recovery, archive, backup, streaming etc. to > server logs at LOG level? They are currently being set into ps display > which is good if the postgres is being run on a standalone box/VM > where users can see the ps display, but it doesn't help much in case > the postgres is being run on a cloud environment where users don't > have access to ps display output. Moreover, the ps display is > transient and will not help to analyze after an issue occurs. Besides recovery, the other activities already provide information through views. I might be missing something but it seems the current views already provide the information that ps displays. > Having the above messages in the server logs will be useful to > understand how the system is/was doing/progressing with these > (sometimes time-intensive) operations. It could be useful for a root cause analysis, however, you are also increasing the number of LOG messages in a system that doesn't/won't require such information. It is fine to add additional DEBUG messages if there isn't a similar one yet. If at least the message level were module-controlled, you could modify a setting to gather more messages from a specific module. Unfortunately, that's not possible so we should avoid superfluous messages. -- Euler Taveira EDB https://www.enterprisedb.com/
Re: add recovery, backup, archive, streaming etc. activity messages to server logs along with ps display
On 11/10/21, 9:43 AM, "Bharath Rupireddy" wrote: > As discussed in [1], isn't it a better idea to add some of activity > messages [2] such as recovery, archive, backup, streaming etc. to > server logs at LOG level? They are currently being set into ps display > which is good if the postgres is being run on a standalone box/VM > where users can see the ps display, but it doesn't help much in case > the postgres is being run on a cloud environment where users don't > have access to ps display output. Moreover, the ps display is > transient and will not help to analyze after an issue occurs. > > Having the above messages in the server logs will be useful to > understand how the system is/was doing/progressing with these > (sometimes time-intensive) operations. I think this would make the logs far too noisy for many servers. For archiving alone, this could cause tens of thousands more log messages per hour on a busy system. I think you can already see such information at a debug level, anyway. Nathan
