Performance Benchmarking in Rails

June 10, 2007 by alex

Na? Ist die Userprofil-Seite mal wieder zu langsam, nachdem beim letzten Release durch geschicktes anordnen und ausblenden noch einmal 3 Bilder und Informationshäppchen mehr draufgepackt werden konnten? Und jetzt will’s wieder keiner gewesen sein und niemand hat eine Ahnung, wo die 500ms denn nun genau hingehen? Für das profilen z.B. einer Rails-Seite stehen dem geneigten Entwickler mehrere Tools zur Verfügung.

logfiles

Erster Anlaufpunkt sind die logfiles in RAILS_ROOT/log - je nach logging-level stehen dort die Gesamtzeit für’s prozessieren der Seite, noch einmal unterschieden in Datenbank- und Render-Zeit (production environment) sowie zusätzlich die Zeiten, die für jeden Datenbank-Query und das rendern von Partials draufgehen.

benchmark do .. end

Wer keine Lust hat, sich im Logfile die entscheidenen Zeiten herauszusuchen, kann auf die von Rails angebotene benachmark-Methode zurückgreifen. Dieser wird einfach ein Block mit dem zu profilenden Code übergeben und schon steht die laufzeit im Logfile. Funktioniert auch im Model.

<%- benachmark 'user details' do -%>
  <%= render_lots_o_stuff %>
<%- end -%>

RubyProf

Wer es ganz genau wissen will, kann RubyProf verwenden. Wie es der Name vermuten lässt, handelt es sich dabei um einen “richtigen” Profiler - man bekommt also nicht nur die Gesamtlaufzeit der durchgemessenen Codes sondern das ganze aufgeschlüsselt nach Methoden, den ganzen Ruby-Stack herunter. Um RubyProf zu installieren, reicht erwartunsggemäß ein einfaches gem install ruby-prof. Der eigentliche Profile-Aufruf erfolgt wieder inline und könnte so aussehen:

<% result = RubyProf.profile do %>
  		  <%= render :partial => 'shared/pinboard', :object => @user, :locals => {:posts_comments => @posts_comments}%>
  		<% end %>
  		<%- printer = RubyProf::GraphHtmlPrinter.new(result)
  		file = File.new('/Users/alex/Desktop/profile.html', 'w')
      printer.print(file, 0)
      file.close -%>

Als Belohnung liegt dann nach kurzer Zeit eine riesige HTML-Tabelle auf dem Desktop, mit den Laufzeiten aller Methodenaufrufe innerhalb des gewählten Blocks, und es stellt sich heraus, dass irgendjemand (wer war das nur wieder?^^) einen fiesen after_initialize-Callback an den User gebaut hat, der für jeden geladenen User ein paar Milisekunden Zeit verbrät…. after_initialize ist gefährlich, don’t do this at home ;)

This entry was posted on June 10, 2007 by alex.