Date: Fri, 11 May 2007 10:31:09 -0400 (EDT)
From: Greg Smith <gsmith@gregsmith.com>
To: pgsql-patches@postgresql.org
Subject: Re: Logging checkpoints and other slowdown causes
In-Reply-To: <46443F02.6060300@enterprisedb.com>
Message-ID: <Pine.GSO.4.64.0705111009080.18685@westnet.com>
References: <Pine.GSO.4.64.0704010051050.14920@westnet.com>
	<200704030814.33999.peter_e@gmx.net>
	<Pine.GSO.4.64.0704030927180.5732@westnet.com>
	<46443F02.6060300@enterprisedb.com>
MIME-Version: 1.0
Content-Type: TEXT/PLAIN; charset=US-ASCII; format=flowed

On Fri, 11 May 2007, Heikki Linnakangas wrote:

> Printing the messages at LOG-level would bring the code in line with the 
> documentation, but I don't think we want to fill the log with checkpoint 
> chatter unless the DBA explicitly asks for that.  How about INFO?

In putting that together, I pushed everything toward the lowest DEBUG 
level that it was possible for it to run at without the messages I wanted 
to see being completely lost.  I didn't want this to get rejected just on 
the basis of being too chatty for regular users.  Putting a single line in 
for each checkpoint at INFO, with all the individual progress points being 
at DEBUG1 or 2, would be close to optimal as far as I'm concerned.  More 
on this below.

> Or we could add a GUC variable similar to log_connections or log_statement to 
> control if the messages are printed or not, and use LOG.

If the levels for the individual messages are adjusted usefully the 
ability to control whether they show up or not falls out of the existing 
log level adjustments; I haven't ever felt a strong need for GUC when 
using this code.  If, as you say, there's already a move in this 
direction, then fine--another GUC would be better.

> We don't need to print the times elapsed in each phase on a separate 
> line, that's just derived information from the other lines, unless we 
> use different log-levels for detail lines

Let me turn this around for a second and ask you this:  what do you think 
people are going to do with this information?  I can tell you what I do. 
I parse the logs and look for that single line with the summary 
information.  I then take the three pieces of information it provides (MB 
written, time to write, time to fsync) and save them into a table.  From 
there I generate stats, scatter plots, all sorts of useful stuff.

If you know when the checkpoint ended, and you know how long each of the 
pieces took, you can reconstruct the other times easily.  The way you 
describe this it is true--that the summary is redundant given the 
detail--but if you put yourself in the shoes of a log file parser the 
other way around is easier to work with.  Piecing together log entries is 
a pain, splitting them is easy.

If I had to only keep one line out of this, it would be the one with the 
summary.  It would be nice to have it logged at INFO.

--
* Greg Smith gsmith@gregsmith.com http://www.gregsmith.com Baltimore, MD