#77 Very sloooooow database performance

[nyj3c]

Loading pages is very slow, it can take more than 30 seconds, it's very bad for user behavior.
This information from postgresql.log with log_min_duration_statement.

Duration: 2101.420 milliseconds: SELECT p.post_id, topic_id, forum_id, p.user_id, post_time, poster_ip, enable_bbcode, p.attach, enable_html, enable_smilies, enable_sig, post_edit_time, post_edit_count, status, pt.post_subject, pt.post_text, username, p.need_moderate, u.user_viewonline FROM jforum_posts p, jforum_posts_text pt, jforum_users u WHERE p.post_id = pt.post_id AND topic_id = $1 AND p.user_id = u.user_id AND p.need_moderate = 0 ORDER BY post_time ASC OFFSET $2 LIMIT $3

jforum=> EXPLAIN SELECT p.post_id, topic_id, forum_id, p.user_id, post_time, poster_ip, enable_bbcode, p.attach, enable_html, enable_smilies, enable_sig, post_edit_time, post_edit_count, status, pt.post_subject, pt.post_text, username, p.need_moderate, u.user_viewonline FROM jforum_posts p, jforum_posts_text pt, jforum_users u WHERE p.post_id = pt.post_id AND topic_id = 18719 AND p.user_id = u.user_id AND p.need_moderate = 0 ORDER BY post_time ASC OFFSET 18040 LIMIT 20;
-[ RECORD 1 ]----------------------------------------------------------------------------------------------------------------
QUERY PLAN | Limit  (cost=105610.64..105610.64 rows=1 width=633)
-[ RECORD 2 ]----------------------------------------------------------------------------------------------------------------
QUERY PLAN |   ->  Sort  (cost=105572.43..105610.64 rows=15285 width=633)
-[ RECORD 3 ]----------------------------------------------------------------------------------------------------------------
QUERY PLAN |         Sort Key: p.post_time
-[ RECORD 4 ]----------------------------------------------------------------------------------------------------------------
QUERY PLAN |         ->  Hash Join  (cost=14278.87..100173.63 rows=15285 width=633)
-[ RECORD 5 ]----------------------------------------------------------------------------------------------------------------
QUERY PLAN |               Hash Cond: (p.user_id = u.user_id)
-[ RECORD 6 ]----------------------------------------------------------------------------------------------------------------
QUERY PLAN |               ->  Hash Join  (cost=13487.28..99076.34 rows=15285 width=619)
-[ RECORD 7 ]----------------------------------------------------------------------------------------------------------------
QUERY PLAN |                     Hash Cond: (pt.post_id = p.post_id)
-[ RECORD 8 ]----------------------------------------------------------------------------------------------------------------
QUERY PLAN |                     ->  Seq Scan on jforum_posts_text pt  (cost=0.00..76023.87 rows=752987 width=547)
-[ RECORD 9 ]----------------------------------------------------------------------------------------------------------------
QUERY PLAN |                     ->  Hash  (cost=13271.80..13271.80 rows=17238 width=76)
-[ RECORD 10 ]---------------------------------------------------------------------------------------------------------------
QUERY PLAN |                           ->  Bitmap Heap Scan on jforum_posts p  (cost=574.02..13271.80 rows=17238 width=76)
-[ RECORD 11 ]---------------------------------------------------------------------------------------------------------------
QUERY PLAN |                                 Recheck Cond: (topic_id = 18719)
-[ RECORD 12 ]---------------------------------------------------------------------------------------------------------------
QUERY PLAN |                                 Filter: (need_moderate = 0)
-[ RECORD 13 ]---------------------------------------------------------------------------------------------------------------
QUERY PLAN |                                 ->  Bitmap Index Scan on idx_posts_topic  (cost=0.00..569.71 rows=17238 width=0)
-[ RECORD 14 ]---------------------------------------------------------------------------------------------------------------
QUERY PLAN |                                       Index Cond: (topic_id = 18719)
-[ RECORD 15 ]---------------------------------------------------------------------------------------------------------------
QUERY PLAN |               ->  Hash  (cost=636.82..636.82 rows=12382 width=18)
-[ RECORD 16 ]---------------------------------------------------------------------------------------------------------------
QUERY PLAN |                     ->  Seq Scan on jforum_users u  (cost=0.00..636.82 rows=12382 width=18)

Indexes and query rewriting can significantly speed up:
CREATE INDEX idx_posts_text ON jforum_posts_text(post_id);

jforum=> EXPLAIN SELECT p.post_id, topic_id, forum_id, p.user_id, post_time, poster_ip, enable_bbcode, p.attach, enable_html, enable_smilies, enable_sig, post_edit_time, post_edit_count, status, pt.post_subject, pt.post_text, username, p.need_moderate, u.user_viewonline FROM jforum_posts p, jforum_posts_text pt, jforum_users u WHERE p.post_id = pt.post_id AND topic_id = 18719 AND p.user_id = u.user_id AND p.need_moderate = 0 ORDER BY post_time ASC OFFSET 18040 LIMIT 20;
-[ RECORD 1 ]-------------------------------------------------------------------------------------------------------------------
QUERY PLAN | Limit  (cost=98976.52..98976.52 rows=1 width=633)
-[ RECORD 2 ]-------------------------------------------------------------------------------------------------------------------
QUERY PLAN |   ->  Sort  (cost=98933.43..98976.52 rows=17238 width=633)
-[ RECORD 3 ]-------------------------------------------------------------------------------------------------------------------
QUERY PLAN |         Sort Key: p.post_time
-[ RECORD 4 ]-------------------------------------------------------------------------------------------------------------------
QUERY PLAN |         ->  Hash Join  (cost=1366.04..92827.45 rows=17238 width=633)
-[ RECORD 5 ]-------------------------------------------------------------------------------------------------------------------
QUERY PLAN |               Hash Cond: (p.user_id = u.user_id)
-[ RECORD 6 ]-------------------------------------------------------------------------------------------------------------------
QUERY PLAN |               ->  Nested Loop  (cost=574.44..91691.09 rows=17238 width=619)
-[ RECORD 7 ]-------------------------------------------------------------------------------------------------------------------
QUERY PLAN |                     ->  Bitmap Heap Scan on jforum_posts p  (cost=574.02..13271.80 rows=17238 width=76)
-[ RECORD 8 ]-------------------------------------------------------------------------------------------------------------------
QUERY PLAN |                           Recheck Cond: (topic_id = 18719)
-[ RECORD 9 ]-------------------------------------------------------------------------------------------------------------------
QUERY PLAN |                           Filter: (need_moderate = 0)
-[ RECORD 10 ]------------------------------------------------------------------------------------------------------------------
QUERY PLAN |                           ->  Bitmap Index Scan on idx_posts_topic  (cost=0.00..569.71 rows=17238 width=0)
-[ RECORD 11 ]------------------------------------------------------------------------------------------------------------------
QUERY PLAN |                                 Index Cond: (topic_id = 18719)
-[ RECORD 12 ]------------------------------------------------------------------------------------------------------------------
QUERY PLAN |                     ->  Index Scan using idx_posts_text on jforum_posts_text pt  (cost=0.42..4.54 rows=1 width=547)
-[ RECORD 13 ]------------------------------------------------------------------------------------------------------------------
QUERY PLAN |                           Index Cond: (post_id = p.post_id)
-[ RECORD 14 ]------------------------------------------------------------------------------------------------------------------
QUERY PLAN |               ->  Hash  (cost=636.82..636.82 rows=12382 width=18)
-[ RECORD 15 ]------------------------------------------------------------------------------------------------------------------
QUERY PLAN |                     ->  Seq Scan on jforum_users u  (cost=0.00..636.82 rows=12382 width=18)

