javaranch/jforum – nailing down a production problem

Posted on by
Reply

JavaRanch successfully cutover to our new forum software yesterday.  Unsurprisingly, we had a variety of small problems that cropped up.  One of them was the fact that anonymous users were able to post.

Below follows the thought process and steps involved in fixing it.  And then in fixing the problems caused by the fix!

  • A moderator noticed anonymous users can post – that’s not good
  • I looked at “general” group and saw deny anonymous posts was selected for all forums.  This looks right.  Hmm.  What’s the fastest thing I can change to prevent anonymous users from posting?
  • I know!  I’ll create a new group, put anonymous in it and give that group read only access.
  • Seems to work.
  • I logged a bug that when not logged in we see “new topics” in one stray place.  (At the time this doesn’t seem related.)
  • Things seem stable.  Time to get off the computer and enjoy Saturday night.
  • Another moderator asked why that was a bug since he gets redirected to login at that point. (This moderator is in Europe and had a good chunk of Sunday before I woke up.  It’s nice how things get done around the world.)
  • Chat session with this moderator – we realized he saw one behavior on our sandbox and I saw the error in production.  We discussed the behavior on test is correct/desired.  I need to figure out why it doesn’t work that way in production.  End chat session.
  • I wonder if the database is out of synch due to our data migration yesterday.
  • I edit ed the new group to force a database update.  If the database wasn’t out of synch, this doesn’t hurt anything.
  • I opened a new browser and tried accessing when logged out.  I get the expected behavior now.  I see the button and am prompted to login when I click it.
  • Now to tie up loose ends – I made the same “change” (edit without changing anything) to the “general” group, moved anonymous back there and got rid of the group created yesterday.
  • Marking it off on the bug list and all done.

My query is too slow – what do I do?

Posted on by
Reply

After posting Tuning JForum for JavaRanch, a couple people asked me offline about what I look for when tuning queries.

Before
The very first thing I do is identify the slow query and benchmark a “before” number.  This proves that there is something to optimize and lets me see if my tuning helped matters.  If I’m tuning a web app, this may start out as a slow page.  If I have a slow web page that uses multiple queries, I’ll add debug statements or use a profiler to see which one(s) are the slowest.  Ultimately by the time I am done with this step, I have a specific query that I want to tune.    I find this step important because it focuses the problem on something attainable.  “Tune one query” is a lot easier than “the website is slow.”  Granted once I’ve tuned the query I am likely to need to identify the next slow query and repeat the process.  But it’s steady progress.

During
Some “tuning opportunities” comes up repeatedly during query optimization.  Some common ones I’ve encountered (not necessarily in the order I would look for them):

  • Missing index – The first thing I do with a slow query is run a database explain and look at the output.  My previous blog entry has an example.  Table/heap scans are a big red flag for a tuning opportunity.  I look at what fields are in the where clause and make sure there is an index matching.  If not, I’ll add one or adjust the query to take advantage of existing indexes.
  • Inefficient query – Sometimes the explain plan shows nested queries where it isn’t necessary or expected.  If this is the case, I’ll rewrite the query to avoid the repetitive work.
  • Returning too many fields – If a query has “select *” or returns a lot of fields, I’ll examine the calling code to make sure they are all used.  If not, I’ll adjust the select clause to only return the fields that are actually needed.  If the database is on a different machine than the application code, network traffic is being wasted transferring unneeded data.  On a local machine, it’s still unnecessary work to read data that the caller does not need.  The effect of this on a network is large though.  Suppose you return just one unneeded column.  A query returning 1000 records has now wasted a kilobyte of network traffic that could have been spent on data you really did want.
  • Too many roundtrips – A lot of small queries isn’t necessarily better than a large one.  There are two reasons for this.  One is the time for network roundtrips.  Your work isn’t getting done while the application and database are waiting for communication to go back and forth.  If the queries can be merged or turned into a stored procedure, the application is likely to perform faster.  Sometimes merging helps overall.  For example, querying a table by primary key 1000 times is going to be slower than making 1000 separate requests to get a row.  If for no other reason than that the database is doing redundant work analyzing the query each time.
  • Check the algorithm – Sometimes the algorithm in the application is just plain inefficient.  There’s not much to say here because you need knowledge of an application to identify cases like this.
  • Can it be cached – Some queries just take time.  It may be a 100 millisecond query run many times a minute.  Or it may be a 1 second query run once every 5 minutes.   The easiest way to make it take less time is to cache the results.  After all, if the database doesn’t need to run the query, it will be faster.

