Re: enable logging of start time/cookie for all backend processes

The attached patch makes a very small but useful change to the behaviour
of log_line_prefix, by enabling the start time (%s) and cookie (%c)
logging to occur for all backends rather than just for session processes
(i.e. backends started for a client connection). We actually need almost
all of this patch, with or without the change in behaviour, so we can
put the cookie in CSVlogs (which I'm still working on), since the
cookie+line number make the natural primary key for the logs. The actual
change in behaviour from this patch comes from the removal of 2 "if
(MyProcPort)" lines in elog.c. Given that, can I sneak this in or should
I wait for 8.4 given we're long past feature freeze?

Most of this has been factored out (and cleaned up) from my previous
CSVlog patch, so it's not new. I did that so that what is left when I
finish will have a rather smaller footprint, as this part seemed fairly
seperable.

cheers

andrew

Andrew Dunstan wrote:
>
> The attached patch makes a very small but useful change to the
> behaviour of log_line_prefix, by enabling the start time (%s) and
> cookie (%c) logging to occur for all backends rather than just for
> session processes (i.e. backends started for a client connection). We
> actually need almost all of this patch, with or without the change in
> behaviour, so we can put the cookie in CSVlogs (which I'm still
> working on), since the cookie+line number make the natural primary key
> for the logs. The actual change in behaviour from this patch comes
> from the removal of 2 "if (MyProcPort)" lines in elog.c. Given that,
> can I sneak this in or should I wait for 8.4 given we're long past
> feature freeze?
>
> Most of this has been factored out (and cleaned up) from my previous
> CSVlog patch, so it's not new. I did that so that what is left when I
> finish will have a rather smaller footprint, as this part seemed
> fairly seperable.
>
>

I haven't seen a response to this. If there's no objection I intend to
apply this.

cheers

andrew

Andrew Dunstan wrote:
>
>
> Andrew Dunstan wrote:
>>
>> The attached patch makes a very small but useful change to the
>> behaviour of log_line_prefix, by enabling the start time (%s) and
>> cookie (%c) logging to occur for all backends rather than just for
>> session processes (i.e. backends started for a client connection). We
>> actually need almost all of this patch, with or without the change in
>> behaviour, so we can put the cookie in CSVlogs (which I'm still
>> working on), since the cookie+line number make the natural primary key
>> for the logs. The actual change in behaviour from this patch comes
>> from the removal of 2 "if (MyProcPort)" lines in elog.c. Given that,
>> can I sneak this in or should I wait for 8.4 given we're long past
>> feature freeze?
>>
>> Most of this has been factored out (and cleaned up) from my previous
>> CSVlog patch, so it's not new. I did that so that what is left when I
>> finish will have a rather smaller footprint, as this part seemed
>> fairly seperable.
>>
>>
>
> I haven't seen a response to this. If there's no objection I intend to
> apply this.

My only objection would be that we're in feature-freeze. We really
should be doing other things ;-) But I'm not going to be the one to put
a full stop to it if the patch already exists and is trivial. You can
probably sneak it in as part of the cvslog stuff...

//Magnus

