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

slow-sql

(Dean Taylor) #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.


Extreme load times - low disk perf?
(Sam Saffron) #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


(Dean Taylor) #3

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


(Dean Taylor) #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:



(Sam Saffron) #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 …


(Dean Taylor) #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.


(Dean Taylor) #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