Slow Query / Check Point Segments

On Thu, Jan 21, 2010 at 9:13 PM, Alex - <aintokyo@hotmail.com> wrote:

Hi
i am experience slow queries when i run some functions. I noticed the
following entries in my server log.
From this, can anyone tell me if I need to change some config parmeters?
System has 18GB Memory
shared_buffers = 4GB                    # min 128kB
temp_buffers = 32MB                     # min 800kB
max_prepared_transactions = 100         # zero disables the feature
work_mem = 256MB                        # min 64kB

That's really big work_mem. What's max_connections?

maintenance_work_mem = 1GB              # min 1MB

That's pretty big too.

wal_buffers = 1024kB                    # min 32kB
checkpoint_segments = 32                # in logfile segments, min 1, 16MB
each
checkpoint_timeout = 30min              # range 30s-1h

2010-01-22 12:18:11 JSTLOG:  checkpoint complete: wrote 52037 buffers
(9.9%); 0 transaction log file(s) added, 0 removed, 0 recycled; write=67.441
s, sync=0.000 s, total=67.453 s
2010-01-22 12:21:48 JSTLOG:  checkpoint complete: wrote 83874 buffers
(16.0%); 0 transaction log file(s) added, 0 removed, 32 recycled;
write=138.040 s, sync=0.000 s, total=138.063 s
2010-01-22 12:23:32 JSTLOG:  checkpoint complete: wrote 82856 buffers
(15.8%); 0 transaction log file(s) added, 0 removed, 32 recycled;
write=18.740 s, sync=0.000 s, total=18.783 s
2010-01-22 12:24:26 JSTLOG:  checkpoint complete: wrote 75145 buffers
(14.3%); 0 transaction log file(s) added, 0 removed, 32 recycled;
write=12.129 s, sync=0.000 s, total=12.132 s
2010-01-22 12:25:30 JSTLOG:  checkpoint complete: wrote 82108 buffers
(15.7%); 0 transaction log file(s) added, 0 removed, 32 recycled;
write=10.619 s, sync=0.000 s, total=10.621 s
2010-01-22 12:28:03 JSTLOG:  checkpoint complete: wrote 87349 buffers
(16.7%); 0 transaction log file(s) added, 0 removed, 32 recycled;
write=82.190 s, sync=0.000 s, total=82.192 s
2010-01-22 12:30:02 JSTLOG:  checkpoint complete: wrote 80797 buffers
(15.4%); 0 transaction log file(s) added, 0 removed, 32 recycled;
write=78.198 s, sync=0.000 s, total=78.201 s
2010-01-22 12:32:03 JSTLOG:  checkpoint complete: wrote 81365 buffers
(15.5%); 0 transaction log file(s) added, 0 removed, 32 recycled;
write=75.968 s, sync=0.000 s, total=75.971 s
2010-01-22 12:33:32 JSTLOG:  checkpoint complete: wrote 98258 buffers
(18.7%); 0 transaction log file(s) added, 0 removed, 32 recycled;
write=52.156 s, sync=0.000 s, total=52.159 s
2010-01-22 12:34:51 JSTLOG:  checkpoint complete: wrote 80089 buffers
(15.3%); 0 transaction log file(s) added, 0 removed, 32 recycled;
write=53.385 s, sync=0.000 s, total=53.387 s
2010-01-22 12:36:08 JSTLOG:  checkpoint complete: wrote 80819 buffers
(15.4%); 0 transaction log file(s) added, 0 removed, 32 recycled;
write=51.476 s, sync=0.000 s, total=51.478 s

Up to now it looks pretty normal. Then:

2010-01-22 13:01:54 JSTLOG:  checkpoint complete: wrote 4892 buffers (0.9%);
0 transaction log file(s) added, 0 removed, 32 recycled; write=494.868 s,
sync=0.000 s, total=494.982 s

Wow that is a really long time for a checkpoint of only 0.9% to take.
I'm gonna guess you went from a lot of inserts up above, then started
running lots of queries that used lots of memory and / or vacuum
chewed up a lot, and the OS swapped out your shared_buffers and they
were getting swapped back in during the checkpoint. But that's just a
guess. Could be other stuff. When this stuff happens, what does the
output of vmstat 60 look like (not just the first line, run it a few
minutes)?

Oh yeah, what's your swappiness setting (assuming you're running some
flavor of linux:

sysctl -a|grep swapp

