On Fri, 29 Jun 2007, Heikki Linnakangas wrote:

LOG: checkpoint complete; buffers written=5869 (35.8%); write=2.081 s, sync=4.851 s, total=7.066 s

My original patch converted the buffers written to MB. Easier to estimate MB/s by eye; I really came to hate multiplying by 8K. And people who have multiple boxes with different BLCKZ could merge their logs together and not have to worry about adjusting for that.

I found this simpler to present the results to non-PostgreSQL people without having to explain the buffer size. It's easy for any IT person to follow; the idea I was working toward was "see, this log entry shows the long pauses are because it's writing 700MB of data all at once here, right next to that statment that took 10 seconds we found with log_min_duration_statement".

The current equivilant of what I had would be CheckpointStats.ckpt_bufs_written * BLCKSZ / (1024*1024) formatted as "%.1f MB"

One thing that's missing, that I originally hoped to achieve with this, is logging the cause of a checkpoint.

The way pg_stat_bgwriter keeps two separate counts for requested (which includes timeouts) and required (out of segments) checkpoints now satisfies the main reason I originally collected that info. I felt it was critical when I wrote that patch for it to be possible to distinguish between which of the two was happening more, it's only in the nice to have category now.

Now, onto some slightly different things here, which were all aimed at developer-level troubleshooting. With the nice reworking for logging checkpoints better, there were three tiny things my original patch did that got lost along the way that I'd suggest Tom might want to consider putting back during the final apply. I'll include mini pseudo-diffs here for those so no one has to find them in my original patch, they're all one-liners:

1) Log every time a new WAL file was created, which ties into the recent discussion here that being a possible performance issue. At least you can look for it happening this way:

--- 1856,1863 ----
errmsg("could not create file \"%s\": %m", tmppath)));

+ ereport(DEBUG2, (errmsg("WAL creating and filling new file on disk")));

* Zero-fill the file. We have to do this the hard way to ensure that all

2) Add a lower-level DEBUG statement when autovaccum was finished, which helped me in several causes figure out if that was the cause of a problem (when really doing low-level testing, I would see a vacuum start, not know if it was done, and then wonder if that was the cause of a slow statement):

*** src/backend/postmaster/autovacuum.c
--- 811,814 ----
+               ereport(DEBUG2,
+ (errmsg("autovacuum: processing database \"%s\" complete", dbname)));

3) I fixed a line in postmaster.c so it formatted fork PIDs the same way most other log statements do; most statements report it as (PID %d) and the difference in this form seemed undesirable (I spent a lot of time at DEBUG2 and these little things started to bug me):

*** src/backend/postmaster/postmaster.c
*** 2630,2636 ****
        /* in parent, successful fork */
! (errmsg_internal("forked new backend, pid=%d socket=%d", (int) pid, port->sock)));
--- 2630,2636 ----
        /* in parent, successful fork */
! (errmsg_internal("forked new backend (PID %d) socket=%d", (int) pid, port->sock)));

Little stuff, but all things I've found valuable on several occasions, which suggests eventually someone else may appreciate them as well.

* Greg Smith [EMAIL PROTECTED] http://www.gregsmith.com Baltimore, MD

---------------------------(end of broadcast)---------------------------
TIP 5: don't forget to increase your free space map settings

Reply via email to