Finding Ruby Memory Causes

Question

I detected a memory leak in my Rails code - that is, I found that the code was leaking, but not why. I shortened it to a test that does not require Rails:

require 'csspool' require 'ruby-mass' def report puts 'Memory ' + 'ps ax -o pid,rss | grep -E "^[[:space:]]*#{$$}"'.strip.split.map(&:to_i)[1].to_s + 'KB' Mass.print end report # note I do not store the return value here CSSPool::CSS::Document.parse(File.new('/home/jason/big.css')) ObjectSpace.garbage_collect sleep 1 report 

ruby-mass supposedly allows me to see all the objects in memory. CSSPool is a racc -based CSS parser . /home/jason/big.css is a 1.5 MB CSS file .

This outputs:

 Memory 9264KB ================================================== Objects within [] namespace ================================================== String: 7261 RubyVM::InstructionSequence: 1151 Array: 562 Class: 313 Regexp: 181 Proc: 111 Encoding: 99 Gem::StubSpecification: 66 Gem::StubSpecification::StubLine: 60 Gem::Version: 60 Module: 31 Hash: 29 Gem::Requirement: 25 RubyVM::Env: 11 Gem::Specification: 8 Float: 7 Gem::Dependency: 7 Range: 4 Bignum: 3 IO: 3 Mutex: 3 Time: 3 Object: 2 ARGF.class: 1 Binding: 1 Complex: 1 Data: 1 Gem::PathSupport: 1 IOError: 1 MatchData: 1 Monitor: 1 NoMemoryError: 1 Process::Status: 1 Random: 1 RubyVM: 1 SystemStackError: 1 Thread: 1 ThreadGroup: 1 fatal: 1 ================================================== Memory 258860KB ================================================== Objects within [] namespace ================================================== String: 7456 RubyVM::InstructionSequence: 1151 Array: 564 Class: 313 Regexp: 181 Proc: 113 Encoding: 99 Gem::StubSpecification: 66 Gem::StubSpecification::StubLine: 60 Gem::Version: 60 Module: 31 Hash: 30 Gem::Requirement: 25 RubyVM::Env: 13 Gem::Specification: 8 Float: 7 Gem::Dependency: 7 Range: 4 Bignum: 3 IO: 3 Mutex: 3 Time: 3 Object: 2 ARGF.class: 1 Binding: 1 Complex: 1 Data: 1 Gem::PathSupport: 1 IOError: 1 MatchData: 1 Monitor: 1 NoMemoryError: 1 Process::Status: 1 Random: 1 RubyVM: 1 SystemStackError: 1 Thread: 1 ThreadGroup: 1 fatal: 1 ================================================== 

You can see the memory going way. Some counters go up, but there are no CSSPool-specific objects. I used the ruby-mass index method to check for objects that are referenced, for example:

 Mass.index.each do |k,v| v.each do |id| refs = Mass.references(Mass[id]) puts refs if !refs.empty? end end 

But then again, it gives me nothing to do with CSSPool, just gem info and the like.

I also tried to output "GC.stat" ...

 puts GC.stat CSSPool::CSS::Document.parse(File.new('/home/jason/big.css')) ObjectSpace.garbage_collect sleep 1 puts GC.stat 

Result:

 {:count=>4, :heap_used=>126, :heap_length=>138, :heap_increment=>12, :heap_live_num=>50924, :heap_free_num=>24595, :heap_final_num=>0, :total_allocated_object=>86030, :total_freed_object=>35106} {:count=>16, :heap_used=>6039, :heap_length=>12933, :heap_increment=>3841, :heap_live_num=>13369, :heap_free_num=>2443302, :heap_final_num=>0, :total_allocated_object=>3771675, :total_freed_object=>3758306} 

As far as I understand, if an object is not referenced and garbage collection occurs, then this object should be cleared from memory. But it seems that this is not what is happening here.

I also read about level C memory leaks, and since CSSPool uses Racc, which uses C code, I think this is possible. I ran my code through Valgrind:

 valgrind --partial-loads-ok=yes --undef-value-errors=no --leak-check=full --fullpath-after= ruby leak.rb 2> valgrind.txt 

The results are here . I'm not sure if this confirms a C-level leak, since I also read that Ruby works with memory that Valgrind does not understand.

Used Versions:

• Ruby 2.0.0-p247 (this is what launches my Rails application)
• Ruby 1.9.3-p392-ref (for testing with ruby ​​mass)
• ruby mass 0.1.3
• CSSPool 4.0.0 from here
• CentOS 6.4 and Ubuntu 13.10

Answer 1

It looks like you are entering The Lost World here. I don't think the problem is with c-bindings in racc .

Ruby's memory management is elegant and cumbersome. It stores objects (called RVALUE s) in so-called heaps about 16 KB in size. At a low level, RVALUE is a c-struct containing a union various standard representations of ruby ​​objects.

So, heaps store RVALUE objects whose size does not exceed 40 bytes. For objects such as String , Array , Hash , etc., This means that small objects can be inserted into the heap, but as soon as they reach the threshold, additional memory will be allocated outside the Ruby bushes.

