Re: Simple query showing 270 hours of CPU time

[Dan Harris <fbsd(at)drivefaster(dot)net>]

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