Обсуждение: Very slow queries w/ NOT IN preparation (seems like a bug, test case)
Hi all, Here is my environment information: # select version(); version ------------------------------------------------------------------------------------------------ PostgreSQL 8.3.4 on i686-pc-linux-gnu, compiled by GCC gcc (GCC) 4.2.4 (Ubuntu 4.2.4-1ubuntu3) (1 row) I've faced strange parser (or may be planner) behaviour. When I do "EXPLAIN SELECT 1 FROM table1 WHERE table1_id IN (...~2000 ids here...);" it works as fast as I expect (50 ms). But when I rewrite it using NOT IN "EXPLAIN SELECT 1 FROM table1 WHERE table1_id NOT IN (...~2000 ids here...);" it gets much more slower (34537 ms). I've done a test case (see attachement) so you can reproduce the situation (correct PSQL parameter in the begining of the script). Another thing is that I set my statement_timeout to 20s and it seems like postgres just ignore this. Is it a bug and why it happens if not? Could someone explain what can I do now to make my NOT IN queries work fast, please? -- Regards, Sergey Konoplev -- PostgreSQL articles in english & russian http://gray-hemp.blogspot.com/search/label/postgresql/
Вложения
Sergey Konoplev wrote: > > I've faced strange parser (or may be planner) behaviour. When I do > "EXPLAIN SELECT 1 FROM table1 WHERE table1_id IN (...~2000 ids > here...);" it works as fast as I expect (50 ms). But when I rewrite it > using NOT IN "EXPLAIN SELECT 1 FROM table1 WHERE table1_id NOT IN > (...~2000 ids here...);" it gets much more slower (34537 ms). Can you post the EXPLAIN ANALYSE output from your NOT IN query? -- Richard Huxton Archonet Ltd
Re: Very slow queries w/ NOT IN preparation (seems like a bug, test case)
От
"Sergey Konoplev"
Дата:
> > Can you post the EXPLAIN ANALYSE output from your NOT IN query? > Seq Scan on table1 (cost=0.00..12648.25 rows=3351 width=0) (actual time=0.054..140.596 rows=5000 loops=1) Filter: (table1_id <> ALL ('{123456789000, ... plus 1999 ids'::bigint[])) Total runtime: 142.303 ms (3 rows) But actual (real) time of running "EXPLAIN SELECT 1 FROM table1 WHERE table1_id NOT IN > (...~2000 ids here...);" is 2000 ids: 34102 ms -- Regards, Sergey Konoplev -- PostgreSQL articles in english & russian http://gray-hemp.blogspot.com/search/label/postgresql/
Sergey Konoplev wrote: >> Can you post the EXPLAIN ANALYSE output from your NOT IN query? >> > > Seq Scan on table1 (cost=0.00..12648.25 rows=3351 width=0) (actual > time=0.054..140.596 rows=5000 loops=1) > Filter: (table1_id <> ALL ('{123456789000, ... plus 1999 ids'::bigint[])) > Total runtime: 142.303 ms > (3 rows) > > But actual (real) time of running "EXPLAIN SELECT 1 FROM table1 WHERE > table1_id NOT IN > (...~2000 ids here...);" is > > 2000 ids: 34102 ms I've never heard of EXPLAIN ANALYSE being *faster* than the actual query, it's usually slower due to all the timing calls. The only thing it doesn't do is actually send the results over the connection to the client. In your case, you're not actually selecting any columns, so that can't be it. Are you sure there's nothing subtly different about the slow query when compared with the explain analyse? -- Richard Huxton Archonet Ltd
Richard Huxton <dev@archonet.com> writes: > I've never heard of EXPLAIN ANALYSE being *faster* than the actual > query, it's usually slower due to all the timing calls. The only thing > it doesn't do is actually send the results over the connection to the > client. In your case, you're not actually selecting any columns, so that > can't be it. If I'm reading it right the query returns 5000 instances of "1". So there's definitely scope for the client side to pose a performance issue. regards, tom lane
Tom Lane wrote: > Richard Huxton <dev@archonet.com> writes: >> I've never heard of EXPLAIN ANALYSE being *faster* than the actual >> query, it's usually slower due to all the timing calls. The only thing >> it doesn't do is actually send the results over the connection to the >> client. In your case, you're not actually selecting any columns, so that >> can't be it. > > If I'm reading it right the query returns 5000 instances of "1". So > there's definitely scope for the client side to pose a performance > issue. But 34s for 5000 single values? Surely you'd loads of queries slow, not just this "not in" query. -- Richard Huxton Archonet Ltd
Re: Very slow queries w/ NOT IN preparation (seems like a bug, test case)
От
"Sergey Konoplev"
Дата:
> I've never heard of EXPLAIN ANALYSE being *faster* than the actual > query, it's usually slower due to all the timing calls. The only thing > it doesn't do is actually send the results over the connection to the > client. In your case, you're not actually selecting any columns, so that > can't be it. > > Are you sure there's nothing subtly different about the slow query when > compared with the explain analyse? > Sorry, but it seems like you didn't understand the problem. The thing is that EXPLAIN (without ANALYZE) ... NOT IN (a lot of values) works very slow but EXPLAIN (without ANALYZE) ... IN (a lot of values) works fast. Just run the test script I attached. -- Regards, Sergey Konoplev -- PostgreSQL articles in english & russian http://gray-hemp.blogspot.com/search/label/postgresql/
"Sergey Konoplev" <gray.ru@gmail.com> writes: > I've faced strange parser (or may be planner) behaviour. When I do > "EXPLAIN SELECT 1 FROM table1 WHERE table1_id IN (...~2000 ids > here...);" it works as fast as I expect (50 ms). But when I rewrite it > using NOT IN "EXPLAIN SELECT 1 FROM table1 WHERE table1_id NOT IN > (...~2000 ids here...);" it gets much more slower (34537 ms). FWIW, I can't reproduce your problem here. The output from your script looks like this: ------------------------------------------ Testing EXPLAIN w/ NOT IN... ------------------------------------------ 100 ids: 16 ms 200 ids: 17 ms 300 ids: 17 ms 400 ids: 18 ms 500 ids: 19 ms 600 ids: 20 ms 700 ids: 21 ms 800 ids: 22 ms 900 ids: 23 ms 1000 ids: 24 ms 1100 ids: 25 ms 1200 ids: 25 ms 1300 ids: 26 ms 1400 ids: 28 ms 1500 ids: 28 ms 1600 ids: 29 ms 1700 ids: 30 ms 1800 ids: 31 ms 1900 ids: 32 ms 2000 ids: 33 ms ------------------------------------------ Testing EXPLAIN w/ IN... ------------------------------------------ 100 ids: 16 ms 200 ids: 17 ms 300 ids: 18 ms 400 ids: 19 ms 500 ids: 20 ms 600 ids: 21 ms 700 ids: 22 ms 800 ids: 23 ms 900 ids: 24 ms 1000 ids: 25 ms 1100 ids: 26 ms 1200 ids: 27 ms 1300 ids: 29 ms 1400 ids: 29 ms 1500 ids: 31 ms 1600 ids: 32 ms 1700 ids: 32 ms 1800 ids: 34 ms 1900 ids: 35 ms 2000 ids: 36 ms regards, tom lane
Re: Very slow queries w/ NOT IN preparation (seems like a bug, test case)
От
"Sergey Konoplev"
Дата:
>> I've never heard of EXPLAIN ANALYSE being *faster* than the actual >> query, it's usually slower due to all the timing calls. The only thing >> it doesn't do is actually send the results over the connection to the >> client. In your case, you're not actually selecting any columns, so that >> can't be it. > > If I'm reading it right the query returns 5000 instances of "1". So > there's definitely scope for the client side to pose a performance > issue. > Query doesn't return 5000 instances of "1". It returns just few rows of EXPLAIN output cos I do EXPLAIN (without ANALYZE) ... NOT IN (a lot of values) (pay attention to NOT IN) And it works extremly slow oposite to EXPLAIN (without ANALYZE) ... IN (a lot of values) which works fast. That is the main problem. Another thing is that even I set statement_timeout to 20s the query with NOT IN finishes working after 30+ seconds without "canceled by statement timeout" error. -- Regards, Sergey Konoplev -- PostgreSQL articles in english & russian http://gray-hemp.blogspot.com/search/label/postgresql/
Sergey Konoplev wrote: >> I've never heard of EXPLAIN ANALYSE being *faster* than the actual >> query, it's usually slower due to all the timing calls. The only thing >> it doesn't do is actually send the results over the connection to the >> client. In your case, you're not actually selecting any columns, so that >> can't be it. >> >> Are you sure there's nothing subtly different about the slow query when >> compared with the explain analyse? >> > > Sorry, but it seems like you didn't understand the problem. > > The thing is that > > EXPLAIN (without ANALYZE) ... NOT IN (a lot of values) > > works very slow but > > EXPLAIN (without ANALYZE) ... IN (a lot of values) > > works fast. It's the EXPLAIN that you're finding slow? Hold on... not seeing it here. ------------------------------------------ Testing EXPLAIN w/ NOT IN... ------------------------------------------ 100 ids: 95 ms 200 ids: 15 ms 300 ids: 17 ms 400 ids: 19 ms 500 ids: 20 ms 600 ids: 21 ms 700 ids: 23 ms 800 ids: 27 ms 900 ids: 26 ms 1000 ids: 27 ms 1100 ids: 29 ms 1200 ids: 30 ms 1300 ids: 33 ms 1400 ids: 45 ms 1500 ids: 35 ms 1600 ids: 37 ms 1700 ids: 39 ms 1800 ids: 40 ms 1900 ids: 42 ms 2000 ids: 44 ms ------------------------------------------ Testing EXPLAIN w/ IN... ------------------------------------------ 100 ids: 15 ms 200 ids: 16 ms 300 ids: 17 ms 400 ids: 20 ms 500 ids: 21 ms 600 ids: 23 ms 700 ids: 25 ms 800 ids: 27 ms 900 ids: 28 ms 1000 ids: 33 ms 1100 ids: 32 ms 1200 ids: 34 ms 1300 ids: 35 ms 1400 ids: 38 ms 1500 ids: 39 ms 1600 ids: 41 ms 1700 ids: 43 ms 1800 ids: 48 ms 1900 ids: 47 ms 2000 ids: 48 ms -- Richard Huxton Archonet Ltd
Sergey Konoplev wrote: > > Another thing is that even I set statement_timeout to 20s the query > with NOT IN finishes working after 30+ seconds without "canceled by > statement timeout" error. Maybe it's not taking that long to execute the query then. Maybe something to do with process startup is delaying things - could you tweak the test script to send the outputs of the explain somewhere other than /dev/null? That way we'd know if there was a big difference between query-execution-time and process-execution-time. -- Richard Huxton Archonet Ltd
Re: Very slow queries w/ NOT IN preparation (seems like a bug, test case)
От
"Helio Campos Mello de Andrade"
Дата:
Hi Sergey,
- It's just guess but it could be the range of a SERIAL TYPE that is generating this behavior.
An example is:
Knowing that "table1_id" is primary a key ( the table will be ordered by it ) and that a serial range is 2147483647 long.
(a) you use 2000 different numbers of this range the planner will search for the 2000 numbers in yours 5000 rows in an ordered way and it will stop when the searched number can't be found any more. It will make, in the worst case, 2000*log(5000) tests ( aprox: 24.575 ).
(b) If you use "~2000" different numbers and the system understands that you want that the rest of the range ( 2147481647 numbers ) have to be searched and it will cost 263.876.368.186 tests.
--
Helio Campos Mello de Andrade
- It's just guess but it could be the range of a SERIAL TYPE that is generating this behavior.
An example is:
Knowing that "table1_id" is primary a key ( the table will be ordered by it ) and that a serial range is 2147483647 long.
(a) you use 2000 different numbers of this range the planner will search for the 2000 numbers in yours 5000 rows in an ordered way and it will stop when the searched number can't be found any more. It will make, in the worst case, 2000*log(5000) tests ( aprox: 24.575 ).
(b) If you use "~2000" different numbers and the system understands that you want that the rest of the range ( 2147481647 numbers ) have to be searched and it will cost 263.876.368.186 tests.
On Tue, Nov 11, 2008 at 12:20 PM, Richard Huxton <dev@archonet.com> wrote:
Sergey Konoplev wrote:Maybe it's not taking that long to execute the query then.
>
> Another thing is that even I set statement_timeout to 20s the query
> with NOT IN finishes working after 30+ seconds without "canceled by
> statement timeout" error.
Maybe something to do with process startup is delaying things - could
you tweak the test script to send the outputs of the explain somewhere
other than /dev/null? That way we'd know if there was a big difference
between query-execution-time and process-execution-time.
--
Richard Huxton
Archonet Ltd
--
Sent via pgsql-general mailing list (pgsql-general@postgresql.org)
To make changes to your subscription:
http://www.postgresql.org/mailpref/pgsql-general
--
Helio Campos Mello de Andrade
Sergey Konoplev wrote: >> Maybe something to do with process startup is delaying things - could >> you tweak the test script to send the outputs of the explain somewhere >> other than /dev/null? That way we'd know if there was a big difference >> between query-execution-time and process-execution-time. >> > > I did \timing and run my query in console. You can find the result in > attachement. Will it be enough? Very strange. The explain runtime is 3.1 seconds, but \timing shows 37.8 seconds before it returns. And it only does this for the NOT IN version of the query, but the IN version seems OK. The two together make no sense to me. If you do the same again but "\o /dev/null" before the /timing, is it still slow? If not, what about "\o /tmp/results.txt"? That should rule out something strange with displaying a very long line (and I admit I'm reduced to wild guesses now). If you run it over the network, can you try running it directly on the server? Finally - did you compile this from source yourself, or is it installed via apt? I'm wondering whether you have an unusual version of a library linked in, and it's taking a long time to parse the query. Actually, we can test that. If you run the same query against an empty table, does it take more than a few milliseconds? -- Richard Huxton Archonet Ltd
Re: Very slow queries w/ NOT IN preparation (seems like a bug, test case)
От
"Sergey Konoplev"
Дата:
>> I did \timing and run my query in console. You can find the result in >> attachement. Will it be enough? > > Very strange. > > The explain runtime is 3.1 seconds, but \timing shows 37.8 seconds > before it returns. > > And it only does this for the NOT IN version of the query, but the IN > version seems OK. > Exactly. > The two together make no sense to me. > > If you do the same again but "\o /dev/null" before the /timing, is it > still slow? Unfortunaly it is. \o /dev/null Time: 38337,644 ms > If not, what about "\o /tmp/results.txt"? The same. Time: 37631,055 ms > That should rule out something strange with displaying a very long line > (and I admit I'm reduced to wild guesses now). I had that wild guess too and tested it after separating ID's list to 10 per line but result is the same. > If you run it over the network, can you try running it directly on the > server? I'm running it directly on my machine. But I tested it remotely too. > Finally - did you compile this from source yourself, or is it installed > via apt? I'm wondering whether you have an unusual version of a library > linked in, and it's taking a long time to parse the query. I've compiled it from sources. BTW, I tested it on both 8.3.3 and 8.3.4. > Actually, we can test that. If you run the same query against an empty > table, does it take more than a few milliseconds? Yes it does. Nothing has changed. -- Regards, Sergey Konoplev -- PostgreSQL articles in english & russian http://gray-hemp.blogspot.com/search/label/postgresql/
Sergey Konoplev wrote: > >> Finally - did you compile this from source yourself, or is it installed >> via apt? I'm wondering whether you have an unusual version of a library >> linked in, and it's taking a long time to parse the query. > > I've compiled it from sources. BTW, I tested it on both 8.3.3 and 8.3.4. Hmm - nothing unusual about your setup, I suppose? >> Actually, we can test that. If you run the same query against an empty >> table, does it take more than a few milliseconds? > > Yes it does. Nothing has changed. So it *must* be something in the planner/parser/explain code, and something specific to your setup. If you connect via psql and then (as root, in another terminal) do: ps auxw | grep postgres you should see the backend that corresponds to your psql connection. strace -p <pid> should then show system calls as they are executed (assuming you have it installed). Execute the explain, and see what is output. Mine flies past, but is composed almost entirely of "gettimeofday" calls (10,000 of them) apart from at the very end where we get some write and send/recv calls (to print the explain results). I've heard of some people having slow "gettimeofday" calls, but not on linux. On the other hand, that seems to be the main difference between strace output with "not in" compared to "in". -- Richard Huxton Archonet Ltd
"Sergey Konoplev" <gray.ru@gmail.com> writes: >> Finally - did you compile this from source yourself, or is it installed >> via apt? I'm wondering whether you have an unusual version of a library >> linked in, and it's taking a long time to parse the query. > I've compiled it from sources. BTW, I tested it on both 8.3.3 and 8.3.4. What configure options did you use, what locale/encoding are you using, what nondefault settings have you got in postgresql.conf? regards, tom lane
Richard Huxton <dev@archonet.com> writes: > If you connect via psql and then (as root, in another terminal) do: > ps auxw | grep postgres > you should see the backend that corresponds to your psql connection. > strace -p <pid> > should then show system calls as they are executed (assuming you have it > installed). Execute the explain, and see what is output. > Mine flies past, but is composed almost entirely of "gettimeofday" calls > (10,000 of them) apart from at the very end where we get some write and > send/recv calls (to print the explain results). I've heard of some > people having slow "gettimeofday" calls, but not on linux. On the other > hand, that seems to be the main difference between strace output with > "not in" compared to "in". AFAICT Sergey is complaining about the speed of EXPLAIN, *not* EXPLAIN ANALYZE. There'd only be a lot of gettimeofday calls in an EXPLAIN ANALYZE test. The whole thing doesn't make a lot of sense to me either. All the slowdown explanations I can think of would apply as much or more to the IN case... regards, tom lane
Por favor, no quiero seguir recibiendo mensajes Tom Lane escribió: > Richard Huxton <dev@archonet.com> writes: > >> If you connect via psql and then (as root, in another terminal) do: >> ps auxw | grep postgres >> you should see the backend that corresponds to your psql connection. >> strace -p <pid> >> should then show system calls as they are executed (assuming you have it >> installed). Execute the explain, and see what is output. >> > > >> Mine flies past, but is composed almost entirely of "gettimeofday" calls >> (10,000 of them) apart from at the very end where we get some write and >> send/recv calls (to print the explain results). I've heard of some >> people having slow "gettimeofday" calls, but not on linux. On the other >> hand, that seems to be the main difference between strace output with >> "not in" compared to "in". >> > > AFAICT Sergey is complaining about the speed of EXPLAIN, *not* EXPLAIN > ANALYZE. There'd only be a lot of gettimeofday calls in an EXPLAIN > ANALYZE test. > > The whole thing doesn't make a lot of sense to me either. All the > slowdown explanations I can think of would apply as much or more to the > IN case... > > regards, tom lane > > Aviso Legal Este mensaje puede contener informacion de interes solo para CVG Venalum. Solo esta permitida su copia, distribuciono uso a personas autorizadas. Si recibio este corre por error, por favor destruyalo. Eventualmentew los correoselectonicos pueden ser alterados. Al respecto, CVG Venalum no se hace responsable por los errores que pudieran afectaral mensaje original.
Вложения
Re: Very slow queries w/ NOT IN preparation (seems like a bug, test case)
От
"Sergey Konoplev"
Дата:
> What configure options did you use, what locale/encoding are you using, > what nondefault settings have you got in postgresql.conf? > > regards, tom lane You are right. I've found the odd thing (that completely drives me mad) in postgresql.conf. You are able to reproduce slow-not-in queries by switching constraint_exclusion to on in your postgresql.conf and running my test (which is attached to the first message). Looking forward to hearing from you. -- Regards, Sergey Konoplev -- PostgreSQL articles in english & russian http://gray-hemp.blogspot.com/search/label/postgresql/
Re: Very slow queries w/ NOT IN preparation (seems like a bug, test case)
От
"Sergey Konoplev"
Дата:
>> What configure options did you use, what locale/encoding are you using, >> what nondefault settings have you got in postgresql.conf? >> >> regards, tom lane > > You are right. I've found the odd thing (that completely drives me > mad) in postgresql.conf. > > You are able to reproduce slow-not-in queries by switching > constraint_exclusion to on in your postgresql.conf and running my test > (which is attached to the first message). > On more thing: If you do EXPLAIN SELECT 1 FROM table1 WHERE table1_id NOT IN (SELECT column1 FROM (VALUES (123),(456),(789),... a lot of IDs here...)_); it works as fast as with constraint_exclusion turned to off. -- Regards, Sergey Konoplev -- PostgreSQL articles in english & russian http://gray-hemp.blogspot.com/search/label/postgresql/
Sergey Konoplev wrote: >>> What configure options did you use, what locale/encoding are you using, >>> what nondefault settings have you got in postgresql.conf? >>> >>> regards, tom lane >> You are right. I've found the odd thing (that completely drives me >> mad) in postgresql.conf. >> >> You are able to reproduce slow-not-in queries by switching >> constraint_exclusion to on in your postgresql.conf and running my test >> (which is attached to the first message). > > On more thing: > > If you do > > EXPLAIN SELECT 1 FROM table1 WHERE table1_id NOT IN (SELECT column1 > FROM (VALUES (123),(456),(789),... a lot of IDs here...)_); > > it works as fast as with constraint_exclusion turned to off. Good detective work sir! I can reproduce the problem here with constraint_exclusion = on. Presumably what it's doing is looking to see if the target table has any relevant CHECK constraints for each of the 2000 values provided. It won't do so for the second example because it's not smart enough to look into the results of another select clause. Hmm - a little bit of grepping... backend/optimizer/util/plancat.c 566:relation_excluded_by_constraints(PlannerInfo *root called from backend/optimizer/path/allpaths.c You could presumably cache the results of the exclusion test, but that's only going to be relevant where you have the same value more than once. You could try to be smarter and evaluate all values in one go I suppose, or limit how many you'll test against. I'm over my head here though - you'll have to see what Tom says. The good news is that you can just issue "SET constraint_exclusion" before individual queries as a temporary workaround. -- Richard Huxton Archonet Ltd