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

From Abadie Lana
Subject Re: Very slow query (3-4mn) on a table with 25millions rows
Date
Msg-id E544BB9A64ABD24DA201745FD316D94551126231@XCH2.iter.org
Whole thread Raw
In response to Re: Very slow query (3-4mn) on a table with 25millions rows  (Martín Marqués <martin@2ndquadrant.com>)
Responses Re: Very slow query (3-4mn) on a table with 25millions rows  (Félix GERZAGUET <felix.gerzaguet@gmail.com>)
List pgsql-performance
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_idand t.status!='Internal'and vat.fieldtype in ('DBF_INLINK','DBF_OUTLINK','DBF_FWDLINK') and
vat.id=s.atttype_idand split_part(split_part(s.attvalue,' ',1),'.',1) in (select e.name from functionalvariables e,
usertemplatevariableut where e.usertemplatevar_id=ut.id and ut.usertempl_id=15) except select s.attvalue from
functionalvarattributess, tags t, usertemplvarattribute utva, usertemplatevariable utv, variableattributetypes vat
wherevat.fieldtype in ('DBF_INLINK','DBF_OUTLINK','DBF_FWDLINK') and vat.id=s.atttype_id and
utv.id=utva.usertempvariable_fkand 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
wheree.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.939rows=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=308287loops=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=651155loop
 
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)
(actualtime=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=36loops=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.435rows=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=48loops=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.75rows=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.098rows=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=318loops=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=308287loops=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=651155loop
 
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=36loops=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.698rows=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.342rows=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.471row
 
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=4164672width=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.061rows=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=16loops=16)
 
                                             Buffers: shared hit=4
                                             ->  Index Scan using usertemp_utv_idx on usertemplatevariable utv
(cost=0.29..8.75rows=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@2ndquadrant.com]
>>Sent: 26 July 2016 12:34
>>To: Abadie Lana; Tom Lane
>>Cc: pgsql-performance@postgresql.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

pgsql-performance by date:

Previous
From: Martín Marqués
Date:
Subject: Re: Very slow query (3-4mn) on a table with 25millions rows
Next
From: Félix GERZAGUET
Date:
Subject: Re: Very slow query (3-4mn) on a table with 25millions rows