Thread: PostgreSQL 12.3 slow index scan chosen
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.LargeContentILIKE '%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.007rows=1 loops=1)
Filter: (disabled = '0'::smallint)
-> Index Scan using objectcustomfieldvalues3 on objectcustomfieldvalues objectcustomfieldvalues_1
(cost=0.56..807603.40rows=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.LargeContentILIKE '%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=146loops=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
Kenneth Marshall <ktm@rice.edu> writes:
> 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:
It looks like the planner is being too optimistic about how quickly the
mergejoin will end:
> -> 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.007rows=1 loops=1)
> Filter: (disabled = '0'::smallint)
> -> Index Scan using objectcustomfieldvalues3 on objectcustomfieldvalues objectcustomfieldvalues_1
(cost=0.56..807603.40rows=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
This merge cost estimate is way lower than the sum of the input scan
estimates, where normally it would be that sum plus a nontrivial charge
for comparisons. So the planner must think that the input scans won't
run to completion. Which is something that can happen; merge join
will stop as soon as either input is exhausted. But in this case it
looks like the objectcustomfieldvalues scan is the one that ran to
completion, while the articles scan had only one row demanded from it.
(We can see from the other plan that articles has 146 rows satisfying
the filter, so that scan must have been shut down before completion.)
The planner must have been expecting the other way around, with not
very much of the expensive objectcustomfieldvalues scan actually getting
done.
The reason for such an estimation error usually is that the maximum
join key values recorded in pg_stats are off: the join side that is
going to be exhausted is the one with the smaller max join key.
"articles" seems to be small enough that the stats for it will be
exact, so your problem is a poor estimate of the max value of
objectcustomfieldvalues.objectid. You might try raising the statistics
target for that table. Or maybe it's just that ANALYZE hasn't been
done lately on one table or the other?
regards, tom lane
On Fri, Jun 19, 2020 at 04:11:10PM -0400, Tom Lane wrote: > > It looks like the planner is being too optimistic about how quickly the > mergejoin will end: > > > -> 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.007rows=1 loops=1) > > Filter: (disabled = '0'::smallint) > > -> Index Scan using objectcustomfieldvalues3 on objectcustomfieldvalues objectcustomfieldvalues_1 (cost=0.56..807603.40rows=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 > > This merge cost estimate is way lower than the sum of the input scan > estimates, where normally it would be that sum plus a nontrivial charge > for comparisons. So the planner must think that the input scans won't > run to completion. Which is something that can happen; merge join > will stop as soon as either input is exhausted. But in this case it > looks like the objectcustomfieldvalues scan is the one that ran to > completion, while the articles scan had only one row demanded from it. > (We can see from the other plan that articles has 146 rows satisfying > the filter, so that scan must have been shut down before completion.) > The planner must have been expecting the other way around, with not > very much of the expensive objectcustomfieldvalues scan actually getting > done. > > The reason for such an estimation error usually is that the maximum > join key values recorded in pg_stats are off: the join side that is > going to be exhausted is the one with the smaller max join key. > "articles" seems to be small enough that the stats for it will be > exact, so your problem is a poor estimate of the max value of > objectcustomfieldvalues.objectid. You might try raising the statistics > target for that table. Or maybe it's just that ANALYZE hasn't been > done lately on one table or the other? > > regards, tom lane Hi Tod, Thank you for the information and suggestion. I tried bumping the statistics for the objectcustomfieldvalues.objectid column to 2k, 5k and 10k followed by an analyze and the query plan stayed the same. I also analyzed the article table repeatedly and their was no change in the plan. The table articles only has 151 rows while the objectcustomfieldvalues table has 19031909 rows. Any idea about why it is so far off? Regards, Ken
Kenneth Marshall <ktm@rice.edu> writes:
> On Fri, Jun 19, 2020 at 04:11:10PM -0400, Tom Lane wrote:
>> The reason for such an estimation error usually is that the maximum
>> join key values recorded in pg_stats are off: the join side that is
>> going to be exhausted is the one with the smaller max join key.
>> "articles" seems to be small enough that the stats for it will be
>> exact, so your problem is a poor estimate of the max value of
>> objectcustomfieldvalues.objectid. You might try raising the statistics
>> target for that table. Or maybe it's just that ANALYZE hasn't been
>> done lately on one table or the other?
> Thank you for the information and suggestion. I tried bumping the statistics for the
> objectcustomfieldvalues.objectid column to 2k, 5k and 10k followed by an analyze and
> the query plan stayed the same. I also analyzed the article table
> repeatedly and their was no change in the plan. The table articles only has 151 rows
> while the objectcustomfieldvalues table has 19031909 rows. Any idea
> about why it is so far off?
What's the actual maximum value of objectcustomfieldvalues.objectid,
and how does that compare to the endpoint value in the pg_stats
histogram for that column? If you've got one outlier in the table,
it might get missed by ANALYZE.
regards, tom lane
On Fri, Jun 19, 2020 at 04:59:15PM -0400, Tom Lane wrote:
>
> > Thank you for the information and suggestion. I tried bumping the statistics for the
> > objectcustomfieldvalues.objectid column to 2k, 5k and 10k followed by an analyze and
> > the query plan stayed the same. I also analyzed the article table
> > repeatedly and their was no change in the plan. The table articles only has 151 rows
> > while the objectcustomfieldvalues table has 19031909 rows. Any idea
> > about why it is so far off?
>
> What's the actual maximum value of objectcustomfieldvalues.objectid,
> and how does that compare to the endpoint value in the pg_stats
> histogram for that column? If you've got one outlier in the table,
> it might get missed by ANALYZE.
>
> regards, tom lane
Hi Tom,
max(objectcustomfieldvalues.objectid) = 28108423 and here is the
histogram for that column:
schemaname | tablename | attname | inherited | null_frac | avg_width | n_distinct |
most_common_vals
|
most_common_freqs |
histogram_bounds
| correlation |
most_common_elems| most_common_elem_freqs | elem_count_histogram
------------+-------------------------+----------+-----------+-----------+-----------+------------+---------------------------------------------------------------------------------------------------------------------------------------------------------+----------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------+----------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------+-------------+-------------------+------------------------+----------------------
public | objectcustomfieldvalues | objectid | f | 0 | 4 | 615227 |
{2521539,2621185,2269417,2847802,2956102,2397380,2623765,183974,2566321,2955862,3303717,3303979,3169130,2525623,1840685,2889335,190737,3188380,3303589}
|
{0.00012,0.000113333335,0.0001,9.3333336e-05,9.3333336e-05,8e-05,8e-05,7.3333336e-05,7.3333336e-05,7.3333336e-05,7.3333336e-05,7.3333336e-05,6.666667e-05,6e-05,4.6666668e-05,4.6666668e-05,4e-05,4e-05,4e-05}
|
{13,2134,3509,26547,34737,40152,46587,50105,52672,55353,57887,59711,61569,63460,65355,67312,69282,71624,73867,75957,77612,79489,81209,82909,84631,86414,88322,90288,92379,94079,95997,97857,99818,101665,103329,105219,107051,107897,109067,110861,112706,114406,116172,117998,119816,121652,124009,126170,128116,129934,132078,134032,135996,137776,139628,141620,143516,145342,147189,149198,151202,153037,154808,156492,158288,160054,161898,163653,165565,167635,169590,171793,173546,175286,177249,179324,181293,183134,185090,187036,188727,190379,191958,193496,195152,197104,199273,201063,202948,204836,206969,208730,210500,212108,213993,215950,217795,219622,221295,223425,225492,227812,229786,231604,233681,235666,237621,239273,241014,242929,244820,246835,248932,251080,253520,255509,257521,259358,261456,263416,265223,267034,268954,270791,272748,274775,276824,279028,280994,282867,284691,286480,288403,290118,291879,293724,295992,298195,300231,302005,303921,305829,307728,312187,322637,324637,326711,328410,330189,331775,333482,335258,337377,339324,341233,343491,345226,346956,348483,350291,352158,354138,356101,358109,360079,361881,364029,365859,367629,369643,371338,373086,375053,376983,378733,380404,382291,384249,386026,387804,390103,392037,394155,396146,397989,399995,401825,403596,405630,407367,409271,410961,412888,414877,416817,418590,420382,422393,424242,425999,427973,429975,431901,433971,435744,437793,439691,441941,443559,445134,446797,448650,450422,452053,453759,455479,457126,458948,460733,462434,464282,466002,467835,469652,471119,472773,474409,476020,477537,479555,481629,483237,484863,486409,488035,489791,491528,493298,495072,496836,498586,500354,502383,504174,505874,507521,509105,510761,512541,514306,515995,517715,519483,521248,522945,524539,526041,527706,529182,530744,532429,533948,535558,537359,539116,540863,542489,544262,546322,548161,549902,551405,553121,554802,556671,558536,560354,562347,564194,565897,567767,569405,571001,572912,574565,576328,578132,580065,581620,583221,585081,586608,588547,590356,592090,593962,595697,597285,598839,600508,602443,604227,605867,607468,609085,610797,612332,613921,615995,617851,619721,621524,623179,625233,626945,628751,630490,632141,633720,635495,637468,639500,641534,643506,645470,647717,649410,651203,653202,654833,656600,658617,660219,661861,663708,665443,667334,669170,670976,672711,674301,675804,677526,678907,680449,682221,684006,685693,687199,688838,690608,692189,693817,695615,697315,699054,700889,702630,704168,705826,707609,709307,710996,712999,714688,716716,718429,720331,722148,723922,725591,727357,729083,730848,732700,734386,736115,738141,739960,741521,743385,745319,747126,749002,750831,752764,754524,756279,758293,759958,761685,763366,764965,766557,768415,769979,771693,773446,775194,777188,779097,780810,782669,784398,786016,787695,789447,791420,793006,794838,796736,798655,800602,802817,804735,806387,808323,810183,811806,813674,815637,817375,819044,820907,822761,824890,826798,828762,830733,832618,834526,836655,838640,840602,842547,844741,846843,848834,850872,852630,854937,856685,858524,860329,862328,864262,866146,868297,870363,872379,874256,876114,877886,880210,882175,884423,886698,888682,890722,892866,895162,897253,899320,901578,903360,905209,907171,909164,911048,913052,915185,917251,919283,921343,923906,925787,929684,931600,933410,935385,937920,940047,942195,944602,946624,948614,951946,953948,955964,958135,1676537,2029763,2276887,2488636,2544458,2621609,2891726,3052758,3304313,3693956,27667772}
| 0.95726633 | | |
(1 row)
Regards,
Ken
Kenneth Marshall <ktm@rice.edu> writes:
> On Fri, Jun 19, 2020 at 04:59:15PM -0400, Tom Lane wrote:
>> What's the actual maximum value of objectcustomfieldvalues.objectid,
>> and how does that compare to the endpoint value in the pg_stats
>> histogram for that column? If you've got one outlier in the table,
>> it might get missed by ANALYZE.
> max(objectcustomfieldvalues.objectid) = 28108423 and here is the
> histogram for that column:
... 3304313,3693956,27667772}
Hmm, does seem like you have some outlier keys. Are any of the keys in
the column you're trying to join to larger than 27667772?
regards, tom lane
On Fri, Jun 19, 2020 at 06:10:34PM -0400, Tom Lane wrote:
> > max(objectcustomfieldvalues.objectid) = 28108423 and here is the
> > histogram for that column:
>
> ... 3304313,3693956,27667772}
>
> Hmm, does seem like you have some outlier keys. Are any of the keys in
> the column you're trying to join to larger than 27667772?
>
> regards, tom lane
Hi Tom,
The only values above 27667772? for objectid are:
# select * from objectcustomfieldvalues where objectid > 27667772;
id | objectid | customfield | content | creator |
created | lastupdatedby | lastupdated | objecttype |
largecontent | contenttype | contentencoding | sortorder | disabled
----------+----------+-------------+------------+---------+---------------------+---------------+---------------------+-----------------+--------------+-------------+-----------------+-----------+----------
19012927 | 27667773 | 375 | 2020-05-12 | 3768865 | 2020-05-13
16:10:39 | 3768865 | 2020-05-13 16:10:39 | RT::Transaction |
| | | 0 | 0
19012928 | 27667774 | 375 | 2020-05-12 | 3768865 | 2020-05-13
16:10:39 | 3768865 | 2020-05-13 16:10:39 | RT::Transaction |
| | | 0 | 0
19020166 | 27680053 | 375 | 2020-05-14 | 3570362 | 2020-05-14
14:14:20 | 3570362 | 2020-05-14 14:14:20 | RT::Transaction |
| | | 0 | 0
19025163 | 27688649 | 375 | 2020-05-13 | 3768865 | 2020-05-14
20:27:04 | 3768865 | 2020-05-14 20:27:04 | RT::Transaction |
| | | 0 | 0
19025164 | 27688650 | 375 | 2020-05-13 | 3768865 | 2020-05-14
20:27:04 | 3768865 | 2020-05-14 20:27:04 | RT::Transaction |
| | | 0 | 0
19025165 | 27688651 | 375 | 2020-05-13 | 3768865 | 2020-05-14
20:27:04 | 3768865 | 2020-05-14 20:27:04 | RT::Transaction |
| | | 0 | 0
19025166 | 27688652 | 375 | 2020-05-13 | 3768865 | 2020-05-14
20:27:04 | 3768865 | 2020-05-14 20:27:04 | RT::Transaction |
| | | 0 | 0
19025167 | 27688676 | 375 | 2020-05-14 | 3768865 | 2020-05-14
20:27:29 | 3768865 | 2020-05-14 20:27:29 | RT::Transaction |
| | | 0 | 0
19031374 | 27698358 | 375 | 2020-05-13 | 3768865 | 2020-05-15
15:32:57 | 3768865 | 2020-05-15 15:32:57 | RT::Transaction |
| | | 0 | 0
19031384 | 27698376 | 375 | 2020-05-14 | 3768865 | 2020-05-15
15:33:50 | 3768865 | 2020-05-15 15:33:50 | RT::Transaction |
| | | 0 | 0
19031385 | 27698377 | 375 | 2020-05-14 | 3768865 | 2020-05-15
15:33:50 | 3768865 | 2020-05-15 15:33:50 | RT::Transaction |
| | | 0 | 0
19033205 | 27701391 | 375 | 2020-05-15 | 3197295 | 2020-05-15
18:21:36 | 3197295 | 2020-05-15 18:21:36 | RT::Transaction |
| | | 0 | 0
19042369 | 27715839 | 375 | 2020-05-18 | 1403795 | 2020-05-18
14:12:35 | 1403795 | 2020-05-18 14:12:35 | RT::Transaction |
| | | 0 | 0
19047274 | 27723981 | 375 | 2020-05-18 | 3197295 | 2020-05-18
19:29:14 | 3197295 | 2020-05-18 19:29:14 | RT::Transaction |
| | | 0 | 0
19048566 | 27726800 | 375 | 2020-05-18 | 3768865 | 2020-05-18
20:23:18 | 3768865 | 2020-05-18 20:23:18 | RT::Transaction |
| | | 0 | 0
19048567 | 27726801 | 375 | 2020-05-18 | 3768865 | 2020-05-18
20:23:18 | 3768865 | 2020-05-18 20:23:18 | RT::Transaction |
| | | 0 | 0
19048568 | 27726802 | 375 | 2020-05-18 | 3768865 | 2020-05-18
20:23:18 | 3768865 | 2020-05-18 20:23:18 | RT::Transaction |
| | | 0 | 0
19048569 | 27726803 | 375 | 2020-05-18 | 3768865 | 2020-05-18
20:23:18 | 3768865 | 2020-05-18 20:23:18 | RT::Transaction |
| | | 0 | 0
19048570 | 27726804 | 375 | 2020-05-18 | 3768865 | 2020-05-18
20:23:18 | 3768865 | 2020-05-18 20:23:18 | RT::Transaction |
| | | 0 | 0
19048571 | 27726805 | 375 | 2020-05-18 | 3768865 | 2020-05-18
20:23:18 | 3768865 | 2020-05-18 20:23:18 | RT::Transaction |
| | | 0 | 0
19048572 | 27726806 | 375 | 2020-05-18 | 3768865 | 2020-05-18
20:23:19 | 3768865 | 2020-05-18 20:23:19 | RT::Transaction |
| | | 0 | 0
19048573 | 27726807 | 375 | 2020-05-18 | 3768865 | 2020-05-18
20:23:19 | 3768865 | 2020-05-18 20:23:19 | RT::Transaction |
| | | 0 | 0
19048574 | 27726808 | 375 | 2020-05-18 | 3768865 | 2020-05-18
20:23:19 | 3768865 | 2020-05-18 20:23:19 | RT::Transaction |
| | | 0 | 0
19054502 | 27738410 | 375 | 2020-05-19 | 3197295 | 2020-05-19
15:01:50 | 3197295 | 2020-05-19 15:01:50 | RT::Transaction |
| | | 0 | 0
19056348 | 27741653 | 375 | 2020-05-19 | 3768865 | 2020-05-19
16:39:01 | 3768865 | 2020-05-19 16:39:01 | RT::Transaction |
| | | 0 | 0
19056349 | 27741654 | 375 | 2020-05-19 | 3768865 | 2020-05-19
16:39:01 | 3768865 | 2020-05-19 16:39:01 | RT::Transaction |
| | | 0 | 0
19056350 | 27741655 | 375 | 2020-05-19 | 3768865 | 2020-05-19
16:39:02 | 3768865 | 2020-05-19 16:39:02 | RT::Transaction |
| | | 0 | 0
19056351 | 27741656 | 375 | 2020-05-19 | 3768865 | 2020-05-19
16:39:02 | 3768865 | 2020-05-19 16:39:02 | RT::Transaction |
| | | 0 | 0
19056352 | 27741657 | 375 | 2020-05-19 | 3768865 | 2020-05-19
16:39:02 | 3768865 | 2020-05-19 16:39:02 | RT::Transaction |
| | | 0 | 0
19056362 | 27741667 | 375 | 2020-05-19 | 3768865 | 2020-05-19
16:39:29 | 3768865 | 2020-05-19 16:39:29 | RT::Transaction |
| | | 0 | 0
19057464 | 27743793 | 375 | 2020-05-19 | 3197295 | 2020-05-19
18:03:16 | 3197295 | 2020-05-19 18:03:16 | RT::Transaction |
| | | 0 | 0
19067180 | 27760343 | 375 | 2020-05-20 | 1403795 | 2020-05-20
18:01:59 | 1403795 | 2020-05-20 18:01:59 | RT::Transaction |
| | | 0 | 0
19067476 | 27760892 | 375 | 2020-05-19 | 3197295 | 2020-05-20
18:23:48 | 3197295 | 2020-05-20 18:23:48 | RT::Transaction |
| | | 0 | 0
19073560 | 27771129 | 375 | 2020-05-21 | 3197295 | 2020-05-21
14:15:54 | 3197295 | 2020-05-21 14:15:54 | RT::Transaction |
| | | 0 | 0
19074011 | 27771902 | 375 | 2020-05-21 | 3570362 | 2020-05-21
15:02:49 | 3570362 | 2020-05-21 15:02:49 | RT::Transaction |
| | | 0 | 0
19081811 | 27784951 | 375 | 2020-05-22 | 2960471 | 2020-05-22
14:52:40 | 2960471 | 2020-05-22 14:52:40 | RT::Transaction |
| | | 0 | 0
19093560 | 27804234 | 375 | 2020-05-26 | 3570362 | 2020-05-26
15:00:29 | 3570362 | 2020-05-26 15:00:29 | RT::Transaction |
| | | 0 | 0
19094043 | 27805100 | 375 | 2020-05-26 | 3570362 | 2020-05-26
15:30:15 | 3570362 | 2020-05-26 15:30:15 | RT::Transaction |
| | | 0 | 0
19094798 | 27806250 | 375 | 2020-05-26 | 3570362 | 2020-05-26
15:59:22 | 3570362 | 2020-05-26 15:59:22 | RT::Transaction |
| | | 0 | 0
19103803 | 27822098 | 375 | 2020-05-27 | 3570362 | 2020-05-27
15:15:37 | 3570362 | 2020-05-27 15:15:37 | RT::Transaction |
| | | 0 | 0
19103893 | 27822211 | 375 | 2020-05-26 | 3768865 | 2020-05-27
15:20:11 | 3768865 | 2020-05-27 15:20:11 | RT::Transaction |
| | | 0 | 0
19103894 | 27822212 | 375 | 2020-05-26 | 3768865 | 2020-05-27
15:20:12 | 3768865 | 2020-05-27 15:20:12 | RT::Transaction |
| | | 0 | 0
19103895 | 27822213 | 375 | 2020-05-26 | 3768865 | 2020-05-27
15:20:12 | 3768865 | 2020-05-27 15:20:12 | RT::Transaction |
| | | 0 | 0
19103896 | 27822214 | 375 | 2020-05-26 | 3768865 | 2020-05-27
15:20:12 | 3768865 | 2020-05-27 15:20:12 | RT::Transaction |
| | | 0 | 0
19103897 | 27822215 | 375 | 2020-05-26 | 3768865 | 2020-05-27
15:20:12 | 3768865 | 2020-05-27 15:20:12 | RT::Transaction |
| | | 0 | 0
19103898 | 27822216 | 375 | 2020-05-26 | 3768865 | 2020-05-27
15:20:12 | 3768865 | 2020-05-27 15:20:12 | RT::Transaction |
| | | 0 | 0
19103899 | 27822217 | 375 | 2020-05-26 | 3768865 | 2020-05-27
15:20:12 | 3768865 | 2020-05-27 15:20:12 | RT::Transaction |
| | | 0 | 0
19103910 | 27822238 | 375 | 2020-05-27 | 3570362 | 2020-05-27
15:21:30 | 3570362 | 2020-05-27 15:21:30 | RT::Transaction |
| | | 0 | 0
19103921 | 27822243 | 375 | 2020-05-27 | 3768865 | 2020-05-27
15:21:39 | 3768865 | 2020-05-27 15:21:39 | RT::Transaction |
| | | 0 | 0
19103922 | 27822244 | 375 | 2020-05-27 | 3768865 | 2020-05-27
15:21:39 | 3768865 | 2020-05-27 15:21:39 | RT::Transaction |
| | | 0 | 0
19103923 | 27822245 | 375 | 2020-05-27 | 3768865 | 2020-05-27
15:21:39 | 3768865 | 2020-05-27 15:21:39 | RT::Transaction |
| | | 0 | 0
19103924 | 27822246 | 375 | 2020-05-27 | 3768865 | 2020-05-27
15:21:39 | 3768865 | 2020-05-27 15:21:39 | RT::Transaction |
| | | 0 | 0
19103925 | 27822247 | 375 | 2020-05-27 | 3768865 | 2020-05-27
15:21:39 | 3768865 | 2020-05-27 15:21:39 | RT::Transaction |
| | | 0 | 0
19109404 | 27830956 | 375 | 2020-05-27 | 3570362 | 2020-05-27
20:42:58 | 3570362 | 2020-05-27 20:42:58 | RT::Transaction |
| | | 0 | 0
19109462 | 27831009 | 375 | 2020-05-27 | 3570362 | 2020-05-27
20:44:12 | 3570362 | 2020-05-27 20:44:12 | RT::Transaction |
| | | 0 | 0
19115179 | 27840467 | 375 | 2020-05-28 | 3570362 | 2020-05-28
15:28:09 | 3570362 | 2020-05-28 15:28:09 | RT::Transaction |
| | | 0 | 0
19115214 | 27840551 | 375 | 2020-05-28 | 3570362 | 2020-05-28
15:29:59 | 3570362 | 2020-05-28 15:29:59 | RT::Transaction |
| | | 0 | 0
19118472 | 27845963 | 375 | 2020-05-28 | 3570362 | 2020-05-28
18:50:57 | 3570362 | 2020-05-28 18:50:57 | RT::Transaction |
| | | 0 | 0
19127210 | 27860753 | 375 | 2020-05-28 | 3768865 | 2020-05-29
17:22:57 | 3768865 | 2020-05-29 17:22:57 | RT::Transaction |
| | | 0 | 0
19127211 | 27860754 | 375 | 2020-05-28 | 3768865 | 2020-05-29
17:22:57 | 3768865 | 2020-05-29 17:22:57 | RT::Transaction |
| | | 0 | 0
19127212 | 27860755 | 375 | 2020-05-28 | 3768865 | 2020-05-29
17:22:57 | 3768865 | 2020-05-29 17:22:57 | RT::Transaction |
| | | 0 | 0
19127213 | 27860756 | 375 | 2020-05-28 | 3768865 | 2020-05-29
17:22:57 | 3768865 | 2020-05-29 17:22:57 | RT::Transaction |
| | | 0 | 0
19127214 | 27860757 | 375 | 2020-05-28 | 3768865 | 2020-05-29
17:22:57 | 3768865 | 2020-05-29 17:22:57 | RT::Transaction |
| | | 0 | 0
19163910 | 27922577 | 375 | 2020-06-02 | 3768865 | 2020-06-03
20:57:29 | 3768865 | 2020-06-03 20:57:29 | RT::Transaction |
| | | 0 | 0
19163911 | 27922578 | 375 | 2020-06-02 | 3768865 | 2020-06-03
20:57:29 | 3768865 | 2020-06-03 20:57:29 | RT::Transaction |
| | | 0 | 0
19163912 | 27922579 | 375 | 2020-06-02 | 3768865 | 2020-06-03
20:57:29 | 3768865 | 2020-06-03 20:57:29 | RT::Transaction |
| | | 0 | 0
19163913 | 27922580 | 375 | 2020-06-02 | 3768865 | 2020-06-03
20:57:29 | 3768865 | 2020-06-03 20:57:29 | RT::Transaction |
| | | 0 | 0
19163914 | 27922582 | 375 | 2020-06-01 | 3768865 | 2020-06-03
20:57:52 | 3768865 | 2020-06-03 20:57:52 | RT::Transaction |
| | | 0 | 0
19163915 | 27922583 | 375 | 2020-06-01 | 3768865 | 2020-06-03
20:57:52 | 3768865 | 2020-06-03 20:57:52 | RT::Transaction |
| | | 0 | 0
19163916 | 27922584 | 375 | 2020-06-01 | 3768865 | 2020-06-03
20:57:52 | 3768865 | 2020-06-03 20:57:52 | RT::Transaction |
| | | 0 | 0
19186439 | 27960807 | 375 | 2020-06-08 | 3197295 | 2020-06-08
16:18:49 | 3197295 | 2020-06-08 16:18:49 | RT::Transaction |
| | | 0 | 0
19189227 | 27965582 | 375 | 2020-06-08 | 22 | 2020-06-08
19:24:19 | 22 | 2020-06-08 19:24:19 | RT::Transaction |
| | | 0 | 0
19189269 | 27965637 | 375 | 2020-06-08 | 402 | 2020-06-08
19:25:20 | 402 | 2020-06-08 19:25:20 | RT::Transaction |
| | | 0 | 0
19189270 | 27965637 | 376 | 22 | 402 | 2020-06-08
19:25:20 | 402 | 2020-06-08 19:25:20 | RT::Transaction |
| | | 0 | 0
19189271 | 27965638 | 375 | 2020-06-08 | 402 | 2020-06-08
19:25:20 | 402 | 2020-06-08 19:25:20 | RT::Transaction |
| | | 0 | 0
19189272 | 27965638 | 376 | 22 | 402 | 2020-06-08
19:25:20 | 402 | 2020-06-08 19:25:20 | RT::Transaction |
| | | 0 | 0
19193472 | 27972893 | 375 | 2020-06-08 | 3197295 | 2020-06-09
12:21:50 | 3197295 | 2020-06-09 12:21:50 | RT::Transaction |
| | | 0 | 0
19204287 | 27991617 | 375 | 2020-06-10 | 3197295 | 2020-06-10
15:52:41 | 3197295 | 2020-06-10 15:52:41 | RT::Transaction |
| | | 0 | 0
19205446 | 27993528 | 375 | 2020-06-10 | 3768865 | 2020-06-10
17:24:43 | 3768865 | 2020-06-10 17:24:43 | RT::Transaction |
| | | 0 | 0
19226664 | 28019342 | 375 | 2020-06-10 | 3768865 | 2020-06-11
15:24:50 | 3768865 | 2020-06-11 15:24:50 | RT::Transaction |
| | | 0 | 0
19226665 | 28019343 | 375 | 2020-06-10 | 3768865 | 2020-06-11
15:24:50 | 3768865 | 2020-06-11 15:24:50 | RT::Transaction |
| | | 0 | 0
19226666 | 28019344 | 375 | 2020-06-10 | 3768865 | 2020-06-11
15:24:50 | 3768865 | 2020-06-11 15:24:50 | RT::Transaction |
| | | 0 | 0
19226667 | 28019345 | 375 | 2020-06-10 | 3768865 | 2020-06-11
15:24:50 | 3768865 | 2020-06-11 15:24:50 | RT::Transaction |
| | | 0 | 0
19233084 | 28030270 | 375 | 2020-06-12 | 3197295 | 2020-06-12
14:05:00 | 3197295 | 2020-06-12 14:05:00 | RT::Transaction |
| | | 0 | 0
19235815 | 28034687 | 375 | 2020-06-12 | 84 | 2020-06-12
17:57:02 | 84 | 2020-06-12 17:57:02 | RT::Transaction |
| | | 0 | 0
19236305 | 28035519 | 375 | 2020-06-12 | 3197295 | 2020-06-12
18:29:25 | 3197295 | 2020-06-12 18:29:25 | RT::Transaction |
| | | 0 | 0
19236386 | 28035692 | 375 | 2020-06-12 | 3197295 | 2020-06-12
18:36:56 | 3197295 | 2020-06-12 18:36:56 | RT::Transaction |
| | | 0 | 0
19237416 | 28037412 | 375 | 2020-06-12 | 3197295 | 2020-06-12
19:44:36 | 3197295 | 2020-06-12 19:44:36 | RT::Transaction |
| | | 0 | 0
19238015 | 28038402 | 375 | 2020-06-12 | 3768865 | 2020-06-12
20:26:15 | 3768865 | 2020-06-12 20:26:15 | RT::Transaction |
| | | 0 | 0
19238016 | 28038403 | 375 | 2020-06-12 | 3768865 | 2020-06-12
20:26:15 | 3768865 | 2020-06-12 20:26:15 | RT::Transaction |
| | | 0 | 0
19238017 | 28038404 | 375 | 2020-06-12 | 3768865 | 2020-06-12
20:26:15 | 3768865 | 2020-06-12 20:26:15 | RT::Transaction |
| | | 0 | 0
19238018 | 28038405 | 375 | 2020-06-12 | 3768865 | 2020-06-12
20:26:15 | 3768865 | 2020-06-12 20:26:15 | RT::Transaction |
| | | 0 | 0
19238032 | 28038422 | 375 | 2020-06-11 | 3768865 | 2020-06-12
20:26:39 | 3768865 | 2020-06-12 20:26:39 | RT::Transaction |
| | | 0 | 0
19238033 | 28038423 | 375 | 2020-06-11 | 3768865 | 2020-06-12
20:26:39 | 3768865 | 2020-06-12 20:26:39 | RT::Transaction |
| | | 0 | 0
19238034 | 28038424 | 375 | 2020-06-11 | 3768865 | 2020-06-12
20:26:39 | 3768865 | 2020-06-12 20:26:39 | RT::Transaction |
| | | 0 | 0
19238035 | 28038425 | 375 | 2020-06-11 | 3768865 | 2020-06-12
20:26:39 | 3768865 | 2020-06-12 20:26:39 | RT::Transaction |
| | | 0 | 0
19240041 | 28042208 | 375 | 2020-06-14 | 1403795 | 2020-06-14
12:50:47 | 1403795 | 2020-06-14 12:50:47 | RT::Transaction |
| | | 0 | 0
19242958 | 28046818 | 375 | 2020-06-15 | 3570362 | 2020-06-15
14:38:57 | 3570362 | 2020-06-15 14:38:57 | RT::Transaction |
| | | 0 | 0
19255465 | 28067560 | 375 | 2020-06-16 | 3570362 | 2020-06-16
18:41:13 | 3570362 | 2020-06-16 18:41:13 | RT::Transaction |
| | | 0 | 0
19279177 | 28108399 | 375 | 2020-06-18 | 3768865 | 2020-06-19
17:38:39 | 3768865 | 2020-06-19 17:38:39 | RT::Transaction |
| | | 0 | 0
19279178 | 28108400 | 375 | 2020-06-18 | 3768865 | 2020-06-19
17:38:39 | 3768865 | 2020-06-19 17:38:39 | RT::Transaction |
| | | 0 | 0
19279179 | 28108401 | 375 | 2020-06-18 | 3768865 | 2020-06-19
17:38:40 | 3768865 | 2020-06-19 17:38:40 | RT::Transaction |
| | | 0 | 0
19279180 | 28108402 | 375 | 2020-06-18 | 3768865 | 2020-06-19
17:38:40 | 3768865 | 2020-06-19 17:38:40 | RT::Transaction |
| | | 0 | 0
19279193 | 28108419 | 375 | 2020-06-17 | 3768865 | 2020-06-19
17:39:12 | 3768865 | 2020-06-19 17:39:12 | RT::Transaction |
| | | 0 | 0
19279194 | 28108420 | 375 | 2020-06-17 | 3768865 | 2020-06-19
17:39:12 | 3768865 | 2020-06-19 17:39:12 | RT::Transaction |
| | | 0 | 0
19279195 | 28108421 | 375 | 2020-06-17 | 3768865 | 2020-06-19
17:39:12 | 3768865 | 2020-06-19 17:39:12 | RT::Transaction |
| | | 0 | 0
19279196 | 28108422 | 375 | 2020-06-17 | 3768865 | 2020-06-19
17:39:12 | 3768865 | 2020-06-19 17:39:12 | RT::Transaction |
| | | 0 | 0
19279197 | 28108423 | 375 | 2020-06-17 | 3768865 | 2020-06-19
17:39:12 | 3768865 | 2020-06-19 17:39:12 | RT::Transaction |
| | | 0 | 0
They are just the time worked, so I do not understand why it is chosing
the crazy path that it does.
Regards,
Ken
Kenneth Marshall <ktm@rice.edu> writes:
> On Fri, Jun 19, 2020 at 06:10:34PM -0400, Tom Lane wrote:
>> Hmm, does seem like you have some outlier keys. Are any of the keys in
>> the column you're trying to join to larger than 27667772?
> The only values above 27667772? for objectid are:
Sorry, I meant the other join column, ie articles.id.
regards, tom lane
On Fri, Jun 19, 2020 at 05:25:33PM -0500, Kenneth Marshall wrote:
> On Fri, Jun 19, 2020 at 06:10:34PM -0400, Tom Lane wrote:
> > > max(objectcustomfieldvalues.objectid) = 28108423 and here is the
> > > histogram for that column:
> >
> > ... 3304313,3693956,27667772}
> >
> > Hmm, does seem like you have some outlier keys. Are any of the keys in
> > the column you're trying to join to larger than 27667772?
> >
> > regards, tom lane
>
> Hi Tom,
>
> The only values above 27667772? for objectid are:
>
> # select * from objectcustomfieldvalues where objectid > 27667772;
> id | objectid | customfield | content | creator |
> created | lastupdatedby | lastupdated | objecttype |
> largecontent | contenttype | contentencoding | sortorder | disabled
>
----------+----------+-------------+------------+---------+---------------------+---------------+---------------------+-----------------+--------------+-------------+-----------------+-----------+----------
> 19012927 | 27667773 | 375 | 2020-05-12 | 3768865 | 2020-05-13
> 16:10:39 | 3768865 | 2020-05-13 16:10:39 | RT::Transaction |
> | | | 0 | 0
> 19012928 | 27667774 | 375 | 2020-05-12 | 3768865 | 2020-05-13
> 16:10:39 | 3768865 | 2020-05-13 16:10:39 | RT::Transaction |
> | | | 0 | 0
> 19020166 | 27680053 | 375 | 2020-05-14 | 3570362 | 2020-05-14
> 14:14:20 | 3570362 | 2020-05-14 14:14:20 | RT::Transaction |
> | | | 0 | 0
> 19025163 | 27688649 | 375 | 2020-05-13 | 3768865 | 2020-05-14
> 20:27:04 | 3768865 | 2020-05-14 20:27:04 | RT::Transaction |
> | | | 0 | 0
> 19025164 | 27688650 | 375 | 2020-05-13 | 3768865 | 2020-05-14
> 20:27:04 | 3768865 | 2020-05-14 20:27:04 | RT::Transaction |
> | | | 0 | 0
> 19025165 | 27688651 | 375 | 2020-05-13 | 3768865 | 2020-05-14
> 20:27:04 | 3768865 | 2020-05-14 20:27:04 | RT::Transaction |
> | | | 0 | 0
> 19025166 | 27688652 | 375 | 2020-05-13 | 3768865 | 2020-05-14
> 20:27:04 | 3768865 | 2020-05-14 20:27:04 | RT::Transaction |
> | | | 0 | 0
> 19025167 | 27688676 | 375 | 2020-05-14 | 3768865 | 2020-05-14
> 20:27:29 | 3768865 | 2020-05-14 20:27:29 | RT::Transaction |
> | | | 0 | 0
> 19031374 | 27698358 | 375 | 2020-05-13 | 3768865 | 2020-05-15
> 15:32:57 | 3768865 | 2020-05-15 15:32:57 | RT::Transaction |
> | | | 0 | 0
> 19031384 | 27698376 | 375 | 2020-05-14 | 3768865 | 2020-05-15
> 15:33:50 | 3768865 | 2020-05-15 15:33:50 | RT::Transaction |
> | | | 0 | 0
> 19031385 | 27698377 | 375 | 2020-05-14 | 3768865 | 2020-05-15
> 15:33:50 | 3768865 | 2020-05-15 15:33:50 | RT::Transaction |
> | | | 0 | 0
> 19033205 | 27701391 | 375 | 2020-05-15 | 3197295 | 2020-05-15
> 18:21:36 | 3197295 | 2020-05-15 18:21:36 | RT::Transaction |
> | | | 0 | 0
> 19042369 | 27715839 | 375 | 2020-05-18 | 1403795 | 2020-05-18
> 14:12:35 | 1403795 | 2020-05-18 14:12:35 | RT::Transaction |
> | | | 0 | 0
> 19047274 | 27723981 | 375 | 2020-05-18 | 3197295 | 2020-05-18
> 19:29:14 | 3197295 | 2020-05-18 19:29:14 | RT::Transaction |
> | | | 0 | 0
> 19048566 | 27726800 | 375 | 2020-05-18 | 3768865 | 2020-05-18
> 20:23:18 | 3768865 | 2020-05-18 20:23:18 | RT::Transaction |
> | | | 0 | 0
> 19048567 | 27726801 | 375 | 2020-05-18 | 3768865 | 2020-05-18
> 20:23:18 | 3768865 | 2020-05-18 20:23:18 | RT::Transaction |
> | | | 0 | 0
> 19048568 | 27726802 | 375 | 2020-05-18 | 3768865 | 2020-05-18
> 20:23:18 | 3768865 | 2020-05-18 20:23:18 | RT::Transaction |
> | | | 0 | 0
> 19048569 | 27726803 | 375 | 2020-05-18 | 3768865 | 2020-05-18
> 20:23:18 | 3768865 | 2020-05-18 20:23:18 | RT::Transaction |
> | | | 0 | 0
> 19048570 | 27726804 | 375 | 2020-05-18 | 3768865 | 2020-05-18
> 20:23:18 | 3768865 | 2020-05-18 20:23:18 | RT::Transaction |
> | | | 0 | 0
> 19048571 | 27726805 | 375 | 2020-05-18 | 3768865 | 2020-05-18
> 20:23:18 | 3768865 | 2020-05-18 20:23:18 | RT::Transaction |
> | | | 0 | 0
> 19048572 | 27726806 | 375 | 2020-05-18 | 3768865 | 2020-05-18
> 20:23:19 | 3768865 | 2020-05-18 20:23:19 | RT::Transaction |
> | | | 0 | 0
> 19048573 | 27726807 | 375 | 2020-05-18 | 3768865 | 2020-05-18
> 20:23:19 | 3768865 | 2020-05-18 20:23:19 | RT::Transaction |
> | | | 0 | 0
> 19048574 | 27726808 | 375 | 2020-05-18 | 3768865 | 2020-05-18
> 20:23:19 | 3768865 | 2020-05-18 20:23:19 | RT::Transaction |
> | | | 0 | 0
> 19054502 | 27738410 | 375 | 2020-05-19 | 3197295 | 2020-05-19
> 15:01:50 | 3197295 | 2020-05-19 15:01:50 | RT::Transaction |
> | | | 0 | 0
> 19056348 | 27741653 | 375 | 2020-05-19 | 3768865 | 2020-05-19
> 16:39:01 | 3768865 | 2020-05-19 16:39:01 | RT::Transaction |
> | | | 0 | 0
> 19056349 | 27741654 | 375 | 2020-05-19 | 3768865 | 2020-05-19
> 16:39:01 | 3768865 | 2020-05-19 16:39:01 | RT::Transaction |
> | | | 0 | 0
> 19056350 | 27741655 | 375 | 2020-05-19 | 3768865 | 2020-05-19
> 16:39:02 | 3768865 | 2020-05-19 16:39:02 | RT::Transaction |
> | | | 0 | 0
> 19056351 | 27741656 | 375 | 2020-05-19 | 3768865 | 2020-05-19
> 16:39:02 | 3768865 | 2020-05-19 16:39:02 | RT::Transaction |
> | | | 0 | 0
> 19056352 | 27741657 | 375 | 2020-05-19 | 3768865 | 2020-05-19
> 16:39:02 | 3768865 | 2020-05-19 16:39:02 | RT::Transaction |
> | | | 0 | 0
> 19056362 | 27741667 | 375 | 2020-05-19 | 3768865 | 2020-05-19
> 16:39:29 | 3768865 | 2020-05-19 16:39:29 | RT::Transaction |
> | | | 0 | 0
> 19057464 | 27743793 | 375 | 2020-05-19 | 3197295 | 2020-05-19
> 18:03:16 | 3197295 | 2020-05-19 18:03:16 | RT::Transaction |
> | | | 0 | 0
> 19067180 | 27760343 | 375 | 2020-05-20 | 1403795 | 2020-05-20
> 18:01:59 | 1403795 | 2020-05-20 18:01:59 | RT::Transaction |
> | | | 0 | 0
> 19067476 | 27760892 | 375 | 2020-05-19 | 3197295 | 2020-05-20
> 18:23:48 | 3197295 | 2020-05-20 18:23:48 | RT::Transaction |
> | | | 0 | 0
> 19073560 | 27771129 | 375 | 2020-05-21 | 3197295 | 2020-05-21
> 14:15:54 | 3197295 | 2020-05-21 14:15:54 | RT::Transaction |
> | | | 0 | 0
> 19074011 | 27771902 | 375 | 2020-05-21 | 3570362 | 2020-05-21
> 15:02:49 | 3570362 | 2020-05-21 15:02:49 | RT::Transaction |
> | | | 0 | 0
> 19081811 | 27784951 | 375 | 2020-05-22 | 2960471 | 2020-05-22
> 14:52:40 | 2960471 | 2020-05-22 14:52:40 | RT::Transaction |
> | | | 0 | 0
> 19093560 | 27804234 | 375 | 2020-05-26 | 3570362 | 2020-05-26
> 15:00:29 | 3570362 | 2020-05-26 15:00:29 | RT::Transaction |
> | | | 0 | 0
> 19094043 | 27805100 | 375 | 2020-05-26 | 3570362 | 2020-05-26
> 15:30:15 | 3570362 | 2020-05-26 15:30:15 | RT::Transaction |
> | | | 0 | 0
> 19094798 | 27806250 | 375 | 2020-05-26 | 3570362 | 2020-05-26
> 15:59:22 | 3570362 | 2020-05-26 15:59:22 | RT::Transaction |
> | | | 0 | 0
> 19103803 | 27822098 | 375 | 2020-05-27 | 3570362 | 2020-05-27
> 15:15:37 | 3570362 | 2020-05-27 15:15:37 | RT::Transaction |
> | | | 0 | 0
> 19103893 | 27822211 | 375 | 2020-05-26 | 3768865 | 2020-05-27
> 15:20:11 | 3768865 | 2020-05-27 15:20:11 | RT::Transaction |
> | | | 0 | 0
> 19103894 | 27822212 | 375 | 2020-05-26 | 3768865 | 2020-05-27
> 15:20:12 | 3768865 | 2020-05-27 15:20:12 | RT::Transaction |
> | | | 0 | 0
> 19103895 | 27822213 | 375 | 2020-05-26 | 3768865 | 2020-05-27
> 15:20:12 | 3768865 | 2020-05-27 15:20:12 | RT::Transaction |
> | | | 0 | 0
> 19103896 | 27822214 | 375 | 2020-05-26 | 3768865 | 2020-05-27
> 15:20:12 | 3768865 | 2020-05-27 15:20:12 | RT::Transaction |
> | | | 0 | 0
> 19103897 | 27822215 | 375 | 2020-05-26 | 3768865 | 2020-05-27
> 15:20:12 | 3768865 | 2020-05-27 15:20:12 | RT::Transaction |
> | | | 0 | 0
> 19103898 | 27822216 | 375 | 2020-05-26 | 3768865 | 2020-05-27
> 15:20:12 | 3768865 | 2020-05-27 15:20:12 | RT::Transaction |
> | | | 0 | 0
> 19103899 | 27822217 | 375 | 2020-05-26 | 3768865 | 2020-05-27
> 15:20:12 | 3768865 | 2020-05-27 15:20:12 | RT::Transaction |
> | | | 0 | 0
> 19103910 | 27822238 | 375 | 2020-05-27 | 3570362 | 2020-05-27
> 15:21:30 | 3570362 | 2020-05-27 15:21:30 | RT::Transaction |
> | | | 0 | 0
> 19103921 | 27822243 | 375 | 2020-05-27 | 3768865 | 2020-05-27
> 15:21:39 | 3768865 | 2020-05-27 15:21:39 | RT::Transaction |
> | | | 0 | 0
> 19103922 | 27822244 | 375 | 2020-05-27 | 3768865 | 2020-05-27
> 15:21:39 | 3768865 | 2020-05-27 15:21:39 | RT::Transaction |
> | | | 0 | 0
> 19103923 | 27822245 | 375 | 2020-05-27 | 3768865 | 2020-05-27
> 15:21:39 | 3768865 | 2020-05-27 15:21:39 | RT::Transaction |
> | | | 0 | 0
> 19103924 | 27822246 | 375 | 2020-05-27 | 3768865 | 2020-05-27
> 15:21:39 | 3768865 | 2020-05-27 15:21:39 | RT::Transaction |
> | | | 0 | 0
> 19103925 | 27822247 | 375 | 2020-05-27 | 3768865 | 2020-05-27
> 15:21:39 | 3768865 | 2020-05-27 15:21:39 | RT::Transaction |
> | | | 0 | 0
> 19109404 | 27830956 | 375 | 2020-05-27 | 3570362 | 2020-05-27
> 20:42:58 | 3570362 | 2020-05-27 20:42:58 | RT::Transaction |
> | | | 0 | 0
> 19109462 | 27831009 | 375 | 2020-05-27 | 3570362 | 2020-05-27
> 20:44:12 | 3570362 | 2020-05-27 20:44:12 | RT::Transaction |
> | | | 0 | 0
> 19115179 | 27840467 | 375 | 2020-05-28 | 3570362 | 2020-05-28
> 15:28:09 | 3570362 | 2020-05-28 15:28:09 | RT::Transaction |
> | | | 0 | 0
> 19115214 | 27840551 | 375 | 2020-05-28 | 3570362 | 2020-05-28
> 15:29:59 | 3570362 | 2020-05-28 15:29:59 | RT::Transaction |
> | | | 0 | 0
> 19118472 | 27845963 | 375 | 2020-05-28 | 3570362 | 2020-05-28
> 18:50:57 | 3570362 | 2020-05-28 18:50:57 | RT::Transaction |
> | | | 0 | 0
> 19127210 | 27860753 | 375 | 2020-05-28 | 3768865 | 2020-05-29
> 17:22:57 | 3768865 | 2020-05-29 17:22:57 | RT::Transaction |
> | | | 0 | 0
> 19127211 | 27860754 | 375 | 2020-05-28 | 3768865 | 2020-05-29
> 17:22:57 | 3768865 | 2020-05-29 17:22:57 | RT::Transaction |
> | | | 0 | 0
> 19127212 | 27860755 | 375 | 2020-05-28 | 3768865 | 2020-05-29
> 17:22:57 | 3768865 | 2020-05-29 17:22:57 | RT::Transaction |
> | | | 0 | 0
> 19127213 | 27860756 | 375 | 2020-05-28 | 3768865 | 2020-05-29
> 17:22:57 | 3768865 | 2020-05-29 17:22:57 | RT::Transaction |
> | | | 0 | 0
> 19127214 | 27860757 | 375 | 2020-05-28 | 3768865 | 2020-05-29
> 17:22:57 | 3768865 | 2020-05-29 17:22:57 | RT::Transaction |
> | | | 0 | 0
> 19163910 | 27922577 | 375 | 2020-06-02 | 3768865 | 2020-06-03
> 20:57:29 | 3768865 | 2020-06-03 20:57:29 | RT::Transaction |
> | | | 0 | 0
> 19163911 | 27922578 | 375 | 2020-06-02 | 3768865 | 2020-06-03
> 20:57:29 | 3768865 | 2020-06-03 20:57:29 | RT::Transaction |
> | | | 0 | 0
> 19163912 | 27922579 | 375 | 2020-06-02 | 3768865 | 2020-06-03
> 20:57:29 | 3768865 | 2020-06-03 20:57:29 | RT::Transaction |
> | | | 0 | 0
> 19163913 | 27922580 | 375 | 2020-06-02 | 3768865 | 2020-06-03
> 20:57:29 | 3768865 | 2020-06-03 20:57:29 | RT::Transaction |
> | | | 0 | 0
> 19163914 | 27922582 | 375 | 2020-06-01 | 3768865 | 2020-06-03
> 20:57:52 | 3768865 | 2020-06-03 20:57:52 | RT::Transaction |
> | | | 0 | 0
> 19163915 | 27922583 | 375 | 2020-06-01 | 3768865 | 2020-06-03
> 20:57:52 | 3768865 | 2020-06-03 20:57:52 | RT::Transaction |
> | | | 0 | 0
> 19163916 | 27922584 | 375 | 2020-06-01 | 3768865 | 2020-06-03
> 20:57:52 | 3768865 | 2020-06-03 20:57:52 | RT::Transaction |
> | | | 0 | 0
> 19186439 | 27960807 | 375 | 2020-06-08 | 3197295 | 2020-06-08
> 16:18:49 | 3197295 | 2020-06-08 16:18:49 | RT::Transaction |
> | | | 0 | 0
> 19189227 | 27965582 | 375 | 2020-06-08 | 22 | 2020-06-08
> 19:24:19 | 22 | 2020-06-08 19:24:19 | RT::Transaction |
> | | | 0 | 0
> 19189269 | 27965637 | 375 | 2020-06-08 | 402 | 2020-06-08
> 19:25:20 | 402 | 2020-06-08 19:25:20 | RT::Transaction |
> | | | 0 | 0
> 19189270 | 27965637 | 376 | 22 | 402 | 2020-06-08
> 19:25:20 | 402 | 2020-06-08 19:25:20 | RT::Transaction |
> | | | 0 | 0
> 19189271 | 27965638 | 375 | 2020-06-08 | 402 | 2020-06-08
> 19:25:20 | 402 | 2020-06-08 19:25:20 | RT::Transaction |
> | | | 0 | 0
> 19189272 | 27965638 | 376 | 22 | 402 | 2020-06-08
> 19:25:20 | 402 | 2020-06-08 19:25:20 | RT::Transaction |
> | | | 0 | 0
> 19193472 | 27972893 | 375 | 2020-06-08 | 3197295 | 2020-06-09
> 12:21:50 | 3197295 | 2020-06-09 12:21:50 | RT::Transaction |
> | | | 0 | 0
> 19204287 | 27991617 | 375 | 2020-06-10 | 3197295 | 2020-06-10
> 15:52:41 | 3197295 | 2020-06-10 15:52:41 | RT::Transaction |
> | | | 0 | 0
> 19205446 | 27993528 | 375 | 2020-06-10 | 3768865 | 2020-06-10
> 17:24:43 | 3768865 | 2020-06-10 17:24:43 | RT::Transaction |
> | | | 0 | 0
> 19226664 | 28019342 | 375 | 2020-06-10 | 3768865 | 2020-06-11
> 15:24:50 | 3768865 | 2020-06-11 15:24:50 | RT::Transaction |
> | | | 0 | 0
> 19226665 | 28019343 | 375 | 2020-06-10 | 3768865 | 2020-06-11
> 15:24:50 | 3768865 | 2020-06-11 15:24:50 | RT::Transaction |
> | | | 0 | 0
> 19226666 | 28019344 | 375 | 2020-06-10 | 3768865 | 2020-06-11
> 15:24:50 | 3768865 | 2020-06-11 15:24:50 | RT::Transaction |
> | | | 0 | 0
> 19226667 | 28019345 | 375 | 2020-06-10 | 3768865 | 2020-06-11
> 15:24:50 | 3768865 | 2020-06-11 15:24:50 | RT::Transaction |
> | | | 0 | 0
> 19233084 | 28030270 | 375 | 2020-06-12 | 3197295 | 2020-06-12
> 14:05:00 | 3197295 | 2020-06-12 14:05:00 | RT::Transaction |
> | | | 0 | 0
> 19235815 | 28034687 | 375 | 2020-06-12 | 84 | 2020-06-12
> 17:57:02 | 84 | 2020-06-12 17:57:02 | RT::Transaction |
> | | | 0 | 0
> 19236305 | 28035519 | 375 | 2020-06-12 | 3197295 | 2020-06-12
> 18:29:25 | 3197295 | 2020-06-12 18:29:25 | RT::Transaction |
> | | | 0 | 0
> 19236386 | 28035692 | 375 | 2020-06-12 | 3197295 | 2020-06-12
> 18:36:56 | 3197295 | 2020-06-12 18:36:56 | RT::Transaction |
> | | | 0 | 0
> 19237416 | 28037412 | 375 | 2020-06-12 | 3197295 | 2020-06-12
> 19:44:36 | 3197295 | 2020-06-12 19:44:36 | RT::Transaction |
> | | | 0 | 0
> 19238015 | 28038402 | 375 | 2020-06-12 | 3768865 | 2020-06-12
> 20:26:15 | 3768865 | 2020-06-12 20:26:15 | RT::Transaction |
> | | | 0 | 0
> 19238016 | 28038403 | 375 | 2020-06-12 | 3768865 | 2020-06-12
> 20:26:15 | 3768865 | 2020-06-12 20:26:15 | RT::Transaction |
> | | | 0 | 0
> 19238017 | 28038404 | 375 | 2020-06-12 | 3768865 | 2020-06-12
> 20:26:15 | 3768865 | 2020-06-12 20:26:15 | RT::Transaction |
> | | | 0 | 0
> 19238018 | 28038405 | 375 | 2020-06-12 | 3768865 | 2020-06-12
> 20:26:15 | 3768865 | 2020-06-12 20:26:15 | RT::Transaction |
> | | | 0 | 0
> 19238032 | 28038422 | 375 | 2020-06-11 | 3768865 | 2020-06-12
> 20:26:39 | 3768865 | 2020-06-12 20:26:39 | RT::Transaction |
> | | | 0 | 0
> 19238033 | 28038423 | 375 | 2020-06-11 | 3768865 | 2020-06-12
> 20:26:39 | 3768865 | 2020-06-12 20:26:39 | RT::Transaction |
> | | | 0 | 0
> 19238034 | 28038424 | 375 | 2020-06-11 | 3768865 | 2020-06-12
> 20:26:39 | 3768865 | 2020-06-12 20:26:39 | RT::Transaction |
> | | | 0 | 0
> 19238035 | 28038425 | 375 | 2020-06-11 | 3768865 | 2020-06-12
> 20:26:39 | 3768865 | 2020-06-12 20:26:39 | RT::Transaction |
> | | | 0 | 0
> 19240041 | 28042208 | 375 | 2020-06-14 | 1403795 | 2020-06-14
> 12:50:47 | 1403795 | 2020-06-14 12:50:47 | RT::Transaction |
> | | | 0 | 0
> 19242958 | 28046818 | 375 | 2020-06-15 | 3570362 | 2020-06-15
> 14:38:57 | 3570362 | 2020-06-15 14:38:57 | RT::Transaction |
> | | | 0 | 0
> 19255465 | 28067560 | 375 | 2020-06-16 | 3570362 | 2020-06-16
> 18:41:13 | 3570362 | 2020-06-16 18:41:13 | RT::Transaction |
> | | | 0 | 0
> 19279177 | 28108399 | 375 | 2020-06-18 | 3768865 | 2020-06-19
> 17:38:39 | 3768865 | 2020-06-19 17:38:39 | RT::Transaction |
> | | | 0 | 0
> 19279178 | 28108400 | 375 | 2020-06-18 | 3768865 | 2020-06-19
> 17:38:39 | 3768865 | 2020-06-19 17:38:39 | RT::Transaction |
> | | | 0 | 0
> 19279179 | 28108401 | 375 | 2020-06-18 | 3768865 | 2020-06-19
> 17:38:40 | 3768865 | 2020-06-19 17:38:40 | RT::Transaction |
> | | | 0 | 0
> 19279180 | 28108402 | 375 | 2020-06-18 | 3768865 | 2020-06-19
> 17:38:40 | 3768865 | 2020-06-19 17:38:40 | RT::Transaction |
> | | | 0 | 0
> 19279193 | 28108419 | 375 | 2020-06-17 | 3768865 | 2020-06-19
> 17:39:12 | 3768865 | 2020-06-19 17:39:12 | RT::Transaction |
> | | | 0 | 0
> 19279194 | 28108420 | 375 | 2020-06-17 | 3768865 | 2020-06-19
> 17:39:12 | 3768865 | 2020-06-19 17:39:12 | RT::Transaction |
> | | | 0 | 0
> 19279195 | 28108421 | 375 | 2020-06-17 | 3768865 | 2020-06-19
> 17:39:12 | 3768865 | 2020-06-19 17:39:12 | RT::Transaction |
> | | | 0 | 0
> 19279196 | 28108422 | 375 | 2020-06-17 | 3768865 | 2020-06-19
> 17:39:12 | 3768865 | 2020-06-19 17:39:12 | RT::Transaction |
> | | | 0 | 0
> 19279197 | 28108423 | 375 | 2020-06-17 | 3768865 | 2020-06-19
> 17:39:12 | 3768865 | 2020-06-19 17:39:12 | RT::Transaction |
> | | | 0 | 0
>
>
> They are just the time worked, so I do not understand why it is chosing
> the crazy path that it does.
>
> Regards,
> Ken
>
Here is another query that is showing the same selection of an index
scan when without it is is soooo much faster:
# explain (analyze,buffers) SELECT COUNT(DISTINCT main.id) FROM Assets
# main JOIN Groups Groups_1 ON ( LOWER(Groups_1.Domain) =
# 'rt::asset-role' ) AND ( Groups_1.Instance = main.id ) JOIN
# CachedGroupMembers CachedGroupMembers_2 ON (
# CachedGroupMembers_2.Disabled = '0' ) AND (
# CachedGroupMembers_2.GroupId = Groups_1.id ) WHERE ( (
# CachedGroupMembers_2.MemberId = '151395' ) ) AND (LOWER(main.Status)
# != 'deleted');
QUERY
PLAN
---------------------------------------------------------------------------------------------------------------------------------------------------------
Aggregate (cost=12488.19..12488.20 rows=1 width=8) (actual
time=46.438..46.439 rows=1 loops=1)
Buffers: shared hit=40111
-> Nested Loop (cost=364.48..12488.19 rows=1 width=4) (actual
time=46.402..46.402 rows=0 loops=1)
Buffers: shared hit=40111
-> Hash Join (cost=363.16..12343.59 rows=59 width=8) (actual
time=4.111..11.633 rows=13194 loops=1)
Hash Cond: (groups_1.instance = main.id)
Buffers: shared hit=529
-> Bitmap Heap Scan on groups groups_1
(cost=186.22..12132.46 rows=13028 width=8) (actual time=0.918..3.492
rows=13380 loops=1)
Recheck Cond: (lower((domain)::text) =
'rt::asset-role'::text)
Heap Blocks: exact=390
Buffers: shared hit=474
-> Bitmap Index Scan on groups2
(cost=0.00..182.97 rows=13028 width=0) (actual time=0.879..0.879
rows=13380 loops=1)
Index Cond: (lower((domain)::text) =
'rt::asset-role'::text)
Buffers: shared hit=84
-> Hash (cost=121.66..121.66 rows=4422 width=4) (actual
time=3.174..3.174 rows=4398 loops=1)
Buckets: 8192 Batches: 1 Memory Usage: 219kB
Buffers: shared hit=55
-> Seq Scan on assets main (cost=0.00..121.66
rows=4422 width=4) (actual time=0.014..2.425 rows=4398 loops=1)
Filter: (lower((status)::text) <>
'deleted'::text)
Rows Removed by Filter: 47
Buffers: shared hit=55
-> Bitmap Heap Scan on cachedgroupmembers cachedgroupmembers_2
(cost=1.32..2.44 rows=1 width=4) (actual time=0.002..0.002 rows=0
loops=13194)
Recheck Cond: ((groupid = groups_1.id) AND (memberid =
151395) AND (disabled = '0'::smallint))
Buffers: shared hit=39582
-> Bitmap Index Scan on disgroumem (cost=0.00..1.32
rows=1 width=0) (actual time=0.002..0.002 rows=0 loops=13194)
Index Cond: ((groupid = groups_1.id) AND (memberid
= 151395) AND (disabled = '0'::smallint))
Buffers: shared hit=39582
Planning Time: 0.520 ms
Execution Time: 46.503 ms
(29 rows)
And with enable_indexscan = 1;
# explain (analyze,buffers) SELECT COUNT(DISTINCT main.id) FROM Assets
# main JOIN Groups Groups_1 ON ( LOWER(Groups_1.Domain) =
# 'rt::asset-role' ) AND ( Groups_1.Instance = main.id ) JOIN
# CachedGroupMembers CachedGroupMembers_2 ON (
# CachedGroupMembers_2.Disabled = '0' ) AND (
# CachedGroupMembers_2.GroupId = Groups_1.id ) WHERE ( (
# CachedGroupMembers_2.MemberId = '151395' ) ) AND (LOWER(main.Status)
# != 'deleted');
QUERY
PLAN
-------------------------------------------------------------------------------------------------------------------------------------------------------------------------
Aggregate (cost=563.50..563.51 rows=1 width=8) (actual
time=2626.584..2626.585 rows=1 loops=1)
Buffers: shared hit=172390
-> Nested Loop (cost=11.13..563.50 rows=1 width=4) (actual
time=2626.568..2626.568 rows=0 loops=1)
Buffers: shared hit=172390
-> Merge Join (cost=10.70..482.35 rows=59 width=8) (actual
time=0.352..2599.829 rows=13194 loops=1)
Merge Cond: (main.id = groups_1.instance)
Buffers: shared hit=132808
-> Index Scan using assets_pkey on assets main
(cost=0.28..160.81 rows=4422 width=4) (actual time=0.039..3.578
rows=4398 loops=1)
Filter: (lower((status)::text) <> 'deleted'::text)
Rows Removed by Filter: 47
Buffers: shared hit=103
-> Index Scan using groups3 on groups groups_1
(cost=0.43..130022.48 rows=13028 width=8) (actual time=0.296..2592.141
rows=13380 loops=1)
Filter: (lower((domain)::text) =
'rt::asset-role'::text)
Rows Removed by Filter: 3853979
Buffers: shared hit=132705
-> Index Only Scan using disgroumem on cachedgroupmembers
cachedgroupmembers_2 (cost=0.43..1.37 rows=1 width=4) (actual
time=0.002..0.002 rows=0 loops=13194)
Index Cond: ((groupid = groups_1.id) AND (memberid =
151395) AND (disabled = '0'::smallint))
Heap Fetches: 0
Buffers: shared hit=39582
Planning Time: 0.562 ms
Execution Time: 2626.651 ms
(21 rows)
I'm not sure if it is just a pathological interaction of this
application with PostgreSQL or something I need to fix. Ideally, I could
figure out a way to have PostgreSQL do it automatically.
Regards,
Ken
[ please keep the mailing list cc'd ]
Kenneth Marshall <ktm@rice.edu> writes:
> Here are the stats for articles.id:
> 4,7,9,11,13,14,16,17,18,19,20,21,22,23,
> 24,25,26,32,33,34,36,40,41,42,43,44,49,50,51,52,53,54,55,56,57,58,59,60,61,62,63,99,100,101,102,106,107,108,109,113,1
14,115,116,117,118,119,120,121,122,123,125,126,127,128,129,130,131,133,134,135,136,137,140,141,142,143,144,145,146,14
7,148,149,150,151,152,153,155,156,157,158,159,160,161,162,163,164,165,166,167,168,169,170,171,172,173,174,175,176,177
,178,179,180,181,182,183,184,185,186,187,188,189,190,191,192,193,194,195,196,197,198,199,200,201,202,203,204,205,206,
207,208,1209,1210,1212,1213,1214,1215,1216,1219,1220,1221,1222,1223}
> That completely matches the max(id) for articles.id.
Hm, well it's clear why the planner is going for the mergejoin strategy:
it expects to only have to scan a very small fraction of the other table
before it's up past objectid = 1223 and can stop merging. And it
seems like it's right ...
... oh, now I see: apparently, your filter condition is such that *no*
rows of the objectcustomfieldvalues table get past the filter:
-> Index Scan using objectcustomfieldvalues3 on objectcustomfieldvalues objectcustomfieldvalues_1
(cost=0.56..807603.40rows=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
"rows=0" is the telltale. So even after we're past objectid = 1223, that
scan continues, because the mergejoin needs to see a higher key before it
knows it can stop.
That's kind of annoying :-(. I wonder if there's a way to be smarter?
This case would work a lot better if the filter conditions were not
applied till after the merge; but of course that wouldn't be an
improvement in general. Or maybe we should penalize the mergejoin
cost estimate if there's a highly selective filter in the way.
(It does look like the planner is correctly estimating that the
filter is quite selective --- it's just not considering the potential
impact on the scan-until-finding-a-greater-key behavior.)
Right now I don't have any better suggestion than disabling mergejoin
if you think the filter is going to be very selective.
regards, tom lane
I wrote:
> ... oh, now I see: apparently, your filter condition is such that *no*
> rows of the objectcustomfieldvalues table get past the filter:
>
> -> Index Scan using objectcustomfieldvalues3 on objectcustomfieldvalues objectcustomfieldvalues_1
(cost=0.56..807603.40rows=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
> That's kind of annoying :-(. I wonder if there's a way to be smarter?
> This case would work a lot better if the filter conditions were not
> applied till after the merge; but of course that wouldn't be an
> improvement in general. Or maybe we should penalize the mergejoin
> cost estimate if there's a highly selective filter in the way.
I experimented with this some more, with the intention of creating a
planner patch that would do the latter, and was surprised to find that
there already is such a penalty. It's sort of indirect and undocumented,
but nonetheless the estimate for whether a mergejoin can stop early
does get heavily de-rated if the planner realizes that the table is
being heavily filtered. So now I'm thinking that your problem is that
"rows=915" is not a good enough estimate of what will happen in this
indexscan. It looks good in comparison to the table size of 19M rows,
but on a percentage basis compared to the true value of 0 rows, it's
still pretty bad. You said you'd increased the stats target for
objectcustomfieldvalues.objectid, but maybe the real problem is needing
to increase the targets for content and largecontent, in hopes of driving
down the estimate for how many rows will pass this filter condition.
regards, tom lane
On Sat, Jun 20, 2020 at 02:22:03PM -0400, Tom Lane wrote:
> I wrote:
> > ... oh, now I see: apparently, your filter condition is such that *no*
> > rows of the objectcustomfieldvalues table get past the filter:
> >
> > -> Index Scan using objectcustomfieldvalues3 on objectcustomfieldvalues objectcustomfieldvalues_1
(cost=0.56..807603.40rows=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
>
> > That's kind of annoying :-(. I wonder if there's a way to be smarter?
> > This case would work a lot better if the filter conditions were not
> > applied till after the merge; but of course that wouldn't be an
> > improvement in general. Or maybe we should penalize the mergejoin
> > cost estimate if there's a highly selective filter in the way.
>
> I experimented with this some more, with the intention of creating a
> planner patch that would do the latter, and was surprised to find that
> there already is such a penalty. It's sort of indirect and undocumented,
> but nonetheless the estimate for whether a mergejoin can stop early
> does get heavily de-rated if the planner realizes that the table is
> being heavily filtered. So now I'm thinking that your problem is that
> "rows=915" is not a good enough estimate of what will happen in this
> indexscan. It looks good in comparison to the table size of 19M rows,
> but on a percentage basis compared to the true value of 0 rows, it's
> still pretty bad. You said you'd increased the stats target for
> objectcustomfieldvalues.objectid, but maybe the real problem is needing
> to increase the targets for content and largecontent, in hopes of driving
> down the estimate for how many rows will pass this filter condition.
>
> regards, tom lane
Hi Tom,
I increased the statistics on the content field because it had the most
values (19000000) versus largecontent (1000). When I reached 8000, the
plan changed to:
# explain (analyze,buffers) 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=1151.07..1151.10 rows=1 width=137) (actual time=1.782..1.782 rows=0 loops=1)
Buffers: shared hit=158
-> Sort (cost=1151.07..1151.08 rows=1 width=137) (actual time=1.781..1.781 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
Buffers: shared hit=158
-> Hash Join (cost=185.12..1151.06 rows=1 width=137) (actual time=1.777..1.777 rows=0 loops=1)
Hash Cond: (objectcustomfieldvalues_1.objectid = main.id)
Buffers: shared hit=158
-> Bitmap Heap Scan on objectcustomfieldvalues objectcustomfieldvalues_1 (cost=177.36..1141.46
rows=699width=4) (actual time=1.704..1.704 rows=0 loops=1)
Recheck Cond: ((largecontent ~~* '%958575%'::text) OR ((content)::text ~~* '%958575%'::text))
Filter: (disabled = 0)
Buffers: shared hit=154
-> BitmapOr (cost=177.36..177.36 rows=868 width=0) (actual time=1.703..1.703 rows=0 loops=1)
Buffers: shared hit=154
-> Bitmap Index Scan on objectcustomfieldvalues_largecontent_trgm (cost=0.00..30.80 rows=1
width=0)(actual time=0.282..0.282 rows=0 loops=1)
Index Cond: (largecontent ~~* '%958575%'::text)
Buffers: shared hit=28
-> Bitmap Index Scan on objectcustomfieldvalues_content_trgm (cost=0.00..146.21 rows=868
width=0)(actual time=1.421..1.421 rows=0 loops=1)
Index Cond: ((content)::text ~~* '%958575%'::text)
Buffers: shared hit=126
-> Hash (cost=5.91..5.91 rows=148 width=137) (actual time=0.071..0.071 rows=148 loops=1)
Buckets: 1024 Batches: 1 Memory Usage: 34kB
Buffers: shared hit=4
-> Seq Scan on articles main (cost=0.00..5.91 rows=148 width=137) (actual time=0.007..0.044
rows=148loops=1)
Filter: (disabled = '0'::smallint)
Rows Removed by Filter: 5
Buffers: shared hit=4
Planning Time: 15.568 ms
Execution Time: 1.818 ms
(30 rows)
Time: 17.679 ms
It is too bad that the statistics target has to be set that high to
choose correctly. I wonder if this class of problem would be handled by
some of the ideas discussed in other threads about pessimizing plans
that have exteremely large downsides. Thank you again for looking into
this and I have learned a lot.
Regards,
Ken
On 2020-Jun-20, Tom Lane wrote: > I wrote: > > ... oh, now I see: apparently, your filter condition is such that *no* > > rows of the objectcustomfieldvalues table get past the filter: > > > > -> Index Scan using objectcustomfieldvalues3 on objectcustomfieldvalues objectcustomfieldvalues_1 (cost=0.56..807603.40rows=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 > You said you'd increased the stats target for > objectcustomfieldvalues.objectid, but maybe the real problem is needing > to increase the targets for content and largecontent, in hopes of driving > down the estimate for how many rows will pass this filter condition. ... but those on content and largecontent are unanchored conditions -- are we still able to do any cardinality analysis using those? I thought not. Maybe a trigram search would help? See contrib/pg_trgm -- as far as I remember that module is able to work with LIKE conditions. -- Álvaro Herrera https://www.2ndQuadrant.com/ PostgreSQL Development, 24x7 Support, Remote DBA, Training & Services
On Mon, Jun 22, 2020 at 03:27:32PM -0400, Alvaro Herrera wrote: > On 2020-Jun-20, Tom Lane wrote: > > > I wrote: > > > ... oh, now I see: apparently, your filter condition is such that *no* > > > rows of the objectcustomfieldvalues table get past the filter: > > > > > > -> Index Scan using objectcustomfieldvalues3 on objectcustomfieldvalues objectcustomfieldvalues_1 (cost=0.56..807603.40rows=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 > > > You said you'd increased the stats target for > > objectcustomfieldvalues.objectid, but maybe the real problem is needing > > to increase the targets for content and largecontent, in hopes of driving > > down the estimate for how many rows will pass this filter condition. > > ... but those on content and largecontent are unanchored conditions -- > are we still able to do any cardinality analysis using those? I thought > not. Maybe a trigram search would help? See contrib/pg_trgm -- as far > as I remember that module is able to work with LIKE conditions. > Hi Alvaro, I do have a pg_trgm GIN index on those fields for the search. Regards, Ken
Alvaro Herrera <alvherre@2ndquadrant.com> writes:
> On 2020-Jun-20, Tom Lane wrote:
>> You said you'd increased the stats target for
>> objectcustomfieldvalues.objectid, but maybe the real problem is needing
>> to increase the targets for content and largecontent, in hopes of driving
>> down the estimate for how many rows will pass this filter condition.
> ... but those on content and largecontent are unanchored conditions --
> are we still able to do any cardinality analysis using those?
Yes, if the stats histogram is large enough we'll apply it by just
evaluating the query operator verbatim on each entry (thereby assuming
that the histogram is usable as a random sample). And we apply the
query condition on each MCV entry too (no assumptions needed there).
The unanchored LIKE conditions could not be used as btree indexquals,
but that has little to do with selectivity estimation.
Since we bound those things at 10K entries, the histogram alone can't give
better than 0.01% estimation precision, which in itself wouldn't have
done the job for the OP -- he needed a couple more places of accuracy
than that. I surmise that he had a nontrivial MCV population as well,
since he found that raising the stats target did eventually drive down
the estimate far enough to fix the problem.
regards, tom lane