Slow performance after upgrading PostreSQL from 9.1 to 9.4

Question

I'm getting extremely slow performance after upgrading Postgres 9.1 to 9.4. Here's an example of a two queries which are running significantly more slowly.

Note: I realize that these queries might be able to be rewritten to work more efficiently, however the main thing I'm concerned about is that after upgrading to a newer version of Postgres, they are suddenly running 100x more slowly! I'm hoping there's a configuration variable someplace I've overlooked.

While doing the upgrade I used the pg_upgrade command with the --link option. The configuration file is the same between 9.4 and 9.1. It's not running on the exact same hardware, but they're both running on a Linode and I've tried using 3 different Linodes now for the new server, so I don't think this is a hardware issue.

It seems like in both cases, 9.4 is using different indexes than 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)

====

After running the analyze script (see the answer below), the problem was solved. For reference, here's the new ANALYZE output (for 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 does not copy (or migrate) statistics for your database.

So you need to analyze your tables in order to update the statistics in the migrated database. pg_upgrade will create a batch file/shell script with the name analyze_new_cluster that can be used for that.

Alternatively you can use vacuum analyze manually to achieve the same thing.

The missing statistics can be detected by looking at the execution plan. The difference between the expected number of rows and the actual numbers are too high:

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

==> 5380 vs. 4 rows

or

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

==> 11855 vs. 63868 rows