Duration: 7404.819 milliseconds: SELECT p.post_id, topic_id, forum_id, p.user_id, post_time, poster_ip, enable_bbcode, p.attach, enable_html, enable_smilies, enable_sig, post_edit_time, post_edit_count, status, pt.post_subject, pt.post_text, username, p.need_moderate, u.user_viewonline FROM jforum_posts p, jforum_posts_text pt, jforum_users u WHERE p.post_id = pt.post_id AND topic_id = $1 AND p.user_id = u.user_id AND p.need_moderate = 0 ORDER BY post_time ASC OFFSET $2 LIMIT $3

jforum=> EXPLAIN SELECT p.post_id, topic_id, forum_id, p.user_id, post_time, poster_ip, enable_bbcode, p.attach, enable_html, enable_smilies, enable_sig, post_edit_time, post_edit_count, status, pt.post_subject, pt.post_text, username, p.need_moderate, u.user_viewonline FROM jforum_posts p, jforum_posts_text pt, jforum_users u WHERE p.post_id = pt.post_id AND topic_id = 19123 AND p.user_id = u.user_id AND p.need_moderate = 0 ORDER BY post_time ASC OFFSET 22000 LIMIT 20;
-[ RECORD 1 ]----------------------------------------------------------------------------------------------------------------
QUERY PLAN | Limit  (cost=106808.61..106808.61 rows=1 width=633)
-[ RECORD 2 ]----------------------------------------------------------------------------------------------------------------
QUERY PLAN |   ->  Sort  (cost=106753.69..106808.61 rows=21965 width=633)
-[ RECORD 3 ]----------------------------------------------------------------------------------------------------------------
QUERY PLAN |         Sort Key: p.post_time
-[ RECORD 4 ]----------------------------------------------------------------------------------------------------------------
QUERY PLAN |         ->  Hash Join  (cost=13861.10..98936.20 rows=21965 width=633)
-[ RECORD 5 ]----------------------------------------------------------------------------------------------------------------
QUERY PLAN |               Hash Cond: (p.user_id = u.user_id)
-[ RECORD 6 ]----------------------------------------------------------------------------------------------------------------
QUERY PLAN |               ->  Hash Join  (cost=13069.51..97705.30 rows=21965 width=619)
-[ RECORD 7 ]----------------------------------------------------------------------------------------------------------------
QUERY PLAN |                     Hash Cond: (pt.post_id = p.post_id)
-[ RECORD 8 ]----------------------------------------------------------------------------------------------------------------
QUERY PLAN |                     ->  Seq Scan on jforum_posts_text pt  (cost=0.00..76985.81 rows=849181 width=547)
-[ RECORD 9 ]----------------------------------------------------------------------------------------------------------------
QUERY PLAN |                     ->  Hash  (cost=12794.95..12794.95 rows=21965 width=76)
-[ RECORD 10 ]---------------------------------------------------------------------------------------------------------------
QUERY PLAN |                           ->  Bitmap Heap Scan on jforum_posts p  (cost=414.65..12794.95 rows=21965 width=76)
-[ RECORD 11 ]---------------------------------------------------------------------------------------------------------------
QUERY PLAN |                                 Recheck Cond: (topic_id = 19123)
-[ RECORD 12 ]---------------------------------------------------------------------------------------------------------------
QUERY PLAN |                                 Filter: (need_moderate = 0)
-[ RECORD 13 ]---------------------------------------------------------------------------------------------------------------
QUERY PLAN |                                 ->  Bitmap Index Scan on idx_posts_topic  (cost=0.00..409.16 rows=21965 width=0)
-[ RECORD 14 ]---------------------------------------------------------------------------------------------------------------
QUERY PLAN |                                       Index Cond: (topic_id = 19123)
-[ RECORD 15 ]---------------------------------------------------------------------------------------------------------------
QUERY PLAN |               ->  Hash  (cost=636.82..636.82 rows=12382 width=18)
-[ RECORD 16 ]---------------------------------------------------------------------------------------------------------------
QUERY PLAN |                     ->  Seq Scan on jforum_users u  (cost=0.00..636.82 rows=12382 width=18)

Duration: 29986.836 milliseconds: SELECT t.*, p.user_id AS last_user_id, p.post_time, p.post_edit_time, (SELECT SUM(p.attach) FROM jforum_posts p WHERE p.topic_id = t.topic_id AND p.need_moderate = 0) AS attach FROM jforum_topics t, jforum_posts p WHERE (t.forum_id = $1 OR t.topic_moved_id = $2) AND p.post_id = t.topic_last_post_id AND p.need_moderate = 0 ORDER BY t.topic_type DESC, (CASE WHEN t.topic_type=3 AND p.post_edit_time IS NOT NULL THEN p.post_edit_time ELSE p.post_time END) DESC OFFSET $3 LIMIT $4

jforum=> EXPLAIN SELECT t.*, p.user_id AS last_user_id, p.post_time, p.post_edit_time, (SELECT SUM(p.attach) FROM jforum_posts p WHERE p.topic_id = t.topic_id AND p.need_moderate = 0) AS attach FROM jforum_topics t, jforum_posts p WHERE (t.forum_id = 1 OR t.topic_moved_id = 1) AND p.post_id = t.topic_last_post_id AND p.need_moderate = 0 ORDER BY t.topic_type DESC, (CASE WHEN t.topic_type=3 AND p.post_edit_time IS NOT NULL THEN p.post_edit_time ELSE p.post_time END) DESC OFFSET 0 LIMIT 50;
-[ RECORD 1 ]----------------------------------------------------------------------------------------------------------------------------------------------
QUERY PLAN | Limit  (cost=2639300.61..2639300.73 rows=50 width=135)
-[ RECORD 2 ]----------------------------------------------------------------------------------------------------------------------------------------------
QUERY PLAN |   ->  Sort  (cost=2639300.61..2639317.83 rows=6889 width=135)
-[ RECORD 3 ]----------------------------------------------------------------------------------------------------------------------------------------------
QUERY PLAN |         Sort Key: t.topic_type, (CASE WHEN ((t.topic_type = 3) AND (p.post_edit_time IS NOT NULL)) THEN p.post_edit_time ELSE p.post_time END)
-[ RECORD 4 ]----------------------------------------------------------------------------------------------------------------------------------------------
QUERY PLAN |         ->  Nested Loop  (cost=0.42..2639071.76 rows=6889 width=135)
-[ RECORD 5 ]----------------------------------------------------------------------------------------------------------------------------------------------
QUERY PLAN |               ->  Seq Scan on jforum_topics t  (cost=0.00..880.75 rows=6889 width=115)
-[ RECORD 6 ]----------------------------------------------------------------------------------------------------------------------------------------------
QUERY PLAN |                     Filter: ((forum_id = 1) OR (topic_moved_id = 1))
-[ RECORD 7 ]----------------------------------------------------------------------------------------------------------------------------------------------
QUERY PLAN |               ->  Index Scan using idx_posts_idx on jforum_posts p  (cost=0.42..4.90 rows=1 width=24)
-[ RECORD 8 ]----------------------------------------------------------------------------------------------------------------------------------------------
QUERY PLAN |                     Index Cond: (post_id = t.topic_last_post_id)
-[ RECORD 9 ]----------------------------------------------------------------------------------------------------------------------------------------------
QUERY PLAN |                     Filter: (need_moderate = 0)
-[ RECORD 10 ]---------------------------------------------------------------------------------------------------------------------------------------------
QUERY PLAN |               SubPlan 1
-[ RECORD 11 ]---------------------------------------------------------------------------------------------------------------------------------------------
QUERY PLAN |                 ->  Aggregate  (cost=378.03..378.04 rows=1 width=4)
-[ RECORD 12 ]---------------------------------------------------------------------------------------------------------------------------------------------
QUERY PLAN |                       ->  Index Scan using idx_posts_topic on jforum_posts p_1  (cost=0.42..377.75 rows=113 width=4)
-[ RECORD 13 ]---------------------------------------------------------------------------------------------------------------------------------------------
QUERY PLAN |                             Index Cond: (topic_id = t.topic_id)
-[ RECORD 14 ]---------------------------------------------------------------------------------------------------------------------------------------------
QUERY PLAN |                             Filter: (need_moderate = 0)

