Merge commit 'rails/master'

actionmailer/lib/action_mailer/base.rb

@@ -256,6 +256,8 @@ module ActionMailer #:nodoc:
   #   +implicit_parts_order+.
   class Base
     include AdvAttrAccessor, PartContainer, Quoting, Utils
+    extend AbstractController::RenderingController
+
     if Object.const_defined?(:ActionController)
       include ActionController::UrlWriter
       include ActionController::Layout
@@ -479,78 +481,84 @@ def initialize(method_name=nil, *parameters) #:nodoc:
     # Initialize the mailer via the given +method_name+. The body will be
     # rendered and a new TMail::Mail object created.
     def create!(method_name, *parameters) #:nodoc:
-      initialize_defaults(method_name)
-      __send__(method_name, *parameters)
-
-      # If an explicit, textual body has not been set, we check assumptions.
-      unless String === @body
-        # First, we look to see if there are any likely templates that match,
-        # which include the content-type in their file name (i.e.,
-        # "the_template_file.text.html.erb", etc.). Only do this if parts
-        # have not already been specified manually.
-        # if @parts.empty?
-          template_root.find_all(@template, {}, template_path).each do |template|
-            @parts << Part.new(
-              :content_type => template.mime_type ? template.mime_type.to_s : "text/plain",
-              :disposition => "inline",
-              :charset => charset,
-              :body => render_template(template, @body)
-            )
-          end
-
-          if @parts.size > 1
-            @content_type = "multipart/alternative" if @content_type !~ /^multipart/
-            @parts = sort_parts(@parts, @implicit_parts_order)
-          end
-        # end
-
-        # Then, if there were such templates, we check to see if we ought to
-        # also render a "normal" template (without the content type). If a
-        # normal template exists (or if there were no implicit parts) we render
-        # it.
-        # ====
-        # TODO: Revisit this
-        # template_exists = @parts.empty?
-        # template_exists ||= template_root.find("#{mailer_name}/#{@template}")
-        # @body = render_message(@template, @body) if template_exists
-
-        # Finally, if there are other message parts and a textual body exists,
-        # we shift it onto the front of the parts and set the body to nil (so
-        # that create_mail doesn't try to render it in addition to the parts).
-        # ====
-        # TODO: Revisit this
-        # if !@parts.empty? && String === @body
-        #   @parts.unshift Part.new(:charset => charset, :body => @body)
-        #   @body = nil
-        # end
-      end
+      ActiveSupport::Orchestra.instrument(:create_mail, :name => method_name) do
+        initialize_defaults(method_name)
+        __send__(method_name, *parameters)
+
+        # If an explicit, textual body has not been set, we check assumptions.
+        unless String === @body
+          # First, we look to see if there are any likely templates that match,
+          # which include the content-type in their file name (i.e.,
+          # "the_template_file.text.html.erb", etc.). Only do this if parts
+          # have not already been specified manually.
+          # if @parts.empty?
+            template_root.find_all(@template, {}, template_path).each do |template|
+              @parts << Part.new(
+                :content_type => template.mime_type ? template.mime_type.to_s : "text/plain",
+                :disposition => "inline",
+                :charset => charset,
+                :body => render_template(template, @body)
+              )
+            end
+
+            if @parts.size > 1
+              @content_type = "multipart/alternative" if @content_type !~ /^multipart/
+              @parts = sort_parts(@parts, @implicit_parts_order)
+            end
+          # end
+
+          # Then, if there were such templates, we check to see if we ought to
+          # also render a "normal" template (without the content type). If a
+          # normal template exists (or if there were no implicit parts) we render
+          # it.
+          # ====
+          # TODO: Revisit this
+          # template_exists = @parts.empty?
+          # template_exists ||= template_root.find("#{mailer_name}/#{@template}")
+          # @body = render_message(@template, @body) if template_exists
+
+          # Finally, if there are other message parts and a textual body exists,
+          # we shift it onto the front of the parts and set the body to nil (so
+          # that create_mail doesn't try to render it in addition to the parts).
+          # ====
+          # TODO: Revisit this
+          # if !@parts.empty? && String === @body
+          #   @parts.unshift Part.new(:charset => charset, :body => @body)
+          #   @body = nil
+          # end
+        end
+
+        # If this is a multipart e-mail add the mime_version if it is not
+        # already set.
+        @mime_version ||= "1.0" if !@parts.empty?
 
