Received: from malur.postgresql.org ([217.196.149.56]) by arkaria.postgresql.org with esmtps (TLS1.2:ECDHE_RSA_AES_256_CBC_SHA1:256) (Exim 4.89) (envelope-from ) id 1ieb4F-0003us-Lq for pgsql-performance@arkaria.postgresql.org; Tue, 10 Dec 2019 08:40:28 +0000 Received: from localhost ([127.0.0.1] helo=malur.postgresql.org) by malur.postgresql.org with esmtp (Exim 4.89) (envelope-from ) id 1ieb4E-0004NW-Be for pgsql-performance@arkaria.postgresql.org; Tue, 10 Dec 2019 08:40:26 +0000 Received: from makus.postgresql.org ([2001:4800:3e1:1::229]) by malur.postgresql.org with esmtps (TLS1.2:ECDHE_RSA_AES_256_CBC_SHA1:256) (Exim 4.89) (envelope-from ) id 1ieRh6-0000tN-8u for pgsql-performance@lists.postgresql.org; Mon, 09 Dec 2019 22:39:56 +0000 Received: from mail-wm1-x342.google.com ([2a00:1450:4864:20::342]) by makus.postgresql.org with esmtps (TLS1.3:ECDHE_RSA_AES_128_GCM_SHA256:128) (Exim 4.92) (envelope-from ) id 1ieRgy-00020y-B0 for pgsql-performance@lists.postgresql.org; Mon, 09 Dec 2019 22:39:54 +0000 Received: by mail-wm1-x342.google.com with SMTP id p9so1089200wmc.2 for ; Mon, 09 Dec 2019 14:39:47 -0800 (PST) DKIM-Signature: v=1; a=rsa-sha256; c=relaxed/relaxed; d=netwidz-com.20150623.gappssmtp.com; s=20150623; h=date:from:to:cc:message-id:in-reply-to:references:subject :mime-version; bh=N4BB79sGPizyzUIF2jGB1AQrSN80nL5yVZ1VZRc2Lyc=; b=EOrAAMExEbWCuPG82mS7e0JhhpA8KtB6g2Tb02e+ghpq6Fq8wT20faM9Lm22YvRu7t /2IXLwVK7ExNVGmsLc5uGBDORW4B+sTLfyYpSYSA0SVbZ00fTzG8sTZPSCAOnWHSd3dB nRU2dCSoIbU54u368SX+1RGuDdP+wbFTuq9jbyYn9veEJF1A2mKksxBJYstlt0zKeZfE NkoTNNtYtR8Y1rV+BwF7hOQXocuVSLAUEEB7YF7N77rICldKMyDw8u03mL/iQH1H+47Q HJpj7FFRCt1mpHIHExF/IFvVzxvlB7ZNIVUtnqaoEAFWwOLuyTdqqb+XBHIkhG3ULlUs kb/w== X-Google-DKIM-Signature: v=1; a=rsa-sha256; c=relaxed/relaxed; d=1e100.net; s=20161025; h=x-gm-message-state:date:from:to:cc:message-id:in-reply-to :references:subject:mime-version; bh=N4BB79sGPizyzUIF2jGB1AQrSN80nL5yVZ1VZRc2Lyc=; b=bFYe0vxO0g0PIijnZFW6i8mR/yj4XF+p0NmZPty/yFc6c3whrTB534AybnvDmGv6xI m+8Fq48OxWsztgx189VVPR6Pfr98R55El4DNFXH59UNyKr2QC19PZJZC78XPybQHghic Ds/fxE+yfYuX+1qz0xTr/4QebJ9fIFV27kYHWR70f8SKUdDShyHGwzL0f9Vb+HZKEEkJ aMzOLa2kgcnAUGGE0O9sjxqvrX3k0PwsUIwTm6lAGn4mk9erfe4e20kuSvTvXJ7IdT1c eJtKv5qF51BmJof29NyyKqdTjcBFCeAhXBkGjegz9YA6aJVvmBNES+IJvk+8EBO7K+lG YzpQ== X-Gm-Message-State: APjAAAWrEVOW+Q/uWDz58Dx8zrUzQGJ3lqHvY11IF6snEw31gcqdXKap C26sGEi/DX9UX1p/TID/Q/Wkpw== X-Google-Smtp-Source: APXvYqw6gggm1OpLSx3x4aqWfwfT7965ayJxEaHhM2wi/Y9DWcbgVBdbP1uEb7rw9pr56UkVN+YuJA== X-Received: by 2002:a1c:2383:: with SMTP id j125mr1367383wmj.87.1575931186463; Mon, 09 Dec 2019 14:39:46 -0800 (PST) Received: from [192.168.1.6] ([90.240.47.176]) by smtp.gmail.com with ESMTPSA id n16sm945153wro.88.2019.12.09.14.39.44 (version=TLS1_2 cipher=ECDHE-RSA-AES128-GCM-SHA256 bits=128/128); Mon, 09 Dec 2019 14:39:45 -0800 (PST) Date: Mon, 9 Dec 2019 22:39:38 +0000 From: Fahiz Mohamed To: Michael Lewis Cc: Pgsql Performance Message-ID: <10b65cf1-a079-4aa3-92f0-ca21375da683@Spark> In-Reply-To: References: <6bd9b9b7-f127-4e48-a456-b3bbcfb741ab@Spark> Subject: Re: Specific query taking time to process X-Readdle-Message-ID: 10b65cf1-a079-4aa3-92f0-ca21375da683@Spark MIME-Version: 1.0 Content-Type: multipart/alternative; boundary="5deecd30_5e884adc_142" List-Id: List-Help: List-Subscribe: List-Post: List-Owner: List-Archive: Precedence: bulk --5deecd30_5e884adc_142 Content-Type: text/plain; charset="utf-8" Content-Transfer-Encoding: quoted-printable Content-Disposition: inline Thank you very much for your prompt responses. I have analysed more regarding this and found the long running query. I ran =22explain analyse=22 on this query and I got following result. (We= have 2 identical DB instances and they consist of same data. Instane 1 t= ook 20+ second to process and instance 2 took less than a second) Instance 1: (This is used by regular User - More than 600,000 request a d= ay) - The result is same even when there is no user in the server. EXPLAIN ANALYZE Nested Loop Semi Join (cost=3D998547.53..3319573.36 rows=3D1 width=3D8) (= actual time=3D10568.217..22945.971 rows=3D22 loops=3D1) -> Hash Semi Join (cost=3D998546.96..3319545.95 rows=3D41 width=3D16) (a= ctual time=3D10568.198..22945.663 rows=3D22 loops=3D1) Hash Cond: (node.id =3D prop.node=5Fid) -> Bitmap Heap Scan on alf=5Fnode node (cost=3D995009.97..3303978.85 = rows=3D4565737 width=3D8) (actual time=3D3304.419..20465.551 rows=3D41109= 751 loops=3D1) Recheck Cond: ((store=5Fid =3D 6) AND (type=5Fqname=5Fid =3D 240))= Rows Removed by Index Recheck: 54239131 =46ilter: (NOT (hashed SubPlan 1)) Rows Removed by =46ilter: 2816 Heap Blocks: exact=3D24301 lossy=3D1875383 -> Bitmap Index Scan on idx=5Falf=5Fnode=5Fmdq (cost=3D0.00..64614= 4.01 rows=3D20047144 width=3D0) (actual time=3D3232.067..3232.067 rows=3D= 44246360 loops=3D1) Index Cond: ((store=5Fid =3D 6) AND (type=5Fqname=5Fid =3D 240)= ) SubPlan 1 -> Bitmap Heap Scan on alf=5Fnode=5Faspects aspect=5F1 (cost=3D25= 03.51..347403.58 rows=3D128379 width=3D8) (actual time=3D25.447..65.392 r= ows=3D5635 loops=3D1) Recheck Cond: (qname=5Fid =3D 251) Heap Blocks: exact=3D40765 -> Bitmap Index Scan on fk=5Falf=5Fnasp=5Fqn (cost=3D0.00..247= 1.41 rows=3D128379 width=3D0) (actual time=3D18.835..18.835 rows=3D239610= loops=3D1) Index Cond: (qname=5Fid =3D 251) -> Hash (cost=3D3526.11..3526.11 rows=3D871 width=3D8) (actual time=3D= 0.045..0.045 rows=3D23 loops=3D1) Buckets: 1024 Batches: 1 Memory Usage: 9kB -> Index Only Scan using idx=5Falf=5Fnprop=5Fs on alf=5Fnode=5Fpro= perties prop (cost=3D0.70..3526.11 rows=3D871 width=3D8) (actual time=3D0= .021..0.042 rows=3D23 loops=3D1) Index Cond: ((qname=5Fid =3D '242'::bigint) AND (string=5Fvalue= =3D 'E292432'::text)) Heap =46etches: 23 -> Index Only Scan using alf=5Fnode=5Faspects=5Fpkey on alf=5Fnode=5Fasp= ects aspect (cost=3D0.57..2.01 rows=3D15 width=3D8) (actual time=3D0.011.= .0.011 rows=3D1 loops=3D22) Index Cond: ((node=5Fid =3D node.id) AND (qname=5Fid =3D 245)) Heap =46etches: 22 Planning time: 0.639 ms Execution time: 22946.036 ms Instance 2: (Only by testers - 250 request a day) Nested Loop Semi Join (cost=3D6471.94..173560841.08 rows=3D2 width=3D8) = (actual time=3D0.162..0.464 rows=3D17 loops=3D1) -> Nested Loop (cost=3D6471.37..173560684.36 rows=3D45 width=3D16) (a= ctual time=3D0.154..0.387 rows=3D17 loops=3D1) -> HashAggregate (cost=3D3508.15..3516.80 rows=3D865 width=3D8)= (actual time=3D0.041..0.047 rows=3D18 loops=3D1) Group Key: prop.node=5Fid -> Index Only Scan using idx=5Falf=5Fnprop=5Fs on alf=5Fno= de=5Fproperties prop (cost=3D0.70..3505.99 rows=3D866 width=3D8) (actual= time=3D0.020..0.035 r ows=3D18 loops=3D1) Index Cond: ((qname=5Fid =3D '242'::bigint) AND (stri= ng=5Fvalue =3D 'E292432'::text)) Heap =46etches: 18 -> Index Scan using alf=5Fnode=5Fpkey on alf=5Fnode node (cost=3D= 2963.22..200644.11 rows=3D1 width=3D8) (actual time=3D0.019..0.019 rows=3D= 1 loops=3D18) Index Cond: (id =3D prop.node=5Fid) =46ilter: ((type=5Fqname=5Fid <> 145) AND (store=5Fid =3D 6= ) AND (type=5Fqname=5Fid =3D 240) AND (NOT (SubPlan 1))) Rows Removed by =46ilter: 0 SubPlan 1 -> Materialize (cost=3D2962.65..397912.89 rows=3D158204= width=3D8) (actual time=3D0.001..0.009 rows=3D85 loops=3D17) -> Bitmap Heap Scan on alf=5Fnode=5Faspects aspect= =5F1 (cost=3D2962.65..396503.87 rows=3D158204 width=3D8) (actual time=3D= 0.021..0.082 rows=3D 85 loops=3D1) Recheck Cond: (qname=5Fid =3D 251) Heap Blocks: exact=3D55 -> Bitmap Index Scan on fk=5Falf=5Fnasp=5Fqn= (cost=3D0.00..2923.10 rows=3D158204 width=3D0) (actual time=3D0.015..0.= 015 rows=3D87 loops=3D 1) Index Cond: (qname=5Fid =3D 251) -> Index Only Scan using alf=5Fnode=5Faspects=5Fpkey on alf=5Fnode=5Fa= spects aspect (cost=3D0.57..34.32 rows=3D12 width=3D8) (actual time=3D0.= 004..0.004 rows=3D1 loop s=3D17) Index Cond: ((node=5Fid =3D node.id) AND (qname=5Fid =3D 245)) Heap =46etches: 17 Planning time: 0.623 ms Execution time: 0.540 ms Configurations are same in both servers. Please advise me on this. Is there any configuration specifically I need = to look like =E2=80=9Cwork=5Fmem=E2=80=9D, =E2=80=9CShared=5Fbuffers=E2=80= =9D, =E2=80=9Ccheckpoint=5Fsegment=E2=80=9D, =E2=80=9Ceffective=5Fcache=5F= size=E2=80=9D, =E2=80=9Cenable=5Fseqscan=E2=80=9D and =E2=80=9Ccheckpoint= =5Fcompression=5Ftarget=E2=80=9D=3F Thanks in advance. =46ahiz On 9 Dec 2019, 19:03 +0000, Michael Lewis , wrote: > > > There is a specific search query I am running to get list of Docume= nts and their metadata from several table in the DB. > > > We are running Postgres 9.6.9 on Amazon RDS (db.m5.4xlarge instance= ) > > > > > > Our current DB consists of 500GB of data and indexes. Most of the r= ows in table are consist of=C2=A0454,078,915 > > > > > > With the fresh DB with the restore of the DATA without any indexes = Search query performs relatively quick and most of the time its less than= a second. > > > > > > But after 3 weeks of use of the DB it sudenly started to slowdown o= nly for this perticular query and it takes 20+ seconds to respond. If I d= o a restore the DB again then it continues to work fine and the symptom p= ops out after 3 weeks time. > > > > > > You haven't been quite clear on the situation and your use case, but = assuming this table has 454 million rows and experiences updates/deletes = then this sounds like you may be having problems with autovacuum. Have yo= u customized parameters to ensure it is running more frequently than defa= ult=3F How are you doing those data restores=3F Perhaps that process is c= leaning up the accumulated bloat and you can run fine again for a while. = Check pg=5Fstat=5Fuser=5Ftables for the last (auto)vacuum that ran, assum= ing you didn't just restore again and are expecting the issue to occur ag= ain soon. --5deecd30_5e884adc_142 Content-Type: text/html; charset="utf-8" Content-Transfer-Encoding: quoted-printable Content-Disposition: inline
Thank you very much for your prompt responses.

I have analysed more regarding this and found the l= ong running query.

I ran =22explain analyse=22 on this query and I got= following result. (We have 2 identical DB instances and they consist of = same data. Instane 1 took 20+ second to process and instance 2 took less = than a second)

Instance 1: (This is used by regular User - More th= an 600,000 request a day) - The result is same even when there is no user= in the server.
EXPLAIN ANALYZE
Nested Loop Semi Join (cost=3D998547.53..3319573.36 rows=3D1 width=
=3D8) (actual time=3D10568.217..22945.971 rows=3D22 loops=3D1)
  -> Hash Semi Join (cost=3D998546.96..33=
19545.95 rows=3D41 width=3D16) (actual time=3D10568.198..22945.663 rows=3D=
22 loops=3D1)
     Hash Cond: (no=
de.id =3D prop.node=5Fid)
     -&=
gt; Bitmap Heap Scan on alf=5Fnode node (cost=3D995009.97..3303978.85 row=
s=3D4565737 width=3D8) (actual time=3D3304.419..20465.551 rows=3D41109751=
 loops=3D1)
        Recheck Cond:=
 ((store=5Fid =3D 6) AND (type=5Fqname=5Fid =3D 240))
        Rows Removed by Index Recheck: 54239131
        =46ilter: (NOT (hashed SubPla=
n 1))
        Rows Removed by =46=
ilter: 2816
        Heap Blocks: =
exact=3D24301 lossy=3D1875383
   =
     -> Bitmap Index Scan on idx=5Falf=5Fnode=5Fmdq (cost=3D0.00..6461=
44.01 rows=3D20047144 width=3D0) (actual time=3D3232.067..3232.067 rows=3D=
44246360 loops=3D1)
           In=
dex Cond: ((store=5Fid =3D 6) AND (type=5Fqname=5Fid =3D 240))
        SubPlan 1
         -> Bitmap Heap Scan on alf=5Fnode=5Faspects asp=
ect=5F1 (cost=3D2503.51..347403.58 rows=3D128379 width=3D8) (actual time=3D=
25.447..65.392 rows=3D5635 loops=3D1)
            Recheck Cond: (qname=5Fid =3D 251)
            Heap Blocks: exact=3D40765
            -> Bitmap Index Scan on fk=5Falf=5F=
nasp=5Fqn (cost=3D0.00..2471.41 rows=3D128379 width=3D0) (actual time=3D1=
8.835..18.835 rows=3D239610 loops=3D1)
               Index Cond: (qname=5Fid =3D 251)
     -> Hash (cost=3D3526.11..3526.11 rows=3D871 =
width=3D8) (actual time=3D0.045..0.045 rows=3D23 loops=3D1)
        Buckets: 1024 Batches: 1 Memory Usage: =
