To: Dan Harris <fbsd@drivefaster.net>
cc: PostgreSQL Performance <pgsql-performance@postgresql.org>
Subject: Re: Simple query showing 270 hours of CPU time 
In-reply-to: <46A0D836.5090806@drivefaster.net> 
References: <46A0D836.5090806@drivefaster.net>
Comments: In-reply-to Dan Harris <fbsd@drivefaster.net>
	message dated "Fri, 20 Jul 2007 09:43:50 -0600"
Date: Fri, 20 Jul 2007 12:42:05 -0400
Message-ID: <10727.1184949725@sss.pgh.pa.us>
From: Tom Lane <tgl@sss.pgh.pa.us>

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.  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