Marty Andrews

artful code

Tuesday, October 25, 2011

A ruby spec profiling story

I've always used ruby-prof in the past to profile my Ruby code, but a colleague yesterday put me on to the Google perftools for Ruby code. A bit of research turned up some interesting things.

According to http://blog.pluron.com/2008/01/ruby-on-rails-i.html,
ruby-prof attributes full cost of garbage collection to the method where GC gets triggered, not the methods that allocate the memory

That was news to me. I tried running the profiler over an app I'm working on, and got this:

Total: 23530 samples
13244 56.3% 56.3% 13244 56.3% garbage_collector
4223 17.9% 74.2% 4331 18.4% ActiveRecord::ConnectionAdapters::Mysql2Adapter#execute
678 2.9% 77.1% 678 2.9% ActiveRecord::ConnectionAdapters::Mysql2Adapter#active?
402 1.7% 78.8% 403 1.7% MonitorMixin::ConditionVariable#signal
258 1.1% 79.9% 294 1.2% Method#call

Wow! That's a massive amount of time in GC! What can I do about that?

That lead me to an article by Jamis Buck at http://37signals.com/svn/posts/2742-the-road-to-faster-tests. It describes a way to address GC issues for Test::Unit, but there's a nice rspec version at https://gist.github.com/790118. I applied that to my code and ran it again. The new profile was:

Total: 11331 samples
3730 32.9% 32.9% 3804 33.6% ActiveRecord::ConnectionAdapters::Mysql2Adapter#execute
2021 17.8% 50.8% 2021 17.8% garbage_collector
720 6.4% 57.1% 720 6.4% ActiveRecord::ConnectionAdapters::Mysql2Adapter#active?
376 3.3% 60.4% 376 3.3% MonitorMixin::ConditionVariable#signal
352 3.1% 63.5% 353 3.1% Object#reconsider_gc_deferment

My spec build time also cam down from 375 seconds to 238 seconds. That's a massive improvement.

The post form Jamis also mentions cleaning up some instance variables, which I'll try amongst some further tweaking, but that improvement was significant enough that I figured it might point someone else in the right direction too.

1 comment:

  1. The same profiling efforts on said colleague's machine showed a GC time of ~4%. Curiously, the GC optimisation still yielded a 23% reduction in rake spec execution time. Is perftools telling fibs?

    ReplyDelete