1 2 3 4 5 6 7 8 9 10 11 12 13 14 15 16 17 18 19 20 21 22 23 24 25 26 27 28 29 30 31 32 33 34 35 36 37 38 39 40 41 42 43 44 45 46 47 48 49 50 51 52 53 54 55 56 57 58 59 60 61 62 63 64 65 66 67 68 69 70 71 72 73 74 75 |
# # 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
1 2 3 4 5 6 7 8 9 10 11 12 13 14 15 16 17 18 19 20 21 22 23 24 25 26 27 28 29 30 31 32 33 34 35 36 37 38 39 40 41 42 43 44 45 46 47 48 49 50 51 52 53 54 55 56 57 58 59 60 61 62 63 64 65 66 67 68 69 70 71 72 73 74 75 76 77 78 79 80 81 82 83 84 85 86 87 88 89 90 91 92 93 94 95 96 97 98 99 100 101 102 103 104 105 106 107 108 109 110 111 112 113 114 115 116 117 118 119 120 121 122 123 124 125 126 127 128 129 130 131 132 133 134 135 136 137 138 139 140 141 142 143 144 145 146 147 148 149 150 151 152 153 154 155 156 157 158 159 160 161 162 163 164 165 166 167 168 169 170 171 172 173 174 175 176 177 178 179 180 181 182 183 184 185 186 187 188 189 190 191 192 193 194 195 196 197 198 199 200 201 202 203 204 205 206 207 208 209 210 211 212 213 214 215 216 217 218 219 220 221 222 223 224 225 226 227 228 229 230 231 232 233 234 235 236 237 238 239 240 |
# # 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