特定版主在评论区遇到 500 服务器错误

我们的一位版主在“审核”(Review)部分总是遇到服务器错误信息。这似乎是由于其中一条生成的查询执行时间远超通常的 30 秒超时限制所致。

具体操作如下:访问 /review 页面,并将 Status 下拉菜单更改为 Everything(尽管选择其他选项时也会出现同样的问题)。对于其他所有工作人员来说,执行相同的操作似乎是瞬间完成的。这位版主是我们最活跃的一位,这似乎会触发该问题。

错误信息

:frowning:
Server Error
while trying to load /review?priority=low&status=all&sort_order=created_at&additional_filters=%7B%7D
Error code: 500 error

生成的查询语句如下:

问题查询
SELECT COUNT(*) FROM "reviewables" LEFT OUTER JOIN "categories" ON "categories"."id" = "reviewables"."category_id" LEFT OUTER JOIN "category_moderation_groups" ON "category_moderation_groups"."category_id" = "categories"."id" WHERE ((reviewables.reviewable_by_moderator AND TRUE) OR (category_moderation_groups.group_id IN (2, 3, 10, 11, 12, 13, 14, 41, 42, 43, 45))) AND (reviewables.category_id IS NULL OR reviewables.category_id IN (1, 46, 120, 89, 12, 8, 80, 27, 128, 39, 20, 5, 121, 117, 6, 24, 18, 93, 94, 54, 31, 15, 83, 34, 81, 33, 22, 60, 57, 40, 119, 129, 63, 64, 38, 21, 106, 17, 122, 74, 77, 123, 127, 7, 9, 10, 11, 13, 14, 19, 23, 25, 26, 28, 29, 30, 32, 35, 37, 41, 42, 43, 44, 45, 48, 49, 50, 51, 52, 53, 55, 56, 58, 59, 61, 62, 65, 66, 67, 68, 69, 70, 71, 72, 73, 75, 76, 78, 79, 82, 84, 85, 86, 87, 88, 90, 91, 92, 95, 96, 97, 98, 99, 100, 101, 102, 103, 104, 107, 108, 109, 110, 111, 112, 113, 114, 115, 116, 118, 124, 125, 126, 127, 130)) AND (NOT EXISTS (
          SELECT 1
          FROM topics private_message
          WHERE private_message.id = reviewables.topic_id
            AND private_message.archetype = 'private_message'
            AND private_message.id NOT IN (SELECT "topics"."id" FROM "topics" WHERE ("topics"."archetype" = 'private_message' AND (topics.id IN (SELECT topic_id
        FROM topic_allowed_users
        WHERE user_id = 12345
        )
              OR topics.id IN (SELECT tg.topic_id
        FROM topic_allowed_groups tg
        JOIN group_users gu ON gu.user_id = 12345 AND gu.group_id = tg.group_id
        )) OR topics.subtype = 'moderator_warning'
        OR topics.id IN (SELECT "reviewables"."topic_id" FROM "reviewables" WHERE "reviewables"."type" = 'ReviewableFlaggedPost' AND "reviewables"."status" = 0 AND (score >= 0.0))
        ))
        )
        ) AND (NOT EXISTS (
          SELECT 1 FROM posts reviewable_target
          WHERE reviewables.target_type = 'Post'
            AND reviewable_target.id = reviewables.target_id
            AND NOT EXISTS (SELECT "posts"."id" FROM "posts" WHERE (posts.post_type IN (1, 2, 3, 4)) AND "posts"."topic_id" IN (SELECT "topics"."id" FROM "topics" LEFT OUTER JOIN "shared_drafts" ON "shared_drafts"."topic_id" = "topics"."id" WHERE "shared_drafts"."id" IS NULL AND ("topics"."archetype" != 'private_message' AND (topics.category_id IS NULL OR topics.category_id IN (SELECT id FROM categories WHERE NOT read_restricted OR id IN (7, 9, 10, 11, 13, 14, 19, 23, 25, 26, 28, 29, 30, 32, 35, 37, 41, 42, 43, 44, 45, 48, 49, 50, 51, 52, 53, 55, 56, 58, 59, 61, 62, 65, 66, 67, 68, 69, 70, 71, 72, 73, 75, 76, 78, 79, 82, 84, 85, 86, 87, 88, 90, 91, 92, 95, 96, 97, 98, 99, 100, 101, 102, 103, 104, 107, 108, 109, 110, 111, 112, 113, 114, 115, 116, 118, 124, 125, 126, 127, 130))) OR "topics"."archetype" = 'private_message' AND "topics"."archetype" = 'private_message' AND ((topics.id IN (SELECT topic_id
        FROM topic_allowed_users
        WHERE user_id = 12345
        )
              OR topics.id IN (SELECT tg.topic_id
        FROM topic_allowed_groups tg
        JOIN group_users gu ON gu.user_id = 12345 AND gu.group_id = tg.group_id
        )) OR topics.subtype = 'moderator_warning'
        OR topics.id IN (SELECT "reviewables"."topic_id" FROM "reviewables" WHERE "reviewables"."type" = 'ReviewableFlaggedPost' AND "reviewables"."status" = 0 AND (score >= 0.0))
        ))) AND (posts.id = reviewable_target.id))
        )
        ) AND "reviewables"."type" IN ('ReviewableFlaggedPost', 'ReviewableQueuedPost', 'ReviewableUser', 'ReviewablePost');

 count
