Add Orchestra instrumentation to fragment and page caching.

7 files changed, 65 insertions, 69 deletions

diff --git a/actionpack/lib/abstract_controller.rb b/actionpack/lib/abstract_controller.rb
index cdeb55b915..76c5845f5b 100644
--- a/actionpack/lib/abstract_controller.rb
+++ b/actionpack/lib/abstract_controller.rb
@@ -3,7 +3,6 @@ require "active_support/core_ext/module/delegation"
 
 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"
diff --git a/actionpack/lib/abstract_controller/benchmarker.rb b/actionpack/lib/abstract_controller/benchmarker.rb
deleted file mode 100644
index 58e9564c2f..0000000000
--- a/actionpack/lib/abstract_controller/benchmarker.rb
+++ /dev/null
@@ -1,38 +0,0 @@
-module AbstractController
-  module Benchmarker
-    extend ActiveSupport::Concern
-
-    include Logger
-
-    module ClassMethods
-      # Execute the passed in block, timing the duration of the block in ms.
-      #
-      # ==== Parameters
-      # title<#to_s>:: The title of block to benchmark
-      # log_level<Integer>:: A valid log level. Defaults to Logger::DEBUG
-      # use_silence<TrueClass, FalseClass>:: Whether or not to silence the
-      #   logger for the duration of the block.
-      #
-      # ==== Returns
-      # Object:: The result of the block
-      def benchmark(title, log_level = ::Logger::DEBUG, use_silence = true)
-        if logger && logger.level >= log_level
-          result = nil
-          ms = Benchmark.ms { result = use_silence ? silence { yield } : yield }
-          logger.add(log_level, "#{title} (#{('%.1f' % ms)}ms)")
-          result
-        else
-          yield
-        end
-      end
-
-      # Silences the logger for the duration of the block.
-      def silence
-        old_logger_level, logger.level = logger.level, ::Logger::ERROR if logger
-        yield
-      ensure
-        logger.level = old_logger_level if logger
-      end
-    end
-  end
-end
diff --git a/actionpack/lib/abstract_controller/logger.rb b/actionpack/lib/abstract_controller/logger.rb
index 980e9d2a8b..79444761d3 100644
--- a/actionpack/lib/abstract_controller/logger.rb
+++ b/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,15 +44,10 @@ module AbstractController
       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)
-      event = ActiveSupport::Orchestra.instrument(:process_action,
-                :request => request, :action => action) do
+      event = ActiveSupport::Orchestra.instrument(:process_action, :action => action) do
         super
       end
 
@@ -50,9 +65,9 @@ module AbstractController
     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
diff --git a/actionpack/lib/action_controller/base.rb b/actionpack/lib/action_controller/base.rb
index 0dae68c7b7..f5bd0a00a1 100644
--- a/actionpack/lib/action_controller/base.rb
+++ b/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
 
diff --git a/actionpack/lib/action_controller/caching/fragments.rb b/actionpack/lib/action_controller/caching/fragments.rb
index 4ef600bea0..59e24619e3 100644
--- a/actionpack/lib/action_controller/caching/fragments.rb
+++ b/actionpack/lib/action_controller/caching/fragments.rb
@@ -53,11 +53,11 @@ module ActionController #:nodoc:
         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,10 +66,12 @@ module ActionController #:nodoc:
         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)
@@ -77,10 +79,12 @@ module ActionController #:nodoc:
         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 @@ module ActionController #:nodoc:
       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
diff --git a/actionpack/lib/action_controller/caching/pages.rb b/actionpack/lib/action_controller/caching/pages.rb
index bd3b5a5875..4fb154470f 100644
--- a/actionpack/lib/action_controller/caching/pages.rb
+++ b/actionpack/lib/action_controller/caching/pages.rb
@@ -62,21 +62,29 @@ module ActionController #:nodoc:
         #   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 @@ module ActionController #:nodoc:
         end
     end
   end
-end
\ No newline at end of file
+end
diff --git a/actionpack/test/controller/caching_test.rb b/actionpack/test/controller/caching_test.rb
index 25e035cb49..bd17df73c7 100644
--- a/actionpack/test/controller/caching_test.rb
+++ b/actionpack/test/controller/caching_test.rb
@@ -625,15 +625,20 @@ class FragmentCachingTest < ActionController::TestCase
   def test_fragment_for_logging
     fragment_computed = false
 
-    @controller.class.expects(:benchmark).with('Cached fragment exists?: views/expensive')
-    @controller.class.expects(:benchmark).with('Cached fragment miss: views/expensive')
-    @controller.class.expects(:benchmark).with('Cached fragment hit: views/expensive').never
+    listener = []
+    ActiveSupport::Orchestra.register listener
 
     buffer = 'generated till now -> '
     @controller.fragment_for(buffer, 'expensive') { fragment_computed = true }
 
+    assert_equal 2, listener.size
+    assert_equal :fragment_exist?, listener[0].name
+    assert_equal :write_fragment, listener[1].name
+
     assert fragment_computed
     assert_equal 'generated till now -> ', buffer
+  ensure
+    ActiveSupport::Orchestra.unregister listener
   end
 
 end