Rails 内存泄露检测：实践一

Posted by devon on December 30th, 2007 filed in 部署与优化

在服务器运行在development模式下式，发现mongrel进程所占用的内存迅速上升，怀疑文件上传引起内存泄露（项目中有大文件上传的应用），以下是测试过程。

服务器环境：

1
2
3
4
5
6
7
8
9
10
11
12
13
14
15
16

 
rails2@server:~$ cat /proc/version
 
Linux version 2.6.16.29-xen (shand@endor) (gcc version 3.4.4 20050314 (prerelease) (Debian 3.4.3-13)) #3 SMP Sun Oct 15 13:15:34 BST 2006
 
rails2@server:~$ ruby -v
 
ruby 1.8.6 (2007-03-13 patchlevel 0) [x86_64-linux]
 
rails2@server:~$ gem -v
 
0.9.4
 
rails2@server:~$ rails -v
 
Rails 2.0.2

Step 1: use valgrind to check the mongrel
安装

1
2
3
4
5
6
7
8
9
10
11
12

 
wget http://valgrind.org/downloads/valgrind-3.3.0.tar.bz2
 
(http://valgrind.org/downloads/current.html#current)tar jxf valgrind-3.3.0.tar.bz2
 
cd valgrind-3.3.0
 
./configure
 
make
 
sudo make install

使用

1
2
3
4

 
valgrind –tool=memcheck program_namecd project_path
 
valgrind –tool=memcheck mongrel_rails start -p 3000 -P log/mongrel.3000.pid

一系列操作后，中断mongrel，获取到如下结果：

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

 
** INT signal received.
 
==13134==
 
==13134== ERROR SUMMARY: 2130785 errors From 130 contexts (suppressed: 2 From 1)
 
==13134== malloc/free: in use at exit: 42,952,786 bytes in 256,684 blocks.
 
==13134== malloc/free: 3,271,446 allocs, 3,014,762 frees, 195,599,435 bytes allocated.
 
==13134== For counts of detected errors, rerun with: -v
 
==13134== searching for pointers to 256,684 not-freed blocks.
 
==13134== checked 47,374,288 bytes.
 
==13134==
 
==13134== LEAK SUMMARY:
 
==13134==    definitely lost: 173,745 bytes in 2,595 blocks.
 
==13134==      possibly lost: 41,456 bytes in 674 blocks.
 
==13134==    still reachable: 42,737,585 bytes in 253,415 blocks.
 
==13134==         suppressed: 0 bytes in 0 blocks.
 
==13134== Rerun with –leak-check=full to see details of leaked memory.

Step 2: memory_profiler
在项目的 lib 下增加 memory_profiler.rb，文件内容为

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

 
# This is a memory profiler for Ruby. Once started, it runs in a thread in the
 
# background, periodically inspecting Ruby's ObjectSpace to look for new
 
# objects and printing a count of objects added and removed since the previous
 
# cycle.
 
#
 
# To use the profiler, do something like this:
 
#
 
#   require 'memory_profiler'
 
#
 
#   MemoryProfiler.start
 
#
 
# The profiler will write logs to ./log/memory_profiler.log.
 
#
 
# If you start MemoryProfiler with the ':string_debug => true' option, then it
 
# will dump a list of all strings in the app into the log/ directory after
 
# each cycle.  You can then use 'diff' to spot which strings were added
 
# between runs.
 
class MemoryProfiler
 
  DEFAULTS = {:delay => 10, :string_debug => false}  def self.start(opt={})
 
    opt = DEFAULTS.dup.merge(opt)
 
Thread.new do
 
      prev = Hash.new(0)
 
      curr = Hash.new(0)
 
      curr_strings = []
 
      delta = Hash.new(0)
 
file = File.open('log/memory_profiler.log','w')
 
loop do
 
        begin
 
          GC.start
 
          curr.clear
 
curr_strings = [] if opt[:string_debug]
 
ObjectSpace.each_object do |o|
 
            curr[o.class] += 1 #Marshal.dump(o).size rescue 1
 
            if opt[:string_debug] and o.class == String
 
              curr_strings.push o
 
            end
 
          end
 
if opt[:string_debug]
 
            File.open("log/memory_profiler_strings.log.#{Time.now.to_i}",'w') do |f|
 
              curr_strings.sort.each do |s|
 
                f.puts s
 
              end
 
            end
 
            curr_strings.clear
 
          end
 
delta.clear
 
          (curr.keys + delta.keys).uniq.each do |k,v|
 
            delta[k] = curr[k]-prev[k]
 
          end
 
file.puts "Top 20"
 
          delta.sort_by { |k,v| -v.abs }[0..19].sort_by { |k,v| -v}.each do |k,v|
 
            file.printf "%+5d: %s (%d)\n", v, k.name, curr[k] unless v == 0
 
          end
 
          file.flush
 
delta.clear
 
          prev.clear
 
          prev.update curr
 
          GC.start
 
        rescue Exception => err
 
          STDERR.puts "** memory_profiler error: #{err}"
 
        end
 
        sleep opt[:delay]
 
      end
 
    end
 
  end
 
end

在 config/enviroment.rb 的未尾加上
require ‘memory_profiler’
MemoryProfiler.start

在 development 模式下重新启动项目，等待一会到分配与回收新的对象已趋于稳定，然后开始测试：

1
2
3
4
5
6
7
8
9
10
11
12
13
14
15
16
17

cd project_path
 
mongrel_rails start -p 3000 -P log/mongrel.3000.pidTop 20
 
   -3: String (71128)
 
Top 20
 
   +3: String (71131)
 
Top 20
 
   -2: String (71129)
 
Top 20
 
   +2: String (71131)

第一次测试
请求一

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

 
Top 20
 
+1940: String (73071)
 
 +203: Regexp (1327)
 
  +65: Hash (669)
 
  +32: Class (1149)
 
  +32: Module (435)
 
  +11: Time (199)
 
   +8: ActionController::Filters::ClassMethods::SymbolFilter (8)
 
   +6: Set (23)
 
   +6: StringIO (6)
 
   +5: ActionController::Filters::ClassMethods::BeforeFilterProxy (5)
 
   +5: ActiveRecord::ConnectionAdapters::MysqlColumn (5)
 
   +3: ActionController::Filters::ClassMethods::AfterFilterProxy (3)
 
   +3: Proc (390)
 
   +3: GetText::TextDomainManager (3)
 
   +3: HashWithIndifferentAccess (3)
 
   +3: Float (54)
 
   +2: Mongrel::HeaderOut (2)
 
   +2: Mongrel::HttpRequest (2)
 
   +2: CGI::Cookie (2)
 
  -25: Array (6051)
 
Top 20
 
 +101: Array (6152)
 
   -1: Mongrel::HeaderOut (1)
 
   -1: Time (198)
 
   -1: Mongrel::HttpParams (1)
 
   -1: Mongrel::HttpRequest (1)
 
   -1: Mongrel::HttpResponse (1)
 
   -1: TCPSocket (1)
 
   -2: Float (52)
 
   -3: StringIO (3)
 
  -21: Hash (648)
 
 -193: String (72878)
 
Top 20
 
   -1: Range (173)
 
   -1: Set (22)
 
   -2: ActionController::Filters::ClassMethods::AfterFilterProxy (1)
 
   -2: Regexp (1325)
 
   -3: Proc (387)
 
   -4: ActionController::Filters::ClassMethods::BeforeFilterProxy (1)
 
   -5: Class (1144)
 
   -6: ActionController::Filters::ClassMethods::SymbolFilter (2)
 
   -9: Module (426)
 
  -13: Hash (635)
 
  -31: Array (6121)
 
 -293: String (72585)
 
Top 20
 
   -3: String (72582)
 
Top 20
 
   +3: String (72585)
 
Top 20
 
   +2: String (72585)
 
Top 20
 
   -2: String (72583)

请求二

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

 
Top 20
 
 +682: String (73267)
 
  +37: Hash (672)
 
  +24: Array (6145)
 
   +9: Module (435)
 
   +8: Regexp (1333)
 
   +7: Proc (394)
 
   +6: ActionController::Filters::ClassMethods::SymbolFilter (8)
 
   +5: Class (1149)
 
   +4: ActionController::Filters::ClassMethods::BeforeFilterProxy (5)
 
   +3: HashWithIndifferentAccess (3)
 
   +2: CGI::Cookie (2)
 
   +2: ActionController::Filters::ClassMethods::AfterFilterProxy (3)
 
   +2: Float (54)
 
   +1: OriginalFile (1)
 
   +1: ActionController::Dispatcher (1)
 
   +1: Set (23)
 
   +1: CGI::Session::ActiveRecordStore (1)
 
   +1: Mongrel::CGIWrapper (1)
 
   +1: ActionController::Flash::FlashHash (1)
 
   +1: ActionView::Base (1)
 
Top 20
 
  +16: Array (6161)
 
   -4: String (73263)
 
Top 20
 
   -1: Array (6160)
 
Top 20
 
Top 20
 
   -3: String (73260)
 
Top 20
 
   +3: String (73263)
 
Top 20
 
   -2: String (73261)

稳定后，开始文件上传（1.6M的文件）：

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

 
Top 20
 
   -2: String (73261)
 
Top 20
 
   +2: String (73263)
 
Top 20
 
   -2: String (73261)
 
Top 20
 
   +2: String (73263)
 
Top 20
 
   -2: String (73261)
 
Top 20
 
   +2: String (73263)
 
Top 20
 
   -2: String (73261)
 
Top 20
 
   +2: String (73263)
 
Top 20
 
   -2: String (73261)
 
Top 20
 
   +2: String (73263)
 
Top 20
 
   -2: String (73261)
 
Top 20
 
   +2: String (73263)

上传完成，重新 render 页面

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

 
Top 20
 
 +674: String (73937)
 
  +38: Hash (710)
 
   +9: Module (444)
 
   +6: ActionController::Filters::ClassMethods::SymbolFilter (14)
 
   +6: StringIO (9)
 
   +5: Class (1154)
 
   +4: ActionController::Filters::ClassMethods::BeforeFilterProxy (9)
 
   +3: Time (200)
 
   +3: Proc (397)
 
   +3: HashWithIndifferentAccess (6)
 
   +3: OriginalFile (3)
 
   +2: CGI::Cookie (4)
 
   +2: Mongrel::HttpParams (3)
 
   +2: Mongrel::HttpRequest (3)
 
   +2: ActionController::Filters::ClassMethods::AfterFilterProxy (5)
 
   +2: Range (176)
 
   +2: Mongrel::HeaderOut (3)
 
   +2: Regexp (1335)
 
   +2: TCPSocket (3)
 
  -84: Array (6076)
 
Top 20
 
 +108: Array (6184)
 
   -1: File (7)
 
   -1: Time (199)
 
   -1: Mongrel::CGIWrapper (1)
 
   -1: ActionController::CgiResponse (1)
 
   -1: CGI::Session (1)
 
   -1: Range (175)
 
   -1: Mongrel::HttpRequest (2)
 
   -1: Mongrel::HeaderOut (2)
 
   -1: CGI::Session::ActiveRecordStore (1)
 
   -1: ActionController::Flash::FlashHash (1)
 
   -1: ActionView::Base (1)
 
   -1: TCPSocket (2)
 
   -1: Mongrel::HttpParams (2)
 
   -2: CGI::Cookie (2)
 
   -2: Float (54)
 
   -3: HashWithIndifferentAccess (3)
 
   -3: StringIO (6)
 
  -23: Hash (687)
 
 -241: String (73696)
 
Top 20
 
   -1: Range (174)
 
   -1: Set (23)
 
   -2: ActionController::Filters::ClassMethods::AfterFilterProxy (3)
 
   -2: Regexp (1333)
 
   -3: Proc (394)
 
   -4: ActionController::Filters::ClassMethods::BeforeFilterProxy (5)
 
   -5: Class (1149)
 
   -6: ActionController::Filters::ClassMethods::SymbolFilter (8)
 
   -9: Module (435)
 
  -13: Hash (674)
 
  -21: Array (6163)
 
 -294: String (73402)
 
Top 20
 
Top 20
 
   -3: String (73399)
 
Top 20
 
   +3: String (73402)
 
Top 20
 
   -2: String (73400)
 
Top 20
 
   +2: String (73402)

第二次测试：
请求一

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

 
Top 20
 
 +594: String (73996)
 
  +31: Hash (705)
 
  +24: Array (6187)
 
   +9: Module (444)
 
   +6: ActionController::Filters::ClassMethods::SymbolFilter (14)
 
   +5: Class (1154)
 
   +4: Proc (398)
 
   +4: ActionController::Filters::ClassMethods::BeforeFilterProxy (9)
 
   +3: HashWithIndifferentAccess (6)
 
   +2: CGI::Cookie (4)
 
   +2: ActionController::Filters::ClassMethods::AfterFilterProxy (5)
 
   +2: Regexp (1335)
 
   +2: Float (56)
 
   +1: CGI::Session::ActiveRecordStore (2)
 
   +1: OriginalFile (1)
 
   +1: ActionController::Flash::FlashHash (2)
 
   +1: Mongrel::CGIWrapper (2)
 
   +1: VideosController (1)
 
   +1: Set (24)
 
   -2: Time (197)
 
Top 20
 
   +2: Array (6189)
 
   -1: CGI::Session (1)
 
   -1: CGI::Session::ActiveRecordStore (1)
 
   -1: ActiveRecord::Errors (1)
 
   -1: Proc (397)
 
   -1: ActionController::UrlRewriter (1)
 
   -1: ActionController::Flash::FlashHash (1)
 
   -1: ActionController::CgiRequest (1)
 
   -1: ActionView::Base (1)
 
   -1: ActionController::CgiResponse (1)
 
   -2: Float (54)
 
   -3: HashWithIndifferentAccess (3)
 
  -14: Hash (691)
 
  -83: String (73913)
 
Top 20
 
   -1: Range (174)
 
   -1: Set (23)
 
   -2: ActionController::Filters::ClassMethods::AfterFilterProxy (3)
 
   -2: Regexp (1333)
 
   -3: Proc (394)
 
   -4: ActionController::Filters::ClassMethods::BeforeFilterProxy (5)
 
   -5: Class (1149)
 
   -6: ActionController::Filters::ClassMethods::SymbolFilter (8)
 
   -9: Module (435)
 
  -13: Hash (678)
 
  -21: Array (6168)
 
 -295: String (73618)
 
Top 20
 
Top 20
 
   -3: String (73615)
 
Top 20
 
   +3: String (73618)

请求二

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

 
Top 20
 
 +668: String (74284)
 
  +34: Hash (712)
 
   +9: Module (444)
 
   +6: ActionController::Filters::ClassMethods::SymbolFilter (14)
 
   +5: Class (1154)
 
   +4: ActionController::Filters::ClassMethods::BeforeFilterProxy (9)
 
   +4: OriginalFile (4)
 
   +3: Proc (397)
 
   +3: Time (200)
 
   +3: StringIO (9)
 
   +3: HashWithIndifferentAccess (6)
 
   +2: Regexp (1335)
 
   +2: Float (56)
 
   +2: ActionController::Filters::ClassMethods::AfterFilterProxy (5)
 
   +2: Range (176)
 
   +1: CGI::Session::ActiveRecordStore (2)
 
   +1: Mongrel::HttpParams (3)
 
   +1: ActionController::UrlRewriter (2)
 
   +1: Set (24)
 
  -92: Array (6076)
 
Top 20
 
 +108: Array (6184)
 
   -1: File (7)
 
   -1: Range (175)
 
   -1: Mongrel::CGIWrapper (1)
 
   -1: ActionController::CgiResponse (1)
 
   -1: Mongrel::HeaderOut (2)
 
   -1: ActionController::UrlRewriter (1)
 
   -1: CGI::Session::ActiveRecordStore (1)
 
   -1: CGI::Session (1)
 
   -1: Mongrel::HttpParams (2)
 
   -1: ActionController::Flash::FlashHash (1)
 
   -1: Mongrel::HttpResponse (2)
 
   -1: TCPSocket (2)
 
   -1: Mongrel::HttpRequest (2)
 
   -2: CGI::Cookie (2)
 
   -2: Float (54)
 
   -3: HashWithIndifferentAccess (3)
 
   -3: StringIO (6)
 
  -25: Hash (687)
 
 -272: String (74012)
 
Top 20
 
   -1: Range (174)
 
   -1: Set (23)
 
   -1: Time (199)
 
   -2: ActionController::Filters::ClassMethods::AfterFilterProxy (3)
 
   -2: Regexp (1333)
 
   -3: Proc (394)
 
   -4: ActionController::Filters::ClassMethods::BeforeFilterProxy (5)
 
   -5: Class (1149)
 
   -6: ActionController::Filters::ClassMethods::SymbolFilter (8)
 
   -9: Module (435)
 
  -13: Hash (674)
 
  -21: Array (6163)
 
 -299: String (73713)
 
Top 20
 
Top 20
 
   -3: String (73710)
 
Top 20
 
   +3: String (73713)

结果中的每一行 表示每个对象在内存中的个数（后面的数字）和增减变化（前面的数字），每10秒计算一次，排出内存中的数量前20。

在整个过程中：
String约增加了2580个，Regexp约增加了200个。

重复4次以后（总共6次）

开始

1
2
3
4

 
 PID USER      PR  NI  VIRT  RES  SHR S %CPU %MEM    TIME+  COMMAND
 
6590 rails2    16   0  101m  52m 2852 S    0  5.2   0:58.65 ruby

结束

1
2

 
6590 rails2    16   0  101m  53m 2852 S    0  5.2   1:29.63 ruby

接着上传一个26M的文件，然后：

1
2

 
6590 rails2    16   0  102m  54m 2852 R   11  5.3   2:45.13 ruby

持续访问页面（不是文件上传）12次之后：

1
2

 
6590 rails2    16   0  103m  55m 2852 S    0  5.4   2:52.27 ruby

5分钟之后：

1
2

 
6590 rails2    16   0  103m  55m 2852 S   15  5.4   3:08.58 ruby

十小时之后：

1
2

 
6590 rails2    16   0 2152m 444m 1420 S    0 43.5  28:04.12 ruby

以上是在服务器上的操作过程，到此可以初步确定在development模式下有内存泄露（服务器一个mongrel一度达到500M）。而且，应该不是由文件上传引起的（持续的页面访问会增加内存泄露）。

参考：
http://valgrind.org/
Tracking down a Rails app memory leak
Tracking a memory leak in Rails
bleak_house
Dike website
Linux on Power 上的调试工具和技术

收藏、分享这篇文章!

Related posts:

  1. Rails 内存泄露检测：实践二 服务器一环境： rails2@server:~$ cat /proc/version Linux version 2.6.16.29-xen (shand@endor) (gcc version...

Related posts brought to you by Yet Another Related Posts Plugin.

Leave a Comment