Re: Very slow query (3-4mn) on a table with 25millions rows

Dear Martin
I run an analyse on the whole database + explicit analyse on tables involved in the query.
Here the result of explain (analyse, buffer). Thanks for your help and let me know if you need more information.

explain (analyze, buffers) select s.attvalue from functionalvarattributes s, tags t, variableattributetypes vat where t.id=s.tag_id and t.status!='Internal'and vat.fieldtype in ('DBF_INLINK','DBF_OUTLINK','DBF_FWDLINK') and vat.id=s.atttype_id and split_part(split_part(s.attvalue,' ',1),'.',1) in (select e.name from functionalvariables e, usertemplatevariable ut where e.usertemplatevar_id=ut.id and ut.usertempl_id=15) except select s.attvalue from functionalvarattributes s, tags t, usertemplvarattribute utva, usertemplatevariable utv, variableattributetypes vat where vat.fieldtype in ('DBF_INLINK','DBF_OUTLINK','DBF_FWDLINK') and vat.id=s.atttype_id and utv.id=utva.usertempvariable_fk and utv.usertempl_id=15 and t.id=s.tag_id and t.status!='Internal'and split_part(split_part(s.attvalue,' ',1),'.',1) in (select e.name from functionalvariables e, usertemplatevariable ut where e.usertemplatevar_id=ut.id and ut.usertempl_id=15);
QUERY PLAN

