Thread: "explain analyse" much slower than actual query
Dear All,
I want to find all of the msg_ids from "messages" that are not in table
"part_tsearch", where both tables are large but the result of the
query is normally small, and often empty. To 'protect' the application
against the unusual case where the result of the query is large I have
added a limit clause:
select msg_id from messages where msg_id not in (select msg_id from part_tsearch) limit 10;
Currently there are about 30,000 rows in each table and about 500
rows in the result of the (un-limit-ed) query. So it is unusual in
the sense that the size of the result is relatively large and the limit
clause will take effect. Both tables are indexed by msg_id.
This was taking longer than I expected, so I decided to
explain-analyse it. However, when I run it under explain-analyse,
it takes even longer than before:
decimail=> select msg_id from messages where msg_id not in (select msg_id from part_tsearch) limit 10;
msg_id
--------
67894
67809
52548
67745
67538
67540
67329
67246
67235
67140
(10 rows)
(that takes about 2 seconds)
decimail=> explain analyse select msg_id from messages where msg_id not in (select msg_id from part_tsearch) limit 10;
QUERY PLAN
----------------------------------------------------------------------------------------------------------------------------------------
Limit (cost=4301.99..10534.34 rows=10 width=4) (actual time=6677.791..72417.068 rows=10 loops=1)
-> Seq Scan on messages (cost=4301.99..11966058.86 rows=19193 width=4) (actual time=6677.725..72416.427 rows=10
loops=1)
Filter: (NOT (subplan))
SubPlan
-> Materialize (cost=4301.99..4830.07 rows=37908 width=4) (actual time=0.097..39.494 rows=862 loops=903)
-> Seq Scan on part_tsearch (cost=0.00..4115.08 rows=37908 width=4) (actual time=0.104..1679.258
rows=37901loops=1)
Total runtime: 72424.066 ms
(7 rows)
As I increase the limit the runtime increases as follows:
limit normal runtime explain-anlyse runtime
10 2 77
20 5 309
40 12 807
80 88
160 149
320 1016
I was not patient enough to wait for the remaining explain-analyse results,
but I feel that there is a linear slowdown of about 60x between the raw
query and the explain-analyse version.
In general, for other queries, explain-analyse reports runtimes that agree
with the runtimes of the actual queries.
But the peculiar behaviour of explain-analyse is really a distraction from
the fact that the query is slow, especially when the limit value is large.
The system seems to be largely CPU-bound during these long run-times.
The query plan reported by explain-analyse is the same in each case. How
many times is it actually doing the seq-scan on part_tsearch? I see
that the rows value reported for "Materialize" is rather different in the
planned and actual numbers. What is this telling me? I analysed the
tables immediately before starting on this.
I was hoping that it would be implemented using some sort of index scan on
the two tables, maybe something involing bitmaps. Is there something that
I can do to the query, or to my indexes, to make this happen?
I tried using "except" rather than "not in <subquery>"; this isn't
exactly identical as "except" is required to return sorted results, which
I don't need; when the limit clause is in effect I don't care
which of the possible ids are returned and I never care about the order.
In this case the runtimes are as follows:
limit normal runtime explain-anlyse runtime
10 15 54
20 15 55
40 19 94
80 9 55
160 20 68
320 10 70
Note that again explain-analyse is slower than the normal runtime, but now
by a factor of about 5 rather than the previous factor of about 60.
Basically, the query runtimes are now essentially constant; I imagine that
they would be flatter if the machine wasn't also running other processes.
The query plan shows that it is doing a sequential pass over each of the
tables, sorting and then doing a set-op - exactly as expected and OK
for large limits, but not for small limits.
I feel that it should be possible to do this in miliseconds, not seconds,
using the existing indexes.
This is with Postgresql 8.1 on Debian GNU/Linux.
(BTW, this is for Decimail, my postgresql-based IMAP mail server. I have
recently added tsearch2-based searching. It is still somewhat experimental
but has never lost any mail. If you're interested, have a look at
http://decimail.org/.)
Many thanks for any advice,
Phil.
(You are welcome to CC: me in any replies)
"Phil Endecott" <spam_from_postgresql_general@chezphil.org> writes:
> I was not patient enough to wait for the remaining explain-analyse results,
> but I feel that there is a linear slowdown of about 60x between the raw
> query and the explain-analyse version.
Slow gettimeofday() ... fairly common on desktop-grade PC hardware :-(.
You seem to have a particularly bad case of it, though, as extrapolating
from your numbers suggests the overhead is something like 20
microseconds per clock reading; the other reporters we've heard from
seemed to get around 1 to 5 usec IIRC. A lot of PCs still use clock
chips that were designed back when multiple microseconds to read the
clock wasn't unreasonable, but with CPU speeds in the GHz range this is
just sucky hardware. It shows up on this example because most of the
node entry/exits are for the Materialize node, which can return the next
row from its internal array in about no time flat, so the clock readings
represent huge percentage overhead.
> But the peculiar behaviour of explain-analyse is really a distraction from
> the fact that the query is slow, especially when the limit value is large.
You need a "hashed subplan" for NOT IN to work reasonably fast. The
fact you're not getting one suggests you either have to raise work_mem,
or you're using some weird datatype that doesn't support hashing.
regards, tom lane
Thanks for the quick reply Tom.
Tom Lane wrote:
>"Phil Endecott" <spam_from_postgresql_general ( at ) chezphil ( dot ) org> writes:
>> I was not patient enough to wait for the remaining explain-analyse results,
>> but I feel that there is a linear slowdown of about 60x between the raw
>> query and the explain-analyse version.
>
> Slow gettimeofday() ... fairly common on desktop-grade PC hardware :-(.
It's actually a virtual machine, and I seem to recall reading something about the
virtualised gettimeofday() being slow. OK, that explains it. Thanks.
>> But the peculiar behaviour of explain-analyse is really a distraction from
>> the fact that the query is slow, especially when the limit value is large.
>
> You need a "hashed subplan" for NOT IN to work reasonably fast. The
> fact you're not getting one suggests you either have to raise work_mem,
> or you're using some weird datatype that doesn't support hashing.
It's an int, and yes, increasing work_mem makes it use a hashed subplan:
QUERY PLAN
----------------------------------------------------------------------------------------------------------------------------------
Limit (cost=4209.76..4213.61 rows=10 width=4) (actual time=5432.840..5461.518 rows=10 loops=1)
-> Seq Scan on messages (cost=4209.76..11608.23 rows=19218 width=4) (actual time=5432.776..5460.859 rows=10
loops=1)
Filter: (NOT (hashed subplan))
SubPlan
-> Seq Scan on part_tsearch (cost=0.00..4115.01 rows=37901 width=4) (actual time=0.390..2984.783
rows=37907loops=1)
Total runtime: 5468.817 ms
So presumably work_mem must be greater than some function of the size of the
table in the subquery. Is there some way to work that out? This (virtual)
machine doesn't have an enormous amount of RAM so I like to keep settings
like this "as high as necessary but no higher".
If I understand it correctly, it is still doing a sequential scan on
part_tsearch that does not terminate early due to the limit clause. So
I'm still seeing run times that are rather worse than I think should be
possible. Can it not step through the indexes in the way that it does
for a Merge Join until it has got enough results to satisfy the limit,
and then terminate?
Thanks,
Phil.
"Phil Endecott" <spam_from_postgresql_general@chezphil.org> writes:
> If I understand it correctly, it is still doing a sequential scan on
> part_tsearch that does not terminate early due to the limit clause. So
> I'm still seeing run times that are rather worse than I think should be
> possible. Can it not step through the indexes in the way that it does
> for a Merge Join until it has got enough results to satisfy the limit,
> and then terminate?
Nope, there is not that much intelligence about NOT IN.
You could possibly manually rewrite the thing as a LEFT JOIN
with a WHERE inner-join-key IS NULL clause. This would probably
lose if most of the outer relation's rows join to many inner rows,
though.
regards, tom lane