quieting DEBUG3 - Mailing list pgsql-hackers

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