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.
- Redis: the average time spent on Redis(local instance): 1.21ms
- Mysql: 0.5-0.9ms per call
UPDATE, SELECT, INSERT
Yes, ruby. Well.. rails
From searching for a field on a table using an indexed attribute ( which I usually do using
User.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
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)
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.
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
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