much slower query in production

Previous Topic Next Topic
 
classic Classic list List threaded Threaded
11 messages Options
Reply | Threaded
Open this post in threaded view
|

much slower query in production

Guillaume Cottenceau-2
Dear all,

I am facing a much, much slower query in production than on my
development computer using a restored production backup, and I
don't understand why nor I see what I could do to speedup the
query on production :/

Short data model explanation: one table stores tickets, one table
stores multicards; tickets can belong to a multicard through a
many-to-one relationship, or be independant from multicards. The
query I am interested in, will be used to update a new column in
the multicards table, containing the count of related tickets.

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

iostat in the middle of this execution:

procs -----------memory---------- ---swap-- -----io---- -system-- ----cpu----
 r  b   swpd   free   buff  cache   si   so    bi    bo   in   cs us sy id wa
 0  1 479548 143652  79412 5609292    0    0  1986   116  999 1115  2  2 71 25
 3  1 479548 134312  79412 5614564    0    0  2386   128 2832 3973 20  2 49 28
 0  1 479548 142520  79428 5617708    0    0  1584   232 3440 3716 11  3 58 29
 0  1 479548 161184  79024 5597756    0    0  1922   144 1249 1562  1  2 70 27
 0  1 479548 161244  79048 5600804    0    0  1556   117 2138 3035  6  2 68 25
 0  2 479548 158384  79048 5604008    0    0  1388   402 2970 4320  6  2 66 27

On my development computer:

# 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..538974.69 rows=204548 width=12) (actual time=0.055..451.691 rows=204548 loops=1)
   SubPlan 1
     ->  Aggregate  (cost=2.57..2.58 rows=1 width=8) (actual time=0.002..0.002 rows=1 loops=204548)
           ->  Index Only Scan using tickets_multicard_uid on tickets  (cost=0.43..2.56 rows=7 width=0) (actual time=0.001..0.001 rows=6 loops=204548)
                 Index Cond: (multicard_uid = multicards.uid)
                 Heap Fetches: 0
 Planning Time: 0.296 ms
 Execution Time: 456.677 ms

The execution time ratio is a huge 3700. I guess the Heap Fetches
difference is the most meaningful here; my understanding would
be, that the index would easily fit in the shared_buffers after a
few subselects, as configuration is 2GB shared_buffers and here's
the index on disk size:

# SELECT relname as index, reltuples as "rows estimate", pg_size_pretty(pg_table_size(quote_ident(relname))) as "on disk size" FROM pg_class, pg_namespace WHERE pg_namespace.oid = pg_class.relnamespace AND relkind = 'i' AND nspname = 'public' AND relname = 'tickets_multicard_uid';
        index          | rows estimate | on disk size
-----------------------+---------------+--------------
 tickets_multicard_uid |    7.2136e+06 | 161 MB

Though it's not too clear for me what "heap fetches" are. It
seems it might be the actual table data fetches (e.g. not an
index fetch), but I don't really know why so many of them are
needed here, and how to reduce that (if that's the explanation
for the longer timing).

It's true that production has constant activity, but not so much
of it, load avg is typically about 0.5, most queries run very
quickly, pg_stat_activity frequently reports no currently running
query; here's iostat during normal production activity, for
reference:

procs -----------memory---------- ---swap-- -----io---- -system-- ----cpu----
 r  b   swpd   free   buff  cache   si   so    bi    bo   in   cs us sy id wa
 0  0 480712 151112  10144 5664784    1    1   310    69    0    0  9  1 88  3
 0  0 480712 151312  10152 5664876    0    0     0   248 4911 7072  9  3 87  0
 0  0 480720 165488  10072 5642564    0    4    76   210 2019 2685  6  1 92  1
 0  0 480720 165332  10088 5642508    0    0     0   221 3535 17545 25  4 70  1
 0  0 480720 144772  10108 5643324    0    0    84   378 3833 5096 11  2 80  7
 0  0 480720 143300  10116 5644144    0    0    42   298 3446 4784  6  1 92  1
 0  0 480720 143300  10136 5644256    0    0    10  2340 1073 1496  1  1 96  2

Here's also a second susequent run on production for comparison:

# 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.101..834176.389 rows=204548 loops=1)
   SubPlan 1
     ->  Aggregate  (cost=7.07..7.08 rows=1 width=8) (actual time=4.075..4.075 rows=1 loops=204548)
           ->  Index Only Scan using tickets_multicard_uid on tickets  (cost=0.43..7.05 rows=9 width=0) (actual time=0.624..4.072 rows=6 loops=204548)
                 Index Cond: (multicard_uid = multicards.uid)
                 Heap Fetches: 1174941
 Planning Time: 0.273 ms
 Execution Time: 834209.323 ms

