clogger RubyGem user+dev discussion/patches/pulls/bugs/help
 help / color / mirror / code / Atom feed
* [PATCH] Added optional POWER argutment to $response_time.
@ 2020-08-02 13:44 Josh Natanson
  2020-08-02 18:55 ` Eric Wong
  0 siblings, 1 reply; 3+ messages in thread
From: Josh Natanson @ 2020-08-02 13:44 UTC (permalink / raw)
  To: Eric Wong; +Cc: clogger-public

This argument allows for conversion of response_time to microsecond
or nanosecond, up to a limit of 9.  Defaults to 0 so backwards compatible.
---
 README                    | 10 ++++++----
 ext/clogger_ext/clogger.c | 28 ++++++++++++++++++++++++++++
 lib/clogger.rb            | 11 +++++++++--
 lib/clogger/pure.rb       |  1 +
 test/test_clogger.rb      | 25 +++++++++++++++++++++++--
 5 files changed, 67 insertions(+), 8 deletions(-)

diff --git a/README b/README
index 1d1d537..7c22fd5 100644
--- a/README
+++ b/README
@@ -69,10 +69,12 @@ that receives a "<<" method:
 * $request_uri - the URI requested ($path_info?$query_string)
 * $request - the first line of the HTTP request
   ($request_method $request_uri $http_version)
-* $request_time, $request_time{PRECISION} - time taken for request
-  (including response body iteration).  PRECISION defaults to 3
-  (milliseconds) if not specified but may be specified anywhere from
-  0(seconds) to 6(microseconds).
+* $request_time, $request_time{PRECISION}, $request_time{POWER, PRECISION} -
+  time taken for request (including response body iteration).  PRECISION
+  defaults to 3 (milliseconds) if not specified but may be specified
+  anywhere from 0(seconds) to 6(microseconds). POWER will raise the time to
+  the provided power of 10, useful for converting to micro- or nanoseconds.
+  POWER defaults to 0 if not specified but may be specified any from 0 to 10
 * $time_iso8601 - current local time in ISO 8601 format,
   e.g. "1970-01-01T00:00:00+00:00"
 * $time_local - current local time in Apache log format,
diff --git a/ext/clogger_ext/clogger.c b/ext/clogger_ext/clogger.c
index fdc23e3..a1f3bc4 100644
--- a/ext/clogger_ext/clogger.c
+++ b/ext/clogger_ext/clogger.c
@@ -374,12 +374,40 @@ static void append_ts(struct clogger *c, VALUE
op, struct timespec *ts)
  rb_str_buf_cat(c->log_buf, buf, nr);
 }

+#define NANO_PER_SEC (1000 * 1000 * 1000)
 static void append_request_time_fmt(struct clogger *c, VALUE op)
 {
  struct timespec now;
+ unsigned long ipow = NUM2ULONG(rb_ary_entry(op, 3));

  clock_gettime(hopefully_CLOCK_MONOTONIC, &now);
  clock_diff(&now, &c->ts_start);
+ if (ipow) {
+   struct timespec prev;
+   unsigned long adj = 1;
+   /*
+     * n.b. timespec.tv_sec may not be time_t on some platforms,
+     * so we use a full timespec struct instead of time_t:
+     */
+   prev.tv_sec = now.tv_sec;
+   do { adj *= 10; } while (--ipow);
+   now.tv_sec *= adj;
+   now.tv_nsec *= adj;
+   if (now.tv_nsec >= NANO_PER_SEC) {
+     int64_t add = now.tv_nsec / NANO_PER_SEC;
+     now.tv_sec += add;
+     now.tv_nsec %= NANO_PER_SEC;
+   }
+   if (now.tv_sec < prev.tv_sec) { /* overflowed */
+     now.tv_nsec = NANO_PER_SEC - 1;
+     /*
+       * some platforms may use unsigned .tv_sec, but
+       * they're not worth supporting, so keep unsigned:
+       */
+     now.tv_sec = (time_t)(sizeof(now.tv_sec) == 4 ?
+                  INT_MAX : LONG_MAX);
+   }
+ }
  append_ts(c, op, &now);
 }

diff --git a/lib/clogger.rb b/lib/clogger.rb
index be1bdce..7ce2b24 100644
--- a/lib/clogger.rb
+++ b/lib/clogger.rb
@@ -51,7 +51,7 @@ private

   SCAN = /([^$]*)(\$+(?:env\{\w+(?:\.[\w\.]+)?\}|
                         e\{[^\}]+\}|
-                        (?:request_)?time\{\d+\}|
+                        (?:request_)?time\{\d+(?:,\d+)?\}|
                         time_(?:utc|local)\{[^\}]+\}|
                         \w*))?([^$]*)/x

@@ -92,7 +92,14 @@ private
         when /\A\$time\{(\d+)\}\z/
           rv << [ OP_TIME, *usec_conv_pair(tok, $1.to_i) ]
         when /\A\$request_time\{(\d+)\}\z/
-          rv << [ OP_REQUEST_TIME, *usec_conv_pair(tok, $1.to_i) ]
+          rv << [ OP_REQUEST_TIME, *usec_conv_pair(tok, $1.to_i), 0 ]
+        when /\A\$request_time\{(\d+),(\d+)\}\z/
+          ipow = $1.to_i
+          prec = $2.to_i
+          if ipow > 9 # nanosecond precision is the highest POSIX goes
+            raise ArgumentError, "#{tok}: too big: #{ipow} (max=9)"
+          end
+          rv << [ OP_REQUEST_TIME, *usec_conv_pair(tok, prec), ipow ]
         else
           tok_sym = tok[1..-1].to_sym
           if special_code = SPECIAL_VARS[tok_sym]
diff --git a/lib/clogger/pure.rb b/lib/clogger/pure.rb
index fddfe79..8f1f706 100644
--- a/lib/clogger/pure.rb
+++ b/lib/clogger/pure.rb
@@ -166,6 +166,7 @@ private
       when OP_TIME_UTC; Time.now.utc.strftime(op[1])
       when OP_REQUEST_TIME
         t = mono_now - start
+        t = t * (10 ** op[3])
         time_format(t.to_i, (t - t.to_i) * 1000000, op[1], op[2])
       when OP_TIME
         t = Time.now
diff --git a/test/test_clogger.rb b/test/test_clogger.rb
index ca3bd55..58c6ca3 100644
--- a/test/test_clogger.rb
+++ b/test/test_clogger.rb
@@ -167,10 +167,11 @@ class TestClogger < Test::Unit::TestCase
       ary = compile_format(
         '$remote_addr - $remote_user [$time_local] ' \
         '"$request" $status $body_bytes_sent "$http_referer" ' \
-        '"$http_user_agent" "$http_cookie" $request_time ' \
+        '"$http_user_agent" "$http_cookie" $request_time $request_time{6,0} ' \
         '$env{rack.url_scheme}' \
         "\n")
     }
+
     expect = [
       [ Clogger::OP_REQUEST, "REMOTE_ADDR" ],
       [ Clogger::OP_LITERAL, " - " ],
@@ -190,7 +191,9 @@ class TestClogger < Test::Unit::TestCase
       [ Clogger::OP_LITERAL, "\" \"" ],
       [ Clogger::OP_REQUEST, "HTTP_COOKIE" ],
       [ Clogger::OP_LITERAL, "\" " ],
-      [ Clogger::OP_REQUEST_TIME, '%d.%03d', 1000 ],
+      [ Clogger::OP_REQUEST_TIME, '%d.%03d', 1000, 0],
+      [ Clogger::OP_LITERAL, " " ],
+      [ Clogger::OP_REQUEST_TIME, '%d', 1, 6],
       [ Clogger::OP_LITERAL, " " ],
       [ Clogger::OP_REQUEST, "rack.url_scheme" ],
       [ Clogger::OP_LITERAL, "\n" ],
@@ -721,6 +724,24 @@ class TestClogger < Test::Unit::TestCase
     assert s[-1].to_f <= 0.110
   end

+  def test_request_time_with_multiplier
+    s = []
+    app = lambda { |env| sleep(0.1) ; [302, [], [] ] }
+    cl = Clogger.new(app, :logger => s, :format => "$request_time{9,0}")
+    status, headers, body = cl.call(@req)
+    assert_nothing_raised { body.each { |x| } ; body.close }
+    assert s[-1].to_f >= 100000000
+    assert s[-1].to_f <= 300000000
+  end
+
+  def test_request_time_with_invalid_multiplier
+    s = []
+    app = lambda { |env| sleep(0.1) ; [302, [], [] ] }
+    assert_raise(ArgumentError) {
+      cl = Clogger.new(app, :logger => s, :format => "$request_time{10,0}")
+    }
+  end
+
   def test_insanely_long_time_format
     s = []
     app = lambda { |env| [200, [], [] ] }
-- 
2.20.1 (Apple Git-117)

^ permalink raw reply related	[flat|nested] 3+ messages in thread
end of thread, other threads:[~2020-08-03 12:42 UTC | newest]

Thread overview: 3+ messages (download: mbox.gz / follow: Atom feed)
-- links below jump to the message on this page --
2020-08-02 13:44 [PATCH] Added optional POWER argutment to $response_time Josh Natanson
2020-08-02 18:55 ` Eric Wong
2020-08-03 12:42   ` Josh Natanson

Code repositories for project(s) associated with this public inbox

	https://yhbt.net/clogger.git/

This is a public inbox, see mirroring instructions
for how to clone and mirror all data and code used for this inbox;
as well as URLs for read-only IMAP folder(s) and NNTP newsgroup(s).