Merge commit 'josevalim/arlog'

actionpack/test/activerecord/controller_runtime_test.rb

@@ -0,0 +1,39 @@
+require 'active_record_unit'
+require 'active_record/rails/controller_runtime'
+require 'fixtures/project'
+
+ActionController::Base.send :include, ActiveRecord::Rails::ControllerRuntime
+
+class ARLoggingController < ActionController::Base
+  def show
+    render :inline => "<%= Project.all %>"
+  end
+end
+
+class ARLoggingTest < ActionController::TestCase
+  tests ARLoggingController
+
+  def setup
+    super
+    set_logger
+  end
+
+  def wait
+    ActiveSupport::Notifications.notifier.wait
+  end
+
+  def test_log_with_active_record
+    get :show
+    wait
+    assert_match /ActiveRecord runtime/, logs[3]
+  end
+
+  private
+    def set_logger
+      @controller.logger = MockLogger.new
+    end
+
+    def logs
+      @logs ||= @controller.logger.logged.compact.map {|l| l.to_s.strip}
+    end
+end

activerecord/lib/active_record/base.rb

@@ -1,4 +1,3 @@
-require 'benchmark'
 require 'yaml'
 require 'set'
 require 'active_support/benchmarkable'

activerecord/lib/active_record/connection_adapters/abstract_adapter.rb

@@ -1,6 +1,7 @@
 require 'date'
 require 'bigdecimal'
 require 'bigdecimal/util'
+require 'active_support/core_ext/benchmark'
 
 # TODO: Autoload these files
 require 'active_record/connection_adapters/abstract/schema_definitions'
@@ -191,16 +192,19 @@ def current_savepoint_name
       end
 
       def log_info(sql, name, ms)
-        @runtime += ms
         if @logger && @logger.debug?
           name = '%s (%.1fms)' % [name || 'SQL', ms]
           @logger.debug(format_log_entry(name, sql.squeeze(' ')))
         end
       end
 
       protected
-        def log(sql, name, &block)
-          ActiveSupport::Notifications.instrument(:sql, :sql => sql, :name => name, &block)
+        def log(sql, name)
+          result = nil
+          ActiveSupport::Notifications.instrument(:sql, :sql => sql, :name => name) do
+            @runtime += Benchmark.ms { result = yield }
+          end
+          result
         rescue Exception => e
           # Log message and raise exception.
           # Set last_verification to 0, so that connection gets verified

activerecord/lib/active_record/rails.rb

@@ -3,13 +3,14 @@
 # here. This is needed for correctly setting up the middleware.
 # In the future, this might become an optional require.
 require "action_controller/rails"
+require "active_record/rails/controller_runtime"
 
 module ActiveRecord
   class Plugin < Rails::Plugin
     plugin_name :active_record
     include_modules_in "ActiveRecord::Base"
 
-    config.action_controller.include "ActiveRecord::ControllerRuntime"
+    config.action_controller.include "ActiveRecord::Rails::ControllerRuntime"
 
     rake_tasks do
       load "active_record/rails/databases.rake"

activerecord/lib/active_record/rails/controller_runtime.rb

@@ -0,0 +1,29 @@
+module ActiveRecord
+  module Rails
+    module ControllerRuntime
+      extend ActiveSupport::Concern
+
+      attr_internal :db_runtime
+
+      def cleanup_view_runtime
+        if ActiveRecord::Base.connected?
+          db_rt_before_render = ActiveRecord::Base.connection.reset_runtime
+          runtime = super
+          db_rt_after_render = ActiveRecord::Base.connection.reset_runtime
+          self.db_runtime = db_rt_before_render + db_rt_after_render
+          runtime - db_rt_after_render
+        else
+          super
+        end
+      end
+
+      module ClassMethods
+        def log_process_action(controller)
+          super
+          db_runtime = controller.send :db_runtime
+          logger.info("  ActiveRecord runtime: %.1fms" % db_runtime.to_f) if db_runtime
+        end
+      end
+    end
+  end
+end