Note: all of this advice assumes we are dealing with a huge table.  Of course if it wasn’t the query would likely not be slow in the first place.

After
How much did it help?  If my change made a significant improvement, I’ll look to see whether I have any other queries with the same problem.  I still gather before/after numbers for these.  It goes faster since I know a way of tuning it before I start though.

tuning jforum for javaranch

Posted on by
2

JavaRanch has been updating our forum software to an extension of JForum.  While testing, Ulf Dittmer noticed that the RSS feeds were incredibly slow – to the point of timing out.  He found that the database query itself was taking so long that the browser gave up.

JavaRanch Moose
Some of the queries built into JForum are written in a way that is fine for forums with a relatively small number of posts – even half a million posts total.  JavaRanch is much larger than that.  We imagine that we are the largest forum to use JForum.  (We have over 400 thousand threads/topics and over 1.7 million posts.)

I enjoy tuning queries, so I started looking at it.  When someone asked me about what I did, I thought it would be nice to blog about my thought process.  I’ve included the before/after queries and execution plans at the bottom so as not to break up the thought process.

1. Run original query at command line in our test environment (which is slightly smaller than the real data set, but close to realistic.)
2. Give up waiting after 5 minutes.
3. Run explain on the original query.
4. Cringe at the heap scan with a relative cost of 16628 – and worse within a nested loop.
5. Wonder why the query needs to do so much processing to get a limited number of rows.  The execution plan shows all that joining occurring on the entire table rather than just the 50 or so rows we care about (via the limit.)
6. Refactor the query to use a subquery to avoid this.  I had used this technique on another similar query the day before and gotten the query down to under 1000 cost units.
7. Run explain again.
8. See cost is 3807.  This is better, but there’s no logical reason it should be four times the cost of the query from yesterday.  Better keep tuning.
9. Hmm.  It’s using the index idx_topics_fp which is on topic_first_post_id.  We have almost 100 forums.  Wouldn’t it be more efficient to include the forum_id in the index.
10. Added index idx_topics_fp_forum on both topic_first_post_id and forum_id.
11. Run explain again.
12. See cost of 978.  Good.  This is about what I got on yesterday’s query.  I guess the built in indexes better matched what I needed on yesterday’s query.
13. Go back to GUI and try URL.  Takes a couple seconds.
14. Commit my changes.  I got a two order of magnitude increase on the query.  Very satisfying.

Original query:

PostModel.selectLatestByForumForRSS = SELECT p.topic_id, p.topic_id, p.post_id, p.forum_id, pt.post_subject AS subject, pt.post_text, p.post_time, p.user_id, u.username, u.user_first_name, u.user_last_name
FROM  jforum_topics t, jforum_posts p, jforum_posts_text pt, jforum_users u
WHERE p.post_id = t.topic_first_post_id
AND p.topic_id = t.topic_id
AND p.user_id = u.user_id
AND p.post_id = pt.post_id
AND p.need_moderate = 0
ORDER BY t.topic_first_post_id DESC

Modified query

PostModel.selectLatestByForumForRSS = SELECT p.topic_id, p.topic_id, p.post_id, p.forum_id, pt.post_subject AS subject, pt.post_text, p.post_time, p.user_id, u.username, u.user_first_name, u.user_last_name
FROM (select topic_first_post_id from jforum_topics where forum_id = ? order by topic_first_post_id desc limit ?) as nested,
jforum_topics t, jforum_posts p, jforum_posts_text pt, jforum_users u
WHERE p.post_id = nested.topic_first_post_id
AND p.topic_id = t.topic_id
AND p.user_id = u.user_id
AND p.post_id = pt.post_id
AND p.need_moderate = 0
ORDER BY t.topic_first_post_id DESC

Original explain