9kB
        -> Index Only Scan=
 using idx=5Falf=5Fnprop=5Fs on alf=5Fnode=5Fproperties prop (cost=3D0.70=
..3526.11 rows=3D871 width=3D8) (actual time=3D0.021..0.042 rows=3D23 loo=
ps=3D1)
           Index Cond: ((=
qname=5Fid =3D '242'::bigint) AND (string=5Fvalue =3D 'E292432'::text))           Heap =46etches: 23
  -> Index Only Scan using alf=5Fn=
ode=5Faspects=5Fpkey on alf=5Fnode=5Faspects aspect (cost=3D0.57..2.01 ro=
ws=3D15 width=3D8) (actual time=3D0.011..0.011 rows=3D1 loops=3D22)
     Index Cond: ((node=5Fid =3D node.=
id) AND (qname=5Fid =3D 245))
   =
  Heap =46etches: 22
 Planning ti=
me: 0.639 ms
 Execution time: 229=
46.036 ms

Instance 2: (Only by testers - 250 request a day) 

Nested Loop Semi Join  (cost=3D6471.94..173560841=
.08 rows=3D2 width=3D8) (actual time=3D0.162..0.464 rows=3D17 loops=3D1)<=
br style=3D=22box-sizing: inherit;=22 />   ->  Nested Loop  (cost=3D64=
71.37..173560684.36 rows=3D45 width=3D16) (actual time=3D0.154..0.387 row=
s=3D17 loops=3D1)
         -> =
 HashAggregate  (cost=3D3508.15..3516.80 rows=3D865 width=3D8) (actual ti=
me=3D0.041..0.047 rows=3D18 loops=3D1)
               Group Key: prop.node=5Fid
               ->  Index Only Scan using idx=5Falf=5Fnpr=
