From: Josh N <josh@natanson.net>
To: <e@yhbt.net>
Cc: Josh N <josh@natanson.net>, <clogger-public@yhbt.net>
Subject: [PATCH] Added optional POWER argument to $response_time
Date: Mon, 3 Aug 2020 08:54:15 -0400 [thread overview]
Message-ID: <20200803125415.83393-1-josh@natanson.net> (raw)
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)
next reply other threads:[~2020-08-03 12:54 UTC|newest]
Thread overview: 3+ messages / expand[flat|nested] mbox.gz Atom feed top
2020-08-03 12:54 Josh N [this message]
2020-08-03 20:58 ` [PATCH] Added optional POWER argument to $response_time Eric Wong
2020-08-05 12:52 ` Josh Natanson
Reply instructions:
You may reply publicly to this message via plain-text email
using any one of the following methods:
* Save the following mbox file, import it into your mail client,
and reply-to-all from there: mbox
Avoid top-posting and favor interleaved quoting:
https://en.wikipedia.org/wiki/Posting_style#Interleaved_style
List information: https://yhbt.net/clogger/
* Reply using the --to, --cc, and --in-reply-to
switches of git-send-email(1):
git send-email \
--in-reply-to=20200803125415.83393-1-josh@natanson.net \
--to=josh@natanson.net \
--cc=clogger-public@yhbt.net \
--cc=e@yhbt.net \
/path/to/YOUR_REPLY
https://kernel.org/pub/software/scm/git/docs/git-send-email.html
* If your mail client supports setting the In-Reply-To header
via mailto: links, try the mailto: link
Be sure your reply has a Subject: header at the top and a blank line
before the message body.
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).