After noticing in the logs that 80% to 95% of my response time is due to rendering, I''m looking for ways to track down places where more time is spent than necessary. Profiling hasn''t been much help, so far. There''s no method using up more than 9% of the time by itself and the top time eaters are Hash#each and similar. Are there tools that help interpret profiler output? Without Windows/Excel, that is. KDE''s KSpread and OpenOffice Calc are unfortunately cumbersome when it comes to sorting by columns (no numeric sorting!?). Michael -- Michael Schuerig The more it stays the same, mailto:michael-q5aiKMLteq4b1SvskN2V4Q@public.gmane.org The less it changes! http://www.schuerig.de/michael/ --Spinal Tap, The Majesty of Rock
> After noticing in the logs that 80% to 95% of my response time is due to > rendering, I''m looking for ways to track down places where more time is > spent than necessary.Stefan Kaes is working on performance improvements in the performance-Branch of the Subversion-repository. I don''t know when the changes will be merged back to the trunk, but ticket#912 (http://dev.rubyonrails.com/ticket/912) seems promising.
Michael Schuerig wrote:>After noticing in the logs that 80% to 95% of my response time is due to >rendering, I''m looking for ways to track down places where more time is >spent than necessary. > >The logs are misleading.>Profiling hasn''t been much help, so far. There''s no method using up more >than 9% of the time by itself and the top time eaters are Hash#each and >similar. Are there tools that help interpret profiler output? Without >Windows/Excel, that is. KDE''s KSpread and OpenOffice Calc are >unfortunately cumbersome when it comes to sorting by columns (no >numeric sorting!?). > >I have been using Ruby Performance Validator under XP (currently in beta test, you can sign up for free). I am not aware of a similar tool for Linux. I have been working to improve performance of the Rails core. Most of the patches will probably be included in the next version. Rendering in itself will probably be up to 25% faster. The overall raw Rails processing speedup (excluding Apache/Rails communication overhead) can be up to a factor of 4.7. If you can, you should avoid the use of link_to with hash parameters. It is really slow. Regards, Stefan
On Thursday 23 June 2005 17:25, Stefan Kaes wrote:> Michael Schuerig wrote:> I have been working to improve performance of the Rails core. Most of > the patches will probably be included in the next version. Rendering > in itself will probably be up to 25% faster. The overall raw Rails > processing speedup (excluding Apache/Rails communication overhead) > can be up to a factor of 4.7.I don''t want to blame Rails, probably its more the way I''m using it that results in a slow response. My test cases are two list views displaying 1000 objects each. In the first case there''s only one model class involved. Attributes are displayed as they come from the object. Rendering takes about 3.3 s/req. The second case is more complicated. An attribute from an associated object (belongs_to) is shown and two attributes from the base object are displayed through partials. Rendering takes about 8.1 s/req. Displaying the attributes straight without the partials improves speed by 1.5 s/req for each. Same improvement when I don''t display the associated object''s attribute. In both cases, I''ve been linking each table cell (2000 and 3000 respectively) two an edit view for the relevant object. Removing this improves the speed by about 1.5 s/req. By comparison, displaying an edit or new view for an object takes between 0.04 and 0.02 s/req on my machine, depending on the complexity of the view and if associated objects are involved. Now, the thing is, regarding list views, I don''t know what performance to expect. I''ve just tried to display the same number of objects using a scaffolded list view with pagination increased to 2000 items per page. This takes about 5 s/req. Thus, it may be that with the number of objects involved there may be little room for improvement.> If you can, you should avoid the use of link_to with hash parameters. > It is really slow.Yes, I''ve already done this before the rough measurements above. Michael -- Michael Schuerig I am the sum total of the parts mailto:michael-q5aiKMLteq4b1SvskN2V4Q@public.gmane.org I control directly. http://www.schuerig.de/michael/ --Daniel C. Dennett, Elbow Room
* Michael Schuerig (michael-q5aiKMLteq4b1SvskN2V4Q@public.gmane.org) [050623 14:45]:> In both cases, I''ve been linking each table cell (2000 and 3000 > respectively) two an edit view for the relevant object. Removing this > improves the speed by about 1.5 s/req.This is an almost useless completely anecdotal bit of information, but (here goes...) back in mid-March I had implemented some big data table views (about 3000 table cells), and found the rendering to be incredibly slow (10 seconds to render a page). Since this wasn''t a personal site and I wasn''t worried about XSS attacks I took out my ubiquitous h() calls and the rendering time went down to ~.5 seconds per page. Rick -- http://www.rickbradley.com MUPRN: 610 | but I don''t think random email haiku | the whole thing is going to go | over very well.
h() does 4 gsub''s, each of which do regular expressions. For 3,000 table cells that is 12,000 regular expressions! This is a complete waste if you need performance, so I wrote a C extension to String that does h natively by replacing character by character the good HTML equivalents. I''ll blog the patch to Ruby soon. Lucas Carlson http://tech.rufy.com/ On Jun 23, 2005, at 12:53 PM, Rick Bradley wrote:> * Michael Schuerig (michael-q5aiKMLteq4b1SvskN2V4Q@public.gmane.org) [050623 14:45]: > > >> In both cases, I''ve been linking each table cell (2000 and 3000 >> respectively) two an edit view for the relevant object. Removing this >> improves the speed by about 1.5 s/req. >> >> > > This is an almost useless completely anecdotal bit of information, but > (here goes...) back in mid-March I had implemented some big data table > views (about 3000 table cells), and found the rendering to be > incredibly > slow (10 seconds to render a page). Since this wasn''t a personal site > and I wasn''t worried about XSS attacks I took out my ubiquitous h() > calls and the rendering time went down to ~.5 seconds per page. > > Rick > -- > http://www.rickbradley.com MUPRN: 610 > | but I don''t think > random email haiku | the whole thing is going to go > | over very well. > _______________________________________________ > Rails mailing list > Rails-1W37MKcQCpIf0INCOvqR/iCwEArCW2h5@public.gmane.org > http://lists.rubyonrails.org/mailman/listinfo/rails > >
I wonder why you want to display 2000 entries on one page. Anyway, I have set up a small test which retrieves all my records (681) from the database. For each record, the owners name (which is a belongs_to relation), the date of entry, and the title field of the record (linking to a show) are displayed on a single page. My machine is an Athlon 64 3000+. Here are the results: CONFIGURATION alphabetic, requests=1000, optionsloading environment 0.40474 page request total r/s ms/r /rezept/alphabetic 86.52030 11.6 86.52 By tuning the garabge collector (see http://dev.rubyonrails.org/svn/rails/branches/performance/railties/dispatches/dispatch.fcgi) I was able to improve this to CONFIGURATION alphabetic.gc10, requests=1000, options=-gc10 loading environment 0.39155 page request total r/s ms/r /rezept/alphabetic 40.75695 24.5 40.76 So for 2000 objects, we can extroplate about 7-8 requests per second, instead of 1/8 req/sec, which you reported (this of course assumes that the algorithms are all linear). So I would say: stay tuned for the next release. Cheers, Stefan
On Friday 24 June 2005 10:38, Stefan Kaes wrote:> I wonder why you want to display 2000 entries on one page.For one thing, to find bottlenecks. Also, I don''t like pagination.> Anyway, I have set up a small test which retrieves all my records > (681) from the database. For each record, the owners name (which is a > belongs_to relation), the date of entry, and the title field of the > record (linking to a show) are displayed on a single page. My machine > is an Athlon 64 3000+.Your machine is probably considerably faster than my P4 2.4GHz, but not that much faster to explain the difference by itself. Also, I notice that you''re using FastCGI; my tests have been with webrick.> So I would say: stay tuned for the next release.I''m not sure about this. As I said, I''m not convinced Rails is to blame for my response time. More likely it is cause by how I use Rails and that''s what I''d like to improve. To do that, though, I first need to find the places where cycles are needlessly burned. It would be a big help to have a hierarchical breakdown of where time is spent in the calltree resulting from a request. Michael -- Michael Schuerig The Fifth Rider of the Apocalypse mailto:michael-q5aiKMLteq4b1SvskN2V4Q@public.gmane.org is a programmer. http://www.schuerig.de/michael/
Michael Schuerig wrote:>On Friday 24 June 2005 10:38, Stefan Kaes wrote: > > >>Anyway, I have set up a small test which retrieves all my records >>(681) from the database. For each record, the owners name (which is a >>belongs_to relation), the date of entry, and the title field of the >>record (linking to a show) are displayed on a single page. My machine >>is an Athlon 64 3000+. >> >> > >Your machine is probably considerably faster than my P4 2.4GHz, but not >that much faster to explain the difference by itself. Also, I notice >that you''re using FastCGI; my tests have been with webrick. > >The tests were run from the command line, without any web server in between. They measure the raw performance of processing a request. As I understand, your measurements were taken from the benchmarking data included on the log files. So your data does not even include the overhead of processing the request, it only measures the rendering speed, and thus does not depend on webrick very much.> > >>So I would say: stay tuned for the next release. >> >> > >I''m not sure about this. >I am.>As I said, I''m not convinced Rails is to blame for my response time. >I am not trying to defend Rails, just showing what kind of speed can possibly be achieved with it.>More likely it is cause by how I use Rails and >that''s what I''d like to improve. To do that, though, I first need to >find the places where cycles are needlessly burned. It would be a big >help to have a hierarchical breakdown of where time is spent in the >calltree resulting from a request. > >I agree, but there is no such tool for Linux, as far as I know. Sometimes the best development tools are only available on Windows ;-) My measurements were taken on Linux, though. (I have a dual boot configuration). -- stefan _______________________________________________ Rails mailing list Rails-1W37MKcQCpIf0INCOvqR/iCwEArCW2h5@public.gmane.org http://lists.rubyonrails.org/mailman/listinfo/rails
On Friday 24 June 2005 11:35, Stefan Kaes wrote:> As I understand, your measurements were taken from the benchmarking > data included on the log files.No! I''m using a script similar to the benchmark.rb example included with actionpack. req = ActionController::TestRequest.new({ "action" => "list" }) req.path_parameters = { :controller => TasksController.controller_path } runtime = Benchmark.measure { RUNS.times { TasksController.process_test(req) } } puts "List: #{runtime.real / RUNS} s/req" Michael -- Michael Schuerig Most people would rather die than think. mailto:michael-q5aiKMLteq4b1SvskN2V4Q@public.gmane.org In fact, they do. http://www.schuerig.de/michael/ --Bertrand Russell
Michael Schuerig wrote:>On Friday 24 June 2005 11:35, Stefan Kaes wrote: > > >>As I understand, your measurements were taken from the benchmarking >>data included on the log files. >> >> > >No! I''m using a script similar to the benchmark.rb example included with >actionpack. > >req = ActionController::TestRequest.new({ "action" => "list" }) >req.path_parameters = { :controller => TasksController.controller_path } >runtime = Benchmark.measure { > RUNS.times { TasksController.process_test(req) } >} >puts "List: #{runtime.real / RUNS} s/req" > >It''s hard to tell why your test performs so badly, without looking at the code. If you post the relevant parts or send it me by e-mail, I will have a look at it. -- stefan _______________________________________________ Rails mailing list Rails-1W37MKcQCpIf0INCOvqR/iCwEArCW2h5@public.gmane.org http://lists.rubyonrails.org/mailman/listinfo/rails
On Friday 24 June 2005 13:46, Stefan Kaes wrote:> Michael Schuerig wrote: > >On Friday 24 June 2005 11:35, Stefan Kaes wrote: > >>As I understand, your measurements were taken from the benchmarking > >>data included on the log files. > > > >No! I''m using a script similar to the benchmark.rb example included > > with actionpack. > > > >req = ActionController::TestRequest.new({ "action" => "list" }) > >req.path_parameters = { :controller => > > TasksController.controller_path } runtime = Benchmark.measure { > > RUNS.times { TasksController.process_test(req) } > >} > >puts "List: #{runtime.real / RUNS} s/req" > > It''s hard to tell why your test performs so badly, without looking at > the code. If you post the relevant parts or send it me by e-mail, I > will have a look at it.The helpers for creating the table are below. It''s not understandable by itself, though. The actual contents of the list are determined by metadata defined in the controller like this class TasksController define_list_action :list, Task, { :column => ''description'', :partial => ''shared/truncate'' }, { :column => ''due_date'', :partial => ''shared/short_date'' }, { :path => ''status.name'', :title => ''Status'', :type => :enum, :include => :status } This works by itself, but can be amended by the user with filter conditions, result ordering and column order. Hashes like the three above, are what the list_view.each/collect/... methods below iterate over. As the code currently is, everything is more dynamic than it need be. Although each row in the list has the same structure, it is recomputed each time through the loop. This is one of my main suspects, but without any profiling data, I''m not sure. Maybe it''s something entirely different, such as dumb use of string operations. Michael require_dependency ''boilerplate/controller_support'' require_dependency ''boilerplate/template_utils'' module BoilerPlate # :nodoc: module Helpers # :nodoc: module EntityListHelper include ActionView::Helpers::AssetTagHelper include ActionView::Helpers::UrlHelper include ActionView::Helpers::TagHelper include ::BoilerPlate::ControllerSupport include ::BoilerPlate::TemplateUtils def entity_list(list_view, entities, caption = '''') head_row = content_tag(''tr'', list_view.collect do |h| content_tag(''th'', column_heading( h[:title] || Inflector.humanize(h[:column]), h[:accesskey])) end ) <<-END <table id="entitylist_table"> <caption>#{caption}</caption> <thead id="entitylist_head"> #{head_row} </thead> <tbody id="entitylist_body"> #{entity_list_body(list_view, entities)} </tbody> </table> END end def entity_list_body(list_view, entities) body_rows = [] entities.each_with_index do |entity, i| body_rows << content_tag(''tr'', columns_for_attributes(entity, list_view), :class => (i.even? ? ''even'' : ''odd'')) end body_rows.join("\n") end def column_heading(text, accesskey = nil) title = _(''Click to change filter settings'') "<span title=\"#{title}\">#{text}</span>" end ### TODO cleanup def columns_for_attributes(object, list_view) link_url = last_action = last_id = nil list_view.collect do |column_meta| action = column_meta[:action_title] || ''edit'' object_id = object.id if action != last_action || object_id != last_id link_url = url_for({ :action => action, :id => object_id }) last_action, last_id = action, object_id end title = column_meta[:action_title] || _(action) if path = column_meta[:path] value = object.get_at_path(path, :default => nil) else value = object.send(column_meta[:column]) end if renderer = column_meta[:partial] locals = { renderer.split(''/'').last => value } if partial_locals = column_meta[:partial_locals] locals.merge!(partial_locals) end value = render_partial(renderer, locals) end if value content_tag(''td'', link_to(value, link_url), :class => column_meta[:class], :title => title) else tag(''td'', :class => column_meta[:class]) end end.join end end end end -- Michael Schuerig I am the sum total of the parts mailto:michael-q5aiKMLteq4b1SvskN2V4Q@public.gmane.org I control directly. http://www.schuerig.de/michael/ --Daniel C. Dennett, Elbow Room
Michael Schuerig wrote:>The helpers for creating the table are below. It''s not understandable by >itself, though. The actual contents of the list are determined by >metadata defined in the controller like this > >class TasksController > define_list_action :list, Task, > { :column => ''description'', :partial => ''shared/truncate'' }, > { :column => ''due_date'', :partial => ''shared/short_date'' }, > { :path => ''status.name'', :title => ''Status'', > :type => :enum, :include => :status } > >This works by itself, but can be amended by the user with filter >conditions, result ordering and column order. Hashes like the three >above, are what the list_view.each/collect/... methods below iterate >over. > >As the code currently is, everything is more dynamic than it need be. >Although each row in the list has the same structure, it is recomputed >each time through the loop. This is one of my main suspects, but >without any profiling data, I''m not sure. Maybe it''s something entirely >different, such as dumb use of string operations. > >Michael > > >require_dependency ''boilerplate/controller_support'' >require_dependency ''boilerplate/template_utils'' > >module BoilerPlate # :nodoc: > module Helpers # :nodoc: > > module EntityListHelper > include ActionView::Helpers::AssetTagHelper > include ActionView::Helpers::UrlHelper > include ActionView::Helpers::TagHelper > include ::BoilerPlate::ControllerSupport > include ::BoilerPlate::TemplateUtils > > def entity_list(list_view, entities, caption = '''') > head_row = content_tag(''tr'', > list_view.collect do |h| > content_tag(''th'', > column_heading( > h[:title] || Inflector.humanize(h[:column]), > h[:accesskey])) > end > ) > > <<-END > <table id="entitylist_table"> > <caption>#{caption}</caption> > <thead id="entitylist_head"> > #{head_row} > </thead> > <tbody id="entitylist_body"> > #{entity_list_body(list_view, entities)} > </tbody> > </table> > END > end > > > def entity_list_body(list_view, entities) > body_rows = [] > entities.each_with_index do |entity, i| > body_rows << content_tag(''tr'', > columns_for_attributes(entity, list_view), > :class => (i.even? ? ''even'' : ''odd'')) > end > body_rows.join("\n") > end > > > def column_heading(text, accesskey = nil) > title = _(''Click to change filter settings'') > "<span title=\"#{title}\">#{text}</span>" > end > > > ### TODO cleanup > def columns_for_attributes(object, list_view) > link_url = last_action = last_id = nil > list_view.collect do |column_meta| > action = column_meta[:action_title] || ''edit'' > object_id = object.id > if action != last_action || object_id != last_id > link_url = url_for({ :action => action, :id => object_id }) > last_action, last_id = action, object_id > end > > title = column_meta[:action_title] || _(action) > > if path = column_meta[:path] > value = object.get_at_path(path, :default => nil) > else > value = object.send(column_meta[:column]) > end > if renderer = column_meta[:partial] > locals = { renderer.split(''/'').last => value } > if partial_locals = column_meta[:partial_locals] > locals.merge!(partial_locals) > end > value = render_partial(renderer, locals) > end > if value > content_tag(''td'', link_to(value, link_url), > :class => column_meta[:class], :title => title) > else > tag(''td'', :class => column_meta[:class]) > end > end.join > end > > end > end >end > > >I don''t have time for a deeper analysis right now, but try replacing url_for({ :action => action, :id => object_id }) with "#{action}/#{object_id}". This should give a BIG speedup (link_to is mainly slow because url_for is slow). Regards, Stefan
On Saturday 25 June 2005 00:13, Stefan Kaes wrote:> I don''t have time for a deeper analysis right now, but try replacing > url_for({ :action => action, :id => object_id }) with > "#{action}/#{object_id}". > > This should give a BIG speedup (link_to is mainly slow because > url_for is slow).Well, there is a speedup, but nothing dramatic. Response time goes down from 8.9 s/req to 7.5 s/req. Michael -- Michael Schuerig All good people read good books mailto:michael-q5aiKMLteq4b1SvskN2V4Q@public.gmane.org Now your conscience is clear http://www.schuerig.de/michael/ --Tanita Tikaram, Twist In My Sobriety
Michael Schuerig wrote:>On Saturday 25 June 2005 00:13, Stefan Kaes wrote: > > >>I don''t have time for a deeper analysis right now, but try replacing >>url_for({ :action => action, :id => object_id }) with >>"#{action}/#{object_id}". >> >>This should give a BIG speedup (link_to is mainly slow because >>url_for is slow). >> >> > >Well, there is a speedup, but nothing dramatic. Response time goes down >from 8.9 s/req to 7.5 s/req. > >1. Refactor your code to compute values that do not depend on row entities before looping through the rows 2. Avoid content_tag and tag calls 3. Remeasure -- stefan _______________________________________________ Rails mailing list Rails-1W37MKcQCpIf0INCOvqR/iCwEArCW2h5@public.gmane.org http://lists.rubyonrails.org/mailman/listinfo/rails