Rallentamento delle prestazioni dopo l'aggiornamento di PostreSQL da 9.1 a 9.4

Question

Sto ottenendo prestazioni estremamente lente dopo l'aggiornamento di Postgres da 9.1 a 9.4. Ecco un esempio di due query che funzionano molto più lentamente.

Nota: mi rendo conto che queste query potrebbero essere riscritte per funzionare in modo più efficiente, tuttavia la cosa principale che mi preoccupa è che dopo l'aggiornamento a una versione più recente di Postgres, stanno improvvisamente eseguendo 100 volte più lentamente! Spero che ci sia una variabile di configurazione in qualche posto che ho trascurato.

Durante l'aggiornamento ho utilizzato il comando pg_upgrade con l'opzione --link. Il file di configurazione è lo stesso tra 9.4 e 9.1. Non funziona con lo stesso identico hardware, ma entrambi funzionano su un Linode e ho provato a utilizzare 3 diversi Linodes per il nuovo server, quindi non penso che questo sia un problema hardware.

Sembra che in entrambi i casi 9.4 utilizzi indici diversi da 9.1?

9,1:

EXPLAIN ANALYZE SELECT "id", "title", "timestamp", "parent", "deleted", "sunk", "closed", "sticky", "lastupdate", "views", "oldid", "editedon", "devpost", "hideblue", "totalvotes", "statustag", "forum_category_id", "account_id" FROM "forum_posts" WHERE "parent" = 882269 ORDER BY "timestamp" DESC LIMIT 1; 
                     QUERY PLAN                  
    ----------------------------------------------------------------------------------------------------------------------------------------------------- 
    Limit (cost=63.87..63.87 rows=1 width=78) (actual time=0.020..0.020 rows=0 loops=1) 
     -> Sort (cost=63.87..63.98 rows=45 width=78) (actual time=0.018..0.018 rows=0 loops=1) 
      Sort Key: "timestamp" 
      Sort Method: quicksort Memory: 17kB 
      -> Index Scan using index_forum_posts_parent on forum_posts (cost=0.00..63.65 rows=45 width=78) (actual time=0.013..0.013 rows=0 loops=1) 
        Index Cond: (parent = 882269) 
    Total runtime: 0.074 ms 
    (7 rows) 

9,4:

EXPLAIN ANALYZE SELECT "id", "title", "timestamp", "parent", "deleted", "sunk", "closed", "sticky", "lastupdate", "views", "oldid", "editedon", "devpost", "hideblue", "totalvotes", "statustag", "forum_category_id", "account_id" FROM "forum_posts" WHERE "parent" = 882269 ORDER BY "timestamp" DESC LIMIT 1; 
                       QUERY PLAN                    
----------------------------------------------------------------------------------------------------------------------------------------------------------------------- 
Limit (cost=0.42..63.48 rows=1 width=1078) (actual time=920.484..920.484 rows=0 loops=1) 
    -> Index Scan Backward using forum_posts_timestamp_index on forum_posts (cost=0.42..182622.07 rows=2896 width=1078) (actual time=920.480..920.480 rows=0 loops=1) 
     Filter: (parent = 882269) 
     Rows Removed by Filter: 1576382 
Planning time: 0.166 ms 
Execution time: 920.521 ms 
(6 rows) 

9,1:

EXPLAIN ANALYZE SELECT "user_library_images"."id", "user_library_images"."imgsrc", "user_library_images"."library_image_id", "user_library_images"."type", "user_library_images"."is_user_uploaded", "user_library_images"."credit", "user_library_images"."orig_dimensions", "user_library_images"."account_id" FROM "user_library_images" INNER JOIN "image_tags" ON "user_library_images"."id" = "image_tags"."user_library_image_id" WHERE ("user_library_images"."account_id" = 769718 AND "image_tags"."tag" ILIKE '%stone%') GROUP BY "user_library_images"."id", "user_library_images"."imgsrc", "user_library_images"."library_image_id", "user_library_images"."type", "user_library_images"."is_user_uploaded", "user_library_images"."credit", "user_library_images"."orig_dimensions", "user_library_images"."account_id" ORDER BY "user_library_images"."id"; 

Group (cost=2015.46..2015.49 rows=1 width=247) (actual time=0.629..0.652 rows=6 loops=1) 
    -> Sort (cost=2015.46..2015.47 rows=1 width=247) (actual time=0.626..0.632 rows=6 loops=1) 
     Sort Key: user_library_images.id, user_library_images.imgsrc, user_library_images.library_image_id, user_library_images.type, user_library_images.is_user_uploaded, user_library_images.credit, user_library_images.orig_dimensions, user_library_images.account_id 
     Sort Method: quicksort Memory: 19kB 
     -> Nested Loop (cost=0.00..2015.45 rows=1 width=247) (actual time=0.283..0.603 rows=6 loops=1) 
       -> Index Scan using index_user_library_images_account on user_library_images (cost=0.00..445.57 rows=285 width=247) (actual time=0.076..0.273 rows=13 loops=1) 
        Index Cond: (account_id = 769718) 
       -> Index Scan using index_image_tags_user_library_image on image_tags (cost=0.00..5.50 rows=1 width=4) (actual time=0.020..0.021 rows=0 loops=13) 
        Index Cond: (user_library_image_id = user_library_images.id) 
        Filter: (tag ~~* '%stone%'::text) 
Total runtime: 0.697 ms 
(11 rows) 

