App/models/topic_tracking_state - `report` - long response times?

Dev
1

I’ve seen a long response times for this SQL query a few times (> 5).

The most recent occurrence is this one where it took 93.2ms:

Executing action: show
T+173.7 ms
Reader
93.2 ms
lib/freedom_patches/active_record_base.rb:7:in `exec_sql'
lib/sql_builder.rb:67:in `exec'
lib/sql_builder.rb:104:in `map_exec'
app/models/topic_tracking_state.rb:136:in `report'
app/controllers/application_controller.rb:323:in `preload_current_user_data'
app/controllers/application_controller.rb:191:in `preload_json'
lib/middleware/anonymous_cache.rb:129:in `call'
config/initializers/100-quiet_logger.rb:10:in `call_with_quiet_assets'
config/initializers/100-silence_logger.rb:26:in `call'
lib/middleware/request_tracker.rb:73:in `call'
lib/scheduler/defer.rb:85:in `process_client'
lib/middleware/unicorn_oobgc.rb:95:in `process_client'

    SELECT 
           u.id AS user_id,
           topics.id AS topic_id,
           topics.created_at,
           highest_post_number,
           last_read_post_number,
           c.id AS category_id,
           tu.notification_level
    FROM topics
    JOIN users u on u.id = 1
    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 = 1 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 ('2016-02-23 19:42:40.186120'::timestamp - INTERVAL '1 MINUTE' * COALESCE(uo.new_topic_duration_minutes, 2880))
               END, us.new_since, '2015-11-11 15:24:58.000000') 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 = 1 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 = 1 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_post_number,
           last_read_post_number,
           c.id AS category_id,
           tu.notification_level
    FROM topics
    JOIN users u on u.id = 1
    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 = 1 AND
          topics.archetype <> 'private_message' AND
          (("topics"."deleted_at" IS NULL AND tu.last_read_post_number < topics.highest_post_number AND COALESCE(tu.notification_level, 1) >= 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 = 1 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 = 1 AND
                               cu.category_id = topics.category_id AND
                               cu.notification_level = 0)

Additionally here is the time before that where it took 31.3ms:

Executing action: show
T+157.0 ms
Reader
31.3 ms
lib/freedom_patches/active_record_base.rb:7:in `exec_sql'
lib/sql_builder.rb:67:in `exec'
lib/sql_builder.rb:104:in `map_exec'
app/models/topic_tracking_state.rb:136:in `report'
app/controllers/application_controller.rb:323:in `preload_current_user_data'
app/controllers/application_controller.rb:191:in `preload_json'
lib/middleware/anonymous_cache.rb:129:in `call'
config/initializers/100-quiet_logger.rb:10:in `call_with_quiet_assets'
config/initializers/100-silence_logger.rb:26:in `call'
lib/middleware/request_tracker.rb:73:in `call'
lib/scheduler/defer.rb:85:in `process_client'
lib/middleware/unicorn_oobgc.rb:95:in `process_client'

    SELECT 
           u.id AS user_id,
           topics.id AS topic_id,
           topics.created_at,
           highest_post_number,
           last_read_post_number,
           c.id AS category_id,
           tu.notification_level
    FROM topics
    JOIN users u on u.id = 1
    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 = 1 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 ('2016-02-23 20:05:52.900200'::timestamp - INTERVAL '1 MINUTE' * COALESCE(uo.new_topic_duration_minutes, 2880))
               END, us.new_since, '2015-11-11 15:24:58.000000') 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 = 1 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 = 1 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_post_number,
           last_read_post_number,
           c.id AS category_id,
           tu.notification_level
    FROM topics
    JOIN users u on u.id = 1
    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 = 1 AND
          topics.archetype <> 'private_message' AND
          (("topics"."deleted_at" IS NULL AND tu.last_read_post_number < topics.highest_post_number AND COALESCE(tu.notification_level, 1) >= 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 = 1 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 = 1 AND
                               cu.category_id = topics.category_id AND
                               cu.notification_level = 0)

There isn’t anything noteworthy using the CPU / disk and no active sidekiq tasks.

2

I have iterated this query probably about 10 times

It gets tracking state for every topic you have with unread or new posts

I will continue iterating it, but it is nasty complicated

1 Like
3

If you want me to get some SQL timing results / EXPLAIN output for some sample sub queries - just pop them over to me.

2 Likes
4

Since updating recently (just before vdom today) I’ve gone from ~150ms mini-profiler totals to ~330ms-520ms - this is what has made me look into the profiler output.

Feeling like >3 second page load times.

I’m unsure if this query is the culprit or it’s something else.

I know you didn’t ask, but I’ve ran an EXPLAIN ANALYZE anyway…

 Append  (cost=9900.06..24626.78 rows=216 width=32) (actual time=49.472..49.472 rows=0 loops=1)
   ->  Hash Anti Join  (cost=9900.06..14435.95 rows=138 width=32) (actual time=20.854..20.854 rows=0 loops=1)
         Hash Cond: (topics.category_id = cu.category_id)
         Join Filter: (tu.last_read_post_number IS NULL)
         ->  Hash Join  (cost=9898.73..14432.88 rows=138 width=36) (actual time=20.851..20.851 rows=0 loops=1)
               Hash Cond: (topics.category_id = c.id)
               Join Filter: ((NOT c.read_restricted) OR u.admin OR (hashed SubPlan 1))
               ->  Hash Right Join  (cost=9872.79..14403.02 rows=347 width=33) (actual time=20.607..20.607 rows=0 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: 333
                     ->  Bitmap Heap Scan on topic_users tu  (cost=63.13..4556.71 rows=2930 width=16) (actual time=0.872..12.349 rows=3034 loops=1)
                           Recheck Cond: (user_id = 1)
                           ->  Bitmap Index Scan on index_topic_users_on_user_id_and_topic_id  (cost=0.00..62.40 rows=2930 width=0) (actual time=0.696..0.696 rows=3036 loops=1)
                                 Index Cond: (user_id = 1)
                     ->  Hash  (cost=9601.91..9601.91 rows=13850 width=25) (actual time=5.448..5.448 rows=333 loops=1)
                           Buckets: 2048  Batches: 1  Memory Usage: 20kB
                           ->  Nested Loop  (cost=552.67..9601.91 rows=13850 width=25) (actual time=0.540..4.954 rows=333 loops=1)
                                 ->  Nested Loop  (cost=0.86..24.93 rows=1 width=34) (actual time=0.129..0.139 rows=1 loops=1)
                                       ->  Nested Loop  (cost=0.57..16.62 rows=1 width=30) (actual time=0.086..0.091 rows=1 loops=1)
                                             ->  Index Scan using users_pkey on users u  (cost=0.29..8.30 rows=1 width=22) (actual time=0.045..0.047 rows=1 loops=1)
                                                   Index Cond: (id = 1)
                                             ->  Index Scan using user_stats_pkey on user_stats us  (cost=0.29..8.30 rows=1 width=12) (actual time=0.033..0.034 rows=1 loops=1)
                                                   Index Cond: (user_id = 1)
                                       ->  Index Scan using index_user_options_on_user_id on user_options uo  (cost=0.29..8.30 rows=1 width=8) (actual time=0.039..0.042 rows=1 loops=1)
                                             Index Cond: (user_id = 1)
                                 ->  Bitmap Heap Scan on topics  (cost=551.82..9438.47 rows=13851 width=21) (actual time=0.403..4.279 rows=333 loops=1)
                                       Recheck Cond: ((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 ('2016-02-23 22:55:48.233807'::timestamp without time zone - ('00:01:00'::interval * (COALESCE(uo.new_topic_duration_minutes, 2880))::double precision)) END, us.new_since, '2015-11-12 21:03:59'::timestamp without time zone)) AND (deleted_at IS NULL) AND ((archetype)::text <> 'private_message'::text))
                                       Filter: (visible OR u.admin OR u.moderator)
                                       ->  Bitmap Index Scan on index_topics_on_created_at_and_visible  (cost=0.00..548.35 rows=13857 width=0) (actual time=0.295..0.295 rows=336 loops=1)
                                             Index Cond: (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 ('2016-02-23 22:55:48.233807'::timestamp without time zone - ('00:01:00'::interval
 * (COALESCE(uo.new_topic_duration_minutes, 2880))::double precision)) END, us.new_since, '2015-11-12 21:03:59'::timestamp without time zone))
               ->  Hash  (cost=6.86..6.86 rows=86 width=5) (actual time=0.211..0.211 rows=86 loops=1)
                     Buckets: 1024  Batches: 1  Memory Usage: 4kB
                     ->  Seq Scan on categories c  (cost=0.00..6.86 rows=86 width=5) (actual time=0.012..0.124 rows=86 loops=1)
               SubPlan 1
                 ->  Nested Loop  (cost=4.49..18.00 rows=1 width=4) (never executed)
                       ->  Hash Join  (cost=4.35..17.50 rows=2 width=4) (never executed)
                             Hash Cond: (cg.group_id = gu.group_id)
                             ->  Seq Scan on category_groups cg  (cost=0.00..11.09 rows=409 width=8) (never executed)
                             ->  Hash  (cost=4.32..4.32 rows=2 width=4) (never executed)
                                   ->  Index Only Scan using index_group_users_on_user_id_and_group_id on group_users gu  (cost=0.29..4.32 rows=2 width=4) (never executed)
                                         Index Cond: (user_id = 1)
                                         Heap Fetches: 0
                       ->  Index Scan using categories_pkey on categories c2  (cost=0.14..0.24 rows=1 width=4) (never executed)
                             Index Cond: (id = cg.category_id)
                             Filter: read_restricted
         ->  Hash  (cost=1.31..1.31 rows=1 width=4) (never executed)
               ->  Seq Scan on category_users cu  (cost=0.00..1.31 rows=1 width=4) (never executed)
                     Filter: ((user_id = 1) AND (notification_level = 0))
   ->  Nested Loop Anti Join  (cost=81.94..10188.67 rows=78 width=32) (actual time=28.614..28.614 rows=0 loops=1)
         Join Filter: ((tu_1.last_read_post_number IS NULL) AND (cu_1.category_id = topics_1.category_id))
         ->  Nested Loop  (cost=81.94..10186.18 rows=78 width=36) (actual time=28.611..28.611 rows=0 loops=1)
               Join Filter: ((topics_1.visible OR u_1.admin OR u_1.moderator) AND ((NOT c_1.read_restricted) OR u_1.admin OR (hashed SubPlan 2)))
               ->  Nested Loop  (cost=63.08..10141.48 rows=118 width=38) (actual time=28.609..28.609 rows=0 loops=1)
                     ->  Nested Loop  (cost=62.93..10107.52 rows=196 width=33) (actual time=28.606..28.606 rows=0 loops=1)
                           ->  Bitmap Heap Scan on topic_users tu_1  (cost=62.64..4563.55 rows=977 width=16) (actual time=0.779..5.591 rows=1476 loops=1)
                                 Recheck Cond: (user_id = 1)
                                 Filter: (COALESCE(notification_level, 1) >= 2)
                                 Rows Removed by Filter: 1558
                                 ->  Bitmap Index Scan on index_topic_users_on_user_id_and_topic_id  (cost=0.00..62.40 rows=2930 width=0) (actual time=0.617..0.617 rows=3036 loops=1)
                                       Index Cond: (user_id = 1)
                           ->  Index Scan using forum_threads_pkey on topics topics_1  (cost=0.29..5.66 rows=1 width=21) (actual time=0.014..0.014 rows=0 loops=1476)
                                 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_post_number))
                                 Rows Removed by Filter: 1
                     ->  Index Scan using categories_pkey on categories c_1  (cost=0.14..0.16 rows=1 width=5) (never executed)
                           Index Cond: (id = topics_1.category_id)
               ->  Materialize  (cost=0.86..24.93 rows=1 width=6) (never executed)
                     ->  Nested Loop  (cost=0.86..24.93 rows=1 width=6) (never executed)
                           ->  Nested Loop  (cost=0.57..16.62 rows=1 width=6) (never executed)
                                 ->  Index Scan using users_pkey on users u_1  (cost=0.29..8.30 rows=1 width=6) (never executed)
                                       Index Cond: (id = 1)
                                 ->  Index Only Scan using user_stats_pkey on user_stats us_1  (cost=0.29..8.30 rows=1 width=4) (never executed)
                                       Index Cond: (user_id = 1)
                                       Heap Fetches: 0
                           ->  Index Only Scan using index_user_options_on_user_id on user_options uo_1  (cost=0.29..8.30 rows=1 width=4) (never executed)
                                 Index Cond: (user_id = 1)
                                 Heap Fetches: 0
               SubPlan 2
                 ->  Nested Loop  (cost=4.49..18.00 rows=1 width=4) (never executed)
                       ->  Hash Join  (cost=4.35..17.50 rows=2 width=4) (never executed)
                             Hash Cond: (cg_1.group_id = gu_1.group_id)
                             ->  Seq Scan on category_groups cg_1  (cost=0.00..11.09 rows=409 width=8) (never executed)
                             ->  Hash  (cost=4.32..4.32 rows=2 width=4) (never executed)
                                   ->  Index Only Scan using index_group_users_on_user_id_and_group_id on group_users gu_1  (cost=0.29..4.32 rows=2 width=4) (never executed)
                                         Index Cond: (user_id = 1)
                                         Heap Fetches: 0
                       ->  Index Scan using categories_pkey on categories c2_1  (cost=0.14..0.24 rows=1 width=4) (never executed)
                             Index Cond: (id = cg_1.category_id)
                             Filter: read_restricted
         ->  Materialize  (cost=0.00..1.32 rows=1 width=4) (never executed)
               ->  Seq Scan on category_users cu_1  (cost=0.00..1.31 rows=1 width=4) (never executed)
                     Filter: ((user_id = 1) AND (notification_level = 0))
 Total runtime: 51.262 ms
