Re: Simple query showing 270 hours of CPU time

Tom Lane wrote:
> Dan Harris <fbsd@drivefaster.net> writes:
>> Here's the strace summary as run for a few second sample:
>
>> % time     seconds  usecs/call     calls    errors syscall
>> ------ ----------- ----------- --------- --------- ----------------
>>   97.25    0.671629          92      7272           semop
>>    1.76    0.012171         406        30           recvfrom
>>    0.57    0.003960          66        60           gettimeofday
>>    0.36    0.002512          28        90           sendto
>>    0.05    0.000317          10        32           lseek
>>    0.01    0.000049           1        48           select
>> ------ ----------- ----------- --------- --------- ----------------
>> 100.00    0.690638                  7532           total
>
>> Here's the query:
>> select id from eventkeywords where word = '00003322'
>
> How sure are you that (a) that's really what it's doing and (b) you are
> not observing multiple executions of the query?  There are no recvfrom
> calls in the inner loops of the backend AFAIR, so this looks to me like
> the execution of 30 different queries.  The number of semops is
> distressingly high, but that's a contention issue not an
> amount-of-runtime issue.

You were absolutely right.  This is one connection that is doing a whole lot of
( slow ) queries.  I jumped the gun on this and assumed it was a single query
taking this long.  Sorry to waste time and bandwidth.

Since you mentioned the number of semops is distressingly high, does this
indicate a tuning problem?  The machine has 64GB of RAM and as far as I can tell
about 63GB is all cache.  I wonder if this is a clue to an undervalued
memory-related setting somewhere?

-Dan