4

We recently upgraded an Amazon RDS instance from PostgreSQL 9.3 to 9.4. There were no problems during the upgrade, and afterwards we ran VACUUM ANALYZE. Performance is now very slow across the board. Here's an example of a query that took a fraction of a second in 9.3:

EXPLAIN ANALYZE SELECT room_name, id FROM common_activityinstance WHERE started_by_id = 1370408 AND room_name IN ('robcv28', 'foobartest', 'noroster', 'jscode', 'cv28', 'johansencouple', 'lv426', 'johansenfamily', 'johansen') AND end_time IS NULL;
                                                                              QUERY PLAN                                                                              
----------------------------------------------------------------------------------------------------------------------------------------------------------------------
 Bitmap Heap Scan on common_activityinstance  (cost=55.63..59.65 rows=1 width=13) (actual time=1.082..1.082 rows=0 loops=1)
   Recheck Cond: ((started_by_id = 1370408) AND (room_name = ANY ('{robcv28,foobartest,noroster,jscode,cv28,johansencouple,lv426,johansenfamily,johansen}'::text[])))
   Filter: (end_time IS NULL)
   Rows Removed by Filter: 925
   ->  BitmapAnd  (cost=55.63..55.63 rows=1 width=0) (actual time=0.349..0.349 rows=0 loops=1)
         ->  Bitmap Index Scan on common_activityinstance_started_by_id  (cost=0.00..5.53 rows=146 width=0) (actual time=0.122..0.122 rows=927 loops=1)
               Index Cond: (started_by_id = 1370408)
         ->  Bitmap Index Scan on common_activityinstance_room_name_c1f9997a_like  (cost=0.00..49.85 rows=1171 width=0) (actual time=0.171..0.171 rows=926 loops=1)
               Index Cond: (room_name = ANY ('{robcv28,foobartest,noroster,jscode,cv28,johansencouple,lv426,johansenfamily,johansen}'::text[]))
 Total runtime: 1.116 ms
(10 rows)

This same query is now much slower in 9.4:

EXPLAIN ANALYZE SELECT room_name, id FROM common_activityinstance WHERE started_by_id = 1370408 AND room_name IN ('robcv28', 'foobartest', 'noroster', 'jscode', 'cv28', 'johansencouple', 'lv426', 'johansenfamily', 'johansen') AND end_time IS NULL;
                                                                          QUERY PLAN                                                                          
--------------------------------------------------------------------------------------------------------------------------------------------------------------
 Bitmap Heap Scan on common_activityinstance  (cost=10157.60..14038.97 rows=45 width=36) (actual time=3923.011..3923.011 rows=0 loops=1)
   Recheck Cond: ((started_by_id = 1370408) AND (end_time IS NULL))
   Rows Removed by Index Recheck: 698
   Filter: (room_name = ANY ('{robcv28,foobartest,noroster,jscode,cv28,johansencouple,lv426,johansenfamily,johansen}'::text[]))
   Heap Blocks: exact=634
   ->  BitmapAnd  (cost=10157.60..10157.60 rows=991 width=0) (actual time=3917.278..3917.278 rows=0 loops=1)
         ->  Bitmap Index Scan on common_activityinstance_started_by_id  (cost=0.00..3282.60 rows=198155 width=0) (actual time=0.245..0.245 rows=927 loops=1)
               Index Cond: (started_by_id = 1370408)
         ->  Bitmap Index Scan on end_time_id  (cost=0.00..6874.73 rows=198155 width=0) (actual time=3915.565..3915.565 rows=1674860 loops=1)
               Index Cond: (end_time IS NULL)
 Planning time: 2.457 ms
 Execution time: 3923.065 ms
(12 rows)

I don't understand why the query plans are different. And this is just one example—another query was running for 15 minutes before I just gave up and stopped it.

I thought maybe there was a problem with the indexes, so I also did REINDEX DATABASE but it didn't help.

