Re: Help Me Understand Why I'm Getting a Bad Query Plan

I hate to nag, but could anybody help me with this? We have a few
related queries that are causing noticeable service delays in our
production system. I've tried a number of different things, but I'm
running out of ideas and don't know what to do next.

Thanks,
Bryan

On Mon, Mar 23, 2009 at 2:03 PM, Bryan Murphy <bmurphy1976(at)gmail(dot)com> wrote:
> Hey Guys,
>
> I've got a query on our production system that isn't choosing a good
> plan.  I can't see why it's choosing to do a sequential scan on the
> ItemExperienceLog table.  That table is about 800mb and has about 2.5
> million records.  This example query only returns 4 records.  I've
> tried upping the statics for ItemExperienceLog.VistorId and
> ItemExperienceLog.ItemId to 1000 (from out default of 100) with no
> success.
>
> Our primary keys are guids stored as char(32) not null.  Our database
> uses UTF-8 encoding and is currently version v8.3.5.
>
> The queries:
>
>
>
> --SET enable_seqscan = off
> --SET enable_seqscan = on
>
> --ALTER TABLE ItemExperienceLog ALTER COLUMN VisitorId SET STATISTICS 1000
> --ALTER TABLE ItemExperienceLog ALTER COLUMN ItemId SET STATISTICS 1000
> --ANALYZE ItemExperienceLog
>
> SELECT MAX(l.Id) as Id, l.ItemId
> FROM ItemExperienceLog l
> INNER JOIN Items_Primary p ON p.Id = l.ItemId
> INNER JOIN Feeds f ON f.Id = p.FeedId
> INNER JOIN Visitors v ON v.Id = l.VisitorId
> WHERE
>        v.UserId = 'fbe2537f21d94f519605612c0bf7c2c5'
>        AND LOWER(f.Slug) = LOWER('Wealth_Building_by_NightingaleConant')
> GROUP BY l.ItemId
>
>
>
> Explain verbose output (set enable_seqscan = on):
>
>
>
> HashAggregate  (cost=124392.54..124392.65 rows=9 width=37) (actual
> time=7765.650..7765.654 rows=4 loops=1)
>  ->  Nested Loop  (cost=2417.68..124392.49 rows=9 width=37) (actual
> time=1706.703..7765.611 rows=11 loops=1)
>        ->  Nested Loop  (cost=2417.68..123868.75 rows=1807 width=70)
> (actual time=36.374..7706.677 rows=3174 loops=1)
>              ->  Hash Join  (cost=2417.68..119679.50 rows=1807
> width=37) (actual time=36.319..7602.221 rows=3174 loops=1)
>                    Hash Cond: (l.visitorid = v.id)
>                    ->  Seq Scan on itemexperiencelog l
> (cost=0.00..107563.09 rows=2581509 width=70) (actual
> time=0.010..4191.251 rows=2579880 loops=1)
>                    ->  Hash  (cost=2401.43..2401.43 rows=1300
> width=33) (actual time=3.673..3.673 rows=897 loops=1)
>                          ->  Bitmap Heap Scan on visitors v
> (cost=22.48..2401.43 rows=1300 width=33) (actual time=0.448..2.523
> rows=897 loops=1)
>                                Recheck Cond: (userid =
> 'fbe2537f21d94f519605612c0bf7c2c5'::bpchar)
>                                ->  Bitmap Index Scan on
> visitors_userid_index2  (cost=0.00..22.16 rows=1300 width=0) (actual
> time=0.322..0.322 rows=897 loops=1)
>                                      Index Cond: (userid =
> 'fbe2537f21d94f519605612c0bf7c2c5'::bpchar)
>              ->  Index Scan using items_primary_pkey on items_primary
> p  (cost=0.00..2.31 rows=1 width=66) (actual time=0.027..0.029 rows=1
> loops=3174)
>                    Index Cond: (p.id = l.itemid)
>        ->  Index Scan using feeds_pkey on feeds f  (cost=0.00..0.28
> rows=1 width=33) (actual time=0.016..0.016 rows=0 loops=3174)
>              Index Cond: (f.id = p.feedid)
>              Filter: (lower((f.slug)::text) =
> 'wealth_building_by_nightingaleconant'::text)
> Total runtime: 7765.767 ms
>
>
>
> Explain verbose output (set enable_seqscan = off):
>
>
>
> HashAggregate  (cost=185274.71..185274.82 rows=9 width=37) (actual
> time=185.024..185.028 rows=4 loops=1)
>  ->  Nested Loop  (cost=0.00..185274.67 rows=9 width=37) (actual
> time=0.252..184.989 rows=11 loops=1)
>        ->  Nested Loop  (cost=0.00..184751.21 rows=1806 width=70)
> (actual time=0.223..134.943 rows=3174 loops=1)
>              ->  Nested Loop  (cost=0.00..180564.28 rows=1806
> width=37) (actual time=0.192..60.214 rows=3174 loops=1)
>                    ->  Index Scan using visitors_userid_index2 on
> visitors v  (cost=0.00..2580.97 rows=1300 width=33) (actual
> time=0.052..2.342 rows=897 loops=1)
>                          Index Cond: (userid =
> 'fbe2537f21d94f519605612c0bf7c2c5'::bpchar)
>                    ->  Index Scan using
> itemexperiencelog__index__visitorid on itemexperiencelog l
> (cost=0.00..134.04 rows=230 width=70) (actual time=0.013..0.040 rows=4
> loops=897)
>                          Index Cond: (l.visitorid = v.id)
>              ->  Index Scan using items_primary_pkey on items_primary
> p  (cost=0.00..2.31 rows=1 width=66) (actual time=0.019..0.020 rows=1
> loops=3174)
>                    Index Cond: (p.id = l.itemid)
>        ->  Index Scan using feeds_pkey on feeds f  (cost=0.00..0.28
> rows=1 width=33) (actual time=0.014..0.014 rows=0 loops=3174)
>              Index Cond: (f.id = p.feedid)
>              Filter: (lower((f.slug)::text) =
> 'wealth_building_by_nightingaleconant'::text)
> Total runtime: 185.117 ms
>
>
>
> The relevent portions of postgresql.conf:
>
>
> max_connections = 100
> shared_buffers = 2GB
> temp_buffers = 32MB
> work_mem = 64MB
> maintenance_work_mem = 256MB
> max_stack_depth = 8MB
> wal_buffers = 1MB
> checkpoint_segments = 32
> random_page_cost = 2.0
> effective_cache_size = 12GB
> default_statistics_target = 100
>
>
>
> The tables and the indexes that matter:
>
>
>
> CREATE TABLE itemexperiencelog
> (
>  id integer NOT NULL DEFAULT nextval('itemexperiencelog__sequence'::regclass),
>  visitorid character(32) NOT NULL,
>  itemid character(32) NOT NULL,
>  created timestamp without time zone NOT NULL,
>  modified timestamp without time zone NOT NULL,
>  "position" integer NOT NULL DEFAULT 0,
>  itemlength integer NOT NULL DEFAULT 0,
>  usercomplete boolean NOT NULL DEFAULT false,
>  contentcomplete boolean NOT NULL DEFAULT false,
>  source character varying(32) NOT NULL,
>  sessionid character(32) NOT NULL,
>  authenticatedatcreation boolean NOT NULL DEFAULT false,
>  CONSTRAINT itemexperiencelog_pkey PRIMARY KEY (id),
>  CONSTRAINT itemexperiencelog_itemid_fkey FOREIGN KEY (itemid)
>      REFERENCES items_primary (id) MATCH SIMPLE
>      ON UPDATE NO ACTION ON DELETE NO ACTION
> )
>
> CREATE INDEX itemexperiencelog__index__itemid
>  ON itemexperiencelog
>  USING btree
>  (itemid);
>
> CREATE INDEX itemexperiencelog__index__visitorid
>  ON itemexperiencelog
>  USING btree
>  (visitorid);
>
>
>
> CREATE TABLE items_primary
> (
>  id character(32) NOT NULL,
>  feedid character(32),
>  slug character varying(255),
>  pubdate timestamp without time zone,
>  isvisible boolean,
>  deleted integer,
>  itemgroupid integer,
>  lockedflags integer NOT NULL,
>  CONSTRAINT items_primary_pkey PRIMARY KEY (id),
>  CONSTRAINT items_itemgroupid_fkey FOREIGN KEY (itemgroupid)
>      REFERENCES itemgroups (id) MATCH SIMPLE
>      ON UPDATE NO ACTION ON DELETE NO ACTION,
>  CONSTRAINT items_primary_feedid_fkey FOREIGN KEY (feedid)
>      REFERENCES feeds (id) MATCH SIMPLE
>      ON UPDATE NO ACTION ON DELETE NO ACTION
> )
> WITH (OIDS=FALSE);
>
> CREATE INDEX items_primary_feedid_index
>  ON items_primary
>  USING btree
>  (feedid);
>
>
>
> CREATE TABLE feeds
> (
>  id character(32) NOT NULL,
>  rssupdateinterval integer,
>  lastrssupdate timestamp without time zone,
>  nextrssupdate timestamp without time zone,
>  url text NOT NULL,
>  title text NOT NULL,
>  subtitle text,
>  link text,
>  slug character varying(2048) NOT NULL,
>  description text,
>  lang character varying(255),
>  copyright text,
>  pubdate timestamp without time zone,
>  lastbuilddate character varying(255),
>  docs text,
>  generator character varying(255),
>  managingeditor character varying(255),
>  webmaster character varying(255),
>  status integer,
>  ttl character varying(255),
>  image_title text,
>  image_url text,
>  image_link text,
>  image_description text,
>  image_width integer,
>  image_height integer,
>  rating character varying(255),
>  skiphours character varying(255),
>  skipdays character varying(255),
>  genretagid character(32),
>  sourceuserid character(32),
>  created timestamp without time zone NOT NULL,
>  deleted integer NOT NULL,
>  cloud_domain character varying(255),
>  cloud_port character varying(255),
>  cloud_path character varying(255),
>  cloud_registerprocedure character varying(255),
>  cloud_protocol character varying(255),
>  itunesauthor character varying(255),
>  itunesblock character varying(255),
>  itunescategories text,
>  itunesimage character varying(255),
>  itunesexplicit character varying(255),
>  ituneskeywords text,
>  itunesnewfeedurl character varying(255),
>  itunesowner_name character varying(255),
>  itunesowner_email character varying(255),
>  itunessubtitle text,
>  itunessummary text,
>  yahooimage text,
>  modified timestamp without time zone NOT NULL,
>  mediatype integer,
>  isvisible boolean NOT NULL DEFAULT false,
>  mediaplayertype integer NOT NULL,
>  episodebrowsecount integer,
>  comments text NOT NULL DEFAULT ''::text,
>  lockedflags integer NOT NULL DEFAULT 0,
>  sequenceid integer NOT NULL DEFAULT nextval('feeds_sequence'::regclass),
>  feedgroupid character(32),
>  bannerurl text,
>  categories text NOT NULL,
>  publisher text,
>  episodefetchstrategy integer NOT NULL,
>  averageuserrating real,
>  userratingscount integer,
>  lastupdate timestamp without time zone NOT NULL,
>  userratingstotal double precision NOT NULL,
>  CONSTRAINT feeds_pkey PRIMARY KEY (id),
>  CONSTRAINT feeds_feedgroupid_fkey FOREIGN KEY (feedgroupid)
>      REFERENCES feedgroups (id) MATCH SIMPLE
>      ON UPDATE NO ACTION ON DELETE NO ACTION,
>  CONSTRAINT fk5cb07d0e1080d15d FOREIGN KEY (sourceuserid)
>      REFERENCES users (id) MATCH SIMPLE
>      ON UPDATE NO ACTION ON DELETE NO ACTION,
>  CONSTRAINT fk5cb07d0eb113835f FOREIGN KEY (genretagid)
>      REFERENCES tags (id) MATCH SIMPLE
>      ON UPDATE NO ACTION ON DELETE NO ACTION,
>  CONSTRAINT feeds_slug_key UNIQUE (slug)
> )
> WITH (OIDS=FALSE);
>
> CREATE UNIQUE INDEX feeds_slug_unique
>  ON feeds
>  USING btree
>  (lower(slug::text));
>
>
>
> CREATE TABLE visitors
> (
>  id character(32) NOT NULL,
>  visitorid character(32) NOT NULL,
>  userid character(32),
>  sessionid text NOT NULL,
>  created timestamp without time zone NOT NULL,
>  modified timestamp without time zone NOT NULL,
>  deleted integer NOT NULL,
>  sequenceid integer DEFAULT nextval('visitors_sequence'::regclass),
>  CONSTRAINT visitors_pkey PRIMARY KEY (id)
> )
> WITH (OIDS=FALSE);
>
> CREATE INDEX visitors_userid_index2
>  ON visitors
>  USING btree
>  (userid);
>
> CREATE INDEX visitors_visitorid_index2
>  ON visitors
>  USING btree
>  (visitorid);
>