Message-ID: <46A0EE6B.6040707@drivefaster.net>
Date: Fri, 20 Jul 2007 11:18:35 -0600
From: Dan Harris <fbsd@drivefaster.net>
User-Agent: Thunderbird 2.0.0.5 (Macintosh/20070716)
MIME-Version: 1.0
To: PostgreSQL Performance <pgsql-performance@postgresql.org>
Subject: Re: Simple query showing 270 hours of CPU time
References: <46A0D836.5090806@drivefaster.net>
 <10727.1184949725@sss.pgh.pa.us>
In-Reply-To: <10727.1184949725@sss.pgh.pa.us>
Content-Type: text/plain; charset=ISO-8859-1; format=flowed
Content-Transfer-Encoding: 7bit

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