Re: [Hobo Users] Inherited ridiculously slow Hobo app, how can I speed it up?

[Matt Jones]

On Jul 11, 2012, at 5:45 PM, Raphael Sofaer wrote:

> Hi Hobo users,
>
> I'm a developer with rails experience working at a neuroscience lab, and we have a legacy hobo app which is ridiculously slow. Some of our index pages take 10 seconds to load. All the time is in view rendering, effectively none in ActiveRecord. How can I figure out what's wrong here? Most of the places I would but benchmarking functions are wrapped up in hobo methods, so I'm not sure what to do. The slowest page uses hobo_index in the controller, and collection and table_plus in the dryml file. Are those a recipe for disaster? I don't think there's any page that has a sub-second load time, though.

The first thing I'd check is the server - is it running in production mode? The behavior you've described sounds a lot like the result of an app running in development mode. Also check to see if the server is overloaded (swapping, etc) as some of the old defaults for gems like Passenger specified an unreasonable number of processes for small machines.

Note that some of the timing stuff (especially on older Rails) will not always give sensible results; for instance, a default index action will only actually load records when they're used on the page, causing the view to get charged most of AR's time as well.

Ping me off-list if you'd like another set of eyes on the code.

--Matt Jones

[Vivek Sampara]

You're issue is page load at the index i would consider looking into the joins to generate and execute the query. Something very similar  happened to me which was because of too many conditions. Can you copy your sql code generated at the console ? 

-Vivek Sampara

--
You received this message because you are subscribed to the Google Groups "Hobo Users" group.

To post to this group, send email to hobo...@googlegroups.com.
To unsubscribe from this group, send email to hobousers+...@googlegroups.com.
For more options, visit this group at http://groups.google.com/group/hobousers?hl=en.

[Raphael Sofaer]

Hi Matt, Vivek,

Here's some more information.  The app is running in production mode, although I'd like it to be a reasonable speed in dev mode also, for development.  Dev mode now is up to twice as slow.  There's tons of free memory and cpu on the machine.  Rails and hobo versions:

    rails (3.0.5)

    hobo (1.3.0)

I've set the log level to debug to get the queries for the particular index page that I'm looking at, the class names aren't secret:

  Processing by PipettePullsController#index as HTML

  PipettePull Load (1.0ms)  SELECT `pipette_pulls`.* FROM `pipette_pulls` LIMIT 300 OFFSET 0

  SQL (0.6ms)  SELECT COUNT(*) FROM `pipette_pulls`

  CACHE (0.0ms)  SELECT `pipette_pulls`.* FROM `pipette_pulls` LIMIT 300 OFFSET 0

  StereotaxicInjection Load (15.1ms)  SELECT `stereotaxic_injections`.* FROM `stereotaxic_injections` WHERE (`stereotaxic_injections`.pipette_pull_id IN (4,[snip, there are about 250 ids in here],303))

  TracerType Load (0.5ms)  SELECT `tracer_types`.* FROM `tracer_types` WHERE (`tracer_types`.`id` IN (6,7,8,10,17,9,11,12,16,24,18,28,27,26,19,21,22,20,23,29,30,33,31,32,34,35))

  CACHE (0.0ms)  SELECT COUNT(*) FROM `pipette_pulls`

Rendered pipette_pulls/index.dryml (9238.8ms)

Completed 200 OK in 9371ms (Views: 9239.8ms | ActiveRecord: 17.2ms)

The queries are insignificant in the total time, and it doesn't seem like there are any hidden relations being loaded.  Here's the controller code for the action:

hobo_model_controller

auto_actions :all

def index

  hobo_index :per_page => 300, :include => {:stereotaxic_injections => :tracer_type}

end

I put the nested include in a couple days ago, which sped it up marginally, and reduced drastically the number of queries.

I noticed that the model has a view_permitted?(field) method which just returns true.  I'm not sure if that's run for every user/model combination, would that be a big performance hit?