[Ulf Dittmer]

Thanks for the analysis, and sorry for being slow to get back to you. I'm not clear on the connection between the proposed index you mentioned (CREATE INDEX idx_posts_text ON jforum_posts_text(post_id)) and the various slow queries: are all those improved by that new index? Or just the first one?

[nyj3c]

Just the first one. The last two queries do not use the index but use a sequential scan.

[nyj3c]

The new index idx_posts_text ON jforum_posts_text(post_id) did not give any increase in perfomance

Duration: 10923.789 milliseconds: SELECT p.post_id, topic_id, forum_id, p.user_id, post_time, poster_ip, enable_bbcode, p.attach, enable_html, enable_smilies, enable_sig, post_edit_time, post_edit_count, status, pt.post_subject, pt.post_text, username, p.need_moderate, u.user_viewonline FROM jforum_posts p, jforum_posts_text pt, jforum_users u WHERE p.post_id = pt.post_id AND topic_id = $1 AND p.user_id = u.user_id AND p.need_moderate = 0 ORDER BY post_time ASC OFFSET $2 LIMIT $3

EXPLAIN ANALYZE SELECT p.post_id, topic_id, forum_id, p.user_id, post_time, poster_ip, enable_bbcode, p.attach, enable_html, enable_smilies, enable_sig, post_edit_time, post_edit_count, status, pt.post_subject, pt.post_text, username, p.need_moderate, u.user_viewonline FROM jforum_posts p, jforum_posts_text pt, jforum_users u WHERE p.post_id = pt.post_id AND topic_id = 19923 AND p.user_id = u.user_id AND p.need_moderate = 0 ORDER BY post_time ASC OFFSET 21400 LIMIT 20;

                                                                        QUERY PLAN                                                                         
-----------------------------------------------------------------------------------------------------------------------------------------------------------
 Limit  (cost=2888942.89..2888943.02 rows=50 width=139) (actual time=32993.151..32993.173 rows=50 loops=1)
   ->  Sort  (cost=2888942.89..2888960.10 rows=6883 width=139) (actual time=32993.148..32993.153 rows=50 loops=1)
         Sort Key: t.topic_type, (CASE WHEN ((t.topic_type = 3) AND (p.post_edit_time IS NOT NULL)) THEN p.post_edit_time ELSE p.post_time END)
         Sort Method: top-N heapsort  Memory: 38kB
         ->  Nested Loop  (cost=140.07..2888714.25 rows=6883 width=139) (actual time=292.663..32956.099 rows=6883 loops=1)
               ->  Bitmap Heap Scan on jforum_topics t  (cost=139.65..758.89 rows=6883 width=119) (actual time=29.563..46.481 rows=6883 loops=1)
                     Recheck Cond: ((forum_id = 1) OR (topic_moved_id = 1))
                     Heap Blocks: exact=415
                     ->  BitmapOr  (cost=139.65..139.65 rows=6883 width=0) (actual time=29.386..29.386 rows=0 loops=1)
                           ->  Bitmap Index Scan on idx_topics_forum  (cost=0.00..131.91 rows=6883 width=0) (actual time=17.728..17.728 rows=6885 loops=1)
                                 Index Cond: (forum_id = 1)
                           ->  Bitmap Index Scan on idx_topics_moved  (cost=0.00..4.29 rows=1 width=0) (actual time=11.653..11.653 rows=0 loops=1)
                                 Index Cond: (topic_moved_id = 1)
               ->  Index Scan using jforum_posts_pkey on jforum_posts p  (cost=0.42..4.87 rows=1 width=24) (actual time=1.384..1.389 rows=1 loops=6883)
                     Index Cond: (post_id = t.topic_last_post_id)
                     Filter: (need_moderate = 0)
               SubPlan 1
                 ->  Aggregate  (cost=414.68..414.69 rows=1 width=4) (actual time=3.385..3.385 rows=1 loops=6883)
                       ->  Bitmap Heap Scan on jforum_posts p_1  (cost=5.28..414.41 rows=110 width=4) (actual time=0.291..3.366 rows=52 loops=6883)
                             Recheck Cond: (topic_id = t.topic_id)
                             Filter: (need_moderate = 0)
                             Heap Blocks: exact=81760
                             ->  Bitmap Index Scan on idx_posts_topic  (cost=0.00..5.25 rows=110 width=0) (actual time=0.211..0.211 rows=52 loops=6883)
                                   Index Cond: (topic_id = t.topic_id)
 Planning time: 263.312 ms
 Execution time: 33016.868 ms

Duration: 18211.708 milliseconds: SELECT t.*, p.user_id AS last_user_id, p.post_time, p.post_edit_time, (SELECT SUM(p.attach) FROM jforum_posts p WHERE p.topic_id = t.topic_id AND p.need_moderate = 0) AS attach FROM jforum_topics t, jforum_posts p WHERE (t.forum_id = $1 OR t.topic_moved_id = $2) AND p.post_id = t.topic_last_post_id AND p.need_moderate = 0 ORDER BY t.topic_type DESC, (CASE WHEN t.topic_type=3 AND p.post_edit_time IS NOT NULL THEN p.post_edit_time ELSE p.post_time END) DESC OFFSET $3 LIMIT $4

EXPLAIN ANALYZE SELECT t.*, p.user_id AS last_user_id, p.post_time, p.post_edit_time, (SELECT SUM(p.attach) FROM jforum_posts p WHERE p.topic_id = t.topic_id AND p.need_moderate = 0) AS attach FROM jforum_topics t, jforum_posts p WHERE (t.forum_id = 1 OR t.topic_moved_id = 1) AND p.post_id = t.topic_last_post_id AND p.need_moderate = 0 ORDER BY t.topic_type DESC, (CASE WHEN t.topic_type=3 AND p.post_edit_time IS NOT NULL THEN p.post_edit_time ELSE p.post_time END) DESC OFFSET 0 LIMIT 50;

                                                                        QUERY PLAN                                                                         
-----------------------------------------------------------------------------------------------------------------------------------------------------------
 Limit  (cost=2888942.89..2888943.02 rows=50 width=139) (actual time=32993.151..32993.173 rows=50 loops=1)
   ->  Sort  (cost=2888942.89..2888960.10 rows=6883 width=139) (actual time=32993.148..32993.153 rows=50 loops=1)
         Sort Key: t.topic_type, (CASE WHEN ((t.topic_type = 3) AND (p.post_edit_time IS NOT NULL)) THEN p.post_edit_time ELSE p.post_time END)
         Sort Method: top-N heapsort  Memory: 38kB
         ->  Nested Loop  (cost=140.07..2888714.25 rows=6883 width=139) (actual time=292.663..32956.099 rows=6883 loops=1)
               ->  Bitmap Heap Scan on jforum_topics t  (cost=139.65..758.89 rows=6883 width=119) (actual time=29.563..46.481 rows=6883 loops=1)
                     Recheck Cond: ((forum_id = 1) OR (topic_moved_id = 1))
                     Heap Blocks: exact=415
                     ->  BitmapOr  (cost=139.65..139.65 rows=6883 width=0) (actual time=29.386..29.386 rows=0 loops=1)
                           ->  Bitmap Index Scan on idx_topics_forum  (cost=0.00..131.91 rows=6883 width=0) (actual time=17.728..17.728 rows=6885 loops=1)
                                 Index Cond: (forum_id = 1)
                           ->  Bitmap Index Scan on idx_topics_moved  (cost=0.00..4.29 rows=1 width=0) (actual time=11.653..11.653 rows=0 loops=1)
                                 Index Cond: (topic_moved_id = 1)
               ->  Index Scan using jforum_posts_pkey on jforum_posts p  (cost=0.42..4.87 rows=1 width=24) (actual time=1.384..1.389 rows=1 loops=6883)
                     Index Cond: (post_id = t.topic_last_post_id)
                     Filter: (need_moderate = 0)
               SubPlan 1
                 ->  Aggregate  (cost=414.68..414.69 rows=1 width=4) (actual time=3.385..3.385 rows=1 loops=6883)
                       ->  Bitmap Heap Scan on jforum_posts p_1  (cost=5.28..414.41 rows=110 width=4) (actual time=0.291..3.366 rows=52 loops=6883)
                             Recheck Cond: (topic_id = t.topic_id)
                             Filter: (need_moderate = 0)
                             Heap Blocks: exact=81760
                             ->  Bitmap Index Scan on idx_posts_topic  (cost=0.00..5.25 rows=110 width=0) (actual time=0.211..0.211 rows=52 loops=6883)
                                   Index Cond: (topic_id = t.topic_id)
 Planning time: 263.312 ms
 Execution time: 33016.868 ms

