[Date Prev][Date Next]   [Thread Prev][Thread Next]   [Thread Index] [Date Index] [Author Index]

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



On Thu, Sep 29, 2011 at 08:58:08AM +0100, Daniel P. Berrange wrote:
> 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.

  Ah right, my bad, objection removed !

Worse is that I wrote that routine mostly, I will blame the old age :-)
It's virLogMessage() which (eventually) ends up writing to the log
outputs...

Daniel

-- 
Daniel Veillard      | libxml Gnome XML XSLT toolkit  http://xmlsoft.org/
daniel veillard com  | Rpmfind RPM search engine http://rpmfind.net/
http://veillard.com/ | virtualization library  http://libvirt.org/


[Date Prev][Date Next]   [Thread Prev][Thread Next]   [Thread Index] [Date Index] [Author Index]