README

Path: README
Last Update: Tue Nov 08 14:06:54 PST 2005

Production Log Analyzer

rails-analyzer.rubyforge.org

rubyforge.org/projects/rails-analyzer

About

The Production Log Analyzer lets you find out which pages on your site are dragging you down. The PL Analyzer requires the use of SyslogLogger from rails_analyzer_tools because the default Logger doesn’t give any way to associate lines logged to a request.

The PL Analyzer also includes action_grep which lets you grab lines from a log that only match a single action.

  action_grep RssController#uber /var/log/production.log

Installing

Download

Grab the gem (or tar.gz) from the RubyForge project:

rubyforge.org/frs/?group_id=586

What you need

Either:

A syslogd that doesn’t suck. This means that syslog.conf(5) shows a !program_name specification. (FreeBSD’s syslogd doesn’t suck, but OS X’s syslogd does.)

or:

Some hacking skills to make Rails log the pid of the process for each line logged. You‘ll also have to teach LogParser#parse about this. Feel free to submit patches with tests. (Patches without tests are useless to me.)

What you need to do

Either:

Use SyslogLogger according to directions on the SyslogLogger RDoc page, including setting up your non-sucky syslogd as directed. (SyslogLogger is included via the rails_analyzer_tools gem.)

rails-analyzer.rubyforge.org/tools/classes/SyslogLogger.html

or:

Use your hacking skills and set up a logger that your hacked LogParser#parse can deal with. (Then send my your patches for integration.)

Then:

Set up a cronjob (or something like that) to run log files through pl_analyze.

Using pl_analyze

To run pl_analyze simply give it the name of a log file to analyze.

  pl_analyze /var/log/production.log

If you want, you can run it from a cron something like this:

  /usr/bin/gzip -dc /var/log/production.log.0.gz | /usr/local/bin/pl_analyze /dev/stdin

Or, have pl_analyze email you (which is preferred, because tabs get preserved):

  /usr/bin/gzip -dc /var/log/production.log.0.gz | /usr/local/bin/pl_analyze /dev/stdin -e devnull@robotcoop.com -s "pl_analyze for `date -v-1d "+%D"`"

In the future, pl_analyze will be able to read from STDIN.

Sample output

  Request Times Summary:          Count   Avg     Std Dev Min     Max
  ALL REQUESTS:                   11      0.576   0.508   0.000   1.470

  ThingsController#view:          3       0.716   0.387   0.396   1.260
  TeamsController#progress:       2       0.841   0.629   0.212   1.470
  RssController#uber:             2       0.035   0.000   0.035   0.035
  PeopleController#progress:      2       0.489   0.489   0.000   0.977
  PeopleController#view:          2       0.731   0.371   0.360   1.102

  Average Request Time: 0.634
  Request Time Std Dev: 0.498

  Slowest Request Times:
          TeamsController#progress took 1.470s
          ThingsController#view took 1.260s
          PeopleController#view took 1.102s
          PeopleController#progress took 0.977s
          ThingsController#view took 0.492s
          ThingsController#view took 0.396s
          PeopleController#view took 0.360s
          TeamsController#progress took 0.212s
          RssController#uber took 0.035s
          RssController#uber took 0.035s

  ------------------------------------------------------------------------

  DB Times Summary:               Count   Avg     Std Dev Min     Max
  ALL REQUESTS:                   11      0.366   0.393   0.000   1.144

  ThingsController#view:          3       0.403   0.362   0.122   0.914
  TeamsController#progress:       2       0.646   0.497   0.149   1.144
  RssController#uber:             2       0.008   0.000   0.008   0.008
  PeopleController#progress:      2       0.415   0.415   0.000   0.830
  PeopleController#view:          2       0.338   0.149   0.189   0.486

  Average DB Time: 0.402
  DB Time Std Dev: 0.394

  Slowest Total DB Times:
          TeamsController#progress took 1.144s
          ThingsController#view took 0.914s
          PeopleController#progress took 0.830s
          PeopleController#view took 0.486s
          PeopleController#view took 0.189s
          ThingsController#view took 0.173s
          TeamsController#progress took 0.149s
          ThingsController#view took 0.122s
          RssController#uber took 0.008s
          RssController#uber took 0.008s

  ------------------------------------------------------------------------

  Render Times Summary:           Count   Avg     Std Dev Min     Max
  ALL REQUESTS:                   11      0.219   0.253   0.000   0.695

  ThingsController#view:          3       0.270   0.171   0.108   0.506
  TeamsController#progress:       2       0.000   0.000   0.000   0.000
  RssController#uber:             2       0.012   0.000   0.012   0.012
  PeopleController#progress:      2       0.302   0.302   0.000   0.604
  PeopleController#view:          2       0.487   0.209   0.278   0.695

  Average Render Time: 0.302
  Render Time Std Dev: 0.251

  Slowest Total Render Times:
          PeopleController#view took 0.695s
          PeopleController#progress took 0.604s
          ThingsController#view took 0.506s
          PeopleController#view took 0.278s
          ThingsController#view took 0.197s
          ThingsController#view took 0.108s
          RssController#uber took 0.012s
          RssController#uber took 0.012s
          TeamsController#progress took 0.000s
          TeamsController#progress took 0.000s

What’s missing

  • More reports
  • Command line arguments including:
    • Help
    • What type of log file you’ve got (if somebody sends patches with tests)
  • Read from STDIN
  • Lots more

[Validate]