---------------------------------------------------------------------------------------------------------------------------------------
---------------------------------------------------------------------
HashSetOp Except (cost=171506.51..2361929.77 rows=1102 width=8) (actual time=75622.307..75622.307 rows=0 loops=1)
Buffers: shared hit=4423 read=925096
-> Append (cost=171506.51..2251904.08 rows=44010276 width=8) (actual time=13510.950..75622.159 rows=320 loops=1)
Buffers: shared hit=4423 read=925096
-> Subquery Scan on "*SELECT* 1" (cost=171506.51..907352.41 rows=310110 width=8) (actual time=13510.950..41131.939 rows=2 lo
ops=1)
Buffers: shared hit=1785 read=462580
-> Hash Join (cost=171506.51..904251.31 rows=310110 width=8) (actual time=13510.947..41131.932 rows=2 loops=1)
Hash Cond: (split_part(split_part((s.attvalue)::text, ' '::text, 1), '.'::text, 1) = (e.name)::text)
Buffers: shared hit=1785 read=462580
-> Hash Join (cost=193.91..726311.49 rows=310110 width=8) (actual time=1.016..33826.718 rows=308287 loops=1)
Hash Cond: (s.tag_id = t.id)
Buffers: shared hit=1070 read=349424
-> Hash Join (cost=188.03..716937.71 rows=1671149 width=16) (actual time=0.941..33398.776 rows=651155 loop
s=1)
Hash Cond: (s.atttype_id = vat.id)
Buffers: shared hit=1067 read=349424
-> Seq Scan on functionalvarattributes s (cost=0.00..604679.32 rows=25429032 width=24) (actual time=
0.002..20099.045 rows=25429808 loops=1)
Buffers: shared hit=965 read=349424
-> Hash (cost=183.18..183.18 rows=388 width=8) (actual time=0.900..0.900 rows=388 loops=1)
Buckets: 1024 Batches: 1 Memory Usage: 16kB
Buffers: shared hit=102
-> Seq Scan on variableattributetypes vat (cost=0.00..183.18 rows=388 width=8) (actual time=0.
005..0.803 rows=388 loops=1)
Filter: ((fieldtype)::text = ANY ('{DBF_INLINK,DBF_OUTLINK,DBF_FWDLINK}'::text[]))
Rows Removed by Filter: 5516
Buffers: shared hit=102
-> Hash (cost=5.43..5.43 rows=36 width=8) (actual time=0.070..0.070 rows=36 loops=1)
Buckets: 1024 Batches: 1 Memory Usage: 2kB
Buffers: shared hit=3
-> Seq Scan on tags t (cost=0.00..5.43 rows=36 width=8) (actual time=0.007..0.057 rows=36 loops=1)
Filter: ((status)::text <> 'Internal'::text)
Rows Removed by Filter: 158
Buffers: shared hit=3
-> Hash (cost=171251.03..171251.03 rows=4926 width=24) (actual time=6801.452..6801.452 rows=16 loops=1)
Buckets: 1024 Batches: 1 Memory Usage: 1kB
Buffers: shared hit=715 read=113156
-> HashAggregate (cost=171201.77..171251.03 rows=4926 width=24) (actual time=6801.417..6801.435 rows=16 lo
ops=1)
Buffers: shared hit=715 read=113156
-> Hash Join (cost=8.95..171189.45 rows=4926 width=24) (actual time=12.812..6801.387 rows=48 loops=1
)
Hash Cond: (e.usertemplatevar_id = ut.id)
Buffers: shared hit=715 read=113156
-> Seq Scan on functionalvariables e (cost=0.00..155513.72 rows=4164672 width=32) (actual time
=5.244..4924.135 rows=4164350 loops=1)
Buffers: shared hit=711 read=113156
-> Hash (cost=8.75..8.75 rows=16 width=8) (actual time=0.030..0.030 rows=16 loops=1)
Buckets: 1024 Batches: 1 Memory Usage: 1kB
Buffers: shared hit=4
-> Index Scan using usertemp_utv_idx on usertemplatevariable ut (cost=0.29..8.75 rows=16
width=8) (actual time=0.012..0.023 rows=16 loops=1)
Index Cond: (usertempl_id = 15)
Buffers: shared hit=4
-> Subquery Scan on "*SELECT* 2" (cost=172515.69..1344551.67 rows=43700166 width=8) (actual time=12639.042..34490.098 rows=3
18 loops=1)
Buffers: shared hit=2638 read=462516
-> Hash Join (cost=172515.69..907550.01 rows=43700166 width=8) (actual time=12639.040..34489.953 rows=318 loops=1)
Hash Cond: (split_part(split_part((s_1.attvalue)::text, ' '::text, 1), '.'::text, 1) = (e_1.name)::text)
Buffers: shared hit=2638 read=462516
-> Hash Join (cost=193.91..726311.49 rows=310110 width=8) (actual time=2.354..26734.043 rows=308287 loops=1)
Hash Cond: (s_1.tag_id = t_1.id)
Buffers: shared hit=1102 read=349392
-> Hash Join (cost=188.03..716937.71 rows=1671149 width=16) (actual time=2.176..26421.280 rows=651155 loop
s=1)
Hash Cond: (s_1.atttype_id = vat_1.id)
Buffers: shared hit=1099 read=349392
-> Seq Scan on functionalvarattributes s_1 (cost=0.00..604679.32 rows=25429032 width=24) (actual tim
e=0.003..16949.841 rows=25429808 loops=1)
Buffers: shared hit=997 read=349392
-> Hash (cost=183.18..183.18 rows=388 width=8) (actual time=2.092..2.092 rows=388 loops=1)
Buckets: 1024 Batches: 1 Memory Usage: 16kB
Buffers: shared hit=102
-> Seq Scan on variableattributetypes vat_1 (cost=0.00..183.18 rows=388 width=8) (actual time=
0.014..1.852 rows=388 loops=1)
Filter: ((fieldtype)::text = ANY ('{DBF_INLINK,DBF_OUTLINK,DBF_FWDLINK}'::text[]))
Rows Removed by Filter: 5516
Buffers: shared hit=102
-> Hash (cost=5.43..5.43 rows=36 width=8) (actual time=0.138..0.138 rows=36 loops=1)
Buckets: 1024 Batches: 1 Memory Usage: 2kB
Buffers: shared hit=3
-> Seq Scan on tags t_1 (cost=0.00..5.43 rows=36 width=8) (actual time=0.016..0.088 rows=36 loops=1)
Filter: ((status)::text <> 'Internal'::text)
Rows Removed by Filter: 158
Buffers: shared hit=3
-> Hash (cost=172320.02..172320.02 rows=141 width=24) (actual time=7386.827..7386.827 rows=2544 loops=1)
Buckets: 1024 Batches: 1 Memory Usage: 134kB
Buffers: shared hit=1536 read=113124
-> Nested Loop (cost=171202.47..172320.02 rows=141 width=24) (actual time=7378.869..7384.698 rows=2544 loo
ps=1)
Buffers: shared hit=1536 read=113124
-> Nested Loop (cost=171202.05..172245.02 rows=16 width=32) (actual time=7378.835..7379.342 rows=256
loops=1)
Buffers: shared hit=751 read=113124
-> HashAggregate (cost=171201.77..171251.03 rows=4926 width=24) (actual time=7368.551..7368.62
0 rows=16 loops=1)
Buffers: shared hit=747 read=113124
-> Hash Join (cost=8.95..171189.45 rows=4926 width=24) (actual time=13.272..7368.471 row
s=48 loops=1)
Hash Cond: (e_1.usertemplatevar_id = ut_1.id)
Buffers: shared hit=747 read=113124
-> Seq Scan on functionalvariables e_1 (cost=0.00..155513.72 rows=4164672 width=32
) (actual time=9.412..5383.223 rows=4164350 loops=1)
Buffers: shared hit=743 read=113124
-> Hash (cost=8.75..8.75 rows=16 width=8) (actual time=0.061..0.061 rows=16 loops=
1)
Buckets: 1024 Batches: 1 Memory Usage: 1kB
Buffers: shared hit=4
-> Index Scan using usertemp_utv_idx on usertemplatevariable ut_1 (cost=0.29
..8.75 rows=16 width=8) (actual time=0.032..0.052 rows=16 loops=1)
Index Cond: (usertempl_id = 15)
Buffers: shared hit=4
-> Materialize (cost=0.29..8.83 rows=16 width=8) (actual time=0.643..0.654 rows=16 loops=16)
Buffers: shared hit=4
-> Index Scan using usertemp_utv_idx on usertemplatevariable utv (cost=0.29..8.75 rows=1
6 width=8) (actual time=0.052..0.075 rows=16 loops=1)
Index Cond: (usertempl_id = 15)
Buffers: shared hit=4
-> Index Only Scan using usertemplvarattribute_atttypeid_key on usertemplvarattribute utva (cost=0.4
2..4.60 rows=9 width=8) (actual time=0.004..0.010 rows=10 loops=256)
Index Cond: (usertempvariable_fk = utv.id)
Heap Fetches: 0
Buffers: shared hit=785
Total runtime: 75622.559 ms
(104 rows)