[nyj3c]

First query plan

                                                                              QUERY PLAN                                                                              
----------------------------------------------------------------------------------------------------------------------------------------------------------------------
 Limit  (cost=105455.50..105455.50 rows=1 width=617) (actual time=9152.530..9152.536 rows=20 loops=1)
   ->  Sort  (cost=105407.00..105455.50 rows=19401 width=617) (actual time=9143.897..9151.119 rows=21420 loops=1)
         Sort Key: p.post_time
         Sort Method: external merge  Disk: 11624kB
         ->  Hash Join  (cost=1297.93..98652.78 rows=19401 width=617) (actual time=86.649..9028.104 rows=21436 loops=1)
               Hash Cond: (p.user_id = u.user_id)
               ->  Nested Loop  (cost=367.21..97334.03 rows=19401 width=603) (actual time=43.302..8933.654 rows=21456 loops=1)
                     ->  Bitmap Heap Scan on jforum_posts p  (cost=366.78..12346.58 rows=19401 width=74) (actual time=4.338..884.153 rows=21456 loops=1)
                           Recheck Cond: (topic_id = 19923)
                           Filter: (need_moderate = 0)
                           Heap Blocks: exact=4441
                           ->  Bitmap Index Scan on idx_posts_topic  (cost=0.00..361.93 rows=19401 width=0) (actual time=3.144..3.144 rows=21456 loops=1)
                                 Index Cond: (topic_id = 19923)
                     ->  Index Scan using idx_posts_text on jforum_posts_text pt  (cost=0.42..4.37 rows=1 width=533) (actual time=0.371..0.373 rows=1 loops=21456)
                           Index Cond: (post_id = p.post_id)
               ->  Hash  (cost=776.54..776.54 rows=12335 width=18) (actual time=43.290..43.290 rows=12335 loops=1)
                     Buckets: 2048  Batches: 1  Memory Usage: 631kB
                     ->  Index Scan using jforum_users_pkey on jforum_users u  (cost=0.29..776.54 rows=12335 width=18) (actual time=0.026..38.715 rows=12335 loops=1)
 Planning time: 64.986 ms
 Execution time: 9154.669 ms

[Ulf Dittmer]

OK, I'll remove it. Should have tested it more than I did.

[nyj3c]

Perfomance problem in nested loops. I tried to rewrite the queries by adding subquery. Perhaps this is not the best solution, but it does not require changing one line of Java code. In PostModel.selectAllByTopicByLimit perfomance has increased approximately 8 times on the cold cache datebase right after start.

In PostModel.selectByUserByLimit perfomance has increased approximately 13 times. As for this query, jforum_topics struct have not information about topic last changing, order by topic_last_post_id not good solution.

And maybe PostModel.selectByUserByLimit and TopicModel.selectByUserByLimit need additional perfomance testing.

EXPLAIN ANALYZE SELECT p.post_id, topic_id, forum_id, p.user_id, post_time, poster_ip, enable_bbcode, p.attach, enable_html, enable_smilies, enable_sig, post_edit_time, post_edit_count, status, pt.post_subject, pt.post_text, username, p.need_moderate, u.user_viewonline FROM jforum_posts p, jforum_posts_text pt, jforum_users u WHERE p.post_id = pt.post_id AND topic_id = 19923 AND p.user_id = u.user_id AND p.need_moderate = 0 ORDER BY post_time ASC OFFSET 21400 LIMIT 20;

                                                                              QUERY PLAN                                                                              
----------------------------------------------------------------------------------------------------------------------------------------------------------------------
 Limit  (cost=105455.50..105455.50 rows=1 width=617) (actual time=9152.530..9152.536 rows=20 loops=1)
   ->  Sort  (cost=105407.00..105455.50 rows=19401 width=617) (actual time=9143.897..9151.119 rows=21420 loops=1)
         Sort Key: p.post_time
         Sort Method: external merge  Disk: 11624kB
         ->  Hash Join  (cost=1297.93..98652.78 rows=19401 width=617) (actual time=86.649..9028.104 rows=21436 loops=1)
               Hash Cond: (p.user_id = u.user_id)
               ->  Nested Loop  (cost=367.21..97334.03 rows=19401 width=603) (actual time=43.302..8933.654 rows=21456 loops=1)
                     ->  Bitmap Heap Scan on jforum_posts p  (cost=366.78..12346.58 rows=19401 width=74) (actual time=4.338..884.153 rows=21456 loops=1)
                           Recheck Cond: (topic_id = 19923)
                           Filter: (need_moderate = 0)
                           Heap Blocks: exact=4441
                           ->  Bitmap Index Scan on idx_posts_topic  (cost=0.00..361.93 rows=19401 width=0) (actual time=3.144..3.144 rows=21456 loops=1)
                                 Index Cond: (topic_id = 19923)
                     ->  Index Scan using idx_posts_text on jforum_posts_text pt  (cost=0.42..4.37 rows=1 width=533) (actual time=0.371..0.373 rows=1 loops=21456)
                           Index Cond: (post_id = p.post_id)
               ->  Hash  (cost=776.54..776.54 rows=12335 width=18) (actual time=43.290..43.290 rows=12335 loops=1)
                     Buckets: 2048  Batches: 1  Memory Usage: 631kB
                     ->  Index Scan using jforum_users_pkey on jforum_users u  (cost=0.29..776.54 rows=12335 width=18) (actual time=0.026..38.715 rows=12335 loops=1)
 Planning time: 64.986 ms
 Execution time: 9154.669 ms
 ~~~

EXPLAIN ANALYZE SELECT p.post_id, topic_id, forum_id, p.user_id, post_time, poster_ip, enable_bbcode, p.attach, enable_html, enable_smilies, enable_sig, post_edit_time, post_edit_count, status, pt.post_subject, pt.post_text, username, p.need_moderate, u.user_viewonline FROM jforum_posts p, jforum_posts_text pt, jforum_users u WHERE p.post_id IN (SELECT p.post_id FROM jforum_posts p WHERE p.topic_id = 19923 AND p.need_moderate = 0 OFFSET 21400 LIMIT 20) AND pt.post_id = p.post_id AND u.user_id = p.user_id ORDER BY post_time ASC;

 ~~~
                                                                               QUERY PLAN                                                                               