-      # If this is a multipart e-mail add the mime_version if it is not
-      # already set.
-      @mime_version ||= "1.0" if !@parts.empty?
+        # build the mail object itself
+        @mail = create_mail
+      end
 
-      # build the mail object itself
-      @mail = create_mail
+      @mail
     end
 
     # Delivers a TMail::Mail object. By default, it delivers the cached mail
     # object (from the <tt>create!</tt> method). If no cached mail object exists, and
     # no alternate has been given as the parameter, this will fail.
     def deliver!(mail = @mail)
       raise "no mail object available for delivery!" unless mail
-      
+
       unless logger.nil?
         logger.info  "Sent mail to #{Array(recipients).join(', ')}"
         logger.debug "\n#{mail.encoded}"
       end
 
-      begin
-        __send__("perform_delivery_#{delivery_method}", mail) if perform_deliveries
-      rescue Exception => e  # Net::SMTP errors or sendmail pipe errors
-        raise e if raise_delivery_errors
+      ActiveSupport::Orchestra.instrument(:deliver_mail, :mail => @mail) do
+        begin
+          __send__("perform_delivery_#{delivery_method}", mail) if perform_deliveries
+        rescue Exception => e # Net::SMTP errors or sendmail pipe errors
+          raise e if raise_delivery_errors
+        end
       end
 
-      return mail
+      mail
     end
 
     private

actionpack/lib/abstract_controller.rb

@@ -3,7 +3,6 @@
 
 module AbstractController
   autoload :Base,                "abstract_controller/base"
-  autoload :Benchmarker,         "abstract_controller/benchmarker"
   autoload :Callbacks,           "abstract_controller/callbacks"
   autoload :Helpers,             "abstract_controller/helpers"
   autoload :Layouts,             "abstract_controller/layouts"

actionpack/lib/abstract_controller/logger.rb

@@ -4,6 +4,26 @@ module AbstractController
   module Logger
     extend ActiveSupport::Concern
 
+    included do
+      cattr_accessor :logger
+    end
+
+    module ClassMethods #:nodoc:
+      # Logs a message appending the value measured.
+      def log_with_time(message, time, log_level=::Logger::DEBUG)
+        return unless logger && logger.level >= log_level
+        logger.add(log_level, "#{message} (%.1fms)" % time)
+      end
+
+      # Silences the logger for the duration of the block.
+      def silence
+        old_logger_level, logger.level = logger.level, ::Logger::ERROR if logge
+        yield
+      ensure
+        logger.level = old_logger_level if logger
+      end
+    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
@@ -24,32 +44,31 @@ def method_missing(*args, &block)
       end
     end
 
-    included do
-      cattr_accessor :logger
-    end
-
     # Override process_action in the AbstractController::Base
     # to log details about the method.
     def process_action(action)
-      retval = super
+      event = ActiveSupport::Orchestra.instrument(:process_action,
+                :controller => self, :action => action) do
+        super
+      end
 
       if logger
         log = DelayedLog.new do
           "\n\nProcessing #{self.class.name}\##{action_name} " \
-          "to #{request.formats} " \
-          "(for #{request_origin}) [#{request.method.to_s.upcase}]"
+          "to #{request.formats} (for #{request_origin}) " \
+          "(%.1fms) [#{request.method.to_s.upcase}]" % event.duration
         end
 
         logger.info(log)
       end
 
-      retval
+      event.result
     end
 
   private
+    # 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
-      # this *needs* to be cached!
-      # otherwise you'd get different results if calling it more than once
       @request_origin ||= "#{request.remote_ip} at #{Time.now.to_s(:db)}"
     end
   end

actionpack/lib/action_controller/base.rb

@@ -2,7 +2,6 @@ module ActionController
   class Base < Metal
     abstract!
 
-    include AbstractController::Benchmarker
     include AbstractController::Callbacks
     include AbstractController::Logger
 

actionpack/lib/action_controller/caching/fragments.rb

@@ -53,11 +53,11 @@ def write_fragment(key, content, options = nil)
         return content unless cache_configured?
 
         key = fragment_cache_key(key)
