Merge pull request #136 from TwP/date-format-perf-upgrade

Improve date format performance

lib/logging/layouts/pattern.rb

@@ -83,7 +83,7 @@ def self.pattern( *args )
   # events is configured to generate tracing information. If this is not
   # the case these fields will always be empty.
   #
-  # The directives for include diagnostic context information in the log
+  # The directives for including diagnostic context information in the log
   # messages are X and x. For the Mapped Diagnostic Context the directive must
   # be accompanied by the key identifying the value to insert into the log
   # message. The X directive can appear multiple times to include multiple
@@ -166,12 +166,9 @@ def self.create_date_format_methods( pl )
       code << "def format_date( time )\n"
       if pl.date_method.nil?
         if pl.date_pattern =~ %r/%s/
-          code << <<-CODE
-            dp = '#{pl.date_pattern}'.gsub('%s','%06d' % time.usec)
-            time.strftime dp
-          CODE
+          code << "time.strftime('#{pl.date_pattern.gsub('%s','%6N')}')\n"
         else
-          code << "time.strftime '#{pl.date_pattern}'\n"
+          code << "time.strftime('#{pl.date_pattern}')\n"
         end
       else
         code << "time.#{pl.date_method}\n"

test/performance.rb

@@ -0,0 +1,66 @@
+#
+# The peformance script is used to output a performance analysis page for the
+# Logging framework. You can run this script simply:
+#
+#   ruby test/performance.rb
+#
+# This will write a file called "performance.html" that you can open in your web
+# browser. You will need the `ruby-prof` gem installed in order to run this
+# script.
+# ------------------------------------------------------------------------------
+require 'rubygems'
+
+libpath = File.expand_path('../../lib', __FILE__)
+$:.unshift libpath
+require 'logging'
+
+begin
+  gem 'log4r'
+  require 'log4r'
+  $log4r = true
+rescue LoadError
+  $log4r = false
+end
+
+require 'logger'
+require 'ruby-prof'
+
+module Logging
+  class Performance
+
+    # number of iterations
+    attr_reader :this_many
+
+    # performance output file name
+    attr_reader :output_file
+
+    def initialize
+      @this_many   = 300_000
+      @output_file = "performance.html"
+    end
+
+    def run
+      pattern = Logging.layouts.pattern \
+        :pattern      => '%.1l, [%d#%p] %5l -- %c: %m\n',
+        :date_pattern => "%Y-%m-%dT%H:%M:%S.%s"
+
+      Logging.appenders.string_io("sio", :layout => pattern)
+
+      logger = ::Logging.logger["Performance"]
+      logger.level = :warn
+      logger.appenders = "sio"
+
+      result = RubyProf.profile do
+        this_many.times {logger.warn 'logged'}
+      end
+
+      printer = RubyProf::GraphHtmlPrinter.new(result)
+      File.open(output_file, "w") { |fd| printer.print(fd) }
+    end
+  end
+end
+
+if __FILE__ == $0
+  perf = Logging::Performance.new
+  perf.run
+end