Thanks again,

Raphael

[Vivek Sampara]

Raphael ,

The only thing thats causing this delay is because of the query ( 250+ IN conditions ). I would normally write a def in the model and do the conditions part there. 

eg. in controller 

def index

  hobo_index 

  @pipette_pulls = Pipette_pull.filtered(current_user) 

end

And model 

def self.filtered(user)

  @pipette_pulls = Pipette_full.all 

  #Write your conditions and filter the data through ruby and return the filtered ones 

  return @pipette_fulls 

end

--
You received this message because you are subscribed to the Google Groups "Hobo Users" group.

To view this discussion on the web visit https://groups.google.com/d/msg/hobousers/-/hjBnu6V8hsYJ.

[Raphael Sofaer]

Hi Vivek,

On Fri, Jul 13, 2012 at 12:55 AM, Vivek Sampara <ravens...@gmail.com> wrote:
> Raphael ,
>
> The only thing thats causing this delay is because of the query ( 250+ IN
> conditions ). I would normally write a def in the model and do the
> conditions part there.
>

That query is a result of the include clause in the query for pipette
pulls, and it takes pretty much no time at all. There aren't any
conditions, everyone can see all of these records. Taking out the
include would just split that query up, and query itself is pretty
much instantaneous. Even instantiating 300 AR objects doesn't take a
second, let alone multiple seconds. When I do the query and print out
the objects and related objects in the console, it takes much less
than a second. I'm pretty sure that whatever is happening is
happening in the views. Can Hobo give me a per-partial (or Hobo
equivalent) breakdown of the time spent?

[Vivek Sampara]

Raphael, 

I dont know how to trace down at that level. All i can say is the time taken to generate the query might be the issue. Rendering wont cause the delay at all. 

[Bryan Larsen]

It looks like you've done a great job of optimizing your database
access. That's usually the first stumbling block in a Hobo
application because it's so easy for Hobo to load things implicitly.

I've seen 10 second DRYML pages before, but I've never before seen a
10 second DRYML page with optimized database access. It does look
like you've got a fairly large page, at least from the number of
elements you're pulling from the database.

FIrst question: is your use pattern amenable to caching? If your
pages change infrequently compared to the number of times they're
accessed, your best bet may be to set up caching and not worry about
initial page render. There are some nice new cache tags in 1.4, but
Rails-style fragment caching is pretty easy to do in 1.3.

Unfortunately the profiling tools you asked for aren't available. One
helpful tool is https://github.com/ddnexus/dryml-firemarker

This will let you understand the hierarchy of tags that went into
producing the page, and may give you an indication of where it would
be helpful to try and flatten things out.

For instance, if it is called a few hundred times, it might be worth
replacing <view:name/> with <%= name %>. You'll lose a permission
check and the overhead of a few function calls. Another example: if
the page consists of a big table, it might provide a nice speed up by
using the <tr:> parameter rather than column parameters.

Finally, Matt offered to help -- take advantage of that offer. He
probably has more experience with Hobo apps, even including Tom &
myself at this point.

cheers,
Bryan

[Matt Jones]

On Jul 13, 2012, at 1:35 AM, Raphael Sofaer wrote:

> Hi Vivek,
>
> On Fri, Jul 13, 2012 at 12:55 AM, Vivek Sampara <ravens...@gmail.com> wrote:
>> Raphael ,
>>
>> The only thing thats causing this delay is because of the query ( 250+ IN
>> conditions ). I would normally write a def in the model and do the
>> conditions part there.
>>
>
> That query is a result of the include clause in the query for pipette
> pulls, and it takes pretty much no time at all. There aren't any
> conditions, everyone can see all of these records. Taking out the
> include would just split that query up, and query itself is pretty
> much instantaneous. Even instantiating 300 AR objects doesn't take a
> second, let alone multiple seconds. When I do the query and print out
> the objects and related objects in the console, it takes much less
> than a second. I'm pretty sure that whatever is happening is
> happening in the views. Can Hobo give me a per-partial (or Hobo
> equivalent) breakdown of the time spent?