-------
 15147
(1 row)

Time: 78545.972 ms (01:18.546)

将 user_id 更改为我自己的(管理员)似乎并没有使速度明显加快,而且我在 /review 上执行相同的操作完全正常,所以我假设代码路径并不相同。

当前使用的 Discourse 版本为:v2026.7.3 +24

在 /logs 里有什么可能相关的内容吗?信息这么少,要_诊断_起来有点困难 :face_with_monocle:

确实有,每次发生这种情况时都会有一条日志记录,但我担心它只是指向了 30 秒的超时设置:

日志:

Pitchfork worker is about to timeout, dumping backtrace for main thread /var/www/discourse/vendor/bundle/ruby/3.4.0/gems/rack-mini-profiler-4.0.1/lib/patches/db/pg/alias_method.rb:109:in 'PG::Connecti

信息:

Pitchfork worker is about to timeout, dumping backtrace for main thread
/var/www/discourse/vendor/bundle/ruby/3.4.0/gems/rack-mini-profiler-4.0.1/lib/patches/db/pg/alias_method.rb:109:in 'PG::Connection#exec'
/var/www/discourse/vendor/bundle/ruby/3.4.0/gems/rack-mini-profiler-4.0.1/lib/patches/db/pg/alias_method.rb:109:in 'PG::Connection#async_exec'
/var/www/discourse/vendor/bundle/ruby/3.4.0/gems/activerecord-8.0.5/lib/active_record/connection_adapters/postgresql/database_statements.rb:167:in 'ActiveRecord::ConnectionAdapters::PostgreSQL::DatabaseStatements#perform_query'
/var/www/discourse/vendor/bundle/ruby/3.4.0/gems/activerecord-8.0.5/lib/active_record/connection_adapters/abstract/database_statements.rb:556:in 'block (2 levels) in ActiveRecord::ConnectionAdapters::DatabaseStatements#raw_execute'
/var/www/discourse/vendor/bundle/ruby/3.4.0/gems/activerecord-8.0.5/lib/active_record/connection_adapters/abstract_adapter.rb:1022:in 'block in ActiveRecord::ConnectionAdapters::AbstractAdapter#with_raw_connection'
/var/www/discourse/vendor/bundle/ruby/3.4.0/gems/activesupport-8.0.5/lib/active_support/concurrency/null_lock.rb:9:in 'ActiveSupport::Concurrency::NullLock#synchronize'
/var/www/discourse/vendor/bundle/ruby/3.4.0/gems/activerecord-8.0.5/lib/active_record/connection_adapters/abstract_adapter.rb:991:in 'ActiveRecord::ConnectionAdapters::AbstractAdapter#with_raw_connection'
/var/www/discourse/vendor/bundle/ruby/3.4.0/gems/activerecord-8.0.5/lib/active_record/connection_adapters/abstract/database_statements.rb:555:in 'block in ActiveRecord::ConnectionAdapters::DatabaseStatements#raw_execute'
/var/www/discourse/vendor/bundle/ruby/3.4.0/gems/activesupport-8.0.5/lib/active_support/notifications/instrumenter.rb:58:in 'ActiveSupport::Notifications::Instrumenter#instrument'
/var/www/discourse/vendor/bundle/ruby/3.4.0/gems/activerecord-8.0.5/lib/active_record/connection_adapters/abstract_adapter.rb:1142:in 'ActiveRecord::ConnectionAdapters::AbstractAdapter#log'
/var/www...

回溯:

activesupport-8.0.5/lib/active_support/broadcast_logger.rb:218:in 'block in ActiveSupport::BroadcastLogger#dispatch' 
activesupport-8.0.5/lib/active_support/broadcast_logger.rb:217:in 'Array#map' 
activesupport-8.0.5/lib/active_support/broadcast_logger.rb:217:in 'ActiveSupport::BroadcastLogger#dispatch' 
activesupport-8.0.5/lib/active_support/broadcast_logger.rb:129:in 'ActiveSupport::BroadcastLogger#error' 
config/pitchfork.conf.rb:178:in 'block in Pitchfork::Configurator#load'
pitchfork-0.18.2/lib/pitchfork/http_server.rb:55:in 'Pitchfork::HttpServer::TimeoutHandler#call' 
pitchfork-0.18.2/lib/pitchfork/soft_timeout.rb:49:in 'block in Pitchfork::SoftTimeout::Request#interrupt' 
pitchfork-0.18.2/lib/pitchfork/soft_timeout.rb:46:in 'Thread::Mutex#synchronize' 
pitchfork-0.18.2/lib/pitchfork/soft_timeout.rb:46:in 'Pitchfork::SoftTimeout::Request#interrupt' 
pitchfork-0.18.2/lib/pitchfork/soft_timeout.rb:94:in 'block (2 levels) in Pitchfork::SoftTimeout#create_timeout_thread' 
pitchfork-0.18.2/lib/pitchfork/soft_timeout.rb:93:in 'Array#each' 
pitchfork-0.18.2/lib/pitchfork/soft_timeout.rb:93:in 'block in Pitchfork::SoftTimeout#create_timeout_thread' 

我还能提供其他什么信息吗?

也许这能有所帮助:

查询执行计划
 Aggregate  (cost=90612107.84..90612107.85 rows=1 width=8) (actual time=32929.952..32930.092 rows=1.00 loops=1)
   Output: count(*)
   Buffers: shared hit=10674180 read=4288620 dirtied=347 written=31039, temp read=7586 written=7593
   I/O Timings: shared read=14261.810 write=293.110, temp read=14.315 write=30.269
   ->  Hash Left Join  (cost=119766.87..90612106.13 rows=682 width=0) (actual time=32194.119..32929.031 rows=15150.00 loops=1)
         Hash Cond: (categories.id = category_moderation_groups.category_id)
         Filter: (reviewables.reviewable_by_moderator OR (category_moderation_groups.group_id = ANY ('{2,3,10,11,12,13,14,41,42,43,45}'::integer[])))
         Buffers: shared hit=10674180 read=4288620 dirtied=347 written=31039, temp read=7586 written=7593
         I/O Timings: shared read=14261.810 write=293.110, temp read=14.315 write=30.269
         ->  Hash Left Join  (cost=119765.73..90612102.02 rows=682 width=5) (actual time=32194.091..32926.732 rows=15150.00 loops=1)
               Output: reviewables.reviewable_by_moderator, categories.id
               Inner Unique: true
               Hash Cond: (reviewables.category_id = categories.id)
               Buffers: shared hit=10674179 read=4288620 dirtied=347 written=31039, temp read=7586 written=7593
               I/O Timings: shared read=14261.810 write=293.110, temp read=14.315 write=30.269
               ->  Nested Loop Anti Join  (cost=119754.18..90612088.62 rows=682 width=5) (actual time=32193.982..32923.913 rows=15150.00 loops=1)
                     Output: reviewables.reviewable_by_moderator, reviewables.category_id
                     Buffers: shared hit=10674144 read=4288620 dirtied=347 written=31039, temp read=7586 written=7593
                     I/O Timings: shared read=14261.810 write=293.110, temp read=14.315 write=30.269
                     ->  Hash Right Anti Join  (cost=118961.51..508536.27 rows=1245 width=9) (actual time=32193.966..32197.445 rows=15150.00 loops=1)
                           Output: reviewables.reviewable_by_moderator, reviewables.topic_id, reviewables.category_id
                           Hash Cond: (reviewable_target.id = reviewables.target_id)
                           Join Filter: ((reviewables.target_type)::text = 'Post'::text)
                           Buffers: shared hit=10620534 read=4187031 dirtied=346 written=30978, temp read=7586 written=7593
                           I/O Timings: shared read=14228.848 write=292.755, temp read=14.315 write=30.269
                           ->  Merge Anti Join  (cost=117907.10..455690.79 rows=10322451 width=4) (actual time=24275.150..30701.899 rows=5224880.00 loops=1)
                                 Output: reviewable_target.id
                                 Merge Cond: (reviewable_target.id = posts.id)
                                 Buffers: shared hit=10619973 read=4187031 dirtied=346 written=30978, temp read=7586 written=7593
                                 I/O Timings: shared read=14228.848 write=292.755, temp read=14.315 write=30.269
                                 ->  Index Only Scan using posts_pkey on public.posts reviewable_target  (cost=0.43..311977.87 rows=10322458 width=4) (actual time=0.015..3721.140 rows=10388505.00 loops=1)
                                       Output: reviewable_target.id
                                       Heap Fetches: 586809
                                       Index Searches: 1
                                       Buffers: shared hit=9845158 read=105882 dirtied=81 written=2154
                                       I/O Timings: shared read=366.948 write=18.531
                                 ->  Sort  (cost=117906.67..117906.68 rows=7 width=4) (actual time=24273.538..24994.595 rows=5163625.00 loops=1)
                                       Output: posts.id
                                       Sort Key: posts.id
                                       Sort Method: external merge  Disk: 60688kB
                                       Buffers: shared hit=774815 read=4081149 dirtied=265 written=28824, temp read=7586 written=7593
                                       I/O Timings: shared read=13861.900 write=274.223, temp read=14.315 write=30.269
                                       ->  Nested Loop  (cost=117845.50..117906.57 rows=7 width=4) (actual time=1068.513..23253.874 rows=5163625.00 loops=1)
                                             Output: posts.id
                                             Buffers: shared hit=774815 read=4081149 dirtied=265 written=28824
                                             I/O Timings: shared read=13861.900 write=274.223
                                             ->  HashAggregate  (cost=117845.06..117845.07 rows=1 width=4) (actual time=1068.458..1116.707 rows=91574.00 loops=1)
                                                   Output: topics.id
                                                   Group Key: topics.id
                                                   Batches: 1  Memory Usage: 5169kB
                                                   Buffers: shared hit=18776 read=79072 dirtied=3
                                                   I/O Timings: shared read=43.128
                                                   ->  Gather  (cost=1818.73..117845.06 rows=1 width=4) (actual time=81.869..1025.742 rows=91574.00 loops=1)
                                                         Output: topics.id
                                                         Workers Planned: 2
                                                         Workers Launched: 2
                                                         Buffers: shared hit=18776 read=79072 dirtied=3
                                                         I/O Timings: shared read=43.128
                                                         ->  Hash Left Join  (cost=818.73..116844.96 rows=1 width=4) (actual time=558.090..1017.927 rows=30524.67 loops=3)
                                                               Output: topics.id
                                                               Inner Unique: true
                                                               Hash Cond: (topics.id = shared_drafts.topic_id)
                                                               Filter: (shared_drafts.id IS NULL)
                                                               Buffers: shared hit=18776 read=79072 dirtied=3
                                                               I/O Timings: shared read=43.128
                                                               Worker 0:  actual time=765.561..1012.978 rows=11078.00 loops=1
                                                                 JIT:
                                                                   Functions: 114
                                                                   Options: Inlining true, Optimization true, Expressions true, Deforming true
                                                                   Timing: Generation 15.225 ms (Deform 3.129 ms), Inlining 135.900 ms, Optimization 287.768 ms, Emission 329.808 ms, Total 768.701 ms
                                                                 Buffers: shared hit=2035 read=15493
                                                                 I/O Timings: shared read=7.217
                                                               Worker 1:  actual time=827.352..1029.012 rows=8561.00 loops=1
                                                                 JIT:
                                                                   Functions: 114
                                                                   Options: Inlining true, Optimization true, Expressions true, Deforming true
                                                                   Timing: Generation 6.162 ms (Deform 2.466 ms), Inlining 166.737 ms, Optimization 318.974 ms, Emission 330.326 ms, Total 822.199 ms
                                                                 Buffers: shared hit=1561 read=11593
                                                                 I/O Timings: shared read=9.948
                                                               ->  Parallel Seq Scan on public.topics  (cost=817.55..115599.40 rows=474050 width=4) (actual time=558.040..1011.488 rows=30524.67 loops=3)
                                                                     Output: topics.id, topics.title, topics.last_posted_at, topics.created_at, topics.updated_at, topics.views, topics.posts_count, topics.user_id, topics.last_post_user_id, topics.reply_count, topics.featured_user1_id, topics.featured_user2_id, topics.featured_user3_id, topics.deleted_at, topics.highest_post_number, topics.like_count, topics.incoming_link_count, topics.category_id, topics.visible, topics.moderator_posts_count, topics.closed, topics.archived, topics.bumped_at, topics.has_summary, topics.archetype, topics.featured_user4_id, topics.notify_moderators_count, topics.spam_count, topics.pinned_at, topics.score, topics.percent_rank, topics.subtype, topics.slug, topics.deleted_by_id, topics.participant_count, topics.word_count, topics.excerpt, topics.pinned_globally, topics.pinned_until, topics.fancy_title, topics.highest_staff_post_number, topics.featured_link, topics.reviewable_score, topics.image_upload_id, topics.slow_mode_seconds, topics.bannered_until, topics.external_id, topics.visibility_reason_id, topics.locale, topics.og_image_upload_id
                                                                     Filter: ((((topics.archetype)::text <> 'private_message'::text) AND ((topics.category_id IS NULL) OR (ANY (topics.category_id = (hashed SubPlan 5).col1)))) OR (((topics.archetype)::text = 'private_message'::text) AND ((topics.archetype)::text = 'private_message'::text) AND ((ANY (topics.id = (hashed SubPlan 6).col1)) OR (ANY (topics.id = (hashed SubPlan 7).col1)) OR ((topics.subtype)::text = 'moderator_warning'::text) OR (ANY (topics.id = (hashed SubPlan 8).col1)))))
                                                                     Rows Removed by Filter: 449563
                                                                     Buffers: shared hit=18773 read=79072 dirtied=3
                                                                     I/O Timings: shared read=43.128
                                                                     Worker 0:  actual time=765.502..1010.751 rows=11078.00 loops=1
                                                                       Buffers: shared hit=2034 read=15493
                                                                       I/O Timings: shared read=7.217
                                                                     Worker 1:  actual time=827.293..1026.236 rows=8561.00 loops=1
                                                                       Buffers: shared hit=1560 read=11593
                                                                       I/O Timings: shared read=9.948
                                                                     SubPlan 5
                                                                       ->  Seq Scan on public.categories categories_1  (cost=0.20..25.06 rows=96 width=4) (actual time=12.092..12.202 rows=123.00 loops=3)
                                                                             Output: categories_1.id
                                                                             Filter: ((NOT categories_1.read_restricted) OR (categories_1.id = ANY ('{7,9,10,11,13,14,19,23,25,26,28,29,30,32,35,37,41,42,43,44,45,48,49,50,51,52,53,55,56,58,59,61,62,65,66,67,68,69,70,71,72,73,75,76,78,79,82,84,85,86,87,88,90,91,92,95,96,97,98,99,100,101,102,103,104,107,108,109,110,111,112,113,114,115,116,118,124,125,126,127,130}'::integer[])))
                                                                             Rows Removed by Filter: 1
                                                                             Buffers: shared hit=69
                                                                             Worker 0:  actual time=16.097..16.230 rows=123.00 loops=1
                                                                               Buffers: shared hit=23
                                                                             Worker 1:  actual time=11.074..11.204 rows=123.00 loops=1
                                                                               Buffers: shared hit=23
                                                                     SubPlan 6
                                                                       ->  Index Only Scan using index_topic_allowed_users_on_user_id_and_topic_id on public.topic_allowed_users topic_allowed_users_1  (cost=0.43..641.51 rows=4328 width=4) (actual time=13.820..15.031 rows=3503.00 loops=3)
                                                                             Output: topic_allowed_users_1.topic_id
                                                                             Index Cond: (topic_allowed_users_1.user_id = 18)
                                                                             Heap Fetches: 879
                                                                             Index Searches: 3
                                                                             Buffers: shared hit=536 read=213
                                                                             I/O Timings: shared read=0.608
                                                                             Worker 0:  actual time=16.351..17.337 rows=3503.00 loops=1
                                                                               Buffers: shared hit=249 read=1
                                                                               I/O Timings: shared read=0.038
                                                                             Worker 1:  actual time=15.636..16.995 rows=3503.00 loops=1
                                                                               Buffers: shared hit=250
                                                                     SubPlan 7
                                                                       ->  Nested Loop  (cost=0.71..128.02 rows=1 width=4) (actual time=17.997..22.239 rows=7742.00 loops=3)
                                                                             Output: tg_1.topic_id
                                                                             Buffers: shared hit=167 read=23
                                                                             I/O Timings: shared read=0.169
                                                                             Worker 0:  actual time=22.450..26.266 rows=7742.00 loops=1
                                                                               Buffers: shared hit=62 read=2
                                                                               I/O Timings: shared read=0.075
                                                                             Worker 1:  actual time=22.307..24.222 rows=7742.00 loops=1
                                                                               Buffers: shared hit=64
                                                                             ->  Index Only Scan using index_group_users_on_user_id_and_group_id on public.group_users gu_1  (cost=0.42..12.23 rows=2 width=4) (actual time=0.076..0.105 rows=11.00 loops=3)
                                                                                   Output: gu_1.user_id, gu_1.group_id
                                                                                   Index Cond: (gu_1.user_id = 18)
                                                                                   Heap Fetches: 33
                                                                                   Index Searches: 3
                                                                                   Buffers: shared hit=46 read=1
                                                                                   I/O Timings: shared read=0.037
                                                                                   Worker 0:  actual time=0.111..0.152 rows=11.00 loops=1
                                                                                     Buffers: shared hit=15 read=1
                                                                                     I/O Timings: shared read=0.037
                                                                                   Worker 1:  actual time=0.101..0.132 rows=11.00 loops=1
                                                                                     Buffers: shared hit=16
                                                                             ->  Index Only Scan using index_topic_allowed_groups_on_group_id_and_topic_id on public.topic_allowed_groups tg_1  (cost=0.29..44.66 rows=1324 width=8) (actual time=0.008..0.126 rows=703.82 loops=33)
                                                                                   Output: tg_1.group_id, tg_1.topic_id
                                                                                   Index Cond: (tg_1.group_id = gu_1.group_id)
                                                                                   Heap Fetches: 1074
                                                                                   Index Searches: 33
                                                                                   Buffers: shared hit=121 read=22
                                                                                   I/O Timings: shared read=0.132
                                                                                   Worker 0:  actual time=0.010..0.194 rows=703.82 loops=11
                                                                                     Buffers: shared hit=47 read=1
                                                                                     I/O Timings: shared read=0.038
                                                                                   Worker 1:  actual time=0.009..0.093 rows=703.82 loops=11
                                                                                     Buffers: shared hit=48
                                                                     SubPlan 8
                                                                       ->  Index Scan using index_reviewables_on_status_and_type on public.reviewables reviewables_2  (cost=0.29..11.89 rows=2 width=4) (actual time=21.244..21.266 rows=5.00 loops=3)
                                                                             Output: reviewables_2.topic_id
                                                                             Index Cond: ((reviewables_2.status = 0) AND ((reviewables_2.type)::text = 'ReviewableFlaggedPost'::text))
                                                                             Filter: (reviewables_2.score >= '0'::double precision)
                                                                             Index Searches: 3
                                                                             Buffers: shared hit=16 read=1
                                                                             I/O Timings: shared read=0.032
                                                                             Worker 0:  actual time=28.239..28.266 rows=5.00 loops=1
                                                                               Buffers: shared hit=5 read=1
                                                                               I/O Timings: shared read=0.032
                                                                             Worker 1:  actual time=19.319..19.348 rows=5.00 loops=1
                                                                               Buffers: shared hit=6
                                                               ->  Hash  (cost=1.08..1.08 rows=8 width=12) (actual time=0.039..0.040 rows=8.00 loops=3)
                                                                     Output: shared_drafts.id, shared_drafts.topic_id
                                                                     Buckets: 1024  Batches: 1  Memory Usage: 9kB
                                                                     Buffers: shared hit=3
                                                                     Worker 0:  actual time=0.048..0.049 rows=8.00 loops=1
                                                                       Buffers: shared hit=1
                                                                     Worker 1:  actual time=0.048..0.049 rows=8.00 loops=1
                                                                       Buffers: shared hit=1
                                                                     ->  Seq Scan on public.shared_drafts  (cost=0.00..1.08 rows=8 width=12) (actual time=0.032..0.033 rows=8.00 loops=3)
                                                                           Output: shared_drafts.id, shared_drafts.topic_id
                                                                           Buffers: shared hit=3
                                                                           Worker 0:  actual time=0.041..0.042 rows=8.00 loops=1
                                                                             Buffers: shared hit=1
                                                                           Worker 1:  actual time=0.041..0.042 rows=8.00 loops=1
                                                                             Buffers: shared hit=1
                                             ->  Index Scan using index_posts_on_topic_id_and_reply_to_post_number on public.posts  (cost=0.43..59.66 rows=184 width=8) (actual time=0.016..0.235 rows=56.39 loops=91574)
                                                   Output: posts.id, posts.user_id, posts.topic_id, posts.post_number, posts.raw, posts.cooked, posts.created_at, posts.updated_at, posts.reply_to_post_number, posts.reply_count, posts.quote_count, posts.deleted_at, posts.off_topic_count, posts.like_count, posts.incoming_link_count, posts.bookmark_count, posts.score, posts.reads, posts.post_type, posts.sort_order, posts.last_editor_id, posts.hidden, posts.hidden_reason_id, posts.notify_moderators_count, posts.spam_count, posts.illegal_count, posts.inappropriate_count, posts.last_version_at, posts.user_deleted, posts.reply_to_user_id, posts.percent_rank, posts.notify_user_count, posts.like_score, posts.deleted_by_id, posts.edit_reason, posts.word_count, posts.version, posts.cook_method, posts.wiki, posts.baked_at, posts.baked_version, posts.hidden_at, posts.self_edits, posts.reply_quoted, posts.via_email, posts.raw_email, posts.public_version, posts.action_code, posts.locked_by_id, posts.image_upload_id, posts.outbound_message_id, posts.qa_vote_count, posts.locale
                                                   Index Cond: (posts.topic_id = topics.id)
                                                   Filter: (posts.post_type = ANY ('{1,2,3,4}'::integer[]))
                                                   Index Searches: 91574
                                                   Buffers: shared hit=756039 read=4002077 dirtied=262 written=28824
                                                   I/O Timings: shared read=13818.772 write=274.223
                           ->  Hash  (cost=867.63..867.63 rows=14942 width=18) (actual time=640.985..640.985 rows=15614.00 loops=1)
                                 Output: reviewables.reviewable_by_moderator, reviewables.topic_id, reviewables.target_type, reviewables.target_id, reviewables.category_id
                                 Buckets: 16384  Batches: 1  Memory Usage: 971kB
                                 Buffers: shared hit=561
                                 ->  Seq Scan on public.reviewables  (cost=0.31..867.63 rows=14942 width=18) (actual time=635.502..638.644 rows=15614.00 loops=1)
                                       Output: reviewables.reviewable_by_moderator, reviewables.topic_id, reviewables.target_type, reviewables.target_id, reviewables.category_id
                                       Filter: (((reviewables.category_id IS NULL) OR (reviewables.category_id = ANY ('{1,46,120,89,12,8,80,27,128,39,20,5,121,117,6,24,18,93,94,54,31,15,83,34,81,33,22,60,57,40,119,129,63,64,38,21,106,17,122,74,77,123,127,7,9,10,11,13,14,19,23,25,26,28,29,30,32,35,37,41,42,43,44,45,48,49,50,51,52,53,55,56,58,59,61,62,65,66,67,68,69,70,71,72,73,75,76,78,79,82,84,85,86,87,88,90,91,92,95,96,97,98,99,100,101,102,103,104,107,108,109,110,111,112,113,114,115,116,118,124,125,126,127,130}'::integer[]))) AND ((reviewables.type)::text = ANY ('{ReviewableFlaggedPost,ReviewableQueuedPost,ReviewableUser,ReviewablePost}'::text[])))
                                       Rows Removed by Filter: 1
                                       Buffers: shared hit=561
                     ->  Index Scan using topics_pkey on public.topics private_message  (cost=792.67..72372.33 rows=1 width=4) (actual time=0.048..0.048 rows=0.00 loops=15150)
                           Output: private_message.id, private_message.title, private_message.last_posted_at, private_message.created_at, private_message.updated_at, private_message.views, private_message.posts_count, private_message.user_id, private_message.last_post_user_id, private_message.reply_count, private_message.featured_user1_id, private_message.featured_user2_id, private_message.featured_user3_id, private_message.deleted_at, private_message.highest_post_number, private_message.like_count, private_message.incoming_link_count, private_message.category_id, private_message.visible, private_message.moderator_posts_count, private_message.closed, private_message.archived, private_message.bumped_at, private_message.has_summary, private_message.archetype, private_message.featured_user4_id, private_message.notify_moderators_count, private_message.spam_count, private_message.pinned_at, private_message.score, private_message.percent_rank, private_message.subtype, private_message.slug, private_message.deleted_by_id, private_message.participant_count, private_message.word_count, private_message.excerpt, private_message.pinned_globally, private_message.pinned_until, private_message.fancy_title, private_message.highest_staff_post_number, private_message.featured_link, private_message.reviewable_score, private_message.image_upload_id, private_message.slow_mode_seconds, private_message.bannered_until, private_message.external_id, private_message.visibility_reason_id, private_message.locale, private_message.og_image_upload_id
                           Index Cond: (private_message.id = reviewables.topic_id)
                           Filter: (((private_message.archetype)::text = 'private_message'::text) AND (NOT (ANY (private_message.id = (SubPlan 4).col1))))
                           Rows Removed by Filter: 1
                           Index Searches: 14513
                           Buffers: shared hit=53610 read=101589 dirtied=1 written=61
                           I/O Timings: shared read=32.962 write=0.356
                           SubPlan 4
                             ->  Materialize  (cost=792.25..140873.63 rows=1227210 width=4) (actual time=3.967..49.455 rows=2668.00 loops=13)
                                   Output: topics_1.id
                                   Storage: Memory  Maximum Storage: 470kB
                                   Buffers: shared hit=4306 read=92830 written=38
                                   I/O Timings: shared read=8.159 write=0.227
                                   ->  Seq Scan on public.topics topics_1  (cost=792.25..129943.58 rows=1227210 width=4) (actual time=51.560..638.925 rows=10931.00 loops=1)
                                         Output: topics_1.id
                                         Filter: ((((topics_1.archetype)::text = 'private_message'::text) AND ((ANY (topics_1.id = (hashed SubPlan 1).col1)) OR (ANY (topics_1.id = (hashed SubPlan 2).col1)))) OR ((topics_1.subtype)::text = 'moderator_warning'::text) OR (ANY (topics_1.id = (hashed SubPlan 3).col1)))
                                         Rows Removed by Filter: 1428444
                                         Buffers: shared hit=4306 read=92830 written=38
                                         I/O Timings: shared read=8.159 write=0.227
                                         SubPlan 1
                                           ->  Index Only Scan using index_topic_allowed_users_on_user_id_and_topic_id on public.topic_allowed_users  (cost=0.43..641.51 rows=4328 width=4) (actual time=9.643..11.475 rows=3503.00 loops=1)
                                                 Output: topic_allowed_users.topic_id
                                                 Index Cond: (topic_allowed_users.user_id = 18)
                                                 Heap Fetches: 293
                                                 Index Searches: 1
                                                 Buffers: shared hit=54 read=195 written=38
                                                 I/O Timings: shared read=0.564 write=0.227
                                         SubPlan 2
                                           ->  Nested Loop  (cost=0.71..128.02 rows=1 width=4) (actual time=9.318..11.005 rows=7742.00 loops=1)
                                                 Output: tg.topic_id
                                                 Buffers: shared hit=31 read=31
                                                 I/O Timings: shared read=0.111
                                                 ->  Index Only Scan using index_group_users_on_user_id_and_group_id on public.group_users gu  (cost=0.42..12.23 rows=2 width=4) (actual time=0.025..0.079 rows=11.00 loops=1)
                                                       Output: gu.user_id, gu.group_id
                                                       Index Cond: (gu.user_id = 18)
                                                       Heap Fetches: 11
                                                       Index Searches: 1
                                                       Buffers: shared hit=7 read=8
                                                       I/O Timings: shared read=0.032
                                                 ->  Index Only Scan using index_topic_allowed_groups_on_group_id_and_topic_id on public.topic_allowed_groups tg  (cost=0.29..44.66 rows=1324 width=8) (actual time=0.005..0.088 rows=703.82 loops=11)
                                                       Output: tg.group_id, tg.topic_id
                                                       Index Cond: (tg.group_id = gu.group_id)
                                                       Heap Fetches: 358
                                                       Index Searches: 11
                                                       Buffers: shared hit=24 read=23
                                                       I/O Timings: shared read=0.079
                                         SubPlan 3
                                           ->  Index Scan using index_reviewables_on_status_and_type on public.reviewables reviewables_1  (cost=0.29..11.89 rows=2 width=4) (actual time=9.076..9.092 rows=5.00 loops=1)
                                                 Output: reviewables_1.topic_id
                                                 Index Cond: ((reviewables_1.status = 0) AND ((reviewables_1.type)::text = 'ReviewableFlaggedPost'::text))
                                                 Filter: (reviewables_1.score >= '0'::double precision)
                                                 Index Searches: 1
                                                 Buffers: shared hit=5
               ->  Hash  (cost=10.00..10.00 rows=124 width=4) (actual time=0.078..0.078 rows=124.00 loops=1)
                     Output: categories.id
                     Buckets: 1024  Batches: 1  Memory Usage: 13kB
                     Buffers: shared hit=35
                     ->  Index Only Scan using categories_pkey on public.categories  (cost=0.14..10.00 rows=124 width=4) (actual time=0.014..0.057 rows=124.00 loops=1)
                           Output: categories.id
                           Heap Fetches: 36
                           Index Searches: 1
                           Buffers: shared hit=35
         ->  Hash  (cost=1.05..1.05 rows=5 width=8) (actual time=0.018..0.019 rows=5.00 loops=1)
               Output: category_moderation_groups.group_id, category_moderation_groups.category_id
               Buckets: 1024  Batches: 1  Memory Usage: 9kB
               Buffers: shared hit=1
               ->  Seq Scan on public.category_moderation_groups  (cost=0.00..1.05 rows=5 width=8) (actual time=0.013..0.014 rows=5.00 loops=1)
                     Output: category_moderation_groups.group_id, category_moderation_groups.category_id
                     Buffers: shared hit=1
 Planning:
   Buffers: shared hit=119
 Planning Time: 4.134 ms
 JIT:
   Functions: 406
   Options: Inlining true, Optimization true, Expressions true, Deforming true
   Timing: Generation 28.778 ms (Deform 8.210 ms), Inlining 331.978 ms, Optimization 1017.108 ms, Emission 969.572 ms, Total 2347.436 ms
 Execution Time: 32947.799 ms
