Update Orchestra instrumentations and move part of logging to Orchestra.

13 files changed, 72 insertions, 67 deletions

diff --git a/actionpack/lib/abstract_controller/logger.rb b/actionpack/lib/abstract_controller/logger.rb
index f4d017b8e5..cf1a6f1240 100644
--- a/actionpack/lib/abstract_controller/logger.rb
+++ b/actionpack/lib/abstract_controller/logger.rb
@@ -10,14 +10,14 @@ module AbstractController
 
     module ClassMethods #:nodoc:
       # Logs a message appending the value measured.
-      def log_with_time(message, time, log_level=::Logger::DEBUG)
+      def log(message, log_level=::Logger::DEBUG)
         return unless logger && logger.level >= log_level
-        logger.add(log_level, "#{message} (%.1fms)" % time)
+        logger.add(log_level, message)
       end
 
       # Silences the logger for the duration of the block.
       def silence
-        old_logger_level, logger.level = logger.level, ::Logger::ERROR if logge
+        old_logger_level, logger.level = logger.level, ::Logger::ERROR if logger
         yield
       ensure
         logger.level = old_logger_level if logger
@@ -47,7 +47,7 @@ module AbstractController
     # Override process_action in the AbstractController::Base
     # to log details about the method.
     def process_action(action)
-      event = ActiveSupport::Orchestra.instrument(:process_action,
+      result = ActiveSupport::Orchestra.instrument(:process_action,
                 :controller => self, :action => action) do
         super
       end
@@ -56,13 +56,13 @@ module AbstractController
         log = DelayedLog.new do
           "\n\nProcessing #{self.class.name}\##{action_name} " \
           "to #{request.formats} (for #{request_origin}) " \
-          "(%.1fms) [#{request.method.to_s.upcase}]" % event.duration
+          "[#{request.method.to_s.upcase}]"
         end
 
         logger.info(log)
       end
 
-      event.result
+      result
     end
 
   private
diff --git a/actionpack/lib/action_controller/caching/fragments.rb b/actionpack/lib/action_controller/caching/fragments.rb
index 59e24619e3..00fb55f843 100644
--- a/actionpack/lib/action_controller/caching/fragments.rb
+++ b/actionpack/lib/action_controller/caching/fragments.rb
@@ -51,40 +51,32 @@ module ActionController #:nodoc:
       # Writes <tt>content</tt> to the location signified by <tt>key</tt> (see <tt>expire_fragment</tt> for acceptable formats)
       def write_fragment(key, content, options = nil)
         return content unless cache_configured?
-
         key = fragment_cache_key(key)
-        event = ActiveSupport::Orchestra.instrument(:write_fragment, :key => key) do
+
+        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
 
       # Reads a cached fragment from the location signified by <tt>key</tt> (see <tt>expire_fragment</tt> for acceptable formats)
       def read_fragment(key, options = nil)
         return unless cache_configured?
-
         key = fragment_cache_key(key)
-        event = ActiveSupport::Orchestra.instrument(:read_fragment, :key => key) do
+
+        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)
-        event = ActiveSupport::Orchestra.instrument(:fragment_exist?, :key => key) do
+
+        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.
@@ -106,11 +98,10 @@ module ActionController #:nodoc:
       # method (or <tt>delete_matched</tt>, for Regexp keys.)
       def expire_fragment(key, options = nil)
         return unless cache_configured?
-
         key = fragment_cache_key(key) unless key.is_a?(Regexp)
         message = nil
 
-        event = ActiveSupport::Orchestra.instrument(:expire_fragment, :key => key) do
+        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)
@@ -119,9 +110,6 @@ module ActionController #:nodoc:
             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 4fb154470f..72551d1fd6 100644
--- a/actionpack/lib/action_controller/caching/pages.rb
+++ b/actionpack/lib/action_controller/caching/pages.rb
@@ -64,12 +64,9 @@ module ActionController #:nodoc:
           return unless perform_caching
           path = page_cache_path(path)
 
-          event = ActiveSupport::Orchestra.instrument(:expire_page, :path => path) do
+          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:
@@ -78,13 +75,10 @@ module ActionController #:nodoc:
           return unless perform_caching
           path = page_cache_path(path)
 
-          event = ActiveSupport::Orchestra.instrument(:cache_page, :path => path) do
+          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
diff --git a/actionpack/lib/action_controller/instrument.rb b/actionpack/lib/action_controller/instrument.rb
new file mode 100644
index 0000000000..00888c425f
--- /dev/null
+++ b/actionpack/lib/action_controller/instrument.rb
@@ -0,0 +1,6 @@
+require 'active_support/orchestra'
+
+ActiveSupport::Orchestra.subscribe(/(read|write|cache|expire|exist)_(fragment|page)\??/) do |event|
+  human_name = event.name.to_s.humanize
+  ActionController::Base.log("#{human_name} (%.1fms)" % event.duration)
+end
diff --git a/actionpack/lib/action_view/template/template.rb b/actionpack/lib/action_view/template/template.rb
index 0f64c23649..84105bd05d 100644
--- a/actionpack/lib/action_view/template/template.rb
+++ b/actionpack/lib/action_view/template/template.rb
@@ -30,7 +30,7 @@ module ActionView
       ActiveSupport::Orchestra.instrument(:render_template, :identifier => identifier) do
         method_name = compile(locals, view)
         view.send(method_name, locals, &block)