9,4:

Group (cost=166708.13..166709.46 rows=59 width=1241) (actual time=9677.052..9677.052 rows=0 loops=1) 
    Group Key: user_library_images.id, user_library_images.imgsrc, user_library_images.library_image_id, user_library_images.type, user_library_images.is_user_uploaded, user_library_images.credit, user_library_images.orig_dimensions, user_library_images.account_id 
    -> Sort (cost=166708.13..166708.28 rows=59 width=1241) (actual time=9677.049..9677.049 rows=0 loops=1) 
     Sort Key: user_library_images.id, user_library_images.imgsrc, user_library_images.library_image_id, user_library_images.type, user_library_images.is_user_uploaded, user_library_images.credit, user_library_images.orig_dimensions, user_library_images.account_id 
     Sort Method: quicksort Memory: 17kB 
     -> Hash Join (cost=10113.22..166706.39 rows=59 width=1241) (actual time=9677.035..9677.035 rows=0 loops=1) 
       Hash Cond: (image_tags.user_library_image_id = user_library_images.id) 
       -> Seq Scan on image_tags (cost=0.00..156488.85 rows=11855 width=4) (actual time=0.301..9592.048 rows=63868 loops=1) 
        Filter: (tag ~~* '%stone%'::text) 
        Rows Removed by Filter: 9370406 
       -> Hash (cost=10045.97..10045.97 rows=5380 width=1241) (actual time=0.047..0.047 rows=4 loops=1) 
        Buckets: 1024 Batches: 1 Memory Usage: 1kB 
        -> Bitmap Heap Scan on user_library_images (cost=288.12..10045.97 rows=5380 width=1241) (actual time=0.027..0.037 rows=4 loops=1) 
          Recheck Cond: (account_id = 769718) 
          Heap Blocks: exact=4 
          -> Bitmap Index Scan on index_user_library_images_account (cost=0.00..286.78 rows=5380 width=0) (actual time=0.019..0.019 rows=4 loops=1) 
           Index Cond: (account_id = 769718) 
Planning time: 0.223 ms 
Execution time: 9677.109 ms 
(19 rows) 

====

Dopo aver eseguito lo script di analisi (vedere la risposta sotto), il problema è stato risolto. Per avere un riferimento, ecco la nuova uscita ANALYZE (per 9,4):

Group (cost=2062.82..2062.91 rows=4 width=248) (actual time=8.775..8.801 rows=7 loops=1) 
    Group Key: user_library_images.id, user_library_images.imgsrc, user_library_images.library_image_id, user_library_images.type, user_library_images.is_user_uploaded, user_library_images.credit, user_library_images.orig_dimensions, user_library_images.account_id 
    -> Sort (cost=2062.82..2062.83 rows=4 width=248) (actual time=8.771..8.780 rows=7 loops=1) 
     Sort Key: user_library_images.id, user_library_images.imgsrc, user_library_images.library_image_id, user_library_images.type, user_library_images.is_user_uploaded, user_library_images.credit, user_library_images.orig_dimensions, user_library_images.account_id 
     Sort Method: quicksort Memory: 19kB 
     -> Nested Loop (cost=0.87..2062.78 rows=4 width=248) (actual time=4.156..8.685 rows=7 loops=1) 
       -> Index Scan using index_user_library_images_account on user_library_images (cost=0.43..469.62 rows=304 width=248) (actual time=0.319..2.528 rows=363 loops=1) 
        Index Cond: (account_id = 769718) 
       -> Index Scan using index_image_tags_user_library_image on image_tags (cost=0.43..5.23 rows=1 width=4) (actual time=0.014..0.014 rows=0 loops=363) 
        Index Cond: (user_library_image_id = user_library_images.id) 
        Filter: (tag ~~* '%stone%'::text) 
        Rows Removed by Filter: 2 
Planning time: 2.956 ms 
Execution time: 8.907 ms 
(14 rows) 



Limit (cost=65.81..65.81 rows=1 width=77) (actual time=0.256..0.256 rows=0 loops=1) 
    -> Sort (cost=65.81..65.92 rows=47 width=77) (actual time=0.252..0.252 rows=0 loops=1) 
     Sort Key: "timestamp" 
     Sort Method: quicksort Memory: 17kB 
     -> Index Scan using index_forum_posts_parent on forum_posts (cost=0.43..65.57 rows=47 width=77) (actual time=0.211..0.211 rows=0 loops=1) 
       Index Cond: (parent = 882269) 
Planning time: 2.978 ms 
Execution time: 0.380 ms 
(8 rows) 

Answer 1

pg_upgrade non copia (o migrare) le statistiche per il database.

Quindi è necessario analizzare le tabelle per aggiornare le statistiche nel database migrato. pg_upgrade creerà uno script batch file/shell con il nome analyze_new_cluster che può essere utilizzato per quello.

In alternativa è possibile utilizzare manualmente vacuum analyze per ottenere la stessa cosa.

Le statistiche mancanti possono essere rilevate osservando il piano di esecuzione. La differenza tra il numero previsto di righe ed i numeri reali sono troppo elevati:

(cost=0.00..286.78 rows=5380 width=0) (actual time=0.019..0.019 rows=4 loops=1) 

==> 5380 vs 4 righe

o

(cost=0.00..156488.85 rows=11855 width=4) (actual time=0.301..9592.048 rows=63868 loops=1) 

==> 11855 63868 vs. righe