[ovs-dev] [PATCH 1/2] Report timestamps in millisecond resolution in log messages.
Paul Ingram
pingram at nicira.com
Fri Sep 13 02:03:51 UTC 2013
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