production_log_analyzer version 1.5.0 has been released!
Eric Hodel | Wed, 16 May 2007 21:43:57 GMT
production_log_analyzer provides three tools to analyze log files created by SyslogLogger. pl_analyze for getting daily reports, action_grep for pulling log lines for a single action and action_errors to summarize errors with counts.
http://seattlerb.rubyforge.org/production_log_analyzer
sudo gem install production_log_analyzer
Changes:
1.5.0
- Fixed empty log bug. Patch by Tim Lucas.
- Fixed bug where sometimes lines would be logged before the Processing line. Patch by Geoff Grosenbach.
rails_analyzer_tools version 1.4.0 has been released!
Eric Hodel | Wed, 16 May 2007 21:41:45 GMT
Rails Analyzer Tools contains Bench, a simple web page benchmarker, Crawler, a tool for beating up on web sites, RailsStat, a tool for monitoring Rails web sites, and IOTail, a tail(1) method for Ruby IOs.
http://seattlerb.rubyforge.org/rails_analyzer_tools
sudo gem install rails_analyzer_tools
Changes:
1.4.0
- Moved to seattlerb project.
SyslogLogger 1.4.0 Released
Eric Hodel | Wed, 09 May 2007 03:44:01 GMT
SyslogLogger version 1.4.0 has been released!
http://seattlerb.rubyforge.org/SyslogLoggerSyslogLogger is a Logger replacement that logs to syslog. It is almost drop-in with a few caveats.
Changes:
1.4.0 / 2007-05-08
- Split from rails_analyzer_tools.
- Added eh methods for compatibility with Logger.
- Added syslog-ng instructions. Patch by Tom Lianza.
- Fixed require in documentation. Reported by Gianni Jacklone.
Process Growth with Railsbench's GC patch
Eric Hodel | Tue, 17 Apr 2007 19:57:00 GMT
My friend Kevin Watt who runs Allpoetry had me help him diagnose problems with memory consumption on his Rails application. He was seeing processes suddenly jump in size by 46MB, when the processes were already over 100MB to begin with. After instrumenting to locate the growth in one innocuous method we went through his patches to Rails.
One of the patches Kevin was using was the Railsbench GC patch. It turns out that this patch has some very useful instrumenting of its own, so I had Kevin call GC.dump in that method, and he got the following values:
HEAP[ 0]: size= 650000 HEAP[ 1]: size=1170001
This means there are slots for 1820001 objects in his process. If you end up creating that many objects Ruby will create a new chunk of object slots by multiplying the previous allocation by 1.8 and adding 1.
The next set of slots would contain slots for 2106002 objects. Each slot takes up 20 bytes of memory, so roughly 40MB of memory would be used. Kevin ended up pulling the patch and now has his processes holding on to around 70MB RSS each, rather than 100 or more.
The Railsbench page contains this note about memory consumption alongside the GC patch:
In addition, a patch for the ruby garbage collector is provided, which can be used to reduce the amount of time spent doing garbage collection, trading memory for speed, as usual (see file GCPATCH for details).
The initial size of the slots can be tuned, but we neglected to explore that option. In large-memory situations the patch's behavior is too negative. Be sure to follow the instructions to the GCPATCH file to get proper operation. Also, monitor your application's memory usage as the patch may cause your machine to use swap when too many objects are being used or if you've tuned improperly.
Test Profiling by Lines Logged
Eric Hodel | Mon, 22 Jan 2007 23:41:00 GMT
At work I've been cleaning up the tests and trying to make them run faster. One way of doing this is profiling the tests and fixing the slow spots. That only works so well, especially if there's lots of duplication or extra work in the tests. With Rails you can go about this a different way, since you have a second source of information on your tests' operation, the log file.
I added the following code to test/test_helper.rb:
raise 'require\'d test/test_helper twice!, you broke it!' if
ENV['RAILS_ENV'] == 'test'At the very top, even above ENV["RALIS_ENV"] = "test" to make sure that the hack to Test::Unit::TestCase below happens only once, then the magic to figure out which test outputs which log lines:
class Test::Unit::TestCase
alias unlogged_run run
def run(result, &block)
RAILS_DEFAULT_LOGGER.debug "RUNNING #{self.class} #{@method_name}"
unlogged_run result, &block
end
end if ENV['PROFILE_LOG']Each test run will be prefixed with text like RUNNING SomeTest test_blah which I can then run this script on:
#!/usr/local/bin/ruby -w
test = nil
tests = Hash.new 0
File.open 'log/test.log' do |fp|
fp.each_line do |line|
if line.strip =~ /^RUNNING (.*)/ then
test = $1
else
tests[test] += 1
end
end
end
tests.sort_by { |test, count| -count }.each do |test, count|
puts "%5d %s" % [count, test]
end
To get the profile information, I run:
rake log:clear; PROFILE_LOG=y rake && script/count_logs
When run on Firebrigade, I get the following output (top 10 only):
130 ProjectViewTest test_show 74 DummyControllerTest test_error_500 59 OwnerTest test_class_owner_count 42 ProjectControllerTest test_index 39 HomeControllerTest test_index_no_builds 38 RestControllerTest test_add_build 35 ProjectControllerTest test_show_no_versions 35 ProjectControllerTest test_search_many_matches 34 RestControllerTest test_add_project 33 RestControllerTest test_add_version
Now I can quickly discover good candidates for refactoring. #test_error_500 above dumps an email into the logs, so it is a bogus result. That leaves ProjectViewTest#test_show as a candidate for simplification or refactoring.
Controlling Rails Process Size
Eric Hodel | Wed, 13 Sep 2006 07:44:00 GMT
Now that Ruby 1.8.5 is out setting process limits is easier than ever before! We used to use a small shell script run from cron to kill processes that got too big for their britches. Unfortunately this was difficult to do both well and simply (we chose simply).
Now, in Ruby 1.8.5, we have Process::setrlimit:
$ ri Process::setrlimit
----------------------------------------------------- Process::setrlimit
Process.setrlimit(resource, cur_limit, max_limit) => nil
Process.setrlimit(resource, cur_limit) => nil
------------------------------------------------------------------------
Sets the resource limit of the process. cur_limit means current
(soft) limit and max_limit means maximum (hard) limit.
If max_limit is not given, cur_limit is used.
resource indicates the kind of resource to limit. The list of
resources are OS dependent. Ruby may support following resources.
Process::RLIMIT_COREcore size (bytes) (SUSv3)
[...]
Process::RLIMIT_RSSresident memory size (bytes) (4.2BSD, GNU/Linux)
There's a bunch more in there, but those were the two I was most interested in using. I really don't want cores, and I don't want my application processes to grow too big, but I want cron jobs to get as big as they need to get.
At the top of config/environment.rb above everything else I have:
Process.setrlimit Process::RLIMIT_RSS, 1024*1024*150, Process::RLIM_INFINITYAnd to eliminate core dumps, in config/environments/production.rb I have:
Process.setrlimit Process::RLIMIT_CORE, 0, Process::RLIM_INFINITYKeeping the hard limit at infinity allows me to increase the limit at a later date, for example when running cron jobs. To give cron jobs different limits I've added a config/environments/cron.rb that slurps the production values then overrides as necessary:
eval File.read("#{RAILS_ROOT}/config/environments/production.rb")
CachedModel.use_local_cache = false
# Cron jobs can use a much memory as they want.
Process.setrlimit Process::RLIMIT_RSS, Process::RLIM_INFINITY
(That eval is in there because of that's the same hack that Rails::Initializer uses to expose config in environment files, bleh.)
render_tree for Rails
Eric Hodel | Fri, 08 Sep 2006 18:02:00 GMT
Spelunking deep in unfamiliar Rails view code? Flushing out the cobwebs and updating your code? Don't know what gets rendered when?
I have a solution for you:
class ActionView::Base
alias plain_render render
RENDERS = [:partial, :template, :file, :action, :text, :inline, :nothing,
:update]
def render(*args)
@level ||= 0
print ' ' * @level
case args.first
when String then
p args.first
when Hash then
hash = args.first
found = hash.keys & RENDERS
if found.length == 1 then
puts "%p => %p" % [found.first, hash[found.first]]
else
raise "Dunno: %p" % [hash]
end
else
raise "Dunno: %p" % [args]
end
@level += 1
result = plain_render(*args)
@level -= 1
result
end
endDrop that in test/render_tree.rb and require it in your tests when you want to see a tree like this:
$ ruby test/views/things_view_test.rb -n test_view
Loaded suite test/views/things_view_test
Started
"things/things-header"
"things/sidebar"
"widgets/forms/goal_form"
:partial => "widgets/sidenav_boxes/invite_and_edit"
"widgets/sidenav_boxes/_invite_and_edit"
:partial => "widgets/forms/edit_worth_doing_form"
"widgets/forms/_edit_worth_doing_form"
:partial => "widgets/sidenav_boxes/tags"
"widgets/sidenav_boxes/_tags"
:partial => "widgets/sidenav_boxes/popular_places"
"widgets/sidenav_boxes/_popular_places"
:partial => "widgets/sidenav_boxes/google_ads"
"widgets/sidenav_boxes/_google_ads"
:partial => "widgets/sidenav_boxes/find_help"
"widgets/sidenav_boxes/_find_help"
:partial => "widgets/sidenav_boxes/people_who_reached_this_goal"
"widgets/sidenav_boxes/_people_who_reached_this_goal"
:partial => "widgets/sidenav_boxes/quotation"
"widgets/sidenav_boxes/_quotation"
:partial => "widgets/sidenav_boxes/goal_created_by"
"widgets/sidenav_boxes/_goal_created_by"
"widgets/general/post_add_messages"
"things/shared_body"
:partial => "widgets/goals_gallery_teaser"
"widgets/_goals_gallery_teaser"
:partial => "entries_bucket"
"things/_entries_bucket"
"widgets/forms/related_goals"
.
Finished in 1.205494 seconds.
1 tests, 7 assertions, 0 failures, 0 errors
(I think I'll end up throwing this into ZenTest.)
Memory leaks, cached_model and backend jobs
Eric Hodel | Thu, 24 Aug 2006 21:08:36 GMT
One of my long-running problems with Rails (and Ruby in general) is that it’s difficult to debug memory leaks. I’ve had a number of cases where I’ve stuck something into a long-lived array or hash and discovered much later that my Ruby process was eating over 100 MB of RAM. While ps makes it easy to see when Ruby’s using lots of RAM, actually figuring out where it went is a lot harder.[...] I asked the Seattle Ruby Group for help, and Ryan Davis gave me a quick little memory leak spotter that he uses. I made a few additions to it, and it helped me discover that my Typo development tree was leaking 1-3 strings per hit
—Memory leak profiling with Rails via scottstuff: Memory leak profiling with Rails
I just used Scott and Ryan’s script to find a memory leak in our backend jobs related to cached_model. We have the local cache enabled for for our sites because we reset the cache every page request. In our backend jobs we don’t clear the local cache so we end up with a Hash that holding every ActiveRecord object we’ve ever retrieved from the database.
So if the warnings in the documentation weren’t enough, here it is again. If you’re using CachedModel in a backend job, be sure to disable the local cache or call cache_reset periodically to allow items to be garbage collected.
Ruby, Rails, Test::Rails Cheat Sheet
Eric Hodel | Thu, 24 Aug 2006 18:07:39 GMT
A cheat sheet that shows the assertions in Test::Unit, the ones added by Rails, and the ones further added by Test::Rails (part of the ZenTest gem).Ruby, Rails, Test::Rails Cheat Sheet
Subclassing vs include
Eric Hodel | Wed, 23 Aug 2006 18:15:00 GMT
In memcached Basics for Rails Rob Sanheim asked:[W]hy make the cached model a class to extend instead of a module? Whether or not a model is cached should be an implementation detail, and shouldn’t define the hierarchy for a class. I know I would rather not use the power of (single!) inheritance just to cache something, when a mix-in should be plenty powerful to do it.
The short answer is:
Using a class the correct way to overlay features on top of another class.
Here’s my long answer:
When you use a class you get super, and super is a beautiful thing. It automatically walks your class’ ancestors and calls the right method in the right order.
A module doesn’t have this property so you can’t use it to overlay features on top of a class. The class’ implementation will always be called before the module’s implementation.
Now you’re going to say something about using alias to shuffle methods around. You could do that, but you’ll have to do this for each method you want to overlay (five in CachedModel) which involves lots of extra typing “do_the_thingy_without_the_stuff” that you could have had for free (and more-prettily) with “super”.
You also get another problem that may cause subtle bugs. When you use alias to overlay features the order of execution is dependent upon the order the files are required in! Intentionally writing code where the behavior may change file load order gives me the heebie-jeebies.
Having to do all that work to get the benefits of a subclass tells me that a module isn’t powerful enough to do what a subclass can, so a module isn’t the right way to add a cache.
I avoid* using modules to overlay features of a class, but do use them to add orthogonal or complementary features. Typically when I write a module it ends up being used like Comparable, Enumerable or Singleton. When I need to do something invasive a subclass is better.
Finally, making the argument that adding caching to ActiveRecord::Base via a subclass shouldn’t define the inheritance argument is very subjective. I could justify using a subclass by saying that ActiveRecord is a data storage class, and CachedModel is just another data store. If you want caching, inherit from CachedModel. If you don’t want caching, inherit from ActiveRecord::Base.
Except void or where prohibited by law. Your milage may vary. Break glass in case of emergency.
Articles