On Fri, Nov 16, 2012 at 12:13 PM, Vlad <marchenko@gmail.com> wrote:
> ok, I've applied that patch and ran. The stall started around 13:50:45...50
> and lasted until the end
>
> https://dl.dropbox.com/u/109778/postgresql-2012-11-16_134904-stripped.log
That isn't as much log as I expected. But I guess only the tip of the
iceberg gets logged, it could be that most spinlocks are contended but
then get acquired just before the sleep (and log) would have happened.
I'm not sure how to figure out just how much spinning is going on
below the surface, but my gut feeling is there isn't enough of it to
explain the amount of slowdown you are seeing (and it would probably
be accounted for as user time rather than system time)
Maybe we could whip up a dummy standalone program that uses PG's
spinlock code in a intentionally contended way and see how your
system reports resource usage for that. Maybe your system reports
fighting for cache lines or whatever is going on behind the scenes as
system time rather than user time, or something.
It would be a little easier to figure out what was going on there if
the log included the pid (%p) so we can see if it is the same process
doing a bunch of consecutive sleeps, or a bunch of different
processes. Also, logging the millisecond (%m rather than %t) would be
helpful.
But the way that the point of contention jumps around a lot points to
a scheduler issue rather than a postgres-specific issue. A backend
gets pre-empted while holding a spinlock, and then the kernel is
resistant to rescheduling it even though all other processes are piled
up behind it. But again, that theory would lead to more log lines
than we see, I would think.
Anyway, pgbouncer might help by ensuring that a connection gets
pre-empted by pgbouncer at a point where it has no locks, rather than
by the kernel at a point where it does hold locks.
Any chance you could try an older kernel and see if that reduces the problem?
One thing that does stand out is that it looks like partitioned hash
tables in dynahash.c could benefit by having their freelist
partitioned as well, assuming we can give up the hash_get_num_entries
function.
Cheers,
Jeff