[logging] Add new "log timestamp precision" command for subsecond timestamps
2007-04-28 Andrew J. Schorr <ajschorr@alumni.princeton.edu>
* command.c: (config_write_host) Save "log timestamp precision"
if not default value.
(show_logging) Show configured timestamp precision.
(config_log_timestamp_precision) Enable configuration of timestamp
precision.
(no_config_log_timestamp_precision) Restore default timestamp
precision.
(cmd_init) Install new timestamp precision commands.
* log.h: (struct zlog) New timestamp_precision field.
(quagga_timestamp) New function to generate a timestamp with the
desired precision.
(struct timestamp_control) Declare a structure for use in avoiding
repeated duplicate calls to quagga_timestamp.
* log.c: (quagga_timestamp) New function to generate a timestamp
of the desired precision.
(time_print) Call quagga_timestamp if the time hasn't already been
calculated.
(vzlog) Initialize a timestamp_control structure and pass it to
time_print and vty_log.
(zlog_backtrace) Fix 64-bit problem: cannot print size_t with %u.
* vty.h: Must now include "log.h".
(vty_log) Takes an additional struct timestamp_control argument.
* vty.c: (vty_log_out) Use new struct timestamp_control and new
quagga_timestamp function to print timestamps of the desired
precision.
(vty_time_print) Use new quagga_timestamp function.
(vty_log) Accept new struct timestamp_control argument and pass it
down to vty_log_out.
diff --git a/lib/log.c b/lib/log.c
index c123f24..7668222 100644
--- a/lib/log.c
+++ b/lib/log.c
@@ -66,32 +66,81 @@
/* For time string format. */
-#define TIME_BUF 27
+
+size_t
+quagga_timestamp(int timestamp_precision, char *buf, size_t buflen)
+{
+ static struct {
+ time_t last;
+ size_t len;
+ char buf[28];
+ } cache;
+ struct timeval clock;
+
+ /* would it be sufficient to use global 'recent_time' here? I fear not... */
+ gettimeofday(&clock, NULL);
+
+ /* first, we update the cache if the time has changed */
+ if (cache.last != clock.tv_sec)
+ {
+ struct tm *tm;
+ cache.last = clock.tv_sec;
+ tm = localtime(&cache.last);
+ cache.len = strftime(cache.buf, sizeof(cache.buf),
+ "%Y/%m/%d %H:%M:%S", tm);
+ }
+ /* note: it's not worth caching the subsecond part, because
+ chances are that back-to-back calls are not sufficiently close together
+ for the clock not to have ticked forward */
+
+ if (buflen > cache.len)
+ {
+ memcpy(buf, cache.buf, cache.len);
+ if ((timestamp_precision > 0) &&
+ (buflen > cache.len+1+timestamp_precision))
+ {
+ /* should we worry about locale issues? */
+ long divisor = 100000;
+ char *p = buf+cache.len;
+ *p++ = '.';
+ do
+ {
+ *p++ = '0'+(clock.tv_usec/divisor);
+ clock.tv_usec %= divisor;
+ divisor /= 10;
+ }
+ while (--timestamp_precision > 0);
+ *p = '\0';
+ return p-buf;
+ }
+ buf[cache.len] = '\0';
+ return cache.len;
+ }
+ if (buflen > 0)
+ buf[0] = '\0';
+ return 0;
+}
/* Utility routine for current time printing. */
static void
-time_print (FILE *fp)
+time_print(FILE *fp, struct timestamp_control *ctl)
{
- int ret;
- char buf [TIME_BUF];
- time_t clock;
- struct tm *tm;
-
- time (&clock);
- tm = localtime (&clock);
-
- ret = strftime (buf, TIME_BUF, "%Y/%m/%d %H:%M:%S", tm);
- if (ret == 0) {
- zlog_warn ("strftime error");
- }
-
- fprintf (fp, "%s ", buf);
+ if (!ctl->already_rendered)
+ {
+ ctl->len = quagga_timestamp(ctl->precision, ctl->buf, sizeof(ctl->buf));
+ ctl->already_rendered = 1;
+ }
+ fprintf(fp, "%s ", ctl->buf);
}
+
/* va_list version of zlog. */
static void
vzlog (struct zlog *zl, int priority, const char *format, va_list args)
{
+ struct timestamp_control tsctl;
+ tsctl.already_rendered = 0;
+
/* If zlog is not specified, use default one. */
if (zl == NULL)
zl = zlog_default;
@@ -99,7 +148,8 @@
/* When zlog_default is also NULL, use stderr for logging. */
if (zl == NULL)
{
- time_print (stderr);
+ tsctl.precision = 0;
+ time_print(stderr, &tsctl);
fprintf (stderr, "%s: ", "unknown");
vfprintf (stderr, format, args);
fprintf (stderr, "\n");
@@ -108,6 +158,7 @@
/* In this case we return at here. */
return;
}
+ tsctl.precision = zl->timestamp_precision;
/* Syslog output */
if (priority <= zl->maxlvl[ZLOG_DEST_SYSLOG])
@@ -122,7 +173,7 @@
if ((priority <= zl->maxlvl[ZLOG_DEST_FILE]) && zl->fp)
{
va_list ac;
- time_print (zl->fp);
+ time_print (zl->fp, &tsctl);
if (zl->record_priority)
fprintf (zl->fp, "%s: ", zlog_priority[priority]);
fprintf (zl->fp, "%s: ", zlog_proto_names[zl->protocol]);
@@ -137,7 +188,7 @@
if (priority <= zl->maxlvl[ZLOG_DEST_STDOUT])
{
va_list ac;
- time_print (stdout);
+ time_print (stdout, &tsctl);
if (zl->record_priority)
fprintf (stdout, "%s: ", zlog_priority[priority]);
fprintf (stdout, "%s: ", zlog_proto_names[zl->protocol]);
@@ -151,7 +202,7 @@
/* Terminal monitor. */
if (priority <= zl->maxlvl[ZLOG_DEST_MONITOR])
vty_log ((zl->record_priority ? zlog_priority[priority] : NULL),
- zlog_proto_names[zl->protocol], format, args);
+ zlog_proto_names[zl->protocol], format, &tsctl, args);
}
static char *
@@ -458,8 +509,8 @@
((size_t)size > sizeof(array)/sizeof(array[0])))
{
zlog_err("Cannot get backtrace, returned invalid # of frames %d "
- "(valid range is between 1 and %u)",
- size, sizeof(array)/sizeof(array[0]));
+ "(valid range is between 1 and %lu)",
+ size, (unsigned long)(sizeof(array)/sizeof(array[0])));
return;
}
zlog(NULL, priority, "Backtrace for %d stack frames:", size);