Re: Consecutive Query Executions with Increasing Execution Time
Shijia Wei <[email protected]> Mon, 16 Dec 2019 11:28:09 -0600
| Newsgroups | gmane.comp.db.postgresql.performance |
|---|---|
| Message-ID | <CABSfb-55VAcUwvy+PtsBsEk8EMfODtC6p65qVHSYhOqWWf80mA@mail.gmail.com> |
--000000000000227a760599d58be6
Content-Type: text/plain; charset="UTF-8"
Content-Transfer-Encoding: quoted-printable
Hi Laurenz,
Each time the identical query executes, the total number of rows selected
stays the same. The table is actually not modified between/during runs.
The query plan stays the same between fast and slow runs. Please find two
copied here:
The first one is the output of the first query in the loop 1-to-20; The
second one is the output of the last query (20th).
1st Query:
Finalize Aggregate (cost=3D126840.37..126840.38 rows=3D1 width=3D12) (act=
ual
time=3D178.825..178.826 rows=3D1 loops=3D1)
Buffers: shared hit=3D17074 read=3D16388
-> Gather (cost=3D126839.73..126840.34 rows=3D6 width=3D12) (actual
time=3D178.786..180.064 rows=3D7 loops=3D1)
Workers Planned: 6
Workers Launched: 6
Buffers: shared hit=3D17074 read=3D16388
-> Partial Aggregate (cost=3D125839.73..125839.74 rows=3D1 width=
=3D12)
(actual time=3D176.781..176.781 rows=3D1 loops=3D7)
Buffers: shared hit=3D17074 read=3D16388
-> Parallel Index Only Scan using i_l_shipdate on lineitem
(cost=3D0.43..120842.46 rows=3D999455 width=3D4) (actual time=3D0.045..114=
.871
rows=3D856704 loops=3D7)
Index Cond: (l_shipdate <=3D '1998-11-11
00:00:00'::timestamp without time zone)
Heap Fetches: 0
Buffers: shared hit=3D17074 read=3D16388
Planning Time: 0.458 ms
Execution Time: 180.111 ms
(14 rows)
20th Query:
Finalize Aggregate (cost=3D126840.37..126840.38 rows=3D1 width=3D12) (act=
ual
time=3D223.928..223.929 rows=3D1 loops=3D1)
Buffers: shared hit=3D17037 read=3D16390
-> Gather (cost=3D126839.73..126840.34 rows=3D6 width=3D12) (actual
time=3D223.856..225.474 rows=3D7 loops=3D1)
Workers Planned: 6
Workers Launched: 6
Buffers: shared hit=3D17037 read=3D16390
-> Partial Aggregate (cost=3D125839.73..125839.74 rows=3D1 width=
=3D12)
(actual time=3D221.918..221.918 rows=3D1 loops=3D7)
Buffers: shared hit=3D17037 read=3D16390
-> Parallel Index Only Scan using i_l_shipdate on lineitem
(cost=3D0.43..120842.46 rows=3D999455 width=3D4) (actual time=3D0.062..143=
.808
rows=3D856704 loops=3D7)
Index Cond: (l_shipdate <=3D '1998-11-11
00:00:00'::timestamp without time zone)
Heap Fetches: 0
Buffers: shared hit=3D17037 read=3D16390
Planning Time: 0.552 ms
Execution Time: 225.529 ms
(14 rows)
One difference I noticed here is that "actual time" of the Parallel Index
Only Scan increased from 114ms to 143ms.
The same holds for other examples that involve Parallel Seq Scan.
Thanks,
Shijia
On Mon, Dec 16, 2019 at 7:25 AM Laurenz Albe <[email protected]>
wrote:
> On Sun, 2019-12-15 at 23:59 -0600, Shijia Wei wrote:
> > I am running TPC-H on recent postgresql (12.0 and 12.1).
> > On some of the queries (that may involve parallel scans) I see this
> interesting behavior:
> > When these queries are executed back-to-back (sent from psql interactiv=
e
> terminal), the total execution time of them increase monotonically.
> >
> > I simplified query-1 to demonstrate this effect:
> > ``` example.sql
> > explain (analyze, buffers) select
> > max(l_shipdate) as max_data,
> > count(*) as count_order
> > from
> > lineitem
> > where
> > l_shipdate <=3D date '1998-12-01' - interval '20' day;
> > ```
> >
> > When I execute (from fish) following command:
> > `for i in (seq 1 20); psql tpch < example.sql | grep Execution; end`
> > The results I get are as follows:
> > "
> > Execution Time: 184.864 ms
> > Execution Time: 192.758 ms
> > Execution Time: 197.380 ms
> > Execution Time: 200.384 ms
> > Execution Time: 202.950 ms
> > Execution Time: 205.695 ms
> > Execution Time: 208.082 ms
> > Execution Time: 209.108 ms
> > Execution Time: 212.428 ms
> > Execution Time: 214.539 ms
> > Execution Time: 215.799 ms
> > Execution Time: 219.057 ms
> > Execution Time: 222.102 ms
> > Execution Time: 223.779 ms
> > Execution Time: 227.819 ms
> > Execution Time: 229.710 ms
> > Execution Time: 239.439 ms
> > Execution Time: 237.649 ms
> > Execution Time: 249.178 ms
> > Execution Time: 261.268 ms
>
> I don't know TPC-H, but the slowdown is not necessarily surprising:
>
> If the number of rows that satisfy the condition keeps growing over time,
> counting those rows will necessarily take longer.
>
> Maybe you can provide more details, for example EXPLAIN (ANALYZE, BUFFERS=
)
> output for the query when it is fast and when it is slow.
>
> Yours,
> Laurenz Albe
> --
> +43-670-6056265
> Cybertec Sch=C3=B6nig & Sch=C3=B6nig GmbH
> Gr=C3=B6hrm=C3=BChlgasse 26, A-2700 Wiener Neustadt
> Web: https://www.cybertec-postgresql.com
>
--000000000000227a760599d58be6
Content-Type: text/html; charset="UTF-8"
Content-Transfer-Encoding: quoted-printable
<div dir=3D"ltr"><div dir=3D"ltr"><div class=3D"gmail_default" style=3D"fon=
t-family:arial,helvetica,sans-serif">Hi <span class=3D"" id=3D":159.1" tabi=
ndex=3D"-1" style=3D"">Laurenz</span>,</div><div class=3D"gmail_default" st=
yle=3D"font-family:arial,helvetica,sans-serif"><br></div><div class=3D"gmai=
l_default" style=3D"font-family:arial,helvetica,sans-serif">Each time the i=
dentical query executes, the total number of rows selected stays the same. =
The table is actually not modified between/during runs.</div><div class=3D"=
gmail_default" style=3D"font-family:arial,helvetica,sans-serif"><br></div><=
div class=3D"gmail_default" style=3D"font-family:arial,helvetica,sans-serif=
">The query plan stays the same between fast and slow runs. Please find two=
copied here:<br>The first one is the output of the first query in the loop=
1-to-20; The second one is the output of the last query (20th).</div><div =
class=3D"gmail_default" style=3D"font-family:arial,helvetica,sans-serif"><b=
r></div><div class=3D"gmail_default" style=3D""><font face=3D"monospace">1s=
t Query:</font></div><div class=3D"gmail_default" style=3D""><font face=3D"=
monospace">=C2=A0Finalize Aggregate =C2=A0(cost=3D126840.37..126840.38 rows=
=3D1 width=3D12) (actual time=3D178.825..178.826 rows=3D1 loops=3D1)<br>=C2=
=A0 =C2=A0Buffers: shared hit=3D17074 read=3D16388<br>=C2=A0 =C2=A0-> =
=C2=A0Gather =C2=A0(cost=3D126839.73..126840.34 rows=3D6 width=3D12) (actua=
l time=3D178.786..180.064 rows=3D7 loops=3D1)<br>=C2=A0 =C2=A0 =C2=A0 =C2=
=A0 =C2=A0Workers Planned: 6<br>=C2=A0 =C2=A0 =C2=A0 =C2=A0 =C2=A0Workers L=
aunched: 6<br>=C2=A0 =C2=A0 =C2=A0 =C2=A0 =C2=A0Buffers: shared hit=3D17074=
read=3D16388<br>=C2=A0 =C2=A0 =C2=A0 =C2=A0 =C2=A0-> =C2=A0Partial Aggr=
egate =C2=A0(cost=3D125839.73..125839.74 rows=3D1 width=3D12) (actual time=
=3D176.781..176.781 rows=3D1 loops=3D7)<br>=C2=A0 =C2=A0 =C2=A0 =C2=A0 =C2=
=A0 =C2=A0 =C2=A0 =C2=A0Buffers: shared hit=3D17074 read=3D16388<br>=C2=A0 =
=C2=A0 =C2=A0 =C2=A0 =C2=A0 =C2=A0 =C2=A0 =C2=A0-> =C2=A0Parallel Index =
Only Scan using i_l_<span class=3D"" id=3D":159.2" tabindex=3D"-1" style=3D=
"">shipdate</span> on <span class=3D"" id=3D":159.3" tabindex=3D"-1" style=
=3D"">lineitem</span> =C2=A0(cost=3D0.43..120842.46 rows=3D999455 width=3D4=
) (actual time=3D0.045..114.871 rows=3D856704 loops=3D7)<br>=C2=A0 =C2=A0 =
=C2=A0 =C2=A0 =C2=A0 =C2=A0 =C2=A0 =C2=A0 =C2=A0 =C2=A0 =C2=A0Index <span c=
lass=3D"" id=3D":159.4" tabindex=3D"-1" style=3D"">Cond</span>: (l_<span cl=
ass=3D"" id=3D":159.5" tabindex=3D"-1" style=3D"">shipdate</span> <=3D &=
#39;1998-11-11 00:00:00'::timestamp without time zone)<br>=C2=A0 =C2=A0=
=C2=A0 =C2=A0 =C2=A0 =C2=A0 =C2=A0 =C2=A0 =C2=A0 =C2=A0 =C2=A0Heap Fetches=
: 0<br>=C2=A0 =C2=A0 =C2=A0 =C2=A0 =C2=A0 =C2=A0 =C2=A0 =C2=A0 =C2=A0 =C2=
=A0 =C2=A0Buffers: shared hit=3D17074 read=3D16388<br>=C2=A0Planning Time: =
0.458 ms<br>=C2=A0Execution Time: 180.111 ms<br>(14 rows)</font><br></div><=
div class=3D"gmail_default" style=3D""><font face=3D"monospace"><br></font>=
</div><div class=3D"gmail_default" style=3D""><font face=3D"monospace">20th=
Query:</font></div><div class=3D"gmail_default" style=3D""><font face=3D"m=
onospace">=C2=A0Finalize Aggregate =C2=A0(cost=3D126840.37..126840.38 rows=
=3D1 width=3D12) (actual time=3D223.928..223.929 rows=3D1 loops=3D1)<br>=C2=
=A0 =C2=A0Buffers: shared hit=3D17037 read=3D16390<br>=C2=A0 =C2=A0-> =
=C2=A0Gather =C2=A0(cost=3D126839.73..126840.34 rows=3D6 width=3D12) (actua=
l time=3D223.856..225.474 rows=3D7 loops=3D1)<br>=C2=A0 =C2=A0 =C2=A0 =C2=
=A0 =C2=A0Workers Planned: 6<br>=C2=A0 =C2=A0 =C2=A0 =C2=A0 =C2=A0Workers L=
aunched: 6<br>=C2=A0 =C2=A0 =C2=A0 =C2=A0 =C2=A0Buffers: shared hit=3D17037=
read=3D16390<br>=C2=A0 =C2=A0 =C2=A0 =C2=A0 =C2=A0-> =C2=A0Partial Aggr=
egate =C2=A0(cost=3D125839.73..125839.74 rows=3D1 width=3D12) (actual time=
=3D221.918..221.918 rows=3D1 loops=3D7)<br>=C2=A0 =C2=A0 =C2=A0 =C2=A0 =C2=
=A0 =C2=A0 =C2=A0 =C2=A0Buffers: shared hit=3D17037 read=3D16390<br>=C2=A0 =
=C2=A0 =C2=A0 =C2=A0 =C2=A0 =C2=A0 =C2=A0 =C2=A0-> =C2=A0Parallel Index =
Only Scan using i_l_<span class=3D"" id=3D":159.6" tabindex=3D"-1" style=3D=
"">shipdate</span> on <span class=3D"" id=3D":159.7" tabindex=3D"-1" style=
=3D"">lineitem</span> =C2=A0(cost=3D0.43..120842.46 rows=3D999455 width=3D4=
) (actual time=3D0.062..143.808 rows=3D856704 loops=3D7)<br>=C2=A0 =C2=A0 =
=C2=A0 =C2=A0 =C2=A0 =C2=A0 =C2=A0 =C2=A0 =C2=A0 =C2=A0 =C2=A0Index <span c=
lass=3D"" id=3D":159.8" tabindex=3D"-1" style=3D"">Cond</span>: (l_<span cl=
ass=3D"" id=3D":159.9" tabindex=3D"-1" style=3D"">shipdate</span> <=3D &=
#39;1998-11-11 00:00:00'::timestamp without time zone)<br>=C2=A0 =C2=A0=
=C2=A0 =C2=A0 =C2=A0 =C2=A0 =C2=A0 =C2=A0 =C2=A0 =C2=A0 =C2=A0Heap Fetches=
: 0<br>=C2=A0 =C2=A0 =C2=A0 =C2=A0 =C2=A0 =C2=A0 =C2=A0 =C2=A0 =C2=A0 =C2=
=A0 =C2=A0Buffers: shared hit=3D17037 read=3D16390<br>=C2=A0Planning Time: =
0.552 ms<br>=C2=A0Execution Time: 225.529 ms<br>(14 rows)</font><br></div><=
div class=3D"gmail_default" style=3D""><font face=3D"monospace"><br></font>=
</div><div class=3D"gmail_default" style=3D""><font face=3D"arial, sans-ser=
if">One=C2=A0 difference I noticed here is that "actual time" of =
the Parallel Index Only Scan increased from 114ms to 143ms.</font></div><di=
v class=3D"gmail_default" style=3D""><font face=3D"arial, sans-serif">The s=
ame holds for other examples that involve Parallel Seq Scan.</font></div><d=
iv class=3D"gmail_default" style=3D""><font face=3D"arial, sans-serif"><br>=
</font></div><div class=3D"gmail_default" style=3D""><font face=3D"arial, s=
ans-serif">Thanks,</font></div><div class=3D"gmail_default" style=3D""><fon=
t face=3D"arial, sans-serif"><span class=3D"" id=3D":159.10" tabindex=3D"-1=
" style=3D"">Shijia</span></font></div></div><br><br><div class=3D"gmail_qu=
ote"><div dir=3D"ltr" class=3D"gmail_attr">On Mon, Dec 16, 2019 at 7:25 AM =
Laurenz Albe <<a href=3D"mailto:[email protected]">laurenz.albe@c=
ybertec.at</a>> wrote:<br></div><blockquote class=3D"gmail_quote" style=
=3D"margin:0px 0px 0px 0.8ex;border-left:1px solid rgb(204,204,204);padding=
-left:1ex">On Sun, 2019-12-15 at 23:59 -0600, Shijia Wei wrote:<br>
> I am running TPC-H on recent postgresql (12.0 and 12.1).<br>
> On some of the queries (that may involve parallel scans) I see this in=
teresting behavior:<br>
> When these queries are executed back-to-back (sent from psql interacti=
ve terminal), the total execution time of them increase monotonically.<br>
> <br>
> I simplified query-1 to demonstrate this effect:<br>
> ``` example.sql<br>
> explain (analyze, buffers) select<br>
>=C2=A0 =C2=A0 =C2=A0 =C2=A0 =C2=A0max(l_shipdate) as max_data,<br>
>=C2=A0 =C2=A0 =C2=A0 =C2=A0 =C2=A0count(*) as count_order<br>
> from<br>
>=C2=A0 =C2=A0 =C2=A0 =C2=A0 =C2=A0lineitem<br>
> where<br>
>=C2=A0 =C2=A0 =C2=A0 =C2=A0 =C2=A0l_shipdate <=3D date '1998-12-=
01' - interval '20' day;<br>
> ```<br>
> <br>
> When I execute (from fish) following command:<br>
> `for i in (seq 1 20); psql tpch < example.sql | grep Execution; end=
`<br>
> The results I get are as follows:<br>
> "<br>
>=C2=A0 Execution Time: 184.864 ms<br>
>=C2=A0 Execution Time: 192.758 ms<br>
>=C2=A0 Execution Time: 197.380 ms<br>
>=C2=A0 Execution Time: 200.384 ms<br>
>=C2=A0 Execution Time: 202.950 ms<br>
>=C2=A0 Execution Time: 205.695 ms<br>
>=C2=A0 Execution Time: 208.082 ms<br>
>=C2=A0 Execution Time: 209.108 ms<br>
>=C2=A0 Execution Time: 212.428 ms<br>
>=C2=A0 Execution Time: 214.539 ms<br>
>=C2=A0 Execution Time: 215.799 ms<br>
>=C2=A0 Execution Time: 219.057 ms<br>
>=C2=A0 Execution Time: 222.102 ms<br>
>=C2=A0 Execution Time: 223.779 ms<br>
>=C2=A0 Execution Time: 227.819 ms<br>
>=C2=A0 Execution Time: 229.710 ms<br>
>=C2=A0 Execution Time: 239.439 ms<br>
>=C2=A0 Execution Time: 237.649 ms<br>
>=C2=A0 Execution Time: 249.178 ms<br>
>=C2=A0 Execution Time: 261.268 ms<br>
<br>
I don't know TPC-H, but the slowdown is not necessarily surprising:<br>
<br>
If the number of rows that satisfy the condition keeps growing over time,<b=
r>
counting those rows will necessarily take longer.<br>
<br>
Maybe you can provide more details, for example EXPLAIN (ANALYZE, BUFFERS)<=
br>
output for the query when it is fast and when it is slow.<br>
<br>
Yours,<br>
Laurenz Albe<br>
-- <br>
+43-670-6056265<br>
Cybertec Sch=C3=B6nig & Sch=C3=B6nig GmbH<br>
Gr=C3=B6hrm=C3=BChlgasse 26, A-2700 Wiener Neustadt<br>
Web: <a href=3D"https://www.cybertec-postgresql.com" rel=3D"noreferrer" tar=
get=3D"_blank">https://www.cybertec-postgresql.com</a><br></blockquote></di=
v><div dir=3D"ltr" class=3D"gmail_signature"><div dir=3D"ltr"><div><div dir=
=3D"ltr"><div><div dir=3D"ltr"><div><div dir=3D"ltr"><div><div dir=3D"ltr">=
<div dir=3D"ltr"><font color=3D"#888888" face=3D"Verdana" size=3D"1"></font=
></div></div></div></div></div></div></div></div></div></div></div></div>
--000000000000227a760599d58be6--