From: Laurenz Albe <laurenz.albe@cybertec.at>
To: James Thompson <james@jthompson.dev>
To: Justin Pryzby <pryzby@telsasoft.com>
Cc: pgsql-performance@postgresql.org
Subject: Re: Please help! Query jumps from 1s -> 4m
Date: Tue, 05 May 2020 10:08:20 +0200
Message-ID: <1949097f3ae6189d111d4e0dba63505db958ffef.camel@cybertec.at> (raw)
In-Reply-To: <CABoe=cRkXAoG_dEBbkLydujV7Mrp+=JWVRLz3-4dT=DvbQdZpQ@mail.gmail.com>
References: <CABoe=cR9s8MvCM9iHZajUL42E0mJXttUqRdsR_GXr4MRjD6YCw@mail.gmail.com>
<20200503153825.GK28974@telsasoft.com>
<CABoe=cRkXAoG_dEBbkLydujV7Mrp+=JWVRLz3-4dT=DvbQdZpQ@mail.gmail.com>
On Mon, 2020-05-04 at 20:12 +0100, James Thompson wrote:
> The change is abrupt, on the 10th execution (but I hadn't spotted it was always after the
> same number of executions until your suggestion - thanks for pointing me in that direction).
>
> I don't see any custom configuration on our end that changes the threshold for this from 5->10.
> Debugging the query call I also see that PgConnection has the prepareThreshold set to 5.
>
> Additionally, the execution plans for the 10th + following queries look fine, they have the
> same structure as if I run the query manually. It's not that the query plan switches,
> it seems as though the same query plan is just > 200X slower than usual.
>
> As for the heap fetches -> as far as I can tell, on both occasions the fetches are relatively
> low and shouldn't account for minutes of execution (even if one is lower than the other).
> Looking through one days logs I do find cases with lower heap fetches too, for example as
> below which has 1977 fetches instead of the previous 6940 but took approx the same time:
> -> Index Only Scan using table1_typea_include_uniqueid_col16_idx on table1 table1alias1 (cost=0.56..17.25 rows=1 width=60) (actual time=56.858..120893.874 rows=67000 loops=1)
> Index Cond: (col20 = $2005)
> Filter: (((col3 = $2004) OR (col3 IS NULL)) AND ((col8)::text = ANY ((ARRAY[$1004, ..., $2003])::text[])))
> Rows Removed by Filter: 2662793
> Heap Fetches: 1977
> Buffers: shared hit=84574 read=3522
>
> Would you agree the statement threshold / heap fetches seems unlikely to be causing this? Any other thoughts?
It does sound suspiciously like custom plans vs. generic plan.
If you are using JDBC, then the cut-off of 10 would make sense:
the JDBC driver uses (server) prepared statements only after the
fifth execution, and the prepared statement will use a generic plan
only after the fifth execution.
It would be good to see the execution plan from the third, seventh
and thirteenth execution. You could use "auto_explain" for that.
Yours,
Laurenz Albe
--
Cybertec | https://www.cybertec-postgresql.com
Reply instructions:
You may reply publicly to this message via plain-text email
using any one of the following methods:
* Reply to all the recipients using the --to and --cc options:
reply via email
To: pgsql-performance@postgresql.org
Cc: laurenz.albe@cybertec.at, james@jthompson.dev, pryzby@telsasoft.com
Subject: Re: Please help! Query jumps from 1s -> 4m
In-Reply-To: <1949097f3ae6189d111d4e0dba63505db958ffef.camel@cybertec.at>
* Save the following mbox file, import it into your mail client,
and reply-to-all from there: mbox
This inbox is served by DDX for PostgreSQL; see mirroring instructions
for how to clone and mirror all data and code used for this inbox