[RAILS] optimizing a slow request

We identified a single slow request in our moderation module: retrieving the json containing the entries to be moderated, feeding our react app.

So in short our datamodel looks as follows:

Class Topic 
  have_many :entries
  have_many :dynamic_attributes

Class Entry
  belongs_to :topic
  has_many :entry_values

Class EntryValue
  belongs_to :entry
  belongs_to :dynamic_attribute 

So in short: topics have a set of (dynamic) attributes that can be entered. An entry_value is the value entered for a dynamic_attribute and those are grouped in a complete entry.

In the moderation, our moderators verify that an entry (collection of entry-values) is appropriate, and have to option to edit or add missing information.

So in our controller we do something like

@entries = @q.result(distinct: true).page params[:page]

We are using ransack to filter/search on our entries. So we know we need entry-values, and possibly their dynamic attributes when building the json, so what is the best approach here? Use eager_load or includes? So what better way to decide than actually test this? So I temporarily changed the controller code as follows:

        preload_option = params[:pre].try(:to_i)
        if preload_option == 0
          @entries = @q.result(distinct: true).page params[:page]
        elsif preload_option == 1
          @entries = @q.result(distinct: true).eager_load(:entry_values).page params[:page]
        else
          @entries = @q.result(distinct: true).includes(:entry_values => :dynamic_attribute).page params[:page]
        end

Note:

  • I can only eager_load one level deep
  • with includes I can immediately fetch all dynamic attributes for the entry-values.

But which will prove to be more beneficial?

So then I ran a small benchmark script:

require 'benchmark'
require 'rest-client'

n = 10
Benchmark.bm do |x|
  x.report("normal ") do
    n.times { RestClient.get("http://admin.lvh.me:3013/moderation/projects/11/entries.json", {}) }
  end
  x.report("eager  ") do
    n.times { RestClient.get("http://admin.lvh.me:3013/moderation/projects/11/entries.json?pre=1", {}) }
  end
  x.report("include") do
    n.times { RestClient.get("http://admin.lvh.me:3013/moderation/projects/11/entries.json?pre=2", {}) }
  end
end

(note: for testing purposes I also disabled the need to authenticate, so I could easily fetch the jsons and time and compare)

This first run gave me the following results:

    normal   0.016362   0.005723   0.022085 ( 35.440171)
    eager    0.010036   0.004336   0.014372 ( 28.632490)
    include  0.012550   0.004061   0.016611 ( 29.173778) 

Ok. Not the kind of improvement I had hoped. Also nice to notice that eager_load in this case is more efficient than using the includes (which seemed a little counter-intuitive maybe).

I had recently changed a small part of the code, because in the moderation we also wanted to be able to edit fields that were not entered, and before we only had to retrieve entered values (:entry_values) so I presume that maybe there I fucked up the performance. Before we called entry.valid_entry_values which looked like

  def valid_entry_values
    entry_values.sorted.select do |ev|
      da = ev.dynamic_attribute
      da.attribute_type != 'item' || (da.attribute_type == 'item' && !ev.item_content_type.nil?)
    end
  end

and I replaced it with the following, adding empty entry-values to be filled in:


  def entry_values_with_empty
    result = []
    self.topic.dynamic_attributes.each do |da|
      ee = entry_values.find_by(dynamic_attribute_id: da.id)
      if ee.nil? || (da.attribute_type == 'item' && ee.item_content_type.nil?)
        ee = entry_values.build(dynamic_attribute: da)
      end
      result << ee
    end
    # check if we have entry-values not yet in the list
    # (e.g. from another topic when the entry was moved, and add those too)
    self.entry_values.each do |entry_value|
      if result.select{|ee| ee.id == entry_value.id}.count == 0
        result << entry_value
      end
    end
   
    result
  end

So what happens if we switch back to the old valid_entry_values : how does that change performance?

I ran my small benchmark script again, and got the following results:

    normal   0.015264   0.005280   0.020544 ( 33.283069)
    eager    0.009901   0.004359   0.014260 ( 17.145350)
    include  0.013153   0.004032   0.017185 ( 17.621856)

