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

On Thu, Sep 29, 2011 at 09:05:59AM +0800, Daniel Veillard wrote: > 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() I think you might be mixing up virLogStr() with a different method. virLogStr() merely memcpy()'s the data into the ring buffer.