Re: Clogger request_time formatting

[Eric Wong <e@yhbt.net>]

Josh Natanson <josh@natanson.net> wrote:
> Thanks for the reminder, I hadn't considered the C extension.  I took
> a look today, but wasn't able to make any headway - my C is very
> rusty, I'm not sure you would want anything I'd write there anyhow.
> That leaves me a little stuck, with the code working frozen in my
> rails app, but without support in the C layer (or passing tests). I'm
> sure you won't want to incorporate a partial change.  If you (or
> someone else) has some time to consider the C side, that would be
> fantastic.  If not, I might have to go another route for my logging.

No worries, below is a proposed patch which adds C support.

I also made the Ruby format compilation cap power-of-10 to be
<=9 to reduce likelyhood of overflows and non-sensical values.
There's no way to get higher resolution than nanoseconds in
POSIX, and most clocks/kernels are lower resolution, even.

Arithmetic is not my strong suit, but the C code should be
pretty straightforward if you're familiar with any other
C-like language, Ruby included.

> Sorry about the email formatting, gmail has ruined me.

Not just you, 99% of the Internet :<


Anyways, can you provide a proper commit message describing the
feature?  Thanks.

 ext/clogger_ext/clogger.c | 32 ++++++++++++++++++++++++++++++++
 lib/clogger.rb            |  7 ++++++-
 2 files changed, 38 insertions(+), 1 deletion(-)

diff --git a/ext/clogger_ext/clogger.c b/ext/clogger_ext/clogger.c
index fdc23e3..a316545 100644
--- a/ext/clogger_ext/clogger.c
+++ b/ext/clogger_ext/clogger.c
@@ -374,12 +374,44 @@ 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 608909d..8559841 100644
--- a/lib/clogger.rb
+++ b/lib/clogger.rb
@@ -92,7 +92,12 @@ private
         when /\A\$time\{(\d+)\}\z/
           rv << [ OP_TIME, *usec_conv_pair(tok, $1.to_i) ]
         when /\A\$request_time\{(\d+),(\d+)\}\z/
-          rv << [ OP_REQUEST_TIME, *usec_conv_pair(tok, $2.to_i), $1.to_i ]
+          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 ]
         when /\A\$request_time\{(\d+)\}\z/
           rv << [ OP_REQUEST_TIME, *usec_conv_pair(tok, $1.to_i), 0 ]
         else