Wrap text
#
# Testing a simple Rails app for memory leaks
# testing done with Rails 2.0.2, MacOS 10.4.11, Ruby 1.8.6_p111
#
# The following is a shell script to recreate the test:
#
rails leaktest
cd leaktest
script/generate scaffold comment name:string body:text
RAILS_ENV=production rake db:migrate
RAILS_ENV=production script/server
#
# *** STOP HERE ***
#
# open another terminal window
# find the process id for the running rails instance with the ps
# command and replace the process id below with the real process id
#
cd leaktest
PID=4815
# display real memory used before first request
ps -p$PID -Orss
# display real memory used after 4 request to static hello page
# followed by 4 requests to list of comments
# the display of the comment body is truncated to 40
# characters like this: <%=h truncate(comment.body, 40) %>
# start measuring with 0 comments
curl --silent http://localhost:3000 >/dev/null; ps -p$PID -Orss
curl --silent http://localhost:3000 >/dev/null; ps -p$PID -Orss
curl --silent http://localhost:3000 >/dev/null; ps -p$PID -Orss
curl --silent http://localhost:3000 >/dev/null; ps -p$PID -Orss
curl --silent http://localhost:3000/comments >/dev/null; ps -p$PID -Orss
curl --silent http://localhost:3000/comments >/dev/null; ps -p$PID -Orss
curl --silent http://localhost:3000/comments >/dev/null; ps -p$PID -Orss
curl --silent http://localhost:3000/comments >/dev/null; ps -p$PID -Orss
# now 100 comments
time RAILS_ENV=production script/runner 'body = "x"*1024; 100.times {|i| Comment.create(:name => "comment#{i}", :body => body)}'
curl --silent http://localhost:3000 >/dev/null; ps -p$PID -Orss
curl --silent http://localhost:3000 >/dev/null; ps -p$PID -Orss
curl --silent http://localhost:3000 >/dev/null; ps -p$PID -Orss
curl --silent http://localhost:3000 >/dev/null; ps -p$PID -Orss
curl --silent http://localhost:3000/comments >/dev/null; ps -p$PID -Orss
curl --silent http://localhost:3000/comments >/dev/null; ps -p$PID -Orss
curl --silent http://localhost:3000/comments >/dev/null; ps -p$PID -Orss
curl --silent http://localhost:3000/comments >/dev/null; ps -p$PID -Orss
# now 1000 comments
time RAILS_ENV=production script/runner 'body = "x"*1024; 900.times {|i| Comment.create(:name => "comment#{i}", :body => body)}'
curl --silent http://localhost:3000 >/dev/null; ps -p$PID -Orss
curl --silent http://localhost:3000 >/dev/null; ps -p$PID -Orss
curl --silent http://localhost:3000 >/dev/null; ps -p$PID -Orss
curl --silent http://localhost:3000 >/dev/null; ps -p$PID -Orss
curl --silent http://localhost:3000/comments >/dev/null; ps -p$PID -Orss
curl --silent http://localhost:3000/comments >/dev/null; ps -p$PID -Orss
curl --silent http://localhost:3000/comments >/dev/null; ps -p$PID -Orss
curl --silent http://localhost:3000/comments >/dev/null; ps -p$PID -Orss
# now 10000 comments
time RAILS_ENV=production script/runner 'body = "x"*1024; 9000.times {|i| Comment.create(:name => "comment#{i}", :body => body)}'
curl --silent http://localhost:3000 >/dev/null; ps -p$PID -Orss
curl --silent http://localhost:3000 >/dev/null; ps -p$PID -Orss
curl --silent http://localhost:3000 >/dev/null; ps -p$PID -Orss
curl --silent http://localhost:3000 >/dev/null; ps -p$PID -Orss
curl --silent http://localhost:3000/comments >/dev/null; ps -p$PID -Orss
curl --silent http://localhost:3000/comments >/dev/null; ps -p$PID -Orss
curl --silent http://localhost:3000/comments >/dev/null; ps -p$PID -Orss
curl --silent http://localhost:3000/comments >/dev/null; ps -p$PID -Orss
# now delete all the comments and see what happens
time RAILS_ENV=production script/runner 'Comment.delete_all'
curl --silent http://localhost:3000 >/dev/null; ps -p$PID -Orss
curl --silent http://localhost:3000 >/dev/null; ps -p$PID -Orss
curl --silent http://localhost:3000 >/dev/null; ps -p$PID -Orss
curl --silent http://localhost:3000 >/dev/null; ps -p$PID -Orss
curl --silent http://localhost:3000/comments >/dev/null; ps -p$PID -Orss
curl --silent http://localhost:3000/comments >/dev/null; ps -p$PID -Orss
curl --silent http://localhost:3000/comments >/dev/null; ps -p$PID -Orss
curl --silent http://localhost:3000/comments >/dev/null; ps -p$PID -Orss
Here's the data produced
#
# After startup the rails app uses 51748 in real memory:
#
# $ ps -p$PID -Orss
# PID RSS TT STAT TIME COMMAND
# 4815 51748 q9 S+ 0:03.96 ruby script/server
#
# After the first request the app is now 28 bytes more memory:
#
# $ curl --silent http://localhost:3000 >/dev/null; ps -p$PID -Orss
# PID RSS TT STAT TIME COMMAND
# 4815 51776 q9 S+ 0:03.96 ruby script/server
#
# The memory used rises after each of the next three requests by
# a small amount: 20, 20, and 24 bytes.
#
# $ curl --silent http://localhost:3000 >/dev/null; ps -p$PID -Orss
# PID RSS TT STAT TIME COMMAND
# 4815 51796 q9 S+ 0:03.96 ruby script/server
# $ curl --silent http://localhost:3000 >/dev/null; ps -p$PID -Orss
# PID RSS TT STAT TIME COMMAND
# 4815 51816 q9 S+ 0:03.96 ruby script/server
# $ curl --silent http://localhost:3000 >/dev/null; ps -p$PID -Orss
# PID RSS TT STAT TIME COMMAND
# 4815 51840 q9 S+ 0:03.96 ruby script/server
#
# The memory used for the app rises slowly in next four requests
# which access the database but strangely they all average about
# 600 bytes less than the requests to the hello page.
#
# $ curl --silent http://localhost:3000/comments >/dev/null; ps -p$PID -Orss
# PID RSS TT STAT TIME COMMAND
# 4815 51248 q9 S+ 0:04.22 ruby script/server
# $ curl --silent http://localhost:3000/comments >/dev/null; ps -p$PID -Orss
# PID RSS TT STAT TIME COMMAND
# 4815 51256 q9 S+ 0:04.23 ruby script/server
# $ curl --silent http://localhost:3000/comments >/dev/null; ps -p$PID -Orss
# PID RSS TT STAT TIME COMMAND
# 4815 51264 q9 S+ 0:04.23 ruby script/server
# $ curl --silent http://localhost:3000/comments >/dev/null; ps -p$PID -Orss
# PID RSS TT STAT TIME COMMAND
# 4815 51272 q9 S+ 0:04.24 ruby script/server
#
# Add 100 comments with each comment having a body with 1024 characters.
# This request to the database takes about 3s.
#
# $ # now 100 comments
# $ time RAILS_ENV=production script/runner 'body = "x"*1024; 100.times {|i| Comment.create(:name => "comment#{i}", :body => body)}'
#
# real 0m3.132s
# user 0m1.981s
# sys 0m0.887s
#
# The memory used by each of these requests now rises constantly by 8 bytes.
#
# $ curl --silent http://localhost:3000 >/dev/null; ps -p$PID -Orss
# PID RSS TT STAT TIME COMMAND
# 4815 51280 q9 S+ 0:04.24 ruby script/server
# $ curl --silent http://localhost:3000 >/dev/null; ps -p$PID -Orss
# PID RSS TT STAT TIME COMMAND
# 4815 51288 q9 S+ 0:04.24 ruby script/server
# $ curl --silent http://localhost:3000 >/dev/null; ps -p$PID -Orss
# PID RSS TT STAT TIME COMMAND
# 4815 51296 q9 S+ 0:04.25 ruby script/server
# $ curl --silent http://localhost:3000 >/dev/null; ps -p$PID -Orss
# PID RSS TT STAT TIME COMMAND
# 4815 51304 q9 S+ 0:04.25 ruby script/server
#
# Accessing a list of 100 comments causes the app to increase from
# 51k to 55k.
#
# $ curl --silent http://localhost:3000/comments >/dev/null; ps -p$PID -Orss
# PID RSS TT STAT TIME COMMAND
# 4815 51976 q9 S+ 0:04.30 ruby script/server
# $ curl --silent http://localhost:3000/comments >/dev/null; ps -p$PID -Orss
# PID RSS TT STAT TIME COMMAND
# 4815 54380 q9 S+ 0:04.34 ruby script/server
# $ curl --silent http://localhost:3000/comments >/dev/null; ps -p$PID -Orss
# PID RSS TT STAT TIME COMMAND
# 4815 54632 q9 S+ 0:04.47 ruby script/server
# $ curl --silent http://localhost:3000/comments >/dev/null; ps -p$PID -Orss
# PID RSS TT STAT TIME COMMAND
# 4815 55176 q9 S+ 0:04.51 ruby script/server
#
# Add 900 more comments for a total of 1000.
# This request to the database takes about 7s.
#
# $ # now 1000 comments
# $ time RAILS_ENV=production script/runner 'body = "x"*1024; 900.times {|i| Comment.create(:name => "comment#{i}", :body => body)}'
#
# real 0m7.270s
# user 0m3.243s
# sys 0m1.798s
#
# The memory usage stays stable at around 55k but each request
# also increases memory by 8 bytes.
#
# $ curl --silent http://localhost:3000 >/dev/null; ps -p$PID -Orss
# PID RSS TT STAT TIME COMMAND
# 4815 55184 q9 S+ 0:04.52 ruby script/server
# $ curl --silent http://localhost:3000 >/dev/null; ps -p$PID -Orss
# PID RSS TT STAT TIME COMMAND
# 4815 55192 q9 S+ 0:04.52 ruby script/server
# $ curl --silent http://localhost:3000 >/dev/null; ps -p$PID -Orss
# PID RSS TT STAT TIME COMMAND
# 4815 55200 q9 S+ 0:04.52 ruby script/server
# $ curl --silent http://localhost:3000 >/dev/null; ps -p$PID -Orss
# PID RSS TT STAT TIME COMMAND
# 4815 55208 q9 S+ 0:04.53 ruby script/server
#
# Accessing a list of 1000 comments causes the app to increase from
# 55k to aproximately 70k. I find it interesting that after the last
# request memory usage dropped by about 3k (5%)
#
# $ curl --silent http://localhost:3000/comments >/dev/null; ps -p$PID -Orss
# PID RSS TT STAT TIME COMMAND
# 4815 64808 q9 S+ 0:05.25 ruby script/server
# $ curl --silent http://localhost:3000/comments >/dev/null; ps -p$PID -Orss
# PID RSS TT STAT TIME COMMAND
# 4815 70276 q9 S+ 0:05.89 ruby script/server
# $ curl --silent http://localhost:3000/comments >/dev/null; ps -p$PID -Orss
# PID RSS TT STAT TIME COMMAND
# 4815 72612 q9 S+ 0:06.52 ruby script/server
# $ curl --silent http://localhost:3000/comments >/dev/null; ps -p$PID -Orss
# PID RSS TT STAT TIME COMMAND
# 4815 69536 q9 S+ 0:07.22 ruby script/server
#
#
# Add 9000 more comments for a total of 1000.
# This request to the database takes about 57s.
#
# $ # now 10000 comments
# $ time RAILS_ENV=production script/runner 'body = "x"*1024; 9000.times {|i| Comment.create(:name => "comment#{i}", :body => body)}'
#
# real 0m57.299s
# user 0m17.476s
# sys 0m9.861s
#
# As long as we aren't accessing the database the memory
# usage stays stable at around 69k but each request
# still also increases memory by 8 bytes.
#
# $ curl --silent http://localhost:3000 >/dev/null; ps -p$PID -Orss
# PID RSS TT STAT TIME COMMAND
# 4815 69544 q9 R+ 0:07.32 ruby script/server
# $ curl --silent http://localhost:3000 >/dev/null; ps -p$PID -Orss
# PID RSS TT STAT TIME COMMAND
# 4815 69552 q9 S+ 0:07.32 ruby script/server
# $ curl --silent http://localhost:3000 >/dev/null; ps -p$PID -Orss
# PID RSS TT STAT TIME COMMAND
# 4815 69560 q9 S+ 0:07.32 ruby script/server
# $ curl --silent http://localhost:3000 >/dev/null; ps -p$PID -Orss
# PID RSS TT STAT TIME COMMAND
# 4815 69568 q9 S+ 0:07.32 ruby script/server
#
# I found this data confusing so ran more tests. After the first four tests
# the memory usage alternated between 236k and 201k.
#
# $ curl --silent http://localhost:3000/comments >/dev/null; ps -p$PID -Orss
# PID RSS TT STAT TIME COMMAND
# 4815 155272 q9 S+ 0:13.37 ruby script/server
# $ curl --silent http://localhost:3000/comments >/dev/null; ps -p$PID -Orss
# PID RSS TT STAT TIME COMMAND
# 4815 194804 q9 S+ 0:19.00 ruby script/server
# $ curl --silent http://localhost:3000/comments >/dev/null; ps -p$PID -Orss
# PID RSS TT STAT TIME COMMAND
# 4815 233648 q9 S+ 0:24.66 ruby script/server
# $ curl --silent http://localhost:3000/comments >/dev/null; ps -p$PID -Orss
# PID RSS TT STAT TIME COMMAND
# 4815 201140 q9 S+ 0:30.35 ruby script/server
# $ curl --silent http://localhost:3000/comments >/dev/null; ps -p$PID -Orss
# PID RSS TT STAT TIME COMMAND
# 4815 236428 q9 S+ 0:36.08 ruby script/server
# $ curl --silent http://localhost:3000/comments >/dev/null; ps -p$PID -Orss
# PID RSS TT STAT TIME COMMAND
# 4815 201140 q9 S+ 0:41.77 ruby script/server
# $ curl --silent http://localhost:3000/comments >/dev/null; ps -p$PID -Orss
# PID RSS TT STAT TIME COMMAND
# 4815 201100 q9 S+ 0:47.35 ruby script/server
# $ curl --silent http://localhost:3000/comments >/dev/null; ps -p$PID -Orss
# PID RSS TT STAT TIME COMMAND
# 4815 236428 q9 S+ 0:53.01 ruby script/server
# $ curl --silent http://localhost:3000/comments >/dev/null; ps -p$PID -Orss
# PID RSS TT STAT TIME COMMAND
# 4815 201100 q9 S+ 0:58.72 ruby script/server
# $ curl --silent http://localhost:3000/comments >/dev/null; ps -p$PID -Orss
# PID RSS TT STAT TIME COMMAND
# 4815 201140 q9 S+ 1:04.08 ruby script/server
# $ curl --silent http://localhost:3000/comments >/dev/null; ps -p$PID -Orss
# PID RSS TT STAT TIME COMMAND
# 4815 236428 q9 S+ 1:09.91 ruby script/server
# $ curl --silent http://localhost:3000/comments >/dev/null; ps -p$PID -Orss
# PID RSS TT STAT TIME COMMAND
# 4815 218724 q9 S+ 1:15.60 ruby script/server
#
# It only took 3s to delete all the comments. The ActiveRecord
# method delete_all removes all the records with direct SQL rather
# than instantiating any ActiveRecord objects and is much faster
# than the method destroy_all.
#
# $ time RAILS_ENV=production script/runner 'Comment.delete_all'
#
# real 0m3.719s
# user 0m1.927s
# sys 0m0.876s
#
# The app is still basically stuck at 218k but the next four
# accesses to the hello page still in crease by 8 bytes with
# each request.
#
# $ curl --silent http://localhost:3000 >/dev/null; ps -p$PID -Orss
# PID RSS TT STAT TIME COMMAND
# 4815 218724 q9 S+ 1:18.93 ruby script/server
# $ curl --silent http://localhost:3000 >/dev/null; ps -p$PID -Orss
# PID RSS TT STAT TIME COMMAND
# 4815 218732 q9 S+ 1:18.93 ruby script/server
# $ curl --silent http://localhost:3000 >/dev/null; ps -p$PID -Orss
# PID RSS TT STAT TIME COMMAND
# 4815 218740 q9 S+ 1:18.93 ruby script/server
# $ curl --silent http://localhost:3000 >/dev/null; ps -p$PID -Orss
# PID RSS TT STAT TIME COMMAND
# 4815 218748 q9 S+ 1:18.93 ruby script/server
#
# The same increase of 8 bytes with each request also shows up when
# accessing the database. I don't understand why the application is
# still taking 218k -- it seems that about 140k of that could be
# garbage collected.
#
# $ curl --silent http://localhost:3000/comments >/dev/null; ps -p$PID -Orss
# PID RSS TT STAT TIME COMMAND
# 4815 218756 q9 S+ 1:18.94 ruby script/server
# $ curl --silent http://localhost:3000/comments >/dev/null; ps -p$PID -Orss
# PID RSS TT STAT TIME COMMAND
# 4815 218764 q9 S+ 1:18.95 ruby script/server
# $ curl --silent http://localhost:3000/comments >/dev/null; ps -p$PID -Orss
# PID RSS TT STAT TIME COMMAND
# 4815 218772 q9 S+ 1:18.95 ruby script/server
# $ curl --silent http://localhost:3000/comments >/dev/null; ps -p$PID -Orss
# PID RSS TT STAT TIME COMMAND
# 4815 218780 q9 S+ 1:18.95 ruby script/server
Pastie
