🔀 Merge pull request #642 from ruby/response_reader-performance

⚡ Much faster ResponseReader performance

Author: nevans

benchmarks/response_reader.yml

@@ -0,0 +1,87 @@
+prelude: |
+  require "net/imap"
+  require "stringio"
+
+  @io = StringIO.new("", "rb")
+  client = Object.new
+  def client.config = @config ||= Net::IMAP::Config.new
+  def client.max_response_size = config.max_response_size
+  client.config # force memoization
+
+  @reader = Net::IMAP::ResponseReader.new(client, @io)
+  def read
+    @io.rewind
+    @reader.read_response_buffer
+  rescue Net::IMAP::ResponseTooLargeError
+    # intentionally ignoring this
+  end
+
+  def b(str) = str.to_str.b
+
+  # Pathological case: nothing but empty literals
+  EMPTY_CONT = "{0}\r\n"               #  5 bytes
+  SMALL_CONT = "{19}\r\nアイマップ4。" # 25 bytes
+  def pathological(size)   = b EMPTY_CONT * (size.to_int / EMPTY_CONT.bytesize) + "\r\n"
+  def small_literals(size) = b SMALL_CONT * (size.to_int / SMALL_CONT.bytesize) + "\r\n"
+  def no_literals(size)    = b "a" * size + "\r\n"
+  def pathological!(...)   = @io.string = pathological(...)
+  def small_literals!(...) = @io.string = small_literals(...)
+  def no_literals!(...)    = @io.string = no_literals(...)
+
+  def warmup(input)
+    @io.string = input
+    output = read
+    output == input or raise "Invalid input? output=%p" % [output]
+    1000.times do read end
+  end
+
+  warmup no_literals    100
+  warmup small_literals 100
+  warmup pathological   100
+
+  no_literals!(1)
+
+benchmark:
+  - { name: "100  B with no literals", prelude: "no_literals!    1e2", script: "read" }
+  - { name: "  1KiB with no literals", prelude: "no_literals!    1e3", script: "read" }
+  - { name: " 10KiB with no literals", prelude: "no_literals!    1e4", script: "read" }
+  - { name: "100KiB with no literals", prelude: "no_literals!    1e5", script: "read" }
+  - { name: "  1MiB with no literals", prelude: "no_literals!    1e6", script: "read" }
+
+  - { name: "100  B of  25B literals", prelude: "small_literals! 1e2", script: "read" }
+  - { name: "  1KiB of  25B literals", prelude: "small_literals! 1e3", script: "read" }
+  - { name: " 10KiB of  25B literals", prelude: "small_literals! 1e4", script: "read" }
+  - { name: "100KiB of  25B literals", prelude: "small_literals! 1e5", script: "read" }
+  # - { name: "  1MiB of  25 byte literals", prelude: "small_literals! 1e6", script: "read" }
+  # - { name: "100MiB of  25 byte literals", prelude: "small_literals! 1e8", script: "read" }
+
+  - { name: "100  B of   0B literals", prelude: "pathological!   1e2", script: "read" }
+  - { name: "  1KiB of   0B literals", prelude: "pathological!   1e3", script: "read" }
+  - { name: " 10KiB of   0B literals", prelude: "pathological!   1e4", script: "read" }
+  - { name: "100KiB of   0B literals", prelude: "pathological!   1e5", script: "read" }
+  # - { name: "  1MiB of   0 byte literals", prelude: "pathological!   1e6", script: "read" }
+  # - { name: "100MiB of   0 byte literals", prelude: "pathological!   1e8", script: "read" }
+
+contexts:
+  - name: local
+    prelude: |
+      $LOAD_PATH.unshift "./lib"
+    require: false
+  - name: local YJIT
+    prelude: |
+      $LOAD_PATH.unshift "./lib"
+      RubyVM::YJIT.enable
+    require: false
+
+  # - name: v0.6.3
+  #   gems:
+  #     net-imap: 0.6.3
+  #   require: false
+  # - name: v0.5.13
+  #   gems:
+  #     net-imap: 0.5.13
+  #   require: false
+  # - name: v0.4.23
+  #   gems:
+  #     net-imap: 0.4.23
+  #   require: false

lib/net/imap/response_reader.rb

@@ -8,51 +8,60 @@ class ResponseReader # :nodoc:
 
       def initialize(client, sock)
         @client, @sock = client, sock
+        # cached config
+        @max_response_size = nil
+        # response buffer state
+        @buff = @literal_size = nil
       end
 
       def read_response_buffer
+        @max_response_size = client.max_response_size
         @buff = String.new
         catch :eof do
           while true
+            guard_response_too_large!
             read_line
-            break unless (@literal_size = get_literal_size)
+            # check before allocating memory for literal
+            guard_response_too_large!
+            break unless literal_size
             read_literal
           end
         end
         buff
       ensure
