Instrumenting cache stores.

activesupport/lib/active_support/cache.rb

@@ -107,16 +107,14 @@ def self.expand_cache_key(key, namespace = nil)
     class Store
       cattr_accessor :logger
 
-      attr_reader :silence, :logger_off
+      attr_reader :silence
+      alias :silence? :silence
 
       def silence!
         @silence = true
         self
       end
 
-      alias silence? silence
-      alias logger_off? logger_off
-
       # Fetches data from the cache, using the given key. If there is data in
       # the cache with the given key, then that data is returned.
       #
@@ -157,26 +155,13 @@ def silence!
       #   cache.fetch("foo")  # => "bar"
       #   sleep(6)
       #   cache.fetch("foo")  # => nil
-      def fetch(key, options = {})
-        @logger_off = true
+      def fetch(key, options = {}, &block)
         if !options[:force] && value = read(key, options)
-          @logger_off = false
-          log("hit", key, options)
           value
         elsif block_given?
-          @logger_off = false
-          log("miss", key, options)
-
-          value = nil
-          ms = Benchmark.ms { value = yield }
-
-          @logger_off = true
-          write(key, value, options)
-          @logger_off = false
-
-          log('write (will save %.2fms)' % ms, key, nil)
-
-          value
+          result = instrument(:generate, key, options, &block)
+          write(key, result, options)
+          result
         end
       end
 
@@ -191,8 +176,8 @@ def fetch(key, options = {})
       # For example, FileStore supports the +:expires_in+ option, which
       # makes the method return nil for cache items older than the specified
       # period.
-      def read(key, options = nil)
-        log("read", key, options)
+      def read(key, options = nil, &block)
+        instrument(:read, key, options, &block)
       end
 
       # Writes the given value to the cache, with the given key.
@@ -210,20 +195,20 @@ def read(key, options = nil)
       #   cache.read("foo")  # => "bar"
       #   sleep(6)
       #   cache.read("foo")  # => nil
-      def write(key, value, options = nil)
-        log("write", key, options)
+      def write(key, value, options = nil, &block)
+        instrument(:write, key, options, &block)
       end
 
-      def delete(key, options = nil)
-        log("delete", key, options)
+      def delete(key, options = nil, &block)
+        instrument(:delete, key, options, &block)
       end
 
-      def delete_matched(matcher, options = nil)
-        log("delete matched", matcher.inspect, options)
+      def delete_matched(matcher, options = nil, &block)
+        instrument(:delete_matched, matcher.inspect, options, &block)
       end
 
-      def exist?(key, options = nil)
-        log("exist?", key, options)
+      def exist?(key, options = nil, &block)
+        instrument(:exist?, key, options, &block)
       end
 
       def increment(key, amount = 1)
@@ -247,14 +232,21 @@ def decrement(key, amount = 1)
       private
         def expires_in(options)
           expires_in = options && options[:expires_in]
-
           raise ":expires_in must be a number" if expires_in && !expires_in.is_a?(Numeric)
-
           expires_in || 0
         end
 
+        def instrument(operation, key, options, &block)
+          payload = { :key => key }
+          payload.merge!(options) if options.is_a?(Hash)
+
+          event = ActiveSupport::Orchestra.instrument(:"cache_#{operation}", payload, &block)
+          log("#{operation} (%.1fms)" % event.duration, key, options)
+          event.result
+        end
+
         def log(operation, key, options)
