Обсуждение: process type escape for log_line_prefix

Hi,

Frequently when reading postgres logs to do some post mortem analysis
I'm left wondering what process emitted an error/log message. After the
fact it's often hard to know wether an error message was emitted by a
user backend or by something internal, say the checkpointer or
autovacuum.  Logging all process starts is often impractical given the
log volume that causes.

So I'm proposing adding an escape displaying the process title (say 'k'
for kind?). So %k would emit something like "autovacuum worker process",
"wal sender process" etc.

I'm thinking it might make sense to give normal connections "" as the
name, they're usually already discernible.

Greetings,

Andres Freund

On Mon, Feb 8, 2016 at 11:32 PM, Andres Freund <andres@anarazel.de> wrote:
> Frequently when reading postgres logs to do some post mortem analysis
> I'm left wondering what process emitted an error/log message. After the
> fact it's often hard to know wether an error message was emitted by a
> user backend or by something internal, say the checkpointer or
> autovacuum.  Logging all process starts is often impractical given the
> log volume that causes.
>
> So I'm proposing adding an escape displaying the process title (say 'k'
> for kind?). So %k would emit something like "autovacuum worker process",
> "wal sender process" etc.

It would be nice to get something consistent between the ps output and
this new prefix, say with for example a miscadmin.h parameter like
MyProcName.

> I'm thinking it might make sense to give normal connections "" as the
> name, they're usually already discernible.

Yeah, that sounds fine for me. What about background workers? I would
think that they should use BackgroundWorker->bgw_name.
-- 
Michael

Re: Michael Paquier 2016-02-10 <CAB7nPqS=wBbZzBcty1KyN-5Y9bPXZ+deJbfcCtebf06eF2Uyvg@mail.gmail.com>
> On Mon, Feb 8, 2016 at 11:32 PM, Andres Freund <andres@anarazel.de> wrote:
> > Frequently when reading postgres logs to do some post mortem analysis
> > I'm left wondering what process emitted an error/log message. After the
> > fact it's often hard to know wether an error message was emitted by a
> > user backend or by something internal, say the checkpointer or
> > autovacuum.  Logging all process starts is often impractical given the
> > log volume that causes.
> >
> > So I'm proposing adding an escape displaying the process title (say 'k'
> > for kind?). So %k would emit something like "autovacuum worker process",
> > "wal sender process" etc.
> 
> It would be nice to get something consistent between the ps output and
> this new prefix, say with for example a miscadmin.h parameter like
> MyProcName.
> 
> > I'm thinking it might make sense to give normal connections "" as the
> > name, they're usually already discernible.
> 
> Yeah, that sounds fine for me. What about background workers? I would
> think that they should use BackgroundWorker->bgw_name.

(Rediscovering an old horse)

Couldn't these processes just set %a = application_name? (This would
obviously need %q to be taught that %a is always valid.)

Christoph

Re: Jeff Janes 2016-10-14 <CAMkU=1xxVuSDpRb3KS+LZU-UxhM9FShiAbs=U3FZrH3xe1B1Sw@mail.gmail.com>
> I don't know why you would have to change %q though.  I assume you would
> just stick %a in from of %q, if that is what you wanted to do.  But I've
> never used %q myself.

I got it the wrong way round - the change will be that %a will be
available in non-session context as well, and hence the "Session only"
column in the log_line_prefix documentation table needs updating. Not
that %q would actually look at that table, but that was my brain was
thinking ;)

Christoph

