Merge remote branch 'jose/perf'

actionpack/lib/abstract_controller/logger.rb

@@ -9,25 +9,5 @@ module Logger
       cattr_accessor :logger
       extend ActiveSupport::Benchmarkable
     end
-
-    # A class that allows you to defer expensive processing
-    # until the logger actually tries to log. Otherwise, you are
-    # forced to do the processing in advance, and send the
-    # entire processed String to the logger, which might
-    # just discard the String if the log level is too low.
-    #
-    # TODO: Require that Rails loggers accept a block.
-    class DelayedLog < ActiveSupport::BasicObject
-      def initialize(&block)
-        @str, @block = nil, block
-      end
-
-      def method_missing(*args, &block)
-        unless @str
-          @str, @block = @block.call, nil
-        end
-        @str.send(*args, &block)
-      end
-    end
   end
 end

actionpack/lib/action_controller/base.rb

@@ -15,7 +15,6 @@ class Base < Metal
     include ActionController::ConditionalGet
     include ActionController::RackDelegation
     include ActionController::Logger
-    include ActionController::Benchmarking
     include ActionController::Configuration
 
     # Legacy modules

actionpack/lib/action_controller/caching.rb

@@ -60,6 +60,17 @@ module ClassMethods
       def cache_configured?
         perform_caching && cache_store
       end
+
+      def log_event(name, before, after, instrumenter_id, payload)
+        if name.to_s =~ /(read|write|cache|expire|exist)_(fragment|page)\??/
+          key_or_path = payload[:key] || payload[:path]
+          human_name  = name.to_s.humanize
+          duration    = (after - before) * 1000
+          logger.info("#{human_name} #{key_or_path.inspect} (%.1fms)" % duration)
+        else
+          super
+        end
+      end
     end
 
     def caching_allowed?

actionpack/lib/action_controller/caching/fragments.rb

@@ -74,7 +74,7 @@ def fragment_exist?(key, options = nil)
         return unless cache_configured?
         key = fragment_cache_key(key)
 
-        ActiveSupport::Notifications.instrument(:fragment_exist?, :key => key) do
+        ActiveSupport::Notifications.instrument(:exist_fragment?, :key => key) do
           cache_store.exist?(key, options)
         end
       end

actionpack/lib/action_controller/metal/benchmarking.rb

-require 'active_support/core_ext/benchmark'
-
-module ActionController #:nodoc:
-  # The benchmarking module times the performance of actions and reports to the logger. If the Active Record
-  # package has been included, a separate timing section for database calls will be added as well.
-  module Benchmarking #:nodoc:
-    extend ActiveSupport::Concern
-
-    protected
-      def render(*args, &block)
-        if logger
-          if Object.const_defined?("ActiveRecord") && ActiveRecord::Base.connected?
-            db_runtime = ActiveRecord::Base.connection.reset_runtime
-          end
-
-          render_output = nil
-          @view_runtime = Benchmark.ms { render_output = super }
-
-          if Object.const_defined?("ActiveRecord") && ActiveRecord::Base.connected?
-            @db_rt_before_render = db_runtime
-            @db_rt_after_render = ActiveRecord::Base.connection.reset_runtime
-            @view_runtime -= @db_rt_after_render
-          end
-
-          render_output
-        else
-          super
-        end
-      end
-
-    private
-      def process_action(*args)
-        if logger
-          ms = [Benchmark.ms { super }, 0.01].max
-          logging_view          = defined?(@view_runtime)
-          logging_active_record = Object.const_defined?("ActiveRecord") && ActiveRecord::Base.connected?
-
-          log_message  = 'Completed in %.0fms' % ms
-
-          if logging_view || logging_active_record
-            log_message << " ("
-            log_message << view_runtime if logging_view
-
-            if logging_active_record
-              log_message << ", " if logging_view
-              log_message << active_record_runtime + ")"
-            else
-              ")"
-            end
-          end
-
-          log_message << " | #{response.status}"
-          log_message << " [#{complete_request_uri rescue "unknown"}]"
-
-          logger.info(log_message)
-        else
-          super
-        end
-      end
-
-      def view_runtime
-        "View: %.0f" % @view_runtime
-      end
-
-      def active_record_runtime
-        db_runtime = ActiveRecord::Base.connection.reset_runtime
-        db_runtime += @db_rt_before_render if @db_rt_before_render
-        db_runtime += @db_rt_after_render if @db_rt_after_render
-        "DB: %.0f" % db_runtime
-      end
-  end
-end

