implements automatic EXPLAIN logging for slow queries

1 files changed, 91 insertions, 0 deletions

diff --git a/activerecord/test/cases/explain_test.rb b/activerecord/test/cases/explain_test.rb
new file mode 100644
index 0000000000..d3eb9c2cb2
--- /dev/null
+++ b/activerecord/test/cases/explain_test.rb
@@ -0,0 +1,91 @@
+require 'cases/helper'
+require 'models/car'
+require 'active_support/core_ext/string/strip'
+
+if ActiveRecord::Base.connection.supports_explain?
+  class ExplainTest < ActiveRecord::TestCase
+    fixtures :cars
+
+    def base
+      ActiveRecord::Base
+    end
+
+    def connection
+      base.connection
+    end
+
+    def test_logging_query_plan
+      base.logger.expects(:warn).with do |value|
+        value.starts_with?('EXPLAIN for:')
+      end
+
+      with_threshold(0) do
+        Car.where(:name => 'honda').all
+      end
+    end
+
+    def test_collecting_sqls_for_explain
+      base.auto_explain_threshold_in_seconds = nil
+      honda = cars(:honda)
+
+      expected_sqls  = []
+      expected_binds = []
+      callback = lambda do |*args|
+        payload = args.last
+        unless base.ignore_explain_notification?(payload)
+          expected_sqls  << payload[:sql]
+          expected_binds << payload[:binds]
+        end
+      end
+
+      result = sqls = binds = nil
+      ActiveSupport::Notifications.subscribed(callback, "sql.active_record") do
+        with_threshold(0) do
+          result, sqls, binds = base.collecting_sqls_for_explain {
+            Car.where(:name => 'honda').all
+          }
+        end
+      end
+
+      assert_equal result, [honda]
+      assert_equal expected_sqls, sqls
+      assert_equal expected_binds, binds
+    end
+
+    def test_exec_explain_with_no_binds
+      sqls  = %w(foo bar)
+      binds = [[], []]
+
+      connection.stubs(:explain).returns('query plan foo', 'query plan bar')
+      expected = sqls.map {|sql| "EXPLAIN for: #{sql}\nquery plan #{sql}"}.join("\n")
+      assert_equal expected, base.exec_explain(sqls, binds)
+    end
+
+    def test_exec_explain_with_binds
+      cols = [Object.new, Object.new]
+      cols[0].expects(:name).returns('wadus')
+      cols[1].expects(:name).returns('chaflan')
+
+      sqls  = %w(foo bar)
+      binds = [[[cols[0], 1]], [[cols[1], 2]]]
+
+      connection.stubs(:explain).returns("query plan foo\n", "query plan bar\n")
+      expected = <<-SQL.strip_heredoc
+        EXPLAIN for: #{sqls[0]} [["wadus", 1]]
+        query plan foo
+
+        EXPLAIN for: #{sqls[1]} [["chaflan", 2]]
+        query plan bar
+      SQL
+      assert_equal expected, base.exec_explain(sqls, binds)
+    end
+
+    def with_threshold(threshold)
+      current_threshold = base.auto_explain_threshold_in_seconds
+      base.auto_explain_threshold_in_seconds = threshold
+      yield
+    ensure
+      base.auto_explain_threshold_in_seconds = current_threshold
+    end
+  end
+end