------------------------------------------------------------------------------------------------------------------------------------------------------------------------
 Sort  (cost=12355.90..12355.91 rows=1 width=617) (actual time=455.507..455.511 rows=20 loops=1)
   Sort Key: p.post_time
   Sort Method: quicksort  Memory: 38kB
   ->  Nested Loop  (cost=12347.72..12355.89 rows=1 width=617) (actual time=399.759..455.345 rows=20 loops=1)
         ->  Nested Loop  (cost=12347.44..12355.57 rows=1 width=603) (actual time=370.258..389.568 rows=20 loops=1)
               ->  Nested Loop  (cost=12347.01..12355.05 rows=1 width=537) (actual time=343.786..361.017 rows=20 loops=1)
                     ->  HashAggregate  (cost=12346.59..12346.60 rows=1 width=4) (actual time=306.746..306.784 rows=20 loops=1)
                           Group Key: p_1.post_id
                           ->  Limit  (cost=12346.58..12346.58 rows=1 width=4) (actual time=306.684..306.731 rows=20 loops=1)
                                 ->  Bitmap Heap Scan on jforum_posts p_1  (cost=366.78..12346.58 rows=19401 width=4) (actual time=81.642..305.136 rows=21420 loops=1)
                                       Recheck Cond: (topic_id = 19923)
                                       Filter: (need_moderate = 0)
                                       Heap Blocks: exact=4426
                                       ->  Bitmap Index Scan on idx_posts_topic  (cost=0.00..361.93 rows=19401 width=0) (actual time=62.259..62.259 rows=21456 loops=1)
                                             Index Cond: (topic_id = 19923)
                     ->  Index Scan using idx_posts_text on jforum_posts_text pt  (cost=0.42..8.45 rows=1 width=533) (actual time=2.704..2.705 rows=1 loops=20)
                           Index Cond: (post_id = p_1.post_id)
               ->  Index Scan using idx_posts_id2 on jforum_posts p  (cost=0.42..0.51 rows=1 width=74) (actual time=1.418..1.420 rows=1 loops=20)
                     Index Cond: (post_id = pt.post_id)
         ->  Index Scan using jforum_users_pkey on jforum_users u  (cost=0.29..0.31 rows=1 width=18) (actual time=3.278..3.281 rows=1 loops=20)
               Index Cond: (user_id = p.user_id)
 Planning time: 718.713 ms
 Execution time: 455.949 ms

 ~~~


EXPLAIN ANALYZE SELECT t.*, p.user_id AS last_user_id, p.post_time, p.post_edit_time, (SELECT SUM(p.attach) FROM jforum_posts p WHERE p.topic_id = t.topic_id AND p.need_moderate = 0) AS attach FROM jforum_topics t, jforum_posts p WHERE (t.forum_id = 1 OR t.topic_moved_id = 1) AND p.post_id = t.topic_last_post_id AND p.need_moderate = 0 ORDER BY t.topic_type DESC, (CASE WHEN t.topic_type=3 AND p.post_edit_time IS NOT NULL THEN p.post_edit_time ELSE p.post_time END) DESC OFFSET 0 LIMIT 50;

                                                                    QUERY PLAN

---

Limit (cost=2888942.89..2888943.02 rows=50 width=139) (actual time=32993.151..32993.173 rows=50 loops=1)
-> Sort (cost=2888942.89..2888960.10 rows=6883 width=139) (actual time=32993.148..32993.153 rows=50 loops=1)
Sort Key: t.topic_type, (CASE WHEN ((t.topic_type = 3) AND (p.post_edit_time IS NOT NULL)) THEN p.post_edit_time ELSE p.post_time END)
Sort Method: top-N heapsort Memory: 38kB
-> Nested Loop (cost=140.07..2888714.25 rows=6883 width=139) (actual time=292.663..32956.099 rows=6883 loops=1)
-> Bitmap Heap Scan on jforum_topics t (cost=139.65..758.89 rows=6883 width=119) (actual time=29.563..46.481 rows=6883 loops=1)
Recheck Cond: ((forum_id = 1) OR (topic_moved_id = 1))
Heap Blocks: exact=415
-> BitmapOr (cost=139.65..139.65 rows=6883 width=0) (actual time=29.386..29.386 rows=0 loops=1)
-> Bitmap Index Scan on idx_topics_forum (cost=0.00..131.91 rows=6883 width=0) (actual time=17.728..17.728 rows=6885 loops=1)
Index Cond: (forum_id = 1)
-> Bitmap Index Scan on idx_topics_moved (cost=0.00..4.29 rows=1 width=0) (actual time=11.653..11.653 rows=0 loops=1)
Index Cond: (topic_moved_id = 1)
-> Index Scan using jforum_posts_pkey on jforum_posts p (cost=0.42..4.87 rows=1 width=24) (actual time=1.384..1.389 rows=1 loops=6883)
Index Cond: (post_id = t.topic_last_post_id)
Filter: (need_moderate = 0)
SubPlan 1
-> Aggregate (cost=414.68..414.69 rows=1 width=4) (actual time=3.385..3.385 rows=1 loops=6883)
-> Bitmap Heap Scan on jforum_posts p_1 (cost=5.28..414.41 rows=110 width=4) (actual time=0.291..3.366 rows=52 loops=6883)
Recheck Cond: (topic_id = t.topic_id)
Filter: (need_moderate = 0)
Heap Blocks: exact=81760
-> Bitmap Index Scan on idx_posts_topic (cost=0.00..5.25 rows=110 width=0) (actual time=0.211..0.211 rows=52 loops=6883)
Index Cond: (topic_id = t.topic_id)
Planning time: 263.312 ms
Execution time: 33016.868 ms

~~~

EXPLAIN ANALYZE SELECT t.*, p.user_id AS last_user_id, p.post_time, p.post_edit_time, (SELECT SUM(p.attach) FROM jforum_posts p WHERE p.topic_id = t.topic_id AND p.need_moderate = 0) AS attach FROM jforum_topics t, jforum_posts p WHERE p.post_id IN (SELECT t.topic_last_post_id FROM jforum_topics t WHERE (t.forum_id = 1 OR t.topic_moved_id = 1) ORDER BY t.topic_last_post_id DESC OFFSET 0 LIMIT 50) AND p.post_id = t.topic_last_post_id AND p.need_moderate = 0 ORDER BY t.topic_type DESC, (CASE WHEN t.topic_type=0 AND p.post_edit_time IS NOT NULL THEN p.post_edit_time ELSE p.post_time END) DESC;

                                                                                    QUERY PLAN                                                                                    
----------------------------------------------------------------------------------------------------------------------------------------------------------------------------------
 Sort  (cost=1282.54..1282.54 rows=2 width=139) (actual time=2230.107..2230.115 rows=50 loops=1)
   Sort Key: t.topic_type, (CASE WHEN ((t.topic_type = 0) AND (p.post_edit_time IS NOT NULL)) THEN p.post_edit_time ELSE p.post_time END)
   Sort Method: quicksort  Memory: 38kB
   ->  Nested Loop  (cost=14.46..1282.53 rows=2 width=139) (actual time=391.619..2229.758 rows=50 loops=1)
         ->  Nested Loop  (cost=14.17..437.12 rows=50 width=28) (actual time=134.234..239.391 rows=50 loops=1)
               ->  HashAggregate  (cost=13.75..14.25 rows=50 width=4) (actual time=134.181..134.241 rows=50 loops=1)
                     Group Key: t_1.topic_last_post_id
                     ->  Limit  (cost=0.29..13.12 rows=50 width=4) (actual time=21.591..133.978 rows=50 loops=1)
                           ->  Index Scan Backward using idx_topics_lp on jforum_topics t_1  (cost=0.29..1770.36 rows=6896 width=4) (actual time=21.589..133.918 rows=50 loops=1)
                                 Filter: ((forum_id = 1) OR (topic_moved_id = 1))
                                 Rows Removed by Filter: 62
               ->  Index Scan using idx_posts_id2 on jforum_posts p  (cost=0.42..8.45 rows=1 width=24) (actual time=2.098..2.099 rows=1 loops=50)
                     Index Cond: (post_id = t_1.topic_last_post_id)
                     Filter: (need_moderate = 0)
         ->  Index Scan using idx_topics_lp on jforum_topics t  (cost=0.29..0.31 rows=1 width=119) (actual time=0.006..0.009 rows=1 loops=50)
               Index Cond: (topic_last_post_id = p.post_id)
         SubPlan 1
           ->  Aggregate  (cost=414.68..414.69 rows=1 width=4) (actual time=39.788..39.788 rows=1 loops=50)
                 ->  Bitmap Heap Scan on jforum_posts p_1  (cost=5.28..414.41 rows=110 width=4) (actual time=9.663..39.199 rows=3208 loops=50)
                       Recheck Cond: (topic_id = t.topic_id)
                       Filter: (need_moderate = 0)
                       Heap Blocks: exact=27933
                       ->  Bitmap Index Scan on idx_posts_topic  (cost=0.00..5.25 rows=110 width=0) (actual time=9.487..9.487 rows=3208 loops=50)
                             Index Cond: (topic_id = t.topic_id)
 Planning time: 192.812 ms
 Execution time: 2230.545 ms

