[ovs-dev] [PATCH 1/2] Report timestamps in millisecond resolution in log messages.

Paul Ingram pingram at nicira.com
Fri Sep 13 01:23:22 UTC 2013


On Sep 11, 2013, at 10:39 PM, Ben Pfaff <blp at nicira.com> wrote:

> 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.

Ok, using ### works too. I like it. (I suppose something like %3. (or choose a format character other than '.') would be the most strftime-like.)

I made a small change to your ### scheme to require runs of consecutive '#' characters and to reprint on each new run.

So given seconds and milliseconds of 12.789, the format string "%S.# %S.###" will produce "12.7 12.789" (instead of "12.7 12.890" where the 789 is spread across the two runs of '#' characters).

Here's my change to your change followed by the full patch (including my sign-off).

Thanks

:: psi

--- a/lib/timeval.c
+++ b/lib/timeval.c
@@ -507,12 +507,14 @@ strftime_msec(char *s, size_t max, const char *format,
     n = strftime(s, max, format, &tm->tm);
     if (n) {
         char decimals[4];
-        char *d, *p;
+        char *p;
 
         sprintf(decimals, "%03d", tm->msec);
-        d = decimals;
         for (p = strchr(s, '#'); p; p = strchr(p, '#')) {
-            *p++ = *d ? *d++ : '0';
+            char *d = decimals;
+            while (*p == '#')  {
+                *p++ = *d ? *d++ : '0';
+            }
         }
     }

--8<--------------------------cut here-------------------------->8--

From: Paul Ingram <pingram at nicira.com>
Date: Thu, 12 Sep 2013 18:19:04 -0700
Subject: [PATCH] Report timestamps in millisecond resolution in log messages.

To make debugging easier.

Signed-off-by: Ben Pfaff <blp at nicira.com>
Signed-off-by: Paul Ingram <pingram at nicira.com>
---
 NEWS                      |    2 ++
 lib/dynamic-string.c      |   21 ++++++++++++---------
 lib/dynamic-string.h      |    7 +++----
 lib/table.c               |    2 +-
 lib/timeval.c             |   45 +++++++++++++++++++++++++++++++++++++++++++++
 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, 97 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 37b4353..69411ac 100644
--- a/lib/timeval.c
+++ b/lib/timeval.c
@@ -493,3 +493,48 @@ 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 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..37806b8 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.9.5





More information about the dev mailing list