SUMMARY: This is a step-by-step overview of how to get Oink installed in your Rails app on Heroku, and use it to analyze your memory usage. Starts with a brief description of the problem space, skip down if you just want to get on with your Oink integration.
My stack includes these technologies: Rails 3, Unicorn, NewRelic, Heroku, Hodel3000CompliantLogger, and now Oink.
Why is understanding memory usage important? For me, it’s because Heroku routes traffic to my dynos randomly. Any time my users spend in request queuing, it’s because the dyno they were assigned is busy. Using Unicorn is a great step in the right direction - it lets my dynos handle three or four requests at a time instead of just one (eg, if I was using thin). So the more Unicorn forks I can cram into a single dyno, the more requests I can handle concurrently. But since the new double-wide dynos are limited to 1GB of memory, if I try to run too many Unicorn forks they get restarted too often because they run out of memory. Understanding exactly how and my an individual thread is using memory lets me know exactly how many forks I can safely run in a single dyno, and potentially work out some optimizations to allow me to squeeze another fork or two in there.
There are a couple really easy ways to get a glimpse into your dyno memory usage. NewRelic is a great start. Here’s an example of the NewRelic memory usage graph, under “Monitoring > Instances”.
This is a great start - I can see that most of my forks are doing just fine, but I definitely have a problem somewhere. At least one fork is using almost half a gig of memory - well above average. Unfortunately that’s all I can find out through NewRelic. I can get a little more info using the log-runtime-metrics addon (currently in beta through Heroku Labs) but so far there aren’t any tools that I know of for analyzing the output and surfacing memory leaks.
Enter Oink.
Oink is a “log parser to identify actions which significantly increase VM heap size.” You can find it at github.com/noahd1/oink. Oink is inserted as middleware into your Rails app. It adds memory usage and ActiveRecord instantiation counts to your log files, which it will then analyze to show you expensive requests. Here’s how to get it going.
First, add the gem to your project:
# Gemfile
gem 'oink', '~> 0.10'
# install it from the command line
$ bundle
Then set it up as middleware. Oink comes with the Hodel3000CompliantLogger, which creates logs in a format that Oink knows how to read. You don’t need to use the Hodel3000CompliantLogger for the rest of your app, you can use it solely for Oink logging. Using STDOUT will cause the Oink logs to be included in your normal Heroku logs.
# application.rb (for all environments - add to any individual environment file like production.rb if you prefer)
config.middleware.use Oink::Middleware, :logger => Hodel3000CompliantLogger.new(STDOUT)
That’s it! Now you need a way to get your log files off Heroku. There are a number of addons you can use to set up log drains. For a super simple solution you can redirect the logs directly to a file on your computer:
$ heroku logs --tail --app YOUR_APP_NAME > production_log.txt
// or if you want to see the output while you're saving it to a file,
// the 'tee' command will show the output in the terminal and also
// append to a file
$ heroku logs --tail --app YOUR_APP_NAME | tee -a production_log.txt
We’re pretty close, but one more thing stands in our way. This is what my logs look like:
2013-07-18T20:49:34.401020+00:00 heroku[web.1]: source=heroku.3018313.web.1.879213-69-78-82-8269e2ef24 measure=memory_pgpgin val=610304 units=pages
2013-07-18T20:49:34.401204+00:00 heroku[web.1]: source=heroku.3018313.web.1.879213-69-78-82-8269e2ef24 measure=memory_pgpgout val=122844 units=pages
2013-07-18T20:49:34.401440+00:00 heroku[web.1]: source=heroku.3018313.web.1.879213-69-78-82-8269e2ef24 measure=diskmbytes val=0 units=MB
2013-07-18T20:49:37.500266+00:00 app[web.2]: Dalli/SASL authenticating as app3018313%40heroku.com
2013-07-18T20:49:37.501179+00:00 app[web.2]: Dalli/SASL: Authenticated
2013-07-18T20:49:37.509081+00:00 app[web.2]: Started GET "/credit_cards" for 108.218.32.158 at 2013-07-18 20:49:37 +0000
2013-07-18T20:49:40.416885+00:00 app[web.2]: Jul 18 20:49:40 a262e3-ed-24-65-fff2cff5ec rails[12]: Oink Action: credit_cards#index
2013-07-18T20:49:40.583043+00:00 app[web.2]: Jul 18 20:49:40 a262e3-ed-24-65-fff2cff5ec rails[12]: Memory usage: 381912 | PID: 12
2013-07-18T20:49:40.583494+00:00 app[web.2]: Jul 18 20:49:40 a262e3-ed-24-65-fff2cff5ec rails[12]: Instantiation Breakdown: Total: 8 | Role: 4 | CreditCard: 2 | User: 1 | AuthenticationToken: 1
2013-07-18T20:49:40.583678+00:00 app[web.2]: Jul 18 20:49:40 a262e3-ed-24-65-fff2cff5ec rails[12]: Oink Log Entry Complete
2013-07-18T20:49:40.586326+00:00 heroku[router]: at=info method=GET path=/credit_cards host=staging.aisle50.com fwd="108.218.32.158" dyno=web.2 connect=1ms service=3118ms status=200 bytes=13849
You can see the effect of the Hodel3000CompliantLogger on the Oink lines. Most obvious is the duplicated/different timestamp “Jul 18 20:49:40”. That’s what Oink is expecting. Unfortunately it’s expecting it at the beginning of the line, but Heroku prepends its own timestamp and dyno info. We must remove it. Personally I do it in vim with a regex:
// open vim
$ vim production_log.txt
// vim commands start when you type a colon, so literally type each
// character on these lines, and hit enter at the end.
// First command removes the heroku logging
// Second command removes non-oink lines (lines that don't contain Oink, Memory, or Instantiation)
// Third command saves the file and quits vim
:%s/\S* \S* //
:g!/Oink\|Memory\|Instantiation/d
:wq
Your log files may be slightly different from mine but the basic concept is the same - strip out the heroku stuff at the beginning of the line. I can use /\S* \S* / but you might need to alter the regex.
Now we have a clean file that Oink will recognize! The most basic Oink commands:
// show actions that used more than 10MB of memory
$ oink production_log.txt --threshold=10
// show actions that created more than 50 ActiveRecord objects
$ oink production_log.txt --threshold=50 -r
From here you’re on your own :)