0

I migrate my data to a new server hardware that after my benchmark looks faster in terms of CPU and disk i/o.

Unfortunatly my query seems slower on that new hardware with the same data and the same query.

Here is my query :

EXPLAIN ANALYZE SELECT AVG(CAST(completeness->>'fr' AS INTEGER)) as average FROM product INNER JOIN channel ON channel.id = product.channel_id WHERE channel_id = 'myUuid';

On old server my times are :
Planning Time: 0.281 ms
Execution Time: 50.683 ms

On the new server my times are:
Planning Time: 0.162 ms
Execution Time: 115.268 ms

That is significally slower, I already tried making a VACUUM FULL and REINDEX mydatabase
And also increasing the default_statistics_target but any of this changed anything.

Of course I'm using the same postgresql version (12.14) and everything I could found in similar questions, do you have any other solutions ?

EDIT : For some more details :

Old and faster :

Aggregate  (cost=58441.85..58441.86 rows=1 width=32) (actual time=66.284..66.285 rows=1 loops=1)
   Buffers: shared hit=1132 read=18379 written=16
   I/O Timings: read=36.167 write=0.101
   ->  Nested Loop  (cost=594.96..58185.68 rows=25617 width=25) (actual time=5.003..61.783 rows=25985 loops=1)
         Buffers: shared hit=1132 read=18379 written=16
         I/O Timings: read=36.167 write=0.101
         ->  Seq Scan on channel  (cost=0.00..1.30 rows=1 width=16) (actual time=0.028..0.031 rows=1 loops=1)
               Filter: (id = 'myuuid'::uuid)
               Rows Removed by Filter: 23
               Buffers: shared hit=1
         ->  Bitmap Heap Scan on product  (cost=594.96..57928.21 rows=25617 width=41) (actual time=4.969..59.276 rows=25985 loops=1)
               Recheck Cond: (channel_id = 'myuuid'::uuid)
               Heap Blocks: exact=19408
               Buffers: shared hit=1131 read=18379 written=16
               I/O Timings: read=36.167 write=0.101
               ->  Bitmap Index Scan on idx_8ac439d272f5a1aa  (cost=0.00..588.55 rows=25617 width=0) (actual time=3.177..3.177 rows=25985 loops=1)
                     Index Cond: (channel_id = 'myuuid'::uuid)
                     Buffers: shared read=102
                     I/O Timings: read=0.389
 Planning Time: 1.945 ms
 Execution Time: 66.585 ms
(21 rows)

New and slower :

Aggregate  (cost=59666.14..59666.15 rows=1 width=32) (actual time=146.506..146.508 rows=1 loops=1)
   Buffers: shared hit=108 read=19371 written=172
   I/O Timings: read=85.949 write=1.528
   ->  Nested Loop  (cost=617.08..59402.07 rows=26407 width=25) (actual time=7.752..139.180 rows=25985 loops=1)
         Buffers: shared hit=108 read=19371 written=172
         I/O Timings: read=85.949 write=1.528
         ->  Seq Scan on channel  (cost=0.00..1.30 rows=1 width=16) (actual time=0.012..0.016 rows=1 loops=1)
               Filter: (id = 'myuuid'::uuid)
               Rows Removed by Filter: 23
               Buffers: shared hit=1
         ->  Bitmap Heap Scan on product  (cost=617.08..59136.70 rows=26407 width=41) (actual time=7.737..134.826 rows=25985 loops=1)
               Recheck Cond: (channel_id = 'myuuid'::uuid)
               Heap Blocks: exact=19374
               Buffers: shared hit=107 read=19371 written=172
               I/O Timings: read=85.949 write=1.528
               ->  Bitmap Index Scan on idx_8ac439d272f5a1aa  (cost=0.00..610.48 rows=26407 width=0) (actual time=5.073..5.073 rows=25987 loops=1)
                     Index Cond: (channel_id = 'myuuid'::uuid)
                     Buffers: shared read=102
                     I/O Timings: read=0.688
 Planning Time: 0.773 ms
 Execution Time: 146.750 ms
(21 rows)
3
  • I've did that and put it above, but I'm not able to tell what is causing such a difference
    – TomLorenzi
    Jul 12, 2023 at 15:37
  • "new server hardware" -- is it actual hardware, or a different VM?
    – mustaccio
    Jul 12, 2023 at 19:52
  • From bare metal to a new VM with normally more ressources and better hardware
    – TomLorenzi
    Jul 13, 2023 at 7:37

1 Answer 1

0

172 written buffers for this type of command seems like a lot. While the time spent writing isn't very high, the fact that it needed to do this amount of writing in the first place suggests the server has a lot of activity going on at the same time as you were profiling the query (and that amount of activity seems to be unequal to the other server) and that it might be competing for resources with that other activities, slowing it down. To isolate the difference in these plans, you should make the servers as quiet as possible before running them. Prevent other user sessions from running, and do a manual vacuum which, once done, should prevent autovac from kicking in at an awkward time. And then do a checkpoint right before the test.

The difference in IO read time is significant. While it does not explain 100% of the difference in time, it does explain the majority of the difference. It could be that competing activity is consuming some of the IO capacity, or it could be the new server is less capable. (You said you benchmarked it, but didn't give any details. Maybe you did it in a way that is not realistic for the current workload).

The difference in buffer "shared hits" is substantial. While that alone is unlikely to explain the difference is timing, it is another difference between the servers that needs to be removed or explained.

1
  • Even with lower use of the resources it still seems slow : Buffers: shared hit=898 read=18582 written=5 with an execution time of 111.733ms I'll try doing some more test on CPU capabilities to see if it might be some server capabilities
    – TomLorenzi
    Jul 13, 2023 at 7:41

Your Answer

By clicking “Post Your Answer”, you agree to our terms of service and acknowledge you have read our privacy policy.

Not the answer you're looking for? Browse other questions tagged or ask your own question.