Make postmaster environment dump easier to skim over
Hi,
I somewhat regularly start postmaster with log_min_messages DEBUG3-5. One
thing that makes that unnecessarily annoying is postmaster's environment dump
at startup. It's visually hard to skip over, as it emits each environment
variable as a separate log message.
It's even worse if one uses log_error_verbosity=verbose or such, to get log
lines:
2024-11-26 11:34:17.739 EST [1097046][postmaster][:0][] DEBUG: 00000: postgres: PostmasterMain: initial environment dump:
2024-11-26 11:34:17.739 EST [1097046][postmaster][:0][] LOCATION: PostmasterMain, postmaster.c:887
2024-11-26 11:34:17.739 EST [1097046][postmaster][:0][] DEBUG: 00000: -----------------------------------------
2024-11-26 11:34:17.739 EST [1097046][postmaster][:0][] LOCATION: PostmasterMain, postmaster.c:890
2024-11-26 11:34:17.739 EST [1097046][postmaster][:0][] DEBUG: 00000: SHELL=/bin/bash
...
2024-11-26 11:34:17.739 EST [1097046][postmaster][:0][] LOCATION: PostmasterMain, postmaster.c:893
2024-11-26 11:34:17.739 EST [1097046][postmaster][:0][] DEBUG: 00000: DISPLAY=:0
2024-11-26 11:34:17.739 EST [1097046][postmaster][:0][] LOCATION: PostmasterMain, postmaster.c:893
2024-11-26 11:34:17.739 EST [1097046][postmaster][:0][] DEBUG: 00000: SHLVL=1
...
2024-11-26 11:34:17.739 EST [1097046][postmaster][:0][] DEBUG: 00000: LC_TIME=C
2024-11-26 11:34:17.739 EST [1097046][postmaster][:0][] LOCATION: PostmasterMain, postmaster.c:893
2024-11-26 11:34:17.739 EST [1097046][postmaster][:0][] DEBUG: 00000: -----------------------------------------
2024-11-26 11:34:17.739 EST [1097046][postmaster][:0][] LOCATION: PostmasterMain, postmaster.c:895
isn't trivial to skim.
I think the dump is occasionally useful, so I don't think the best course is
to remove it entirely. But I think we could fairly easily improve the
situation by emitting all environment variables as a single elog message.
2024-11-26 11:35:58.877 EST [1097572][postmaster][:0][] DEBUG: 00000: postgres: PostmasterMain: initial environment dump:
SHELL=/bin/bash
...
DISPLAY=:0
SHLVL=1
...
LC_TIME=C
2024-11-26 11:35:58.877 EST [1097572][postmaster][:0][] LOCATION: PostmasterMain, postmaster.c:879
is - IMNSHO - a heck of a lot more skimmable.
In the attached patch I chose to omit the "-----------------------------------------"
that we previously emmitted. IMO they're not really needed anymore now that
this is emitted as one message.
I'm not sure why the message includes "progname" and
PostmasterMain. Particularly the latter seems redundant with the elog
infrastructure today, the message is quite old (an elog since a033daf56639 in
2002 and an fprintf in the current location since ebb0a2014930, in 2000). But
I didn't touch that for now.
Alternatively we could just remove the message.
Greetings,
Andres Freund
Attachments:
v1-0001-postmaster-Reduce-verbosity-of-environment-dump-d.patchtext/x-diff; charset=us-asciiDownload
From 66aa0b81a25db80d2beb31df656a475c84b09d9b Mon Sep 17 00:00:00 2001
From: Andres Freund <andres@anarazel.de>
Date: Tue, 26 Nov 2024 11:48:58 -0500
Subject: [PATCH v1] postmaster: Reduce verbosity of environment dump debug
message
Emitting each variable is unnecessarily verbose / hard to skim over.
Author:
Reviewed-by:
Discussion: https://postgr.es/m/
Backpatch:
---
src/backend/postmaster/postmaster.c | 19 ++++++++++---------
1 file changed, 10 insertions(+), 9 deletions(-)
diff --git a/src/backend/postmaster/postmaster.c b/src/backend/postmaster/postmaster.c
index 78e66a06ac5..f17923adac1 100644
--- a/src/backend/postmaster/postmaster.c
+++ b/src/backend/postmaster/postmaster.c
@@ -839,20 +839,21 @@ PostmasterMain(int argc, char *argv[])
#endif
/* For debugging: display postmaster environment */
+ if (message_level_is_interesting(DEBUG3))
{
extern char **environ;
char **p;
+ StringInfoData si;
- ereport(DEBUG3,
- (errmsg_internal("%s: PostmasterMain: initial environment dump:",
- progname)));
- ereport(DEBUG3,
- (errmsg_internal("-----------------------------------------")));
+ initStringInfo(&si);
+
+ appendStringInfo(&si, "%s: PostmasterMain: initial environment dump:",
+ progname);
for (p = environ; *p; ++p)
- ereport(DEBUG3,
- (errmsg_internal("\t%s", *p)));
- ereport(DEBUG3,
- (errmsg_internal("-----------------------------------------")));
+ appendStringInfo(&si, "\n%s", *p);
+
+ ereport(DEBUG3, errmsg_internal("%s", si.data));
+ pfree(si.data);
}
/*
--
2.45.2.746.g06e570c0df.dirty
On 26/11/2024 18:55, Andres Freund wrote:
I somewhat regularly start postmaster with log_min_messages DEBUG3-5. One
thing that makes that unnecessarily annoying is postmaster's environment dump
at startup. It's visually hard to skip over, as it emits each environment
variable as a separate log message.
I never do that and therefore didn't realize that we print that :-).
It's even worse if one uses log_error_verbosity=verbose or such, to get log
lines:2024-11-26 11:34:17.739 EST [1097046][postmaster][:0][] DEBUG: 00000: postgres: PostmasterMain: initial environment dump:
2024-11-26 11:34:17.739 EST [1097046][postmaster][:0][] LOCATION: PostmasterMain, postmaster.c:887
2024-11-26 11:34:17.739 EST [1097046][postmaster][:0][] DEBUG: 00000: -----------------------------------------
2024-11-26 11:34:17.739 EST [1097046][postmaster][:0][] LOCATION: PostmasterMain, postmaster.c:890
2024-11-26 11:34:17.739 EST [1097046][postmaster][:0][] DEBUG: 00000: SHELL=/bin/bash
...
2024-11-26 11:34:17.739 EST [1097046][postmaster][:0][] LOCATION: PostmasterMain, postmaster.c:893
2024-11-26 11:34:17.739 EST [1097046][postmaster][:0][] DEBUG: 00000: DISPLAY=:0
2024-11-26 11:34:17.739 EST [1097046][postmaster][:0][] LOCATION: PostmasterMain, postmaster.c:893
2024-11-26 11:34:17.739 EST [1097046][postmaster][:0][] DEBUG: 00000: SHLVL=1
...
2024-11-26 11:34:17.739 EST [1097046][postmaster][:0][] DEBUG: 00000: LC_TIME=C
2024-11-26 11:34:17.739 EST [1097046][postmaster][:0][] LOCATION: PostmasterMain, postmaster.c:893
2024-11-26 11:34:17.739 EST [1097046][postmaster][:0][] DEBUG: 00000: -----------------------------------------
2024-11-26 11:34:17.739 EST [1097046][postmaster][:0][] LOCATION: PostmasterMain, postmaster.c:895isn't trivial to skim.
I think the dump is occasionally useful, so I don't think the best course is
to remove it entirely. But I think we could fairly easily improve the
situation by emitting all environment variables as a single elog message.2024-11-26 11:35:58.877 EST [1097572][postmaster][:0][] DEBUG: 00000: postgres: PostmasterMain: initial environment dump:
SHELL=/bin/bash
...
DISPLAY=:0
SHLVL=1
...
LC_TIME=C
2024-11-26 11:35:58.877 EST [1097572][postmaster][:0][] LOCATION: PostmasterMain, postmaster.c:879is - IMNSHO - a heck of a lot more skimmable.
In the attached patch I chose to omit the "-----------------------------------------"
that we previously emmitted. IMO they're not really needed anymore now that
this is emitted as one message.
+1
I'm not sure why the message includes "progname" and
PostmasterMain. Particularly the latter seems redundant with the elog
infrastructure today, the message is quite old (an elog since a033daf56639 in
2002 and an fprintf in the current location since ebb0a2014930, in 2000). But
I didn't touch that for now.
+1 for removing PostmasterMain. The progname might be useful I guess,
but it'd not clear from the message that that's what "postgres" is.
Maybe change it to "progname: \"%s\", initial environment: ".
--
Heikki Linnakangas
Neon (https://neon.tech)
On 26.11.24 17:55, Andres Freund wrote:
I think the dump is occasionally useful, so I don't think the best course is
to remove it entirely. But I think we could fairly easily improve the
situation by emitting all environment variables as a single elog message.2024-11-26 11:35:58.877 EST [1097572][postmaster][:0][] DEBUG: 00000: postgres: PostmasterMain: initial environment dump:
SHELL=/bin/bash
...
DISPLAY=:0
SHLVL=1
...
LC_TIME=C
2024-11-26 11:35:58.877 EST [1097572][postmaster][:0][] LOCATION: PostmasterMain, postmaster.c:879is - IMNSHO - a heck of a lot more skimmable.
In the attached patch I chose to omit the "-----------------------------------------"
that we previously emmitted. IMO they're not really needed anymore now that
this is emitted as one message.
Yes, that makes a lot of sense.
I'm not sure why the message includes "progname" and
PostmasterMain. Particularly the latter seems redundant with the elog
infrastructure today, the message is quite old (an elog since a033daf56639 in
2002 and an fprintf in the current location since ebb0a2014930, in 2000). But
I didn't touch that for now.
Yes, that looks like an unnecessary leftover. Let's just remove it.
Hi,
On 2024-11-27 14:56:33 +0100, Peter Eisentraut wrote:
On 26.11.24 17:55, Andres Freund wrote:
I think the dump is occasionally useful, so I don't think the best course is
to remove it entirely. But I think we could fairly easily improve the
situation by emitting all environment variables as a single elog message.2024-11-26 11:35:58.877 EST [1097572][postmaster][:0][] DEBUG: 00000: postgres: PostmasterMain: initial environment dump:
SHELL=/bin/bash
...
DISPLAY=:0
SHLVL=1
...
LC_TIME=C
2024-11-26 11:35:58.877 EST [1097572][postmaster][:0][] LOCATION: PostmasterMain, postmaster.c:879is - IMNSHO - a heck of a lot more skimmable.
In the attached patch I chose to omit the "-----------------------------------------"
that we previously emmitted. IMO they're not really needed anymore now that
this is emitted as one message.Yes, that makes a lot of sense.
I'm not sure why the message includes "progname" and
PostmasterMain. Particularly the latter seems redundant with the elog
infrastructure today, the message is quite old (an elog since a033daf56639 in
2002 and an fprintf in the current location since ebb0a2014930, in 2000). But
I didn't touch that for now.Yes, that looks like an unnecessary leftover. Let's just remove it.
Thanks for looking Peter and Heikki. Removed progname and PostmasterMain
references and pushed.
Greetings,
Andres Freund