PostgreSQL 12.3 slow index scan chosen

From: Kenneth Marshall <ktm(at)rice(dot)edu>
To: pgsql-performance(at)lists(dot)postgresql(dot)org
Subject: PostgreSQL 12.3 slow index scan chosen
Date: 2020-06-19 19:49:14
Message-ID: 20200619194914.GI1497@aart.rice.edu
Views: Raw Message | Whole Thread | Download mbox | Resend email
Thread:
Lists: pgsql-performance

Hi PostgreSQL users,

I was looking at a slow query in our CMDB that using postgresql-12.3 as its
backend. I since I am using the pg_trgm extension elsewhere I decided to give
it a try. To my surprise, the query plan did not change. But when I disabled
the index scan I got the much, much faster scan using a bitmap index scan.
Any ideas about why that is being chosen? Here are the details:

shared_buffers = 12GB
work_mem = 128MB
maintenance_work_mem = 2GB
effective_io_concurrency = 200
max_worker_processes = 24
max_parallel_maintenance_workers = 4
max_parallel_workers_per_gather = 4
max_parallel_workers = 24
random_page_cost = 1.1
seq_page_cost = 1.0
effective_cache_size = 36GB
default_statistics_target = 500
from_collapse_limit = 30
join_collapse_limit = 30

Slow version with index scan:

# explain analyze SELECT DISTINCT main.* FROM Articles main JOIN ObjectCustomFieldValues ObjectCustomFieldValues_1 ON ( ObjectCustomFieldValues_1.Disabled = '0' ) AND ( ObjectCustomFieldValues_1.ObjectId = main.id ) WHERE (ObjectCustomFieldValues_1.LargeContent ILIKE '%958575%' OR ObjectCustomFieldValues_1.Content ILIKE '%958575%') AND (main.Disabled = '0') ORDER BY main.SortOrder ASC, main.Name ASC;
QUERY PLAN
-------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------
Unique (cost=892.65..892.68 rows=1 width=137) (actual time=21165.464..21165.464 rows=0 loops=1)
-> Sort (cost=892.65..892.66 rows=1 width=137) (actual time=21165.462..21165.462 rows=0 loops=1)
Sort Key: main.sortorder, main.name, main.id, main.summary, main.class, main.parent, main.uri, main.creator, main.created, main.lastupdatedby, main.lastupdated
Sort Method: quicksort Memory: 25kB
-> Merge Join (cost=0.71..892.64 rows=1 width=137) (actual time=21165.453..21165.453 rows=0 loops=1)
Merge Cond: (main.id = objectcustomfieldvalues_1.objectid)
-> Index Scan using articles_pkey on articles main (cost=0.14..9.08 rows=142 width=137) (actual time=0.007..0.007 rows=1 loops=1)
Filter: (disabled = '0'::smallint)
-> Index Scan using objectcustomfieldvalues3 on objectcustomfieldvalues objectcustomfieldvalues_1 (cost=0.56..807603.40 rows=915 width=4) (actual time=21165.441..21165.441 rows=0 loops=1)
Filter: ((disabled = 0) AND ((largecontent ~~* '%958575%'::text) OR ((content)::text ~~* '%958575%'::text)))
Rows Removed by Filter: 19030904
Planning Time: 1.198 ms
Execution Time: 21165.552 ms
(13 rows)

Time: 21167.239 ms (00:21.167)

Fast version with enable_indexscan = 0:

