Обсуждение: explain analyze reports that my queries are fast but they run very slowly

Le 2012-12-27 à 12:10, Nikolas Everett a écrit :

> We just upgraded from 8.3 to 9.1 and we're seeing some performance problems.  When we EXPLAIN ANALYZE our queries the
explainresult claim that the queries are reasonably fast but the wall clock time is way way longer.  Does anyone know
whythis might happen? 
>
> Like so:
> db=>\timing
> db=>EXPLAIN ANALYZE SELECT max(id) FROM foo WHERE blah_id = 1209123;
>
> The plan is sensible.  The estimates are sensible.  The actual DB time reads like it is very sensible.  But the wall
clocktime is like 11 seconds and the \timing report confirms it. 
>
> Any ideas?

Could you post the actual plans? On both versions? That would help a lot.

Also, http://explain.depesz.com/ helps readability.

Bye,
François

On 27/12/12 17:21, François Beausoleil wrote:
>
> Le 2012-12-27 à 12:10, Nikolas Everett a écrit :
>
>> We just upgraded from 8.3 to 9.1 and we're seeing some performance problems.  When we EXPLAIN ANALYZE our queries
theexplain result claim that the queries are reasonably fast but the wall clock time is way way longer.  Does anyone
knowwhy this might happen? 
>>

Is it possible you missed an optimisation setting in the migration
process? I made that mistake, and much later found performance was
somewhat degraded (but surprisingly not as much as I'd expected) by my
having failed to set effective_cache_size.

Also, if you just did a dump/restore, it might help to run Analyse once
(it seems that Analyse is normally run automatically via vacuum, but the
first time you insert the data, it may not happen).

A side-effect of Analyse it that it will pull all the tables into the OS
memory cache (or try to) - which may give significantly faster results
(try running the same query twice in succession: it's often 5x faster
the 2nd time).

HTH,

Richard

Nikolas Everett <nik9000@gmail.com> writes:
> We just upgraded from 8.3 to 9.1 and we're seeing some performance
> problems.  When we EXPLAIN ANALYZE our queries the explain result claim
> that the queries are reasonably fast but the wall clock time is way way
> longer.  Does anyone know why this might happen?

> Like so:
> db=>\timing
> db=>EXPLAIN ANALYZE SELECT max(id) FROM foo WHERE blah_id = 1209123;

> The plan is sensible.  The estimates are sensible.  The actual DB time
> reads like it is very sensible.  But the wall clock time is like 11 seconds
> and the \timing report confirms it.

Seems like the extra time would have to be in parsing/planning, or in
waiting to acquire AccessShareLock on the table.  It's hard to believe
the former for such a simple query, unless the table has got thousands
of indexes or something silly like that.  Lock waits are surely possible
if there is something else contending for exclusive lock on the table,
but it's hard to see how the wait time would be so consistent.

BTW, the explain.depesz.com link you posted clearly does not correspond
to the above query (it's not doing a MAX), so another possibility is
confusion about what query is really causing trouble.  We've seen people
remove essential details before while trying to anonymize their query.

            regards, tom lane

Nikolas Everett <nik9000@gmail.com> writes:
> After more digging it looks like this table has an inordinate number
> of indices (10 ish).

10 doesn't sound like a lot.

> There a whole buch of conditional indicies for other
> columns that we're not checking.  The particular column that is causing us
> trouble exists in both a regular (con_id) and a composite index (con_id,
> somthing_else).

You're not being at all clear here.  Are you trying to say that only
queries involving "WHERE col = constant" for a particular column seem
to be slow?  If so, maybe the column has a weird datatype or a wildly
out of line statistics target?  (Still hard to see how you get to 11-ish
seconds in planning, though.)

One thing you might do is watch the backend process in "top" or local
equivalent, and see if it's spending most of the 11 seconds sleeping, or
accumulating CPU time, or accumulating I/O.  That info would eliminate
a lot of possibilities.

            regards, tom lane

Nikolas Everett <nik9000@gmail.com> writes:
> We straced the backend during the explain and it looked like the open
> commands were taking several seconds each.

Kind of makes me wonder if you have a whole lot of tables ("whole lot"
in this context probably means tens of thousands) and are storing the
database on a filesystem that doesn't scale well to lots of files in one
directory.  If that's the explanation, the reason the 8.3 installation
was okay was likely that it was stored on a more modern filesystem.

BTW, please keep the list cc'd on replies.

            regards, tom lane

Nikolas Everett <nik9000@gmail.com> writes:
> On Thu, Dec 27, 2012 at 4:33 PM, Tom Lane <tgl@sss.pgh.pa.us> wrote:
>> Nikolas Everett <nik9000@gmail.com> writes:
>>> We straced the backend during the explain and it looked like the open
>>> commands were taking several seconds each.

>> Kind of makes me wonder if you have a whole lot of tables ("whole lot"
>> in this context probably means tens of thousands) and are storing the
>> database on a filesystem that doesn't scale well to lots of files in one
>> directory.  If that's the explanation, the reason the 8.3 installation
>> was okay was likely that it was stored on a more modern filesystem.

> We have 1897 files for our largest database which really isn't a whole lot.

OK...

>  The old servers were EXT3 over FC to a NetApp running RHEL5 PPC.  The new
> servers are on NFS to the same NetApp running RHEL5 Intel.

Now I'm wondering about network glitches or NFS configuration problems.
This is a bit outside my expertise unfortunately, but it seems clear
that your performance issue is somewhere in that area.

            regards, tom lane