Received: from malur.postgresql.org ([217.196.149.56])
	by arkaria.postgresql.org with esmtps (TLS1.2:ECDHE_RSA_AES_256_CBC_SHA1:256)
	(Exim 4.92)
	(envelope-from <pgsql-performance-owner+archive@lists.postgresql.org>)
	id 1j711n-0006ou-Jq
	for pgsql-performance@arkaria.postgresql.org; Wed, 26 Feb 2020 18:03:23 +0000
Received: from localhost ([127.0.0.1] helo=malur.postgresql.org)
	by malur.postgresql.org with esmtp (Exim 4.89)
	(envelope-from <pgsql-performance-owner+archive@lists.postgresql.org>)
	id 1j710n-0004qQ-0f
	for pgsql-performance@arkaria.postgresql.org; Wed, 26 Feb 2020 18:02:21 +0000
Received: from makus.postgresql.org ([2001:4800:3e1:1::229])
	by malur.postgresql.org with esmtps (TLS1.2:ECDHE_RSA_AES_256_CBC_SHA1:256)
	(Exim 4.89)
	(envelope-from <gc@mnc.ch>)
	id 1j710m-0004qJ-Jw
	for pgsql-performance@lists.postgresql.org; Wed, 26 Feb 2020 18:02:20 +0000
Received: from mail.mnc.ch ([62.2.77.205])
	by makus.postgresql.org with esmtps (TLS1.2:ECDHE_RSA_AES_256_GCM_SHA384:256)
	(Exim 4.92)
	(envelope-from <gc@mnc.ch>)
	id 1j710e-0008Rm-BK
	for pgsql-performance@postgresql.org; Wed, 26 Feb 2020 18:02:18 +0000
X-Virus-Scanned: amavisd-new at mnc.ch
Sender: gc@mnc.ch
Received: by gc-P7xxDM3-G.localdomain (Postfix, from userid 1000)
	id 4307580960; Wed, 26 Feb 2020 19:02:05 +0100 (CET)
From: Guillaume Cottenceau <gc@mnc.ch>
To: Justin Pryzby <pryzby@telsasoft.com>
Cc: pgsql-performance@postgresql.org
Subject: Re: much slower query in production
References: <878skpnx0u.fsf@mnc.ch> <20200226162809.GZ31889@telsasoft.com>
Date: Wed, 26 Feb 2020 19:02:05 +0100
In-Reply-To: <20200226162809.GZ31889@telsasoft.com> (Justin Pryzby's message
	of "Wed, 26 Feb 2020 10:28:09 -0600")
Message-ID: <87tv3dmdlu.fsf@mnc.ch>
MIME-Version: 1.0
Content-Type: text/plain
List-Id: <pgsql-performance.lists.postgresql.org>
List-Help: <https://lists.postgresql.org/manage/>
List-Subscribe: <https://lists.postgresql.org/manage/>
List-Post: <mailto:pgsql-performance@lists.postgresql.org>
List-Owner: <mailto:pgsql-performance-owner@lists.postgresql.org>
List-Archive: <https://www.postgresql.org/list/pgsql-performance>
Precedence: bulk

Justin Pryzby <pryzby 'at' telsasoft.com> writes:

> On Wed, Feb 26, 2020 at 05:17:21PM +0100, Guillaume Cottenceau wrote:
>> On production:
>> 
>> # EXPLAIN ANALYZE SELECT transaction_uid, (SELECT COUNT(*) FROM tickets WHERE multicard_uid = multicards.uid) from multicards;
>>                                                                                    QUERY PLAN                                                                                    
>> ---------------------------------------------------------------------------------------------------------------------------------------------------------------------------------
>>  Seq Scan on multicards  (cost=0.00..1455177.30 rows=204548 width=12) (actual time=0.178..1694987.355 rows=204548 loops=1)
>>    SubPlan 1
>>      ->  Aggregate  (cost=7.07..7.08 rows=1 width=8) (actual time=8.283..8.283 rows=1 loops=204548)
>>            ->  Index Only Scan using tickets_multicard_uid on tickets  (cost=0.43..7.05 rows=9 width=0) (actual time=1.350..8.280 rows=6 loops=204548)
>>                  Index Cond: (multicard_uid = multicards.uid)
>>                  Heap Fetches: 1174940
>>  Planning Time: 1.220 ms
>>  Execution Time: 1695029.673 ms
>
>> The execution time ratio is a huge 3700. I guess the Heap Fetches
>> difference is the most meaningful here;
>
> Yes, it's doing an "index only" scan, but not very effectively.
> Vacuum the tickets table to set relallvisible and see if that helps.
>
> If so, try to keep it better vacuumed with something like
> ALTER TABLE tickets SET (AUTOVACUUM_VACUUM_SCALE_FACTOR=0.005);

Thanks for your reply! The effect is huge:

# vacuum analyze tickets;
VACUUM
Time: 182850.756 ms (03:02.851)

# EXPLAIN ANALYZE SELECT transaction_uid, (SELECT COUNT(*) FROM tickets WHERE multicard_uid = multicards.uid) from multicards;
                                                                                   QUERY PLAN                                                                                    
---------------------------------------------------------------------------------------------------------------------------------------------------------------------------------
 Seq Scan on multicards  (cost=0.00..947739.65 rows=204548 width=12) (actual time=15.579..5210.869 rows=204548 loops=1)
   SubPlan 1
     ->  Aggregate  (cost=4.59..4.60 rows=1 width=8) (actual time=0.025..0.025 rows=1 loops=204548)
           ->  Index Only Scan using tickets_multicard_uid on tickets  (cost=0.43..4.57 rows=8 width=0) (actual time=0.022..0.024 rows=6 loops=204548)
                 Index Cond: (multicard_uid = multicards.uid)
                 Heap Fetches: 8
 Planning Time: 71.469 ms
 Execution Time: 5223.408 ms
(8 rows)

Time: 5332.361 ms (00:05.332)

(and subsequent executions are below 1 second)

It is actually consistent with using a restored backup on the dev
computer, as my understanding is this comes out without any
garbage and like a perfectly vacuumed database. Btw do you have
any hint as to how to perform timings using production data which
are consistent with production? Backup/restore is maybe not the
way to go, but rather a block device level copy?

Since postgresql 8, I have to say I rely entirely on autovacuum,
and did not notice it could really run too infrequently for the
work and create such difference. I see in documentation a default
autovacuum_vacuum_scale_factor = 0.2, is that something that is
typically lowered globally, e.g. maybe on a fairly active system?
I am worried that changing that configuration for that table to
0.005 would fix this query and similar ones, but later I might
face the same situation on other tables. Or how would you elect
tables for a lowered value configuration?

Thanks!

-- 
Guillaume Cottenceau