I don't recall anything like that out-of-the-box, but you could try doing something like this, someplace in the DRYML:

<% benchmark 'Some Label' do %>
... view code ...
<% end %>

This is an ActiveSupport helper that will print out the specified message along with the time taken inside the block. I suspect the hotspot's in table-plus someplace, but I can't think of where it would be bad offhand.

You might also want to try out NewRelic - they've got a free version with all the features for the first 14 days. It's been a while since I used them on an app with DRYML views, but they've got some pretty solid benchmarking stuff and will provide at least *some* insight.

I'll see what I can reproduce over here this weekend.

--Matt Jones

[Owen Dall]

Thanks for looking into this, Matt.

-Owen

> --
> You received this message because you are subscribed to the Google Groups "Hobo Users" group.
> To post to this group, send email to hobo...@googlegroups.com.
> To unsubscribe from this group, send email to hobousers+...@googlegroups.com.
> For more options, visit this group at http://groups.google.com/group/hobousers?hl=en.
>

--



Owen Dall

Vice President | Chief Technology Officer

Barquin International

www.barquin.com

Office: 202.296.7147 | Mobile: tel:410.991.0811

Fax: 202.296.8903 | email: od...@barquin.com

[Ignacio Huerta]

-----BEGIN PGP SIGNED MESSAGE-----
Hash: SHA1

Hi Raphael,

I've seen this kind of issues before. I suspect the problem lies in
the the way Hobo creates the table, running a lot of code for every
element in every row. I would recommend:

- - Decide if you really need 300 elements per page. I usually work with
50 or so, and it's a huge difference.

- - Create your own "table-plus" with your own helper. Just enclose a
manual table with a div class="table-plus" and you'll get the looks
and it'll probably much faster.

- - There are a lot of complex benchmarking solutions, but I usually
enjoy this hack:
START = Time.now
# Here it goes the code you are benchmarking
logger.info ((Time.now - START)*1000).to_s + 'ms since START'

- - Use page caching if the content is not changing a lot.




Not related to your question, but other important tips for performance
and user experience:

- - In development mode, Rails 3.2 with Active Reload makes a huge
difference. As you are in Rails 3.0 I would try the rails-dev-boost
gem. It has some glitches but makes development mode usable!

- - Cache assets, fingerprinting them so the browser doesn't ask for
them. This has been made much easier and faster in Rails 3.2, but Hobo
is not ready just yet.

- - Load javascript after the page has loaded (lazy loading). I'm using
right now something like this, and you win something like 200ms in
Firefox:

<extend tag="page">
<old-page merge>
<scripts: replace/>
<append-body:>
<script defer type="text/javascript">
(function() {
function getScript(url,success){
var script=document.createElement('script');
script.src=url;
var head=document.getElementsByTagName('head')[0],
done=false;
script.onload=script.onreadystatechange = function(){
if (!done){
if (!this.readyState || this.readyState == 'loaded' ||
this.readyState == 'complete'){
done=true;
success();
script.onload = script.onreadystatechange = null;
head.removeChild(script);
}}
};
head.appendChild(script);
}
setTimeout(function() {
getScript('/assets/application.js',function(){
// YOUR CODE GOES HERE AND IS EXECUTED AFTER JQUERY LOADS
});
},250);
})();
</script>
</append-body:>
</old-page>
</extend>

Regards,
Ignacio

El 13/07/12 01:44, Raphael Sofaer escribi�:

> -- You received this message because you are subscribed to the

> Google Groups "Hobo Users" group. To view this discussion on the
> web visit

> https://groups.google.com/d/msg/hobousers/-/hjBnu6V8hsYJ. To post

