Hello all.
To our surprise this morning, we found a query that used to return
it's result in about 50 ~ 100ms now take about 7.000ms to run.
After some investigation, we found out that the PostgreSQL server
(8.1) changed the execution plan (I'm assuming because the number of
rows increased).
Since this query may be executed a few times per second, it caused
some problem :)
The query is the following:
SELECT meta_id, meta_type, COUNT(M.post_id) as count
FROM dc_meta M LEFT JOIN dc_post P ON M.post_id = P.post_id
WHERE P.blog_id = 'b4c62627b3203e7780078cf2f6373ab5'
AND M.blog_id = 'b4c62627b3203e7780078cf2f6373ab5'
AND meta_type = 'tag'
AND ((post_status = 1 AND post_password IS NULL ))
GROUP BY meta_id,meta_type,P.blog_id
ORDER BY count DESC
LIMIT 40
The dc_post table has the following fields:
- post_id bigint NOT NULL,
- blog_id character varying(32) NOT NULL,
- post_password character varying(32),
- post_status smallint NOT NULL DEFAULT 0,
- and some other not used for this query ;)
Usefull indexes:
- dc_pk_post PRIMARY KEY(post_id)
- dc_fk_post_blog FOREIGN KEY (blog_id)
- dc_idx_blog_post_post_status btree (blog_id, post_status)
- dc_idx_post_blog_id btree (blog_id)
dc_meta is as follow:
- meta_id character varying(255) NOT NULL,
- meta_type character varying(64) NOT NULL,
- post_id bigint NOT NULL,
- blog_id character varying(32)
With indexes:
- dc_pk_meta PRIMARY KEY(meta_id, meta_type, post_id)
- dc_fk_meta_blog FOREIGN KEY (blog_id)
- dc_fk_meta_post FOREIGN KEY (post_id)
- dc_idx_meta_blog_id btree (blog_id)
- dc_idx_meta_meta_type btree (meta_type)
- dc_idx_meta_post_id btree (post_id)
(Aren't the foreign keys and index redundant btw? :)
I've attached the EXPLAIN ANALYZE that runs now, the one that runs on
our test server (witch contains data from 10 days ago), and another
one on the production server with nested loop disabled.
The query plan for the test server is the same that the production
server was last week.
On production
dc_meta contains approx 791756 rows
dc_post contains approx 235524 rows
On test :
dc_meta contains approx 641398 rows
dc_post contains approx 211295 rows
The statistics are at the default value everywhere (10)
The 'b4c6' blog is one of your biggest blogs, which contains 9326 tags
and 3178 posts on the production server (9156 / 3132 in test)
Does anyone have and idea why this happened and how we may be able to
fix the problem ?
Disabling nested loop falls back on the previous plan, but we can't
really disable them since the application used (dotclear) and it's db
layer is designed to work with mysql as well.
For the moment I've changed the query to remove the P.blog_id =
'b4c6..' clause and it does the trick, but it's still slower than the
previous one.
Thank you for your time
--
Romuald Brunet
Limit (cost=34380.87..34380.97 rows=40 width=94) (actual time=96.698..96.753 rows=40 loops=1)
-> Sort (cost=34380.87..34381.16 rows=115 width=94) (actual time=96.696..96.712 rows=40 loops=1)
Sort Key: count(m.post_id)
-> HashAggregate (cost=34375.50..34376.94 rows=115 width=94) (actual time=85.320..89.064 rows=3688 loops=1)
-> Hash Join (cost=10298.29..34374.35 rows=115 width=94) (actual time=35.783..71.702 rows=8957 loops=1)
Hash Cond: ("outer".post_id = "inner".post_id)
-> Bitmap Heap Scan on dc_meta m (cost=336.93..24341.33 rows=9401 width=58) (actual time=3.812..26.720 rows=9156 loops=1)
Recheck Cond: ((blog_id)::text = 'b4c62627b3203e7780078cf2f6373ab5'::text)
Filter: ((meta_type)::text = 'tag'::text)
-> Bitmap Index Scan on dc_idx_meta_blog_id (cost=0.00..336.93 rows=9407 width=0) (actual time=3.168..3.168 rows=9156 loops=1)
Index Cond: ((blog_id)::text = 'b4c62627b3203e7780078cf2f6373ab5'::text)
-> Hash (cost=9954.92..9954.92 rows=2577 width=44) (actual time=31.918..31.918 rows=3038 loops=1)
-> Bitmap Heap Scan on dc_post p (cost=35.51..9954.92 rows=2577 width=44) (actual time=2.508..28.751 rows=3038 loops=1)
Recheck Cond: (((blog_id)::text = 'b4c62627b3203e7780078cf2f6373ab5'::text) AND (post_status = 1))
Filter: (post_password IS NULL)
-> Bitmap Index Scan on dc_idx_blog_post_post_status (cost=0.00..35.51 rows=2584 width=0) (actual time=1.650..1.650 rows=3038 loops=1)
Index Cond: (((blog_id)::text = 'b4c62627b3203e7780078cf2f6373ab5'::text) AND (post_status = 1))
Total runtime: 97.191 ms
Limit (cost=2740.03..2740.03 rows=1 width=96) (actual time=7712.844..7712.923 rows=40 loops=1)
-> Sort (cost=2740.03..2740.03 rows=1 width=96) (actual time=7712.840..7712.840 rows=40 loops=1)
Sort Key: count(m.post_id)
-> HashAggregate (cost=2740.01..2740.02 rows=1 width=96) (actual time=7700.404..7704.470 rows=3726 loops=1)
-> Nested Loop (cost=13.19..2740.00 rows=1 width=96) (actual time=3.379..7682.910 rows=9123 loops=1)
-> Index Scan using dc_idx_blog_post_post_status on dc_post p (cost=0.00..590.28 rows=118 width=44) (actual time=0.167..17.707 rows=3083 loops=1)
Index Cond: (((blog_id)::text = 'b4c62627b3203e7780078cf2f6373ab5'::text) AND (post_status = 1))
Filter: (post_password IS NULL)
-> Bitmap Heap Scan on dc_meta m (cost=13.19..18.21 rows=1 width=60) (actual time=2.476..2.480 rows=3 loops=3083)
Recheck Cond: ((m.post_id = "outer".post_id) AND ((m.blog_id)::text = 'b4c62627b3203e7780078cf2f6373ab5'::text))
Filter: ((meta_type)::text = 'tag'::text)
-> BitmapAnd (cost=13.19..13.19 rows=1 width=0) (actual time=2.472..2.472 rows=0 loops=3083)
-> Bitmap Index Scan on dc_idx_meta_post_id (cost=0.00..3.02 rows=292 width=0) (actual time=0.042..0.042 rows=3 loops=3083)
Index Cond: (m.post_id = "outer".post_id)
-> Bitmap Index Scan on dc_idx_meta_blog_id (cost=0.00..9.92 rows=834 width=0) (actual time=2.737..2.737 rows=9326 loops=2735)
Index Cond: ((blog_id)::text = 'b4c62627b3203e7780078cf2f6373ab5'::text)
Total runtime: 7713.392 ms
Limit (cost=4031.92..4031.92 rows=1 width=96) (actual time=66.881..66.934 rows=40 loops=1)
-> Sort (cost=4031.92..4031.92 rows=1 width=96) (actual time=66.879..66.905 rows=40 loops=1)
Sort Key: count(m.post_id)
-> HashAggregate (cost=4031.90..4031.91 rows=1 width=96) (actual time=54.785..58.600 rows=3726 loops=1)
-> Hash Join (cost=582.57..4031.89 rows=1 width=96) (actual time=15.047..40.772 rows=9128 loops=1)
Hash Cond: ("outer".post_id = "inner".post_id)
-> Bitmap Heap Scan on dc_meta m (cost=9.92..3455.06 rows=834 width=60) (actual time=3.413..15.116 rows=9326 loops=1)
Recheck Cond: ((blog_id)::text = 'b4c62627b3203e7780078cf2f6373ab5'::text)
Filter: ((meta_type)::text = 'tag'::text)
-> Bitmap Index Scan on dc_idx_meta_blog_id (cost=0.00..9.92 rows=834 width=0) (actual time=2.829..2.829 rows=9326 loops=1)
Index Cond: ((blog_id)::text = 'b4c62627b3203e7780078cf2f6373ab5'::text)
-> Hash (cost=572.35..572.35 rows=118 width=44) (actual time=11.567..11.567 rows=3084 loops=1)
-> Bitmap Heap Scan on dc_post p (cost=2.71..572.35 rows=118 width=44) (actual time=2.472..8.466 rows=3084 loops=1)
Recheck Cond: (((blog_id)::text = 'b4c62627b3203e7780078cf2f6373ab5'::text) AND (post_status = 1))
Filter: (post_password IS NULL)
-> Bitmap Index Scan on dc_idx_blog_post_post_status (cost=0.00..2.71 rows=118 width=0) (actual time=1.533..1.533 rows=3084 loops=1)
Index Cond: (((blog_id)::text = 'b4c62627b3203e7780078cf2f6373ab5'::text) AND (post_status = 1))
Total runtime: 67.315 ms
--
Sent via pgsql-performance mailing list (pgsql-performance@xxxxxxxxxxxxxx)
To make changes to your subscription:
http://www.postgresql.org/mailpref/pgsql-performance
