Thread: quieting DEBUG3

It's been my observation that setting client_min_messages or
log_min_messages to DEBUG3 is almost invariably impractical, because
every SQL statement spews about SIX messages about the transaction
state:

rhaas=# select 1;
DEBUG:  StartTransactionCommand
DEBUG:  StartTransaction
DEBUG:  name: unnamed; blockState:       DEFAULT; state: INPROGR,
xid/subid/cid: 0/1/0, nestlvl: 1, children:
DEBUG:  CommitTransactionCommand
DEBUG:  CommitTransaction
DEBUG:  name: unnamed; blockState:       STARTED; state: INPROGR,
xid/subid/cid: 0/1/0, nestlvl: 1, children:?column?
----------       1
(1 row)

I think this is excessive.  I will grant you that DEBUG3 is cranking
it up pretty high, but I notice that DEBUG2 produces no messages at
all in the same situation, and DEBUG5 doesn't produce any more than
DEBUG3.  The practical effect of this is that a logging level of
DEBUG3 or higher is impractical both on production systems (because
the logs will fill up) and for testing purposes (because sorting
through garbage of the type shown above is too much work).  Here's
what I propose:

1. Remove the StartTransactionCommand and CommitTransactionCommand
ereport calls from start_xact_command() and finish_xact_command.  I
can't think of any way that these calls can justify themselves at any
log level.  They're going to happen on every single statement.
They're just a constant string with no potentially-useful detail
information.  And they're largely redundant with the other messages.

2. Modify xact.c to reduce the log level of the remaining log messages
that appear in the above output from DEBUG3 to DEBUG5.

3. Refactor the logging in xact.c to be less chatty.
ShowTransactionState currently prints its string argument as a
separate message, and then recurses to dump one line per
TransactionState entry.  Instead, let's use it as a prefix for each of
the messages that follows.  Those messages are already quite long, but
if they only appear at DEBUG5 it doesn't matter that much, and we can
also easily make them shorter without losing information.  In
particular, I suggest that we:

- omit "name: unnamed; " from each line and instead only display the
name if there is one
- omit "children: " when no children exist
- print the blockstate using %s instead of %13s, to avoid adding
padding whitespace
- display the nest level in parentheses after the string prefix
instead of printing nestlvl: %d

So instead of this:

DEBUG:  StartTransaction
DEBUG:  name: unnamed; blockState:       DEFAULT; state: INPROGR,
xid/subid/cid: 0/1/0, nestlvl: 1, children:

We would get this:

DEBUG:  StartTransaction(1): blockState: DEFAULT; state: INPROGR,
xid/subid/cid: 0/1/0

...and only at DEBUG5.

Thoughts?

-- 
Robert Haas
EnterpriseDB: http://www.enterprisedb.com
The Enterprise PostgreSQL Company

On 28 October 2015 at 04:52, Robert Haas <robertmhaas@gmail.com> wrote:

> Thoughts?

I agree with you that DEBUG3 is currently impractical. So much so that
when testing/debugging I often change log severities of messages of
interest so they'll show up at DEBUG2 instead, rather than running in
DEBUG3.

Simplifying the StartTransaction log to a single message line is
clearly sensible.

I tend to see a lot of:

DEBUG:  StartTransactionCommand
DEBUG:  StartTransaction
DEBUG:  name: unnamed; blockState:       DEFAULT; state: INPROGR,
xid/subid/cid: 0/1/0, nestlvl: 1, children:
DEBUG:  ProcessUtility
DEBUG:  CommitTransactionCommand
DEBUG:  StartTransactionCommand
DEBUG:  ProcessQuery
DEBUG:  CommitTransactionCommand
DEBUG:  StartTransactionCommand
DEBUG:  ProcessQuery
DEBUG:  CommitTransactionCommand
DEBUG:  StartTransactionCommand
DEBUG:  ProcessUtility
DEBUG:  CommitTransactionCommand
DEBUG:  CommitTransaction
DEBUG:  name: unnamed; blockState:           END; state: INPROGR,
xid/subid/cid: 3778/1/2, nestlvl: 1, children:

