From 45739ed1153f99471ca4c68b1a9576dcfdb6e497 Mon Sep 17 00:00:00 2001 From: Paul Ingram Date: Thu, 12 Sep 2013 18:19:04 -0700 Subject: [PATCH] vlog: Report timestamps in millisecond resolution in log messages. To make debugging easier. Signed-off-by: Ben Pfaff Signed-off-by: Paul Ingram --- NEWS | 2 ++ lib/dynamic-string.c | 21 ++++++++++-------- lib/dynamic-string.h | 7 +++--- lib/table.c | 2 +- lib/timeval.c | 46 +++++++++++++++++++++++++++++++++++++++ lib/timeval.h | 10 +++++++++ lib/vlog.c | 16 +++++++------- lib/vlog.h | 2 +- ovsdb/ovsdb-tool.c | 3 ++- python/ovs/vlog.py | 3 ++- tests/vlog.at | 2 +- utilities/ovs-appctl.8.in | 11 ++++++++-- utilities/ovs-ofctl.c | 3 ++- 13 files changed, 99 insertions(+), 29 deletions(-) diff --git a/NEWS b/NEWS index 7069892f4..9df7f8503 100644 --- a/NEWS +++ b/NEWS @@ -24,6 +24,8 @@ v2.0.0 - xx xxx xxxx * New "ofp-parse" for printing OpenFlow messages read from a file. - Added configurable flow caching support to IPFIX exporter. - Dropped support for Linux pre-2.6.32. + - Log files now report times with millisecond resolution. (Previous + versions only reported whole seconds.) v1.11.0 - 28 Aug 2013 diff --git a/lib/dynamic-string.c b/lib/dynamic-string.c index 9b3e7ba3b..5137d9f64 100644 --- a/lib/dynamic-string.c +++ b/lib/dynamic-string.c @@ -183,21 +183,24 @@ ds_put_printable(struct ds *ds, const char *s, size_t n) } } -/* Writes time 'when' to 'string' based on 'template', in local time or UTC - * based on 'utc'. */ +/* Writes the current time with optional millisecond resolution to 'string' + * based on 'template'. + * The current time is either localtime or UTC based on 'utc'. */ void -ds_put_strftime(struct ds *ds, const char *template, time_t when, bool utc) +ds_put_strftime_msec(struct ds *ds, const char *template, long long int when, + bool utc) { - struct tm tm; + struct tm_msec tm; if (utc) { - gmtime_r(&when, &tm); + gmtime_msec(when, &tm); } else { - localtime_r(&when, &tm); + localtime_msec(when, &tm); } for (;;) { size_t avail = ds->string ? ds->allocated - ds->length + 1 : 0; - size_t used = strftime(&ds->string[ds->length], avail, template, &tm); + size_t used = strftime_msec(&ds->string[ds->length], avail, template, + &tm); if (used) { ds->length += used; return; @@ -209,12 +212,12 @@ ds_put_strftime(struct ds *ds, const char *template, time_t when, bool utc) /* Returns a malloc()'d string for time 'when' based on 'template', in local * time or UTC based on 'utc'. */ char * -xastrftime(const char *template, time_t when, bool utc) +xastrftime_msec(const char *template, long long int when, bool utc) { struct ds s; ds_init(&s); - ds_put_strftime(&s, template, when, utc); + ds_put_strftime_msec(&s, template, when, utc); return s.string; } diff --git a/lib/dynamic-string.h b/lib/dynamic-string.h index c069586e9..227234379 100644 --- a/lib/dynamic-string.h +++ b/lib/dynamic-string.h @@ -61,10 +61,9 @@ int ds_get_line(struct ds *, FILE *); int ds_get_preprocessed_line(struct ds *, FILE *, int *line_number); int ds_get_test_line(struct ds *, FILE *); -void ds_put_strftime(struct ds *, const char *template, time_t when, bool utc) - STRFTIME_FORMAT(2); -char *xastrftime(const char *template, time_t when, bool utc) - STRFTIME_FORMAT(1); +void ds_put_strftime_msec(struct ds *, const char *template, long long int when, + bool utc); +char *xastrftime_msec(const char *template, long long int when, bool utc); char *ds_cstr(struct ds *); const char *ds_cstr_ro(const struct ds *); diff --git a/lib/table.c b/lib/table.c index 21f490504..46281703f 100644 --- a/lib/table.c +++ b/lib/table.c @@ -221,7 +221,7 @@ table_print_table_line__(struct ds *line) static char * table_format_timestamp__(void) { - return xastrftime("%Y-%m-%d %H:%M:%S", time_wall(), true); + return xastrftime_msec("%Y-%m-%d %H:%M:%S.###", time_wall_msec(), true); } static void diff --git a/lib/timeval.c b/lib/timeval.c index faf8e7bc8..c01dcedd6 100644 --- a/lib/timeval.c +++ b/lib/timeval.c @@ -610,3 +610,49 @@ timeval_dummy_register(void) unixctl_command_register("time/warp", "MSECS", 1, 1, timeval_warp_cb, NULL); } + + + +/* strftime() with an extension for high-resolution timestamps. Any '#'s in + * 'format' will be replaced by subseconds, e.g. use "%S.###" to obtain results + * like "01.123". */ +size_t +strftime_msec(char *s, size_t max, const char *format, + const struct tm_msec *tm) +{ + size_t n; + + n = strftime(s, max, format, &tm->tm); + if (n) { + char decimals[4]; + char *p; + + sprintf(decimals, "%03d", tm->msec); + for (p = strchr(s, '#'); p; p = strchr(p, '#')) { + char *d = decimals; + while (*p == '#') { + *p++ = *d ? *d++ : '0'; + } + } + } + + return n; +} + +struct tm_msec * +localtime_msec(long long int now, struct tm_msec *result) +{ + time_t now_sec = now / 1000; + localtime_r(&now_sec, &result->tm); + result->msec = now % 1000; + return result; +} + +struct tm_msec * +gmtime_msec(long long int now, struct tm_msec *result) +{ + time_t now_sec = now / 1000; + gmtime_r(&now_sec, &result->tm); + result->msec = now % 1000; + return result; +} diff --git a/lib/timeval.h b/lib/timeval.h index 8dd2e2b06..29eb9827e 100644 --- a/lib/timeval.h +++ b/lib/timeval.h @@ -57,8 +57,14 @@ BUILD_ASSERT_DECL(TYPE_IS_SIGNED(time_t)); #endif #endif /* ifndef CACHE_TIME */ +struct tm_msec { + struct tm tm; + int msec; +}; + void time_postfork(void); void time_refresh(void); + time_t time_now(void); time_t time_wall(void); long long int time_msec(void); @@ -72,6 +78,10 @@ int time_poll(struct pollfd *, int n_pollfds, long long int timeout_when, long long int timespec_to_msec(const struct timespec *); long long int timeval_to_msec(const struct timeval *); +struct tm_msec *localtime_msec(long long int now, struct tm_msec *result); +struct tm_msec *gmtime_msec(long long int now, struct tm_msec *result); +size_t strftime_msec(char *s, size_t max, const char *format, + const struct tm_msec *); void xgettimeofday(struct timeval *); void xclock_gettime(clock_t, struct timespec *); diff --git a/lib/vlog.c b/lib/vlog.c index a2671121f..37806b8db 100644 --- a/lib/vlog.c +++ b/lib/vlog.c @@ -583,7 +583,7 @@ static void vlog_init__(void) { static char *program_name_copy; - time_t now; + long long int now; /* openlog() is allowed to keep the pointer passed in, without making a * copy. The daemonize code sometimes frees and replaces 'program_name', @@ -593,10 +593,10 @@ vlog_init__(void) program_name_copy = program_name ? xstrdup(program_name) : NULL; openlog(program_name_copy, LOG_NDELAY, LOG_DAEMON); - now = time_wall(); + now = time_wall_msec(); if (now < 0) { - char *s = xastrftime("%a, %d %b %Y %H:%M:%S", now, true); - VLOG_ERR("current time is negative: %s (%ld)", s, (long int) now); + char *s = xastrftime_msec("%a, %d %b %Y %H:%M:%S", now, true); + VLOG_ERR("current time is negative: %s (%lld)", s, now); free(s); } @@ -746,12 +746,12 @@ format_log_message(const struct vlog_module *module, enum vlog_level level, ds_put_cstr(s, vlog_get_module_name(module)); break; case 'd': - p = fetch_braces(p, "%Y-%m-%d %H:%M:%S", tmp, sizeof tmp); - ds_put_strftime(s, tmp, time_wall(), false); + p = fetch_braces(p, "%Y-%m-%d %H:%M:%S.###", tmp, sizeof tmp); + ds_put_strftime_msec(s, tmp, time_wall_msec(), false); break; case 'D': - p = fetch_braces(p, "%Y-%m-%d %H:%M:%S", tmp, sizeof tmp); - ds_put_strftime(s, tmp, time_wall(), true); + p = fetch_braces(p, "%Y-%m-%d %H:%M:%S.###", tmp, sizeof tmp); + ds_put_strftime_msec(s, tmp, time_wall_msec(), true); break; case 'm': /* Format user-supplied log message and trim trailing new-lines. */ diff --git a/lib/vlog.h b/lib/vlog.h index d2c6679e2..d7d63bf11 100644 --- a/lib/vlog.h +++ b/lib/vlog.h @@ -64,7 +64,7 @@ enum vlog_level vlog_get_level_val(const char *name); #define VLOG_FACILITIES \ VLOG_FACILITY(SYSLOG, "ovs|%05N|%c%T|%p|%m") \ VLOG_FACILITY(CONSOLE, "%D{%Y-%m-%dT%H:%M:%SZ}|%05N|%c%T|%p|%m") \ - VLOG_FACILITY(FILE, "%D{%Y-%m-%dT%H:%M:%SZ}|%05N|%c%T|%p|%m") + VLOG_FACILITY(FILE, "%D{%Y-%m-%dT%H:%M:%S.###Z}|%05N|%c%T|%p|%m") enum vlog_facility { #define VLOG_FACILITY(NAME, PATTERN) VLF_##NAME, VLOG_FACILITIES diff --git a/ovsdb/ovsdb-tool.c b/ovsdb/ovsdb-tool.c index 7cd048519..867012743 100644 --- a/ovsdb/ovsdb-tool.c +++ b/ovsdb/ovsdb-tool.c @@ -519,7 +519,8 @@ do_show_log(int argc, char *argv[]) date = shash_find_data(json_object(json), "_date"); if (date && date->type == JSON_INTEGER) { time_t t = json_integer(date); - char *s = xastrftime(" %Y-%m-%d %H:%M:%S", t, true); + char *s = xastrftime_msec(" %Y-%m-%d %H:%M:%S", + t * 1000LL, true); fputs(s, stdout); free(s); } diff --git a/python/ovs/vlog.py b/python/ovs/vlog.py index 25ae4ea3b..14679d9cb 100644 --- a/python/ovs/vlog.py +++ b/python/ovs/vlog.py @@ -60,7 +60,8 @@ class Vlog: if not Vlog.__inited: return - now = datetime.datetime.utcnow().strftime("%Y-%m-%dT%H:%M:%SZ") + dt = datetime.datetime.utcnow(); + now = dt.strftime("%Y-%m-%dT%H:%M:%S.%%iZ") % (dt.microsecond/1000) syslog_message = ("%s|%s|%s|%s" % (Vlog.__msg_num, self.name, level, message)) diff --git a/tests/vlog.at b/tests/vlog.at index 957d87227..35336ce55 100644 --- a/tests/vlog.at +++ b/tests/vlog.at @@ -9,7 +9,7 @@ AT_CHECK([$PYTHON $srcdir/test-vlog.py --log-file log_file \ AT_CHECK([diff log_file stderr_log]) -AT_CHECK([sed -e 's/.*-.*-.*T..:..:..Z|//' \ +AT_CHECK([sed -e 's/.*-.*-.*T..:..:..\....Z|//' \ -e 's/File ".*", line [[0-9]][[0-9]]*,/File , line ,/' \ stderr_log], [0], [dnl 0|module_0|EMER|emergency diff --git a/utilities/ovs-appctl.8.in b/utilities/ovs-appctl.8.in index df5630978..1cf888d38 100644 --- a/utilities/ovs-appctl.8.in +++ b/utilities/ovs-appctl.8.in @@ -158,13 +158,20 @@ The current date and time in ISO 8601 format (YYYY\-MM\-DD HH:MM:SS). .IP \fB%d{\fIformat\fB}\fR The current date and time in the specified \fIformat\fR, which takes the same format as the \fItemplate\fR argument to \fBstrftime\fR(3). +As an extension, any \fB#\fR characters in \fIformat\fR will be +replaced by fractional seconds, e.g. use \fB%H:%M:%S.###\fR for the +time to the nearest millisecond. Sub-second times are only +approximate and currently decimal places after the third will always +be reported as zero. . .IP \fB%D\fR The current UTC date and time in ISO 8601 format (YYYY\-MM\-DD HH:MM:SS). . .IP \fB%D{\fIformat\fB}\fR -The current UTC date and time in the specified \fIformat\fR, which takes -the same format as the \fItemplate\fR argument to \fBstrftime\fR(3). +The current UTC date and time in the specified \fIformat\fR, which +takes the same format as the \fItemplate\fR argument to +\fBstrftime\fR(3). Supports the same extension for sub-second +resolution as \fB%d{\fR...\fB}\fR. . .IP \fB%m\fR The message being logged. diff --git a/utilities/ovs-ofctl.c b/utilities/ovs-ofctl.c index 547d50c5b..27af1b826 100644 --- a/utilities/ovs-ofctl.c +++ b/utilities/ovs-ofctl.c @@ -1388,7 +1388,8 @@ monitor_vconn(struct vconn *vconn, bool reply_to_echo_requests) run(retval, "vconn_recv"); if (timestamp) { - char *s = xastrftime("%Y-%m-%d %H:%M:%S: ", time_wall(), true); + char *s = xastrftime_msec("%Y-%m-%d %H:%M:%S.###: ", + time_wall_msec(), true); fputs(s, stderr); free(s); } -- 2.20.1