clogger RubyGem user+dev discussion/patches/pulls/bugs/help
 help / color / mirror / Atom feed
* [PATCH] Added optional POWER argument to $response_time
@ 2020-08-03 12:54 Josh N
  2020-08-03 20:58 ` Eric Wong
  0 siblings, 1 reply; 3+ messages in thread
From: Josh N @ 2020-08-03 12:54 UTC (permalink / raw)
  To: e; +Cc: Josh N, clogger-public

This argument allows for conversion of response_time to microsecond
or nanosecond by multiplying by a power of 10, 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..27ff553 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 9
 * $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	[flat|nested] 3+ messages in thread

* Re: [PATCH] Added optional POWER argument to $response_time
  2020-08-03 12:54 [PATCH] Added optional POWER argument to $response_time Josh N
@ 2020-08-03 20:58 ` Eric Wong
  2020-08-05 12:52   ` Josh Natanson
  0 siblings, 1 reply; 3+ messages in thread
From: Eric Wong @ 2020-08-03 20:58 UTC (permalink / raw)
  To: Josh N; +Cc: clogger-public

Thanks Josh!

There's some trailing whitespace issues, so I applied with
"git am --whitespace=fix" and pushed to https://yhbt.net/clogger.git
as commit 81cf3b2f31a55a2caf8222c6847ca8d9c01f8eee

In the future, it's worth enabling git's default pre-commit hook
which does "git diff-index --check --cached $against --" for all
your projects for ease-of-merging and patch review.

There's a few other unrelated things I'll cleanup but expect a
release in the next week or so.  Thanks again.

^ permalink raw reply	[flat|nested] 3+ messages in thread

* Re: [PATCH] Added optional POWER argument to $response_time
  2020-08-03 20:58 ` Eric Wong
@ 2020-08-05 12:52   ` Josh Natanson
  0 siblings, 0 replies; 3+ messages in thread
From: Josh Natanson @ 2020-08-05 12:52 UTC (permalink / raw)
  To: Eric Wong; +Cc: clogger-public

Thanks again for all the help.  Next time I contribute, I'll make more
time to get my environment in order before starting the process.

^ permalink raw reply	[flat|nested] 3+ messages in thread

end of thread, other threads:[~2020-08-05 12:52 UTC | newest]

Thread overview: 3+ messages (download: mbox.gz / follow: Atom feed)
-- links below jump to the message on this page --
2020-08-03 12:54 [PATCH] Added optional POWER argument to $response_time Josh N
2020-08-03 20:58 ` Eric Wong
2020-08-05 12:52   ` Josh Natanson

clogger RubyGem user+dev discussion/patches/pulls/bugs/help

This inbox may be cloned and mirrored by anyone:

	git clone --mirror https://yhbt.net/clogger-public
	git clone --mirror http://ou63pmih66umazou.onion/clogger-public

	# If you have public-inbox 1.1+ installed, you may
	# initialize and index your mirror using the following commands:
	public-inbox-init -V1 clogger-public clogger-public/ https://yhbt.net/clogger-public \
		clogger-public@yhbt.net clogger-public@bogomips.org clogger@librelist.org clogger@librelist.com
	public-inbox-index clogger-public

Example config snippet for mirrors.
Newsgroups are available over NNTP:
	nntp://news.public-inbox.org/inbox.comp.lang.ruby.clogger
	nntp://ou63pmih66umazou.onion/inbox.comp.lang.ruby.clogger
 note: .onion URLs require Tor: https://www.torproject.org/

code repositories for the project(s) associated with this inbox:

	clogger.git

AGPL code for this site: git clone https://public-inbox.org/public-inbox.git