Re: Specific query taking time to process

--000000000000b02b6105995f2c6c
Content-Type: text/plain; charset="UTF-8"

On Mon, Dec 9, 2019 at 3:39 PM Fahiz Mohamed <[email protected]> wrote:

> I ran "explain analyse" 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 than 600,000 request a
> day) - The result is same even when there is no user in the server.
>
>      -> Bitmap Heap Scan on alf_node node (cost=995009.97..3303978.85 rows=4565737 width=8) (actual time=3304.419..20465.551 rows=41109751 loops=1)
>         Recheck Cond: ((store_id = 6) AND (type_qname_id = 240))
>         Rows Removed by Index Recheck: 54239131
>         Filter: (NOT (hashed SubPlan 1))
>         Rows Removed by Filter: 2816
>         Heap Blocks: exact=24301 lossy=1875383
>
>
> Planning time: 0.639 ms
> Execution time: 22946.036 ms
>
>
https://paquier.xyz/postgresql-2/postgres-9-4-feature-highlight-lossyexact-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_mem to fit all the references to the
individual rows which perhaps isn't surprising when it estimates it needs
4.5 million rows and ends up with 41 million.

Do both DB instances have the same data? I ask because the two plans are
rather different which makes me think that statistics about the data are
not very similar. Are both configured the same, particularly for
shared_buffers and work_mem, as well as the various planning cost
parameters like random_page cost? If you can provide these plans again with
explain( analyze, buffers ) this time? Did you check on the last time
autovacuum ran in pg_stat_user_tables?

--000000000000b02b6105995f2c6c
Content-Type: text/html; charset="UTF-8"
Content-Transfer-Encoding: quoted-printable

<div dir=3D"ltr"><div dir=3D"ltr">On Mon, Dec 9, 2019 at 3:39 PM Fahiz Moha=
med &lt;<a href=3D"mailto:[email protected]">[email protected]</a>&gt; wrot=
e:<br></div><div class=3D"gmail_quote"><blockquote class=3D"gmail_quote" st=
yle=3D"margin:0px 0px 0px 0.8ex;border-left:1px solid rgb(204,204,204);padd=
ing-left:1ex">



<div>
<div name=3D"messageBodySection">
<div dir=3D"auto"><div dir=3D"auto">I ran &quot;explain analyse&quot; on th=
is 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 instanc=
e 2 took less than a second)</div>
<div dir=3D"auto"><br></div>
<div dir=3D"auto">Instance 1: (This is used by regular User - More than 600=
,000 request a day) - The result is same even when there is no user in the =
server.</div>
<div dir=3D"auto">
<pre style=3D"box-sizing:inherit;margin-top:4px;margin-bottom:4px;padding:8=
px;font-size:12px;line-height:1.50001;font-variant-ligatures:none;white-spa=
ce:pre-wrap;word-break:normal;border-radius:4px;color:rgb(209,210,211);font=
-family:Monaco,Menlo,Consolas,&quot;Courier New&quot;,monospace"><pre style=
=3D"white-space:pre-wrap;box-sizing:inherit;margin-top:4px;margin-bottom:4p=
x;padding:8px;line-height:1.50001;word-break:normal;border-radius:4px;font-=
family:Monaco,Menlo,Consolas,&quot;Courier New&quot;,monospace">     -&gt; =
Bitmap Heap Scan on alf_node node (cost=3D995009.97..3303978.85 rows=3D4565=
737 width=3D8) (actual time=3D3304.419..20465.551 rows=3D41109751 loops=3D1=
)<br style=3D"box-sizing:inherit">        Recheck Cond: ((store_id =3D 6) A=
ND (type_qname_id =3D 240))<br style=3D"box-sizing:inherit">        Rows Re=
moved by Index Recheck: 54239131<br style=3D"box-sizing:inherit">        Fi=
lter: (NOT (hashed SubPlan 1))<br style=3D"box-sizing:inherit">        Rows=
 Removed by Filter: 2816<br style=3D"box-sizing:inherit">        Heap Block=
s: exact=3D24301 lossy=3D1875383</pre><br style=3D"box-sizing:inherit"> Pla=
nning time: 0.639 ms<br style=3D"box-sizing:inherit"> Execution time: 22946=
.036 ms</pre></div></div></div></div></blockquote><div><br></div><div><a hr=
ef=3D"https://paquier.xyz/postgresql-2/postgres-9-4-feature-highlight-lossy=
exact-pages-for-bitmap-heap-scan/">https://paquier.xyz/postgresql-2/postgre=
s-9-4-feature-highlight-lossyexact-pages-for-bitmap-heap-scan/</a>=C2=A0<br=
></div><div><br></div><div>That seems like a lot of lossy blocks. As I unde=
rstand it, that means the system didn&#39;t have enough work_mem to fit all=
 the references to the individual rows which perhaps isn&#39;t surprising w=
hen it estimates it needs 4.5 million rows and ends up with 41 million.</di=
v><div><br></div><div>Do both DB instances have the same data? I ask becaus=
e the two plans are rather different which makes me think that statistics a=
bout the data are not very similar. Are both configured the same, particula=
rly for shared_buffers and work_mem, as well as the various planning cost p=
arameters like random_page cost? If you can provide these plans again with =
explain( analyze, buffers ) this time? Did you check on the last time autov=
acuum ran in=C2=A0pg_stat_user_tables?</div><div><br></div><div><br></div><=
/div></div>

--000000000000b02b6105995f2c6c--