Heap fetches still almost the same, albeit timing divided by two.

Both environments are running postgresql 11.5, with 2GB
shared_buffers. Differences I can think of: production is using
ext4 on drbd on SATA and linux 3.2, dev is using ext4 (no drbd)
on SSD and linux 4.15. I can't believe SSD would explain the
difference alone? If positive, then I know what we should do on
production..

Thanks for any hints/help!

--
Guillaume Cottenceau


Reply | Threaded
Open this post in threaded view
|

Re: much slower query in production

Justin Pryzby
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);

--
Justin


Reply | Threaded
Open this post in threaded view
|

Re: much slower query in production

Michael Lewis
By the way, I expect the time is cut in half while heap fetches stays similar because the index is now in OS cache on the second run and didn't need to be fetched from disk. Definitely need to check on vacuuming as Justin says. If you have a fairly active system, you would need to run this query many times in order to push other stuff out of shared_buffers and get this query to perform more like it does on dev.

Do you have the option to re-write the query or is this generated by an ORM? You are forcing the looping as I read this query. If you aggregate before you join, then the system should be able to do a single scan of the index, aggregate, then join those relatively few rows to the multicards table records.

SELECT transaction_uid, COALESCE( sub.count, 0 ) AS count FROM multicards LEFT JOIN (SELECT multicard_uid, COUNT(*) AS count FROM tickets GROUP BY multicard_uid ) AS sub ON sub.multicard_uid = multicards.uid;
Reply | Threaded
Open this post in threaded view
|

Re: much slower query in production

Guillaume Cottenceau-2
In reply to this post by Justin Pryzby
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


Reply | Threaded
Open this post in threaded view
|

Re: much slower query in production

Guillaume Cottenceau-2
In reply to this post by Michael Lewis
Michael Lewis <mlewis 'at' entrata.com> writes:

> By the way, I expect the time is cut in half while heap fetches stays similar because the index is now in OS cache on the
> second run and didn't need to be fetched from disk. Definitely need to check on vacuuming as Justin says. If you have a fairly
> active system, you would need to run this query many times in order to push other stuff out of shared_buffers and get this
> query to perform more like it does on dev.
>
> Do you have the option to re-write the query or is this generated by an ORM? You are forcing the looping as I read this query.
> If you aggregate before you join, then the system should be able to do a single scan of the index, aggregate, then join those
> relatively few rows to the multicards table records.
>
> SELECT transaction_uid, COALESCE( sub.count, 0 ) AS count FROM multicards LEFT JOIN (SELECT multicard_uid, COUNT(*) AS count
> FROM tickets GROUP BY multicard_uid ) AS sub ON sub.multicard_uid = multicards.uid;

Thanks for this hint! I always hit this fact that I never write
good queries using explicit joins :/

Execution time (before vacuuming the table as adviced by Justin)
down 38x to 44509ms using this query :)

Real query was an UPDATE of the multicards table to set the count
value. I rewrote this using your approach but I think I lack what
coalesce did in your query, this would update only the rows where
count >= 1 obviously:

UPDATE multicards
   SET defacements = count
  FROM ( SELECT multicard_uid, COUNT(*) AS count FROM tickets GROUP BY multicard_uid ) AS sub
 WHERE uid = multicard_uid;

Any hinted solution to do that in one pass? I could do a first
pass setting defacements = 0, but that would produce more garbage :/

Thanks!

--
Guillaume Cottenceau


Reply | Threaded
Open this post in threaded view
|

Re: much slower query in production

Michael Lewis
UPDATE multicards
   SET defacements = COALESCE( count, 0 )
  FROM ( SELECT multicard_uid, COUNT(*) AS count FROM tickets GROUP BY multicard_uid ) AS sub
 WHERE uid = multicard_uid OR multicard_uid is null;

I expect this should work. Not sure of performance of course.
Reply | Threaded
Open this post in threaded view
|

Re: much slower query in production

Michaeldba@sqlexec.com
Vacuum everything that you restored

Sent from my iPhone

On Feb 26, 2020, at 1:19 PM, Michael Lewis <[hidden email]> wrote:


UPDATE multicards
   SET defacements = COALESCE( count, 0 )
  FROM ( SELECT multicard_uid, COUNT(*) AS count FROM tickets GROUP BY multicard_uid ) AS sub
 WHERE uid = multicard_uid OR multicard_uid is null;