On 2016-10-14 13:11:51 +0200, Christoph Berg wrote:
> Re: Michael Paquier 2016-02-10 <CAB7nPqS=wBbZzBcty1KyN-5Y9bPXZ+deJbfcCtebf06eF2Uyvg@mail.gmail.com>
> > On Mon, Feb 8, 2016 at 11:32 PM, Andres Freund <andres@anarazel.de> wrote:
> > > Frequently when reading postgres logs to do some post mortem analysis
> > > I'm left wondering what process emitted an error/log message. After the
> > > fact it's often hard to know wether an error message was emitted by a
> > > user backend or by something internal, say the checkpointer or
> > > autovacuum.  Logging all process starts is often impractical given the
> > > log volume that causes.
> > >
> > > So I'm proposing adding an escape displaying the process title (say 'k'
> > > for kind?). So %k would emit something like "autovacuum worker process",
> > > "wal sender process" etc.
> > 
> > It would be nice to get something consistent between the ps output and
> > this new prefix, say with for example a miscadmin.h parameter like
> > MyProcName.
> > 
> > > I'm thinking it might make sense to give normal connections "" as the
> > > name, they're usually already discernible.
> > 
> > Yeah, that sounds fine for me. What about background workers? I would
> > think that they should use BackgroundWorker->bgw_name.
> 
> (Rediscovering an old horse)
> 
> Couldn't these processes just set %a = application_name?

It'd not get me what I'd want, no. E.g for walsenders that'd not be
parsable in a meaningful way.  I really would like an escape that'd
always output one of:
Postmaster, Startup, BgWriter, Checkpointer, WalWriter, WalReceiver,
AutovacLauncher, AutovacWorker, PgArch, PgStat, SysLogger, Backend,
BackgroundWorker.

Greetings,

Andres Freund

On 2016-10-15 17:43:40 -0700, Jeff Janes wrote:
> On Fri, Oct 14, 2016 at 11:51 AM, Andres Freund <andres@anarazel.de> wrote:
> 
> > On 2016-10-14 13:11:51 +0200, Christoph Berg wrote:
> > > Re: Michael Paquier 2016-02-10 <CAB7nPqS=wBbZzBcty1KyN-
> > 5Y9bPXZ+deJbfcCtebf06eF2Uyvg@mail.gmail.com>
> > > > On Mon, Feb 8, 2016 at 11:32 PM, Andres Freund <andres@anarazel.de>
> > wrote:
> > > > > Frequently when reading postgres logs to do some post mortem analysis
> > > > > I'm left wondering what process emitted an error/log message. After
> > the
> > > > > fact it's often hard to know wether an error message was emitted by a
> > > > > user backend or by something internal, say the checkpointer or
> > > > > autovacuum.  Logging all process starts is often impractical given
> > the
> > > > > log volume that causes.
> > > > >
> > > > > So I'm proposing adding an escape displaying the process title (say
> > 'k'
> > > > > for kind?). So %k would emit something like "autovacuum worker
> > process",
> > > > > "wal sender process" etc.
> > > >
> > > > It would be nice to get something consistent between the ps output and
> > > > this new prefix, say with for example a miscadmin.h parameter like
> > > > MyProcName.
> > > >
> > > > > I'm thinking it might make sense to give normal connections "" as the
> > > > > name, they're usually already discernible.
> > > >
> > > > Yeah, that sounds fine for me. What about background workers? I would
> > > > think that they should use BackgroundWorker->bgw_name.
> > >
> > > (Rediscovering an old horse)
> > >
> > > Couldn't these processes just set %a = application_name?
> >
> > It'd not get me what I'd want, no. E.g for walsenders that'd not be
> > parsable in a meaningful way.  I really would like an escape that'd
> > always output one of:
> > Postmaster, Startup, BgWriter, Checkpointer, WalWriter, WalReceiver,
> > AutovacLauncher, AutovacWorker, PgArch, PgStat, SysLogger, Backend,
> > BackgroundWorker.
> >
> 
> I'm not sure what you are proposing.   Which of those 13 strings you listed
> would a walsender advertise itself as?

Oops, left that one out (as it's not one of the pids explicitly listed
in postmaster.c, which I went over). 'WalSender'.

> Why would stuffing one of those words into %k be different than
> stuffing that same word into %a, where %a would otherwise be the empty
> string?

Because you very well might want to keep tracking application_name for
walsenders - as that's important e.g. for sync replica tracking purposes
- and be able to categorize log messages by the type of process.

- Andres