--- src/main/config/database/postgresql/postgresql.sql
+++ src/main/config/database/postgresql/postgresqlnew.sql
@@ -39,12 +39,10 @@
 PostModel.selectAllByTopicByLimit = SELECT p.post_id, topic_id, forum_id, p.user_id, post_time, poster_ip, enable_bbcode, p.attach, \
    enable_html, enable_smilies, enable_sig, post_edit_time, post_edit_count, status, pt.post_subject, pt.post_text, username, p.need_moderate, u.user_viewonline \
    FROM jforum_posts p, jforum_posts_text pt, jforum_users u \
-   WHERE p.post_id = pt.post_id \
-   AND topic_id = ? \
-   AND p.user_id = u.user_id \
-   AND p.need_moderate = 0 \
-   ORDER BY post_time ASC \
-   OFFSET ? LIMIT ?
+   WHERE p.post_id IN (SELECT p.post_id FROM jforum_posts p WHERE p.topic_id = ? AND p.need_moderate = 0 \
+   ORDER BY post_time ASC OFFSET ? LIMIT ?) \
+   AND pt.post_id = p.post_id AND u.user_id = p.user_id \
+   ORDER BY post_time ASC

 PostModel.selectByUserByLimit = SELECT p.post_id, topic_id, forum_id, p.user_id, post_time, poster_ip, enable_bbcode, p.attach, \
    enable_html, enable_smilies, enable_sig, post_edit_time, post_edit_count, status, pt.post_subject, pt.post_text, username, p.need_moderate, u.user_viewonline \
@@ -86,11 +84,11 @@
    WHERE p.topic_id = t.topic_id \
    AND p.need_moderate = 0) AS attach \
         FROM jforum_topics t, jforum_posts p \
-        WHERE (t.forum_id = ? OR t.topic_moved_id = ?) \
-   AND p.post_id = t.topic_last_post_id \
-   AND p.need_moderate = 0 \
-   ORDER BY t.topic_type DESC, (CASE WHEN t.topic_type=3 AND p.post_edit_time IS NOT NULL THEN p.post_edit_time ELSE p.post_time END) DESC \
-   OFFSET ? LIMIT ?
+        WHERE p.post_id IN (SELECT t.topic_last_post_id FROM jforum_topics t WHERE (t.forum_id = ? OR t.topic_moved_id = ?) \
+        ORDER BY t.topic_last_post_id DESC OFFSET ? LIMIT ?) \
+   AND p.post_id = t.topic_last_post_id \
+   AND p.need_moderate = 0 \
+   ORDER BY t.topic_type DESC, (CASE WHEN t.topic_type=3 AND p.post_edit_time IS NOT NULL THEN p.post_edit_time ELSE p.post_time END) DESC

 TopicModel.selectByUserByLimit = SELECT t.*, p.user_id AS last_user_id, p.post_time, p.post_edit_time, (SELECT SUM(p.attach) \
         FROM jforum_posts p \

PostModel.selectAllByTopicByLimit = SELECT p.post_id, topic_id, forum_id, p.user_id, post_time, poster_ip, enable_bbcode, p.attach, \
        enable_html, enable_smilies, enable_sig, post_edit_time, post_edit_count, status, pt.post_subject, pt.post_text, username, p.need_moderate, u.user_vi$
        FROM jforum_posts p, jforum_posts_text pt, jforum_users u \
        WHERE p.post_id IN (SELECT p.post_id FROM jforum_posts p WHERE p.topic_id = ? AND p.need_moderate = 0 \
        ORDER BY post_time ASC OFFSET ? LIMIT ?) \
        AND pt.post_id = p.post_id AND u.user_id = p.user_id \
        ORDER BY post_time ASC

TopicModel.selectAllByForumByLimit = SELECT t.*, p.user_id AS last_user_id, p.post_time, p.post_edit_time, (SELECT SUM(p.attach) \
        FROM jforum_posts p \
        WHERE p.topic_id = t.topic_id \
        AND p.need_moderate = 0) AS attach \
        FROM jforum_topics t, jforum_posts p \
        WHERE p.post_id IN (SELECT t.topic_last_post_id FROM jforum_topics t WHERE (t.forum_id = ? OR t.topic_moved_id = ?) \
        ORDER BY t.topic_last_post_id DESC OFFSET ? LIMIT ?) \
        AND p.post_id = t.topic_last_post_id \
        AND p.need_moderate = 0 \
        ORDER BY t.topic_type DESC, (CASE WHEN t.topic_type=3 AND p.post_edit_time IS NOT NULL THEN p.post_edit_time ELSE p.post_time END) DESC

[Ulf Dittmer]

Thanks, that's good stuff. I'll take this up when I next dabble with JForum. That's going to be some time, but it'll make it into the next release.

[Ulf Dittmer]

I've applied the patch to PostModel.selectAllByTopicByLimit and TopicModel.selectAllByForumByLimit, and a similiar one to PostModel.selectByUserByLimit, both for the generic SQL and the Postgres-specific SQL. Let me know if they do the job for you (while EXPLAIN indicates it works, my test DB is too small to see it in action).

[Jeff Steele]

Just FYI, these changes are not supported by MySQL and prevent the topics from being viewed. I opened a separate ticket before I found this one.

[Ulf Dittmer]

Thanks for reporting that. I've undone the changes for DBs other than Postgres. Unreleased changes do not always get the amount of testing that a release version would :-/

[nyj3c]

Thanks, PostModel.selectAllByTopicByLimit and TopicModel.selectAllByForumByLimit work good. But TopicModel.selectRecentTopicsByLimit and TopicModel.selectHottestTopicsByLimit requests need additional optimization. And for net.jforum.dao.PostDAO#selectAllByTopic use LIMIT Integer.MAX_VALUE - 1 is a bad idea, on big topics query execution time 2 minutes.

--- src/main/config/database/postgresql/postgresql.sql
+++ src/main/config/database/postgresql/postgresqlnew.sql
@@ -87,6 +87,26 @@
     AND p.need_moderate = 0 \
     ORDER BY t.topic_type DESC, (CASE WHEN t.topic_type=3 AND p.post_edit_time IS NOT NULL THEN p.post_edit_time ELSE p.post_time END) DESC

+TopicModel.selectRecentTopicsByLimit = SELECT t.*, p.user_id AS last_user_id, p.post_time, p.post_edit_time, \
+        (SELECT SUM(p.attach) \
+        FROM jforum_posts p \
+        WHERE p.topic_id = t.topic_id \
+        AND p.need_moderate = 0) AS attach \
+    FROM jforum_topics t, jforum_posts p \
+        WHERE p.post_id IN (SELECT t.topic_last_post_id FROM jforum_topics t ORDER BY t.topic_last_post_id DESC LIMIT ?) \
+    AND p.post_id = t.topic_last_post_id \
+    AND p.need_moderate = 0 \
+    ORDER BY CASE WHEN t.topic_type=3 AND p.post_edit_time IS NOT NULL THEN p.post_edit_time ELSE p.post_time END DESC
+
+TopicModel.selectHottestTopicsByLimit = SELECT t.*, p.user_id AS last_user_id, p.post_time, p.post_edit_time, (SELECT SUM(p.attach) \
+        FROM jforum_posts p \
+        WHERE p.topic_id = t.topic_id \
+        AND p.need_moderate = 0) AS attach \
+    FROM jforum_topics t, jforum_posts p \
+        WHERE p.post_id IN (SELECT topic_last_post_id FROM jforum_topics ORDER BY topic_views DESC LIMIT ?) \
+    AND p.post_id = t.topic_last_post_id \
+    AND p.need_moderate = 0
+
 TopicModel.selectByUserByLimit = SELECT t.*, p.user_id AS last_user_id, p.post_time, p.post_edit_time, (SELECT SUM(p.attach) \
         FROM jforum_posts p \
         WHERE p.topic_id = t.topic_id \

--- src/main/java/net/jforum/dao/generic/GenericPostDAO.java
+++ src/main/java/net/jforum/dao/generic/GenericPostDAOnew.java

@@ -351,15 +351,15 @@
    /**
     * @see net.jforum.dao.PostDAO#selectAllByTopic(int)
     */
    @Override public List<Post> selectAllByTopic(int topicId)
    {
-       return this.selectAllByTopicByLimit(topicId, 0, Integer.MAX_VALUE - 1);
+       return this.selectAllByTopicByLimit(topicId, 0, 100);
    }

[Ulf Dittmer]

I added the optimized PostgreSQL queries.

As to not using Integer.MAX_VALUE, I went a different route that uses SQL without the LIMIT - it should have the same effect. Hardcoding limits on how many posts per topic there can be, or how many topics per forum causes peroblem that would require substantial workarounds.

[nyj3c]

These changes in src/main/java/net/jforum/dao/generic/GenericTopicDAO.java cause NullPointerException

line 116-117
src/main/java/net/jforum/repository/PostRepository.java
PostDAO pm = DataAccessDriver.getInstance().newPostDAO();
posts = pm.selectAllByTopic(topicId);

if set 100 like in my patch this.selectAllByForumByLimit(forumId, 0, 100) forum work quick without freezes, but posts.cache need be disable, otherwise the posts bigger 100 are not loaded; topic.cache.enabled = true and posts.cache.enabled = false

ERROR [ExceptionWriter] - net.jforum.exceptions.ForumException: java.lang.reflect.InvocationTargetException
        at sun.reflect.NativeMethodAccessorImpl.invoke0(Native Method)
        at sun.reflect.NativeMethodAccessorImpl.invoke(NativeMethodAccessorImpl.java:62)
        at sun.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:43)
        at java.lang.reflect.Method.invoke(Method.java:498)
        at net.jforum.Command.process(Command.java:117)
        at net.jforum.JForum.processCommand(JForum.java:258)
        at net.jforum.JForum.service(JForum.java:240)
        at javax.servlet.http.HttpServlet.service(HttpServlet.java:742)
        at org.apache.catalina.core.ApplicationFilterChain.internalDoFilter(ApplicationFilterChain.java:231)
        at org.apache.catalina.core.ApplicationFilterChain.doFilter(ApplicationFilterChain.java:166)
        at org.apache.tomcat.websocket.server.WsFilter.doFilter(WsFilter.java:52)
        at org.apache.catalina.core.ApplicationFilterChain.internalDoFilter(ApplicationFilterChain.java:193)
        at org.apache.catalina.core.ApplicationFilterChain.doFilter(ApplicationFilterChain.java:166)
        at net.jforum.csrf.CsrfFilter.doFilter(CsrfFilter.java:100)
        at org.apache.catalina.core.ApplicationFilterChain.internalDoFilter(ApplicationFilterChain.java:193)
        at org.apache.catalina.core.ApplicationFilterChain.doFilter(ApplicationFilterChain.java:166)
        at net.jforum.util.legacy.clickstream.ClickstreamFilter.doFilter(ClickstreamFilter.java:59)
        at org.apache.catalina.core.ApplicationFilterChain.internalDoFilter(ApplicationFilterChain.java:193)
        at org.apache.catalina.core.ApplicationFilterChain.doFilter(ApplicationFilterChain.java:166)
        at org.apache.catalina.core.StandardWrapperValve.invoke(StandardWrapperValve.java:198)
        at org.apache.catalina.core.StandardContextValve.invoke(StandardContextValve.java:96)
        at org.apache.catalina.authenticator.AuthenticatorBase.invoke(AuthenticatorBase.java:478)
        at org.apache.catalina.core.StandardHostValve.invoke(StandardHostValve.java:140)
        at org.apache.catalina.valves.ErrorReportValve.invoke(ErrorReportValve.java:80)
        at org.apache.catalina.valves.AbstractAccessLogValve.invoke(AbstractAccessLogValve.java:650)
        at org.apache.catalina.core.StandardEngineValve.invoke(StandardEngineValve.java:87)
        at org.apache.catalina.connector.CoyoteAdapter.service(CoyoteAdapter.java:342)
        at org.apache.coyote.http11.Http11Processor.service(Http11Processor.java:799)
        at org.apache.coyote.AbstractProcessorLight.process(AbstractProcessorLight.java:66)
        at org.apache.coyote.AbstractProtocol$ConnectionHandler.process(AbstractProtocol.java:868)
        at org.apache.tomcat.util.net.NioEndpoint$SocketProcessor.doRun(NioEndpoint.java:1457)
        at org.apache.tomcat.util.net.SocketProcessorBase.run(SocketProcessorBase.java:49)
        at java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1149)
        at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:624)
        at org.apache.tomcat.util.threads.TaskThread$WrappingRunnable.run(TaskThread.java:61)
        at java.lang.Thread.run(Thread.java:748)
