On Mon, Sep 09, 2013 at 06:05:42PM -0700, Paul Ingram wrote:
> To make debugging easier.
It's reasonable enough.
I didn't really like the %. format specification for this. It is
inflexible--what if someone wants only tenths of a second or wants
microseconds? It is also somewhat hard to parse since it uses %
(naturally enough though). Anyway I thought about it for a minute and
concluded that one can reasonably just replace '#' in the strftime()
formatted output with fractional seconds, so that "%S.###" outputs
milliseconds, "%S.#" outputs tenths, etc. Also this allows for
formatting properly for cultures that prefer to use a comma for the
decimal point.
I made this change.
Some indentation was weird (I think you indented with tabs instead of
spaces and we must have different tab stops). I fixed it.
NEWS and manpages needed an update. I did it.
I need a sign-off.
Here's what I folded in, followed by a revised patch. Comments?
diff --git a/NEWS b/NEWS
index 09c98eb..4dd9568 100644
--- a/NEWS
+++ b/NEWS
@@ -1,5 +1,7 @@
Post-v2.0.0
---------------------
+ - Log files now report times with millisecond resolution. (Previous
+ versions only reported whole seconds.)
v2.0.0 - xx xxx xxxx
diff --git a/lib/dynamic-string.c b/lib/dynamic-string.c
index 66ffc8f..5137d9f 100644
--- a/lib/dynamic-string.c
+++ b/lib/dynamic-string.c
@@ -188,7 +188,7 @@ ds_put_printable(struct ds *ds, const char *s, size_t n)
* The current time is either localtime or UTC based on 'utc'. */
void
ds_put_strftime_msec(struct ds *ds, const char *template, long long int when,
- bool utc)
+ bool utc)
{
struct tm_msec tm;
if (utc) {
@@ -200,7 +200,7 @@ ds_put_strftime_msec(struct ds *ds, const char *template,
long long int when,
for (;;) {
size_t avail = ds->string ? ds->allocated - ds->length + 1 : 0;
size_t used = strftime_msec(&ds->string[ds->length], avail, template,
- &tm);
+ &tm);
if (used) {
ds->length += used;
return;
diff --git a/lib/table.c b/lib/table.c
index c49487c..4628170 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_msec("%Y-%m-%d %H:%M:%S.%.", time_wall_msec(), 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 6af0bac..1e5eeb2 100644
--- a/lib/timeval.c
+++ b/lib/timeval.c
@@ -70,9 +70,6 @@ static struct rusage *get_recent_rusage(void);
static void refresh_rusage(void);
static void timespec_add(struct timespec *sum,
const struct timespec *a, const struct timespec *b);
-static void format_msec(char *buf, size_t buf_len, const char *fmt, int msec);
-static char *buf_copy(char *dst, const char *dst_end,
- const char *src, const char *src_end);
static void
init_clock(struct clock *c, clockid_t id)
@@ -499,77 +496,44 @@ timeval_dummy_register(void)
}
-/* Millisecond resolution timestamps. */
+/* 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)
{
- char buf[256];
+ size_t n;
- format_msec(buf, sizeof buf, format, tm->msec);
+ n = strftime(s, max, format, &tm->tm);
+ if (n) {
+ char decimals[4];
+ char *d, *p;
- return strftime(s, max, buf, &tm->tm);
+ sprintf(decimals, "%03d", tm->msec);
+ d = decimals;
+ for (p = strchr(s, '#'); p; p = strchr(p, '#')) {
+ *p++ = *d ? *d++ : '0';
+ }
+ }
+
+ return n;
}
-struct tm_msec*
-localtime_msec(long long int now, struct tm_msec *result) {
+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);
+ 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) {
+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;
}
-
-void
-format_msec(char *buf, size_t buf_len, const char *fmt, int msec)
-{
- char *buf_ptr = buf;
- const char *buf_end = buf + buf_len;
- const char *fmt_ptr = fmt;
- const char *add_ptr = fmt_ptr;
-
- bool percent = false;
-
- char msec_buf[4];
- const char *msec_end = msec_buf;
- ovs_assert(sprintf(msec_buf, "%03i", MIN(msec, 999)) == 3);
- msec_end += strlen(msec_buf);
-
- while (*fmt_ptr) {
- if (percent) {
- if (*fmt_ptr == '.') {
- buf_ptr = buf_copy(buf_ptr, buf_end, add_ptr, fmt_ptr-1);
- buf_ptr = buf_copy(buf_ptr, buf_end, msec_buf, msec_end);
-
- add_ptr = fmt_ptr+1;
- }
- percent = false;
- }
- else if (*fmt_ptr == '%') {
- percent = true;
- }
- fmt_ptr++;
- }
-
- buf_ptr = buf_copy(buf_ptr, buf_end, add_ptr, fmt_ptr);
-
- ovs_assert(buf_ptr <= buf_end);
-
- *(buf_ptr < buf_end ? buf_ptr : buf_ptr-1) = '\0';
-}
-
-static char *
-buf_copy(char *dst, const char *dst_end, const char *src, const char *src_end)
-{
- int len = MIN(dst_end-dst, src_end-src);
- memcpy(dst, src, len);
- dst += len;
- return dst;
-}
diff --git a/lib/timeval.h b/lib/timeval.h
index dfe5a98..99b3af0 100644
--- a/lib/timeval.h
+++ b/lib/timeval.h
@@ -58,10 +58,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);
+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 *tm);
+ 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 2b97da1..37806b8d 100644
--- a/lib/vlog.c
+++ b/lib/vlog.c
@@ -746,11 +746,11 @@ 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);
+ 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);
+ 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':
diff --git a/lib/vlog.h b/lib/vlog.h
index 9699379..d7d63bf 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:%S.%.Z}|%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 7cd0485..8670127 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/utilities/ovs-appctl.8.in b/utilities/ovs-appctl.8.in
index df56309..1cf888d 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 86efb04..a5a5c02 100644
--- a/utilities/ovs-ofctl.c
+++ b/utilities/ovs-ofctl.c
@@ -1396,7 +1396,7 @@ monitor_vconn(struct vconn *vconn, bool
reply_to_echo_requests)
run(retval, "vconn_recv");
if (timestamp) {
- char *s = xastrftime_msec("%Y-%m-%d %H:%M:%S.%.: ",
+ char *s = xastrftime_msec("%Y-%m-%d %H:%M:%S.###: ",
time_wall_msec(), true);
fputs(s, stderr);
free(s);
--8<--------------------------cut here-------------------------->8--
From: Paul Ingram <ping...@nicira.com>
Date: Mon, 9 Sep 2013 18:05:42 -0700
Subject: [PATCH] Report timestamps in millisecond resolution in log messages.
To make debugging easier.
Signed-off-by: Ben Pfaff <b...@nicira.com>
---
NEWS | 2 ++
lib/dynamic-string.c | 21 ++++++++++++---------
lib/dynamic-string.h | 7 +++----
lib/table.c | 2 +-
lib/timeval.c | 43 +++++++++++++++++++++++++++++++++++++++++++
lib/timeval.h | 9 +++++++++
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, 95 insertions(+), 29 deletions(-)
diff --git a/NEWS b/NEWS
index 09c98eb..4dd9568 100644
--- a/NEWS
+++ b/NEWS
@@ -1,5 +1,7 @@
Post-v2.0.0
---------------------
+ - Log files now report times with millisecond resolution. (Previous
+ versions only reported whole seconds.)
v2.0.0 - xx xxx xxxx
diff --git a/lib/dynamic-string.c b/lib/dynamic-string.c
index 9b3e7ba..5137d9f 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 c069586..2272343 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 21f4905..4628170 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 3262397..1e5eeb2 100644
--- a/lib/timeval.c
+++ b/lib/timeval.c
@@ -494,3 +494,46 @@ 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 *d, *p;
+
+ sprintf(decimals, "%03d", tm->msec);
+ d = decimals;
+ for (p = strchr(s, '#'); p; p = strchr(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 d0962ee..99b3af0 100644
--- a/lib/timeval.h
+++ b/lib/timeval.h
@@ -40,6 +40,11 @@ BUILD_ASSERT_DECL(TYPE_IS_SIGNED(time_t));
#define TIME_MAX TYPE_MAXIMUM(time_t)
#define TIME_MIN TYPE_MINIMUM(time_t)
+struct tm_msec {
+ struct tm tm;
+ int msec;
+};
+
time_t time_now(void);
time_t time_wall(void);
long long int time_msec(void);
@@ -53,6 +58,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 a267112..37806b8d 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 d2c6679..d7d63bf 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 7cd0485..8670127 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 25ae4ea..14679d9 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 957d872..35336ce 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 <name>, line <number>,/' \
stderr_log], [0], [dnl
0|module_0|EMER|emergency
diff --git a/utilities/ovs-appctl.8.in b/utilities/ovs-appctl.8.in
index df56309..1cf888d 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 95bf1bf..a5a5c02 100644
--- a/utilities/ovs-ofctl.c
+++ b/utilities/ovs-ofctl.c
@@ -1396,7 +1396,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);
}
--
1.7.10.4
_______________________________________________
dev mailing list
dev@openvswitch.org
http://openvswitch.org/mailman/listinfo/dev