Andrew Dunstan wrote:
>
>
> Andrew Dunstan wrote:
>>
>> The attached patch makes a very small but useful change to the behaviour
>> of log_line_prefix, by enabling the start time (%s) and cookie (%c)
>> logging to occur for all backends rather than just for session processes
>> (i.e. backends started for a client connection). We actually need almost
>> all of this patch, with or without the change in behaviour, so we can put
>> the cookie in CSVlogs (which I'm still working on), since the cookie+line
>> number make the natural primary key for the logs. The actual change in
>> behaviour from this patch comes from the removal of 2 "if (MyProcPort)"
>> lines in elog.c. Given that, can I sneak this in or should I wait for 8.4
>> given we're long past feature freeze?
>>
>> Most of this has been factored out (and cleaned up) from my previous
>> CSVlog patch, so it's not new. I did that so that what is left when I
>> finish will have a rather smaller footprint, as this part seemed fairly
>> seperable.
>
> I haven't seen a response to this. If there's no objection I intend to
> apply this.

I was just looking at it. I was wondering why didn't you set the start
time in syslogger and bgwriter. If it isn't necessary for those, why do
you bother setting it in autovac launcher?

I am also wondering if setting it in InitAuxiliaryProcess is redundant
(or rather, whether the extra set in each auxiliary process is redundant
with the call in InitAuxiliaryProcess).

--
Alvaro Herrera http://www.CommandPrompt.com/
The PostgreSQL Company - Command Prompt, Inc.

Alvaro Herrera wrote:
> I am also wondering if setting it in InitAuxiliaryProcess is redundant
> (or rather, whether the extra set in each auxiliary process is redundant
> with the call in InitAuxiliaryProcess).
>

Well, it's set right at the front of SubPostmasterMain, immediately
after setting MyProcPid. Is that enough to catch every path? I think
it's a better place than InitAuxiliaryProcess, because at that stage no
logging can have taken place. Maybe we just need to remove the other
special cases ... I'll take another look.

cheers

andrew

Andrew Dunstan wrote:
>
>
> Alvaro Herrera wrote:
>> I am also wondering if setting it in InitAuxiliaryProcess is redundant
>> (or rather, whether the extra set in each auxiliary process is redundant
>> with the call in InitAuxiliaryProcess).
>>
>
> Well, it's set right at the front of SubPostmasterMain, immediately after
> setting MyProcPid. Is that enough to catch every path?

Only in the EXEC_BACKEND case, right? It's not used at all in the other
case.

--
Alvaro Herrera http://www.CommandPrompt.com/
PostgreSQL Replication, Consulting, Custom Development, 24x7 support

Alvaro Herrera wrote:
> Andrew Dunstan wrote:
>
>> Alvaro Herrera wrote:
>>
>>> I am also wondering if setting it in InitAuxiliaryProcess is redundant
>>> (or rather, whether the extra set in each auxiliary process is redundant
>>> with the call in InitAuxiliaryProcess).
>>>
>>>
>> Well, it's set right at the front of SubPostmasterMain, immediately after
>> setting MyProcPid. Is that enough to catch every path?
>>
>
> Only in the EXEC_BACKEND case, right? It's not used at all in the other
> case.
>
>

Yeah. I need to stop multitasking - brain functions less well.

My original thought was that it needed to be set anywhere MyProcPid was
set. That still seems to make sense, it just looks like I missed a few
places, which I should fix.

cheers

andrew

Andrew Dunstan wrote:

> Alvaro Herrera wrote:
>> Andrew Dunstan wrote:
>>
>>> Alvaro Herrera wrote:
>>>
>>>> I am also wondering if setting it in InitAuxiliaryProcess is redundant
>>>> (or rather, whether the extra set in each auxiliary process is redundant
>>>> with the call in InitAuxiliaryProcess).

> My original thought was that it needed to be set anywhere MyProcPid was
> set. That still seems to make sense, it just looks like I missed a few
> places, which I should fix.

+1 because of cleanliness, even if some calls turn out to be redundant.
That was in fact what I initially thought you were doing.

--
Alvaro Herrera http://www.PlanetPostgreSQL.org/
"Porque francamente, si para saber manejarse a uno mismo hubiera que
rendir examen... ¿Quién es el machito que tendría carnet?" (Mafalda)

Alvaro Herrera wrote:
>
>> My original thought was that it needed to be set anywhere MyProcPid was
>> set. That still seems to make sense, it just looks like I missed a few
>> places, which I should fix.
>>
>
> +1 because of cleanliness, even if some calls turn out to be redundant.
> That was in fact what I initially thought you were doing.
>
>

OK, here's the revised patch.

cheers

andrew

Andrew Dunstan wrote:
>
> The attached patch makes a very small but useful change to the behaviour of
> log_line_prefix, by enabling the start time (%s) and cookie (%c) logging to
> occur for all backends rather than just for session processes (i.e.
> backends started for a client connection). We actually need almost all of
> this patch, with or without the change in behaviour, so we can put the
> cookie in CSVlogs (which I'm still working on), since the cookie+line
> number make the natural primary key for the logs. The actual change in
> behaviour from this patch comes from the removal of 2 "if (MyProcPort)"
> lines in elog.c. Given that, can I sneak this in or should I wait for 8.4
> given we're long past feature freeze?

Thinking again about the feature itself I wonder if it actually makes
sense -- maybe it does make sense to be able to display the session ID,
but the start time? Why would anyone care about the start time of
syslogger or bgwriter? We don't even have a use for the "hey, this
process was started" log line, why would anyone care about having the
start time in the log line prefix?

Actually having the cookie in all processes is another matter, as far as
it's useful for CSV logs. But then, is it? Maybe the auxiliary
processes should identify themselves with fixed cookies or something
particular that lets one distinguish, say, a bgwriter from a syslogger,
but is there a case from distinguishing one bgwriter from another?

--
Alvaro Herrera http://www.amazon.com/gp/registry/CTMLCN8V17R4
"Amanece. (Ignacio Reyes)
El Cerro San Cristóbal me mira, cínicamente, con ojos de virgen"

Alvaro Herrera wrote:
> Andrew Dunstan wrote:
>
>> The attached patch makes a very small but useful change to the behaviour of
>> log_line_prefix, by enabling the start time (%s) and cookie (%c) logging to
>> occur for all backends rather than just for session processes (i.e.
>> backends started for a client connection). We actually need almost all of
>> this patch, with or without the change in behaviour, so we can put the
>> cookie in CSVlogs (which I'm still working on), since the cookie+line
>> number make the natural primary key for the logs. The actual change in
>> behaviour from this patch comes from the removal of 2 "if (MyProcPort)"
>> lines in elog.c. Given that, can I sneak this in or should I wait for 8.4
>> given we're long past feature freeze?
>>
>
> Thinking again about the feature itself I wonder if it actually makes
> sense -- maybe it does make sense to be able to display the session ID,
> but the start time? Why would anyone care about the start time of
> syslogger or bgwriter? We don't even have a use for the "hey, this
> process was started" log line, why would anyone care about having the
> start time in the log line prefix?
>
> Actually having the cookie in all processes is another matter, as far as
> it's useful for CSV logs. But then, is it? Maybe the auxiliary
> processes should identify themselves with fixed cookies or something
> particular that lets one distinguish, say, a bgwriter from a syslogger,
> but is there a case from distinguishing one bgwriter from another?
>
>

It's not about distinguishing one bgwriter from another, it's about
distinguishing it from any other process at any time whatsoever that has
had the same pid. cookie+linenumber should be unique. pid+linenumber
isn't. (And every process gets its own line number sequence, so we can't
just give, say, all the bgwriter processes the same cookie). Logging the
start time on its own isn't much extra benefit, although I expect log
parsers will find it nicer to be able to handle a more consistent
logging style rather than having to handle non-session processes as a
special case. But having the cookie available in all cases is the whole
point of this - I wouldn't have done it unless I had needed to be able
to set a primary key for loadable logs.

If you want to invent some other style of cookie we can look at that.
Back when we looked at it originally nobody came up with a better
suggestion than process_start.pid. But that surely would be for a later
release ;-)

So, short answer - yes, I think it makes sense. But if there's any
serious argument I won't change the observable behaviour in elog.c, just
the infrastructure.

cheers

andrew

Andrew Dunstan wrote:
>
>
> Alvaro Herrera wrote:
>> Andrew Dunstan wrote:
>>
>>> The attached patch makes a very small but useful change to the
>>> behaviour of log_line_prefix, by enabling the start time (%s) and
>>> cookie (%c) logging to occur for all backends rather than just for
>>> session processes (i.e. backends started for a client connection).
>>> We actually need almost all of this patch, with or without the
>>> change in behaviour, so we can put the cookie in CSVlogs (which I'm
>>> still working on), since the cookie+line number make the natural
>>> primary key for the logs. The actual change in behaviour from this
>>> patch comes from the removal of 2 "if (MyProcPort)" lines in elog.c.
>>> Given that, can I sneak this in or should I wait for 8.4 given we're
>>> long past feature freeze?
>>>
>>
>> Thinking again about the feature itself I wonder if it actually makes
>> sense -- maybe it does make sense to be able to display the session ID,
>> but the start time? Why would anyone care about the start time of
>> syslogger or bgwriter? We don't even have a use for the "hey, this
>> process was started" log line, why would anyone care about having the
>> start time in the log line prefix?
>>
>> Actually having the cookie in all processes is another matter, as far as
>> it's useful for CSV logs. But then, is it? Maybe the auxiliary
>> processes should identify themselves with fixed cookies or something
>> particular that lets one distinguish, say, a bgwriter from a syslogger,
>> but is there a case from distinguishing one bgwriter from another?
>>
>>
>
> It's not about distinguishing one bgwriter from another, it's about
> distinguishing it from any other process at any time whatsoever that
> has had the same pid. cookie+linenumber should be unique.
> pid+linenumber isn't. (And every process gets its own line number
> sequence, so we can't just give, say, all the bgwriter processes the
> same cookie). Logging the start time on its own isn't much extra
> benefit, although I expect log parsers will find it nicer to be able
> to handle a more consistent logging style rather than having to handle
> non-session processes as a special case. But having the cookie
> available in all cases is the whole point of this - I wouldn't have
> done it unless I had needed to be able to set a primary key for
> loadable logs.
>
> If you want to invent some other style of cookie we can look at that.
> Back when we looked at it originally nobody came up with a better
> suggestion than process_start.pid. But that surely would be for a
> later release ;-)
>
> So, short answer - yes, I think it makes sense. But if there's any
> serious argument I won't change the observable behaviour in elog.c,
> just the infrastructure.
>
>

In the absence of further discussion I have committed this.

That clears the decks for me to have yet another go at CSVlogs ;-)

cheers

andrew