Re: Simple query showing 270 hours of CPU time

Tom Lane wrote:
> Dan Harris <fbsd(at)drivefaster(dot)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