Greg Smith wrote:
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"

I don't think we currently use MB in any other log messages. If we go down that route, we need to consider switching to MB everywhere.

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

This could be useful.

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)));

Did you check out log_autovacuum? Doesn't it do what you need?

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)));

Hmm. Since it's DEBUG2 I don't care much either way. The changed message looks inconsistent to me, since socket is printed differently.

  Heikki Linnakangas

---------------------------(end of broadcast)---------------------------
TIP 9: In versions below 8.0, the planner will ignore your desire to
      choose an index scan if your joining column's datatypes do not

Reply via email to