Sometimes a project can get large with many lines of code and some of those parts may have some leaks. These leaks might not be bad at first, but it will eventually can eat up all the memory on a server and cause it to act slow. Then, the thins/mongrels will have to be restarted to free up the memory. A bad memory leak will require the mongrels be restarted frequently.
Sometimes the cause may be a gem that uses a C library that has memory leaks or maybe there's a problem with the way code is using a particular method. This is where Bleak House comes in handy. It's an implementation of Ruby that tracks Objects in the Ruby Heap and analyzes those Objects.
Here's some steps I took to try to track down the cause of a memory leak on a project.
Setting up the Server
Depending on how you installed your Ruby, installing the gem can be a breeze or hell. For users that compiled Ruby from source all you need to do is:
sudo gem install bleak_house
If you're on a packaged version of Ruby, like the one that comes with Leopard. I recommend installing from source and installing the gem. To install it along side of that version of Ruby requires a lot of patching to the gem files.
For Leopard, here's how I compiled Ruby. WARNING This will basically break all your gems so you will have to reinstall them.
cd /usr/local/src
wget ftp://ftp.ruby-lang.org/pub/ruby/1.8/ruby-1.8.6-p369.tar.gz
tar xzf ruby-1.8.6-p369
cd ruby-1.8.6-p369
./configure --enable-shared --enable-pthread CFLAGS=-D_XOPEN_SOURCE=1
make
sudo make install
Add your new ruby path towards the end of your ~/.bash_profile:
export PATH="/usr/local/bin:/usr/local/sbin:/usr/local/mysql/bin:$PATH"
source ~/.bash_profile
Finally, install the gem:
gem install bleak_house
After installing that gem, now you need to add this line to your envirnoment.rb:
require 'bleak_house'
Start the server using ruby-bleak-house
BLEAK_HOUSE=1 ruby-bleak-house ./script/server
Find a way to do POST and GET requests to your server to get the problem to resurface
For GETs, I would use httperf and pound the server incrementally.
httperf --hog --server www.awesomeness.site --rate=8 --num-con=800 --uri=/leaky
POSTs were tricky for this particular project. The authentication was done through a centralized server where it does some cookie magic. So, I used curl with a cookie file.
The Cookie File uses Netscape's cookie format (tab seperated). Belong is an example format
.netscape.com TRUE / FALSE 946684799 NETSCAPE_ID 100103
Here's the definition of each of those parmeters:
domain - The domain that created AND that can read the variable.
flag - A TRUE/FALSE value indicating if all machines within a given domain can access the variable. This value is set automatically by the browser, depending on the value you set for domain.
path - The path within the domain that the variable is valid for.
secure - A TRUE/FALSE value indicating if a secure connection with the domain is needed to access the variable.
expiration - The UNIX time that the variable will expire on. UNIX time is defined as the number of seconds since Jan 1, 1970 00:00:00 GMT.
name - The name of the variable.
value - The value of the variable.
Here's my cookie.txt:
# Netscape HTTP Cookie File
# http://www.netscape.com/newsref/std/cookie_spec.html
# This file was generated by libcurl! Edit at your own risk.
www.awesomeness.site TRUE / FALSE 0 _my_session BAh7BjoPc2Vzc2lvbl9pZCIlZGRjMWEyODdhMGYyYTUzOTRmNDRjMTkzNjExMWYyMDQ%3D--e853584782ddb6561c88459997ff00e6de76e292
www.awesomeness.site TRUE / FALSE 1 SERVERID
.awesomeness.site TRUE / FALSE 0 user_auth %20424%3D12dsff32dasd45097374221%7C%3B
Curl command to POST 100 times and use my cookies
for i in {1..1000}; do curl www.awesomeness.site/leak_upload/create -X POST -H "Content-Length:19" -d 'text%5Bbody%5D=abc' -b cookies.txt; done
Analyzing the Results
Stop the server and it'll start dumping some data to your /tmp/ directory:
** BleakHouse: working...
** BleakHouse: complete
** Bleakhouse: run 'bleak /tmp/bleak.22930.0.dump' to analyze.
Do exactly what it tells you to do:
bleak /tmp/bleak.22930.0.dump
My output:
Displaying top 100 most common line/class pairs
4297007 total objects
4297007 filled heap slots
3724030 free heap slots
2150566 (eval):3:String
1162682 __null__:__null__:__node__
85544 /usr/lib/ruby/gems/1.8/gems/activerecord-2.3.2/lib/active_record/connection_adapters/abstract/query_cache.rb:85:Hash
85543 /usr/lib/ruby/gems/1.8/gems/activerecord-2.3.2/lib/active_record/base.rb:1655:Hash
64865 __null__:__null__:String
64017 /usr/lib/ruby/gems/1.8/gems/activerecord-2.3.2/lib/active_record/base.rb:1651:Role
58974 /usr/lib/ruby/gems/1.8/gems/activesupport-2.3.2/lib/active_support/core_ext/blank.rb:50:String
31429 /usr/lib/ruby/gems/1.8/gems/activerecord-2.3.2/lib/active_record/attribute_methods.rb:102:String
26674 /usr/lib/ruby/gems/1.8/gems/activesupport-2.3.2/lib/active_support/callbacks.rb:180:Class
26673 /usr/lib/ruby/gems/1.8/gems/activerecord-2.3.2/lib/active_record/validations.rb:221:Hash
26673 /usr/lib/ruby/gems/1.8/gems/activerecord-2.3.2/lib/active_record/validations.rb:1050:ActiveRecord::Errors
21345 /usr/lib/ruby/gems/1.8/gems/activerecord-2.3.2/lib/active_record/associations/association_collection.rb:387:Array
21342 /usr/lib/ruby/gems/1.8/gems/activerecord-2.3.2/lib/active_record/dirty.rb:102:Hash
21338 /usr/lib/ruby/gems/1.8/gems/activerecord-2.3.2/lib/active_record/base.rb:3008:Hash
21338 /usr/lib/ruby/gems/1.8/gems/activerecord-2.3.2/lib/active_record/base.rb:2436:Hash
16094 /usr/lib/ruby/gems/1.8/gems/activerecord-2.3.2/lib/active_record/base.rb:1651:User
16010 /usr/lib/ruby/gems/1.8/gems/activerecord-2.3.2/lib/active_record/associations.rb:1277:ActiveRecord::Associations::HasManyAssociation
16004 /usr/lib/ruby/gems/1.8/gems/activerecord-2.3.2/lib/active_record/timestamp.rb:22:Time
11033 (eval):1:__node__
So, the top item is (eval):3:String. For this project, a lot of Strings Manipulation was used but it shouldn't grow that large. So I searched good old Google and found this blog post. It turns out our version of ruby on the server was 1.8.6 p114 which did have this crazy memory leaks with Strings. So, I updated ruby to 1.8.7 and String's position in the bleak dump dropped down towards the bottom of the list.
Alex,
great post. I'd really like to try this out.
Questions:
- what are the numbers in the first column of the bleak house output? Bytes? Objects?
- are those totals for the duration of the process? (rather than, like, dunno, bytes/h... nah, that's silly... nvm)
An alternative to curl and crazy cookies is Jakarta jMeter; it has a proxy that can record a browser session and often enough it just works. Slick.
Also, you can use something like --prefix=/usr/local/wacky/location --program-suffix=-bh when ./configure'ing to avoid clobbering gems and stuff (gives you stuff like gem-bh, irb-bh and ruby-bh).
Sweet! :)