Lana ABADIE
Database Engineer
CODAC Section

ITER Organization, Building 72/4108, SCOD, Control System Division
Route de Vinon-sur-Verdon - CS 90 046 - 13067 St Paul Lez Durance Cedex - France
Phone: +33 4 42 17 84 02
Get the latest ITER news on http://www.iter.org/whatsnew
>>-----Original Message-----
>>From: Martín Marqués [mailto:martin(at)2ndquadrant(dot)com]
>>Sent: 26 July 2016 12:34
>>To: Abadie Lana; Tom Lane
>>Cc: pgsql-performance(at)postgresql(dot)org
>>Subject: Re: [PERFORM] Very slow query (3-4mn) on a table with 25millions
>>rows
>>
>>El 26/07/16 a las 06:01, Abadie Lana escribió:
>>> Hi Tom,
>>> Thanks for the hints..
>>>
>>> I made various tests for index
>>> The best I could get is the following one with
>>> create index vat_funcvaratt_multi_idx on
>>functionalvarattributes(split_part(split_part(attvalue,' ',1),'.',1), tag_id,
>>atttype_id);
>>> analyze functionalvarattributes;
>>
>>I suggest running analyze over the other tables involved in the query
>>(or over the whole DB) and then sending back the explain analyze, or
>>even better EXPLAIN (ANALYZE,BUFFERS).
>>
>>Some estimates are close and others are really wrong.
>>
>>I'm not saying that's going to give you a big bust but we'll be able to
>>see the planner with fresh stats
>>
>>--
>>Martín Marqués http://www.2ndQuadrant.com/
>>PostgreSQL Development, 24x7 Support, Training & Services