Explain analyze slower than actual query in postgres

Question

I have the following query

select * from activity_feed where user_id in (select following_id from user_follow where follower_id=:user_id)
union 
select * from activity_feed where project_id in (select project_id from user_project_follow where user_id=:user_id)
order by id desc limit 30

Which runs in approximately 14 ms according to postico

But when i do explain analyze on this query , the plannig time is 0.5 ms and the execution time is around 800 ms (which is what i would actually expect). Is this because the query without explain analyze is returning cached results? I still get less than 20 ms results even when. use other values.

Which one is more indictivie of the performance I'll get in production? I also realized that this is a rather inefficient query, I can't seem to figure out an index that would make this more efficient. It's possible that I will have to not use union

Edit: the execution plan

Limit  (cost=1380.94..1380.96 rows=10 width=148) (actual time=771.111..771.405 rows=10 loops=1)
  ->  Sort  (cost=1380.94..1385.64 rows=1881 width=148) (actual time=771.097..771.160 rows=10 loops=1)
        Sort Key: activity_feed."timestamp" DESC
        Sort Method: top-N heapsort  Memory: 27kB
        ->  HashAggregate  (cost=1321.48..1340.29 rows=1881 width=148) (actual time=714.888..743.273 rows=4462 loops=1)
              Group Key: activity_feed.id, activity_feed."timestamp", activity_feed.user_id, activity_feed.verb, activity_feed.object_type, activity_feed.object_id, activity_feed.project_id, activity_feed.privacy_level, activity_feed.local_time, activity_feed.local_date
              ->  Append  (cost=5.12..1274.46 rows=1881 width=148) (actual time=0.998..682.466 rows=4487 loops=1)
                    ->  Hash Join  (cost=5.12..610.43 rows=1350 width=70) (actual time=0.982..326.089 rows=3013 loops=1)
                          Hash Cond: (activity_feed.user_id = user_follow.following_id)
                          ->  Seq Scan on activity_feed  (cost=0.00..541.15 rows=24215 width=70) (actual time=0.016..150.535 rows=24215 loops=1)
                          ->  Hash  (cost=4.78..4.78 rows=28 width=8) (actual time=0.911..0.922 rows=29 loops=1)
                                Buckets: 1024  Batches: 1  Memory Usage: 10kB
                                ->  Index Only Scan using unique_user_follow_pair on user_follow  (cost=0.29..4.78 rows=28 width=8) (actual time=0.022..0.334 rows=29 loops=1)
                                      Index Cond: (follower_id = '17420532762804570'::bigint)
                                      Heap Fetches: 0
                    ->  Hash Join  (cost=30.50..635.81 rows=531 width=70) (actual time=0.351..301.945 rows=1474 loops=1)
                          Hash Cond: (activity_feed_1.project_id = user_project_follow.project_id)
                          ->  Seq Scan on activity_feed activity_feed_1  (cost=0.00..541.15 rows=24215 width=70) (actual time=0.027..143.896 rows=24215 loops=1)
                          ->  Hash  (cost=30.36..30.36 rows=11 width=8) (actual time=0.171..0.182 rows=11 loops=1)
                                Buckets: 1024  Batches: 1  Memory Usage: 9kB
                                ->  Index Only Scan using idx_user_project_follow_temp on user_project_follow  (cost=0.28..30.36 rows=11 width=8) (actual time=0.020..0.102 rows=11 loops=1)
                                      Index Cond: (user_id = '17420532762804570'::bigint)
                                      Heap Fetches: 11
Planning Time: 0.571 ms
Execution Time: 771.774 ms

Thanks for the help in advance!

Answer 1

Very slow clock access like you show here (nearly 100 fold slower when TIMING defaults to ON!) usually indicates either old hardware or an old kernel IME. Not being able to trust EXPLAIN (ANALYZE) to get good data can be very frustrating if you are very particular about performance, so you should consider upgrading your hardware or your OS.