On Fri, Feb 22, 2013 at 9:45 AM, Jack Royal-Gordon <jack@xxxxxxxxxxxxxxxxxxxxxxxxxx> 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@xxxxxxxxx> wrote:On Fri, Feb 22, 2013 at 8:36 AM, jackrg <jack@xxxxxxxxxxxxxxxxxxxxxxxxxx> 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
