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