Merge pull request #7708 from bdurand/optimize_log_subscribers

Optimize log subscribers to check if the log level is sufficient

actionmailer/lib/action_mailer/log_subscriber.rb

@@ -1,13 +1,15 @@
 module ActionMailer
   class LogSubscriber < ActiveSupport::LogSubscriber
     def deliver(event)
+      return unless logger.info?
       recipients = Array(event.payload[:to]).join(', ')
-      info("\nSent mail to #{recipients} (%1.fms)" % event.duration)
+      info("\nSent mail to #{recipients} (#{event.duration.round(1)}ms)")
       debug(event.payload[:mail])
     end
 
     def receive(event)
-      info("\nReceived mail (%.1fms)" % event.duration)
+      return unless logger.info?
+      info("\nReceived mail (#{event.duration.round(1)}ms)")
       debug(event.payload[:mail])
     end
 

actionpack/lib/action_controller/log_subscriber.rb

@@ -4,6 +4,8 @@ module ActionController
     INTERNAL_PARAMS = %w(controller action format _method only_path)
 
     def start_processing(event)
+      return unless logger.info?
+
       payload = event.payload
       params  = payload[:params].except(*INTERNAL_PARAMS)
       format  = payload[:format]
@@ -14,6 +16,8 @@ module ActionController
     end
 
     def process_action(event)
+      return unless logger.info?
+
       payload   = event.payload
       additions = ActionController::Base.log_process_action(payload)
 
@@ -22,35 +26,36 @@ module ActionController
         exception_class_name = payload[:exception].first
         status = ActionDispatch::ExceptionWrapper.status_code_for_exception(exception_class_name)
       end
-      message = "Completed #{status} #{Rack::Utils::HTTP_STATUS_CODES[status]} in %.0fms" % event.duration
+      message = "Completed #{status} #{Rack::Utils::HTTP_STATUS_CODES[status]} in #{event.duration.round}ms"
       message << " (#{additions.join(" | ")})" unless additions.blank?
 
       info(message)
     end
 
     def halted_callback(event)
-      info "Filter chain halted as #{event.payload[:filter]} rendered or redirected"
+      info("Filter chain halted as #{event.payload[:filter]} rendered or redirected")
     end
 
     def send_file(event)
-      info("Sent file %s (%.1fms)" % [event.payload[:path], event.duration])
+      info("Sent file #{event.payload[:path]} (#{event.duration.round(1)}ms)")
     end
 
     def redirect_to(event)
-      info "Redirected to #{event.payload[:location]}"
+      info("Redirected to #{event.payload[:location]}")
     end
 
     def send_data(event)
-      info("Sent data %s (%.1fms)" % [event.payload[:filename], event.duration])
+      info("Sent data #{event.payload[:filename]} (#{event.duration.round(1)}ms)")
     end
 
     %w(write_fragment read_fragment exist_fragment?
        expire_fragment expire_page write_page).each do |method|
       class_eval <<-METHOD, __FILE__, __LINE__ + 1
         def #{method}(event)
+          return unless logger.info?
           key_or_path = event.payload[:key] || event.payload[:path]
           human_name  = #{method.to_s.humanize.inspect}
-          info("\#{human_name} \#{key_or_path} \#{"(%.1fms)" % event.duration}")
+          info("\#{human_name} \#{key_or_path} (\#{event.duration.round(1)}ms)")
         end
       METHOD
     end

actionpack/lib/action_view/log_subscriber.rb

@@ -3,10 +3,13 @@ module ActionView
   #
   # Provides functionality so that Rails can output logs from Action View.
   class LogSubscriber < ActiveSupport::LogSubscriber
+    VIEWS_PATTERN = /^app\/views\//.freeze
+
     def render_template(event)
+      return unless logger.info?
       message = "  Rendered #{from_rails_root(event.payload[:identifier])}"
       message << " within #{from_rails_root(event.payload[:layout])}" if event.payload[:layout]
-      message << (" (%.1fms)" % event.duration)
+      message << " (#{event.duration.round(1)}ms)"
       info(message)
     end
     alias :render_partial :render_template
@@ -19,7 +22,7 @@ module ActionView
   protected
 
     def from_rails_root(string)
-      string.sub("#{Rails.root}/", "").sub(/^app\/views\//, "")
+      string.sub("#{Rails.root}/", "").sub(VIEWS_PATTERN, "")
     end
   end
 end

activerecord/lib/active_record/log_subscriber.rb

@@ -1,11 +1,13 @@
 module ActiveRecord
   class LogSubscriber < ActiveSupport::LogSubscriber
+    IGNORE_PAYLOAD_NAMES = ["SCHEMA", "EXPLAIN"]
+    
     def self.runtime=(value)
-      Thread.current["active_record_sql_runtime"] = value
+      Thread.current[:active_record_sql_runtime] = value
     end
 
     def self.runtime
-      Thread.current["active_record_sql_runtime"] ||= 0
+      Thread.current[:active_record_sql_runtime] ||= 0
     end
 
     def self.reset_runtime
@@ -24,9 +26,9 @@ module ActiveRecord
 
       payload = event.payload
 
-      return if 'SCHEMA' == payload[:name]
+      return if IGNORE_PAYLOAD_NAMES.include?(payload[:name])
 
-      name  = '%s (%.1fms)' % [payload[:name], event.duration]
+      name  = "#{payload[:name]} (#{event.duration.round(1)}ms)"
       sql   = payload[:sql].squeeze(' ')
       binds = nil
 

activesupport/CHANGELOG.md

@@ -239,4 +239,6 @@
 
 *   Remove deprecated ActiveSupport::JSON::Variable. *Erich Menge*
 
+*   Optimize log subscribers to check log level before doing any processing. *Brian Durand*
+
 Please check [3-2-stable](https://github.com/rails/rails/blob/3-2-stable/activesupport/CHANGELOG.md) for previous changes.