Re: Simple query showing 270 hours of CPU time

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. I think you're looking at a backend that has
simply executed one heckuva lot of queries on behalf of its client,
and that inquiring into what the client thinks it's doing might be the
first order of business.

regards, tom lane