TomekB
November 17, 2017, 1:24pm
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)
;
How big is the database? Size of all tables and number of rows for each?
TomekB
November 17, 2017, 9:20pm
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
TomekB
January 31, 2018, 1:40pm
4
My problem is getting worse, it takes 7-8 secs to load the first page for a logged user ;(
Falco
January 31, 2018, 3:34pm
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.
5 Likes
I wonder why top_topics is 9GB. That seems odd @neil ?
1 Like
TomekB
February 1, 2018, 8:18am
7
EXPLAIN ANALYZE for a query that takes about 3 secs.
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
3 Likes
TomekB
February 1, 2018, 8:21am
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
2 Likes
neil
February 1, 2018, 5:19pm
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?
6 Likes
Falco
February 1, 2018, 5:40pm
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:
https://github.com/discourse/discourse/blob/master/app/models/topic_tracking_state.rb#L161-L180
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.
4 Likes
sam
February 1, 2018, 6:28pm
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.
1 Like
sam
February 2, 2018, 12:03am
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.
5 Likes
TomekB
February 2, 2018, 2:21pm
13
I’m not sure I understand what you mean, can you give me the exact queries to run?
riking
February 4, 2018, 3:47am
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?
6 Likes
sam
February 6, 2018, 5:42pm
16
Can you try applying:
https://github.com/discourse/discourse/commit/884b9d4b78c39eab83f1ef39703a348459ca7764
Just update to latest tests-passed (once it hits in a few minutes)
9 Likes
TomekB
February 7, 2018, 9:50am
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!
6 Likes
