Use Strftime to improve fixed timestamp performance

fluent · Dec 19, 2017 · 80e45ea · 80e45ea
1 parent bc77372
commit 80e45ea
Show file tree

Hide file tree

Showing 6 changed files with 38 additions and 19 deletions.
diff --git a/fluentd.gemspec b/fluentd.gemspec
@@ -27,7 +27,7 @@ Gem::Specification.new do |gem|
   gem.add_runtime_dependency("sigdump", ["~> 0.2.2"])
   gem.add_runtime_dependency("tzinfo", ["~> 1.0"])
   gem.add_runtime_dependency("tzinfo-data", ["~> 1.0"])
-  gem.add_runtime_dependency("strptime", ["~> 0.1"])
+  gem.add_runtime_dependency("strptime", [">= 0.2.1", "< 1.0.0"])
   gem.add_runtime_dependency("dig_rb", ["~> 1.0.0"])
 
   # build gem for a certain platform. see also Rakefile

diff --git a/lib/fluent/log.rb b/lib/fluent/log.rb
@@ -163,21 +163,22 @@ def logdev=(logdev)
     def format=(fmt)
       return if @format == fmt
 
+      @time_format = '%Y-%m-%d %H:%M:%S %z'
+      @time_formatter = Strftime.new(@time_format)
+
       case fmt
       when :text
         @format = :text
-        @time_format = '%Y-%m-%d %H:%M:%S %z'
         @formatter = Proc.new { |type, time, level, msg|
           r = caller_line(type, time, @depth_offset, level)
           r << msg
           r
         }
       when :json
         @format = :json
