Time.to_s and the 19 million row scan 3
Lately we've been noticing slowness on Lingr's database. Some queries were taking a ridiculously long time to complete, even some COMMITs were taking half a minute or more. The slowdown seemed to be across the board, rather than isolated into a particular table or a particular query.
After much investigation, MySQL upgrades, etc, Kenn finally noticed something weird in the slow query logs.
We had many queries in there that referenced time ranges, like this:
SELECT * from events WHERE created_at >= '2008-01-21 00:00:00' ...
but occasionally, one would show up that looked just a little bit different, like this:
SELECT * from events WHERE created_at >= '2008-01-21 00:00:00 PST' ...With the help of MySQL's EXPLAIN statement, Kenn quickly discovered that while the first type of query would use indexes, and scan only, say, 100,000 rows, the second type would scan all 20,000,000+ rows. Further examination of the output of EXPLAIN revealed that the second query issued 4 warnings. SHOW WARNINGS revealed the following:
Incorrect datetime value: '2008-01-21 00:00:00 PST' for column 'created_at' at row 1
YIKES! We misformatted a timestamp in a query, and as a result, MySQL was scanning the entire 20M+ row table every time.
I tracked this query down in our code to something like this:
UserMessage.find_all_by_room_id @room.id, :conditions => "created_at >= '#{@time.to_s}'..."
As it turns out, time.to_s renders the timezone by default. Rails has added a nice format specifier, so you can say time.to_s(:db), and we were doing this everywhere else, but had forgotten the (:db) in this one place.
MySQL was barfing on the timezone specifier, and silently falling back to scanning the entire table. To add insult to injury, this query occurred in the rendering of an RSS feed, so it was used not infrequently.
Lesson learned- be very careful in how you format queries involving datetime fields. Forget to use the :db format specifier, and you could suffer terrible consequences.
For the extra curious, I did manage to find a MySQL ticket that seemed somewhat related.
Comments
-
D'oh! FWIW, it looks like Rails will do this conversion for you if you use ? placeholders in your query. Model.find(:all, :conditions => ["created_at >= ?", time]) Then you don't have to remember the pesky to_s(:db). (The place where to_s(:db) always gets me is in fixtures...)
-
Does anyone know if there's a way to make MySQL raise an error instead of silently logging the warning? I would prefer to see an exception than have to check SHOW WARNINGS after each query.
-
i canot open and chat only i see no put the name for chat plz help
