In our first post of this series, we introduced the basic concepts of performance tuning and demonstated how you can simulate load using Flood IO and analyse performance using New Relic.
In this post we go on to identify and tune the remaining problems in our application under test.
Slow Transaction Traces
The top 5 web transactions by percent of wall clock time in New Relic helps prioritise points of interest (POI). AsyncController and CachingController have the highest percentage so we focus on those next.
The same transactions are consistently slow (+10s) in Flood IO.
New Relic has automatically caputed slow transaction traces for these transactions.
The AsyncController trace gives us call count and duration which helps further isolate a POI.
Trace details show 99.82% of time is being spent in application code within the ERB template of the index view.
Ouch! Taking a look at application code reveals a blocking 10s call to the send_email_to_user method. Moving this long running task to an asynchronous background process should improve response times. We use the queue classic gemwhich provides a simple interface to a message queue since we already have PostgreSQL and are not looking to add any additional infrastructure.
Problem Solved
We add the queue and repeat the baseline.
Our prediction was sound. It looks like async is no longer in the top 5 slowest transactions in Flood IO. New Relic confirms the same.
Database Traces
big_list is now the slowest transaction in Flood IO and slow transaction tracesin New Relic show the same.
Trace details show 91% of time in the find_by_sql method of the WebSiteController. Drilling down into SQL details, the query plan shows 100K rows returned.
The business logic only requires a record count and the first record in the collection we can quickly test the hypothesis and a leaner solution.
Problem Solved
We modify the query and repeat the baseline.
Our prediction was sound. It looks like big_list is no longer in the top 5 slowest transactions in Flood IO. New Relic confirms the same.
We haven't finished with the database yet, we sort by highest throughput and look at the top 5 database operations by wall clock time.
The find method of the Icon model is called frequently and is the slowest in terms of wall clock time. Trace details also show the index method of the LoopControllermakes this call.
We hypothesize that by eager loading the associations we can avoid an N + 1 query problem. We modify the query and repeat the baseline.
Our prediction was sound and New Relic shows much more sane throughput in the database.
Next Steps
Now that we've solved more performance problems using New Relic slow transaction and database traces, read our last post in this series to discover how we find and tune the remaining performance problems present in our application under test.