Pastie now auto-senses if line-wrap is a bad or good idea. Feedback?
## mark a section (Learn more)
This paste will be private.
# # 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
Pasted February 20, 2008 8:25PM EDT
by stepheneb