Caused by: java.lang.reflect.InvocationTargetException
        ... 36 more
Caused by: java.lang.NullPointerException
        at org.postgresql.core.CachedQueryCreateAction.create(CachedQueryCreateAction.java:39)
        at org.postgresql.core.CachedQueryCreateAction.create(CachedQueryCreateAction.java:17)
        at org.postgresql.util.LruCache.borrow(LruCache.java:115)
        at org.postgresql.core.QueryExecutorBase.borrowQuery(QueryExecutorBase.java:271)
        at org.postgresql.jdbc.PgConnection.borrowQuery(PgConnection.java:146)
        at org.postgresql.jdbc.PgPreparedStatement.<init>(PgPreparedStatement.java:85)
        at org.postgresql.jdbc.PgConnection.prepareStatement(PgConnection.java:1223)
        at org.postgresql.jdbc.PgConnection.prepareStatement(PgConnection.java:1681)
        at org.postgresql.jdbc.PgConnection.prepareStatement(PgConnection.java:371)
        at com.mchange.v2.c3p0.impl.NewProxyConnection.prepareStatement(NewProxyConnection.java:567)
        at net.jforum.dao.generic.GenericPostDAO.selectAllByTopicByLimit(GenericPostDAO.java:377)
        at net.jforum.dao.generic.GenericPostDAO.selectAllByTopic(GenericPostDAO.java:356)
        at net.jforum.repository.PostRepository.selectAllByTopicByLimit(PostRepository.java:117)
        at net.jforum.view.forum.common.PostCommon.topicPosts(PostCommon.java:358)
        at net.jforum.view.forum.PostAction.list(PostAction.java:168)
        ... 36 more


