Thread: Consecutive Query Executions with Increasing Execution Time

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 interactive terminal), the total execution time of them
increasemonotonically.
 
> 
> 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

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önig & Schönig GmbH
Gröhrmühlgasse 26, A-2700 Wiener Neustadt
Web: https://www.cybertec-postgresql.com

Shijia Wei <shijiawei@utexas.edu> writes:
> 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.

FWIW, I can't reproduce this here.  Using a different chosen-at-random
query, I tried

$ for i in `seq 1 20`; do
> psql -c 'explain (analyze) select * from tenk1 a,tenk1 b where a.hundred=b.hundred;' regression | grep Execution
> done
 Execution Time: 468.548 ms
 Execution Time: 467.905 ms
 Execution Time: 467.634 ms
 Execution Time: 465.852 ms
 Execution Time: 463.328 ms
 Execution Time: 462.541 ms
 Execution Time: 463.922 ms
 Execution Time: 466.171 ms
 Execution Time: 464.778 ms
 Execution Time: 464.474 ms
 Execution Time: 466.087 ms
 Execution Time: 463.092 ms
 Execution Time: 463.700 ms
 Execution Time: 468.924 ms
 Execution Time: 464.970 ms
 Execution Time: 464.844 ms
 Execution Time: 464.665 ms
 Execution Time: 465.247 ms
 Execution Time: 465.931 ms
 Execution Time: 466.722 ms


> 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.

A conceivable theory is that the previous backends haven't exited yet and
the extra runtime represents overhead due to having lots of active
PGPROC entries.  This is pretty hard to credit on a multi-core machine,
however.  I think it'd require assuming that the old backends have some
seconds' worth of cleanup work to do before they can exit, which makes
little sense.  (Unless, perhaps, you have turned on coverage
instrumentation, or some other expensive debug monitoring?)

I concur with the suggestion to try to pin down where the cycles are
going.  I'd suggest using perf or some similar tool.

            regards, tom lane

On Mon, Dec 16, 2019 at 9:28 AM Shijia Wei <shijiawei@utexas.edu> wrote:
> 1st Query:

>                      Buffers: shared hit=17074 read=16388

> 20th Query:

>                      Buffers: shared hit=17037 read=16390

Why do the first and the twentieth executions of the query have almost
identical "buffers shared/read" numbers? That seems odd.

-- 
Peter Geoghegan

Peter Geoghegan <pg@bowt.ie> writes:
> Why do the first and the twentieth executions of the query have almost
> identical "buffers shared/read" numbers? That seems odd.

It's repeat execution of the same query, so that doesn't seem odd to me.

This last set of numbers suggests that there's some issue with the
parallel execution infrastructure in particular, though I don't see what
it would be.  Doesn't execParallel wait for the workers to exit before
the leader finishes its query?  If so, how is there any persistent state
that would interfere with a later query?

            regards, tom lane

Could it be that your CPUs is warming and throttling? You didn't mention the platform used, so I'm not sure whether
it'sa server or a laptop 

Nicolas

Le 16 décembre 2019 21:50:17 GMT+01:00, Tom Lane <tgl@sss.pgh.pa.us> a écrit :
>Peter Geoghegan <pg@bowt.ie> writes:
>> Why do the first and the twentieth executions of the query have
>almost
>> identical "buffers shared/read" numbers? That seems odd.
>
>It's repeat execution of the same query, so that doesn't seem odd to
>me.
>
>This last set of numbers suggests that there's some issue with the
>parallel execution infrastructure in particular, though I don't see
>what
>it would be.  Doesn't execParallel wait for the workers to exit before
>the leader finishes its query?  If so, how is there any persistent
>state
>that would interfere with a later query?
>
>            regards, tom lane

--
Envoyé de mon appareil Android avec Courriel K-9 Mail. Veuillez excuser ma brièveté.

Nicolas Charles <nicolas.charles@normation.com> writes:
> Could it be that your CPUs is warming and throttling? You didn't mention the platform used, so I'm not sure whether
it'sa server or a laptop 

Hmm, that's an interesting thought.  The OP did say the CPU type,
but according to Intel's spec page for it [1] the difference between
base and turbo frequency is only 4.0 vs 4.2 GHz, which doesn't seem
like enough to explain the results ... unless you suppose it actually
throttled to below base freq, which surely shouldn't happen that fast.
Might be worth watching the CPU frequency while doing the test though.