It's pretty spammy, and the StartTransactionCommand /
CommitTransactionCommand entries don't seem to add any useful
information.

I'm not so sure about bumping transaction tracing down to DEBUG5,
given that transaction control is pretty important, and can be an
issue when chasing problems with cache accesses, etc. There's a lot of
other output, too, and once simplified to one line I think it's
reasonable to retain at DEBUG3.

I'd be pretty happy to get:


DEBUG:  StartTransaction(1): blockState: DEFAULT; state: INPROGR,
xid/subid/cid: 0/1/0
DEBUG:  ProcessUtility
DEBUG:  ProcessQuery
DEBUG:  ProcessQuery
DEBUG:  ProcessUtility
DEBUG:  CommitTransaction(1): blockState: END; state: INPROGR,
xid/subid/cid: 3778/1/2

instead.

I think it'd be helpful to define some level of policy about what the
debug levels are intended for, so there's some guidance on what level
to emit messages on rather than playing "pick a number". But that
shouldn't hold up the simplifications you propose here, except maybe
the DEBUG3 to DEBUG5 change.

-- Craig Ringer                   http://www.2ndQuadrant.com/PostgreSQL Development, 24x7 Support, Training & Services

Craig Ringer <craig@2ndquadrant.com> writes:
> I think it'd be helpful to define some level of policy about what the
> debug levels are intended for, so there's some guidance on what level
> to emit messages on rather than playing "pick a number".

+1 ... I doubt anyone has ever looked at that in a holistic way.
        regards, tom lane

On Wed, Oct 28, 2015 at 1:51 AM, Tom Lane <tgl@sss.pgh.pa.us> wrote:
> Craig Ringer <craig@2ndquadrant.com> writes:
>> I think it'd be helpful to define some level of policy about what the
>> debug levels are intended for, so there's some guidance on what level
>> to emit messages on rather than playing "pick a number".
>
> +1 ... I doubt anyone has ever looked at that in a holistic way.

Well, I don't know that I could give really specific guidance on each
individual level, but what I think is pretty clear is that messages
which tell you about something that's likely to happen very frequently
should only appear if you have really cranked the logging up to the
maximum.   So a message that fires every time you touch a data block
had better be DEBUG5, but a message that fires at most once per
checkpoint cycle can afford to be DEBUG1.  Qualitatively, I think that
higher debug level (DEBUG1, DEBUG2) should focus on telling you about
things that are potentially interesting and maybe a little bit
unusual, while tracing messages that report things which are entirely
routine should use lower debug levels (DEBUG4, DEBUG5).

I agree with Craig that the transaction system is interesting and
important, but it's not the *only* interesting and important subsystem
we have ... and any log level below DEBUG2 is basically useless right
now; the stuff you want is almost guaranteed to be lost in the noise.

-- 
Robert Haas
EnterpriseDB: http://www.enterprisedb.com
The Enterprise PostgreSQL Company

On Wed, Oct 28, 2015 at 6:57 AM, Robert Haas <robertmhaas@gmail.com> wrote:
> On Wed, Oct 28, 2015 at 1:51 AM, Tom Lane <tgl@sss.pgh.pa.us> wrote:
>> Craig Ringer <craig@2ndquadrant.com> writes:
>>> I think it'd be helpful to define some level of policy about what the
>>> debug levels are intended for, so there's some guidance on what level
>>> to emit messages on rather than playing "pick a number".
>>
>> +1 ... I doubt anyone has ever looked at that in a holistic way.
>
> Well, I don't know that I could give really specific guidance on each
> individual level, but what I think is pretty clear is that messages
> which tell you about something that's likely to happen very frequently
> should only appear if you have really cranked the logging up to the
> maximum.   So a message that fires every time you touch a data block
> had better be DEBUG5, but a message that fires at most once per
> checkpoint cycle can afford to be DEBUG1.  Qualitatively, I think that
> higher debug level (DEBUG1, DEBUG2) should focus on telling you about
> things that are potentially interesting and maybe a little bit
> unusual, while tracing messages that report things which are entirely
> routine should use lower debug levels (DEBUG4, DEBUG5).

