Re: Slow Query / Check Point Segments

On Thu, Jan 21, 2010 at 9:13 PM, Alex - <aintokyo(at)hotmail(dot)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)?