actionpack/lib/action_controller/metal/filter_parameter_logging.rb

@@ -2,8 +2,6 @@ module ActionController
   module FilterParameterLogging
     extend ActiveSupport::Concern
 
-    include AbstractController::Logger
-
     module ClassMethods
       # Replace sensitive parameter data from the request log.
       # Filters parameters that have any of the arguments as a substring.
@@ -54,23 +52,25 @@ def filter_parameter_logging(*filter_words, &block)
         end
         protected :filter_parameters
       end
-    end
 
-    INTERNAL_PARAMS = [:controller, :action, :format, :_method, :only_path]
+    protected
 
-    def process(*)
-      response = super
-      if logger
-        parameters = filter_parameters(params).except!(*INTERNAL_PARAMS)
-        logger.info { "  Parameters: #{parameters.inspect}" } unless parameters.empty?
+      # Overwrite log_process_action to include parameters information.
+      # If this method is invoked, it means logger is defined, so don't
+      # worry with such scenario here.
+      def log_process_action(controller) #:nodoc:
+        params = controller.send(:filter_parameters, controller.request.params)
+        logger.info "  Parameters: #{params.inspect}" unless params.empty?
+        super
       end
-      response
     end
 
+    INTERNAL_PARAMS = [:controller, :action, :format, :_method, :only_path]
+
   protected
 
     def filter_parameters(params)
-      params.dup
+      params.dup.except!(*INTERNAL_PARAMS)
     end
 
   end

actionpack/lib/action_controller/metal/logger.rb

 require 'abstract_controller/logger'
 
 module ActionController
+  # Adds instrumentation to <tt>process_action</tt> and a <tt>log_event</tt> method
+  # responsible to log events from ActiveSupport::Notifications. This module handles
+  # :process_action and :render_template events but allows any other module to hook
+  # into log_event and provide its own logging facilities (as in ActionController::Caching).
   module Logger
-    # Override process_action in the AbstractController::Base
-    # to log details about the method.
+    extend ActiveSupport::Concern
+
+    attr_internal :view_runtime
+
     def process_action(action)
-      result = ActiveSupport::Notifications.instrument(:process_action,
-                :controller => self, :action => action) do
+      ActiveSupport::Notifications.instrument(:process_action, :controller => self, :action => action) do
         super
       end
+    end
 
+    def render(*args, &block)
       if logger
-        log = AbstractController::Logger::DelayedLog.new do
-          "\n\nProcessing #{self.class.name}\##{action_name} " \
-          "to #{request.formats} (for #{request_origin}) " \
-          "[#{request.method.to_s.upcase}]"
+        render_output = nil
+
+        self.view_runtime = cleanup_view_runtime do
+          Benchmark.ms { render_output = super }
         end
 
-        logger.info(log)
+        render_output
+      else
+        super
       end
+    end
 
-      result
+    # If you want to remove any time taken into account in :view_runtime
+    # wrongly, you can do it here:
+    #
+    #   def cleanup_view_runtime
+    #     super - time_taken_in_something_expensive
+    #   end
+    #
+    # :api: plugin
+    def cleanup_view_runtime #:nodoc:
+      yield
     end
 
-  private
+    module ClassMethods
+      # This is the hook invoked by ActiveSupport::Notifications.subscribe.
+      # If you need to log any event, overwrite the method and do it here.
+      def log_event(name, before, after, instrumenter_id, payload) #:nodoc:
+        if name == :process_action
+          duration     = [(after - before) * 1000, 0.01].max
+          controller   = payload[:controller]
+          request      = controller.request
+
+          logger.info "\n\nProcessed #{controller.class.name}##{payload[:action]} " \
+            "to #{request.formats} (for #{request.remote_ip} at #{before.to_s(:db)}) " \
+            "[#{request.method.to_s.upcase}]"
 