# explain analyze SELECT DISTINCT main.* FROM Articles main JOIN ObjectCustomFieldValues ObjectCustomFieldValues_1 ON ( ObjectCustomFieldValues_1.Disabled = '0' ) AND ( ObjectCustomFieldValues_1.ObjectId = main.id ) WHERE (ObjectCustomFieldValues_1.LargeContent ILIKE '%958575%' OR ObjectCustomFieldValues_1.Content ILIKE '%958575%') AND (main.Disabled = '0') ORDER BY main.SortOrder ASC, main.Name ASC;
QUERY PLAN
---------------------------------------------------------------------------------------------------------------------------------------------------------------------------
Unique (cost=1315.42..1315.45 rows=1 width=137) (actual time=0.306..0.306 rows=0 loops=1)
-> Sort (cost=1315.42..1315.43 rows=1 width=137) (actual time=0.305..0.305 rows=0 loops=1)
Sort Key: main.sortorder, main.name, main.id, main.summary, main.class, main.parent, main.uri, main.creator, main.created, main.lastupdatedby, main.lastupdated
Sort Method: quicksort Memory: 25kB
-> Hash Join (cost=52.89..1315.41 rows=1 width=137) (actual time=0.296..0.297 rows=0 loops=1)
Hash Cond: (objectcustomfieldvalues_1.objectid = main.id)
-> Bitmap Heap Scan on objectcustomfieldvalues objectcustomfieldvalues_1 (cost=45.27..1305.40 rows=915 width=4) (actual time=0.213..0.213 rows=0 loops=1)
Recheck Cond: ((largecontent ~~* '%958575%'::text) OR ((content)::text ~~* '%958575%'::text))
Filter: (disabled = 0)
-> BitmapOr (cost=45.27..45.27 rows=1136 width=0) (actual time=0.210..0.210 rows=0 loops=1)
-> Bitmap Index Scan on objectcustomfieldvalues_largecontent_trgm (cost=0.00..15.40 rows=1 width=0) (actual time=0.041..0.041 rows=0 loops=1)
Index Cond: (largecontent ~~* '%958575%'::text)
-> Bitmap Index Scan on objectcustomfieldvalues_content_trgm (cost=0.00..29.41 rows=1135 width=0) (actual time=0.168..0.168 rows=0 loops=1)
Index Cond: ((content)::text ~~* '%958575%'::text)
-> Hash (cost=5.84..5.84 rows=142 width=137) (actual time=0.079..0.079 rows=146 loops=1)
Buckets: 1024 Batches: 1 Memory Usage: 34kB
-> Seq Scan on articles main (cost=0.00..5.84 rows=142 width=137) (actual time=0.010..0.053 rows=146 loops=1)
Filter: (disabled = '0'::smallint)
Rows Removed by Filter: 5
Planning Time: 1.308 ms
Execution Time: 0.356 ms
(21 rows)

Time: 2.113 ms

And the schema information:

# \d articles
Table "public.articles"
Column | Type | Collation | Nullable | Default
---------------+-----------------------------+-----------+----------+--------------------------------------
id | integer | | not null | nextval('articles_id_seq'::regclass)
name | character varying(255) | | not null | ''::character varying
summary | character varying(255) | | not null | ''::character varying
sortorder | integer | | not null | 0
class | integer | | not null | 0
parent | integer | | not null | 0
uri | character varying(255) | | |
creator | integer | | not null | 0
created | timestamp without time zone | | |
lastupdatedby | integer | | not null | 0
lastupdated | timestamp without time zone | | |
disabled | smallint | | not null | 0
Indexes:
"articles_pkey" PRIMARY KEY, btree (id)

# \d objectcustomfieldvalues
Table "public.objectcustomfieldvalues"
Column | Type | Collation | Nullable | Default
-----------------+-----------------------------+-----------+----------+---------------------------------------------------------
id | integer | | not null | nextval('ticketcustomfieldvalues_id_s'::text::regclass)
objectid | integer | | not null |
customfield | integer | | not null |
content | character varying(255) | | |
creator | integer | | not null | 0
created | timestamp without time zone | | |
lastupdatedby | integer | | not null | 0
lastupdated | timestamp without time zone | | |
objecttype | character varying(255) | | not null |
largecontent | text | | |
contenttype | character varying(80) | | |
contentencoding | character varying(80) | | |
sortorder | integer | | not null | 0
disabled | integer | | not null | 0
Indexes:
"ticketcustomfieldvalues_pkey" PRIMARY KEY, btree (id) CLUSTER
"objectcustomfieldvalues1" btree (customfield, objecttype, objectid, content)
"objectcustomfieldvalues2" btree (customfield, objecttype, objectid)
"objectcustomfieldvalues3" btree (objectid, objecttype)
"objectcustomfieldvalues4" btree (id) WHERE id IS NULL OR id = 0
"objectcustomfieldvalues_content_trgm" gin (content gin_trgm_ops)
"objectcustomfieldvalues_largecontent_trgm" gin (largecontent gin_trgm_ops)
"ticketcustomfieldvalues1" btree (customfield, objectid, content)

Any suggestions would be appreciated.

Regards,
Ken

Responses

Browse pgsql-performance by date

  From Date Subject
Next Message Tom Lane 2020-06-19 20:11:10 Re: PostgreSQL 12.3 slow index scan chosen
Previous Message Michael Lewis 2020-06-19 18:37:12 Re: Unclamped row estimates whith OR-ed subplans