EzDevInfo.com

How to profile Rake task?

I need to profile the rake task. Cause I'm noob I know only how to profile .rb code like this: ruby -Ilib -S ruby-prof -p graph_html profile.rb > profile.html

But how do I profile a specific Rake task?

How can I profile Ruby code in 1.9.2?

What can I use to profile code in 1.9.2? All of the versions of ruby-prof I've found segfault against 1.9.2.

For instance, when I add

gem "ruby-prof"

to my Rails project's Gemfile and run

bundle
bundle exec ruby-prof config/environment.rb

I get a segfault.

Is there a new profiling gem in town? Is there a way to make ruby-prof play nice?

How do I track down a memory leak in my Ruby code?

Question

I'm debugging a memory leak in a rake task. I want to see a call stack of:

• Living objects
• What object or line originally allocated those objects

Is this possible with ruby-prof?

If not, what tool should I use?

Setup

Gems

• rails 3.2.16
• event_bus 1.0.0 (https://github.com/kevinrutherford/event_bus)
• activerecord-fast-import (https://github.com/jsuchal/activerecord-fast-import)

Rake task

• Imports a CSV file directly into a MySql database using DATA LOAD INFILE and Active Record objects.

What I've Tried

I've tried the modes

• RubyProf::ALLOCATIONS
• RubyProf::MEMORY

All it says in the documentation is:

RubyProf::ALLOCATIONS Object allocation reports show how many objects each method in a program allocates.

RubyProf::MEMORY Memory usage reports show how much memory each method in a program uses.

This implies that ruby-prof just reports on the total allocation of objects, not just the ones that are living.

I've tried Ruby-Mass and Bloat Check but neither seem to be able to do what I want. Ruby-Mass also crashes because it's finding FactoryGirl objects in memory for some reason...

Understanding ruby-prof output

I ran ruby-profiler on one of my programs. I'm trying to figure out what each fields mean. I'm guessing everything is CPU time (and not wall clock time), which is fantastic. I want to understand what the "---" stands for. Is there some sort of stack information in there. What does calls a/b mean?

Thanks!

Thread ID: 81980260
Total Time: 0.28

  %total   %self     total      self      wait     child            calls   Name
--------------------------------------------------------------------------------
                      0.28      0.00      0.00      0.28              5/6     FrameParser#receive_data
 100.00%   0.00%      0.28      0.00      0.00      0.28                6     FrameParser#read_frames
                      0.28      0.00      0.00      0.28              4/4     ChatServerClient#receive_frame
                      0.00      0.00      0.00      0.00             5/47     Fixnum#+
                      0.00      0.00      0.00      0.00              1/2     DebugServer#receive_frame
                      0.00      0.00      0.00      0.00            10/29     String#[]
                      0.00      0.00      0.00      0.00            10/21     <Class::Range>#allocate
                      0.00      0.00      0.00      0.00            10/71     String#index
--------------------------------------------------------------------------------
 100.00%   0.00%      0.28      0.00      0.00      0.28                5     FrameParser#receive_data
                      0.28      0.00      0.00      0.28              5/6     FrameParser#read_frames
                      0.00      0.00      0.00      0.00             5/16     ActiveSupport::CoreExtensions::String::OutputSafety#add_with_safety
--------------------------------------------------------------------------------
                      0.28      0.00      0.00      0.28              4/4     FrameParser#read_frames
 100.00%   0.00%      0.28      0.00      0.00      0.28                4     ChatServerClient#receive_frame
                      0.28      0.00      0.00      0.28              4/6     <Class::Lal>#safe_call
--------------------------------------------------------------------------------
                      0.00      0.00      0.00      0.00              1/6     <Class::Lal>#safe_call
                      0.00      0.00      0.00      0.00              1/6     DebugServer#receive_frame
                      0.28      0.00      0.00      0.28              4/6     ChatServerClient#receive_frame
 100.00%   0.00%      0.28      0.00      0.00      0.28                6     <Class::Lal>#safe_call
                      0.21      0.00      0.00      0.21              2/4     ChatUserFunction#register
                      0.06      0.00      0.00      0.06              2/2     ChatUserFunction#packet
                      0.01      0.00      0.00      0.01            4/130     Class#new
                      0.00      0.00      0.00      0.00              1/1     DebugServer#profile_stop
                      0.00      0.00      0.00      0.00             1/33     String#==
                      0.00      0.00      0.00      0.00              1/6     <Class::Lal>#safe_call
                      0.00      0.00      0.00      0.00              5/5     JSON#parse
                      0.00      0.00      0.00      0.00              5/8     <Class::Log>#log
                      0.00      0.00      0.00      0.00              5/5     String#strip!
--------------------------------------------------------------------------------

Profiling Ruby Code

Besides ruby-prof and and the core Benchmark class, what do you use to profile your Ruby code? In particular, how do you find the bottlenecks in your code? It almost feels like I need to work on my own little tool just to figure out where all the time is being spent in my code.

I realize ruby-prof provides this, but the output is frankly very confusing and doesn't make it easy to find out which actual blocks of your own code are the source of the issue (it tells you about which method calls took the most time though). So I'm not really getting as much out of it as I'd like, and haven't really been able to make use of it.

Perhaps I'm doing it wrong? Are there alternatives? Google searches don't bring up anything for me.

Newrelic developermode not working with ruby-prof

I'm using the newrelic_rpm developer mode locally in a rails 3.2 app. This is working fine.

When I install ruby-prof and click "start profiling" in the newrelic local dashboard and go back to my app, every page in my app gives "undefined method `pop' for #.

The top few lines of the traceback:

newrelic_rpm (3.6.4.122) lib/new_relic/agent/instrumentation/controller_instrumentation.rb:421:in `ensure in perform_action_with_newrelic_profile'
newrelic_rpm (3.6.4.122) lib/new_relic/agent/instrumentation/controller_instrumentation.rb:421:in `perform_action_with_newrelic_profile'
newrelic_rpm (3.6.4.122) lib/new_relic/agent/instrumentation/controller_instrumentation.rb:305:in `perform_action_with_newrelic_trace'
newrelic_rpm (3.6.4.122) lib/new_relic/agent/instrumentation/rails3/action_controller.rb:37:in `process_action'
actionpack (3.2.13) lib/abstract_controller/base.rb:121:in `process'

Any ideas how to work out what's going wrong?

Errors with ruby-prof in a Rails Performance Test

I'm creating a Rails Performance test, as described in the Rails Guide, and I'm having problems with ruby-prof.

I'm using Ruby 1.9.2-p0 (though experienced the same issue on p320) and Rails 3.1.0.

I have a pretty simple test for a controller that is equivalent to this example.

According to the guide, I need to install ruby-prof before I can use performance tests. Sure enough, if I run my performance test without it, I get:

Specify ruby-prof as application's dependency in Gemfile to run benchmarks.

If I follow the guide's instructions to the letter, I add this to my Gemfile:

gem 'ruby-prof', :git => 'git://github.com/wycats/ruby-prof.git'

...and get version 0.11.0 from the wycats repository. When I run my test I get this error:

/Users/craig/.rvm/gems/ruby-1.9.2-p0/bundler/gems/ruby-prof-ffae61a89553/lib/ruby-prof/abstract_printer.rb:44:in `inspect': undefined method `to_s' for #<Class:0x000001025a3f18> (NoMethodError)
from /Users/craig/.rvm/gems/ruby-1.9.2-p0/bundler/gems/ruby-prof-ffae61a89553/lib/ruby-prof/abstract_printer.rb:44:in `full_name'
...

But "wycats" doesn't appear to be the canonical Github repo for ruby-prof. The documentation refers to rdp (Roger Pack). If I use that repo instead:

gem 'ruby-prof', :git => 'git://github.com/rdp/ruby-prof.git'

...I get version 0.11.2, and get this error:

/Users/craig/.rvm/gems/ruby-1.9.2-p0/gems/activesupport-3.1.0/lib/active_support/testing/performance/ruby.rb:39:in run': undefined methodvalues' for [#]:Array (NoMethodError) from /Users/craig/.rvm/gems/ruby-1.9.2-p0/gems/activesupport-3.1.0/lib/active_support/testing/performance.rb:140:in `run_profile' ...

I get the same error if I just use the gem from rubygems directly (again, version 0.11.2):

gem 'ruby-prof'

Any ideas what's going wrong, or how to resolve it?

Mutex sleep is taking a lot of CPU

I profiled my event-machine based application with ruby-prof and found the following interesting:

                  5.28    0.00    5.28    0.00          4/4     Mutex#synchronize
90.72%   0.00%    5.28    0.00    5.28    0.00            4     Mutex#sleep

I think ruby-prof counts only CPU ticks, and hence I'm unable to figure out why mutex sleep might take CPU time. I'd assume it sleeps on the kernel level not counting towards the fiber time. Any ideas? Even better, I'd want the Mutex#sleep to release control to the event machine, so it can do other stuff.

How do I get ruby-prof to ignore Ruby core / standard library / gem methods?

I'm new to Ruby profiling, and it seems like ruby-prof is a popular choice. I just installed the gem and invoked my program:

ruby-prof ./my-prog.rb

However, the output is incredibly verbose, because profiling data for all the Ruby core and standard library methods, and other gems are included. For example, the top three lines are:

8.79      0.011     0.010     0.000     0.001     3343  *String#% 
7.28      0.078     0.009     0.000     0.069     2068  *Array#each 
4.93      0.038     0.006     0.000     0.032     1098  *Array#map 

That's not remotely useful information for me, since I already know that my program deals with Strings and Arrays a lot, and presumably those classes have already had the hell optimised out of them. I only care about the hotspots in my code.

I tried some of the other printer modes, e.g. -p graph_html and -p call_stack, but they all have the same problem.

I see that ruby-prof supports some method elimination and simplification:

-x, --exclude regexp             exclude methods by regexp (see method elimination)
-X, --exclude-file file          exclude methods by regexp listed in file (see method elimination)
    --exclude-common-cycles      make common iterators like Integer#times appear inlined
    --exclude-common-callbacks   make common callbacks invocations like Integer#times appear

but there doesn't seem to be any obvious way to get what I really want, which is profiling data for my code only, i.e. with time elapsed inside code from Ruby core / stdlib, and other gems only being counted as time elapsed inside my code.

Once I can see that my code has a method foo which is a performance bottleneck due to being called thousands of times and not performing well, then and only do I want to see the breakdown of time elapsed between my code and core/library code called within that particular method.

I can't understand why this isn't a standard feature, since I would expect that it's what everyone wants to do: profile your own code first, and then once you've run out of things to optimize, potentially start optimizing the gems you use and maybe even Ruby core / stdlib. What am I missing?

Ruby profiler stack level too deep error

It seems like I always get this error on one of my scripts:

/Users/amosng/.rvm/gems/ruby-1.9.3-p194/gems/ruby-prof-0.11.2/lib/ruby-prof/profile.rb:25: stack level too deep (SystemStackError)

Has anyone encountered this error before? What could be causing it, and what can I be doing to prevent it from happening?

I run my ruby-prof scripts using the command

ruby-prof --printer=graph --file=profile.txt scraper.rb -- "fall 2012"

Edit I'm on Mac OS X, if that matters. Doing ulimit -s 64000 doesn't seem to help much, unfortunately. Here is what ulimit -a gives:

$ ulimit -a
core file size          (blocks, -c) 0
data seg size           (kbytes, -d) unlimited
file size               (blocks, -f) unlimited
max locked memory       (kbytes, -l) unlimited
max memory size         (kbytes, -m) unlimited
open files                      (-n) 256
pipe size            (512 bytes, -p) 1
stack size              (kbytes, -s) 64000
cpu time               (seconds, -t) unlimited
max user processes              (-u) 709
virtual memory          (kbytes, -v) unlimited

Edit 2

Andrew Grimm's solution worked just fine to prevent ruby-prof from crashing, but the profiler seems to have problems of its own, because I see percentages like 679.50% of total time taken for a process...

Ruby segmentation fault when running a profile test

I get the segmentation fault error below when I run rake test:profile. I'm using ruby 1.9.2p290 (2011-07-09 revision 32553) [i686-linux]. But it also happens with the p320 version of Ruby 1.9.2 and similar error happens with Ruby 1.9.3.

active_support/testing/performance/ruby.rb:36 actually says just RubyProf.pause. And I'm running the test with the profile options :runs => 5, :metrics => [:cpu_time], :formats => [:tree]. See my gem list at the end of the post too.

Any suggestion will be appreciated.

Error trace:

/home/manuel/.rvm/gems/ruby-1.9.2-p290@dev3dynamic/gems/activesupport-3.2.8/lib/active_support/testing/performance/ruby.rb:36: [BUG] Segmentation fault
ruby 1.9.2p290 (2011-07-09 revision 32553) [i686-linux]

-- control frame ----------
c:0017 p:0058 s:0062 b:0062 l:000061 d:000061 METHOD /home/manuel/.rvm/gems/ruby-1.9.2-p290@dev3dynamic/gems/activesupport-3.2.8/lib/active_support/testing/performance/ruby.rb:36
c:0016 p:0060 s:0059 b:0059 l:000058 d:000058 METHOD /home/manuel/.rvm/gems/ruby-1.9.2-p290@dev3dynamic/gems/activesupport-3.2.8/lib/active_support/testing/performance.rb:140
c:0015 p:0044 s:0053 b:0053 l:000043 d:000052 BLOCK  /home/manuel/.rvm/gems/ruby-1.9.2-p290@dev3dynamic/gems/activesupport-3.2.8/lib/active_support/testing/performance.rb:52
c:0014 p:---- s:0049 b:0049 l:000048 d:000048 FINISH
c:0013 p:---- s:0047 b:0047 l:000046 d:000046 CFUNC  :each
c:0012 p:0056 s:0044 b:0044 l:000043 d:000043 METHOD /home/manuel/.rvm/gems/ruby-1.9.2-p290@dev3dynamic/gems/activesupport-3.2.8/lib/active_support/testing/performance.rb:50
c:0011 p:0091 s:0039 b:0039 l:000020 d:000038 BLOCK  /home/manuel/.rvm/rubies/ruby-1.9.2-p290/lib/ruby/1.9.1/minitest/unit.rb:656
c:0010 p:---- s:0034 b:0034 l:000033 d:000033 FINISH
c:0009 p:---- s:0032 b:0032 l:000031 d:000031 CFUNC  :each
c:0008 p:0026 s:0029 b:0029 l:000020 d:000028 BLOCK  /home/manuel/.rvm/rubies/ruby-1.9.2-p290/lib/ruby/1.9.1/minitest/unit.rb:650
c:0007 p:---- s:0026 b:0026 l:000025 d:000025 FINISH
c:0006 p:---- s:0024 b:0024 l:000023 d:000023 CFUNC  :each
c:0005 p:0082 s:0021 b:0021 l:000020 d:000020 METHOD /home/manuel/.rvm/rubies/ruby-1.9.2-p290/lib/ruby/1.9.1/minitest/unit.rb:649
c:0004 p:0188 s:0016 b:0016 l:000015 d:000015 METHOD /home/manuel/.rvm/rubies/ruby-1.9.2-p290/lib/ruby/1.9.1/minitest/unit.rb:609
c:0003 p:0057 s:0007 b:0007 l:001a1c d:000360 BLOCK  /home/manuel/.rvm/rubies/ruby-1.9.2-p290/lib/ruby/1.9.1/minitest/unit.rb:508
c:0002 p:---- s:0004 b:0004 l:000003 d:000003 FINISH
c:0001 p:0000 s:0002 b:0002 l:00207c d:00207c TOP
---------------------------
-- Ruby level backtrace information ----------------------------------------
/home/manuel/.rvm/rubies/ruby-1.9.2-p290/lib/ruby/1.9.1/minitest/unit.rb:508:in `block in autorun'
/home/manuel/.rvm/rubies/ruby-1.9.2-p290/lib/ruby/1.9.1/minitest/unit.rb:609:in `run'
/home/manuel/.rvm/rubies/ruby-1.9.2-p290/lib/ruby/1.9.1/minitest/unit.rb:649:in `run_test_suites'
/home/manuel/.rvm/rubies/ruby-1.9.2-p290/lib/ruby/1.9.1/minitest/unit.rb:649:in `each'
/home/manuel/.rvm/rubies/ruby-1.9.2-p290/lib/ruby/1.9.1/minitest/unit.rb:650:in `block in run_test_suites'
/home/manuel/.rvm/rubies/ruby-1.9.2-p290/lib/ruby/1.9.1/minitest/unit.rb:650:in `each'
/home/manuel/.rvm/rubies/ruby-1.9.2-p290/lib/ruby/1.9.1/minitest/unit.rb:656:in `block (2 levels) in run_test_suites'
/home/manuel/.rvm/gems/ruby-1.9.2-p290@dev3dynamic/gems/activesupport-3.2.8/lib/active_support/testing/performance.rb:50:in `run'
/home/manuel/.rvm/gems/ruby-1.9.2-p290@dev3dynamic/gems/activesupport-3.2.8/lib/active_support/testing/performance.rb:50:in `each'
/home/manuel/.rvm/gems/ruby-1.9.2-p290@dev3dynamic/gems/activesupport-3.2.8/lib/active_support/testing/performance.rb:52:in `block in run'
/home/manuel/.rvm/gems/ruby-1.9.2-p290@dev3dynamic/gems/activesupport-3.2.8/lib/active_support/testing/performance.rb:140:in `run_profile'
/home/manuel/.rvm/gems/ruby-1.9.2-p290@dev3dynamic/gems/activesupport-3.2.8/lib/active_support/testing/performance/ruby.rb:36:in `run'

-- C level backtrace information -------------------------------------------
/home/manuel/.rvm/rubies/ruby-1.9.2-p290/lib/libruby.so.1.9(rb_vm_bugreport+0x72) [0xb76aef72]
/home/manuel/.rvm/rubies/ruby-1.9.2-p290/lib/libruby.so.1.9(+0x54123) [0xb758b123]
/home/manuel/.rvm/rubies/ruby-1.9.2-p290/lib/libruby.so.1.9(rb_bug+0x33) [0xb758be13]
/home/manuel/.rvm/rubies/ruby-1.9.2-p290/lib/libruby.so.1.9(+0x1090c3) [0xb76400c3]
[0xb775440c]
/home/manuel/.rvm/gems/ruby-1.9.2-p290@dev3dynamic/gems/ruby-prof-0.11.2/lib/ruby_prof.so(+0x32c1) [0xb5f8a2c1]
/home/manuel/.rvm/rubies/ruby-1.9.2-p290/lib/libruby.so.1.9(rb_threadptr_exec_event_hooks+0xe4) [0xb76b3434]
/home/manuel/.rvm/rubies/ruby-1.9.2-p290/lib/libruby.so.1.9(+0x16ca1d) [0xb76a3a1d]
/home/manuel/.rvm/rubies/ruby-1.9.2-p290/lib/libruby.so.1.9(+0x16d460) [0xb76a4460]
/home/manuel/.rvm/rubies/ruby-1.9.2-p290/lib/libruby.so.1.9(rb_yield+0x55) [0xb76a92a5]
/home/manuel/.rvm/rubies/ruby-1.9.2-p290/lib/libruby.so.1.9(rb_ary_each+0x4a) [0xb755981a]
/home/manuel/.rvm/rubies/ruby-1.9.2-p290/lib/libruby.so.1.9(+0x16345d) [0xb769a45d]
/home/manuel/.rvm/rubies/ruby-1.9.2-p290/lib/libruby.so.1.9(+0x1711f0) [0xb76a81f0]
/home/manuel/.rvm/rubies/ruby-1.9.2-p290/lib/libruby.so.1.9(+0x167ea0) [0xb769eea0]
/home/manuel/.rvm/rubies/ruby-1.9.2-p290/lib/libruby.so.1.9(+0x16d460) [0xb76a4460]
/home/manuel/.rvm/rubies/ruby-1.9.2-p290/lib/libruby.so.1.9(rb_yield+0x55) [0xb76a92a5]
/home/manuel/.rvm/rubies/ruby-1.9.2-p290/lib/libruby.so.1.9(rb_ary_each+0x4a) [0xb755981a]
/home/manuel/.rvm/rubies/ruby-1.9.2-p290/lib/libruby.so.1.9(+0x16345d) [0xb769a45d]
/home/manuel/.rvm/rubies/ruby-1.9.2-p290/lib/libruby.so.1.9(+0x1711f0) [0xb76a81f0]
/home/manuel/.rvm/rubies/ruby-1.9.2-p290/lib/libruby.so.1.9(+0x167ea0) [0xb769eea0]
/home/manuel/.rvm/rubies/ruby-1.9.2-p290/lib/libruby.so.1.9(+0x16d460) [0xb76a4460]
/home/manuel/.rvm/rubies/ruby-1.9.2-p290/lib/libruby.so.1.9(rb_yield+0x55) [0xb76a92a5]
/home/manuel/.rvm/rubies/ruby-1.9.2-p290/lib/libruby.so.1.9(rb_ary_each+0x4a) [0xb755981a]
/home/manuel/.rvm/rubies/ruby-1.9.2-p290/lib/libruby.so.1.9(+0x16345d) [0xb769a45d]
/home/manuel/.rvm/rubies/ruby-1.9.2-p290/lib/libruby.so.1.9(+0x1711f0) [0xb76a81f0]
/home/manuel/.rvm/rubies/ruby-1.9.2-p290/lib/libruby.so.1.9(+0x167ea0) [0xb769eea0]
/home/manuel/.rvm/rubies/ruby-1.9.2-p290/lib/libruby.so.1.9(+0x16d460) [0xb76a4460]
/home/manuel/.rvm/rubies/ruby-1.9.2-p290/lib/libruby.so.1.9(rb_vm_invoke_proc+0xf9) [0xb76a5459]
/home/manuel/.rvm/rubies/ruby-1.9.2-p290/lib/libruby.so.1.9(rb_proc_call+0x57) [0xb7596d87]
/home/manuel/.rvm/rubies/ruby-1.9.2-p290/lib/libruby.so.1.9(rb_call_end_proc+0x24) [0xb758f294]
/home/manuel/.rvm/rubies/ruby-1.9.2-p290/lib/libruby.so.1.9(rb_exec_end_proc+0x208) [0xb7591af8]
/home/manuel/.rvm/rubies/ruby-1.9.2-p290/lib/libruby.so.1.9(+0x5abb9) [0xb7591bb9]
/home/manuel/.rvm/rubies/ruby-1.9.2-p290/lib/libruby.so.1.9(ruby_cleanup+0x128) [0xb7591d38]
/home/manuel/.rvm/rubies/ruby-1.9.2-p290/lib/libruby.so.1.9(ruby_run_node+0x3e) [0xb759209e]
/home/manuel/.rvm/rubies/ruby-1.9.2-p290/bin/ruby(main+0x68) [0x8048668]
/lib/i386-linux-gnu/libc.so.6(__libc_start_main+0xf3) [0xb73b8113]
/home/manuel/.rvm/rubies/ruby-1.9.2-p290/bin/ruby() [0x8048691]

[NOTE]
You may have encountered a bug in the Ruby interpreter or extension libraries.
Bug reports are welcome.
For details: http://www.ruby-lang.org/bugreport.html

Aborted
rake aborted!
Command failed with status (134): [/home/manuel/.rvm/rubies/ruby-1.9.2-p290/b...]

Tasks: TOP => test:profile
(See full trace by running task with --trace)

gem list:

actionmailer (3.2.8)
actionpack (3.2.8)
active_scaffold_vho (3.1.4)
activemodel (3.2.8)
activerecord (3.2.8)
activeresource (3.2.8)
activesupport (3.2.8)
acts_as_versioned (0.2.3)
addressable (2.2.8)
airbrake (3.1.2)
analytics-logger (0.3.7)
ancestry (1.3.0)
annotate (2.5.0)
archive-tar-minitar (0.5.2)
arel (3.0.2)
authlogic (3.1.3)
authlogic_device_tokens (0.1.1)
aws-sdk (1.5.8)
best_in_place (0.2.3)
bootstrap-will_paginate (0.0.7)
bson (1.6.4)
bson_ext (1.6.4)
builder (3.0.0)
bundler (1.1.5)
capybara (1.1.2)
central_logger (0.3.2)
childprocess (0.3.4)
columnize (0.3.6)
daemons (1.1.8)
database_cleaner (0.8.0)
deadlock_retry (1.0.2)
delayed_job (3.0.3)
delayed_job_active_record (0.3.2)
diff-lcs (1.1.3)
engineyard (1.4.29)
engineyard-serverside-adapter (1.6.4)
erubis (2.7.0)
escape (0.0.4)
factory_girl (3.6.0)
fast_xs (0.8.0)
fastercsv (1.5.5)
ffi (1.1.2)
formtastic (2.2.1)
headless (0.3.1)
highline (1.6.13)
hike (1.2.1)
hpricot (0.8.6)
httparty (0.8.3)
i18n (0.6.0)
imagesize (0.1.1)
journey (1.0.4)
jquery-rails (2.0.2)
json (1.7.5)
json_pure (1.7.4)
kgio (2.7.4)
launchy (2.0.5)
libwebsocket (0.1.5)
linecache19 (0.5.12)
liquid (2.3.0)
macaddr (1.6.1)
mail (2.4.4)
memcache-client (1.8.5)
mime-types (1.19)
mongo (1.6.2)
mongoid (2.4.11)
multi_json (1.3.6)
multi_xml (0.5.1)
multipart-post (1.1.5)
mysql2 (0.3.11)
net-ssh (2.2.2)
newrelic_rpm (3.4.1)
nokogiri (1.5.5)
open4 (1.3.0)
polyglot (0.3.3)
pr_geohash (1.0.0)
rack (1.4.1)
rack-cache (1.2)
rack-ssl (1.3.2)
rack-test (0.6.1)
rails (3.2.8)
railties (3.2.8)
raindrops (0.10.0)
rake (0.9.2.2)
rdoc (3.12)
recurly (0.4.14)
redcarpet (2.1.1)
redis (3.0.1)
render_component_vho (3.2.1)
rest-client (1.6.7)
rinku (1.7.0)
rsolr (1.0.6)
rspec (2.11.0)
rspec-core (2.11.1)
rspec-expectations (2.11.2)
rspec-mocks (2.11.1)
rspec-rails (2.11.0)
ruby-dbus (0.7.2)
ruby-debug-base19 (0.11.25)
ruby-debug19 (0.11.6)
ruby-prof (0.11.2)
ruby_core_source (0.1.5)
rubyzip (0.9.9)
selenium-webdriver (2.25.0)
shotgun (0.9)
spork (0.9.2)
sprockets (2.1.3)
sqlite3 (1.3.6)
stringex (1.4.0)
sunspot (1.3.0)
sunspot_cell (0.1.2)
sunspot_index_queue (1.1.3)
sunspot_rails (1.3.0)
sunspot_solr (1.3.3)
systemu (2.5.2)
thor (0.16.0)
tilt (1.3.3)
treetop (1.4.10)
tzinfo (0.3.33)
unicorn (4.3.1)
uuid (2.3.5)
uuidtools (2.1.3)
validatable (1.6.7)
watir-webdriver (0.6.1)
will_paginate (3.0.3)
workflow (0.8.1)
xpath (0.1.4)
yajl-ruby (1.1.0)
yard (0.8.2.1)

Profile Jekyll build time

I use Jekyll to build my site, and it is starting to take a rather long time (a few minutes) to compile the site (of a bit more than 600 posts). I suspect that some plugins might be responsible, but it seems there must be a better way to profile the performance of the build than to simply toggle on and off different plugins and parsers.

The minimal output during the build doesn't give any hints -- all the time is simply spent in the "building site" step. I thought I could run the jekyll script through ruby-prof to get some idea, so I made a quick local copy of the jekyll script as jekyll.rb in my site root directory and ran

ruby-prof jekyll.rb

The site looks like it builds fine, but the profiler just chokes with an ugly core dump.

[NOTE]
You may have encountered a bug in the Ruby interpreter or extension libraries.
Bug reports are welcome.
For details: http://www.ruby-lang.org/bugreport.html

Aborted (core dumped)

Is there a more intelligent way to profile the building process of my site and figure out why it's so slow?

Secondly, are there any tricks to speed up the compile time? (For instance, I see the existence of a _cache directory in _plugins, but don't know exactly what it does. I also see an --auto flag to Jekyll, but don't see how I could configure it such that it always recompiles certain pages wether or not they have changed (e.g. the twitter plugin needs to be re-run each time) while not recompiling the unchanged posts).

If anyone wants to poke around first-hand, the Jekyll source of the site is on Github, with some notes in the readme about additional gem dependencies.

Low-overhead Ruby profiling?

I have a Ruby program that takes about 4 minutes to complete task and I'd like to get it down to under 1 minute.

I tried ruby-prof from gem but enabling it increases running times to ~30 minutes, and doesn't even seem to preserve monotonicity particularly well (some changes reliably improve performance-with-profiler and as reliably deteriorate performance-without-profiler). This task also cannot really be broken down into parts that can be meaningfully profiled independently.

What's the current best way to profile Ruby code with lowest overhead?

I use OSX, but if for any reason profiler requires another OS, I might reboot.

EDIT: perftools.rb has much lower overhead, but results look rather dubious to be honest, way outside any reasonable sampling error - at the very least it must be messing with GC or i/o buffering or something like that, causing a lot of silly misattributions. It still beats ruby-prof.

I'll keep the question open in case someone knows anything better than that.

Which is the best graphical ruby profiler?

The best match that I have found until now is to use ruby-prof from command line and try to guess the graph reading from there.

require 'ruby-prof'

# Profile the code
RubyProf.start
...
[code to profile]
...
result = RubyProf.stop

# Print a flat profile to text
printer = RubyProf::FlatPrinter.new(result)
printer.print(STDOUT)

https://github.com/rdp/ruby-prof

The main problem with this approach is that you have to modify your code to see the profiling and is not very readable.

Also I have tried if some IDEs: RubyMine, Aptana and Netbeans and no one has a proper graphical interface to profile code.

Any recommendation?

ruby-prof "Wait" column in the results: what is it?

The results for the ruby-prof output always contains a value for the "Wait" column. However, I've never found a description of what this value is and in all the times I've used ruby-prof, I've never seen this column ever take on a value other than 0.

What is this value supposed to represent? Any help would be appreciated. Thanks!