-    # Returns the request origin with the IP and time. This needs to be cached,
-    # otherwise we would get different results for each time it calls.
-    def request_origin
-      @request_origin ||= "#{request.remote_ip} at #{Time.now.to_s(:db)}"
+          log_process_action(controller)
+
+          message = "Completed in %.0fms" % duration
+          message << " | #{controller.response.status}"
+          message << " [#{request.request_uri rescue "unknown"}]"
+
+          logger.info(message)
+        elsif name == :render_template
+          # TODO Make render_template logging work if you are using just ActionView
+          duration = (after - before) * 1000
+          message = "Rendered #{payload[:identifier]}"
+          message << " within #{payload[:layout]}" if payload[:layout]
+          message << (" (%.1fms)" % duration)
+          logger.info(message)
+        end
+      end
+
+    protected
+
+      # A hook which allows logging what happened during controller process action.
+      # :api: plugin
+      def log_process_action(controller) #:nodoc:
+        view_runtime = controller.send :view_runtime
+        logger.info("  View runtime: %.1fms" % view_runtime.to_f) if view_runtime
+      end
     end
   end
-end
+end
\ No newline at end of file

actionpack/lib/action_controller/rails.rb

 module ActionController
   class Plugin < Rails::Plugin
     plugin_name :action_controller
+    include_modules_in "ActionController::Base"
 
     initializer "action_controller.set_configs" do |app|
       app.config.action_controller.each do |k,v|
@@ -14,10 +15,6 @@ class Plugin < Rails::Plugin
     end
 
     # Routing must be initialized after plugins to allow the former to extend the routes
-    # ---
-    # If Action Controller is not one of the loaded frameworks (Configuration#frameworks)
-    # this does nothing. Otherwise, it loads the routing definitions and sets up
-    # loading module used to lazily load controllers (Configuration#controller_paths).
     initializer "action_controller.initialize_routing" do |app|
       app.route_configuration_files << app.config.routes_configuration_file
       app.route_configuration_files << app.config.builtin_routes_configuration_file
@@ -88,13 +85,8 @@ class Plugin < Rails::Plugin
     initializer "action_controller.notifications" do |app|
       require 'active_support/notifications'
 
-      ActiveSupport::Notifications.subscribe(/(read|write|cache|expire|exist)_(fragment|page)\??/) do |*args|
-        event = ActiveSupport::Notifications::Event.new(*args)
-
-        if logger = ActionController::Base.logger
-          human_name = event.name.to_s.humanize
-          logger.info("#{human_name} (%.1fms)" % event.duration)
-        end
+      ActiveSupport::Notifications.subscribe do |*args|
+        ActionController::Base.log_event(*args) if ActionController::Base.logger
       end
     end
 

actionpack/lib/action_view/render/partials.rb

@@ -191,45 +191,60 @@ def initialize(view_context, options, block)
       def setup(options, block)
         partial = options[:partial]
 
-        @options    = options
-        @locals     = options[:locals] || {}
-        @block      = block
+        @options = options
+        @locals  = options[:locals] || {}
+        @block   = block
 
         if String === partial
-          @object = options[:object]
-          @path   = partial
+          @object     = options[:object]
+          @path       = partial
+          @collection = collection
         else
           @object = partial
-          @path   = partial_path(partial)
+
+          if @collection = collection
+            paths = @collection_paths = @collection.map { |o| partial_path(o) }
+            @path = paths.uniq.size == 1 ? paths.first : nil
+          else
+            @path = partial_path
+          end
         end
       end
 
       def render
-        if @collection = collection
-          render_collection
+        options = @options
+
+        if @collection
+          ActiveSupport::Notifications.instrument(:render_collection, :path => @path,
+                                                  :count => @collection.size) do
+            render_collection
+          end
         else
-          @template = template = find_template
-          render_template(template, @object || @locals[template.variable_name])
+          content = ActiveSupport::Notifications.instrument(:render_partial, :path => @path) do
+            render_partial
+          end
+
+          if !@block && options[:layout]
+            content = @view._render_layout(find_template(options[:layout]), @locals){ content }
+          end
+          content
         end
       end
 
       def render_collection
         @template = template = find_template
-
         return nil if @collection.blank?
 
         if @options.key?(:spacer_template)
           spacer = find_template(@options[:spacer_template]).render(@view, @locals)
         end
 
-        result = template ? collection_with_template(template) : collection_without_template
+        result = template ? collection_with_template : collection_without_template
         result.join(spacer).html_safe!
       end
 