op=5Fs on alf=5Fnode=5Fproperties prop  (cost=3D0.70..3505.99 rows=3D866 =
width=3D8) (actual time=3D0.020..0.035 r
ows=3D18 loops=3D1)
     =
                Index Cond: ((qname=5Fid =3D '242'::bigint) AND (string=5F=
value =3D 'E292432'::text))
     =
                Heap =46etches: 18
         ->  Index Scan using alf=5Fnode=5Fpkey on alf=5Fnode node  =
(cost=3D2963.22..200644.11 rows=3D1 width=3D8) (actual time=3D0.019..0.01=
9 rows=3D1 loops=3D18)
          =
     Index Cond: (id =3D prop.node=5Fid)
               =46ilter: ((type=5Fqname=5Fid <> 145) AND (s=
tore=5Fid =3D 6) AND (type=5Fqname=5Fid =3D 240) AND (NOT (SubPlan 1)))               Rows Removed by =46=
ilter: 0
               SubPlan 1=

                 ->  Material=
ize  (cost=3D2962.65..397912.89 rows=3D158204 width=3D8) (actual time=3D0=
.001..0.009 rows=3D85 loops=3D17)
                       ->  Bitmap Heap Scan on alf=5Fnode=5Faspects a=
spect=5F1  (cost=3D2962.65..396503.87 rows=3D158204 width=3D8) (actual ti=
me=3D0.021..0.082 rows=3D
85 loop=
s=3D1)
                          =
   Recheck Cond: (qname=5Fid =3D 251)
                             Heap Blocks: exact=3D55
                             ->  Bitmap Index S=