-          logger.debug("Cache #{operation}: #{key}#{options ? " (#{options.inspect})" : ""}") if logger && !silence? && !logger_off?
+          logger.debug("Cache #{operation}: #{key}#{options ? " (#{options.inspect})" : ""}") if logger && !silence?
         end
     end
   end

activesupport/lib/active_support/cache/file_store.rb

@@ -16,49 +16,53 @@ def initialize(cache_path)
       # - +:expires_in+ - the number of seconds that this value may stay in
       #   the cache.
       def read(name, options = nil)
-        super
+        super do
+          file_name = real_file_path(name)
+          expires = expires_in(options)
 
-        file_name = real_file_path(name)
-        expires = expires_in(options)
-
-        if File.exist?(file_name) && (expires <= 0 || Time.now - File.mtime(file_name) < expires)
-          File.open(file_name, 'rb') { |f| Marshal.load(f) }
+          if File.exist?(file_name) && (expires <= 0 || Time.now - File.mtime(file_name) < expires)
+            File.open(file_name, 'rb') { |f| Marshal.load(f) }
+          end
         end
       end
 
       # Writes a value to the cache.
       def write(name, value, options = nil)
-        super
-        ensure_cache_path(File.dirname(real_file_path(name)))
-        File.atomic_write(real_file_path(name), cache_path) { |f| Marshal.dump(value, f) }
-        value
+        super do
+          ensure_cache_path(File.dirname(real_file_path(name)))
+          File.atomic_write(real_file_path(name), cache_path) { |f| Marshal.dump(value, f) }
+          value
+        end
       rescue => e
         logger.error "Couldn't create cache directory: #{name} (#{e.message})" if logger
       end
 
       def delete(name, options = nil)
-        super
-        File.delete(real_file_path(name))
+        super do
+          File.delete(real_file_path(name))
+        end
       rescue SystemCallError => e
         # If there's no cache, then there's nothing to complain about
       end
 
       def delete_matched(matcher, options = nil)
-        super
-        search_dir(@cache_path) do |f|
-          if f =~ matcher
-            begin
-              File.delete(f)
-            rescue SystemCallError => e
-              # If there's no cache, then there's nothing to complain about
+        super do
+          search_dir(@cache_path) do |f|
+            if f =~ matcher
+              begin
+                File.delete(f)
+              rescue SystemCallError => e
+                # If there's no cache, then there's nothing to complain about
+              end
             end
           end
         end
       end
 
       def exist?(name, options = nil)
-        super
-        File.exist?(real_file_path(name))
+        super do
+          File.exist?(real_file_path(name))
+        end
       end
 
       private

activesupport/lib/active_support/cache/mem_cache_store.rb

@@ -54,8 +54,9 @@ def read_multi(*keys)
       end
 
       def read(key, options = nil) # :nodoc:
-        super
-        @data.get(key, raw?(options))
+        super do
+          @data.get(key, raw?(options))
+        end
       rescue MemCache::MemCacheError => e
         logger.error("MemCacheError (#{e}): #{e.message}")
         nil
@@ -69,22 +70,24 @@ def read(key, options = nil) # :nodoc:
       # - <tt>:expires_in</tt> - the number of seconds that this value may stay in
       #   the cache. See ActiveSupport::Cache::Store#write for an example.
       def write(key, value, options = nil)
-        super
-        method = options && options[:unless_exist] ? :add : :set
-        # memcache-client will break the connection if you send it an integer
-        # in raw mode, so we convert it to a string to be sure it continues working.
-        value = value.to_s if raw?(options)
-        response = @data.send(method, key, value, expires_in(options), raw?(options))
-        response == Response::STORED
+        super do
+          method = options && options[:unless_exist] ? :add : :set
+          # memcache-client will break the connection if you send it an integer
+          # in raw mode, so we convert it to a string to be sure it continues working.
+          value = value.to_s if raw?(options)
+          response = @data.send(method, key, value, expires_in(options), raw?(options))
+          response == Response::STORED
+        end
       rescue MemCache::MemCacheError => e
         logger.error("MemCacheError (#{e}): #{e.message}")
         false
       end
 
       def delete(key, options = nil) # :nodoc:
-        super
-        response = @data.delete(key, expires_in(options))
-        response == Response::DELETED
+        super do
+          response = @data.delete(key, expires_in(options))
+          response == Response::DELETED
+        end
       rescue MemCache::MemCacheError => e
         logger.error("MemCacheError (#{e}): #{e.message}")
         false
@@ -94,7 +97,9 @@ def exist?(key, options = nil) # :nodoc:
         # Doesn't call super, cause exist? in memcache is in fact a read
         # But who cares? Reading is very fast anyway
         # Local cache is checked first, if it doesn't know then memcache itself is read from
-        !read(key, options).nil?
+        super do
+          !read(key, options).nil?
+        end
       end
 
       def increment(key, amount = 1) # :nodoc:

activesupport/lib/active_support/cache/memory_store.rb

@@ -20,28 +20,33 @@ def initialize
       end
 
       def read(name, options = nil)
-        super
-        @data[name]
+        super do
+          @data[name]
+        end
       end
 
       def write(name, value, options = nil)
-        super
-        @data[name] = (value.duplicable? ? value.dup : value).freeze
+        super do
+          @data[name] = (value.duplicable? ? value.dup : value).freeze
+        end
       end
 
       def delete(name, options = nil)
-        super
-        @data.delete(name)
+        super do
+          @data.delete(name)
+        end
       end
 
       def delete_matched(matcher, options = nil)
-        super
-        @data.delete_if { |k,v| k =~ matcher }
+        super do
+          @data.delete_if { |k,v| k =~ matcher }
+        end
       end
 
       def exist?(name,options = nil)
-        super
-        @data.has_key?(name)
+        super do
+          @data.has_key?(name)
+        end
       end
 
       def clear