-      def collection_with_template(template)
-        options = @options
-
-        segments, locals, as = [], @locals, options[:as] || template.variable_name
+      def collection_with_template(template = @template)
+        segments, locals, as = [], @locals, @options[:as] || template.variable_name
 
         counter_name  = template.counter_name
         locals[counter_name] = -1
@@ -245,16 +260,14 @@ def collection_with_template(template)
         segments
       end
 
-      def collection_without_template
-        options = @options
-
-        segments, locals, as = [], @locals, options[:as]
+      def collection_without_template(collection_paths = @collection_paths)
+        segments, locals, as = [], @locals, @options[:as]
         index, template = -1, nil
 
-        @collection.each do |object|
-          template = find_template(partial_path(object))
+        @collection.each_with_index do |object, i|
+          template = find_template(collection_paths[i])
           locals[template.counter_name] = (index += 1)
-          locals[template.variable_name] = object
+          locals[as || template.variable_name] = object
 
           segments << template.render(@view, locals)
         end
@@ -263,18 +276,15 @@ def collection_without_template
         segments
       end
 
-      def render_template(template, object = @object)
-        options, locals, view = @options, @locals, @view
-        locals[options[:as] || template.variable_name] = object
+      def render_partial(object = @object)
+        @template = template = find_template
+        locals, view = @locals, @view
 
-        content = template.render(view, locals) do |*name|
-          @view._layout_for(*name, &@block)
-        end
+        object ||= locals[template.variable_name]
+        locals[@options[:as] || template.variable_name] = object
 
-        if @block || !options[:layout]
-          content
-        else
-          find_template(options[:layout]).render(@view, @locals) { content }
+        template.render(view, locals) do |*name|
+          view._layout_for(*name, &@block)
         end
       end
 
@@ -305,9 +315,9 @@ def _find_template(path)
 
       def partial_path(object = @object)
         @partial_names[object.class] ||= begin
-          return nil unless object.respond_to?(:to_model)
+          object = object.to_model if object.respond_to?(:to_model)
 
-          object.to_model.class.model_name.partial_path.dup.tap do |partial|
+          object.class.model_name.partial_path.dup.tap do |partial|
             path = @view.controller_path
             partial.insert(0, "#{File.dirname(path)}/") if path.include?(?/)
           end

actionpack/lib/action_view/render/rendering.rb

@@ -73,25 +73,24 @@ def render(options = {}, locals = {}, &block) #:nodoc:
     # would be <html>Hello David</html>.
     def _layout_for(name = nil, &block)
       return @_content_for[name || :layout] if !block_given? || name
-
       capture(&block)
     end
 
     def _render_inline(inline, layout, options)
-      handler  = Template.handler_class_for_extension(options[:type] || "erb")
-      template = Template.new(options[:inline], "inline template", handler, {})
+      locals = options[:locals]
 
-      locals  = options[:locals]
-      content = template.render(self, locals)
+      content = ActiveSupport::Notifications.instrument(:render_inline) do
+        handler  = Template.handler_class_for_extension(options[:type] || "erb")
+        template = Template.new(options[:inline], "inline template", handler, {})
+        template.render(self, locals)
+      end
 
       _render_text(content, layout, locals)
     end
 
     def _render_text(content, layout, locals)
-      content = layout.render(self, locals) do |*name|
-        _layout_for(*name) { content }
-      end if layout
-
+      ActiveSupport::Notifications.instrument(:render_text)
+      content = _render_layout(layout, locals){ content } if layout
       content
     end
 
@@ -108,23 +107,27 @@ def render_template(options)
     end
 
     def _render_template(template, layout = nil, options = {}, partial = nil)
-      logger && logger.info do
-        msg = "Rendering #{template.inspect}"
-        msg << " (#{options[:status]})" if options[:status]
-        msg
+      locals = options[:locals] || {}
+
+      content = ActiveSupport::Notifications.instrument(:render_template,
+                :identifier => template.identifier, :layout => (layout ? layout.identifier : nil)) do
+        partial ? _render_partial_object(template, options) : template.render(self, locals)
       end
 
-      locals  = options[:locals] || {}
-      content = partial ? _render_partial_object(template, options) : template.render(self, locals)
       @_content_for[:layout] = content
 
       if layout
         @_layout = layout.identifier
