From 2816f3ceaa31452f6bb67a7a7297e6795221cb35 Mon Sep 17 00:00:00 2001 From: Eric Wong Date: Fri, 24 Dec 2010 15:41:53 -0800 Subject: use clock_gettime for time resolution 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). --- ext/clogger_ext/clogger.c | 55 ++++++++++++++++++++++++---------------------- ext/clogger_ext/extconf.rb | 4 ++++ test/test_clogger.rb | 10 +++++++++ 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 #include #ifdef HAVE_RUBY_IO_H # include @@ -10,25 +11,21 @@ #include #include #include -#include #include #ifdef HAVE_FCNTL_H # include #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 -- cgit v1.2.3-24-ge0c7