From 561885aea28c9422fbdfb2be54220b10d4911973 Mon Sep 17 00:00:00 2001 From: =?UTF-8?q?Jos=C3=A9=20Valim?= Date: Fri, 25 Dec 2009 12:32:16 +0100 Subject: [PATCH 1/8] String#<< should work for any object which responds to :to_str, so enable this without the performance hit and make Fixnum safe by default. --- .../core_ext/string/output_safety.rb | 12 ++++++++++ .../test/core_ext/string_ext_test.rb | 24 +++++++++++++++++++ 2 files changed, 36 insertions(+) diff --git a/activesupport/lib/active_support/core_ext/string/output_safety.rb b/activesupport/lib/active_support/core_ext/string/output_safety.rb index 3e6ab0ebd2..ceed90ce79 100644 --- a/activesupport/lib/active_support/core_ext/string/output_safety.rb +++ b/activesupport/lib/active_support/core_ext/string/output_safety.rb @@ -1,3 +1,15 @@ +class Object + def html_safe? + false + end +end + +class Fixnum + def html_safe? + true + end +end + class String attr_accessor :_rails_html_safe alias html_safe? _rails_html_safe diff --git a/activesupport/test/core_ext/string_ext_test.rb b/activesupport/test/core_ext/string_ext_test.rb index 56ed296dac..6ed209f724 100644 --- a/activesupport/test/core_ext/string_ext_test.rb +++ b/activesupport/test/core_ext/string_ext_test.rb @@ -350,6 +350,24 @@ class OutputSafetyTest < ActiveSupport::TestCase assert_equal @string, @string.html_safe! end + test "A fixnum is safe by default" do + assert 5.html_safe? + end + + test "An object is unsafe by default" do + klass = Class.new(Object) do + def to_str + "other" + end + end + + @string.html_safe! + @string << klass.new + + assert_equal "helloother", @string + assert !@string.html_safe? + end + test "Adding a safe string to another safe string returns a safe string" do @other_string = "other".html_safe! @string.html_safe! @@ -416,4 +434,10 @@ class OutputSafetyTest < ActiveSupport::TestCase @other_string << @string assert @other_string.html_safe? end + + test "Concatting a fixnum to safe always yields safe" do + @string.html_safe! + @string.concat(13) + assert @string.html_safe? + end end From 48273a44c6176b72e432f365c7905fd8c4d4b754 Mon Sep 17 00:00:00 2001 From: =?UTF-8?q?Jos=C3=A9=20Valim?= Date: Fri, 25 Dec 2009 20:25:18 +0100 Subject: [PATCH 2/8] Wrap layout rendering in one method: _render_layout (this should make partial instrumentation easier). --- actionpack/lib/action_view/render/partials.rb | 2 +- actionpack/lib/action_view/render/rendering.rb | 12 ++++++------ 2 files changed, 7 insertions(+), 7 deletions(-) diff --git a/actionpack/lib/action_view/render/partials.rb b/actionpack/lib/action_view/render/partials.rb index aeaf1ee4ff..00b12ad3a9 100644 --- a/actionpack/lib/action_view/render/partials.rb +++ b/actionpack/lib/action_view/render/partials.rb @@ -274,7 +274,7 @@ module ActionView if @block || !options[:layout] content else - find_template(options[:layout]).render(@view, @locals) { content } + @view._render_layout(find_template(options[:layout]), @locals){ content } end end diff --git a/actionpack/lib/action_view/render/rendering.rb b/actionpack/lib/action_view/render/rendering.rb index d4d16b4d98..c4033fad9e 100644 --- a/actionpack/lib/action_view/render/rendering.rb +++ b/actionpack/lib/action_view/render/rendering.rb @@ -73,7 +73,6 @@ module ActionView # would be Hello David. def _layout_for(name = nil, &block) return @_content_for[name || :layout] if !block_given? || name - capture(&block) end @@ -88,10 +87,7 @@ module ActionView end def _render_text(content, layout, locals) - content = layout.render(self, locals) do |*name| - _layout_for(*name) { content } - end if layout - + content = _render_layout(layout, locals){ content } if layout content end @@ -121,10 +117,14 @@ module ActionView if layout @_layout = layout.identifier logger.info("Rendering template within #{layout.inspect}") if logger - content = layout.render(self, locals) { |*name| _layout_for(*name) } + content = _render_layout(layout, locals) end content end + + def _render_layout(layout, locals, &block) + layout.render(self, locals){ |*name| _layout_for(*name, &block) } + end end end From c86424a72d229c519179a6cdf1d37e93b46e1e38 Mon Sep 17 00:00:00 2001 From: =?UTF-8?q?Jos=C3=A9=20Valim?= Date: Fri, 25 Dec 2009 23:37:16 +0100 Subject: [PATCH 3/8] Break instrumentation into several end-points so rendering of partials can be optimized. --- actionpack/lib/action_view/render/partials.rb | 42 ++++++++++--------- .../lib/action_view/render/rendering.rb | 24 +++++++---- actionpack/lib/action_view/template.rb | 6 +-- 3 files changed, 42 insertions(+), 30 deletions(-) diff --git a/actionpack/lib/action_view/render/partials.rb b/actionpack/lib/action_view/render/partials.rb index 00b12ad3a9..04edb9ab44 100644 --- a/actionpack/lib/action_view/render/partials.rb +++ b/actionpack/lib/action_view/render/partials.rb @@ -205,11 +205,22 @@ module ActionView end def render + options = @options + if @collection = collection - render_collection + ActiveSupport::Notifications.instrument(:render_collection, :path => @path, + :count => @collection.size) do + render_collection + end else - @template = template = find_template - render_template(template, @object || @locals[template.variable_name]) + content = ActiveSupport::Notifications.instrument(:render_partial, :path => @path) do + render_partial + end + + if !@block && options[:layout] + content = @view._render_layout(find_template(options[:layout]), @locals){ content } + end + content end end @@ -227,9 +238,7 @@ module ActionView end def collection_with_template(template) - options = @options - - segments, locals, as = [], @locals, options[:as] || template.variable_name + segments, locals, as = [], @locals, @options[:as] || template.variable_name counter_name = template.counter_name locals[counter_name] = -1 @@ -246,9 +255,7 @@ module ActionView end def collection_without_template - options = @options - - segments, locals, as = [], @locals, options[:as] + segments, locals, as = [], @locals, @options[:as] index, template = -1, nil @collection.each do |object| @@ -263,18 +270,15 @@ module ActionView segments end - def render_template(template, object = @object) - options, locals, view = @options, @locals, @view - locals[options[:as] || template.variable_name] = object + def render_partial(object = @object) + @template = template = find_template + locals, view = @locals, @view - content = template.render(view, locals) do |*name| - @view._layout_for(*name, &@block) - end + object ||= locals[template.variable_name] + locals[@options[:as] || template.variable_name] = object - if @block || !options[:layout] - content - else - @view._render_layout(find_template(options[:layout]), @locals){ content } + template.render(view, locals) do |*name| + view._layout_for(*name, &@block) end end diff --git a/actionpack/lib/action_view/render/rendering.rb b/actionpack/lib/action_view/render/rendering.rb index c4033fad9e..5e7dd3e2df 100644 --- a/actionpack/lib/action_view/render/rendering.rb +++ b/actionpack/lib/action_view/render/rendering.rb @@ -77,16 +77,19 @@ module ActionView end def _render_inline(inline, layout, options) - handler = Template.handler_class_for_extension(options[:type] || "erb") - template = Template.new(options[:inline], "inline template", handler, {}) + locals = options[:locals] - locals = options[:locals] - content = template.render(self, locals) + content = ActiveSupport::Notifications.instrument(:render_inline) do + handler = Template.handler_class_for_extension(options[:type] || "erb") + template = Template.new(options[:inline], "inline template", handler, {}) + template.render(self, locals) + end _render_text(content, layout, locals) end def _render_text(content, layout, locals) + ActiveSupport::Notifications.instrument(:render_text) content = _render_layout(layout, locals){ content } if layout content end @@ -110,8 +113,13 @@ module ActionView msg end - locals = options[:locals] || {} - content = partial ? _render_partial_object(template, options) : template.render(self, locals) + locals = options[:locals] || {} + + content = ActiveSupport::Notifications.instrument(:render_template, + :identifier => template.identifier, :layout => (layout ? layout.identifier : nil)) do + partial ? _render_partial_object(template, options) : template.render(self, locals) + end + @_content_for[:layout] = content if layout @@ -124,7 +132,9 @@ module ActionView end def _render_layout(layout, locals, &block) - layout.render(self, locals){ |*name| _layout_for(*name, &block) } + ActiveSupport::Notifications.instrument(:render_layout, :identifier => layout.identifier) do + layout.render(self, locals){ |*name| _layout_for(*name, &block) } + end end end end diff --git a/actionpack/lib/action_view/template.rb b/actionpack/lib/action_view/template.rb index d46c989d11..adaf6544a7 100644 --- a/actionpack/lib/action_view/template.rb +++ b/actionpack/lib/action_view/template.rb @@ -36,10 +36,8 @@ module ActionView end def render(view, locals, &block) - ActiveSupport::Notifications.instrument(:render_template, :identifier => identifier) do - method_name = compile(locals, view) - view.send(method_name, locals, &block) - end + method_name = compile(locals, view) + view.send(method_name, locals, &block) rescue Exception => e if e.is_a?(Template::Error) e.sub_template_of(self) From ff1a1c0b4d08567e8aeaef698003b5cd96d79686 Mon Sep 17 00:00:00 2001 From: =?UTF-8?q?Jos=C3=A9=20Valim?= Date: Sat, 26 Dec 2009 11:02:41 +0100 Subject: [PATCH 4/8] Optimize <%= render(@posts) %>. --- actionpack/lib/action_view/render/partials.rb | 18 ++++++++++++++---- 1 file changed, 14 insertions(+), 4 deletions(-) diff --git a/actionpack/lib/action_view/render/partials.rb b/actionpack/lib/action_view/render/partials.rb index 04edb9ab44..eb035ae2dd 100644 --- a/actionpack/lib/action_view/render/partials.rb +++ b/actionpack/lib/action_view/render/partials.rb @@ -233,7 +233,17 @@ module ActionView spacer = find_template(@options[:spacer_template]).render(@view, @locals) end - result = template ? collection_with_template(template) : collection_without_template + result = if template + collection_with_template(template) + else + paths = @collection.map { |o| partial_path(o) } + + if paths.uniq.size == 1 + collection_with_template(find_template(paths.first)) + else + collection_without_template(paths) + end + end result.join(spacer).html_safe! end @@ -254,12 +264,12 @@ module ActionView segments end - def collection_without_template + def collection_without_template(collection_paths) segments, locals, as = [], @locals, @options[:as] index, template = -1, nil - @collection.each do |object| - template = find_template(partial_path(object)) + @collection.each_with_index do |object, i| + template = find_template(collection_paths[i]) locals[template.counter_name] = (index += 1) locals[template.variable_name] = object From 8a36e907d2a0a28be1fa8334221cc2e195d75168 Mon Sep 17 00:00:00 2001 From: =?UTF-8?q?Jos=C3=A9=20Valim?= Date: Sat, 26 Dec 2009 12:43:48 +0100 Subject: [PATCH 5/8] More <%= render(@posts) %> optimization. --- actionpack/lib/action_view/render/partials.rb | 44 +++++++++---------- 1 file changed, 20 insertions(+), 24 deletions(-) diff --git a/actionpack/lib/action_view/render/partials.rb b/actionpack/lib/action_view/render/partials.rb index eb035ae2dd..5158415c20 100644 --- a/actionpack/lib/action_view/render/partials.rb +++ b/actionpack/lib/action_view/render/partials.rb @@ -191,23 +191,30 @@ module ActionView def setup(options, block) partial = options[:partial] - @options = options - @locals = options[:locals] || {} - @block = block + @options = options + @locals = options[:locals] || {} + @block = block if String === partial - @object = options[:object] - @path = partial + @object = options[:object] + @path = partial + @collection = collection else @object = partial - @path = partial_path(partial) + + if @collection = collection + paths = @collection_paths = @collection.map { |o| partial_path(o) } + @path = paths.uniq.size == 1 ? paths.first : nil + else + @path = partial_path + end end end def render options = @options - if @collection = collection + if @collection ActiveSupport::Notifications.instrument(:render_collection, :path => @path, :count => @collection.size) do render_collection @@ -226,28 +233,17 @@ module ActionView def render_collection @template = template = find_template - return nil if @collection.blank? if @options.key?(:spacer_template) spacer = find_template(@options[:spacer_template]).render(@view, @locals) end - result = if template - collection_with_template(template) - else - paths = @collection.map { |o| partial_path(o) } - - if paths.uniq.size == 1 - collection_with_template(find_template(paths.first)) - else - collection_without_template(paths) - end - end + result = template ? collection_with_template : collection_without_template result.join(spacer).html_safe! end - def collection_with_template(template) + def collection_with_template(template = @template) segments, locals, as = [], @locals, @options[:as] || template.variable_name counter_name = template.counter_name @@ -264,14 +260,14 @@ module ActionView segments end - def collection_without_template(collection_paths) + def collection_without_template(collection_paths = @collection_paths) segments, locals, as = [], @locals, @options[:as] index, template = -1, nil @collection.each_with_index do |object, i| template = find_template(collection_paths[i]) locals[template.counter_name] = (index += 1) - locals[template.variable_name] = object + locals[as || template.variable_name] = object segments << template.render(@view, locals) end @@ -319,9 +315,9 @@ module ActionView def partial_path(object = @object) @partial_names[object.class] ||= begin - return nil unless object.respond_to?(:to_model) + object = object.to_model if object.respond_to?(:to_model) - object.to_model.class.model_name.partial_path.dup.tap do |partial| + object.class.model_name.partial_path.dup.tap do |partial| path = @view.controller_path partial.insert(0, "#{File.dirname(path)}/") if path.include?(?/) end From 75ba102a80965b2612df0253d1278581a88b8d66 Mon Sep 17 00:00:00 2001 From: =?UTF-8?q?Jos=C3=A9=20Valim?= Date: Sat, 26 Dec 2009 20:28:53 +0100 Subject: [PATCH 6/8] Remove ActionView inline logging to ActiveSupport::Notifications and create ActionController::Base#log_event, so everything can be logged within one listener. Also expose log_process_action as a hook for different modules to include their own information during the action processing. This allow ActiveRecord to hook and any other ORM. Finally, this commit changes 'Processing' and 'Rendering' in logs to 'Processed' and 'Rendered' because at the point it's logged, everying already happened. --- actionpack/lib/abstract_controller/logger.rb | 20 ----- actionpack/lib/action_controller/base.rb | 1 - actionpack/lib/action_controller/caching.rb | 11 +++ .../action_controller/caching/fragments.rb | 2 +- .../metal/active_record_runtime.rb | 27 ++++++ .../action_controller/metal/benchmarking.rb | 72 ---------------- .../metal/filter_parameter_logging.rb | 24 +++--- .../lib/action_controller/metal/logger.rb | 82 ++++++++++++++----- actionpack/lib/action_controller/rails.rb | 13 +-- .../lib/action_view/render/rendering.rb | 9 +- actionpack/test/abstract_unit.rb | 23 ++++++ actionpack/test/controller/base_test.rb | 7 -- actionpack/test/controller/benchmark_test.rb | 33 -------- actionpack/test/controller/caching_test.rb | 2 +- .../test/controller/filter_params_test.rb | 2 +- actionpack/test/controller/logging_test.rb | 68 ++++++++++----- actionpack/test/controller/render_test.rb | 32 +------- activerecord/lib/active_record/rails.rb | 4 +- .../notifications/instrumenter.rb | 11 ++- activesupport/test/notifications_test.rb | 22 +++-- 20 files changed, 205 insertions(+), 260 deletions(-) create mode 100644 actionpack/lib/action_controller/metal/active_record_runtime.rb delete mode 100644 actionpack/lib/action_controller/metal/benchmarking.rb delete mode 100644 actionpack/test/controller/benchmark_test.rb diff --git a/actionpack/lib/abstract_controller/logger.rb b/actionpack/lib/abstract_controller/logger.rb index e3bcd28da7..a23a13e1d6 100644 --- a/actionpack/lib/abstract_controller/logger.rb +++ b/actionpack/lib/abstract_controller/logger.rb @@ -9,25 +9,5 @@ module AbstractController cattr_accessor :logger extend ActiveSupport::Benchmarkable 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 - # entire processed String to the logger, which might - # just discard the String if the log level is too low. - # - # TODO: Require that Rails loggers accept a block. - class DelayedLog < ActiveSupport::BasicObject - def initialize(&block) - @str, @block = nil, block - end - - def method_missing(*args, &block) - unless @str - @str, @block = @block.call, nil - end - @str.send(*args, &block) - end - end end end diff --git a/actionpack/lib/action_controller/base.rb b/actionpack/lib/action_controller/base.rb index dbba69f637..67656110c4 100644 --- a/actionpack/lib/action_controller/base.rb +++ b/actionpack/lib/action_controller/base.rb @@ -15,7 +15,6 @@ module ActionController include ActionController::ConditionalGet include ActionController::RackDelegation include ActionController::Logger - include ActionController::Benchmarking include ActionController::Configuration # Legacy modules diff --git a/actionpack/lib/action_controller/caching.rb b/actionpack/lib/action_controller/caching.rb index d784138ebe..69ed84da95 100644 --- a/actionpack/lib/action_controller/caching.rb +++ b/actionpack/lib/action_controller/caching.rb @@ -60,6 +60,17 @@ module ActionController #:nodoc: def cache_configured? perform_caching && cache_store end + + def log_event(name, before, after, instrumenter_id, payload) + if name.to_s =~ /(read|write|cache|expire|exist)_(fragment|page)\??/ + key_or_path = payload[:key] || payload[:path] + human_name = name.to_s.humanize + duration = (after - before) * 1000 + logger.info("#{human_name} #{key_or_path.inspect} (%.1fms)" % duration) + else + super + end + end end def caching_allowed? diff --git a/actionpack/lib/action_controller/caching/fragments.rb b/actionpack/lib/action_controller/caching/fragments.rb index 8c1167d526..f569d0dd8b 100644 --- a/actionpack/lib/action_controller/caching/fragments.rb +++ b/actionpack/lib/action_controller/caching/fragments.rb @@ -74,7 +74,7 @@ module ActionController #:nodoc: return unless cache_configured? key = fragment_cache_key(key) - ActiveSupport::Notifications.instrument(:fragment_exist?, :key => key) do + ActiveSupport::Notifications.instrument(:exist_fragment?, :key => key) do cache_store.exist?(key, options) end end diff --git a/actionpack/lib/action_controller/metal/active_record_runtime.rb b/actionpack/lib/action_controller/metal/active_record_runtime.rb new file mode 100644 index 0000000000..29f6dcc783 --- /dev/null +++ b/actionpack/lib/action_controller/metal/active_record_runtime.rb @@ -0,0 +1,27 @@ +module ActionController + module ActiveRecordRuntime + extend ActiveSupport::Concern + + attr_internal :db_runtime + + def cleanup_view_runtime + if Object.const_defined?("ActiveRecord") && ActiveRecord::Base.connected? + db_rt_before_render = ActiveRecord::Base.connection.reset_runtime + runtime = super + db_rt_after_render = ActiveRecord::Base.connection.reset_runtime + self.db_runtime = db_rt_before_render + db_rt_after_render + runtime - db_rt_after_render + else + super + end + end + + module ClassMethods + def process_log_action(controller) + super + db_runtime = controller.send :db_runtime + logger.info(" ActiveRecord runtime: %.1fms" % db_runtime.to_f) if db_runtime + end + end + end +end \ No newline at end of file diff --git a/actionpack/lib/action_controller/metal/benchmarking.rb b/actionpack/lib/action_controller/metal/benchmarking.rb deleted file mode 100644 index f73f635b0d..0000000000 --- a/actionpack/lib/action_controller/metal/benchmarking.rb +++ /dev/null @@ -1,72 +0,0 @@ -require 'active_support/core_ext/benchmark' - -module ActionController #:nodoc: - # The benchmarking module times the performance of actions and reports to the logger. If the Active Record - # package has been included, a separate timing section for database calls will be added as well. - module Benchmarking #:nodoc: - extend ActiveSupport::Concern - - protected - def render(*args, &block) - if logger - if Object.const_defined?("ActiveRecord") && ActiveRecord::Base.connected? - db_runtime = ActiveRecord::Base.connection.reset_runtime - end - - render_output = nil - @view_runtime = Benchmark.ms { render_output = super } - - if Object.const_defined?("ActiveRecord") && ActiveRecord::Base.connected? - @db_rt_before_render = db_runtime - @db_rt_after_render = ActiveRecord::Base.connection.reset_runtime - @view_runtime -= @db_rt_after_render - end - - render_output - else - super - end - end - - private - def process_action(*args) - if logger - ms = [Benchmark.ms { super }, 0.01].max - logging_view = defined?(@view_runtime) - logging_active_record = Object.const_defined?("ActiveRecord") && ActiveRecord::Base.connected? - - log_message = 'Completed in %.0fms' % ms - - if logging_view || logging_active_record - log_message << " (" - log_message << view_runtime if logging_view - - if logging_active_record - log_message << ", " if logging_view - log_message << active_record_runtime + ")" - else - ")" - end - end - - log_message << " | #{response.status}" - log_message << " [#{complete_request_uri rescue "unknown"}]" - - logger.info(log_message) - else - super - end - end - - def view_runtime - "View: %.0f" % @view_runtime - end - - def active_record_runtime - db_runtime = ActiveRecord::Base.connection.reset_runtime - db_runtime += @db_rt_before_render if @db_rt_before_render - db_runtime += @db_rt_after_render if @db_rt_after_render - "DB: %.0f" % db_runtime - end - end -end diff --git a/actionpack/lib/action_controller/metal/filter_parameter_logging.rb b/actionpack/lib/action_controller/metal/filter_parameter_logging.rb index a53c052075..59e200396a 100644 --- a/actionpack/lib/action_controller/metal/filter_parameter_logging.rb +++ b/actionpack/lib/action_controller/metal/filter_parameter_logging.rb @@ -2,8 +2,6 @@ module ActionController module FilterParameterLogging extend ActiveSupport::Concern - include AbstractController::Logger - module ClassMethods # Replace sensitive parameter data from the request log. # Filters parameters that have any of the arguments as a substring. @@ -54,23 +52,25 @@ module ActionController end protected :filter_parameters end + + protected + + # Overwrite log_process_action to include parameters information. + # If this method is invoked, it means logger is defined, so don't + # worry with such scenario here. + def log_process_action(controller) #:nodoc: + params = controller.send(:filter_parameters, controller.request.params) + logger.info " Parameters: #{params.inspect}" unless params.empty? + super + end end INTERNAL_PARAMS = [:controller, :action, :format, :_method, :only_path] - def process(*) - response = super - if logger - parameters = filter_parameters(params).except!(*INTERNAL_PARAMS) - logger.info { " Parameters: #{parameters.inspect}" } unless parameters.empty? - end - response - end - protected def filter_parameters(params) - params.dup + params.dup.except!(*INTERNAL_PARAMS) end end diff --git a/actionpack/lib/action_controller/metal/logger.rb b/actionpack/lib/action_controller/metal/logger.rb index 956d7dd371..5d14f6c9c9 100644 --- a/actionpack/lib/action_controller/metal/logger.rb +++ b/actionpack/lib/action_controller/metal/logger.rb @@ -1,34 +1,74 @@ require 'abstract_controller/logger' module ActionController + # Adds instrumentation to process_action and a log_event method + # responsible to log events from ActiveSupport::Notifications. This module handles + # :process_action and :render_template events but allows any other module to hook + # into log_event and provide its own logging facilities (as in ActionController::Caching). module Logger - # Override process_action in the AbstractController::Base - # to log details about the method. + extend ActiveSupport::Concern + + attr_internal :view_runtime + def process_action(action) - result = ActiveSupport::Notifications.instrument(:process_action, - :controller => self, :action => action) do + ActiveSupport::Notifications.instrument(:process_action, :controller => self, :action => action) do super end - - if logger - log = AbstractController::Logger::DelayedLog.new do - "\n\nProcessing #{self.class.name}\##{action_name} " \ - "to #{request.formats} (for #{request_origin}) " \ - "[#{request.method.to_s.upcase}]" - end - - logger.info(log) - end - - result end - private + def render(*args, &block) + if logger + render_output = nil - # 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 - @request_origin ||= "#{request.remote_ip} at #{Time.now.to_s(:db)}" + self.view_runtime = cleanup_view_runtime do + Benchmark.ms { render_output = super } + end + + render_output + else + super + end + end + + def cleanup_view_runtime + yield + end + + module ClassMethods + def log_event(name, before, after, instrumenter_id, payload) + if name == :process_action + duration = [(after - before) * 1000, 0.01].max + controller = payload[:controller] + request = controller.request + + logger.info "\n\nProcessed #{controller.class.name}##{payload[:action]} " \ + "to #{request.formats} (for #{request.remote_ip} at #{before.to_s(:db)}) " \ + "[#{request.method.to_s.upcase}]" + + log_process_action(controller) + + message = "Completed in %.0fms" % duration + message << " | #{controller.response.status}" + message << " [#{request.request_uri rescue "unknown"}]" + + logger.info(message) + elsif name == :render_template + # TODO Make render_template logging work if you are using just ActionView + duration = (after - before) * 1000 + message = "Rendered #{payload[:identifier]}" + message << " within #{payload[:layout]}" if payload[:layout] + message << (" (%.1fms)" % duration) + logger.info(message) + end + end + + protected + + # A hook which allows logging what happened during controller process action. + def log_process_action(controller) #:nodoc: + view_runtime = controller.send :view_runtime + logger.info(" View runtime: %.1fms" % view_runtime.to_f) if view_runtime + end end end end diff --git a/actionpack/lib/action_controller/rails.rb b/actionpack/lib/action_controller/rails.rb index 36a52b3149..e381828ee4 100644 --- a/actionpack/lib/action_controller/rails.rb +++ b/actionpack/lib/action_controller/rails.rb @@ -14,10 +14,6 @@ module ActionController end # Routing must be initialized after plugins to allow the former to extend the routes - # --- - # If Action Controller is not one of the loaded frameworks (Configuration#frameworks) - # this does nothing. Otherwise, it loads the routing definitions and sets up - # loading module used to lazily load controllers (Configuration#controller_paths). initializer "action_controller.initialize_routing" do |app| app.route_configuration_files << app.config.routes_configuration_file app.route_configuration_files << app.config.builtin_routes_configuration_file @@ -88,13 +84,8 @@ module ActionController initializer "action_controller.notifications" do |app| require 'active_support/notifications' - ActiveSupport::Notifications.subscribe(/(read|write|cache|expire|exist)_(fragment|page)\??/) do |*args| - event = ActiveSupport::Notifications::Event.new(*args) - - if logger = ActionController::Base.logger - human_name = event.name.to_s.humanize - logger.info("#{human_name} (%.1fms)" % event.duration) - end + ActiveSupport::Notifications.subscribe do |*args| + ActionController::Base.log_event(*args) if ActionController::Base.logger end end diff --git a/actionpack/lib/action_view/render/rendering.rb b/actionpack/lib/action_view/render/rendering.rb index 5e7dd3e2df..0302e44b4e 100644 --- a/actionpack/lib/action_view/render/rendering.rb +++ b/actionpack/lib/action_view/render/rendering.rb @@ -107,12 +107,6 @@ module ActionView end def _render_template(template, layout = nil, options = {}, partial = nil) - logger && logger.info do - msg = "Rendering #{template.inspect}" - msg << " (#{options[:status]})" if options[:status] - msg - end - locals = options[:locals] || {} content = ActiveSupport::Notifications.instrument(:render_template, @@ -124,8 +118,7 @@ module ActionView if layout @_layout = layout.identifier - logger.info("Rendering template within #{layout.inspect}") if logger - content = _render_layout(layout, locals) + content = _render_layout(layout, locals) end content diff --git a/actionpack/test/abstract_unit.rb b/actionpack/test/abstract_unit.rb index a9341b60df..8c65087898 100644 --- a/actionpack/test/abstract_unit.rb +++ b/actionpack/test/abstract_unit.rb @@ -50,6 +50,14 @@ ORIGINAL_LOCALES = I18n.available_locales.map {|locale| locale.to_s }.sort FIXTURE_LOAD_PATH = File.join(File.dirname(__FILE__), 'fixtures') FIXTURES = Pathname.new(FIXTURE_LOAD_PATH) +# Turn on notifications +require 'active_support/notifications' +Thread.abort_on_exception = true + +ActiveSupport::Notifications.subscribe do |*args| + ActionController::Base.log_event(*args) if ActionController::Base.logger +end + module SetupOnce extend ActiveSupport::Concern @@ -87,6 +95,21 @@ class ActiveSupport::TestCase end end +class MockLogger + attr_reader :logged + attr_accessor :level + + def initialize + @level = Logger::DEBUG + @logged = [] + end + + def method_missing(method, *args, &blk) + @logged << args.first + @logged << blk.call if block_given? + end +end + class ActionController::IntegrationTest < ActiveSupport::TestCase def self.build_app(routes = nil) ActionDispatch::MiddlewareStack.new { |middleware| diff --git a/actionpack/test/controller/base_test.rb b/actionpack/test/controller/base_test.rb index 8f8ada8d8c..65118f9bc9 100644 --- a/actionpack/test/controller/base_test.rb +++ b/actionpack/test/controller/base_test.rb @@ -158,13 +158,6 @@ class PerformActionTest < ActionController::TestCase assert_raise(ActionController::UnknownAction) { get :hidden_action } assert_raise(ActionController::UnknownAction) { get :another_hidden_action } end - - def test_namespaced_action_should_log_module_name - use_controller Submodule::ContainedNonEmptyController - @controller.logger = MockLogger.new - get :public_action - assert_match /Processing\sSubmodule::ContainedNonEmptyController#public_action/, @controller.logger.logged[1] - end end class DefaultUrlOptionsTest < ActionController::TestCase diff --git a/actionpack/test/controller/benchmark_test.rb b/actionpack/test/controller/benchmark_test.rb deleted file mode 100644 index 66ebfcf20a..0000000000 --- a/actionpack/test/controller/benchmark_test.rb +++ /dev/null @@ -1,33 +0,0 @@ -require 'abstract_unit' - -# Provide some static controllers. -class BenchmarkedController < ActionController::Base - def public_action - render :nothing => true - end - - def rescue_action(e) - raise e - end -end - -class BenchmarkTest < ActionController::TestCase - tests BenchmarkedController - - class MockLogger - def method_missing(*args) - end - end - - def setup - super - # benchmark doesn't do anything unless a logger is set - @controller.logger = MockLogger.new - @request.host = "test.actioncontroller.i" - end - - def test_with_http_1_0_request - @request.host = nil - assert_nothing_raised { get :public_action } - end -end diff --git a/actionpack/test/controller/caching_test.rb b/actionpack/test/controller/caching_test.rb index 4ea2e57741..679eaf7b38 100644 --- a/actionpack/test/controller/caching_test.rb +++ b/actionpack/test/controller/caching_test.rb @@ -640,7 +640,7 @@ class FragmentCachingTest < ActionController::TestCase assert fragment_computed assert_equal 'generated till now -> ', buffer ActiveSupport::Notifications.notifier.wait - assert_equal [:fragment_exist?, :write_fragment], events.map(&:first) + assert_equal [:exist_fragment?, :write_fragment], events.map(&:first) end end diff --git a/actionpack/test/controller/filter_params_test.rb b/actionpack/test/controller/filter_params_test.rb index 43bef34885..420ebeacf4 100644 --- a/actionpack/test/controller/filter_params_test.rb +++ b/actionpack/test/controller/filter_params_test.rb @@ -70,9 +70,9 @@ class FilterParamTest < ActionController::TestCase FilterParamController.filter_parameter_logging(:lifo, :amount) get :payment, :lifo => 'Pratik', :amount => '420', :step => '1' + ActiveSupport::Notifications.notifier.wait filtered_params_logs = logs.detect {|l| l =~ /\AParameters/ } - assert filtered_params_logs.index('"amount"=>"[FILTERED]"') assert filtered_params_logs.index('"lifo"=>"[FILTERED]"') assert filtered_params_logs.index('"step"=>"1"') diff --git a/actionpack/test/controller/logging_test.rb b/actionpack/test/controller/logging_test.rb index 2b5e8d8bde..4206dffa7e 100644 --- a/actionpack/test/controller/logging_test.rb +++ b/actionpack/test/controller/logging_test.rb @@ -1,48 +1,74 @@ require 'abstract_unit' -class LoggingController < ActionController::Base - def show - render :nothing => true +module Another + class LoggingController < ActionController::Base + layout "layouts/standard" + + def show + render :nothing => true + end + + def with_layout + render :template => "test/hello_world", :layout => true + end end end class LoggingTest < ActionController::TestCase - tests LoggingController - - class MockLogger - attr_reader :logged - attr_accessor :level - - def initialize - @level = Logger::DEBUG - end - - def method_missing(method, *args, &blk) - @logged ||= [] - @logged << args.first - @logged << blk.call if block_given? - end - end + tests Another::LoggingController def setup super set_logger end + def get(*args) + super + wait + end + + def wait + ActiveSupport::Notifications.notifier.wait + end + def test_logging_without_parameters get :show - assert_equal 3, logs.size + assert_equal 4, logs.size assert_nil logs.detect {|l| l =~ /Parameters/ } end def test_logging_with_parameters get :show, :id => '10' - assert_equal 4, logs.size + assert_equal 5, logs.size params = logs.detect {|l| l =~ /Parameters/ } assert_equal 'Parameters: {"id"=>"10"}', params end + def test_log_controller_with_namespace_and_action + get :show + assert_match /Processed\sAnother::LoggingController#show/, logs[1] + end + + def test_log_view_runtime + get :show + assert_match /View runtime/, logs[2] + end + + def test_log_completed_status_and_request_uri + get :show + last = logs.last + assert_match /Completed/, last + assert_match /200/, last + assert_match /another\/logging\/show/, last + end + + def test_logger_prints_layout_and_template_rendering_info + get :with_layout + logged = logs.find {|l| l =~ /render/i } + assert_match /Rendered (.*)test\/hello_world.erb within (.*)layouts\/standard.html.erb/, logged + end + private def set_logger @controller.logger = MockLogger.new diff --git a/actionpack/test/controller/render_test.rb b/actionpack/test/controller/render_test.rb index 54f2739d38..2c3dc2a72d 100644 --- a/actionpack/test/controller/render_test.rb +++ b/actionpack/test/controller/render_test.rb @@ -10,19 +10,6 @@ module Fun end end -class MockLogger - attr_reader :logged - - def initialize - @logged = [] - end - - def method_missing(method, *args, &blk) - @logged << args.first - @logged << blk.call if block_given? - end -end - class TestController < ActionController::Base protect_from_forgery @@ -1500,21 +1487,4 @@ class LastModifiedRenderTest < ActionController::TestCase get :conditional_hello_with_bangs assert_response :success end -end - -class RenderingLoggingTest < ActionController::TestCase - tests TestController - - def setup - super - @request.host = "www.nextangle.com" - end - - def test_logger_prints_layout_and_template_rendering_info - @controller.logger = MockLogger.new - get :layout_test - logged = @controller.logger.logged.find_all {|l| l =~ /render/i } - assert logged[0] =~ %r{Rendering.*test/hello_world} - assert logged[1] =~ %r{Rendering template within.*layouts/standard} - end -end +end \ No newline at end of file diff --git a/activerecord/lib/active_record/rails.rb b/activerecord/lib/active_record/rails.rb index ddbc555113..e272d4eebc 100644 --- a/activerecord/lib/active_record/rails.rb +++ b/activerecord/lib/active_record/rails.rb @@ -50,8 +50,8 @@ module ActiveRecord initializer "active_record.notifications" do require 'active_support/notifications' - ActiveSupport::Notifications.subscribe("sql") do |name, before, after, result, instrumenter_id, payload| - ActiveRecord::Base.connection.log_info(payload[:sql], name, after - before) + ActiveSupport::Notifications.subscribe("sql") do |name, before, after, instrumenter_id, payload| + ActiveRecord::Base.connection.log_info(payload[:sql], payload[:name], (after - before) * 1000) end end diff --git a/activesupport/lib/active_support/notifications/instrumenter.rb b/activesupport/lib/active_support/notifications/instrumenter.rb index fb95422af2..0655dd0cb6 100644 --- a/activesupport/lib/active_support/notifications/instrumenter.rb +++ b/activesupport/lib/active_support/notifications/instrumenter.rb @@ -10,10 +10,10 @@ module ActiveSupport end def instrument(name, payload={}) - time = Time.now - result = yield if block_given? + time = Time.now + yield if block_given? ensure - @notifier.publish(name, time, Time.now, result, @id, payload) + @notifier.publish(name, time, Time.now, @id, payload) end private @@ -23,15 +23,14 @@ module ActiveSupport end class Event - attr_reader :name, :time, :end, :transaction_id, :result, :payload + attr_reader :name, :time, :end, :transaction_id, :payload - def initialize(name, start, ending, result, transaction_id, payload) + def initialize(name, start, ending, transaction_id, payload) @name = name @payload = payload.dup @time = start @transaction_id = transaction_id @end = ending - @result = result end def duration diff --git a/activesupport/test/notifications_test.rb b/activesupport/test/notifications_test.rb index 4f880d0db7..3ba77ae135 100644 --- a/activesupport/test/notifications_test.rb +++ b/activesupport/test/notifications_test.rb @@ -134,27 +134,25 @@ module Notifications class EventTest < TestCase def test_events_are_initialized_with_details - event = event(:foo, Time.now, Time.now + 1, 1, random_id, :payload => :bar) + time = Time.now + event = event(:foo, time, time + 0.01, random_id, {}) + assert_equal :foo, event.name - assert_equal Hash[:payload => :bar], event.payload + assert_equal time, event.time + assert_equal 10.0, event.duration end def test_events_consumes_information_given_as_payload - time = Time.now - event = event(:foo, time, time + 0.01, 1, random_id, {}) - - assert_equal Hash.new, event.payload - assert_equal time, event.time - assert_equal 1, event.result - assert_equal 10.0, event.duration + event = event(:foo, Time.now, Time.now + 1, random_id, :payload => :bar) + assert_equal Hash[:payload => :bar], event.payload end def test_event_is_parent_based_on_time_frame time = Time.utc(2009, 01, 01, 0, 0, 1) - parent = event(:foo, Time.utc(2009), Time.utc(2009) + 100, nil, random_id, {}) - child = event(:foo, time, time + 10, nil, random_id, {}) - not_child = event(:foo, time, time + 100, nil, random_id, {}) + parent = event(:foo, Time.utc(2009), Time.utc(2009) + 100, random_id, {}) + child = event(:foo, time, time + 10, random_id, {}) + not_child = event(:foo, time, time + 100, random_id, {}) assert parent.parent_of?(child) assert !child.parent_of?(parent) From 7e8b7f46bfc086a36db996420fbee93348c5268e Mon Sep 17 00:00:00 2001 From: =?UTF-8?q?Jos=C3=A9=20Valim?= Date: Sun, 27 Dec 2009 13:31:36 +0100 Subject: [PATCH 7/8] Add config.action_controller.include behavior to plugins. --- railties/lib/rails/configuration.rb | 20 +++++++++++++++++++- railties/lib/rails/plugin.rb | 18 ++++++++++++++++++ railties/test/plugins/configuration_test.rb | 16 ++++++++++++++++ 3 files changed, 53 insertions(+), 1 deletion(-) diff --git a/railties/lib/rails/configuration.rb b/railties/lib/rails/configuration.rb index 086f67a419..cb321536d2 100644 --- a/railties/lib/rails/configuration.rb +++ b/railties/lib/rails/configuration.rb @@ -1,6 +1,24 @@ require 'active_support/ordered_options' module Rails + # Create a Plugin::Options from ActiveSuppot::OrderedOptions, + # which support the following syntax: + # + # controller.action_controller.include FooBar + # + class Plugin::Options < ActiveSupport::OrderedOptions #:nodoc: + attr_reader :includes + + def initialize(*args) + @includes = [] + super + end + + def include(*args) + @includes.concat(args) + end + end + # Temporarily separate the plugin configuration class from the main # configuration class while this bit is being cleaned up. class Plugin::Configuration @@ -16,7 +34,7 @@ module Rails @options = base.options.dup @middleware = base.middleware.dup else - @options = Hash.new { |h,k| h[k] = ActiveSupport::OrderedOptions.new } + @options = Hash.new { |h,k| h[k] = Rails::Plugin::Options.new } @middleware = ActionDispatch::MiddlewareStack.new end end diff --git a/railties/lib/rails/plugin.rb b/railties/lib/rails/plugin.rb index 0699affea7..aa325c6f76 100644 --- a/railties/lib/rails/plugin.rb +++ b/railties/lib/rails/plugin.rb @@ -25,6 +25,24 @@ module Rails Configuration.default end + # Creates an initializer which includes all given modules to the given class. + # + # module Rails + # class ActionController < Rails::Plugin + # plugin_name :action_controller + # include_modules_in "ActionController::Base" + # end + # end + # + def self.include_modules_in(klass, from=plugin_name) + self.initializer :"#{from}.include_modules" do |app| + klass = klass.constantize if klass.is_a?(String) + app.config.send(from).includes.each do |mod| + klass.send(:include, mod.is_a?(String) ? mod.constantize : mod) + end + end + end + class Vendored < Plugin def self.all(list, paths) plugins = [] diff --git a/railties/test/plugins/configuration_test.rb b/railties/test/plugins/configuration_test.rb index 5786316d1d..0843d05577 100644 --- a/railties/test/plugins/configuration_test.rb +++ b/railties/test/plugins/configuration_test.rb @@ -8,6 +8,10 @@ module PluginsTest require "rails" end + module Bar; end + module Baz; end + module All; end + test "config is available to plugins" do class Foo < Rails::Plugin ; end assert_nil Foo.config.action_controller.foo @@ -24,6 +28,18 @@ module PluginsTest assert_equal "hello", AppTemplate::Application.config.foo.greetings end + test "plugin configurations allow modules to be given" do + class Foo < Rails::Plugin ; config.foo.include(Bar, Baz) ; end + assert_equal [Bar, Baz], Foo.config.foo.includes + end + + test "plugin includes given modules in given class" do + class Foo < Rails::Plugin ; config.foo.include(Bar, "PluginsTest::ConfigurationTest::Baz") ; include_modules_in All ; end + Foo.new.run_initializers(Foo) + assert All.ancestors.include?(Bar) + assert All.ancestors.include?(Baz) + end + test "plugin config merges are deep" do class Foo < Rails::Plugin ; config.foo.greetings = 'hello' ; end class MyApp < Rails::Application From 97db79ab3c0af7b6805dcaee99384d96ccb3567d Mon Sep 17 00:00:00 2001 From: =?UTF-8?q?Jos=C3=A9=20Valim?= Date: Sun, 27 Dec 2009 13:32:40 +0100 Subject: [PATCH 8/8] Remove ActiveRecord runtime logging from ActionPack and place in ActiveRecord, adding it through config.action_controller.include hook. --- .../lib/action_controller/metal/logger.rb | 17 ++++++++++++++--- actionpack/lib/action_controller/rails.rb | 1 + activerecord/lib/active_record.rb | 1 + .../lib/active_record/controller_runtime.rb | 4 ++-- activerecord/lib/active_record/rails.rb | 3 +++ 5 files changed, 21 insertions(+), 5 deletions(-) rename actionpack/lib/action_controller/metal/active_record_runtime.rb => activerecord/lib/active_record/controller_runtime.rb (92%) diff --git a/actionpack/lib/action_controller/metal/logger.rb b/actionpack/lib/action_controller/metal/logger.rb index 5d14f6c9c9..e71f77fbb2 100644 --- a/actionpack/lib/action_controller/metal/logger.rb +++ b/actionpack/lib/action_controller/metal/logger.rb @@ -30,12 +30,22 @@ module ActionController end end - def cleanup_view_runtime + # If you want to remove any time taken into account in :view_runtime + # wrongly, you can do it here: + # + # def cleanup_view_runtime + # super - time_taken_in_something_expensive + # end + # + # :api: plugin + def cleanup_view_runtime #:nodoc: yield end module ClassMethods - def log_event(name, before, after, instrumenter_id, payload) + # This is the hook invoked by ActiveSupport::Notifications.subscribe. + # If you need to log any event, overwrite the method and do it here. + def log_event(name, before, after, instrumenter_id, payload) #:nodoc: if name == :process_action duration = [(after - before) * 1000, 0.01].max controller = payload[:controller] @@ -65,10 +75,11 @@ module ActionController protected # A hook which allows logging what happened during controller process action. + # :api: plugin def log_process_action(controller) #:nodoc: view_runtime = controller.send :view_runtime logger.info(" View runtime: %.1fms" % view_runtime.to_f) if view_runtime end end end -end +end \ No newline at end of file diff --git a/actionpack/lib/action_controller/rails.rb b/actionpack/lib/action_controller/rails.rb index e381828ee4..6ebb50887b 100644 --- a/actionpack/lib/action_controller/rails.rb +++ b/actionpack/lib/action_controller/rails.rb @@ -1,6 +1,7 @@ module ActionController class Plugin < Rails::Plugin plugin_name :action_controller + include_modules_in "ActionController::Base" initializer "action_controller.set_configs" do |app| app.config.action_controller.each do |k,v| diff --git a/activerecord/lib/active_record.rb b/activerecord/lib/active_record.rb index 196b87c0ac..2cfd528f2c 100644 --- a/activerecord/lib/active_record.rb +++ b/activerecord/lib/active_record.rb @@ -52,6 +52,7 @@ module ActiveRecord autoload :Batches autoload :Calculations autoload :Callbacks + autoload :ControllerRuntime autoload :DynamicFinderMatch autoload :DynamicScopeMatch autoload :Migration diff --git a/actionpack/lib/action_controller/metal/active_record_runtime.rb b/activerecord/lib/active_record/controller_runtime.rb similarity index 92% rename from actionpack/lib/action_controller/metal/active_record_runtime.rb rename to activerecord/lib/active_record/controller_runtime.rb index 29f6dcc783..1281901ae8 100644 --- a/actionpack/lib/action_controller/metal/active_record_runtime.rb +++ b/activerecord/lib/active_record/controller_runtime.rb @@ -1,5 +1,5 @@ -module ActionController - module ActiveRecordRuntime +module ActiveRecord + module ControllerRuntime extend ActiveSupport::Concern attr_internal :db_runtime diff --git a/activerecord/lib/active_record/rails.rb b/activerecord/lib/active_record/rails.rb index e272d4eebc..8b22f869bc 100644 --- a/activerecord/lib/active_record/rails.rb +++ b/activerecord/lib/active_record/rails.rb @@ -7,6 +7,9 @@ require "action_controller/rails" module ActiveRecord class Plugin < Rails::Plugin plugin_name :active_record + include_modules_in "ActiveRecord::Base" + + config.action_controller.include "ActiveRecord::ControllerRuntime" initializer "active_record.set_configs" do |app| app.config.active_record.each do |k,v|