From: | Bruce Momjian <bruce(at)momjian(dot)us> |
---|---|
To: | Greg Smith <gsmith(at)gregsmith(dot)com> |
Cc: | pgsql-patches(at)postgresql(dot)org |
Subject: | Re: Logging checkpoints and other slowdown causes |
Date: | 2007-04-03 01:23:17 |
Message-ID: | 200704030123.l331NHj11400@momjian.us |
Views: | Raw Message | Whole Thread | Download mbox | Resend email |
Thread: | |
Lists: | pgsql-hackers pgsql-patches |
Your patch has been added to the PostgreSQL unapplied patches list at:
http://momjian.postgresql.org/cgi-bin/pgpatches
It will be applied as soon as one of the PostgreSQL committers reviews
and approves it.
---------------------------------------------------------------------------
Greg Smith wrote:
> This patch puts entries in the log file around some backend events that
> regularly cause client pauses, most of which are visible only when running
> with log_min_messages = debug2. The main focus is regularly occuring
> checkpoints, from either running out of segments or hitting a timeout.
> This is an example of what gets written to the logs at checkpoint time:
>
> DEBUG2: checkpoint required (timeout passed)
> DEBUG2: checkpoint starting
> DEBUG2: checkpoint flushing buffer pool
> DEBUG2: checkpoint database fsync starting
> DEBUG2: checkpoint database fsync complete
> DEBUG1: checkpoint buffers dirty=16.7 MB (13.0%) write=174.8 ms
> sync=3716.5 ms
> DEBUG2: checkpoint complete; 0 transaction log file(s) added, 0 removed,
> 0 recycled
>
> The idea here is that if you want to really watch what your system is
> doing, either to track down a problem or for benchmarking, you log at
> DEBUG2 and timestamp the logs with something like log_line_prefix =
> '[%m]:'. Then line up your timestamped transactions with the logs to
> figure out what happened during bad periods. This is very easy to do with
> the timestamped pgbench latency logs for example, so you can put them in
> time sequence order and see something like "oh, those long transactions
> all came in between the fsync start and end". The summary line with the
> write/sync timing information has a broader use and suggests when you need
> to go deeper, which is why I put that one at DEBUG1.
>
> I also adjust some other log messages to make it easier to run the system
> at DEBUG2 without going completely crazy, like moving individual WAL
> segment recycles to DEBUG3 and standardizing the format of the fork/exit
> messages so they're easier to filter out.
>
> My main concern about this code is how it adds several gettimeofday calls
> and complicated string building inside FlushBufferPool, all of which is
> wasted if this data isn't actually going to get logged. I'd like to have
> something that tells me whether I should even bother, but I didn't want to
> poke into the elog variables for fear of adding a dependency on its
> current structure to here. Ideally, it would be nice to call something
> like WillLog(DEBUG2) and get a boolean back saying whether something at
> that log level will be output anywhere; I don't know enough about the
> logging code to add such a thing to it myself.
>
> --
> * Greg Smith gsmith(at)gregsmith(dot)com http://www.gregsmith.com Baltimore, MD
Content-Description:
[ Attachment, skipping... ]
>
> ---------------------------(end of broadcast)---------------------------
> TIP 4: Have you searched our list archives?
>
> http://archives.postgresql.org
--
Bruce Momjian <bruce(at)momjian(dot)us> http://momjian.us
EnterpriseDB http://www.enterprisedb.com
+ If your life is a hard drive, Christ can be your backup. +
From | Date | Subject | |
---|---|---|---|
Next Message | Bruce Momjian | 2007-04-03 01:25:19 | Re: Implicit casts to text |
Previous Message | Bruce Momjian | 2007-04-03 01:21:16 | Re: Feature thought: idle in transaction timeout |
From | Date | Subject | |
---|---|---|---|
Next Message | Bruce Momjian | 2007-04-03 01:25:53 | Re: COPY-able sql log outputs |
Previous Message | Bruce Momjian | 2007-04-03 01:23:05 | Re: Add usage counts to pg_buffercache |