A Hodel 3000 Compliant Logger for the Rest of Us

A Hodel 3000 Compliant Logger for the Rest of Us 30 comments

posted Wednesday, January 3, 2007 by topfunky

The Rails Analyzer Tools are a very useful way to keep tabs on the performance of your site. They were written by Eric Hodel and have been open-sourced to the community by the Robot Co-Op.

The problem is that you need to install and run SysLogLogger to make it work. If you have more than one Rails app on a box, or if you don’t have root access to the box, or if you are on a shared host, you are out of luck.

No longer!

Install the Gems on Your Server

gem install production_log_analyzer
gem install rails_analyzer_tools

Install the Hodel3000CompliantLogger in your Rails app

Download the logger replacement and put it in your lib directory. (I’ll make this into a proper plugin soon.)

In the Initializer section of environment.rb, add

require 'hodel_3000_compliant_logger'
config.logger = Hodel3000CompliantLogger.new(config.log_path)

Run your app

For some reason, the standard script/server forces logging to work the old way. If I run mongrel_rails start, it works fine. I’m also running a production app with mongrel and it works as expected.

If you tail -f log/development.log you should see something like this:

Jan 03 10:08:09 topfunky rails[4535]: Rendered shared/_menu (0.14430)
Jan 03 10:08:09 topfunky rails[4535]: Rendered shared/_flashes (0.00882)
Jan 03 10:08:09 topfunky rails[4535]: Completed in 1.70117 (0 reqs/sec) | Rendering: 1.61409 (94%) | DB: 0.02340 (1%) | 200 OK [http://localhost/products/capistrano-concepts]

Analyze

Deploy your app, or just try this out locally from the command-line.

$ pl_analyze log/development.log

Request Times Summary:          Count   Avg     Std Dev Min     Max
ALL REQUESTS:                   33      0.226   0.304   0.005   1.695

OrdersController#show:          6       0.071   0.112   0.005   0.316
ProductsController#show:        3       0.306   0.061   0.231   0.381
ProductsController#home:        2       0.318   0.068   0.249   0.386
OrdersController#index:         2       0.328   0.206   0.123   0.534
PagesController#show:           2       0.432   0.047   0.385   0.479
ProductsController#index:       1       0.279   0.000   0.279   0.279

Slowest Request Times:
        OrdersController#index took 0.534s
        PagesController#show took 0.479s
        ProductsController#home took 0.386s
        PagesController#show took 0.385s
        ProductsController#show took 0.381s

# DB times and Render times follow

rails_stat is also nice for seeing a live report of the performance of your app.

$ rails_stat log/development.log

~ 0.9 req/sec, 14.2 queries/sec, 19.9 lines/sec
~ 0.3 req/sec, 14.1 queries/sec, 17.0 lines/sec

Once more, with feeling!

Run the report in a cron task and send the results to yourself via email (see the -e flag to pl_analyze), or automate the reporting with Capistrano.

desc "Analyze Rails Log instantaneously" 
task :pl_analyze, :roles => :app do
  run "pl_analyze #{shared_path}/log/#{rails_env}.log" do |ch, st, data|
    print data
  end
end

desc "Run rails_stat" 
task :rails_stat, :roles => :app do
  stream "rails_stat #{shared_path}/log/#{rails_env}.log" 
end

For more details on Capistrano, buy the new PeepCode Capistrano Concepts screencast.

And again, from the top

For extra credit, use my Mint Pepper plugin (download) and my Mint Rails Plugin to put nightly data into the database (also requires the setup of logrotate, to be discussed later).

Note

Remember, this is not about maximum performance. These reports show you the actual performance of your app as it is being browsed, not the theoretical maximum performance.

Shameless Advert

30 comments

Leave a response

Ryan Mulligan

Followed your guide and got this error when I tryed to do pl_analyze. For some reason longest_request_name – name.length is a negative number.

Any Ideas?

cag@spoon:~/c$ pl_analyze log/development.log 
/usr/lib/ruby/gems/1.8/gems/production_log_analyzer-1.3.0/lib/production_log/analyzer.rb:381:in `*': negative argument (ArgumentError)
        from /usr/lib/ruby/gems/1.8/gems/production_log_analyzer-1.3.0/lib/production_log/analyzer.rb:381:in `pad_request_name'
        from /usr/lib/ruby/gems/1.8/gems/production_log_analyzer-1.3.0/lib/production_log/analyzer.rb:318:in `summarize'
        from /usr/lib/ruby/gems/1.8/gems/production_log_analyzer-1.3.0/lib/production_log/analyzer.rb:257:in `request_times_summary'
        from /usr/lib/ruby/gems/1.8/gems/production_log_analyzer-1.3.0/lib/production_log/analyzer.rb:280:in `report'
        from /usr/lib/ruby/gems/1.8/gems/production_log_analyzer-1.3.0/bin/pl_analyze:31
        from /usr/bin/pl_analyze:18:in `load'
        from /usr/bin/pl_analyze:18

topfunky

@Ryan: Try deleting your old log and try again with a fresh one that uses the new format (although I’m using mixed logs with success).

Also, make sure you hit a few different pages so there’s some data to work with.
topfunky

@Ryan: Argh…I’m getting that too for some older apps.

My edge and 1.2rc1 apps parse correctly, but older ones throw that same error when being parsed by pl_analyze.

I can’t see any difference in the log, but I’ll dig further and see if I can get it working with Rails 1.1 apps.
Jacob Atzen

I can see the logger removes newlines which makes backtraces in the logfile almost unreadable. Is there some reason for this or is it possible to simply prefix each line with the timestamp/pid?
topfunky

@Jacob: I believe you could move the logger code to production.rb if you only want to use this type of logging in production. The pl_analyze parser expects things to be all on one line.

But why are you reading backtraces in logfiles anyway? I use the exception_notification plugin in production and can’t remember the last time I needed to look at the logfile directly.

@Ryan: I think I found the bug and will file a patch with Eric. Basically, parser.rb approx line 148 wants to see that the “Processing” line is the first in an array for each entry. However, Rails engines and other plugins can print log lines before the Processing line. Commenting out the conditional “if entry.first ….” seems to fix it.
Ryan Mulligan

@topfunky: I tried removing log, and hitting a couple of pages. No Luck.

I am using edge revision 5831.
Ryan Mulligan

Are you saying to comment out the if and end statements and leave the body, or the entire block?
Chaz

How odd. Switching loggers worked fine with mongrel, but when I tried it out with Apache1/FastCGI, FastCGI kept on crashing.

I found replacing the call to Socket#gethostname with a hardcoded host fixed the problem. Just in case anyone else is unfortunate enough to be still using Apache1/fastcgi in 2007.

Thanks for the Poor Man’s SysLogLogger! I wanted to try out these scripts a while ago, but gave up when I saw the dependency since I got no root on my production machine.
topfunky

@Ryan: I’ve fixed it and submitted a patch to Eric. Check back in a while for an update or see the patch

@Chaz: Good to know. I’ll put a note in about that. I want to run it on some shared host apps that are on FastCGI, also.
John Topley

Geoffrey, slightly off-topic, but have you been able to successfully install Mint on a Rails Machine yet? I added the rewrite rules below to /public/.htaccess but I get a routing error when I try to access /mint/

RewriteCond %{REQUEST_URI} ^/mint.* RewriteRule .* – [L]

—Any ideas?
topfunky

@John: No, I haven’t installed PHP or Mint there yet, but that’s the same rewrite rule I’m using elsewhere. I hope to try it out on RailsMachine later this month.

In the meantime, you can also install Mint on a subdomain of another server and use that (mint.mydomain.com). You’ll just need to reference the full url in your mint include (http://mint.mydomain.com/mint/?js) and add the subdomain to the “Site domains” section in the Mint preferences.

There’s something on the Mint forums about this, but I can’t find it right now.
John Topley

Thanks Geoffrey!
Ryan Mulligan

Anyone who cares, the problem I was having with pl_analyze was having a linebreak when I copied the hodel compliant logger. People should make sure that each log entry is on one line when doing this.
Tim Lucas

@ryan and geoff: I’ve just posted a patch for the negative argument error and misc nil errors for empty log files. These two bugs are in addition to the one geoffrey’s patch fixes.

The patch is the same format as geoffery’s (you’ll need to run patch -p0 from within your lib/gems/1.8 directory)

Hopefully Eric (or another coopian) can commit the two fixes soon.
Taylor Singletary

When I turned this logger on it seems to ignore log-specific settings like… now there’s color in the production log and shows each SQL query (like in development mode)—even in production mode… Is this expected behavior? I’ve got filtered parameters and am hoping that this doesn’t do anything to them.
ed

I had to add this to my production.rb because the default level is debug and was filling up my prod logs in a hurry!

config.logger.level = Logger::INFO
nap

ever figure out why script/server forces the standard logging?
Mike

This only works for me in development and test mode. On my production server, where I’m running Apache2 and FCGI, it uses the old format. Strange.
topfunky

FastCGI may have different behavior. I’m using it with Mongrel in production, or “mongrel_rails start” in development.
James

The reason why script/server fails is because it deliberately initializes the logger (see line 50 in railties/lib/commands/servers/mongrel.rb).

It seems like commenting out this line will use the new logger when you use script/server. Furthermore, even with the line commented out and the default logger, everything looks like it’s running fine.

The ticket describing this is here – folks, please do verify this so that someone in Rails core will take notice and apply the patch :)
tommy

Hey, when I try to use the pl_analyze tool, it shows up: $pl_analyze log/development.log No requests to analyze

- I’ve downloaded my production.log and ran it using the same way and still get the error.

Using rails 1.2.3
topfunky

@tommy: Does your log look like the example above, with “rails³⁴³³²²” near the beginning of every line? pl_analyze needs that in order to be able to analyze the log.

Or, try visiting multiple controller URLs. I sometimes get weird errors when only one controller has been visited and pl_analyze can’t parse the log correctly.
Seth

I just gotta say THANK YOU for this. This kicks ass, and enabled me to track down some serious performance issues with my app.

I’m considering wrapping this into a plugin…...hrm.
topfunky

@Seth: There is a plugin, but the load order of Rails vs. plugins makes it basically impossible to have this used as the logger if loaded from a plugin.

http://topfunky.net/svn/plugins/hodel_3000_compliant_logger/
Bill

One of the concerns SyslogLogger addressed was the performance hit from the environment being evaluated last:

http://www.dotrb.com/2007/8/11/scaling-rails-with-sysloglogger

Does the Hodel3000 logger eliminate this concern as well?
houseyesredg

leaf more than little a real pruning my dad sour, and we we just
Brian

Tried this out and it worked like a champ in Rails 2.1. Thank you. i still need to look at log rotation and levels for dev vs. prod but it looks good so far.
Matthew Bergman

Lovely full feature logger. Has made palmist a blast. but how do you write to it?
Ramon

It seems that my setup isn’t able to find the library you provided. I get an error about it not being able to find the hodel_3000_compliant_logger. I have no idea too as to why… it works fine in development.
Geoffrey Grosenbach
@Ramon
- Is the logger file in your lib directory?
- Are you requiring it from environment.rb?
- For kicks, try requiring it with the absolute path to the file.
- What version of Rails?