DomainKey-Signature: a=rsa-sha1; c=nofws; d=gmail.com; s=beta;
	h=received:message-id:date:from:user-agent:mime-version:to:cc:subject:references:in-reply-to:content-type:content-transfer-encoding:sender;
	b=SY6o+m19lbPw17teWzoKwDiiCoqsAmUVz42Fi5Yirs04UiYlITq9MNexIASGEMuf3SfCrc03e1ZNdOut0+xbH2cvc4hjoofSzWgVpJrQ8v1EkgBXOA+JyIU8HcPYjsvQBJWoFmH6KrrvGmO2uC2eCVXHIBAABbojlrtxN0tCoG0=
Message-ID: <46448DC8.4050102@enterprisedb.com>
Date: Fri, 11 May 2007 16:37:44 +0100
From: Heikki Linnakangas <heikki@enterprisedb.com>
User-Agent: Icedove 1.5.0.10 (X11/20070329)
MIME-Version: 1.0
To: Greg Smith <gsmith@gregsmith.com>
CC: pgsql-patches@postgresql.org
Subject: Re: Logging checkpoints and other slowdown causes
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>
	<Pine.GSO.4.64.0705111009080.18685@westnet.com>
In-Reply-To: <Pine.GSO.4.64.0705111009080.18685@westnet.com>
Content-Type: text/plain; charset=ISO-8859-1; format=flowed
Content-Transfer-Encoding: 7bit

Greg Smith wrote:
> On Fri, 11 May 2007, Heikki Linnakangas wrote:
>> 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.

The need for GUC becomes apparent when you start adding logging to other 
modules as well, like we did for autovacuum a while back. If there 
wasn't a log_autovacuum parameter, you'd have to choose between logging 
checkpoints and autovacuum actions, or neither.

>> 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.

Yeah, if we have the summary line we don't need the other lines and vice 
versa. I have sympathy for parsing log files, I've done that a lot in 
the past and I can see what you mean. Having the individual lines is 
nice when you're monitoring a running system; you don't get the summary 
line until the checkpoint is finished. I suppose we can have both the 
individual lines and the summary, the extra lines shouldn't hurt anyone, 
and you won't get them unless you turn on the new log_checkpoints 
parameter anyway.

-- 
   Heikki Linnakangas
   EnterpriseDB   http://www.enterprisedb.com