-        logger.info("Rendering template within #{layout.inspect}") if logger
-        content = layout.render(self, locals) { |*name| _layout_for(*name) }
+        content  = _render_layout(layout, locals)
       end
 
       content
     end
+
+    def _render_layout(layout, locals, &block)
+      ActiveSupport::Notifications.instrument(:render_layout, :identifier => layout.identifier) do
+        layout.render(self, locals){ |*name| _layout_for(*name, &block) }
+      end
+    end
   end
 end

actionpack/lib/action_view/template.rb

@@ -36,10 +36,8 @@ def initialize(source, identifier, handler, details)
     end
 
     def render(view, locals, &block)
-      ActiveSupport::Notifications.instrument(:render_template, :identifier => identifier) do
-        method_name = compile(locals, view)
-        view.send(method_name, locals, &block)
-      end
+      method_name = compile(locals, view)
+      view.send(method_name, locals, &block)
     rescue Exception => e
       if e.is_a?(Template::Error)
         e.sub_template_of(self)

actionpack/test/abstract_unit.rb

@@ -50,6 +50,14 @@
 FIXTURE_LOAD_PATH = File.join(File.dirname(__FILE__), 'fixtures')
 FIXTURES = Pathname.new(FIXTURE_LOAD_PATH)
 
+# Turn on notifications
+require 'active_support/notifications'
+Thread.abort_on_exception = true
+
+ActiveSupport::Notifications.subscribe do |*args|
+  ActionController::Base.log_event(*args) if ActionController::Base.logger
+end
+
 module SetupOnce
   extend ActiveSupport::Concern
 
@@ -87,6 +95,21 @@ class ActiveSupport::TestCase
   end
 end
 