Any ideas?

  • Perhaps queries are slow because of the restart? Did you see similar behaviour in the past, after restarts? – ypercubeᵀᴹ Nov 20 '17 at 16:56
  • We haven't had to restart very often, but we've never seen anything like this before. – Rob Johansen Nov 20 '17 at 17:00
  • Is common_activityinstance_room_name_c1f9997a_like available on your new server ? It's being used by the first query but not the second. – KookieMonster Nov 21 '17 at 11:28
  • It's listed as one of the indexes when I do \d common_activityinstance so I assume it's available. I'm not sure how to make the query planner choose the same plans as before, so I guess that needs to be my focus (but I thought that's what VACUUM ANALYZE would accomplish). – Rob Johansen Nov 21 '17 at 14:37
2

Since the entire database seemed to be affected, I decided to try a VACUUM (FULL, ANALYZE). It took 50 hours and 4 minutes to complete, but it was totally worth it. Our database disk usage went from 1259 GB down to 747 GB (reclaiming a whopping 512 GB of space), and performance across the board has returned back to the levels we were seeing before the upgrade.

0

You've got two totally different bitmap scans that are happening there.. Fast..

   ->  BitmapAnd  (cost=55.63..55.63 rows=1 width=0) (actual time=0.349..0.349 rows=0 loops=1)
         ->  Bitmap Index Scan on common_activityinstance_started_by_id  (cost=0.00..5.53 rows=146 width=0) (actual time=0.122..0.122 rows=927 loops=1)
               Index Cond: (started_by_id = 1370408)
         ->  Bitmap Index Scan on common_activityinstance_room_name_c1f9997a_like  (cost=0.00..49.85 rows=1171 width=0) (actual time=0.171..0.171 rows=926 loops=1)
               Index Cond: (room_name = ANY ('{robcv28,foobartest,noroster,jscode,cv28,johansencouple,lv426,johansenfamily,johansen}'::text[]))
 Total runtime: 1.116 ms

Slow..

   ->  BitmapAnd  (cost=10157.60..10157.60 rows=991 width=0) (actual time=3917.278..3917.278 rows=0 loops=1)
         ->  Bitmap Index Scan on common_activityinstance_started_by_id  (cost=0.00..3282.60 rows=198155 width=0) (actual time=0.245..0.245 rows=927 loops=1)
               Index Cond: (started_by_id = 1370408)
         ->  Bitmap Index Scan on end_time_id  (cost=0.00..6874.73 rows=198155 width=0) (actual time=3915.565..3915.565 rows=1674860 loops=1)
               Index Cond: (end_time IS NULL)

So what's happening the IS NULL condition is expecting 200k rows, and it's getting 1.5 million, so it's using an scan on end_time_id rather than common_activityinstance_room_name_c1f9997a_like

Let's look at the query,

EXPLAIN ANALYZE SELECT room_name, id
FROM common_activityinstance
WHERE started_by_id = 1370408
  AND room_name IN ('robcv28', 'foobartest', 'noroster', 'jscode', 'cv28', 'johansencouple', 'lv426', 'johansenfamily', 'johansen')
  AND end_time IS NULL;

We don't know what the use case here is, but how often do you search where end_time IS NOT NULL on room_name. I would nuke the index end_time_in, and common_activityinstance_started_by_id and instead make that a partial index (assuming you don't actually care about the rows that have end_time set and they're archival.

CREATE INDEX ON common_activityinstance (started_by_id, room_name)
  WHERE end_time IS NULL;
ANALYZE common_activityinstance;
  • Thank you for taking the time to reply; I really appreciate it. I will certainly try your suggestion, but is it normal after an upgrade to have to drop/change indexes like this? What I provided was just one example of a query that only became slow after the upgrade. We have many more queries—possibly all of them—that are performing painfully slower. If we have to analyze and correct all of them one by one, I guess we have no choice but is that really necessary? If so, upgrading major versions seems totally broken in PostgreSQL. Why would anyone ever do it if this is required? – Rob Johansen Nov 22 '17 at 16:06
  • @AlienBishop I have no idea what you're seeing beyond what you've given me. It's normal to have to do some kind of work when you upgrade from one major version to another. It happens. I would have jumped from 9.3 to 10.0. Then I would have seen if the performance is acceptable. If not, I would have looked at changing or modernizing the SQL. If that failed, I would have looked into whatever regressions could be made inside the database itself. – Evan Carroll Nov 22 '17 at 17:59

Your Answer

By clicking “Post Your Answer”, you agree to our terms of service, privacy policy and cookie policy

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