Merge commit 'jose/orchestra'

21 files changed, 548 insertions, 254 deletions

diff --git a/actionmailer/lib/action_mailer/base.rb b/actionmailer/lib/action_mailer/base.rb
index 065c6c8ba1..b3005c2e5e 100644
--- a/actionmailer/lib/action_mailer/base.rb
+++ b/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,58 +481,62 @@ module ActionMailer #: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
@@ -538,19 +544,21 @@ module ActionMailer #:nodoc:
     # 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
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 06b64d5cb2..f4d017b8e5 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,32 +44,31 @@ 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)
-      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
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/lib/action_controller/dispatch/dispatcher.rb b/actionpack/lib/action_controller/dispatch/dispatcher.rb
index 9ad1cadfd3..ba316b9e63 100644
--- a/actionpack/lib/action_controller/dispatch/dispatcher.rb
+++ b/actionpack/lib/action_controller/dispatch/dispatcher.rb
@@ -54,7 +54,7 @@ module ActionController
         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
diff --git a/actionpack/lib/action_dispatch/middleware/callbacks.rb b/actionpack/lib/action_dispatch/middleware/callbacks.rb
index 0a2b4cf5f7..2f86a382c2 100644
--- a/actionpack/lib/action_dispatch/middleware/callbacks.rb
+++ b/actionpack/lib/action_dispatch/middleware/callbacks.rb
@@ -1,40 +1,55 @@
 module ActionDispatch
   class Callbacks
-    include ActiveSupport::Callbacks
-    define_callbacks :prepare, :before, :after
+    include ActiveSupport::NewCallbacks
+
+    define_callbacks :call, :terminator => "result == false", :scope => :kind
+    define_callbacks :prepare, :scope => :name
+
+    # Add a preparation callback. Preparation callbacks are run before every
+    # request in development mode, and before the first request in production mode.
+    #
+    # If a symbol with a block is given, the symbol is used as an identifier.
+    # That allows to_prepare to be called again with the same identifier to
+    # replace the existing callback. Passing an identifier is a suggested
+    # practice if the code adding a preparation block may be reloaded.
+    def self.to_prepare(*args, &block)
+      if args.first.is_a?(Symbol) && block_given?
+        define_method :"__#{args.first}", &block
+        set_callback(:prepare, :"__#{args.first}")
+      else
+        set_callback(:prepare, *args, &block)
+      end
+    end
+
+    def self.before(*args, &block)
+      set_callback(:call, :before, *args, &block)
+    end
+
+    def self.around(*args, &block)
+      set_callback(:call, :around, *args, &block)
+    end
+
+    def self.after(*args, &block)
+      set_callback(:call, :after, *args, &block)
+    end
 
     class << self
       # DEPRECATED
-      alias_method :prepare_dispatch, :prepare
       alias_method :before_dispatch, :before
+      alias_method :around_dispatch, :around
       alias_method :after_dispatch, :after
     end
 
-    # Add a preparation callback. Preparation callbacks are run before every
-    # request in development mode, and before the first request in production
-    # mode.
-    #
-    # An optional identifier may be supplied for the callback. If provided,
-    # to_prepare may be called again with the same identifier to replace the
-    # existing callback. Passing an identifier is a suggested practice if the
-    # code adding a preparation block may be reloaded.
-    def self.to_prepare(identifier = nil, &block)
-      @prepare_callbacks ||= ActiveSupport::Callbacks::CallbackChain.new
-      callback = ActiveSupport::Callbacks::Callback.new(:prepare, block, :identifier => identifier)
-      @prepare_callbacks.replace_or_append!(callback)
-    end
-
     def initialize(app, prepare_each_request = false)
       @app, @prepare_each_request = app, prepare_each_request
-      run_callbacks :prepare
+      _run_prepare_callbacks
     end
 
     def call(env)
-      run_callbacks :before
-      run_callbacks :prepare if @prepare_each_request
-      @app.call(env)
-    ensure
-      run_callbacks :after, :enumerator => :reverse_each
+      _run_call_callbacks do
+        _run_prepare_callbacks if @prepare_each_request
+        @app.call(env)
+      end
     end
   end
 end
diff --git a/actionpack/lib/action_view/template/template.rb b/actionpack/lib/action_view/template/template.rb
index 7d6964e3e3..80c1bab7d5 100644
--- a/actionpack/lib/action_view/template/template.rb
+++ b/actionpack/lib/action_view/template/template.rb
@@ -27,8 +27,10 @@ module ActionView
     end
     
     def render(view, locals, &block)
-      method_name = compile(locals, view)
-      view.send(method_name, locals, &block)
+      ActiveSupport::Orchestra.instrument(:render_template, :identifier => identifier) do
+        method_name = compile(locals, view)
+        view.send(method_name, locals, &block)
+      end.result
     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 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
diff --git a/actionpack/test/controller/dispatcher_test.rb b/actionpack/test/controller/dispatcher_test.rb
index 9fae1fcf63..150fc83cde 100644
--- a/actionpack/test/controller/dispatcher_test.rb
+++ b/actionpack/test/controller/dispatcher_test.rb
@@ -3,13 +3,16 @@ require 'abstract_unit'
 class DispatcherTest < Test::Unit::TestCase
   Dispatcher = ActionController::Dispatcher
 
+  class Foo
+    cattr_accessor :a, :b
+  end
+
   def setup
     ENV['REQUEST_METHOD'] = 'GET'
 
     # Clear callbacks as they are redefined by Dispatcher#define_dispatcher_callbacks
-    ActionDispatch::Callbacks.instance_variable_set("@prepare_callbacks", ActiveSupport::Callbacks::CallbackChain.new)
-    ActionDispatch::Callbacks.instance_variable_set("@before_callbacks", ActiveSupport::Callbacks::CallbackChain.new)
-    ActionDispatch::Callbacks.instance_variable_set("@after_callbacks", ActiveSupport::Callbacks::CallbackChain.new)
+    ActionDispatch::Callbacks.reset_callbacks(:prepare)
+    ActionDispatch::Callbacks.reset_callbacks(:call)
 
     @old_router, Dispatcher.router = Dispatcher.router, mock()
     Dispatcher.router.stubs(:call).returns([200, {}, 'response'])
@@ -68,13 +71,12 @@ class DispatcherTest < Test::Unit::TestCase
   end
 
   def test_to_prepare_with_identifier_replaces
-    a = b = nil
-    Dispatcher.to_prepare(:unique_id) { |*args| a = b = 1 }
-    Dispatcher.to_prepare(:unique_id) { |*args| a = 2 }
+    Dispatcher.to_prepare(:unique_id) { |*args| Foo.a, Foo.b = 1, 1 }
+    Dispatcher.to_prepare(:unique_id) { |*args| Foo.a = 2 }
 
     dispatch
-    assert_equal 2, a
-    assert_equal nil, b
+    assert_equal 2, Foo.a
+    assert_equal nil, Foo.b
   end
 
   private
diff --git a/activerecord/lib/active_record/connection_adapters/abstract_adapter.rb b/activerecord/lib/active_record/connection_adapters/abstract_adapter.rb
index fab70f34b9..78c7a4b697 100755
--- a/activerecord/lib/active_record/connection_adapters/abstract_adapter.rb
+++ b/activerecord/lib/active_record/connection_adapters/abstract_adapter.rb
@@ -201,16 +201,12 @@ module ActiveRecord
 
       protected
         def log(sql, name)
-          if block_given?
-            result = nil
-            ms = Benchmark.ms { result = yield }
-            @runtime += ms
-            log_info(sql, name, ms)
-            result
-          else
-            log_info(sql, name, 0)
-            nil
+          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
         rescue Exception => e
           # Log message and raise exception.
           # Set last_verification to 0, so that connection gets verified
@@ -221,10 +217,10 @@ module ActiveRecord
           raise translate_exception(e, message)
         end
 
-      def translate_exception(e, message)
-        # override in derived class
-        ActiveRecord::StatementInvalid.new(message)
-      end
+        def translate_exception(e, message)
+          # override in derived class
+          ActiveRecord::StatementInvalid.new(message)
+        end
 
         def format_log_entry(message, dump = nil)
           if ActiveRecord::Base.colorize_logging