-
-        self.class.benchmark "Cached fragment miss: #{key}" do
+        event = ActiveSupport::Orchestra.instrument(:write_fragment, :key => key) do
           cache_store.write(key, content, options)
         end
 
+        self.class.log_with_time("Cached fragment miss: #{key}", event.duration)
         content
       end
 
@@ -66,21 +66,25 @@ def read_fragment(key, options = nil)
         return unless cache_configured?
 
         key = fragment_cache_key(key)
-
-        self.class.benchmark "Cached fragment hit: #{key}" do
+        event = ActiveSupport::Orchestra.instrument(:read_fragment, :key => key) do
           cache_store.read(key, options)
         end
+
+        self.class.log_with_time("Cached fragment hit: #{key}", event.duration)
+        event.result
       end
 
       # Check if a cached fragment from the location signified by <tt>key</tt> exists (see <tt>expire_fragment</tt> for acceptable formats)
       def fragment_exist?(key, options = nil)
         return unless cache_configured?
 
         key = fragment_cache_key(key)
-
-        self.class.benchmark "Cached fragment exists?: #{key}" do
+        event = ActiveSupport::Orchestra.instrument(:fragment_exist?, :key => key) do
           cache_store.exist?(key, options)
         end
+
+        self.class.log_with_time("Cached fragment exists?: #{key}", event.duration)
+        event.result
       end
 
       # Removes fragments from the cache.
@@ -103,17 +107,21 @@ def fragment_exist?(key, options = nil)
       def expire_fragment(key, options = nil)
         return unless cache_configured?
 
-        key = key.is_a?(Regexp) ? key : fragment_cache_key(key)
+        key = fragment_cache_key(key) unless key.is_a?(Regexp)
+        message = nil
 
-        if key.is_a?(Regexp)
-          self.class.benchmark "Expired fragments matching: #{key.source}" do
+        event = ActiveSupport::Orchestra.instrument(:expire_fragment, :key => key) do
+          if key.is_a?(Regexp)
+            message = "Expired fragments matching: #{key.source}"
             cache_store.delete_matched(key, options)
-          end
-        else
-          self.class.benchmark "Expired fragment: #{key}" do
+          else
+            message = "Expired fragment: #{key}"
             cache_store.delete(key, options)
           end
         end
+
+        self.class.log_with_time(message, event.duration)
+        event.result
       end
     end
   end

actionpack/lib/action_controller/caching/pages.rb

@@ -62,21 +62,29 @@ module ClassMethods
         #   expire_page "/lists/show"
         def expire_page(path)
           return unless perform_caching
+          path = page_cache_path(path)
 
-          benchmark "Expired page: #{page_cache_file(path)}" do
-            File.delete(page_cache_path(path)) if File.exist?(page_cache_path(path))
+          event = ActiveSupport::Orchestra.instrument(:expire_page, :path => path) do
+            File.delete(path) if File.exist?(path)
           end
+
+          log_with_time("Expired page: #{path}", event.duration)
+          event.result
         end
 
         # Manually cache the +content+ in the key determined by +path+. Example:
         #   cache_page "I'm the cached content", "/lists/show"
         def cache_page(content, path)
           return unless perform_caching
+          path = page_cache_path(path)
 
-          benchmark "Cached page: #{page_cache_file(path)}" do
-            FileUtils.makedirs(File.dirname(page_cache_path(path)))
-            File.open(page_cache_path(path), "wb+") { |f| f.write(content) }
+          event = ActiveSupport::Orchestra.instrument(:cache_page, :path => path) do
+            FileUtils.makedirs(File.dirname(path))
+            File.open(path, "wb+") { |f| f.write(content) }
           end
+
+          log_with_time("Cached page: #{path}", event.duration)
+          event.result
         end
 
         # Caches the +actions+ using the page-caching approach that'll store the cache in a path within the page_cache_directory that
@@ -149,4 +157,4 @@ def caching_allowed
         end
     end
   end
-end
+end

actionpack/lib/action_controller/dispatch/dispatcher.rb

@@ -54,7 +54,7 @@ def define_dispatcher_callbacks(cache_classes)
         end
       end
 
-      delegate :to_prepare, :prepare_dispatch, :before_dispatch, :after_dispatch,
+      delegate :to_prepare, :before_dispatch, :around_dispatch, :after_dispatch,
         :to => ActionDispatch::Callbacks
 
       def new