+class MockLogger
+  attr_reader :logged
+  attr_accessor :level
+
+  def initialize
+    @level = Logger::DEBUG
+    @logged = []
+  end
+
+  def method_missing(method, *args, &blk)
+    @logged << args.first
+    @logged << blk.call if block_given?
+  end
+end
+
 class ActionController::IntegrationTest < ActiveSupport::TestCase
   def self.build_app(routes = nil)
     ActionDispatch::MiddlewareStack.new { |middleware|

actionpack/test/controller/base_test.rb

@@ -158,13 +158,6 @@ def test_get_on_hidden_should_fail
     assert_raise(ActionController::UnknownAction) { get :hidden_action }
     assert_raise(ActionController::UnknownAction) { get :another_hidden_action }
   end
-
-  def test_namespaced_action_should_log_module_name
-    use_controller Submodule::ContainedNonEmptyController
-    @controller.logger = MockLogger.new
-    get :public_action
-    assert_match /Processing\sSubmodule::ContainedNonEmptyController#public_action/, @controller.logger.logged[1]
-  end
 end
 
 class DefaultUrlOptionsTest < ActionController::TestCase

actionpack/test/controller/benchmark_test.rb

-require 'abstract_unit'
-
-# Provide some static controllers.
-class BenchmarkedController < ActionController::Base
-  def public_action
-    render :nothing => true
-  end
-
-  def rescue_action(e)
-    raise e
-  end
-end
-
-class BenchmarkTest < ActionController::TestCase
-  tests BenchmarkedController
-
-  class MockLogger
-    def method_missing(*args)
-    end
-  end
-
-  def setup
-    super
-    # benchmark doesn't do anything unless a logger is set
-    @controller.logger = MockLogger.new
-    @request.host = "test.actioncontroller.i"
-  end
-
-  def test_with_http_1_0_request
-    @request.host = nil
-    assert_nothing_raised { get :public_action }
-  end
-end

actionpack/test/controller/caching_test.rb

@@ -640,7 +640,7 @@ def test_fragment_for_logging
     assert fragment_computed
     assert_equal 'generated till now -> ', buffer
     ActiveSupport::Notifications.notifier.wait
-    assert_equal [:fragment_exist?, :write_fragment], events.map(&:first)
+    assert_equal [:exist_fragment?, :write_fragment], events.map(&:first)
   end
 
 end

actionpack/test/controller/filter_params_test.rb

@@ -70,9 +70,9 @@ def test_filter_parameters_inside_logs
     FilterParamController.filter_parameter_logging(:lifo, :amount)
 
     get :payment, :lifo => 'Pratik', :amount => '420', :step => '1'
+    ActiveSupport::Notifications.notifier.wait
 
     filtered_params_logs = logs.detect {|l| l =~ /\AParameters/ }
-
     assert filtered_params_logs.index('"amount"=>"[FILTERED]"')
     assert filtered_params_logs.index('"lifo"=>"[FILTERED]"')
     assert filtered_params_logs.index('"step"=>"1"')

actionpack/test/controller/logging_test.rb

 require 'abstract_unit'
 
-class LoggingController < ActionController::Base
-  def show
-    render :nothing => true
-  end
-end
-
-class LoggingTest < ActionController::TestCase
-  tests LoggingController
-
-  class MockLogger
-    attr_reader :logged
-    attr_accessor :level
+module Another
+  class LoggingController < ActionController::Base
+    layout "layouts/standard"
 
-    def initialize
-      @level = Logger::DEBUG
+    def show
+      render :nothing => true
     end
 
-    def method_missing(method, *args, &blk)
-      @logged ||= []
-      @logged << args.first
-      @logged << blk.call if block_given?
+    def with_layout
+      render :template => "test/hello_world", :layout => true
     end
   end
+end
+
+class LoggingTest < ActionController::TestCase
+  tests Another::LoggingController
 
   def setup
     super
     set_logger
   end
 
+  def get(*args)
+    super
+    wait
+  end
+
+  def wait
+    ActiveSupport::Notifications.notifier.wait
+  end
+
   def test_logging_without_parameters
     get :show
-    assert_equal 3, logs.size
+    assert_equal 4, logs.size
     assert_nil logs.detect {|l| l =~ /Parameters/ }
   end
 
   def test_logging_with_parameters
     get :show, :id => '10'
-    assert_equal 4, logs.size
+    assert_equal 5, logs.size
 
     params = logs.detect {|l| l =~ /Parameters/ }
     assert_equal 'Parameters: {"id"=>"10"}', params
   end
 
+  def test_log_controller_with_namespace_and_action
+    get :show
+    assert_match /Processed\sAnother::LoggingController#show/, logs[1]
+  end
+
+  def test_log_view_runtime
+     get :show
+     assert_match /View runtime/, logs[2]
+   end
+
+  def test_log_completed_status_and_request_uri
+    get :show
+    last = logs.last
+    assert_match /Completed/, last
+    assert_match /200/, last
+    assert_match /another\/logging\/show/, last
+  end
+
+  def test_logger_prints_layout_and_template_rendering_info
+    get :with_layout
+    logged = logs.find {|l| l =~ /render/i }
+    assert_match /Rendered (.*)test\/hello_world.erb within (.*)layouts\/standard.html.erb/, logged
+  end
+
   private
     def set_logger
       @controller.logger = MockLogger.new

actionpack/test/controller/render_test.rb

@@ -10,19 +10,6 @@ def hello_world
   end
 end
 
-class MockLogger
-  attr_reader :logged
-
-  def initialize
-    @logged = []
-  end
-
-  def method_missing(method, *args, &blk)
-    @logged << args.first
-    @logged << blk.call if block_given?
-  end
-end
-
 class TestController < ActionController::Base
   protect_from_forgery
 
@@ -1500,21 +1487,4 @@ def test_last_modified_works_with_less_than_too
     get :conditional_hello_with_bangs
     assert_response :success
   end
-end
-
-class RenderingLoggingTest < ActionController::TestCase
-  tests TestController
-
-  def setup
-    super
-    @request.host = "www.nextangle.com"
-  end
-
-  def test_logger_prints_layout_and_template_rendering_info
-    @controller.logger = MockLogger.new
-    get :layout_test
-    logged = @controller.logger.logged.find_all {|l| l =~ /render/i }
-    assert logged[0] =~ %r{Rendering.*test/hello_world}
-    assert logged[1] =~ %r{Rendering template within.*layouts/standard}
-  end
-end
+end
\ No newline at end of file

activerecord/lib/active_record.rb

@@ -52,6 +52,7 @@ module ActiveRecord
     autoload :Batches
     autoload :Calculations
     autoload :Callbacks
+    autoload :ControllerRuntime
     autoload :DynamicFinderMatch
     autoload :DynamicScopeMatch
     autoload :Migration

activerecord/lib/active_record/controller_runtime.rb

+module ActiveRecord
+  module ControllerRuntime
+    extend ActiveSupport::Concern
+
+    attr_internal :db_runtime
+
+    def cleanup_view_runtime
+      if Object.const_defined?("ActiveRecord") && 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 process_log_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
\ No newline at end of file

activerecord/lib/active_record/rails.rb

@@ -7,6 +7,9 @@
 module ActiveRecord
   class Plugin < Rails::Plugin
     plugin_name :active_record
+    include_modules_in "ActiveRecord::Base"
+
+    config.action_controller.include "ActiveRecord::ControllerRuntime"
 
     initializer "active_record.set_configs" do |app|
       app.config.active_record.each do |k,v|
@@ -50,8 +53,8 @@ class Plugin < Rails::Plugin
     initializer "active_record.notifications" do
       require 'active_support/notifications'
 
-      ActiveSupport::Notifications.subscribe("sql") do |name, before, after, result, instrumenter_id, payload|
-        ActiveRecord::Base.connection.log_info(payload[:sql], name, after - before)
+      ActiveSupport::Notifications.subscribe("sql") do |name, before, after, instrumenter_id, payload|
+        ActiveRecord::Base.connection.log_info(payload[:sql], payload[:name], (after - before) * 1000)
       end
     end
 

activesupport/lib/active_support/core_ext/string/output_safety.rb

+class Object
+  def html_safe?
+    false
+  end
+end
+
+class Fixnum
+  def html_safe?
+    true
+  end
+end
+
 class String
   attr_accessor :_rails_html_safe
   alias html_safe? _rails_html_safe

activesupport/lib/active_support/notifications/instrumenter.rb

@@ -10,10 +10,10 @@ def initialize(notifier)
       end
 
       def instrument(name, payload={})
-        time   = Time.now
-        result = yield if block_given?
+        time = Time.now
+        yield if block_given?
       ensure
-        @notifier.publish(name, time, Time.now, result, @id, payload)
+        @notifier.publish(name, time, Time.now, @id, payload)
       end
 
       private
@@ -23,15 +23,14 @@ def unique_id
     end
 
     class Event
-      attr_reader :name, :time, :end, :transaction_id, :result, :payload
+      attr_reader :name, :time, :end, :transaction_id, :payload
 
-      def initialize(name, start, ending, result, transaction_id, payload)
+      def initialize(name, start, ending, transaction_id, payload)
         @name           = name
         @payload        = payload.dup
         @time           = start
         @transaction_id = transaction_id
         @end            = ending
-        @result         = result
       end
 
       def duration

activesupport/test/core_ext/string_ext_test.rb

@@ -350,6 +350,24 @@ def setup
     assert_equal @string, @string.html_safe!
   end
 
+  test "A fixnum is safe by default" do
+    assert 5.html_safe?
+  end
+
+  test "An object is unsafe by default" do
+    klass = Class.new(Object) do
+      def to_str
+        "other"
+      end
+    end
+
+    @string.html_safe!
+    @string << klass.new
+
+    assert_equal "helloother", @string
+    assert !@string.html_safe?
+  end
+
   test "Adding a safe string to another safe string returns a safe string" do
     @other_string = "other".html_safe!
     @string.html_safe!
@@ -416,4 +434,10 @@ def setup
     @other_string << @string
     assert @other_string.html_safe?
   end
+
+  test "Concatting a fixnum to safe always yields safe" do
+    @string.html_safe!
+    @string.concat(13)
+    assert @string.html_safe?
+  end
 end

activesupport/test/notifications_test.rb

@@ -134,27 +134,25 @@ def test_event_is_pushed_even_without_block
 
   class EventTest < TestCase
     def test_events_are_initialized_with_details
-      event = event(:foo, Time.now, Time.now + 1, 1, random_id, :payload => :bar)
-      assert_equal :foo, event.name
-      assert_equal Hash[:payload => :bar], event.payload
-    end
-
-    def test_events_consumes_information_given_as_payload
       time = Time.now
-      event = event(:foo, time, time + 0.01, 1, random_id, {})
+      event = event(:foo, time, time + 0.01, random_id, {})
 
-      assert_equal Hash.new, event.payload
+      assert_equal :foo, event.name
       assert_equal time, event.time
-      assert_equal 1, event.result
       assert_equal 10.0, event.duration
     end
 
+    def test_events_consumes_information_given_as_payload
+      event = event(:foo, Time.now, Time.now + 1, random_id, :payload => :bar)
+      assert_equal Hash[:payload => :bar], event.payload
+    end
+
     def test_event_is_parent_based_on_time_frame
       time = Time.utc(2009, 01, 01, 0, 0, 1)
 
-      parent    = event(:foo, Time.utc(2009), Time.utc(2009) + 100, nil, random_id, {})
-      child     = event(:foo, time, time + 10, nil, random_id, {})
-      not_child = event(:foo, time, time + 100, nil, random_id, {})
+      parent    = event(:foo, Time.utc(2009), Time.utc(2009) + 100, random_id, {})
+      child     = event(:foo, time, time + 10, random_id, {})
+      not_child = event(:foo, time, time + 100, random_id, {})
 
       assert parent.parent_of?(child)
       assert !child.parent_of?(parent)

railties/lib/rails/configuration.rb

 require 'active_support/ordered_options'
 
 module Rails
+  # Create a Plugin::Options from ActiveSuppot::OrderedOptions,
+  # which support the following syntax:
+  #
+  #   controller.action_controller.include FooBar
+  #
+  class Plugin::Options < ActiveSupport::OrderedOptions #:nodoc:
+    attr_reader :includes
+
+    def initialize(*args)
+      @includes = []
+      super
+    end
+
+    def include(*args)
+      @includes.concat(args)
+    end
+  end
+
   # Temporarily separate the plugin configuration class from the main
   # configuration class while this bit is being cleaned up.
   class Plugin::Configuration
@@ -16,7 +34,7 @@ def initialize(base = nil)
         @options    = base.options.dup
         @middleware = base.middleware.dup
       else
-        @options    = Hash.new { |h,k| h[k] = ActiveSupport::OrderedOptions.new }
+        @options    = Hash.new { |h,k| h[k] = Rails::Plugin::Options.new }
         @middleware = ActionDispatch::MiddlewareStack.new
       end
     end

railties/lib/rails/plugin.rb

@@ -25,6 +25,24 @@ def self.config
       Configuration.default
     end
 
+    # Creates an initializer which includes all given modules to the given class.
+    #
+    #   module Rails
+    #     class ActionController < Rails::Plugin
+    #       plugin_name :action_controller
+    #       include_modules_in "ActionController::Base"
+    #     end
+    #   end
+    #
+    def self.include_modules_in(klass, from=plugin_name)
+      self.initializer :"#{from}.include_modules" do |app|
+        klass = klass.constantize if klass.is_a?(String)
+        app.config.send(from).includes.each do |mod|
+          klass.send(:include, mod.is_a?(String) ? mod.constantize : mod)
+        end
+      end
+    end
+
     class Vendored < Plugin
       def self.all(list, paths)
         plugins = []

railties/test/plugins/configuration_test.rb

@@ -8,6 +8,10 @@ def setup
       require "rails"
     end
 
+    module Bar; end
+    module Baz; end
+    module All; end
+
     test "config is available to plugins" do
       class Foo < Rails::Plugin ; end
       assert_nil Foo.config.action_controller.foo
@@ -24,6 +28,18 @@ class Foo < Rails::Plugin ; config.foo.greetings = "hello" ; end
       assert_equal "hello", AppTemplate::Application.config.foo.greetings
     end
 
+    test "plugin configurations allow modules to be given" do
+      class Foo < Rails::Plugin ; config.foo.include(Bar, Baz) ; end
+      assert_equal [Bar, Baz], Foo.config.foo.includes
+    end
+
+    test "plugin includes given modules in given class" do
+      class Foo < Rails::Plugin ; config.foo.include(Bar, "PluginsTest::ConfigurationTest::Baz") ; include_modules_in All ; end
+      Foo.new.run_initializers(Foo)
+      assert All.ancestors.include?(Bar)
+      assert All.ancestors.include?(Baz)
+    end
+
     test "plugin config merges are deep" do
       class Foo < Rails::Plugin ; config.foo.greetings = 'hello' ; end
       class MyApp < Rails::Application