diff --git a/activesupport/lib/active_support/autoload.rb b/activesupport/lib/active_support/autoload.rb
index 75706855d6..423d5448c3 100644
--- a/activesupport/lib/active_support/autoload.rb
+++ b/activesupport/lib/active_support/autoload.rb
@@ -17,6 +17,7 @@ module ActiveSupport
   autoload :Multibyte, 'active_support/multibyte'
   autoload :NewCallbacks, 'active_support/new_callbacks'
   autoload :OptionMerger, 'active_support/option_merger'
+  autoload :Orchestra, 'active_support/orchestra'
   autoload :OrderedHash, 'active_support/ordered_hash'
   autoload :OrderedOptions, 'active_support/ordered_options'
   autoload :Rescuable, 'active_support/rescuable'
diff --git a/activesupport/lib/active_support/cache.rb b/activesupport/lib/active_support/cache.rb
index e28df8efa5..25f9555388 100644
--- a/activesupport/lib/active_support/cache.rb
+++ b/activesupport/lib/active_support/cache.rb
@@ -107,16 +107,14 @@ module ActiveSupport
     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 @@ module ActiveSupport
       #   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 @@ module ActiveSupport
       # 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 @@ module ActiveSupport
       #   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 @@ module ActiveSupport
       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
diff --git a/activesupport/lib/active_support/cache/file_store.rb b/activesupport/lib/active_support/cache/file_store.rb
index 75eed5ed94..7521efe7c5 100644
--- a/activesupport/lib/active_support/cache/file_store.rb
+++ b/activesupport/lib/active_support/cache/file_store.rb
@@ -16,49 +16,53 @@ module ActiveSupport
       # - +: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
diff --git a/activesupport/lib/active_support/cache/mem_cache_store.rb b/activesupport/lib/active_support/cache/mem_cache_store.rb
index 7c97b05261..ea38baa9ad 100644
--- a/activesupport/lib/active_support/cache/mem_cache_store.rb
+++ b/activesupport/lib/active_support/cache/mem_cache_store.rb
@@ -54,8 +54,9 @@ module ActiveSupport
       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 @@ module ActiveSupport
       # - <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 @@ module ActiveSupport
         # 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:
diff --git a/activesupport/lib/active_support/cache/memory_store.rb b/activesupport/lib/active_support/cache/memory_store.rb
index 21ba79cf3d..66ce1bc93a 100644
--- a/activesupport/lib/active_support/cache/memory_store.rb
+++ b/activesupport/lib/active_support/cache/memory_store.rb
@@ -20,28 +20,33 @@ module ActiveSupport
       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
diff --git a/activesupport/lib/active_support/new_callbacks.rb b/activesupport/lib/active_support/new_callbacks.rb
index e78a3b2b6f..c56b9ad1ac 100644
--- a/activesupport/lib/active_support/new_callbacks.rb
+++ b/activesupport/lib/active_support/new_callbacks.rb
@@ -295,7 +295,7 @@ module ActiveSupport
           "(#{filter})"
         when Proc
           @klass.send(:define_method, method_name, &filter)
-          return method_name if filter.arity == 0
+          return method_name if filter.arity <= 0
 
           method_name << (filter.arity == 1 ? "(self)" : " self, Proc.new ")
         else
@@ -374,7 +374,7 @@ module ActiveSupport
       #   save
       # end
       #
-      # The _run_set_callback :save,s method can optionally take a key, which
+      # The _run_set_callback :save method can optionally take a key, which
       # will be used to compile an optimized callback method for each
       # key. See #define_callbacks for more information.
       #
