Author Archives: Jeanne Boyarsky

production is slow – tuning jforum for javaranch – part 2

Posted on by

A moderator reported that moving topics took a long time in production and our sandbox.  I just tried it and got 70 seconds through the GUI!  It didn’t used to take this long.  I’m comparing our development sandbox a few months ago to our development sandbox today.  Clearly something has changed.  The question is what!

I heard a couple people liked reading about the thought process for troubleshooting slow queries. If you aren’t familiar with what a database explain is used for, see that entry before reading this one.

This time the path to success was a little more meandering.  I’ve left the dead ends in here so you get a feel for the actual thought process and not a sanitized version.  if you are a student, this is a decent feel for what problems look like in the “real” world.

  1. First step – find piece of code in JForum that handles moving threads.
  2. It’s GenericForumDAO.moveTopics.  I see this method was modified by us (JavaRanch) to support leaving a copy of the thread in the original forum or creating a new copy and locking the original (for use in moving to our private “Trash Can” forum.)  We made that change a long time ago though and it wasn’t slow then.
  3. Looking at the method, I see a number of database queries.  I’m adding logging (nothing fancy – just System.out’s) to see which query is using up so much time.
  4. The method I added logging to takes 5-8 milliseconds.  (across two trials).  Yet the browser plugs away for almost a full minute after that.
  5. Ah!  The web/action layer class ModerationHelper makes a bunch of calls to clear/reload the cache.  I bet that’s where all the time is going.  Adding logging on that level and redeploying.
  6. Now we are getting somewhere.  Everything goes very quickly until the part where the hotest topics get reloaded and then that takes almost a minute.
  7. Yuck.  Table scans left and right.  No wonder it takes so long.  Three tables scans, joining on the result and THEN discarding almost all the records.  (see “original query” and “original explain” in supplemental materials section below)
  8. If I was doing this by brute force, I would add an index on topic_views and refactor the query to search on the the topics table only joining with the others on result.  This is similar to the last post where I walked through an optimization.  However, I’m not sure that makes sense here.
  9. This definition of hottest posts uses the most page views forever.  This is ok for now because all the migrated posts started with zero views against them.  Making the hottest threads really “the hottest threads since our Saturday January 3rd migration.”  What happens down the road.  When a thread stops being viewed altogether, it’s not hot anymore.  I’m thinking it would be better to put a time based constraint on things.
  10. I’ll post in our Moderators Only forum to get some feedback on my proposed definition change and go have dinner.
  11. Unanimous agreement on my proposed definition from everyone who saw the question while I was eating.  Including the site owner.  Good news.
  12. Modify the query to add a where clause by thread last modified date
  13. This modified query takes 80 thousand units instead of 253 thousand units.  Better but still way too high.
  14. Next I’ll try adding index on topic_last_post_id, topic_views
  15. Running explain again gives the exact same output.  It isn’t using the index.
  16. Dropping the index since it didn’t work.  I may re-add it later but I like to test only one variable at a time.
  17. The database seems to be favoring the table scan of the forum table first.  Probably because this table is order of magnitudes smaller than the other two in the join.
  18. Now I’ll try removing the forum table from the query and run an explain to see what happens.  It’s still 78 thousand units, but at least it is using an index (post_time) as the first step.
  19. Time to try to add the index and run explain again.  Nothing.  Still 78 thousand units.
  20. All right.  This tweaking thing isn’t getting me anywhere.  New approach.  How would I build this query if I were writing it from scratch.
  21. The base query that I want to happen first is explain select p.post_id from jforum_posts p WHERE p.post_time >= ‘2008-01-01’.  Running an explain on just this says it takes 1 thousand cost units.  That sounds high – I’ll query some details.  Over 100 thousand posts in a few days?  Oh yeah!  It’s 2009 – a New Year.  I should know that – I celebrated recently.
  22. Re-running the original query with the post_time clause gives me under two thousand cost units.  Whew.  That’s much better.
  23. Now I’m uploading the changed query to our sandbox environment to see how the move performs.  Three to five seconds.  Good.
  24. Another moderator suggested using replies and not views.  This is a good idea, but has no effect on performance so I switched it. (see “Final query” in supplemental materials)
  25. And a good techie verifies everything so running explain one last time to confirm this last change didn’t affect performance.  It didn’t.  Performance is still ok. ( see “Final explain” in supplemental materials)

Summary

Two orders of magnitude performance improvement on the database query and a web action that isn’t painful to wait for.  I’m happy with that.  Not only is it faster, but we uncovered a better business definition for the query.

I also learned the last time we tested a move on our sandbox server was before we tested migrating large quantities of data.  Making it an invalid test.

Supplemental materials

Original query

SELECT t.*, p.user_id AS last_user_id, p.post_time, p.attach AS attach, f.forum_name \
FROM jforum_topics t, jforum_posts p, jforum_forums f \
WHERE p.post_id = t.topic_last_post_id \
AND p.need_moderate = 0 \
and p.forum_id = f.forum_id \
ORDER BY topic_views DESC \
LIMIT ?

Original explain

Row #         QUERY PLAN
1       Limit (cost=253457.29..253457.39 rows=40 width=132)
2       -> Sort (cost=253457.29..254467.05 rows=403905 width=132)
3       Sort Key: t.topic_views
4       -> Hash Join (cost=26807.80..136006.35 rows=403905 width=132)
5       Hash Cond: (“outer”.forum_id = “inner”.forum_id)
6       -> Hash Join (cost=26707.81..129847.79 rows=403905 width=113)
7       Hash Cond: (“outer”.post_id = “inner”.topic_last_post_id)
8       -> Seq Scan on jforum_posts p (cost=0.00..50770.74 rows=1775019 width=24)
9       Filter: (need_moderate = 0)
10       -> Hash (cost=19386.05..19386.05 rows=403905 width=93)
11       -> Seq Scan on jforum_topics t (cost=0.00..19386.05 rows=403905 width=93)
12       -> Hash (cost=99.79..99.79 rows=79 width=27)
13       -> Seq Scan on jforum_forums f (cost=0.00..99.79 rows=79 width=27)

Final query

SELECT t.*, p.user_id AS last_user_id, p.post_time, p.attach AS attach, f.forum_name \
FROM jforum_topics t, jforum_posts p, jforum_forums f \
WHERE p.post_time >= ? \
and p.post_id = t.topic_last_post_id \
AND p.need_moderate = 0 \
and p.forum_id = f.forum_id \
ORDER BY topic_replies DESC \
LIMIT ?

Final explain:

Row #         QUERY PLAN
1       Limit (cost=1774.18..1774.23 rows=20 width=132)
2       -> Sort (cost=1774.18..1774.28 rows=40 width=132)
3       Sort Key: t.topic_replies
4       -> Hash Join (cost=99.99..1773.12 rows=40 width=132)
5       Hash Cond: (“outer”.forum_id = “inner”.forum_id)
6       -> Nested Loop (cost=0.00..1672.53 rows=40 width=113)
7       -> Index Scan using idx_posts_time on jforum_posts p (cost=0.00..678.22 rows=177 width=24)
8       Index Cond: (post_time >= ‘2009-01-05 00:00:00’::timestamp without time zone)
9       Filter: (need_moderate = 0)
10       -> Index Scan using idx_topics_lp on jforum_topics t (cost=0.00..5.61 rows=1 width=93)
11       Index Cond: (“outer”.post_id = t.topic_last_post_id)
12       -> Hash (cost=99.79..99.79 rows=79 width=27)
13       -> Seq Scan on jforum_forums f (cost=0.00..99.79 rows=79 width=27)

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.