One of the things we’ve added to our applications in the last few months is a little gem that (among other things) adds a comment to each MySQL query that is generated by one of our applications.
Now, when we look at our Rails or slow query logs, our MySQL queries include the application, controller, and action that generated them:
Account Load (0.3ms) SELECT `accounts`.* FROM `accounts` WHERE `accounts`.`queenbee_id` = 1234567890 LIMIT 1 /*application:BCX,controller:project_imports,action:show*/
When we’re trying to improve a slow query, or identify a customer problem, we never have to go digging to understand where the query came from—it’s just right there. This comes in handy in development, support, and operations – we used it during a pre-launch review of unindexed queries in the brand new Basecamp which launched a couple months ago. If you combine this with something like pt-query-digest, you end up with a powerful understanding of how each Rails action interacts with MySQL.
It’s easy to add these comments to your Rails application in a relatively unintrusive way. We’ve released our approach that works in both Rails 2.3.x and Rails 3.x.x apps as a gem, marginalia.
marginalia (mar-gi-na-lia, pl. noun) — marginal notes or embellishments
Merriam-Webster
We’ve been using this in production on all of our apps now since December, ranging from Rails 2.3.5 to Rails master and Ruby 1.8.7 to 1.9.3. You should be able to have it running in your application in a matter of minutes.
It’s worth acknowledging that anytime you modify the internals of something outside your direct control there are risks, and that every function call adds some overhead. In our testing, these have both been well worth the tradeoff, but I absolutely encourage you to consider the tradeoff you’re making for yourself every time you instrument or log something. You may certainly have a different set of tradeoffs, and you should absolutely test on your own application.
Have a suggested improvement to our sample code or another way to do this? We’d love to hear it.
Thanks to Taylor for the original idea, and to Nick for helping to extract it into its own gem.
Oleh
on 24 Apr 12This deserves to live in rails core
TK
on 24 Apr 12@37signals
Why are you implicitly stating “LIMIT 1” to your query?
That implies that your unique identifier (queenbee_id) is not in fact unique.
Dan
on 24 Apr 12@TK There is no reason to assume queenbee_id has a unique constraint. It looks like a foreign key to me.
Josh Butts
on 24 Apr 12This seems like it would play havoc with the MySQL query cache if you run the same queries in lots of places, since the comments are used in the hash that the server calculates.
Jarin Udom
on 24 Apr 12@TK
I am not a database guru, but I believe it probably makes the query slightly faster (even if there is an index on queenbee_id) because MySQL knows to stop looking after it finds the first match.
Dobry Den
on 24 Apr 12@Jarin
Yep! http://dev.mysql.com/doc/refman/5.0/en/limit-optimization.html
Casey Durfee
on 24 Apr 12“This seems like it would play havoc with the MySQL query cache if you run the same queries in lots of places, since the comments are used in the hash that the server calculates.”
Good point. MySQL used to ignore using the query cache for anything where the first 6 characters weren’t “SELECT”—which is probably why they are putting the comment at the end of the SQL.
Now it’s a little smarter and it won’t ignore the cache if there are comments at the beginning, but it doesn’t strip the comments out when calculating the hash, so you’re correct.
Percona Server (which 37signals uses) and MariaDB have a setting to strip comments out for the query cache.
Ralph Bodenner
on 24 Apr 12Neat little hack. New Relic links SQL queries to traces of individual requests, too, and displays them all together.
JK
on 25 Apr 12Query cache considered harmful under high write loads. You end up bottlenecking on the cache mutex!
See http://www.percona.com/doc/percona-server/5.5/performance/query_cache_enhance.html for disabling the query cache (setting cache size 0 isn’t enough) and ignoring query comments. Disabling the query cache is available in MySQL 5.5 release, too.
George
on 25 Apr 12Using that link does not say it will perform a faster query.
What it does say is that if you are expect multiple rows to be returned and LIMIT the result set to X, then yes – it will be faster.
However, if only one resultset is expected to begin with (as is in this blog post example above) – no performance gain will be achieved.
Doug B.
on 25 Apr 12Sign
Yet another post indicative of 37signals clueless nature.
Eamon
on 26 Apr 12There’s a Percona patch for stripping comments from queries to allow them to cache properly: query_cache_with_comments.
Like most optimizations, there’s a time and a place for the query cache. If you’re concerned about the cache mutex, the Percona builds offer a new thread state that you can monitor to see if you’re really running into it: see Query Cache Enhancements.
Eamon
on 26 Apr 12(By the way, Perl CDBI folks can do something very similar by overriding “transform_sql” and adding a comment with the output from “caller”. We’ve been doing that for several years now.)
This discussion is closed.