where is all the time going on ruby-prof

[Alon Burg]

Hi 

I am trying to profile a Rails 3 application. More specifically trying to understand how come my JBuilder views are taking 600msec to render ~55KB of JSON (5.7K gzipped)

I installed ruby-prof and Rack::RubyProf middleware.

First (normal) test yielded this flat.txt

Thread ID: 2502256640

Total: 2.972724

Sort by: self_time

 %self     total     self     wait    child    calls   name

  6.18      0.30     0.18     0.00     0.11       17  *Kernel#require 

  6.18      0.18     0.18     0.00     0.00     2381   <Class::Thread>#start 

  4.11      0.15     0.12     0.00     0.03     7369  *Array#hash 

  3.11      0.09     0.09     0.00     0.00    19572   <Class::Thread>#current 

  3.04      0.10     0.09     0.00     0.01      176   Dragonfly::Job#serialize 

  1.51      0.07     0.04     0.00     0.02    41279   Hash#[]= 

  1.42      0.34     0.04     0.00     0.30       17  *ActiveSupport::Dependencies::Loadable#load_dependency 

  1.28      0.15     0.04     0.00     0.11     8776   Mongoid::Threaded#stack 

  1.21      0.12     0.04     0.00     0.09     1174   <Module::CBson>#deserialize 

  1.20      0.28     0.04     0.24     0.00     2381   Thread#join 

  1.18      0.04     0.04     0.00     0.00    74165   Module#=== 

  1.13      0.06     0.03     0.00     0.02     4000   Mongoid::Attributes#respond_to? 

  1.02      0.03     0.03     0.00     0.00    37701   Symbol#to_s 

Second test I rendered the JBuilder 10 times in a loop inside the controller - hoping to make the problematic calls more apparent

Thread ID: 2511939460

Total: 9.747937

Sort by: self_time

 %self     total     self     wait    child    calls   name

  3.07      0.30     0.30     0.00     0.00     3439   IO#write 

  2.00      0.63     0.20     0.00     0.43       17  *Kernel#require

  2.00      0.20     0.20     0.00     0.00     3546   String#[] 

  1.94      0.21     0.19     0.00     0.02    13606   String#gsub 

  1.90      0.19     0.19     0.00     0.00    10593   String#sub 

  1.80      0.20     0.18     0.00     0.03     1681   Mongoid::Fields::Serializable#evaluated_default 

  1.45      0.31     0.14     0.00     0.17     1174   <Module::CBson>#deserialize 

  1.42      0.14     0.14     0.00     0.00     2381   <Class::Thread>#start 

  1.34      0.18     0.13     0.00     0.05   106233   Hash#[]= ########################

  1.26      0.12     0.12     0.00     0.00    10154   String#sub! 

  1.26      0.98     0.12     0.00     0.86     2519   ActionView::Helpers::DateHelper#distance_of_time_in_words 

  1.21      0.13     0.12     0.00     0.01     1801   String#match 

  1.12      0.11     0.11     0.00     0.00   100928   Module#=== ##############

  1.12      0.45     0.11     0.00     0.34    17652  *Array#map ###############

  1.07      0.10     0.10     0.00     0.00       11   ActionView::Context#_prepare_context 

  1.00      0.10     0.10     0.00     0.00   115128   Symbol#to_s #############

What I can't figure out: It seems like what RubyProf is showing top "heavy" but still I cannot seem to see the real problem as these calls are only taking about ~80% of the time.

If I understand correctly it seems like this is a problem of templates being compiled into different function names (which is probably also the main cause of time consumptions).

Is there any way to gain better insight into this?

Am I assuming correctly the above?

Any thoughts about optimizing this?

Thanks,

Alon

[rogerdpack]

You know, I've wondered about that sometimes in the past,
too...like...where is all the time going?

the graphviz or other output formats might be useful, since it doesn't
immediately appear to see what's going on (or the ruby-perf tools,
though i've never used them).
Which version of ruby are you using?
-r

[Alon Burg]

correction... I meant 20%:

What I can't figure out: It seems like what RubyProf is showing top "heavy" but still I cannot seem to see the real problem as these calls are only taking about ~20% of the time.

[Roger Pack]

what do you mean by top "heavy"?
If it's that "the profile seems to say some things are using most cpu,
when they actually aren't" then...maybe your hypothesis is right and
the cpu is scattered.

Also broadening the "range" of cpu code can sometimes help (like
profiling all of rails instead of just the one view).
-r

[Caleb Clausen]

On 05/14/2012 03:45 PM, Alon Burg wrote:
> Hi
> I am trying to profile a Rails 3 application. More specifically trying
> to understand how come my JBuilder views are taking 600msec to render
> ~55KB of JSON (5.7K gzipped)
> I installed ruby-prof and Rack::RubyProf middleware.
>
> First (normal) test yielded this flat.txt

