Search code examples
ruby-on-railsrubyprofilingrspecjruby

Use Ruby profile to track down slow execution in RSpec

I have a bunch of rspec tests that are taking entirely too long to run. I am trying to figure out where the bottleneck is and the logical place to start is using the standard libraries profile library. Execution is happening with JRuby 1.5.2 in this particular case. Here is the output after embedding the profile library in my spec:

 %   cumulative   self              self     total
 time   seconds   seconds    calls  ms/call  ms/call  name
  0.37     0.37      0.37       69     5.33     5.33  #<Class:#<Object:0x99b2a1d>>#include
  0.01     0.38      0.01      208     0.06     0.06  String#fast_xs
  0.00    98.99      0.00        1     0.00 98987.00  #toplevel

I need to look into why 208 calls are being made to String#fast_xs, but the real question here is what exactly is happening in #toplevel? There is a latency of 98987.00ms being spent on something in there and I need a more granular way of seeing the breakdown to understand what I can change in my spec tests to speed things up.

Solution

  • There are so many questions like this. Some profile output is shown, and the question: "What's going on?"

    There's no need to puzzle over the profile output. You can find the problem(s) right away. The more time they take, the easier they are to find.

    Anything that deals in self-time, ms-per-call, call counts, etc. is stuck in the pit of performance myths.

    Added: For example

    • self time (exclusive) is based on the premise that the only way you can waste time is by not calling functions. When functions are called unnecessarily, that you'd like to find and get rid of, or if IO is done unnecessarily, it doesn't show up in self time. IO and other blocking time doesn't show up at all if samples are only taken when the program is unblocked.

    • ms-per-call (inclusive), multiplied by call count of a function, divided by total time, gives fraction of time the function is responsible for. With only two of these three numbers you can't tell if the function is spending too much time or not.

    • If you can tell if a function is responsible for a good fraction of time, you still need to find the lines within it that are responsible for the time. If the profiler acts like the only units you care about are functions, you're still left doing detective work.