-      end.result
+      end
     rescue Exception => e
       if e.is_a?(TemplateError)
         e.sub_template_of(self)
diff --git a/actionpack/test/controller/caching_test.rb b/actionpack/test/controller/caching_test.rb
index 495b431307..99d7192a9e 100644
--- a/actionpack/test/controller/caching_test.rb
+++ b/actionpack/test/controller/caching_test.rb
@@ -628,20 +628,13 @@ class FragmentCachingTest < ActionController::TestCase
 
   def test_fragment_for_logging
     fragment_computed = false
-
-    listener = []
-    ActiveSupport::Orchestra.register listener
+    ActiveSupport::Orchestra.queue.expects(:publish).times(4)
 
     buffer = 'generated till now -> '
     @controller.fragment_for(buffer, 'expensive') { fragment_computed = true }
 
-    assert_equal 1, listener.count { |e| e.name == :fragment_exist? }
-    assert_equal 1, listener.count { |e| e.name == :write_fragment }
-
     assert fragment_computed
     assert_equal 'generated till now -> ', buffer
-  ensure
-    ActiveSupport::Orchestra.unregister listener
   end
 
 end
diff --git a/activerecord/lib/active_record/base.rb b/activerecord/lib/active_record/base.rb
index 283aa7ddfc..eae59dfad7 100755
--- a/activerecord/lib/active_record/base.rb
+++ b/activerecord/lib/active_record/base.rb
@@ -1,3 +1,4 @@
+require 'benchmark'
 require 'yaml'
 require 'set'
 require 'active_support/dependencies'
@@ -11,6 +12,7 @@ require 'active_support/core_ext/hash/indifferent_access'
 require 'active_support/core_ext/hash/slice'
 require 'active_support/core_ext/string/behavior'
 require 'active_support/core_ext/symbol'
+require 'active_support/core_ext/benchmark'
 require 'active_support/core_ext/object/metaclass'
 
 module ActiveRecord #:nodoc:
diff --git a/activerecord/lib/active_record/connection_adapters/abstract_adapter.rb b/activerecord/lib/active_record/connection_adapters/abstract_adapter.rb
index 694e1e561c..b411fe7526 100755
--- a/activerecord/lib/active_record/connection_adapters/abstract_adapter.rb
+++ b/activerecord/lib/active_record/connection_adapters/abstract_adapter.rb
@@ -1,4 +1,3 @@
-require 'benchmark'
 require 'date'
 require 'bigdecimal'
 require 'bigdecimal/util'
@@ -12,8 +11,6 @@ require 'active_record/connection_adapters/abstract/connection_pool'
 require 'active_record/connection_adapters/abstract/connection_specification'
 require 'active_record/connection_adapters/abstract/query_cache'
 
-require 'active_support/core_ext/benchmark'
-
 module ActiveRecord
   module ConnectionAdapters # :nodoc:
     # ActiveRecord supports multiple database systems. AbstractAdapter and
@@ -33,6 +30,7 @@ module ActiveRecord
       include Quoting, DatabaseStatements, SchemaStatements
       include QueryCache
       include ActiveSupport::Callbacks
+
       define_callbacks :checkout, :checkin
 
       @@row_even = true
@@ -193,6 +191,7 @@ module ActiveRecord
       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(' ')))
@@ -200,13 +199,8 @@ module ActiveRecord
       end
 
       protected
-        def log(sql, name)
-          event = ActiveSupport::Orchestra.instrument(:sql, :sql => sql, :name => name) do
-            yield if block_given?
-          end
-          @runtime += event.duration
-          log_info(sql, name, event.duration)
-          event.result
+        def log(sql, name, &block)
+          ActiveSupport::Orchestra.instrument(:sql, :sql => sql, :name => name, &block)
         rescue Exception => e
           # Log message and raise exception.
           # Set last_verification to 0, so that connection gets verified
diff --git a/activerecord/lib/active_record/instrument.rb b/activerecord/lib/active_record/instrument.rb
new file mode 100644
index 0000000000..06d3e40080
--- /dev/null
+++ b/activerecord/lib/active_record/instrument.rb
@@ -0,0 +1,5 @@
+require 'active_support/orchestra'
+
+ActiveSupport::Orchestra.subscribe("sql") do |event|
+  ActiveRecord::Base.connection.log_info(event.payload[:sql], event.payload[:name], event.duration)
+end
diff --git a/activesupport/lib/active_support/cache.rb b/activesupport/lib/active_support/cache.rb
index a415686020..dfd53462af 100644
--- a/activesupport/lib/active_support/cache.rb
+++ b/activesupport/lib/active_support/cache.rb
@@ -219,7 +219,6 @@ module ActiveSupport
       end
 
       def increment(key, amount = 1)