(94 rows)
EDIT: When browsing using "Incognito Mode" (i.e. logged out) performance and page load is FAR improved sub 1-second load times.

EDIT: The commit that caused the performance issue is somewhere in these 28 commits:
https://github.com/discourse/discourse/compare/f6b1238d6c22b518a7ef3d2331ee56f5f869bcf1...c344bd3fd192fdee9fc3714f038f9334e1933fc6

5

Hmmm… where are you noticing the slow?

  • When you reload on a topic page?
  • When you visit a topic from front page?

Both have very diff perf profiles, only query I am catching as “needing optimising” in “visit from front page” is the suggested topics query …

1 Like
6

Yes, but it might just be the fact that I’m logged in.

I’m struggling to reproduce this consistently, I’m restarting everything and monitoring Digital Ocean graphs…
… My apologies some of this is starting to feel like I’m on a noisy Digital Ocean instance.

Even zipping a file is slow with Discourse shutdown.

When I have more consistent resources I will retest.

3 Likes
7

I have gone back and re-tested after confirming performance issues with the Digital Ocean instance have been resolved.

I have “deleted” the incorrect information from my previous posts above.

The performance of the EXPLAIN is accurate, this query ranges from ~30ms to ~110ms (usually somewhere in the middle).

Currently I haven’t updated to the latest (VDOM), running a version from just before VDOM hit:
https://github.com/discourse/discourse/c344bd3fd192fdee9fc3714f038f9334e1933fc62

1 Like