Wow! Now the eager_load or includes really seem to pay off. Also: almost the same speed improvement. Ok.

So if we check the entry_values_with_empty more closely, the implementation is somewhat naive: for each dynamic-attribute it will attempt to find the corresponding entry-value, except ... we use a query each time for each dynamic attribute, for each entry ... Mmmmmm. Let's see if we can improve this:

  def entry_values_with_empty
    result = []
    self.topic.dynamic_attributes.each do |da|
      ee = entry_values.detect{|ev| ev.dynamic_attribute_id == da.id}
      if ee.nil? || (da.attribute_type == 'item' && ee.item_content_type.nil?)
        ee = entry_values.build(dynamic_attribute: da)
      end
      result << ee
    end
    # check if we have entry-values not yet in the list
    # (e.g. from another topic when the entry was moved, and add those too)
    self.entry_values.each do |entry_value|
      if result.select{|ee| ee.id == entry_value.id}.count == 0
        result << entry_value
      end
    end

    result
  end

Notice: we only changed one line, replacing the find_by with a detect. This will, instead of launching a new query, iterate over the already retrieved array of entry_values. But does this make any difference?

Launching my small test script now returns the following:

    normal   0.016051   0.005418   0.021469 ( 16.448649)
    eager    0.009454   0.003858   0.013312 ( 22.479142)
    include  0.012419   0.003872   0.016291 ( 14.236868)

NICE! **fireworks** Not what I expected to see at all. A little baffled that the normal case is improved that much, and that the eager_load does not improve it (on the contrary). We have now found our optimal combination: improving the entry_values_with_empty and adding the includes will give the best performance.

Is this what you would have expected? Bottomline remains: it helps to measure (in Dutch we say: meten is weten which rhymes)


Comments
Add comment

Recent comments

Tags

ruby on rails 34 ruby 26 rails3 17 rails 15 oracle 11 rspec 9 rspec2 7 jquery 7 ubuntu 5 javascript 5 windows 5 activerecord 3 refactoring 3 geoserver 3 gis 3 arrrrcamp 3 actionmailer 2 oracle spatial 2 tdd 2 postgis 2 routing 2 rvm 2 mongoid 2 csharp 2 thin 2 win32 2 gem 2 rails4 2 git 2 service 2 haml 2 cucumber 2 view testing 2 i18n 1 displaysleep 1 spatial 1 gemsets 1 wubi 1 oracle_enhanced_adapter 1 migrations 1 watchr 1 ci 1 plugins 1 coderetreat 1 ie8 1 ssl 1 oci 1 nested model form 1 wcf 1 11.04 1 jsonp 1 ruby-oci8 1 teamcity 1 engines 1 pgadmin 1 soap 1 content_for 1 word automation 1 plugin 1 capybara 1 xml 1 bootstrap 1 migrate to rails3 1 mvc 1 unity 1 rendering 1 word2007 1 x64 1 limited stock 1 fast tests 1 pl/sql 1 delayed_job 1 pdf 1 test coverage 1 optimization 1 processing 1 borland 1 method_missing 1 cross-browser 1 devise 1 schema_plus 1 mongo 1 mongrel 1 dual boot 1 usability 1 mongrel_service 1 dba 1 mission statement 1 model 1 metadata 1 rcov 1 exceptions 1 image_tag 1 attachments 1 bde 1 css 1 yield 1 ajax 1 generative art 1 rails-assets 1 coordinate systems 1 submodules 1 netzke 1 ora-01031 1 authlogic 1 postgresql 1 shopping cart 1 agile 1 fast_tagger 1 subjective 1 wice_grid 1 generators 1 nvidia 1 mongodb 1 etsyhacks 1 staleobjecterror 1 session 1 jeweler 1 wordpress hacked 1 jasmine 1 heroku 1 rjs 1 life 1 unobtrusive-javascript 1 render_anywhere 1 html5 1 rails31 1 json 1 cocoon 1 mingw32 1 observe_field 1 osx 1 actionwebservice 1 testing 1 debugging 1 strings 1