From 3c9a37c9c474b9ae2be2cdb73a5ee0c3439d4e5e Mon Sep 17 00:00:00 2001 From: =?UTF-8?q?Jos=C3=A9=20Valim?= Date: Wed, 16 Sep 2009 19:53:49 -0300 Subject: Added Orchestra. --- activesupport/lib/active_support/autoload.rb | 1 + activesupport/lib/active_support/orchestra.rb | 103 ++++++++++++++++ activesupport/test/orchestra_test.rb | 161 ++++++++++++++++++++++++++ 3 files changed, 265 insertions(+) create mode 100644 activesupport/lib/active_support/orchestra.rb create mode 100644 activesupport/test/orchestra_test.rb 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/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 -- cgit v1.2.3 From 8f47f311b7665d74220baf1449b39dc4e70e13e2 Mon Sep 17 00:00:00 2001 From: =?UTF-8?q?Jos=C3=A9=20Valim?= Date: Fri, 18 Sep 2009 08:08:02 -0300 Subject: Instrument process_action, render and sql. --- actionpack/lib/abstract_controller/logger.rb | 11 +++++++---- actionpack/lib/action_view/template/template.rb | 6 ++++-- .../connection_adapters/abstract_adapter.rb | 22 +++++++++------------- 3 files changed, 20 insertions(+), 19 deletions(-) diff --git a/actionpack/lib/abstract_controller/logger.rb b/actionpack/lib/abstract_controller/logger.rb index 06b64d5cb2..980e9d2a8b 100644 --- a/actionpack/lib/abstract_controller/logger.rb +++ b/actionpack/lib/abstract_controller/logger.rb @@ -31,19 +31,22 @@ module AbstractController # 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, + :request => request, :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 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/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 -- cgit v1.2.3 From 7cc1c2e71da1ad277acc7a7664321d2224a56bb8 Mon Sep 17 00:00:00 2001 From: =?UTF-8?q?Jos=C3=A9=20Valim?= Date: Sat, 19 Sep 2009 12:31:47 -0300 Subject: Add Orchestra instrumentation to fragment and page caching. --- actionpack/lib/abstract_controller.rb | 1 - actionpack/lib/abstract_controller/benchmarker.rb | 38 ---------------------- actionpack/lib/abstract_controller/logger.rb | 31 +++++++++++++----- actionpack/lib/action_controller/base.rb | 1 - .../lib/action_controller/caching/fragments.rb | 32 +++++++++++------- actionpack/lib/action_controller/caching/pages.rb | 20 ++++++++---- actionpack/test/controller/caching_test.rb | 11 +++++-- 7 files changed, 65 insertions(+), 69 deletions(-) delete mode 100644 actionpack/lib/abstract_controller/benchmarker.rb 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:: A valid log level. Defaults to Logger::DEBUG - # use_silence:: 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 key exists (see expire_fragment 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 -- cgit v1.2.3 From a0233dd3b21416e62be82f9b1b81258d985633bb Mon Sep 17 00:00:00 2001 From: =?UTF-8?q?Jos=C3=A9=20Valim?= Date: Sun, 20 Sep 2009 10:09:08 -0300 Subject: Use NewCallbacks on ActionDispatch::Callbacks. --- actionpack/lib/abstract_controller/logger.rb | 3 +- .../lib/action_controller/dispatch/dispatcher.rb | 2 +- .../lib/action_dispatch/middleware/callbacks.rb | 61 ++++++++++++++-------- actionpack/test/controller/dispatcher_test.rb | 18 ++++--- activesupport/lib/active_support/new_callbacks.rb | 4 +- 5 files changed, 53 insertions(+), 35 deletions(-) diff --git a/actionpack/lib/abstract_controller/logger.rb b/actionpack/lib/abstract_controller/logger.rb index 79444761d3..f4d017b8e5 100644 --- a/actionpack/lib/abstract_controller/logger.rb +++ b/actionpack/lib/abstract_controller/logger.rb @@ -47,7 +47,8 @@ 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, :action => action) do + event = ActiveSupport::Orchestra.instrument(:process_action, + :controller => self, :action => action) do super 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/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/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. # -- cgit v1.2.3 From 09f798ba18029363378d80b19f9f88a055c44bb2 Mon Sep 17 00:00:00 2001 From: =?UTF-8?q?Jos=C3=A9=20Valim?= Date: Sun, 20 Sep 2009 11:09:17 -0300 Subject: Instrument create and deliver in ActionMailer. --- actionmailer/lib/action_mailer/base.rb | 120 ++++++++++++++++++--------------- 1 file changed, 64 insertions(+), 56 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 -- cgit v1.2.3 From 4215e9ab936efca915ca998273d2fc0c46bb59b8 Mon Sep 17 00:00:00 2001 From: =?UTF-8?q?Jos=C3=A9=20Valim?= Date: Sun, 20 Sep 2009 12:07:21 -0300 Subject: Instrumenting cache stores. --- activesupport/lib/active_support/cache.rb | 60 ++++++++++------------ .../lib/active_support/cache/file_store.rb | 46 +++++++++-------- .../lib/active_support/cache/mem_cache_store.rb | 31 ++++++----- .../lib/active_support/cache/memory_store.rb | 25 +++++---- 4 files changed, 84 insertions(+), 78 deletions(-) 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 # - :expires_in - 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 -- cgit v1.2.3