-        @buff = nil
+        @buff = @literal_size = nil
       end
 
       private
 
+      # cached config
+      attr_reader :max_response_size
+
+      # response buffer state
       attr_reader :buff, :literal_size
 
       def bytes_read          = buff.bytesize
       def empty?              = buff.empty?
-      def done?               = line_done? && !get_literal_size
+      def done?               = line_done? && !literal_size
       def line_done?          = buff.end_with?(CRLF)
-      def get_literal_size    = /\{(\d+)\}\r\n\z/n =~ buff && $1.to_i
+
+      def get_literal_size(buff)
+        buff.end_with?("}\r\n") && buff.rindex(/\{(\d+)\}\r\n\z/n) && $1.to_i
+      end
 
       def read_line
-        buff << (@sock.gets(CRLF, read_limit) or throw :eof)
-        max_response_remaining! unless line_done?
+        line = (@sock.gets(CRLF, max_response_remaining) or throw :eof)
+        @literal_size = get_literal_size(line)
+        buff << line
       end
 
       def read_literal
-        # check before allocating memory for literal
-        max_response_remaining!
         literal = String.new(capacity: literal_size)
-        buff << (@sock.read(read_limit(literal_size), literal) or throw :eof)
+        buff << (@sock.read(literal_size, literal) or throw :eof)
       ensure
         @literal_size = nil
       end
 
-      def read_limit(limit = nil)
-        [limit, max_response_remaining!].compact.min
-      end
-
-      def max_response_size      = client.max_response_size
       def max_response_remaining = max_response_size &.- bytes_read
       def response_too_large?    = max_response_size &.< min_response_size
       def min_response_size      = bytes_read + min_response_remaining
@@ -61,10 +70,11 @@ def min_response_remaining
         empty? ? 3 : done? ? 0 : (literal_size || 0) + 2
       end
 
