out of time
-
Why you see hundreds of “SHOW TABLES” queries when running ruby-prof in Rails
As part of my continuning quest to make ruby-prof a useful part of my optimization toolkit, I decided to finally investigate why, when running the profiler, I was seeing the SQL query “SHOW TABLES” output over and over, hundreds of times, in the log. And it was super-slow - over a minute to finish a request that otherwise clocked in around a second.
After digging around in ruby-prof and ActiveRecord, I discovered the following interesting facts:
- For each method call that it logs, ruby-prof calls #inspect() on the receiving class. It does this from within its C layer, so it’s not immediately obvious, but the call is received in the Ruby layer.
- When you call #inspect() on a class that extends ActiveRecord::Base, it queries the database with “SHOW TABLES”
- Every time.
- Seriously.
This happens when you instantiate one of RubyProf’s Printer instances, so it doesn’t actually affect profiling data, but it still slows things down quite considerably. So, I threw in this monkey patch:
(class <<ActiveRecord::Base; self; end).module_eval do alias_method :_ar_inspect, :inspect def inspect self.name end end html_printer = RubyProf::GraphHtmlPrinter.new(result) (class <<ActiveRecord::Base; self; end).module_eval do alias_method :inspect, :_ar_inspect endAs it turns out, the process of building the printer object is still quite slow, but it is, as you’d expect, a lot faster without all of those SQL queries.