I figured it would go something like this:

DEBUG1 once or a few times per statement/autovac/checkpoint
DEBUG2 several times per statement/autovac/checkpoint (like once per
joined relation in the planner)
DEBUG3 once or a few times per row/block
DEBUG4 several times per row/block
DEBUG5 memory allocation.

>
> I agree with Craig that the transaction system is interesting and
> important, but it's not the *only* interesting and important subsystem
> we have ... and any log level below DEBUG2 is basically useless right
> now; the stuff you want is almost guaranteed to be lost in the noise.

The main use I have for any of the DEBUG levels above 1 is to step
through them with vim in a specific source file to see what someone
felt was important to log when they were debugging that file in the
past.  Then I change the ones I like to LOG or NOTICE and recompile to
get a targeted verbose logging build.  This is not to disparage their
usefulness, it is hard to imagine me getting into a new part of the
code without the ability to use these archeological markers.  They are
often more useful than the /* comments */ .



Cheers,

Jeff

On Wed, Oct 28, 2015 at 5:26 PM, Jeff Janes <jeff.janes@gmail.com> wrote:
> I figured it would go something like this:
>
> DEBUG1 once or a few times per statement/autovac/checkpoint
> DEBUG2 several times per statement/autovac/checkpoint (like once per
> joined relation in the planner)
> DEBUG3 once or a few times per row/block
> DEBUG4 several times per row/block
> DEBUG5 memory allocation.

I feel like this fails to take account of things that often don't
occur at all.  On this scale, the messages I'm complaining about could
justifiably be DEBUG1 rather than DEBUG3, which would render all of
the DEBUG levels essentially useless.  How about this: imagine a
reasonably busy system processing a thousand queries or so per second,
and consider log volume:

A given DEBUG1 message shouldn't fire more than ~1/sec.
A given DEBUG2 message shouldn't fire more than ~10/sec
A given DEBUG3 message shouldn't fire more than ~100/sec
A given DEBUG4 message shouldn't fire more than ~1000/sec
Anything which fires more than ~1000/s is DEBUG5

On this scale, most of the debug messages that the system actually
generates today are fine at their current levels - some of the DEBUG4
stuff could probably be bumped up to higher levels.  But the messages
I'm complaining about are at least one level too high.

Another point I want to reiterate - because nobody seems to be
addressing it - is that some of these messages are totally useless.  I
grant that printing the transaction state (XIDs, CIDs, etc.) is
useful.  But does anybody really think that it's useful for every
statement to *additionally* generate DEBUG:  CommitTransactionCommand?Who looks at that?  What value does it have?  We
donot print a
 
message when any other function that is called for every query is
entered - why that one?  Whether we adjust the log levels of the
messages we have or not, we surely ought to get rid of the ones that
are useless clutter.  Can anyone think of a single instance in which
that particular message has been useful in debugging ... anything?

-- 
Robert Haas
EnterpriseDB: http://www.enterprisedb.com
The Enterprise PostgreSQL Company

Robert Haas wrote:

> Another point I want to reiterate - because nobody seems to be
> addressing it - is that some of these messages are totally useless.  I
> grant that printing the transaction state (XIDs, CIDs, etc.) is
> useful.  But does anybody really think that it's useful for every
> statement to *additionally* generate DEBUG:  CommitTransactionCommand?
>  Who looks at that?  What value does it have?  We do not print a
> message when any other function that is called for every query is
> entered - why that one?

No, it is useless, let's get rid of it.  Maybe it was a useful debugging
tool when postgres.c was being developed, but it's not useful now and
instead very bothersome.

> Whether we adjust the log levels of the messages we have or not, we
> surely ought to get rid of the ones that are useless clutter.

Agreed.  I liked your proposal for reduction of transaction state
printout to a single, denser line.

> Can anyone think of a single instance in which that particular message
> has been useful in debugging ... anything?

Not I.

-- 
Álvaro Herrera                http://www.2ndQuadrant.com/
PostgreSQL Development, 24x7 Support, Remote DBA, Training & Services

On Wed, Oct 28, 2015 at 3:10 PM, Alvaro Herrera
<alvherre@2ndquadrant.com> wrote:
> Robert Haas wrote:
>
>> Another point I want to reiterate - because nobody seems to be
>> addressing it - is that some of these messages are totally useless.  I
>> grant that printing the transaction state (XIDs, CIDs, etc.) is
>> useful.  But does anybody really think that it's useful for every
>> statement to *additionally* generate DEBUG:  CommitTransactionCommand?
>>  Who looks at that?  What value does it have?  We do not print a
>> message when any other function that is called for every query is
>> entered - why that one?
>
> No, it is useless, let's get rid of it.  Maybe it was a useful debugging
> tool when postgres.c was being developed, but it's not useful now and
> instead very bothersome.
>
>> Whether we adjust the log levels of the messages we have or not, we
>> surely ought to get rid of the ones that are useless clutter.
>
> Agreed.  I liked your proposal for reduction of transaction state
> printout to a single, denser line.
>
>> Can anyone think of a single instance in which that particular message
>> has been useful in debugging ... anything?
>
> Not I.

Right: me either.  So, here is a series of three patches.

0001 completely removes the debug messages for
StartTransactionCommand, CommitTransactionCommand, ProcessQuery, and
ProcessUtility.  AFAICS, those are entirely log spam.  Nobody ever
wants to see them; they are a pure waste of cycles.

0002 adjusts the ShowTransactionState() output.  Every call to
ShowTransactionState() currently produces N + 1 lines of log output,
where N is the number of entries on the transaction state stack.  With
this patch, each call to ShowTransactionState() produces N lines of
output.  All of the same information is still printed.  In the common
case where N = 1, this reduces the number of lines of output by 50%
without losing any information.  The individual lines are also a bit
shorter, again without removing any information, but just tightening
up the format.

0003 reduces the ShowTransactionState() output from DEBUG3 to DEBUG5.
I did find this output help in some of the parallel query development,
but I think the need to look at these messages is going to be
uncommon.  Developers might care, but not often, and users never will.
Even after 0002 the log volume from turning this on is very high, so I
think it makes sense to push this down to a lower level.

If anybody objects to these, please say which specific patch you
object to and for what reason.  Last year's discussion veered off into
a discussion of what the general policy for setting DEBUGn levels
ought to be, which didn't reach any conclusion, but I don't think that
should bar clear improvements.  I think that all of these are
improvements, and that 0001 and 0002 are particularly clear-cut.

--
Robert Haas
EnterpriseDB: http://www.enterprisedb.com
The Enterprise PostgreSQL Company

Robert Haas wrote:

> Right: me either.  So, here is a series of three patches.

+1 to the general idea of the three patches.  I didn't review nor test
them in detail.

-- 
Álvaro Herrera                https://www.2ndQuadrant.com/
PostgreSQL Development, 24x7 Support, Remote DBA, Training & Services

On Wed, Nov 16, 2016 at 12:00 PM, Alvaro Herrera
<alvherre@2ndquadrant.com> wrote:
> Robert Haas wrote:
>
>> Right: me either.  So, here is a series of three patches.
>
> +1 to the general idea of the three patches.  I didn't review nor test
> them in detail.

Thanks.  Hearing no objections, committed.

-- 
Robert Haas
EnterpriseDB: http://www.enterprisedb.com
The Enterprise PostgreSQL Company