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: 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(-) (limited to 'actionpack/lib') 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 -- cgit v1.2.3 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: Break instrumentation into several end-points so rendering of partials can be optimized. --- actionpack/lib/action_view/render/partials.rb | 42 ++++++++++++++------------ actionpack/lib/action_view/render/rendering.rb | 24 ++++++++++----- actionpack/lib/action_view/template.rb | 6 ++-- 3 files changed, 42 insertions(+), 30 deletions(-) (limited to 'actionpack/lib') 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) -- cgit v1.2.3 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: Optimize <%= render(@posts) %>. --- actionpack/lib/action_view/render/partials.rb | 18 ++++++++++++++---- 1 file changed, 14 insertions(+), 4 deletions(-) (limited to 'actionpack/lib') 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 -- cgit v1.2.3 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: More <%= render(@posts) %> optimization. --- actionpack/lib/action_view/render/partials.rb | 44 ++++++++++++--------------- 1 file changed, 20 insertions(+), 24 deletions(-) (limited to 'actionpack/lib') 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 -- cgit v1.2.3 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: 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 ++++ .../lib/action_controller/caching/fragments.rb | 2 +- .../metal/active_record_runtime.rb | 27 ++++++++ .../lib/action_controller/metal/benchmarking.rb | 72 ---------------------- .../metal/filter_parameter_logging.rb | 22 +++---- actionpack/lib/action_controller/metal/logger.rb | 70 ++++++++++++++++----- actionpack/lib/action_controller/rails.rb | 13 +--- actionpack/lib/action_view/render/rendering.rb | 9 +-- 10 files changed, 108 insertions(+), 139 deletions(-) create mode 100644 actionpack/lib/action_controller/metal/active_record_runtime.rb delete mode 100644 actionpack/lib/action_controller/metal/benchmarking.rb (limited to 'actionpack/lib') 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 - end - INTERNAL_PARAMS = [:controller, :action, :format, :_method, :only_path] + protected - def process(*) - response = super - if logger - parameters = filter_parameters(params).except!(*INTERNAL_PARAMS) - logger.info { " Parameters: #{parameters.inspect}" } unless parameters.empty? + # 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 - response end + INTERNAL_PARAMS = [:controller, :action, :format, :_method, :only_path] + 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 + end + def render(*args, &block) 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}]" + render_output = nil + + self.view_runtime = cleanup_view_runtime do + Benchmark.ms { render_output = super } end - logger.info(log) + render_output + else + super end + end - result + def cleanup_view_runtime + yield end - private + 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}]" - # 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)}" + 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 -- cgit v1.2.3 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: Remove ActiveRecord runtime logging from ActionPack and place in ActiveRecord, adding it through config.action_controller.include hook. --- .../metal/active_record_runtime.rb | 27 ---------------------- actionpack/lib/action_controller/metal/logger.rb | 17 +++++++++++--- actionpack/lib/action_controller/rails.rb | 1 + 3 files changed, 15 insertions(+), 30 deletions(-) delete mode 100644 actionpack/lib/action_controller/metal/active_record_runtime.rb (limited to 'actionpack/lib') diff --git a/actionpack/lib/action_controller/metal/active_record_runtime.rb b/actionpack/lib/action_controller/metal/active_record_runtime.rb deleted file mode 100644 index 29f6dcc783..0000000000 --- a/actionpack/lib/action_controller/metal/active_record_runtime.rb +++ /dev/null @@ -1,27 +0,0 @@ -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/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| -- cgit v1.2.3