[ovs-dev] [PATCH 1/2] Report timestamps in millisecond resolution in log messages.
Ben Pfaff
blp at nicira.com
Fri Sep 13 16:07:30 UTC 2013
You're welcome.
On Thu, Sep 12, 2013 at 07:03:51PM -0700, Paul Ingram wrote:
> I just noticed that you fixed a silly error in ovsdb/ovsdb-tool.c that
> I introduced in my original patch.
>
> Thanks for that
>
> :: psi
>
> On Sep 12, 2013, at 6:23 PM, Paul Ingram <pingram at nicira.com> wrote:
>
> > 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