Horton

Thread

Commits

  1. postmaster: Reduce verbosity of environment dump debug message

  1. Make postmaster environment dump easier to skim over

    Andres Freund <andres@anarazel.de> — 2024-11-26T16:55:18Z

    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

  2. Re: Make postmaster environment dump easier to skim over

    Heikki Linnakangas <hlinnaka@iki.fi> — 2024-11-26T17:08:30Z

    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: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.

+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)

  3. Re: Make postmaster environment dump easier to skim over

    Peter Eisentraut <peter@eisentraut.org> — 2024-11-27T13:56:33Z

    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: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.

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.

  4. Re: Make postmaster environment dump easier to skim over

    Andres Freund <andres@anarazel.de> — 2024-11-27T16:18:49Z

    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: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.
> 
> 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