should tell you. I set it to something small like 5 or so on db
servers. Default of 60 is fine for an interactive desktop but usually
too high for a server.

Alex - wrote:

checkpoint_segments = 32 # in logfile segments, min 1,
16MB each
checkpoint_timeout = 30min # range 30s-1h

These parameters are not so interesting on their own. The important
thing to check is how often checkpoints are happening, and how much work
each of them do. Here's a useful section from your logs to comment on:

2010-01-22 12:21:48 JSTLOG: checkpoint complete: wrote 83874 buffers
(16.0%); 0 transaction log file(s) added, 0 removed, 32 recycled;
write=138.040 s, sync=0.000 s, total=138.063 s
2010-01-22 12:23:32 JSTLOG: checkpoint complete: wrote 82856 buffers
(15.8%); 0 transaction log file(s) added, 0 removed, 32 recycled;
write=18.740 s, sync=0.000 s, total=18.783 s
2010-01-22 12:24:26 JSTLOG: checkpoint complete: wrote 75145 buffers
(14.3%); 0 transaction log file(s) added, 0 removed, 32 recycled;
write=12.129 s, sync=0.000 s, total=12.132 s
2010-01-22 12:25:30 JSTLOG: checkpoint complete: wrote 82108 buffers
(15.7%); 0 transaction log file(s) added, 0 removed, 32 recycled;
write=10.619 s, sync=0.000 s, total=10.621 s
2010-01-22 12:28:03 JSTLOG: checkpoint complete: wrote 87349 buffers
(16.7%); 0 transaction log file(s) added, 0 removed, 32 recycled;
write=82.190 s, sync=0.000 s, total=82.192 s

Here you're getting a checkpoint every minute or three, and each of them
is writing out ~80000 buffers = 625MB. That is crazy, and no wonder
your queries are slow--the system is spending all of its time doing
constant, extremely expensive checkpoints.

You should re-tune this system until the checkpoints show up no more
often than every 5 minutes, and preferably closer to 10. In your case,
that means greatly increasing checkpoint_segments.. And you might as
well decrease checkpoint_timeout, because right now the timeout is
rarely ever being reached before the system runs out of working segments
and executes a checkpoint for that reason.

I would suggest changing the parameters to these:

checkpoint_segments = 96 # in logfile segments, min 1,
16MB each
checkpoint_timeout = 10min # range 30s-1h

And seeing how long the interval between checkpoints becomes under load
afterwards. That should make it in the just >5 minute range. I'd
expect that the number of buffers will only increase a bit, so instead
of dumping out 625MB every minute or three you should see maybe 800MB
every 5 minutes--big improvement.

Also: just after making the change, save a copy of:

select now(),* from pg_stat_bgwriter

And then run that same query again a few hours after the change (and
maybe the next day twoo). Subtract the two values to see how much they
changed, and then you'll find some useful info to compute the checkpoint
interval without even looking at the logs. There's a lot of theory and
comments about this area at
http://www.westnet.com/~gsmith/content/postgresql/chkp-bgw-83.htm

2010-01-22 12:36:08 JSTLOG: checkpoint complete: wrote 80819 buffers
(15.4%); 0 transaction log file(s) added, 0 removed, 32 recycled;
write=51.476 s, sync=0.000 s, total=51.478 s
2010-01-22 13:01:54 JSTLOG: checkpoint complete: wrote 4892 buffers
(0.9%); 0 transaction log file(s) added, 0 removed, 32 recycled;
write=494.868 s, sync=0.000 s, total=494.982 s

See that last one? That's a checkpoint that's being driven by time
expiring (30 minutes) rather than running out of segments. That just
suggests that the system was mostly idle during that period. Long write
times are perfectly fine here, the checkpoints are spread out over a
long time if possible in order to reduce average I/O. You're just not
seeing that the rest of the time because checkpoints are happening so often.

--
Greg Smith 2ndQuadrant Baltimore, MD
PostgreSQL Training, Services and Support
greg@2ndQuadrant.com www.2ndQuadrant.com

Greg,thanks for the suggestions, will try an test.
You wrote: That just suggests that the system was mostly idle during that period.
Thats actually not the case, it was just the time the function finished.

Alex

Date: Fri, 22 Jan 2010 01:21:59 -0500
From: greg@2ndquadrant.com
To: aintokyo@hotmail.com
CC: pgsql-general@postgresql.org
Subject: Re: [GENERAL] Slow Query / Check Point Segments

Alex - wrote:

checkpoint_segments = 32 # in logfile segments,
min 1, 16MB each
checkpoint_timeout = 30min # range 30s-1h

These parameters are not so interesting on their own. The important
thing to check is how often checkpoints are happening, and how much
work each of them do. Here's a useful section from your logs to
comment on:

2010-01-22 12:21:48 JSTLOG: checkpoint complete: wrote 83874
buffers (16.0%); 0 transaction log file(s) added, 0 removed, 32
recycled; write=138.040 s, sync=0.000 s, total=138.063 s
2010-01-22 12:23:32 JSTLOG: checkpoint complete: wrote 82856
buffers (15.8%); 0 transaction log file(s) added, 0 removed, 32
recycled; write=18.740 s, sync=0.000 s, total=18.783 s
2010-01-22 12:24:26 JSTLOG: checkpoint complete: wrote 75145
buffers (14.3%); 0 transaction log file(s) added, 0 removed, 32
recycled; write=12.129 s, sync=0.000 s, total=12.132 s
2010-01-22 12:25:30 JSTLOG: checkpoint complete: wrote 82108
buffers (15.7%); 0 transaction log file(s) added, 0 removed, 32
recycled; write=10.619 s, sync=0.000 s, total=10.621 s
2010-01-22 12:28:03 JSTLOG: checkpoint complete: wrote 87349
buffers (16.7%); 0 transaction log file(s) added, 0 removed, 32
recycled; write=82.190 s, sync=0.000 s, total=82.192 s

Here you're getting a checkpoint every minute or three, and each of
them is writing out ~80000 buffers = 625MB. That is crazy, and no
wonder your queries are slow--the system is spending all of its time
doing constant, extremely expensive checkpoints.

You should re-tune this system until the checkpoints show up no more
often than every 5 minutes, and preferably closer to 10. In your case,
that means greatly increasing checkpoint_segments.. And you might as
well decrease checkpoint_timeout, because right now the timeout is
rarely ever being reached before the system runs out of working
segments and executes a checkpoint for that reason.

I would suggest changing the parameters to these:

checkpoint_segments = 96 # in logfile segments, min
1, 16MB each
checkpoint_timeout = 10min # range 30s-1h

And seeing how long the interval between checkpoints becomes under load
afterwards. That should make it in the just >5 minute range. I'd
expect that the number of buffers will only increase a bit, so instead
of dumping out 625MB every minute or three you should see maybe 800MB
every 5 minutes--big improvement.

Also: just after making the change, save a copy of:

select now(),* from pg_stat_bgwriter

And then run that same query again a few hours after the change (and
maybe the next day twoo). Subtract the two values to see how much they
changed, and then you'll find some useful info to compute the
checkpoint interval without even looking at the logs. There's a lot of
theory and comments about this area at
http://www.westnet.com/~gsmith/content/postgresql/chkp-bgw-83.htm

2010-01-22 12:36:08 JSTLOG: checkpoint complete: wrote 80819
buffers (15.4%); 0 transaction log file(s) added, 0 removed, 32
recycled; write=51.476 s, sync=0.000 s, total=51.478 s
2010-01-22 13:01:54 JSTLOG: checkpoint complete: wrote 4892
buffers (0.9%); 0 transaction log file(s) added, 0 removed, 32
recycled; write=494.868 s, sync=0.000 s, total=494.982 s

See that last one? That's a checkpoint that's being driven by time
expiring (30 minutes) rather than running out of segments. That just
suggests that the system was mostly idle during that period. Long
write times are perfectly fine here, the checkpoints are spread out
over a long time if possible in order to reduce average I/O. You're
just not seeing that the rest of the time because checkpoints are
happening so often.

--
Greg Smith 2ndQuadrant Baltimore, MD
PostgreSQL Training, Services and Support
greg@2ndQuadrant.com www.2ndQuadrant.com

_________________________________________________________________
Shopping Trolley Mechanic If It Exists, You'll Find it on SEEK
http://clk.atdmt.com/NMN/go/157639755/direct/01/

Greg Smith wrote:

2010-01-22 12:21:48 JSTLOG: checkpoint complete: wrote 83874 buffers
(16.0%); 0 transaction log file(s) added, 0 removed, 32 recycled;
write=138.040 s, sync=0.000 s, total=138.063 s
2010-01-22 12:23:32 JSTLOG: checkpoint complete: wrote 82856 buffers
(15.8%); 0 transaction log file(s) added, 0 removed, 32 recycled;
write=18.740 s, sync=0.000 s, total=18.783 s
2010-01-22 12:24:26 JSTLOG: checkpoint complete: wrote 75145 buffers
(14.3%); 0 transaction log file(s) added, 0 removed, 32 recycled;
write=12.129 s, sync=0.000 s, total=12.132 s
2010-01-22 12:25:30 JSTLOG: checkpoint complete: wrote 82108 buffers
(15.7%); 0 transaction log file(s) added, 0 removed, 32 recycled;
write=10.619 s, sync=0.000 s, total=10.621 s
2010-01-22 12:28:03 JSTLOG: checkpoint complete: wrote 87349 buffers
(16.7%); 0 transaction log file(s) added, 0 removed, 32 recycled;
write=82.190 s, sync=0.000 s, total=82.192 s

Here you're getting a checkpoint every minute or three, and each of
them is writing out ~80000 buffers = 625MB. That is crazy, and no
wonder your queries are slow--the system is spending all of its time
doing constant, extremely expensive checkpoints.
.....

