noahd1 / oink

Log parser to identify actions which significantly increase VM heap size
MIT License
1.18k stars 71 forks source link

{}[https://codeclimate.com/github/noahd1/oink]

=== 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 (http://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

When used as a gem, this is automatically brought in as a dependency.

=== Installation

Add oink to your Gemfile

gem "oink"

In most rails environments this is sufficient and oink will be required for you via bundler. If not, add a require statement "require 'oink'" in your app.

=== Configuration

Oink is middleware for instrumentation during the runtime of your application as well as log parsers for offline crunching of the logs generated by the middleware.

The middleware class to include into your stack is "Oink::Middleware". For rails using an initializer is recommended:

Rails.application.middleware.use Oink::Middleware

Oink::Middleware writes log entries to log/oink.log in your application root directory by default.

You can also initialize it with an optional logger instance enabling your application to write Oink log entries to your application's default log file:

Rails.application.middleware.use( Oink::Middleware, :logger => Rails.logger )

(This setup enables Oink to work with Request Log Analyzer (https://github.com/wvanbergen/request-log-analyzer), which currently parses rails logs)

Oink::Middleware logs memory and activerecord usage by default.

You can configure which using the :instruments option. For memory only:

Rails.application.middleware.use( Oink::Middleware, :instruments => :memory )

For activerecord instantiation counts only:

Rails.application.middleware.use( Oink::Middleware, :instruments => :activerecord )

Note that the previous way of configuring oink, as a set of modules to include into rails controllers, is deprecated.

== Analyzing logs

After installing the plugin and aggregating some enhanced logs, run the 'oink' executable against your server logs.

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

    Aggregated Totals: Action Max Mean Min Total Number of requests SportsController#show 101560 19754 4 5590540 283 CommentsController#create 8344 701 4 253324 361 ColorSchemesController#show 10124 739 4 68756 93 PublicPagesController#join 9004 1346 8 51172 38 DashboardsController#show 13696 2047 8 45036 22 SessionsController#create 9220 528 8 17448 33 GroupsController#show 10748 1314 8 15776 12

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]: Completed in 2008ms (View: 1136, DB: 264) | 200 OK [http://www.example.com/users/45] Feb 08 11:39:52 ey33-s00302 rails[9076]: Oink Action: 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]: Oink Log Entry Complete

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

=== Authors