-        @time_format = '%Y-%m-%d %H:%M:%S %z'
         @formatter = Proc.new { |type, time, level, msg|
           r = {
-            'time' => time.strftime(@time_format),
+            'time' => @time_formatter.exec(time),
             'level' => LEVEL_TEXT[level],
             'message' => msg
           }
@@ -191,6 +192,11 @@ def format=(fmt)
       nil
     end
 
+    def time_format=(time_fmt)
+      @time_format = time_fmt
+      @time_formatter = Strftime.new(@time_format)
+    end
+
     def reopen!
       # do nothing in @logger.reopen! because it's already reopened in Supervisor.load_config
       @logger.reopen! if @logger
@@ -423,7 +429,7 @@ def dump_stacktrace(type, backtrace, level)
         end
       else
         r = {
-          'time' => time.strftime(@time_format),
+          'time' => @time_formatter.exec(time),
           'level' => LEVEL_TEXT[level],
         }
         if wid = get_worker_id(type)
@@ -491,7 +497,7 @@ def caller_line(type, time, depth, level)
                        else
                          "".freeze
                        end
-      log_msg = "#{time.strftime(@time_format)} [#{LEVEL_TEXT[level]}]: #{worker_id_part}"
+      log_msg = "#{@time_formatter.exec(time)} [#{LEVEL_TEXT[level]}]: #{worker_id_part}"
       if @debug_mode
         line = caller(depth+1)[0]
         if match = /^(.+?):(\d+)(?::in `(.*)')?/.match(line)
@@ -545,8 +551,8 @@ def enable_color(b = true)
     extend Forwardable
     def_delegators '@logger', :get_worker_id, :enable_color?, :enable_debug, :enable_event,
       :disable_events, :log_event_enabled, :log_event_enamed=, :time_format, :time_format=,
-      :event, :caller_line, :puts, :write, :<<, :flush, :reset, :out, :out=,
-      :optional_header, :optional_header=, :optional_attrs, :optional_attrs=
+      :time_formatter, :time_formatter=, :event, :caller_line, :puts, :write, :<<, :flush,
+      :reset, :out, :out=, :optional_header, :optional_header=, :optional_attrs, :optional_attrs=
   end
 
 

diff --git a/lib/fluent/plugin/formatter_stdout.rb b/lib/fluent/plugin/formatter_stdout.rb
@@ -21,13 +21,14 @@ module Plugin
     class StdoutFormatter < Formatter
       Plugin.register_formatter('stdout', self)
 
-      TIME_FORMAT = '%Y-%m-%d %H:%M:%S.%9N %z'
+      TIME_FORMAT = '%Y-%m-%d %H:%M:%S.%N %z'
 
       config_param :output_type, :string, default: 'json'
 
       def configure(conf)
         super
 
+        @time_formatter = Strftime.new(TIME_FORMAT)
         @sub_formatter = Plugin.new_formatter(@output_type, parent: self.owner)
         @sub_formatter.configure(conf)
       end
@@ -38,7 +39,7 @@ def start
       end
 
       def format(tag, time, record)
-        "#{Time.at(time).localtime.strftime(TIME_FORMAT)} #{tag}: #{@sub_formatter.format(tag, time, record).chomp}\n"
+        "#{@time_formatter.exec(Time.at(time).localtime)} #{tag}: #{@sub_formatter.format(tag, time, record).chomp}\n"
       end
 
       def stop

diff --git a/lib/fluent/plugin/out_stdout.rb b/lib/fluent/plugin/out_stdout.rb
@@ -24,7 +24,6 @@ class StdoutOutput < Output
 
     DEFAULT_LINE_FORMAT_TYPE = 'stdout'
     DEFAULT_FORMAT_TYPE = 'json'
-    TIME_FORMAT = '%Y-%m-%d %H:%M:%S.%9N %z'
 
     config_section :buffer do
       config_set_default :chunk_keys, ['tag']

diff --git a/lib/fluent/time.rb b/lib/fluent/time.rb
@@ -319,6 +319,7 @@ def initialize(format = nil, localtime = true, timezone = nil)
       @tc2 = 0
       @tc2_str = nil
 
+      strftime = format && (Strftime.new(format) rescue nil)
       if format && format =~ /(^|[^%])(%%)*%L|(^|[^%])(%%)*%\d*N/
         define_singleton_method(:format, method(:format_with_subsec))
         define_singleton_method(:call, method(:format_with_subsec))
@@ -327,13 +328,15 @@ def initialize(format = nil, localtime = true, timezone = nil)
         define_singleton_method(:call, method(:format_with_subsec))
       end
 
-      formatter = Fluent::Timezone.formatter(timezone, format)
+      formatter = Fluent::Timezone.formatter(timezone, strftime ? strftime : format)
       @format_nocache = case
-                        when formatter           then formatter
-                        when format && localtime then ->(time){ Time.at(time).strftime(format) }
-                        when format              then ->(time){ Time.at(time).utc.strftime(format) }
-                        when localtime           then ->(time){ Time.at(time).iso8601 }
-                        else                          ->(time){ Time.at(time).utc.iso8601 }
+                        when formatter             then formatter
+                        when strftime && localtime then ->(time){ strftime.exec(Time.at(time)) }
+                        when format && localtime   then ->(time){ Time.at(time).strftime(format) }
+                        when strftime              then ->(time){ strftime.exec(Time.at(time).utc) }
+                        when format                then ->(time){ Time.at(time).utc.strftime(format) }
+                        when localtime             then ->(time){ Time.at(time).iso8601 }
+                        else                            ->(time){ Time.at(time).utc.iso8601 }
                         end
     end
 

diff --git a/lib/fluent/timezone.rb b/lib/fluent/timezone.rb
@@ -97,10 +97,15 @@ def self.formatter(timezone = nil, format = nil)
       if NUMERIC_PATTERN === timezone
         offset = Time.zone_offset(timezone)
 
-        if format
+        case
+        when format.is_a?(String)
           return Proc.new {|time|
             Time.at(time).localtime(offset).strftime(format)
           }
+        when format.is_a?(Strftime)
+          return Proc.new {|time|
+            format.exec(Time.at(time).localtime(offset))
+          }
         else
           return Proc.new {|time|
             Time.at(time).localtime(offset).iso8601
@@ -116,10 +121,15 @@ def self.formatter(timezone = nil, format = nil)
           return nil
         end
 
-        if format
+        case
+        when format.is_a?(String)
           return Proc.new {|time|
             Time.at(time).localtime(tz.period_for_utc(time).utc_total_offset).strftime(format)
           }
+        when format.is_a?(Strftime)
+          return Proc.new {|time|
+            format.exec(Time.at(time).localtime(tz.period_for_utc(time).utc_total_offset))
+          }
         else
           return Proc.new {|time|
             Time.at(time).localtime(tz.period_for_utc(time).utc_total_offset).iso8601