we're having a similar problem with a very update intensive database
that is part of a 24/7 manufacturing operation (no breathing time unless
there's an unusual line down situtation)

a snip of the log...

2010-01-23 01:02:19 MYTLOG: checkpoint complete: wrote 764 buffers
(0.3%); 0 transaction log file(s) added, 0 removed, 20 recycled;
write=31.207 s, sync=0.147 s, total=31.394 s
2010-01-23 01:08:13 MYTLOG: checkpoint complete: wrote 7535 buffers
(2.9%); 0 transaction log file(s) added, 0 removed, 20 recycled;
write=86.510 s, sync=0.260 s, total=86.791 s
2010-01-23 01:13:22 MYTLOG: checkpoint complete: wrote 12786 buffers
(4.9%); 0 transaction log file(s) added, 0 removed, 17 recycled;
write=95.028 s, sync=0.135 s, total=95.182 s
2010-01-23 01:16:22 MYTLOG: checkpoint complete: wrote 11720 buffers
(4.5%); 0 transaction log file(s) added, 0 removed, 19 recycled;
write=41.854 s, sync=0.640 s, total=42.518 s
2010-01-23 01:19:11 MYTLOG: checkpoint complete: wrote 10436 buffers
(4.0%); 0 transaction log file(s) added, 0 removed, 20 recycled;
write=50.330 s, sync=0.510 s, total=50.861 s
2010-01-23 01:23:19 MYTLOG: checkpoint complete: wrote 6446 buffers
(2.5%); 0 transaction log file(s) added, 0 removed, 20 recycled;
write=57.195 s, sync=0.583 s, total=57.790 s
2010-01-23 01:27:54 MYTLOG: checkpoint complete: wrote 4454 buffers
(1.7%); 0 transaction log file(s) added, 0 removed, 20 recycled;
write=44.805 s, sync=0.118 s, total=44.943 s
2010-01-23 01:32:36 MYTLOG: checkpoint complete: wrote 4645 buffers
(1.8%); 0 transaction log file(s) added, 0 removed, 20 recycled;
write=50.792 s, sync=0.689 s, total=51.502 s
2010-01-23 01:37:13 MYTLOG: checkpoint complete: wrote 5722 buffers
(2.2%); 0 transaction log file(s) added, 0 removed, 20 recycled;
write=58.077 s, sync=0.606 s, total=58.707 s
2010-01-23 01:41:20 MYTLOG: checkpoint complete: wrote 5006 buffers
(1.9%); 0 transaction log file(s) added, 0 removed, 20 recycled;
write=36.064 s, sync=0.898 s, total=36.986 s
2010-01-23 01:46:14 MYTLOG: checkpoint complete: wrote 3644 buffers
(1.4%); 0 transaction log file(s) added, 0 removed, 20 recycled;
write=54.873 s, sync=0.659 s, total=55.554 s
2010-01-23 01:51:15 MYTLOG: checkpoint complete: wrote 5534 buffers
(2.1%); 0 transaction log file(s) added, 0 removed, 20 recycled;
write=63.152 s, sync=0.374 s, total=63.546 s

The admin tells me the current parameters are...

checkpoint_segments = 20 # in logfile segments, min 1,
16MB eac
checkpoint_timeout = 5min # range 30s-1h

and I'm suggesting 60 and 15min, does that seem reasonable?

This is running on a 16 core UltrasparcIV server, solaris 10, zfs, tons
of disks on SAN with multiple tablespaces on different ZFS's, with the
block sizes tuned appropriately

John R Pierce wrote:

we're having a similar problem with a very update intensive database
that is part of a 24/7 manufacturing operation (no breathing time
unless there's an unusual line down situtation)

Your problem is actually a bit different.

2010-01-23 01:08:13 MYTLOG: checkpoint complete: wrote 7535 buffers
(2.9%); 0 transaction log file(s) added, 0 removed, 20 recycled;
write=86.510 s, sync=0.260 s, total=86.791 s
2010-01-23 01:13:22 MYTLOG: checkpoint complete: wrote 12786 buffers
(4.9%); 0 transaction log file(s) added, 0 removed, 17 recycled;
write=95.028 s, sync=0.135 s, total=95.182 s
2010-01-23 01:16:22 MYTLOG: checkpoint complete: wrote 11720 buffers
(4.5%); 0 transaction log file(s) added, 0 removed, 19 recycled;
write=41.854 s, sync=0.640 s, total=42.518 s
2010-01-23 01:19:11 MYTLOG: checkpoint complete: wrote 10436 buffers
(4.0%); 0 transaction log file(s) added, 0 removed, 20 recycled;
write=50.330 s, sync=0.510 s, total=50.861 s

Your interval between checkpoints isn't too bad--3 minutes on the worst
of these. And the amount per checkpoint isn't that high either: 12786
buffers=100MB. Your problem is that the sync on that 100MB write is
taking an awfully long time. Spacing your checkpoints out further would
help, sure, but I wouldn't be surprised to find that doesn't do much for
you. Worth a shot, unlikely to hurt anything, just not optimistic about
it being the right think the way I was on the other message.

This is running on a 16 core UltrasparcIV server, solaris 10, zfs,
tons of disks on SAN with multiple tablespaces on different ZFS's,
with the block sizes tuned appropriately

My guess is that there's something wrong with your config such that
writes followed by fsync are taking longer than they should. When I see
"sync=0.640 s" into a SAN where that sync operation should be near
instant, I'd be looking for issues in the ZFS intent log setup, how much
data you've setup ZFS to write cache, and the write cache policy on the
SAN hardware. There's something weird going on here, that sync should
be near instant on your hardware with such a small write volume.

Unfortunately, you may have to take the server down to find out exactly
what's going on, which doesn't sound practical for your environment.
(And people wonder why I have near religious zeal about testing disk
hardware before systems go into production)

--
Greg Smith 2ndQuadrant Baltimore, MD
PostgreSQL Training, Services and Support
greg@2ndQuadrant.com www.2ndQuadrant.com

Greg Smith wrote:

My guess is that there's something wrong with your config such that
writes followed by fsync are taking longer than they should. When I
see "sync=0.640 s" into a SAN where that sync operation should be near
instant, I'd be looking for issues in the ZFS intent log setup, how
much data you've setup ZFS to write cache, and the write cache policy
on the SAN hardware. There's something weird going on here, that sync
should be near instant on your hardware with such a small write volume.

Unfortunately, you may have to take the server down to find out
exactly what's going on, which doesn't sound practical for your
environment. (And people wonder why I have near religious zeal about
testing disk hardware before systems go into production)

there's a further complication. this system is deep in southeast asia
on a rather slow and saturated network connection such that trying to
figure out stuff about it is challenging at best. I know the database
has a lot of write volume overall, and its only one of several databases
running in different zones on the server. I know nothing about the SAN,
I suspect its a EMC Symmetrix of some sort. Probably a generation or
two behind latest. The operations people are used to running large
oracle databases.

John R Pierce wrote:

I know the database has a lot of write volume overall, and its only
one of several databases running in different zones on the server. I
know nothing about the SAN, I suspect its a EMC Symmetrix of some
sort. Probably a generation or two behind latest. The operations
people are used to running large oracle databases.

One thing you might try is making the PostgreSQL install act more like
an Oracle one in terms of how it does writes. By default, PostgreSQL
does its WAL writes by writing and then calling a sync method. On
Solaris, you should be able to safely change this in the postgresql.conf
file to be:

wal_sync_method=open_datasync

Which I don't think is the default (you can confirm with "show
wal_sync_method;" via psql on your database). That will use O_DSYNC
writes, which are more like how Oracle approaches this and therefore
potentially a better tuned path for your install.

More on this subject, including idea for further tweaking

http://www.postgresql.org/docs/8.4/static/runtime-config-wal.html
http://blogs.sun.com/jkshah/entry/postgresql_wal_sync_method_and
http://www.westnet.com/~gsmith/content/postgresql/TuningPGWAL.htm

From what you've shown and described, I'm not sure what other
PostgreSQL tuning you might do to improve the specific symptoms you're
seeing. The particular issue you've got I'd normally start attacking on
the filesystem and hardware side of things. There's a reason why many
people avoid SANs in this context, there's a lot of ways you can screw
up in this particular aspect of their performance relative to what you
get with direct attached storage, and it's hard to tell which you've run
into when a problem does pop up.

--
Greg Smith 2ndQuadrant Baltimore, MD
PostgreSQL Training, Services and Support
greg@2ndQuadrant.com www.2ndQuadrant.com

Greg Smith wrote:

John R Pierce wrote:

I know the database has a lot of write volume overall, and its only
one of several databases running in different zones on the server. I
know nothing about the SAN, I suspect its a EMC Symmetrix of some
sort. Probably a generation or two behind latest. The operations
people are used to running large oracle databases.

One thing you might try is making the PostgreSQL install act more like
an Oracle one in terms of how it does writes. By default, PostgreSQL
does its WAL writes by writing and then calling a sync method. On
Solaris, you should be able to safely change this in the
postgresql.conf file to be:

iostat -x 5 or 15 shows a bunch of LUNs are as much as 10% busy, but
the service time stays under 50ms... this is one of the busiest of the
15 second samples over a 10 min period I'm just showing a representive
sampling of the busiest LUNs out of 40, the physical storage is all
raid10's on a DMX4.

extended device statistics
device r/s w/s kr/s kw/s wait actv svc_t %w %b
sd1 0.0 0.0 0.0 0.0 0.0 0.0 0.0 0 0
...
ssd10 0.0 33.2 0.0 546.6 0.0 1.0 28.9 0 7
ssd11 0.0 27.7 0.0 573.9 0.0 0.9 34.0 0 6
ssd12 0.0 56.2 0.0 576.6 0.0 1.5 26.5 0 10
ssd13 0.0 30.8 0.0 505.5 0.0 0.9 28.7 0 7
ssd14 0.0 42.9 0.0 498.4 0.0 1.4 32.9 0 9
ssd15 0.0 38.3 0.0 557.6 0.0 1.7 44.0 0 8
ssd16 0.0 41.1 0.0 520.5 0.0 1.3 32.0 0 9
ssd17 0.0 52.4 0.0 528.6 0.0 1.3 24.8 0 10
ssd18 0.0 29.0 0.0 503.9 0.0 1.2 41.4 0 7
...

most show near 0% busy and 10/th that volume of writes or reads.

zpool iostat 15 also shows this io peak for about a minute or two
every few minutes but its nowhere near hardware capacity

$ zpool iostat 15
capacity operations bandwidth
pool used avail read write read write
---------- ----- ----- ----- ----- ----- -----
data-p1 268G 101G 109 386 1.16M 6.98M
data-p2 340M 33.2G 0 2 491 36.8K
---------- ----- ----- ----- ----- ----- -----
..............
---------- ----- ----- ----- ----- ----- -----
data-p1 268G 101G 40 6 527K 164K
data-p2 341M 33.2G 0 0 0 0
---------- ----- ----- ----- ----- ----- -----
data-p1 268G 101G 36 1.35K 306K 19.2M
data-p2 341M 33.2G 0 0 0 0
---------- ----- ----- ----- ----- ----- -----
data-p1 268G 101G 45 585 445K 2.01M
data-p2 341M 33.2G 0 0 0 0
---------- ----- ----- ----- ----- ----- -----
data-p1 268G 101G 47 38 410K 1.05M
data-p2 341M 33.2G 0 0 0 0
---------- ----- ----- ----- ----- ----- -----
data-p1 268G 101G 68 145 745K 4.11M
data-p2 341M 33.2G 0 0 0 0
---------- ----- ----- ----- ----- ----- -----
data-p1 268G 101G 38 168 311K 4.60M
data-p2 340M 33.2G 0 9 0 294K
---------- ----- ----- ----- ----- ----- -----
data-p1 268G 101G 55 65 504K 1.18M
data-p2 340M 33.2G 0 0 0 0
---------- ----- ----- ----- ----- ----- -----
data-p1 268G 101G 5 1.07K 43.1K 9.71M
data-p2 340M 33.2G 0 0 0 0
---------- ----- ----- ----- ----- ----- -----
data-p1 268G 101G 46 7 549K 179K
data-p2 340M 33.2G 0 0 0 0
---------- ----- ----- ----- ----- ----- -----
^C

wal_sync_method=open_datasync

Which I don't think is the default (you can confirm with "show
wal_sync_method;" via psql on your database). That will use O_DSYNC
writes, which are more like how Oracle approaches this and therefore
potentially a better tuned path for your install.

thats what its set to now.

More on this subject, including idea for further tweaking

http://www.postgresql.org/docs/8.4/static/runtime-config-wal.html
http://blogs.sun.com/jkshah/entry/postgresql_wal_sync_method_and
http://www.westnet.com/~gsmith/content/postgresql/TuningPGWAL.htm

From what you've shown and described, I'm not sure what other
PostgreSQL tuning you might do to improve the specific symptoms you're
seeing. The particular issue you've got I'd normally start attacking
on the filesystem and hardware side of things. There's a reason why
many people avoid SANs in this context, there's a lot of ways you can
screw up in this particular aspect of their performance relative to
what you get with direct attached storage, and it's hard to tell which
you've run into when a problem does pop up.

The SAN is a dmx4, and it seems to be damn fast by all low level tests i
can run. this database is really getting hammered on. a couple of
the tables take 8-12 hours to vacuum. these are tables with many
millions of small rows that are updated randomly at a high speed, using
a rather large primary key (the PK is 6 or 8 short text fields, the
'data' is a couple counters). The performance got a lot better when we
set these tables for fill factor of 50 but the table size doubled (duh)
which apparently produced its own problems so they are trying fill
factor 70. there's probably 100 connections.

cpu and vm usage for a couple minutes...

$ vmstat 15
kthr memory page disk faults cpu
r b w swap free re mf pi po fr de sr s1 sd sd sd in sy cs us
sy id
2 0 0 30980016 1555616 20 260 40 0 0 0 0 -0 4 4 5 2231 21989 11168
25 4 72
0 0 0 30765664 1227536 57 368 185 0 0 0 0 0 8 13 5 1366 64055 48764
34 7 59
2 0 0 30757576 1218784 0 12 0 0 0 0 0 0 8 8 9 7137 82432 58548
53 12 36
3 0 0 30750528 1211736 0 15 0 0 0 0 0 0 39 44 35 2959 85558 64763
40 10 51
0 0 0 30745624 1206832 0 9 0 0 0 0 0 0 0 0 1 1253 65697 51775
32 7 62
0 0 0 30739896 1201104 21 127 97 0 0 0 0 0 3 2 5 1271 67217 52826
34 7 59
1 0 0 30729832 1191592 32 296 0 0 0 0 0 0 0 1 2 5030 82152 53824
45 12 43
3 0 0 30722528 1184328 28 239 0 0 0 0 0 0 11 10 15 2201 87922 66675
38 10 52
1 0 0 30720800 1181984 0 12 0 0 0 0 0 0 36 34 60 1970 68696 52730
38 8 54
0 0 0 30716152 1177320 34 248 259 0 0 0 0 0 3 3 10 1139 71591 55853
31 8 61
3 0 0 30708216 1169312 0 13 0 0 0 0 0 0 6 6 6 9114 90349 60455
56 15 29
5 0 0 30700448 1161544 0 15 0 0 0 0 0 0 29 29 36 3196 61634 34290
47 11 41
0 0 0 30694528 1155624 0 10 0 0 0 0 0 0 35 35 32 1343 62273 48045
33 7 60
0 0 0 30686688 1148592 36 282 171 0 0 0 0 0 2 2 5 1068 75579 59492
30 8 62

I'm thinking its zfs tuning we need to do, not physical disk IO, and
thats a topic for another list, I guess. I know quite a lot has been
done, using different zfs block sizes for different tablespaces, putting
index and data in different tablespaces, and so forth.

Hi,
Please have a look at the functions also - what are they doing? In Oracle
I have come across a situation where a lot of redo log was generated
because one SQL was updating an entire table, instead of a few selected
records. Since the new data was the same as the old data (for records
which shouldn't have been updated in the first place), the functionality
of the application was fine. But it was generating a lot of redo log
(similar to WAL in PostgreSQL) and causing serious performance issues
because of the redo generation, buffer getting filled up quickly and so
on.
Jayadevan

From: Alex - <aintokyo@hotmail.com>
To: <pgsql-general@postgresql.org>
Date: 01/22/2010 09:42 AM
Subject: [GENERAL] Slow Query / Check Point Segments
Sent by: pgsql-general-owner@postgresql.org

Hi
i am experience slow queries when i run some functions. I noticed the
following entries in my server log.

From this, can anyone tell me if I need to change some config parmeters?

System has 18GB Memory
shared_buffers = 4GB # min 128kB
temp_buffers = 32MB # min 800kB
max_prepared_transactions = 100 # zero disables the feature
work_mem = 256MB # min 64kB
maintenance_work_mem = 1GB # min 1MB
wal_buffers = 1024kB # min 32kB
checkpoint_segments = 32 # in logfile segments, min 1, 16MB
each
checkpoint_timeout = 30min # range 30s-1h

2010-01-22 12:18:11 JSTLOG: checkpoint complete: wrote 52037 buffers
(9.9%); 0 transaction log file(s) added, 0 removed, 0 recycled;
write=67.441 s, sync=0.000 s, total=67.453 s
2010-01-22 12:21:48 JSTLOG: checkpoint complete: wrote 83874 buffers
(16.0%); 0 transaction log file(s) added, 0 removed, 32 recycled;
write=138.040 s, sync=0.000 s, total=138.063 s
2010-01-22 12:23:32 JSTLOG: checkpoint complete: wrote 82856 buffers
(15.8%); 0 transaction log file(s) added, 0 removed, 32 recycled;
write=18.740 s, sync=0.000 s, total=18.783 s
2010-01-22 12:24:26 JSTLOG: checkpoint complete: wrote 75145 buffers
(14.3%); 0 transaction log file(s) added, 0 removed, 32 recycled;
write=12.129 s, sync=0.000 s, total=12.132 s
2010-01-22 12:25:30 JSTLOG: checkpoint complete: wrote 82108 buffers
(15.7%); 0 transaction log file(s) added, 0 removed, 32 recycled;
write=10.619 s, sync=0.000 s, total=10.621 s
2010-01-22 12:28:03 JSTLOG: checkpoint complete: wrote 87349 buffers
(16.7%); 0 transaction log file(s) added, 0 removed, 32 recycled;
write=82.190 s, sync=0.000 s, total=82.192 s
2010-01-22 12:30:02 JSTLOG: checkpoint complete: wrote 80797 buffers
(15.4%); 0 transaction log file(s) added, 0 removed, 32 recycled;
write=78.198 s, sync=0.000 s, total=78.201 s
2010-01-22 12:32:03 JSTLOG: checkpoint complete: wrote 81365 buffers
(15.5%); 0 transaction log file(s) added, 0 removed, 32 recycled;
write=75.968 s, sync=0.000 s, total=75.971 s
2010-01-22 12:33:32 JSTLOG: checkpoint complete: wrote 98258 buffers
(18.7%); 0 transaction log file(s) added, 0 removed, 32 recycled;
write=52.156 s, sync=0.000 s, total=52.159 s
2010-01-22 12:34:51 JSTLOG: checkpoint complete: wrote 80089 buffers
(15.3%); 0 transaction log file(s) added, 0 removed, 32 recycled;
write=53.385 s, sync=0.000 s, total=53.387 s
2010-01-22 12:36:08 JSTLOG: checkpoint complete: wrote 80819 buffers
(15.4%); 0 transaction log file(s) added, 0 removed, 32 recycled;
write=51.476 s, sync=0.000 s, total=51.478 s
2010-01-22 13:01:54 JSTLOG: checkpoint complete: wrote 4892 buffers
(0.9%); 0 transaction log file(s) added, 0 removed, 32 recycled;
write=494.868 s, sync=0.000 s, total=494.982 s

Thanks for any advice
Alex

If It Exists, You'll Find it on SEEK Shopping Trolley Mechanic

DISCLAIMER:

"The information in this e-mail and any attachment is intended only for
the person to whom it is addressed and may contain confidential and/or
privileged material. If you have received this e-mail in error, kindly
contact the sender and destroy all copies of the original communication.
IBS makes no warranty, express or implied, nor guarantees the accuracy,
adequacy or completeness of the information contained in this email or any
attachment and is not liable for any errors, defects, omissions, viruses
or for resultant loss or damage, if any, direct or indirect."