Slow SQL query causes homepage to load in 2-4 sec


(Tomek) #1

I have some performance issues with loading the homepage of my forum. The first request takes a long time (2-4 sec) to complete. I see one query in particular that usually takes almost 2 sec. What can I do to improve? I have my DB on a dedicated server with db_shared_buffers: "8GB" and db_work_mem: "100MB"

lib/freedom_patches/active_record_base.rb:7:in `exec_sql'
lib/sql_builder.rb:67:in `exec'
lib/sql_builder.rb:103:in `map_exec'
app/models/topic_tracking_state.rb:178:in `report'
app/controllers/application_controller.rb:446:in `preload_current_user_data'
app/controllers/application_controller.rb:253:in `preload_json'
lib/middleware/anonymous_cache.rb:149:in `call'
config/initializers/100-quiet_logger.rb:16:in `call'
config/initializers/100-silence_logger.rb:29:in `call'
lib/middleware/request_tracker.rb:110:in `call'
lib/scheduler/defer.rb:87:in `process_client'
    SELECT 
        u.id AS user_id,
        topics.id AS topic_id,
        topics.created_at,
        highest_staff_post_number highest_post_number,
        last_read_post_number,
        c.id AS category_id,
        tu.notification_level
    FROM topics
    JOIN users u on u.id = 29622
    JOIN user_stats AS us ON us.user_id = u.id
    JOIN user_options AS uo ON uo.user_id = u.id
    JOIN categories c ON c.id = topics.category_id
    LEFT JOIN topic_users tu ON tu.topic_id = topics.id AND tu.user_id = u.id
    WHERE u.id = 29622 AND
        topics.archetype <> 'private_message' AND
        ((1=0) OR ("topics"."deleted_at" IS NULL AND topics.created_at >= GREATEST(CASE
                WHEN COALESCE(uo.new_topic_duration_minutes, 2880) = -1 THEN u.created_at
                WHEN COALESCE(uo.new_topic_duration_minutes, 2880) = -2 THEN COALESCE(u.previous_visit_at,u.created_at)
                ELSE ('2017-11-17 13:16:32.122898'::timestamp - INTERVAL '1 MINUTE' * COALESCE(uo.new_topic_duration_minutes, 2880))
            END, us.new_since, '2017-11-11 22:34:58') AND tu.last_read_post_number IS NULL AND COALESCE(tu.notification_level, 2) >= 2)) AND
        (topics.visible OR u.admin OR u.moderator) AND
        topics.deleted_at IS NULL AND
        ( NOT c.read_restricted OR u.admin OR category_id IN (
            SELECT c2.id FROM categories c2
            JOIN category_groups cg ON cg.category_id = c2.id
            JOIN group_users gu ON gu.user_id = 29622 AND cg.group_id = gu.group_id
            WHERE c2.read_restricted )
        )
        AND NOT EXISTS( SELECT 1 FROM category_users cu
                        WHERE last_read_post_number IS NULL AND
                            cu.user_id = 29622 AND
                            cu.category_id = topics.category_id AND
                            cu.notification_level = 0)


UNION ALL

    SELECT 
        u.id AS user_id,
        topics.id AS topic_id,
        topics.created_at,
        highest_staff_post_number highest_post_number,
        last_read_post_number,
        c.id AS category_id,
        tu.notification_level
    FROM topics
    JOIN users u on u.id = 29622
    JOIN user_stats AS us ON us.user_id = u.id
    JOIN user_options AS uo ON uo.user_id = u.id
    JOIN categories c ON c.id = topics.category_id
    LEFT JOIN topic_users tu ON tu.topic_id = topics.id AND tu.user_id = u.id
    WHERE u.id = 29622 AND
        topics.archetype <> 'private_message' AND
        (("topics"."deleted_at" IS NULL AND tu.last_read_post_number < topics.highest_staff_post_number AND tu.notification_level >= 2) OR (1=0)) AND
        (topics.visible OR u.admin OR u.moderator) AND
        topics.deleted_at IS NULL AND
        ( NOT c.read_restricted OR u.admin OR category_id IN (
            SELECT c2.id FROM categories c2
            JOIN category_groups cg ON cg.category_id = c2.id
            JOIN group_users gu ON gu.user_id = 29622 AND cg.group_id = gu.group_id
            WHERE c2.read_restricted )
        )
        AND NOT EXISTS( SELECT 1 FROM category_users cu
                        WHERE last_read_post_number IS NULL AND
                            cu.user_id = 29622 AND
                            cu.category_id = topics.category_id AND
                            cu.notification_level = 0)

;

(Jeff Atwood) #2

How big is the database? Size of all tables and number of rows for each?


(Tomek) #3
Size	Ext Size	Table
9892 MB	9031 MB	top_topics
8255 MB	5537 MB	topic_views
7044 MB	3863 MB	post_search_data
6576 MB	2541 MB	posts
4448 MB	1855 MB	post_search_data
4018 MB	1201 MB	posts
3391 MB	1524 MB	incoming_links
2553 MB	1015 MB	topics
896 MB	658 MB	directory_items
862 MB	603 MB	user_actions
828 MB	527 MB	post_timings
785 MB	542 MB	user_actions
759 MB	241 MB	topics
723 MB	137 MB	topic_link_clicks
630 MB	199 MB	topic_search_data
599 MB	330 MB	post_custom_fields
595 MB	328 MB	post_custom_fields
521 MB	265 MB	topic_links
476 MB	176 MB	topic_users
449 MB	326 MB	directory_items
432 MB	86 MB	topic_search_data
388 MB	302 MB	top_topics
387 MB	196 MB	topic_links
383 MB	243 MB	post_timings
374 MB	148 MB	post_stats
359 MB	142 MB	post_stats
316 MB	178 MB	permalinks
311 MB	118 MB	topic_users
264 MB	192 MB	users
220 MB	112 MB	draft_sequences
211 MB	108 MB	draft_sequences
198 MB	90 MB	permalinks
170 MB	58 MB	user_profile_views
164 MB	162 MB	user_histories
147 MB	88 MB	email_logs
103 MB	56 MB	users
84 MB	51 MB	notifications
77 MB	33 MB	user_custom_fields
77 MB	44 MB	user_search_data
76 MB	33 MB	user_custom_fields
71 MB	13 MB	optimized_images
67 MB	46 MB	user_emails
62 MB	12 MB	user_stats
61 MB	42 MB	user_profiles
61 MB	35 MB	user_search_data
59 MB	28 MB	email_tokens
58 MB	28 MB	email_tokens
45 MB	40 MB	unsubscribe_keys
41 MB	27 MB	user_profiles
39 MB	27 MB	uploads
39 MB	19 MB	group_users
37 MB	18 MB	group_users
34 MB	6352 kB	user_options
31 MB	6224 kB	user_stats
31 MB	6224 kB	user_options
29 MB	6616 kB	scheduler_stats
29 MB	13 MB	notifications
25 MB	5384 kB	drafts
20 MB	12 MB	user_badges
19 MB	8712 kB	application_requests
19 MB	11 MB	user_visits
19 MB	8280 kB	user_auth_tokens
17 MB	5488 kB	post_revisions
17 MB	10064 kB	user_badges
11 MB	6720 kB	uploads
9640 kB	312 kB	user_auth_token_logs
9200 kB	9120 kB	incoming_emails
8856 kB	4512 kB	quoted_posts
7824 kB	936 kB	single_sign_on_records
7784 kB	4680 kB	incoming_referers
6464 kB	1840 kB	post_replies
6432 kB	4048 kB	user_avatars
6176 kB	3296 kB	quoted_posts
6008 kB	4672 kB	post_uploads
3912 kB	2216 kB	topic_allowed_users
3784 kB	2240 kB	post_actions
3616 kB	1120 kB	post_replies
3016 kB	1760 kB	user_avatars
2632 kB	1888 kB	category_featured_topics
2288 kB	2232 kB	stylesheet_cache
2224 kB	664 kB	categories
1744 kB	360 kB	scheduler_stats
1616 kB	336 kB	search_logs
1504 kB	560 kB	plugin_store_rows
1408 kB	656 kB	topic_allowed_groups
1112 kB	304 kB	optimized_images
1024 kB	816 kB	theme_fields
880 kB	392 kB	post_revisions
832 kB	464 kB	topic_tags
824 kB	816 kB	stylesheet_cache
760 kB	416 kB	given_daily_likes
744 kB	528 kB	topic_custom_fields
680 kB	264 kB	queued_posts
664 kB	304 kB	user_archived_messages
608 kB	272 kB	post_details
496 kB	312 kB	incoming_domains
376 kB	240 kB	group_archived_messages
360 kB	272 kB	user_histories
280 kB	224 kB	post_uploads
240 kB	72 kB	tags
232 kB	112 kB	schema_migration_details
216 kB	112 kB	schema_migration_details
160 kB	128 kB	category_featured_topics
144 kB	136 kB	email_logs
136 kB	120 kB	group_histories
128 kB	120 kB	group_histories
128 kB	104 kB	category_search_data
128 kB	104 kB	categories
128 kB	88 kB	badges
128 kB	112 kB	themes
120 kB	112 kB	user_profile_views
120 kB	96 kB	topic_views
120 kB	80 kB	schema_migrations
112 kB	80 kB	schema_migrations
112 kB	88 kB	badges
112 kB	104 kB	user_api_keys
112 kB	104 kB	category_search_data
112 kB	104 kB	post_actions
104 kB	96 kB	site_customizations
96 kB	88 kB	screened_ip_addresses
96 kB	88 kB	screened_ip_addresses
96 kB	72 kB	color_scheme_colors
96 kB	56 kB	site_settings
96 kB	88 kB	groups
96 kB	88 kB	groups
96 kB	88 kB	screened_emails
96 kB	88 kB	screened_urls
88 kB	80 kB	topic_allowed_groups
88 kB	80 kB	group_mentions
88 kB	80 kB	topic_timers
88 kB	80 kB	muted_users
88 kB	80 kB	child_themes
88 kB	80 kB	category_users
88 kB	72 kB	single_sign_on_records
88 kB	80 kB	user_warnings
88 kB	80 kB	topic_allowed_users
88 kB	80 kB	user_visits
80 kB	72 kB	topic_embeds
80 kB	72 kB	category_custom_fields
80 kB	72 kB	custom_emojis
80 kB	72 kB	topic_link_clicks
80 kB	72 kB	watched_words
80 kB	72 kB	onceoff_logs
80 kB	72 kB	onceoff_logs
80 kB	72 kB	translation_overrides
80 kB	72 kB	category_custom_fields
80 kB	72 kB	badge_types
80 kB	72 kB	badge_types
72 kB	64 kB	application_requests
72 kB	64 kB	given_daily_likes
64 kB	56 kB	embeddable_hosts
64 kB	56 kB	web_hook_event_types
64 kB	56 kB	badge_groupings
64 kB	64 kB	versions
64 kB	56 kB	badge_groupings
64 kB	56 kB	color_schemes
64 kB	56 kB	site_settings
64 kB	64 kB	versions
64 kB	56 kB	api_keys
64 kB	56 kB	web_hook_event_types
56 kB	48 kB	tag_search_data
56 kB	48 kB	category_groups
56 kB	48 kB	post_action_types
56 kB	56 kB	drafts
56 kB	48 kB	post_action_types
56 kB	48 kB	tag_users
56 kB	48 kB	category_groups
48 kB	48 kB	incoming_emails
48 kB	40 kB	user_exports
40 kB	32 kB	category_tag_groups
40 kB	32 kB	tag_group_memberships
40 kB	40 kB	user_api_keys
32 kB	32 kB	screened_urls
32 kB	32 kB	facebook_user_infos
32 kB	24 kB	tag_groups
32 kB	32 kB	twitter_user_infos
32 kB	24 kB	ar_internal_metadata
32 kB	32 kB	google_user_infos
32 kB	32 kB	google_user_infos
32 kB	32 kB	incoming_links
32 kB	32 kB	topic_custom_fields
32 kB	32 kB	invites
32 kB	32 kB	screened_emails
32 kB	32 kB	invites
32 kB	32 kB	github_user_infos
32 kB	32 kB	api_keys
32 kB	32 kB	queued_posts
32 kB	24 kB	user_fields
32 kB	32 kB	facebook_user_infos
32 kB	32 kB	github_user_infos
32 kB	32 kB	twitter_user_infos
24 kB	24 kB	muted_users
24 kB	24 kB	topic_invites
24 kB	24 kB	web_hook_events
24 kB	24 kB	topic_embeds
24 kB	24 kB	message_bus
24 kB	24 kB	oauth2_user_infos
24 kB	24 kB	topic_invites
24 kB	24 kB	plugin_store_rows
24 kB	24 kB	group_custom_fields
24 kB	24 kB	group_mentions
24 kB	24 kB	color_scheme_colors
24 kB	24 kB	category_users
24 kB	24 kB	tags
24 kB	24 kB	user_open_ids
24 kB	24 kB	category_tags
24 kB	24 kB	email_change_requests
24 kB	24 kB	translation_overrides
24 kB	24 kB	message_bus
24 kB	24 kB	warnings
24 kB	24 kB	web_hook_events
24 kB	24 kB	incoming_referers
24 kB	24 kB	category_tags
24 kB	24 kB	unsubscribe_keys
24 kB	24 kB	email_change_requests
24 kB	24 kB	group_custom_fields
24 kB	24 kB	oauth2_user_infos
24 kB	24 kB	tag_users
24 kB	24 kB	user_open_ids
24 kB	24 kB	post_details
16 kB	16 kB	tag_groups
16 kB	16 kB	category_featured_users
16 kB	16 kB	group_archived_messages
16 kB	16 kB	color_schemes
16 kB	16 kB	tag_group_memberships
16 kB	16 kB	category_tag_groups
16 kB	16 kB	instagram_user_infos
16 kB	16 kB	remote_themes
16 kB	16 kB	incoming_domains
16 kB	16 kB	user_field_options
16 kB	16 kB	instagram_user_infos
16 kB	16 kB	user_archived_messages
16 kB	16 kB	user_field_options
16 kB	16 kB	user_fields
16 kB	16 kB	user_exports
16 kB	16 kB	category_featured_users
16 kB	16 kB	topic_tags
16 kB	16 kB	web_hooks
16 kB	16 kB	web_hooks
16 kB	16 kB	embeddable_hosts
8192 bytes	8192 bytes	invited_groups
8192 bytes	8192 bytes	web_hook_event_types_hooks
8192 bytes	8192 bytes	categories_web_hooks
8192 bytes	8192 bytes	groups_web_hooks
8192 bytes	8192 bytes	groups_web_hooks
8192 bytes	8192 bytes	categories_web_hooks
8192 bytes	8192 bytes	developers
8192 bytes	8192 bytes	web_hook_event_types_hooks
8192 bytes	8192 bytes	invited_groups
8192 bytes	8192 bytes	developers

(Tomek) #4

My problem is getting worse, it takes 7-8 secs to load the first page for a logged user ;(


(Rafael dos Santos Silva) #5

Take the slow query from the MiniProfiler (thing with numbers at top left) and run it with psql, as EXPLAIN ANALYZE $query, then paste the results here.

Also, I saw a very active Discourse get better performance running in spinning disks, so I guess something is very wrong.


(Jeff Atwood) #6

I wonder why top_topics is 9GB. That seems odd @neil?


(Tomek) #7

EXPLAIN ANALYZE for a query that takes about 3 secs.
This is consistent meaning each time I run it I get similar results.

Append  (cost=224504.33..298195.43 rows=4264 width=32) (actual time=2164.210..2811.605 rows=151 loops=1)
->  Hash Anti Join  (cost=224504.33..247949.29 rows=3309 width=32) (actual time=2164.208..2787.392 rows=85 loops=1)
        Hash Cond: (topics.category_id = cu.category_id)
        Join Filter: (tu.last_read_post_number IS NULL)
        ->  Hash Join  (cost=224495.29..247898.44 rows=3315 width=36) (actual time=2164.146..2787.263 rows=85 loops=1)
            Hash Cond: (topics.category_id = c.id)
            Join Filter: (((NOT c.read_restricted) OR u.admin OR (hashed SubPlan 1)) AND (topics.created_at >= GREATEST(CASE WHEN (COALESCE(uo.new_topic_duration_minutes, 2880) = '-1'::integer) THEN u.created_at WHEN (COALESCE(uo.new_topic_duration_minutes, 2880) = '-2'::integer) THEN COALESCE(u.previous_visit_at, u.created_at) ELSE ('2018-02-01 08:14:09.813495'::timestamp without time zone - ('00:01:00'::interval * (COALESCE(uo.new_topic_duration_minutes, 2880))::double precision)) END, us.new_since, '2018-01-26 19:25:08'::timestamp without time zone)))
            Rows Removed by Join Filter: 531113
            ->  Hash Right Join  (cost=224440.81..247511.19 rows=11073 width=53) (actual time=2153.460..2416.891 rows=531198 loops=1)
                    Hash Cond: ((tu.user_id = u.id) AND (tu.topic_id = topics.id))
                    Filter: ((tu.last_read_post_number IS NULL) AND (COALESCE(tu.notification_level, 2) >= 2))
                    Rows Removed by Filter: 1284
                    ->  Bitmap Heap Scan on topic_users tu  (cost=230.39..23105.41 rows=10059 width=16) (actual time=2.795..32.127 rows=11147 loops=1)
                        Recheck Cond: (user_id = 29622)
                        Heap Blocks: exact=4085
                        ->  Bitmap Index Scan on index_topic_users_on_user_id_and_topic_id  (cost=0.00..227.87 rows=10059 width=0) (actual time=2.055..2.055 rows=11179 loops=1)
                                Index Cond: (user_id = 29622)
                    ->  Hash  (cost=213487.15..213487.15 rows=714885 width=45) (actual time=2097.736..2097.736 rows=532482 loops=1)
                        Buckets: 1048576  Batches: 1  Memory Usage: 53953kB
                        ->  Nested Loop  (cost=0.84..213487.15 rows=714885 width=45) (actual time=1.925..1786.062 rows=532482 loops=1)
                                Join Filter: (topics.visible OR u.admin OR u.moderator)
                                ->  Nested Loop  (cost=0.84..16.89 rows=1 width=26) (actual time=0.259..0.265 rows=1 loops=1)
                                    ->  Index Scan using users_pkey on users u  (cost=0.42..8.44 rows=1 width=22) (actual time=0.120..0.122 rows=1 loops=1)
                                            Index Cond: (id = 29622)
                                    ->  Index Scan using index_user_options_on_user_id on user_options uo  (cost=0.42..8.44 rows=1 width=8) (actual time=0.131..0.134 rows=1 loops=1)
                                            Index Cond: (user_id = 29622)
                                ->  Seq Scan on topics  (cost=0.00..206318.55 rows=715171 width=21) (actual time=1.650..1675.564 rows=532482 loops=1)
                                    Filter: ((deleted_at IS NULL) AND (deleted_at IS NULL) AND ((archetype)::text <> 'private_message'::text))
                                    Rows Removed by Filter: 23895
            ->  Hash  (cost=40.08..40.08 rows=82 width=17) (actual time=0.387..0.387 rows=82 loops=1)
                    Buckets: 1024  Batches: 1  Memory Usage: 13kB
                    ->  Nested Loop  (cost=0.42..40.08 rows=82 width=17) (actual time=0.154..0.321 rows=82 loops=1)
                        ->  Index Scan using user_stats_pkey on user_stats us  (cost=0.42..8.44 rows=1 width=12) (actual time=0.131..0.133 rows=1 loops=1)
                                Index Cond: (user_id = 29622)
                        ->  Seq Scan on categories c  (cost=0.00..30.82 rows=82 width=5) (actual time=0.009..0.124 rows=82 loops=1)
            SubPlan 1
                ->  Nested Loop  (cost=0.69..13.37 rows=1 width=4) (never executed)
                    ->  Nested Loop  (cost=0.42..10.61 rows=1 width=4) (never executed)
                            Join Filter: (cg.group_id = gu.group_id)
                            ->  Index Only Scan using index_group_users_on_user_id_and_group_id on group_users gu  (cost=0.42..8.44 rows=1 width=4) (never executed)
                                Index Cond: (user_id = 29622)
                                Heap Fetches: 0
                            ->  Seq Scan on category_groups cg  (cost=0.00..1.52 rows=52 width=8) (never executed)
                    ->  Index Scan using categories_pkey on categories c2  (cost=0.27..2.75 rows=1 width=4) (never executed)
                            Index Cond: (id = cg.category_id)
                            Filter: read_restricted
        ->  Hash  (cost=9.02..9.02 rows=2 width=4) (actual time=0.022..0.022 rows=0 loops=1)
            Buckets: 1024  Batches: 1  Memory Usage: 8kB
            ->  Bitmap Heap Scan on category_users cu  (cost=4.20..9.02 rows=2 width=4) (actual time=0.021..0.021 rows=0 loops=1)
                    Recheck Cond: ((user_id = 29622) AND (notification_level = 0))
                    ->  Bitmap Index Scan on idx_category_users_u1  (cost=0.00..4.19 rows=2 width=0) (actual time=0.019..0.019 rows=0 loops=1)
                        Index Cond: ((user_id = 29622) AND (notification_level = 0))
->  Nested Loop Anti Join  (cost=244.18..50203.50 rows=955 width=32) (actual time=3.616..24.173 rows=66 loops=1)
        Join Filter: (tu_1.last_read_post_number IS NULL)
        ->  Nested Loop  (cost=244.04..50033.59 rows=957 width=36) (actual time=3.594..23.965 rows=66 loops=1)
            Join Filter: ((NOT c_1.read_restricted) OR u_1.admin OR (hashed SubPlan 2))
            ->  Nested Loop  (cost=230.40..49702.88 rows=1066 width=33) (actual time=3.584..23.687 rows=66 loops=1)
                    Join Filter: (topics_1.visible OR u_1.admin OR u_1.moderator)
                    ->  Nested Loop  (cost=1.27..25.34 rows=1 width=6) (actual time=0.160..0.165 rows=1 loops=1)
                        ->  Nested Loop  (cost=0.84..16.89 rows=1 width=6) (actual time=0.119..0.122 rows=1 loops=1)
                                ->  Index Scan using users_pkey on users u_1  (cost=0.42..8.44 rows=1 width=6) (actual time=0.029..0.030 rows=1 loops=1)
                                    Index Cond: (id = 29622)
                                ->  Index Only Scan using user_stats_pkey on user_stats us_1  (cost=0.42..8.44 rows=1 width=4) (actual time=0.087..0.088 rows=1 loops=1)
                                    Index Cond: (user_id = 29622)
                                    Heap Fetches: 1
                        ->  Index Only Scan using index_user_options_on_user_id on user_options uo_1  (cost=0.42..8.44 rows=1 width=4) (actual time=0.038..0.040 rows=1 loops=1)
                                Index Cond: (user_id = 29622)
                                Heap Fetches: 1
                    ->  Nested Loop  (cost=229.14..49666.88 rows=1066 width=33) (actual time=3.413..23.485 rows=66 loops=1)
                        ->  Bitmap Heap Scan on topic_users tu_1  (cost=228.71..23128.88 rows=3353 width=16) (actual time=2.767..14.108 rows=691 loops=1)
                                Recheck Cond: (user_id = 29622)
                                Filter: (COALESCE(notification_level, 1) >= 2)
                                Rows Removed by Filter: 10456
                                Heap Blocks: exact=4085
                                ->  Bitmap Index Scan on index_topic_users_on_user_id_and_topic_id  (cost=0.00..227.87 rows=10059 width=0) (actual time=2.000..2.000 rows=11179 loops=1)
                                    Index Cond: (user_id = 29622)
                        ->  Index Scan using topics_pkey on topics topics_1  (cost=0.42..7.90 rows=1 width=21) (actual time=0.013..0.013 rows=0 loops=691)
                                Index Cond: (id = tu_1.topic_id)
                                Filter: ((deleted_at IS NULL) AND (deleted_at IS NULL) AND ((archetype)::text <> 'private_message'::text) AND (tu_1.last_read_post_number < highest_staff_post_number))
                                Rows Removed by Filter: 1
            ->  Index Scan using categories_pkey on categories c_1  (cost=0.27..0.29 rows=1 width=5) (actual time=0.003..0.003 rows=1 loops=66)
                    Index Cond: (id = topics_1.category_id)
            SubPlan 2
                ->  Nested Loop  (cost=0.69..13.37 rows=1 width=4) (never executed)
                    ->  Nested Loop  (cost=0.42..10.61 rows=1 width=4) (never executed)
                            Join Filter: (cg_1.group_id = gu_1.group_id)
                            ->  Index Only Scan using index_group_users_on_user_id_and_group_id on group_users gu_1  (cost=0.42..8.44 rows=1 width=4) (never executed)
                                Index Cond: (user_id = 29622)
                                Heap Fetches: 0
                            ->  Seq Scan on category_groups cg_1  (cost=0.00..1.52 rows=52 width=8) (never executed)
                    ->  Index Scan using categories_pkey on categories c2_1  (cost=0.27..2.75 rows=1 width=4) (never executed)
                            Index Cond: (id = cg_1.category_id)
                            Filter: read_restricted
        ->  Index Only Scan using idx_category_users_u2 on category_users cu_1  (cost=0.14..0.17 rows=1 width=4) (actual time=0.002..0.002 rows=0 loops=66)
            Index Cond: ((category_id = topics_1.category_id) AND (user_id = 29622) AND (notification_level = 0))
            Heap Fetches: 0
Planning time: 25.623 ms
Execution time: 2815.374 ms

(Tomek) #8

I have another query that takes another 3 seconds to complete (which in total makes over 6-7 secs to load the forum for the first time):

Append  (cost=224504.33..298195.43 rows=4264 width=32) (actual time=1990.064..2623.731 rows=151 loops=1)
->  Hash Anti Join  (cost=224504.33..247949.29 rows=3309 width=32) (actual time=1990.064..2606.236 rows=85 loops=1)
        Hash Cond: (topics.category_id = cu.category_id)
        Join Filter: (tu.last_read_post_number IS NULL)
        ->  Hash Join  (cost=224495.29..247898.44 rows=3315 width=36) (actual time=1990.013..2606.115 rows=85 loops=1)
            Hash Cond: (topics.category_id = c.id)
            Join Filter: (((NOT c.read_restricted) OR u.admin OR (hashed SubPlan 1)) AND (topics.created_at >= GREATEST(CASE WHEN (COALESCE(uo.new_topic_duration_minutes, 2880) = '-1'::integer) THEN u.created_at WHEN (COALESCE(uo.new_topic_duration_minutes, 2880) = '-2'::integer) THEN COALESCE(u.previous_visit_at, u.created_at) ELSE ('2018-02-01 08:14:13.81256'::timestamp without time zone - ('00:01:00'::interval * (COALESCE(uo.new_topic_duration_minutes, 2880))::double precision)) END, us.new_since, '2018-01-26 19:25:08'::timestamp without time zone)))
            Rows Removed by Join Filter: 531113
            ->  Hash Right Join  (cost=224440.81..247511.19 rows=11073 width=53) (actual time=1979.385..2236.331 rows=531198 loops=1)
                    Hash Cond: ((tu.user_id = u.id) AND (tu.topic_id = topics.id))
                    Filter: ((tu.last_read_post_number IS NULL) AND (COALESCE(tu.notification_level, 2) >= 2))
                    Rows Removed by Filter: 1284
                    ->  Bitmap Heap Scan on topic_users tu  (cost=230.39..23105.41 rows=10059 width=16) (actual time=2.546..11.093 rows=11147 loops=1)
                        Recheck Cond: (user_id = 29622)
                        Heap Blocks: exact=4085
                        ->  Bitmap Index Scan on index_topic_users_on_user_id_and_topic_id  (cost=0.00..227.87 rows=10059 width=0) (actual time=1.839..1.839 rows=11179 loops=1)
                                Index Cond: (user_id = 29622)
                    ->  Hash  (cost=213487.15..213487.15 rows=714885 width=45) (actual time=1946.922..1946.922 rows=532482 loops=1)
                        Buckets: 1048576  Batches: 1  Memory Usage: 53953kB
                        ->  Nested Loop  (cost=0.84..213487.15 rows=714885 width=45) (actual time=1.430..1639.424 rows=532482 loops=1)
                                Join Filter: (topics.visible OR u.admin OR u.moderator)
                                ->  Nested Loop  (cost=0.84..16.89 rows=1 width=26) (actual time=0.084..0.090 rows=1 loops=1)
                                    ->  Index Scan using users_pkey on users u  (cost=0.42..8.44 rows=1 width=22) (actual time=0.053..0.055 rows=1 loops=1)
                                            Index Cond: (id = 29622)
                                    ->  Index Scan using index_user_options_on_user_id on user_options uo  (cost=0.42..8.44 rows=1 width=8) (actual time=0.023..0.027 rows=1 loops=1)
                                            Index Cond: (user_id = 29622)
                                ->  Seq Scan on topics  (cost=0.00..206318.55 rows=715171 width=21) (actual time=1.329..1534.485 rows=532482 loops=1)
                                    Filter: ((deleted_at IS NULL) AND (deleted_at IS NULL) AND ((archetype)::text <> 'private_message'::text))
                                    Rows Removed by Filter: 23895
            ->  Hash  (cost=40.08..40.08 rows=82 width=17) (actual time=0.217..0.217 rows=82 loops=1)
                    Buckets: 1024  Batches: 1  Memory Usage: 13kB
                    ->  Nested Loop  (cost=0.42..40.08 rows=82 width=17) (actual time=0.059..0.167 rows=82 loops=1)
                        ->  Index Scan using user_stats_pkey on user_stats us  (cost=0.42..8.44 rows=1 width=12) (actual time=0.040..0.042 rows=1 loops=1)
                                Index Cond: (user_id = 29622)
                        ->  Seq Scan on categories c  (cost=0.00..30.82 rows=82 width=5) (actual time=0.007..0.067 rows=82 loops=1)
            SubPlan 1
                ->  Nested Loop  (cost=0.69..13.37 rows=1 width=4) (never executed)
                    ->  Nested Loop  (cost=0.42..10.61 rows=1 width=4) (never executed)
                            Join Filter: (cg.group_id = gu.group_id)
                            ->  Index Only Scan using index_group_users_on_user_id_and_group_id on group_users gu  (cost=0.42..8.44 rows=1 width=4) (never executed)
                                Index Cond: (user_id = 29622)
                                Heap Fetches: 0
                            ->  Seq Scan on category_groups cg  (cost=0.00..1.52 rows=52 width=8) (never executed)
                    ->  Index Scan using categories_pkey on categories c2  (cost=0.27..2.75 rows=1 width=4) (never executed)
                            Index Cond: (id = cg.category_id)
                            Filter: read_restricted
        ->  Hash  (cost=9.02..9.02 rows=2 width=4) (actual time=0.013..0.013 rows=0 loops=1)
            Buckets: 1024  Batches: 1  Memory Usage: 8kB
            ->  Bitmap Heap Scan on category_users cu  (cost=4.20..9.02 rows=2 width=4) (actual time=0.013..0.013 rows=0 loops=1)
                    Recheck Cond: ((user_id = 29622) AND (notification_level = 0))
                    ->  Bitmap Index Scan on idx_category_users_u1  (cost=0.00..4.19 rows=2 width=0) (actual time=0.011..0.011 rows=0 loops=1)
                        Index Cond: ((user_id = 29622) AND (notification_level = 0))
->  Nested Loop Anti Join  (cost=244.18..50203.50 rows=955 width=32) (actual time=3.251..17.461 rows=66 loops=1)
        Join Filter: (tu_1.last_read_post_number IS NULL)
        ->  Nested Loop  (cost=244.04..50033.59 rows=957 width=36) (actual time=3.230..17.295 rows=66 loops=1)
            Join Filter: ((NOT c_1.read_restricted) OR u_1.admin OR (hashed SubPlan 2))
            ->  Nested Loop  (cost=230.40..49702.88 rows=1066 width=33) (actual time=3.218..17.067 rows=66 loops=1)
                    Join Filter: (topics_1.visible OR u_1.admin OR u_1.moderator)
                    ->  Nested Loop  (cost=1.27..25.34 rows=1 width=6) (actual time=0.073..0.078 rows=1 loops=1)
                        ->  Nested Loop  (cost=0.84..16.89 rows=1 width=6) (actual time=0.054..0.057 rows=1 loops=1)
                                ->  Index Scan using users_pkey on users u_1  (cost=0.42..8.44 rows=1 width=6) (actual time=0.029..0.030 rows=1 loops=1)
                                    Index Cond: (id = 29622)
                                ->  Index Only Scan using user_stats_pkey on user_stats us_1  (cost=0.42..8.44 rows=1 width=4) (actual time=0.020..0.021 rows=1 loops=1)
                                    Index Cond: (user_id = 29622)
                                    Heap Fetches: 1
                        ->  Index Only Scan using index_user_options_on_user_id on user_options uo_1  (cost=0.42..8.44 rows=1 width=4) (actual time=0.016..0.018 rows=1 loops=1)
                                Index Cond: (user_id = 29622)
                                Heap Fetches: 1
                    ->  Nested Loop  (cost=229.14..49666.88 rows=1066 width=33) (actual time=3.133..16.952 rows=66 loops=1)
                        ->  Bitmap Heap Scan on topic_users tu_1  (cost=228.71..23128.88 rows=3353 width=16) (actual time=2.637..12.758 rows=691 loops=1)
                                Recheck Cond: (user_id = 29622)
                                Filter: (COALESCE(notification_level, 1) >= 2)
                                Rows Removed by Filter: 10456
                                Heap Blocks: exact=4085
                                ->  Bitmap Index Scan on index_topic_users_on_user_id_and_topic_id  (cost=0.00..227.87 rows=10059 width=0) (actual time=1.922..1.922 rows=11179 loops=1)
                                    Index Cond: (user_id = 29622)
                        ->  Index Scan using topics_pkey on topics topics_1  (cost=0.42..7.90 rows=1 width=21) (actual time=0.006..0.006 rows=0 loops=691)
                                Index Cond: (id = tu_1.topic_id)
                                Filter: ((deleted_at IS NULL) AND (deleted_at IS NULL) AND ((archetype)::text <> 'private_message'::text) AND (tu_1.last_read_post_number < highest_staff_post_number))
                                Rows Removed by Filter: 1
            ->  Index Scan using categories_pkey on categories c_1  (cost=0.27..0.29 rows=1 width=5) (actual time=0.002..0.002 rows=1 loops=66)
                    Index Cond: (id = topics_1.category_id)
            SubPlan 2
                ->  Nested Loop  (cost=0.69..13.37 rows=1 width=4) (never executed)
                    ->  Nested Loop  (cost=0.42..10.61 rows=1 width=4) (never executed)
                            Join Filter: (cg_1.group_id = gu_1.group_id)
                            ->  Index Only Scan using index_group_users_on_user_id_and_group_id on group_users gu_1  (cost=0.42..8.44 rows=1 width=4) (never executed)
                                Index Cond: (user_id = 29622)
                                Heap Fetches: 0
                            ->  Seq Scan on category_groups cg_1  (cost=0.00..1.52 rows=52 width=8) (never executed)
                    ->  Index Scan using categories_pkey on categories c2_1  (cost=0.27..2.75 rows=1 width=4) (never executed)
                            Index Cond: (id = cg_1.category_id)
                            Filter: read_restricted
        ->  Index Only Scan using idx_category_users_u2 on category_users cu_1  (cost=0.14..0.17 rows=1 width=4) (actual time=0.002..0.002 rows=0 loops=66)
            Index Cond: ((category_id = topics_1.category_id) AND (user_id = 29622) AND (notification_level = 0))
            Heap Fetches: 0
Planning time: 9.772 ms
Execution time: 2625.697 ms

(Neil Lalonde) #9

In both those queries, this step takes about 1.6 seconds:

->  Seq Scan on topics  (cost=0.00..206318.55 rows=715171 width=21) (actual time=1.650..1675.564 rows=532482 loops=1)    
    Filter: ((deleted_at IS NULL) AND (deleted_at IS NULL) AND ((archetype)::text <> 'private_message'::text))
    Rows Removed by Filter: 23895

Filtering out deleted topics and private messages still leaves 532k topics in the result. After all other filters have completed, only 85 rows are returned.

Maybe we can simplify this filter, which is removing 531k topics:

Join Filter: (((NOT c.read_restricted) OR u.admin OR (hashed SubPlan 1)) AND (topics.created_at >= GREATEST(CASE WHEN (COALESCE(uo.new_topic_duration_minutes, 2880) = '-1'::integer) THEN u.created_at WHEN (COALESCE(uo.new_topic_duration_minutes, 2880) = '-2'::integer) THEN COALESCE(u.previous_visit_at, u.created_at) ELSE ('2018-02-01 08:14:09.813495'::timestamp without time zone - ('00:01:00'::interval * (COALESCE(uo.new_topic_duration_minutes, 2880))::double precision)) END, us.new_since, '2018-01-26 19:25:08'::timestamp without time zone)))
                Rows Removed by Join Filter: 531113

It includes topics.created_at >= some date, but i guess the CASE is burying it. /shrug

@Falco Any ideas?


(Rafael dos Santos Silva) #10

Since this is a seq scan this should get faster when we upgrade to PostgreSQL 10.

But this is a very delicate query (since we run it every time a logged in hits /latest) and in reality we should never do a seq scan in a situation like this.

Looks like @sam has some battle scars in this code part:

I believe you hit the right spot here @neil, we need to ensure this filter works.

Since I’m not familiar with this code, I’ll dig further in the next days.


(Sam Saffron) #11

We can probably optimise a bit more by running a prep query first or something like that, will have a look and see if there is anything more we can do.


(Sam Saffron) #12

Note, this is a slower less common variant of the query, since it applies only to staff.

Can you do some homework for me.

Split this into 4 pieces:

  • staff first part prior to union all
  • staff second part
  • non staff (user with lots of read state) first part
  • non staff second part

Then run each of these… which is slowest… what is the plan for each of the puzzle pieces.


(Tomek) #13

I’m not sure I understand what you mean, can you give me the exact queries to run?


(Kane York) #15

There should be a second version of this query showing up in the logs, mostly identical but without highest_staff_post_number.

Also note that there is a UNION ALL here; split the query into 2 on that.

So that’s a 2x2 matrix; try running EXPLAIN ANALYZE on all 4; is there a significant difference for staff vs nonstaff?


(Sam Saffron) #16

Can you try applying:

Just update to latest tests-passed (once it hits in a few minutes)


(Tomek) #17

It sort of helped, after this patch the load times are 1-2 secs on average (instead of 4-8 secs before).

Thank you! :smiley: