Apparently poor performance in partial rendering - string concatenation problems?

Hi all,

I have a page which displays search results, and each result has a
common format. So I have a partial that describes an individual search
result, and I iterate on that partial to show the results.

I'm finding performance is abysmal, and to my surprise it's unrelated
to:
- my database query (runs fast)
- calculations done in the partial (I've removed them all and
experimentally just put static html in the partial)

It really seems to all be in string concatenation. For example, in my
search results page if I do this on my search results page, it runs in
under a HALF a second (with 50 items):

output = []
bookmark_list.each{|bm| output <<
render_to_string(:partial=>'list_item', :object=>bm)}

However as soon as I take that output variable and print it to the
screen, the execution time jumps up to almost THREE seconds:

<%=output%>

That one line seems to slam the server - and the only thing that line
does is print the output (yes, it also does an array.join, but I've
added that and found no serious performance impact).

The big bummer here is that it means that even if I cached the output
it would save me nothing, because the big slowdown is when I add that
output to the body of the page. It seems like something is really slow
when appending that big string to the page.

Does anyone know why this is happening? It's really surprising to me,
and I'm not even sure what workarounds are available. Interestingly,
I've found if I cut the search results partial ('list_item') so all of
the HTML is on one line, it cut the execution time down from about 3
seconds to just under 2 seconds. There's definitely something at work
here that I'm not understanding. Since the use of partials is so
common, it seems like these kinds of operations would not be unusual,
so I'm hoping someone out there has some insight to what's going on.

Thank you in advance!
Tom Lianza

Jeff Pritchard wrote:

Tom Lianza wrote:
> Hi all,
>
> I have a page which displays search results, and each result has a
> common format. So I have a partial that describes an individual search
> result, and I iterate on that partial to show the results.
>
>
> Does anyone know why this is happening? It's really surprising to me,
> and I'm not even sure what workarounds are available. Interestingly,
> I've found if I cut the search results partial ('list_item') so all of
> the HTML is on one line, it cut the execution time down from about 3
> seconds to just under 2 seconds. There's definitely something at work
> here that I'm not understanding. Since the use of partials is so
> common, it seems like these kinds of operations would not be unusual,
> so I'm hoping someone out there has some insight to what's going on.
>
> Thank you in advance!
> Tom Lianza

Tom, I don't know the answer, but I think it will almost certainly have
something to do with what you are using for a server. Is this local
using Webrick? Or is it deployed and using a real webserver, and if so,
which one?

Sorry, I should have been more clear about where those numbers are
coming from. I've been benchmarking the system via the command-line
functional tests to get those numbers. I'm not using a client, a web
server, or doing anything over a network connection - I've
intentionally eliminated all of those variables. I'm just using the
standard functional test framework provided with Rails.

For what it's worth, my benchmarks are comparable on my mac (dual core
mini) and laptop (gentoo linux, 2ghz). The benchmarks look like this.
The first column represents the number of items in the search result.
You can see the execution time grows fairly linearly:

      user system total real
0 0.130000 0.000000 0.130000 ( 0.150675)
1 0.070000 0.000000 0.070000 ( 0.081635)
2 0.110000 0.000000 0.110000 ( 0.116907)
3 0.110000 0.000000 0.110000 ( 0.121843)
4 0.120000 0.000000 0.120000 ( 0.121839)
5 0.310000 0.000000 0.310000 ( 0.315779)
6 0.310000 0.000000 0.310000 ( 0.313566)
7 0.300000 0.000000 0.300000 ( 0.315578)
8 0.310000 0.000000 0.310000 ( 0.319840)
9 0.310000 0.000000 0.310000 ( 0.323880)
10 0.540000 0.010000 0.550000 ( 0.549162)
11 0.510000 0.000000 0.510000 ( 0.520871)
12 0.550000 0.000000 0.550000 ( 0.551898)
13 0.550000 0.000000 0.550000 ( 0.558383)
14 0.550000 0.010000 0.560000 ( 0.559715)
15 0.740000 0.010000 0.750000 ( 0.750723)
16 0.780000 0.000000 0.780000 ( 0.788720)
17 0.750000 0.010000 0.760000 ( 0.756788)
18 0.790000 0.000000 0.790000 ( 0.812792)
19 0.790000 0.000000 0.790000 ( 0.816859)
20 1.020000 0.000000 1.020000 ( 1.048609)
21 1.010000 0.000000 1.010000 ( 1.024415)
22 1.010000 0.000000 1.010000 ( 1.026359)
23 1.010000 0.000000 1.010000 ( 1.030071)
24 1.020000 0.010000 1.030000 ( 1.032542)
25 1.250000 0.010000 1.260000 ( 1.264821)
26 1.250000 0.010000 1.260000 ( 1.271283)
27 1.270000 0.010000 1.280000 ( 1.323564)
28 1.280000 0.000000 1.280000 ( 1.305153)
29 1.290000 0.000000 1.290000 ( 1.314197)
30 1.520000 0.000000 1.520000 ( 1.537685)
31 1.570000 0.010000 1.580000 ( 1.616285)
32 1.570000 0.010000 1.580000 ( 1.591001)
33 1.560000 0.010000 1.570000 ( 1.581793)
34 1.560000 0.010000 1.570000 ( 1.583032)
35 1.820000 0.000000 1.820000 ( 1.848094)
36 1.830000 0.010000 1.840000 ( 1.844669)
37 1.820000 0.010000 1.830000 ( 1.853609)
38 1.870000 0.010000 1.880000 ( 1.890035)
39 1.870000 0.010000 1.880000 ( 1.894273)
40 2.090000 0.010000 2.100000 ( 2.116339)
41 2.130000 0.010000 2.140000 ( 2.158593)
42 2.170000 0.020000 2.190000 ( 2.223613)
43 2.190000 0.010000 2.200000 ( 2.251828)
44 2.190000 0.010000 2.200000 ( 2.213679)
45 2.420000 0.020000 2.440000 ( 2.490541)
46 2.480000 0.020000 2.500000 ( 2.622734)
47 2.460000 0.010000 2.470000 ( 2.567351)
48 2.490000 0.010000 2.500000 ( 2.517507)
49 2.530000 0.010000 2.540000 ( 2.644702)
50 2.810000 0.020000 2.830000 ( 2.852417)

Don’t render_to_string use render_partial instead:

<% for item in @list %>
    <%= render_partial 'item', item %>
 <% end %>

Possibly Tom is running into a GC problem which relates to the expansion of Strings and lots of temporary objects as described by _why (Check out Mistake#1):
http://whytheluckystiff.net/articles/theFullyUpturnedBin.html

Steve Longdo wrote:

Don't render_to_string use render_partial instead:

<% for item in @list %>
    <%= render_partial 'item', item %>
<% end %>

It may not have been obvious from my code snippet, but the reason I was
trying render_to_string was because I was trying to avoid the exact
problem that _why describes in Mistake #1. I was doing
render_to_string so that I could use the (more efficient) concatenation
to an array (the thing named 'output' in my snippet), rather than
relying on <%=render_partial which, as I understand it, actually uses
the less efficient string<< under the hood.

Either way I do it, I don't see a substantial performance difference,
unfortunately. The time it takes to render the partial is the same in
both cases. Perhaps there's something I'm misunderstanding here.

Frederick Cheung wrote:

That's very odd, I've never seen anything like that. I've you tried
profiling to make sure where the slow down is ?
How much text does each partial generate ? I'm pretty sure I've done
similar type things with no where near such a rendering slowdown.

Fred

Thanks for the response, Fred. I also appreciate the validation that
it feels like something is wrong here :slight_smile:

So, looking though the code I think I see what makes my problem
different from most - I'm taking this partial and sending it back as
part of an RJS template. It looks like there is a ton of
string-scanning happening to convert the html down to JavaScript-able
code, which is really slow. By all means, take a look at the profiling
output and let me know if you agree. I also see a suspicious url_for
command in there, but I have trouble knowing if that's a serious
contributor to the problem, or if it's in my code or the rjs code. This
is what appear to be the relevant blocks (in order, with irrelevant
blocks omitted, if you see the word 'giftalicious' that's the name of
my controller):

Tom wrote:

Frederick Cheung wrote:
> That's very odd, I've never seen anything like that. I've you tried
> profiling to make sure where the slow down is ?
> How much text does each partial generate ? I'm pretty sure I've done
> similar type things with no where near such a rendering slowdown.
>
> Fred

Thanks for the response, Fred. I also appreciate the validation that
it feels like something is wrong here :slight_smile:

So, looking though the code I think I see what makes my problem
different from most - I'm taking this partial and sending it back as
part of an RJS template. It looks like there is a ton of
string-scanning happening to convert the html down to JavaScript-able
code, which is really slow.

FYI, I found this patch which will be part of rails 1.2 that supposedly
helps alleviate this problem:

"Performance problems with .to_json as used for .rjs templates"
http://dev.rubyonrails.org/ticket/3473

Tom