Re: [libvirt] [PATCH 1/2] logging: Do not log timestamp through syslog

On Wed, Sep 28, 2011 at 04:46:11PM +0200, Jiri Denemark wrote: > Syslog puts the timestamp to every message anyway so this removes > redundant data. > --- > src/util/logging.c | 121 +++++++++++++++++++++++++++++++-------------------- > src/util/logging.h | 9 ++-- > 2 files changed, 78 insertions(+), 52 deletions(-) > > diff --git a/src/util/logging.c b/src/util/logging.c > index a638510..4ffaf75 100644 > --- a/src/util/logging.c > +++ b/src/util/logging.c > @@ -98,7 +98,8 @@ static int virLogResetFilters(void); > static int virLogResetOutputs(void); > static int virLogOutputToFd(const char *category, int priority, > const char *funcname, long long linenr, > - const char *str, int len, void *data); > + const char *timestamp, const char *str, > + void *data); > > /* > * Logs accesses must be serialized though a mutex > @@ -282,16 +283,16 @@ void virLogShutdown(void) { > /* > * Store a string in the ring buffer > */ > -static void virLogStr(const char *str, int len) { > +static void virLogStr(const char *str) > +{ > int tmp; > + int len; > > if ((str == NULL) || (virLogBuffer == NULL) || (virLogSize <= 0)) > return; > - if (len <= 0) > - len = strlen(str); > + len = strlen(str); > if (len >= virLogSize) > return; > - virLogLock(); > > /* > * copy the data and reset the end, we cycle over the end of the buffer > @@ -317,7 +318,6 @@ static void virLogStr(const char *str, int len) { > if (virLogStart >= virLogSize) > virLogStart -= virLogSize; > } > - virLogUnlock(); > } > > static void virLogDumpAllFD(const char *msg, int len) { > @@ -618,12 +618,28 @@ cleanup: > return ret; > } > > +static char * > +virLogFormatTimestamp(void) > +{ > + struct timeval cur_time; > + struct tm time_info; > + char *str = NULL; > + > + gettimeofday(&cur_time, NULL); > + localtime_r(&cur_time.tv_sec, &time_info); > + > + if (virAsprintf(&str, "%02d:%02d:%02d.%03d", > + time_info.tm_hour, time_info.tm_min, time_info.tm_sec, > + (int) (cur_time.tv_usec / 1000)) < 0) > + return NULL; > + > + return str; > +} > + > static int > virLogFormatString(char **msg, > const char *funcname, > long long linenr, > - struct tm *time_info, > - struct timeval *cur_time, > int priority, > const char *str) > { > @@ -637,25 +653,19 @@ virLogFormatString(char **msg, > * to just grep for it to find the right place. > */ > if ((funcname != NULL)) { > - ret = virAsprintf(msg, "%02d:%02d:%02d.%03d: %d: %s : %s:%lld : %s\n", > - time_info->tm_hour, time_info->tm_min, > - time_info->tm_sec, (int) cur_time->tv_usec / 1000, > - virThreadSelfID(), > - virLogPriorityString(priority), funcname, linenr, str); > + ret = virAsprintf(msg, "%d: %s : %s:%lld : %s\n", > + virThreadSelfID(), virLogPriorityString(priority), > + funcname, linenr, str); > } else { > - ret = virAsprintf(msg, "%02d:%02d:%02d.%03d: %d: %s : %s\n", > - time_info->tm_hour, time_info->tm_min, > - time_info->tm_sec, (int) cur_time->tv_usec / 1000, > - virThreadSelfID(), > - virLogPriorityString(priority), str); > + ret = virAsprintf(msg, "%d: %s : %s\n", > + virThreadSelfID(), virLogPriorityString(priority), > + str); > } > return ret; > } > > static int > -virLogVersionString(char **msg, > - struct tm *time_info, > - struct timeval *cur_time) > +virLogVersionString(char **msg) > { > #ifdef PACKAGER_VERSION > # ifdef PACKAGER > @@ -670,9 +680,7 @@ virLogVersionString(char **msg, > "libvirt version: " VERSION > #endif > > - return virLogFormatString(msg, NULL, 0, > - time_info, cur_time, > - VIR_LOG_INFO, LOG_VERSION_STRING); > + return virLogFormatString(msg, NULL, 0, VIR_LOG_INFO, LOG_VERSION_STRING); > } > > /** > @@ -694,9 +702,8 @@ void virLogMessage(const char *category, int priority, const char *funcname, > static bool logVersionStderr = true; > char *str = NULL; > char *msg = NULL; > - struct timeval cur_time; > - struct tm time_info; > - int len, fprio, i, ret; > + char *timestamp = NULL; > + int fprio, i, ret; > int saved_errno = errno; > int emit = 1; > va_list ap; > @@ -730,16 +737,15 @@ void virLogMessage(const char *category, int priority, const char *funcname, > goto cleanup; > } > va_end(ap); > - gettimeofday(&cur_time, NULL); > - localtime_r(&cur_time.tv_sec, &time_info); > > - ret = virLogFormatString(&msg, funcname, linenr, > - &time_info, &cur_time, > - priority, str); > + ret = virLogFormatString(&msg, funcname, linenr, priority, str); > VIR_FREE(str); > if (ret < 0) > goto cleanup; > > + if (!(timestamp = virLogFormatTimestamp())) > + goto cleanup; > + > /* > * Log based on defaults, first store in the history buffer, > * then if emit push the message on the outputs defined, if none > @@ -748,42 +754,49 @@ void virLogMessage(const char *category, int priority, const char *funcname, > * threads, but avoid intermixing. Maybe set up locks per output > * to improve paralellism. > */ > - len = strlen(msg); > - virLogStr(msg, len); > + virLogLock(); > + virLogStr(timestamp); > + virLogStr(msg); > + virLogUnlock(); Hum, I'm not sure I like that, I think virLogStr ends up doing a synchronous write, and if that's the case we are doing 2 costly operations instead of one. I really prefer we merge the strings in memory before calling virLogStr()