Hi!

Yes, this is the expected behaviour when you are working with with SVN repositories. Retrospectiva (as a typical RubyOnRails application) uses ~40M of RAM, the rest is consumed by the Ruby-SVN bindings (for various reasons). The memory consumption is directly proportional to the size of your repository, but your demand of ~100M of RAM seems quite reasonable to me.

Please don’t worry being Out Of Memory after a few days, the memory allocation will not grow any further.

Regards
Dimitrij

Hi Dimitrij, It does grow further and seems never to stop

Is the SVN binding keeping a cache? And It does get OOM and the boxe crashed once a few days.

Please have a look on lib/patches.rb, line 76

Try to change

  @@gc_count = (@@gc_count + 1) % 20

to a lower value, eg:

  @@gc_count = (@@gc_count + 1) % 10

This should slow-down your memory growth (and the SVN processing speed :-().

Dimitrij

@Kou: Do you have any idea how to solve this problem in the long term?

I have done this

 @@gc_count = (@@gc_count + 1) % 10

and the memory usage is increasing much slower, after 2 days:

root     27862  0.8 20.6 163004 108344 ?       S    Jun06  28:43 /usr/bin/ruby18 /usr/bin/mongrel_rails start -d -e production

Is it really Subversion bindings problem? I can’t confirm that Subversion related features (log list, diff and so on) increase memory usage.

I think we need to profile which feature increases memory usage.

Hi Kou!

Yes, the problem is definitely SVN related, since the memory consumption grows with the number of allocated Pools and Roots, but please don’t worry about this problem anymore, I’ve solved it over the weekend and also created a test to confirm it’s resolution. I will commit the both within the next few days.

Dimitrij

Great!

If I should fix the Subversion bindings, please tell me.

Well, I was too enthusiastic, my patch fixes a specific memory leak, but unfortunately opens a new one.

@Ming-Wei: Could you please add the following code to your environment.rb?

module MemoryLogging
  def self.included(base)
    base.send(:include, InstanceMethods)
    base.send(:after_filter, :log_mem_stat)
  end

  module InstanceMethods
    protected

      def log_mem_stat(additional_position_message = nil)
        return unless PLATFORM =~ /linux/
        vm_info = File.read("/proc/self/status").grep(/^Vm(RSS|Size)/).map do |l| 
          l.chomp.gsub(/\t/, ' ').gsub(/ +/, ' ')
        end
        rss, size = vm_info.map{|l| l.scan(/\d+/).first.to_i}
        rss_diff = $vm_rss ? rss - $vm_rss : 0
        size_diff = $vm_size ? size - $vm_size : 0

        if rss_diff.abs > 300 || size_diff.abs > 300
          info = "PID #{$$}, #{vm_info.join(', ')}, Size Diff #{size_diff} kB, RSS Diff #{rss_diff} kB" 
          additional_position_message ||= request.env['REQUEST_URI']
          mem_logger.info "#{info} - #{additional_position_message}" 
        end
        $vm_rss, $vm_size = rss, size
      end

      def mem_logger
        @mem_logger ||= Logger.new(File.join(RAILS_ROOT, 'log', 'memlog.log'))
      end

  end
end
ActionController::Base.send(:include, MemoryLogging)

Could you please let you Retrospectiva run for at least 24h (don’t forget to delete tmp/cache first) and send me the resulting log/memlog.log. My memory consumption does no grow as fast as yours and I’d like to investigate why.

Thanks
Dimitrij

@Kou:

I’ve tested my memory allocation using Subversion 1.4.2 & 1.4.3 It seems that 1.4.3 works much more efficiently (less memory consumption). Could you think of a specific reason for that?

Cheers
Dimitrij

There are any the Ruby bindings changes between 1.4.2 and 1.4.3. Subversion 1.4.3 may be improved memory usage.

There are → There aren’t

ok, I’ve added that block.

root     12175 18.5  3.9  23716 20640 ?        R    15:01   0:00 /usr/bin/ruby18 /usr/bin/mongrel_rails start -d -e production

cleaned the tmp/cache, restarted mongrel, I will send the log file.

the memory.log

Hi again!

I did a full rewrite of the repository handling in [140]. My own memory consumption has dropped by 50% and seems to remain stable, please give me some feedback about how the changes are working out for you. I will create a backport for the 1.0 branch, once I know that this solution works.

If you’d like to trace the memory footprint add the following code to the config/environment.rb:

module MemoryLogging
  def self.included(base)
    base.send(:include, InstanceMethods)
    base.send(:after_filter, :log_mem_stat)
  end

  module InstanceMethods
    protected

      @@vm_diff_logger = Logger.new(File.join(RAILS_ROOT, 'log', 'mem-diff.log'))
      @@vm_time_logger = Logger.new(File.join(RAILS_ROOT, 'log', 'mem-time.log'))

      @@vm_mstart = Time.now
      @@vm_time_iv = 60.minutes
      @@vm_time_ts = @@vm_mstart + @@vm_time_iv
      @@vm_reqs = 0

      def log_mem_stat
        return unless PLATFORM =~ /linux/
        @@vm_reqs += 1

        vm_info = File.read("/proc/self/status").grep(/^Vm(RSS|Size)/).map do |l| 
          l.chomp.gsub(/\t/, ' ').gsub(/ +/, ' ')
        end        
        virt, res    = vm_info.map{|l| l.scan(/\d+/).first.to_i}
        vdiff, rdiff = ($vm_virt ? virt - $vm_virt : 0), ($vm_res ? res - $vm_res : 0)
        $vm_virt, $vm_res = virt, res

        info = "PID #{$$}, VIRT #{virt} kB, RES #{res} kB, VDIFF #{vdiff} kB, RDIFF #{rdiff} kB" 
        @@vm_diff_logger.info("#{info} | #{request.env['REQUEST_URI']}")

        if Time.now > @@vm_time_ts 
          mins = ((@@vm_time_ts - @@vm_mstart) / 60).to_i
          @@vm_time_ts += @@vm_time_iv
          @@vm_time_logger.info("#{info} | #{mins} minutes, #{@@vm_reqs} requests, #{@@vm_reqs/mins} rpm")        
        end
      end

  end
end
ActionController::Base.send(:include, MemoryLogging)

As promised, I’ve created a backport of my patch for the v1.0 branch and it seems to work much better (at least for me).

I made a test-script (attached), it works on Linux only and uses the test-environment database. To try it, copy the file to test/other/memory_test.rb and run it with the repository path as parameter. Example:

  ruby test/other/memory_test.rb /var/svn/myrepo

I did the test with the v1.0rc3:

  ...
  [+] Started 'test_02_process_changed_nodes' (VIRT 42080 kB, RES 33564 kB, VDIFF 0 kB, RDIFF 8 kB)
      Processing 10000 nodes
      Status after 2000 nodes (VIRT 275280 kB, RES 246784 kB, VDIFF 233200 kB, RDIFF 213220 kB)
      Status after 4000 nodes (VIRT 490584 kB, RES 437140 kB, VDIFF 215304 kB, RDIFF 190356 kB)
      Status after 6000 nodes (VIRT 724408 kB, RES 555148 kB, VDIFF 233824 kB, RDIFF 118008 kB)
      Status after 8000 nodes (VIRT 928256 kB, RES 611852 kB, VDIFF 203848 kB, RDIFF 56704 kB)
      Status after 10000 nodes (VIRT 1094612 kB, RES 635776 kB, VDIFF 166356 kB, RDIFF 23924 kB)
  [=] Finished after 505s (VIRT 1094612 kB, RES 635780 kB, VDIFF 0 kB, RDIFF 4 kB)
  ...

And this is my result after the patch:

  ...
  [+] Started 'test_02_process_changed_nodes' (VIRT 43264 kB, RES 34744 kB, VDIFF 0 kB, RDIFF 8 kB)
      Processing 10000 nodes
      Status after 2000 nodes (VIRT 68004 kB, RES 59548 kB, VDIFF 24740 kB, RDIFF 24804 kB)
      Status after 4000 nodes (VIRT 91948 kB, RES 81680 kB, VDIFF 23944 kB, RDIFF 22132 kB)
      Status after 6000 nodes (VIRT 135620 kB, RES 121516 kB, VDIFF 43672 kB, RDIFF 39836 kB)
      Status after 8000 nodes (VIRT 144064 kB, RES 129772 kB, VDIFF 8444 kB, RDIFF 8256 kB)
      Status after 10000 nodes (VIRT 154716 kB, RES 140412 kB, VDIFF 10652 kB, RDIFF 10640 kB)
  [=] Finished after 268s (VIRT 154716 kB, RES 140412 kB, VDIFF 0 kB, RDIFF 0 kB)
  ...

Please tell me if it works for you as well as for me.

Dimitrij

PS: I used a well-sized repository (3500 commits, 50MB) of a C application (similar to CallWeaver) for my tests.