I expect this should work. Not sure of performance of course.
Reply | Threaded
Open this post in threaded view
|

Re: much slower query in production

Guillaume Cottenceau-2
In reply to this post by Michael Lewis
Michael Lewis <mlewis 'at' entrata.com> writes:

>  UPDATE multicards
>  SET defacements = COALESCE( count, 0 )
>  FROM ( SELECT multicard_uid, COUNT(*) AS count FROM tickets GROUP BY multicard_uid ) AS sub
>  WHERE uid = multicard_uid OR multicard_uid is null;
>
> I expect this should work. Not sure of performance of course.

This looked great but as it seems you suspected, it's very slow :/
I interrupted it after 5 minutes run on my dev computer.

--
Guillaume Cottenceau


Reply | Threaded
Open this post in threaded view
|

Re: much slower query in production

Jeff Janes
In reply to this post by Guillaume Cottenceau-2
On Wed, Feb 26, 2020 at 11:17 AM Guillaume Cottenceau <[hidden email]> wrote:
Dear all,

I am facing a much, much slower query in production than on my
development computer using a restored production backup, and I
don't understand why nor I see what I could do to speedup the
query on production :/

You've already seen a VACUUM fixed it.

This must have been a logical restore (from pg_dump), not a physical restore (from pg_basebackup for example) correct?

A physical restore should have resulted in a database in the same state of vacuuming as its source was.  A logical restore will not, and since it is an append-only process it will not trigger autovacuum to run, either.

If you do a logical restore, probably the first should you do afterwards is a VACUUM ANALYZE.

Cheers,

Jeff
Reply | Threaded
Open this post in threaded view
|

Re: much slower query in production

Jeff Janes
In reply to this post by Guillaume Cottenceau-2
On Wed, Feb 26, 2020 at 1:02 PM Guillaume Cottenceau <[hidden email]> wrote:

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.

I think I got that backwards in my previous email.  It is the dev that was restored, not the prod?  But unless you went out of your way to vacuum dev, it would not be perfectly vacuumed.  If it were a logical restore, it would be perfectly unvacuumed, and if a physical restore would be in the same state of vacuuming as the database it was cloned from.
 
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?

block device copy seems like overkill, just using pg_basebackup should be good enough.
 

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?

The autovacuum system has never been redesigned with the needs of index-only-scans in mind.  If I have a table for which index-only scans are important, I'd set  autovacuum_vacuum_scale_factor = 0 and set autovacuum_vacuum_threshold to about 5% of the number of blocks in the table.  There is no syntax to say '5% of the number of blocks in the table' so you have to compute it yourself and hardcode the result, which makes it unsuitable for a global setting.  And this still only addresses UPDATE and DELETE operations, not INSERTs.  If you have INSERT only or mostly table for which index-only-scans are important, you might need to set up cron jobs to do vacuuming.

Cheers,

Jeff
Reply | Threaded
Open this post in threaded view
|

Re: much slower query in production

Guillaume Cottenceau-2
Jeff Janes <jeff.janes 'at' gmail.com> writes:

> On Wed, Feb 26, 2020 at 1:02 PM Guillaume Cottenceau <[hidden email]> wrote:
>
>  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.
>
> I think I got that backwards in my previous email. It is the
> dev that was restored, not the prod? But unless you went out of

Yes (prod was also restored not so long ago, when updating to pg
11.5 tho).

> your way to vacuum dev, it would not be perfectly vacuumed. If
> it were a logical restore, it would be perfectly unvacuumed,
> and if a physical restore would be in the same state of
> vacuuming as the database it was cloned from.
>
>  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?
>
> block device copy seems like overkill, just using pg_basebackup should be good enough.
>
>  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?
>
> The autovacuum system has never been redesigned with the needs of index-only-scans in mind. If I have a table for which
> index-only scans are important, I'd set autovacuum_vacuum_scale_factor = 0 and set autovacuum_vacuum_threshold to about 5% of
> the number of blocks in the table. There is no syntax to say '5% of the number of blocks in the table' so you have to compute
> it yourself and hardcode the result, which makes it unsuitable for a global setting. And this still only addresses UPDATE and

It seems also difficult for us as this table grows over time (and
is trimmed only infrequently).

> DELETE operations, not INSERTs. If you have INSERT only or mostly table for which index-only-scans are important, you might
> need to set up cron jobs to do vacuuming.

Thanks!

--
Guillaume Cottenceau