Re: High SYS CPU - need advise

On Thu, Nov 15, 2012 at 2:44 PM, Vlad <marchenko@gmail.com> wrote:
>
>>
>> yeah.  ok, nest steps:
>> *) can you confirm that postgres process is using high cpu (according
>> to top) during stall time
>
>
> yes, CPU is spread across a lot of postmasters
>
>   PID USER      PR  NI  VIRT  RES  SHR S %CPU %MEM    TIME+  COMMAND
> 29863 pgsql     20   0 3636m 102m  36m R 19.1  0.3   0:01.33 postmaster
> 30277 pgsql     20   0 3645m 111m  37m R 16.8  0.3   0:01.27 postmaster
> 11966 pgsql     20   0 3568m  22m  15m R 15.1  0.1   0:00.66 postmaster
>  8073 pgsql     20   0 3602m  60m  26m S 13.6  0.2   0:00.77 postmaster
> 29780 pgsql     20   0 3646m 115m  43m R 13.6  0.4   0:01.13 postmaster
> 11865 pgsql     20   0 3606m  61m  23m S 12.8  0.2   0:01.87 postmaster
> 29379 pgsql     20   0 3603m  70m  30m R 12.8  0.2   0:00.80 postmaster
> 29727 pgsql     20   0 3616m  77m  31m R 12.5  0.2   0:00.81 postmaster
>
>>
>> *) if, so, please strace that process and save some of the log
>
>
> https://dl.dropbox.com/u/109778/stall_postmaster.log

ok, excellent.   reviewing the log, this immediately caught my eye:

recvfrom(8, "\27\3\1\0@", 5, 0, NULL, NULL) = 5
recvfrom(8, "\327\327\nl\231LD\211\346\243@WW\254\244\363C\326\247\341\177\255\263~\327HDv-\3466\353"...,
64, 0, NULL, NULL) = 64
select(0, NULL, NULL, NULL, {0, 1000})  = 0 (Timeout)
select(0, NULL, NULL, NULL, {0, 1000})  = 0 (Timeout)
select(0, NULL, NULL, NULL, {0, 1000})  = 0 (Timeout)
select(0, NULL, NULL, NULL, {0, 2000})  = 0 (Timeout)
select(0, NULL, NULL, NULL, {0, 3000})  = 0 (Timeout)
select(0, NULL, NULL, NULL, {0, 4000})  = 0 (Timeout)
select(0, NULL, NULL, NULL, {0, 6000})  = 0 (Timeout)
select(0, NULL, NULL, NULL, {0, 7000})  = 0 (Timeout)
select(0, NULL, NULL, NULL, {0, 8000})  = 0 (Timeout)
select(0, NULL, NULL, NULL, {0, 9000})  = 0 (Timeout)
semop(41713721, {{2, 1, 0}}, 1)         = 0
lseek(295, 0, SEEK_END)                 = 0
lseek(296, 0, SEEK_END)                 = 8192

this is definitely pointing to spinlock issue. see: slock.c what you
are seeing here is a backend getting caught in a spin loop via a stuck
spinlock. 0-9 = 10 times.  did you by any chance check the logs? did
any backends restart? we are looking for this:

        elog(PANIC, "stuck spinlock (%p) detected at %s:%d",
                 lock, file, line);

Anything else going on in the log?   The way to enable locks status is
via LWLOCK_STATS macro.  But before doing any thing plz check logs for
error/panic.

merlin