Re: Specific query taking time to process

--5df1495a_a0382c5_142
Content-Type: text/plain; charset="utf-8"
Content-Transfer-Encoding: quoted-printable
Content-Disposition: inline

There is a slight different in both instance=E2=80=99s data. Inastanbce 1=
 contains latest data and instance 2 consists of data which is 3 weeks ol=
der than instance 1.

=46ollowing are the number of rows in each table in both instances

Instance 1
alf=5Fnode : 96493129 rows
alf=5Fnode=5Fproperties : 455599288 rows
alf=5Fnode=5Faspects : 150153006 rowsInstance 2
alf=5Fnode : 90831396 rows
alf=5Fnode=5Fproperties : 440792247 rows
alf=5Fnode=5Faspects : 146648241 rows

I hope the above data difference can make a drastic difference. Please co=
rrect me if I am wrong.

I checked =22pg=5Fstat=5Fuser=5Ftables=22 and autovacuum never run agains=
t those tables.

I did execute vacuum manually and I noticed the below in the output

=22IN=46O: vacuuming =22public.alf=5Fnode=5Faspects=22
IN=46O: =22alf=5Fnode=5Faspects=22: found 0 removable, 150264654 nonremov=
able row versions in 812242 pages
DETAIL: 0 dead row versions cannot be removed yet.
CPU 13.53s/33.35u sec elapsed 77.88 sec.


IN=46O: analyzing =22public.alf=5Fnode=5Faspects=22
IN=46O: =22alf=5Fnode=5Faspects=22: scanned 30000 of 812242 pages, contai=
ning 5550000 live rows and 0 dead rows; 30000 rows in sample, 150264770 e=
stimated total rows=22

Did the vacuum worked fine=3F

I did =22explain( analyze, buffers )=22 below are the results:

Instance 1:

=C2=A0Nested Loop Semi Join (cost=3D441133.07..1352496.76 rows=3D1 width=3D=
8) (actual time=3D9054.324..10029.748 rows=3D22 loops=3D1)
Buffers: shared hit=3D1617812
-> Merge Semi Join (cost=3D441132.50..1352359.19 rows=3D41 width=3D16) (a=
ctual time=3D9054.296..10029.547 rows=3D22 loops=3D1)
Merge Cond: (node.id =3D prop.node=5Fid)
Buffers: shared hit=3D1617701
-> Index Only Scan using idx=5Falf=5Fnode=5Ftqn on alf=5Fnode node (cost=3D=
441041.93..1340831.48 rows=3D4593371 width=3D8) (actual t
ime=3D4.418..7594.637 rows=3D40998148 loops=3D1)
Index Cond: ((type=5Fqname=5Fid =3D 240) AND (store=5Fid =3D 6))
=46ilter: (NOT (hashed SubPlan 1))
Rows Removed by =46ilter: 130
Heap =46etches: 0
Buffers: shared hit=3D1617681
SubPlan 1
-> Bitmap Heap Scan on alf=5Fnode=5Faspects aspect=5F1 (cost=3D3418.63..4=
40585.22 rows=3D182459 width=3D8) (actual time=3D0.
583..2.992 rows=3D4697 loops=3D1)
Recheck Cond: (qname=5Fid =3D 251)
Heap Blocks: exact=3D1774
Buffers: shared hit=3D1791
-> Bitmap Index Scan on fk=5Falf=5Fnasp=5Fqn (cost=3D0.00..3373.01 rows=3D=
182459 width=3D0) (actual time=3D0.384..0.38
4 rows=3D4697 loops=3D1)
Index Cond: (qname=5Fid =3D 251)
Buffers: shared hit=3D17
-> Index Only Scan using idx=5Falf=5Fnprop=5Fs on alf=5Fnode=5Fproperties=
 prop (cost=3D0.70..41.74 rows=3D852 width=3D8) (actual time=3D
0.022..0.037 rows=3D23 loops=3D1)
Index Cond: ((qname=5Fid =3D '242'::bigint) AND (string=5Fvalue =3D 'E292=
432'::text))
Heap =46etches: 0
Buffers: shared hit=3D20
-> Index Only Scan using alf=5Fnode=5Faspects=5Fpkey on alf=5Fnode=5Faspe=
cts aspect (cost=3D0.57..38.80 rows=3D14 width=3D8) (actual time=3D0.
007..0.007 rows=3D1 loops=3D22)
Index Cond: ((node=5Fid =3D node.id) AND (qname=5Fid =3D 245))
Heap =46etches: 22
Buffers: shared hit=3D111
Planning time: 0.621 ms
Execution time: 10029.799 ms
(29 rows)


Instance 2:

Nested Loop Semi Join (cost=3D6471.94..173560891.23 rows=3D2 width=3D8) (=
actual time=3D0.162..0.470 rows=3D17 loops=3D1)
Buffers: shared hit=3D257
-> Nested Loop (cost=3D6471.37..173560734.51 rows=3D45 width=3D16) (actua=
l time=3D0.154..0.392 rows=3D17 loops=3D1)
Buffers: shared hit=3D172
-> HashAggregate (cost=3D3508.15..3516.80 rows=3D865 width=3D8) (actual t=
ime=3D0.039..0.043 rows=3D18 loops=3D1)
Group Key: prop.node=5Fid
Buffers: shared hit=3D23
-> Index Only Scan using idx=5Falf=5Fnprop=5Fs on alf=5Fnode=5Fproperties=
 prop (cost=3D0.70..3505.99 rows=3D866 width=3D8)
(actual time=3D0.019..0.033 rows=3D18 loops=3D1)
Index Cond: ((qname=5Fid =3D '242'::bigint) AND (string=5Fvalue =3D 'E292=
432'::text))
Heap =46etches: 18
Buffers: shared hit=3D23
-> Index Scan using alf=5Fnode=5Fpkey on alf=5Fnode node (cost=3D2963.22.=
.200644.17 rows=3D1 width=3D8) (actual time=3D0.019..
0.019 rows=3D1 loops=3D18)
Index Cond: (id =3D prop.node=5Fid)
=46ilter: ((type=5Fqname=5Fid <> 145) AND (store=5Fid =3D 6) AND (type=5F=
qname=5Fid =3D 240) AND (NOT (SubPlan 1)))
Rows Removed by =46ilter: 0
Buffers: shared hit=3D149
SubPlan 1
-> Materialize (cost=3D2962.65..397913.00 rows=3D158204 width=3D8) (actua=
l time=3D0.002..0.009 rows=3D85 loops=3D17)
Buffers: shared hit=3D59
-> Bitmap Heap Scan on alf=5Fnode=5Faspects aspect=5F1 (cost=3D2962.65..3=
96503.98 rows=3D158204 width=3D8) (ac
tual time=3D0.025..0.085 rows=3D85 loops=3D1)
Recheck Cond: (qname=5Fid =3D 251)
Heap Blocks: exact=3D55
Buffers: shared hit=3D59
-> Bitmap Index Scan on fk=5Falf=5Fnasp=5Fqn (cost=3D0.00..2923.10 rows=3D=
158204 width=3D0) (actual time
=3D0.019..0.019 rows=3D87 loops=3D1)
Index Cond: (qname=5Fid =3D 251)
Buffers: shared hit=3D4
-> Index Only Scan using alf=5Fnode=5Faspects=5Fpkey on alf=5Fnode=5Faspe=
cts aspect (cost=3D0.57..34.32 rows=3D12 width=3D8) (actual t
ime=3D0.004..0.004 rows=3D1 loops=3D17)
Index Cond: ((node=5Fid =3D node.id) AND (qname=5Fid =3D 245))
Heap =46etches: 17
Buffers: shared hit=3D85
Planning time: 0.642 ms
Execution time: 0.546 ms
(32 rows)

With the vacuum and reindex on those tables manage to reduce the time to =
10s from 30s, but still I don't get the exact performance as Instance 2.

work=5Fmem was set to 4mb previously and in instance 1 its set to 160mb a=
nd instance 2 still using 4mb as work=5Fmem.

shared=5Fbuffers set to 8GB in both.

Both are on Postgres DB version 9.6.9

Thanks in advance.

=46ahiz
On 10 Dec 2019, 20:15 +0000, Michael Lewis <mlewis=40entrata.com>, wrote:=

> On Mon, Dec 9, 2019 at 3:39 PM =46ahiz Mohamed <fahiz=40netwidz.com> wr=
ote:
> > > I ran =22explain analyse=22 on this query and I got following resul=
t. (We have 2 identical DB instances and they consist of same data. Insta=
ne 1 took 20+ second to process and instance 2 took less than a second)
> > >
> > > Instance 1: (This is used by regular User - More than 600,000 reque=
st a day) - The result is same even when there is no user in the server.
> > >     -> Bitmap Heap Scan on alf=5Fnode node (cost=3D995009.97..33039=
78.85 rows=3D4565737 width=3D8) (actual time=3D3304.419..20465.551 rows=3D=
41109751 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
> > >
> > > Planning time: 0.639 ms
> > > Execution time: 22946.036 ms
> >
> > https://paquier.xyz/postgresql-2/postgres-9-4-feature-highlight-lossy=
exact-pages-for-bitmap-heap-scan/
> >
> > That seems like a lot of lossy blocks. As I understand it, that means=
 the system didn't have enough work=5Fmem to fit all the references to th=
e individual rows which perhaps isn't surprising when it estimates it nee=
ds 4.5 million rows and ends up with 41 million.
> >
> > Do both DB instances have the same data=3F I ask because the two plan=
s are rather different which makes me think that statistics about the dat=
a are not very similar. Are both configured the same, particularly for sh=
ared=5Fbuffers and work=5Fmem, as well as the various planning cost param=
eters like random=5Fpage cost=3F If you can provide these plans again wit=
h explain( analyze, buffers ) this time=3F Did you check on the last time=
 autovacuum ran in=C2=A0pg=5Fstat=5Fuser=5Ftables=3F
> >
> >

--5df1495a_a0382c5_142
Content-Type: text/html; charset="utf-8"
Content-Transfer-Encoding: quoted-printable
Content-Disposition: inline

<html xmlns=3D=22http://www.w3.org/1999/xhtml=22>
<head>
<title></title>
</head>
<body>
<div name=3D=22messageBodySection=22>
<div dir=3D=22auto=22>There is a slight different in both instance=E2=80=99=
s data. Inastanbce 1 contains latest data and instance 2 consists of data=
 which is 3 weeks older than instance 1.&=23160;
<div dir=3D=22auto=22><br /></div>
<div dir=3D=22auto=22>=46ollowing are the number of rows in each table in=
 both instances</div>
<div dir=3D=22auto=22><br /></div>
<div dir=3D=22auto=22>
<div class=3D=22c-message=5F=5Fcontent=5Fheader=22 style=3D=22box-sizing:=
 inherit; line-height: 1; margin: 9px 0px -5px; color: rgb(209, 210, 211)=
; font-family: Slack-Lato, appleLogo, sans-serif; font-size: 15px; font-v=
ariant-ligatures: common-ligatures; orphans: 2; widows: 2; background-col=
or: rgb(34, 37, 41);=22></div>
<div class=3D=22c-message=5F=5Fmessage=5Fblocks c-message=5F=5Fmessage=5F=
blocks--rich=5Ftext=22 style=3D=22box-sizing: inherit; max-width: none; o=
verflow-wrap: break-word; color: rgb(209, 210, 211); font-family: Slack-L=
ato, appleLogo, sans-serif; font-size: 15px; font-variant-ligatures: comm=
on-ligatures; orphans: 2; widows: 2; background-color: rgb(34, 37, 41);=22=
>
<div class=3D=22p-block=5Fkit=5Frenderer p-block=5Fkit=5Frenderer--absorb=
=5Fmargin=22 data-qa=3D=22block-kit-renderer=22 style=3D=22box-sizing: in=
herit; margin-top: 0px; width: 557px;=22>
<div class=3D=22p-block=5Fkit=5Frenderer=5F=5Fblock=5Fwrapper p-block=5Fk=
it=5Frenderer=5F=5Fblock=5Fwrapper--first=22 style=3D=22box-sizing: inher=
it; display: flex;=22>
<div class=3D=22p-rich=5Ftext=5Fblock=22 dir=3D=22auto=22 style=3D=22box-=
sizing: inherit; counter-reset: list-0 0 list-1 0 list-2 0 list-3 0 list-=
4 0 list-5 0 list-6 0 list-7 0 list-8 0 list-9 0; width: 557px; white-spa=
ce: pre-wrap; line-height: 1.46668; margin: 8px 0px -4px;=22>
<div class=3D=22p-rich=5Ftext=5Fsection=22 style=3D=22box-sizing: inherit=
; counter-reset: list-0 0 list-1 0 list-2 0 list-3 0 list-4 0 list-5 0 li=
st-6 0 list-7 0 list-8 0 list-9 0;=22>Instance 1<br style=3D=22box-sizing=
: inherit;=22 />
alf=5Fnode : 96493129 rows<br style=3D=22box-sizing: inherit;=22 />
alf=5Fnode=5Fproperties : 455599288 <span style=3D=22caret-color: rgb(213=
, 218, 222);=22>rows</span><br style=3D=22box-sizing: inherit;=22 />
alf=5Fnode=5Faspects : 150153006 <span style=3D=22caret-color: rgb(213, 2=
18, 222);=22>rows</span><span class=3D=22c-mrkdwn=5F=5Fbr=22 data-stringi=
fy-type=3D=22paragraph-break=22 style=3D=22box-sizing: inherit; display: =
block; height: 8px;=22></span><span style=3D=22caret-color: rgb(213, 218,=
 222);=22>Instance 2</span><br style=3D=22box-sizing: inherit;=22 />
alf=5Fnode : 90831396 <span style=3D=22caret-color: rgb(213, 218, 222);=22=
>rows</span><br style=3D=22box-sizing: inherit;=22 />
alf=5Fnode=5Fproperties : 440792247 <span style=3D=22caret-color: rgb(213=
, 218, 222);=22>rows</span><br style=3D=22box-sizing: inherit;=22 />
alf=5Fnode=5Faspects : 146648241 <span style=3D=22caret-color: rgb(213, 2=
18, 222);=22>rows</span></div>
</div>
</div>
</div>
</div>
</div>
</div>
</div>
<div name=3D=22messageSignatureSection=22><br />
<div dir=3D=22auto=22>I hope the above data difference can make a drastic=
 difference. Please correct me if I am wrong.</div>
<div dir=3D=22auto=22><br /></div>
<div dir=3D=22auto=22>I checked =22pg=5Fstat=5Fuser=5Ftables=22 and autov=
acuum never run against those tables.</div>
<div dir=3D=22auto=22><br /></div>
<div dir=3D=22auto=22>I did execute vacuum manually and I noticed the bel=
ow in the output</div>
<div dir=3D=22auto=22><br /></div>
<div dir=3D=22auto=22>=22IN=46O: vacuuming =22public.alf=5Fnode=5Faspects=
=22</div>
<div dir=3D=22auto=22>IN=46O: =22alf=5Fnode=5Faspects=22: found 0 removab=
le, 150264654 nonremovable row versions in 812242 pages</div>
<div dir=3D=22auto=22>DETAIL: 0 dead row versions cannot be removed yet.<=
/div>
<div dir=3D=22auto=22>CPU 13.53s/33.35u sec elapsed 77.88 sec.</div>
<div dir=3D=22auto=22><br /></div>
<div dir=3D=22auto=22><br /></div>
<div dir=3D=22auto=22>IN=46O: analyzing =22public.alf=5Fnode=5Faspects=22=
</div>
<div dir=3D=22auto=22>IN=46O: =22alf=5Fnode=5Faspects=22: scanned 30000 o=
f 812242 pages, containing 5550000 live rows and 0 dead rows; 30000 rows =
in sample, 150264770 estimated total rows=22</div>
<div dir=3D=22auto=22><br /></div>
<div dir=3D=22auto=22>Did the vacuum worked fine=3F</div>
<div dir=3D=22auto=22><br /></div>
<div dir=3D=22auto=22>I did =22explain( analyze, buffers )=22 below are t=
he results:</div>
<div dir=3D=22auto=22><br /></div>
<div dir=3D=22auto=22>Instance 1:&=23160;</div>
<div dir=3D=22auto=22><br /></div>
<div dir=3D=22auto=22>&=23160;Nested Loop Semi Join (cost=3D441133.07..13=
52496.76 rows=3D1 width=3D8) (actual time=3D9054.324..10029.748 rows=3D22=
 loops=3D1)<br />
Buffers: shared hit=3D1617812<br />
-&gt; Merge Semi Join (cost=3D441132.50..1352359.19 rows=3D41 width=3D16)=
 (actual time=3D9054.296..10029.547 rows=3D22 loops=3D1)<br />
Merge Cond: (<a href=3D=22http://node.id=22>node.id</a> =3D prop.node=5Fi=
d)<br />
Buffers: shared hit=3D1617701<br />
-&gt; Index Only Scan using idx=5Falf=5Fnode=5Ftqn on alf=5Fnode node (co=
st=3D441041.93..1340831.48 rows=3D4593371 width=3D8) (actual t<br />
ime=3D4.418..7594.637 rows=3D40998148 loops=3D1)<br />
Index Cond: ((type=5Fqname=5Fid =3D 240) AND (store=5Fid =3D 6))<br />
=46ilter: (NOT (hashed SubPlan 1))<br />
Rows Removed by =46ilter: 130<br />
Heap =46etches: 0<br />
Buffers: shared hit=3D1617681<br />
SubPlan 1<br />
-&gt; Bitmap Heap Scan on alf=5Fnode=5Faspects aspect=5F1 (cost=3D3418.63=
..440585.22 rows=3D182459 width=3D8) (actual time=3D0.<br />
583..2.992 rows=3D4697 loops=3D1)<br />
Recheck Cond: (qname=5Fid =3D 251)<br />
Heap Blocks: exact=3D1774<br />
Buffers: shared hit=3D1791<br />
-&gt; Bitmap Index Scan on fk=5Falf=5Fnasp=5Fqn (cost=3D0.00..3373.01 row=
s=3D182459 width=3D0) (actual time=3D0.384..0.38<br />
4 rows=3D4697 loops=3D1)<br />
Index Cond: (qname=5Fid =3D 251)<br />
Buffers: shared hit=3D17<br />
-&gt; Index Only Scan using idx=5Falf=5Fnprop=5Fs on alf=5Fnode=5Fpropert=
ies prop (cost=3D0.70..41.74 rows=3D852 width=3D8) (actual time=3D<br />
0.022..0.037 rows=3D23 loops=3D1)<br />
Index Cond: ((qname=5Fid =3D '242'::bigint) AND (string=5Fvalue =3D 'E292=
432'::text))<br />
Heap =46etches: 0<br />
Buffers: shared hit=3D20<br />
-&gt; Index Only Scan using alf=5Fnode=5Faspects=5Fpkey on alf=5Fnode=5Fa=
spects aspect (cost=3D0.57..38.80 rows=3D14 width=3D8) (actual time=3D0.<=
br />
007..0.007 rows=3D1 loops=3D22)<br />
Index Cond: ((node=5Fid =3D <a href=3D=22http://node.id=22>node.id</a>) A=
ND (qname=5Fid =3D 245))<br />
Heap =46etches: 22<br />
Buffers: shared hit=3D111<br />
Planning time: 0.621 ms<br />
Execution time: 10029.799 ms<br />
(29 rows)<br /></div>
<div dir=3D=22auto=22><br /></div>
<div dir=3D=22auto=22><br /></div>
<div dir=3D=22auto=22>Instance 2:&=23160;</div>
<div dir=3D=22auto=22><br /></div>
<div dir=3D=22auto=22>Nested Loop Semi Join (cost=3D6471.94..173560891.23=
 rows=3D2 width=3D8) (actual time=3D0.162..0.470 rows=3D17 loops=3D1)<br =
/>
Buffers: shared hit=3D257<br />
-&gt; Nested Loop (cost=3D6471.37..173560734.51 rows=3D45 width=3D16) (ac=
tual time=3D0.154..0.392 rows=3D17 loops=3D1)<br />
Buffers: shared hit=3D172<br />
-&gt; HashAggregate (cost=3D3508.15..3516.80 rows=3D865 width=3D8) (actua=
l time=3D0.039..0.043 rows=3D18 loops=3D1)<br />
Group Key: prop.node=5Fid<br />
Buffers: shared hit=3D23<br />
-&gt; Index Only Scan using idx=5Falf=5Fnprop=5Fs on alf=5Fnode=5Fpropert=
ies prop (cost=3D0.70..3505.99 rows=3D866 width=3D8)<br />
(actual time=3D0.019..0.033 rows=3D18 loops=3D1)<br />
Index Cond: ((qname=5Fid =3D '242'::bigint) AND (string=5Fvalue =3D 'E292=
432'::text))<br />
Heap =46etches: 18<br />
Buffers: shared hit=3D23<br />
-&gt; Index Scan using alf=5Fnode=5Fpkey on alf=5Fnode node (cost=3D2963.=
22..200644.17 rows=3D1 width=3D8) (actual time=3D0.019..<br />
0.019 rows=3D1 loops=3D18)<br />
Index Cond: (id =3D prop.node=5Fid)<br />
=46ilter: ((type=5Fqname=5Fid &lt;&gt; 145) AND (store=5Fid =3D 6) AND (t=
ype=5Fqname=5Fid =3D 240) AND (NOT (SubPlan 1)))<br />
Rows Removed by =46ilter: 0<br />
Buffers: shared hit=3D149<br />
SubPlan 1<br />
-&gt; Materialize (cost=3D2962.65..397913.00 rows=3D158204 width=3D8) (ac=
tual time=3D0.002..0.009 rows=3D85 loops=3D17)<br />
Buffers: shared hit=3D59<br />
-&gt; Bitmap Heap Scan on alf=5Fnode=5Faspects aspect=5F1 (cost=3D2962.65=
..396503.98 rows=3D158204 width=3D8) (ac<br />
tual time=3D0.025..0.085 rows=3D85 loops=3D1)<br />
Recheck Cond: (qname=5Fid =3D 251)<br />
Heap Blocks: exact=3D55<br />
Buffers: shared hit=3D59<br />
-&gt; Bitmap Index Scan on fk=5Falf=5Fnasp=5Fqn (cost=3D0.00..2923.10 row=
s=3D158204 width=3D0) (actual time<br />
=3D0.019..0.019 rows=3D87 loops=3D1)<br />
Index Cond: (qname=5Fid =3D 251)<br />
Buffers: shared hit=3D4<br />
-&gt; Index Only Scan using alf=5Fnode=5Faspects=5Fpkey on alf=5Fnode=5Fa=
spects aspect (cost=3D0.57..34.32 rows=3D12 width=3D8) (actual t<br />
ime=3D0.004..0.004 rows=3D1 loops=3D17)<br />
Index Cond: ((node=5Fid =3D <a href=3D=22http://node.id=22>node.id</a>) A=
ND (qname=5Fid =3D 245))<br />
Heap =46etches: 17<br />
Buffers: shared hit=3D85<br />
Planning time: 0.642 ms<br />
Execution time: 0.546 ms<br />
(32 rows)<br /></div>
<div dir=3D=22auto=22><br /></div>
<div dir=3D=22auto=22>With the vacuum and reindex on those tables manage =
to reduce the time to 10s from 30s, but still I don't get the exact perfo=
rmance as Instance 2.</div>
<div dir=3D=22auto=22><br /></div>
<div dir=3D=22auto=22>work=5Fmem was set to 4mb previously and in instanc=
e 1 its set to 160mb and instance 2 still using 4mb as work=5Fmem.&=23160=
;</div>
<div dir=3D=22auto=22><br /></div>
<div dir=3D=22auto=22>shared=5Fbuffers set to 8GB in both.</div>
<div dir=3D=22auto=22><br /></div>
<div dir=3D=22auto=22>Both are on Postgres DB version 9.6.9</div>
<div dir=3D=22auto=22><br /></div>
<div dir=3D=22auto=22>Thanks in advance.</div>
<div dir=3D=22auto=22><br /></div>
<div dir=3D=22auto=22>=46ahiz</div>
</div>
<div name=3D=22messageReplySection=22>On 10 Dec 2019, 20:15 +0000, Michae=
l Lewis &lt;mlewis=40entrata.com&gt;, wrote:<br />
<blockquote type=3D=22cite=22 class=3D=22spark=5Fquote=22 style=3D=22marg=
in: 5px 5px; padding-left: 10px; border-left: thin solid =231abc9c;=22>
<div dir=3D=22ltr=22>
<div dir=3D=22ltr=22>On Mon, Dec 9, 2019 at 3:39 PM =46ahiz Mohamed &lt;<=
a href=3D=22mailto:fahiz=40netwidz.com=22>fahiz=40netwidz.com</a>&gt; wro=
te:<br /></div>
<div class=3D=22gmail=5Fquote=22>
<blockquote class=3D=22gmail=5Fquote spark=5Fquote=22 style=3D=22margin: =
5px 5px; padding-left: 10px; border-left: thin solid =23e67e22;=22>
<div>
<div name=3D=22messageBodySection=22>
<div dir=3D=22auto=22>
<div dir=3D=22auto=22>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)</div>
<div dir=3D=22auto=22><br /></div>
<div dir=3D=22auto=22>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.</div>
<div dir=3D=22auto=22>
<pre style=3D=22box-sizing:inherit;margin-top:4px;margin-bottom:4px;paddi=
ng:8px;font-size:12px;line-height:1.50001;font-variant-ligatures:none;whi=
te-space:pre-wrap;word-break:normal;border-radius:4px;color:rgb(209,210,2=
11);font-family:Monaco,Menlo,Consolas,&quot;Courier New&quot;,monospace=22=
></pre>
<pre style=3D=22white-space:pre-wrap;box-sizing:inherit;margin-top:4px;ma=
rgin-bottom:4px;padding:8px;line-height:1.50001;word-break:normal;border-=
radius:4px;font-family:Monaco,Menlo,Consolas,&quot;Courier New&quot;,mono=
space=22>     -&gt; Bitmap Heap Scan on alf=5Fnode node (cost=3D995009.97=
..3303978.85 rows=3D4565737 width=3D8) (actual time=3D3304.419..20465.551=
 rows=3D41109751 loops=3D1)<br style=3D=22box-sizing:inherit=22 />       =
 Recheck Cond: ((store=5Fid =3D 6) AND (type=5Fqname=5Fid =3D 240))<br st=
yle=3D=22box-sizing:inherit=22 />        Rows Removed by Index Recheck: 5=
4239131<br style=3D=22box-sizing:inherit=22 />        =46ilter: (NOT (has=
hed SubPlan 1))<br style=3D=22box-sizing:inherit=22 />        Rows Remove=
d by =46ilter: 2816<br style=3D=22box-sizing:inherit=22 />        Heap Bl=
ocks: exact=3D24301 lossy=3D1875383</pre>
<pre><br style=3D=22box-sizing:inherit=22 /> Planning time: 0.639 ms<br s=
tyle=3D=22box-sizing:inherit=22 /> Execution time: 22946.036 ms</pre></di=
v>
</div>
</div>
</div>
</blockquote>
<div><br /></div>
<div><a href=3D=22https://paquier.xyz/postgresql-2/postgres-9-4-feature-h=
ighlight-lossyexact-pages-for-bitmap-heap-scan/=22>https://paquier.xyz/po=
stgresql-2/postgres-9-4-feature-highlight-lossyexact-pages-for-bitmap-hea=
p-scan/</a>&=23160;<br /></div>
<div><br /></div>
<div>That seems like a lot of lossy blocks. As I understand it, that mean=
s the system didn't have enough work=5Fmem to fit all the references to t=
he individual rows which perhaps isn't surprising when it estimates it ne=
eds 4.5 million rows and ends up with 41 million.</div>
<div><br /></div>
<div>Do both DB instances have the same data=3F I ask because the two pla=
ns are rather different which makes me think that statistics about the da=
ta are not very similar. Are both configured the same, particularly for s=
hared=5Fbuffers and work=5Fmem, as well as the various planning cost para=
meters like random=5Fpage cost=3F If you can provide these plans again wi=
th explain( analyze, buffers ) this time=3F Did you check on the last tim=
e autovacuum ran in&=23160;pg=5Fstat=5Fuser=5Ftables=3F</div>
<div><br /></div>
<div><br /></div>
</div>
</div>
</blockquote>
</div>
</body>
</html>

--5df1495a_a0382c5_142--