Re: Problems with pg_locks explosion - Mailing list pgsql-performance

Hi Jeff, 

Sorry I should've mentioned the new instance is Postgres 9.2.3. The old instance IO maxed out the disk/io available on a single EBS volume on AWS. It had 2000 PIOPS but was constantly bottlenecked. I assumed that striping 6 1000 IOPS volumes in RAID-0 would give me some breathing space on that front, and looking at the iostat (just included in previous email) it seems to be doing OK. 

I actually had pg_pool running as a test but to avoid having too many moving parts in the change removed it from the equation. Need to look into the proper configuration so it doesn't saturate my cluster worse than I'm doing myself.

I've commented inline. 

Regards,

Armand

PS. This is probably the most helpful mailing list I've ever come across. Starting to feel a little more that it can be solved. 

On Tue, Apr 2, 2013 at 2:21 AM, Jeff Janes <jeff.janes@gmail.com> wrote:

On Mon, Apr 1, 2013 at 3:35 PM, Armand du Plessis <adp@bank.io> wrote:

[Apologies, I first sent this to the incorrect list, postgres-admin, in the event you receive it twice]

Hi there,

I'm hoping someone on the list can shed some light on an issue I'm having with our Postgresql cluster. I'm literally tearing out my hair and don't have a deep enough understanding of Postgres to find the problem. 

What's happening is I had severe disk/io issues on our original Postgres cluster (9.0.8)

and switched to a new instance with a RAID-0 volume array.

What was the old instance IO?  Did you do IO benchmarking on both?

 

The machine's CPU usage would hover around 30% and our database would run lightning fast with pg_locks hovering between 100-200. 

Within a few seconds something would trigger a massive increase in pg_locks so that it suddenly shoots up to 4000-8000. At this point everything dies. Queries that usually take a few milliseconds takes minutes and everything is unresponsive until I restart postgres. 

I think that pg_locks is pretty much a red herring.  All it means is that you have a lot more active connections than you used to.   All active connections are going to hold various locks, while most idle connections (other than 'idle in transaction') connections will not hold any.

Although I doubt it will solve this particular problem, you should probably use a connection pooler.

shared_buffers = 32GB

That seems very high.  There are reports that using >8 GB leads to precisely the type of problem you are seeing (checkpoint associated freezes).  Although I've never seen those reports when fsync=off.  

I thought you might be suffering from the problem solved in release 9.1 by item "Merge duplicate fsync requests (Robert Haas, Greg Smith)", but then I realized that with fsync=off it could not be that.

 

max_connections = 800

That also is very high.

The problems seem to overlap with checkpoints. 

2013-04-01 21:31:35.592 UTC,,,26877,,5159fa5f.68fd,1,,2013-04-01 21:21:35 UTC,,0,LOG,00000,"checkpoint starting: time",,,,,,,,,""

2013-04-01 21:40:35.033 UTC,,,26877,,5159fa5f.68fd,2,,2013-04-01 21:21:35 UTC,,0,LOG,00000,"checkpoint complete: wrote 100635 buffers (2.4%); 0 transaction log file(s) added, 0 removed, 1 recycled; write=539.439 s, sync=0.000 s, total=539.441 s; sync files=0, longest=0.000 s, average=0.000 s",,,,,,,,,""

2013-04-01 21:41:35.093 UTC,,,26877,,5159fa5f.68fd,3,,2013-04-01 21:21:35 UTC,,0,LOG,00000,"checkpoint starting: time",,,,,,,,,""

I think you changed checkpoint_timout from default (5 min) to 10 minutes, without telling us.  Anyway, this is where it would be nice to know how much of the 539.439 s in the write phase was spent blocking on writes, and how much was spent napping.  But that info is not collected by pgsql.

I did actually change it to 25 minutes. Apologies it was probably lost in the text of a previous email. Here's the changed settings:

# - Background Writer -

bgwriter_delay = 200ms                  # 10-10000ms between rounds

bgwriter_lru_maxpages = 400             # 0-1000 max buffers written/round

bgwriter_lru_multiplier = 2.0           # 0-10.0 multipler on buffers scanned/round

checkpoint_segments = 128

checkpoint_timeout = 25min  

It seems to be lasting longer with these settings. 

 

Your top output looked for it was a time at which there were no problems, and it didn't include the top processes, so it wasn't very informative.

 

If you could upgrade to 9.2 and capture some data with track_io_timing, that could be useful.

I'm looking into track_io_timing.

 

Cheers,

Jeff