Обсуждение: 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
On Fri, Oct 14, 2016 at 4:11 AM, Christoph Berg <myon@debian.org> 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? (This would
obviously need %q to be taught that %a is always valid.)
+1 from me on having non-session processes set application_name for logging purposes, I've long wanted that.
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.
Cheers,
Jeff
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 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? 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? The only problem I can see is if someone has an application which calls itself "WalReceiver", for example, so you can't distinguish a real WalReceiver from a self-declared WalReceiver.
I'd be happy to replace the %a in my log_line_prefix with %a%k, but I don't really see the point of of %a and %k being different things.
Cheers,
Jeff
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