about summary refs log tree commit homepage
diff options
context:
space:
mode:
authorEric Wong <normalperson@yhbt.net>2010-12-24 15:41:53 -0800
committerEric Wong <normalperson@yhbt.net>2010-12-24 15:48:18 -0800
commit2816f3ceaa31452f6bb67a7a7297e6795221cb35 (patch)
tree3f3ed0229d2ce15e8287c513a2efa2a6fb47012f
parent9b46379f75f384c86e42046ab03ce55231197c92 (diff)
This lets us use CLOCK_MONOTONIC so we are not affected by
system clock changes.

We still convert to microseconds instead of nanoseconds for
(pure)-Ruby 1.8 code compatibility.  There is also little need
for nanosecond timer resolution in log files (microsecond is not
needed, even).
-rw-r--r--ext/clogger_ext/clogger.c55
-rw-r--r--ext/clogger_ext/extconf.rb4
-rw-r--r--test/test_clogger.rb10
3 files changed, 43 insertions, 26 deletions
diff --git a/ext/clogger_ext/clogger.c b/ext/clogger_ext/clogger.c
index 09eeffd..e4a64b5 100644
--- a/ext/clogger_ext/clogger.c
+++ b/ext/clogger_ext/clogger.c
@@ -1,4 +1,5 @@
-#define _BSD_SOURCE
+#define _POSIX_C_SOURCE 200112L
+#include <time.h>
 #include <ruby.h>
 #ifdef HAVE_RUBY_IO_H
 #  include <ruby/io.h>
@@ -10,25 +11,21 @@
 #include <sys/types.h>
 #include <sys/stat.h>
 #include <sys/time.h>
-#include <time.h>
 #include <errno.h>
 #ifdef HAVE_FCNTL_H
 #  include <fcntl.h>
 #endif
 #include "ruby_1_9_compat.h"
 
-/* in case _BSD_SOURCE doesn't give us this macro */
-#ifndef timersub
-#  define timersub(a, b, result) \
-do { \
-        (result)->tv_sec = (a)->tv_sec - (b)->tv_sec; \
-        (result)->tv_usec = (a)->tv_usec - (b)->tv_usec; \
-        if ((result)->tv_usec < 0) { \
-                --(result)->tv_sec; \
-                (result)->tv_usec += 1000000; \
-        } \
-} while (0)
-#endif
+static void clock_diff(struct timespec *a, const struct timespec *b)
+{
+        a->tv_sec -= b->tv_sec;
+        a->tv_nsec -= b->tv_nsec;
+        if (a->tv_nsec < 0) {
+                --a->tv_sec;
+                a->tv_nsec += 1000000000;
+        }
+}
 
 /* give GCC hints for better branch prediction
  * (we layout branches so that ASCII characters are handled faster) */
@@ -78,7 +75,7 @@ struct clogger {
         VALUE body;
 
         off_t body_bytes_sent;
-        struct timeval tv_start;
+        struct timespec ts_start;
 
         int fd;
         int wrap_body;
@@ -336,34 +333,40 @@ static void append_body_bytes_sent(struct clogger *c)
         rb_str_buf_cat(c->log_buf, buf, nr);
 }
 
-static void append_tv(struct clogger *c, const VALUE *op, struct timeval *tv)
+static void append_ts(struct clogger *c, const VALUE *op, struct timespec *ts)
 {
-        char buf[sizeof(".000000") + ((sizeof(tv->tv_sec) * 8) / 3)];
+        char buf[sizeof(".000000") + ((sizeof(ts->tv_sec) * 8) / 3)];
         int nr;
         char *fmt = RSTRING_PTR(op[1]);
         int ndiv = NUM2INT(op[2]);
+        int usec = ts->tv_nsec / 1000;
 
         nr = snprintf(buf, sizeof(buf), fmt,
-                      (int)tv->tv_sec, (int)(tv->tv_usec / ndiv));
+                      (int)ts->tv_sec, (int)(usec / ndiv));
         assert(nr > 0 && nr < (int)sizeof(buf));
         rb_str_buf_cat(c->log_buf, buf, nr);
 }
 
 static void append_request_time_fmt(struct clogger *c, const VALUE *op)
 {
-        struct timeval now, d;
+        struct timespec now;
+        int r = clock_gettime(CLOCK_MONOTONIC, &now);
+
+        if (unlikely(r != 0))
+                rb_sys_fail("clock_gettime(CLOCK_MONONTONIC)");
 
-        gettimeofday(&now, NULL);
-        timersub(&now, &c->tv_start, &d);
-        append_tv(c, op, &d);
+        clock_diff(&now, &c->ts_start);
+        append_ts(c, op, &now);
 }
 
 static void append_time_fmt(struct clogger *c, const VALUE *op)
 {
-        struct timeval now;
+        struct timespec now;
+        int r = clock_gettime(CLOCK_REALTIME, &now);
 
-        gettimeofday(&now, NULL);
-        append_tv(c, op, &now);
+        if (unlikely(r != 0))
+                rb_sys_fail("clock_gettime(CLOCK_REALTIME)");
+        append_ts(c, op, &now);
 }
 
 static void append_request_uri(struct clogger *c)
@@ -725,7 +728,7 @@ static VALUE ccall(struct clogger *c, VALUE env)
 {
         VALUE rv;
 
-        gettimeofday(&c->tv_start, NULL);
+        clock_gettime(CLOCK_MONOTONIC, &c->ts_start);
         c->env = env;
         c->cookies = Qfalse;
         rv = rb_funcall(c->app, call_id, 1, env);
diff --git a/ext/clogger_ext/extconf.rb b/ext/clogger_ext/extconf.rb
index b327ada..60c46a7 100644
--- a/ext/clogger_ext/extconf.rb
+++ b/ext/clogger_ext/extconf.rb
@@ -13,6 +13,10 @@ begin
     have_macro('O_NONBLOCK', %w(unistd.h fcntl.h))
   end
 
+  unless have_macro('CLOCK_MONOTONIC', 'time.h', '-D_POSIX_C_SOURCE=200112L')
+    $CPPFLAGS += '-D_POSIX_SOURCE_200112L'
+    have_func('CLOCK_MONOTONIC', 'time.h')
+  end
   have_func('localtime_r', 'time.h') or raise "localtime_r needed"
   have_func('gmtime_r', 'time.h') or raise "gmtime_r needed"
   have_func('rb_str_set_len', 'ruby.h')
diff --git a/test/test_clogger.rb b/test/test_clogger.rb
index 9252a42..47387bb 100644
--- a/test/test_clogger.rb
+++ b/test/test_clogger.rb
@@ -647,4 +647,14 @@ class TestClogger < Test::Unit::TestCase
       Clogger.new(app, :logger=> $stderr, :path => tmp.path)
     }
   end
+
+  def test_request_time
+    s = []
+    app = lambda { |env| sleep(0.1) ; [302, [], [] ] }
+    cl = Clogger.new(app, :logger => s, :format => "$request_time")
+    status, headers, body = cl.call(@req)
+    assert_nothing_raised { body.each { |x| } ; body.close }
+    assert s[-1].to_f >= 0.100
+    assert s[-1].to_f <= 0.110
+  end
 end