Very slow queries w/ NOT IN preparation (seems like a bug, test case)

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

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

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

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

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.

On Tue, Nov 11, 2008 at 12:20 PM, Richard Huxton <dev@archonet.com> wrote:

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

--
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

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

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, distribucion o uso a personas autorizadas. Si recibio este corre por error, por favor destruyalo. Eventualmentew los correos electonicos pueden ser alterados. Al respecto, CVG Venalum no se hace responsable por los errores que pudieran afectar al mensaje original.

"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

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/

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/