This extra memory is flexible; will be released as soon as the object becomes GCed. This is why your test file with big_string shows up-memory behavior:

 def report puts 'Memory ' + `ps ax -o pid,rss | grep -E "^[[:space:]]*#{$$}"` .strip.split.map(&:to_i)[1].to_s + 'KB' end report big_var = " " * 10000000 report big_var = nil report ObjectSpace.garbage_collect sleep 1 report # ⇒ Memory 11788KB # ⇒ Memory 65188KB # ⇒ Memory 65188KB # ⇒ Memory 11788KB 

But heaps (see GC[:heap_length] ) are not themselves released back to the OS after they are acquired. Listen, I will make a vague change in your test folder:

 - big_var = " " * 10000000 + big_var = 1_000_000.times.map(&:to_s) 

And, voilá:

 # ⇒ Memory 11788KB # ⇒ Memory 65188KB # ⇒ Memory 65188KB # ⇒ Memory 57448KB 

The memory is no longer output back to the OS, because each element of the array that I entered corresponds to the size of RVALUE and is stored in a ruby ​​heap.

If you checked the output of GC.stat after starting GC, you will find that the value of GC[:heap_used] decreasing as expected. Ruby now has a lot of heaps, done.

To summarize: I don't think the c code is c . I think the problem is presenting a huge base64 image in your css . I have no idea what is going on inside the parser, but it seems like a huge string causes the amount of ruby ​​heap to increase.

Hope this helps.

Answer 2

Ok, I found the answer. I leave my other answer, because this information was very difficult to collect, it is related, and it can help someone else in finding a related problem.

Your problem, however, seems to be related to the fact that Ruby does not actually free memory back to the operating system after purchasing it.

Memory allocation

Although Ruby programmers do not often worry about memory allocation, sometimes the following question arises:

Why did my Ruby process remain so large even after I cleared all references to large objects? Im / sure / GC ran several times and freed up my large objects, and I did not lose memory.

The programmer may ask the same question:

I free () -ed a lot of memory, why is my process still so big?

Allocating memory for user space from the kernel is cheaper in large chunks, so user space avoids interacting with the kernel by doing more work.

User space libraries / runtimes implement a memory allocator (e.g. malloc (3) in libc) that takes large chunks of kernel2 memory and divides them into smaller parts for use by user space applications.

Thus, it may take several user-space allocations before user-space needs to request more memory from the kernel. Thus, if you receive a large chunk of memory from the kernel and use only a small part of it, this large chunk of memory remains allocated.

Releasing memory back to the kernel also comes at a cost. User space memory allocators can hold this memory (in private) in the hope that it can be reused in the same process and not returned to the kernel for use in other processes. (Ruby Best Practices)

Thus, your objects may well be garbage collected and returned back to Ruby's available memory, but since Ruby never returns the OS unused memory, the rss value for the process remains the same even after garbage collection. This is actually by design. According to Mike Perham :

... And since MRI never returns unused memory, our daemon can easily take 300-400 MB if it uses only 100-200.

It is important to note that this is essentially a design. Rubys history is mainly used as a command line tool for word processing and therefore appreciates a quick start and a small amount of memory. It was not designed for long daemon / server processes. Java makes a similar compromise in its client and server virtual machines.

Answer 3

This may be due to the "Lazy Sweeping" feature in Ruby 1.9.3 and later.

Lazy sweeping basically means that when garbage is collected, Ruby only "sweeps" enough objects to create space for the new objects that it needs to create. It does this because while the Ruby garbage collector is running, it does nothing else. This is called Stop the World garbage collection.

Essentially, lazy sweeping reduces the time Ruby needs to “stop the world." You can learn more about lazy sweeping here .

What does your environment variable RUBY_GC_MALLOC_LIMIT look like?

Here is an excerpt from Sam Saffron 's blog regarding lazy sweeping and RUBY_GC_MALLOC_LIMIT:

GC in Ruby 2.0 comes in two different flavors. We have a “full” GC that starts after we allocate more than our malloc_limit and a lazy sweep (partial GC) that will work if we ever run out of free space in our heaps.

Lazy scanning takes less time than a full GC, but only performs a partial GC. The goal is to run a shorter GC more often, thereby increasing overall throughput. The world stops, but in less time.

malloc_limit is set to 8MB out of the box, you can raise it by setting RUBY_GC_MALLOC_LIMIT above.

Is your RUBY_GC_MALLOC_LIMIT extremely tall? Mine is set to 100000000 (100 MB). The default value is about 8 MB, but for applications with rails, they recommend it a little higher. If yours is too tall, this may prevent Ruby from deleting garbage objects, because he believes that he has enough room for growth.

Answer 4

Building on @mudasobwa's explanation, I finally found a reason. CSSPool code checked a very long data URI for escape sequences. This will call a scan URI with a regular expression that matches the escape sequence or a single character, map these results with unescape, and then join it back to the string. This effectively allocated a string for each character in the URI. I changed it for gsub escape sequences that seem to give the same results (all tests passed) and significantly reduce the final memory used.

Using the same test case that was originally published (behind Mass.print output of Mass.print ), this is the result before the change:

 Memory 12404KB Memory 292516KB 

and this is the result after the change:

 Memory 12236KB Memory 19584KB