ERROR [ExceptionWriter] - net.jforum.exceptions.ForumException: java.lang.reflect.InvocationTargetException
        at sun.reflect.NativeMethodAccessorImpl.invoke0(Native Method)
        at sun.reflect.NativeMethodAccessorImpl.invoke(NativeMethodAccessorImpl.java:62)
        at sun.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:43)
        at java.lang.reflect.Method.invoke(Method.java:498)
        at net.jforum.Command.process(Command.java:117)
        at net.jforum.JForum.processCommand(JForum.java:258)
        at net.jforum.JForum.service(JForum.java:240)
        at javax.servlet.http.HttpServlet.service(HttpServlet.java:742)
        at org.apache.catalina.core.ApplicationFilterChain.internalDoFilter(ApplicationFilterChain.java:231)
        at org.apache.catalina.core.ApplicationFilterChain.doFilter(ApplicationFilterChain.java:166)
        at org.apache.tomcat.websocket.server.WsFilter.doFilter(WsFilter.java:52)
        at org.apache.catalina.core.ApplicationFilterChain.internalDoFilter(ApplicationFilterChain.java:193)
        at org.apache.catalina.core.ApplicationFilterChain.doFilter(ApplicationFilterChain.java:166)
        at net.jforum.csrf.CsrfFilter.doFilter(CsrfFilter.java:100)
        at org.apache.catalina.core.ApplicationFilterChain.internalDoFilter(ApplicationFilterChain.java:193)
        at org.apache.catalina.core.ApplicationFilterChain.doFilter(ApplicationFilterChain.java:166)
        at net.jforum.util.legacy.clickstream.ClickstreamFilter.doFilter(ClickstreamFilter.java:59)
        at org.apache.catalina.core.ApplicationFilterChain.internalDoFilter(ApplicationFilterChain.java:193)
        at org.apache.catalina.core.ApplicationFilterChain.doFilter(ApplicationFilterChain.java:166)
        at org.apache.catalina.core.StandardWrapperValve.invoke(StandardWrapperValve.java:198)
        at org.apache.catalina.core.StandardContextValve.invoke(StandardContextValve.java:96)
        at org.apache.catalina.authenticator.AuthenticatorBase.invoke(AuthenticatorBase.java:478)
        at org.apache.catalina.core.StandardHostValve.invoke(StandardHostValve.java:140)
        at org.apache.catalina.valves.ErrorReportValve.invoke(ErrorReportValve.java:80)
        at org.apache.catalina.valves.AbstractAccessLogValve.invoke(AbstractAccessLogValve.java:650)
        at org.apache.catalina.core.StandardEngineValve.invoke(StandardEngineValve.java:87)
        at org.apache.catalina.connector.CoyoteAdapter.service(CoyoteAdapter.java:342)
        at org.apache.coyote.http11.Http11Processor.service(Http11Processor.java:799)
        at org.apache.coyote.AbstractProcessorLight.process(AbstractProcessorLight.java:66)
        at org.apache.coyote.AbstractProtocol$ConnectionHandler.process(AbstractProtocol.java:868)
        at org.apache.tomcat.util.net.NioEndpoint$SocketProcessor.doRun(NioEndpoint.java:1457)
        at org.apache.tomcat.util.net.SocketProcessorBase.run(SocketProcessorBase.java:49)
        at java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1149)
        at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:624)
        at org.apache.tomcat.util.threads.TaskThread$WrappingRunnable.run(TaskThread.java:61)
        at java.lang.Thread.run(Thread.java:748)
Caused by: java.lang.reflect.InvocationTargetException
        ... 36 more
Caused by: java.lang.NullPointerException
        at org.postgresql.core.CachedQueryCreateAction.create(CachedQueryCreateAction.java:39)
        at org.postgresql.core.CachedQueryCreateAction.create(CachedQueryCreateAction.java:17)
        at org.postgresql.util.LruCache.borrow(LruCache.java:115)
        at org.postgresql.core.QueryExecutorBase.borrowQuery(QueryExecutorBase.java:271)
        at org.postgresql.jdbc.PgConnection.borrowQuery(PgConnection.java:146)
        at org.postgresql.jdbc.PgPreparedStatement.<init>(PgPreparedStatement.java:85)
        at org.postgresql.jdbc.PgConnection.prepareStatement(PgConnection.java:1223)
        at org.postgresql.jdbc.PgConnection.prepareStatement(PgConnection.java:1681)
        at org.postgresql.jdbc.PgConnection.prepareStatement(PgConnection.java:371)
        at com.mchange.v2.c3p0.impl.NewProxyConnection.prepareStatement(NewProxyConnection.java:567)
        at net.jforum.dao.generic.GenericTopicDAO.selectAllByForumByLimit(GenericTopicDAO.java:465)
        at net.jforum.dao.generic.GenericTopicDAO.selectAllByForum(GenericTopicDAO.java:447)
        at net.jforum.view.forum.common.TopicsCommon.topicsByForum(TopicsCommon.java:107)
        at net.jforum.view.forum.ForumAction.show(ForumAction.java:180)
        ... 36 more

[Ulf Dittmer]

I have long suspected that the topic/post cache is dodgy. Way back when JForum was introduced at CodeRanch, I remember us disabling the caches due to some bug. I'll look into what's involved to make them work, but possibly the solution is to disable them permanently.

[Ulf Dittmer]

I'm trying to repoduce the problem. With the code as it is now in the repo, and topic.cache.enabled = true and posts.cache.enabled = false, a topic with more than 100 posts will cause the exception - is that correct?

[nyj3c]

Right. With the code as it is now in the repo (r666)
If topic.cache.enabled = true arises forums/show NullPointerException
If posts.cache.enabled = true arises posts/list NullPointerException

If topic.cache.enabled = true and posts.cache.enabled = true arises forums/show NullPointerException and posts/list NullPointerException

If topic.cache.enabled = false and posts.cache.enabled = false all work ...

It all NOT depends on the number of posts.

About topic with more than 100 posts concerns my experiments with changes return this.selectAllByTopicByLimit(topicId, 0, 100); in net.jforum.dao.PostDAO#selectAllByTopic

If change: forum work quick without freezes, but the posts in topic bigger 100 are not loaded.

If not change: in big topic (for example 15000 posts in topic) forum freeze, page can load 2 minutes and bigger. This beecause query with huge limit (Integer.MAX_VALUE - 1).

[nyj3c]

To add:
topic.cache.enabled = true before commit [r664] work good and no freeze forum.

freeze and sloooooow load only posts.cache.enabled = true on big topics

[Ulf Dittmer]

That's quite odd. I'm testing with both caches enabled and all works fine. There must be additional conditions for the errors to manifest.

I also tested with either one turned on and the other one off - all is fine.

This is with the EhCache engine.

[Ulf Dittmer]

Which cache engine are you using?

[nyj3c]

Sorry about that. I try re-install forum and can not reproduce problem. All is fine, on mysql and postgres.
Recursive diff between old working copy show difference csrfguard.properties, jforum-custom.conf, language and templates perhaps it arises NullPointerException.

Problem with posts.cache.enabled = true stiil remains on big topic, forum freeze, page load slow.

I tried to optimize another query and big topic with posts.cache.enabled = true worked quick.

--- a/src/main/config/database/postgresql/postgresql.sql
+++ b/src/main/config/database/postgresql/postgresql.sql
@@ -44,6 +44,15 @@
     AND pt.post_id = p.post_id AND u.user_id = p.user_id \
     ORDER BY post_time ASC

+PostModel.selectAllByTopic = SELECT p.post_id, topic_id, forum_id, p.user_id, post_time, poster_ip, enable_bbcode, p.attach, \
+       enable_html, enable_smilies, enable_sig, post_edit_time, post_edit_count, status, pt.post_subject, pt.post_text, username, p.need_moderate, u.user_viewonline \
+       FROM jforum_posts p, jforum_posts_text pt, jforum_users u \
+       WHERE p.post_id IN (SELECT p.post_id FROM jforum_posts p WHERE p.topic_id = ? AND p.need_moderate = 0 \
+       ORDER BY post_time ASC) \
+       AND pt.post_id = p.post_id \
+       AND p.user_id = u.user_id \
+       ORDER BY post_time ASC
+
 PostModel.selectByUserByLimit = SELECT p.post_id, topic_id, forum_id, p.user_id, post_time, poster_ip, enable_bbcode, p.attach, \
     enable_html, enable_smilies, enable_sig, post_edit_time, post_edit_count, status, pt.post_subject, pt.post_text, username, p.need_moderate, u.user_viewonline \
     FROM jforum_posts p, jforum_posts_text pt, jforum_users u \

[Ulf Dittmer]

OK, I've added that optimized query.

Problem with posts.cache.enabled = true stiil remains on big topic, forum freeze, page load slow.

That should be taken care of when using the latest version from the repository, no?