diff --git a/activesupport/lib/active_support/orchestra.rb b/activesupport/lib/active_support/orchestra.rb
new file mode 100644
index 0000000000..efe30669d8
--- /dev/null
+++ b/activesupport/lib/active_support/orchestra.rb
@@ -0,0 +1,103 @@
+require 'thread'
+
+module ActiveSupport
+  # Orchestra provides an instrumentation API for Ruby. To instrument an action
+  # in Ruby you just need to:
+  #
+  #   ActiveSupport::Orchestra.instrument(:render, :extra => :information) do
+  #     render :text => "Foo"
+  #   end
+  #
+  # Those actions are consumed by listeners. A listener is anything that responds
+  # to push. You can even register an array:
+  #
+  #   @listener = []
+  #   ActiveSupport::Orchestra.register @listener
+  #
+  #   ActiveSupport::Orchestra.instrument(:render, :extra => :information) do
+  #     render :text => "Foo"
+  #   end
+  #
+  #   event           #=> ActiveSupport::Orchestra::Event
+  #   event.name      #=> :render
+  #   event.duration  #=> 10 (in miliseconds)
+  #   event.result    #=> "Foo"
+  #   event.payload   #=> { :extra => :information }
+  #
+  # Orchestra ships with a default listener implementation which puts events in
+  # a stream and consume them in a Thread. This implementation is thread safe
+  # and is available at ActiveSupport::Orchestra::Listener.
+  #
+  module Orchestra
+    @stacked_events = Hash.new { |h,k| h[k] = [] }
+    @listeners = []
+
+    def self.instrument(name, payload=nil)
+      stack = @stacked_events[Thread.current.object_id]
+      event = Event.new(name, stack.last, payload)
+      stack << event
+      event.result = yield
+      event
+    ensure
+      event.finish!
+      stack.delete(event)
+      @listeners.each { |s| s.push(event) }
+    end
+
+    def self.register(listener)
+      @listeners << listener
+    end
+
+    def self.unregister(listener)
+      @listeners.delete(listener)
+    end
+
+    class Event
+      attr_reader :name, :time, :duration, :parent, :thread_id, :payload
+      attr_accessor :result
+
+      def initialize(name, parent=nil, payload=nil)
+        @name      = name
+        @time      = Time.now
+        @thread_id = Thread.current.object_id
+        @parent    = parent
+        @payload   = payload
+      end
+
+      def finish!
+        @duration = 1000 * (Time.now.to_f - @time.to_f)
+      end
+    end
+
+    class Listener
+      attr_reader :mutex, :signaler, :thread
+
+      def initialize
+        @mutex, @signaler = Mutex.new, ConditionVariable.new
+        @stream = []
+        @thread = Thread.new do
+          loop do
+            (event = @stream.shift) ? consume(event) : wait
+          end
+        end
+      end
+
+      def wait
+        @mutex.synchronize do
+          @signaler.wait(@mutex)
+        end
+      end
+
+      def push(event)
+        @mutex.synchronize do
+          @stream.push(event)
+          @signaler.broadcast
+        end
+      end
+
+      def consume(event)
+        raise NotImplementedError
+      end
+    end
+  end
+end
diff --git a/activesupport/test/orchestra_test.rb b/activesupport/test/orchestra_test.rb
new file mode 100644
index 0000000000..683cc36f6a
--- /dev/null
+++ b/activesupport/test/orchestra_test.rb
@@ -0,0 +1,161 @@
+require 'abstract_unit'
+
+class OrchestraEventTest < Test::Unit::TestCase
+  def setup
+    @parent = ActiveSupport::Orchestra::Event.new(:parent)
+  end
+
+  def test_initialization_with_name_and_parent_and_payload
+    event = ActiveSupport::Orchestra::Event.new(:awesome, @parent, :payload => "orchestra")
+    assert_equal(:awesome, event.name)
+    assert_equal(@parent, event.parent)
+    assert_equal({ :payload => "orchestra" }, event.payload)
+  end
+
+  def test_thread_id_is_set_on_initialization
+    event = ActiveSupport::Orchestra::Event.new(:awesome)
+    assert_equal Thread.current.object_id, event.thread_id
+  end
+
+  def test_current_time_is_set_on_initialization
+    previous_time = Time.now.utc
+    event = ActiveSupport::Orchestra::Event.new(:awesome)
+    assert_kind_of Time, event.time
+    assert event.time.to_f >= previous_time.to_f
+  end
+ 
+  def test_duration_is_set_when_event_finishes
+    event = ActiveSupport::Orchestra::Event.new(:awesome)
+    sleep(0.1)
+    event.finish!
+    assert_in_delta 100, event.duration, 30
+  end
+end
+
+class OrchestraMainTest < Test::Unit::TestCase
+  def setup
+    @listener = []
+    ActiveSupport::Orchestra.register @listener
+  end
+
+  def teardown
+    ActiveSupport::Orchestra.unregister @listener
+  end
+
+  def test_orchestra_allows_any_action_to_be_instrumented
+    event = ActiveSupport::Orchestra.instrument(:awesome, "orchestra") do
+      sleep(0.1)
+    end
+
+    assert_equal :awesome, event.name
+    assert_equal "orchestra", event.payload
+    assert_in_delta 100, event.duration, 30
+  end
+
+  def test_block_result_is_stored
+    event = ActiveSupport::Orchestra.instrument(:awesome, "orchestra") do
+      1 + 1
+    end
+
+    assert_equal 2, event.result
+  end
+
+  def test_events_are_published_to_a_listener
+    event = ActiveSupport::Orchestra.instrument(:awesome, "orchestra") do
+      1 + 1
+    end
+
+    assert_equal 1, @listener.size
+    assert_equal :awesome, @listener.last.name
+    assert_equal "orchestra", @listener.last.payload
+  end
+
+  def test_nested_events_can_be_instrumented
+    ActiveSupport::Orchestra.instrument(:awesome, "orchestra") do
+      ActiveSupport::Orchestra.instrument(:wot, "child") do
+        sleep(0.1)
+      end
+
+      assert_equal 1, @listener.size
+      assert_equal :wot, @listener.first.name
+      assert_equal "child", @listener.first.payload
+
+      assert_nil @listener.first.parent.duration
+      assert_in_delta 100, @listener.first.duration, 30
+    end
+
+    assert_equal 2, @listener.size
+    assert_equal :awesome, @listener.last.name
+    assert_equal "orchestra", @listener.last.payload
+    assert_in_delta 100, @listener.first.parent.duration, 30
+  end
+
+  def test_event_is_pushed_even_if_block_fails
+    ActiveSupport::Orchestra.instrument(:awesome, "orchestra") do
+      raise "OMG"
+    end rescue RuntimeError
+
+    assert_equal 1, @listener.size
+    assert_equal :awesome, @listener.last.name
+    assert_equal "orchestra", @listener.last.payload
+  end
+end
+
+class OrchestraListenerTest < Test::Unit::TestCase
+  class MyListener < ActiveSupport::Orchestra::Listener
+    attr_reader :consumed
+
+    def consume(event)
+      @consumed ||= []
+      @consumed << event
+    end
+  end
+
+  def setup
+    @listener = MyListener.new
+    ActiveSupport::Orchestra.register @listener
+  end
+
+  def teardown
+    ActiveSupport::Orchestra.unregister @listener
+  end
+
+  def test_thread_is_exposed_by_listener
+    assert_kind_of Thread, @listener.thread
+  end
+
+  def test_event_is_consumed_when_an_action_is_instrumented
+    ActiveSupport::Orchestra.instrument(:sum) do
+      1 + 1
+    end
+    sleep 0.1
+    assert_equal 1, @listener.consumed.size
+    assert_equal :sum, @listener.consumed.first.name
+    assert_equal 2, @listener.consumed.first.result
+  end
+
+  def test_with_sevaral_consumers_and_several_events
+    @another = MyListener.new
+    ActiveSupport::Orchestra.register @another
+
+    1.upto(100) do |i|
+      ActiveSupport::Orchestra.instrument(:value) do
+        i
+      end
+    end
+
+    sleep 0.1
+
+    assert_equal 100, @listener.consumed.size
+    assert_equal :value, @listener.consumed.first.name
+    assert_equal 1, @listener.consumed.first.result
+    assert_equal 100, @listener.consumed.last.result
+
+    assert_equal 100, @another.consumed.size
+    assert_equal :value, @another.consumed.first.name
+    assert_equal 1, @another.consumed.first.result
+    assert_equal 100, @another.consumed.last.result
+  ensure
+    ActiveSupport::Orchestra.unregister @another
+  end
+end