I was speculating about some OS-level problem myself.  Plain old "top"
might be enough to show relevant info if it's in that area.

            regards, tom lane

[1]
https://ark.intel.com/content/www/us/en/ark/products/88195/intel-core-i7-6700k-processor-8m-cache-up-to-4-20-ghz.html

Hi,

On 2019-12-16 17:48:16 -0500, Tom Lane wrote:
> Hmm, that's an interesting thought.  The OP did say the CPU type,
> but according to Intel's spec page for it [1] the difference between
> base and turbo frequency is only 4.0 vs 4.2 GHz, which doesn't seem
> like enough to explain the results ... unless you suppose it actually
> throttled to below base freq, which surely shouldn't happen that fast.
> Might be worth watching the CPU frequency while doing the test though.

FWIW, it takes about 3s for my laptop CPU to throttle way below
non-turbo when I put it under strenuous load. Obviously that's a laptop,
and caused by a firmware bug leading to fans not spinning fast enough
automatically. But it'd not take that much for insufficient cooling to
cause problems in a desktop either. Been there, done that.

But: I don't see that causing a 10x slowdown as reported in the first
mail in this thread.


I think we need a system-wide perf profile during a few initial "good"
runs and then later from a few "really bad" runs. For that you'd have to
make sure you compiled postgres with debug symbols (--enable-debug to
configure), and then run something like
perf record -o fast.data --call-graph dwarf -a sleep 3
while running repeated "fast" queries and then
perf record -o slow.data --call-graph dwarf -a sleep 3

and then show us the results of something like
perf report -i fast.data -g folded --percent-limit 1 > fast.txt
perf report -i slow.data -g folded --percent-limit 1 > slow.txt

and also, if your perf is new enough:
perf diff fast.data slow.data > diff.txt

- Andres

On Mon, 2019-12-16 at 15:50 -0500, Tom Lane wrote:
> Peter Geoghegan <pg@bowt.ie> writes:
> > Why do the first and the twentieth executions of the query have almost
> > identical "buffers shared/read" numbers? That seems odd.
> 
> It's repeat execution of the same query, so that doesn't seem odd to me.

Really?  Shouldn't the blocks be in shared buffers after a couple
of executions?

Yours,
Laurenz Albe
-- 
Cybertec | https://www.cybertec-postgresql.com

On Tue, 2019-12-17 at 11:11 -0500, Jeff Janes wrote:
> On Tue, Dec 17, 2019 at 8:08 AM Laurenz Albe <laurenz.albe@cybertec.at> wrote:
> > On Mon, 2019-12-16 at 15:50 -0500, Tom Lane wrote:
> > > Peter Geoghegan <pg@bowt.ie> writes:
> > > > Why do the first and the twentieth executions of the query have almost
> > > > identical "buffers shared/read" numbers? That seems odd.
> > > 
> > > It's repeat execution of the same query, so that doesn't seem odd to me.
> > 
> > Really?  Shouldn't the blocks be in shared buffers after a couple
> > of executions?
> 
> If it is doing a seq scan (I don't know if it is) they intentionally use a
> small ring buffer to, so they evict their own recently used blocks, rather
> than evicting other people's blocks.  So these blocks won't build up in
> shared_buffers very rapidly just on the basis of repeated seq scans.

Sure, but according to the execution plans it is doing a Parallel Index Only Scan.

Yours,
Laurenz Albe
-- 
Cybertec | https://www.cybertec-postgresql.com

Laurenz Albe <laurenz.albe@cybertec.at> writes:
> On Tue, 2019-12-17 at 11:11 -0500, Jeff Janes wrote:
>> If it is doing a seq scan (I don't know if it is) they intentionally use a
>> small ring buffer to, so they evict their own recently used blocks, rather
>> than evicting other people's blocks.  So these blocks won't build up in
>> shared_buffers very rapidly just on the basis of repeated seq scans.

> Sure, but according to the execution plans it is doing a Parallel Index Only Scan.

Nonetheless, the presented test case consists of repeatedly doing
the same query, in a fresh session each time.  If there's not other
activity then this should reach some sort of steady state.  The
table is apparently fairly large, so I don't find it surprising
that the steady state fails to be 100% cached.

            regards, tom lane