Row #         QUERY PLAN
1       Limit (cost=97566.69..97566.70 rows=1 width=504)
2       -> Sort (cost=97566.69..97566.70 rows=1 width=504)
3       Sort Key: t.topic_id
4       -> Nested Loop (cost=275.61..97566.68 rows=1 width=504)
5       -> Nested Loop (cost=275.61..97560.76 rows=1 width=473)
6       -> Nested Loop (cost=275.61..97556.05 rows=1 width=32)
7       Join Filter: (“inner”.topic_id = “outer”.topic_id)
8       -> Bitmap Heap Scan on jforum_topics t (cost=275.61..16628.72 rows=18174 width=8)
9       Recheck Cond: (forum_id = 1)
10       -> Bitmap Index Scan on idx_topics_forum (cost=0.00..275.61 rows=18174 width=0)
11       Index Cond: (forum_id = 1)
12       -> Index Scan using jforum_posts_pkey on jforum_posts p (cost=0.00..4.44 rows=1 width=24)
13       Index Cond: (p.post_id = “outer”.topic_first_post_id)
14       Filter: (need_moderate = 0)
15       -> Index Scan using jforum_posts_text_pkey on jforum_posts_text pt (cost=0.00..4.70 rows=1 width=449)
16       Index Cond: (“outer”.post_id = pt.post_id)
17       -> Index Scan using jforum_users_pkey on jforum_users u (cost=0.00..5.91 rows=1 width=35)
18       Index Cond: (“outer”.user_id = u.user_id)

Explain on modified query
Row #         QUERY PLAN
1       Sort (cost=3807.84..3807.94 rows=40 width=504)
2       Sort Key: t.topic_id
3       -> Nested Loop (cost=0.00..3806.78 rows=40 width=504)
4       -> Nested Loop (cost=0.00..3579.24 rows=40 width=500)
5       -> Nested Loop (cost=0.00..3342.41 rows=40 width=469)
6       -> Nested Loop (cost=0.00..3164.39 rows=40 width=453)
7       -> Limit (cost=0.00..2975.39 rows=40 width=4)
8       -> Index Scan Backward using idx_topics_fp on jforum_topics (cost=0.00..1351866.51 rows=18174 width=4)
9       Filter: (forum_id = 1)
10       -> Index Scan using jforum_posts_text_pkey on jforum_posts_text pt (cost=0.00..4.70 rows=1 width=449)
11       Index Cond: (pt.post_id = “outer”.topic_first_post_id)
12       -> Index Scan using jforum_posts_pkey on jforum_posts p (cost=0.00..4.44 rows=1 width=24)
13       Index Cond: (p.post_id = “outer”.topic_first_post_id)
14       Filter: (need_moderate = 0)
15       -> Index Scan using jforum_users_pkey on jforum_users u (cost=0.00..5.91 rows=1 width=35)
16       Index Cond: (“outer”.user_id = u.user_id)
17       -> Index Scan using jforum_topics_pkey on jforum_topics t (cost=0.00..5.68 rows=1 width=4)
18       Index Cond: (“outer”.topic_id = t.topic_id)

Explain after index
Row #         QUERY PLAN
1       Sort (cost=978.89..978.99 rows=40 width=504)
2       Sort Key: t.topic_id
3       -> Nested Loop (cost=0.00..977.83 rows=40 width=504)
4       -> Nested Loop (cost=0.00..741.01 rows=40 width=473)
5       -> Nested Loop (cost=0.00..513.47 rows=40 width=469)
6       -> Nested Loop (cost=0.00..335.45 rows=40 width=453)
7       -> Limit (cost=0.00..146.44 rows=40 width=4)
8       -> Index Scan Backward using idx_topics_fp_forum on jforum_topics (cost=0.00..66535.36 rows=18174 width=4)
9       Index Cond: (forum_id = 1)
10       -> Index Scan using jforum_posts_text_pkey on jforum_posts_text pt (cost=0.00..4.70 rows=1 width=449)
11       Index Cond: (pt.post_id = “outer”.topic_first_post_id)
12       -> Index Scan using jforum_posts_pkey on jforum_posts p (cost=0.00..4.44 rows=1 width=24)
13       Index Cond: (p.post_id = “outer”.topic_first_post_id)
14       Filter: (need_moderate = 0)
15       -> Index Scan using jforum_topics_pkey on jforum_topics t (cost=0.00..5.68 rows=1 width=4)
16       Index Cond: (“outer”.topic_id = t.topic_id)
17       -> Index Scan using jforum_users_pkey on jforum_users u (cost=0.00..5.91 rows=1 width=35)
18       Index Cond: (“outer”.user_id = u.user_id)