[PATCH] Added optional POWER argutment to $response_time.

[PATCH] Added optional POWER argutment to $response_time.

[Josh Natanson]

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)

Re: [PATCH] Added optional POWER argutment to $response_time.

[Eric Wong]

Josh Natanson <josh@natanson.net> wrote:
> Subject: Re: [PATCH] Added optional POWER argutment to $response_time.

Hi Josh,

spelling: "argument"

Btw, I'm no math expert, so I'm not sure if "power" is even the
correct term, here.  Is "order-of-magnitude" more correct?  (or
just "ORDER").

Also, no need for "." in commit titles (or email subjects).

> 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} -

There's a space between "POWER," and "PRECISION" in the
documentation.  However, the code below doesn't accept a space
(and I prefer it not).

> +  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));

While the space-indented Ruby parts came out fine, the .c code
uses hard tabs and they weren't preserved in this patch.

Based on your headers, it seems like you're using the gmail
web GUI instead of a mail client; and that doesn't preserve
hard tabs in inline messages.

Quoting Documentation/process/email-clients.rst from linux.git(*):

> Gmail (Web GUI)
> ***************
> 
> Does not work for sending patches.
> 
> Gmail web client converts tabs to spaces automatically.
> 
> At the same time it wraps lines every 78 chars with CRLF style line breaks
> although tab2space problem can be solved with external editor.

Again, for one-off patches, "git format-patch"-generated attachments
are probably fine if you don't want to configure "git send-email".

Btw, I realize some of this can seem nitpicky and strange to
you; but I'm really trying to get the world away from
monopolies, centralized tools; along with preparing you and
others to contribute to other projects with a decentralized,
asynchronous workflow.

(*) https://yhbt.net/mirrors/linux.git/plain/Documentation/process/email-clients.rst

> 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

No spaces here between the args, which confirms my comments
about the README change.

The rest of the patch looked fine.
Can you take another shot at resending with my comments
addressed?  No rush, though.  Thanks again.

Re: [PATCH] Added optional POWER argutment to $response_time.

[Josh Natanson]

Thanks Eric, will try to address and resubmit shortly, with the
exception of the term "POWER".  I went that route after seeing your C
variable name, but I double-checked and "power of 10" seems to be the
clearest language to use, so I'm inclined to leave it as is (unless
you have a specific alternative suggestion).