noahd1 / oink

Oink

• github.com/noahd1/oink

Description

Rails plugin and log parser to help narrow down the source(s) of increased memory usage in rails applications.

Synopsis

Oink adds memory and active record instantiation information to rails log during runtime and provides an executable to help digest the enhanced logs.

Given a minimum threshold and a metric (memory or active record instantiation), the oink executable reports:

1. The top ten single requests which exceeded the threshold for the metric, ordered by the request which exceeded the threshold the most
2. The number of times each action exceeded the threshold for the metric, ordered by the action which exceeded the threshold the most
3. (in verbose mode) The log lines produced by requests which exceeded the threshold

Many thanks to Ben Johnson for Memory Usage Logger (github.com/binarylogic/memory_usage_logger/tree/master) which is the basis of this plugin.

Dependencies

Currently oink can only parse logs in the Hodel3000Logger format

• github.com/topfunky/hodel_3000_compliant_logger/tree/master

Install

To print memory usage at the end of each request, include Oink::MemoryUsageLogger in your controller. This will add lines like:

class ApplicationController

  include Oink::MemoryUsageLogger

end

which results in lines like this added to each request:

  Feb 08 11:39:54 ey33-s00302 rails[9076]: Memory usage: 316516 | PID: 9076

To print active record instantiation at the end of each request, include Oink::InstanceTypeCounter in your controller.

  class ApplicationController
    include Oink::InstanceTypeCounter
  end

which results in lines like this added to each request:

  Feb 27 13:21:04 ey04-s00295 rails[11862]: Instantiation Breakdown: Total: 73 | User: 34 | Group: 20 | Medium: 20 | Sport: 10 | Post: 4 | Discussion: 2

Usage

After installing the plugin and aggregating some enhanced logs, run the oink executable against the logs. This will typically be installed as script/oink. Oink can point at a log file or a directory of log files

  Usage: oink [options] files
      -t, --threshold [INTEGER]        Memory threshold in MB
      -f, --file filepath              Output to file
          --format FORMAT              Select format
                                         (ss,v,s,verbose,short-summary,summary)
      -m, --memory                     Check for Memory Threshold (default)
      -r, --active-record              Check for Active Record Threshold

Oink hunts for requests which exceed a given threshold. In "memory" mode (the default), the threshold represents a megabyte memory increase from the previous request. In "active record" mode (turned on by passing the —active-record switch), the threshold represents the number of active record objects instantiated during a request.

e.g. To find all actions which increase the heap size more than 75 MB, where log files are location in /tmp/logs/

  $ oink --threshold=75 /tmp/logs/*
  ---- MEMORY THRESHOLD ----
  THRESHOLD: 75 MB

  -- SUMMARY --
  Worst Requests:
  1. Feb 02 16:26:06, 157524 KB, SportsController#show
  2. Feb 02 20:11:54, 134972 KB, DashboardsController#show
  3. Feb 02 19:06:13, 131912 KB, DashboardsController#show
  4. Feb 02 08:07:46, 115448 KB, GroupsController#show
  5. Feb 02 12:19:53, 112924 KB, GroupsController#show
  6. Feb 02 13:03:00, 112064 KB, ColorSchemesController#show
  7. Feb 02 13:01:59, 109148 KB, SessionsController#create
  8. Feb 02 06:11:17, 108456 KB, PublicPagesController#join
  9. Feb 02 08:43:06, 94468 KB, CommentsController#create
  10. Feb 02 20:49:44, 82340 KB, DashboardsController#show

  Worst Actions:
  10, DashboardsController#show
  9, GroupsController#show
  5, PublicPagesController#show
  5, UsersController#show
  3, MediaController#show
  2, SportsController#show
  1, SessionsController#create
  1, GroupInvitesController#by_email
  1, MediaController#index
  1, PostsController#show
  1, PhotoVotesController#create
  1, AlbumsController#index
  1, SignupsController#new
  1, ColorSchemesController#show
  1, PublicPagesController#join
  1, CommentsController#create

e.g. In verbose mode, oink will print out all the log information from your logs about the actions which exceeded the threshold specified

  $ oink --format verbose --threshold=75 /tmp/logs/*

  ---------------------------------------------------------------------
  Feb 08 11:39:52 ey33-s00302 rails[9076]: Processing UsersController#show (for 11.187.34.45 at 2009-02-08 11:39:52) [GET]
  Feb 08 11:39:52 ey33-s00302 rails[9076]: Parameters: {"action"=>"show", "id"=>"45", "controller"=>"users"}
  Feb 08 11:39:52 ey33-s00302 rails[9076]: Rendering template within layouts/application
  Feb 08 11:39:52 ey33-s00302 rails[9076]: Rendering users/show
  Feb 08 11:39:54 ey33-s00302 rails[9076]: Memory usage: 316516 | PID: 9076
  Feb 08 11:39:54 ey33-s00302 rails[9076]: Completed in 2008ms (View: 1136, DB: 264) | 200 OK [http://www.example.com/users/45]
  ---------------------------------------------------------------------

Verbose format prints the summary as well as each action which exceeded the threshold.

Authors

• Maintained by Noah Davis
• Thanks to Weplay (weplay.com) for sponsoring development and supporting open sourcing it from the start