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:
src/backend/access/transam/xlog.c
--- 1856,1863 ----
(errcode_for_file_access(),
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 ----
do_autovacuum();
+ 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 */
ereport(DEBUG2,
! (errmsg_internal("forked new backend, pid=%d
socket=%d",
(int) pid,
port->sock)));
--- 2630,2636 ----
/* in parent, successful fork */
ereport(DEBUG2,
! (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
EnterpriseDB http://www.enterprisedb.com
---------------------------(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
match
