[GENERAL] 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=37901 loops=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 277 20 5309 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 955 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) ---(end of broadcast)--- TIP 5: don't forget to increase your free space map settings
Re: [GENERAL] explain analyse much slower than actual query
Phil Endecott [EMAIL PROTECTED] 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 ---(end of broadcast)--- TIP 6: explain analyze is your friend
Re: [GENERAL] explain analyse much slower than actual query
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=37907 loops=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. ---(end of broadcast)--- TIP 9: In versions below 8.0, the planner will ignore your desire to choose an index scan if your joining column's datatypes do not match
Re: [GENERAL] explain analyse much slower than actual query
Phil Endecott [EMAIL PROTECTED] 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 ---(end of broadcast)--- TIP 1: if posting/reading through Usenet, please send an appropriate subscribe-nomail command to [EMAIL PROTECTED] so that your message can get through to the mailing list cleanly
