Re: Waiting on ExclusiveLock on extension

On 4/17/15 4:22 PM, Andomar wrote:
>
>> Yes, but did you have the same workload when you upgraded to 9.3 as
>> you do today?
>
> The workload is very similar. We upgraded from 9.1 to 9.3 only two
> months ago, and our usage statistics have not changed much. There were
> no "remaining connection slots are reserved for non-replication
> superuser connections" messages in the weeks after the 9.3 upgrade.
>
>> BTW, something else to be aware of: because you essentially re-loaded
>> all your data in a single transaction, that means that a: you'll be
>> doing a lot of hint bit updates until all data has been read a second
>> time, and b: a lot of this data will come up for freezing at around
>> the same time, creating a big chunk of work for autovacuum. That's
>> caused problems for me in the past, though that was on a database that
>> had a pretty high workload.
>
> We run "VACUUM ALL" every night and although that gave a bit more CPU
> and I/O but nothing major.
>
> When the problem occurs, the symptoms are:
> - spike to a very high load average (= CPU usage)
> - messages about long waits on ExclusiveLock on extension appear
> - remaining connection slots are reserved (with corresponding end user
> impact)
>
> An example of a message with 1 second wait duration and a lot of waiting
> queries:
>
> process 667 still waiting for ExclusiveLock on extension of relation
> 1249 of database 16406 after 1005.226 ms","Process holding the lock:
> 36279. Wait queue: 36725, 36405, 36511, 36721, 36280, 36048, 36566,
...
> 49019, 667, 877, 1306, 1070, 1265.",,,,"SQL statement ""CREATE TEMPORARY
> TABLE

Ok, that's a MAJOR hint, because relation 1249 is a system catalog;
namely pg_attribute. So I think what's happening here is that your
catalog has become horrifically bloated. I'm 99% certain that VACUUM ALL
will not vacuum the catalog tables.

Do you by chance have autovacuum turned off?

A manual VACUUM VERBOSE pg_attribute might provide some immediate relief.

> An example of a message with 140 second wait duration:
>
> process 27173 acquired ExclusiveLock on extension of relation 16787 of
> database 16406 after 138522.699 ms",,,,,"SQL statement ""INSERT INTO

This is a different case though, because 16787 is not a catalog table.
(SELECT 16787::regclass; will tell you what table that is).

> There are about 50 queries a second, so a 10 second lock will exhaust
> the number of available connections.

Are you using a connection pool? Establishing 50 new database
connections per second won't do anything to help performance...

Running out of connections in this scenario isn't surprising.

> We keep sar logs, and they show an unusual amount of pgscand/s and
> pgsteal/s around the time of the problem:
>
> 07:25:01 PM  pgpgin/s pgpgout/s   fault/s  majflt/s  pgfree/s pgscank/s
> pgscand/s pgsteal/s    %vmeff
> 08:25:01 PM     29.93   1069.13 393727.33      0.00 170655.03 0.00
> 90.20     90.20    100.00
> 08:26:01 PM     20.14   1325.55 388751.51      0.00 157188.40 0.00
> 315.81    315.81    100.00

...

> pgscand/s = Number of pages scanned directly per second.
> pgsteal/s = Number of pages the system has reclaimed from cache
> (pagecache and swapcache) per second to satisfy its memory demands.
>
> Could the pgscand and pgsteal numbers provide a hint?  They're sometimes
> zero for more than half an hour, so they don't seem related to checkpoints.

I think what that means is that there was suddenly a big spike in memory
demand at the OS level, so now the OS is frantically dumping cached
pages. That in itself won't explain this, but it may be a clue.

In order to extend a relation we need to ask the filesystem to actually
extend the file (which presumably means at least writing some metadata
to disk), and then I think we create a WAL record. Creating the WAL
record won't by itself write to disk... *unless* the wal_buffers are all
already full. So if you also see an I/O spike when this happens you
could well just be starved from the I/O system (though obviously it'd be
better if we handled that situation more elegantly than this).

Another possibility given the big uptick in page scanning in the OS is
that you're saturating the memory bus... but you'd need WAY more than 5k
pages/s to do that.

I do suspect your pgfree/s is very high though; putting 200k pages/s on
the free list seems like something's broken.

BTW,
http://www.postgresql.org/message-id/466D72D2-68EC-4FF4-93B8-43B687E7B705@simply.name
contains a list of URLs about relation extension problems.
--
Jim Nasby, Data Architect, Blue Treble Consulting
Data in Trouble? Get it in Treble! http://BlueTreble.com