can on fk=5Falf=5Fnasp=5Fqn  (cost=3D0.00..2923.10 rows=3D158204 width=3D=
0) (actual time=3D0.015..0.015 rows=3D87 loops=3D
1)
             =
                      Index Cond: (qname=5Fid =3D 251)
   ->  Index Only Scan using alf=5Fnode=5Faspect=
s=5Fpkey on alf=5Fnode=5Faspects aspect  (cost=3D0.57..34.32 rows=3D12 wi=
dth=3D8) (actual time=3D0.004..0.004 rows=3D1 loop
s=3D17)
       =
  Index Cond: ((node=5Fid =3D node.id) AND (qname=5Fid =3D 245))
         Heap =46etches: 17
 Planning time: 0.623 ms
 Execution time: 0.540 ms

Configurations are same in both servers.

Please advise me on this. Is there any configuratio= n specifically I need to look like =E2=80=9Cwork=5Fmem=E2=80=9D, =E2=80=9C= Shared=5Fbuffers=E2=80=9D, =E2=80=9Ccheckpoint=5Fsegment=E2=80=9D, =E2=80= =9Ceffective=5Fcache=5Fsize=E2=80=9D, =E2=80=9Cenable=5Fseqscan=E2=80=9D = and =E2=80=9Ccheckpoint=5Fcompression=5Ftarget=E2=80=9D=3F&=23160;

Thanks in advance.

=46ahiz

On 9 Dec 2019, 19:03 +0000, Michael= Lewis <mlewis=40entrata.com>, wrote:
There is a specific search query I am running to ge= t list of Documents and their metadata from several table in the DB.
We are running Postgres 9.6.9 on Amazon RDS (db.m5= .4xlarge instance)

Our current DB consists of 500GB of data and indexe= s. Most of the rows in table are consist of&=23160;454,078,915

With the fresh DB with the restore of the DATA with= out any indexes Search query performs relatively quick and most of the ti= me its less than a second.&=23160;

But after 3 weeks of use of the DB it sudenly start= ed to slowdown only for this perticular query and it takes 20+ seconds to= respond. If I do a restore the DB again then it continues to work fine a= nd the symptom pops out after 3 weeks time.&=23160;


You haven't been quite clear on the situation and your use case, but= assuming this table has 454 million rows and experiences updates/deletes= then this sounds like you may be having problems with autovacuum. Have y= ou customized parameters to ensure it is running more frequently than def= ault=3F How are you doing those data restores=3F Perhaps that process is = cleaning up the accumulated bloat and you can run fine again for a while.= Check pg=5Fstat=5Fuser=5Ftables for the last (auto)vacuum that ran, assu= ming you didn't just restore again and are expecting the issue to occur a= gain soon.
--5deecd30_5e884adc_142--