Message-ID: <4C4D5220.9010101@postnewspapers.com.au>
Date: Mon, 26 Jul 2010 17:15:12 +0800
From: Craig Ringer <craig@postnewspapers.com.au>
User-Agent: Mozilla/5.0 (X11; U; Linux i686; en-US;
	rv:1.9.1.9) Gecko/20100423 Lightning/1.0b1 Thunderbird/3.0.4
MIME-Version: 1.0
To: =?UTF-8?B?UGlvdHIgR2FzaWTFgm8=?= <quaker@barbara.eu.org>
CC: pgsql-performance@postgresql.org
Subject: Re: Big difference in time returned by EXPLAIN ANALYZE
	SELECT ... AND 	SELECT ...
References: <AANLkTinHPkEDijSHbxY3KxygO2SWy6XMPLvn=CvnWdG8@mail.gmail.com>
In-Reply-To: <AANLkTinHPkEDijSHbxY3KxygO2SWy6XMPLvn=CvnWdG8@mail.gmail.com>
Content-Type: text/plain; charset=UTF-8
Content-Transfer-Encoding: 8bit

On 26/07/10 16:35, Piotr Gasidło wrote:
> Hello,
> 
> I've found strange problem in my database (8.4.4, but also 9.0beta3,
> default postgresql.conf, shared_buffers raised to 256MB).
> 
> EXPLAIN ANALYZE SELECT ...
> Total runtime: 4.782 ms
> Time: 25,970 ms
> 
> SELECT ...
> ...
> (21 rows)
> 
> Time: 23,042 ms
> 
> Test done in psql connected by socket to server (same host, using
> \timing to get runtime).
> 
> Does big difference in "Total runtime" and "Time" is normal?

Given that EXPLAIN ANALYZE doesn't transfer large rowsets to the client,
it can't really be time taken to transfer the data, which is the usual
difference between 'explain analyze' timings and psql client-side timings.

Given that, I'm wondering if the difference in this case is planning
time. I can't really imagine the query planner taking 20 seconds (!!) to
run, though, no matter how horrifyingly complicated the query and table
structure were, unless there was something going wrong.

Another possibility, then, is that for some reason queries are being
delayed from starting or delayed before results are being returned, so
the server completes them in a short amount of time but it takes a while
for psql to find out they're finished.

In your position, at this point I'd be doing things like hooking a
debugger up to the postgres backend and interrupting its execution
periodically to see what it's up to while this query runs. I'd also be
using wireshark to look at network activity to see if there were any
clues there. I'd be using "top", "vmstat" and "iostat" to examine
system-level load if it was practical to leave the system otherwise
idle, so I could see if CPU/memory/disk were in demand, and for how long.

--
Craig Ringer