[PATCH 0/2] fixes for pure-Ruby users

[PATCH 0/2] fixes for pure-Ruby users

[Eric Wong]

These bugs were discovered by some folks who forgot to upgrade from
clogger 1.0.1 when when upgrading from MRI 1.9.3 to 2.1 and were
inadvertently using the pure Ruby version instead of the C extension.

New release coming, but does not affect users of the C extension.

Eric Wong (2):
      pure: fix reentrancy of request_time
      pure: use monotonic clock if possible

[PATCH 1/2] pure: fix reentrancy of request_time

[Eric Wong]

For users unable to compile the C extension, multithreaded usage
of clogger could return invalid request time measurements.

This does not affect users of the C extension.
---
 lib/clogger/pure.rb | 17 +++++++++--------
 1 file changed, 9 insertions(+), 8 deletions(-)

diff --git a/lib/clogger/pure.rb b/lib/clogger/pure.rb
index bb3fc16..9efb00c 100644
--- a/lib/clogger/pure.rb
+++ b/lib/clogger/pure.rb
@@ -6,7 +6,7 @@
 class Clogger
 
   attr_accessor :env, :status, :headers, :body
-  attr_writer :body_bytes_sent
+  attr_writer :body_bytes_sent, :start
 
   def initialize(app, opts = {})
     # trigger autoload to avoid thread-safety issues later on
@@ -28,10 +28,10 @@ def initialize(app, opts = {})
   end
 
   def call(env)
-    @start = Time.now
+    start = Time.now
     resp = @app.call(env)
     unless resp.instance_of?(Array) && resp.size == 3
-      log(env, 500, {})
+      log(env, 500, {}, start)
       raise TypeError, "app response not a 3 element Array: #{resp.inspect}"
     end
     status, headers, body = resp
@@ -39,13 +39,14 @@ def call(env)
     if @wrap_body
       @reentrant = env['rack.multithread'] if @reentrant.nil?
       wbody = @reentrant ? self.dup : self
+      wbody.start = start
       wbody.env = env
       wbody.status = status
       wbody.headers = headers
       wbody.body = body
       return [ status, headers, wbody ]
     end
-    log(env, status, headers)
+    log(env, status, headers, start)
     [ status, headers, body ]
   end
 
@@ -60,8 +61,8 @@ def each
 
   def close
     @body.close if @body.respond_to?(:close)
-    ensure
-      log(@env, @status, @headers)
+  ensure
+    log(@env, @status, @headers)
   end
 
   def reentrant?
@@ -153,7 +154,7 @@ def time_format(sec, usec, format, div)
     format % [ sec, usec / div ]
   end
 
-  def log(env, status, headers)
+  def log(env, status, headers, start = @start)
     str = @fmt_ops.map { |op|
       case op[0]
       when OP_LITERAL; op[1]
@@ -164,7 +165,7 @@ def log(env, status, headers)
       when OP_TIME_LOCAL; Time.now.strftime(op[1])
       when OP_TIME_UTC; Time.now.utc.strftime(op[1])
       when OP_REQUEST_TIME
-        t = Time.now - @start
+        t = Time.now - start
         time_format(t.to_i, (t - t.to_i) * 1000000, op[1], op[2])
       when OP_TIME
         t = Time.now
-- 
EW

[PATCH 2/2] pure: use monotonic clock if possible

[Eric Wong]

Ruby 2.1.0 and later exposes Process.clock_gettime, resulting
in less garbage and access to the monotonic clock if it is
available.  Try to use it to achieve feature parity with the
C extension (which has always used the monotonic clock if possible).
---
 lib/clogger/pure.rb | 14 ++++++++++++--
 1 file changed, 12 insertions(+), 2 deletions(-)

diff --git a/lib/clogger/pure.rb b/lib/clogger/pure.rb
index 9efb00c..5e7ccfe 100644
--- a/lib/clogger/pure.rb
+++ b/lib/clogger/pure.rb
@@ -28,7 +28,7 @@ def initialize(app, opts = {})
   end
 
   def call(env)
-    start = Time.now
+    start = mono_now
     resp = @app.call(env)
     unless resp.instance_of?(Array) && resp.size == 3
       log(env, 500, {}, start)
@@ -165,7 +165,7 @@ def log(env, status, headers, start = @start)
       when OP_TIME_LOCAL; Time.now.strftime(op[1])
       when OP_TIME_UTC; Time.now.utc.strftime(op[1])
       when OP_REQUEST_TIME
-        t = Time.now - start
+        t = mono_now - start
         time_format(t.to_i, (t - t.to_i) * 1000000, op[1], op[2])
       when OP_TIME
         t = Time.now
@@ -185,4 +185,14 @@ def log(env, status, headers, start = @start)
     end
     nil
   end
+
+  # favor monotonic clock if possible, and try to use clock_gettime in
+  # more recent Rubies since it generates less garbage
+  if defined?(Process::CLOCK_MONOTONIC)
+    def mono_now; Process.clock_gettime(Process::CLOCK_MONOTONIC); end
+  elsif defined?(Process::CLOCK_REALTIME)
+    def mono_now; Process.clock_gettime(Process::CLOCK_REALTIME); end
+  else
+    def mono_now; Time.now.to_f; end
+  end
 end
-- 
EW