Re: Consecutive Query Executions with Increasing Execution Time
Olivier Gautherot <[email protected]> Mon, 16 Dec 2019 09:03:54 +0100
| Newsgroups | gmane.comp.db.postgresql.performance |
|---|---|
| Message-ID | <CAJ7S9TWyZyO8MzxfpcNQJ=5RqiyoerWj_vD5nDQBNJCTJGGCkw@mail.gmail.com> |
--0000000000007abcdb0599cda7bf Content-Type: text/plain; charset="UTF-8" Hi Shijia, It sounds like concurrency on the queries: the second starts before the first ends, and so on. With a short wait in between you ensure sequential execution. Notice that you also have the overhead of concurrent psql... Sounds normal to me. Best regards Olivier On Mon, Dec 16, 2019, 07:00 Shijia Wei <[email protected]> wrote: > Hi all, > > 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 interactive > 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 <= 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 > " > In addition, if the repeated more times, the total execution time can end > up being 10X and more!!! > > When there a wait period in-between queries, (e.g. sleep 10) in the above > for loop, this increasing execution time behavior goes a way. > For more complex queries, the "wait period" needs to be longer to avoid > the increase in execution time. > > Some metadata about this table "lineitem": > tpch=# \d lineitem > Table "public.lineitem" > Column | Type | Collation | Nullable | Default > -----------------+-----------------------+-----------+----------+--------- > l_orderkey | integer | | not null | > l_partkey | integer | | not null | > l_suppkey | integer | | not null | > l_linenumber | integer | | not null | > l_quantity | numeric(15,2) | | not null | > l_extendedprice | numeric(15,2) | | not null | > l_discount | numeric(15,2) | | not null | > l_tax | numeric(15,2) | | not null | > l_returnflag | character(1) | | not null | > l_linestatus | character(1) | | not null | > l_shipdate | date | | not null | > l_commitdate | date | | not null | > l_receiptdate | date | | not null | > l_shipinstruct | character(25) | | not null | > l_shipmode | character(10) | | not null | > l_comment | character varying(44) | | not null | > Indexes: > "i_l_commitdate" btree (l_commitdate) > "i_l_orderkey" btree (l_orderkey) > "i_l_orderkey_quantity" btree (l_orderkey, l_quantity) > "i_l_partkey" btree (l_partkey) > "i_l_receiptdate" btree (l_receiptdate) > "i_l_shipdate" btree (l_shipdate) > "i_l_suppkey" btree (l_suppkey) > "i_l_suppkey_partkey" btree (l_partkey, l_suppkey) > > tpch=# SELECT relname, relpages, reltuples, relallvisible, relkind, > relnatts, relhassubclass, reloptions, pg_table_size(oid) FROM pg_class > WHERE relname='lineitem'; > relname | relpages | reltuples | relallvisible | relkind | relnatts > | relhassubclass | reloptions | pg_table_size > > ----------+----------+--------------+---------------+---------+----------+----------------+------------+--------------- > lineitem | 112503 | 6.001167e+06 | 112503 | r | 16 > | f | | 921903104 > (1 row) > > Postgresql 12.0 and 12.1 are all manually installed from source. > Both are running on Ubuntu 16.04 kernel 4.4.0-142-generic, on Intel(R) > Core(TM) i7-6700K. > > > Any help greatly appreciated! > > Shijia > --0000000000007abcdb0599cda7bf Content-Type: text/html; charset="UTF-8" Content-Transfer-Encoding: quoted-printable <div dir=3D"auto"><div>Hi Shijia,<br><br>It sounds like concurrency on the = queries: the second starts before the first ends, and so on. With a short w= ait in between you ensure sequential execution. Notice that you also have t= he overhead of concurrent psql...</div><div dir=3D"auto"><br></div><div dir= =3D"auto">Sounds normal to me.</div><div dir=3D"auto"><br></div><div dir=3D= "auto">Best regards</div><div dir=3D"auto">Olivier</div><div dir=3D"auto"><= br></div><div dir=3D"auto"><br><div class=3D"gmail_quote" dir=3D"auto"><div= dir=3D"ltr" class=3D"gmail_attr">On Mon, Dec 16, 2019, 07:00 Shijia Wei &l= t;<a href=3D"mailto:[email protected]">[email protected]</a>> wrot= e:<br></div><blockquote class=3D"gmail_quote" style=3D"margin:0 0 0 .8ex;bo= rder-left:1px #ccc solid;padding-left:1ex"><div dir=3D"ltr"><div class=3D"g= mail_default" style=3D"font-family:arial,helvetica,sans-serif">Hi all,</div= ><div class=3D"gmail_default" style=3D"font-family:arial,helvetica,sans-ser= if"><br></div><div class=3D"gmail_default" style=3D"font-family:arial,helve= tica,sans-serif">I am running <span id=3D"m_4960127569523798833:1wh.1">TPC<= /span>-H on recent <span id=3D"m_4960127569523798833:1wh.2">postgresql</spa= n> (12.0 and 12.1).</div><div class=3D"gmail_default" style=3D"font-family:= arial,helvetica,sans-serif">On some of the queries (that may involve parall= el scans) I see this interesting behavior:</div><div class=3D"gmail_default= " style=3D"font-family:arial,helvetica,sans-serif">When these queries are e= xecuted back-to-back (sent from <span id=3D"m_4960127569523798833:1wh.3">ps= ql</span> interactive terminal), the total execution time of them increase= =C2=A0monotonically.</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">I simplified query-1 to demonst= rate this effect:</div><div class=3D"gmail_default"><font face=3D"monospace= ">``` example.<span id=3D"m_4960127569523798833:1wh.4">sql</span></font></d= iv><div class=3D"gmail_default"><font face=3D"monospace">explain (analyze, = buffers) select<br>=C2=A0 =C2=A0 =C2=A0 =C2=A0 max(l_<span id=3D"m_49601275= 69523798833:1wh.5">shipdate</span>) as max_data,<br>=C2=A0 =C2=A0 =C2=A0 = =C2=A0 count(*) as count_order<br>from<br>=C2=A0 =C2=A0 =C2=A0 =C2=A0 <span= id=3D"m_4960127569523798833:1wh.6">lineitem</span><br>where<br>=C2=A0 =C2= =A0 =C2=A0 =C2=A0 l_<span id=3D"m_4960127569523798833:1wh.7">shipdate</span= > <=3D date '1998-12-01' - interval '20' day;<br>```</fo= nt></div><div class=3D"gmail_default"><font face=3D"monospace"><br></font><= /div><div class=3D"gmail_default"><font face=3D"arial, helvetica, sans-seri= f">When I execute (from fish) following command:</font><br><font face=3D"mo= nospace">`for i in (seq 1 20); <span id=3D"m_4960127569523798833:1wh.8">psq= l</span> <span id=3D"m_4960127569523798833:1wh.9">tpch</span> < example.= <span id=3D"m_4960127569523798833:1wh.10">sql</span> | grep Execution; end`= </font><br><font face=3D"arial, helvetica, sans-serif">The results I get ar= e as follows:</font><br><font face=3D"arial, helvetica, sans-serif">"<= /font><br><font face=3D"arial, helvetica, sans-serif">=C2=A0Execution Time:= 184.864 ms</font><br><font face=3D"arial, helvetica, sans-serif">=C2=A0Exe= cution Time: 192.758 ms</font><br><font face=3D"arial, helvetica, sans-seri= f">=C2=A0Execution Time: 197.380 ms</font><br><font face=3D"arial, helvetic= a, sans-serif">=C2=A0Execution Time: 200.384 ms</font><br><font face=3D"ari= al, helvetica, sans-serif">=C2=A0Execution Time: 202.950 ms</font><br><font= face=3D"arial, helvetica, sans-serif">=C2=A0Execution Time: 205.695 ms</fo= nt><br><font face=3D"arial, helvetica, sans-serif">=C2=A0Execution Time: 20= 8.082 ms</font><br><font face=3D"arial, helvetica, sans-serif">=C2=A0Execut= ion Time: 209.108 ms</font><br><font face=3D"arial, helvetica, sans-serif">= =C2=A0Execution Time: 212.428 ms</font><br><font face=3D"arial, helvetica, = sans-serif">=C2=A0Execution Time: 214.539 ms</font><br><font face=3D"arial,= helvetica, sans-serif">=C2=A0Execution Time: 215.799 ms</font><br><font fa= ce=3D"arial, helvetica, sans-serif">=C2=A0Execution Time: 219.057 ms</font>= <br><font face=3D"arial, helvetica, sans-serif">=C2=A0Execution Time: 222.1= 02 ms</font><br><font face=3D"arial, helvetica, sans-serif">=C2=A0Execution= Time: 223.779 ms</font><br><font face=3D"arial, helvetica, sans-serif">=C2= =A0Execution Time: 227.819 ms</font><br><font face=3D"arial, helvetica, san= s-serif">=C2=A0Execution Time: 229.710 ms</font><br><font face=3D"arial, he= lvetica, sans-serif">=C2=A0Execution Time: 239.439 ms</font><br><font face= =3D"arial, helvetica, sans-serif">=C2=A0Execution Time: 237.649 ms</font><b= r><font face=3D"arial, helvetica, sans-serif">=C2=A0Execution Time: 249.178= ms</font><br><font face=3D"arial, helvetica, sans-serif">=C2=A0Execution T= ime: 261.268 ms</font><br><font face=3D"arial, helvetica, sans-serif">"= ;</font></div><div class=3D"gmail_default"><font face=3D"arial, helvetica, = sans-serif">In addition, if the repeated more times, the total execution ti= me can end up being 10X and more!!!</font></div><div class=3D"gmail_default= "><font face=3D"arial, helvetica, sans-serif"><br></font></div><div class= =3D"gmail_default"><font face=3D"arial, helvetica, sans-serif">When there a= wait period in-between queries, (e.g. </font><font face=3D"monospace">slee= p 10</font><font face=3D"arial, helvetica, sans-serif">) in the above for l= oop, this increasing execution time behavior goes a way.</font></div><div c= lass=3D"gmail_default"><font face=3D"arial, helvetica, sans-serif">For more= complex queries, the "wait period" needs to be longer to avoid t= he increase in execution time.</font></div><div class=3D"gmail_default" sty= le=3D"font-family:arial,helvetica,sans-serif"><br>Some <span id=3D"m_496012= 7569523798833:1wh.11">metadata</span> about this table "<span id=3D"m_= 4960127569523798833:1wh.12">lineitem</span>":</div><div class=3D"gmail= _default"><font face=3D"monospace"><span id=3D"m_4960127569523798833:1wh.13= ">tpch</span>=3D# \d <span id=3D"m_4960127569523798833:1wh.14">lineitem</sp= an><br>=C2=A0 =C2=A0 =C2=A0 =C2=A0 =C2=A0 =C2=A0 =C2=A0 =C2=A0 =C2=A0 =C2= =A0 =C2=A0 =C2=A0 =C2=A0Table "public.<span id=3D"m_496012756952379883= 3:1wh.15">lineitem</span>"<br>=C2=A0 =C2=A0 =C2=A0Column =C2=A0 =C2=A0= =C2=A0| =C2=A0 =C2=A0 =C2=A0 =C2=A0 Type =C2=A0 =C2=A0 =C2=A0 =C2=A0 =C2= =A0| Collation | <span id=3D"m_4960127569523798833:1wh.16">Nullable</span> = | Default<br>-----------------+-----------------------+-----------+--------= --+---------<br>=C2=A0l_<span id=3D"m_4960127569523798833:1wh.17">orderkey<= /span> =C2=A0 =C2=A0 =C2=A0| integer =C2=A0 =C2=A0 =C2=A0 =C2=A0 =C2=A0 =C2= =A0 =C2=A0 | =C2=A0 =C2=A0 =C2=A0 =C2=A0 =C2=A0 | not null |<br>=C2=A0l_<sp= an id=3D"m_4960127569523798833:1wh.18">partkey</span> =C2=A0 =C2=A0 =C2=A0 = | integer =C2=A0 =C2=A0 =C2=A0 =C2=A0 =C2=A0 =C2=A0 =C2=A0 | =C2=A0 =C2=A0 = =C2=A0 =C2=A0 =C2=A0 | not null |<br>=C2=A0l_<span id=3D"m_4960127569523798= 833:1wh.19">suppkey</span> =C2=A0 =C2=A0 =C2=A0 | integer =C2=A0 =C2=A0 =C2= =A0 =C2=A0 =C2=A0 =C2=A0 =C2=A0 | =C2=A0 =C2=A0 =C2=A0 =C2=A0 =C2=A0 | not = null |<br>=C2=A0l_<span id=3D"m_4960127569523798833:1wh.20">linenumber</spa= n> =C2=A0 =C2=A0| integer =C2=A0 =C2=A0 =C2=A0 =C2=A0 =C2=A0 =C2=A0 =C2=A0 = | =C2=A0 =C2=A0 =C2=A0 =C2=A0 =C2=A0 | not null |<br>=C2=A0l_quantity =C2= =A0 =C2=A0 =C2=A0| numeric(15,2) =C2=A0 =C2=A0 =C2=A0 =C2=A0 | =C2=A0 =C2= =A0 =C2=A0 =C2=A0 =C2=A0 | not null |<br>=C2=A0l_<span id=3D"m_496012756952= 3798833:1wh.21">extendedprice</span> | numeric(15,2) =C2=A0 =C2=A0 =C2=A0 = =C2=A0 | =C2=A0 =C2=A0 =C2=A0 =C2=A0 =C2=A0 | not null |<br>=C2=A0l_discoun= t =C2=A0 =C2=A0 =C2=A0| numeric(15,2) =C2=A0 =C2=A0 =C2=A0 =C2=A0 | =C2=A0 = =C2=A0 =C2=A0 =C2=A0 =C2=A0 | not null |<br>=C2=A0l_tax =C2=A0 =C2=A0 =C2= =A0 =C2=A0 =C2=A0 | numeric(15,2) =C2=A0 =C2=A0 =C2=A0 =C2=A0 | =C2=A0 =C2= =A0 =C2=A0 =C2=A0 =C2=A0 | not null |<br>=C2=A0l_<span id=3D"m_496012756952= 3798833:1wh.22">returnflag</span> =C2=A0 =C2=A0| character(1) =C2=A0 =C2=A0= =C2=A0 =C2=A0 =C2=A0| =C2=A0 =C2=A0 =C2=A0 =C2=A0 =C2=A0 | not null |<br>= =C2=A0l_<span id=3D"m_4960127569523798833:1wh.23">linestatus</span> =C2=A0 = =C2=A0| character(1) =C2=A0 =C2=A0 =C2=A0 =C2=A0 =C2=A0| =C2=A0 =C2=A0 =C2= =A0 =C2=A0 =C2=A0 | not null |<br>=C2=A0l_<span id=3D"m_4960127569523798833= :1wh.24">shipdate</span> =C2=A0 =C2=A0 =C2=A0| date =C2=A0 =C2=A0 =C2=A0 = =C2=A0 =C2=A0 =C2=A0 =C2=A0 =C2=A0 =C2=A0| =C2=A0 =C2=A0 =C2=A0 =C2=A0 =C2= =A0 | not null |<br>=C2=A0l_<span id=3D"m_4960127569523798833:1wh.25">commi= tdate</span> =C2=A0 =C2=A0| date =C2=A0 =C2=A0 =C2=A0 =C2=A0 =C2=A0 =C2=A0 = =C2=A0 =C2=A0 =C2=A0| =C2=A0 =C2=A0 =C2=A0 =C2=A0 =C2=A0 | not null |<br>= =C2=A0l_<span id=3D"m_4960127569523798833:1wh.26">receiptdate</span> =C2=A0= | date =C2=A0 =C2=A0 =C2=A0 =C2=A0 =C2=A0 =C2=A0 =C2=A0 =C2=A0 =C2=A0| =C2= =A0 =C2=A0 =C2=A0 =C2=A0 =C2=A0 | not null |<br>=C2=A0l_<span id=3D"m_49601= 27569523798833:1wh.27">shipinstruct</span> =C2=A0| character(25) =C2=A0 =C2= =A0 =C2=A0 =C2=A0 | =C2=A0 =C2=A0 =C2=A0 =C2=A0 =C2=A0 | not null |<br>=C2= =A0l_<span id=3D"m_4960127569523798833:1wh.28">shipmode</span> =C2=A0 =C2= =A0 =C2=A0| character(10) =C2=A0 =C2=A0 =C2=A0 =C2=A0 | =C2=A0 =C2=A0 =C2= =A0 =C2=A0 =C2=A0 | not null |<br>=C2=A0l_comment =C2=A0 =C2=A0 =C2=A0 | ch= aracter varying(44) | =C2=A0 =C2=A0 =C2=A0 =C2=A0 =C2=A0 | not null |<br>In= dexes:<br>=C2=A0 =C2=A0 "i_l_<span id=3D"m_4960127569523798833:1wh.29"= >commitdate</span>" <span id=3D"m_4960127569523798833:1wh.30">btree</s= pan> (l_<span id=3D"m_4960127569523798833:1wh.31">commitdate</span>)<br>=C2= =A0 =C2=A0 "i_l_<span id=3D"m_4960127569523798833:1wh.32">orderkey</sp= an>" <span id=3D"m_4960127569523798833:1wh.33">btree</span> (l_<span i= d=3D"m_4960127569523798833:1wh.34">orderkey</span>)<br>=C2=A0 =C2=A0 "= i_l_<span id=3D"m_4960127569523798833:1wh.35">orderkey</span>_quantity"= ; <span id=3D"m_4960127569523798833:1wh.36">btree</span> (l_<span id=3D"m_4= 960127569523798833:1wh.37">orderkey</span>, l_quantity)<br>=C2=A0 =C2=A0 &q= uot;i_l_<span id=3D"m_4960127569523798833:1wh.38">partkey</span>" <spa= n id=3D"m_4960127569523798833:1wh.39">btree</span> (l_<span id=3D"m_4960127= 569523798833:1wh.40">partkey</span>)<br>=C2=A0 =C2=A0 "i_l_<span id=3D= "m_4960127569523798833:1wh.41">receiptdate</span>" <span id=3D"m_49601= 27569523798833:1wh.42">btree</span> (l_<span id=3D"m_4960127569523798833:1w= h.43">receiptdate</span>)<br>=C2=A0 =C2=A0 "i_l_<span id=3D"m_49601275= 69523798833:1wh.44">shipdate</span>" <span id=3D"m_4960127569523798833= :1wh.45">btree</span> (l_<span id=3D"m_4960127569523798833:1wh.46">shipdate= </span>)<br>=C2=A0 =C2=A0 "i_l_<span id=3D"m_4960127569523798833:1wh.4= 7">suppkey</span>" <span id=3D"m_4960127569523798833:1wh.48">btree</sp= an> (l_<span id=3D"m_4960127569523798833:1wh.49">suppkey</span>)<br>=C2=A0 = =C2=A0 "i_l_<span id=3D"m_4960127569523798833:1wh.50">suppkey</span>_<= span id=3D"m_4960127569523798833:1wh.51">partkey</span>" <span id=3D"m= _4960127569523798833:1wh.52">btree</span> (l_<span id=3D"m_4960127569523798= 833:1wh.53">partkey</span>, l_<span id=3D"m_4960127569523798833:1wh.54">sup= pkey</span>)<br></font></div><div class=3D"gmail_default"><font face=3D"mon= ospace"><br></font></div><div class=3D"gmail_default"><font face=3D"monospa= ce"><span id=3D"m_4960127569523798833:1wh.55">tpch</span>=3D# SELECT <span = id=3D"m_4960127569523798833:1wh.56">relname</span>, <span id=3D"m_496012756= 9523798833:1wh.57">relpages</span>, <span id=3D"m_4960127569523798833:1wh.5= 8">reltuples</span>, <span id=3D"m_4960127569523798833:1wh.59">relallvisibl= e</span>, <span id=3D"m_4960127569523798833:1wh.60">relkind</span>, <span i= d=3D"m_4960127569523798833:1wh.61">relnatts</span>, <span id=3D"m_496012756= 9523798833:1wh.62">relhassubclass</span>, <span id=3D"m_4960127569523798833= :1wh.63">reloptions</span>, pg_table_size(<span id=3D"m_4960127569523798833= :1wh.64">oid</span>) FROM pg_class WHERE <span id=3D"m_4960127569523798833:= 1wh.65">relname</span>=3D'lineitem';<br>=C2=A0<span id=3D"m_4960127= 569523798833:1wh.66">relname</span> =C2=A0| <span id=3D"m_49601275695237988= 33:1wh.67">relpages</span> | =C2=A0<span id=3D"m_4960127569523798833:1wh.68= ">reltuples</span> =C2=A0 | <span id=3D"m_4960127569523798833:1wh.69">relal= lvisible</span> | <span id=3D"m_4960127569523798833:1wh.70">relkind</span> = | <span id=3D"m_4960127569523798833:1wh.71">relnatts</span> | <span id=3D"m= _4960127569523798833:1wh.72">relhassubclass</span> | <span id=3D"m_49601275= 69523798833:1wh.73">reloptions</span> | pg_table_size<br>----------+-------= ---+--------------+---------------+---------+----------+----------------+--= ----------+---------------<br>=C2=A0<span id=3D"m_4960127569523798833:1wh.7= 4">lineitem</span> | =C2=A0 112503 | 6.001167e+06 | =C2=A0 =C2=A0 =C2=A0 = =C2=A0112503 | r =C2=A0 =C2=A0 =C2=A0 | =C2=A0 =C2=A0 =C2=A0 16 | f =C2=A0 = =C2=A0 =C2=A0 =C2=A0 =C2=A0 =C2=A0 =C2=A0| =C2=A0 =C2=A0 =C2=A0 =C2=A0 =C2= =A0 =C2=A0| =C2=A0 =C2=A0 921903104<br>(1 row)</font><br></div><div class= =3D"gmail_default"><font face=3D"monospace"><br></font></div><div class=3D"= gmail_default"><font face=3D"arial, sans-serif"><span id=3D"m_4960127569523= 798833:1wh.75">Postgresql</span> 12.0 and 12.1 are all=C2=A0</font>manually= installed from source.</div><div class=3D"gmail_default"><font face=3D"ari= al, sans-serif">Both are running on <span id=3D"m_4960127569523798833:1wh.7= 6">Ubuntu</span> 16.04 kernel=C2=A0</font>4.4.0-142-generic, on Intel(R) Co= re(TM) i7-6700K.</div><div class=3D"gmail_default"><br></div><div class=3D"= gmail_default"><br></div><div class=3D"gmail_default">Any help greatly appr= eciated!</div><div class=3D"gmail_default"><br></div><div class=3D"gmail_de= fault"><span id=3D"m_4960127569523798833:1wh.77">Shijia</span></div></div> </blockquote></div></div></div> --0000000000007abcdb0599cda7bf--