Friday findings: find and find_by_attribute in Rails 3.1.12

Today I spent several hours debugging the cause for some http call to the Rails based service I work in, and what could be the reason for a simple call being 4x slower than our average.

The call was simple: ruby code interacting with a couple of SQL queries and redis.

Current time: Friday 23.45

Result: Found the cause. User.find_by_attribute(value)

The suspects

  • Redis: the average time spent on Redis(local instance): 1.21ms
  • Mysql: 0.5-0.9ms per call UPDATE, SELECT, INSERT
  • Ruby?

Yes, ruby. Well.. rails

From searching for a field on a table using an indexed attribute ( which I usually do usingUser.find_by_indexed_attribute("value") ), at some point during development, I decided to use the PRIMARY_KEY of the model.

For what it takes, I just changed it to User.find_by_id(id). This should work, but it doesn’t.

Debugging this threw: Wall time: ~200ms of which ~180ms are spent in ruby code doing something on User.find_by_id(id).

What is that something?

This is what happens when you do Model.find_by_attribute('value') in rails 3.1:

  # Enables dynamic finders like <tt>User.find_by_user_name(user_name)</tt> and
  # <tt>User.scoped_by_user_name(user_name). Refer to Dynamic attribute-based finders
  # section at the top of this file for more detailed information.
  #
  # It's even possible to use all the additional parameters to +find+. For example, the
  # full interface for +find_all_by_amount+ is actually <tt>find_all_by_amount(amount, options)</tt>.
  #
  # Each dynamic finder using <tt>scoped_by_*</tt> is also defined in the class after it
  # is first invoked, so that future attempts to use it do not run through method_missing.
  def method_missing(method_id, *arguments, &block)

Trust me. See the rails 3.1-stable code

This last line Each dynamic finder using scoped_by_ is also defined in the class after it* also adds another layer of fun to your every day debugging. It makes the response times vary a lot in between two apparently similar calls to the model using in this case a PRIMARY KEY.

The solution

  • User.find(id) whenever the id is a primary key identifier. – Avoid dynamic finders when possible.

Http call wall time: 7-9ms of which ~1.5ms correspond to User.find(id)

For me it’s the start of the weekend. Let’s see what happens on Monday, hopefully fix and release!

Note: This happened to me while running rails 3.1.12 and ruby 1.9.2

Advertisements

About marianovalles

My name is Mariano Vallés. I'm originally from Mendoza, Argentina. I'm a software engineer and an EMDC (European Master in Distributed Computing) graduate. In 2010 I moved to Barcelona, then I moved to Stockholm and now I live in Berlin and work for Wooga as a Backend Engineer.

Leave a Reply

Fill in your details below or click an icon to log in:

WordPress.com Logo

You are commenting using your WordPress.com account. Log Out / Change )

Twitter picture

You are commenting using your Twitter account. Log Out / Change )

Facebook photo

You are commenting using your Facebook account. Log Out / Change )

Google+ photo

You are commenting using your Google+ account. Log Out / Change )

Connecting to %s

%d bloggers like this: