Pastie Support Pastie or read my Pastie << self blog

#
# 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

#
# 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