We have MySQL slow query logs from a suite of applications, mostly in Ruby, some using Rails ActiveRecord, others using Sequel.
We'd love to be able to easily track a particular (MySQL) slow query back to the code which generated it. Is there a feature that can be enabled in these tools, or a patch that can be applied to them, which adds instrumentation embedded into SQL comments, something like a __FILE__ and __FUNCTION__ identifier?
Interesting question, here is how I would handle it...
I would use config.active_record.auto_explain_threshold_in_seconds to automatically explain slow queries, as it sounds like you are doing.
Then, I would override the logging_query_plan method in ActiveRecord::Explain to add any relevant data to your log. Here is an example that adds the current stacktrace:
# /config/initializers/add_additional_instumentation_to_explain.rb
module ActiveRecord
module Explain
def logging_query_plan # :nodoc:
return yield unless logger
threshold = auto_explain_threshold_in_seconds
current = Thread.current
if threshold && current[:available_queries_for_explain].nil?
begin
queries = current[:available_queries_for_explain] = []
start = Time.now
result = yield
if Time.now - start > threshold
# START ADDING ADDITIONAL INFORMATION
begin
puts 'ADDING ADDITIONAL INFORMATION...'
raise 'foo'
rescue
puts 'DISPLAYING THE CURRENT STACKTRACE FOR THE FOLLOWING EXPLAIN'
puts $@
end
logger.warn(exec_explain(queries))
end
result
ensure
current[:available_queries_for_explain] = nil
end
else
yield
end
end
end
end
I would prefer a method that doesn't rely on an entire modified method from rails, but this is the only way that I could get it to work reliably.
For what it's worth, this would be pretty easy to spin off into a gem, with a new one for each rails version, and just include the relevant gem for your version, per app, as it sounds like you may possibly support multiple versions of rails. This would serve to minimize some of the brittleness of said approach. Anyway, hope this helps - good luck!