Thread: Avoiding Recheck Cond when using Select Distinct
The following query produces a Recheck Cond and a costly Bitmap Heap Scan
even though I have a composite index that covers both columns being filtered
and selected. I believe this is because the initial bitmap scan produces
2912 rows, which is too many for the available bitmap space. I've tried
rewriting the command as "Select ... group by" but it still uses the BHS. Is
there a way to rewrite this command that would improve performance by
avoiding the costly Bitmap Heap Scan?
SELECT distinct store_id, book_id FROM "sales_points" WHERE
"sales_points"."store_id" IN (1, 2, 3, 4, 5, 6, 199, 201, 202) AND
"sales_points"."book_id" IN (421, 422, 419, 420)
Here is the explain/analyze output:
"HashAggregate (cost=5938.72..5939.01 rows=97 width=8) (actual
time=10.837..10.854 rows=32 loops=1)"
" -> Bitmap Heap Scan on sales_points (cost=47.03..5936.53 rows=2191
width=8) (actual time=0.547..5.296 rows=4233 loops=1)"
" Recheck Cond: (book_id = ANY ('{421,422,419,420}'::integer[]))"
" Filter: (store_id = ANY ('{1,2,3,4,5,6,199,201,202}'::integer[]))"
" -> Bitmap Index Scan on index_sales_points_on_book_id
(cost=0.00..46.92 rows=4430 width=0) (actual time=0.469..0.469 rows=4233
loops=1)"
" Index Cond: (book_id = ANY ('{421,422,419,420}'::integer[]))"
"Total runtime: 10.935 ms"
Actual runtime is more like 15ms when tested against a development database
(which gave est. total runtime of 6ms). Under load in production, the
command takes 10,158 ms. Tuning Postgre is not an option, as the instance
is provided by Heroku and as far as I know cannot be tuned by me.
--
View this message in context:
http://postgresql.1045698.n5.nabble.com/Avoiding-Recheck-Cond-when-using-Select-Distinct-tp5746290.html
Sent from the PostgreSQL - performance mailing list archive at Nabble.com.
On Fri, Feb 22, 2013 at 8:36 AM, jackrg <jack@groundbreakingsoftware.com> wrote:
Can you show us the definition of that index?
How do you know that the bitmap heap scan is costly, since you haven't gotten it to use an alternative to compare it to? As a temporary experimental measure, you could at least set enable_bitmapscan TO off, to see what happens.
I don't understand the parenthetical. In the explain plan you show, where is 6ms coming from?
Do you mean 10.158 ms rather than 10,158 ms? If the production environment really takes 1000 times longer than the environment in which you gathered the EXPLAIN, then I would seriously doubt how useful that EXPLAIN could possibly be.
Cheers,
Jeff
The following query produces a Recheck Cond and a costly Bitmap Heap Scan
even though I have a composite index that covers both columns being filtered
and selected.
Can you show us the definition of that index?
I believe this is because the initial bitmap scan produces
2912 rows, which is too many for the available bitmap space. I've tried
rewriting the command as "Select ... group by" but it still uses the BHS. Is
there a way to rewrite this command that would improve performance by
avoiding the costly Bitmap Heap Scan?
How do you know that the bitmap heap scan is costly, since you haven't gotten it to use an alternative to compare it to? As a temporary experimental measure, you could at least set enable_bitmapscan TO off, to see what happens.
SELECT distinct store_id, book_id FROM "sales_points" WHERE
"sales_points"."store_id" IN (1, 2, 3, 4, 5, 6, 199, 201, 202) AND
"sales_points"."book_id" IN (421, 422, 419, 420)
Here is the explain/analyze output:
"HashAggregate (cost=5938.72..5939.01 rows=97 width=8) (actual
time=10.837..10.854 rows=32 loops=1)"
" -> Bitmap Heap Scan on sales_points (cost=47.03..5936.53 rows=2191
width=8) (actual time=0.547..5.296 rows=4233 loops=1)"
" Recheck Cond: (book_id = ANY ('{421,422,419,420}'::integer[]))"
" Filter: (store_id = ANY ('{1,2,3,4,5,6,199,201,202}'::integer[]))"
" -> Bitmap Index Scan on index_sales_points_on_book_id
(cost=0.00..46.92 rows=4430 width=0) (actual time=0.469..0.469 rows=4233
loops=1)"
" Index Cond: (book_id = ANY ('{421,422,419,420}'::integer[]))"
"Total runtime: 10.935 ms"
Actual runtime is more like 15ms when tested against a development database
(which gave est. total runtime of 6ms).
I don't understand the parenthetical. In the explain plan you show, where is 6ms coming from?
Under load in production, the
command takes 10,158 ms.
Do you mean 10.158 ms rather than 10,158 ms? If the production environment really takes 1000 times longer than the environment in which you gathered the EXPLAIN, then I would seriously doubt how useful that EXPLAIN could possibly be.
Jeff
2013/2/22 jackrg <jack@groundbreakingsoftware.com>
Tuning Postgre is not an option, as the instance
is provided by Heroku and as far as I know cannot be tuned by me.
Most tuning parameters can be set at per-query basis, so you can issue
alter database set param=value
to have same effect as if it was set through postgresql.conf.
On Fri, Feb 22, 2013 at 9:59 AM, Vitalii Tymchyshyn <tivv00@gmail.com> wrote: >> Tuning Postgre is not an option, as the instance >> is provided by Heroku and as far as I know cannot be tuned by me. >> > Most tuning parameters can be set at per-query basis, so you can issue > alter database set param=value > to have same effect as if it was set through postgresql.conf. Jack, Jeff brought up some great points and What Vitalii suggested should let you tweak most knobs, but if you're running into limitations of the platform or you find default settings which seem outright incorrect, please file a support ticket and we'll be happy to work with you. Thanks, Maciek Heroku Postgres
On Fri, Feb 22, 2013 at 9:45 AM, Jack Royal-Gordon <jack@groundbreakingsoftware.com> wrote:
When I made up some random data that I thought was plausible, the planner did choose to use this use this index. You might have some skew in your data that we need to know more about in order to reproduce this (But that is probably not worthwhile, see below)
I suspect this is because the planner assumes that IO is rather expensive, and the bitmap plan saves on IO slightly while taking more CPU. But since all your data is in memory in this case, the IO savings are not real, while the extra CPU time is real. However, this is probably not relevant. Shaving 5ms off of a 10ms execution time looks impressive, but shaving 5ms off of your problematic case of 10s isn't going to do much for you.
It could be that the time savings extrapolated to the problem case will be multiplicative rather than additive. But my gut is telling me it won't be multiplicative. In fact it will probably go the other way, if the bitmap truly is more IO efficient, and your problematic case is due to poor IO performance, then getting it off the bitmap scan could easily make things worse.
If the server is so overwhelmed that it takes 1000 times longer, I think it would be setting off alarm bells all over the place, rather than with just this one query. Unless all that other activity is driving your data out of the cache so this query need to read it back from disk when on dev system it doesn't need to. But that means you need to find a way to simulate the actual cache hit on your dev system, or you won't be able to do realistic testing.
It would really help to have "explain (analyze, buffers)". Especially if you turn on track_io_timing, (although that part probably can't be done on Heroku, as it requires superuser access.)
It would help even more if you can get that information while the server is misbehaving, rather than when it is not. Does Heroku support auto_explain?
More likely would be that some operation caused it to change to a different plan that is inherently inefficient, rather than changing the efficiency of a given plan. That is where auto_explain would help. Also, if the bad execution is coming through your app, while the execution through psql, then maybe your app is secretly changing some of the planner settings.
Cheers,
Jeff
On Feb 22, 2013, at 9:19 AM, Jeff Janes <jeff.janes@gmail.com> wrote:On Fri, Feb 22, 2013 at 8:36 AM, jackrg <jack@groundbreakingsoftware.com> wrote:The following query produces a Recheck Cond and a costly Bitmap Heap Scan
even though I have a composite index that covers both columns being filtered
and selected.
Can you show us the definition of that index?CREATE INDEX test ON sales_points USING btree (book_id, store_id);
When I made up some random data that I thought was plausible, the planner did choose to use this use this index. You might have some skew in your data that we need to know more about in order to reproduce this (But that is probably not worthwhile, see below)
Here's the "Explan Analze" output after setting enable_bitmapscan off:I believe this is because the initial bitmap scan produces
2912 rows, which is too many for the available bitmap space. I've tried
rewriting the command as "Select ... group by" but it still uses the BHS. Is
there a way to rewrite this command that would improve performance by
avoiding the costly Bitmap Heap Scan?
How do you know that the bitmap heap scan is costly, since you haven't gotten it to use an alternative to compare it to? As a temporary experimental measure, you could at least set enable_bitmapscan TO off, to see what happens."HashAggregate (cost=8202.02..8203.33 rows=131 width=8) (actual time=4.275..4.280 rows=32 loops=1)"" -> Index Only Scan using test on sales_points (cost=0.01..8187.46 rows=2912 width=8) (actual time=0.083..3.268 rows=4233 loops=1)"" Index Cond: ((book_id = ANY ('{421,422,419,420}'::integer[])) AND (store_id = ANY ('{1,2,3,4,5,6,199,201,202}'::integer[])))"" Heap Fetches: 4233""Total runtime: 4.331 ms"While the total runtime reported is actually less, the costs reported are 50% higher.
I suspect this is because the planner assumes that IO is rather expensive, and the bitmap plan saves on IO slightly while taking more CPU. But since all your data is in memory in this case, the IO savings are not real, while the extra CPU time is real. However, this is probably not relevant. Shaving 5ms off of a 10ms execution time looks impressive, but shaving 5ms off of your problematic case of 10s isn't going to do much for you.
It could be that the time savings extrapolated to the problem case will be multiplicative rather than additive. But my gut is telling me it won't be multiplicative. In fact it will probably go the other way, if the bitmap truly is more IO efficient, and your problematic case is due to poor IO performance, then getting it off the bitmap scan could easily make things worse.
That's right, 10K ms. That's why I started trying to tune the performance of this query -- I had a warning in my log of a long-running query. Two thoughts why these numbers might be so different: 1) in production but not in the standalone test, many jobs are hitting the database simultaneously, so perhaps there was a great deal of I/O wait time involved;Under load in production, the
command takes 10,158 ms.
Do you mean 10.158 ms rather than 10,158 ms? If the production environment really takes 1000 times longer than the environment in which you gathered the EXPLAIN, then I would seriously doubt how useful that EXPLAIN could possibly be.
If the server is so overwhelmed that it takes 1000 times longer, I think it would be setting off alarm bells all over the place, rather than with just this one query. Unless all that other activity is driving your data out of the cache so this query need to read it back from disk when on dev system it doesn't need to. But that means you need to find a way to simulate the actual cache hit on your dev system, or you won't be able to do realistic testing.
It would really help to have "explain (analyze, buffers)". Especially if you turn on track_io_timing, (although that part probably can't be done on Heroku, as it requires superuser access.)
It would help even more if you can get that information while the server is misbehaving, rather than when it is not. Does Heroku support auto_explain?
2) production and the standalone test were separated by about 8 hours, and its possible that some sort of auto-vacuum operation had taken place to make the execution more efficient.
More likely would be that some operation caused it to change to a different plan that is inherently inefficient, rather than changing the efficiency of a given plan. That is where auto_explain would help. Also, if the bad execution is coming through your app, while the execution through psql, then maybe your app is secretly changing some of the planner settings.
Cheers,
Jeff
On Sat, Feb 23, 2013 at 3:53 PM, Jeff Janes <jeff.janes@gmail.com> wrote: > It would really help to have "explain (analyze, buffers)". Especially if > you turn on track_io_timing, (although that part probably can't be done on > Heroku, as it requires superuser access.) Right, that's not supported right now, although given that the superuser is primarily for performance considerations (right?), perhaps we should find some way of exposing this. > It would help even more if you can get that information while the server is > misbehaving, rather than when it is not. Does Heroku support auto_explain? We used to have some support for it, but given that all the tunables there are superuser-only, we found it wasn't very useful in its current form and took it out. Same as above: we probably should find a way of exposing the tunables here to a less-trusted user. It'd be great to have more granularity in some of these permissions.
On Mon, Feb 25, 2013 at 10:11 AM, Maciek Sakrejda <m.sakrejda@gmail.com> wrote:
I don't think it is SUSET for performance reasons, as the ordinary user already has plenty of ways to shoot themselves (and fellow users) in the foot performance-wise. I think it was based on the idea that those tracking tools that the administrator has turned on, ordinary users may turn off. I think the other way around would be fine (if it is off for the server, the user can still turn it on for their session--and presumably also turn it off again if it is one only because they set it that way, not because the administrator set it that way), but I think that that behavior is not trivial to implement. I looked in the archives, but the SUSET nature of this doesn't seem to have been discussed.
Cheers,
Jeff
On Sat, Feb 23, 2013 at 3:53 PM, Jeff Janes <jeff.janes@gmail.com> wrote:Right, that's not supported right now, although given that the
> It would really help to have "explain (analyze, buffers)". Especially if
> you turn on track_io_timing, (although that part probably can't be done on
> Heroku, as it requires superuser access.)
superuser is primarily for performance considerations (right?),
perhaps we should find some way of exposing this.
I don't think it is SUSET for performance reasons, as the ordinary user already has plenty of ways to shoot themselves (and fellow users) in the foot performance-wise. I think it was based on the idea that those tracking tools that the administrator has turned on, ordinary users may turn off. I think the other way around would be fine (if it is off for the server, the user can still turn it on for their session--and presumably also turn it off again if it is one only because they set it that way, not because the administrator set it that way), but I think that that behavior is not trivial to implement. I looked in the archives, but the SUSET nature of this doesn't seem to have been discussed.
Cheers,
Jeff