Pastie Show Pastie some love

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

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