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.
Noah wrote this on Apr 24 2012 There are 13 comments.
Oleh 24 Apr 12
This deserves to live in rails core
TK 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 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 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.
Jarin Udom 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 24 Apr 12
@Jarin
Yep! http://dev.mysql.com/doc/refman/5.0/en/limit-optimization.html
Casey Durfee 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 24 Apr 12
Neat little hack. New Relic links SQL queries to traces of individual requests, too, and displays them all together.
JK 25 Apr 12
Query 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 25 Apr 12
Using 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. 25 Apr 12
Sign
Yet another post indicative of 37signals clueless nature.
Eamon 26 Apr 12
There’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 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.