-      def max_response_remaining!
-        return max_response_remaining unless response_too_large?
-        raise ResponseTooLargeError.new(
-          max_response_size:, bytes_read:, literal_size:,
+      def guard_response_too_large! = (raise self if response_too_large?)
+
+      def exception(msg = nil)
+        ResponseTooLargeError.new(
+          msg, max_response_size:, bytes_read:, literal_size:,
         )
       end
 

test/lib/helper.rb

@@ -62,6 +62,117 @@ def wait_for_response_count(imap, type:, count:,
     end
   end
 
+  # assert_linear_performance didn't fail reliably until "n" was far too high,
+  # even though the problem was very obvious at lower "n" values, by looking at
+  # the mean (plus stddev) rather than the max (plus variance-based "safety
+  # factor").
+  #
+  # So rather than use "max" as the baseline, this uses μ + 2σ (or max).
+  def assert_strict_linear_time(sequence, prepare: proc do end,
+                                base_repeats: 100,
+                                repeats:        5,
+                                allow_stdev_above_mean: 2,
+                                outlier_safety_factor:  3,
+                                mean_safety_factor:     2,
+                                verbose: false,
+                                &code)
+    pend "No PERFORMANCE_CLOCK found" unless defined?(PERFORMANCE_CLOCK)
+
+    measure  = proc do |&block|
+      st = Process.clock_gettime(PERFORMANCE_CLOCK)
+      block.call
+      t = Process.clock_gettime(PERFORMANCE_CLOCK)
+      t - st
+    end
+
+    measure_base = proc do |sequence, prepare:, &code|
+      stats = RunningStats.new
+      base_repeats.times do
+        *args = prepare.(sequence.first)
+        time = measure.call { code.call(*args) }
+        warn "  - %0.9f" % [time] if verbose == :very
+        stats.push time
+      end
+      stats
+    end
+
+    scale = ->(base, base_size, size) { base * size.fdiv(base_size) }
+
+    warn "Measuring (#{base_repeats} times) for n=#{sequence.first}." if verbose
+    base_stats = measure_base.(sequence, prepare:, &code)
+    base_time  = [base_stats.stddev_above_mean(3), base_stats.max].min
+
+    base_timeout_msg = "min=%s max=%s mean=%s stddev=%s timeout=%s" % [
+      base_stats.min, base_stats.max, base_stats.mean, base_stats.stddev,
+      base_time
+    ].map { "%0.6f" % _1 }
+
+    warn "  n=%d -> %p" % [sequence.first, base_stats] if verbose
+    warn "  base timeout=%0.6f" % [base_time] if verbose
+
+    sequence.each.drop(1).to_h {|n|
+      linear_limit = scale.(base_time, sequence.first, n)
+      each_timeout = linear_limit * outlier_safety_factor
+      mean_timeout = linear_limit *    mean_safety_factor
+      full_timeout = mean_timeout * repeats * 1.1
+      timeout_msg = "for n=%s linear_limit=%0.6f timeout=%0.6f mean_timeout=%0.6f" % [
+        n, linear_limit, each_timeout, mean_timeout
+      ]
+      warn "Measuring (#{repeats} times) #{timeout_msg}:" if verbose
+      timeout_msg = "#{timeout_msg} #{base_timeout_msg}"
+      *args = prepare.call(n)
+      times = Timeout.timeout(full_timeout, Timeout::Error, timeout_msg) do
+        Array.new(repeats) {
+          time = Timeout.timeout(each_timeout, Timeout::Error, timeout_msg) do
+            measure.call do code.call(*args) end
+          end
+          assert_operator time, :<=, each_timeout,
+            "super-linear time %0.6f %s" % [time, timeout_msg]
+          warn "  ---- %0.9f" % [time] if verbose == :very
+          time
+        }
+      end
+      stats = RunningStats.new(times)
+      warn "  n=%d -> %p" % [n, stats] if verbose
+      assert_operator stats.mean, :<=, mean_timeout,
+        "super-linear mean time %0.6f %s" % [stats.mean, timeout_msg]
+      [n, stats]
+    }
+  end
+
+  class RunningStats
+    attr_reader :samples, :min, :max, :mean
+
+    def initialize(input = nil)
+      @samples = 0
+      @mean    = 0.0
+      @s       = 0.0
+      @min     = nil
+      @max     = nil
+      input&.each do push _1 end
+    end
+
+    def push(x)
+      @min      = @min ? [@min, x].min : x
+      @max      = @max ? [@max, x].max : x
+      @samples += 1
+      delta     = (x - @mean)
+      @mean    += delta / @samples
+      @s       += delta * (x - @mean)
+    end
+
+    def variance; (@samples >= 1) ? @s / (@samples - 1) : 0.0 end
+    def stddev;   Math.sqrt(variance) end
+
+    def stddev_above_mean(mult = 1) = mean + mult * stddev
+
+    def inspect
+      "#<%s samples=%d min=%0.6f max=%0.6f mean=%0.6f stddev=%0.6f>" % [
+        self.class, samples, min, max, mean, stddev
+      ]
+    end
+  end
+
   # Copied from minitest
   def assert_pattern
     flunk "assert_pattern requires a block to capture errors." unless block_given?

test/net/imap/test_response_reader.rb

@@ -54,15 +54,15 @@ def literal(str) = "{#{str.bytesize}}\r\n#{str}"
     exact = "+ 345678\r\n"
     very_over     = "+ 3456789 #{?a * (16<<10)}}\r\n"
     slightly_over = "+ 34567890\r\n" # CRLF after the limit
-    io = StringIO.new([under, exact, very_over, slightly_over].join)
+    io = StringIO.new([under, exact, very_over, slightly_over].join, "rb")
     rcvr = Net::IMAP::ResponseReader.new(client, io)
     assert_equal under, rcvr.read_response_buffer.to_str
     assert_equal exact, rcvr.read_response_buffer.to_str
     assert_raise Net::IMAP::ResponseTooLargeError do
       result = rcvr.read_response_buffer
       flunk "Got result: %p" % [result]
     end
-    io = StringIO.new(slightly_over)
+    io = StringIO.new(slightly_over, "rb")
     rcvr = Net::IMAP::ResponseReader.new(client, io)
     assert_raise Net::IMAP::ResponseTooLargeError do
       result = rcvr.read_response_buffer
@@ -74,12 +74,34 @@ def literal(str) = "{#{str.bytesize}}\r\n#{str}"
     barely_over = "+ 3456789\r\n"  # CRLF straddles the boundary
     client = FakeClient.new
     client.config.max_response_size = 10
-    io = StringIO.new(barely_over)
+    io = StringIO.new(barely_over, "rb")
     rcvr = Net::IMAP::ResponseReader.new(client, io)
     assert_raise Net::IMAP::ResponseTooLargeError do
       result = rcvr.read_response_buffer
       flunk "Got result: %p" % [result]
     end
   end
 
+  test "linear performance detecting literal continuation" do
+    omit_unless_cruby "flaky on different platforms"
+    omit_if(ENV["CI"], "slow and flaky, skipping in CI")
+
+    client = FakeClient.new
+    io = StringIO.new "", "rb"
+    rcvr = Net::IMAP::ResponseReader.new(client, io)
+
+    sequence = [100, 1_000, 10_000]
+    assert_strict_linear_time(sequence, prepare: ->(n) {
+      parts = Array.new(n) {|i| "BODY[#{i.succ}] {1}\r\nX" }.join(" ")
+      response = "* 1 FETCH (#{parts})\r\n"
+      embedded = "#{response}* OK next response\r\n"
+      io.string = embedded
+      assert_equal response, rcvr.read_response_buffer
+      io.rewind
+      response
+    }) do
+      io.rewind
+      rcvr.read_response_buffer
+    end
+  end
 end