(270 rows)

该执行计划显示 PostgreSQL 正在处理数百万条帖子以进行可见性检查,且估算行数与实际行数存在巨大差异(估算 7 行,实际 516 万行)。

我将查询语句和执行计划提供给 LLM,看它能否帮助识别瓶颈。它建议进行一处小改动,通过在 Reviewable.viewable_by 中使用 OFFSET 0,使得对单个可审查帖子进行索引查找,而不是扫描数百万条帖子:

result.where(<<~SQL)
  NOT EXISTS (
    SELECT 1 FROM posts reviewable_target
    WHERE reviewables.target_type = 'Post'
      AND reviewable_target.id = reviewables.target_id
      AND NOT EXISTS (#{visible_target.to_sql})
+   OFFSET 0
  )
SQL

我直接测试了修改后的查询(尚未修改 Discourse 代码),执行时间从 32.95 秒降至 1.64 秒,返回的可审查项目数量完全相同,均为 15,150 个。

我对 PostgreSQL 不太熟悉,但据我理解,OFFSET 0 是 PostgreSQL 规划器的一种变通方法,因此这可能不是正确的永久解决方案,但也许有助于定位问题所在。

我找到了一种优化查询的方法,无需使用 OFFSET 0 技巧

2 个赞

太好了,感谢您这么快就处理了!您觉得这个修复可以回移到 v2026.7 版本吗?

已完成 :white_check_mark:

https://github.com/discourse/discourse/pull/44523

2 个赞

谢谢!很高兴确认这个问题已经解决了。:+1:

1 个赞