Not quite what you're asking, but...
I usually find the ruby-prof (and gprof, whose output ruby-prof is
imitating) flat views to be unhelpful. I recommend the graph_html output
style instead, tho it does take longer to figure out how to read. It's
nicer because it helps you figure out not just what functions are taking
all the time, but what functions call them, and what functions call
them, etc. Usually, you want to optimize not the place where the time is
being spent, but something several levels up the call stack, and figure
out how to get it to not call that function at all.

I'd also strongly suggest looking at Aman Gupta's perftools.rb... which
I think roger was alluding to. It also shows you the callers of the time
sinks, but it also has an output mode where it creates a jpg that is
very easy to read.

> correction... I meant 20%: What I can't figure out: It seems like

> what RubyProf is showing top "heavy" but still I cannot seem to see

> the real problem as these calls are only taking about ~20% of the
> time.

I _think_ what might be happening is that ruby-prof is showing you the
top 20 offenders or whatever... but together these only amount to 20-25%
of the total. So, you're seeing the tip of the iceberg, but most of it
is still beneath the surface. Again, a larger, gestalt view which shows
you the callers as well as the actual slow paths might help.

The fact that require shows up high in both of the outputs you posted
indicates that your test run is still dominated by startup time. Try 100
or 1000 iterations and see if that require doesn't get pushed down.

Other than that, I see a lot of sub and gsub and IO#write, indicating a
string-heavy computation load. Without source code, its very hard to
tell much more than that.

[Alon Burg]

Hi Caleb & Roger,

Thank you very much for your responses.

I tried adding PerfTools but still seem to be missing some understanding of where is most of the time spent and which functions are eating all of the cpu/performance.

A few clarifications on the stack I am profile: Rails 3.1 + Mongoid + JBuilder for JSON rendering.

The main issue I am trying to debug is why the JBuilder JSON rendering is taking 80% of the request time in production (530msec spent on views / 640sec total request time)

Attached is my PerfTools + RubyProf results

Thoughts?

[Roger Pack]

Which version of ruby?
-r

[alon burg]

Ruby 1.9.3

[Roger Pack]

Have you tried profiling just the rendering part? What does that give?
-r

[alon burg]

I am not sure how can I do that

[Roger Pack]

Are you benchmarking a single view?

[alon burg]

yep - single view

[Roger Pack]

> yep - single view

With my rails 2.3 app, at the end of the view add a line like

render :action => 'new'

Then just put your profiling "stuff" around that one line.
HTH.
-r

[Caleb Clausen]

On 05/15/2012 04:27 AM, Alon Burg wrote:
> Hi Caleb & Roger,
> Thank you very much for your responses.
> I tried adding PerfTools but still seem to be missing some understanding
> of where is most of the time spent and which functions are eating all of
> the cpu/performance.
>
> A few clarifications on the stack I am profile: Rails 3.1 + Mongoid +
> JBuilder for JSON rendering.
> The main issue I am trying to debug is why the JBuilder JSON rendering
> is taking 80% of the request time in production (530msec spent on views
> / 640sec total request time)
>
> Attached is my PerfTools + RubyProf results

Ok, took a look at the profiler outputs you sent. perftools wasn't very
enlightening... all the boxes were about the same size, so nothing is
jumping out there. Plus, it's rails so of course there's some big long
call stack....

the graph.html is more revealing, I think. Usually interpreting these is
a matter of pouring over the output for hours combined with spelunking
the source code, (which is deeper than I intend to go) but here are some
things that are obvious:

1) 17 calls to Mongoid::Collections::Retry#retry_on_connection_failure
accounted for 44.33% of time. It's something to think further on... I'd
say that there probably shouldn't have been any calls to this. Lots of
time spent in Mongoid generally, but it all seems to flow towards this.
Maybe your mongo server needs more resources?

2) JBuilder (which I don't know what that is, I thought that was a
borland ide) shows up at maybe 32%? not sure what's going on there.

3) actual time rendering json looks to be around 16%. considering your
workload, this is interesting. it could be worth optimizing the json
render, maybe with some custom renderers which would be faster than the
generic ones from JSON, but that's not where you need to look first.

4) Mongoid (and other things) are doing lots of Kernel#tap, which is
silly. profiler claims this is only 0.1%, but this could be deceptive.
Might be worth trying to inline this.

It looks like this test run only went for maybe 4 seconds? How many
queries were done for this run? Once again, I recommend longer test runs
when doing profiling, to help filter out the noise better. A couple
minutes is a good lower limit.

I recommend you try to learn how to read graph_html; I know there are
some guides out there that could help you. Google for something like
'interpreting ruby-prof output' or 'interpreting gprof output' (since
ruby-prof and gprof give very similar outputs).

[alon burg]

Hey Caleb,

Thank you for the in-depth investigation and response.

Indeed Mongoid is taking some significant time but this is only in development mode. Production looks better in this aspect.

On the other hand the JBuilder rendering is still problematic in production as well and this is that part I would like to optimize.

I will try your suggestion of profiling only the view rendering part + repeating the test for few minutes in order to filter noise.

Thanks

Alon