> to this group, send email to hobo...@googlegroups.com. To
> unsubscribe from this group, send email to
> hobousers+...@googlegroups.com. For more options, visit
> this group at http://groups.google.com/group/hobousers?hl=en.

- --
Ignacio Huerta Arteche
http://www.ihuerta.net
Tel�fono: 0034 645 70 77 35
Email realizado con software libre
-----BEGIN PGP SIGNATURE-----
Version: GnuPG v1.4.10 (GNU/Linux)
Comment: Using GnuPG with Mozilla - http://enigmail.mozdev.org/

iEYEARECAAYFAlAAZa4ACgkQBPlUJ6RHaOR7PACff2OQNs0wNIPUyXKTjV8E5FYv
pA8AnRVxXU6mU4GJw0fBkPsRA3xcwPmz
=xkaX
-----END PGP SIGNATURE-----

[Peter Booth]

I'd second the recommendation for new relic, and also suggest driving the app hard with a test tool and seeing whether you're io or compute bound.

Are you running on a physical or a VM?

Sent from my iPhone

[Matt Jones]

On Jul 12, 2012, at 7:44 PM, Raphael Sofaer wrote:

> Hi Matt, Vivek,
>
> Here's some more information. The app is running in production mode, although I'd like it to be a reasonable speed in dev mode also, for development. Dev mode now is up to twice as slow. There's tons of free memory and cpu on the machine. Rails and hobo versions:
> rails (3.0.5)
> hobo (1.3.0)

Just to verify, which Ruby are you running on? (1.8.6 / 1.8.7 / 1.9.2)

Some preliminary profiling on 1.9.2 is turning up (bizarrely) Array#to_s as a major time sink. This may be a side-effect of changes in 1.9 (it used to just glue all the strings together, now it adds brackets + inspects the strings). More as this develops.

--Matt Jones

[Raphael Sofaer]

Hi everyone,

I'm not going to be able to try any of these measures until tonight,
but thank you all for your suggestions. I did benchmark the
table-plus call, and all the time is inside of that call (9531.3/9953,
for example). I'll try to go in there and investigate tonight.

Matt, we are running ruby 1.9.2, so that Array#to_s problem could be relevant.
Ignatio, assets and javascript loading aren't an issue, and I'm not
really willing to look at caching, since that could introduce problems
that the lab techs would have trouble understanding if I make
incorrect assumptions. I'll try replacing table-plus with a manual
table to see if that speeds things up. Are the permissions checks
done in the controller, or in the view?

Peter, the app is running on a physical machine, and it's definitely
compute time that is the majority of the request time.

I was pretty worried when I saw this problem, since I'd never seen
Hobo before, but now I'm confident I will find a resolution, since
this list is so helpful.
Thanks again,
Raphael Sofaer

[Owen Dall]

Please keep us updated on your progress...

Thanks,

Owen

[Tomoaki Hayasaka]

Hi,

As Bryan already mentioned about it, <a> and <view> for active record
objects are slow. Eliminating calls for those tags (and fields=""
attribute which calls <view> internally) may be worth it.

See following results. You'll see dryml itself is already not fast
(the first entry, 500 * "string" takes 250..300ms including GC), as
well as <a> and <view> are much slower.

<!-- app/views/front/index.dryml -->
<section class="content-body">
<!-- C2Q 9550 2.83GHz, Linux 3.2.0-2-686-pae (Debian sid), ruby 1.9.2p180, hobo 1.3.0, rails 3.0.10
guest (GC enabled)
/ logged-in user (GC enabled)
/ logged-in user (GC enabled, custom <view for="User">)
/ logged-in user (GC disabled) -->
<br/>
<!-- 316 / 311 / 312 / 248 ms --><how-slow num="500">string</how-slow>
<!-- 214 / 209 / 214 / 182 ms --><how-slow num="400">string</how-slow>
<!-- 159 / 154 / 155 / 126 ms --><how-slow num="300">string</how-slow>
<!-- 83 / 80 / 82 / 82 ms --><how-slow num="200">string</how-slow>
<!-- 50 / 49 / 50 / 52 ms --><how-slow num="100">string</how-slow>
<!-- 313 / 310 / 316 / 250 ms --><how-slow><%= can_view?(current_user) %></how-slow>
<!-- 709 / 700 / 702 / 572 ms --><how-slow><view with="&%(string)"/></how-slow>
<br/>
<!-- 309 / 384 / 382 / 320 ms --><how-slow><%= current_user.to_s %></how-slow>
<!-- 708 / 765 / 769 / 639 ms --><how-slow><view with="&current_user.to_s"/></how-slow>
<br/>
<!-- 343 / 494 / 498 / 405 ms --><how-slow><do with="&current_user"><%= this.login %></do></how-slow>
<!-- 738 / 964 / 967 / 794 ms --><how-slow><do with="&current_user"><view with="&this.login"/></do></how-slow>
<!-- 735 / 1078 / 1054 / 904 ms --><how-slow><do with="&current_user"><view:login/></do></how-slow>
<br/>
<!-- 721 / 704 / 708 / 581 ms --><how-slow><a href="&user_path(1)">string</a></how-slow>
<!-- 317 / 789 / 794 / 673 ms --><how-slow><% raise Hobo::PermissionDeniedError unless can_view?(current_user) %><% if current_user.signed_up? %><a href="&user_path(current_user.id)"><%= current_user.to_s %></a><% else %><%= current_user.to_s %><% end %></how-slow>
<!-- 343 / 824 / 825 / 696 ms --><how-slow><do with="&current_user"><% raise Hobo::PermissionDeniedError unless can_view? %><% if this.signed_up? %><a href="&user_path(this.id)"><%= this.to_s %></a><% else %><%= this.to_s %><% end %></do></how-slow>
<!-- 410 / 2310 / 1329 / 1905 ms --><how-slow><view with="&current_user"/></how-slow>
<!-- 425 / 1633 / 1635 / 1384 ms --><how-slow><a with="&current_user"/></how-slow>
</section>

<!-- app/views/taglibs/application.dryml -->
<def tag="how-slow" attrs="num">
<% disable_gc = false %>
<% num ||= 500 %>
<% GC.start %>
<% GC.disable if disable_gc %>
<% t0 = Time.now %>
<div style="display: none;">
<repeat with="&(0..(num.to_i))">
<do param="default"/>
</repeat>
</div>
<% GC.enable if disable_gc %>
<% GC.start %>
<% t1 = Time.now %>
<br/>
<%= ((t1 - t0) * 1000).to_i %>
</def>

<!--
<def tag="view" for="User">
<% raise Hobo::PermissionDeniedError, "view of non-viewable user #{this}" unless can_view? %>
<% if this.signed_up? %>
<a href="&user_path(this.id)"><%= this.to_s %></a><%# user_path(user.id) is much faster than user_path(user) %>
<% else %>
<%= this.to_s %>
<% end %>
</def>
-->

-----
Tomoaki Hayasaka <haya...@pfsl.mech.tohoku.ac.jp>

[Matt Jones]

Replying to my own message - Array#to_s is *part* of the problem (not helped by debugging code I left in - ugh) but another (unexpected) time-sink is actually method_missing on NilClass. Turns out, this code:

a, b = nil

tries to call to_ary on nil, builds a NoMethodError, and then *silently discards it*. I'm seeing something like 12% of the total runtime soaking into this utterly useless behavior. Disabling whiny nils shifts where the time goes, but doesn't stop it; there's something obscure going on in Ruby's guts that's causing this.

In the meantime, the truly adventurous can try changing the definition of new_context (in template_environment.rb) from this:

def new_context
ctx = [ @_this, @_this_parent, @_this_field, @_this_type,
@_form_field_path, @_form_field_paths_by_object ]
@_this_type = nil
res = nil
outer_res = @view.with_output_buffer { res = yield }
Rails.logger.error("new_context: #{caller.first}") if !outer_res.blank? && outer_res.to_s != res.to_s
@_this, @_this_parent, @_this_field, @_this_type, @_form_field_path, @_form_field_paths_by_object = ctx
res.to_s
end

to this:

def new_context
ctx = [ @_this, @_this_parent, @_this_field, @_this_type,
@_form_field_path, @_form_field_paths_by_object ]
@_this_type = nil
res = nil
outer_res = @view.with_output_buffer { res = yield }
@_this, @_this_parent, @_this_field, @_this_type, @_form_field_path, @_form_field_paths_by_object = ctx
if res.is_a?(Array)
res.join('')
else
res.to_s
end
end

This restores the ruby1.8 behavior of Array#to_s, and saves a considerable amount of time. However, I'm not sure it's the right fix, since the return value of the old version of new_context was *clearly* nonsense for the cases it fixes (it returned a formatted array, like this: "['something', 'some_other_thing', 'bleh']") so the join may not be needed at all, since those cases never turn up in the displayed HTML.

Fun fact: the ERB created by DRYML is sufficiently weird (especially with all the new_context recursion) that it tends to confuse ruby-prof - turning on memory profiling causes it to claim (sometimes) that 18014398505397860 bytes have been allocated...

More updates soon.

--Matt Jones

[Bryan Larsen]

> - - Create your own "table-plus" with your own helper. Just enclose a
> manual table with a div class="table-plus" and you'll get the looks
> and it'll probably much faster.
>

There's a nice intermediate step here that will get you most of the
speed up without much of the work.

Rather than:

<table-plus fields="foo,bar">
<foo-view:>a</foo-view:>
<bar-view:>b</bar-view:>
</table-plus>

Do:

<table-plus fields="foo,bar">
<tr:>
<td>a</td>
<td>b</td>
</tr:>
</table-plus>

cheers,
Bryan

[Raphael Jedidiah Sofaer]

Hi Bryan,

This worked well. switching out:

<table-plus fields="this,stereotaxic_injections"/>

For:

<table-plus fields="this,stereotaxic_injections">
<tr:>
<td><%=link_to this,pipette_pull_path(this)%></td>
<td>
<repeat with="&this.stereotaxic_injections">
<span>
<%= link_to this.to_s + ",", stereotaxic_injection_path(this)%>
</span>
</repeat>
</td>
</tr:>
</table-plus>

Cut the render time from around 16s to 5s. Since this is a big page with hundreds of links out, I'm going to take that improvement and apply it to the rest of the index pages on the site. I also tried:

<table-plus fields="this,stereotaxic_injections">
<tr:>
<td><a/></td>
<td>
<repeat with="&this.stereotaxic_injections">
<a/>
</repeat>
</td>
</tr:>
</table-plus>

That cut out only about 3s, leaving the render time around 13s. So most of the time is in <a/>, I think.

Thanks for your help, everyone!
Raphael Sofaer
>
> cheers,
> Bryan

>
> --
> You received this message because you are subscribed to the Google Groups "Hobo Users" group.

[Owen Dall]

Interesting...

[Bryan Larsen]

If you do this instead of <a/>, how much does it help?

<a href="&stereotaxic_injection_path(this)"><%= this.to_s %>,</a>

That runs <a> in "dumb mode".

thanks,
Bryan

[Raphael Jedidiah Sofaer]

It's the same as using link_to. Pretty much all of the overhead of <a/> doesn't happen.

>
> <a href="&stereotaxic_injection_path(this)"><%= this.to_s %>,</a>
>
> That runs <a> in "dumb mode".
>
> thanks,
> Bryan
>

[Bryan Larsen]

>
> It's the same as using link_to. Pretty much all of the overhead of <a/> doesn't happen.
>

Good. That's what I expected, but expectations don't always get met. :)

thanks,
Bryan