-        log("incrementing", key, amount)
         if num = read(key)
           write(key, num + amount)
         else
@@ -228,7 +227,6 @@ module ActiveSupport
       end
 
       def decrement(key, amount = 1)
-        log("decrementing", key, amount)
         if num = read(key)
           write(key, num - amount)
         else
@@ -247,13 +245,14 @@ module ActiveSupport
           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
+          # Cache events should be logged or not?
+          # log(operation, key, options)
+          ActiveSupport::Orchestra.instrument(:"cache_#{operation}", payload, &block)
         end
 
         def log(operation, key, options)
-          logger.debug("Cache #{operation}: #{key}#{options ? " (#{options.inspect})" : ""}") if logger && !silence?
+          return unless logger && !silence?
+          logger.debug("Cache #{operation}: #{key}#{options ? " (#{options.inspect})" : ""}")
         end
     end
   end
diff --git a/activesupport/lib/active_support/cache/mem_cache_store.rb b/activesupport/lib/active_support/cache/mem_cache_store.rb
index 516af99ce9..bec9de86ed 100644
--- a/activesupport/lib/active_support/cache/mem_cache_store.rb
+++ b/activesupport/lib/active_support/cache/mem_cache_store.rb
@@ -103,17 +103,20 @@ module ActiveSupport
       end
 
       def increment(key, amount = 1) # :nodoc:
-        log("incrementing", key, amount)
+        response = instrument(:increment, key, :amount => amount) do
+          @data.incr(key, amount)
+        end
 
-        response = @data.incr(key, amount)
         response == Response::NOT_FOUND ? nil : response
       rescue MemCache::MemCacheError
         nil
       end
 
       def decrement(key, amount = 1) # :nodoc:
-        log("decrement", key, amount)
-        response = @data.decr(key, amount)
+        response = instrument(:decrement, key, :amount => amount) do
+          @data.decr(key, amount)
+        end
+
         response == Response::NOT_FOUND ? nil : response
       rescue MemCache::MemCacheError
         nil
diff --git a/activesupport/lib/active_support/orchestra.rb b/activesupport/lib/active_support/orchestra.rb
index 7c9c3074e3..7d4c25669d 100644
--- a/activesupport/lib/active_support/orchestra.rb
+++ b/activesupport/lib/active_support/orchestra.rb
@@ -66,7 +66,7 @@ module ActiveSupport
       def instrument(name, payload={})
         payload[:time]      = Time.now
         payload[:thread_id] = Thread.current.object_id
-        payload[:result]    = yield
+        payload[:result]    = yield if block_given?
       ensure
         payload[:duration] = 1000 * (Time.now.to_f - payload[:time].to_f)
         @publisher.publish(name, payload)
@@ -147,7 +147,7 @@ module ActiveSupport
         end
 
         def publish(name, payload)
-          unless @pattern && name.to_s !~ @pattern
+          unless @pattern && !(@pattern === name.to_s)
             @queue << [name, payload]
           end
         end
diff --git a/activesupport/test/orchestra_test.rb b/activesupport/test/orchestra_test.rb
index 810d99ebeb..7a6e9208b4 100644
--- a/activesupport/test/orchestra_test.rb
+++ b/activesupport/test/orchestra_test.rb
@@ -90,18 +90,39 @@ class OrchestraMainTest < Test::Unit::TestCase
     assert_equal Hash[:payload => "orchestra"], @events.last.payload
   end
 
+  def test_event_is_pushed_even_without_block
+    ActiveSupport::Orchestra.instrument(:awesome, :payload => "orchestra")
+    sleep(0.1)
+
+    assert_equal 1, @events.size
+    assert_equal :awesome, @events.last.name
+    assert_equal Hash[:payload => "orchestra"], @events.last.payload
+  end
+
   def test_subscriber_with_pattern
     @another = []
-    ActiveSupport::Orchestra.subscribe(/cache/) { |event| @another << event }
+    ActiveSupport::Orchestra.subscribe("cache"){ |event| @another << event }
+    ActiveSupport::Orchestra.instrument(:cache){ 1 }
+
+    sleep(0.1)
+
+    assert_equal 1, @another.size
+    assert_equal :cache, @another.first.name
+    assert_equal 1, @another.first.result
+  end
+
+  def test_subscriber_with_pattern_as_regexp
+    @another = []
+    ActiveSupport::Orchestra.subscribe(/cache/){ |event| @another << event }
 
     ActiveSupport::Orchestra.instrument(:something){ 0 }
-    ActiveSupport::Orchestra.instrument(:cache){ 10 }
+    ActiveSupport::Orchestra.instrument(:cache){ 1 }
 
     sleep(0.1)
 
     assert_equal 1, @another.size
     assert_equal :cache, @another.first.name
-    assert_equal 10, @another.first.result
+    assert_equal 1, @another.first.result
   end
 
   def test_with_several_consumers_and_several_events