Date: Sun, 3 May 2020 10:38:26 -0500
From: Justin Pryzby <pryzby@telsasoft.com>
To: James Thompson <james@jthompson.dev>
Cc: pgsql-performance@postgresql.org
Subject: Re: Please help! Query jumps from 1s -> 4m
Message-ID: <20200503153825.GK28974@telsasoft.com>
References: 
 <CABoe=cR9s8MvCM9iHZajUL42E0mJXttUqRdsR_GXr4MRjD6YCw@mail.gmail.com>
MIME-Version: 1.0
Content-Type: text/plain; charset=us-ascii
Content-Disposition: inline
In-Reply-To: 
 <CABoe=cR9s8MvCM9iHZajUL42E0mJXttUqRdsR_GXr4MRjD6YCw@mail.gmail.com>
User-Agent: Mutt/1.9.4 (2018-02-28)
Precedence: bulk

On Sun, May 03, 2020 at 09:58:27AM +0100, James Thompson wrote:
> Hi,
> 
> Hoping someone can help with this performance issue that's been driving a
> few of us crazy :-) Any guidance greatly appreciated.
> 
> A description of what you are trying to achieve and what results you
> expect.:
>  - I'd like to get an understanding of why the following query (presented
> in full, but there are specific parts that are confusing me) starts off
> taking ~second in duration but 'switches' to taking over 4 minutes.

Does it "switch" abruptly or do you get progressively slower queries ?
If it's abrupt following the 5th execution, I guess you're hitting this:

https://www.postgresql.org/message-id/Pine.BSO.4.64.0802131404090.6785@leary.csoft.net
https://www.postgresql.org/message-id/A737B7A37273E048B164557ADEF4A58B50FB8D5E@ntex2010i.host.magwien.gv.at

>  - we initially saw this behaviour for the exact same sql with a different
> index that resulted in an index scan. To try and fix the issue we've
> created an additional index with additional included fields so we now have
> Index Only Scans, but are still seeing the same problem.

>  Segments of interest:
>  1. ->  Index Only Scan using table1_typea_include_uniqueid_col16_idx on
> table1 table1alias1  (cost=0.56..17.25 rows=1 width=60) (actual
> time=110.539..123828.134 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: 2662652
>         Heap Fetches: 6940
>         Buffers: shared hit=46619 read=42784 written=52

> If I run the same queries now:
> Index Only Scan using table1_typea_include_uniqueid_col16_idx on table1
> table1alias1  (cost=0.56..2549.69 rows=69 width=36)
> (actual time=1.017..1221.375 rows=67000 loops=1)
> Heap Fetches: 24
> Buffers: shared hit=2849 read=2483

It looks to me like you're getting good performance following a vacuum, when
Heap Fetches is low.  So you'd want to run vacuum more often, like:
| ALTER TABLE table1 SET (autovacuum_vacuum_scale_factor=0.005).

But maybe I've missed something - you showed the bad query plan, but not the
good one, and I wonder if they may be subtly different, and that's maybe masked
by the replaced identifiers.

-- 
Justin